[Xapian-discuss] another DatabaseModifiedError issue

[Markus Wörle]

Am 28.05.2008 um 15:09 schrieb Olly Betts:

> Could this be due to the automatic flushing which happens (by default
> every 10000 changed documents)?  You can avoid that by using
> transactions, or by setting environment variable  
> XAPIAN_FLUSH_THRESHOLD
> to a very large value.
>

> Otherwise, what's the minimum time between explicit flushes on the
> *same* database object?
>
> And what's the maximum search time?

I already set XAPIAN_FLUSH_THRESHOLD to 100000. My writer gets about  
1200 changes per minute, and flush()es a database after a configured  
period of time, between 5 and 30 minutes. Therefore the minimum time  
between expicit flushes on the same database object should never go  
below 5 minutes.

The slowest search during the last 24 hours took about 1.2 seconds.

> Perhaps add logging around the flush() and reopen()+get_mset() calls  
> to
> make sure these times are as you think they are?

I did so, and actually found out several things:

* I added microsecond-timestamps to my logfiles and collected samples  
over night. It seems that my problem has in fact nothing to do with  
consecutive flushes of different databases. It seems that I noticed  
this behaviour by chance and took wrong conclusions after I saw my  
workaround (the sleeps between the flushes) working.

Instead, I found out that the errors occurs after flushing my most  
frequented index (which is called 'profile').

For examle,

my writer says:
29/05/08 08:20:05 (21663) [Wtf::Retriever] processing /var/lib/wtf/ 
spin-de/queue/16029258.queue
29/05/08 08:20:06 (21663) [Wtf::Index] 1212042006.4986 flushing  
profile 1242 docs
29/05/08 08:20:49 (21663) [Wtf::Index] 1212042049.26964 flushed  
profile in 43 s
29/05/08 08:20:49 (21663) [Wtf::Retriever] processing /var/lib/wtf/ 
spin-de/queue/16029259.queue

my reader says:
29/05/08 08:20:49 (27530) [Wtf::Search] 1212042049.20936 reopen() db  
profile
29/05/08 08:20:49 (27530) [Wtf::Search] 1212042049.21301 mset() db  
profile
terminate called after throwing an instance of  
'Xapian::DatabaseModifiedError'

* I (amateurishly) patched the xapian-core lib to log all calls of  
FlintDatabase::set_revision_number(), and the throw-points of the  
XapianModifiedErrors.

After that, the logs say,

writer:
29/05/08 15:09:07 (15024) [Wtf::Index] 1212066547.26159 flushing  
profile 3517 docs
new_revision: 9965
29/05/08 15:10:13 (15024) [Wtf::Index] 1212066613.75014 flushed  
profile in 66 s
(...)
29/05/08 15:14:08 (15024) [Wtf::Index] 1212066848.09385 flushing  
profile 2768 docs
new_revision: 9966
29/05/08 15:15:09 (15024) [Wtf::Index] 1212066909.94393 flushed  
profile in 61 s
(...)
29/05/08 15:19:09 (15024) [Wtf::Index] 1212067149.55253 flushing  
profile 3246 docs
new_revision: 9967
29/05/08 15:20:12 (15024) [Wtf::Index] 1212067212.71607 flushed  
profile in 63 s

You see the database revision got only increased by 1 with each  
explicit flush().

reader:
29/05/08 15:15:09 (15062) [Wtf::Search] 1212066909.91764 reopen() db  
profile
29/05/08 15:15:09 (15062) [Wtf::Search] 1212066909.9181 mset() db  
profile
Xapian::DatabaseModifiedError: set_overwritten
terminate called after throwing an instance of  
'Xapian::DatabaseModifiedError'
29/05/08 15:15:09 (15060) [Wtf::Search] 1212066909.99887 reopen() db  
profile
29/05/08 15:15:09 (15060) [Wtf::Search] 1212066909.99924 mset() db  
profile
Xapian::DatabaseModifiedError: set_overwritten
terminate called after throwing an instance of  
'Xapian::DatabaseModifiedError'

Which means that the exception got thrown in  
FlintTable::set_overwritten().

I hope this information helps in some way.

Regards,
mrks