[ZODB-Dev] Re: Serious ZODB time reversal

[Andreas Kaiser]

Dieter Maurer wrote:

> Andreas Kaiser wrote at 2004-8-31 09:55 +0200:
> 
>>i have a plone instance which generates lots of "ZODB conflict error" in
>>event.log:
>>
>>2004-08-30T20:09:36 INFO(0) ZODB conflict error at 
>>/VirtualHostBase/http/host:80/foo/bar/VirtualHostRoot/X/y/folder_contents: 
>>database conflict error (oid 000000000000042d, serial was 
>>0357800120ebecdd, now 03577ffbb17eac22) (27 conflicts since startup at 
>>2004-08-30T19:19:28)
>>------
>>2004-08-30T20:09:49 INFO(0) ZODB conflict error at 
>>/VirtualHostBase/http/host:80/foo/bar/VirtualHostRoot/X/y/folder_contents: 
>>database conflict error (oid 000000000000042d, serial was 
>>0357800120ebecdd, now 03577ffbb17eac22) (28 conflicts since startup at 
>>2004-08-30T19:19:28)
>>
>>
>>1) I alwas have exactly 2 or more log records like the above for 1
>>   request.
>>
>>2) Such errors only occur with authenticated users who don´t have the
>>   "Manager" role assigned to the user itself, but have some local
>>   role(s) assigned on a subfolder of the site.
>>
>>3) Such requests consume _really_much_ cpu
>>  (> 20 seconds on a athlon-xp 2600+ / 2gb)
>>
>>Has anybody expierenced something like this?
> 
> 
> We, too, saw 1) and 3) occasionally.
> We now assume the following cause chain:
> 
>   Relevance ranking information caused excessive loads from our
>   ZEO server. This drastically slowed down some requests
>   and increased the conflict probability.
>   The actual conflicts were caused by the "TemporaryStorage"
>   (used for sessions) as it has very limited conflict resolution
>   capabilities.
> 
> The behaviour drastically improved after we banned relevance ranking
> information.

Could you please provide a little more information on how to "bann 
relevance ranking information"? I hardly know anything about ZODB 
internals (never heard of "relevance ranking information" at all), so 
any pointers to relevant documentation are appreciated.

>>I´ve also applied a patch posted by Dieter Maurer on this newsgroup to
>>get more detailed information about the objects causing the conflicts,
>>but to be honest: I don´t know what to do with this information (i.e.
>>how to identify the objects causing the problems).
> 
> The "serial was" and "now" are timestamps which can be converted
> into meaningfull times:
> 
>      from ZODB import TimeStamp
>      from binascii import a2b_hex
> 
>      str(TimeStamp(a2b_hex(timestamp)))
> 
> What is very interesting: your "was" ("2004-08-30 18:09:07.715996")
> is larger than "now" ("2004-08-30 18:03:41.600347").
> 
> This means some form of time reversal: your storage developped into
> the past: when the object was read (the serial was), it was
> last modified at "18:09" but now (at commit time), it was
> last modified at "18:03". Between reading and commit, your object
> jumped back in time...
> 
> I already saw a similar post...
> 
> Of course, time reversal can cause all forms of paradoxa and inconsistencies.
> The "Conflict Error" above, are a really harmless effect...

Yes, they don´t seem to cause any inconsitencies, the only problem is 
the enormous cpu time consumed, which makes the application rather 
unuasble for users who don´t have the "Manager" role associated.

> I expect some bug in the "TemporaryStorage" implementation.

Would replacing "TemporaryStorage" by e.g. "FileStorage" help in any 
way? Would there be any side-effects?

> I will check our log files whether I can detect there time
> reversal, too.


Thanks a lot for your help, I´m really lost here....

Andreas