Psqlexception error deadlock detected

Предисловие Ситуация: есть высоконагруженная мета-игра для наших танков под названием Глобальная карта. Эдакая пошаговая настолка для команд, где бои происходят...

Время прочтения
7 мин

Просмотры 53K

Предисловие

Ситуация: есть высоконагруженная мета-игра для наших танков под названием Глобальная карта. Эдакая пошаговая настолка для команд, где бои происходят в реальном танковом клиенте. В пиковые часы на карте несколько тысяч руководителей кланов производят игровые действия: атакуют друг друга, перемещают дивизии, покупают, продают,

грабят корованы

. Помимо этого, существует десяток сервисов, которые также могут вносить изменения в игровую ситуацию: подкидывают деньжат, штрафуют, добавляют игроков в клан и прочее.

Всё это неизбежно приводит к дедлокам. Так вот, хочу вам поведать историю о том, как мы эти периодические проблемы держим в допустимых рамках.

Немного о внутреннем устройстве бекенда

  • Основная база данных — PostgreSQL 9.5.
  • Уровень изоляции транзакций — стандартный по умолчанию READ COMMITED.
  • ORM — SQLAlchemy.

Часть 1: Мониторинг

Как проявляется Deadlock

Когда у нас возникает Deadlock, то падает исключение следующего вида:

ERROR: deadlock detected
DETAIL: Process 18293 waits for ShareLock on transaction 639; blocked by process 18254.
Process 18254 waits for ShareLock on transaction 640; blocked by process 18293.
HINT: See server log for query details.
CONTEXT: while updating tuple (0,9) in relation "users"

Первое, на что следует обратить внимание, — это строчка:
HINT: See server log for query details.

Действительно, если мы посмотрим серверные логи, то увидим для этого же места следующее:
ERROR: deadlock detected

И дальше конкретику:

DETAIL: Process 18293 waits for ShareLock on transaction 639; blocked by process 18254.
      Process 18254 waits for ShareLock on transaction 640; blocked by process 18293.
      Process 18293: update users set balance = balance + 10 where id = 2;
      Process 18254: update users set balance = balance + 10 where id = 3;

HINT: See server log for query details.
CONTEXT: while updating tuple (0,9) in relation "users"

И, наконец, запрос, на котором произошла ошибка:

STATEMENT: update users set balance = balance + 10 where id = 2;


Логирование запросов при этом не обязано быть включено.

Круто. Но первая глобальная проблема для любого более-менее серьёзного проекта — то, что у вас нет доступа к серверным логам вследствие политики безопасности. Иногда вообще нет никакого доступа. А иногда можно попросить участок, но надо ждать. Иногда это 30 минут, иногда день.

А хотелось бы получать такую информацию сразу. В особенности, если у вас в проекте есть Sentry, и большинство ошибок команда разработки получает сразу.

Как-то подкрутить сервер, чтобы он такую информацию выдавал обычным клиентам — нельзя. Вследствие политики безопасности разработчиков базы. Но, если у вашего пользователя к базе доступ обычный, без всяких там ограничений на выполнения служебных функций и без Row-Level security policies, то организовать себе доступ к подобной информации всё же можно.

Ручной захват

Мы можем преобразовать наши классы так, чтобы вручную получать похожую информацию. И даже больше. Для этого после отлова исключения о дедлоке, нам необходимо:

  • Временно ничего не откатывать в текущем соединении с базой и вообще ничего не трогать там.
  • Создать ещё одно соединение и выполнить в нём простейший запрос: 
    SELECT * FROM pg_stat_activity;

  • Результаты положить в доступное для просмотра разработчиками хранилище. Например отправить по Sentry как ошибку.

Пример: реализация сбора информации по дедлоку на SQLAlchemy

db.py

from contextlib import contextmanager

from sqlalchemy import create_engine
from sqlalchemy.exc import OperationalError

engine = create_engine('postgresql+psycopg2://postgres:12345678@localhost/postgres')


def log_pg_stat_activity():
    '''Log, write or send through Sentry pg_stat_activity'''
    debug_conn = engine.connect()
    for process in debug_conn.execute('''
        SELECT pid, application_name, state, query FROM pg_stat_activity;
    ''').fetchall():
        print(process)

@contextmanager
def connection():
    conn = engine.connect()
    try:
        yield conn
    except OperationalError as ex:
        log_pg_stat_activity()
        raise


@contextmanager
def transaction():
    with connection() as conn:
        with conn.begin() as trans:
            try:
                yield conn
            except OperationalError as ex:
                if 'deadlock detected' in ex.args[0]:
                    log_pg_stat_activity()
                    # Log exception
                    print(ex)
                    trans.rollback()
                else:
                    raise

deadlock_test.py

from multiprocessing import Process
from time import sleep
from threading import Thread

from sqlalchemy.orm import sessionmaker

from db import transaction


def process1():
    with transaction() as tran:
        tran.execute('UPDATE users SET balance = balance + 10 WHERE id = 3;')
        sleep(1)
        tran.execute('UPDATE users SET balance = balance + 10 WHERE id = 1 RETURNING pg_sleep(1);')


def process2():
    with transaction() as tran:
        tran.execute('UPDATE users SET balance = balance + 10 WHERE id = 1;')
        sleep(1)
        tran.execute('UPDATE users SET balance = balance + 10 WHERE id = 3 RETURNING pg_sleep(1);')


if __name__ == '__main__':
    p1 = Thread(target=process1)
    p2 = Thread(target=process2)
    p1.start()
    p2.start()
    sleep(4)

Или на github.

В данном случае у нас есть высокая вероятность того, что мы увидим какой именно запрос сломал нам транзакцию, вычислив его по PID и посмотрев текущий query.

Но бывает и так, что вычислив соединение по PID и посмотрев на query вы можете увидеть совсем не тот query, который устроил нам дедлок, а какой-нибудь следующий за ним по логике. Ведь пока вы ловили исключение и открывали соединение, нужный нам запрос для отлова мог и завершиться. Всё что мы можем здесь сделать — это работать через pgBouncer или его аналоги для минимизации времени установления соединения и использовать application_name.

application_name

