TracTicketChangelogPlugin very slow

[Clemens Feige]

Hello

The "Changelog" Plugin seem to be very slow with >100 changesets.

We recently installed the "TracTicketChangelogPlugin" on our system
(TRAC 1.4.2, Linux, SQLite). It is very welcome because it gives a nice
overview of all changesets related to a ticket.

https://trac-hacks.org/wiki/TracTicketChangelogPlugin

However, suddenly my users complain about slow loading of tickets. Some
tickets with 50-150 changesets have loading times >30 seconds. If I
disable the TracTicketChangelogPlugin, then loading time is only 2 seconds.

I tried to shorten the message length, but this did not change the
loading times:

[ticketlog]
log_message_maxlength = 50

As far as I know, the plugin is still based on Genshi. Could this be the
reason why it is so slow?

Trac Hacks #13283
Convert templates to Jinja2
https://trac-hacks.org/ticket/13283

Any other users of this plugin?
What are your performance experiences?

Can I limit the number of displayed changesets, maybe only 20 most
recent ones?

I there anything else I can do?

I would be forced to disable this nice plugin, otherwise.

Thanks
Clemens

[RjOllos]

On Thursday, February 25, 2021 at 2:01:51 PM UTC-8 Clemens Feige wrote:

Hello

The "Changelog" Plugin seem to be very slow with >100 changesets.

We recently installed the "TracTicketChangelogPlugin" on our system
(TRAC 1.4.2, Linux, SQLite). It is very welcome because it gives a nice
overview of all changesets related to a ticket.

https://trac-hacks.org/wiki/TracTicketChangelogPlugin

However, suddenly my users complain about slow loading of tickets. Some
tickets with 50-150 changesets have loading times >30 seconds. If I
disable the TracTicketChangelogPlugin, then loading time is only 2 seconds.

I tried to shorten the message length, but this did not change the
loading times:

[ticketlog]
log_message_maxlength = 50

As far as I know, the plugin is still based on Genshi. Could this be the
reason why it is so slow?

Trac Hacks #13283
Convert templates to Jinja2
https://trac-hacks.org/ticket/13283

Any other users of this plugin?
What are your performance experiences?

Can I limit the number of displayed changesets, maybe only 20 most
recent ones?

Sounds like a good option to add to the plugin, perhaps with a link to a /log page showing all tickets associated with the ticket.

[Clemens Feige]

RjOllos wrote on 26.02.2021 at 03:28:

Hello

Please help, my TracTicketChangelogPlugin is still very slow. It takes over 30 seconds for some tickets. If I cannot find a solution I must disable this wonderful plugin.

For me it looks like the performance bottleneck is the SQL query not the Genshi template processing.

I made an experiment to limit the number of change-log to 10 (instead 150). As expected I got only 10 change-logs in the output. Unfortunately this did not change the extreme long wait time (still >30 seconds).

The SQL query is made in function `_get_ticket_revisions` in
https://trac-hacks.org/browser/tracticketchangelogplugin/1.2/ticketlog/web_ui.py#L187

    SELECT p.value, r.rev, r.author, r.time, r.message
    FROM ticket_revision AS tr
     LEFT JOIN revision AS r
      ON r.repos=tr.repos AND r.rev=tr.rev
     LEFT JOIN repository AS p
      ON p.id=tr.repos AND p.name='name'
    WHERE tr.ticket=%s
    LIMIT 10

Note the "LIMIT 10" in the last SQL line which I inserted in my experiment. The total wait time is not influenced by this "LIMIT 10".  I am neither a database nor TRAC expert. But this SQL query looks rather simple. I cannot imagine that this takes 30 seconds. The `ticket_revision` table is short and has only 1000 rows on my repo.

Some specs about my setup:
- TRAC 1.4.2
- TracTicketChangelogPlugin 1.2 (r17251 by rjollos on 2018-07-30)
- Linux with TRAC running via apache Mod-WSQI
- SQLite database
- 500 tickets
- SVN with 5000 commits
- I have a powerful server with plenty of RAM, SSD and otherwise fast TRAC

Clemens

[Clemens Feige]

P.S.

I created a ticket for this:

https://trac-hacks.org/ticket/13965

Clemens

[Jun Omae]

> The SQL query is made in function `_get_ticket_revisions` in
> https://trac-hacks.org/browser/tracticketchangelogplugin/1.2/ticketlog/web_ui.py#L187
>
> SELECT p.value, r.rev, r.author, r.time, r.message
> FROM ticket_revision AS tr
> LEFT JOIN revision AS r
> ON r.repos=tr.repos AND r.rev=tr.rev
> LEFT JOIN repository AS p
> ON p.id=tr.repos AND p.name='name'
> WHERE tr.ticket=%s
> LIMIT 10
>
> Note the "LIMIT 10" in the last SQL line which I inserted in my experiment. The total wait time is not influenced by this "LIMIT 10". I am neither a database nor TRAC expert. But this SQL query looks rather simple. I cannot imagine that this takes 30 seconds. The `ticket_revision` table is short and has only 1000 rows on my repo.
>
> Some specs about my setup:
> - TRAC 1.4.2
> - TracTicketChangelogPlugin 1.2 (r17251 by rjollos on 2018-07-30)
> - Linux with TRAC running via apache Mod-WSQI
> - SQLite database
> - 500 tickets
> - SVN with 5000 commits
> - I have a powerful server with plenty of RAM, SSD and otherwise fast TRAC

