Статьи

Остерегайтесь медленных обратных вызовов транзакций весной

TL; DR

Если вашему приложению не удается получить новое соединение с базой данных, перезапуск посредника ActiveMQ может помочь. Заинтересованы?

Проблема с производительностью

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

01
02
03
04
05
06
07
08
09
10
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30003ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:555) ~[HikariCP-2.4.7.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:188) ~[HikariCP-2.4.7.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:147) ~[HikariCP-2.4.7.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:99) ~[HikariCP-2.4.7.jar:na]
    at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:211) ~[spring-jdbc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) ~[spring-tx-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:447) ~[spring-tx-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:277) ~[spring-tx-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.3.4.RELEASE.jar:4.3.4.RELEASE]

Чтобы полностью понять, что происходит, давайте сначала посмотрим, что под ним делает пул соединений Spring и JDBC. Каждый раз, когда Spring встречает метод @Transactional он оборачивает его с помощью TransactionInterceptor . Этот перехватчик будет косвенно запрашивать TransactionManager для текущей транзакции. Если его нет, AbstractPlatformTransactionManager пытается создать новую транзакцию. В случае JDBC DataSourceTransactionManager начнет новую транзакцию, сначала получив новое соединение с базой данных. В конце Spring запрашивает настроенный источник данных (в нашем случае HikariPool ) для нового Connection . Вы можете прочитать все это из вышеупомянутой трассировки стека, ничего нового.

Очень медленный запрос

Так в чем же причина данного исключения? Мы используем Hikari в качестве примера, но описание действительно для всех реализаций пула DataSource я знаю. Hikari смотрит на свой внутренний пул соединений и пытается вернуть неактивный объект Connection . Если нет свободных соединений и пул еще не заполнен, Hikari без проблем создаст новое физическое соединение и вернет его. Однако, если пул заполнен, но все соединения в настоящее время используются, Hikari беспомощен. Он должен ждать, надеясь, что другой поток вернет Connection в ближайшем будущем, чтобы он мог передать его другому клиенту. Но через 30 секунд (настраиваемое время ожидания) у Хикари произойдет тайм-аут и произойдет сбой.

Что может быть основной причиной этого исключения? Представьте, что ваш сервер действительно усердно обрабатывает сотни запросов, каждый из которых требует подключения к базе данных для запросов. Если все запросы выполняются быстро, они должны довольно быстро возвращать соединения обратно в пул, чтобы другие запросы могли их повторно использовать. Даже при большой нагрузке время ожидания не должно быть катастрофическим. Сбой Хикари через 30 секунд может означать, что все соединения были фактически заняты, по крайней мере, полминуты, что довольно ужасно! Другими словами, у нас есть система, которая хранит все соединения с базой данных вечно (ну, в течение десятков секунд), истощая все остальные клиентские потоки.

Судя по всему, у нас очень медленный запрос к базе данных, давайте посмотрим на движок базы данных! В зависимости от используемой СУБД у вас будут разные инструменты. В нашем случае PostgreSQL сообщил, что на самом деле наше приложение имеет 10 открытых соединений — максимальный размер пула. Но это ничего не значит — мы объединяем соединения, поэтому желательно, чтобы при умеренной нагрузке все разрешенные соединения были открыты. Только когда приложение находится в режиме ожидания, пул соединений может решить закрыть некоторые соединения. Но это должно быть сделано очень консервативно, потому что открытие физического соединения обратно довольно дорого.

Итак, у нас есть все эти соединения, открытые в соответствии с PostgreSQL, какие запросы они выполняют? Что ж, смущающе, все соединения простаивают, и последняя команда была … COMMIT . С точки зрения базы данных у нас есть множество открытых соединений, все бездействующие и готовые к обслуживанию транзакций. С точки зрения Spring все связи заняты, и мы не можем получить больше. Что происходит? На данный момент мы уверены, что SQL не проблема.

Имитация сбоя

Мы посмотрели на дамп стека сервера и быстро нашли проблему. Давайте посмотрим на упрощенный фрагмент кода, который оказался виновником после анализа дампа стека. Я написал пример приложения, доступного на GitHub, который выявляет ту же проблему:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
@RestController
open class Sample(
        private val jms: JmsOperations,
        private val jdbc: JdbcOperations) {
  
    @Transactional
    @RequestMapping(method = arrayOf(GET, POST), value = "/")
    open fun test(): String {
        TransactionSynchronizationManager.registerSynchronization(sendMessageAfterCommit())
        val result = jdbc.queryForObject("SELECT 2 + 2", Int::class.java)
        return "OK " + result
    }
  
    private fun sendMessageAfterCommit(): TransactionSynchronizationAdapter {
        return object : TransactionSynchronizationAdapter() {
            override fun afterCommit() {
                val result = "Hello " + Instant.now()
                jms.send("queue", { it.createTextMessage(result) })
            }
        }
    }
  
}

