Description

When using

    xapian_search = True
    xapian_index_history = True

it takes a very long time (here: around 30 s) to store edited pages with many revisions (here: around 500). This behavior stops when xapian_index_history is set to False again.

Steps to reproduce

Configure a wiki with xapian search enabled.

    xapian_search = True
    xapian_index_history = True

Generate the Xapian index.
Edit a page with many revisions.

Example

Component selection

maybe in MoinMoin/search/Xapian.py
- Maybe the index is updated when saving a page, but it shouldn't be needed to scan all revisions again and again.
- I did not try to debug the problem so far as it stops when switching off xapian_index_history.

Details

MoinMoin Version	1.8.1
OS and Version	SunOS sun 5.10
Python Version	Python 2.5.2
Server Setup	Apache 2.2 (mpm_prefork) with mod_wsgi 2.3
Server Details	xapian-core-1.0.10 and xapian-bindings-1.0.10
Language you are using the wiki in (set in the browser/UserPreferences)	de

Workaround

    xapian_search = True
    xapian_index_history = False

Discussion

Likely the code does not differentiate between pages being indexed for the first time (needs to index all revisions) and for subsequent index runs (needs to index only new revisions).

BTW, trying to reindex the same page revisions shouldn't be as bad as it sounds, because it does first a timestamp check and does only index that revision if it detects some change. So maybe the slowdown was caused by another problem, see below.

Testing

1

I installed the latest files from hg, set xapian_index_history = True and rebuild the index. http://lotek.heavy.ch/ (using xapian 1.0.4 ).But I think history search doesn't works. But (at least) a performance problem I could not verify with my wiki. How can I verify that xapian_index_history is really working? Thinks somebody else need testing, too. Sorry I can now verify that it works for me without any performance problem. I made a mistake and used the normal search, but should use the "extended search" with the correct historysearch=1. Maybe somebody else should testing also.. thx & bye -- MarcelHäfner 2009-01-28 18:19:11

Old Revsion Version: http://lotek.heavy.ch/Projekte?action=recall&rev=13
Keyword: And I can still hear her complain
Current Version: http://lotek.heavy.ch/Projekte (Revision 94)
Keyword: is not any more on this page
Search Command: http://lotek.heavy.ch/FindPage?action=fullsearch&advancedsearch=1&and_terms=And+I+can+still+hear+her+complain&or_terms=&not_terms=&mtime=&categories=&language=&mimetype=&historysearch=1
Result: it works!

2

fixed with http://hg.moinmo.in/moin/1.8/rev/38110c49d0a6 for my system
- I applied http://hg.moinmo.in/moin/1.8/rev/af8cea9bfcda and then http://hg.moinmo.in/moin/1.8/rev/af09c1b3a153 to get the patch through

New bug introduced with those bugfixes

Description

In MoinMoin 1.8.1 on the system mentioned above with the patches from above I get threading/locking errors.
Users do not get to see a new page after saving an edited page. The browser keeps loading "forever". Nevertheless the update is stored immediately as usual. MoinMoin seems to hang while trying to update the xapian index.

Details

After some usage (edits) of the wikis in the farm there seems to be a locking problem when updating.

