]> git.ipfire.org Git - thirdparty/sqlalchemy/sqlalchemy.git/commitdiff
- add lots more to the profiling section
authorMike Bayer <mike_mp@zzzcomputing.com>
Fri, 16 May 2014 15:53:12 +0000 (11:53 -0400)
committerMike Bayer <mike_mp@zzzcomputing.com>
Fri, 16 May 2014 15:54:51 +0000 (11:54 -0400)
- add the query profiling recipe, fix it with a stack as we now nest those
calls occasionally
- tabs to spaces

Conflicts:
doc/build/faq.rst

doc/build/faq.rst

index 9b65a18bd5783b70cecd62310f04a014c5a17fd0..33d42167a04455b4c6dbae5b8dcecc5af85f283b 100644 (file)
@@ -7,9 +7,9 @@ Frequently Asked Questions
 ============================
 
 .. contents::
-       :local:
-       :class: faq
-       :backlinks: none
+    :local:
+    :class: faq
+    :backlinks: none
 
 
 Connections / Engines
@@ -35,17 +35,17 @@ How do I pass custom connect arguments to my database API?
 The :func:`.create_engine` call accepts additional arguments either
 directly via the ``connect_args`` keyword argument::
 
-       e = create_engine("mysql://scott:tiger@localhost/test",
-                                               connect_args={"encoding": "utf8"})
+    e = create_engine("mysql://scott:tiger@localhost/test",
+                        connect_args={"encoding": "utf8"})
 
 Or for basic string and integer arguments, they can usually be specified
 in the query string of the URL::
 
-       e = create_engine("mysql://scott:tiger@localhost/test?encoding=utf8")
+    e = create_engine("mysql://scott:tiger@localhost/test?encoding=utf8")
 
 .. seealso::
 
-       :ref:`custom_dbapi_args`
+    :ref:`custom_dbapi_args`
 
 "MySQL Server has gone away"
 ----------------------------
@@ -87,10 +87,10 @@ I'm on MyISAM - how do I turn it off?
 The behavior of the connection pool's connection return behavior can be
 configured using ``reset_on_return``::
 
-       from sqlalchemy import create_engine
-       from sqlalchemy.pool import QueuePool
+    from sqlalchemy import create_engine
+    from sqlalchemy.pool import QueuePool
 
-       engine = create_engine('mysql://scott:tiger@localhost/myisam_database', pool=QueuePool(reset_on_return=False))
+    engine = create_engine('mysql://scott:tiger@localhost/myisam_database', pool=QueuePool(reset_on_return=False))
 
 I'm on SQL Server - how do I turn those ROLLBACKs into COMMITs?
 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
@@ -99,7 +99,7 @@ I'm on SQL Server - how do I turn those ROLLBACKs into COMMITs?
 to ``True``, ``False``, and ``None``.   Setting to ``commit`` will cause
 a COMMIT as any connection is returned to the pool::
 
-       engine = create_engine('mssql://scott:tiger@mydsn', pool=QueuePool(reset_on_return='commit'))
+    engine = create_engine('mssql://scott:tiger@mydsn', pool=QueuePool(reset_on_return='commit'))
 
 
 I am using multiple connections with a SQLite database (typically to test transaction operation), and my test program is not working!
@@ -115,7 +115,7 @@ current SQLAlchemy versions.
 
 .. seealso::
 
-       :ref:`pysqlite_threading_pooling` - info on PySQLite's behavior.
+    :ref:`pysqlite_threading_pooling` - info on PySQLite's behavior.
 
 How do I get at the raw DBAPI connection when using an Engine?
 --------------------------------------------------------------
@@ -126,10 +126,10 @@ version of the DBAPI connection via the :attr:`.Connection.connection` attribute
 :attr:`.ConnectionFairy.connection` attribute on that - but there should never be any need to access
 the non-pool-proxied DBAPI connection, as all methods are proxied through::
 
-       engine = create_engine(...)
-       conn = engine.connect()
-       conn.connection.<do DBAPI things>
-       cursor = conn.connection.cursor(<DBAPI specific arguments..>)
+    engine = create_engine(...)
+    conn = engine.connect()
+    conn.connection.<do DBAPI things>
+    cursor = conn.connection.cursor(<DBAPI specific arguments..>)
 
 You must ensure that you revert any isolation level settings or other
 operation-specific settings on the connection back to normal before returning
@@ -140,10 +140,10 @@ either :class:`.Connection` or the proxied connection, which will de-associate
 the connection from the pool such that it will be closed and discarded
 when :meth:`.Connection.close` is called::
 
-       conn = engine.connect()
-       conn.detach()  # detaches the DBAPI connection from the connection pool
-       conn.connection.<go nuts>
-       conn.close()  # connection is closed for real, the pool replaces it with a new connection
+    conn = engine.connect()
+    conn.detach()  # detaches the DBAPI connection from the connection pool
+    conn.connection.<go nuts>
+    conn.close()  # connection is closed for real, the pool replaces it with a new connection
 
 MetaData / Schema
 ==================
@@ -156,10 +156,10 @@ strict about table locks, and 2. you have a connection still open which
 contains locks on the table and is distinct from the connection being used for
 the DROP statement.  Heres the most minimal version of the pattern::
 
-       connection = engine.connect()
-       result = connection.execute(mytable.select())
+    connection = engine.connect()
+    result = connection.execute(mytable.select())
 
-       mytable.drop(engine)
+    mytable.drop(engine)
 
 Above, a connection pool connection is still checked out; furthermore, the
 result object above also maintains a link to this connection.  If
@@ -171,17 +171,17 @@ connection procured from the :class:`.Engine` which will lock.
 
 The solution is to close out all connections before emitting DROP TABLE::
 
