Slow execution of SQLAlchemy statements vs. plain text

303 views
Skip to first unread message

Sebastian Meinhardt

unread,
May 27, 2019, 12:05:48 PM5/27/19
to sqlalchemy
Hello,

given an SQLAlchemy engine `con` (cx_oracle dialect) and a moderately complex SQLAlchemy selectable object `sql`, the following code will consistently take ~15 seconds:

con.execute(sql).fetchall()

Whereas with the exact same engine and query the following code will only take a fraction of a second:

compiled = sql.compile(dialect=con.dialect)
statement = compiled.string
params = compiled.params
con.execute(statement, params).fetchall()

So, apparently something goes horribly wrong when executing an selectable. I assume that there is something wrong on my side as a general error in SQLAlchemy in this regard would probably have been noticed. However: How do I even debug this? In the end, I did trace the problem down to the `do_execute` function in engine.default:

    def do_execute(self, cursor, statement, parameters, context=None):
        cursor.execute(statement, parameters)

Both of my code examples visit this line of code with the exact same values for `statement` and `parameters`, though the way they get there is slightly different and so are the `cursor` and `context` objects. When I try to step further down in the debugger, the next frame would be `output_type_handler` in dialects.oracle.cx_oracle. However, the time is already lost before stepping into that function. That is, just entering this frame takes ~15 seconds in my first code but is near instantaneous in my second code.

I do not really know how to continue debugging from this point. Anybody have any advice or any ideas what might be going on here? The only difference that looks even remotely relevant to me at that point is that within the `context` we have a value for `context.compiled` for the first code and None for the second code. I tried setting it to None in the debugger but that had no effect on the execution speed. The cursors look both the same to me in both codes.

At this point I do not even know what else to look for and would appreciate any advice how to proceed. After not finding anything in the local context I would assume the problem is somewhere in some global state but without intimate knowledge of the inner working of SQLAlchemy I don't think I will be able to find the root cause.

Mike Bayer

unread,
May 27, 2019, 5:13:53 PM5/27/19
to sqlal...@googlegroups.com


On Mon, May 27, 2019, at 12:05 PM, Sebastian Meinhardt wrote:
Hello,

given an SQLAlchemy engine `con` (cx_oracle dialect) and a moderately complex SQLAlchemy selectable object `sql`, the following code will consistently take ~15 seconds:

con.execute(sql).fetchall()

Whereas with the exact same engine and query the following code will only take a fraction of a second:

compiled = sql.compile(dialect=con.dialect)
statement = compiled.string
params = compiled.params
con.execute(statement, params).fetchall()

a leading cause of this would be that the statement returns many rows and a large amount of time is spent in processing datatypes for each result row.  When you execute the string directly, the metadata about the datatypes present in your SELECT statement are lost and the raw cx_oracle result is returned.

the cx_oracle dialect has undergone many changes across recent releases in response to continued major changes in cx_oracle itself in recent months, so it's critical you share the exact version of cx_Oracle in use as well as that of SQLAlchemy.    There have been many performance sensitive behaviors changed and re-changed such as:





plenty of reasons for typing issues to act differently across releases and different cx_oracle versions.   Oracle has a pretty developer-unfriendly typing system and cx_Oracle's developer works very hard to allow it to be customizable, however this means it's very open ended and it's been quite difficult to get every edge working correctly without crushing performance problems.

So, apparently something goes horribly wrong when executing an selectable. I assume that there is something wrong on my side as a general error in SQLAlchemy in this regard would probably have been noticed. However: How do I even debug this? In the end, I did trace the problem down to the `do_execute` function in engine.default:

    def do_execute(self, cursor, statement, parameters, context=None):
        cursor.execute(statement, parameters)


use the recipe at https://docs.sqlalchemy.org/en/13/faq/performance.html#code-profiling, for a difference this noticeable it should be fairly straightforward to identify the codepath taking up the time spent in the slow version.





Both of my code examples visit this line of code with the exact same values for `statement` and `parameters`, though the way they get there is slightly different and so are the `cursor` and `context` objects. When I try to step further down in the debugger, the next frame would be `output_type_handler` in dialects.oracle.cx_oracle. However, the time is already lost before stepping into that function. That is, just entering this frame takes ~15 seconds in my first code but is near instantaneous in my second code.

I do not really know how to continue debugging from this point. Anybody have any advice or any ideas what might be going on here? The only difference that looks even remotely relevant to me at that point is that within the `context` we have a value for `context.compiled` for the first code and None for the second code. I tried setting it to None in the debugger but that had no effect on the execution speed. The cursors look both the same to me in both codes.

At this point I do not even know what else to look for and would appreciate any advice how to proceed. After not finding anything in the local context I would assume the problem is somewhere in some global state but without intimate knowledge of the inner working of SQLAlchemy I don't think I will be able to find the root cause.


--
SQLAlchemy -
The Python SQL Toolkit and Object Relational Mapper
 
 
To post example code, please provide an MCVE: Minimal, Complete, and Verifiable Example. See http://stackoverflow.com/help/mcve for a full description.
---
You received this message because you are subscribed to the Google Groups "sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+...@googlegroups.com.
To post to this group, send email to sqlal...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Sebastian Meinhardt