[Sun Feb 08 10:22:31 2009] [error] Exception in thread Thread-11:
[Sun Feb 08 10:22:31 2009] [error] Traceback (most recent call last):
[Sun Feb 08 10:22:31 2009] [error]   File "/opt/webstack/python/lib/python2.5/threading.py", line 486, in __bootstrap_inner
[Sun Feb 08 10:22:31 2009] [error]     self.run()
[Sun Feb 08 10:22:31 2009] [error]   File "/opt/webstack/python/lib/python2.5/threading.py", line 446, in run
[Sun Feb 08 10:22:31 2009] [error]     self.__target(*self.__args, **self.__kwargs)
[Sun Feb 08 10:22:31 2009] [error]   File "/opt/moin/lib/python2.5/site-packages/MoinMoin/search/builtin.py",line 335, in func
[Sun Feb 08 10:22:31 2009] [error]     return f(*args, **kwargs)
[Sun Feb 08 10:22:31 2009] [error]   File "/opt/moin/lib/python2.5/site-packages/MoinMoin/search/Xapian.py", line 285, in _do_queued_updates
[Sun Feb 08 10:22:31 2009] [error]     self._index_page(request, writer, name, mode='update')
[Sun Feb 08 10:22:31 2009] [error]   File "/opt/moin/lib/python2.5/site-packages/MoinMoin/search/Xapian.py", line 447, in _index_page
[Sun Feb 08 10:22:31 2009] [error]     self._index_page_rev(request, writer, p, mode=mode)
[Sun Feb 08 10:22:31 2009] [error]   File "/opt/moin/lib/python2.5/site-packages/MoinMoin/search/Xapian.py", line 536, in _index_page_rev
[Sun Feb 08 10:22:31 2009] [error]     enq, mset, docs = writer.search(query, valuesWanted=['pagename', 'attachment', 'mtime', 'wikiname', ])
[Sun Feb 08 10:22:31 2009] [error]   File "/opt/moin/lib/python2.5/site-packages/MoinMoin/support/xapwrap/index.py", line 417, in protectedMethod
[Sun Feb 08 10:22:31 2009] [error]     self.setupDB()
[Sun Feb 08 10:22:31 2009] [error]   File "/opt/moin/lib/python2.5/site-packages/MoinMoin/support/xapwrap/index.py", line 527, in setupDB
[Sun Feb 08 10:22:31 2009] [error]     self._setupDB()
[Sun Feb 08 10:22:31 2009] [error]   File "/opt/moin/lib/python2.5/site-packages/MoinMoin/support/xapwrap/index.py", line 798, in _setupDB
[Sun Feb 08 10:22:31 2009] [error]     raise DatabaseLockError(errorMsg)
[Sun Feb 08 10:22:31 2009] [error] DatabaseLockError: cannot acquire lock file for xapian index /srv/www/mywiki/data/cache/xapian/indexbecause it is owned by process 3914
[Sun Feb 08 10:22:31 2009] [error]
...

These are the open files of the process 3914:

