导读

生产使用xtrabackup做备份, 难免会遇到Unable to obtain lock. Please try again later报错. 这个报错很简单,也很经典. 故来分析下.

环境:
mysql 5.7.38
xtrabackup 2.4.26
xtrabackup 源码是2.4.27的…

复现

这个案例比较常见, 所以我们直接在测试环境复现. 有兴趣的还可以打开general log验证下.

-- session 1 模拟慢SQL
select sleep(10000000000); -- 睡到天荒地老

等60秒后, 再开一个会话发起备份

xtrabackup --defaults-file=/data/mysql_3308/conf/mysql_3308.cnf \
--host=192.168.101.21 \
--port=3308 \
--user=root \
--password=123456 \
--parallel=2 \
--ftwrl-wait-timeout=120 \
--ftwrl-wait-threshold=60 \
--target-dir=/data/backup/t20250228 \
--backup

参数讲解:
--ftwrl-wait-timeout=120 执行ftwrl之前检查连接的时间为120秒(即这120秒内有1秒满足要求即可)
--ftwrl-wait-threshold=60 若所有SQL的执行时间均小于60秒,则发起ftwrl, 否则一直等,直到超时(ftwrl-wait-timeou)

然后我们就可以在innodb数据文件备份完之后, 发现如下信息:

250228 16:02:58 [02]        ...done
250228 16:02:58 [02] Copying ./db3/AaBc.ibd to /data/backup/t20250228/db3/AaBc.ibd
250228 16:02:58 [02]        ...done
250228 16:02:58 [02] Copying ./db3/t20231220.ibd to /data/backup/t20250228/db3/t20231220.ibd
250228 16:02:58 [02]        ...done
250228 16:02:58 [02] Copying ./db3/t20240117.ibd to /data/backup/t20250228/db3/t20240117.ibd
250228 16:02:58 [02]        ...done
250228 16:02:59 >> log scanned up to (49322991226)
250228 16:03:00 >> log scanned up to (49322991226)
250228 16:03:01 [01]        ...done
250228 16:03:01 >> log scanned up to (49322991226)
250228 16:03:01 Waiting 120 seconds for queries running longer than 60 seconds to finish
250228 16:03:01 Waiting for query 1199 (duration 808 sec): select sleep(1000000)250228 16:03:02 >> log scanned up to (49322991226)
250228 16:03:02 Waiting for query 1199 (duration 809 sec): select sleep(1000000)250228 16:03:03 >> log scanned up to (49322991226)
............................................
............................................
250228 16:05:00 Waiting for query 1199 (duration 927 sec): select sleep(1000000)250228 16:05:00 >> log scanned up to (49322991226)
250228 16:05:01 Waiting for query 1199 (duration 928 sec): select sleep(1000000)250228 16:05:01 >> log scanned up to (49322991226)
250228 16:05:02 Unable to obtain lock. Please try again later

也就是在这120秒(ftwrl-wait-timeout)内, 一直存在执行时间超过(ftwrl-wait-threshold)的SQL语句.
日志里面打印了相关的SQL语句的, 当然慢日志里面通常也有.

源码分析

之前讲过遇到这种问题, 怎么根据报错找到相关源码位置的.(应该是去年的某篇文章,具体的我也忘记了-_-). 这里再来看下:
使用grep -r key找到对应报错的函数

# 下载源码
wget https://downloads.percona.com/downloads/Percona-XtraBackup-2.4/Percona-XtraBackup-2.4.27/source/tarball/percona-xtrabackup-2.4.27.tar.gz
tar -xvf percona-xtrabackup-2.4.27.tar.gz
# 进入源码目录, 不熟悉的画, 可以就最外面层
cd percona-xtrabackup-2.4.27/storage/innobase/xtrabackup/src
# 搜索报错信息
grep -r 'Unable to obtain lock'

这个完整的函数如下:

static
bool
wait_for_no_updates(MYSQL *connection, uint timeout, uint threshold)
{       
        time_t  start_time;
        
        start_time = time(NULL);
        
        msg_ts("Waiting %u seconds for queries running longer than %u seconds "
               "to finish\n", timeout, threshold);
        
        while (time(NULL) <= (time_t)(start_time + timeout)) {
                if (!have_queries_to_wait_for(connection, threshold)) {
                        return(true);
                }
                os_thread_sleep(1000000);
        }
        
        msg_ts("Unable to obtain lock. Please try again later.");
        
        return(false);
}

然后继续使用grep -r找到调这个函数的函数, 和这个函数要调用的其它函数. 然后串起来.

本案例比较简单, 就上面那个函数基本上就能确定了.

如下是整理之后的函数调用关系.

我这里省略了innodb备份的过程, 也省略了后面的ftwrl等信息

还有个关键的函数have_queries_to_wait_for代码如下:

static
bool
have_queries_to_wait_for(MYSQL *connection, uint threshold)
{
        MYSQL_RES *result;
        MYSQL_ROW row;
        bool all_queries;

        result = xb_mysql_query(connection, "SHOW FULL PROCESSLIST", true);

        all_queries = (opt_lock_wait_query_type == QUERY_TYPE_ALL);
        while ((row = mysql_fetch_row(result)) != NULL) {
                const char      *info           = row[7];
                char            *id             = row[0];
                int             duration;

                duration = (row[5] != NULL) ? atoi(row[5]) : 0;

                if (info != NULL
                    && duration >= (int)threshold
                    && ((all_queries && is_query(info))
                        || is_update_query(info))) {
                        msg_ts("Waiting for query %s (duration %d sec): %s",
                               id, duration, info);
                        mysql_free_result(result);
                        return(true);
                }
        }

        mysql_free_result(result);

        return(false);
}

结合上面两个函数分析, 也就是开始备份之后(innodb备份完成之后), 判断是否有慢SQL执行时间达到ftwrl-wait-threshold,有的话, 就一直等ftwrl-wait-timeout, 否则就继续备份. 代码里很直接的使用SHOW FULL PROCESSLIST语句查询, 我们也可以在general log里面找到相关信息

如果某个时间没得执行超过ftwrl-wait-threshold的SQL时, 就会执行后续的myisam备份过程. (我这里就以Kill连接来模拟)

总结和建议

我们使用ftwrl-wait-*这样的参数来防止因为慢SQL导致长时间备份不成功, 但这种判断方式过于草率. 比如我们模拟的这个场景, 如果不加上ftwrl-wait-timeout的话, 是能直接备份成功的. 因为sleep不影响ftwrl. (当然也可以通过–ftwrl-wait-query-type调整要判断的sql类型)
.

而且备份是比较重要的, 可能某段时间确实存在一定的慢sql, 那大不了多等会, 总比备份失败好点, 也可以监控下备份时间. 定期优化下慢SQL也是不错的选择.
所以不建议使用--ftwrl-wait-*相关参数.(实际环境请根据自己的情况决定,这里只是建议.)