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