Custom Query / Reports are very slow

[michaelni@…]

Simply listing issues is very slow, the more issues are listed and the more columns are, the slower. That is 10-20 seconds for displaying 300 tickets with all columns. While the comma delimited output of the same query just takes a fraction of a second. Speed also does not seem to improve by repeating the request.

The problem (to a lesser extent) can be reproduced with trac.edgewall.org too. I suspect its the same issue as the symptoms look the same. But iam just guessing here

here's an example:

time wget 'http://trac.edgewall.org/query?max=1000&col=id&col=summary&col=status&col=owner&col=type&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority'
--2012-03-21 00:37:14--  http://trac.edgewall.org/query?max=1000&col=id&col=summary&col=status&col=owner&col=type&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority
Resolving trac.edgewall.org... 176.9.102.26
Connecting to trac.edgewall.org|176.9.102.26|:80... connected.
HTTP request sent, awaiting response... 200 Ok
Length: 1762922 (1.7M) [text/html]
Saving to: “query?max=1000&col=id&col=summary&col=status&col=owner&col=type&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority”

2012-03-21 00:37:24 (1.05 MB/s) - “query?max=1000&col=id&col=summary&col=status&col=owner&col=type&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority” saved [1762922/1762922]

real	0m9.574s
user	0m0.008s
sys	0m0.068s

time wget 'http://trac.edgewall.org/query?format=csv&max=1000&col=id&col=summary&col=status&col=owner&col=type&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority'
--2012-03-21 00:38:54--  http://trac.edgewall.org/query?format=csv&max=1000&col=id&col=summary&col=status&col=owner&col=type&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority
Resolving trac.edgewall.org... 176.9.102.26
Connecting to trac.edgewall.org|176.9.102.26|:80... connected.
HTTP request sent, awaiting response... 200 Ok
Length: 164781 (161K) [text/csv]
Saving to: “query?format=csv&max=1000&col=id&col=summary&col=status&col=owner&col=type&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority.1”

2012-03-21 00:38:55 (671 KB/s) - “query?format=csv&max=1000&col=id&col=summary&col=status&col=owner&col=type&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority.1” saved [164781/164781]

real	0m0.691s
user	0m0.000s
sys	0m0.012s

[Christian Boos]

>>> size_html, time_html = 1762922.0, 9.574
>>> size_text, time_text = 164781.0, 0.691
>>> size_html / size_text, time_html / time_text
(10.698575685303524, 13.855282199710565)

Pretty much the same ratio, and the remaining difference can certainly be explained by the extra complexity of Genshi' html templates vs. text templates.

Of course, one wouldn't expect that the major part of the processing time for such queries is devoted to the rendering, but that's a well known issue we have with our beloved Genshi templating engine ;-)

