Query parameter binding time increases exponentially with bind variable count #567

GertBurger · 2021-06-02T13:25:17Z

What versions are you using?

platform.platform: Linux-5.4.0-73-generic-x86_64-with-debian-buster-sid
sys.maxsize > 2**32: True
platform.python_version: 3.7.8
cx_Oracle.version: 7.3.0
cx_Oracle.clientversion: (19, 11, 0, 0, 0)  # Version 12.x was the same

Describe the problem
As the number bind variables increase, the more time is spent in libclntsh.so prior to the query being sent to the server. The relationship between number of bind variables and time taken is super linear and gets pretty slow.

On my machine a query with 60k parameters take close to 20secs, the same query via postgresql/psycopg2 takes 400msec.

Is this an oracle client issue? Am I doing something wrong? Is cx_Oracle doing something wrong?

So far I have only tested this with selects and only as part of IN conditions.

In [52]: run(1000)
CPU times: user 16.5 ms, sys: 8.03 ms, total: 24.6 ms
Wall time: 24.1 ms

In [53]: run(10000)
CPU times: user 491 ms, sys: 0 ns, total: 491 ms
Wall time: 492 ms

In [54]: run(20000)
CPU times: user 2.2 s, sys: 0 ns, total: 2.2 s
Wall time: 2.2 s

In [55]: run(30000)
CPU times: user 4.98 s, sys: 0 ns, total: 4.98 s
Wall time: 4.99 s

In [56]: run(40000)
CPU times: user 8.95 s, sys: 0 ns, total: 8.95 s
Wall time: 8.95 s

In [57]: run(50000)
CPU times: user 14.1 s, sys: 0 ns, total: 14.1 s
Wall time: 14.1 s

In [58]: run(60000)
CPU times: user 19.7 s, sys: 2.71 ms, total: 19.7 s
Wall time: 19.7 s

Profile:

Include a runnable Python script that shows the problem.

Needs ipython for %time and a preexisting cursor instance. You also need to provide a table name at YOUR_TABLE. Any table with an ID column will work, preferably an empty table.

def run(limit):
     bind_values = list(range(limit))
     bind_names = [":" + str(i + 1) for i in range(len(bind_values))]
     conditions = []
     for offset in range(0, limit, 1000):
         conditions.append(f"ID in ({','.join(bind_names[offset:offset+1000])})")
     sql = f"select 1 from YOUR_TABLE where " + " or ".join(conditions)
     %time list(cursor.execute(sql, bind_values))

The text was updated successfully, but these errors were encountered:

cjbj · 2021-06-08T02:10:07Z

Did you dig into any DPI tracing to see whether the time is spent in Oracle Client code or the DB? Did you try the same statement using hard coded values, to see if it's the DB that is taking time, and whether some indexing etc would help?

In general, if you're using 60K parameters I wonder if there aren't better solutions, such as loading into a global temp table, as mentioned in the doc - this suggestion originated from a (now) old Tom Kyte article.

GertBurger · 2021-06-08T08:36:03Z

Thanks for the ideas Christopher, they were useful in understanding some of the complexity of this.

My findings are:

Getting repeatable results from tests is hard due to various caches. :P Is connection.stmtcache=0 on client and client_result_cache_size=0 on server sufficient?
DPI_DEBUG_LEVEL gives some insight, see log further down.
Hard coded query with 65k IN values results in >95% of time being spent in server. i.e. client side cpu time is minimal.
With 65k bind vars the ratio of client vs server cpu time ranges from 50:50 to 70:30, i.e. 70% client side vs 30% server side. There seems to be some more caching affecting the timings here.
CPU time spent client side for 10k bind vars vs 65k bind vars increase +-7x above linear level. i.e. 65k bind var query has 6.5x more variables but takes +-50x as long to process client side.

So are the only options?:

Don't use bind vars when there would be a lot. Query generation can be tricky then.
Use less bind vars per query and more queries. There should be sweet spot between number of vars vs number of queries for a certain network latency.
Somehow using a subquery to generate the where conditions. This would be hard to generalize across an app...

Anything else?

DPI_DEBUG_LEVEL=31, 65k bind variables and querying a table that doesn't exist:

