Performance with PyPy

[zoomorph]

SQLAlchemy seems to run quite a bit slower (2-3x) under PyPy. I've gathered some pstats profiles comparing the two.

PyPy (latest nightly build) + SQLAlchemy (master branch) + psycopg2cffi:

        1    0.000    0.000    0.017    0.017 /myapp/tpserv/client/client.py:285(handle_client_line)
        1    0.000    0.000    0.017    0.017 /myapp/tpserv/client/client.py:859(handle_request_statistics)
        1    0.000    0.000    0.017    0.017 /myapp/tpserv/tank/tank.py:419(initial_load)
        1    0.000    0.000    0.014    0.014 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2435(first)
        1    0.000    0.000    0.014    0.014 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2267(__getitem__)
        1    0.000    0.000    0.012    0.012 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2516(__iter__)
        1    0.000    0.000    0.010    0.010 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2530(_execute_and_instances)
        1    0.000    0.000    0.010    0.010 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:846(execute)
        1    0.000    0.000    0.010    0.010 /myapp/env_pypy/site-packages/sqlalchemy/sql/elements.py:322(_execute_on_connection)
        1    0.000    0.000    0.010    0.010 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:975(_execute_clauseelement)
        1    0.000    0.000    0.005    0.005 <string>:1(<lambda>)
        1    0.000    0.000    0.005    0.005 /myapp/env_pypy/site-packages/sqlalchemy/sql/elements.py:431(compile)
        1    0.000    0.000    0.005    0.005 /myapp/env_pypy/site-packages/sqlalchemy/sql/elements.py:496(_compiler)
        1    0.000    0.000    0.005    0.005 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:328(__init__)
        1    0.000    0.000    0.005    0.005 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:166(__init__)
      2/1    0.000    0.000    0.005    0.005 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:211(process)
        1    0.000    0.000    0.005    0.005 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:1062(_execute_context)
     50/1    0.002    0.000    0.005    0.005 /myapp/env_pypy/site-packages/sqlalchemy/sql/visitors.py:75(_compiler_dispatch)
        1    0.000    0.000    0.005    0.005 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:1474(visit_select)
       22    0.000    0.000    0.003    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:1254(_label_select_column)
        1    0.000    0.000    0.003    0.003 /myapp/env_pypy/site-packages/sqlalchemy/dialects/postgresql/psycopg2.py:457(get_result_proxy)
        1    0.000    0.000    0.003    0.003 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:407(__init__)
        1    0.000    0.000    0.003    0.003 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:423(_init_metadata)
        1    0.003    0.003    0.003    0.003 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:189(__init__)
       22    0.000    0.000    0.003    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:551(visit_label)
        2    0.000    0.000    0.002    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/loading.py:27(instances)
        2    0.000    0.000    0.002    0.001 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:18(check_closed_)
        1    0.000    0.000    0.002    0.002 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2934(_compile_context)
        2    0.000    0.000    0.001    0.001 /usr/local/pypy/lib-python/2.7/logging/__init__.py:1163(info)
        2    0.000    0.000    0.001    0.001 /usr/local/pypy/lib-python/2.7/logging/__init__.py:1273(_log)
        1    0.000    0.000    0.001    0.001 /myapp/env_pypy/site-packages/sqlalchemy/engine/default.py:441(do_execute)
        1    0.000    0.000    0.001    0.001 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:193(execute)
     10/5    0.000    0.000    0.001    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/operators.py:294(__eq__)
        2    0.000    0.000    0.001    0.001 /usr/local/pypy/lib-python/2.7/logging/__init__.py:1294(handle)
      9/7    0.000    0.000    0.001    0.000 {operator.eq}
        2    0.000    0.000    0.001    0.001 /usr/local/pypy/lib-python/2.7/logging/__init__.py:1326(callHandlers)
        1    0.000    0.000    0.001    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:3297(setup_context)
        6    0.000    0.000    0.001    0.000 /usr/local/pypy/lib-python/2.7/logging/__init__.py:757(handle)
        3    0.000    0.000    0.001    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/attributes.py:174(operate)
       48    0.001    0.000    0.001    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/interfaces.py:459(_get_context_loader)
        1    0.001    0.001    0.001    0.001 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:675(_pq_execute)
       24    0.000    0.000    0.001    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/interfaces.py:491(setup)
        2    0.000    0.000    0.001    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/relationships.py:950(__eq__)
        6    0.000    0.000    0.001    0.000 /usr/local/pypy/lib-python/2.7/logging/__init__.py:860(emit)
        1    0.000    0.000    0.001    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:3258(row_processor)
        1    0.000    0.000    0.001    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/loading.py:221(instance_processor)
        1    0.000    0.000    0.001    0.001 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:806(fetchall)
        1    0.000    0.000    0.001    0.001 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:775(_fetchall_impl)

