mysql事务回滚卡住_MySQL Transaction--事务无法正常回滚导致的异常

问题表现：系统增删改操作明显变慢(由原来的几十毫秒变为几十秒)

查看未提交事务

## 查看未提交的事务 ##SELECTp.ID,

P.USER,

P.HOST,

p.DB,

P.TIME,

T.trx_started,

T.trx_isolation_level,

T.trx_tables_locked,

T.trx_rows_locked,

t.trx_state,

p.COMMANDASprocess_stateFROM`information_schema`.`INNODB_TRX` tINNER JOIN`information_schema`.`PROCESSLIST` pON t.trx_mysql_thread_id=p.idWHERE t.trx_state='RUNNING'

AND p.COMMAND='Sleep'

ORDER BY T.trx_started ASC \G

发现无未提交事务。

查看执行时间较长的进程

SELECT *

FROMinformation_schema.processlistWHERE TIME>10 andCOMMANDNOT IN('Binlog Dump')ORDER BY TIME DESC LIMIT 10;

未发现异常

PS1: processlist表中的TIME字段是指进程处理目前状态的时间，而不是进程开始执行到现在的时间。

查看事务版本Purge情况

mysql_exe="/export/servers/mysql/bin/mysql"

mysql_host="127.0.0.1"

mysql_port=3358

user_name="root"

user_psw="root.psw"for i in $(seq 1 10)

do

echo `date+"%Y-%m-%d %T"`

( ${mysql_exe} \--host="${mysql_host}" \--port=$mysql_port \--user="${user_name}" \--password="${user_psw}" \--execute="show engine innodb status \G" \

| egrep 'History list length|Purge done for trx' ) 2>/dev/nullsleep3done

执行结果为：

2019-04-08 21:36:41

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2494727

2019-04-08 21:36:44

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2494863

2019-04-08 21:36:47

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2495019

2019-04-08 21:36:50

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2495149

2019-04-08 21:36:53

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2495292

2019-04-08 21:36:56

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2495394

2019-04-08 21:36:59

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2495464

2019-04-08 21:37:02

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2495624

2019-04-08 21:37:05

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2495709

2019-04-08 21:37:08

Purge done for trx's n:o < 2291233765 undo n:o < 3126066 state: running

History list length 2495905

从上面可看出，“Purge done for trx's n:o”一直未变，而“History list length”在缓慢增长。

查看当前事务状态

SELECTtrx_id,trx_state,trx_operation_state,

trx_isolation_level,trx_startedFROM information_schema.INNODB_TRX

ORDER BY trx_started;

查询结果：

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

| trx_id | trx_state | trx_operation_state | trx_isolation_level | trx_started |

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

| 2291587663 | ROLLING BACK | rollback | REPEATABLE READ | 2019-04-08 12:31:59 |

| 421571830792992 | RUNNING | fetching rows | READ COMMITTED | 2019-04-08 21:42:06 |

| 421571830788432 | RUNNING | fetching rows | READ COMMITTED | 2019-04-08 21:42:02 |

| 421571830855920 | RUNNING | NULL | READ COMMITTED | 2019-04-08 21:42:06 |

| 421571830721856 | RUNNING | fetching rows | READ COMMITTED | 2019-04-08 21:42:02 |

| 421571830734624 | RUNNING | fetching rows | READ COMMITTED | 2019-04-08 21:42:00 |

| 421571830658016 | RUNNING | starting index read | READ COMMITTED | 2019-04-08 21:42:06 |

| 421571830851360 | RUNNING | starting index read | READ COMMITTED | 2019-04-08 21:42:06 |

| 421571831050176 | RUNNING | starting index read | READ COMMITTED | 2019-04-08 21:42:06 |

| 421571830975392 | RUNNING | starting index read | READ COMMITTED | 2019-04-08 21:42:06 |

| 421571830783872 | RUNNING | NULL | READ COMMITTED | 2019-04-08 21:42:06 |

| 421571830789344 | RUNNING | NULL | READ COMMITTED | 2019-04-08 21:42:06 |

| 421571830741920 | RUNNING | fetching rows | READ COMMITTED | 2019-04-08 21:42:05 |

| 421571830800288 | RUNNING | fetching rows | READ COMMITTED | 2019-04-08 21:42:04 |

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

其中有一条事务处开始于8个小时前并长期处于于"rollback"状态。

通过" SHOW ENGINE INNODB STATUS \G " 命令也能看到该事务信息：

---TRANSACTION 2291587663, ACTIVE 28172 sec rollback

ROLLING BACK 10670 lock struct(s), heap size 1089744, 312287 row lock(s), undo log entries 8953223

MySQL thread id 27564734, OS thread handle 139960483022592, query id 175236062467 172.20.186.43 user_rw1

查看BINLOG信息

ll -h --time-style='+%Y-%m-%d %H:%M:%S' /export/data/mysql/data/mysql-bin*

在最后写入时间12:31:57分的binlog中，应该包含超大事务，导致异常。

问题原因

在数据库开发中，“将多个操作合并到一个事务“和“将多个操作拆分到多个事务”是两个对立的操作，需要根据业务需要和场景决定如何使用，在上面场景中，研发同事将大量DML操作( 超过1000行记录修改)封装为一个超大事务中，并且在事务处理过程中引入其他非数据库操作，导致整个事务周期较长，同时检查业务线程执行时间的作业按照processlist表中TIME字段判断线程情况，导致这种超大事务没有被及时KILL，当问题爆发后，超大事务被KILL，但回滚操作需要很长时间。