In the meantime, you should try to use a recent version of Genshi (at least 0.6; as you didn't say which Trac version you were using, you might be using a Genshi 0.5 version).

See also TracDev/Performance#Genshi.

[Michael Niedermayer <michaelni@…>]

Replying to cboos:

>>> size_html, time_html = 1762922.0, 9.574
>>> size_text, time_text = 164781.0, 0.691
>>> size_html / size_text, time_html / time_text
(10.698575685303524, 13.855282199710565)

Pretty much the same ratio, and the remaining difference can certainly be explained by the extra complexity of Genshi' html templates vs. text templates.

Indeed but let me provide a slightly different example:

2012-03-21 12:10:16 (6.15 MB/s) - `query?max=1000&col=id&col=summary&col=owner&col=type&col=status&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority&col=description' saved [2735893/2735893]
real	0m10.059s

2012-03-21 12:10:36 (3.37 MB/s) - `query?format=csv&max=1000&col=id&col=summary&col=owner&col=type&col=status&col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority&col=description' saved [1048416/1048416]
real	0m0.964s

theres still a factor of 10.4 difference between the times but only a 2.6 factor in the bytes.

The same query with max=3000 ends up with csv with 2718937 bytes and 0m1.554s so IMHO the bytes are not really the issue.

In the meantime, you should try to use a recent version of Genshi (at least 0.6; as you didn't say which Trac version you were using, you might be using a Genshi 0.5 version).

We use Genshi 0.6 already and Trac 0.12.2

[Christian Boos]

Replying to Michael Niedermayer <michaelni@…>:

Replying to cboos:

>>> size_html, time_html = 1762922.0, 9.574
>>> size_text, time_text = 164781.0, 0.691
>>> size_html / size_text, time_html / time_text
(10.698575685303524, 13.855282199710565)

Pretty much the same ratio, and the remaining difference can certainly be explained by the extra complexity of Genshi' html templates vs. text templates.

Wait, exporting a .csv doesn't even imply Genshi templates. So it's really Genshi templating vs. specialized content generation (csv writer).

Indeed but let me provide a slightly different example: […] theres still a factor of 10.4 difference between the times but only a 2.6 factor in the bytes.

The same query with max=3000 ends up with csv with 2718937 bytes and 0m1.554s so IMHO the bytes are not really the issue.

Well, the slow down is just due to the fact that a lot of data goes through the Genshi template. The direct output generation scales better than the Genshi rendering when more data gets generated.

In the meantime, you should try to use a recent version of Genshi (at least 0.6; as you didn't say which Trac version you were using, you might be using a Genshi 0.5 version).

We use Genshi 0.6 already and Trac 0.12.2

Could you try with all plugins disabled? If this makes a big difference, identify the culprit plugin by enabling them again one by one. There might be one which implements the ITemplateStreamFilter interface in a sub-optimal way.

[Michael Niedermayer <michaelni@…>]

Replying to cboos:

Replying to Michael Niedermayer <michaelni@…>:

Replying to cboos:

Of course, one wouldn't expect that the major part of the processing time for such queries is devoted to the rendering, but that's a well known issue we have with our beloved Genshi templating engine ;-)

Please fix it :)

IMHO a acceptable rendering speed of such table should be in the 5-10milli seconds range not 5-10 seconds. And yeah iam saying this as a C and ASM developer not a friend of big modern web frameworks.

Also i think you are loosing users due to this genshi performance issues, or at least for me it would have been a factor in our decission to use trac had i known/realized it back then and had something equivalent thats faster existed, i dont know if the alternatives perform better …

In the meantime, you should try to use a recent version of Genshi (at least 0.6; as you didn't say which Trac version you were using, you might be using a Genshi 0.5 version).

We use Genshi 0.6 already and Trac 0.12.2

Could you try with all plugins disabled? If this makes a big difference, identify the culprit plugin by enabling them again one by one. There might be one which implements the ITemplateStreamFilter interface in a sub-optimal way.

We only use the account manager & spam filter. Ive installed trac on my local box and used a backup of our site and benchmarked with and without plugins. And i cant see any speed difference related to completely uninstalled plugins at all. trac runs faster (not fast) on my local box but that should be because our server just has a less power cpu.

[osimons]

Replying to Michael Niedermayer <michaelni@…>:

We use Genshi 0.6 already and Trac 0.12.2

Could you ensure that your Genshi install has the speedups module compiled and installed? This should not throw an ImportError:

python -c "import genshi._speedups"

Genshi speedups should be default enabled when installing latest from repository. However, if you get Genshi from a package manager it really all depends on how that recipe is configured.

To compare, please install latest Genshi 0.6.1dev by doing:

python setup.py --with-speedups install

If not previously installed, how does speedups affect your numbers?

[Michael Niedermayer <michaelni@…>]

Replying to osimons:

To compare, please install latest Genshi 0.6.1dev by doing:

python setup.py --with-speedups install

If not previously installed, how does speedups affect your numbers?

It appears speedups where not installed or at least the command errord. upgrading to 0.6.1dev —with-speedups changes a search query on the server from 3.1 to 2.8 seconds. I also tried Genshi trunk (on my local box) but it seems not to be compatible with trac 0.12.2.

[osimons]

BTW, I've added Genshi '... (with|without speedups)' detail to System Information in [11030]. Should make it easier to access this information.

[Christian Boos]

Note that the Genshi speedups may buy you a few % improvements on some setups on some platforms, but in general it's hardly worth the trouble. The Genshi performance issue remains, speedups or not.

[Christian Boos]

I've opened a new proposal ticket to address this (#11185) first at the level of the [[TicketQuery(...,format=table)]], then for generalizing it.

The generalization part (query first, reports later) could correspond to this ticket.

[Jun Omae]

Enabling [trac] use_chunked_encoding option reduces time to first byte. The option is introduced in milestone:1.0.6.

use_chunked_encoding	Time to first byte	Total time
disabled (default)	3,910 ms	3,937 ms
enabled	1,190 ms	3,990 ms

*) Timing of query page for 1,000 active tickets

[Christian Boos]

This will be fixed by the migration of the template engine from Genshi to Jinja2. When it's done, we can time again t.e.o and compare.

Right now we have:

$ time curl -o query.html 'https://trac.edgewall.org/query?max=1000&col=id&col=summary&col=status&col=owner&col=type& col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1823k  100 1823k    0     0   121k      0  0:00:15  0:00:15 --:--:--  383k

real    0m15.162s
user    0m0.015s
sys     0m0.000s

[Christian Boos]

Today, before upgrade, best time of 3: 0m9.886s (for 10530 matches and a 1823k query.html).

[Christian Boos]

After the upgrade to trunk, best time of 3: 0m3.913s (for 10530 matches and a 1327k query.html).

And 0m2.189s (for a 1405k query.html) after disabling the tracspamfilter.filters.trapfield.* components (the one implementing the ITemplateStreamFilter interface and forcing the backward compatibility Genshi filtering to take place).

$ time curl -o query.html 'https://trac.edgewall.org/query?max=1000&col=id&col=summary&col=status&col=owner&col=type& col=priority&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1405k  100 1405k    0     0   712k      0  0:00:01  0:00:01 --:--:--  713k

real    0m2.115s
user    0m0.046s
sys     0m0.031s

In comparison, the time needed to generate the corresponding .csv file is:

$ time curl -o query.csv 'https://trac.edgewall.org/query?format=csv&max=1000&col=id&col=summary&col=status&col=owner&col=type&col=milestone&col=component&col=version&col=severity&col=resolution&col=time&col=reporter&col=keywords&col=cc&order=priority'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  169k  100  169k    0     0   249k      0 --:--:-- --:--:-- --:--:--  250k

real    0m0.768s
user    0m0.046s
sys     0m0.000s

So it only takes roughly 3 times longer to generate the HTML than it takes to generate the CSV: not bad!