Ticket #3771 (new defect)

Opened 9 months ago

Last modified 8 months ago

trac: ticket create/update operations are very slow

Reported by: cri Owned by:
Priority: major Milestone: Future Releases
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 9 months ago by mooffie

Attaching files too is fast. Perhaps only operations that trigger emails are slow? (attachments don't trigger emails.)

Replying to cri:

Maybe there's some kind of bottleneck in writing to the backend database?


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.

Last edited 9 months ago by egmont (previous) (diff)

comment:2 Changed 9 months ago by zaytsev

Test switching delivery agent to sendmail-compatible executable.

comment:3 in reply to: ↑ 1 Changed 9 months 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 9 months 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 months ago by andrew_b

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

comment:6 Changed 8 months 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:7 Changed 8 months ago by 0xe2.0x9a.0x9b

  • Cc 0xe2.0x9a.0x9b@… added

comment:8 Changed 8 months 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 :-(

Note: See TracTickets for help on using tickets.