Unique constraint violations during records creation in parallel
slafon51 opened this issue · 2 comments
Hello,
During a migration phase, we have a large number of records being created in parallel.
These records are created in different collections within the same bucket.
We noticed that errors were appearing during the creation of history lines : it seems that the index "idx_objects_parent_id_resource_name_last_modified" generate duplicate keys when 2 history lines are created at the same time.
The error stacktrace :
2024-02-22 15:30:10,446 ERROR [kinto.core.storage.postgresql.client:56][waitress-2] (psycopg2.errors.UniqueViolation) duplicate key value violates unique constraint "idx_objects_parent_id_resource_name_last_modified"
DETAIL: Key (parent_id, resource_name, last_modified)=(/buckets/fresq_referentiel, history, 2024-02-22 15:30:10.444) already exists.
[SQL:
INSERT INTO objects (id, parent_id, resource_name, data, last_modified, deleted)
VALUES (%(object_id)s, %(parent_id)s,
%(resource_name)s, (%(data)s)::JSONB,
from_epoch(%(last_modified)s),
FALSE)
ON CONFLICT (id, parent_id, resource_name) DO UPDATE
SET last_modified = from_epoch(%(last_modified)s),
data = (%(data)s)::JSONB,
deleted = FALSE
WHERE objects.deleted = TRUE
RETURNING id, data, as_epoch(last_modified) AS last_modified;
]
[parameters: {'object_id': '8e4d8dbc-5ead-4ff2-ab3b-4706ef6e0da1', 'parent_id': '/buckets/fresq_referentiel', 'resource_name': 'history', 'data': '{"date":"2024-02-22T15:30:10.443925+00:00","target":{"data":{"id_fiche":"5387","numero_fiche":"RNCP5237","intitule":"Activit\\u00E9s et techniques de ... (422 characters truncated) ... "resource_name":"record","collection_id":"rncp","record_id":"4b9374c3-b167-4add-9fc1-103bff758462"}', 'last_modified': None}]
(Background on this error at: https://sqlalche.me/e/20/gkpj)
Traceback (most recent call last):
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1969, in _exec_single_context
self.dialect.do_execute(
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/default.py", line 922, in do_execute
cursor.execute(statement, parameters)
psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "idx_objects_parent_id_resource_name_last_modified"
DETAIL: Key (parent_id, resource_name, last_modified)=(/buckets/fresq_referentiel, history, 2024-02-22 15:30:10.444) already exists.
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/opt/venv/lib/python3.12/site-packages/kinto/core/storage/postgresql/client.py", line 44, in connect
yield session
File "/opt/venv/lib/python3.12/site-packages/kinto/core/storage/postgresql/__init__.py", line 313, in create
result = conn.execute(sa.text(query % safe_holders), placeholders)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 2308, in execute
return self._execute_internal(
^^^^^^^^^^^^^^^^^^^^^^^
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 2199, in _execute_internal
result = conn.execute(
^^^^^^^^^^^^^
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1416, in execute
return meth(
^^^^^
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/sql/elements.py", line 517, in _execute_on_connection
return connection._execute_clauseelement(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1639, in _execute_clauseelement
ret = self._execute_context(
^^^^^^^^^^^^^^^^^^^^^^
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1848, in _execute_context
return self._exec_single_context(
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1988, in _exec_single_context
self._handle_dbapi_exception(
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 2344, in _handle_dbapi_exception
raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1969, in _exec_single_context
self.dialect.do_execute(
File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/default.py", line 922, in do_execute
cursor.execute(statement, parameters)
sqlalchemy.exc.IntegrityError: (psycopg2.errors.UniqueViolation) duplicate key value violates unique constraint "idx_objects_parent_id_resource_name_last_modified"
DETAIL: Key (parent_id, resource_name, last_modified)=(/buckets/fresq_referentiel, history, 2024-02-22 15:30:10.444) already exists.
[SQL:
INSERT INTO objects (id, parent_id, resource_name, data, last_modified, deleted)
VALUES (%(object_id)s, %(parent_id)s,
%(resource_name)s, (%(data)s)::JSONB,
from_epoch(%(last_modified)s),
FALSE)
ON CONFLICT (id, parent_id, resource_name) DO UPDATE
SET last_modified = from_epoch(%(last_modified)s),
data = (%(data)s)::JSONB,
deleted = FALSE
WHERE objects.deleted = TRUE
RETURNING id, data, as_epoch(last_modified) AS last_modified;
]
[parameters: {'object_id': '8e4d8dbc-5ead-4ff2-ab3b-4706ef6e0da1', 'parent_id': '/buckets/fresq_referentiel', 'resource_name': 'history', 'data': '{"date":"2024-02-22T15:30:10.443925+00:00","target":{"data":{"id_fiche":"5387","numero_fiche":"RNCP5237","intitule":"Activit\\u00E9s et techniques de ... (422 characters truncated) ... "resource_name":"record","collection_id":"rncp","record_id":"4b9374c3-b167-4add-9fc1-103bff758462"}', 'last_modified': None}]
(Background on this error at: https://sqlalche.me/e/20/gkpj)
How can these errors be prevented ?
Best regards.
Thanks for reporting this @slafon51 🙏
How many requests per second do you send?
Also, is the server responding with 409? (which you could retry on the client)
Is it the first time you encounter this? Or is it recently only? (ie. since we upgraded to SQLAlchemy v2 #3122)
This is something we identified a long time ago #602 and at the time we decided not to invest more efforts. This is basically due to the fact that we generate timestamps instead of using sequences
Thank you @leplatrem for your reply.
The server does indeed return a "409 CONFLICT" error.
According to the logs I have, we sent an average of 70 requests per second, and got a 409 error every 2 seconds.
Initially, records were created sequentially without any problem. It was only recently that we parallelized it and encountered these errors.
We're going to look at setting up a retry system in the event of 409 errors.
Best regards.