ODPI [30232] 2021-06-08 18:26:23.244: fn start dpiVar_release(0x556e6caa5140)
ODPI [30232] 2021-06-08 18:26:23.244: ref 0x556e6caa5140 (dpiVar) -> 1
ODPI [30232] 2021-06-08 18:26:23.244: fn end dpiVar_release(0x556e6caa5140) -> 0
ODPI [30232] 2021-06-08 18:26:23.244: fn start dpiVar_release(0x556e6caa4f20)
ODPI [30232] 2021-06-08 18:26:23.244: ref 0x556e6caa4f20 (dpiVar) -> 1
ODPI [30232] 2021-06-08 18:26:23.244: fn end dpiVar_release(0x556e6caa4f20) -> 0
.
.
.
ODPI [30232] 2021-06-08 18:26:24.229: fn start dpiStmt_release(0x556e68157d60)
ODPI [30232] 2021-06-08 18:26:24.229: ref 0x556e68157d60 (dpiStmt) -> 0
ODPI [30232] 2021-06-08 18:26:24.229: ref 0x556e681ecd90 (dpiVar) -> 0
ODPI [30232] 2021-06-08 18:26:24.229: ref 0x556e67962530 (dpiConn) -> 65002
ODPI [30232] 2021-06-08 18:26:24.229: ref 0x556e681cd2a0 (dpiVar) -> 0
ODPI [30232] 2021-06-08 18:26:24.288: ref 0x556e6b1b5720 (dpiVar) -> 0
ODPI [30232] 2021-06-08 18:26:24.288: ref 0x556e67962530 (dpiConn) -> 62112
ODPI [30232] 2021-06-08 18:26:24.288: ref 0x556e6b1b5940 (dpiVar) -> 0
.
.
.
ODPI [30232] 2021-06-08 18:26:25.057: ref 0x556e67962530 (dpiConn) -> 2
ODPI [30232] 2021-06-08 18:26:25.057: ref 0x556e67962530 (dpiConn) -> 1
ODPI [30232] 2021-06-08 18:26:25.057: fn end dpiStmt_release(0x556e68157d60) -> 0

