Ticket #3771 (closed defect: fixed)
trac: ticket create/update operations are very slow
Reported by: | cri | Owned by: | |
---|---|---|---|
Priority: | major | Milestone: | |
Component: | adm | Version: | master |
Keywords: | Cc: | 0xe2.0x9a.0x9b@… | |
Blocked By: | Blocking: | ||
Branch state: | no branch | Votes for changeset: |
Description
(I hope the "adm" Component is ok)
I've noticed that creating or updating a ticket on this trac system is a very slow operation; it requires about 20-30 seconds to complete, while all other operations (e.g. searching tickets, previewing changes to a ticket) are quite fast. Maybe there's some kind of bottleneck in writing to the backend database?
I never got failures or error messages, only noticed this unusual delay.
Change History
comment:1 in reply to: ↑ description ; follow-up: ↓ 3 Changed 8 years ago by mooffie
comment:2 Changed 8 years ago by zaytsev
Test switching delivery agent to sendmail-compatible executable.
comment:3 in reply to: ↑ 1 Changed 8 years ago by egmont
Replying to mooffie:
Attaching files too is fast. Perhaps only operations that trigger emails are slow? (attachments don't trigger emails.)
Editing comments is also fast, so yup, it's quite likely the emails.
comment:4 Changed 8 years ago by zaytsev
I don't think it's emails; it used to be the case some time ago when posting comments was taking up to 60 seconds, and I've discovered that it had to do something with local SMTP was specified as a hostname in Trac config and for some weird reason first DNS server was always timing out, so I replaced it with an IP address (127.0.0.1) and it became a lot faster...
Now, I have just replaced SMTP with sendmail, and it didn't seem to make any difference. Moreover, I can see in the logs that submission itself happens just before the page fully loads, and it only takes a fraction of a second.
So, apparently, it is something after it writes the comment to the database, but before it sends out the email?! I was thinking might be the spam filter trying to submit the comment text to some external service like Akismet, but it's disabled in the settings.
I have no idea where this might come from, and profiling Trac is really difficult. I've managed to obtain a trace last time, but most time is spent in some mysterious "<string>:1(<Expression u'prefix'>)" which doesn't tell me anything.
I don't think it's annoying enough to try to make time to fix it, and I'd rather prefer to get this server set up cleanly anew using SCM et al. on RHEL 7, if someone else has time to spend on such stuff... so, I'm leaning towards closing this as a wontfix.
Ordered by: internal time, call count List reduced from 689 to 20 due to restriction <20> ncalls tottime percall cumtime percall filename:lineno(function) 11 63.001 5.727 63.001 5.727 <string>:1(<Expression u'prefix'>) 25 6.118 0.245 6.119 0.245 /usr/lib/python2.6/site-packages/trac/db/util.py:48(execute) 510847 1.222 0.000 2.129 0.000 /usr/lib/python2.6/site-packages/trac/db/util.py:41(__iter__) 512420 0.908 0.000 0.908 0.000 /usr/lib64/python2.6/encodings/utf_8.py:15(decode) 510706 0.489 0.000 8.652 0.000 /usr/lib/python2.6/site-packages/trac/env.py:464(get_known_users) 1 0.395 0.395 9.062 9.062 /usr/lib/python2.6/site-packages/trac/notification.py:265(__init__) 2 0.215 0.107 0.215 0.107 /usr/lib64/python2.6/subprocess.py:1344(_communicate_with_poll) 14 0.042 0.003 0.042 0.003 /usr/lib64/python2.6/socket.py:409(readline) 1 0.009 0.009 0.009 0.009 /usr/lib/python2.6/site-packages/trac/db/util.py:68(executemany) 10 0.008 0.001 0.008 0.001 /usr/lib/python2.6/site-packages/trac/db/pool.py:53(try_rollback) 2 0.006 0.003 0.006 0.003 /usr/lib64/python2.6/sre_compile.py:307(_optimize_unicode) 4 0.004 0.001 0.004 0.001 /usr/lib64/python2.6/subprocess.py:459(_eintr_retry_call) 100/28 0.003 0.000 0.008 0.000 /usr/lib64/python2.6/sre_parse.py:385(_parse) 2 0.003 0.002 0.031 0.015 /usr/lib/python2.6/site-packages/trac/ticket/api.py:256(get_ticket_fields) 2 0.002 0.001 0.006 0.003 /usr/lib64/python2.6/subprocess.py:1110(_execute_child) 180/25 0.002 0.000 0.011 0.000 /usr/lib64/python2.6/sre_compile.py:38(_compile) 727/3 0.002 0.000 0.003 0.001 /usr/lib64/python2.6/copy.py:144(deepcopy) 1039 0.001 0.000 0.001 0.000 /usr/lib64/python2.6/sre_parse.py:188(__next) 22 0.001 0.000 0.006 0.000 /usr/lib/python2.6/site-packages/Genshi-0.6-py2.6.egg/genshi/template/eval.py:428(_compile) 243/100 0.001 0.000 0.001 0.000 /usr/lib64/python2.6/sre_parse.py:146(getwidth)
comment:5 Changed 8 years ago by andrew_b
Ticket #3799 has been marked as a duplicate of this ticket.
comment:6 Changed 8 years ago by 0xe2.0x9a.0x9b
If Trac is waiting for an event external to Trac then maybe some information can be obtained by running Trac under "strace" with timing information and examining the log.
comment:8 Changed 8 years ago by zaytsev
If Trac is waiting for an event external to Trac
The thing is, I have no idea whether that's true or not, and the "run under strace" part is a huge PITA. Trac isn't a normal program, it runs inside a WSGI server, and it's a total pain to debug.
I think the most promising approach would be to write a script that imports Trac as a module, creates a new ticket using internal APIs, and run it under cProfile or vmprof, but I need to find some time to get to it :-/
What comes out of Hotshot doesn't look useful at all :-(
comment:9 Changed 4 years ago by ossi
any chance to have another look at this? it's not only painful for current contributors, but it also makes the project look unmaintained and is therefore a potential turn-off for new contributors.
i for one would strace -f -tt the *whole* process tree and see whether there is some unexpected system activity. also, just watching (h)top might give a first clue.
also, this trac instance is by now ridiculously outdated (8 years!) and thus probably has some qualities of swiss cheese, apart from seriously lagging in features.
comment:10 Changed 2 years ago by zaytsev
Just checking the "status quo" :-/
comment:11 Changed 17 months ago by zaytsev
Ticket #4457 has been marked as a duplicate of this ticket.
comment:12 Changed 3 months ago by andrew_b
Looks like this error is gone away.
At least the update delay is not so long.
comment:13 Changed 3 months ago by zaytsev
- Status changed from new to closed
- Resolution set to fixed
Wow! Let's see.
comment:14 Changed 3 months ago by ossi
sure? the comment i just posted went through a lot faster, but unless you're hosting this on a 486, it's still kind of fishy.
let's see how long this one takes ...
comment:15 follow-up: ↓ 16 Changed 3 months ago by ossi
15-20 seconds (i counted in my head, so ...).
comment:16 in reply to: ↑ 15 Changed 3 months ago by andrew_b
comment:17 Changed 3 months ago by ossi
but it's still "very slow", wouldn't you agree?
comment:18 Changed 3 months ago by zaytsev
Well, I don't think any further investigation with this Trac installation makes sense - either we should setup all anew on a new OS, because basically almost everything is outdated / not supported by now, or migrate to GitHub. I'd favor the latter course of action, but still have to prioritize other items on my todo lists :-/
Attaching files too is fast. Perhaps only operations that trigger emails are slow? (attachments don't trigger emails.)
Replying to cri:
Interestingly, you can reload the ticket in a separate tab/window and see your new comment instantly. So a comment in itself is written quickly.