Даже если вы получили тот запрос, который вызвал дедлок, у вас всё равно могут возникнуть трудности с пониманием, в каком месте логики он был вызван. И вот здесь на помощь приходит поле application_name. По умолчанию оно инициализируется не сильно полезной информацией, но его можно менять. А что если писать туда то место, откуда мы начинали транзакцию?

Сказано, сделано!

Пример: реализация установки application_name через SQLAlchemy

db.py

from traceback import extract_stack
@contextmanager
def transaction(application_name=None):
    with connection() as conn:
        if application_name is None:
            caller = extract_stack()[-3]
            conn.execution_options(autocommit=True).execute("SET application_name = %s", '%s:%s' % (caller[0], caller[1]))
        with conn.begin() as trans:
            try:
                yield conn
            except OperationalError as ex:
                if 'deadlock detected' in ex.args[0]:
                    log_pg_stat_activity()
                    # Log exception
                    print(ex)
                    trans.rollback()
                else:
                    raise

Или на github.

Вуаля. Теперь можно быстро открывать файлы в нужных местах и смотреть код.

pid application_name state query
1 8613 deadlock_test.py:10 idle in transaction (aborted) UPDATE users SET balance = balance + 10 WHERE id = 1 RETURNING pg_sleep(1);
2 8614 deadlock_test.py:17 active UPDATE users SET balance = balance + 10 WHERE id = 3 RETURNING pg_sleep(1);
3 8617 active SELECT pid, application_name, state, query FROM pg_stat_activity;

Думаем о серверных логах

Вся эта магия, описанная сверху хороша, но теоретически может не сработать. Иногда вам всё же не обойтись без серверных логов, поэтому необходимо сделать ещё два шага:

  • Обговорить понятную процедуру получения нужных участков серверных логов в разумное время с заинтересованными сторонами.
  • Делать их в требуемом вами формате, изменив log_line_prefix в postgresql.conf. На машине разработчика например можно так: log_line_prefix = 'APP:%a PID:%p TR:%x '.

Часть 2: Как бороться с дедлоками

Обычно в таких разделах дают ссылки на документацию об уровнях изоляции транзакций, видах блокировок и предлагают думать и анализировать в разрезе своего приложения. Я тоже так сделаю, но позже. А сначала просто опишу как мы это делаем чаще всего, ибо так уже получилось, что дедлоки у нас очень похожи друг на друга.

