Trac becomes very slow with many (>50) milestones

[easteregg@…]

I have a trac instance on a vhost. first of all, i present you all the informations about this trac:

root@****:/home/trac/log# uname -a
Linux ****.stratoserver.net 2.6.32-028stab091.2 #1 SMP Fri Jun 3 00:02:40 MSD 2011 i686 GNU/Linux

1 core of a
model name	: Quad-Core AMD Opteron(tm) Processor 2347 HE
cpu MHz		: 1431.597

root@****:/home/trac/log# python --version
Python 2.6.6


ii  libapache2-mod-python              3.3.1-9+b1                   Python-embedding module for Apache 2
ii  apache2-mpm-prefork                2.2.16-6+squeeze8            Apache HTTP Server - traditional non-threaded model

root@****:/home/trac/log# ls -lha /usr/local/lib/python2.6/dist-packages/
insgesamt 44K
drwxrwsr-x 10 root staff 4,0K 25. Sep 20:49 .
drwxrwsr-x  4 root staff  128 19. Jun 2011  ..
drwxr-sr-x  4 root staff 4,0K 25. Sep 20:49 Babel-0.9.6-py2.6.egg
-rw-r--r--  1 root staff  427 25. Sep 20:49 easy-install.pth
drwxr-sr-x  4 root staff 4,0K 25. Sep 20:49 Genshi-0.6-py2.6.egg
drwxr-sr-x  4 root staff 4,0K 13. Sep 11:40 IniAdmin-0.2_r11914-py2.6.egg
drwxr-sr-x  5 root staff 4,0K  8. Sep 09:02 Trac-1.0-py2.6.egg
drwxr-sr-x  4 root staff 4,0K 13. Sep 11:40 TracAccountManager-0.3.2-py2.6.egg
drwxr-sr-x  4 root staff 4,0K 21. Jun 2011  TracHTTPAuth-1.1-py2.6.egg
drwxr-sr-x  4 root staff 4,0K 13. Sep 11:39 TracWysiwyg-0.12.0.4_r11158-py2.6.egg
drwxr-sr-x  4 root staff 4,0K 13. Sep 11:39 TracXMLRPC-1.1.2_r11439-py2.6.egg

httpconf: 

        <Location />
           SetHandler mod_python
           PythonHandler trac.web.modpython_frontend
           PythonPath "sys.path + ['/usr/share/trac']"
           PythonOption TracEnv /home/trac
           PythonOption TracUriRoot /
           PythonOption TracLocale "de_DE.UTF-8"

        </Location>

okay. so far so good, now you know on what box im working on. we have plenty of milestones (about 15 open, rest closed)

and we have serious performance issues, the box itsself idles most of the time, only a svn and this trac is running on the box. i tried nearly everything to tune the performace. static content is hosted on a seperated domain, not served by trac itself.

when it comes to navigating through the trac instance it sometimes is very slow. as database backend im using mysql. there are no slow queries so i decided to enable sql logging and take a look whats happening. when i browse through pages with no database access, everything is quite fine. but when it comes to the wiki or to the roadmap i usually have to wait 3-10 seconds till the page get served (messured in google chrome, with only one user at this time which was me!)

so i took a look into the debug log and found, that there is no caching and queries got fired multiple times instead of get cached or something. it seems, not a single query is the problem, but the hugh amount of queries fired (multiple times)

i attached a samplelog for only one pagerequest (roadmap). i should mention that only about 15 milestones are open and i display only open milestones (so why is there a query to closed milestones?!) and why so many queries?

this result in very poor performance.

i attach a image recording the pageloadtimes and the example log

[anonymous]

i forget to mention, during a request, the cpu goes up to 100% during the time the page need to get served.

[anonymous]

and some info about the db usage

[Christian Boos]

Well, first remark, from looking at tracdb.png​, you didn't configure MySQL properly, as specified in MySqlDb (neither the use of MyISAM or of the utf_general_ci encoding is correct).

But that's not related to the performance problem, which I believe is genuine.

Now it looks like you have a TicketQuery macro in every milestone description, which somehow also plays a role in the slowness you experience. Can you try to disable the TicketQuery macro for a test, to see what difference it makes? ( Admin / General - Extensions / Trac 1.0 / TicketQueryMacro [ ] → deactivate + Apply changes)

