On 08/12/2013 10:07 PM, Eli Carter wrote:
On 08/12/2013 12:29 PM, Christian Boos wrote:
On 8/10/2013 10:29 PM, Eli Carter wrote:
Ok, I've updated the patch series:
...
part2: warn on slow SQL
Unmodified from the initial post; when debug_sql is enabled, logs a
warning if an SQL statement takes over 10 seconds to execute.
Wouldn't it be better to fetch the value of "10" seconds from the
configuration? ([trac] debug_sql_timing_threshold?). 3 seconds may be
already too long for many people...
Makes sense, but getting a configuration option into that code is
starting to get a little awkward; it doesn't have easy access to the
trac env, and adding a new option done in the same manner as the 'log'
parameter complained about an unexpected keyword argument. I'll have to
look at it a bit more...
I think I have this worked out; see db-locked-mitigation-v4-part2.patch.
It does require touching all the db backends though. Thoughts?
part4: warn on slow next_rev()
This logs a warning if next_rev() takes more than 10 seconds to
complete, suggesting enabling [trac] debug_sql. (Was "part3b".)
The purpose of this is to give the admin that first breadcrumb to
lead them to the underlying cause of their slowness.
Same thing, we could use the configured threshold for the timing.
Default could still be 10s of course, but people could then easily make
it more sensitive without hacking the code.
That looks doable...
Ok, I implemented a configurable [trac] slow_repo_warning_threshold in
db-locked-mitigation-v4-part4.patch
Feedback welcomed,
Eli
--
You received this message because you are subscribed to the Google Groups "Trac
Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To post to this group, send email to [email protected].
Visit this group at http://groups.google.com/group/trac-dev.
For more options, visit https://groups.google.com/groups/opt_out.
Index: trac/db/api.py
===================================================================
--- trac/db/api.py (revision 12082)
+++ trac/db/api.py (working copy)
@@ -105,10 +105,10 @@
attached to the `error` attribute of the connector.
"""
- def get_connection(path, log=None, **kwargs):
+ def get_connection(path, log=None, warn_threshold=0, **kwargs):
"""Create a new connection to the database."""
- def init_db(path, log=None, **kwargs):
+ def init_db(path, log=None, warn_threshold=0, **kwargs):
"""Initialize the database."""
def to_sql(table):
@@ -139,6 +139,13 @@
"""Show the SQL queries in the Trac log, at DEBUG level.
''(Since 0.11.5)''""")
+ debug_sql_timing_threshold = IntOption('trac',
+ 'debug_sql_timing_threshold', '10',
+ """SQL execution duration threshold at which to log slow SQL queries
+ at WARN level, in seconds. Use '0' to specify ''no warnings''.
+ Requires [trac] debug_sql = true.
+ ''(Since 0.12.6)''""")
+
def __init__(self):
self._cnx_pool = None
self._transaction_local = ThreadLocal(db=None)
@@ -206,6 +213,7 @@
if self.debug_sql:
args['log'] = self.log
+ args['warn_threshold'] = self.debug_sql_timing_threshold
return connector, args
_get_connector = get_connector # For 0.11 compatibility
Index: trac/db/mysql_backend.py
===================================================================
--- trac/db/mysql_backend.py (revision 12082)
+++ trac/db/mysql_backend.py (working copy)
@@ -80,9 +80,10 @@
self.error = _("Cannot load Python bindings for MySQL")
yield ('mysql', self.error and -1 or 1)
- def get_connection(self, path, log=None, user=None, password=None,
- host=None, port=None, params={}):
- cnx = MySQLConnection(path, log, user, password, host, port, params)
+ def get_connection(self, path, log=None, warn_threshold=0, user=None,
+ password=None, host=None, port=None, params={}):
+ cnx = MySQLConnection(path, log, warn_threshold, user, password, host,
+ port, params)
if not self._version:
self._version = get_pkginfo(MySQLdb).get('version',
MySQLdb.__version__)
@@ -217,7 +218,7 @@
poolable = True
- def __init__(self, path, log, user=None, password=None, host=None,
+ def __init__(self, path, log, warn_threshold, user=None, password=None, host=None,
port=None, params={}):
if path.startswith('/'):
path = path[1:]
@@ -237,7 +238,7 @@
if self.charset != 'utf8':
cnx.query("SET NAMES %s" % self.charset)
cnx.store_result()
- ConnectionWrapper.__init__(self, cnx, log)
+ ConnectionWrapper.__init__(self, cnx, log, warn_threshold)
self._is_closed = False
def cast(self, column, type):
@@ -284,4 +285,4 @@
self._is_closed = True
def cursor(self):
- return IterableCursor(MySQLUnicodeCursor(self.cnx), self.log)
+ return IterableCursor(MySQLUnicodeCursor(self.cnx), self.log, self.warn_threshold)
Index: trac/db/postgres_backend.py
===================================================================
--- trac/db/postgres_backend.py (revision 12082)
+++ trac/db/postgres_backend.py (working copy)
@@ -81,10 +81,10 @@
self.error = _("Cannot load Python bindings for PostgreSQL")
yield ('postgres', self.error and -1 or 1)
- def get_connection(self, path, log=None, user=None, password=None,
- host=None, port=None, params={}):
- cnx = PostgreSQLConnection(path, log, user, password, host, port,
- params)
+ def get_connection(self, path, log=None, warn_threshold=0, user=None,
+ password=None, host=None, port=None, params={}):
+ cnx = PostgreSQLConnection(path, log, warn_threshold, user, password,
+ host, port, params)
if not self._version:
self._version = get_pkginfo(psycopg).get('version',
psycopg.__version__)
@@ -92,10 +92,10 @@
self.required = True
return cnx
- def init_db(self, path, log=None, user=None, password=None, host=None,
- port=None, params={}):
- cnx = self.get_connection(path, log, user, password, host, port,
- params)
+ def init_db(self, path, log=None, warn_threshold=0, user=None,
+ password=None, host=None, port=None, params={}):
+ cnx = self.get_connection(path, log, warn_threshold, user, password,
+ host, port, params)
cursor = cnx.cursor()
if cnx.schema:
cursor.execute('CREATE SCHEMA "%s"' % cnx.schema)
@@ -206,8 +206,8 @@
poolable = True
- def __init__(self, path, log=None, user=None, password=None, host=None,
- port=None, params={}):
+ def __init__(self, path, log=None, warn_threshold=0, user=None,
+ password=None, host=None, port=None, params={}):
if path.startswith('/'):
path = path[1:]
if 'host' in params:
@@ -225,7 +225,7 @@
cnx.commit()
except (DataError, ProgrammingError):
cnx.rollback()
- ConnectionWrapper.__init__(self, cnx, log)
+ ConnectionWrapper.__init__(self, cnx, log, warn_threshold)
def cast(self, column, type):
# Temporary hack needed for the union of selects in the search module
@@ -255,5 +255,5 @@
""" % (table, column, table))
def cursor(self):
- return IterableCursor(self.cnx.cursor(), self.log)
+ return IterableCursor(self.cnx.cursor(), self.log, self.warn_threshold)
Index: trac/db/sqlite_backend.py
===================================================================
--- trac/db/sqlite_backend.py (revision 12082)
+++ trac/db/sqlite_backend.py (working copy)
@@ -161,7 +161,7 @@
"2.5.5 or higher")
yield ('sqlite', self.error and -1 or 1)
- def get_connection(self, path, log=None, params={}):
+ def get_connection(self, path, log=None, warn_threshold=0, params={}):
if not self._version:
self._version = get_pkginfo(sqlite).get(
'version', '%d.%d.%s' % sqlite.version_info)
@@ -176,7 +176,7 @@
extpath = os.path.join(self.env.path, extpath)
self._extensions.append(extpath)
params['extensions'] = self._extensions
- return SQLiteConnection(path, log, params)
+ return SQLiteConnection(path, log, warn_threshold, params)
def init_db(self, path, log=None, params={}):
if path != ':memory:':
@@ -239,7 +239,7 @@
poolable = have_pysqlite and sqlite_version >= (3, 3, 8) \
and sqlite.version_info >= (2, 5, 0)
- def __init__(self, path, log=None, params={}):
+ def __init__(self, path, log=None, warn_threshold=0, params={}):
if have_pysqlite == 0:
raise TracError(_("Cannot load Python bindings for SQLite"))
self.cnx = None
@@ -273,13 +273,13 @@
cnx.load_extension(ext)
cnx.enable_load_extension(False)
- ConnectionWrapper.__init__(self, cnx, log)
+ ConnectionWrapper.__init__(self, cnx, log, warn_threshold)
def cursor(self):
cursor = self.cnx.cursor((PyFormatCursor, EagerCursor)[self._eager])
self._active_cursors[cursor] = True
cursor.cnx = self
- return IterableCursor(cursor, self.log)
+ return IterableCursor(cursor, self.log, self.warn_threshold)
def rollback(self):
for cursor in self._active_cursors.keys():
Index: trac/db/util.py
===================================================================
--- trac/db/util.py (revision 12082)
+++ trac/db/util.py (working copy)
@@ -15,7 +15,9 @@
#
# Author: Christopher Lenz <[email protected]>
+import time
+
def sql_escape_percent(sql):
import re
return re.sub("'((?:[^']|(?:''))*)'",
@@ -29,11 +31,12 @@
Iteration will generate the rows of a SELECT query one by one.
"""
- __slots__ = ['cursor', 'log']
+ __slots__ = ['cursor', 'log', 'warn_threshold']
- def __init__(self, cursor, log=None):
+ def __init__(self, cursor, log=None, warn_threshold=0):
self.cursor = cursor
self.log = log
+ self.warn_threshold = warn_threshold
def __getattr__(self, name):
return getattr(self.cursor, name)
@@ -51,9 +54,22 @@
try:
if args:
self.log.debug('args: %r', args)
+ start = time.time()
r = self.cursor.execute(sql_escape_percent(sql), args)
else:
+ start = time.time()
r = self.cursor.execute(sql)
+ duration = time.time() - start
+ if self.warn_threshold and duration > self.warn_threshold:
+ if args:
+ self.log.warn(
+ "SQL execution took %0.2fs for %r with args %r",
+ duration, sql, args)
+ else:
+ self.log.warn("SQL execution took %0.2fs for %r",
+ duration, sql)
+ else:
+ self.log.debug("SQL execution took %0.2fs", duration)
rows = getattr(self.cursor, 'rows', None)
if rows is not None:
self.log.debug("prefetch: %d rows", len(rows))
@@ -92,11 +108,12 @@
:since 0.12: This wrapper no longer makes cursors produced by the
connection iterable using `IterableCursor`.
"""
- __slots__ = ('cnx', 'log')
+ __slots__ = ('cnx', 'log', 'warn_threshold')
- def __init__(self, cnx, log=None):
+ def __init__(self, cnx, log=None, warn_threshold=0):
self.cnx = cnx
self.log = log
+ self.warn_threshold = warn_threshold
def __getattr__(self, name):
return getattr(self.cnx, name)
Index: trac/versioncontrol/api.py
===================================================================
--- trac/versioncontrol/api.py (revision 11954)
+++ trac/versioncontrol/api.py (working copy)
@@ -18,7 +18,7 @@
import time
from trac.admin import AdminCommandError, IAdminCommandProvider, get_dir_list
-from trac.config import ListOption, Option
+from trac.config import ListOption, Option, IntOption
from trac.core import *
from trac.resource import IResourceManager, Resource, ResourceNotFound
from trac.util.concurrency import threading
@@ -322,6 +322,15 @@
repositories specified here. The default is to synchronize the default
repository, for backward compatibility. (''since 0.12'')""")
+ repository_slow_warning_threshold = IntOption('trac',
+ 'repository_slow_warning_threshold', '10',
+ doc="""Threshold for warnings on slow repository operations, in seconds.
+
+ This value determines at what a repository operation has taken so long
+ that the administrator should be warned about it, so the admin can
+ locate the cause of slow responses. Set to 0 to disable.
+ (''since 0.12.6'')""")
+
def __init__(self):
self._cache = {}
self._lock = threading.Lock()
Index: trac/versioncontrol/cache.py
===================================================================
--- trac/versioncontrol/cache.py (revision 11954)
+++ trac/versioncontrol/cache.py (working copy)
@@ -15,6 +15,7 @@
# Author: Christopher Lenz <[email protected]>
import os
+import time
from trac.cache import cached
from trac.core import TracError
@@ -52,6 +53,8 @@
self._metadata_id = (CachedRepository.__module__ + '.'
+ CachedRepository.__name__ + '.metadata:'
+ str(self.repos.id))
+ self.duration_warning_threshold = env.config.getint('trac',
+ 'slow_repo_warning_threshold')
Repository.__init__(self, repos.name, repos.params, log)
def close(self):
@@ -360,12 +363,25 @@
# return self._next_prev_rev('<', rev, path)
return self.repos.previous_rev(self.normalize_rev(rev), path)
- def next_rev(self, rev, path=''):
+ def _next_rev(self, rev, path):
if self.has_linear_changesets:
return self._next_prev_rev('>', rev, path)
else:
return self.repos.next_rev(self.normalize_rev(rev), path)
+ def next_rev(self, rev, path=''):
+ if self.duration_warning_threshold:
+ start = time.time()
+ n_rev = self._next_rev(rev, path)
+ duration = time.time() - start
+ if duration > self.duration_warning_threshold:
+ self.log.warn("Finding rev %s -> %s for %r took %0.2fs. "
+ "Setting [trac] debug_sql = true may provide clues.",
+ rev, n_rev, path, duration)
+ else: # don't bother timing it
+ n_rev = self._next_rev(rev, path)
+ return n_rev
+
def _next_prev_rev(self, direction, rev, path=''):
srev = self.db_rev(rev)
db = self.env.get_db_cnx()