-       connection = engine.connect()
-       result = connection.execute(mytable.select())
+    connection = engine.connect()
+    result = connection.execute(mytable.select())
 
-       # fully read result sets
-       result.fetchall()
+    # fully read result sets
+    result.fetchall()
 
-       # close connections
-       connection.close()
+    # close connections
+    connection.close()
 
-       # now locks are removed
-       mytable.drop(engine)
+    # now locks are removed
+    mytable.drop(engine)
 
 Does SQLAlchemy support ALTER TABLE, CREATE VIEW, CREATE TRIGGER, Schema Upgrade Functionality?
 -----------------------------------------------------------------------------------------------
@@ -198,11 +198,11 @@ How can I sort Table objects in order of their dependency?
 
 This is available via the :attr:`.MetaData.sorted_tables` function::
 
-       metadata = MetaData()
-       # ... add Table objects to metadata
-       ti = metadata.sorted_tables:
-       for t in ti:
-           print t
+    metadata = MetaData()
+    # ... add Table objects to metadata
+    ti = metadata.sorted_tables:
+    for t in ti:
+        print t
 
 How can I get the CREATE TABLE/ DROP TABLE output as a string?
 ---------------------------------------------------------------
@@ -210,21 +210,21 @@ How can I get the CREATE TABLE/ DROP TABLE output as a string?
 Modern SQLAlchemy has clause constructs which represent DDL operations. These
 can be rendered to strings like any other SQL expression::
 
-       from sqlalchemy.schema import CreateTable
+    from sqlalchemy.schema import CreateTable
 
-       print CreateTable(mytable)
+    print CreateTable(mytable)
 
 To get the string specific to a certain engine::
 
-       print CreateTable(mytable).compile(engine)
+    print CreateTable(mytable).compile(engine)
 
 There's also a special form of :class:`.Engine` that can let you dump an entire
 metadata creation sequence, using this recipe::
 
-       def dump(sql, *multiparams, **params):
-           print sql.compile(dialect=engine.dialect)
-       engine = create_engine('postgresql://', strategy='mock', executor=dump)
-       metadata.create_all(engine, checkfirst=False)
+    def dump(sql, *multiparams, **params):
+        print sql.compile(dialect=engine.dialect)
+    engine = create_engine('postgresql://', strategy='mock', executor=dump)
+    metadata.create_all(engine, checkfirst=False)
 
 The `Alembic <https://bitbucket.org/zzzeek/alembic>`_ tool also supports
 an "offline" SQL generation mode that renders database migrations as SQL scripts.
@@ -250,16 +250,16 @@ A little introduction to the issue. The IN operator in SQL, given a list of
 elements to compare against a column, generally does not accept an empty list,
 that is while it is valid to say::
 
-       column IN (1, 2, 3)
+    column IN (1, 2, 3)
 
 it's not valid to say::
 
-       column IN ()
+    column IN ()
 
 SQLAlchemy's :meth:`.Operators.in_` operator, when given an empty list, produces this
 expression::
 
-       column != column
+    column != column
 
 As of version 0.6, it also produces a warning stating that a less efficient
 comparison operation will be rendered. This expression is the only one that is
@@ -268,18 +268,18 @@ both database agnostic and produces correct results.
 For example, the naive approach of "just evaluate to false, by comparing 1=0
 or 1!=1", does not handle nulls properly. An expression like::
 
-       NOT column != column
+    NOT column != column
 
 will not return a row when "column" is null, but an expression which does not
 take the column into account::
 
-       NOT 1=0
+    NOT 1=0
 
 will.
 
 Closer to the mark is the following CASE expression::
 
-       CASE WHEN column IS NOT NULL THEN 1=0 ELSE NULL END
+    CASE WHEN column IS NOT NULL THEN 1=0 ELSE NULL END
 
 We don't use this expression due to its verbosity, and its also not
 typically accepted by Oracle within a WHERE clause - depending
@@ -299,35 +299,64 @@ ORM Configuration
 How do I map a table that has no primary key?
 ---------------------------------------------
 
+The SQLAlchemy ORM, in order to map to a particular table, needs there to be
+at least one column denoted as a primary key column; multiple-column,
+i.e. composite, primary keys are of course entirely feasible as well.  These
+columns do **not** need to be actually known to the database as primary key
+columns, though it's a good idea that they are.  It's only necessary that the columns
+*behave* as a primary key does, e.g. as a unique and not nullable identifier
+for a row.
+
+Most ORMs require that objects have some kind of primary key defined
+because the object in memory must correspond to a uniquely identifiable
+row in the database table; at the very least, this allows the
+object can be targeted for UPDATE and DELETE statements which will affect only
+that object's row and no other.   However, the importance of the primary key
+goes far beyond that.  In SQLAlchemy, all ORM-mapped objects are at all times
+linked uniquely within a :class:`.Session`
+to their specific database row using a pattern called the :term:`identity map`,
+a pattern that's central to the unit of work system employed by SQLAlchemy,
+and is also key to the most common (and not-so-common) patterns of ORM usage.
+
+
+.. note::
+
+    It's important to note that we're only talking about the SQLAlchemy ORM; an
+    application which builds on Core and deals only with :class:`.Table` objects,
+    :func:`.select` constructs and the like, **does not** need any primary key
+    to be present on or associated with a table in any way (though again, in SQL, all tables
+    should really have some kind of primary key, lest you need to actually
+    update or delete specific rows).
+
 In almost all cases, a table does have a so-called :term:`candidate key`, which is a column or series
 of columns that uniquely identify a row.  If a table truly doesn't have this, and has actual
 fully duplicate rows, the table is not corresponding to `first normal form <http://en.wikipedia.org/wiki/First_normal_form>`_ and cannot be mapped.   Otherwise, whatever columns comprise the best candidate key can be
 applied directly to the mapper::
 