pfiles 3914
3914:   /opt/webstack/apache2/2.2/bin/httpd -D 32bit -k start
  Current rlimit: 65536 file descriptors
   0: S_IFCHR mode:0666 dev:284,0 ino:6815752 uid:0 gid:3 rdev:13,2
      O_RDONLY
      /devices/pseudo/mm@0:null
   1: S_IFCHR mode:0666 dev:284,0 ino:6815752 uid:0 gid:3 rdev:13,2
      O_WRONLY|O_CREAT|O_TRUNC
      /devices/pseudo/mm@0:null
   2: S_IFREG mode:0640 dev:85,3 ino:19986 uid:80 gid:80 size:63453
      O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
      /var/adm/apache/error_log
   3: S_IFDOOR mode:0444 dev:293,0 ino:59 uid:0 gid:0 size:0
      O_RDONLY|O_LARGEFILE FD_CLOEXEC  door to nscd[164]
      /var/run/name_service_door
   4: S_IFSOCK mode:0666 dev:291,0 ino:43656 uid:0 gid:0 size:0
      O_RDWR|O_NONBLOCK
        SOCK_STREAM
        SO_SNDBUF(16384),SO_RCVBUF(5120)
        sockname: AF_UNIX /var/run/opt/webstack/apache2/2.2/wsgi.3913.0.1.sock
        peername: AF_UNIX
   5: S_IFSOCK mode:0666 dev:291,0 ino:8758 uid:0 gid:0 size:0
      O_RDWR
        SOCK_STREAM
        SO_SNDBUF(49152),SO_RCVBUF(49152),IP_NEXTHOP(0.192.0.0)
        sockname: AF_INET 0.0.0.0  port: 0
   6: S_IFPORT mode:0000 dev:294,0 uid:80 gid:80 size:0
   7: S_IFIFO mode:0000 dev:282,0 ino:2298 uid:0 gid:0 size:0
      O_RDWR|O_NONBLOCK
   8: S_IFIFO mode:0000 dev:282,0 ino:2298 uid:0 gid:0 size:0
      O_RDWR
   9: S_IFREG mode:0640 dev:85,3 ino:19777 uid:80 gid:80 size:4561789
      O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
      /var/adm/apache/access_log
  11: S_IFREG mode:0640 dev:85,3 ino:20007 uid:80 gid:80 size:76035
      O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
      /var/adm/apache/moin.log
  12: S_IFREG mode:0644 dev:288,3 ino:4049138829 uid:0 gid:0 size:0
      O_WRONLY|O_CREAT|O_EXCL|O_LARGEFILE
  13: S_IFREG mode:0600 dev:288,2 ino:4084601856 uid:0 gid:0 size:0
      O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE
  14: S_IFSOCK mode:0666 dev:291,0 ino:550 uid:0 gid:0 size:0
      O_RDWR
        SOCK_STREAM
        SO_SNDBUF(16384),SO_RCVBUF(5120)
        sockname: AF_UNIX /var/run/opt/webstack/apache2/2.2/wsgi.3913.0.1.sock
  15: S_IFREG mode:0660 dev:181,65544 ino:64227 uid:0 gid:80 size:49152
      O_RDONLY|O_LARGEFILE
      /srv/www/mywiki/data/cache/xapian/index/record.DB
  16: S_IFREG mode:0660 dev:181,65544 ino:64230 uid:0 gid:80 size:172032
      O_RDONLY|O_LARGEFILE
      /srv/www/mywiki/data/cache/xapian/index/value.DB
  17: S_IFREG mode:0660 dev:181,65544 ino:64225 uid:0 gid:80 size:1810432
      O_RDONLY|O_LARGEFILE
      /srv/www/mywiki/data/cache/xapian/index/termlist.DB
  18: S_IFREG mode:0660 dev:181,65544 ino:64234 uid:0 gid:80 size:7544832
      O_RDONLY|O_LARGEFILE
      /srv/www/mywiki/data/cache/xapian/index/position.DB
  19: S_IFREG mode:0660 dev:181,65544 ino:64223 uid:0 gid:80 size:10010624
      O_RDONLY|O_LARGEFILE
      /srv/www/mywiki/data/cache/xapian/index/postlist.DB
  20: S_IFREG mode:0640 dev:85,3 ino:20007 uid:80 gid:80 size:76035
      O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
      /var/adm/apache/moin.log
  21: S_IFREG mode:0660 dev:181,65544 ino:64586 uid:0 gid:80 size:16384
      O_RDONLY|O_LARGEFILE
      /srv/www/finwiki/data/cache/xapian/index/record.DB
  22: S_IFREG mode:0660 dev:181,65544 ino:64588 uid:0 gid:80 size:73728
      O_RDONLY|O_LARGEFILE
      /srv/www/finwiki/data/cache/xapian/index/value.DB
  23: S_IFREG mode:0660 dev:181,65544 ino:64584 uid:0 gid:80 size:827392
      O_RDONLY|O_LARGEFILE
      /srv/www/finwiki/data/cache/xapian/index/termlist.DB
  24: S_IFREG mode:0660 dev:181,65544 ino:64590 uid:0 gid:80 size:3448832
      O_RDONLY|O_LARGEFILE
      /srv/www/finwiki/data/cache/xapian/index/position.DB
  25: S_IFREG mode:0660 dev:181,65544 ino:64582 uid:0 gid:80 size:4898816
      O_RDONLY|O_LARGEFILE
      /srv/www/finwiki/data/cache/xapian/index/postlist.DB
  26: S_IFPORT mode:0000 dev:294,0 uid:80 gid:80 size:0
  27: S_IFREG mode:0660 dev:181,65544 ino:28508 uid:80 gid:80 size:1570470
      O_RDONLY|O_LARGEFILE
      /srv/www/mywiki/data/edit-log
  29: S_IFREG mode:0640 dev:85,3 ino:20007 uid:80 gid:80 size:76035
      O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
      /var/adm/apache/moin.log
  30: S_IFREG mode:0660 dev:181,65544 ino:28508 uid:80 gid:80 size:1570470
      O_RDONLY|O_LARGEFILE
      /srv/www/mywiki/data/edit-log
  31: S_IFSOCK mode:0666 dev:291,0 ino:47397 uid:0 gid:0 size:0
      O_RDWR
        SOCK_STREAM
        SO_SNDBUF(16384),SO_RCVBUF(5120)
        sockname: AF_UNIX
  32: S_IFREG mode:0660 dev:181,65544 ino:28508 uid:80 gid:80 size:1570470
      O_RDONLY|O_LARGEFILE
      /srv/www/mywiki/data/edit-log
  44: S_IFREG mode:0640 dev:85,3 ino:20007 uid:80 gid:80 size:76035
      O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
      /var/adm/apache/moin.log

