Edgewall Software
Modify

Opened 15 years ago

Closed 15 years ago

#7064 closed defect (fixed)

very large embedded preformatted text causes severe performance problems

Reported by: datallah@… Owned by: Tim Hatch
Priority: normal Milestone: 0.10.5
Component: wiki system Version: 0.10.4
Severity: major Keywords:
Cc: Branch:
Release Notes:
API Changes:
Internal Changes:

Description

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

Attachments (1)

t7064.diff (1.8 KB ) - added by Tim Hatch 15 years ago.
Diff for 0.10-stable

Download all attachments as: .zip

Change History (4)

comment:1 by Tim Hatch, 15 years ago

Component: renderingwiki system
Milestone: 0.10.5
Owner: changed from Christian Boos to Tim Hatch
Status: newassigned

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.

by Tim Hatch, 15 years ago

Attachment: t7064.diff added

Diff for 0.10-stable

comment:2 by Christian Boos, 15 years ago

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

comment:3 by Tim Hatch, 15 years ago

Resolution: fixed
Status: assignedclosed
Version: 0.10.4

It's now in 0.10-stable as r6789

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Tim Hatch.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Tim Hatch to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.