-       class SomeClass(Base):
-               __table__ = some_table_with_no_pk
-               __mapper_args__ = {
-                       'primary_key':[some_table_with_no_pk.c.uid, some_table_with_no_pk.c.bar]
-               }
+    class SomeClass(Base):
+        __table__ = some_table_with_no_pk
+        __mapper_args__ = {
+            'primary_key':[some_table_with_no_pk.c.uid, some_table_with_no_pk.c.bar]
+        }
 
 Better yet is when using fully declared table metadata, use the ``primary_key=True``
 flag on those columns::
 
-       class SomeClass(Base):
-               __tablename__ = "some_table_with_no_pk"
+    class SomeClass(Base):
+        __tablename__ = "some_table_with_no_pk"
 
-               uid = Column(Integer, primary_key=True)
-               bar = Column(String, primary_key=True)
+        uid = Column(Integer, primary_key=True)
+        bar = Column(String, primary_key=True)
 
 All tables in a relational database should have primary keys.   Even a many-to-many
 association table - the primary key would be the composite of the two association
 columns::
 
-       CREATE TABLE my_association (
-         user_id INTEGER REFERENCES user(id),
-         account_id INTEGER REFERENCES account(id),
-         PRIMARY KEY (user_id, account_id)
-       )
+    CREATE TABLE my_association (
+      user_id INTEGER REFERENCES user(id),
+      account_id INTEGER REFERENCES account(id),
+      PRIMARY KEY (user_id, account_id)
+    )
 
 
 How do I configure a Column that is a Python reserved word or similar?
@@ -344,9 +373,9 @@ This information is all available from the :class:`.Mapper` object.
 To get at the :class:`.Mapper` for a particular mapped class, call the
 :func:`.inspect` function on it::
 
-       from sqlalchemy import inspect
+    from sqlalchemy import inspect
 
-       mapper = inspect(MyClass)
+    mapper = inspect(MyClass)
 
 From there, all information about the class can be acquired using such methods as:
 
@@ -378,43 +407,43 @@ I'm using Declarative and setting primaryjoin/secondaryjoin using an ``and_()``
 
 Are you doing this?::
 
-       class MyClass(Base):
-           # ....
+    class MyClass(Base):
+        # ....
 
-           foo = relationship("Dest", primaryjoin=and_("MyClass.id==Dest.foo_id", "MyClass.foo==Dest.bar"))
+        foo = relationship("Dest", primaryjoin=and_("MyClass.id==Dest.foo_id", "MyClass.foo==Dest.bar"))
 
 That's an ``and_()`` of two string expressions, which SQLAlchemy cannot apply any mapping towards.  Declarative allows :func:`.relationship` arguments to be specified as strings, which are converted into expression objects using ``eval()``.   But this doesn't occur inside of an ``and_()`` expression - it's a special operation declarative applies only to the *entirety* of what's passed to primaryjoin or other arguments as a string::
 
-       class MyClass(Base):
-           # ....
+    class MyClass(Base):
+        # ....
 
-           foo = relationship("Dest", primaryjoin="and_(MyClass.id==Dest.foo_id, MyClass.foo==Dest.bar)")
+        foo = relationship("Dest", primaryjoin="and_(MyClass.id==Dest.foo_id, MyClass.foo==Dest.bar)")
 
 Or if the objects you need are already available, skip the strings::
 
-       class MyClass(Base):
-           # ....
+    class MyClass(Base):
+        # ....
 
-           foo = relationship(Dest, primaryjoin=and_(MyClass.id==Dest.foo_id, MyClass.foo==Dest.bar))
+        foo = relationship(Dest, primaryjoin=and_(MyClass.id==Dest.foo_id, MyClass.foo==Dest.bar))
 
 The same idea applies to all the other arguments, such as ``foreign_keys``::
 
-       # wrong !
-       foo = relationship(Dest, foreign_keys=["Dest.foo_id", "Dest.bar_id"])
+    # wrong !
+    foo = relationship(Dest, foreign_keys=["Dest.foo_id", "Dest.bar_id"])
 
-       # correct !
-       foo = relationship(Dest, foreign_keys="[Dest.foo_id, Dest.bar_id]")
+    # correct !
+    foo = relationship(Dest, foreign_keys="[Dest.foo_id, Dest.bar_id]")
 
-       # also correct !
-       foo = relationship(Dest, foreign_keys=[Dest.foo_id, Dest.bar_id])
+    # also correct !
+    foo = relationship(Dest, foreign_keys=[Dest.foo_id, Dest.bar_id])
 
-       # if you're using columns from the class that you're inside of, just use the column objects !
-       class MyClass(Base):
-           foo_id = Column(...)
-           bar_id = Column(...)
-           # ...
+    # if you're using columns from the class that you're inside of, just use the column objects !
+    class MyClass(Base):
+        foo_id = Column(...)
+        bar_id = Column(...)
+        # ...
 
-           foo = relationship(Dest, foreign_keys=[foo_id, bar_id])
+        foo = relationship(Dest, foreign_keys=[foo_id, bar_id])
 
 Performance
 ===========
@@ -422,6 +451,11 @@ Performance
 How can I profile a SQLAlchemy powered application?
 ---------------------------------------------------
 
+Looking for performance issues typically involves two stratgies.  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 :func:`.create_engine`) can give an
@@ -446,6 +480,41 @@ the ORM "eager loading" typically means to use joins so that results across mult
 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::
