MySQL 案例：The age of the last checkpoint is X

原创

王文安@DBA

发布于 2021-03-22 14:57:49

1.2K0

发布于 2021-03-22 14:57:49

文章被收录于专栏：腾讯云数据库专家服务

背景

近期发现有一个实例 Crash 了，在排查问题的过程中遇到了一个比较少见的日志信息，就抽时间看了一下，在这里做一下记录。

问题描述

现象上，MySQL 出现了 Crash，摘录部分错误日志内容，如下：

2021-03-12T14:54:26.302945+08:00 0 [ERROR] InnoDB: The age of the last checkpoint is 8106349, which exceeds the log group capacity 7546061.
2021-03-12T14:54:37.165502+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139648846694144 has waited at buf0buf.cc line 4090 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f04f5b122d8 created in file buf0buf.cc line 1428
a writer (thread id 139648846694144) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3775
......

这个报错的直接原因就是A long semaphore wait，导致 InnoDB 自己主动 Crash，主要的问题是上面那一段 ERROR 的 log。

原因分析

按经验来推断的话，估计是 last checkpoint 的位置太远，导致 redo log 空间不够用了（8106349 > 7546061）。不过也有人提出了疑问，这个 age 代表的意思不一定是指上一次 checkpoint 到当前的时间，也有可能是指当前需要进行 checkpoint 的位点，超过了 redo log 的大小，所以抛出来这个 ERROR。

最简单的验证办法就是翻一下源代码了，找一下这个报错信息中，位点数据的计算方式。代码以 5.7.31 的官方版本为例，搜索之后找到这一段错误信息所在的位置：

./storage/innobase/log/log0log.cc

log_close(void)
/*===========*/
{
        ......
        lsn = log->lsn;
        ......
        checkpoint_age = lsn - log->last_checkpoint_lsn;

        if (checkpoint_age >= log->log_group_capacity) {
                DBUG_EXECUTE_IF(
                        "print_all_chkp_warnings",
                        log_has_printed_chkp_warning = false;);

                if (!log_has_printed_chkp_warning
                    || difftime(time(NULL), log_last_warning_time) > 15) {

                        log_has_printed_chkp_warning = true;
                        log_last_warning_time = time(NULL);

                        ib::error() << "The age of the last checkpoint is "
                                << checkpoint_age << ", which exceeds the log"
                                " group capacity " << log->log_group_capacity
                                << ".";
                }
        }
        ......
}

可以看到在日志中显示的数值是 checkpoint_age 和 log_group_capacity，后者应该就是 redo log 的大小，前者是通过一个公式计算出来的：

checkpoint_age = lsn - log->last_checkpoint_lsn

从公式上看，显然这个 age 代表的是当前的 LSN 和上一次 checkpoint 时 LSN 的差距。

因此引起这次A long semaphore wait的主要原因就是当前的日志 lsn 距离上一次 checkpoint 过久或者过远，更准确的原因则需要继续深入分析为什么一直没有进行 checkpoint 了，不在本文的讨论范围之内。