Closing a large dataset with CLOBS taking FOREVER

[aehimself]

I don't know when it changed or if it was always like this, but... I open a dataset with a decent amount of records. When I am attempting to close it with Dataset.Close (or freeing it, does not really matter) the program gets stuck in this cycle for about 10-20 minutes!!!

procedure TZAbstractCachedResultSet.ResetCursor;
var
I: Integer;
begin
if Assigned(FRowAccessor) then begin
for I := 0 to FRowsList.Count - 1 do
FRowAccessor.DisposeBuffer(PZRowBuffer(FRowsList[ I]));
for I := 0 to FInitialRowsList.Count - 1 do
FRowAccessor.DisposeBuffer(PZRowBuffer(FInitialRowsList[ I]));
FRowsList.Clear;
FInitialRowsList.Clear;
FCurrentRowsList.Clear;
end;
FNextRowIndex := 0;
inherited ResetCursor;
end;

FRowList.Count is 1558812, in each cycle it's calling TZAbstractOracleBlob.Destroy -> FreeOCIResources. I understand we are attempting to clean up after ourselves, but does it really take close to half an hour for the driver to release 1-1,5 million blobs?!

I'm a bit suspicious that Michael's commit (10/18/2020, 9:33:46 AM, 7c378e729d53566f24c2510e33a07635fe036ee4, resolve aehimself's connect->kill-connection->disconnect logic) might have to do something with this slowdown...?
At the moment I'm checking how long it really takes and how many records I exactly had in the dataset. After that I'll try to roll back that commit to see if it makes a difference.

Any help is greatly appreciated, as this is wait time is not really viable for closing any dataset.

[aehimself]

Fyi, I'm still waiting for it to close my dataset. Since then.

What is even more surprising, the memory usage of the application is INCREASING continuously as it's freeing up the resources...? :|

[aehimself]

The dataset was overly large. After 4 hours of waiting fir it to close (at this point application was already using 3,8 GB memory instead of the normal 500M - 1G) I decided to go ahead with a smaller version.

SELECT CLOBFIELD FROM TABLE

Code is:

Code: Select all

 sw := TStopWatch.StartNew;
 Try
  i := SQLQuery.RecordCount;
  SQLQuery.Close;
 Finally
  TMessageDialog.ShowDialog('Closing the dataset with ' + i.ToString + ' records took ' + sw.ElapsedMilliseconds.ToString + ' ms');
 End;

With the test dataset having 951 records, results are the following:

No multithreaded mode, no cached lobs: 9997, 10461, 10004. Average: 10154 ms
Multithreaded mode, no cached lobs: 9917, 10245, 10188. Average: 10116 ms
No multithreaded mode, cached lobs: 5, 5, 5. Average: 5 ms
Multithreaded mode, cached lobs: 5, 5, 5. Average: 5 ms

So... cached lobs free up perfectly, while uncached lobs suck. Badly. After https://sourceforge.net/p/zeoslib/code-0/7033/ cached lobs started to work, so uncached version creates a TZOracleCachedResultSet while cached version creates a TZCachedResultSet. The question is, before said commit there was only TZOracleCachedResultSet and it was working fine...?

Edit: Rolling back said commit by Michael did not speed things up. I'll try to investigate further.

[aehimself]

Commenting out the call to FreeOCIResources from (effectively removing) TZAbstractOracleBlob.Destroy fixes the issue. Now the 951 uncached lobs free up in 0 ms.

Edit:
I pinpointed the issue. ZDbcOracleResultSet.pas:3310:

Code: Select all

      Status := FPlainDriver.OCILobIsOpen(FOCISvcCtx, FOCIError, FLobLocator, B);

Without this line (and the free up block below, otherwise throws AVs) freeing up in 18-22 ms. With this line (and only this, still without the freeing up part) closing the dataset with 951 records takes 10 seconds.

The thing is, even with the cleanup part included, DeLeaker reports that ORAOCIICUS.DLL itself leaks a TREMENDOUS amount of resources (including heap memory and critical sections, a total of 331)... I wonder if it is just one more well made driver.
Let's see if I can make a difference by downgrading / upgrading from 19.8.

Edit: There's no newer version than 19.8, and previous versions take me to a logon page where I have no account for. Just perfect.

For the time being I think I'll just remove the destructor part. It also worths to think about. We have a number of CLOB fields, and each time we talk to the server:

https://docs.oracle.com/cd/B10501_01/ap ... i16m34.htm

For internal LOBs, this call requires a server round- trip because it checks the state on the server to see if the LOB is indeed open. For external LOBs (BFILEs), this call also requires a round- trip because the actual operating system file on the server side must be checked to see if it is actually open.

Even with fast connections, that can be the reason why the closedown is this slow... if 1 call takes 10 milliseconds, 1000 calls take 10 seconds. 1,5 million calls takes more than 2 hours (!!!)

[aehimself]

According to my test, that part is completely useless. I'll need Michael to confirm this, so I'm not going to create a patch. But.

From that ~1000 fields, OCILobIsOpen ALWAYS returned false, the inner closing was never executed. The reason? Every action is surrounded by a Try...Finally block, like this:

Code: Select all

function TBlobField.GetAsBytes: TArray<Byte>;
var
  Len: Integer;
  LStream: TStream;
begin
  LStream := DataSet.CreateBlobStream(Self, bmRead); // <- LOBStream opens, reads data. Call to OCILobOpen
  try
    Len := LStream.Size;
    SetLength(Result, Len);
    LStream.ReadBuffer(Result, Len);
  finally
    LStream.Free; // <- LOBStream closes before getting freed. Call to OCILobClose
  end;
end;

This means that there are NO ways a lobstream will still be open (even if it was accessed during it's lifetime) when the dataset is being closed.
I suggest that we set FLobLocator to nil before calling FreeOCIResources in the destructor, threfore skipping the slow, unnecessary part.

But @egonhugeist, please check and confirm.

Edit:
I never mentioned what exactly I am talking about. I also realized that a few more "hacks" will be needed, as setting FLobLocator to nil will not execute the cleanup in the Finally part:

Code: Select all

destructor TZAbstractOracleBlob.Destroy;
begin
  FreeOCIResources;
  inherited;
end;

procedure TZAbstractOracleBlob.FreeOCIResources;
var Status: sword;
  B: LongBool;
begin
  if (FLobLocator <> nil) and FLocatorAllocated then try
    if not FReleased then begin
      Status := FPlainDriver.OCILobIsOpen(FOCISvcCtx, FOCIError, FLobLocator, B);
      if Status <> OCI_SUCCESS then
        FOracleConnection.HandleErrorOrWarning(FOCIError, status,
          lcOther, 'OCILobIsOpen', Self);
      if B then begin // Here B is ALWAYS false!
        Status := FPlainDriver.OCILobClose(FOCISvcCtx, FOCIError, FLobLocator);
        if Status <> OCI_SUCCESS then
          FOracleConnection.HandleErrorOrWarning(FOCIError, status,
            lcOther, 'OCILobClose', Self);
      end;
    end;
  finally
    Status := FPlainDriver.OCIDescriptorFree(FLobLocator, FDescriptorType);
    FLobLocator := nil;
    if Status <> OCI_SUCCESS then
      FOracleConnection.HandleErrorOrWarning(FOCIError, status,
        lcOther, 'OCIDescriptorFree', Self);
  end;
end;

[aehimself]

This would be my patch, confirmed working:

Code: Select all

destructor TZAbstractOracleBlob.Destroy;
begin
  FLocatorAllocated := False;
  FreeOCIResources;
  inherited;
end;

{$IFDEF FPC} {$PUSH} {$WARN 5057 off : Local variable "B" does not seem to be initialized} {$ENDIF}
procedure TZAbstractOracleBlob.FreeOCIResources;
var Status: sword;
  B: LongBool;
begin
  Try
    if (FLobLocator <> nil) and FLocatorAllocated then
      if not FReleased then begin
        Status := FPlainDriver.OCILobIsOpen(FOCISvcCtx, FOCIError, FLobLocator, B);
        if Status <> OCI_SUCCESS then
          FOracleConnection.HandleErrorOrWarning(FOCIError, status,
            lcOther, 'OCILobIsOpen', Self);
        if B then begin
          Status := FPlainDriver.OCILobClose(FOCISvcCtx, FOCIError, FLobLocator);
          if Status <> OCI_SUCCESS then
            FOracleConnection.HandleErrorOrWarning(FOCIError, status,
              lcOther, 'OCILobClose', Self);
        end;
      end;
  finally
    if FLobLocator <> nil Then
    Begin
      Status := FPlainDriver.OCIDescriptorFree(FLobLocator, FDescriptorType);
      FLobLocator := nil;
      if Status <> OCI_SUCCESS then
        FOracleConnection.HandleErrorOrWarning(FOCIError, status,
          lcOther, 'OCIDescriptorFree', Self);
    End;
  end;
end;

[marsupilami]

I checked your changes into SVN and currently wait for the test suites to finis.

Regarding older versions: I do have Express Editions of Oracle 11.2 and 18.4 Z/ 18c. If it helps I can send you a link...

[aehimself]

I checked your changes into SVN and currently wait for the test suites to finis.

That is exactly I wanted to avoid by sending a pull request, but let's see what the tests say :)

Regarding older versions: I do have Express Editions of Oracle 11.2 and 18.4 Z/ 18c. If it helps I can send you a link...

While yes, it would mean a lot; I am genuinely fed up by this "register or nothing" theory going on right now. I mean; yes, we might f*cked up the latest driver but hey if you pay, you might go back to a previous, maybe more stable version.

I am just disappointed in Oracle. I wish our company wouldn't have signed a contract with them :(

[marsupilami]

That is exactly I wanted to avoid by sending a pull request, but let's see what the tests say

This is what we have an automated testing system for Unfortunately the tests say things like:

Exception: [EZSQLException] SQL Error: OCI_INVALID_HANDLE
Code: -2 Message: OCIDescriptorFree

and

Exception: [EAccessViolation] Access violation at address 61F39BB3 in module 'OraClient11.Dll'. Read of address 00F338BC
at: $61F39BB3

So - I reverted your changes. You might want to use ZTestAll for testing your changes. I will have to write a wiki page regarding this...
If you want to see more about these errors: Look into the tests on Jenkins for Delphi 2010, build number 1001.

While yes, it would mean a lot; I am genuinely fed up by this "register or nothing" theory going on right now. I mean; yes, we might f*cked up the latest driver but hey if you pay, you might go back to a previous, maybe more stable version.

I am just disappointed in Oracle. I wish our company wouldn't have signed a contract with them

Regarding the old versions: I sent a PM to you Regarding Oracle being shit - well - I don't know anyone using Oracle. But then I don't have clients with huge databases Honestly we don't use any closed source database for any of our solutions anymore...

[aehimself]

Unfortunately the tests say things like:

Exception: [EZSQLException] SQL Error: OCI_INVALID_HANDLE
Code: -2 Message: OCIDescriptorFree

and

Exception: [EAccessViolation] Access violation at address 61F39BB3 in module 'OraClient11.Dll'. Read of address 00F338BC
at: $61F39BB3

So - I reverted your changes.

I saw those on Jenkins today. Strange, the logic shouldn't have changed for anything else calling .FreeOCIResources, plus it's working in my application... I'll have a second look.

You might want to use ZTestAll for testing your changes. I will have to write a wiki page regarding this...

Tbh it would be awesome to be able to run the test cases on my PC. It's useful to know if a checkin fixes one thing but breaks 10 other.

Regarding Oracle being shit - well - I don't know anyone using Oracle. But then I don't have clients with huge databases ;) Honestly we don't use any closed source database for any of our solutions anymore...

I attempted to steer the company towards a free, open source alternative a while ago. But then again, talking about a ~20 year old legacy application where people already got used to the limitations of Oracle... guess how much success I had.
This was my first interaction with Oracle and I dislike it will all my heart :)

[EgonHugeist]

Hope https://sourceforge.net/p/zeoslib/code-0/7076/ will resolve that issue?
Thanks for pointing this out again? The testcases do not benchmark stl...

[aehimself]

Yes, indeed!

951 uncached lobs now close in 0 ms, cached ones in 10 ms.

Thank you!