+
+    from sqlalchemy import event
+    from sqlalchemy.engine import Engine
+    import time
+    import logging
+
+    logging.basicConfig()
+    logger = logging.getLogger("myapp.sqltime")
+    logger.setLevel(logging.DEBUG)
+
+    @event.listens_for(Engine, "before_cursor_execute")
+    def before_cursor_execute(conn, cursor, statement,
+                            parameters, context, executemany):
+        conn.info.setdefault('query_start_time', []).append(time.time())
+        logger.debug("Start Query: %s" % statement)
+
+    @event.listens_for(Engine, "after_cursor_execute")
+    def after_cursor_execute(conn, cursor, statement,
+                            parameters, context, executemany):
+        total = time.time() - conn.info['query_start_time'].pop(-1)
+        logger.debug("Query Complete!")
+        logger.debug("Total Time: %f" % total)
+
+Above, we use the :meth:`.ConnectionEvents.before_cursor_execute` and
+:meth:`.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 :class:`._ConnectionRecord.info` dictionary; we use a
+stack here for the occasional case where the cursor execute events may be nested.
+
+Code Profiling
+^^^^^^^^^^^^^^
+
 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
@@ -453,67 +522,184 @@ by the :term:`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 profiling, such as cProfile or hotshot.  Here is a
-decorator similar to that used by SQLAlchemy's test suite for performance
-metrics::
+For that you need to use the
+`Python Profiling Module <https://docs.python.org/2/library/profile.html>`_.
+Below is a simple recipe which works profiling into a context manager::
+
+    import cProfile
+    import StringIO
+    import pstats
+    import contextlib
+
+    @contextlib.contextmanager
+    def profiled():
+        pr = cProfile.Profile()
+        pr.enable()
+        yield
+        pr.disable()
+        s = StringIO.StringIO()
+        ps = pstats.Stats(pr, stream=s).sort_stats('cumulative')
+        ps.print_stats()
+        # uncomment this to see who's calling what
+        # ps.print_callers()
+        print s.getvalue()
+
+To profile a section of code::
+
+    with profiled():
+        Session.query(FooClass).filter(FooClass.somevalue==8).all()
 
-       import cProfile as profiler
-       import gc, pstats, time
+The output of profiling can be used to give an idea where time is
+being spent.   A section of profiling output looks like this::
 
-       def profile(fn):
-           def wrapper(*args, **kw):
-               elapsed, stat_loader, result = _profile("foo.txt", fn, *args, **kw)
-               stats = stat_loader()
-               stats.sort_stats('cumulative')
-               stats.print_stats()
-               # uncomment this to see who's calling what
-               # stats.print_callers()
-               return result
-           return wrapper
+    13726 function calls (13042 primitive calls) in 0.014 seconds
 
-       def _profile(filename, fn, *args, **kw):
-           load_stats = lambda: pstats.Stats(filename)
-           gc.collect()
+    Ordered by: cumulative time
 
-           began = time.time()
-           profiler.runctx('result = fn(*args, **kw)', globals(), locals(),
-                           filename=filename)
-           ended = time.time()
+    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
+    222/21    0.001    0.000    0.011    0.001 lib/sqlalchemy/orm/loading.py:26(instances)
+    220/20    0.002    0.000    0.010    0.001 lib/sqlalchemy/orm/loading.py:327(_instance)
+    220/20    0.000    0.000    0.010    0.000 lib/sqlalchemy/orm/loading.py:284(populate_state)
+       20    0.000    0.000    0.010    0.000 lib/sqlalchemy/orm/strategies.py:987(load_collection_from_subq)
+       20    0.000    0.000    0.009    0.000 lib/sqlalchemy/orm/strategies.py:935(get)
+        1    0.000    0.000    0.009    0.009 lib/sqlalchemy/orm/strategies.py:940(_load)
+       21    0.000    0.000    0.008    0.000 lib/sqlalchemy/orm/strategies.py:942(<genexpr>)
+        2    0.000    0.000    0.004    0.002 lib/sqlalchemy/orm/query.py:2400(__iter__)
+        2    0.000    0.000    0.002    0.001 lib/sqlalchemy/orm/query.py:2414(_execute_and_instances)
+        2    0.000    0.000    0.002    0.001 lib/sqlalchemy/engine/base.py:659(execute)
+        2    0.000    0.000    0.002    0.001 lib/sqlalchemy/sql/elements.py:321(_execute_on_connection)
+        2    0.000    0.000    0.002    0.001 lib/sqlalchemy/engine/base.py:788(_execute_clauseelement)
 
-           return ended - began, load_stats, locals()['result']
+    ...
 
-To profile a section of code, place it in a function with the decorator::
+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.
 
-    @profile
-    def go():
-        return Session.query(FooClass).filter(FooClass.somevalue==8).all()
-    myfoos = go()
+Execution Slowness
+^^^^^^^^^^^^^^^^^^
 
-The output of profiling can be used to give an idea where time is
-being spent.  If for example you see all the time being spent within
-``cursor.execute()``, that's the low level DBAPI call to the database,
-and it means your query should be optimized, either by adding indexes
+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::
+
+    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.
 
