Охота на “idle in transactions”

Привет

Я извиняюсь за то, что вот уже несколько дней от меня нет ни строчки, но суета связанная с переездом в МСК отнимает практически всё время, плюс редко удаётся выйти в сеть. Обещаю в ближайшее время исправить ситуацию, а пока вот...

Перевод Hunting "idle in transactions" с select * from depesz;

Если вы когда-нибудь встречались с коннектами в “idle in transaction”, то вы скорее всего ненавидите их. Я знаю это точно, т.к. сам их ненавижу. Они мешают таким "класным штукам" как репликация, вакуум, DDL запросы.

Так что когда я замечал их в в какой-либо базе, я сразу решал принимать меры.

Легко сказать, сложно сделать. Как же устранить проблему?

Я, конечно, мог бы убить все процессы postgres'а в сотоянии “idle in transaction”, но это не безопасное и, определённо, не оптимальное решение.

Лучшим решением было бы исправить те части кода, которые создают коннекты, ожидающие (простаивающие в) транзакции. Но как?

Прежде всего давайте зададим простой вопрос: что же такое соединение в “idle in transaction”?

Всё очень просто: это удерживающий соединение процесс postgres, который начал транзакцию, возможно что-то делал в её рамках, но сейчас ничего уже не делает, и транзакция всё ещё остаётся открытой ожидая COMMIT'а или ROLLBACK'а.

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

К счастью, немного манипуляций на Perl, и мы сможем получить некоторую информацию.

Стачала настроим PostgreSQL так, что он будет логировать все запросы с точными "таймстэмпами" и длительностью выполнения запросов. Например, используя такие настройки:

            name            |     setting

----------------------------+-----------------

 log_line_prefix            | %m %u@%d %p %r

 log_min_duration_statement | 0

Логи будут выглядеть так:

2008-08-28 16:58:31.978 CEST some_user@some_database 26001 10.3.5.1(45094) LOG:  duration: 1.387 ms  statement: SELECT ...

Интересующие части это "таймстэмп" вначале и длительность запроса.

Первое что надо знать, это то, что "таймстэмп" показывает время окончания выполнения запроса. Т.к. он равен '2008-08-28 16:58:31.978' и длительнось немного больше 1млс, то можно полагать, что время начала запроса '2008-08-28 16:58:31.977'.

Теперь мы знаем время начала и окончания запроса.

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

Основываясь на этом я написал программу, которая делает анализ и выводит интересующую информацию.

Вот таким образом:

=> zcat postgresql-2008-08-28_165831.log.gz | ./find-iit-connections.pl 2>/dev/null

162ms @ 2008-08-28 16:58:55.795 CEST (pid: 8570), queries:

  - begin

  - some_query

  - other_query

  - another

  - the query *after* long idle in transaction

Она ищет периоды idle-in-transactions больше 100млс. Изменить время можно в строке:

my $MINIMAL_IDLE_TO_REPORT = 100;

Вывод отображает то как долго было ожидание в транзакции (162млс), в какое время оно закончилось, pid процесса, кторый был в этом состоянии, и список всех запросов (с начала транзакции) за которыми это последовало.

С этой информацией найти проблемный участок кода становится намного легче.

Комментарии

David Fetter, 30 августа 2008 в 14:14
Не было бы проще загрузить CVS логи (см. снизу траницы: http://www.postgresql.org/docs/current/static/runtime-config-logging.html) в аналитическую БД и выполнить SQL операцию над ними?
Cheers,
David.

depesz, 30 августа 2008 в 22:28
Определённо, но проблема в том, что баа данных, которую я имел ввиду, работает под 8.2., а CVS логи добавлены только в 8.3.

Robert Treat, 1 сентября 2008 в 15:00
На некоторых системах включение логирования запросов звучит довольно пугающе. Я время от времени пользуюсь dtrace для таких вещей, но когда речь идёт о IIT, надо быть довольно удачливым, чтобы получить всю верную информацию. Однако, одна вешь, которую можно сделать, это посмотреть на pg_locks для того, чтобы определить что блокируется IIT. Вместе с информацией о пользователе/хосте/приложении этого часто бывает достаточно для локализации той самой части приложения и без логирования всех запросов.