Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Database deadlock when messages are sent rapidly #235

Open
kiootic opened this issue Nov 21, 2018 · 2 comments
Open

Database deadlock when messages are sent rapidly #235

kiootic opened this issue Nov 21, 2018 · 2 comments

Comments

@kiootic
Copy link

kiootic commented Nov 21, 2018

Reproduction steps:
send messages between two users rapidly (e.g. 0.5s)

Expected result:
messages are sent normally

Actual result:
sometimes error would occur:

Error Domain=SKYOperationErrorDomain Code=10000 "An unexpected error has occurred." UserInfo={SKYErrorMessage=(psycopg2.extensions.TransactionRollbackError) deadlock detected
DETAIL:  Process 1402 waits for ShareLock on transaction 33541; blocked by process 1543.
Process 1543 waits for ShareLock on transaction 33595; blocked by process 1402.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (11,10) in relation "user_conversation"
 [SQL: '\n            UPDATE %(schema_name)s.user_conversation\n            SET\n                "_updated_at" = CURRENT_TIMESTAMP\n            WHERE\n                "conversation" = %(conversation_id)s\n                AND "user" = %(user_id)s\n        '] [parameters: {'schema_name': <psycopg2.extensions.AsIs object at 0x7f8ecc0a4540>, 'conversation_id': 'a1924405-71d8-4262-ae46-2baf5e175c38', 'user_id': 'c1001719-8171-44c7-9a33-d356c407b01a'}] (Background on this error at: http://sqlalche.me/e/e3q8), NSErrorFailingURLKey=http://127.0.0.1:3000/record/save, trace=Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
    context)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
    cursor.execute(statement, parameters)
psycopg2.extensions.TransactionRollbackError: deadlock detected
DETAIL:  Process 1402 waits for ShareLock on transaction 33541; blocked by process 1543.
Process 1543 waits for ShareLock on transaction 33595; blocked by process 1402.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (11,10) in relation "user_conversation"


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 43, in wrapper
    return dict(result=f(self, *args, **kwargs))
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 102, in call_func
    return self.hook(obj, param)
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 187, in hook
    returned = func(record, original_record, conn)
  File "/usr/local/lib/python3.6/site-packages/skygear/decorators.py", line 90, in hook_func
    func(record, original_record, db)
  File "chat/chat/message_handlers.py", line 336, in message_after_save_handler
    return handle_message_after_save(record, original_record, conn)
  File "chat/chat/message_handlers.py", line 193, in handle_message_after_save
    'user_id': current_user_id()
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 942, in execute
    return self._execute_text(object, multiparams, params)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1104, in _execute_text
    statement, parameters
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
    context)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
    exc_info
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 248, in reraise
    raise value.with_traceback(tb)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
    context)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
    cursor.execute(statement, parameters)
sqlalchemy.exc.OperationalError: (psycopg2.extensions.TransactionRollbackError) deadlock detected
DETAIL:  Process 1402 waits for ShareLock on transaction 33541; blocked by process 1543.
Process 1543 waits for ShareLock on transaction 33595; blocked by process 1402.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (11,10) in relation "user_conversation"
 [SQL: '\n            UPDATE %(schema_name)s.user_conversation\n            SET\n                "_updated_at" = CURRENT_TIMESTAMP\n            WHERE\n                "conversation" = %(conversation_id)s\n                AND "user" = %(user_id)s\n        '] [parameters: {'schema_name': <psycopg2.extensions.AsIs object at 0x7f8ecc0a4540>, 'conversation_id': 'a1924405-71d8-4262-ae46-2baf5e175c38', 'user_id': 'c1001719-8171-44c7-9a33-d356c407b01a'}] (Background on this error at: http://sqlalche.me/e/e3q8)
, SKYOperationErrorHTTPStatusCodeKey=200, SKYErrorName=UnexpectedError, NSLocalizedDescription=An unexpected error has occurred.}
@kiootic
Copy link
Author

kiootic commented Nov 21, 2018

Also following error may occur in same situation:

Error Domain=SKYOperationErrorDomain Code=10000 "An unexpected error has occurred." UserInfo={SKYErrorMessage=QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30 (Background on this error at: http://sqlalche.me/e/3o7r), NSErrorFailingURLKey=http://127.0.0.1:3000/chat/mark_as_read, trace=Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 43, in wrapper
    return dict(result=f(self, *args, **kwargs))
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 100, in call_func
    return self.op(obj, param.get('args', {}))
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 181, in op
    return serialize_value(func(*args, **kwargs))
  File "chat/chat/receipt_handlers.py", line 275, in mark_as_read_lambda
    return handle_mark_as_read(arg)
  File "chat/chat/receipt_handlers.py", line 49, in handle_mark_as_read
    mark_messages(message_ids, True, True)
  File "chat/chat/receipt_handlers.py", line 107, in mark_messages
    __update_and_notify_messages(new_message_ids)
  File "chat/chat/receipt_handlers.py", line 235, in __update_and_notify_messages
    message.notifyParticipants()
  File "chat/chat/message.py", line 105, in notifyParticipants
    self)
  File "chat/chat/pubsub.py", line 33, in _publish_record_event
    'record': serialize_record(record)
  File "chat/chat/pubsub.py", line 14, in _publish_event
    channel_names = _get_channels_by_user_ids(user_ids)
  File "chat/chat/utils.py", line 21, in _get_channels_by_user_ids
    with db.conn() as conn:
  File "/usr/local/lib/python3.6/contextlib.py", line 81, in __enter__
    return next(self.gen)
  File "/usr/local/lib/python3.6/site-packages/skygear/utils/db.py", line 120, in conn
    with _get_engine().begin() as conn:
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1992, in begin
    conn = self.contextual_connect(close_with_result=close_with_result)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2123, in contextual_connect
    self._wrap_pool_connect(self.pool.connect, None),
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2158, in _wrap_pool_connect
    return fn()
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/pool.py", line 403, in connect
    return _ConnectionFairy._checkout(self)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/pool.py", line 791, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/pool.py", line 532, in checkout
    rec = pool._do_get()
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1189, in _do_get
    (self.size(), self.overflow(), self._timeout), code="3o7r")
sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30 (Background on this error at: http://sqlalche.me/e/3o7r)
, SKYOperationErrorHTTPStatusCodeKey=500, SKYErrorName=UnexpectedError, NSLocalizedDescription=An unexpected error has occurred.}

@AdrianM
Copy link

AdrianM commented Oct 29, 2020

Hi, we have the same issue on our on-premise setup (skygear + skygear chat, 1.7.X). Is there some news about this issue or a possible solution?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants