Performance

    The caching system allows SQLAlchemy 1.4 and above to be more performant than SQLAlchemy 1.3 with regards to the time spent converting SQL constructs into strings repeatedly. However, this only works if caching is enabled for the dialect and SQL constructs in use; if not, string compilation is usually similar to that of SQLAlchemy 1.3, with a slight decrease in speed in some cases.

    There is one case however where if SQLAlchemy’s new caching system has been disabled (for reasons below), performance for the ORM may be in fact significantly poorer than that of 1.3 or other prior releases which is due to the lack of caching within ORM lazy loaders and object refresh queries, which in the 1.3 and earlier releases used the now-legacy system. If an application is seeing significant (30% or higher) degradations in performance (measured in time for operations to complete) when switching to 1.4, this is the likely cause of the issue, with steps to mitigate below.

    See also

    - overview of the caching system

    Object will not produce a cache key, Performance Implications - additional information regarding the warnings generated for elements that don’t enable caching.

    Here, we want to use the technique described at engine logging, looking for statements with the [no key] indicator or even [dialect does not support caching]. The indicators we would see for SQL statements that are successfully participating in the caching system would be indicating [generated in Xs] when statements are invoked for the first time and then [cached since Xs ago] for the vast majority of statements subsequent. If [no key] is prevalent in particular for SELECT statements, or if caching is disabled entirely due to [dialect does not support caching], this can be the cause of significant performance degradation.

    See also

    Step two - identify what constructs are blocking caching from being enabled

    Assuming statements are not being cached, there should be warnings emitted early in the application’s log (SQLAlchemy 1.4.28 and above only) indicating dialects, objects, and SQL constructs that are not participating in caching.

    For user defined datatypes such as those which extend TypeDecorator and , the warnings will look like:

    For custom and third party SQL elements, such as those constructed using the techniques described at Custom SQL Constructs and Compilation Extension, these warnings will look like:

    1. sqlalchemy.exc.SAWarning: Class MyClass will not make use of SQL
    2. compilation caching as it does not set the 'inherit_cache' attribute to
    3. ``True``. This can have significant performance implications including some
    4. performance degradations in comparison to prior SQLAlchemy versions. Set
    5. this attribute to True if this object can make use of the cache key
    6. generated by the superclass. Alternatively, this attribute may be set to
    7. False which will disable this warning.

    For custom and third party dialects which make use of the class hierarchy, the warnings will look like:

    1. sqlalchemy.exc.SAWarning: Dialect database:driver will not make use of SQL
    2. compilation caching as it does not set the 'supports_statement_cache'
    3. attribute to ``True``. This can have significant performance implications
    4. including some performance degradations in comparison to prior SQLAlchemy
    5. versions. Dialect maintainers should seek to set this attribute to True
    6. after appropriate development and testing for SQLAlchemy 1.4 caching
    7. support. Alternatively, this attribute may be set to False which will
    8. disable this warning.

    Steps to mitigate the lack of caching include:

    • Review and set to True for all custom types which extend from TypeDecorator, , as well as subclasses of these such as PickleType. Set this only if the custom type does not include any additional state attributes which affect how it renders SQL:

      1. class MyCustomType(TypeDecorator):
      2. cache_ok = True
      3. impl = String

      If the types in use are from a third-party library, consult with the maintainers of that library so that it may be adjusted and released.

      See also

      - background on requirements to enable caching for custom datatypes.

    • Make sure third party dialects set Dialect.supports_statement_cache to True. What this indicates is that the maintainers of a third party dialect have made sure their dialect works with SQLAlchemy 1.4 or greater, and that their dialect doesn’t include any compilation features which may get in the way of caching. As there are some common compilation patterns which can in fact interfere with caching, it’s important that dialect maintainers check and test this carefully, adjusting for any of the legacy patterns which won’t work with caching.

      See also

    • Custom SQL classes, including all DQL / DML constructs one might create using the , as well as ad-hoc subclasses of objects such as Column or . The HasCacheKey.inherit_cache attribute may be set to True for trivial subclasses, which do not contain any subclass-specific state information which affects the SQL compilation.

      See also

      - guidelines for applying the HasCacheKey.inherit_cache attribute.

    See also

    - caching system overview

    Object will not produce a cache key, Performance Implications - background on warnings emitted when caching is not enabled for specific constructs and/or dialects.

    Looking for performance issues typically involves two strategies. One is query profiling, and the other is code profiling.

    Query Profiling

    Sometimes just plain SQL logging (enabled via python’s logging module or via the echo=True argument on ) can give an idea how long things are taking. For example, if you log something right after a SQL operation, you’d see something like this in your log:

    1. 17:37:48,325 INFO [sqlalchemy.engine.base.Engine.0x...048c] SELECT ...
    2. 17:37:48,326 INFO [sqlalchemy.engine.base.Engine.0x...048c] {<params>}

    if you logged myapp.somemessage right after the operation, you know it took 334ms to complete the SQL part of things.

    Logging SQL will also illustrate if dozens/hundreds of queries are being issued which could be better organized into much fewer queries. When using the SQLAlchemy ORM, the “eager loading” feature is provided to partially (contains_eager()) or fully (, subqueryload()) automate this activity, but without the ORM “eager loading” typically means to use joins so that results across multiple tables can be loaded in one result set instead of multiplying numbers of queries as more depth is added (i.e. r + r*r2 + r*r2*r3 …)

    For more long-term profiling of queries, or to implement an application-side “slow query” monitor, events can be used to intercept cursor executions, using a recipe like the following:

    1. from sqlalchemy import event
    2. from sqlalchemy.engine import Engine
    3. import time
    4. import logging
    5. logging.basicConfig()
    6. logger = logging.getLogger("myapp.sqltime")
    7. logger.setLevel(logging.DEBUG)
    8. @event.listens_for(Engine, "before_cursor_execute")
    9. def before_cursor_execute(conn, cursor, statement, parameters, context, executemany):
    10. conn.info.setdefault("query_start_time", []).append(time.time())
    11. logger.debug("Start Query: %s", statement)
    12. @event.listens_for(Engine, "after_cursor_execute")
    13. def after_cursor_execute(conn, cursor, statement, parameters, context, executemany):
    14. total = time.time() - conn.info["query_start_time"].pop(-1)
    15. logger.debug("Query Complete!")
    16. logger.debug("Total Time: %f", total)

    Above, we use the and ConnectionEvents.after_cursor_execute() events to establish an interception point around when a statement is executed. We attach a timer onto the connection using the info dictionary; we use a stack here for the occasional case where the cursor execute events may be nested.

    If logging reveals that individual queries are taking too long, you’d need a breakdown of how much time was spent within the database processing the query, sending results over the network, being handled by the DBAPI, and finally being received by SQLAlchemy’s result set and/or ORM layer. Each of these stages can present their own individual bottlenecks, depending on specifics.

    For that you need to use the . Below is a simple recipe which works profiling into a context manager:

    To profile a section of code:

    1. with profiled():
    2. session.scalars(select(FooClass).where(FooClass.somevalue == 8)).all()

    The output of profiling can be used to give an idea where time is being spent. A section of profiling output looks like this:

    1. 13726 function calls (13042 primitive calls) in 0.014 seconds
    2. Ordered by: cumulative time
    3. ncalls tottime percall cumtime percall filename:lineno(function)
    4. 222/21 0.001 0.000 0.011 0.001 lib/sqlalchemy/orm/loading.py:26(instances)
    5. 220/20 0.002 0.000 0.010 0.001 lib/sqlalchemy/orm/loading.py:327(_instance)
    6. 220/20 0.000 0.000 0.010 0.000 lib/sqlalchemy/orm/loading.py:284(populate_state)
    7. 20 0.000 0.000 0.010 0.000 lib/sqlalchemy/orm/strategies.py:987(load_collection_from_subq)
    8. 20 0.000 0.000 0.009 0.000 lib/sqlalchemy/orm/strategies.py:935(get)
    9. 1 0.000 0.000 0.009 0.009 lib/sqlalchemy/orm/strategies.py:940(_load)
    10. 2 0.000 0.000 0.004 0.002 lib/sqlalchemy/orm/query.py:2400(__iter__)
    11. 2 0.000 0.000 0.002 0.001 lib/sqlalchemy/orm/query.py:2414(_execute_and_instances)
    12. 2 0.000 0.000 0.002 0.001 lib/sqlalchemy/engine/base.py:659(execute)
    13. 2 0.000 0.000 0.002 0.001 lib/sqlalchemy/sql/elements.py:321(_execute_on_connection)
    14. 2 0.000 0.000 0.002 0.001 lib/sqlalchemy/engine/base.py:788(_execute_clauseelement)

    Above, we can see that the instances() SQLAlchemy function was called 222 times (recursively, and 21 times from the outside), taking a total of .011 seconds for all calls combined.

    Execution Slowness

    The specifics of these calls can tell us where the time is being spent. If for example, you see time being spent within cursor.execute(), e.g. against the DBAPI:

    1. 2 0.102 0.102 0.204 0.102 {method 'execute' of 'sqlite3.Cursor' objects}

    this would indicate that the database is taking a long time to start returning results, and it means your query should be optimized, either by adding indexes or restructuring the query and/or underlying schema. For that task, analysis of the query plan is warranted, using a system such as EXPLAIN, SHOW PLAN, etc. as is provided by the database backend.

    An inordinately large number of rows would be indicated by a very slow call to fetchall() at the DBAPI level:

    1. 2 0.300 0.600 0.300 0.600 {method 'fetchall' of 'sqlite3.Cursor' objects}

    An unexpectedly large number of rows, even if the ultimate result doesn’t seem to have many rows, can be the result of a cartesian product - when multiple sets of rows are combined together without appropriately joining the tables together. It’s often easy to produce this behavior with SQLAlchemy Core or ORM query if the wrong Column objects are used in a complex query, pulling in additional FROM clauses that are unexpected.

    On the other hand, a fast call to fetchall() at the DBAPI level, but then slowness when SQLAlchemy’s is asked to do a fetchall(), may indicate slowness in processing of datatypes, such as unicode conversions and similar:

    1. # the DBAPI cursor is fast...
    2. 2 0.020 0.040 0.020 0.040 {method 'fetchall' of 'sqlite3.Cursor' objects}
    3. ...
    4. # but SQLAlchemy's result proxy is slow, this is type-level processing
    5. 2 0.100 0.200 0.100 0.200 lib/sqlalchemy/engine/result.py:778(fetchall)

    In some cases, a backend might be doing type-level processing that isn’t needed. More specifically, seeing calls within the type API that are slow are better indicators - below is what it looks like when we use a type like this:

    the profiling output of this intentionally slow operation can be seen like this:

    1. 200 0.001 0.000 0.237 0.001 lib/sqlalchemy/sql/type_api.py:911(process)
    2. 200 0.001 0.000 0.236 0.001 test.py:28(process_result_value)
    3. 200 0.235 0.001 0.235 0.001 {time.sleep}

    that is, we see many expensive calls within the type_api system, and the actual time consuming thing is the time.sleep() call.

    Make sure to check the Dialect documentation for notes on known performance tuning suggestions at this level, especially for databases like Oracle. There may be systems related to ensuring numeric accuracy or string processing that may not be needed in all cases.

    There also may be even more low-level points at which row-fetching performance is suffering; for example, if time spent seems to focus on a call like socket.receive(), that could indicate that everything is fast except for the actual network connection, and too much time is spent with data moving over the network.

    Result Fetching Slowness - ORM

    To detect slowness in ORM fetching of rows (which is the most common area of performance concern), calls like populate_state() and _instance() will illustrate individual ORM object populations:

    1. # the ORM calls _instance for each ORM-loaded row it sees, and
    2. # populate_state for each ORM-loaded row that results in the population
    3. # of an object's attributes
    4. 220/20 0.001 0.000 0.010 0.000 lib/sqlalchemy/orm/loading.py:327(_instance)
    5. 220/20 0.000 0.000 0.009 0.000 lib/sqlalchemy/orm/loading.py:284(populate_state)

    The ORM’s slowness in turning rows into ORM-mapped objects is a product of the complexity of this operation combined with the overhead of cPython. Common strategies to mitigate this include:

    • fetch individual columns instead of full entities, that is:

      1. select(User.id, User.name)

      instead of:

      1. select(User)
    • Use Bundle objects to organize column-based results:

      1. u_b = Bundle("user", User.id, User.name)
      2. a_b = Bundle("address", Address.id, Address.email)
      3. for user, address in session.execute(select(u_b, a_b).join(User.addresses)):
      4. ...
    • Use result caching - see for an in-depth example of this.

    The output of a profile can be a little daunting but after some practice they are very easy to read.

    See also

    Performance - a suite of performance demonstrations with bundled profiling capabilities.

    The nature of ORM inserts has changed, as most included drivers use RETURNING with insertmanyvalues support as of SQLAlchemy 2.0. See the section for details.

    Third party drivers can opt in to the new bulk infrastructure as well with some small code changes assuming their backends support the necessary syntaxes. SQLAlchemy developers would encourage users of third party dialects to post issues with these drivers, so that they may contact SQLAlchemy developers for assistance.