How to debug slow start-up time for SQLAlchemy queries?

Question

I'm trying to diagnose where my application is spending time in executing SQL Alchemy queries. I've observed a 300ms interval between executing a query and the start of the SQLAlchemy transaction. In this interval there are no logs to report what is happening under-the-hood. I have the following snippet which creates a new scoped-session and then uses the session to lookup an item by primary key. This operation is taking about 500ms.

Could anyone suggest how I could speed up this lookup? The 375ms its taking to start executing the query is where my real concern is.

Function snippet:

def review_item(review_id):
    """Review a specific item."""        
    logger.info('Creating a new DB session')
    session = m.DBSession()
    logger.debug('Session created')

    logger.info('Building query at %s', review_id, datetime.now())
    qry = session.query(m.Result).filter_by(image_id=review_id)
    logger.info('Running query')
    item = qry.one()
    logger.info('Retrieved item %s at %s', item, datetime.now())

    return item

I see the following log output:

2015-10-19 13:51:06,874 INFO  [treachery.views][waitress] Creating a new DB session
2015-10-19 13:51:06,874 DEBUG [treachery.views][waitress] Session created
2015-10-19 13:51:06,875 INFO  [treachery.views][waitress] Building query at 2015-10-19 13:51:06.875089
2015-10-19 13:51:06,875 INFO  [treachery.views][waitress] Running query
2015-10-19 13:51:07,261 INFO  [sqlalchemy.engine.base.Engine][waitress] BEGIN (implicit)
2015-10-19 13:51:07,262 INFO  [sqlalchemy.engine.base.Engine][waitress] SELECT result.image_id AS result_image_id, result.tag_classes AS result_tag_classes, result.tag_probs AS result_tag_probs 
 FROM result 
 WHERE result.image_id = %(image_id_1)s
2015-10-19 13:51:07,262 INFO  [sqlalchemy.engine.base.Engine][waitress] {'image_id_1': u'2015/05/e1f04824d496457cb74b668976b991ef.jpeg'}
2015-10-19 13:51:07,372 DEBUG [sqlalchemy.engine.base.Engine][waitress] Col ('result_image_id', 'result_tag_classes', 'result_tag_probs')
2015-10-19 13:51:07,373 DEBUG [sqlalchemy.engine.base.Engine][waitress] Row (u'2015/05/e1f04824d496457cb74b668976b991ef.jpeg', [u'nobody', u'painting', u'decoration', u'indoors', u'food', u'pattern', u'frame', u'one', u'travel', u'illustration', u'hanging', u'wood', u'background', u'people', u'wall', u'table', u'design', u'exhibition', u'house', u'flower'], [0.989168643951416, 0.975763559341431, 0.96831738948822, 0.952613711357117, 0.945497691631317, 0.941344261169434, 0.932282328605652, 0.928139090538025, 0.926733613014221, 0.912606000900269, 0.883346319198608, 0.875022172927856, 0.871710419654846, 0.865160286426544, 0.86181652545929, 0.821693539619446, 0.810265898704529, 0.798673629760742, 0.796967625617981, 0.789543986320496])
2015-10-19 13:51:07,373 DEBUG [treachery.views][waitress] Retrieved item <treachery.models.Result object at 0x7f82b409a250> at 2015-10-19 13:51:07.373463

Observe the long delay (almost 400ms) between the log-line "Running query" and "the BEGIN(implicit)" log-line when the query starts executing.

Answer 1

SQLAlchemy connects to the database lazily, so if the above code is the very first SQL query that runs in the app then it would need to create a new connection, which for many RDBMSes is a quite slow operation.

I my guess is correct then subsequent calls to the same function should not have that 400ms delay.

Here's a question at serverfault discussing various causes of MySQL being slow to open new connections.