unread,
May 28, 2019, 5:29:19 AM5/28/19
to sqlalchemy
Thank you for the pointers! After digging into this some more, I found that this is definitely related to something in cartain versions of SQLAlchemy. I also tried different versions of cx_Oracle (6.4.1, 7.1.2, and 7.1.3) but that had no effect on the performance of the statement.

I did not try all possible combinations of SQLAlchemy and cx_Oracle but I tried to do a little bisection on the SQLAlchemy version while keeping cx_Oracle fixed at 7.1.3. What I found:
  • 1.3.0 and above: Fine!
  • 1.2.19: slow
  • 1.2.12: slow
  • 1.2.6: slow
  • 1.2.3: slow
  • 1.2.2: slow
  • 1.2.1: Fine
  • 1.2.0: Fine
  • 1.1,18: Fine
So, the culprint is SQLAlchemy 1.2.2 and 1.3.0 fixes whatever was wrong. While that solves my problem in an elegant way (I wanted to upgrade to 1.3+ anyway) I will still try to find the root cause by profiling my application the way you suggested. Maybe something can be learned from that to avoid future regressions. However, that will take some time. I will be back with the results, later!

Sebastian Meinhardt

unread,
May 28, 2019, 6:46:19 AM5/28/19
to sqlalchemy
The profiler results are in but they do not tell me anything that I did not already find by manually stepping through the code. See my first post, above. The method that takes all the time is `execute` of `cx_Oracle.Cursor` itself. I cannot step into that because that is some C-call.

I did however spend some time on discerning the differences between executing a plain text statement vs. a query object. The main difference appeared to be the `pre_exec` method in the cx_Oracle dialect that only gets called for query objects but not for plain text. And Heureka! It is the call to `self.set_input_sizes` (line 629 in cx_oracle.py in SQLAlchemy 1.2.19). While the call itself is inconspicuous, it causes the huge delay when calling `execute` on the cursor later down the line. If I delete this call, my code works fine for both, the plain text and the query object.

However, comparing this to SQLAlchemy 1.3.0 (the first version to not have the problem) does not really point me to a solution of the puzzle: Version 1.3.0 has the same call to `self.set_input_sizes` and it gets called with the same parameters. Thus, I am back to square 1: I know that setting the input sizes somehow screws up the cursor execution but this is not the root cause.I notice that fixes to `setinputsizes` show up several times in the links that you provided. Thus, I assume that I stumbled on one of those problems, though I cannot tell exactly which one of those.

Still, upgrading to 1.3.x solves my problem. Thanks for all the help!

Mike Bayer

unread,
May 28, 2019, 10:20:31 AM5/28/19
to sqlal...@googlegroups.com


On Tue, May 28, 2019, at 5:29 AM, Sebastian Meinhardt wrote:
Thank you for the pointers! After digging into this some more, I found that this is definitely related to something in cartain versions of SQLAlchemy. I also tried different versions of cx_Oracle (6.4.1, 7.1.2, and 7.1.3) but that had no effect on the performance of the statement.

I did not try all possible combinations of SQLAlchemy and cx_Oracle but I tried to do a little bisection on the SQLAlchemy version while keeping cx_Oracle fixed at 7.1.3. What I found:
  • 1.3.0 and above: Fine!
  • 1.2.19: slow
  • 1.2.12: slow
  • 1.2.6: slow
  • 1.2.3: slow
  • 1.2.2: slow
  • 1.2.1: Fine
  • 1.2.0: Fine
  • 1.1,18: Fine

yes so that is definitely this change:


and the issue that probably fixed it is https://docs.sqlalchemy.org/en/13/changelog/changelog_13.html#change-54fc6a60b98ea236b117f1a22bb56ac7  where the issue reported had to do with inserts but it ended up being a total rewrite (by no means the first) of how the cx_Oracle dialect handles string values.   The performance-related change there is that it no longer uses cx_Oracle DBAPI's unicode conversion procedures and instead uses the very performant ones that come with SQLAlchemy.  Python has a huge performance gotcha in the area of unicode coercion that has to do with how you invoke the decoding codec, PyMySQL was also affected by this for a long time.




So, the culprint is SQLAlchemy 1.2.2 and 1.3.0 fixes whatever was wrong. While that solves my problem in an elegant way (I wanted to upgrade to 1.3+ anyway) I will still try to find the root cause by profiling my application the way you suggested. Maybe something can be learned from that to avoid future regressions. However, that will take some time. I will be back with the results, later!


--
SQLAlchemy -
The Python SQL Toolkit and Object Relational Mapper
 
 
To post example code, please provide an MCVE: Minimal, Complete, and Verifiable Example. See http://stackoverflow.com/help/mcve for a full description.
---
You received this message because you are subscribed to the Google Groups "sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+...@googlegroups.com.
To post to this group, send email to sqlal...@googlegroups.com.

Mike Bayer

unread,
May 28, 2019, 10:21:20 AM5/28/19
to sqlal...@googlegroups.com

Still, upgrading to 1.3.x solves my problem. Thanks for all the help!


--
SQLAlchemy -
The Python SQL Toolkit and Object Relational Mapper
 
 
To post example code, please provide an MCVE: Minimal, Complete, and Verifiable Example. See http://stackoverflow.com/help/mcve for a full description.
---
You received this message because you are subscribed to the Google Groups "sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+...@googlegroups.com.
To post to this group, send email to sqlal...@googlegroups.com.
Reply all
Reply to author
Forward
0 new messages