вопрос

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

2021-01-13 10:25:20.838 WARN [http-nio-7010-exec-104][SqlExceptionHelper.java:127] - SQL Error: 1205, SQLState: 41000
2021-01-13 10:25:20.839 INFO [http-nio-7010-exec-104][AbstractBatchImpl.java:193] - HHH000010: On release of batch it still contained JDBC statements
2021-01-13 10:25:20.839 ERROR [http-nio-7010-exec-104][SqlExceptionHelper.java:129] - Lock wait timeout exceeded; try restarting transaction
Stack trace:
org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockTimeoutException: could not execute statement
...
Caused by: org.hibernate.exception.LockTimeoutException: could not execute statement
	at org.hibernate.dialect.MySQLDialect$3.convert(MySQLDialect.java:520)
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:95)
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:207)
	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3134)
	at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3013)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3393)
	at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:145)
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:582)
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:456)
	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337)
	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
	at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1282)
	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:465)
	at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:2963)
	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2339)
	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:485)
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:147)
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$100(JdbcResourceLocalTransactionCoordinatorImpl.java:38)
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:231)
	at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:65)
	at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:61)
	at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517)
	... 181 more
Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1084)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4232)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4164)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2615)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2776)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2843)
	at com.mysql.jdbc.LoadBalancedMySQLConnection.execSQL(LoadBalancedMySQLConnection.java:166)
	at sun.reflect.GeneratedMethodAccessor366.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.mysql.jdbc.LoadBalancingConnectionProxy.invoke(LoadBalancingConnectionProxy.java:651)
	at com.mysql.jdbc.LoadBalancingConnectionProxy.invoke(LoadBalancingConnectionProxy.java:556)
	at com.sun.proxy.$Proxy212.execSQL(Unknown Source)
	at com.mysql.fabric.jdbc.FabricMySQLConnectionProxy.execSQL(FabricMySQLConnectionProxy.java:961)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2085)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2337)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2265)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2249)
	at sun.reflect.GeneratedMethodAccessor369.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
	at com.sun.proxy.$Proxy465.executeUpdate(Unknown Source)
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:204)
	... 201 more

Бизнес-сценарий: опубликуйте некоторые определенные ресурсы и обнаружите, что они ждали, пока тайм-аут не выдаст исключение.

Процесс расположения проблемы

Из ненормального стека корень проблемы состоит в том, что заблокировка ожидания ожидания ожидания; попробуйте перезапустить транзакцию. С точки зрения информации, это должно быть: тайм-аут блокировки MySQL
Вначале считалось, что большие ресурсы вызывают больше операций SQL, таким образом достигая установленного максимального времени ожидания. Попробуйте смоделировать такие большие ресурсы при тестировании и пре-продакшне, но данные можно просмотреть нормально. Проверьте значение innodb_lock_wait_timeout в каждой среде с помощью оператора sql (ниже) и убедитесь, что оно равно 50 с. В сочетании с цепочкой вызовов на пинпоинте можно обнаружить, что время выполнения всей транзакции составляет около 4 с, но транзакция не была зафиксирована, пока не истечет время ожидания. Таким образом, тайм-аут, вызванный самим бизнесом, можно исключить.

SHOW VARIABLES LIKE 'innodb_lock_wait_timeout';

Исключив возможность тайм-аута самого бизнеса, в основном можно подтвердить, что это тайм-аут, вызванный ожиданием блокировки между двумя транзакциями. Поскольку ожидание блокировки — это исключение, генерируемое mysql, первая реакция заключается в том, предоставляет ли mysql соответствующие сведения об ожидании блокировки, чтобы помочь в обнаружении проблемы. После Baidu и Google было обнаружено, что в information_schema mysql есть несколько таблиц (innodb_trx, innodb_locks, innodb_lock_waits) для хранения информации, связанной с блокировкой, и ее можно использовать для обнаружения проблем.