Python 2.7 + SQLAlchemy (master branch) + psycopg2:

        1    0.000    0.000    0.005    0.005 /myapp/tpserv/client/client.py:285(handle_client_line)
        1    0.000    0.000    0.005    0.005 /myapp/tpserv/client/client.py:859(handle_request_statistics)
        1    0.000    0.000    0.005    0.005 /myapp/tpserv/tank/tank.py:419(initial_load)
        1    0.000    0.000    0.004    0.004 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2435(first)
        1    0.000    0.000    0.004    0.004 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2267(__getitem__)
        1    0.000    0.000    0.003    0.003 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2516(__iter__)
        1    0.000    0.000    0.003    0.003 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2530(_execute_and_instances)
        1    0.000    0.000    0.003    0.003 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:846(execute)
        1    0.000    0.000    0.003    0.003 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py:322(_execute_on_connection)
        1    0.000    0.000    0.003    0.003 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:975(_execute_clauseelement)
        1    0.000    0.000    0.001    0.001 <string>:1(<lambda>)
        1    0.000    0.000    0.001    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py:431(compile)
        1    0.000    0.000    0.001    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py:496(_compiler)
        1    0.000    0.000    0.001    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:328(__init__)
        1    0.000    0.000    0.001    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:166(__init__)
        1    0.000    0.000    0.001    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:1062(_execute_context)
      2/1    0.000    0.000    0.001    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:211(process)
     50/1    0.000    0.000    0.001    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/visitors.py:75(_compiler_dispatch)
        1    0.000    0.000    0.001    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:1474(visit_select)
        2    0.000    0.000    0.001    0.000 /usr/lib/python2.7/logging/__init__.py:1142(info)
        2    0.000    0.000    0.001    0.000 /usr/lib/python2.7/logging/__init__.py:1252(_log)
        2    0.000    0.000    0.001    0.000 /usr/lib/python2.7/logging/__init__.py:1273(handle)
        2    0.000    0.000    0.001    0.000 /usr/lib/python2.7/logging/__init__.py:1305(callHandlers)
        6    0.000    0.000    0.001    0.000 /usr/lib/python2.7/logging/__init__.py:736(handle)
       22    0.000    0.000    0.001    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:1254(_label_select_column)
        1    0.000    0.000    0.001    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py:441(do_execute)
        1    0.001    0.001    0.001    0.001 {method 'execute' of 'psycopg2._psycopg.cursor' objects}
        6    0.000    0.000    0.001    0.000 /usr/lib/python2.7/logging/__init__.py:839(emit)
       22    0.000    0.000    0.001    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:551(visit_label)
        4    0.000    0.000    0.001    0.000 /usr/lib/python2.7/logging/handlers.py:68(emit)
     10/5    0.000    0.000    0.001    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/operators.py:294(__eq__)
        4    0.000    0.000    0.001    0.000 /usr/lib/python2.7/logging/__init__.py:933(emit)
      9/7    0.000    0.000    0.001    0.000 {operator.eq}
        1    0.000    0.000    0.001    0.001 /usr/lib/python2.7/contextlib.py:21(__exit__)
        1    0.000    0.000    0.001    0.001 /myapp/tpcommon/profile.py:11(profile)
        3    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/attributes.py:174(operate)
        2    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/relationships.py:950(__eq__)
        1    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2934(_compile_context)
        2    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/loading.py:27(instances)
        1    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:1616(_compose_select_body)
       26    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:590(visit_column)
        1    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/dialects/postgresql/psycopg2.py:457(get_result_proxy)
      8/2    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/visitors.py:86(_compiler_dispatch)
        1    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/result.py:407(__init__)
        1    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/result.py:423(_init_metadata)
      7/6    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py:507(_init_compiled)
      2/1    0.000    0.000    0.000    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:705(visit_clauselist)

