title: sqlalchemy logs show slower requests than postgres logs
body: <p>this is my Flask-sqlalchemy code that's constantly polling for some data:</p>
  
  <pre><code>start_time = datetime.now()
  query = Controller.query
  sid = request.args.get('sid', "", type=str)
  if sid:
      safe_sid = sanitize_user_input(sid, escape="/")
      query = query.filter(Controller.sid.startswith(safe_sid, escape="/"))
  else:
      query = query.filter(Controller.sid != None)
  if 'name' in request.args:
      query = query.name_like(request.args['name'])
  head = request.args.get('head', 0, type=int)
  if head == 1:
      query = query.head_only()
  query = query.options(joinedload('monitors'), joinedload('maintenance'))
  query = query.order_by(Controller.id)
  controllers = query.all()
  logger.info('controllers/ delta after query: {}'.format(str(datetime.now()-start_time)))
  </code></pre>
  
  <p>it shows the following times in the log:</p>
  
  <pre><code>2015-07-12T01:16:34 controllers/ delta after query: 0:00:00.850631
  2015-07-12T01:16:37 controllers/ delta after query: 0:00:00.859993
  </code></pre>
  
  <p>so basically it's about 900 ms.</p>
  
  <p>However, when I look at postgres logs I see much smaller values:</p>
  
  <pre><code>2015-07-12 01:16:33.400 EDT &gt;LOG:  duration: 136.405 ms  statement:
  SELECT controller.sid AS controller_sid, controller.id AS controller_id,
      controller.type AS controller_type, controller.name AS controller_name,
      controller.description AS controller_description, controller.address AS controller_address,
      controller.last_response AS controller_last_response, controller.gis_id AS controller_gis_id,
      controller.tag AS controller_tag, controller.parent_id AS controller_parent_id,
      controller.rdp_id AS controller_rdp_id, controller.root_node_id AS controller_root_node_id,
      asuno_roles_1.id AS asuno_roles_1_id, asuno_roles_1.slug AS asuno_roles_1_slug,
      asuno_roles_1.name AS asuno_roles_1_name, asuno_roles_1.description AS asuno_roles_1_description,
      asuno_users_1.id AS asuno_users_1_id, asuno_users_1.name AS asuno_users_1_name,
      asuno_users_1.username AS asuno_users_1_username, asuno_users_1.password_hash AS asuno_users_1_password_hash,
      asuno_users_1.active AS asuno_users_1_active, rdp_dispatcher_1.user_id AS rdp_dispatcher_1_user_id,
      rdp_dispatcher_1.rdp_id AS rdp_dispatcher_1_rdp_id, maintenance_1.id AS maintenance_1_id,
      maintenance_1.date_from AS maintenance_1_date_from, maintenance_1.date_to AS maintenance_1_date_to,
      maintenance_1.reason AS maintenance_1_reason, maintenance_1.controller_id AS maintenance_1_controller_id,
      maintenance_1.user_id AS maintenance_1_user_id, controller_monitor_1.id AS controller_monitor_1_id,
      controller_monitor_1.sid AS controller_monitor_1_sid,
      controller_monitor_1.node_type AS controller_monitor_1_node_type,
      controller_monitor_1.name AS controller_monitor_1_name,
      controller_monitor_1.tag AS controller_monitor_1_tag,
      controller_monitor_1.denotation AS controller_monitor_1_denotation,
      controller_monitor_1.alias AS controller_monitor_1_alias,
      controller_monitor_1.controller_id AS controller_monitor_1_controller_id,
      controller_monitor_1.value AS controller_monitor_1_value,
      controller_monitor_1.silent AS controller_monitor_1_silent,
      controller_monitor_1.last_reading_timestamp AS controller_monitor_1_last_reading_timestamp,
      controller_monitor_1.payload AS controller_monitor_1_payload
  
  FROM controller LEFT OUTER JOIN maintenance AS maintenance_1 ON controller.id = maintenance_1.controller_id 
      AND maintenance_1.date_from &lt;= TIMEZONE('utc', CURRENT_TIMESTAMP) 
      AND maintenance_1.date_to &gt;= TIMEZONE('utc', CURRENT_TIMESTAMP) 
      LEFT OUTER JOIN asuno_users AS asuno_users_1 ON asuno_users_1.id = maintenance_1.user_id
      LEFT OUTER JOIN (roles_users AS roles_users_1 
      JOIN asuno_roles AS asuno_roles_1 ON asuno_roles_1.id = roles_users_1.role_id) 
      ON asuno_users_1.id = roles_users_1.user_id 
      LEFT OUTER JOIN rdp_dispatcher AS rdp_dispatcher_1 ON asuno_users_1.id = rdp_dispatcher_1.user_id 
      LEFT OUTER JOIN controller_monitor AS controller_monitor_1 ON controller.id = controller_monitor_1.controller_id
  
  
  WHERE (controller.sid LIKE 'obekty-no:artiukhinoi' || '%' ESCAPE '/') 
      AND controller.parent_id IS NULL ORDER BY controller.id, maintenance_1.date_from
  </code></pre>
  
  <p>Where do the extra 600ms come from?</p>