#  锁等待的对应关系
select * from information_schema.innodb_lock_waits;
# 当前出现的锁
select * from information_schema.innodb_locks;
# 当前运行的所有事务
select * from information_schema.innodb_trx;
# 当前线程详情
show full processlist;

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

Из приведенного выше анализа данных это: вызвано транзакцией, открытой вчера, количество потоков, соответствующих транзакции, составляет 20154145, информация, соответствующая идентификатору потока, равна нулю, а пользователь является учетной записью, обычно используемой бизнесом. Учитывая, что аннотация @Transactional используется для объявления транзакций в бизнесе, само собой разумеется, что spring обычно должен управлять транзакциями для фиксации и отката. Итак, я обнаружил это, но я до сих пор не нашел основную причину.

Думая, что если это вызвано определенным делом, после перезапуска службы, после отключения соединения MySQL, это должно быть нормально. Итак, служба была перезапущена.
После перезапуска обнаруживается, что проблема все еще существует, и ресурс по-прежнему не может быть опубликован. Поэтому я снова нашел администратора базы данных, чтобы получить соответствующие данные. Анализ данных показывает, что идентификатор транзакции, удерживающей блокировку, изменился, и исходная транзакция исчезла, но была открыта новая транзакция, и транзакция удерживает блокировку, в результате чего последующий бизнес не может получить блокировку. как обычно. Кроме того, время начала транзакции в основном происходит через некоторое время после перезапуска службы. Таким образом, должен быть какой-то бизнес, который откроет новую транзакцию и никогда не зафиксирует ее.

В сочетании с бизнес-сценарием, после долгих размышлений, я все еще не могу придумать ни одного бизнеса, который вызвал бы эту ситуацию. Следовательно, только администратор базы данных может сначала уничтожить транзакцию, удерживающую блокировку.
В это время произошло очень волшебное событие: когда администратор баз данных убил поток, MQ отправил аварийное сообщение об аномальном потреблении. На данный момент виновник, из-за которого блокировка ждала тайм-аут, найден.
Можно найти дальнейший анализ потребления этого MQ: MQ запустит транзакцию, в транзакции получит все задействованные ресурсы (около 1 Вт), а затем цикл for выполнит операции связывания на связанных ресурсах. Поэтому после открытия транзакции она не смогла отправить

Подробное объяснение таблиц, связанных с блокировкой mysql.

таблица innodb_lock_waits

инструкция на официальном сайте mysql
Значение каждого поля

requesting_trx_id：请求事务的ID
requested_lock_id：请求事务的锁ID。可以和 INNODB_LOCKS 表 JOIN
blocking_trx_id：阻塞事务的 ID
blocking_lock_id：阻塞事务的锁ID。可以和 INNODB_LOCKS 表 JOIN

таблица innodb_locks

инструкция на официальном сайте mysql
Значение каждого поля

lock_id：锁id
lock_trx_id：拥有锁的事务ID。可以和 INNODB_TRX 表 JOIN 得到事务的详细信息
lock_mode：锁的模式。有如下锁类型：行级锁包括：S、X、IS、IX，分别代表：共享锁、排它锁、意向共享锁、意向排它锁。表级锁包括：S_GAP、X_GAP、IS_GAP、IX_GAP 和 AUTO_INC，分别代表共享间隙锁、排它间隙锁、意向共享间隙锁、意向排它间隙锁和自动递增锁。
lock_type：锁的类型。RECORD 代表行级锁，TABLE 代表表级锁。
lock_table：被锁定的或者包含锁定记录的表的名称。
lock_index：当lock_table='RECORD' 时，表示索引的名称；否则为 NULL。
lock_space：当lock_table='RECORD' 时，表示锁定行的表空间ID；否则为 NULL。
lock_page：当lock_table='RECORD' 时，表示锁定行的页号；否则为 NULL。
lock_rec：当lock_table='RECORD'时，表示一堆页面中锁定行的数量，亦即被锁定的记录号；否则为 NULL。
lock_data：当lock_table='RECORD' 时，表示锁定行的主键；否则为NULL

таблица innodb_trx

инструкция на официальном сайте mysql
Значение каждого поля