initial_load basically executes one select query.

Perhaps some optimizations can be made for better PyPy performance? I will try to gather more data.

[Mike Bayer]

Here's a tip with profiling, which is you need to get a lot more data than just a single execution with .013 of time. Try running something a few thousand times, so that the biggest hotspots become apparent through per-invocation and overall time spent.

This is unlikely to be any kind of "issue" in SQLAlchemy, when Pypy has a regression I consider it to be their bug. I'm not sure to what degree SQLAlchemy is part of their CI performance suites but IMO it definitely should be.

[Mike Bayer]

no info to work with here

[zoomorph]

Hi Mike,

I created a simple benchmark to gather some better data:

# leaving out table defs for brevity

if "PyPy" in sys.version:
    ENGINE = create_engine("postgresql+psycopg2cffi://user@/tpdb", use_native_unicode=False)
else:
    ENGINE = create_engine("postgresql+psycopg2://user@/tpdb", use_native_unicode=False)

ENGINE.execution_options(stream_results=True)

SESSIONMAKER = sessionmaker(bind=ENGINE)

session = SESSIONMAKER()

for x in xrange(30000):
    tank = session.query(Tank).filter(Tank.tank_id == x).first()
    if tank:
        tank.tank_name = tank.tank_name[1:] + tank.tank_name[0]
        session.commit()

Here are the first 100 lines of the pstats outputs.

PyPy:

Sat Feb 14 01:53:50 2015    pypy.stats

         687886505 function calls (686601723 primitive calls) in 106.157 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.222    0.222  106.770  106.770 test.py:1(<module>)
    21234    0.038    0.000   73.236    0.003 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:745(commit)
42468/21234    0.293    0.000   73.197    0.003 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:381(commit)
    21234    3.604    0.000   52.669    0.002 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:290(_remove_snapshot)
 30651551   31.301    0.000   45.672    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/state.py:360(_expire)
    30001    0.085    0.000   29.835    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2435(first)
    30001    0.186    0.000   29.744    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2267(__getitem__)
    51234    0.061    0.000   27.504    0.001 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:846(execute)
    51231    0.076    0.000   27.414    0.001 /myapp/env_pypy/site-packages/sqlalchemy/sql/elements.py:322(_execute_on_connection)
    51231    0.315    0.000   27.338    0.001 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:975(_execute_clauseelement)
    30001    0.066    0.000   24.866    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2516(__iter__)
    30001    0.129    0.000   22.310    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2530(_execute_and_instances)
    51234    0.246    0.000   19.932    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:1062(_execute_context)
    81248    0.072    0.000   17.655    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:26(check_closed_)
    51236    0.026    0.000   16.161    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/default.py:441(do_execute)
    51239    0.115    0.000   16.082    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:201(execute)
42468/21234    0.116    0.000   14.598    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:350(_prepare_impl)
    72470    0.041    0.000   14.480    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:1959(flush)
    21234    0.540    0.000   14.391    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:2010(_flush)
    51239   11.579    0.000   13.086    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:677(_pq_execute)
    21234    0.170    0.000   11.731    0.001 /myapp/env_pypy/site-packages/sqlalchemy/orm/unitofwork.py:351(execute)
    21234    0.049    0.000    9.745    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/unitofwork.py:528(execute)
    21234    0.197    0.000    9.696    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/persistence.py:123(save_obj)
