From 792bd4f8835e9aef355a904b773f208a022e5e95 Mon Sep 17 00:00:00 2001 From: Dannon Baker Date: Wed, 15 Feb 2017 10:06:36 -0500 Subject: [PATCH 1/5] Implementation of slow query logging. Disabled by default. --- lib/galaxy/config.py | 4 +++- lib/galaxy/model/mapping.py | 5 +++-- lib/galaxy/model/orm/engine_factory.py | 21 +++++++++++++++++---- 3 files changed, 23 insertions(+), 7 deletions(-) diff --git a/lib/galaxy/config.py b/lib/galaxy/config.py index 4fb2a53a8ac..042361e637c 100644 --- a/lib/galaxy/config.py +++ b/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.") diff --git a/lib/galaxy/model/mapping.py b/lib/galaxy/model/mapping.py index 890262232a4..c691eba0128 100644 --- a/lib/galaxy/model/mapping.py +++ b/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 diff --git a/lib/galaxy/model/orm/engine_factory.py b/lib/galaxy/model/orm/engine_factory.py index 4183e985e54..85684e18d6c 100644 --- a/lib/galaxy/model/orm/engine_factory.py +++ b/lib/galaxy/model/orm/engine_factory.py @@ -1,10 +1,11 @@ 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 +16,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 ) From 9135226ae40dd2222172fd6883511f682c72f7a4 Mon Sep 17 00:00:00 2001 From: Dannon Baker Date: Wed, 15 Feb 2017 10:08:52 -0500 Subject: [PATCH 2/5] Aarrghs spacing. --- lib/galaxy/config.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/galaxy/config.py b/lib/galaxy/config.py index 042361e637c..a566cfc88b2 100644 --- a/lib/galaxy/config.py +++ b/lib/galaxy/config.py @@ -123,7 +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)) + 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. From 42d2a1a4e33b28c98faef4f003edebb600710562 Mon Sep 17 00:00:00 2001 From: Dannon Baker Date: Wed, 15 Feb 2017 10:15:14 -0500 Subject: [PATCH 3/5] Add forgotten sample change. --- config/galaxy.ini.sample | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/config/galaxy.ini.sample b/config/galaxy.ini.sample index 1fa4cb63684..336be53393b 100644 --- a/config/galaxy.ini.sample +++ b/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 From 28fe37c977b18d83d91e7a1d604112f62857073f Mon Sep 17 00:00:00 2001 From: Dannon Baker Date: Wed, 15 Feb 2017 11:47:17 -0500 Subject: [PATCH 4/5] Style tweaks. My flake8-in-editor had silently died and was not warning me anymore, super. --- lib/galaxy/config.py | 2 +- lib/galaxy/model/orm/engine_factory.py | 5 +++-- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/lib/galaxy/config.py b/lib/galaxy/config.py index a566cfc88b2..de66ec47a00 100644 --- a/lib/galaxy/config.py +++ b/lib/galaxy/config.py @@ -1039,7 +1039,7 @@ class ConfiguresGalaxyMixin: object_store=self.object_store, trace_logger=getattr(self, "trace_logger", None), use_pbkdf2=self.config.get_bool( 'use_pbkdf2', True ), - slow_query_log_threshold = self.config.slow_query_log_threshold ) + slow_query_log_threshold=self.config.slow_query_log_threshold ) if combined_install_database: log.info("Install database targetting Galaxy's database configuration.") diff --git a/lib/galaxy/model/orm/engine_factory.py b/lib/galaxy/model/orm/engine_factory.py index 85684e18d6c..4773128d3f0 100644 --- a/lib/galaxy/model/orm/engine_factory.py +++ b/lib/galaxy/model/orm/engine_factory.py @@ -5,6 +5,7 @@ from sqlalchemy.engine import Engine log = logging.getLogger( __name__ ) + 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: @@ -19,12 +20,12 @@ def build_engine(url, engine_options, database_query_profiling_proxy=False, trac if slow_query_log_threshold: @event.listens_for(Engine, "before_cursor_execute") def before_cursor_execute(conn, cursor, statement, - parameters, context, executemany): + 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): + 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)) From b14dccab631b2a68ca0131ceca27426668d9b2e2 Mon Sep 17 00:00:00 2001 From: Dannon Baker Date: Wed, 15 Feb 2017 13:02:56 -0500 Subject: [PATCH 5/5] Import formatting... --- lib/galaxy/model/orm/engine_factory.py | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/galaxy/model/orm/engine_factory.py b/lib/galaxy/model/orm/engine_factory.py index 4773128d3f0..16133de1ba0 100644 --- a/lib/galaxy/model/orm/engine_factory.py +++ b/lib/galaxy/model/orm/engine_factory.py @@ -1,5 +1,6 @@ import logging import time + from sqlalchemy import create_engine, event from sqlalchemy.engine import Engine