-If you see many thousands of calls related to fetching rows, it may
-mean your query is returning more rows than expected - a cartesian
-product as a result of an incomplete join can cause this issue.   Yet
-another issue is time spent within type handling - a SQLAlchemy type
-such as :class:`.Unicode` will perform string encoding/decoding on bind
-parameters and result columns, which may not be  needed in all cases,
-and in some cases some backends might be doing work like this erroneously.
-Make sure to check the :doc:`Dialect documentation <dialects/index>` for notes
-on known performance issues, especially for databases like Oracle.
+Result Fetching Slowness - Core
+^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
+
+If on the other hand you see many thousands of calls related to fetching rows,
+or very long calls to ``fetchall()``, it may
+mean your query is returning more rows than expected, or that the fetching
+of rows itself is slow.   The ORM itself typically uses ``fetchall()`` to fetch
+rows (or ``fetchmany()`` if the :meth:`.Query.yield_per` option is used).
+
+An inordinately large number of rows would be indicated
+by a very slow call to ``fetchall()`` at the DBAPI level::
+
+    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 :class:`.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 :class:`.ResultProxy` is asked to do a ``fetchall()``,
+may indicate slowness in processing of datatypes, such as unicode conversions
+and similar::
+
+    # the DBAPI cursor is fast...
+    2    0.020    0.040    0.020    0.040 {method 'fetchall' of 'sqlite3.Cursor' objects}
+
+    ...
+
+    # but SQLAlchemy's result proxy is slow, this is type-level processing
+    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::
+
+    from sqlalchemy import TypeDecorator
+    import time
+
+    class Foo(TypeDecorator):
+        impl = String
+
+        def process_result_value(self, value, thing):
+            # intentionally add slowness for illustration purposes
+            time.sleep(.001)
+            return value
+
+the profiling output of this intentionally slow operation can be seen like this::
+
+      200    0.001    0.000    0.237    0.001 lib/sqlalchemy/sql/type_api.py:911(process)
+      200    0.001    0.000    0.236    0.001 test.py:28(process_result_value)
+      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 :doc:`Dialect documentation <dialects/index>`
+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::
+
+    # the ORM calls _instance for each ORM-loaded row it sees, and
+    # populate_state for each ORM-loaded row that results in the population
+    # of an object's attributes
+    220/20    0.001    0.000    0.010    0.000 lib/sqlalchemy/orm/loading.py:327(_instance)
+    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, not rows, that is::
+
+      session.query(User.id, User.name)
+
+  instead of::
+
+      session.query(User)
+
+* Use :class:`.Bundle` objects to organize column-based results::
+
+      u_b = Bundle('user', User.id, User.name)
+      a_b = Bundle('address', Address.id, Address.email)
+
+      for user, address in session.query(u_b, a_b).join(User.addresses):
+          # ...
+
+* Use result caching - see :ref:`examples_caching` for an in-depth example
+  of this.
+
+* Consider a faster interpreter like that of Pypy.
 
 The output of a profile can be a little daunting but after some
-practice they are very easy to read.   There was once someone on the
-mailing list claiming slowness, and after having him post the results
-of profile, I was able to demonstrate that the speed problems were due
-to network latency - the time spent within cursor.execute() as well as
-all Python methods was very fast, whereas the majority of time was
-spent on socket.receive().
+practice they are very easy to read.
 
 If you're feeling ambitious, there's also a more involved example of
 SQLAlchemy profiling within the SQLAlchemy unit tests in the
@@ -562,106 +748,106 @@ The example below illustrates time-based tests for four different
 methods of inserting rows, going from the most automated to the least.
 With cPython 2.7, runtimes observed::
 
-       classics-MacBook-Pro:sqlalchemy classic$ python test.py
-       SQLAlchemy ORM: Total time for 100000 records 14.3528850079 secs
-       SQLAlchemy ORM pk given: Total time for 100000 records 10.0164160728 secs
-       SQLAlchemy Core: Total time for 100000 records 0.775382995605 secs
-       sqlite3: Total time for 100000 records 0.676795005798 sec
+    classics-MacBook-Pro:sqlalchemy classic$ python test.py
+    SQLAlchemy ORM: Total time for 100000 records 14.3528850079 secs
+    SQLAlchemy ORM pk given: Total time for 100000 records 10.0164160728 secs
+    SQLAlchemy Core: Total time for 100000 records 0.775382995605 secs
+    sqlite3: Total time for 100000 records 0.676795005798 sec
 
 We can reduce the time by a factor of three using recent versions of `Pypy <http://pypy.org/>`_::
 
-       classics-MacBook-Pro:sqlalchemy classic$ /usr/local/src/pypy-2.1-beta2-osx64/bin/pypy test.py
-       SQLAlchemy ORM: Total time for 100000 records 5.88369488716 secs
-       SQLAlchemy ORM pk given: Total time for 100000 records 3.52294301987 secs
-       SQLAlchemy Core: Total time for 100000 records 0.613556146622 secs
-       sqlite3: Total time for 100000 records 0.442467927933 sec
+    classics-MacBook-Pro:sqlalchemy classic$ /usr/local/src/pypy-2.1-beta2-osx64/bin/pypy test.py
+    SQLAlchemy ORM: Total time for 100000 records 5.88369488716 secs
+    SQLAlchemy ORM pk given: Total time for 100000 records 3.52294301987 secs
+    SQLAlchemy Core: Total time for 100000 records 0.613556146622 secs
+    sqlite3: Total time for 100000 records 0.442467927933 sec
 
 Script::
 