337190339    8.918    0.000    8.918    0.000 {method 'pop' of 'dict' objects}
    21234    0.250    0.000    8.371    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/persistence.py:577(_emit_update_statements)
    30005    0.024    0.000    6.879    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/elements.py:431(compile)
    30005    0.021    0.000    6.856    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/elements.py:496(_compiler)
    30005    0.104    0.000    6.835    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:328(__init__)
    30005    0.065    0.000    6.716    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:166(__init__)
60007/30005    0.055    0.000    6.650    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:211(process)
630038/30005    0.647    0.000    6.631    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/visitors.py:75(_compiler_dispatch)
    30004    0.465    0.000    6.560    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:1474(visit_select)
    42473    5.192    0.000    5.346    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/connection.py:646(_execute_command)
    21234    0.041    0.000    4.426    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:1556(commit)
    21234    0.026    0.000    4.386    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:1590(_do_commit)
    51236    0.497    0.000    4.366    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/loading.py:27(instances)
    21234    0.095    0.000    4.360    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:679(_commit_impl)
    42471    0.080    0.000    4.317    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/connection.py:39(check_closed_)
    21234    0.038    0.000    4.235    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/default.py:414(do_commit)
    42470    0.018    0.000    4.225    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/connection.py:79(check_async_)
    42470    0.031    0.000    4.207    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/connection.py:57(check_tpc_)
    21234    0.033    0.000    4.103    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/connection.py:192(commit)
    21234    0.086    0.000    4.070    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/connection.py:739(_commit)
 61303108    1.457    0.000    3.640    0.000 /myapp/env_pypy/site-packages/sqlalchemy/util/langhelpers.py:750(_reset)
 30715253    3.237    0.000    3.237    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/state.py:242(dict)
    30001    0.128    0.000    2.445    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2934(_compile_context)
 61303108    1.351    0.000    2.183    0.000 /myapp/env_pypy/site-packages/sqlalchemy/util/langhelpers.py:753(reset)
   270015    0.629    0.000    2.163    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:1254(_label_select_column)
    30004    0.269    0.000    2.098    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:1616(_compose_select_body)
    51234    0.122    0.000    1.826    0.000 /myapp/env_pypy/site-packages/sqlalchemy/dialects/postgresql/psycopg2.py:457(get_result_proxy)
61465982/61465872    0.858    0.000    1.728    0.000 /myapp/env_pypy/site-packages/sqlalchemy/util/langhelpers.py:744(__get__)
    30001    0.034    0.000    1.727    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:2523(_connection_from_session)
    30001    0.028    0.000    1.693    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:800(connection)
114937/72469    0.152    0.000    1.685    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:304(_connection_for_bind)
    51234    0.054    0.000    1.656    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:407(__init__)
    30001    0.020    0.000    1.646    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:806(fetchall)
    30001    0.012    0.000    1.635    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:873(_connection_for_bind)
    51234    0.044    0.000    1.602    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:423(_init_metadata)
 30714568    1.568    0.000    1.568    0.000 {method 'clear' of 'dict' objects}
    51231    0.567    0.000    1.542    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/default.py:507(_init_compiled)
    30004    0.801    0.000    1.538    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:189(__init__)
    30001    0.014    0.000    1.531    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/result.py:775(_fetchall_impl)
    51239    0.058    0.000    1.488    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/connection.py:641(_begin_transaction)
    30008    0.009    0.000    1.471    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:39(check_no_tuples_)
    30001    0.065    0.000    1.461    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:357(fetchall)
    21235    0.125    0.000    1.461    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:2008(contextual_connect)
    21241    0.199    0.000    1.397    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:866(_build_row)
90015/60007    0.227    0.000    1.380    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/visitors.py:86(_compiler_dispatch)
    30001    0.225    0.000    1.312    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:3047(_simple_statement)
    51239    0.187    0.000    1.279    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:722(_pq_fetch)
    51236    0.712    0.000    1.268    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:912(_combine_cmd_params)
    42468    0.255    0.000    1.238    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:445(close)
    30004    0.247    0.000    1.183    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:1590(_setup_select_stack)
