Problem packing RelStorage

[tflorac]

Hi,
As issue #448 was closed, I'm opening a new issue for the same problem...
I'm using RelStorage 3.4.5 with Python 3.5 and PostgreSQL 9.6 on a Debian "Stretch" server, with default settings; the storage (containing 3 millions objects) is history-free, and it is packed each day.
I get the same packing error very frequently; if I truncate the tables, the pack is OK, but the problem appears again a few days after... :-/

Best regards,
Thierry

[tflorac]

Hi,
I didn't received any feedback for this issue...
The problem is always here, and my database packing is always failing except if I truncate the tables before...
Could it be possible to "force" tables truncation before packing?
Bets regards,
Thierry

[jamadden]

I would prefer not to add a 'force truncate' option, because that would just be hiding the underlying issue, and it's that issue that needs to be fixed (if it isn't database-specific). I've never reproduced anything like this. If you can provide a simple reproducer, that would go a long way to solving this.

[tflorac]

Hi Jason,
I don't know how to reproduce this problem actually.
A pack fails, I truncate the tables, pack is working again and after a few days of normal usage it fails again... :/
Best regards,
Thierry

[wosc]

I have the same issue: relstorage-3.5.0, python-3.10, keep_history=no, postgres-9.6, zodbpack fails with "zoid=xyz already exists", running truncate object_refs_added fixes that, but only temporarily. I'm seeing it rather frequently in our staging environment (which receives very little user traffic), with the error occurring as little as 4 hours after the previous successful zodbpack run.

