very large embedded preformatted text causes severe performance problems

[datallah@…]

While debugging an issue with the Pidgin trac instance guided by thatch, this issue became apparent.

Tim describes where the code causing the issue lies below:

21:54 <thatch> we have a bad algorithm in handle_code_block that does a splitlines() then appends them one by one to the dest string
21:54 <thatch> I'm not sure if you know python, but str + str = allocates a new str...
21:54 <datallah> yeah :) nice
21:55 <thatch> so toward the end you'd have 4.00mb + one line = 4.01mb additional... + one line = 4.02mb additional...
21:55 <datallah> right... classic problem

Corresponding backtrace/pystack of process in the process of rendering:

(gdb) bt
#0  0x00002b2b07f7e28c in mmap64 () from /lib/libc.so.6
#1  0x00002b2b07f24d28 in free () from /lib/libc.so.6
#2  0x00002b2b07f2616d in malloc () from /lib/libc.so.6
#3  0x0000000000455ea0 in _PyUnicode_New (length=937336) at ../Objects/unicodeobject.c:204
#4  0x00000000004637b6 in PyUnicodeUCS4_Concat (left=0xe763c0, right=0x394000)
    at ../Objects/unicodeobject.c:5040
#5  0x000000000047123e in PyEval_EvalFrame (f=0xc4e680) at ../Python/ceval.c:1322
#6  0x0000000000472d99 in PyEval_EvalFrame (f=0xbcb640) at ../Python/ceval.c:3651
#7  0x0000000000474f48 in PyEval_EvalCodeEx (co=0x2b2b09af7260, globals=<value optimized out>,
    locals=<value optimized out>, args=0xd751a0, argcount=4, kws=0xd751c0, kwcount=0,
    defs=0x2b2b09ae4cc8, defcount=2, closure=0x0) at ../Python/ceval.c:2741
#8  0x0000000000472ca5 in PyEval_EvalFrame (f=0xd74fe0) at ../Python/ceval.c:3661
#9  0x0000000000474f48 in PyEval_EvalCodeEx (co=0x2b2b09af7ea0, globals=<value optimized out>,
    locals=<value optimized out>, args=0x2, argcount=4, kws=0xac1068, kwcount=0, defs=0x2b2b09af8b08,
    defcount=3, closure=0x0) at ../Python/ceval.c:2741
#10 0x0000000000472ca5 in PyEval_EvalFrame (f=0xac0e00) at ../Python/ceval.c:3661
#11 0x0000000000474f48 in PyEval_EvalCodeEx (co=0x2aaaaac5fb20, globals=<value optimized out>,
    locals=<value optimized out>, args=0x2aaaaaae04d8, argcount=5, kws=0x5, kwcount=0, defs=0x0,
    defcount=0, closure=0x0) at ../Python/ceval.c:2741
#12 0x0000000000472ca5 in PyEval_EvalFrame (f=0xd5f6c0) at ../Python/ceval.c:3661
#13 0x0000000000472d99 in PyEval_EvalFrame (f=0x8afb70) at ../Python/ceval.c:3651
#14 0x0000000000472d99 in PyEval_EvalFrame (f=0xc77fb0) at ../Python/ceval.c:3651
#15 0x0000000000472d99 in PyEval_EvalFrame (f=0xa3c970) at ../Python/ceval.c:3651
#16 0x0000000000474f48 in PyEval_EvalCodeEx (co=0x2b2b09b1c6c0, globals=<value optimized out>,
    locals=<value optimized out>, args=0x2b2b09b09200, argcount=2, kws=0x2, kwcount=0, defs=0x0,
    defcount=0, closure=0x0) at ../Python/ceval.c:2741