342816/151710    0.127    0.000    1.180    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/typecasts.py:69(typecast)
    21235    0.238    0.000    1.128    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/loading.py:283(_instance)
   270015    0.265    0.000    1.110    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:551(visit_label)
342816/151710    0.102    0.000    1.092    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/typecasts.py:32(cast)
    21234    0.160    0.000    1.045    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/unitofwork.py:375(finalize_flush_changes)
    30004    0.155    0.000    1.011    0.000 <string>:1(select)
    30009    0.428    0.000    0.990    0.000 /myapp/env_pypy/site-packages/psycopg2cffi/_impl/cursor.py:759(_pq_fetch_tuples)
    30001    0.075    0.000    0.982    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:1234(query)
    30001    0.091    0.000    0.941    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:3258(row_processor)
    63702    0.095    0.000    0.918    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/persistence.py:985(_connections_for_states)
    60004    0.060    0.000    0.910    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/compiler.py:1016(visit_bindparam)
    30001    0.015    0.000    0.907    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:106(__init__)
120008/30003    0.134    0.000    0.898    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/operators.py:294(__eq__)
    30001    0.100    0.000    0.892    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/query.py:111(_set_entities)
    30001    0.004    0.000    0.862    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/attributes.py:174(operate)
90005/30003    0.040    0.000    0.858    0.000 {operator.eq}
    30004    0.208    0.000    0.856    0.000 /myapp/env_pypy/site-packages/sqlalchemy/sql/selectable.py:2218(__init__)
    21235    0.029    0.000    0.840    0.000 /myapp/env_pypy/site-packages/sqlalchemy/engine/base.py:2059(_wrap_pool_connect)
    21234    0.195    0.000    0.834    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/session.py:1480(_register_newly_persistent)
    30001    0.226    0.000    0.833    0.000 /myapp/env_pypy/site-packages/sqlalchemy/orm/loading.py:221(instance_processor)

Python:

Sat Feb 14 01:55:44 2015    python.stats

         33426364 function calls (32528639 primitive calls) in 78.037 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.436    0.436   78.394   78.394 test.py:1(<module>)
    30001    0.131    0.000   48.443    0.002 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2435(first)
    30001    0.596    0.000   48.302    0.002 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2267(__getitem__)
    30001    0.121    0.000   41.594    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2516(__iter__)
    51234    0.140    0.000   39.926    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:846(execute)
    51231    0.085    0.000   39.715    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py:322(_execute_on_connection)
    51231    0.438    0.000   39.630    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:975(_execute_clauseelement)
    30001    0.167    0.000   35.365    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2530(_execute_and_instances)
    21234    0.098    0.000   23.727    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:745(commit)
42468/21234    0.310    0.000   23.629    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:381(commit)
    51234    0.667    0.000   20.817    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:1062(_execute_context)
    30005    0.078    0.000   18.009    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py:431(compile)
    30005    0.072    0.000   17.931    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py:496(_compiler)
    30005    0.321    0.000   17.859    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:328(__init__)
    30005    0.093    0.000   17.465    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:166(__init__)
60007/30005    0.092    0.000   17.372    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:211(process)
630038/30005    1.350    0.000   17.323    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/visitors.py:75(_compiler_dispatch)
    30004    0.732    0.000   17.226    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:1474(visit_select)
