trac: ticket create/update operations are very slow

[mc-butler]

Important

This issue was migrated from Trac:

Origin	https://midnight-commander.org/ticket/3771
Reporter	cri (cri@….org)
Mentions	0xe2.0x9a.0x9b@….com

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

[mc-butler]

Changed by mooffie (@mooffie) on Feb 12, 2017 at 0:14 UTC

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

Replying to cri (#3771):

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.

[mc-butler]

Changed by zaytsev (@zyv) on Feb 12, 2017 at 9:53 UTC (comment 2)

Test switching delivery agent to sendmail-compatible executable.

[mc-butler]

Changed by egmont (@egmontkob) on Feb 12, 2017 at 14:15 UTC (comment 1.3)

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.

[mc-butler]

Changed by zaytsev (@zyv) on Feb 12, 2017 at 21:49 UTC (comment 4)

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)

[mc-butler]

Changed by andrew_b (@aborodin) on Mar 24, 2017 at 12:35 UTC (comment 5)

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

[mc-butler]

Changed by 0xe2.0x9a.0x9b (0xe2.0x9a.0x9b@….com) on Mar 24, 2017 at 16:05 UTC (comment 6)

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.

[mc-butler]

Changed by 0xe2.0x9a.0x9b (0xe2.0x9a.0x9b@….com) on Mar 24, 2017 at 16:07 UTC (comment 7)

• Cc set to 0xe2.0x9a.0x9b@….com

[mc-butler]

Changed by zaytsev (@zyv) on Mar 24, 2017 at 20:53 UTC (comment 8)

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

[mc-butler]

Changed by ossi (@ossilator) on Oct 14, 2020 at 16:44 UTC (comment 9)

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.

[mc-butler]

Changed by zaytsev (@zyv) on Oct 1, 2022 at 18:47 UTC (comment 10)

Just checking the "status quo" :-/

[mc-butler]

Changed by zaytsev (@zyv) on May 11, 2023 at 6:02 UTC (comment 11)

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

[mc-butler]

Changed by andrew_b (@aborodin) on Jul 13, 2024 at 5:34 UTC (comment 12)

Looks like this error is gone away.

At least the update delay is not so long.

[mc-butler]

Changed by zaytsev (@zyv) on Jul 14, 2024 at 9:04 UTC (comment 13)

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

Wow! Let's see.

[mc-butler]

Changed by ossi (@ossilator) on Jul 19, 2024 at 10:03 UTC (comment 14)

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

[mc-butler]

Changed by ossi (@ossilator) on Jul 19, 2024 at 10:03 UTC (comment 15)

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

[mc-butler]

Changed by andrew_b (@aborodin) on Jul 19, 2024 at 10:59 UTC (comment 15.16)

Replying to ossi:

15-20 seconds

are less than a minute.

[mc-butler]

Changed by ossi (@ossilator) on Jul 19, 2024 at 11:08 UTC (comment 17)

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

[mc-butler]

Changed by zaytsev (@zyv) on Jul 19, 2024 at 15:40 UTC (comment 18)

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

[mc-butler]

Changed by zaytsev (@zyv) on Jul 28, 2024 at 10:46 UTC (comment 19)

• Milestone Future Releases deleted

[mc-butler]

Changed by zaytsev (@zyv) on Feb 22, 2025 at 14:02 UTC

• Blocked by set to #3746

(In #3746) In the meantime, GitHub has added:

1. Issue types
2. Parent <> child issue relationships
3. Branches and pull-request connections
4. Ticket resolutions including links
5. Ticket information unfurling into lists
6. Ticket references in the timeline
7. Advanced filtering and searching
8. Sorting by reactions (voting)

Migration has now become feasible, and miraculously I have been able to allocate resources to get some work done... Will post to the list soon.