Query links (eg [query: ....]) amazingly slow

[fabien]

When using multiple [query: ...] in a wiki page, it takes a few seconds and 100% of CPU on the server to generate the page (mod_python + apache2).

Check here : https://lampsvn.epfl.ch/trac/scala/wiki

Other wiki pages are fast. But, if I copy the web to the trac demo site, it works fine and it seems to use the same version as me. My configuration uses sqlite.

[fabien]

Forgot to give trac demo URL : http://www.hosted-projects.com/trac/TracDemo/Demo/wiki/test_query

[cboos]

Seems like the Query.from_string is to blame, and the fact that this triggers the creation of a Query object which calls TicketSystem.get_ticket_fields().

[fabien]

I just tried to apply the patch on version 0.10.4 First, it looks good, request is not slow anymore, but I get randomly this error : Python Traceback

Traceback (most recent call last):

File "/var/lib/python-support/python2.4/trac/web/main.py", line 406, in dispatch_request

dispatcher.dispatch(req)

File "/var/lib/python-support/python2.4/trac/web/main.py", line 237, in dispatch

resp = chosen_handler.process_request(req)

File "/var/lib/python-support/python2.4/trac/wiki/web_ui.py", line 135, in process_request

self._render_view(req, db, page)

File "/var/lib/python-support/python2.4/trac/wiki/web_ui.py", line 443, in _render_view

req.hdfwiki? = {

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 1001, in wiki_to_html

Formatter(env, req, absurls, db).format(wikitext, out, escape_newlines)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 824, in format

result = re.sub(self.wiki.rules, self.replace, line)

File "sre.py", line 142, in sub

return _compile(pattern, 0).sub(repl, string, count)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 770, in replace

replacement = self.handle_match(fullmatch)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 766, in handle_match

return internal_handler(match, fullmatch)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 364, in _lhref_formatter

return self._make_link(ns, target, match, label)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 371, in _make_link

escape(label, False))

File "/var/lib/python-support/python2.4/trac/ticket/query.py", line 668, in _format_link

query = Query.from_string(formatter.env, query)

File "/var/lib/python-support/python2.4/trac/ticket/query.py", line 94, in from_string

return cls(env, constraints, **kw)

File "/var/lib/python-support/python2.4/trac/ticket/query.py", line 54, in init

if self.order != 'id' \

KeyError?: 'name'

Thanks for your help.

[cboos]

Thanks for the testing. Well, it seems like I need to be more careful about race conditions here. I'll provide an updated patch shortly.

[cboos]

Same as first patch but with locking add (for latest 0.11dev trunk)

[cboos]

Same as first patch but with locking add (this time for 0.10)

[cboos]

Ok, here's a new patch. Can you please test attachment:cache-get_ticket_fields-trac-0.10.diff (that one applies cleanly on 0.10.4)

[fabien]

Ok. I applied it and tried it. It looks good and stable. Thanks a lot !

It's now used in production. I'll let you know if it's still ok under load.

[cboos]

Replying to fabien:

Ok. I applied it and tried it. It looks good and stable. Thanks a lot ! It's now used in production. I'll let you know if it's still ok under load.

Are you talking about https://lampsvn.epfl.ch/trac/scala/wiki ? If so, are you sure it's with the latest patch attachment:cache-get_ticket_fields-trac-0.10.diff? The exception seem to happen again, and quite systematically for a while. Then, it started to work intermittently. If you're using Apache+mod_python as the web front end, did you do a full restart after patching Trac?

[anonymous]

Yes, it's the right URL and I restarted apache2 with the latest patch applied. We also get random errors when creating a new ticket :

Python Traceback

Traceback (most recent call last):

File "/var/lib/python-support/python2.4/trac/web/main.py", line 406, in dispatch_request

dispatcher.dispatch(req)

File "/var/lib/python-support/python2.4/trac/web/main.py", line 237, in dispatch

resp = chosen_handler.process_request(req)

File "/var/lib/python-support/python2.4/trac/ticket/web_ui.py", line 140, in process_request

ticket = Ticket(self.env, db=db)

