Reading large chunk of data from cursor returned from a stored procedure is extremely slow

[smsteel]

1. What versions are you using?
   Oracle Database 11.2.0.4
   platform.platform: Linux-3.10.0-1127.el7.x86_64-x86_64-with-centos-7.8.2003-Core
   sys.maxsize > 2**32: True
   platform.python_version: 3.6.10
   cx_Oracle.version: 8.0.1
   cx_Oracle.clientversion: (12, 2, 0, 1, 0)

2. Describe the problem

We have a stored procedure with OUT parameter REF CURSOR. When we had aroud ~1k records returned performance was good enough. Now it goes beyond 140 seconds with 50k.

While executing the same procedure and parameters, reading cursor from PL/SQL Developer IDE is very fast, so query is not the problem.

3. Include a runnable Python script that shows the problem.

import cx_Oracle

dsn = cx_Oracle.makedsn('ip', 1521, 'db')
pool = cx_Oracle.SessionPool(
  user='...',
  password='...',
  dsn=dsn,
  min=1,
  max=10,
  increment=1,
  threaded=True,
  encoding="UTF-8"
)
connection = pool.acquire(purity=cx_Oracle.ATTR_PURITY_NEW)
cursor = connection.cursor()

data = cursor.var(cx_Oracle.CURSOR)

cursor.callproc('proc_name, [
  # couple of in params here
  data
])
data_cursor = data.getvalue()
rows = data_cursor.fetchmany()
while rows:
  for records in data_cursor:
    print(records)
  rows = data_cursor.fetchmany()

So what's strange code execution stops on first data_cursor.fetchmany() and most of the time (like 130s of 140s) is running first fetchmany(), then it reads very fast and continuing calls of fetchmany() goes fast as well.

[anthony-tuininga]

Can you provide a test case that we can run independently that demonstrates the problem?

You can try a few different combinations to see if configuration is the issue:

• try with a standalone connection instead of a pool
• try with a newer version of the Oracle Client libraires (19)

You can also examine the output from setting the environment variable DPI_DEBUG_LEVEL to the value 4. This will tell you where the time is being taken. If it is happening in dpiStmt_fetchRows() as you suspect, then you'll want to examine server side reports to find out where the time is being taken on the server.

[cjbj]

Don't forget to tune the data fetch buffer sizes: https://cx-oracle.readthedocs.io/en/latest/user_guide/tuning.html#tuning-fetch-performance

[Exzentttt]

In my case the problem is in the function that runs too long.
Check dpiStmt_fetchRows(), how do u test your functions in PL/SQL Developer?
My result in PL/SQL Developer matches the result of the work cx_Oracle

[smsteel]

So, yes, execution halts at dpiStmt_fetchRows for ~139s, while reading actually finishes really fast:

2020-10-10T11:13:15.152015174Z ODPI [00006] 2020-10-10 11:13:15.151: fn end dpiStmt_define(0x55dc6a20eab0) -> 0
2020-10-10T11:13:15.152022588Z ODPI [00006] 2020-10-10 11:13:15.151: fn start dpiStmt_fetchRows(0x55dc6a20eab0)
2020-10-10T11:15:33.891814960Z ODPI [00006] 2020-10-10 11:15:33.891: fn end dpiStmt_fetchRows(0x55dc6a20eab0) -> 0
# Here goes fast execution of dpiStmt_fetchRows in while loop
2020-10-10T11:15:35.077119308Z ODPI [00006] 2020-10-10 11:15:35.076: fn start dpiStmt_fetchRows(0x55dc6a20eab0)
2020-10-10T11:15:35.084529279Z ODPI [00006] 2020-10-10 11:15:35.084: fn end dpiStmt_fetchRows(0x55dc6a20eab0) -> 0
2020-10-10T11:15:35.085436501Z success main 140.202s.
2020-10-10T11:15:35.085567638Z ODPI [00006] 2020-10-10 11:15:35.084: fn start dpiPool_release(0x55dc6a15e860)
2020-10-10T11:15:35.085585706Z ODPI [00006] 2020-10-10 11:15:35.084: fn end dpiPool_release(0x55dc6a15e860) -> 0
2020-10-10T11:15:35.085595603Z ODPI [00006] 2020-10-10 11:15:35.084: fn start dpiVar_release(0x55dc6a217070)
# Session closing