I've tried a bit to reproduce this in isolation (e.g. in a separate psql db on the same server, load some very minimal data into zodb/relstorage with the same application code, run zodbpack, etc), but haven't managed to provoke the error that way. :(

[templiert]

I am having the same pack issue, both with mysql and postgresql:

• truncate object_ref and object_refs_added fixes the issue
• after a few hours the problem occurs again
• I think the same issue was reported 13 years ago here. My two takeaways:

  • it is quite safe to remove rows from object_ref as long as you also remove the corresponding rows from object_refs_added. To be 100% safe, you could just clear both object_refs_added and object_ref before packing

  • some insight into how it had supposedly been fixed in 1.5.0. But probably does not apply here:

    If you interrupt the pack operation while the object_ref table is being filled

I am sharing my 2x configurations and tracebacks below.

main config

• win10
• no framework (no Plone, no ZEO)
• the db is 1 day old, so this is not due to version mismatch across packing attempts

        keep-history false
        commit-lock-timeout 60
        shared-blob-dir false
        pack-gc true 
        cache-local-mb 10000
        cache-local-object-max 1000000
        cache-local-dir {params_relstorage.cache_local_dir}

postgresql 16

INFO 2024-01-24T10:00:21.465 >>> ------------------ open db ... -------------------
DEBUG 2024-01-24T10:00:21.566 Using value 0.31 from environ 'RS_PERF_LOG_TRACE_MIN'=0.31 (default=0.31) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.568 Using value 1.24 from environ 'RS_PERF_LOG_DEBUG_MIN'=1.24 (default=1.24) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.568 Using value 3.03 from environ 'RS_PERF_LOG_INFO_MIN'=3.03 (default=3.03) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.568 Using value 9.24 from environ 'RS_PERF_LOG_WARNING_MIN'=9.24 (default=9.24) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.574 Using value 20.1 from environ 'RS_PERF_LOG_ERROR_MIN'=20.1 (default=20.1) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.577 Using value WARN from environ 'RS_PERF_LOG_DETAILS_LEVEL'='WARN' (default='WARN') | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.578 Using value on from environ 'RS_PERF_LOG_ENABLE'='on' (default='on') | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.578 Using value 0.1 from environ 'RS_PERF_STATSD_SAMPLE_RATE'=0.1 (default=0.1) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.578 Using value True from environ 'RS_COMMIT_EXIT_CRIT_EARLY'=True (default=True) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.605 Using value 1024 from environ 'RS_CURSOR_ARRAYSIZE'=1024 (default=1024) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.adapters.drivers | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.714 Using value None from environ 'RS_CACHE_POLL_TIMEOUT'=None (default=None) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.cache.mvcc | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.714 Using value 1000 from environ 'RS_CACHE_MVCC_MAX_DEPTH'=1000 (default=1000) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.cache.mvcc | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.722 Using value None from environ 'RS_MAX_POOLED_STORE_CONNECTIONS'=None (default=None) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.adapters.connections | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.733 Using value False from environ 'RELSTORAGE_LOCK_EARLY'=False (default=False) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.storage.tpc | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.745 Using value 4096 from environ 'RS_PACK_CURSOR_ARRAYSIZE'=4096 (default=4096) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.745 Using value 4096 from environ 'RS_PACK_STORE_BATCH_SIZE'=4096 (default=4096) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.745 Using value 120 from environ 'RS_PACK_COMMIT_FREQUENCY'=120 (default=120) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.745 Using value 1024 from environ 'RS_PACK_DOWNLOAD_BATCH_SIZE'=1024 (default=1024) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.751 Using value 1000 from environ 'RS_PACK_HP_DELETE_BATCH_SIZE'=1000 (default=1000) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-24T10:00:21.786 Using driver <relstorage.adapters.postgresql.drivers.psycopg2.Psycopg2Driver object at 0x0000027714B84210> for requested name 'auto' | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | drivers | relstorage.adapters.drivers | _select_driver_by_name | 69
DEBUG 2024-01-24T10:00:21.786 Reading stored procedures from C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\postgresql\procs and C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\postgresql\procs\hf | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | schema | relstorage.adapters.schema | _read_proc_files | 278
DEBUG 2024-01-24T10:00:21.888 Message from the RDBMS: NOTICE:  relation "zoid_seq" already exists, skipping | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | drivers | relstorage.adapters.postgresql.drivers | __transaction_boundary | 301
DEBUG 2024-01-24T10:00:21.971 Connection: <Connection at 0x27731c3f850 to 'C:\\myuser\\relstorage\\cache_local\\relstorage-cache2-mydb.sqlite3' in_transaction=False>.
	Using sqlite3 version: 3.41.2.
	Default    connection settings: {'page_size': 4096, 'mmap_size': 0, 'temp_store': 0, 'wal_autocheckpoint': 1000, 'soft_heap_limit': 0, 'cache_size': -2000, 'page_count': 10876, 'busy_timeout': 15000, 'query_only': 0, 'journal_mode': 'wal'}.
	Changing   connection settings: {'journal_size_limit': -1, 'synchronous': 2, 'cache_spill': 483}.
	Desired    connection settings: {'journal_size_limit': 10485760, 'synchronous': 1, 'cache_spill': 0}.
	Unapplied  connection settings: {}.
	 | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | drivers | relstorage.adapters.sqlite.drivers | __check_and_log | 246
INFO 2024-01-24T10:00:23.835 Bulk update of empty cache: Examined 77196 and stored 77196 items from <Connection at 0x27731c3f850 to 'C:\\myuser\\relstorage\\cache_local\\relstorage-cache2-mydb.sqlite3' in_transaction=False> in 0.11539816856384277 using 48.78 MB. (8.32 MB local) (<relstorage.cache.local_client.LocalClient object at 0x00000277229B9BD0>)
DEBUG 2024-01-24T10:00:23.838 Function read_from_sqlite took 1.779s. | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _util | relstorage.cache.local_client.timing | do_log_duration_info | 280
INFO 2024-01-24T10:00:23.852 Polling 77196 oids stored in cache with SQL timeout None
INFO 2024-01-24T10:00:24.581 Polled 77196 older oids stored in cache (27877 found in database); 73720 survived
DEBUG 2024-01-24T10:00:24.589 Connection: <Connection at 0x27731c3f850 to 'C:\\myuser\\relstorage\\cache_local\\relstorage-cache2-mydb.sqlite3' in_transaction=False>.
	Using sqlite3 version: 3.41.2.
	Default    connection settings: {'page_size': 4096, 'mmap_size': 0, 'temp_store': 0, 'wal_autocheckpoint': 1000, 'soft_heap_limit': 0, 'cache_size': -2000, 'page_count': 10876, 'busy_timeout': 15000, 'query_only': 0, 'journal_mode': 'wal'}.
	Changing   connection settings: {'journal_size_limit': -1, 'synchronous': 2, 'cache_spill': 483}.
	Desired    connection settings: {'journal_size_limit': 10485760, 'synchronous': 1, 'cache_spill': 0}.
	Unapplied  connection settings: {}.
	 | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | drivers | relstorage.adapters.sqlite.drivers | __check_and_log | 246
DEBUG 2024-01-24T10:00:24.714 Removed 3476 invalid OIDs from <Connection at 0x27731c3f850 to 'C:\\myuser\\relstorage\\cache_local\\relstorage-cache2-mydb.sqlite3' in_transaction=closed> | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | local_client | relstorage.cache.local_client | remove_invalid_persistent_oids | 315
DEBUG 2024-01-24T10:00:24.715 Using driver <relstorage.adapters.postgresql.drivers.psycopg2.Psycopg2Driver object at 0x0000027731111210> for requested name 'auto' | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | drivers | relstorage.adapters.drivers | _select_driver_by_name | 69
DEBUG 2024-01-24T10:00:24.922 Invalidating all persistent objects for viewer <StorageCache at 0x2773c3b97e0 hvt=None bytes=40758995 len=73720 state=<relstorage.cache.mvcc.MVCCDatabaseCoordinator object at 0x000002772386A710>> (detached? False) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | mvcc | relstorage.cache.mvcc | _find_changes_for_viewer | 331
DEBUG 2024-01-24T10:00:24.922 new transaction | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _transaction | txn.8676 | __init__ | 114
DEBUG 2024-01-24T10:00:24.926 commit | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | _transaction | txn.8676 | commit | 290
INFO 2024-01-24T10:00:24.930 <<< -------------------- open db. -------------------- | 3.462s
INFO 2024-01-24T10:00:24.930 >>> ------------- open db conection ... --------------
INFO 2024-01-24T10:00:24.932 <<< --------------- open db conection. --------------- | 0.001s
WARNING 2024-01-24T10:00:24.936 pack db in parallel | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | zodb | root | _open_pack_backup_db
INFO 2024-01-24T10:00:24.939 >>> ------------------ pack db ... -------------------
INFO 2024-01-24T10:00:25.040 pack: beginning pre-pack
INFO 2024-01-24T10:00:25.138 Analyzing transactions committed Wed Jan 24 09:59:50 2024 or before (TID 285436396177254946)
INFO 2024-01-24T10:00:25.140 pre_pack: filling the pack_object table
INFO 2024-01-24T10:00:25.700 pre_pack: Filled the pack_object table
DEBUG 2024-01-24T10:00:25.773 pre_pack: Collecting objects to examine. | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | packundo | relstorage.adapters.packundo | fill_object_refs | 1228
DEBUG 2024-01-24T10:00:26.300 pre_pack: Downloaded objects to examine (memory delta: 52.00 KB; download time: 0.21; sort time 0.08) | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | packundo | relstorage.adapters.packundo | fill_object_refs | 1265
INFO 2024-01-24T10:00:26.352 pre_pack: analyzing references from 28901 object(s) (memory delta: 52.00 KB)
ERROR 2024-01-24T10:00:26.490 pre_pack: failed | 2892 | Dask Worker process (from Nanny) | Dask-Default-Threads-2892-3875 | 8676 | packundo | relstorage.adapters.packundo | pre_pack | 1454 | (<class 'psycopg2.errors.UniqueViolation'>, UniqueViolation('duplicate key value violates unique constraint "object_refs_added_pkey"\nDETAIL:  Key (zoid)=(20975) already exists.\n'), <traceback object at 0x000002770E003B40>) | None
Traceback (most recent call last):
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\packundo.py", line 1451, in pre_pack
    self._pre_pack_main(load_connection, store_connection,
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\packundo.py", line 1530, in _pre_pack_main
    self.fill_object_refs(load_connection, store_connection, get_references)
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\packundo.py", line 1331, in fill_object_refs
    refs_found = self._add_refs_for_oids(load_batcher, store_batcher,
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\packundo.py", line 1388, in _add_refs_for_oids
    store_batcher.insert_into(
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\batch.py", line 149, in insert_into
    self._flush_if_needed()
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\batch.py", line 100, in _flush_if_needed
    return self.flush()
           ^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\batch.py", line 273, in flush
    count += self._do_inserts()
             ^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\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)=(20975) already exists.

mysql 8.0

INFO 2024-01-23T09:23:09.370 >>> ------------------ open db ... -------------------
DEBUG 2024-01-23T09:23:09.492 Using value 0.31 from environ 'RS_PERF_LOG_TRACE_MIN'=0.31 (default=0.31) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.492 Using value 1.24 from environ 'RS_PERF_LOG_DEBUG_MIN'=1.24 (default=1.24) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.494 Using value 3.03 from environ 'RS_PERF_LOG_INFO_MIN'=3.03 (default=3.03) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.494 Using value 9.24 from environ 'RS_PERF_LOG_WARNING_MIN'=9.24 (default=9.24) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.494 Using value 20.1 from environ 'RS_PERF_LOG_ERROR_MIN'=20.1 (default=20.1) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.494 Using value WARN from environ 'RS_PERF_LOG_DETAILS_LEVEL'='WARN' (default='WARN') | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.497 Using value on from environ 'RS_PERF_LOG_ENABLE'='on' (default='on') | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.497 Using value 0.1 from environ 'RS_PERF_STATSD_SAMPLE_RATE'=0.1 (default=0.1) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.timing | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.497 Using value True from environ 'RS_COMMIT_EXIT_CRIT_EARLY'=True (default=True) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.514 Using value 1024 from environ 'RS_CURSOR_ARRAYSIZE'=1024 (default=1024) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.adapters.drivers | _setting_from_environ | 104
INFO 2024-01-23T09:23:09.540 >>>  check MFOV bare | station 2 | wafer   58_a | scan    -5 | slab    202 | region  1 | mfov    39 ... 
DEBUG 2024-01-23T09:23:09.611 Using value None from environ 'RS_CACHE_POLL_TIMEOUT'=None (default=None) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.cache.mvcc | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.612 Using value 1000 from environ 'RS_CACHE_MVCC_MAX_DEPTH'=1000 (default=1000) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.cache.mvcc | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.617 Using value None from environ 'RS_MAX_POOLED_STORE_CONNECTIONS'=None (default=None) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.adapters.connections | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.627 Using value False from environ 'RELSTORAGE_LOCK_EARLY'=False (default=False) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.storage.tpc | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.655 Using value 4096 from environ 'RS_PACK_CURSOR_ARRAYSIZE'=4096 (default=4096) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.657 Using value 4096 from environ 'RS_PACK_STORE_BATCH_SIZE'=4096 (default=4096) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.658 Using value 120 from environ 'RS_PACK_COMMIT_FREQUENCY'=120 (default=120) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.658 Using value 1024 from environ 'RS_PACK_DOWNLOAD_BATCH_SIZE'=1024 (default=1024) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.659 Using value 1000 from environ 'RS_PACK_HP_DELETE_BATCH_SIZE'=1000 (default=1000) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.adapters.packundo | _setting_from_environ | 104
DEBUG 2024-01-23T09:23:09.665 Attempting to load driver named 'gevent MySQLdb' from 'MySQLdb' failed; if no driver was specified, or the driver was set to 'auto', there may be more drivers to attempt. | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | drivers | relstorage.adapters.drivers | _check_preconditions | 230
Traceback (most recent call last):
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\drivers.py", line 228, in _check_preconditions
    mod = self.get_driver_module()
          ^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\drivers.py", line 250, in get_driver_module
    return importlib.import_module(self.MODULE_NAME)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\importlib\__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<frozen importlib._bootstrap>", line 1204, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1176, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1140, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'MySQLdb'
DEBUG 2024-01-23T09:23:09.670 Attempting to load driver named 'MySQLdb' from 'MySQLdb' failed; if no driver was specified, or the driver was set to 'auto', there may be more drivers to attempt. | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | drivers | relstorage.adapters.drivers | _check_preconditions | 230
Traceback (most recent call last):
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\drivers.py", line 228, in _check_preconditions
    mod = self.get_driver_module()
          ^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\drivers.py", line 250, in get_driver_module
    return importlib.import_module(self.MODULE_NAME)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\importlib\__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<frozen importlib._bootstrap>", line 1204, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1176, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1140, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'MySQLdb'
DEBUG 2024-01-23T09:23:09.683 Using driver <relstorage.adapters.mysql.drivers.pymysql.PyMySQLDriver object at 0x00000165A46CADD0> for requested name 'auto' | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | drivers | relstorage.adapters.drivers | _select_driver_by_name | 69
DEBUG 2024-01-23T09:23:09.684 Reading stored procedures from C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\mysql\procs and C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\mysql\procs\hf | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.schema | _read_proc_files | 278
DEBUG 2024-01-23T09:23:09.714 All tables already InnoDB | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | __convert_all_tables_to_innodb | 188
DEBUG 2024-01-23T09:23:09.729 Checksum for procedure clean_temp_state matches: 9463343e2db8cd538d99d8afffdb87bd; ver 8 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | create_procedures | 290
DEBUG 2024-01-23T09:23:09.729 Checksum for procedure lock_database_for_commit matches: 38b3c22833a2ae50b6939f360446bd35; ver 8 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | create_procedures | 290
DEBUG 2024-01-23T09:23:09.729 Checksum for procedure lock_objects_and_detect_conflicts matches: a617f93c778db85e258f1d7304caa475; ver 8 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | create_procedures | 290
DEBUG 2024-01-23T09:23:09.734 Checksum for procedure make_current_tid matches: e10a5b980efd7a2fec4ade0f1494fa2f; ver 8 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | create_procedures | 290
DEBUG 2024-01-23T09:23:09.735 Checksum for procedure make_tid_for_epoch matches: 39468fb7223acf263f9ea38d2d61ab63; ver 8 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | create_procedures | 290
DEBUG 2024-01-23T09:23:09.735 Checksum for procedure set_min_oid matches: 07a5d39473e135f12de318352513d102; ver 8 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | create_procedures | 290
DEBUG 2024-01-23T09:23:09.735 Checksum for procedure lock_and_choose_tid matches: c9b39e55afaaa86a0ebb7cf63144f2de; ver 8 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | create_procedures | 290
DEBUG 2024-01-23T09:23:09.737 Checksum for procedure lock_and_choose_tid_and_move matches: c47a16074a90087cb0588743b295f9b1; ver 8 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | create_procedures | 290
DEBUG 2024-01-23T09:23:09.737 Checksum for procedure lock_and_choose_tid_p matches: 2d368ceb66767b88f791a8176e9e9773; ver 8 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | schema | relstorage.adapters.mysql.schema | create_procedures | 290
DEBUG 2024-01-23T09:23:09.771 Garbage collected 1595 old OIDs less than 40012 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | oidallocator | relstorage.adapters.oidallocator | garbage_collect_oids | 208
DEBUG 2024-01-23T09:23:09.775 Garbage collected 0 old OIDs less than 40012 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | oidallocator | relstorage.adapters.oidallocator | garbage_collect_oids | 208
DEBUG 2024-01-23T09:23:09.796 Connection: <Connection at 0x165a9da3150 to 'C:\\myuser\\relstorage\\cache_local\\relstorage-cache2-mydb.sqlite3' in_transaction=False>.
	Using sqlite3 version: 3.41.2.
	Default    connection settings: {'page_size': 4096, 'mmap_size': 0, 'temp_store': 0, 'wal_autocheckpoint': 1000, 'soft_heap_limit': 0, 'cache_size': -2000, 'page_count': 3975, 'busy_timeout': 15000, 'query_only': 0, 'journal_mode': 'wal'}.
	Changing   connection settings: {'journal_size_limit': -1, 'synchronous': 2, 'cache_spill': 483}.
	Desired    connection settings: {'journal_size_limit': 10485760, 'synchronous': 1, 'cache_spill': 0}.
	Unapplied  connection settings: {}.
	 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | drivers | relstorage.adapters.sqlite.drivers | __check_and_log | 246
INFO 2024-01-23T09:23:11.856 Bulk update of empty cache: Examined 30527 and stored 30527 items from <Connection at 0x165a9da3150 to 'C:\\myuser\\relstorage\\cache_local\\relstorage-cache2-mydb.sqlite3' in_transaction=False> in 0.09353160858154297 using -116502528 bytes. (3.38 MB local) (<relstorage.cache.local_client.LocalClient object at 0x000001659D8050D0>)
DEBUG 2024-01-23T09:23:11.865 Function read_from_sqlite took 2.023s. | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _util | relstorage.cache.local_client.timing | do_log_duration_info | 280
INFO 2024-01-23T09:23:11.878 Polling 30527 oids stored in cache with SQL timeout None
INFO 2024-01-23T09:23:12.539 Polled 30527 older oids stored in cache (15070 found in database); 30527 survived
DEBUG 2024-01-23T09:23:12.539 Removed 0 invalid OIDs from (no oids to remove) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | local_client | relstorage.cache.local_client | remove_invalid_persistent_oids | 315
DEBUG 2024-01-23T09:23:12.549 Attempting to load driver named 'gevent MySQLdb' from 'MySQLdb' failed; if no driver was specified, or the driver was set to 'auto', there may be more drivers to attempt. | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | drivers | relstorage.adapters.drivers | _check_preconditions | 230
Traceback (most recent call last):
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\drivers.py", line 228, in _check_preconditions
    mod = self.get_driver_module()
          ^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\drivers.py", line 250, in get_driver_module
    return importlib.import_module(self.MODULE_NAME)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\importlib\__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<frozen importlib._bootstrap>", line 1204, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1176, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1140, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'MySQLdb'
DEBUG 2024-01-23T09:23:12.549 Attempting to load driver named 'MySQLdb' from 'MySQLdb' failed; if no driver was specified, or the driver was set to 'auto', there may be more drivers to attempt. | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | drivers | relstorage.adapters.drivers | _check_preconditions | 230
Traceback (most recent call last):
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\drivers.py", line 228, in _check_preconditions
    mod = self.get_driver_module()
          ^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\drivers.py", line 250, in get_driver_module
    return importlib.import_module(self.MODULE_NAME)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\importlib\__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<frozen importlib._bootstrap>", line 1204, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1176, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1140, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'MySQLdb'
DEBUG 2024-01-23T09:23:12.549 Using driver <relstorage.adapters.mysql.drivers.pymysql.PyMySQLDriver object at 0x00000165830949D0> for requested name 'auto' | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | drivers | relstorage.adapters.drivers | _select_driver_by_name | 69
DEBUG 2024-01-23T09:23:13.207 Invalidating all persistent objects for viewer <StorageCache at 0x165adedeab0 hvt=None bytes=15750041 len=30527 state=<relstorage.cache.mvcc.MVCCDatabaseCoordinator object at 0x000001658C1D8C10>> (detached? False) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | mvcc | relstorage.cache.mvcc | _find_changes_for_viewer | 331
DEBUG 2024-01-23T09:23:13.209 new transaction | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _transaction | txn.22424 | __init__ | 114
DEBUG 2024-01-23T09:23:13.218 commit | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _transaction | txn.22424 | commit | 290
INFO 2024-01-23T09:23:13.219 <<< -------------------- open db. -------------------- | 3.843s
INFO 2024-01-23T09:23:13.220 >>> ------------- open db conection ... --------------
INFO 2024-01-23T09:23:13.221 <<< --------------- open db conection. --------------- | 0.001s
WARNING 2024-01-23T09:23:13.223 pack db in parallel | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | zodb | root | _open_pack_backup_db
INFO 2024-01-23T09:23:13.224 >>> ------------------ pack db ... -------------------
INFO 2024-01-23T09:23:13.247 pack: beginning pre-pack
INFO 2024-01-23T09:23:13.282 Analyzing transactions committed Tue Jan 23 09:22:29 2024 or before (TID 285430051012054818)
INFO 2024-01-23T09:23:13.301 pre_pack: filling the pack_object table
INFO 2024-01-23T09:23:15.945 pre_pack: Filled the pack_object table
DEBUG 2024-01-23T09:23:16.035 pre_pack: Collecting objects to examine. | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | packundo | relstorage.adapters.packundo | fill_object_refs | 1228
DEBUG 2024-01-23T09:23:16.819 pre_pack: Downloaded objects to examine (memory delta: 328.00 KB; download time: 0.29; sort time 0.08) | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | packundo | relstorage.adapters.packundo | fill_object_refs | 1265
INFO 2024-01-23T09:23:16.897 pre_pack: analyzing references from 29066 object(s) (memory delta: 328.00 KB)
ERROR 2024-01-23T09:23:17.110 pre_pack: failed | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | packundo | relstorage.adapters.packundo | pre_pack | 1454 | (<class 'pymysql.err.IntegrityError'>, IntegrityError(1062, "Duplicate entry '559705' for key 'object_refs_added.PRIMARY'"), <traceback object at 0x000001659A1D3C00>) | None
Traceback (most recent call last):
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\packundo.py", line 1451, in pre_pack
    self._pre_pack_main(load_connection, store_connection,
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\packundo.py", line 1530, in _pre_pack_main
    self.fill_object_refs(load_connection, store_connection, get_references)
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\packundo.py", line 1331, in fill_object_refs
    refs_found = self._add_refs_for_oids(load_batcher, store_batcher,
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\packundo.py", line 1388, in _add_refs_for_oids
    store_batcher.insert_into(
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\batch.py", line 149, in insert_into
    self._flush_if_needed()
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\batch.py", line 100, in _flush_if_needed
    return self.flush()
           ^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\batch.py", line 273, in flush
    count += self._do_inserts()
             ^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\relstorage\adapters\batch.py", line 364, in _do_inserts
    self.cursor.execute(stmt, params)
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\pymysql\cursors.py", line 153, in execute
    result = self._query(query)
             ^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\pymysql\cursors.py", line 322, in _query
    conn.query(q)
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\pymysql\connections.py", line 558, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\pymysql\connections.py", line 822, in _read_query_result
    result.read()
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\pymysql\connections.py", line 1200, in read
    first_packet = self.connection._read_packet()
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\pymysql\connections.py", line 772, in _read_packet
    packet.raise_for_error()
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\pymysql\protocol.py", line 221, in raise_for_error
    err.raise_mysql_exception(self._data)
  File "C:\Users\myuser\AppData\Local\anaconda3\Lib\site-packages\pymysql\err.py", line 143, in raise_mysql_exception
    raise errorclass(errno, errval)
pymysql.err.IntegrityError: (1062, "Duplicate entry '559705' for key 'object_refs_added.PRIMARY'")

ERROR 2024-01-23T09:23:17.213 <<< ---------------- Failed pack db. -----------------

INFO 2024-01-23T09:23:17.214 >>> -------------- close connection ... --------------
INFO 2024-01-23T09:23:17.218 peform last commit before closing
DEBUG 2024-01-23T09:23:17.218 new transaction | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _transaction | txn.22424 | __init__ | 114
DEBUG 2024-01-23T09:23:17.221 commit | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | _transaction | txn.22424 | commit | 290
INFO 2024-01-23T09:23:17.226 <<< --------------- close connection. ---------------- | 0.009s
INFO 2024-01-23T09:23:17.228 >>> ------------------ close db ... ------------------
DEBUG 2024-01-23T09:23:17.237 Closing storage cache with stats {'hits': 1, 'misses': 0, 'sets': 0, 'ratio': 1.0, 'len': 30527, 'bytes': 15750041, 'local_index_stats': None, 'global_index_stats': {'registered_viewers': 1, 'oldest viewer': None, 'hvt': 285430051012054818, 'index': {'depth': 1, 'hvt': 285430051012054818, 'min hvt': 285430051012054818, 'total OIDS': 85816, 'unique OIDs': 85816}}} | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | __init__ | relstorage | close | 397
DEBUG 2024-01-23T09:23:17.240 Connection: <Connection at 0x165a9da1150 to 'C:\\myuser\\relstorage\\cache_local\\relstorage-cache2-mydb.sqlite3' in_transaction=False>.
	Using sqlite3 version: 3.41.2.
	Default    connection settings: {'page_size': 4096, 'mmap_size': 0, 'temp_store': 0, 'wal_autocheckpoint': 1000, 'soft_heap_limit': 0, 'cache_size': -2000, 'page_count': 3975, 'busy_timeout': 15000, 'query_only': 0, 'journal_mode': 'wal'}.
	Changing   connection settings: {'journal_size_limit': -1, 'synchronous': 2, 'cache_spill': 483}.
	Desired    connection settings: {'journal_size_limit': 10485760, 'synchronous': 1, 'cache_spill': 0}.
	Unapplied  connection settings: {}.
	 | 12688 | Dask Worker process (from Nanny) | Dask-Default-Threads-12688-3934 | 22424 | drivers | relstorage.adapters.sqlite.drivers | __check_and_log | 246
INFO 2024-01-23T09:23:17.422 Storing persistent cache: Examined 30527 entries and rejected 30527 (already in db: 30527) in 0.014732800016645342
INFO 2024-01-23T09:23:17.528 Wrote 0 items to <Connection at 0x165a9da1150 to 'C:\\myuser\\relstorage\\cache_local\\relstorage-cache2-mydb.sqlite3' in_transaction=closed> in 0.08444476127624512 (0.038126468658447266 to fetch current, 0.0552066000236664 to insert batch (0 rows), 0.004695700015872717 to write, 0.016435099998489022 to trim). Used 324.00 KB memory. (Storage: <relstorage.cache.cache.PyCache object at 0x00000165AFE5E760>) Total hits 1; misses 0; ratio 1.0 (stores: 0)
INFO 2024-01-23T09:23:17.534 <<< ------------------- close db. -------------------- | 0.303s