背景
近期发现有一个实例 Crash 了，在排查问题的过程中遇到了一个比较少见的日志信息，就抽时间看了一下，在这里做一下记录。
问题描述
现象上，MySQL 出现了 Crash，摘录部分错误日志内容，如下：
代码语言：txt复制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 的官方版本为例，搜索之后找到这一段错误信息所在的位置：
代码语言：txt复制./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 了，不在本文的讨论范围之内。
总结
知识重积累，不积跬步，无以至千里；不积小流，无以成江海。要认真对待工作中遇到的每一个理解上可能有歧义或者不清晰的问题点和知识点。