Несколько практик избегания deadlock`ов

Частый случай №1: Классический дедлок

Самый наш частый случай следующий:

  • Происходит игровое действие, затрагивающее сразу несколько игроков.
  • При этом игроки нередко могут совершать несколько действий в одно и то же время. Например, у нас: у крупных кланов есть много подразделений, участвующих в боях.
  • При выигрыше или проигрыше начисляются очки клану. И таких начислений параллельно может быть очень много.

То есть имеем ситуацию, когда пришёл пяток результатов боёв, их обработка распараллелилась, при этом в параллельных процессах, бывает, встречаются одни и те же игроки.

Всё что тут можно сделать: или выстраивать начисления в цепочку, но это медленно, или позволять начислениям падать и пробовать начислить чуть позже.

Частый случай №2: Сам себе злобный буратино (ССЗБ)

У нас походовая игра. Раз в ход происходит пересчёт баланса игроков, учитывая большое количество совершённых ими игровых действий. На время изменения баланса мы блокировали другие изменения через SELECT… FOR UPDATE. Хотя мы блокировали не сразу всех, а чанками по 100, всё равно иногда уходили в дедлок с процессом, который начисляет бонусы за бой, который не останавливается на время расчёта хода.

Так вот, оказалось, что мы были неправы. SELECT… FOR UPDATE — слишком мощная блокировка, необходимая только если выполняются 2 условия:

  • Условный id текущей таблицы используется как внешний ключ в другой.
  • Этот же условный id может быть изменён/удалён в результате дальнейших действий.

Возьмём пример:

--P1: 
BEGIN;
--P2: 
BEGIN;
--P1: 
SELECT id FROM clans WHERE id=1 FOR UPDATE;
--P2: 
INSERT INTO users(clan_id, name) VALUES(1, 'Alpha');

P2 в данной ситуации повиснет, поскольку мы даём СУБД понять, что запись с id=1 может перестать существовать. Однако в P1 мы не делаем ничего такого, только хотим защитить баланс клана от изменений. Поэтому, когда мы изменили FOR UPDATE на FOR NO KEY UPDATE, мы перестали ловить дедлоки.

Бонус №1

SELECT… FOR UPDATE в примере выше вызван явно. Но вы получите аналогичный эффект, если затронете своими изменениями уникальный ключ, на который ссылается внешний ключ из других таблиц. А любой UPDATE, который не затрагивает своими изменениями подобные ключи, вызовет блокировку аналогичную SELECT… FOR NO KEY UPDATE. Я вам рекомендую ознакомиться с этими особенностями в статье «Явные блокировки» в списке литературы ниже.

Бонус №2

Вернёмся к ещё одной любопытной детали из первоначальной ошибки:

CONTEXT: while updating tuple (0,9) in relation "users"

Что за тупл спросите вы? Это физический адрес строчки в таблице, из-за которой возник конфликт. Дело в том, что в каждой таблице есть служебные поля, которые запросом SELECT * не выбираются. Однако стоит явно указать к примеру ctid среди полей, как мы увидим этот самый тупл:

SELECT ctid, id, nickname, balance FROM public.users;

Пользы от него немного в случае дедлока, ибо разблокированный процесс скорее всего обновит конфликтную строчку, и у неё изменится этот ctid (поскольку любой UPDATE в PostgreSQL на самом деле INSERT, а старая строчка помечается как невидимая и позже будет удалена автовакуумом). Но знать стоит, вдруг когда-нибудь пригодится.

Что почитать

  • Deadlocks in PostgreSQL — описание всех видов блокировок
  • Explicit locking или Явные блокировки (на русском). Более подробнее о блокировках.
    Lock Monitoring — скрипты, показывающие как мониторить блокировки
    System Columns — про скрытые служебные поля в таблицах
    Introduction to PostgreSQL physical storage — про физическое хранение данных в PostgreSQL
Источник

Many might have seen PostgreSQL issue the following error message: "ERROR: deadlock detected". But what does it really mean? How can we prevent a deadlock and how can we reproduce the problem? Let’s dive into PostgreSQL locking and understand what deadlock and deadlock_timeout really mean.

How does a deadlock happen?

Many people approach us because they want to understand what a deadlock is and how it can happen. They also want to understand how a deadlock can be avoided and what software developers can do about it.
If you want to understand how a deadlock occurs, all you need is a table containing two lines. That’s sufficient to explain the basic principle of deadlocks.

Here is some easy-to-use sample data:

test=# CREATE TABLE t_data (id int, data int);
CREATE TABLE
test=# INSERT INTO t_data VALUES (1, 100), (2, 200);
INSERT 0 2
test=# TABLE t_data;
id  | data
----+------
1   | 100
2   | 200
(2 rows)

The crux is that if data is updated in a different order, transactions might have to wait for one another to be finished. It is perfectly fine if transaction 1 has to wait for transaction 2. But what happens if transaction 1 has to wait for transaction 2 and transaction 2 has to wait for transaction 1? In that case, the system has two choices:

  • Wait infinitely, or
  • Abort one transaction and commit the other transaction.

As waiting infinitely is not an option, PostgreSQL will abort one of these transactions after some time (deadlock_timeout). Here is what happens:

Transaction 1 Transaction 2 Comment
BEGIN; BEGIN;
UPDATE t_data
SET data = data * 10
WHERE id = 1
RETURNING *;
id  | data
----+------
1   | 1000
(1 row)		 UPDATE t_data
SET data = data * 10
WHERE id = 2
RETURNING *;
id  | data
----+------
2   | 2000
(1 row)		 works perfectly
UPDATE t_data
SET data = data * 10
WHERE id = 2
RETURNING *;		 has to wait until transaction 2 releases the lock on the row containing id = 2
… waits … UPDATE t_data
SET data = data * 10
WHERE id = 1
RETURNING *;		 wants to lock the row locked by transaction id: now both are supposed to wait
… deadlock timeout … … deadlock timeout … PostgreSQL waits (deadlock_timeout) and triggers deadlock detection after this timeout (not immediately)
update proceeds: “UPDATE 1” ERROR: deadlock detected a transaction has to die
COMMIT; the rest commits normally

The error message we will see is:

ERROR: deadlock detected
DETAIL: Process 70725 waits for ShareLock on transaction 891717; blocked by process 70713.
Process 70713 waits for ShareLock on transaction 891718; blocked by process 70725.
HINT: See server log for query details.
CONTEXT: while updating tuple (0,1) in relation "t_data"

The reason is that transactions have to wait for one another. If two transactions are in a conflict, PostgreSQL will not resolve the problem immediately, rather it will wait for deadlock_timeout and then trigger the deadlock detection algorithm to resolve the problem.

Why does PostgreSQL wait for some time before it steps in and fixes things? The reason is that deadlock detection is quite expensive, and therefore not immediately triggering it makes sense. The default value here is 1 second, which is high enough to avoid pointless deadlock detection attempts, but is still short enough to fix the problem in a useful and timely manner.

How to fix and avoid deadlocks

The most important thing to know is: There is NO MAGIC CONFIGURATION PARAMETER to fix this problem. The problem does NOT depend on configuration. It depends on the execution order of operations. In other words, you cannot magically fix it without understanding the application and its underlying operations.

The only thing that can fix the problem is to change the execution order, as shown in the next listing:

test=# SELECT * FROM t_data ;
id  | data
----+------
1   | 1000
2   | 2000
(2 rows)

This is the data you should see after committing the transaction that did not fail before. Thus we can see what happens if two transactions execute in a different order:

Transaction 1 Transaction 2 Comment
BEGIN;
UPDATE t_data
SET data = data * 10
WHERE id = 1
RETURNING *;
id  | data
----+------
1   | 1000
(1 row)		 BEGIN;
UPDATE t_data
SET data = data * 10
WHERE id = 1
RETURNING *;
UPDATE t_data
SET data = data * 10
WHERE id = 2
RETURNING *;
id  | data
----+-------
2   | 20000
(1 row)		 … wait …
COMMIT; … wait …
UPDATE t_data
SET data = data * 10
WHERE id = 1
RETURNING *;
id  | data
----+--------
1   | 100000
(1 row)		 re-read the value and use the newly committed entries
UPDATE t_data
SET data = data * 10
WHERE id = 2
RETURNING *;
id  | data
----+--------
2   | 200000
(1 row)		 re-read the value and use the newly committed entries
COMMIT;

In this case, there is no deadlock. However, in a real work scenario it is hardly possible to simply swap the execution order. That’s why this is more of a theoretical solution to the problem than a practical one. However, there are no other options to fix the problem of deadlocks. In the case of deadlocks, being aware of how to prevent them is the best cure.

Finally …

Locking is really important. Deadlocks are not the only concern in this area. Performance might be equally important, therefore it makes sense to deal with performance-related locking effects as well. Stay tuned for more on this topic.

If you want to learn more about important features of PostgreSQL, you might want to check out a blog post about UPDATE which can be found here.

Please leave your comments below. In order to receive regular updates on important changes in PostgreSQL, subscribe to our newsletter, or follow us on Twitter, Facebook, or LinkedIn.

Источник

In a meeting today about performance I mentioned these integration tests and that I hadn’t run them in a while. I just ran them again on the 4.3 branch (commit 0330ae3) and they passed the first time but failed the second time I ran them (exception including database deadlock below), which is consistent with what I was seeing before.

Again, these are pretty normal and mundane API calls made the to Dataverse installation running on my laptop. I don’t feel like we should be getting database deadlocks.

@scolapasta you (or anyone) can run these by opening SearchIT.java in Netbeans, right clicking, and selecting «Test File».

[2015-10-07T16:33:50.949-0400] [glassfish 4.1] [WARNING] [AS-EJB-00056] [javax.enterprise.ejb.container] [tid: _ThreadID=124 _ThreadName=http-listener-2(3)] [timeMillis: 1444250030949] [levelValue: 900] [[
  A system exception occurred during an invocation on EJB IndexServiceBean, method: public java.util.concurrent.Future edu.harvard.iq.dataverse.search.IndexServiceBean.indexDataset(edu.harvard.iq.dataverse.Dataset,boolean)]]

[2015-10-07T16:33:50.949-0400] [glassfish 4.1] [WARNING] [] [javax.enterprise.ejb.container] [tid: _ThreadID=124 _ThreadName=http-listener-2(3)] [timeMillis: 1444250030949] [levelValue: 900] [[

javax.ejb.TransactionRolledbackLocalException: Exception thrown from bean
    at com.sun.ejb.containers.EJBContainerTransactionManager.checkExceptionClientTx(EJBContainerTransactionManager.java:662)
    at com.sun.ejb.containers.EJBContainerTransactionManager.postInvokeTx(EJBContainerTransactionManager.java:507)
    at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4566)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2074)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2044)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:220)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)
    at com.sun.proxy.$Proxy450.indexDataset(Unknown Source)
    at edu.harvard.iq.dataverse.search.__EJB31_Generated__IndexServiceBean__Intf____Bean__.indexDataset(Unknown Source)
    at edu.harvard.iq.dataverse.engine.command.impl.UpdateDatasetCommand.save(UpdateDatasetCommand.java:199)
    at edu.harvard.iq.dataverse.engine.command.impl.UpdateDatasetCommand.execute(UpdateDatasetCommand.java:110)
    at edu.harvard.iq.dataverse.engine.command.impl.UpdateDatasetCommand.execute(UpdateDatasetCommand.java:37)
    at edu.harvard.iq.dataverse.EjbDataverseEngine.submit(EjbDataverseEngine.java:181)
    at sun.reflect.GeneratedMethodAccessor190.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1081)
    at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1153)
    at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:4786)
    at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:656)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:46)
    at org.jboss.weld.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:52)
    at sun.reflect.GeneratedMethodAccessor124.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doCall(SystemInterceptorProxy.java:163)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:140)
    at sun.reflect.GeneratedMethodAccessor132.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:369)
    at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:4758)
    at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:4746)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:212)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)
    at com.sun.proxy.$Proxy437.submit(Unknown Source)
    at edu.harvard.iq.dataverse.__EJB31_Generated__EjbDataverseEngine__Intf____Bean__.submit(Unknown Source)
    at edu.harvard.iq.dataverse.api.datadeposit.MediaResourceManagerImpl.replaceOrAddFiles(MediaResourceManagerImpl.java:289)
    at edu.harvard.iq.dataverse.api.datadeposit.MediaResourceManagerImpl.addResource(MediaResourceManagerImpl.java:186)
    at org.swordapp.server.MediaResourceAPI.post(MediaResourceAPI.java:272)
    at edu.harvard.iq.dataverse.api.datadeposit.SWORDv2MediaResourceServlet.doPost(SWORDv2MediaResourceServlet.java:64)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:344)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
    at org.glassfish.tyrus.servlet.TyrusServletFilter.doFilter(TyrusServletFilter.java:295)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
    at org.ocpsoft.rewrite.servlet.RewriteFilter.doFilter(RewriteFilter.java:205)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:316)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)
    at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
    at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
    at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:99)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:174)
    at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
    at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
    at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:412)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:282)
    at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)
    at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)
    at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:201)
    at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:175)
    at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
    at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:284)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:201)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:133)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
    at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
    at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:561)
    at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:565)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:545)
    at java.lang.Thread.run(Thread.java:745)
Caused by: javax.ejb.EJBTransactionRolledbackException
    at com.sun.ejb.containers.BaseContainer.mapLocal3xException(BaseContainer.java:2342)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2123)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2044)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:220)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)
    at com.sun.proxy.$Proxy412.indexPermissionsOnSelfAndChildren(Unknown Source)
    at edu.harvard.iq.dataverse.search.__EJB31_Generated__SolrIndexServiceBean__Intf____Bean__.indexPermissionsOnSelfAndChildren(Unknown Source)
    at edu.harvard.iq.dataverse.search.IndexServiceBean.indexDatasetPermissions(IndexServiceBean.java:570)
    at edu.harvard.iq.dataverse.search.IndexServiceBean.indexDataset(IndexServiceBean.java:386)
    at sun.reflect.GeneratedMethodAccessor735.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1081)
    at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1153)
    at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:4786)
    at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:656)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:46)
    at org.jboss.weld.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:52)
    at sun.reflect.GeneratedMethodAccessor124.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doCall(SystemInterceptorProxy.java:163)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:140)
    at sun.reflect.GeneratedMethodAccessor132.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:369)
    at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:4758)
    at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:4746)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:212)
    ... 82 more
Caused by: javax.ejb.TransactionRolledbackLocalException: Exception thrown from bean
    at com.sun.ejb.containers.EJBContainerTransactionManager.checkExceptionClientTx(EJBContainerTransactionManager.java:662)
    at com.sun.ejb.containers.EJBContainerTransactionManager.postInvokeTx(EJBContainerTransactionManager.java:507)
    at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4566)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2074)
    ... 117 more
Caused by: javax.ejb.EJBTransactionRolledbackException
    at com.sun.ejb.containers.BaseContainer.mapLocal3xException(BaseContainer.java:2342)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2123)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2044)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:220)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)
    at com.sun.proxy.$Proxy467.findDatasetVersionPerms(Unknown Source)
    at edu.harvard.iq.dataverse.search.__EJB31_Generated__SearchPermissionsServiceBean__Intf____Bean__.findDatasetVersionPerms(Unknown Source)
    at edu.harvard.iq.dataverse.search.SolrIndexServiceBean.makeDatasetSolrDoc(SolrIndexServiceBean.java:247)
    at edu.harvard.iq.dataverse.search.SolrIndexServiceBean.constructDatasetSolrDocs(SolrIndexServiceBean.java:148)
    at edu.harvard.iq.dataverse.search.SolrIndexServiceBean.determineSolrDocs(SolrIndexServiceBean.java:95)
    at edu.harvard.iq.dataverse.search.SolrIndexServiceBean.indexPermissionsForOneDvObject(SolrIndexServiceBean.java:330)
    at edu.harvard.iq.dataverse.search.SolrIndexServiceBean.indexPermissionsOnSelfAndChildren(SolrIndexServiceBean.java:397)
    at sun.reflect.GeneratedMethodAccessor195.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1081)
    at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1153)
    at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:4786)
    at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:656)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:46)
    at org.jboss.weld.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:52)
    at sun.reflect.GeneratedMethodAccessor124.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doCall(SystemInterceptorProxy.java:163)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:140)
    at sun.reflect.GeneratedMethodAccessor132.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:369)
    at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:4758)
    at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:4746)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:212)
    ... 115 more
Caused by: javax.ejb.TransactionRolledbackLocalException: Exception thrown from bean
    at com.sun.ejb.containers.EJBContainerTransactionManager.checkExceptionClientTx(EJBContainerTransactionManager.java:662)
    at com.sun.ejb.containers.EJBContainerTransactionManager.postInvokeTx(EJBContainerTransactionManager.java:507)
    at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4566)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2074)
    ... 153 more
Caused by: javax.ejb.EJBTransactionRolledbackException
    at com.sun.ejb.containers.BaseContainer.mapLocal3xException(BaseContainer.java:2342)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2123)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2044)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:220)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)
    at com.sun.proxy.$Proxy468.rolesAssignments(Unknown Source)
    at edu.harvard.iq.dataverse.__EJB31_Generated__DataverseRoleServiceBean__Intf____Bean__.rolesAssignments(Unknown Source)
    at edu.harvard.iq.dataverse.search.SearchPermissionsServiceBean.findDvObjectPerms(SearchPermissionsServiceBean.java:88)
    at edu.harvard.iq.dataverse.search.SearchPermissionsServiceBean.findDatasetVersionPerms(SearchPermissionsServiceBean.java:81)
    at sun.reflect.GeneratedMethodAccessor718.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1081)
    at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1153)
    at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:4786)
    at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:656)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:46)
    at org.jboss.weld.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:52)
    at sun.reflect.GeneratedMethodAccessor124.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doCall(SystemInterceptorProxy.java:163)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:140)
    at sun.reflect.GeneratedMethodAccessor132.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:369)
    at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:4758)
    at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:4746)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:212)
    ... 151 more
Caused by: javax.ejb.TransactionRolledbackLocalException: Exception thrown from bean
    at com.sun.ejb.containers.EJBContainerTransactionManager.checkExceptionClientTx(EJBContainerTransactionManager.java:662)
    at com.sun.ejb.containers.EJBContainerTransactionManager.postInvokeTx(EJBContainerTransactionManager.java:507)
    at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4566)
    at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2074)
    ... 186 more
Caused by: javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.5.2.v20140319-9ad6abd): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: org.postgresql.util.PSQLException: ERROR: deadlock detected
  Detail: Process 32317 waits for ShareLock on transaction 2435586; blocked by process 32312.
Process 32312 waits for ShareLock on transaction 2435585; blocked by process 32317.
  Hint: See server log for query details.
  Where: SQL statement "SELECT 1 FROM ONLY "public"."dvobject" x WHERE "id" OPERATOR(pg_catalog.=) $1 FOR SHARE OF x"
Error Code: 0
Call: UPDATE DVOBJECT SET INDEXTIME = ? WHERE (ID = ?)
    bind => [2 parameters bound]
Query: UpdateObjectQuery([Dataset id:27 ])
    at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:868)
    at org.eclipse.persistence.internal.jpa.QueryImpl.performPreQueryFlush(QueryImpl.java:963)
    at org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:207)
    at org.eclipse.persistence.internal.jpa.QueryImpl.getResultList(QueryImpl.java:469)
    at edu.harvard.iq.dataverse.DataverseRoleServiceBean.rolesAssignments(DataverseRoleServiceBean.java:185)
    at sun.reflect.GeneratedMethodAccessor175.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1081)
    at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1153)
    at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:4786)
    at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:656)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:46)
    at org.jboss.weld.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:52)
    at sun.reflect.GeneratedMethodAccessor124.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:608)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doCall(SystemInterceptorProxy.java:163)
    at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:140)
    at sun.reflect.GeneratedMethodAccessor132.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:883)
    at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:822)
    at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:369)
    at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:4758)
    at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:4746)
    at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:212)
    ... 184 more
Caused by: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.5.2.v20140319-9ad6abd): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: org.postgresql.util.PSQLException: ERROR: deadlock detected
  Detail: Process 32317 waits for ShareLock on transaction 2435586; blocked by process 32312.
Process 32312 waits for ShareLock on transaction 2435585; blocked by process 32317.
  Hint: See server log for query details.
  Where: SQL statement "SELECT 1 FROM ONLY "public"."dvobject" x WHERE "id" OPERATOR(pg_catalog.=) $1 FOR SHARE OF x"
Error Code: 0
Call: UPDATE DVOBJECT SET INDEXTIME = ? WHERE (ID = ?)
    bind => [2 parameters bound]
Query: UpdateObjectQuery([Dataset id:27 ])
    at org.eclipse.persistence.exceptions.DatabaseException.sqlException(DatabaseException.java:340)
    at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.processExceptionForCommError(DatabaseAccessor.java:1611)
    at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeDirectNoSelect(DatabaseAccessor.java:898)
    at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeNoSelect(DatabaseAccessor.java:962)
    at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:631)
    at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:558)
    at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:2002)
    at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:298)
    at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:242)
    at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:228)
    at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.updateObject(DatasourceCallQueryMechanism.java:797)
    at org.eclipse.persistence.internal.queries.StatementQueryMechanism.updateObject(StatementQueryMechanism.java:435)
    at org.eclipse.persistence.internal.queries.DatabaseQueryMechanism.updateObjectForWriteWithChangeSet(DatabaseQueryMechanism.java:1079)
    at org.eclipse.persistence.queries.UpdateObjectQuery.executeCommitWithChangeSet(UpdateObjectQuery.java:84)
    at org.eclipse.persistence.internal.queries.DatabaseQueryMechanism.executeWriteWithChangeSet(DatabaseQueryMechanism.java:301)
    at org.eclipse.persistence.queries.WriteObjectQuery.executeDatabaseQuery(WriteObjectQuery.java:58)
    at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:899)
    at org.eclipse.persistence.queries.DatabaseQuery.executeInUnitOfWork(DatabaseQuery.java:798)
    at org.eclipse.persistence.queries.ObjectLevelModifyQuery.executeInUnitOfWorkObjectLevelModifyQuery(ObjectLevelModifyQuery.java:108)
    at org.eclipse.persistence.queries.ObjectLevelModifyQuery.executeInUnitOfWork(ObjectLevelModifyQuery.java:85)
    at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2896)
    at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1804)
    at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1786)
    at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1737)
    at org.eclipse.persistence.internal.sessions.CommitManager.commitChangedObjectsForClassWithChangeSet(CommitManager.java:267)
    at org.eclipse.persistence.internal.sessions.CommitManager.commitAllObjectsWithChangeSet(CommitManager.java:130)
    at org.eclipse.persistence.internal.sessions.AbstractSession.writeAllObjectsWithChangeSet(AbstractSession.java:4207)
    at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitToDatabase(UnitOfWorkImpl.java:1441)
    at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitToDatabaseWithPreBuiltChangeSet(UnitOfWorkImpl.java:1587)
    at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.writeChanges(RepeatableWriteUnitOfWork.java:452)
    at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:863)
    ... 216 more
Caused by: org.postgresql.util.PSQLException: ERROR: deadlock detected
  Detail: Process 32317 waits for ShareLock on transaction 2435586; blocked by process 32312.
Process 32312 waits for ShareLock on transaction 2435585; blocked by process 32317.
  Hint: See server log for query details.
  Where: SQL statement "SELECT 1 FROM ONLY "public"."dvobject" x WHERE "id" OPERATOR(pg_catalog.=) $1 FOR SHARE OF x"
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2101)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1834)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:510)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:386)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:332)
    at sun.reflect.GeneratedMethodAccessor140.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.postgresql.ds.jdbc23.AbstractJdbc23PooledConnection$StatementHandler.invoke(AbstractJdbc23PooledConnection.java:453)
    at com.sun.proxy.$Proxy382.executeUpdate(Unknown Source)
    at com.sun.gjc.spi.base.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:125)
    at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeDirectNoSelect(DatabaseAccessor.java:890)
    ... 244 more
]]
Источник

Содержание

  1. Deadlock в insert запросе в postgres
  2. Ответы (1 шт):
  3. Как мы ловим Deadlock`и на PostgreSQL и чиним их
  4. Предисловие
  5. Немного о внутреннем устройстве бекенда
  6. Часть 1: Мониторинг
  7. Как проявляется Deadlock
  8. Ручной захват
  9. application_name
  10. Думаем о серверных логах
  11. Часть 2: Как бороться с дедлоками
  12. Несколько практик избегания deadlock`ов
  13. Частый случай №1: Классический дедлок
  14. Частый случай №2: Сам себе злобный буратино (ССЗБ)
  15. Бонус №1
  16. Бонус №2
  17. PostgreSQL: Understanding deadlocks
  18. How does a deadlock happen?
  19. How to fix and avoid deadlocks
  20. Finally …

Deadlock в insert запросе в postgres

Получаю время от времени ошибку

Message: SQLSTATE[40P01]: Deadlock detected: 7 ERROR: deadlock detected

Запрос вида (для примера сокращу, в запросе может быть до 250 строк и много контента):

Так же есть ньюанс что подобные запросы выполняются на 40 серверах к одной базе данных

Как с таким бороться?

Ответы (1 шт):

в запросе может быть до 250 строк

Логично предположить, что конкурентно вставляете одни и те же данные в разном порядке.

Как же ON CONFLICT DO NOTHING ? А что он может?

  • t1: begin
  • t2: begin
  • t1: insert 1 on conflict — никто не мешает, записали
  • t2: insert 2 on conflict — никто не мешает, записали
  • t2: insert 1 on conflict — хм, это же значение пишет t1, но мы не знаем можем ли мы сделать do nothing, т.к. если t1 сделает rollback — мы сделаем неправильный выбор. Потому ждём окончание t1
  • t1: insert 2 on conflict — а это значение хочет t2 писать, подождём её завершения.
  • t1 или t2 спустя время deadlock_timeout — что-то я долго жду, проверю-ка граф ожиданий. Опа, действительно deadlock, отменяю свою транзакцию. Вторая транзакция соответственно разблокируется.

insert на много строк всё равно транзакция и потому может быть аналогично.

Отсортируйте записываемые множества по какому-либо признаку в идентичном порядке.

Источник

Как мы ловим Deadlock`и на PostgreSQL и чиним их