42468/21234    0.218    0.000   16.470    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:350(_prepare_impl)
    72470    0.166    0.000   16.301    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:1959(flush)
    21234    0.519    0.000   15.990    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:2010(_flush)
    21234    0.129    0.000   13.074    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py:351(execute)
    51236    0.090    0.000   13.010    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py:441(do_execute)
    51239   12.522    0.000   12.921    0.000 {method 'execute' of 'psycopg2._psycopg.cursor' objects}
    21234    0.075    0.000   10.808    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py:528(execute)
    21234    0.319    0.000   10.733    0.001 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py:123(save_obj)
   270015    1.443    0.000    9.936    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:1254(_label_select_column)
    21234    0.384    0.000    8.947    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py:577(_emit_update_statements)
   270015    1.823    0.000    7.416    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:551(visit_label)
    30001    0.197    0.000    5.951    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2934(_compile_context)
    51236    0.441    0.000    5.527    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/loading.py:27(instances)
    21234    0.040    0.000    3.812    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:1556(commit)
    21234    0.037    0.000    3.772    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:1590(_do_commit)
    21234    0.175    0.000    3.735    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:679(_commit_impl)
    30001    0.316    0.000    3.615    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:3047(_simple_statement)
    51234    0.194    0.000    3.600    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/dialects/postgresql/psycopg2.py:457(get_result_proxy)
    30001    0.626    0.000    3.528    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:3258(row_processor)
    21234    0.103    0.000    3.528    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py:414(do_commit)
   300018    1.907    0.000    3.496    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:590(visit_column)
    30004    0.441    0.000    3.408    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:1616(_compose_select_body)
    21234    3.385    0.000    3.385    0.000 {method 'commit' of 'psycopg2._psycopg.connection' objects}
    51234    0.164    0.000    3.261    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/result.py:407(__init__)
    30004    0.163    0.000    3.221    0.000 <string>:1(select)
    51234    0.196    0.000    3.098    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/result.py:423(_init_metadata)
    30004    0.694    0.000    3.058    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/selectable.py:2218(__init__)
    51231    1.224    0.000    3.010    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py:507(_init_compiled)
    30001    0.681    0.000    2.870    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/loading.py:221(instance_processor)
    30004    1.523    0.000    2.864    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/result.py:189(__init__)
90015/60007    0.308    0.000    2.537    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/visitors.py:86(_compiler_dispatch)
    30001    0.070    0.000    2.424    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:2523(_connection_from_session)
120008/30003    0.184    0.000    2.377    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/operators.py:294(__eq__)
    30001    0.095    0.000    2.354    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:800(connection)
    30001    0.044    0.000    2.325    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/attributes.py:174(operate)
114937/72469    0.329    0.000    2.323    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:304(_connection_for_bind)
90005/30003    0.136    0.000    2.280    0.000 {operator.eq}
205348/205238    0.347    0.000    2.251    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py:744(__get__)
    30001    0.062    0.000    2.192    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/properties.py:260(operate)
    30001    0.044    0.000    2.174    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:873(_connection_for_bind)
    30001    0.133    0.000    2.073    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/annotation.py:93(__eq__)
   270012    0.430    0.000    1.985    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/interfaces.py:499(create_row_processor)
    42468    0.227    0.000    1.881    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:445(close)
    30013    0.036    0.000    1.879    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py:731(operate)
    30001    0.073    0.000    1.878    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:1234(query)
    30001    0.040    0.000    1.805    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:106(__init__)
    30004    0.193    0.000    1.791    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:1590(_setup_select_stack)
    30001    0.179    0.000    1.765    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:111(_set_entities)
    30013    0.054    0.000    1.751    0.000 <string>:1(<lambda>)
    30001    0.453    0.000    1.744    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py:3297(setup_context)
2663264/2663262    1.450    0.000    1.714    0.000 {isinstance}
    30013    0.118    0.000    1.697    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/type_api.py:57(operate)
    30002    0.130    0.000    1.647    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:872(visit_binary)
    63702    0.170    0.000    1.632    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py:985(_connections_for_states)
   330017    0.796    0.000    1.614    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:1098(_truncated_identifier)
    21235    0.081    0.000    1.612    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:2008(contextual_connect)
    30013    0.145    0.000    1.577    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/default_comparator.py:21(_boolean_compare)
    30004    0.166    0.000    1.499    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/selectable.py:2505(_get_display_froms)
    30002    0.123    0.000    1.465    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:903(_generate_generic_binary)
   900046    0.892    0.000    1.417    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:2623(quote)
    60004    0.209    0.000    1.383    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py:1016(visit_bindparam)
    21234    0.059    0.000    1.310    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py:557(execute)
    30004    0.191    0.000    1.306    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/selectable.py:2477(_froms)
    60025    0.630    0.000    1.276    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py:896(__init__)
   270012    0.543    0.000    1.266    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/interfaces.py:491(setup)
    21234    0.248    0.000    1.251    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py:222(delete_obj)
    21234    0.195    0.000    1.237    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py:290(_remove_snapshot)
    30004    0.238    0.000    1.187    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/selectable.py:3149(_columns_plus_names)
    21234    0.064    0.000    1.123    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py:793(close)
   270012    0.498    0.000    1.107    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/strategies.py:162(create_row_processor)
    21234    0.037    0.000    1.059    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/pool.py:796(close)
    30013    0.146    0.000    1.058    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/sql/default_comparator.py:269(_check_literal)
    21234    0.116    0.000    1.056    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py:375(finalize_flush_changes)
    42468    0.132    0.000    1.045    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py:255(_organize_states_for_save)
    21234    0.045    0.000    1.022    0.000 /myapp/env_python/local/lib/python2.7/site-packages/sqlalchemy/pool.py:681(_checkin)

