Edgewall Software
Modify

Opened 6 years ago

Closed 5 years ago

Last modified 5 years ago

#6436 closed defect (fixed)

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

Reported by: fabien Owned by: cboos
Priority: highest Milestone: 0.11.2
Component: ticket system Version: 0.10.4
Severity: major Keywords: query
Cc:
Release Notes:
API Changes:

Description (last modified by cboos)

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.

Attachments (6)

cache-get_ticket_fields-r6792.diff (1.0 KB) - added by cboos 6 years ago.
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().
cache-get_ticket_fields-r6823.diff (1.7 KB) - added by cboos 6 years ago.
Same as first patch but with locking add (for latest 0.11dev trunk)
cache-get_ticket_fields-trac-0.10.diff (1.8 KB) - added by cboos 6 years ago.
Same as first patch but with locking add (this time for 0.10)
cache-get_ticket_fields-trac-0.10.2.diff (1.8 KB) - added by cboos 6 years ago.
A safer version, with a copy of the fields
cache-get_ticket_fields-r6843.diff (4.9 KB) - added by cboos 6 years ago.
cache for field data, using locking + cache reset method called when appropriate
t6436-slowness-query-r7610.diff (9.4 KB) - added by cboos 5 years ago.
Updated patch, doing the restrict_owner transformations outside of the TicketSystem(env).get_ticket_fields()

Download all attachments as: .zip

Change History (36)

comment:2 Changed 6 years ago by cboos

  • Description modified (diff)

comment:3 Changed 6 years ago by cboos

  • Milestone changed from 0.10.5 to 0.11.1
  • Priority changed from normal to high

Changed 6 years ago by 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().

comment:4 Changed 6 years ago by 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.

comment:5 Changed 6 years ago by 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.

Changed 6 years ago by cboos

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

Changed 6 years ago by cboos

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

comment:6 Changed 6 years ago by cboos

  • Milestone changed from 0.11.1 to 0.11
  • Status changed from new to assigned

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)

comment:7 follow-up: Changed 6 years ago by 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.

comment:8 in reply to: ↑ 7 Changed 6 years ago by 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?

comment:9 Changed 6 years ago by 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.

Changed 6 years ago by cboos

A safer version, with a copy of the fields

comment:10 Changed 6 years ago by 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.

comment:11 Changed 6 years ago by 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.

Changed 6 years ago by cboos

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

comment:12 Changed 6 years ago by 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.

comment:13 Changed 6 years ago by 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.

comment:14 follow-up: Changed 6 years ago by cboos

  • Milestone changed from 0.11 to 0.12
  • Priority changed from high to highest

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.

comment:15 Changed 6 years ago by anonymous

  • Resolution set to fixed
  • Status changed from assigned to closed

comment:16 Changed 6 years ago by osimons

  • Resolution fixed deleted
  • Status changed from closed to reopened

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

comment:17 in reply to: ↑ 14 Changed 6 years ago by 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.

comment:18 Changed 6 years ago by anonymous

  • Owner changed from cboos to anonymous
  • Status changed from reopened to new

comment:19 Changed 6 years ago by rblank

  • Owner changed from anonymous to cboos

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

comment:20 Changed 6 years ago by cboos

  • Milestone changed from 0.13 to 0.11.2

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

comment:21 Changed 6 years ago by cboos

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

comment:22 Changed 6 years ago by 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.

Changed 5 years ago by cboos

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

comment:23 Changed 5 years ago by cboos

  • Component changed from wiki system to ticket system
  • Keywords review added

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.

comment:24 follow-up: Changed 5 years ago by 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.

comment:25 in reply to: ↑ 24 Changed 5 years ago by 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.

comment:26 follow-up: Changed 5 years ago by 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).

comment:27 in reply to: ↑ 26 Changed 5 years ago by cboos

  • Keywords review removed
  • Resolution set to fixed
  • Status changed from new to closed

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

comment:28 Changed 5 years ago by 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).

comment:29 in reply to: ↑ description Changed 5 years ago by anonymous

  • Type changed from defect to task

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.

comment:30 Changed 5 years ago by rblank

  • Type changed from task to defect

Add Comment

Modify Ticket

Change Properties
<Author field>
Action
as closed The owner will remain cboos.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from cboos to the specified user.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.