[Reinder Feenstra <reinderfeenstra@…>]

Do you have query caching enabled in MySQL?

SHOW VARIABLES LIKE 'have_query_cache';

[anonymous]

yea, i enabled caching, its same configuration we use for a highperformance db server. so no problem there. the querietimes show that this is not the bottleneck

with ticketmacro disbled i get the roadmap in about 0.8 secs (which is still pretty slow i guess)

right now i have 13 open milestones with 11 macros (quite basic, just print all the open tickets attached to the milestone)

[anonymous]

btw, the myisam was created by the initial setup 2 years ago. i never took a closer look at the tables. after converting to innodb i noticed a extra speeddrop from 3.x to 4.x seconds :/

[Christian Boos]

For 1.0-stable, a simple cache will probably be enough to fix the performance issue we're seeing here. It shouldn't be too costly to keep everything in memory, even for 50-100 milestones.

See repos:cboos.git:ticket10879-MilestoneCache.

Also available as a single patch for easier testing in t10879-MilestoneCache-r11383.patch​.

[Christian Boos]

combined changes, up to [a91cce24/cboos.git]

[anonymous]

okay, that improoved the performace of our trac a little. now we have times of 2,5 secs instead of 4 secs… which is still pretty slow. where is the bottleneck on the trac system? in dont understand why a little installation of trac on this system is so darn slow. its only a vhost but still it should have enough power to run this stuff.

i often encounter pretty slow performace on random situations even when browsing the wiki or just on the loginpage.

i have other php driven applications on this host which are fairly hughe projects and they perform way better. and i applied almost every tweak i could find on the internet to this system for getting the last bit of performance out of trac. i managed to increasse the speed over the time… from 10 sec to 2.5 sec right now. but i dont understand why trac is still so freakingly slow! even with a freshly installed trac i encounter slow performance… which is pretty annoying.

what are the typical bottlenecs with trac? db issues … i already checked this. this isnt the bottlenec. but what else? high disk io ? it seems, generally cpu performance is a bottleneck… with one request all the time 100% …

even with tracd without ssl its still pretty low performance…

[Christian Boos]

From tracperformance.png​, I see roadmap at 245.43 KB, which is quite a lot already for our template engine (see also #10635, which seems relevant here as you have TicketQuery calls in your milestone descriptions).

You could also post a new trac.log, with the patch applied (same request and debug level as trac.log​).

[easteregg@…]

okay, here is the new log.

it seems to be way less db queries. so we can cross out the mysql server as the bottleneck. i'll post you some new samples of browsing the wiki in a sec

[easteregg@…]

as you can see the performance is pretty unstable, sometimes the requests takes way longer than usual. there vhost has still only me as the user and nothing else to do.

[easteregg@…]

any new thoughts on this topic? :/ still pretty annoying.

[Christian Boos]

I've tested again the (rebased) branch, and everything seems to be fine. However as it has not been tested in the wild, I think it's not appropriate to commit it now, right before the release.

I'll do it first thing for 1.0.2.

As for more ideas to boost performance in this situation, well, I guess sidestepping the template engine and reworking the data model would help, but that's nothing for 1.0.x ;-)

[anonymous]

hm, its a pitty, im using this since the beginning of the ticket at hat no issues at all. but its highly recommanded, that you investigate more into the performance of the trac project, cause its so freakingly slow… :/

[Christian Boos]

Ah, thanks for the renewed feedback, I think your experience with the patch counts as "testing in the wild" ;-)

I'll apply it then. And yes, I agree with the goal of working harder to improve overall performance.

[anonymous]

what make me curious is the fact, that its pretty unstable. i using two instances of trac. on on a vhost at a shared server with other customers of the isp and one within a virtual machine on my private root server. both a very unstable in the facts of performance. sometimes it took the same page around 100times more time to load. i i could nail it, why!

i wonder, what did you use for your trac hosting here?

the second trac instance on my private root is based on a i7 8 thread 3,2ghz cpu with 2 cores assigned to the virtual machine trac is inside…

[Christian Boos]

You may want to describe your configuration in more details and ask for advice on the Trac-users mailing list (although at first glance, a intermittent 100x increase could correspond to the server restarting or being swapped in again). If the server is Linux, you could try to catch a strace of the process while it's taking excessive time, as if it's really 100x times more, you have time enough to log in, find the pid and start strace -p.

