next_rev is slow, particularly in the direct-svnfs case

[cboos]

This is a continuation of #7490, which became too "big" to be usable. Please keep that other ticket closed.

A lot of possible reasons for bad performance have been identified, some of them fixed, most being due to installation and configuration issues. Please refer to the TracPerformance checklist, and help maintain that wiki page with your findings.

This ticket should be used to help identify the remaining performance bottlenecks, a part from those which are already known (see TracDev/Performance).

[cboos]

Got a surprisingly slow going request today, in our domestic Trac, so I investigated a bit.

This was a /browser request, accessing a small file from an old tag at r2259 in our main repository (> 33k revisions).

This takes between 1 to 3 minutes, whereas the corresponding svn cat is instantaneous and another Trac instance takes 1.8 seconds (both Trac instances running at r9150).

The main differentiator was the use of direct-svnfs vs. svn, as I checked that the other Trac instance would show the same slowness when switching the repository type.

With gdb, I see that most of the time is spent in Subversion libraries, apparently going through a lot of revisions ... pystack shows:

(gdb) pystack
/opt/subversion-1.6.4/lib/svn-python/libsvn/fs.py (244): svn_fs_revision_root
build/bdist.linux-x86_64/egg/trac/versioncontrol/svn_fs.py (468): _history
build/bdist.linux-x86_64/egg/trac/versioncontrol/svn_fs.py (524): next_rev
build/bdist.linux-x86_64/egg/trac/versioncontrol/web_ui/browser.py (431): process_request
build/bdist.linux-x86_64/egg/trac/web/main.py (431): dispatch
build/bdist.linux-x86_64/egg/trac/web/main.py (228): _dispatch_request
build/bdist.linux-x86_64/egg/trac/web/main.py (496): dispatch_request

(and if someone has a version of pystack that terminates or can be interrupted, I'll take it!)

So next_rev is slow (we knew it), but can be extremely slow in the direct-svnfs case. Maybe we should consider bailing out and returning None after a while there, or even have a smarter implementation which uses a dichotomic search for example.

[cboos]

I think the point in comment:1 shouldn't hold back the 0.11.7 release, like more generally this ticket which is a "well known" issue.

[cboos]

The general topic Trac 0.11 really slow, high cpu usage (continued) and in particular most of the remaining unsolved cases from #7490, have now been addressed part of #9111 by r10002. Condition.wait(timeout) is a performance killer in Python, as it does a kind of "active" wait. This seems to have been fixed in Python 3.2 which uses the appropriate library call (see ​PythonBug:3155). Never assume the underlying system does the "right thing", but look at the code to be sure...

Retargeting this ticket to fix comment:1.

[jvilla@…]

Hi,

I installed a Trac server about a year ago (0.11). The system that's running our Trac instances is a pretty fast system with 16gb of memory, so that shouldn't be the problem.

I've been noticing that Trac would take between 3 to 5 seconds to fully load a ticket. I cleaned up one plugin that was causing problems, but I'm still left with a system that is uber-slow.

I've been fishing through the Trac logs and I've found something that raises an eyebrow.

Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/Trac-0.12.2-py2.6.egg/trac/web/main.py", line 512, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/lib/python2.6/site-packages/Trac-0.12.2-py2.6.egg/trac/web/main.py", line 238, in dispatch
    resp = chosen_handler.process_request(req)
  File "/usr/lib/python2.6/site-packages/TicketExtPlugin-0.3.2_r7776-py2.6.egg/ticketext/template.py", line 93, in process_request
    template_api.process_tickettemplate(self.env, req, 'type')
  File "/usr/lib/python2.6/site-packages/TicketExtPlugin-0.3.2_r7776-py2.6.egg/ticketext/api.py", line 62, in process_tickettemplate
    req.write(response)
  File "/usr/lib/python2.6/site-packages/Trac-0.12.2-py2.6.egg/trac/web/api.py", line 534, in write
    raise ValueError("Can't send unicode content")
ValueError: Can't send unicode content

Could this be causing something? I noticed that it says Trac 0.12, which I thought I wasn't running on this system. As said, I thought my version was 0.11.

Any help would be great,

Thanks!

[cboos]

Replying to jvilla@…:

Hi,

I installed a Trac server about a year ago (0.11). The system that's running our Trac instances is a pretty fast system with 16gb of memory, so that shouldn't be the problem.

I've been noticing that Trac would take between 3 to 5 seconds to fully load a ticket. I cleaned up one plugin that was causing problems, but I'm still left with a system that is uber-slow.

I've been fishing through the Trac logs and I've found something that raises an eyebrow.

Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/Trac-0.12.2-py2.6.egg/trac/web/main.py", line 512, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/lib/python2.6/site-packages/Trac-0.12.2-py2.6.egg/trac/web/main.py", line 238, in dispatch
    resp = chosen_handler.process_request(req)
  File "/usr/lib/python2.6/site-packages/TicketExtPlugin-0.3.2_r7776-py2.6.egg/ticketext/template.py", line 93, in process_request
    template_api.process_tickettemplate(self.env, req, 'type')
  File "/usr/lib/python2.6/site-packages/TicketExtPlugin-0.3.2_r7776-py2.6.egg/ticketext/api.py", line 62, in process_tickettemplate
    req.write(response)
  File "/usr/lib/python2.6/site-packages/Trac-0.12.2-py2.6.egg/trac/web/api.py", line 534, in write
    raise ValueError("Can't send unicode content")
ValueError: Can't send unicode content

Could this be causing something? I noticed that it says Trac 0.12, which I thought I wasn't running on this system. As said, I thought my version was 0.11.

This is obviously an InstallationIssue... nothing wrong with Trac itself and nothing related to this ticket...

It seems that this TicketExtPlugin? will only work with Trac < 0.11.6 (see r8609), and obviously you have 0.12.2 installed (also verify in the /about page as TRAC_ADMIN or in Admin / Plugins). So you can either try to fix that plugin (recommended) or downgrade (uninstall all Trac versions in site-packages, then reinstall 0.11.5 - not recommended).

If you can get anything more specific about the slow down (does it also happen without that plugin?), then please create a new ticket.

[jvilla@…]

Thank you and my apologies. I got a little confused.

I will create a new ticket after this because even while disabling that plugin, Trac is still taking 4.83 seconds to load data from tickets.

[cboos]

Ok, and on a side note let me bump the priority of this ticket, as I think the next_rev thing is causing the slowdown I see in my own production Trac... I didn't have time yet to do an in-depth debugging session but there seem to be a problem with the source:tags/trac-0.12.2/trac/versioncontrol/cache.py@:365-366#L364​ part which doesn't seem to use the indexes (well, indeed there are no indexes​ on the paths...).

[cboos]

Next on my list of things we should really fix...

[cboos]

There's also a glitch with prev_rev, when the branch supporting a file has been deleted, e.g.
source:/branches/0.11-stable/contrib/bugzilla2trac.py@8233​, Previous Revision points to r6936. This corresponds to the deletion of a "wrong" version of branches/0.11-stable, which has been recreated later in r6940 - see log.

[cboos]

The short term "fix" for the slowness will be addressed by #8639 (use relative links and defer computation of the actual next or prev revision).

The longer term fix is to rework the cache so that access to prev/next revision for any path could be obtained directly.

The short-term workaround is likely to stay ofr the direct-svnfs case, though.