trac: ticket create/update operations are very slow

[cri]

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

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

[zaytsev]

Test switching delivery agent to sendmail-compatible executable.

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

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

[andrew_b]

Ticket #3799 has been marked as a duplicate of this ticket.

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

[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 :-(

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

[zaytsev]

Just checking the "status quo" :-/

[zaytsev]

Ticket #4457 has been marked as a duplicate of this ticket.

[andrew_b]

Looks like this error is gone away.

At least the update delay is not so long.

[zaytsev]

Wow! Let's see.

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

[ossi]

15-20 seconds (i counted in my head, so ...).

[andrew_b]

Replying to ossi:

15-20 seconds

are less than a minute.

[ossi]

but it's still "very slow", wouldn't you agree?

[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 :-/