慢查询日志中发现大量commit,如下
SET timestamp=1552353143;
commit;
# User@Host: dubosql[dubosql] @ dubbo*.local [*.*.*.*] Id: 87388049
# Query_time: 5.056767 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1552353143;
commit;
# User@Host: dubosql[dubosql] @ dubbo*.local [*.*.*.*] Id: 87388046
# Query_time: 5.053214 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1552353143;
commit;
# User@Host: dubosql[dubosql] @ dubbo*.local [*.*.*.*] Id: 87386347
# Query_time: 5.016747 Lock_time: 0.000098 Rows_sent: 0 Rows_examined: 0
出现这种情况甚是奇怪，一开始毫无头绪。只能试着重现，找台机器测试，commit操作基本上都是0.00 sec，然后又怀疑是不是大事务，然后更新了100W行数据，进行测试，commit也是0.00 sec，并不会记录到慢查询日志中。
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> update tb1 set c2='testcommit1112323123213' ;
Query OK, 1000000 rows affected (15.91 sec)
Rows matched: 1000000 Changed: 1000000 Warnings: 0
mysql> commit;
Query OK, 0 rows affected (0.00 sec)
针对慢查询出现的时间点，又去找到error日志，发现日志中对应的时间点有
2019-03-12 09:12:24 3411 [Warning] WSREP: Failed to report last committed 943412934, -4 (Interrupted system call)
又跑去查阅相关资料，发现这个只是galera集群的一个bug，无关紧要，从而想到是不是由于数据库的架构原因，我这边是galera for mysql三主模式，再一次在集群中重现大事务commit,发现果不其然，慢查询日志中记录了commit操作，从而找到问题根源
mysql> update tb1 set c2='testcommit1112323' ;
Query OK, 1000000 rows affected (41.59 sec)
Rows matched: 1000000 Changed: 1000000 Warnings: 0
mysql> commit;
Query OK, 0 rows affected (6.91 sec)
# Time: 2019-03-13T02:18:43.517537Z
# User@Host: root[root] @ localhost [] Id: 32
# Query_time: 41.592426 Lock_time: 0.074788 Rows_sent: 0 Rows_examined: 1000000
SET timestamp=1552443523;
update tb1 set c2='testcommit1112323';
# Time: 2019-03-13T02:18:58.644945Z
# User@Host: root[root] @ localhost [] Id: 32
# Query_time: 6.915626 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1552443538;
commit;
结论：当发现慢查询日志中记录大量commit操作后，肯定是提交commit操作时，消耗了不少时间，由于galera同步复制模式，需要数据复制到集群中其他服务器中，从而导致commit需要时间长。进而找到研发优化大事务，拆分大事务。
网友评论