File "/var/lib/python-support/python2.4/trac/ticket/model.py", line 42, in init

self._init_defaults(db)

File "/var/lib/python-support/python2.4/trac/ticket/model.py", line 62, in _init_defaults

'default_' + fieldname?)

KeyError?: 'name'

and still on the wiki page :

Python Traceback

Traceback (most recent call last):

File "/var/lib/python-support/python2.4/trac/web/main.py", line 406, in dispatch_request

dispatcher.dispatch(req)

File "/var/lib/python-support/python2.4/trac/web/main.py", line 237, in dispatch

resp = chosen_handler.process_request(req)

File "/var/lib/python-support/python2.4/trac/wiki/web_ui.py", line 135, in process_request

self._render_view(req, db, page)

File "/var/lib/python-support/python2.4/trac/wiki/web_ui.py", line 443, in _render_view

req.hdfwiki? = {

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 1001, in wiki_to_html

Formatter(env, req, absurls, db).format(wikitext, out, escape_newlines)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 824, in format

result = re.sub(self.wiki.rules, self.replace, line)

File "sre.py", line 142, in sub

return _compile(pattern, 0).sub(repl, string, count)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 770, in replace

replacement = self.handle_match(fullmatch)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 766, in handle_match

return internal_handler(match, fullmatch)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 364, in _lhref_formatter

return self._make_link(ns, target, match, label)

File "/var/lib/python-support/python2.4/trac/wiki/formatter.py", line 371, in _make_link

escape(label, False))

File "/var/lib/python-support/python2.4/trac/ticket/query.py", line 668, in _format_link

query = Query.from_string(formatter.env, query)

File "/var/lib/python-support/python2.4/trac/ticket/query.py", line 94, in from_string

return cls(env, constraints, **kw)

File "/var/lib/python-support/python2.4/trac/ticket/query.py", line 54, in init

if self.order != 'id' \

KeyError?: 'name'

Thanks for your help.

[cboos]

A safer version, with a copy of the fields

[cboos]

fabien, sorry for the trouble, but it appears that 0.10 modifies the fields returned by Ticket.get_ticket_fields() (at least deleting the name field, which explains the above error).

I've uploaded another patch (attachment:cache-get_ticket_fields-trac-0.10.2.diff), which appears to work for me on 0.10.4. So far I tested only on trunk, and there it doesn't seem we modify the fields, but it nevertheless seems to be risky now to not copy them, even for trunk.

[cboos]

Also, note that with those patches, any changes to the possible values of fields (priority, versions, etc.) won't be taken into account until a server restart. This is a severe limitation. We need to do either something like r6837 or a more sophisticated approach as outlined in TracDev/JournalingProposal earlier today.

[cboos]

cache for field data, using locking + cache reset method called when appropriate

[cboos]

The latest patch (attachment:cache-get_ticket_fields-r6843.diff) does the right thing for 0.11.

Unfortunately, the cache invalidation done using config.touch can't be backported to 0.10. For those that will eventually use the attachment:cache-get_ticket_fields-trac-0.10.2.diff patch, you should be aware of this limitation, and know about the need to restart the server after a custom field configuration change or changes to the database concerning the enum fields or the milestones.

[fabien]

Thanks for the new patch. I will try it on a test server, but I won't put it now on the real server because of the limitation. I will wait until the release of 0.11

Thanks again.

[cboos]

The [ticket] restrict_owner = true setting is problematic here: we'd need to invalidate the cache whenever a user gains or loose TICKET_MODIFY, and there's currently no API for this.

[osimons]

Please don't close tickets that obviously aren't fixed as per cboos' last comment.

[cboos]

Replying to cboos:

The [ticket] restrict_owner = true setting is problematic here: we'd need to invalidate the cache whenever a user gains or loose TICKET_MODIFY, and there's currently no API for this.

Actually dealing with the restrict_owner logic in Ticket(env).get_ticket_fields() (see ticket/api.py) is wrong, as this completely by-passes the fine-grained permissions. The field options should only be computed one we have the actual ticket id at hand.

Once the above problem gets fixed, the patch introducing cacheing (see comment:12) should be enough to address the speed issue reported in this ticket.