And here the mod_wsgi configuration

    WSGIDaemonProcess wsgi_default user=webservd group=webservd home=/srv/www processes=1 threads=10 maximum-requests=500 display-name=wsgi

New Result

A new bug was introduced or is visible now after the other bugs in xapian search were fixed.

Hmm, I think I didn't change anything related to locking. Can you test with 1.8.2 please (maybe some patch didn't apply correctly?) I am not seeing strange effects on moinmo.in site - is that crashing related to history search only? -- ThomasWaldmann 2009-02-08 19:49:13

The problem is not related to history search, it always happens with xapian search turned on. Maybe I couldn't see before as so many page updates lead to delays with xapian history search.
I upgraded to clean 1.8.2 but it didn't change. Some thread keeps the symbolic link data/cache/xapian/index/xapian_lock -> PID and when another thread/process wants to update he finds it locked:

2009-02-09 06:42:48,982 MoinMoin.search.builtin WARNING can't index: can't acquire lock

So its better to open a new Bug or any other idea what to change in the apache mpm prefork / mod_wsgi / xapian setup ?
Hmm, I switched off the loading of mod_ssl. For now I did not see the problem again. With LogLevel info in apache I saw that the wsgi daemon instances also use mod_ssl, maybe that lead to problems.
My workaround now is to comment out the SSLCryptoDevice in the ssl configuration of apache. There seem to be multi-threading problems with pkcs11 (at least in that very environment with mod_wsgi).

# SSLCryptoDevice pkcs11

This problem is out of the focus of MoinMoin.

Please open a new bug for the locking trouble, so we can gather all evidence there.

xapian index locking in moin 1.9 is done rather differently, so I guess this is fixed now.
The problem described was fixed with the bugfix below in 1.8 . The other problem was out of the focus of MoinMoin. It was some locking/multi-threading issue between Apache and libpkcs (used for https) , it went away with the workaround above and sun fixed their library some months after my bug report, so there is no more issue.

Plan

Priority:
Assigned to:
Status: fixed (please test)
- fixed by http://hg.moinmo.in/moin/1.8/rev/38110c49d0a6
- a somewhat related problem was fixed by http://hg.moinmo.in/moin/1.8/rev/af09c1b3a153 (it repeatedly indexed the same file attachments over and over again, for every revision of the page)

CategoryMoinMoinBugFixed

MoinMoin: MoinMoinBugs/1.8.1_XapianIndexHistoryPerformanceSavingManyRevisionPage (last edited 2010-01-11 11:02:04 by p5B175173)