-       import time
-       import sqlite3
-
-       from sqlalchemy.ext.declarative import declarative_base
-       from sqlalchemy import Column, Integer, String,  create_engine
-       from sqlalchemy.orm import scoped_session, sessionmaker
-
-       Base = declarative_base()
-       DBSession = scoped_session(sessionmaker())
-       engine = None
-
-       class Customer(Base):
-           __tablename__ = "customer"
-           id = Column(Integer, primary_key=True)
-           name = Column(String(255))
-
-       def init_sqlalchemy(dbname='sqlite:///sqlalchemy.db'):
-           global engine
-           engine = create_engine(dbname, echo=False)
-           DBSession.remove()
-           DBSession.configure(bind=engine, autoflush=False, expire_on_commit=False)
-           Base.metadata.drop_all(engine)
-           Base.metadata.create_all(engine)
-
-       def test_sqlalchemy_orm(n=100000):
-           init_sqlalchemy()
-           t0 = time.time()
-           for i in range(n):
-               customer = Customer()
-               customer.name = 'NAME ' + str(i)
-               DBSession.add(customer)
-               if i % 1000 == 0:
-                   DBSession.flush()
-           DBSession.commit()
-           print("SQLAlchemy ORM: Total time for " + str(n) +
-                       " records " + str(time.time() - t0) + " secs")
-
-       def test_sqlalchemy_orm_pk_given(n=100000):
-           init_sqlalchemy()
-           t0 = time.time()
-           for i in range(n):
-               customer = Customer(id=i+1, name="NAME " + str(i))
-               DBSession.add(customer)
-               if i % 1000 == 0:
-                   DBSession.flush()
-           DBSession.commit()
-           print("SQLAlchemy ORM pk given: Total time for " + str(n) +
-               " records " + str(time.time() - t0) + " secs")
-
-       def test_sqlalchemy_core(n=100000):
-           init_sqlalchemy()
-           t0 = time.time()
-           engine.execute(
-               Customer.__table__.insert(),
-               [{"name": 'NAME ' + str(i)} for i in range(n)]
-           )
-           print("SQLAlchemy Core: Total time for " + str(n) +
-               " records " + str(time.time() - t0) + " secs")
-
-       def init_sqlite3(dbname):
-           conn = sqlite3.connect(dbname)
-           c = conn.cursor()
-           c.execute("DROP TABLE IF EXISTS customer")
-           c.execute("CREATE TABLE customer (id INTEGER NOT NULL, "
-                                       "name VARCHAR(255), PRIMARY KEY(id))")
-           conn.commit()
-           return conn
-
-       def test_sqlite3(n=100000, dbname='sqlite3.db'):
-           conn = init_sqlite3(dbname)
-           c = conn.cursor()
-           t0 = time.time()
-           for i in range(n):
-               row = ('NAME ' + str(i),)
-               c.execute("INSERT INTO customer (name) VALUES (?)", row)
-           conn.commit()
-           print("sqlite3: Total time for " + str(n) +
-               " records " + str(time.time() - t0) + " sec")
-
-       if __name__ == '__main__':
-           test_sqlalchemy_orm(100000)
-           test_sqlalchemy_orm_pk_given(100000)
-           test_sqlalchemy_core(100000)
-           test_sqlite3(100000)
+    import time
+    import sqlite3
+
+    from sqlalchemy.ext.declarative import declarative_base
+    from sqlalchemy import Column, Integer, String,  create_engine
+    from sqlalchemy.orm import scoped_session, sessionmaker
+
+    Base = declarative_base()
+    DBSession = scoped_session(sessionmaker())
+    engine = None
+
+    class Customer(Base):
+        __tablename__ = "customer"
+        id = Column(Integer, primary_key=True)
+        name = Column(String(255))
+
+    def init_sqlalchemy(dbname='sqlite:///sqlalchemy.db'):
+        global engine
+        engine = create_engine(dbname, echo=False)
+        DBSession.remove()
+        DBSession.configure(bind=engine, autoflush=False, expire_on_commit=False)
+        Base.metadata.drop_all(engine)
+        Base.metadata.create_all(engine)
+
+    def test_sqlalchemy_orm(n=100000):
+        init_sqlalchemy()
+        t0 = time.time()
+        for i in range(n):
+            customer = Customer()
+            customer.name = 'NAME ' + str(i)
+            DBSession.add(customer)
+            if i % 1000 == 0:
+                DBSession.flush()
+        DBSession.commit()
+        print("SQLAlchemy ORM: Total time for " + str(n) +
+                    " records " + str(time.time() - t0) + " secs")
+
+    def test_sqlalchemy_orm_pk_given(n=100000):
+        init_sqlalchemy()
+        t0 = time.time()
+        for i in range(n):
+            customer = Customer(id=i+1, name="NAME " + str(i))
+            DBSession.add(customer)
+            if i % 1000 == 0:
+                DBSession.flush()
+        DBSession.commit()
+        print("SQLAlchemy ORM pk given: Total time for " + str(n) +
+            " records " + str(time.time() - t0) + " secs")
+
+    def test_sqlalchemy_core(n=100000):
+        init_sqlalchemy()
+        t0 = time.time()
+        engine.execute(
+            Customer.__table__.insert(),
+            [{"name": 'NAME ' + str(i)} for i in range(n)]
+        )
+        print("SQLAlchemy Core: Total time for " + str(n) +
+            " records " + str(time.time() - t0) + " secs")
+
+    def init_sqlite3(dbname):
+        conn = sqlite3.connect(dbname)
+        c = conn.cursor()
+        c.execute("DROP TABLE IF EXISTS customer")
+        c.execute("CREATE TABLE customer (id INTEGER NOT NULL, "
+                                    "name VARCHAR(255), PRIMARY KEY(id))")
+        conn.commit()
+        return conn
+
+    def test_sqlite3(n=100000, dbname='sqlite3.db'):
+        conn = init_sqlite3(dbname)
+        c = conn.cursor()
+        t0 = time.time()
+        for i in range(n):
+            row = ('NAME ' + str(i),)
+            c.execute("INSERT INTO customer (name) VALUES (?)", row)
+        conn.commit()
+        print("sqlite3: Total time for " + str(n) +
+            " records " + str(time.time() - t0) + " sec")
+
+    if __name__ == '__main__':
+        test_sqlalchemy_orm(100000)
+        test_sqlalchemy_orm_pk_given(100000)
+        test_sqlalchemy_core(100000)
+        test_sqlite3(100000)
 
 
 
