- 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_logfile03 -rw-r----- 1 greatsql greatsql 134217728 7月 27 17:31 ib_logfile14 -rw-r----- 1 greatsql greatsql 134217728 8月 4 18:03 ib_logfile25 -rw-r----- 1 greatsql greatsql 134217728 8月 9 22:55 ib_logfile36 [#3#root@greatsql82 /data/mysql8023/data 22:55:45]3 stat ib_logfile07 文件："ib_logfile0"`8 大小：134217728 块：262144 IO 块：4096 一般文件9 设施：fd00h/64768d Inode：75740704 硬链接：110 权限：(0640/-rw-r-----) Uid：( 1000/ greatsql) Gid：( 1000/ greatsql)11 最近拜访：2022-08-04 19:22:32.746184752 +080012 最近更改：2022-08-09 22:55:40.166964294 +080013 最近改变：2022-08-09 22:55:40.166964294 +080014 创立工夫：-`15 [#4#root@greatsql82 /data/mysql8023/data 22:56:13]4 stat ib_logfile316 文件："ib_logfile3"17 大小：134217728 块：262144 IO 块：4096 一般文件18 设施：******* Inode：75740707 硬链接：119 权限：(0640/-rw-r-----) Uid：( 1000/ greatsql) Gid：( 1000/ greatsql)20 最近拜访：2022-08-04 19:22:48.510210526 +080021 最近更改：2022-08-09 22:55:39.741963331 +080022 最近改变：2022-08-09 22:55:39.741963331 +080023 创立工夫：-在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=FD003 `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=05 `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=1146887 `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=09 273996 01:02:18.534428831 1 mysqld (2617.3021) > pread fd=39(<f>/data/mysql8023/data/test/t.ibd) size=1024 pos=010 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=012 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=015 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=FD0016 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=6553621 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=1638423 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=13330176025 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=13330278427 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=27529 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=13330278431 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=13330278433 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=13330329635 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=13330329637 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/
技术交换群：
微信：扫码增加GreatSQL社区助手微信好友，发送验证信息加群。
- ib_logfile和mysql_bin_MySQL的InnoDB引擎中事务日志ib_logfile0和ib_logfile1详解 ↩
- InnoDB redo log漫游 ↩