[rblank]

Please don't change ticket fields without a (good) reason.

[cboos]

So I'll try to make a fix for 0.11.2 this week-end.

[cboos]

Not 100% finished yet, just realized I need to support restrict_owner in the query module as well.

[cboos]

#7678 closed as duplicate.

TODO: count the number of calls to SELECT username,action FROM permission; (i.e. get_user_permissions), compare before/after the patch.

[cboos]

Updated patch, doing the restrict_owner transformations outside of the TicketSystem(env).get_ticket_fields()

[cboos]

Please test the attachment:t6436-slowness-query-r7610.diff change, which caches the ticket fields computed by TicketSystem().get_ticket_fields() and invalidates the cache as needed using the config.touch() trick.

The modifications to those fields that used to be done when the restrict_owner flag was enabled should now be done outside of this call, by using the TicketSystem(env).eventually_restrict_owner(field[,ticket]) call.

Rationale:

• there was no easy way to invalidate the cache when the TICKET_MODIFY permissions changed (comment:14)
• the cost of this owner restriction feature can be quite huge in itself (comment:22), so only doing this when really needed is helpful
• that restriction was not taking fine-grained permissions into account (comment:17)

The speed gained by the caching is quite appreciable: on a "pathological" page, the rendering goes down from something like 9s to 0.7s (I had lots of query macros but very few "users", so the savings can only be bigger in real situations).

Also, with this change it should be also much cheaper to create Ticket objects.

[rblank]

One quick question: will the config.touch() trick work if trac.ini is not writable by the web server? This is the case in my installations. My guess is that it won't.

[cboos]

Sorry I replied earlier, but apparently forgot to "Save"...

Replying to rblank:

One quick question: will the config.touch() trick work if trac.ini is not writable by the web server? This is the case in my installations. My guess is that it won't.

No it won't, but as this trick is already used in other places (propagate InterMapTxt updates, install plugin in webadmin), you already have other (minor) issues with this setup.

What is really needed is some kind of cache validation infrastructure, so that when we create caches (we already do in a couple of places), we don't have to resort to new tricks each time but rather check for the validity of the cache, and re-create it if needed. Symmetrically, when we change something that we know will affect a cache, signal the change so that the next check for validity will fail. But I think this is beyond the scope of this ticket, and we could discuss that in #7739 for example.

What we could eventually do is to release 0.11.2 without that change, then apply early in "0.11.3dev", so this will eventually give us more time to get feedback from the field.

[rblank]

I have been running some stress-testing for about an hour, using tracd, with very good results. I have a page with 90 [query:...] links, and an environment with about 100 users having TICKET_MODIFY permission. Without patch, the page takes about 25 seconds to load. With the patch, about 2.5 seconds.

Then, I opened 15 tabs with autorefresh every 5 seconds, and watched the pages loading and the debug log. I could see no errors, neither in the browser, nor in the log.

Finally, I ran 8 wget instances fetching the page in a loop. Again, no errors on either client or server side. This gives a good indication that the locking issues above seem to have been solved.

Modifying e.g. a component while the 8 wget instance were fetching did trigger an environment reload, and everything continued working. Memory usage stayed reasonable (I don't remember the exact value, but I think it was around 70 MiB at the end).

[cboos]

Replying to rblank:

(snip) Modifying e.g. a component while the 8 wget instance were fetching did trigger an environment reload, and everything continued working. ...

That's quite good, I think this indeed shows the change is robust. Thanks for the testing!

Committed in [7640:7642].

[rblank]

BTW, re. [7640], the camelCase variable was my mistake, sorry about that (old habits tend to stick). That code places the "Assign to" field at the end of the form (#7018).

[anonymous]

Replying to fabien:

When using multiple [query: ...] in a wiki page, it takes a few seconds and 100% of CPU on the server to generate the page (mod_python + apache2). Check here : https://lampsvn.epfl.ch/trac/scala/wiki Other wiki pages are fast. But, if I copy the web to the trac demo site, it works fine and it seems to use the same version as me. My configuration uses sqlite.