@@ -680,43 +866,43 @@ It usually corresponds to an application that catches an exception
 upon :meth:`.Session.flush` or :meth:`.Session.commit` and
 does not properly handle the exception.    For example::
 
-       from sqlalchemy import create_engine, Column, Integer
-       from sqlalchemy.orm import sessionmaker
-       from sqlalchemy.ext.declarative import declarative_base
+    from sqlalchemy import create_engine, Column, Integer
+    from sqlalchemy.orm import sessionmaker
+    from sqlalchemy.ext.declarative import declarative_base
 
-       Base = declarative_base(create_engine('sqlite://'))
+    Base = declarative_base(create_engine('sqlite://'))
 
-       class Foo(Base):
-           __tablename__ = 'foo'
-           id = Column(Integer, primary_key=True)
+    class Foo(Base):
+        __tablename__ = 'foo'
+        id = Column(Integer, primary_key=True)
 
-       Base.metadata.create_all()
+    Base.metadata.create_all()
 
-       session = sessionmaker()()
+    session = sessionmaker()()
 
-       # constraint violation
-       session.add_all([Foo(id=1), Foo(id=1)])
+    # constraint violation
+    session.add_all([Foo(id=1), Foo(id=1)])
 
-       try:
-           session.commit()
-       except:
-           # ignore error
-           pass
+    try:
+        session.commit()
+    except:
+        # ignore error
+        pass
 
-       # continue using session without rolling back
-       session.commit()
+    # continue using session without rolling back
+    session.commit()
 
 
 The usage of the :class:`.Session` should fit within a structure similar to this::
 
-       try:
-           <use session>
-           session.commit()
-       except:
-          session.rollback()
-          raise
-       finally:
-          session.close()  # optional, depends on use case
+    try:
+        <use session>
+        session.commit()
+    except:
+       session.rollback()
+       raise
+    finally:
+       session.close()  # optional, depends on use case
 
 Many things can cause a failure within the try/except besides flushes. You
 should always have some kind of "framing" of your session operations so that
@@ -742,21 +928,21 @@ decreased by the fact that many database operations require a ROLLBACK in any
 case. Postgres in particular has operations which, once failed, the
 transaction is not allowed to continue::
 
-       test=> create table foo(id integer primary key);
-       NOTICE:  CREATE TABLE / PRIMARY KEY will create implicit index "foo_pkey" for table "foo"
-       CREATE TABLE
-       test=> begin;
-       BEGIN
-       test=> insert into foo values(1);
-       INSERT 0 1
-       test=> commit;
-       COMMIT
-       test=> begin;
-       BEGIN
-       test=> insert into foo values(1);
-       ERROR:  duplicate key value violates unique constraint "foo_pkey"
-       test=> insert into foo values(2);
-       ERROR:  current transaction is aborted, commands ignored until end of transaction block
+    test=> create table foo(id integer primary key);
+    NOTICE:  CREATE TABLE / PRIMARY KEY will create implicit index "foo_pkey" for table "foo"
+    CREATE TABLE
+    test=> begin;
+    BEGIN
+    test=> insert into foo values(1);
+    INSERT 0 1
+    test=> commit;
+    COMMIT
+    test=> begin;
+    BEGIN
+    test=> insert into foo values(1);
+    ERROR:  duplicate key value violates unique constraint "foo_pkey"
+    test=> insert into foo values(2);
+    ERROR:  current transaction is aborted, commands ignored until end of transaction block
 
 What SQLAlchemy offers that solves both issues is support of SAVEPOINT, via
 :meth:`.Session.begin_nested`. Using :meth:`.Session.begin_nested`, you can frame an operation that may
@@ -771,17 +957,17 @@ refusing to guess about what context its being used. For example, the
 :class:`.Session` supports "framing" above within multiple levels. Such as, suppose
 you had a decorator ``@with_session()``, which did this::
 
-       def with_session(fn):
-          def go(*args, **kw):
-              session.begin(subtransactions=True)
-              try:
-                  ret = fn(*args, **kw)
-                  session.commit()
-                  return ret
-              except:
-                  session.rollback()
-                  raise
-          return go
+    def with_session(fn):
+       def go(*args, **kw):
+           session.begin(subtransactions=True)
+           try:
+               ret = fn(*args, **kw)
+               session.commit()
+               return ret
+           except:
+               session.rollback()
+               raise
+       return go
 
 The above decorator begins a transaction if one does not exist already, and
 then commits it, if it were the creator. The "subtransactions" flag means that
