什么？MySQL 8.0 會同時修改兩個ib_logfilesN 檔案？-有解無憂

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=https://www.cnblogs.com/greatsql/archive/2022/09/05/:.........8..........eKq.............................@..@!......................
11    273998 01:02:18.534449603 1 mysqld (2617.3021) > pread fd=39(/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(/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(/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(/data/mysql8023/data/test/t.ibd) cmd=5(F_SETFL)
17    274005 01:02:18.534510349 1 mysqld (2617.3021) < fcntl res=0(/dev/null)
18    274006 01:02:18.534511842 1 mysqld (2617.3021) > fcntl fd=39(/data/mysql8023/data/test/t.ibd) cmd=8(F_SETLK)
19    274007 01:02:18.534518620 1 mysqld (2617.3021) < fcntl res=0(/dev/null)
20    274012 01:02:18.534537370 1 mysqld (2617.3021) > pread fd=39(/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(/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(/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=https://www.cnblogs.com/greatsql/archive/2022/09/05/.....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=https://www.cnblogs.com/greatsql/archive/2022/09/05/...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=https://www.cnblogs.com/greatsql/archive/2022/09/05/.....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=https://www.cnblogs.com/greatsql/archive/2022/09/05/.......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=https://www.cnblogs.com/greatsql/archive/2022/09/05/..........".......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=https://www.cnblogs.com/greatsql/archive/2022/09/05/..........".......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=https://www.cnblogs.com/greatsql/archive/2022/09/05/.....(....".......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=https://www.cnblogs.com/greatsql/archive/2022/09/05/.E..................?..(........................................................
42    302247 01:02:19.924998103 0 mysqld (2617.2661) > pwrite fd=4(/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社區

技術交流群：

微信：掃碼添加GreatSQL社區助手微信好友，發送驗證資訊加群，

ib_logfile和mysql_bin_MySQL的InnoDB引擎中事務日志ib_logfile0和ib_logfile1詳解 ??
InnoDB redo log漫游 ??

轉載請註明出處，本文鏈接：https://www.uj5u.com/shujuku/503632.html

標籤：其他

上一篇：什么？MySQL 8.0 會同時修改兩個ib_logfilesN 檔案？

下一篇：如何在javascript中轉換日期