Это в Котлине, просто ради изучения. Пример приложения выполняет две вещи: * очень, очень простой запрос к базе данных, просто чтобы доказать, что это не проблема * ловушка post-commit отправляет сообщение JMS

JMS?

К настоящему моменту становится очевидным, что проблема должна быть связана с этим пост-коммитом, но почему? Начнем с самого начала. Весьма типично, что мы хотим выполнить транзакцию базы данных и отправить сообщение JMS, только когда транзакция завершится успешно. Мы не можем просто поместить jms.send() как последний оператор в транзакционный метод по нескольким причинам:

  • @Transactional может быть частью более крупной транзакции, окружающей наш метод, но мы хотим отправить сообщение, когда вся транзакция будет завершена
  • Что еще более важно, транзакция может завершиться неудачей при фиксации, тогда как мы уже отправили сообщение JMS

Эти замечания применяются ко всем побочным эффектам, которые не участвуют в транзакции, и вы хотите выполнить их после фиксации. Конечно, может случиться так, что транзакция фиксируется, но ловушка post-commit не выполняется, поэтому семантика обратного вызова afterCommit() не более одного раза. Но, по крайней мере, мы гарантируем, что побочный эффект не произойдет, если данные не будут сохранены в базе данных (пока). Это разумный компромисс, когда распределенные транзакции не вариант — и они редко бывают.

Такая идиома может быть найдена во многих приложениях и, как правило, хорошо. Представьте, что вы получаете запрос, сохраняете что-то в базе данных и отправляете SMS-сообщение клиенту, подтверждающее, что запрос был обработан. Без перехвата после фиксации вы получите отправку SMS, но в случае отката данные не будут записаны в базу данных. Или даже смешнее : если вы автоматически повторяете неудачную транзакцию, вы можете отправить несколько SMS-сообщений без сохранения данных. Так что ловушки после фиксации важны 1 . Что случилось потом? Прежде чем смотреть на дамп стека, давайте рассмотрим метрики, которые предоставляет Hikari:

При умеренно высокой нагрузке (25 одновременных запросов, смоделированных с помощью ab ) мы ясно видим, что пул из 10 соединений полностью используется. Однако 15 потоков (запросов) заблокированы в ожидании подключения к базе данных. Они могут в конечном итоге получить соединение или время ожидания через 30 секунд. По-прежнему кажется, что проблема в каком-то длительном запросе SQL, но если серьезно, 2 + 2 ? Нет.

Проблема с ActiveMQ

Пришло время раскрыть дамп стека. Большинство соединений застряли в Хикари, ожидая соединения. Это нас не интересует, это всего лишь симптом, а не причина. Давайте посмотрим на 10 потоков, которые фактически удерживают соединение, что они замышляют?

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
"http-nio-9099-exec-2@6415" daemon prio=5 tid=0x28 nid=NA waiting
  java.lang.Thread.State: WAITING
      [...4 frames omitted...]
      at org.apache.activemq.transport.FutureResponse.getResult
      at o.a.a.transport.ResponseCorrelator.request
      at o.a.a.ActiveMQConnection.syncSendPacket
      at o.a.a.ActiveMQConnection.syncSendPacket
      at o.a.a.ActiveMQSession.syncSendPacket
      at o.a.a.ActiveMQMessageProducer.
      at o.a.a.ActiveMQSession.createProducer
      [...5  frames omitted...]
      at org.springframework.jms.core.JmsTemplate.send
      at com.nurkiewicz.Sample$sendMessageAfterCommit$1.afterCommit
      at org.springframework.transaction.support.TransactionSynchronizationUtils.invokeAfterCommit
      at o.s.t.s.TransactionSynchronizationUtils.triggerAfterCommit
      at o.s.t.s.AbstractPlatformTransactionManager.triggerAfterCommit
      at o.s.t.s.AbstractPlatformTransactionManager.processCommit
      at o.s.t.s.AbstractPlatformTransactionManager.commit
      [...73 frames omitted...]

