[Zope-dev] Data.fs corruption when creating lots of objects.

[R. David Murray]

More info on the database corruption.  I took out my reindex_object
call (to reduce the ZCatalog activity), and did a get_transaction().commit()
after every object addition.  The load failed when it filled the disk
at 6GB of data.

So I went back and started loading it in 2500 record chunks and
packing after each one.  The first chunk resulted in a 177 MB
Data.fs file.  A pack on this took it down to 8MB.  Loading the
second chunk ballooned it to 295MB.  Packing that resulted in the
error I saw before when doing the load by sections:

   Error Type: CorruptedTransactionError                             
   Error Value: /usr/local/zope/directory/var/Data.fs data record exceeds
   transaction record at 185738594

Tranalyzer says:

Traceback (innermost last):
  File "tranalyzer.py", line 333, in ?
    main(sys.argv)
  File "tranalyzer.py", line 325, in main
    t = Transaction(f, off, refs)
  File "tranalyzer.py", line 170, in __init__
    self.obs.append(Record(f, refs))
  File "tranalyzer.py", line 211, in __init__
    self.vstring = f.c(vl - 16)
  File "tranalyzer.py", line 105, in c
    self.checkleft(n)
  File "tranalyzer.py", line 87, in checkleft
    raise 'Not enough data left, %d < %d' % (self.left, n)
Not enough data left, 6816 < 23567

so it finds the same problem.

Looking at the Tranalyzer output, it looks like I have three objects
per record added after a pack, but about 52 objects in each transaction
before packing.  As the load progresses, some of these objects get
rather large (>16K).

What's going on here?  The amount of data and objects being thrown
around here seems *totally* crazy.  I'm especially puzzled by those
larger and larger object sizes during a load, given that the size
of the input records is consistent.  The objects that remain after
packing are of a very reasonable size (around 350-400 bytes each).
And why does the addition of a single new ZClass instance result
in *52* objects in the transaction, when I would assume that only
the Catalog and the containing folder are getting modified in the
transaction?

(For review, I'm adding a simple catalog aware ZClass object that
has about a dozen properties, but I'm trying to add a little less
than 60,000 of them).

Can anyone with some knowledge of how the ZODB in general and FileStorage
in particular works give me a clue what is going on here?  Is this
really normal behavior, to need this huge amount of disk space to
handle what seem to be simple updates?

I'm trying to narrow down the corruption to a quickly repeatable
operation so I can start to insturment what's going on, but I'm really
puzzled by what the Zope transaction/object machinery is doing here.

--RDM