Предисловие

Ситуация: есть высоконагруженная мета-игра для наших танков под названием Глобальная карта. Эдакая пошаговая настолка для команд, где бои происходят в реальном танковом клиенте. В пиковые часы на карте несколько тысяч руководителей кланов производят игровые действия: атакуют друг друга, перемещают дивизии, покупают, продают, грабят корованы. Помимо этого, существует десяток сервисов, которые также могут вносить изменения в игровую ситуацию: подкидывают деньжат, штрафуют, добавляют игроков в клан и прочее.

Всё это неизбежно приводит к дедлокам. Так вот, хочу вам поведать историю о том, как мы эти периодические проблемы держим в допустимых рамках.

Немного о внутреннем устройстве бекенда

Часть 1: Мониторинг

Как проявляется Deadlock

Когда у нас возникает Deadlock, то падает исключение следующего вида:

ERROR: deadlock detected
DETAIL: Process 18293 waits for ShareLock on transaction 639; blocked by process 18254.
Process 18254 waits for ShareLock on transaction 640; blocked by process 18293.
HINT: See server log for query details.
CONTEXT: while updating tuple (0,9) in relation «users»

Первое, на что следует обратить внимание, — это строчка:
HINT: See server log for query details.

Действительно, если мы посмотрим серверные логи, то увидим для этого же места следующее:
ERROR: deadlock detected

