Ok, I've updated the patch series:
part1: implicit sync
When the implicit sync fails, add a warning box to the request, and
send additional information as well as the traceback to the log at error
level. (Instead of trying to cram it all into the warning box.)
No longer claims to have synchronized the repo in the error path.
It still catches 'Exception' since I didn't think the additional
complexity of narrowing it to the Sqlite exception was worthwhile.
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.
part3: uncache previous_rev()
Makes previous_rev() unconditionally go to the repository without
hitting the node_change table. (Was "part3a".)
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.
Comments?
Eli
----------------------. "If it ain't broke now,
Eli Carter \ it will be soon." -- crypto-gram
[email protected] `---------------------------------------------
--
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/versioncontrol/api.py
===================================================================
--- trac/versioncontrol/api.py (revision 11935)
+++ trac/versioncontrol/api.py (working copy)
@@ -22,7 +22,7 @@
from trac.core import *
from trac.resource import IResourceManager, Resource, ResourceNotFound
from trac.util.concurrency import threading
-from trac.util.text import printout, to_unicode
+from trac.util.text import printout, to_unicode, exception_to_unicode
from trac.util.translation import _
from trac.web.api import IRequestFilter
@@ -340,7 +340,26 @@
try:
repo = self.get_repository(reponame)
if repo:
- repo.sync()
+ try:
+ repo.sync()
+ except Exception, e:
+ add_warning(req, _("Failed to sync with "
+ "repository \"%(name)s\": %(error)s; "
+ "repository information may be out of date. "
+ "Look in the Trac log for more information "
+ "including mitigation strategies.",
+ name=reponame or '(default)',
+ error=to_unicode(e.message)))
+ self.log.error("Failed to sync with repository "
+ "\"%s\"; You may be able to reduce the impact "
+ "of this issue by configuring [trac] "
+ "repository_sync_per_request; see "
+ "http://trac.edgewall.org/wiki/";
+ "TracRepositoryAdmin#ExplicitSync for more "
+ "detail. Exception: %s",
+ reponame or '(default)',
+ exception_to_unicode(e, traceback=True))
+ continue
else:
self.log.warning("Unable to find repository '%s' for "
"synchronization",
Index: trac/db/util.py
===================================================================
--- trac/db/util.py (revision 11935)
+++ 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("'((?:[^']|(?:''))*)'",
@@ -51,9 +53,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 duration > 10:
+ 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))
Index: trac/versioncontrol/cache.py
===================================================================
--- trac/versioncontrol/cache.py (revision 11935)
+++ trac/versioncontrol/cache.py (working copy)
@@ -349,10 +349,9 @@
return self.rev_db(self.metadata.get(CACHE_YOUNGEST_REV))
def previous_rev(self, rev, path=''):
- if self.has_linear_changesets:
- return self._next_prev_rev('<', rev, path)
- else:
- return self.repos.previous_rev(self.normalize_rev(rev), path)
+ # Hitting the repository is faster than searching the database,
+ # particularly as the number of entries in node_change grows large.
+ return self.repos.previous_rev(self.normalize_rev(rev), path)
def next_rev(self, rev, path=''):
if self.has_linear_changesets:
--- trac/versioncontrol/cache.py.p3a 2013-08-10 14:39:27.262798340 -0500
+++ trac/versioncontrol/cache.py 2013-08-10 14:43:09.522563725 -0500
@@ -15,6 +15,7 @@
# Author: Christopher Lenz <[email protected]>
import os
+import time
from trac.cache import cached
from trac.core import TracError
@@ -354,10 +355,17 @@
return self.repos.previous_rev(self.normalize_rev(rev), path)
def next_rev(self, rev, path=''):
+ start = time.time()
if self.has_linear_changesets:
- return self._next_prev_rev('>', rev, path)
+ n_rev = self._next_prev_rev('>', rev, path)
else:
- return self.repos.next_rev(self.normalize_rev(rev), path)
+ n_rev = self.repos.next_rev(self.normalize_rev(rev), path)
+ duration = time.time() - start
+ if duration > 10:
+ 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)
+ return n_rev
def _next_prev_rev(self, direction, rev, path=''):
srev = self.db_rev(rev)