ODPI [30232] 2021-06-08 18:26:25.057: fn start dpiConn_prepareStmt(0x556e67962530)
ODPI [30232] 2021-06-08 18:26:25.057: ref 0x556e68704710 (dpiStmt) -> 1 [NEW]
ODPI [30232] 2021-06-08 18:26:25.057: ref 0x556e67962530 (dpiConn) -> 2
ODPI [30232] 2021-06-08 18:26:25.057: SQL select 1 from asdfasdfasdf where id in (:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16,:17,:18,:19,:20,:21,:22,.....
ODPI [30232] 2021-06-08 18:26:49.981: fn end dpiConn_prepareStmt(0x556e67962530) -> 0

ODPI [30232] 2021-06-08 18:26:49.981: fn start dpiStmt_getInfo(0x556e68704710)
ODPI [30232] 2021-06-08 18:26:49.981: fn end dpiStmt_getInfo(0x556e68704710) -> 0
ODPI [30232] 2021-06-08 18:26:49.981: fn start dpiStmt_setFetchArraySize(0x556e68704710)
ODPI [30232] 2021-06-08 18:26:49.981: fn end dpiStmt_setFetchArraySize(0x556e68704710) -> 0
ODPI [30232] 2021-06-08 18:26:49.981: fn start dpiConn_newVar(0x556e67962530)
ODPI [30232] 2021-06-08 18:26:49.981: ref 0x556e67cf88d0 (dpiVar) -> 1 [NEW]
ODPI [30232] 2021-06-08 18:26:49.981: ref 0x556e67962530 (dpiConn) -> 3
ODPI [30232] 2021-06-08 18:26:49.981: fn end dpiConn_newVar(0x556e67962530) -> 0
ODPI [30232] 2021-06-08 18:26:49.981: fn start dpiVar_getSizeInBytes(0x556e67cf88d0)
ODPI [30232] 2021-06-08 18:26:49.981: fn end dpiVar_getSizeInBytes(0x556e67cf88d0) -> 0
ODPI [30232] 2021-06-08 18:26:49.981: fn start dpiVar_setFromBytes(0x556e67cf88d0)
ODPI [30232] 2021-06-08 18:26:49.981: fn end dpiVar_setFromBytes(0x556e67cf88d0) -> 0
.
.
.
ODPI [30232] 2021-06-08 18:26:53.462: fn start dpiConn_newVar(0x556e67962530)
ODPI [30232] 2021-06-08 18:26:53.462: ref 0x556e6fb0d000 (dpiVar) -> 1 [NEW]
ODPI [30232] 2021-06-08 18:26:53.462: ref 0x556e67962530 (dpiConn) -> 65002
ODPI [30232] 2021-06-08 18:26:53.462: fn end dpiConn_newVar(0x556e67962530) -> 0
ODPI [30232] 2021-06-08 18:26:53.462: fn start dpiVar_getSizeInBytes(0x556e6fb0d000)
ODPI [30232] 2021-06-08 18:26:53.462: fn end dpiVar_getSizeInBytes(0x556e6fb0d000) -> 0
ODPI [30232] 2021-06-08 18:26:53.462: fn start dpiVar_setFromBytes(0x556e6fb0d000)
ODPI [30232] 2021-06-08 18:26:53.462: fn end dpiVar_setFromBytes(0x556e6fb0d000) -> 0

ODPI [30232] 2021-06-08 18:26:53.462: fn start dpiStmt_bindByPos(0x556e68704710)
ODPI [30232] 2021-06-08 18:26:53.462: ref 0x556e67cf88d0 (dpiVar) -> 2
ODPI [30232] 2021-06-08 18:26:53.462: fn end dpiStmt_bindByPos(0x556e68704710) -> 0
.
.
.
ODPI [30232] 2021-06-08 18:27:17.051: fn start dpiStmt_bindByPos(0x556e68704710)
ODPI [30232] 2021-06-08 18:27:17.052: ref 0x556e6fb0d000 (dpiVar) -> 2
ODPI [30232] 2021-06-08 18:27:17.052: fn end dpiStmt_bindByPos(0x556e68704710) -> 0

ODPI [30232] 2021-06-08 18:27:17.052: fn start dpiStmt_execute(0x556e68704710)
ODPI [30232] 2021-06-08 18:27:40.766: OCI error ORA-00942: table or view does not exist (dpiStmt_execute / execute)
ODPI [30232] 2021-06-08 18:27:40.766: fn end dpiStmt_execute(0x556e68704710) -> -1
---------------------------------------------------------------------------
DatabaseError                             Traceback (most recent call last)
<timed eval> in <module>

DatabaseError: ORA-00942: table or view does not exist

In [10]:

Ignoring the part after the query is sent, time spent client side is split somewhat evenly between dpiConn_prepareStmt and dpiStmt_bindByPos stage.

cjbj · 2021-06-11T11:57:11Z

Thanks for the detail, which we'll mull over. I wonder if this is memory allocations?

How much control do you have over the data? Unless you are repeating the query with exactly the same number of parameters, you are not going to get benefits from the statement cache or cursor reuse. You will get some security benefits, but if you have control over the data, perhaps you can filter it safely and build up the statement by concatenation.

I wonder if some kind of analytic query is what you really need, but that isn't my area.

anthony-tuininga · 2021-06-19T20:39:03Z

I did some analysis of this and discovered that the Oracle Client libraries are the source of the slowdowns involved. @cjbj will follow up after we discuss this further internally.

cjbj · 2021-06-21T06:17:12Z

I created an Oracle bug / enhancement request 33023288 to track this.

stale · 2021-07-21T07:52:34Z

This issue has been automatically marked as inactive because it has not been updated recently. It will be closed if no further activity occurs. Thank you for your contributions.

stale · 2021-07-28T09:26:07Z

This issue has been automatically closed because it has not been updated for a month.

GertBurger · 2021-11-05T04:57:50Z

Has there been any movement on that request?

cjbj · 2021-11-05T05:44:22Z

@GertBurger no!

cjbj · 2021-11-05T05:48:49Z

@GertBurger You mentioned the IN clause case before. Check the newish example in Binding Multiple Values to a SQL WHERE IN Clause. This will give you just one bind variable for a large number of values:

SQL> CREATE OR REPLACE TYPE name_array AS TABLE OF VARCHAR2(25);
  2  /

then the application could do:

type_obj = connection.gettype("NAME_ARRAY")
obj = type_obj.newobject()
obj.extend(["Smith", "Taylor"])
cursor.execute("""select employee_id, first_name, last_name
                  from employees
                  where last_name in (select * from table(:1))""",
                  [obj])
for row in cursor:
    print(row)

cjbj · 2021-11-05T06:38:24Z

LOL. I've updated my earlier comment with an example in the correct programming language.

GertBurger added the question label Jun 2, 2021

stale bot added the inactive label Jul 21, 2021

stale bot closed this as completed Jul 28, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Query parameter binding time increases exponentially with bind variable count #567

Query parameter binding time increases exponentially with bind variable count #567

GertBurger commented Jun 2, 2021

cjbj commented Jun 8, 2021

Uh oh!

GertBurger commented Jun 8, 2021

Uh oh!

cjbj commented Jun 11, 2021

Uh oh!

anthony-tuininga commented Jun 19, 2021

Uh oh!

cjbj commented Jun 21, 2021

Uh oh!

stale bot commented Jul 21, 2021

Uh oh!

stale bot commented Jul 28, 2021

Uh oh!

GertBurger commented Nov 5, 2021

Uh oh!

cjbj commented Nov 5, 2021

Uh oh!

cjbj commented Nov 5, 2021 •

edited

Loading

Uh oh!

cjbj commented Nov 5, 2021

Uh oh!

Query parameter binding time increases exponentially with bind variable count #567

Query parameter binding time increases exponentially with bind variable count #567

Comments

GertBurger commented Jun 2, 2021

cjbj commented Jun 8, 2021

Uh oh!

GertBurger commented Jun 8, 2021

Uh oh!

cjbj commented Jun 11, 2021

Uh oh!

anthony-tuininga commented Jun 19, 2021

Uh oh!

cjbj commented Jun 21, 2021

Uh oh!

stale bot commented Jul 21, 2021

Uh oh!

stale bot commented Jul 28, 2021

Uh oh!

GertBurger commented Nov 5, 2021

Uh oh!

cjbj commented Nov 5, 2021

Uh oh!

cjbj commented Nov 5, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cjbj commented Nov 5, 2021

Uh oh!

cjbj commented Nov 5, 2021 •

edited

Loading