Antoine Pitrou wrote:
> Hello,
>
> I've got some scripts which take quite a bit of time and I wanted to
> investigate why they were so long. So I profiled them using cProfile
> and I was quite surprised to get the following results. In short, SQL
> queries themselves take less than 10% of the total time, and most of
> the time is taken by SQLAlchemy itself (you'll notice than in the 50
> first CPU consumers below, there isn't a single function of my own
> application).
>
> I should point out that this particular script doesn't manipulate that
> many objects (a few thousands of them perhaps), and the queries aren't
> complex at all. It would be good to know whether there are well known
> techniques to help reduce the overall overhead of SQLAlchemy which, in
> this case, is really bewildering.
>
> Thank you
>
> Antoine.
>
>
> 61307243 function calls (59670236 primitive calls) in 343.725
> CPU seconds
>
> Ordered by: internal time
> List reduced from 1369 to 50 due to restriction <50>
>
> ncalls tottime percall cumtime percall filename:lineno
> (function)
> 23771 20.189 0.001 20.189 0.001 {method 'query' of
> '_mysql.connection' objects}
> 4455901 9.244 0.000 9.244 0.000 {isinstance}
> 1736162 8.706 0.000 25.237 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/unitofwork.py:426
> (collection)
> 23771 7.567 0.000 17.396 0.001 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/engine/base.py:1432
> (_init_metadata)
> 1985456 6.111 0.000 10.047 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/unitofwork.py:342
> (polymorphic_tasks)
> 288526 5.666 0.000 23.924 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/compiler.py:261
> (visit_label)
> 53348 4.785 0.000 69.452 0.001 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/mapper.py:1190
> (_save_obj)
> 316457 4.688 0.000 7.344 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/compiler.py:278
> (visit_column)
> 2803666 4.359 0.000 4.359 0.000 {method 'get' of 'dict'
> objects}
> 712463/23808 4.182 0.000 61.672 0.003 /usr/lib/python2.6/
> site-packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/visitors.py:
> 49(_compiler_dispatch)
> 23771 3.595 0.000 3.595 0.000 {method 'store_result'
> of '_mysql.connection' objects}
> 1095673 3.499 0.000 3.499 0.000 {hasattr}
> 712463/23808 3.446 0.000 61.827 0.003 /usr/lib/python2.6/
> site-packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/compiler.py:
> 216(process)
> 13680 3.374 0.000 43.671 0.003 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/compiler.py:510
> (visit_select)
> 10091 3.258 0.000 13.926 0.001 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/compiler.py:671
> (_get_colparams)
> 10953 3.137 0.000 7.880 0.001 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/topological.py:162
> (_sort)
> 246189 3.055 0.000 8.127 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/interfaces.py:592
> (create_row_processor)
> 49248 2.992 0.000 9.442 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/mapper.py:1514
> (_register_dependencies)
> 832076 2.951 0.000 2.951 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/state.py:49(dict)
> 205064 2.893 0.000 23.348 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/unitofwork.py:655
> (preexecute)
> 651433 2.831 0.000 7.188 0.000 {method 'decode' of
> 'str' objects}
> 348681 2.771 0.000 6.485 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/interfaces.py:589
> (setup)
> 1423203 2.687 0.000 3.681 0.000 {method 'add' of 'set'
> objects}
> 829956 2.686 0.000 4.001 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/unitofwork.py:433
> (elements)
> 1842480 2.657 0.000 2.657 0.000 {method 'append' of
> 'list' objects}
> 253492 2.637 0.000 6.252 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/attributes.py:1241
> (from_attribute)
> 594870 2.618 0.000 3.582 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/interfaces.py:568
> (__get_context_strategy)
> 291982 2.617 0.000 13.526 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/state.py:87
> (get_history)
> 754720 2.613 0.000 6.251 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/unitofwork.py:437
> (polymorphic_elements)
> 118594 2.608 0.000 2.608 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/util.py:721(values)
> 288526 2.564 0.000 4.196 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/compiler.py:488
> (label_select_column)
> 1070557 2.554 0.000 2.557 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/compiler.py:1106
> (quote)
> 316426 2.327 0.000 3.313 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/compiler.py:447
> (_truncated_identifier)
> 441735 2.235 0.000 3.934 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/types.py:124
> (dialect_impl)
> 13673 2.207 0.000 13.730 0.001 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/query.py:1959
> (setup_context)
> 133921 2.206 0.000 29.651 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/query.py:1293
> (instances)
> 651397 2.185 0.000 2.185 0.000 {_codecs.utf_8_decode}
> 41026 2.174 0.000 4.237 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/util.py:1090
> (unique_list)
> 651397 2.172 0.000 4.358 0.000 /usr/lib64/python2.6/
> encodings/utf_8.py:15(decode)
> 330640 2.135 0.000 2.675 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/compiler.py:423
> (operator_string)
> 151781 2.109 0.000 2.544 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/expression.py:1935
> (__init__)
> 629208 1.972 0.000 1.972 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/attributes.py:1051
> (get_impl)
> 307596 1.906 0.000 10.107 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/unitofwork.py:441
> (polymorphic_tosave_elements)
> 13680 1.903 0.000 10.286 0.001 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/sql/expression.py:3218
> (__init__)
> 307596 1.850 0.000 9.449 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/unitofwork.py:445
> (polymorphic_todelete_elements)
> 293765/232025 1.841 0.000 56.237 0.000 /usr/lib/python2.6/
> site-packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/
> attributes.py:354(get)
> 207147 1.840 0.000 3.282 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/strategies.py:113
> (create_row_processor)
> 479136 1.811 0.000 1.811 0.000 /usr/lib64/python2.6/
> weakref.py:242(__getitem__)
> 382082 1.771 0.000 12.761 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/unitofwork.py:171
> (get_task_by_mapper)
> 205064 1.736 0.000 32.974 0.000 /usr/lib/python2.6/site-
> packages/SQLAlchemy-0.5.4p2-py2.6.egg/sqlalchemy/orm/unitofwork.py:687
> (execute)
the 53K calls to mapper._save_obj() indicate that your flush plan is
creating an enormous dependency tree. Or, much less likely, you're using
the "batch=False" flag on mapper, which is highly not recommended. For a
simple flush plan, such as a list of objects A each of which contain a
one-to-many collection of objects B, _save_obj() would be called about
four times. A flush plan like the one you have could for example occur
in some self-referential scenarios, if you have a deep tree of recursive
relationships for example. A test script illustrating mappings and
sample objects which produce a huge flush like this would be helpful, as
there may be either an improvement to your mapping, or within the unit of
work code which could optimize whatever is occurring here.
>
> --
>
> You received this message because you are subscribed to the Google Groups
> "sqlalchemy" group.
> To post to this group, send email to sqlalch...@googlegroups.com.
> To unsubscribe from this group, send email to
> sqlalchemy+unsubscr...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/sqlalchemy?hl=en.
>
>
>
--
You received this message because you are subscribed to the Google Groups
"sqlalchemy" group.
To post to this group, send email to sqlalch...@googlegroups.com.
To unsubscribe from this group, send email to
sqlalchemy+unsubscr...@googlegroups.com.
For more options, visit this group at
http://groups.google.com/group/sqlalchemy?hl=en.