#17 0x0000000000472ca5 in PyEval_EvalFrame (f=0xb32150) at ../Python/ceval.c:3661
#18 0x0000000000472d99 in PyEval_EvalFrame (f=0xb2bde0) at ../Python/ceval.c:3651
#19 0x0000000000472d99 in PyEval_EvalFrame (f=0xb95140) at ../Python/ceval.c:3651
#20 0x0000000000472d99 in PyEval_EvalFrame (f=0xc0c6d0) at ../Python/ceval.c:3651
#21 0x0000000000472d99 in PyEval_EvalFrame (f=0xaa8330) at ../Python/ceval.c:3651
#22 0x0000000000474f48 in PyEval_EvalCodeEx (co=0x2b2b09b12110, globals=<value optimized out>,
    locals=<value optimized out>, args=0x2aaaaac5b2e8, argcount=1, kws=0x0, kwcount=0, defs=0x0,
    defcount=0, closure=0x0) at ../Python/ceval.c:2741
#23 0x00000000004bc293 in function_call (func=0x2b2b09b1f8c0, arg=0x2aaaaac5b2d0, kw=0x0)
    at ../Objects/funcobject.c:548
#24 0x00000000004139f0 in PyObject_Call (func=0x0, arg=0x394000, kw=0x3) at ../Objects/abstract.c:1795
#25 0x00000000004196ee in instancemethod_call (func=<value optimized out>, arg=0x2aaaaac5b2d0, kw=0x0)
    at ../Objects/classobject.c:2532
#26 0x00000000004139f0 in PyObject_Call (func=0x0, arg=0x394000, kw=0x3) at ../Objects/abstract.c:1795
#27 0x000000000046e390 in PyEval_CallObjectWithKeywords (func=0x2aaaaef98be0, arg=0x2b2b0791c050,
    kw=0x0) at ../Python/ceval.c:3435
#28 0x00000000004a014d in t_bootstrap (boot_raw=0x2aaab043d430) at ../Modules/threadmodule.c:434
#29 0x00002b2b07a1ff1a in start_thread () from /lib/libpthread.so.0
#30 0x00002b2b07f815d2 in clone () from /lib/libc.so.6
#31 0x0000000000000000 in ?? ()
(gdb) pystack
/usr/local/lib/python2.4/site-packages/trac/wiki/formatter.py (719): handle_code_block
/usr/local/lib/python2.4/site-packages/trac/wiki/formatter.py (719): format
/usr/local/lib/python2.4/site-packages/trac/wiki/formatter.py (996): wiki_to_html
/usr/local/lib/python2.4/site-packages/trac/ticket/web_ui.py (570): _insert_ticket_data
/usr/local/lib/python2.4/site-packages/trac/ticket/web_ui.py (278): process_request
/usr/local/lib/python2.4/site-packages/trac/web/main.py (278): dispatch
/usr/local/lib/python2.4/site-packages/trac/web/main.py (152): dispatch_request
/usr/local/lib/python2.4/site-packages/trac/web/_fcgi.py (291): handler
/usr/local/lib/python2.4/site-packages/trac/web/_fcgi.py (567): run
/usr/local/lib/python2.4/site-packages/trac/web/_fcgi.py (567): _start_request
/usr/local/lib/python2.4/site-packages/trac/web/_fcgi.py (770): _do_params
/usr/local/lib/python2.4/site-packages/trac/web/_fcgi.py (775): process_input
/usr/local/lib/python2.4/site-packages/trac/web/_fcgi.py (664): run

Trac is running as a python 2.4 fcgi process through lighttpd on a Debian etch VMWare VM (host is CentOS 4 IIRC).

[Tim Hatch]

Using the same input data, I was able to reproduce the problem using Python 2.5 on FreeBSD and tracd. A 4.6MB ticket containing around 346000 lines (almost entirely in one large code block) takes more than 15 minutes to render (wget gives up at that point) for both 0.10 and 0.11.

The list version committed in r6788 takes around 2.7s to render the same ticket.

---

As a side note, the symptom is that Python takes up 100% cpu and appears to deadlock acquiring the GIL when gdb is attached at random. In all cases though, the pystack output shows handle_code_block or the wiki's format method at the top. This is one of many traces provided, and the only one that directly hinted at string concatenation being the issue.

[Tim Hatch]

Diff for 0.10-stable

[Christian Boos]

Great work Tim! I'm OK to backport this one to 0.10-stable, as this seems to be an important bug fix - I think that explains the performance issues reported in #4476 (which prompted the max_description_size thing).

[Tim Hatch]

It's now in 0.10-stable as r6789