Description
For some reason all the operations that check page's ACLs are slow on my wiki. Profiling reveals that group cache is regenerated with every request. Since there are 840 group pages in my wiki, this takes a while.
Most of the group pages and user home pages don't appear in the editlog, because they were created automatically with a script.
Deleting cache didn't help. Moving the pages from 1.3.5 to 1.5.2 didn't help.
Steps to reproduce
Example
This is the test version after upgrade to 1.5.2: http://helios.wmid.amu.edu.pl/~sheep/cgi-bin/edu.cgi
Details
A profile from affected wiki:
44928 function calls (44808 primitive calls) in 1.580 CPU seconds
Ordered by: cumulative time, internal time, call count
List reduced from 281 to 40 due to restriction <40>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 1.578 1.578 request.py:727(run)
1 0.000 0.000 1.572 1.572 wikiaction.py:447(do_show)
9 0.001 0.000 1.474 0.164 security.py:52(<lambda>)
9 0.000 0.000 1.467 0.163 wikiacl.py:184(may)
22 0.000 0.000 1.466 0.067 request.py:143(getDicts)
1 0.056 0.056 1.466 1.466 wikidicts.py:301(scandicts)
844 0.074 0.000 1.198 0.001 Page.py:504(mtime_usecs)
847 0.059 0.000 0.602 0.001 editlog.py:77(__init__)
844 0.038 0.000 0.522 0.001 logfile.py:95(reverse)
2601 0.084 0.000 0.516 0.000 Page.py:291(getPagePath)
2646 0.150 0.000 0.447 0.000 Page.py:260(getPageStatus)
1747 0.052 0.000 0.430 0.000 Page.py:23(__init__)
1747 0.131 0.000 0.378 0.000 Page.py:62(reset)
843 0.073 0.000 0.278 0.000 logfile.py:288(previous)
2646 0.062 0.000 0.234 0.000 Page.py:195(getPageBasePath)
846 0.065 0.000 0.210 0.000 logfile.py:314(to_end)
843 0.039 0.000 0.182 0.000 logfile.py:284(__previous)
962/906 0.052 0.000 0.177 0.000 Page.py:139(get_rev)
843 0.053 0.000 0.128 0.000 editlog.py:128(parser)
1686 0.050 0.000 0.107 0.000 logfile.py:25(__init__)
1 0.001 0.001 0.104 0.104 Page.py:887(send_page)
6219 0.095 0.000 0.095 0.000 posixpath.py:56(join)
904 0.049 0.000 0.076 0.000 Page.py:122(get_rev_dir)
843 0.024 0.000 0.062 0.000 wikiutil.py:192(unquoteWikiname)
1686 0.043 0.000 0.057 0.000 logfile.py:54(__calculate_offsets)
1 0.001 0.001 0.051 0.051 wikiutil.py:969(send_title)
904 0.031 0.000 0.045 0.000 Page.py:106(get_current_from_pagedir)
844 0.027 0.000 0.038 0.000 wikiutil.py:81(decodeUserInput)
847 0.037 0.000 0.037 0.000 logfile.py:117(__getattr__)
24 0.000 0.000 0.035 0.001 sre.py:213(_compile)
3 0.000 0.000 0.034 0.011 sre_compile.py:490(compile)
1 0.000 0.000 0.032 0.032 classical.py:109(header)
1 0.000 0.000 0.029 0.029 eventlog.py:24(add)
1 0.000 0.000 0.028 0.028 web.py:12(isSpiderAgent)
1 0.000 0.000 0.028 0.028 sre.py:131(search)
1747 0.025 0.000 0.025 0.000 wikiutil.py:159(quoteWikinameFS)
1762 0.025 0.000 0.025 0.000 posixpath.py:168(exists)
3 0.000 0.000 0.024 0.008 sre_parse.py:658(parse)
1686 0.023 0.000 0.023 0.000 editlog.py:29(__cmp__)
3 0.001 0.000 0.023 0.008 sre_parse.py:301(_parse_sub)
Ordered by: cumulative time, internal time, call count
List reduced from 281 to 40 due to restriction <40>
Function was called by...
request.py:727(run) profile:0(profiler)(1) 0.000
wikiaction.py:447(do_show) request.py:727(run)(1) 1.578
security.py:52(<lambda>) Page.py:887(send_page)(1) 0.104
classical.py:72(iconbar)(3) 0.011
classical.py:150(edittext_link)(1) 0.006
request.py:428(getAvailableActions)(2) 0.003
wikiaction.py:447(do_show)(1) 1.572
wikiutil.py:969(send_title)(1) 0.051
wikiacl.py:184(may) security.py:52(<lambda>)(9) 1.474
request.py:143(getDicts) __init__.py:287(getText)(13) 0.011
wikiacl.py:184(may)(9) 1.467
wikidicts.py:301(scandicts) request.py:143(getDicts)(1) 1.466
Page.py:504(mtime_usecs) wikidicts.py:301(scandicts)(844) 1.466
editlog.py:77(__init__) Page.py:342(_last_edited)(2) 0.004
Page.py:504(mtime_usecs)(844) 1.198
wikidicts.py:301(scandicts)(1) 1.466
logfile.py:95(reverse) Page.py:504(mtime_usecs)(844) 1.198
Page.py:291(getPagePath) AttachFile.py:50(getAttachDir)(1) 0.001
Page.py:62(reset)(1746) 0.378
Page.py:342(_last_edited)(2) 0.004
Page.py:446(exists)(3) 0.016
Page.py:1219(send_page_content)(1) 0.003
caching.py:14(__init__)(2) 0.000
editlog.py:77(__init__)(845) 0.602
eventlog.py:14(__init__)(1) 0.000
Page.py:260(getPageStatus) Page.py:139(get_rev)(45) 0.177
Page.py:291(getPagePath)(2601) 0.516
Page.py:23(__init__) AttachFile.py:50(getAttachDir)(1) 0.001
__init__.py:287(getText)(13) 0.011
__init__.py:439(trail)(4) 0.005
classical.py:195(availableactions)(6) 0.009
classical.py:265(username)(1) 0.004
editlog.py:77(__init__)(844) 0.602
request.py:57(__init__)(1) 0.002
request.py:727(run)(1) 1.578
security.py:52(<lambda>)(9) 1.474
wikiaction.py:447(do_show)(1) 1.572
wikidicts.py:301(scandicts)(844) 1.466
wikiutil.py:439(getSysPage)(19) 0.015
wikiutil.py:489(getHomePage)(3) 0.003
Page.py:62(reset) Page.py:23(__init__)(1747) 0.430
logfile.py:288(previous) Page.py:342(_last_edited)(2) 0.004
logfile.py:95(reverse)(841) 0.522
Page.py:195(getPageBasePath) Page.py:260(getPageStatus)(2646) 0.447
logfile.py:314(to_end) Page.py:342(_last_edited)(2) 0.004
logfile.py:95(reverse)(844) 0.522
logfile.py:284(__previous) logfile.py:288(previous)(843) 0.278
Page.py:139(get_rev) Page.py:180(current_rev)(9) 0.003
Page.py:195(getPageBasePath)(904) 0.234
Page.py:313(_text_filename)(7) 0.001
Page.py:446(exists)(42) 0.016
editlog.py:128(parser) logfile.py:284(__previous)(843) 0.182
logfile.py:25(__init__) logfile.py:314(to_end)(1686) 0.210
Page.py:887(send_page) wikiaction.py:447(do_show)(1) 1.572
posixpath.py:56(join) Page.py:62(reset)(1747) 0.378
Page.py:106(get_current_from_pagedir)(904) 0.045
Page.py:122(get_rev_dir)(904) 0.076
Page.py:260(getPageStatus)(2646) 0.447
caching.py:14(__init__)(1) 0.000
caching.py:29(_filename)(9) 0.000
user.py:309(__filename)(8) 0.000
Page.py:122(get_rev_dir) Page.py:139(get_rev)(904) 0.177
wikiutil.py:192(unquoteWikiname) editlog.py:128(parser)(843) 0.128
logfile.py:54(__calculate_offsets) logfile.py:25(__init__)(1686) 0.107
wikiutil.py:969(send_title) Page.py:887(send_page)(1) 0.104
Page.py:106(get_current_from_pagedir) Page.py:139(get_rev)(904) 0.177
wikiutil.py:81(decodeUserInput) request.py:644(_setup_args_from_cgi_form)(1) 0.000
wikiutil.py:192(unquoteWikiname)(843) 0.062
logfile.py:117(__getattr__) logfile.py:314(to_end)(846) 0.210
logfile.py:404(_add)(1) 0.000
sre.py:213(_compile) sre.py:131(search)(1) 0.028
sre.py:178(compile)(23) 0.008
sre_compile.py:490(compile) sre.py:213(_compile)(3) 0.035
classical.py:109(header) wikiutil.py:969(send_title)(1) 0.051
eventlog.py:24(add) Page.py:887(send_page)(1) 0.104
web.py:12(isSpiderAgent) eventlog.py:24(add)(1) 0.029
sre.py:131(search) web.py:12(isSpiderAgent)(1) 0.028
wikiutil.py:159(quoteWikinameFS) Page.py:62(reset)(1747) 0.378
posixpath.py:168(exists) Page.py:122(get_rev_dir)(904) 0.076
Page.py:260(getPageStatus)(848) 0.447
Page.py:446(exists)(3) 0.016
caching.py:32(exists)(2) 0.000
filesys.py:17(makedirs)(1) 0.000
user.py:318(exists)(3) 0.000
user.py:745(getTrail)(1) 0.001
sre_parse.py:658(parse) sre_compile.py:490(compile)(3) 0.034
editlog.py:29(__cmp__) logfile.py:288(previous)(1686) 0.278
sre_parse.py:301(_parse_sub) sre_parse.py:658(parse)(3) 0.024MoinMoin Version |
1.3.5, 1.5.2 |
OS and Version |
PLD Linux AC, xfs filesystem |
Python Version |
2.4.2 |
Server Setup |
fast cgi |
Server Details |
apache 2 |
Workaround
Replacing one line in the method scandicts in wikidicts.py prevented the group pages regeneration: The line
if lastchange < self.namespace_timestamp and dump==0:
was replaced with
if dump==0:
The drawback is that newly added group pages are ignored until the cache is refreshed.
Discussion
The code of wikidicts.scandict has been changed after 1.5.2, so I need results from a more recent version (tla or 1.5.3-rc1).
If you still can reproduce the problem:
- I don't need a profile
- the timestamps of data/edit-log, data/cache/wikidicts/dicts_groups for some requests would be more interesting.
- please attach dicts_groups if possible
- scanning of the groups/dicts up to once a minute (if there have been edits) is normal, btw. - it should not dump them, though, if no page has been changed, added or deleted.
Plan
- Priority:
- Assigned to:
- Status: reporter could not reproduce with 1.5.3-rc2, so it should be fixed