I recommend measuring the time of query using ".timer" option in
SQLite shell before improving query performance.
Also "EXPLAIN QUERY PLAN SELECT ...." is useful to analyze the query.

sqlite> .timer on
sqlite> SELECT p.value, r.rev, r.author, r.time, r.message
...> FROM ticket_revision AS tr
...> LEFT JOIN revision AS r
...> ON r.repos=tr.repos AND r.rev=tr.rev
...> LEFT JOIN repository AS p
...> ON p.id=tr.repos AND p.name='name'
...> WHERE tr.ticket=17
...> ;
...
Run Time: real 0.001 user 0.000000 sys 0.004000
sqlite>
sqlite> EXPLAIN QUERY PLAN
...> SELECT p.value, r.rev, r.author, r.time, r.message
...> FROM ticket_revision AS tr
...> LEFT JOIN revision AS r
...> ON r.repos=tr.repos AND r.rev=tr.rev
...> LEFT JOIN repository AS p
...> ON p.id=tr.repos AND p.name='name'
...> WHERE tr.ticket=17
...> ;
0|0|0|SEARCH TABLE ticket_revision AS tr USING COVERING INDEX
sqlite_autoindex_ticket_revision_1 (ticket=?)
0|1|1|SEARCH TABLE revision AS r USING INDEX
sqlite_autoindex_revision_1 (repos=? AND rev=?)
0|2|2|SEARCH TABLE repository AS p USING INDEX
sqlite_autoindex_repository_1 (id=? AND name=?)
sqlite>

--
Jun Omae <jun...@gmail.com> (大前 潤)

[Clemens Feige]

On Thursday, February 25, 2021 at 2:01:51 PM UTC-8 Clemens wrote:
> The "Changelog" Plugin seem to be very slow with >100 changesets.

> Please help, my TracTicketChangelogPlugin is still very slow. It takes over 30 seconds for some tickets. If I cannot find a solution I must disable this wonderful plugin.
>
> For me it looks like the performance bottleneck is the SQL query not the Genshi template processing.
>
> I made an experiment to limit the number of change-log to 10 (instead 150). As expected I got only 10 change-logs in the output. Unfortunately this did not change the extreme long wait time (still >30 seconds).
>

> The SQL query is made in function `_get_ticket_revisions` in
> https://trac-hacks.org/browser/tracticketchangelogplugin/1.2/ticketlog/web_ui.py#L187

Jun Omae wrote on 27.02.2021 at 02:42:
>
> I recommend measuring the time of query using ".timer" option in
> SQLite shell before improving query performance.
> Also "EXPLAIN QUERY PLAN SELECT ...." is useful to analyze the query.

Hello

I made more experiments (thanks Jun for the SQLite hints).

Details are documented in the ticket:
https://trac-hacks.org/ticket/13965

First I suspected that SQL database query might be the performance
bottleneck. However, it seems SQL is not the problem (as far as I could
find). Among other I simply disabled the SQL query in the code and it
did not change ticket loading time. Also the SQLite query times are very
quick, less than 1 second.

As far as I know, the plugin is still based on Genshi. (see #13283).
https://trac-hacks.org/ticket/13283

Can this be a performance problem?

In my log I can see the following warning:

Trac[chrome] WARNING: Component TicketLogModule relies on deprecated
Genshi stream filtering

I experimented with the Python code and could find out that the line 150
from filter_stream function may be responsible:

https://trac-hacks.org/browser/tracticketchangelogplugin/1.2/ticketlog/web_ui.py#L150

stream |= Transformer('//div[@id="ticket"]').after(template)

If I disable this line, then as expected the change-log will not appear
in the HTML output, but the loading time will be quick.

What is confusing is that the loading time problem seems not
proportional with the number of change-sets. I have tickets with 300
related SVN change-sets which load faster than other tickets with 150
related SVN change-sets. Also note that our ticket descriptions are
often very

I could not find the pattern, but it seems to be a combination of:
- number of related SVN change-sets
- number of ticket changes (my users often change ticket description)
- length or complexity of ticket description (my users love long
description texts with many tables and pictures)

Just to make this sure, all tickets (even the longest ones) load quickly
as soon as I disable the TracTicketChangelogPlugin.


Clemens

[Clemens Feige]

Clemens Feige wrote on 28.02.2021 at 00:03:

>> Please help, my TracTicketChangelogPlugin is still very slow. It takes
>> over 30 seconds for some tickets. If I cannot find a solution I must
>> disable this wonderful plugin.
>>

> As far as I know, the plugin is still based on Genshi. (see #13283).
> https://trac-hacks.org/ticket/13283
>
> Can this be a performance problem?
>
> In my log I can see the following warning:
>
>    Trac[chrome] WARNING: Component TicketLogModule relies on deprecated
> Genshi stream filtering
>
>

> Clemens
>

Hello

Jun has developed a very promising patch. I tested it and it seems to
solve the performance issues. The new code does not rely on Genshi
templates anymore while the SQL query is the same.
See track-hacks #13965 for details.
https://trac-hacks.org/ticket/13965

I hope that this patch will become the seed for a new version of
TracTicketChangelogPlugin soon.

Thanks
Clemens