И дальше конкретику:

DETAIL: Process 18293 waits for ShareLock on transaction 639; blocked by process 18254.
Process 18254 waits for ShareLock on transaction 640; blocked by process 18293.
Process 18293: update users set balance = balance + 10 where > Process 18254: update users set balance = balance + 10 where >
HINT: See server log for query details.
CONTEXT: while updating tuple (0,9) in relation «users»

И, наконец, запрос, на котором произошла ошибка:

STATEMENT: update users set balance = balance + 10 where >


Логирование запросов при этом не обязано быть включено.

Круто. Но первая глобальная проблема для любого более-менее серьёзного проекта — то, что у вас нет доступа к серверным логам вследствие политики безопасности. Иногда вообще нет никакого доступа. А иногда можно попросить участок, но надо ждать. Иногда это 30 минут, иногда день.

А хотелось бы получать такую информацию сразу. В особенности, если у вас в проекте есть Sentry, и большинство ошибок команда разработки получает сразу.

Как-то подкрутить сервер, чтобы он такую информацию выдавал обычным клиентам — нельзя. Вследствие политики безопасности разработчиков базы. Но, если у вашего пользователя к базе доступ обычный, без всяких там ограничений на выполнения служебных функций и без Row-Level security policies, то организовать себе доступ к подобной информации всё же можно.