[Christian Boos]

Patch applied in [11523:11525] and merged into trunk in r11528.

[fbrettschneider@…]

This is definitely worth a trial to update to 1.0.1. With lots of milestones, I usually see delays of 2 to 3 seconds on page reload by 100% server CPU load. I'm going to compare to 1.0.0 as soon as the Bitnami version is released.

[fbrettschneider@…]

Replying to Reinder Feenstra <reinderfeenstra@…>:

Do you have query caching enabled in MySQL?

Is there also a caching in SQLite? If yes, where can I configure it?

[fbrettschneider@…]

Replying to fbrettschneider@…:

…delays of 2 to 3 seconds on page reload by 100% server CPU load… I'm going to compare to 1.0.0 …

1.0.1 feels slightly better but not a breakthrough. I would say 25% faster. Though I haven't got a profiling for seeing how the time is distributed over all the layers. I still wonder if increasing the SQLite cache would help, but I already asked ​here because I don't know how to do that.

[easteregg@…]

this is still quite worse!

in the meantime the machine got a little upgrade and i have a second trac setup runnig, which is completly empty except for about 350 tickets. and its still very slow. i have loadingtimes around 2-5 seconds with the a current version of python and the trac, genshi and babel at trunk.

i got a dualcore vm with 1750mhz each core and about 6gigs of ram. nothing else to do for this machine. so why is this still so freakingly slow?

[Christian Boos]

Replying to easteregg@…:

this is still quite worse!

in the meantime the machine got a little upgrade and i have a second trac setup runnig, which is completly empty except for about 350 tickets. and its still very slow. i have loadingtimes around 2-5 seconds with the a current version of python and the trac, genshi and babel at trunk.

Sorry, but you have to be a bit more specific: load time of what, the /roadmap page? If so, how many visible milestones, anything special within their description?

It's most likely an InstallationIssue at this point, if you haven't done so already, please go through the points listed in TracPerformance and try to identify what's wrong on your side.

[easteregg@…]

no its not, its still the worse performance. its almost the same system as stated in the initial post here on this ticket! except that i moved the virtual machine to a more powerful host.

the wiki has only two ticketqueries

[[TicketQuery(order=id,desc=1,status!=closed,format=table)]]
[[BR]]
[[BR]]
[[TicketQuery(order=id,desc=1,status=closed,format=table)]]

and thats it. no milestones, no special usecases, just some plain tickets (total count is at the moment 312 tickets).

ill attach the current loadtimes, with a plain trac, checked out this morning from the trunk.

[easteregg@…]

and please note, that the roadmap is completly empty! there is nothing to display!

Trac	        1.1.2dev-r11803
Genshi	        0.8dev-r1238 (with speedups)
mod_python	3.3.1
MySQL	server: "5.5.31-0+wheezy1-log", client: "5.5.31", thread-safe: 1
MySQLdb	        1.2.3
Python	        2.7.3 (default, Jan 2 2013, 17:14:22) [GCC 4.7.2]
setuptools	0.6
jQuery	        1.7.2

[Christian Boos]

Seeing attachment:tracperf.png​​, I think there are two things going on in your installation:

• having more than a second for successive requests on an empty /roadmap is definitely not normal and indicative of an issue in your installation; so it's really a general InstallationIssue; please do as I've told, review all points in TracPerformance and try to see what you could have done wrong. In particular, check you mod_python setup, look at the trac.log file and the apache access.log and error.log, as it really looks like you have an environment restart for every request
• having an additional 2s for a wiki page where you have such costly requests is expected, unfortunately; you end up with 809K of data and that's really a lot for our template engine (Genshi). It is known (TracDev/Performance#Genshi).
  Workarounds:
  • don't use format=table
  • have more specific queries to get less results

If you really have a problem with the second point and want to open a specific ticket for that, feel free to do so.

But this ticket ended up being about a (modest) speed improvement to milestones retrieval, and has been closed once that task was complete, so please leave it at that.

[Christian Boos]

Replying to cboos:

If you really have a problem with the second point and want to open a specific ticket for that, feel free to do so.

Actually, I have a problem with that as well ;-) See follow-up in #11185.