胖虎的工具箱-编程导航 胖虎的工具箱-编程导航

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

2年前 (2022) 程序员胖胖胖虎阿
307 0 0
  • GreatSQL社区原创内容未经授权不得随意使用，转载请联系小编并注明来源。
  • GreatSQL是MySQL的国产分支版本，使用上与MySQL一致。
  • 作者介绍：孙黎，GreatDB 认证DBA

问题现象描述

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

ll ib_logfile*
-rw-r----- 1 greatsql greatsql 134217728 8月 4 18:36 ib_logfile0
-rw-r----- 1 greatsql greatsql 134217728 7月 27 17:31 ib_logfile1
-rw-r----- 1 greatsql greatsql 134217728 8月 4 18:03 ib_logfile2
-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  ib_logfile*
2 -rw-r----- 1 greatsql greatsql 134217728 8月   9 22:55 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月   9 22:55 ib_logfile3
6 [#3#root@greatsql82 /data/mysql8023/data 22:55:45]3 stat  ib_logfile0
7 文件："ib_logfile0"`
8 大小：134217728       块：262144     IO 块：4096   普通文件
9 设备：fd00h/64768d      Inode：75740704    硬链接：1
10 权限：(0640/-rw-r-----)  Uid：( 1000/ greatsql)   Gid：( 1000/ greatsql)
11 最近访问：2022-08-04 19:22:32.746184752 +0800
12 最近更改：2022-08-09 22:55:40.166964294 +0800
13 最近改动：2022-08-09 22:55:40.166964294 +0800
14 创建时间：-`
15 [#4#root@greatsql82 /data/mysql8023/data 22:56:13]4 stat  ib_logfile3
16 文件："ib_logfile3"
17 大小：134217728       块：262144     IO 块：4096   普通文件
18 设备：*******       Inode：75740707    硬链接：1
19 权限：(0640/-rw-r-----)  Uid：( 1000/ greatsql)   Gid：( 1000/ greatsql)
20 最近访问：2022-08-04 19:22:48.510210526 +0800
21 最近更改：2022-08-09 22:55:39.741963331 +0800
22 最近改动：2022-08-09 22:55:39.741963331 +0800
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 sysdig    proc.pid=2617   and  fd.type=file  
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    `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    `273989 01:02:18.534384266 1 mysqld (2617.3021) < lseek res=0
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    `273991 01:02:18.534386657 1 mysqld (2617.3021) < lseek res=114688
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    `273993 01:02:18.534388675 1 mysqld (2617.3021) < lseek res=0
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    273997 01:02:18.534446476 1 mysqld (2617.3021) < pread res=1024 data=:.........8..........eKq.............................@..@!......................
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    273999 01:02:18.534481272 1 mysqld (2617.3021) < pread res=16384 data=:.........8..........eKq.............................@..@!......................
13    274000 01:02:18.534485006 1 mysqld (2617.3021) > close fd=39(<f>/data/mysql8023/data/test/t.ibd)
14    274001 01:02:18.534487333 1 mysqld (2617.3021) < close res=0
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    274004 01:02:18.534507922 1 mysqld (2617.3021) > fcntl fd=39(<f>/data/mysql8023/data/test/t.ibd) cmd=5(F_SETFL)
17    274005 01:02:18.534510349 1 mysqld (2617.3021) < fcntl res=0(<f>/dev/null)
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    274007 01:02:18.534518620 1 mysqld (2617.3021) < fcntl res=0(<f>/dev/null)
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    274549 01:02:18.551004551 2 mysqld (2617.3021) < pread res=16384 data=x...................?..KE................x......................................
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    274578 01:02:18.553158586 2 mysqld (2617.3021) < pread res=16384 data=..Nv.................e>8........................................................
24    274904 01:02:18.567111657 3 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=1024 pos=133301760
25    274908 01:02:18.567152231 3 mysqld (2617.2665) < pwrite res=1024 data=.......N.."......Z/........Q.......Q.......:......Z/r.........Z/...........*....
26    274912 01:02:18.567167495 3 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=512 pos=133302784
27    274913 01:02:18.567170922 3 mysqld (2617.2665) < pwrite res=512 data=.....x.x..".....................................................................
28    275149 01:02:18.573320262 2 mysqld (2617.3021) > write fd=36(<f>/data/mysql8023/log/mysql-bin.000011) size=275
29    275150 01:02:18.573353921 2 mysqld (2617.3021) < write res=275 data=...b!....K.............'.5...Q..'w{...........................9 ........8.....b.
30    275244 01:02:18.574223831 3 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=512 pos=133302784
31    275245 01:02:18.574249340 3 mysqld (2617.2665) < pwrite res=512 data=.....p.x..".....................................................................
32    276355 01:02:18.652355052 1 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=512 pos=133302784
33    276362 01:02:18.652389109 1 mysqld (2617.2665) < pwrite res=512 data=.......x..".....................................................................
34    276366 01:02:18.652400127 1 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=512 pos=133303296
35    276369 01:02:18.652404698 1 mysqld (2617.2665) < pwrite res=512 data=..........".......8.............................................................
36    277222 01:02:18.658160528 1 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=512 pos=133303296
37    277223 01:02:18.658196012 1 mysqld (2617.2665) < pwrite res=512 data=..........".......8....>$.......................................................
38    279425 01:02:18.769808947 1 mysqld (2617.2665) > pwrite fd=11(<f>/data/mysql8023/data/ib_logfile3) size=512 pos=133303296` 
39    279426 01:02:18.769861708 1 mysqld (2617.2665) < pwrite res=512 data=.....(....".......8....>$........>$.............................................
40    281529 01:02:18.924391804 3 mysqld (2617.2657) > pwrite fd=12(<f>/data/mysql8023/data/#ib_16384_0.dblwr) size=147456 pos=262144` 
41    281539 01:02:18.925125943 3 mysqld (2617.2657) < pwrite res=147456 data=.E..................?..(........................................................
42    302247 01:02:19.924998103 0 mysqld (2617.2661) > pwrite fd=4(<f>/data/mysql8023/data/ib_logfile0) size=512 pos=512` 
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 两个位置

     select  *  from  threads  where  THREAD_OS_ID  in (2665,2661) \G
  *************************** 1. row ***************************
            THREAD_ID: 27
                 NAME: thread/innodb/log_checkpointer_thread
                 TYPE: BACKGROUND
  
  ...
  
          THREAD_OS_ID: 2661
              RESOURCE_GROUP: SYS_default
  *************************** 2. row ***************************
            THREAD_ID: 31
                 NAME: thread/innodb/log_writer_thread
                 TYPE: BACKGROUND
  ...
               THREAD_OS_ID: 2665
            RESOURCE_GROUP: SYS_default
  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社区，对本文出炉给与的技术支持。

Enjoy GreatSQL 🙂

## 关于 GreatSQL

GreatSQL是由万里数据库维护的MySQL分支，专注于提升MGR可靠性及性能，支持InnoDB并行查询特性，是适用于金融级应用的MySQL分支版本。

相关链接： GreatSQL社区 Gitee GitHub Bilibili

GreatSQL社区：

欢迎来GreatSQL社区发帖提问
https://greatsql.cn/

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

技术交流群：

微信：扫码添加GreatSQL社区助手微信好友，发送验证信息加群。

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

  1.  ib_logfile和mysql_bin_MySQL的InnoDB引擎中事务日志ib_logfile0和ib_logfile1详解 ↩
  2. InnoDB redo log漫游 ↩
版权声明：程序员胖胖胖虎阿 发表于 2022年10月29日 下午6:24。
转载请注明：什么？MySQL 8.0 会同时修改两个ib_logfilesN 文件？ | 胖虎的工具箱-编程导航

相关文章

IntelliJ IDEA2022 激活码(Intellij IDEA专业版破解版激活破解教程)
程序员胖胖胖虎阿
355
经典的Java算法面试题
程序员胖胖胖虎阿
344
Linux安装与卸载软件
程序员胖胖胖虎阿
282
openSUSE 11.2 文泉中文字体安装
程序员胖胖胖虎阿
244
Maven的build生命周期和常用plugin
程序员胖胖胖虎阿
307
idea的2022.2破解方法(IntelliJ IDEA安装及激活码,全年更新)
程序员胖胖胖虎阿
193

暂无评论

暂无评论...
致力于称为最好的程序员导航网站

友链申请 免责声明 关于我们

Copyright © 2022  胖虎的工具箱-编程导航   陇ICP备2022001249号