Interestingly:

Committing seems ~3x slower on PyPy. _remove_snapshot is almost free in Python but one of the big offenders in PyPy. _expire is called ~1400x per modified tank object in PyPy compared with only once per object in Python. Any idea what's up with this?

I hope this provides some better insight. PyPy appears to make up some long time further on, so it's not as bad as I was seeing in my real app (2-3x slower), which requires further investigation. Thanks.

[Mike Bayer]

OK well keep in mind, Pypy needs "warm up" time, your code has to actually run for awhile while Pypy's JIT figures out the best thing to do with it. This is sort of why I think SQLAlchemy's unit tests run really terribly with Pypy, because the program is constantly changing what it's doing and Pypy can't optimize for that.

[zoomorph]

Do you have any idea why the excessive calls would be made to _expire when using PyPy?

I tried Python + psycopg2cffi and behavior is similar to Python + psycopg2.

I've been using PyPy in production for a couple years. My application is long running (several days) and, unfortunately, performance of SQLAlchemy queries don't seem to get any better over time.

[Mike Bayer]

theres a simple reason why that could happen, because pypy doesn't use a reference counting GC, and if a Session sees a lot of objects go through it that are then dereferenced, it still could have a lot of weakrefs lying around. Calling session.commit() then does expire of everything present which would hit all those objects.

if the performance of queries from the point of formulation to emitting the string is slow, the baked query feature which is done except for documentation at https://bitbucket.org/zzzeek/sqlalchemy/src/c48df197a66acb628ac79d8a55422b7b37f8d2bd/lib/sqlalchemy/ext/baked.py?at=ticket_3054 will reduce that by 80%.

[zoomorph]

Hi Mike,

Thanks for your assistance.

I've set expire_on_commit=False and manually expunged the objects in my test loop and it greatly improved performance with PyPy. This seems like it might be a stumbling block for anyone using SQLAlchemy with PyPy. Luckily for me, I don't want to expire_on_commit in this application.

PyPy now beats cPython... eventually. PyPy is 2x slower at 1000 iterations, catches up at 7000 iterations, and is 2x faster by 30000 iterations. Unfortunately, my real app presumably doesn't execute this code enough times for PyPy's JIT to master it, hence appearing 2x slower. I guess I over-estimated the JIT since it's optimized other code I've benchmarked in far less iterations.

I am very interested in benchmarking BakedQuery to see how caching the queries would help. However, I think I'll have to wait for documentation before I can figure out how to use it. I will try to benchmark it once it's in the master branch. :-)

[Mike Bayer]

• Mapped state internals have been reworked to allow for a 50% reduction in callcounts specific to the "expiration" of objects, as in the "auto expire" feature of :meth:.Session.commit and for :meth:.Session.expire_all, as well as in the "cleanup" step which occurs when object states are garbage collected. fixes #3307

→ <<cset 3209a73b92e1>>

[Mike Bayer]

so FWIW I got callcounts down about 50% in that area specifically. There's faster ways to expire, e.g. "lazy" expire where we don't actually touch the objects until someone uses them, but that would be too big a change for now.

[zoomorph]

Excellent. I'll benchmark this change when I can. Thanks!