Все эти соединения прикреплены к клиентскому коду ActiveMQ. Само по себе это необычно, разве отправка сообщения JMS не должна быть быстрой и асинхронной? Ну не совсем. Спецификация JMS определила определенные гарантии, некоторые из которых мы можем контролировать. Во многих случаях семантика «забыть и забыть» недостаточна. Что вам действительно нужно, так это подтверждение от брокера, что сообщение было получено и сохранено. Это означает, что мы должны: * создать физическое соединение с ActiveMQ (надеюсь, оно объединено так же, как и соединения JDBC) * выполнить рукопожатие, авторизацию и т. Д. (Как описано выше, пул очень помогает) * отправить сообщение JMS по сети * ждать подтверждения от брокер, как правило, предполагает постоянство на стороне брокера

Все эти шаги являются синхронными и не бесплатными, безусловно. Кроме того, ActiveMQ имеет несколько механизмов, которые могут еще больше замедлить производителя (отправителя): настройка производительности , асинхронная отправка , что происходит с быстрым производителем и медленным потребителем .

Крюки после фиксации, правда?

Таким образом, мы определили, что нестандартная производительность ActiveMQ на стороне производителя замедляет нас. Но как это влияет на пул соединений с базой данных? В этот момент мы перезапустили брокеров ActiveMQ и ситуация нормализовалась. В чем причина того, что продюсеры были такими медленными в тот день? — это выходит за рамки этой статьи. У нас есть время для изучения кода Spring Framework. Как выполняются хуки после фиксации? Вот соответствующая часть бесценной трассировки стека, очищенная (читайте снизу вверх):

1
2
3
4
5
6
7
c.n.Sample$sendMessageAfterCommit$1.afterCommit()
o.s.t.s.TransactionSynchronizationUtils.invokeAfterCommit()
o.s.t.s.TransactionSynchronizationUtils.triggerAfterCommit()
o.s.t.s.AbstractPlatformTransactionManager.triggerAfterCommit()
o.s.t.s.AbstractPlatformTransactionManager.processCommit()
o.s.t.s.AbstractPlatformTransactionManager.commit()
o.s.t.i.TransactionAspectSupport.commitTransactionAfterReturning()

Вот как выглядит AbstractPlatformTransactionManager.processCommit() , значительно упрощенный:

01
02
03
04
05
06
07
08
09
10
11
12
private void processCommit(DefaultTransactionStatus status) throws TransactionException {
    try {
        prepareForCommit(status);
        triggerBeforeCommit(status);
        triggerBeforeCompletion(status);
        doCommit(status);
        triggerAfterCommit(status);
        triggerAfterCompletion(status);
    } finally {
        cleanupAfterCompletion(status);  //release connection here
    }
}

Я удалил большую часть кода обработки ошибок, чтобы визуализировать основную проблему. Закрытие (на самом деле, освобождение обратно в пул) соединения JDBC происходит очень поздно в cleanupAfterCompletion() . Таким образом, на практике существует разрыв между вызовом doCommit() (физическая doCommit() транзакции) и освобождением соединения. Этот промежуток времени незначителен, если перехваты после фиксации и после завершения отсутствуют или дешевы. Но в нашем случае ловушка взаимодействовала с ActiveMQ, и в этот конкретный день производитель ActiveMQ работал исключительно медленно. Это создает довольно необычную ситуацию, когда соединение бездействует, вся работа завершена, но мы все еще удерживаем соединение без видимой причины. Это в основном временная утечка соединения.

Решение и резюме

Я далек от того, чтобы утверждать, что это ошибка в среде Spring (протестировано с spring-tx 4.3.7.RELEASE ), но я был бы рад услышать обоснование этой реализации. Хук Post commit не может каким-либо образом изменить транзакцию или соединение, поэтому на данный момент он бесполезен, но мы все еще держимся за него. Каковы решения? Очевидно, что хорошим началом является избегание длительного или непредсказуемого / небезопасного кода в обработчике после фиксации или после завершения. Но что, если вам действительно нужно отправить сообщение JMS, сделать вызов RESTful или сделать какой-нибудь другой побочный эффект? Я бы предложил перенести побочный эффект в пул потоков и выполнить это асинхронно. Конечно, это означает, что ваш побочный эффект может потеряться в случае отказа машины. Но, по крайней мере, вы не угрожаете общей стабильности системы.

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