trx_id：事务ID
trx_state：事务状态，有以下几种状态：RUNNING、LOCK WAIT、ROLLING BACK 和 COMMITTING
trx_started：事务开始时间
trx_requested_lock_id：事务当前正在等待锁的标识，可以和 INNODB_LOCKS 表 JOIN 以得到更多详细信息
trx_wait_started：事务开始等待的时间
trx_weight：事务的权重
trx_mysql_thread_id：事务线程 ID，可以和 PROCESSLIST 表 JOIN。
trx_query：事务正在执行的 SQL 语句。
trx_operation_state：事务当前操作状态。
trx_tables_in_use：当前事务执行的 SQL 中使用的表的个数。
trx_tables_locked：当前执行 SQL 的行锁数量。
trx_lock_structs：事务保留的锁数量。
trx_lock_memory_bytes：事务锁住的内存大小，单位为 BYTES。
trx_rows_locked：事务锁住的记录数。包含标记为 DELETED，并且已经保存到磁盘但对事务不可见的行。
trx_rows_modified：事务更改的行数。
trx_concurrency_tickets：事务并发票数。
trx_isolation_level：当前事务的隔离级别。
trx_unique_checks：是否打开唯一性检查的标识。
trx_foreign_key_checks：是否打开外键检查的标识。
trx_last_foreign_key_error：最后一次的外键错误信息。
trx_adaptive_hash_latched：自适应散列索引是否被当前事务锁住的标识。
trx_adaptive_hash_timeout：是否立刻放弃为自适应散列索引搜索 LATCH 的标识

таблица списка процессов

инструкция на официальном сайте mysql
Значение каждого поля

Id：连接标识符。可通过kill id将该线程kill掉
User：访问的用户
Host：发出该语句的客户端的主机名。格式：host_name:client_port
db：线程的默认数据库。如果未选择任何数据库，则为null
Command: 线程代表客户端执行的命令类型。如果会话处于空闲状态，则为Sleep。该列的值对应于客户端/服务器协议的 命令和 状态变量
Time：线程处于其当前状态的时间（以秒为单位）
State：指示线程正在执行的操作，事件或状态
Info：线程正在执行的语句。如果线程不执行任何语句，则为null

В заключение

Будьте внимательны при развитии бизнеса: старайтесь не проводить длинных транзакций, длинные транзакции могут легко вызвать конкуренцию замков
При обнаружении исключения превышение времени ожидания блокировки вы можете комбинировать innodb_lock_waits (соответствие ожидания блокировки), innodb_locks (текущие блокировки), innodb_trx (все текущие транзакции) и отображать полный список процессов (детали текущего потока) для анализа и обработки. Конкретные шаги заключаются в следующем:
- выберите * из information_schema.innodb_lock_waits, узнайте транзакции, ожидающие друг друга
  - Фокус на: blocking_trx_id (идентификатор блокирующей транзакции)
- выберите * из information_schema.innodb_locks, просмотрите соответствующие данные каждой блокировки транзакции
  - Фокус на: lock_trx_id (идентификатор блокирующей транзакции), lock_table (заблокированная таблица), lock_data (первичный ключ заблокированной строки)
- выберите * из information_schema.innodb_trx, чтобы получить информацию о текущей транзакции
  - Сосредоточьтесь на: trx_id (идентификатор транзакции), trx_state (состояние транзакции), trx_started (время начала транзакции), trx_mysql_thread_id (идентификатор соответствующего потока), trx_query (выполненный оператор)
- показать полный список процессов; получить подробную информацию о текущих потоках, чтобы помочь в поиске проблемы
- После определения идентификатора потока, соответствующего транзакции, вызывающей ожидание блокировки, используйте команду kill id; для уничтожения соответствующего потока.

Ссылка на ссылку

Превышено время ожидания блокировки Решения о MySQL
Тайм-аут ожидания блокировки транзакции MySQL Превышен тайм-аут ожидания блокировки; попробуйте перезапустить транзакцию
Детали списка процессов