Merge pull request #3625 from dannon/backport_query_logging

[17.01] Usable slow query logging

config/galaxy.ini.sample

@@ -117,6 +117,11 @@ paste.app_factory = galaxy.web.buildapp:app_factory
 # 'galaxy.model.orm.logging_connection_proxy'
 #database_query_profiling_proxy = False
 
+# Slow query logging.  Queries slower than the threshold indicated below will
+# be logged to debug.  A value of '0' is disabled.  For example, you would set
+# this to .005 to log all queries taking longer than 5 milliseconds
+# slow_query_log_threshold = 0
+
 # By default, Galaxy will use the same database to track user data and
 # tool shed install data.  There are many situations in which it is
 # valuable to separate these - for instance bootstrapping fresh Galaxy

lib/galaxy/config.py

@@ -123,6 +123,7 @@ class Configuration( object ):
         self.database_engine_options = get_database_engine_options( kwargs )
         self.database_create_tables = string_as_bool( kwargs.get( "database_create_tables", "True" ) )
         self.database_query_profiling_proxy = string_as_bool( kwargs.get( "database_query_profiling_proxy", "False" ) )
+        self.slow_query_log_threshold = float( kwargs.get( "slow_query_log_threshold", 0) )
 
         # Don't set this to true for production databases, but probably should
         # default to True for sqlite databases.
@@ -1037,7 +1038,8 @@ class ConfiguresGalaxyMixin:
                                    database_query_profiling_proxy=self.config.database_query_profiling_proxy,
                                    object_store=self.object_store,
                                    trace_logger=getattr(self, "trace_logger", None),
-                                   use_pbkdf2=self.config.get_bool( 'use_pbkdf2', True ) )
+                                   use_pbkdf2=self.config.get_bool( 'use_pbkdf2', True ),
+                                   slow_query_log_threshold=self.config.slow_query_log_threshold )
 
         if combined_install_database:
             log.info("Install database targetting Galaxy's database configuration.")

lib/galaxy/model/mapping.py

@@ -2564,7 +2564,8 @@ model.WorkflowInvocation.update = _workflow_invocation_update
 
 
 def init( file_path, url, engine_options={}, create_tables=False, map_install_models=False,
-        database_query_profiling_proxy=False, object_store=None, trace_logger=None, use_pbkdf2=True ):
+        database_query_profiling_proxy=False, object_store=None, trace_logger=None, use_pbkdf2=True,
+        slow_query_log_threshold=0):
     """Connect mappings to the database"""
     # Connect dataset to the file path
     model.Dataset.file_path = file_path
@@ -2573,7 +2574,7 @@ def init( file_path, url, engine_options={}, create_tables=False, map_install_mo
     # Use PBKDF2 password hashing?
     model.User.use_pbkdf2 = use_pbkdf2
     # Load the appropriate db module
-    engine = build_engine( url, engine_options, database_query_profiling_proxy, trace_logger )
+    engine = build_engine( url, engine_options, database_query_profiling_proxy, trace_logger, slow_query_log_threshold )
 
     # Connect the metadata to the database.
     metadata.bind = engine

lib/galaxy/model/orm/engine_factory.py

@@ -1,10 +1,13 @@
 import logging
+import time
+
+from sqlalchemy import create_engine, event
+from sqlalchemy.engine import Engine
+
 log = logging.getLogger( __name__ )
 
-from sqlalchemy import create_engine
 
-
-def build_engine(url, engine_options, database_query_profiling_proxy=False, trace_logger=None):
+def build_engine(url, engine_options, database_query_profiling_proxy=False, trace_logger=None, slow_query_log_threshold=0):
     # Should we use the logging proxy?
     if database_query_profiling_proxy:
         import galaxy.model.orm.logging_connection_proxy as logging_connection_proxy
@@ -15,6 +18,18 @@ def build_engine(url, engine_options, database_query_profiling_proxy=False, trac
         proxy = logging_connection_proxy.TraceLoggerProxy( trace_logger )
     else:
         proxy = None
+    if slow_query_log_threshold:
+        @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())
+
+        @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)
+            if total > slow_query_log_threshold:
+                log.debug("Slow query: %f(s) for %s" % (total, statement))
 
     # Create the database engine
     engine = create_engine( url, proxy=proxy, **engine_options )