PL/SQL Developer getting that cursor for 20s, but we finally got 140s from there as well - so the problem is inside that procedure, in SQL query returning into REF CURSOR, and not in cx_Oracle.
My best guess it builds different plan for some reason.

On a side note, maybe it will be useful to add DPI_DEBUG_LEVEL to Tuning cx_Oracle documentation explaining how you can check where your code is slow.

[smsteel]

Don't forget to tune the data fetch buffer sizes: https://cx-oracle.readthedocs.io/en/latest/user_guide/tuning.html#tuning-fetch-performance

By the way, setting arraysize on cursor returning from procudure does nothing.

data = cursor.var(cx_Oracle.CURSOR)
cursor.callproc('test_procedure', [data])
data_cursor = data.getvalue()
data_cursor.arraysize = 500
data_cursor.fetchmany(500)

That code will throw a cx_Oracle.InterfaceError: rows to fetch exceeds array size. Setting arraysize on a cursor that is used to call a procedure does not matter as well.

[cjbj]

I didn't get an error with your sample. Can you recheck?

cursor = connection.cursor()
cursor.execute("""
               create or replace procedure myrefcursorproc (
                   rc out sys_refcursor
               ) as
               begin
                   --open rc for select last_name from employees;
                   open rc for select * from all_objects;
               end;
               """)

# Tuned fetch
refCursor = connection.cursor()
# refCursor.prefetchrows = 10000  # setting this has no effect in cx_Oracle 8.0
cursor.callproc("myrefcursorproc", [refCursor])
start = time.time()
refCursor.arraysize = 10000
r = refCursor.fetchall()
elapsed = time.time() - start
print("Time:", elapsed, "seconds")

# The variant syntax works for me
data = cursor.var(cx_Oracle.CURSOR)
cursor.callproc("myrefcursorproc", [data])
data_cursor = data.getvalue()
data_cursor.arraysize = 10000
start = time.time()
r = data_cursor.fetchall()
elapsed = time.time() - start
print("Time:", elapsed, "seconds")

# Default internal buffer values will be slower for large numbers of rows
refCursor = connection.cursor()
# refCursor.prefetchrows = 2 # default value.  Setting is ignored in cx_Oracle 8.0
cursor.callproc("myrefcursorproc", [refCursor])
start = time.time()
refCursor.arraysize = 100  # default value
r = refCursor.fetchall()
elapsed = time.time() - start
print("Time:", elapsed, "seconds")

Output using my very remote DB is like:

$ python rc.py
Time: 1.944246768951416 seconds
Time: 1.97428560256958 seconds
Time: 27.41403889656067 seconds

I've noted that the RefCursor.py sample should show how to set the prefetch & array sizes. I also have noted the earlier comment about Tuning doc and tracing.

[I updated the code regarding prefetching based on later comments]

[cjbj]

On reflection,I suspect refCursor.prefetchrows really needs to be set before calling the PL/SQL procedure. @anthony-tuininga will be able to confirm, if I (or you) don't get around to testing it.

[anthony-tuininga]

Yes, refCursor.prefetchrows would need to be set before calling the PL/SQL procedure since the ref cursor is executed on the server. Currently, however, I believe that the value would be ignored anyway and the default value used. We'll investigate and get back to you on this.

[smsteel]

I didn't get an error with your sample. Can you recheck?

I get error with fetchmany setting parameter to 500

[anthony-tuininga]

We have confirmed that refCursor.prefetchRows is being ignored and have a patch that resolves this that is being tested. Hopefully this will resolve your issue for you!

[smsteel]

Are you sure this fixes the problem? Reading code in the commit fixing the issue i see only this exception raised: cxoError_raiseAndReturnInt. Does the value in refCursor.prefetchrows actually being used to fetch right amount of rows?

[anthony-tuininga]

Yes, it does. There is a test case that demonstrates that as well. Give it a whirl and confirm for yourself!

[anthony-tuininga]

Assuming this has been resolved since it was included in cx_Oracle 8.1 released in December 2020!

[smsteel]

Yes, the issue was resolved. Didn't see dpiStmt_setPrefetchRows first time for some reason. :)