Ручной захват

Мы можем преобразовать наши классы так, чтобы вручную получать похожую информацию. И даже больше. Для этого после отлова исключения о дедлоке, нам необходимо:

  • Временно ничего не откатывать в текущем соединении с базой и вообще ничего не трогать там.
  • Создать ещё одно соединение и выполнить в нём простейший запрос:
  • Результаты положить в доступное для просмотра разработчиками хранилище. Например отправить по Sentry как ошибку.

    • В данном случае у нас есть высокая вероятность того, что мы увидим какой именно запрос сломал нам транзакцию, вычислив его по PID и посмотрев текущий query.

    Но бывает и так, что вычислив соединение по PID и посмотрев на query вы можете увидеть совсем не тот query, который устроил нам дедлок, а какой-нибудь следующий за ним по логике. Ведь пока вы ловили исключение и открывали соединение, нужный нам запрос для отлова мог и завершиться. Всё что мы можем здесь сделать — это работать через pgBouncer или его аналоги для минимизации времени установления соединения и использовать application_name.

    application_name

    Даже если вы получили тот запрос, который вызвал дедлок, у вас всё равно могут возникнуть трудности с пониманием, в каком месте логики он был вызван. И вот здесь на помощь приходит поле application_name. По умолчанию оно инициализируется не сильно полезной информацией, но его можно менять. А что если писать туда то место, откуда мы начинали транзакцию?

    Вуаля. Теперь можно быстро открывать файлы в нужных местах и смотреть код.

    pid application_name state query
    1 8613 deadlock_test.py:10 idle in transaction (aborted) UPDATE users SET balance = balance + 10 WHERE RETURNING pg_sleep(1);
    2 8614 deadlock_test.py:17 active UPDATE users SET balance = balance + 10 WHERE RETURNING pg_sleep(1);
    3 8617 active SELECT pid, application_name, state, query FROM pg_stat_activity;

    Думаем о серверных логах

    Вся эта магия, описанная сверху хороша, но теоретически может не сработать. Иногда вам всё же не обойтись без серверных логов, поэтому необходимо сделать ещё два шага:

    • Обговорить понятную процедуру получения нужных участков серверных логов в разумное время с заинтересованными сторонами.
    • Делать их в требуемом вами формате, изменив log_line_prefix в postgresql.conf. На машине разработчика например можно так: log_line_prefix = ‘APP:%a PID:%p TR:%x ‘ .

    Часть 2: Как бороться с дедлоками

    Обычно в таких разделах дают ссылки на документацию об уровнях изоляции транзакций, видах блокировок и предлагают думать и анализировать в разрезе своего приложения. Я тоже так сделаю, но позже. А сначала просто опишу как мы это делаем чаще всего, ибо так уже получилось, что дедлоки у нас очень похожи друг на друга.

    Несколько практик избегания deadlock`ов

    Частый случай №1: Классический дедлок

    Самый наш частый случай следующий:

    • Происходит игровое действие, затрагивающее сразу несколько игроков.
    • При этом игроки нередко могут совершать несколько действий в одно и то же время. Например, у нас: у крупных кланов есть много подразделений, участвующих в боях.
    • При выигрыше или проигрыше начисляются очки клану. И таких начислений параллельно может быть очень много.

    То есть имеем ситуацию, когда пришёл пяток результатов боёв, их обработка распараллелилась, при этом в параллельных процессах, бывает, встречаются одни и те же игроки.

    Всё что тут можно сделать: или выстраивать начисления в цепочку, но это медленно, или позволять начислениям падать и пробовать начислить чуть позже.

    Частый случай №2: Сам себе злобный буратино (ССЗБ)

    У нас походовая игра. Раз в ход происходит пересчёт баланса игроков, учитывая большое количество совершённых ими игровых действий. На время изменения баланса мы блокировали другие изменения через SELECT… FOR UPDATE. Хотя мы блокировали не сразу всех, а чанками по 100, всё равно иногда уходили в дедлок с процессом, который начисляет бонусы за бой, который не останавливается на время расчёта хода.

    Так вот, оказалось, что мы были неправы. SELECT… FOR UPDATE — слишком мощная блокировка, необходимая только если выполняются 2 условия:

    • Условный id текущей таблицы используется как внешний ключ в другой.
    • Этот же условный id может быть изменён/удалён в результате дальнейших действий.

    Возьмём пример:

    P2 в данной ситуации повиснет, поскольку мы даём СУБД понять, что запись с может перестать существовать. Однако в P1 мы не делаем ничего такого, только хотим защитить баланс клана от изменений. Поэтому, когда мы изменили FOR UPDATE на FOR NO KEY UPDATE, мы перестали ловить дедлоки.

    Бонус №1

    SELECT… FOR UPDATE в примере выше вызван явно. Но вы получите аналогичный эффект, если затронете своими изменениями уникальный ключ, на который ссылается внешний ключ из других таблиц. А любой UPDATE, который не затрагивает своими изменениями подобные ключи, вызовет блокировку аналогичную SELECT… FOR NO KEY UPDATE. Я вам рекомендую ознакомиться с этими особенностями в статье «Явные блокировки» в списке литературы ниже.

    Бонус №2

    Вернёмся к ещё одной любопытной детали из первоначальной ошибки:

    CONTEXT: while updating tuple (0,9) in relation «users»

    Что за тупл спросите вы? Это физический адрес строчки в таблице, из-за которой возник конфликт. Дело в том, что в каждой таблице есть служебные поля, которые запросом SELECT * не выбираются. Однако стоит явно указать к примеру ctid среди полей, как мы увидим этот самый тупл:

    Пользы от него немного в случае дедлока, ибо разблокированный процесс скорее всего обновит конфликтную строчку, и у неё изменится этот ctid (поскольку любой UPDATE в PostgreSQL на самом деле INSERT, а старая строчка помечается как невидимая и позже будет удалена автовакуумом). Но знать стоит, вдруг когда-нибудь пригодится.

    Источник

    PostgreSQL: Understanding deadlocks

    Many might have seen PostgreSQL issue the following error message: «ERROR: deadlock detected» . But what does it really mean? How can we prevent a deadlock and how can we reproduce the problem? Let’s dive into PostgreSQL locking and understand what deadlock and deadlock_timeout really mean.

    How does a deadlock happen?

    Many people approach us because they want to understand what a deadlock is and how it can happen. They also want to understand how a deadlock can be avoided and what software developers can do about it.
    If you want to understand how a deadlock occurs, all you need is a table containing two lines. That’s sufficient to explain the basic principle of deadlocks.

    Here is some easy-to-use sample data:

    The crux is that if data is updated in a different order, transactions might have to wait for one another to be finished. It is perfectly fine if transaction 1 has to wait for transaction 2. But what happens if transaction 1 has to wait for transaction 2 and transaction 2 has to wait for transaction 1? In that case, the system has two choices:

    • Wait infinitely, or
    • Abort one transaction and commit the other transaction.

    As waiting infinitely is not an option, PostgreSQL will abort one of these transactions after some time (deadlock_timeout). Here is what happens:

    Transaction 1 Transaction 2 Comment
    BEGIN; BEGIN;
    UPDATE t_data
    SET data = data * 10
    WHERE/> RETURNING *;
    id | data
    —-+——
    1 | 1000
    (1 row)    		 UPDATE t_data
    SET data = data * 10
    WHERE/> RETURNING *;
    id | data
    —-+——
    2 | 2000
    (1 row)    		 works perfectly
    UPDATE t_data
    SET data = data * 10
    WHERE/> RETURNING *;    		 has to wait until transaction 2 releases the lock on the row containing >
    … waits … UPDATE t_data
    SET data = data * 10
    WHERE/> RETURNING *;    		 wants to lock the row locked by transaction id: now both are supposed to wait
    … deadlock timeout … … deadlock timeout … PostgreSQL waits (deadlock_timeout) and triggers deadlock detection after this timeout (not immediately)
    update proceeds: “UPDATE 1” ERROR: deadlock detected a transaction has to die
    COMMIT; the rest commits normally

    The error message we will see is:

    ERROR: deadlock detected
    DETAIL: Process 70725 waits for ShareLock on transaction 891717; blocked by process 70713.
    Process 70713 waits for ShareLock on transaction 891718; blocked by process 70725.
    HINT: See server log for query details.
    CONTEXT: while updating tuple (0,1) in relation «t_data»

    The reason is that transactions have to wait for one another. If two transactions are in a conflict, PostgreSQL will not resolve the problem immediately, rather it will wait for deadlock_timeout and then trigger the deadlock detection algorithm to resolve the problem.

    Why does PostgreSQL wait for some time before it steps in and fixes things? The reason is that deadlock detection is quite expensive, and therefore not immediately triggering it makes sense. The default value here is 1 second, which is high enough to avoid pointless deadlock detection attempts, but is still short enough to fix the problem in a useful and timely manner.

    How to fix and avoid deadlocks

    The most important thing to know is: There is NO MAGIC CONFIGURATION PARAMETER to fix this problem. The problem does NOT depend on configuration. It depends on the execution order of operations. In other words, you cannot magically fix it without understanding the application and its underlying operations.

    The only thing that can fix the problem is to change the execution order, as shown in the next listing:

    This is the data you should see after committing the transaction that did not fail before. Thus we can see what happens if two transactions execute in a different order:

    Transaction 1 Transaction 2 Comment
    BEGIN;
    UPDATE t_data
    SET data = data * 10
    WHERE/> RETURNING *;
    id | data
    —-+——
    1 | 1000
    (1 row)    		 BEGIN;
    UPDATE t_data
    SET data = data * 10
    WHERE/> RETURNING *;
    UPDATE t_data
    SET data = data * 10
    WHERE/> RETURNING *;
    id | data
    —-+——-
    2 | 20000
    (1 row)    		 … wait …
    COMMIT; … wait …
    UPDATE t_data
    SET data = data * 10
    WHERE/> RETURNING *;
    id | data
    —-+———
    1 | 100000
    (1 row)    		 re-read the value and use the newly committed entries
    UPDATE t_data
    SET data = data * 10
    WHERE/> RETURNING *;
    id | data
    —-+———
    2 | 200000
    (1 row)    		 re-read the value and use the newly committed entries
    COMMIT;

    In this case, there is no deadlock. However, in a real work scenario it is hardly possible to simply swap the execution order. That’s why this is more of a theoretical solution to the problem than a practical one. However, there are no other options to fix the problem of deadlocks. In the case of deadlocks, being aware of how to prevent them is the best cure.

    Finally …

    Locking is really important. Deadlocks are not the only concern in this area. Performance might be equally important, therefore it makes sense to deal with performance-related locking effects as well. Stay tuned for more on this topic.

    If you want to learn more about important features of PostgreSQL, you might want to check out a blog post about UPDATE which can be found here.

    Please leave your comments below. In order to receive regular updates on important changes in PostgreSQL, subscribe to our newsletter , or follow us on Twitter , Facebook , or LinkedIn .

    Hans-Jürgen Schönig

    Hans-Jürgen Schönig has experience with PostgreSQL since the 90s. He is CEO and technical lead of CYBERTEC, which is one of the market leaders in this field and has served countless customers around the globe since the year 2000.

    Источник

    Источник

    Понравилась статья? Поделить с друзьями:
  • Psql как изменить пароль пользователя
  • Provider named pipes provider error 40 ошибка
  • Ps4 ошибка ce 34788 0 как исправить
  • Ps4 ошибка ce 33937 5
  • Ps4 ошибка ce 32753 0