fstest reports time-stamp reduction, what does it mean and should I be worried?
Hi All, For one customer, I have a secondary storage server that copies repozo backups, restores them and then runs fstest over the restored result once every few hours. (I'd like to move to zeoraid, but it's not quite there yet!) On a few occasions recently, fstest has complained similar to the following: time-stamp reduction at 25557500079: 0x037c544b2c8defcc <= 0x037c550ba17c7555 What does this mean? Why does it appear to go away later? Should I be worried about it? cheers, Chris -- Simplistix - Content Management, Zope & Python Consulting - http://www.simplistix.co.uk
Chris Withers wrote at 2009-3-5 11:28 +0000:
For one customer, I have a secondary storage server that copies repozo backups, restores them and then runs fstest over the restored result once every few hours. (I'd like to move to zeoraid, but it's not quite there yet!)
On a few occasions recently, fstest has complained similar to the following:
time-stamp reduction at 25557500079: 0x037c544b2c8defcc <= 0x037c550ba17c7555
Are you using an old ZODB version? Modern ZODB versions should no longer be able to produce this situation.
What does this mean?
A "FileStorage" file is effectively a sequence of transaction logs. The transaction id is usually a timestamp. As a later transaction log entry is written later, its transaction id (aka timestamp) should be leater as earlier transaction logs. This is not the case in your storage. In older ZODB versions, this should happen when your clock jumped back into the past. Modern ZODB versions ensure that transaction ids are strictly increasing (of course, then they are no longer timestamps).
Why does it appear to go away later?
It should only go away when the out-of-order transaction log entry is deleted in a pack process.
Should I be worried about it?
The information in "ConflictError" log entries give you wrong time information. Also, packing may work differently than your expect (during packing the transaction ids are interpreted as timestamps -- and this requires that they truely reflect the time (which does not jump into the past)). -- Dieter
Dieter Maurer wrote:
Are you using an old ZODB version?
Nope, Zope 2.9.8.
In older ZODB versions, this should happen when your clock jumped back into the past.
The clocks on both the storage servers are NTP synched and I'm pretty sure they've not jumped back at any point...
Also, packing may work differently than your expect (during packing the transaction ids are interpreted as timestamps -- and this requires that they truely reflect the time (which does not jump into the past)).
Well, the storage in question is packed once an hour, and I've had no complaints from the customers, so I'm guessing this may not matter... Chris
Chris Withers wrote at 2009-3-8 12:26 +0000:
Nope, Zope 2.9.8.
In older ZODB versions, this should happen when your clock jumped back into the past.
The clocks on both the storage servers are NTP synched and I'm pretty sure they've not jumped back at any point...
Another (more serious) cause can be a corruption of the storage file. The timestamp is part of the file data -- it the data changes, the timestamps may seem to be out of order. -- Dieter
participants (2)
-
Chris Withers -
Dieter Maurer