Serious ZODB time reversal (was: Re: [ZODB-Dev] ZODB conflict error with authenticated users)

[Dieter Maurer]

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.

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

I expect some bug in the "TemporaryStorage" implementation.
I will check our log files whether I can detect there time
reversal, too.

-- 
Dieter