search

zodb / relstorage

A backend for ZODB that stores pickles in a relational database.
Other
54 stars 46 forks source link

Problem packing RelStorage #448

Closed jensens closed 3 years ago

jensens commented 3 years ago

I have a Plone 5.2.3 setup and use RelStorage in a Docker Swarm setup. It is using the latest v12 image from https://hub.docker.com/_/postgres (which is a 12.6 currently) - unmodified.

I run RelStorage in history free mode and is configured for historical reasons with a separate blobstorage like so:

    %import relstorage
    <relstorage>
        keep-history false
        shared-blob-dir true
        blob-dir /blobstorage
        cache-local-mb $(RELSTORAGE_LOCAL_MB)
        <postgresql>
            dsn dbname='plone' host='db' user='plone' 
        </postgresql>
    </relstorage>

Until today I never tried to pack the DB after the migration to Python 3. It does not grow much here due to history free mode.

But now I got:

plone@792a10ec4502:/plone/buildout$ ./bin/zodbpack -d 1 relstorage-pack.cfg
2021-03-02 10:13:30,456 [relstorage._util] DEBUG Using value 0.31 from environ 'RS_PERF_LOG_TRACE_MIN'=0.31 (default=0.31)
2021-03-02 10:13:30,456 [relstorage._util] DEBUG Using value 1.24 from environ 'RS_PERF_LOG_DEBUG_MIN'=1.24 (default=1.24)
2021-03-02 10:13:30,457 [relstorage._util] DEBUG Using value 3.03 from environ 'RS_PERF_LOG_INFO_MIN'=3.03 (default=3.03)
2021-03-02 10:13:30,457 [relstorage._util] DEBUG Using value 9.24 from environ 'RS_PERF_LOG_WARNING_MIN'=9.24 (default=9.24)
2021-03-02 10:13:30,457 [relstorage._util] DEBUG Using value 20.1 from environ 'RS_PERF_LOG_ERROR_MIN'=20.1 (default=20.1)
2021-03-02 10:13:30,457 [relstorage._util] DEBUG Using value WARN from environ 'RS_PERF_LOG_DETAILS_LEVEL'='WARN' (default='WARN')
2021-03-02 10:13:30,457 [relstorage._util] DEBUG Using value on from environ 'RS_PERF_LOG_ENABLE'='on' (default='on')
2021-03-02 10:13:30,520 [relstorage._util] DEBUG Using value None from environ 'RS_CACHE_POLL_TIMEOUT'=None (default=None)
2021-03-02 10:13:30,521 [relstorage._util] DEBUG Using value None from environ 'RS_MAX_POOLED_STORE_CONNECTIONS'=None (default=None)
2021-03-02 10:13:30,528 [zodbpack] INFO Opening storage (RelStorageFactory)...
2021-03-02 10:13:30,535 [relstorage._util] DEBUG Using value 4096 from environ 'RS_PACK_CURSOR_ARRAYSIZE'=4096 (default=4096)
2021-03-02 10:13:30,535 [relstorage._util] DEBUG Using value 4096 from environ 'RS_PACK_STORE_BATCH_SIZE'=4096 (default=4096)
2021-03-02 10:13:30,535 [relstorage._util] DEBUG Using value 120 from environ 'RS_PACK_COMMIT_FREQUENCY'=120 (default=120)
2021-03-02 10:13:30,535 [relstorage._util] DEBUG Using value 1024 from environ 'RS_PACK_DOWNLOAD_BATCH_SIZE'=1024 (default=1024)
2021-03-02 10:13:30,535 [relstorage._util] DEBUG Using value 1000 from environ 'RS_PACK_HP_DELETE_BATCH_SIZE'=1000 (default=1000)
2021-03-02 10:13:30,555 [relstorage.adapters.drivers] DEBUG Using driver <relstorage.adapters.postgresql.drivers.psycopg2.Psycopg2Driver object at 0x7fd1621b2e80> for requested name 'auto'
2021-03-02 10:13:30,555 [relstorage.adapters.schema] DEBUG Reading stored procedures from /home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/postgresql/procs and /home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/postgresql/procs/hf
2021-03-02 10:13:30,565 [relstorage.adapters.postgresql.drivers] DEBUG Message from the RDBMS: NOTICE:  relation "zoid_seq" already exists, skipping
2021-03-02 10:13:30,577 [ZODB.blob] DEBUG (39) Blob directory `/blobstorage` has layout marker set. Selected `bushy` layout. 
2021-03-02 10:13:30,579 [zodbpack] INFO Packing storage (RelStorageFactory).
2021-03-02 10:13:30,582 [relstorage.storage.pack] INFO pack: beginning pre-pack
2021-03-02 10:13:30,588 [relstorage.storage.pack] INFO Analyzing transactions committed Mon Mar  1 10:09:53 2021 or before (TID 278773914251888315)
2021-03-02 10:13:30,588 [relstorage.adapters.packundo] INFO pre_pack: filling the pack_object table
2021-03-02 10:13:44,717 [relstorage.adapters.packundo] INFO pre_pack: Filled the pack_object table
2021-03-02 10:13:44,723 [relstorage.adapters.packundo] DEBUG pre_pack: Collecting objects to examine.
2021-03-02 10:14:35,673 [relstorage.adapters.packundo] DEBUG pre_pack: Downloaded objects to examine (memory delta: 0 KB; download time: 50.84; sort time 0.03)
2021-03-02 10:14:35,679 [relstorage.adapters.packundo] INFO pre_pack: analyzing references from 652027 object(s) (memory delta: 0 KB)
2021-03-02 10:14:37,960 [relstorage.adapters.packundo] ERROR pre_pack: failed
Traceback (most recent call last):
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/packundo.py", line 1445, in pre_pack
    self._pre_pack_main(load_connection, store_connection,
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/packundo.py", line 1524, in _pre_pack_main
    self.fill_object_refs(load_connection, store_connection, get_references)
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/packundo.py", line 1325, in fill_object_refs
    refs_found = self._add_refs_for_oids(load_batcher, store_batcher,
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/packundo.py", line 1382, in _add_refs_for_oids
    store_batcher.insert_into(
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/batch.py", line 149, in insert_into
    self._flush_if_needed()
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/batch.py", line 100, in _flush_if_needed
    return self.flush()
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/batch.py", line 273, in flush
    count += self._do_inserts()
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/batch.py", line 364, in _do_inserts
    self.cursor.execute(stmt, params)
psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "object_refs_added_pkey"
DETAIL:  Key (zoid)=(8834895) already exists.

Traceback (most recent call last):
  File "./bin/zodbpack", line 292, in <module>
    sys.exit(relstorage.zodbpack.main())
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/zodbpack.py", line 106, in main
    storage.pack(t, ZODB.serialize.referencesf)
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/storage/__init__.py", line 915, in pack
    result = pack.pack(t, referencesf, prepack_only, skip_prepack)
  File "src/perfmetrics/metric.py", line 72, in perfmetrics._metric._AbstractMetricImpl.__call__
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/storage/pack.py", line 208, in pack
    tid_int = self.__pre_pack(t, referencesf)
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/storage/pack.py", line 135, in __pre_pack
    self.packundo.pre_pack(tid_int, get_references)
  File "src/perfmetrics/metric.py", line 72, in perfmetrics._metric._AbstractMetricImpl.__call__
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/packundo.py", line 1445, in pre_pack
    self._pre_pack_main(load_connection, store_connection,
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/packundo.py", line 1524, in _pre_pack_main
    self.fill_object_refs(load_connection, store_connection, get_references)
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/packundo.py", line 1325, in fill_object_refs
    refs_found = self._add_refs_for_oids(load_batcher, store_batcher,
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/packundo.py", line 1382, in _add_refs_for_oids
    store_batcher.insert_into(
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/batch.py", line 149, in insert_into
    self._flush_if_needed()
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/batch.py", line 100, in _flush_if_needed
    return self.flush()
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/batch.py", line 273, in flush
    count += self._do_inserts()
  File "/home/plone/.buildout/shared-eggs/RelStorage-3.4.0-py3.8-linux-x86_64.egg/relstorage/adapters/batch.py", line 364, in _do_inserts
    self.cursor.execute(stmt, params)
psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "object_refs_added_pkey"
DETAIL:  Key (zoid)=(8834895) already exists.

I have no clue whats going on. Any idea whats wrong?

Further I checked a zodbconvert to filestorage which works fine.

jamadden commented 3 years ago

I haven't encountered that before. It would seem to be something data-dependent. I don't suppose the database is something you could share?

That assumes the pack tables had been in a good state before beginning. If you haven't packed this database in awhile, but had packed it at some point in the past using an older version of RelStorage, that might not be the case — RelStorage relies on some sorting/de-duplication happening in the database, but in the past I don't think it did. You could test this by truncating the pack tables, then trying the pack again:

$ psql …
relstoragetest=> TRUNCATE TABLE object_refs_added, object_ref, pack_object CASCADE;
TRUNCATE TABLE
relstoragetest=> commit;
jensens commented 3 years ago

This fixed it, thanks so much! It looks like the pack tables were broken. I just have no idea why.

jamadden commented 3 years ago

Glad it was an easy fix!

It looks like the pack tables were broken. I just have no idea why.

Presumably it was packed a long time ago with an older version of RelStorage. Some state in the pack tables is left behind on purpose, but apparently across large version differences that can be an issue.