• 什么？MySQL 8.0 会同时修改两个ib_logfilesN 文件？

    问题现象描述

    测试MySQL单机时，无意发现，MySQL 8.0的 ib_logfilesN的显示如下：

    1. ll ib_logfile*
    2. -rw-r----- 1 greatsql greatsql 134217728 8月 4 18:36 ib_logfile0
    3. -rw-r----- 1 greatsql greatsql 134217728 7月 27 17:31 ib_logfile1
    4. -rw-r----- 1 greatsql greatsql 134217728 8月 4 18:03 ib_logfile2
    5. -rw-r----- 1 greatsql greatsql 134217728 8月 4 18:36 ib_logfile3

    其中 ib_logfile0、iblogfile3 的 最近改动时间为：2022-08-04 18:36

    印象中，MySQL 8.0对 redo 做了大量优化，难道刷盘也做了改变？

    重现现象

    赶紧登录到MySQL 重新执行一条insert，再观察一下。

    1. 1  ib_logfile*
    2. 2 -rw-r----- 1 greatsql greatsql 134217728 8月   9 22:55 ib_logfile0
    3. 3 -rw-r----- 1 greatsql greatsql 134217728 7月  27 17:31 ib_logfile1
    4. 4 -rw-r----- 1 greatsql greatsql 134217728 8月   4 18:03 ib_logfile2
    5. 5 -rw-r----- 1 greatsql greatsql 134217728 8月   9 22:55 ib_logfile3
    6. 6 [#3#root@greatsql82 /data/mysql8023/data 22:55:45]3 stat  ib_logfile0
    7. 7 文件："ib_logfile0"`
    8. 8 大小：134217728       块：262144     IO 块：4096   普通文件
    9. 9 设备：fd00h/64768d      Inode：75740704    硬链接：1
    10. 10 权限：(0640/-rw-r-----)  Uid：( 1000/ greatsql)   Gid：( 1000/ greatsql)
    11. 11 最近访问：2022-08-04 19:22:32.746184752 +0800
    12. 12 最近更改：2022-08-09 22:55:40.166964294 +0800
    13. 13 最近改动：2022-08-09 22:55:40.166964294 +0800
    14. 14 创建时间：-`
    15. 15 [#4#root@greatsql82 /data/mysql8023/data 22:56:13]4 stat  ib_logfile3
    16. 16 文件："ib_logfile3"
    17. 17 大小：134217728       块：262144     IO 块：4096   普通文件
    18. 18 设备：*******       Inode：75740707    硬链接：1
    19. 19 权限：(0640/-rw-r-----)  Uid：( 1000/ greatsql)   Gid：( 1000/ greatsql)
    20. 20 最近访问：2022-08-04 19:22:48.510210526 +0800
    21. 21 最近更改：2022-08-09 22:55:39.741963331 +0800
    22. 22 最近改动：2022-08-09 22:55:39.741963331 +0800
    23. 23 创建时间：-

    在MySQL端执行一个事务后，可以看到 ib_logfile0、iblogfile3 都发生了改变， iblogfile3 先改变， iblogfile0 后改变，且改动时间相差不到 0.42s

    赶紧翻一下官网手册

    By default, the redo log is physically represented on disk by two files named ib_logfile0 and ib_logfile1. MySQL writes to the redo log files in a circular fashion.

    没有新变化，依旧是循环写 （那为啥写了iblogfile3后，还会写iblogfile0呢？）

    实践追踪

    最直接的当然是去看源码，一切尽在源码中。不过看代码实在太麻烦，不太适合大多数的人，gdb debug 过程，技术要求门槛较高。

    有没有一个工具，能让运维人员直观地观测一下呢?

    当然有！

    sysdig 这是笔者在GreatSQL社区了解到的一款观测性神器。

    在MySQL执行

    insert into test.t values(1,'aa');

    追踪如下：

    1. 1 sysdig    proc.pid=2617   and  fd.type=file  
    2. 2    273983 01:02:18.534336211 1 mysqld (2617.3021) < open fd=39(<f>/data/mysql8023/data/test/t.ibd) name=./test/t.ibd(/data/mysql8023/data/test/t.ibd) flags=1(O_RDONLY) mode=0 dev=FD00
    3. 3    `273988 01:02:18.534381910 1 mysqld (2617.3021) > lseek fd=39(<f>/data/mysql8023/data/test/t.ibd) offset=0 whence=1(SEEK_CUR)
    4. 4    `273989 01:02:18.534384266 1 mysqld (2617.3021) < lseek res=0
    5. 5    `273990 01:02:18.534385778 1 mysqld (2617.3021) > lseek fd=39(<f>/data/mysql8023/data/test/t.ibd) offset=0 whence=2(SEEK_END)
    6. 6    `273991 01:02:18.534386657 1 mysqld (2617.3021) < lseek res=114688
    7. 7    `273992 01:02:18.534387686 1 mysqld (2617.3021) > lseek fd=39(<f>/data/mysql8023/data/test/t.ibd) offset=0 whence=0(SEEK_SET)
    8. 8    `273993 01:02:18.534388675 1 mysqld (2617.3021) < lseek res=0
    9. 9    273996 01:02:18.534428831 1 mysqld (2617.3021) > pread fd=39(<f>/data/mysql8023/data/test/t.ibd) size=1024 pos=0
    10. 10    273997 01:02:18.534446476 1 mysqld (2617.3021) < pread res=1024 data=:.........8..........eKq.............................@..@!......................
    11. 11    273998 01:02:18.534449603 1 mysqld (2617.3021) > pread fd=39(<f>/data/mysql8023/data/test/t.ibd) size=16384 pos=0
    12. 12    273999 01:02:18.534481272 1 mysqld (2617.3021) < pread res=16384 data=:.........8..........eKq.............................@..@!......................
    13. 13    274000 01:02:18.534485006 1 mysqld (2617.3021) > close fd=39(<f>/data/mysql8023/data/test/t.ibd)
    14. 14    274001 01:02:18.534487333 1 mysqld (2617.3021) < close res=0
    15. 15    274003 01:02:18.534504990 1 mysqld (2617.3021) < open fd=39(<f>/data/mysql8023/data/test/t.ibd) name=./test/t.ibd(/data/mysql8023/data/test/t.ibd) flags=3(O_RDWR) mode=0 dev=FD00
    16. 16    274004 01:02:18.534507922 1 mysqld (2617.3021) > fcntl fd=39(<f>/data/mysql8023/data/test/t.ibd) cmd=5(F_SETFL)
    17. 17    274005 01:02:18.534510349 1 mysqld (2617.3021) < fcntl res=0(<f>/dev/null)
    18. 18    274006 01:02:18.534511842 1 mysqld (2617.3021) > fcntl fd=39(<f>/data/mysql8023/data/test/t.ibd) cmd=8(F_SETLK)
    19. 19    274007 01:02:18.534518620 1 mysqld (2617.3021) < fcntl res=0(<f>/dev/null)
    20. 20    274012 01:02:18.534537370 1 mysqld (2617.3021) > pread fd=39(<f>/data/mysql8023/data/test/t.ibd) size=16384 pos=65536
    21. 21    274549 01:02:18.551004551 2 mysqld (2617.3021) < pread res=16384 data=x...................?..KE................x......................................
    22. 22    274553 01:02:18.551086413 2 mysqld (2617.3021) > pread fd=39(<f>/data/mysql8023/data/test/t.ibd) size=16384 pos=16384
    23. 23    274578 01:02:18.553158586 2 mysqld (2617.3021) < pread res=16384 data=..Nv.................e>8........................................................
    24. 24    274904 01:02:18.567111657 3 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=1024 pos=133301760
    25. 25    274908 01:02:18.567152231 3 mysqld (2617.2665) < pwrite res=1024 data=.......N.."......Z/........Q.......Q.......:......Z/r.........Z/...........*....
    26. 26    274912 01:02:18.567167495 3 mysqld (2617.2665) > pwrite fd=11(/data/mysql8023/data/ib_logfile3) size=512 pos=133302784
    27. 27    274913 01:02:18.567170922 3 mysqld (2617.2665) < pwrite res=512 data=.....x.x..".....................................................................
    28. 28    275149 01:02:18.573320262 2 mysqld (2617.3021) > write fd=36(<f>/data/mysql8023/log/mysql-bin.000011) size=275
    29. 29    275150 01:02:18.573353921 2 mysqld (2617.3021) < write res=275 data=...b!....K.............'.5...Q..'w{...........................9 ........8.....b.
    30. 30    275244 01:02:18.574223831 3 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=512 pos=133302784
    31. 31    275245 01:02:18.574249340 3 mysqld (2617.2665) < pwrite res=512 data=.....p.x..".....................................................................
    32. 32    276355 01:02:18.652355052 1 mysqld (2617.2665) > pwrite fd=11(/data/mysql8023/data/ib_logfile3) size=512 pos=133302784
    33. 33    276362 01:02:18.652389109 1 mysqld (2617.2665) < pwrite res=512 data=.......x..".....................................................................
    34. 34    276366 01:02:18.652400127 1 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=512 pos=133303296
    35. 35    276369 01:02:18.652404698 1 mysqld (2617.2665) < pwrite res=512 data=..........".......8.............................................................
    36. 36    277222 01:02:18.658160528 1 mysqld (2617.2665) > pwrite fd=11(/data/mysql8023/data/ib_logfile3) size=512 pos=133303296
    37. 37    277223 01:02:18.658196012 1 mysqld (2617.2665) < pwrite res=512 data=..........".......8....>$.......................................................
    38. 38    279425 01:02:18.769808947 1 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=512 pos=133303296` 
    39. 39    279426 01:02:18.769861708 1 mysqld (2617.2665) < pwrite res=512 data=.....(....".......8....>$........>$.............................................
    40. 40    281529 01:02:18.924391804 3 mysqld (2617.2657) > pwrite fd=12(/data/mysql8023/data/#ib_16384_0.dblwr) size=147456 pos=262144` 
    41. 41    281539 01:02:18.925125943 3 mysqld (2617.2657) < pwrite res=147456 data=.E..................?..(........................................................
    42. 42    302247 01:02:19.924998103 0 mysqld (2617.2661) > pwrite fd=4(/data/mysql8023/data/ib_logfile0) size=512 pos=512` 
    43. 43    302248 01:02:19.925043052 0 mysqld (2617.2661) < pwrite res=512 data=......".....?..(.......(........................................................

    分析过程

    分析以上追踪日志，可以得到：

    1、 （2617.3021） 2617 是 mysqld 进程号， 3021 是执行SQL语句的 THREAD_OS_ID ，可以看到操作 t.ibd 文件（FD39)的完整过程，这里没有追踪到FD39 write的过程，说明redo日志落盘，checkpoint向前更新，就能完成事务提交，不需要等待数据的真正落盘。

    2、

    • 2665线程 thread/innodb/log_writer_thread 先写/data/mysql8023/data/ib_logfile3

    • 2661线程thread/innodb/log_checkpointer_thread 更新/data/mysql8023/data/ib_logfile0 pos512 和 pos1536 两个位置

    1.  select  *  from  threads  where  THREAD_OS_ID  in (2665,2661) \G
    2.     *************************** 1. row ***************************
    3.               THREAD_ID: 27
    4.                    NAME: thread/innodb/log_checkpointer_thread
    5.                    TYPE: BACKGROUND
    6.     
    7.     ...
    8.     
    9.             THREAD_OS_ID: 2661
    10.                 RESOURCE_GROUP: SYS_default
    11.     *************************** 2. row ***************************
    12.               THREAD_ID: 31
    13.                    NAME: thread/innodb/log_writer_thread
    14.                    TYPE: BACKGROUND
    15.     ...
    16.                  THREAD_OS_ID: 2665
    17.               RESOURCE_GROUP: SYS_default
    18.     2 rows in set (0.00 sec)

    3、 log_filesN 每次更新的大小为512B *N N>=1

    4、 当前正在记录redo内容的文件为 ib_logfile3 pos 到了133303296

    以上通过可观测性追踪，粗略验证了 前文对 "Ib_logfile的checkpoint field" 的描述准确性。

    理论依据

    事务日志或称redo日志，在MySQL中默认以 ib_logfile0,ib_logfile1 名称存在,可以手工修改参数，调节开启几组日志来服务于当前MySQL数据库,MySQL采用顺序，循环写方式，每开启一个事务时，会把一些相关信息记录事务日志中(记录对数据文件数据修改的物理位置或叫做偏移量);

    这个系列文件个数由参数 innodb_log_files_in_group 控制，若设置为4，则命名为 ib_logfile0~3

    这些文件的写入是顺序、循环写的， logfile0 写完从 logfile1 继续， logfile3 写完则 logfile0 继续。

    在系统崩溃重启时，作事务重做；在系统正常时，每次 checkpoint 时间点，会将之前写入事务应用到数据文件中。

    Ib_logfile的checkpoint field

    实际上不仅要记录 checkpoint 做到哪儿 (LOG_CHECKPOINT_LSN) ，还要记录用到了哪个位置 (LOG_CHECKPOINT_OFFSET) 等其他信息。所以在 ib_logfile0 的头部预留了空间，用于记录这些信息。

    因此即使使用后面的 logfile ，每次 checkpoint 完成后， ib_logfile0 都是要更新的。同时你会发现所谓的顺序写盘，也并不是绝对的

    相关的一些数字

    a) InnoDB 留了两个 checkpoint filed ，按照注释的解释，目的是为了能够 “write alternately”

    b) 每个 checkpint field 需要的大小空间为304字节。(相关定义在log0log.h)

    c) 第一个 checkpoint 的起始位置在 ib_logfile0 的第512字节 (OS_FILE_LOG_BLOCK_SIZE) 处；

    d) “第二个在 1536 (3 * OS_FILE_LOG_BLOCK_SIZE) 字节处” [^引1]

    Redo log 文件以 ib_logfile[number] 命名，日志目录可以通过参数 innodb_log_group_home_dir 控制。 Redo log 以顺序的方式写入文件文件，写满时则回溯到第一个文件，进行覆盖写。（但在做 redo checkpoint 时，也会更新第一个日志文件的头部 checkpoint 标记，所以严格来讲也不算顺序写）。

    “在InnoDB内部，逻辑上 ib_logfile 被当成了一个文件，对应同一个space id。由于是使用512字节block对齐写入文件，可以很方便的根据全局维护的LSN号计算出要写入到哪一个文件以及对应的偏移量。”[^引2]

    总结

    8.0 一个自动提交事务，redo落文件的方式追踪 1.通过后台线程 thread/innodb/log_writer_thread 写redo，通过另一个后台线程 thread/innodb/log_checkpointer_thread ，在 ib_logfile0 的pos=512 pos=1536 ，分别记录checkpoint 。两个线程都是以512B的整数倍为单位，写文件。

    追踪过程比结论重要。sysdig在可观测性方面提供了强大的帮助。理论联系实际，才是探索未知事务之道。

    最后感谢GreatSQL社区，对本文出炉给与的技术支持。

  • 相关阅读:
    机器学习之集成学习算法简介
    声明式事务管理参数配置
    SpringBoot OAuth2.0认证管理流程详解
    Gnome-keyring如何进行密码的CRUD
    OpenCV（三十九）：积分图像
    【UE】刀光粒子效果——part1
    DoIP——step1：车辆连接
    六 系统可靠性分析与设计
    WebGL笔记：矩阵的变换之平移的实现
    【SQL server速成之路】触发器
  • 原文地址：https://blog.csdn.net/m0_73257876/article/details/126698420