performance issue with extreme long waiting times

[clemens]

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

This ticket was created for the corresponding ​mailing list thread

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.

However, 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. Even with endabled TracTicketChangelogPlugin, some tickets are quite fast (typically those with few changesets).

Setup

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

Config

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

[ticketlog]
log_message_maxlength = 50

SQL

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).

SQL experiment 1

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

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".

SQL experiment 2

Next I simply removed the SQL query from code. Instead I simply assigned fixed values to the variables.

Result: It did not change the loading time.

Genshi

As far as I know, the plugin is still based on Genshi (see #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 following line 150 from filter_stream function may be responsible: source:/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.

Tickets

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.

[Jun Omae]

In the attached patch​, filter_stream() will be no longer used.

[clemens]

slightly improved JavaScript file (which applies correct ID)

[clemens]

Replying to Jun Omae:

In the attached patch​, filter_stream() will be no longer used.

Your patch works great. I tested it and all my performance issues are solved. All my affected tickets (some of them previously had loading times over 30 seconds) now load in less than 3 seconds. Thanks.

I recommend that a new plugin version is created from the patch.

Please see my slightly improved JavaScript file: attachment:ticketlog.js​ which:

• applies correct ID to the div container, otherwise CSS rules will not match
• avoids that the "ticket log" container is inserted a second time if already exists (typically when using "save-as" from your browser)
• has comments
• I confirm that the HTML output now looks identical to what was produced with the old Genshi based approach. (But much faster of course!)

[clemens]

Note: This new approach should also solve #13283.

[Jun Omae]

Thanks for the feedback.

• applies correct ID to the div container, otherwise CSS rules will not match

id="ticket_log" should be generated server side.

Revised t13965-remove-use-of-genshi.v3.diff​ based on the feedback.

[Ryan J Ollos]

Looks good. Please feel free to commit it.

[Jun Omae]

In 18030:

TracTicketChangelogPlugin 1.2.0dev: commit history is inserted using javascript rather than Genshi transformer (closes #13965)

[Jun Omae]

Thanks for the reviewing. Pushed the patch.

[Alexey]

After r18030 i have error

KeyError: 'ticketlog\\templates'

when try to exec trac_admin -deploy command on Trac 1.2.6

[Ryan J Ollos]

In 18033:

TracTicketChangelogPlugin 1.2.0dev: Extract messages

Remove templates path from ITemplateProvider impl

Refs #13965.

[Ryan J Ollos]

Replying to Alexey:

After r18030 i have error

I couldn't reproduce, but could you try with r18033?

[clemens]

I just tested the PIP installation procedure with r18033 on TRAC 1.4.2. It works well.

I am surprised to see that the plugin version number "1.2.0.dev0" has not changed. Should it be incremented? After all, Jun's new approach is somewhat different than what we we had before.

# pip install svn+https://trac-hacks.org/svn/tracticketchangelogplugin/1.2/
Collecting svn+https://trac-hacks.org/svn/tracticketchangelogplugin/1.2/
  Checking out https://trac-hacks.org/svn/tracticketchangelogplugin/1.2/ to /tmp/pip-req-build-L21iHf
Requirement already satisfied: Trac in /usr/local/lib/python2.7/dist-packages (from TracTicketChangelog==1.2.0.dev0) (1.4.2)
Requirement already satisfied: jinja2>=2.9.3 in /usr/local/lib/python2.7/dist-packages (from Trac->TracTicketChangelog==1.2.0.dev0) (2.11.2)
Requirement already satisfied: setuptools>=0.6 in /usr/lib/python2.7/dist-packages (from Trac->TracTicketChangelog==1.2.0.dev0) (40.8.0)
Requirement already satisfied: MarkupSafe>=0.23 in /usr/local/lib/python2.7/dist-packages (from jinja2>=2.9.3->Trac->TracTicketChangelog==1.2.0.dev0) (1.1.1)
Building wheels for collected packages: TracTicketChangelog
  Running setup.py bdist_wheel for TracTicketChangelog ... done
  Stored in directory: /tmp/pip-ephem-wheel-cache-DtSAWw/wheels/ee/1f/8b/d2cc01bc3e4fa33d68050afef57b8d69955d363671d51a81a8
Successfully built TracTicketChangelog
Installing collected packages: TracTicketChangelog
Successfully installed TracTicketChangelog-1.2.0.dev0

[Jun Omae]

Replying to Ryan J Ollos:

Replying to Alexey:

After r18030 i have error

I couldn't reproduce, but could you try with r18033?

Thanks for the fixing, Ryan. I tried to fix it, however it seems the trac-hacks.org was down.

$ svn up
Updating '.':
svn: E170013: Unable to connect to a repository at URL 'https://trac-hacks.org/svn/tracticketchangelogplugin'
svn: E120108: Error running context: The server unexpectedly closed the connection.

(Yeah, I couldn't produce it, too.)

[Ryan J Ollos]

Replying to Jun Omae:

I tried to fix it, however it seems the trac-hacks.org was down.

I hope we can resolve the up-time issues eventually but haven't had time to look into the problem.

[Ryan J Ollos]

Replying to clemens:

I am surprised to see that the plugin version number "1.2.0.dev0" has not changed. Should it be incremented?

We can tag a release after a few days to allow issues such as comment:10 to be found.

[Alexey]

Replying to Ryan J Ollos:

Replying to Alexey:

After r18030 i have error

I couldn't reproduce, but could you try with r18033?

r18033 works fine

[Ryan J Ollos]

In 18038:

TracTicketChangelogPlugin 1.2.0.1dev: Bump version after release

Refs #13965.

[Ryan J Ollos]

Published to ​pypi:TracTicketChangelog.