Description
The edit-log file is opened many times when accessing pages.
Steps to reproduce
- Have a single thread, single process wiki running.
- Trace the activity of the process and filter for open calls.
The edit-log can be completely empty for this.
Example
Component selection
- general
Details
Output of truss -t open,close -p #pid when accessing a missing page:
/4: open64("/dev/urandom", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/cache/test/surgeprotect/surge-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/cache/test/surgeprotect/surge-logy4pQ_l.tmp", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW, 0600) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/event-log", O_WRONLY|O_APPEND|O_CREAT, 0666) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/pages/MeineStartSeite/revisions/99999999", O_RDONLY) Err#2 ENOENT
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/pages/MeineStartSeite/revisions/99999999", O_RDONLY) Err#2 ENOENT
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/pages/MissingPage/cache/text_htmlNwPA6B.tmp", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW, 0600) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: open64("/srv/www/test/data/edit-log", O_RDONLY) = 11
/4: close(11) = 0
/4: close(10) = 0
/4: close(9) = 0MoinMoin Version |
1.9.1 |
OS and Version |
SunOS sun 5.10 Generic_142901-03 i86pc i386 i86pc |
Python Version |
2.6.1 |
Server Setup |
Apache 2.2.11 |
Server Details |
mod_wsgi 3.1, mpm_prefork |
Language you are using the wiki in (set in the browser/UserPreferences) |
de |
Workaround
Discussion
Is this a real problem (describe why) or is it just something you noticed?
I noticed that the times for saving pages are increasing (> 2 s) and wanted to see if something goes wrong. So I traced some page edits. When editing pages many more things get opened (Xapian, Group pages, page edit-log), but I recognized that between all the regular opens, there are many calls of the global edit-log. The time used for these opens might be small for a simple request, but the number of calls seems to increase for more complex operations (e.g. groups from acls are looked up, and between these calls there are always many open calls to the edit-log, too). To make the problem simpler I reduced the trace to a simple page request and I wondered many open calls to the edit-log there, too.
- I have a performance problem, but I can not guarantee that this is the cause.
Well, all the accesses you see to edit-log are likely the "uptodate" checks from moin's page caching system. It uses the global edit-log to see if someone edited something in moin. I guess usually that should be covered quite good by the operating system filesystem cache. -- ThomasWaldmann 2010-02-01 16:41:24
- I see 107 calls to open64("/srv/www/test/data/edit-log", O_RDONLY) for a specific single page edit (from pressing the "Save changes" to the page view), they add up to around 0.5 s with tracing on. The calls all should be satisfied from the os cache, but the sheer number of consecutive calls seems strange to me.
- For the single page request above it were around 60 opens to edit-log.
- Note: if you just normally access "a single page", lots of pages are accessed interally from the theme and also for links (to check whether those pages exist).
- So you mean, that all those open() calls are to verify if a page in an internal cache has been changed (and a new entry in the edit-log exists) ?
- Yes.
- So you mean, that all those open() calls are to verify if a page in an internal cache has been changed (and a new entry in the edit-log exists) ?
- Note: if you just normally access "a single page", lots of pages are accessed interally from the theme and also for links (to check whether those pages exist).
We just recently finally were able to upgrade our busiest wiki from 1.8.x to 1.9.x and were hit by this as well. Tracing same user load on 1.8.x shows a many but tolerable amount of opens and seeks for the edit-log, on 1.9 there ia a constant flood of edit-log opens and seeks (in order of thousands). Our wiki instance has 12k pages with hundreds of revisions on many of them, our old server with two mirrored SATA disks was able to keep up with the load on 1.8, but with 1.9 hugely increased redundant(?) edit-log activity melts down totally.
Seems like hundreds of edit-log opens/seeks is now a norm for any request related to a more complex page. -- fenris [2011-10-18] (ps. edit-log itself is about 20 megs and pages are heavily interlinked). Usually, if same file is used again and again, the OS caching should do a good job and the stuff should basically reside in memory. So, are you sure that really this is the reason and not something else? -- ThomasWaldmann 2011-10-20 03:13:32
Pretty sure, there is something pessimal wrt/to access pattern of hundreds of edit-log opens and sub sequent seeks per request, maybe related to file access time updates (I could try mounting ext3 with noatime option later on when we have a bigger maintenance break)? We sort of verified that this change of behavior is related to edit-log changes between 1.8.x and 1.9.x by reverting selectively/by hand the changeset 4149 (http://hg.moinmo.in/moin/1.9/rev/769850545997) and getting almost tenfold performance (back to 1.8.x level) gain both under heavy user load and under test scripts that walk/exercise wiki content. We might have broken something when we reverted the change tho. Performance problem seems to be far worse on heavily linked and nontrivial pages, more cache item checks for them? -- fenris 2011-10-20 10:19:10
Just a note; in some "shared" hosting environment you're also limited for e.g. 4096 simultaneous open files. I do not think that this can lead to a problem, 'coz if every connection needs 100 open files, you'll still would need more then 40 page requests every second... (and then definitely you would need first a own server, I guess). Btw. I clean up big edit log files automatically with lograte... not nice but it helps a bit to keep up with performance. Not related to saving, but if you create a new page I found that 2 impacts can delay it:
If you have a lot (hundred) of simliary pages (like MoinMoinBugs/....), the underlay "MissingPage" with the macro <<LikePages((none))>> will display all those hundres "like pages"
- If you open the editor and have hundred of category pages, then it needs also some time to load them into the select field
-- MarcelHäfner 2011-10-18 14:38:00
Plan
- Priority:
- Assigned to:
- Status: no bug - we likely won't try to optimize that in 1.9. moin2 will do this stuff very differently anyway.