@@ -790,19 +976,19 @@ except a counter is incremented - this counter is decremented when :meth:`.Sessi
 is called and only when it goes back to zero does the actual COMMIT happen. It
 allows this usage pattern::
 
-       @with_session
-       def one():
-          # do stuff
-          two()
+    @with_session
+    def one():
+       # do stuff
+       two()
 
 
-       @with_session
-       def two():
-          # etc.
+    @with_session
+    def two():
+       # etc.
 
-       one()
+    one()
 
-       two()
+    two()
 
 ``one()`` can call ``two()``, or ``two()`` can be called by itself, and the
 ``@with_session`` decorator ensures the appropriate "framing" - the transaction
@@ -876,21 +1062,21 @@ method, which emits a `SELECT COUNT`. The reason this is not possible is
 because evaluating the query as a list would incur two SQL calls instead of
 one::
 
-       class Iterates(object):
-           def __len__(self):
-               print "LEN!"
-               return 5
+    class Iterates(object):
+        def __len__(self):
+            print "LEN!"
+            return 5
 
-           def __iter__(self):
-               print "ITER!"
-               return iter([1, 2, 3, 4, 5])
+        def __iter__(self):
+            print "ITER!"
+            return iter([1, 2, 3, 4, 5])
 
-       list(Iterates())
+    list(Iterates())
 
 output::
 
-       ITER!
-       LEN!
+    ITER!
+    LEN!
 
 How Do I use Textual SQL with ORM Queries?
 -------------------------------------------
@@ -933,81 +1119,81 @@ ORM behind the scenes, the end user sets up object
 relationships naturally. Therefore, the recommended way to
 set ``o.foo`` is to do just that - set it!::
 
-       foo = Session.query(Foo).get(7)
-       o.foo = foo
-       Session.commit()
+    foo = Session.query(Foo).get(7)
+    o.foo = foo
+    Session.commit()
 
 Manipulation of foreign key attributes is of course entirely legal.  However,
 setting a foreign-key attribute to a new value currently does not trigger
 an "expire" event of the :func:`.relationship` in which it's involved.  This means
 that for the following sequence::
 
-       o = Session.query(SomeClass).first()
-       assert o.foo is None  # accessing an un-set attribute sets it to None
-       o.foo_id = 7
+    o = Session.query(SomeClass).first()
+    assert o.foo is None  # accessing an un-set attribute sets it to None
+    o.foo_id = 7
 
 ``o.foo`` is initialized to ``None`` when we first accessed it.  Setting
 ``o.foo_id = 7`` will have the value of "7" as pending, but no flush
 has occurred - so ``o.foo`` is still ``None``::
 
-       # attribute is already set to None, has not been
-       # reconciled with o.foo_id = 7 yet
-       assert o.foo is None
+    # attribute is already set to None, has not been
+    # reconciled with o.foo_id = 7 yet
+    assert o.foo is None
 
 For ``o.foo`` to load based on the foreign key mutation is usually achieved
 naturally after the commit, which both flushes the new foreign key value
 and expires all state::
 
-       Session.commit()  # expires all attributes
+    Session.commit()  # expires all attributes
 
-       foo_7 = Session.query(Foo).get(7)
+    foo_7 = Session.query(Foo).get(7)
 
-       assert o.foo is foo_7  # o.foo lazyloads on access
+    assert o.foo is foo_7  # o.foo lazyloads on access
 
 A more minimal operation is to expire the attribute individually - this can
 be performed for any :term:`persistent` object using :meth:`.Session.expire`::
 
-       o = Session.query(SomeClass).first()
-       o.foo_id = 7
-       Session.expire(o, ['foo'])  # object must be persistent for this
+    o = Session.query(SomeClass).first()
+    o.foo_id = 7
+    Session.expire(o, ['foo'])  # object must be persistent for this
 
-       foo_7 = Session.query(Foo).get(7)
+    foo_7 = Session.query(Foo).get(7)
 
-       assert o.foo is foo_7  # o.foo lazyloads on access
+    assert o.foo is foo_7  # o.foo lazyloads on access
 
 Note that if the object is not persistent but present in the :class:`.Session`,
 it's known as :term:`pending`.   This means the row for the object has not been
 INSERTed into the database yet.  For such an object, setting ``foo_id`` does not
 have meaning until the row is inserted; otherwise there is no row yet::
 
-       new_obj = SomeClass()
-       new_obj.foo_id = 7
+    new_obj = SomeClass()
+    new_obj.foo_id = 7
 
-       Session.add(new_obj)
+    Session.add(new_obj)
 
-       # accessing an un-set attribute sets it to None
-       assert new_obj.foo is None
+    # accessing an un-set attribute sets it to None
+    assert new_obj.foo is None
 
-       Session.flush()  # emits INSERT
+    Session.flush()  # emits INSERT
 
-       # expire this because we already set .foo to None
-       Session.expire(o, ['foo'])
+    # expire this because we already set .foo to None
+    Session.expire(o, ['foo'])
 
-       assert new_obj.foo is foo_7  # now it loads
+    assert new_obj.foo is foo_7  # now it loads
 
 
 .. topic:: Attribute loading for non-persistent objects
 
-       One variant on the "pending" behavior above is if we use the flag
-       ``load_on_pending`` on :func:`.relationship`.   When this flag is set, the
-       lazy loader will emit for ``new_obj.foo`` before the INSERT proceeds; another
-       variant of this is to use the :meth:`.Session.enable_relationship_loading`
-       method, which can "attach" an object to a :class:`.Session` in such a way that
-       many-to-one relationships load as according to foreign key attributes
-       regardless of the object being in any particular state.
-       Both techniques are **not recommended for general use**; they were added to suit
-       specific programming scenarios encountered by users which involve the repurposing
-       of the ORM's usual object states.
+    One variant on the "pending" behavior above is if we use the flag
+    ``load_on_pending`` on :func:`.relationship`.   When this flag is set, the
+    lazy loader will emit for ``new_obj.foo`` before the INSERT proceeds; another
+    variant of this is to use the :meth:`.Session.enable_relationship_loading`
+    method, which can "attach" an object to a :class:`.Session` in such a way that
+    many-to-one relationships load as according to foreign key attributes
+    regardless of the object being in any particular state.
+    Both techniques are **not recommended for general use**; they were added to suit
+    specific programming scenarios encountered by users which involve the repurposing
+    of the ORM's usual object states.
 
 The recipe `ExpireRelationshipOnFKChange <http://www.sqlalchemy.org/trac/wiki/UsageRecipes/ExpireRelationshipOnFKChange>`_ features an example using SQLAlchemy events
 in order to coordinate the setting of foreign key attributes with many-to-one