关于mysql:什么MySQL-80-会同时修改两个iblogfilesN-文件

34次阅读

共计 9297 个字符，预计需要花费 24 分钟才能阅读完成。

  • 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/

技术交换群：

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

  1.  ib_logfile 和 mysql_bin_MySQL 的 InnoDB 引擎中事务日志 ib_logfile0 和 ib_logfile1 详解 ↩
  2. InnoDB redo log 漫游 ↩

正文完
mysql
发表至： mysql
2022-09-05
 0
关于sql:SQL-性能优化太太太太太太太有用了
关于mysql:万答3MGR最佳配置参考PFS里的监测指标要全开吗mysqld进程占用内存过高怎么排查
关于mysql:utf8改成utf8mb4实战教程
关于mysql:一文带你入门MySQL