背景

由于业务中有备份某个业务表的定时任务 会在每天指定时间点做一次备份【使用quartz】

各位也都知道各种timeout的相关问题

socketTimeout

connectTimeOut

queryTimeOut

transactionTimeOut

等等

事实上 每一个timeout都有其特殊的用处

相传不久前美团外卖挂机事件也是由于前一天晚上发布临时调整了timeout导致~

问题

我们系统中使用了mybatis的timeout 默认情况配置30s

因此开发为了防止对应sql超时设置了为500s

但是事务时间设置为180s

@Intercepts({
        @Signature(type = StatementHandler.class, method = "update", args = {Statement.class}),
        @Signature(type = StatementHandler.class, method = "batch", args = {Statement.class}),
        @Signature(type = StatementHandler.class, method = "query", args = {Statement.class, ResultHandler.class})})
public class MybatisTransactionTimeoutInterceptor implements Interceptor {
 
    @Override
    public Object intercept(Invocation invocation) throws Throwable {
        Statement stmt = (Statement) invocation.getArgs()[0];
        Collection< Object> values = TransactionSynchronizationManager.getResourceMap().values();
        if (values.size() > 0) {
            for (Object obj : values) {
                if (obj != null && obj instanceof ConnectionHolder) {
                    ConnectionHolder holder = (ConnectionHolder) obj;
                    if (holder.hasTimeout()) {
                        int queryTimeOut = holder.getTimeToLiveInSeconds();
                        if (stmt.getQueryTimeout() != 0) {
                            queryTimeOut = queryTimeOut < stmt.getQueryTimeout() ? queryTimeOut : stmt.getQueryTimeout();
                        }
                        stmt.setQueryTimeout(queryTimeOut);
                    }
                    break;
                }
            }
        }
 
        return invocation.proceed();
    }
 
    @Override
    public Object plugin(Object target) {
        return Plugin.wrap(target, this);
    }
 
    @Override
    public void setProperties(Properties properties) {
 
    }
}

那么实质上应当在180s的时候就抛出异常

但是结果均是大约在270s左右抛出异常。

service运行时间和事务时长不一致！居然额外多出了90s！

分析

首先分析该service

该service十分简单基本没有太多业务操作

考虑其设置超时时间应当正确为180s【事实上正常执行一次该sql需要约4min+】

但是基本在200s+能够返回

通过show processlist命令查看对应mysql连接处于query end 状态

面向Google编程后发现大部分用户提到 磁盘空间占用不足 导致出现长时间 queryend yuan-xulong.iteye.com/blog/204729…

和我们系统不符【继续观察系统】

发现sql语句恰好在180s后更改了状态为query end【证明query timeout 是生效的】

但是系统在200s+才收到异常的原因是mysql对应连接长时间hang在了query end 状态

继续面向谷歌编程 检索到如下一句话

We’re running on MySQL Percona 5.5 on InnoDB, and whenever our system has bad performance we see that there are a LOT of INSERT threads stuck in the “query end” state.

According to Google searches, this state doesn’t do anything, it’s just:

This state occurs after processing a query but before the freeing items state.

Does this mean that the ‘freeing items’ state has a queue that all of our INSERTs have to wait for, or is there something else going on during this state?

Edit: The innodb_flush_log_at_trx_commit variable is already set at 0.

都提到了该状态通常出现在insert之后 我们的sql语句时大量的插入某个表【因此考虑可能导致log相当多 涉及到磁盘】

查看 innodb_flush_log_at_trx_commit

Variable_name Valueinnodb_flush_log_at_trx_commit 2

一、参数解释

0：log buffer将每秒一次地写入log file中，并且log file的flush(刷到磁盘)操作同时进行。该模式下在事务提交的时候，不会主动触发写入磁盘的操作。

1：每次事务提交时MySQL都会把log buffer的数据写入log file，并且flush(刷到磁盘)中去，该模式为系统默认。

2：每次事务提交时MySQL都会把log buffer的数据写入log file，但是flush(刷到磁盘)操作并不会同时进行。该模式下，MySQL会每秒执行一次 flush(刷到磁盘)操作。

二、参数修改

找到mysql配置文件mysql.ini，修改成合适的值，然后重启mysql。

三、注意事项

当设置为0，该模式速度最快，但不太安全，mysqld进程的崩溃会导致上一秒钟所有事务数据的丢失。

当设置为1，该模式是最安全的，但也是最慢的一种方式。在mysqld 服务崩溃或者服务器主机crash的情况下，binary log 只有可能丢失最多一个语句或者一个事务。。当设置为2，该模式速度较快，也比0安全，只有在操作系统崩溃或者系统断电的情况下，上一秒钟所有事务数据才可能丢失。

考虑由于大量的插入导致需要flush log 导致sql语句hang在query end状态

措施

在大量插入的场景下可以适当放宽事务时长