Strace跟踪mysql运行过程
来自Linux78|wiki
Strace简介
strace是个功能强大的Linux调试分析诊断工具，可用于跟踪程序执行时进程系统调用(system call)和所接收的信号，尤其是针对源码不可读或源码无法再编译的程序。 使用strace的正确姿势：
strace -T -tt -o /tmp/strace.log CMD strace -T -tt CMD 2>&1 |tee /tmp/strace.log strace -T -tt -s 100 -o /tmp/strace.log CMD strace -T -tt -s 100 -ff -o /tmp/strace.log CMD #加ff强制strace主线程，如果跟踪mysql，则将CMD替换为/usr/local/mysqld strace -T -tt -s 100 -e trace=XXXX -o /tmp/strace.log CMD
root@:mysql_dev:~$strace -c ls > /dev/null % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000024 2 11 open 0.00 0.000000 0 10 read 0.00 0.000000 0 1 write 0.00 0.000000 0 14 close 0.00 0.000000 0 12 fstat 0.00 0.000000 0 28 mmap 0.00 0.000000 0 16 mprotect 0.00 0.000000 0 3 munmap 0.00 0.000000 0 3 brk 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 3 3 ioctl 0.00 0.000000 0 1 1 access 0.00 0.000000 0 1 execve 0.00 0.000000 0 1 fcntl 0.00 0.000000 0 2 getdents 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 1 statfs 0.00 0.000000 0 1 arch_prctl 0.00 0.000000 0 2 1 futex 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 1 openat 0.00 0.000000 0 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000024 117 5 total
跟踪MySQL启动时，依次读取my.cnf的顺序 首先查看mysqld命令行帮助信息，可以看到默认查找My.cnf的顺序：
[root@mysql-118 ~]# /opt/my4406/bin/mysqld --verbose --help|more ... ... Default options are read from the following files in the given order: /etc/my.cnf /etc/mysql/my.cnf /usr/local/Percona-Server-5.7.24-27-Linux.x86_64.ssl101/etc/my.cnf ~/.my.cnf
使用strace跟踪验证：strace /opt/my4406/bin/mysqld 2>&1|tee strace_1.log
[root@mysql-119 ~]# more strace_1.log|grep "my.cnf"
stat("/etc/my.cnf", 0x7ffcd22ba4e0) = -1 ENOENT (No such file or directory)
stat("/etc/mysql/my.cnf", 0x7ffcd22ba4e0) = -1 ENOENT (No such file or directory)
stat("/usr/local/Percona-Server-5.7.24-27-Linux.x86_64.ssl101/etc/my.cnf", 0x7ffcd22ba4e0) = -1 ENOENT (No such file or directory)
stat("/root/.my.cnf", 0x7ffcd22ba4e0) = -1 ENOENT (No such file or directory)
由于mysql8.0支持参数修改持久化，每次参数修改会保存到mysqld-auto.cnf，重启mysqld时最后都会读取该配置文件里面的内容覆盖掉前面的配置。所以starce可以看到mysql8多查找了一个配置文件：
[root@mysql-118 ~]# cat strace_mysql8.log|grep ".cnf"
stat("/etc/my.cnf", 0x7ffc58c1eaf0) = -1 ENOENT (No such file or directory)
stat("/etc/mysql/my.cnf", 0x7ffc58c1eaf0) = -1 ENOENT (No such file or directory)
stat("/usr/local/mysql/etc/my.cnf", 0x7ffc58c1eaf0) = -1 ENOENT (No such file or directory)
stat("/root/.my.cnf", 0x7ffc58c1eaf0) = -1 ENOENT (No such file or directory)
stat("data/mysqld-auto.cnf", 0x7ffc58c22620) = -1 ENOENT (No such file or directory)
为strace输出添加时间戳
[root@mysql-119 ~]# strace -T -tt -s 100 -o /tmp/strace_2.log /opt/my4406/bin/mysqld
08:02:42.959913 stat("/etc/my.cnf", 0x7ffdd3d6a1e0) = -1 ENOENT (No such file or directory) <0.000011>
08:02:42.960008 stat("/etc/mysql/my.cnf", 0x7ffdd3d6a1e0) = -1 ENOENT (No such file or directory) <0.000011>
08:02:42.960064 stat("/usr/local/Percona-Server-5.7.24-27-Linux.x86_64.ssl101/etc/my.cnf", 0x7ffdd3d6a1e0) = -1 ENOENT (No such file or directory) <0.000007>
08:02:42.960105 stat("/root/.my.cnf", 0x7ffdd3d6a1e0) = -1 ENOENT (No such file or directory) <0.000011>
MySQL默认启动的线程数 操作系统查看：ps -T pidof mysqld 无法看出每个线程具体是什么，不推荐使用。
利用pstack查看：pstack pidof mysql 不可直接在生产库执行，会导致mysql变的更慢，不推荐使用。
查询performance_schema.threads mysql5.7以上的版本，推荐使用此方法。可以详细的看出每个线程是什么线程
[root@mysql-119 ~]# mysql --socket=/opt/my4406/run/mysql.sock Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 509 Server version: 5.7.24-27-log Percona Server (GPL), Release 27, Revision bd42700 Copyright (c) 2009-2017 Percona LLC and/or its affiliates Copyright (c) 2000, 2017, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> select thread_id, name from performance_schema.threads ; +-----------+----------------------------------------+ | thread_id | name | +-----------+----------------------------------------+ | 1 | thread/sql/main | | 2 | thread/sql/thread_timer_notifier | | 3 | thread/innodb/io_ibuf_thread | | 4 | thread/innodb/io_log_thread | | 5 | thread/innodb/io_read_thread | | 6 | thread/innodb/io_read_thread | | 7 | thread/innodb/io_read_thread | | 8 | thread/innodb/io_read_thread | | 9 | thread/innodb/io_read_thread | | 10 | thread/innodb/io_read_thread | | 11 | thread/innodb/io_read_thread | | 12 | thread/innodb/io_read_thread | | 13 | thread/innodb/io_write_thread | | 14 | thread/innodb/io_write_thread | | 15 | thread/innodb/io_write_thread | | 16 | thread/innodb/io_write_thread | | 17 | thread/innodb/io_write_thread | | 18 | thread/innodb/io_write_thread | | 19 | thread/innodb/io_write_thread | | 20 | thread/innodb/io_write_thread | | 21 | thread/innodb/page_cleaner_thread | | 22 | thread/innodb/page_cleaner_thread | | 23 | thread/innodb/page_cleaner_thread | | 24 | thread/innodb/page_cleaner_thread | | 25 | thread/innodb/buf_lru_manager_thread | | 26 | thread/innodb/buf_lru_manager_thread | | 27 | thread/innodb/buf_lru_manager_thread | | 28 | thread/innodb/buf_lru_manager_thread | | 29 | thread/innodb/srv_monitor_thread | | 31 | thread/innodb/srv_lock_timeout_thread | | 32 | thread/innodb/srv_error_monitor_thread | | 33 | thread/innodb/srv_master_thread | | 34 | thread/innodb/srv_purge_thread | | 35 | thread/innodb/srv_worker_thread | | 36 | thread/innodb/srv_worker_thread | | 37 | thread/innodb/srv_worker_thread | | 38 | thread/innodb/buf_dump_thread | | 39 | thread/innodb/dict_stats_thread | | 40 | thread/sql/slave_io | | 41 | thread/sql/slave_sql | | 42 | thread/sql/slave_worker | | 43 | thread/sql/slave_worker | | 44 | thread/sql/slave_worker | | 45 | thread/sql/slave_worker | | 46 | thread/sql/signal_handler | | 47 | thread/sql/compress_gtid_table | | 549 | thread/sql/one_connection | +-----------+----------------------------------------+ 47 rows in set (0.00 sec)
去除重复：
mysql> select name,count(*) as cnt from performance_schema.threads group by name order by cnt ; +----------------------------------------+-----+ | name | cnt | +----------------------------------------+-----+ | thread/innodb/buf_dump_thread | 1 | | thread/sql/main | 1 | | thread/sql/slave_io | 1 | | thread/innodb/srv_lock_timeout_thread | 1 | | thread/innodb/io_ibuf_thread | 1 | | thread/innodb/srv_master_thread | 1 | | thread/sql/compress_gtid_table | 1 | | thread/innodb/dict_stats_thread | 1 | | thread/innodb/srv_monitor_thread | 1 | | thread/sql/thread_timer_notifier | 1 | | thread/sql/slave_sql | 1 | | thread/innodb/srv_error_monitor_thread | 1 | | thread/innodb/io_log_thread | 1 | | thread/sql/signal_handler | 1 | | thread/innodb/srv_purge_thread | 1 | | thread/sql/one_connection | 1 | | thread/innodb/srv_worker_thread | 3 | | thread/innodb/buf_lru_manager_thread | 4 | | thread/sql/slave_worker | 4 | | thread/innodb/page_cleaner_thread | 4 | | thread/innodb/io_read_thread | 8 | | thread/innodb/io_write_thread | 8 | +----------------------------------------+-----+ 22 rows in set (0.00 sec)
以上看到io_read_thread和io_write_thread都是8，可以查看和参数配置的线程数是否一致：
mysql> show variables like 'innodb_%io_threads'; +-------------------------+-------+ | Variable_name | Value | +-------------------------+-------+ | innodb_read_io_threads | 8 | | innodb_write_io_threads | 8 | +-------------------------+-------+ 2 rows in set (0.00 sec) page_cleaner_thread是4： mysql> show variables like 'innodb_page_cleaner%'; +----------------------+-------+ | Variable_name | Value | +----------------------+-------+ | innodb_page_cleaners | 4 | +----------------------+-------+ 1 row in set (0.00 sec) slave_worker是4: mysql> show variables like '%slave%worker%'; +------------------------+-------+ | Variable_name | Value | +------------------------+-------+ | slave_parallel_workers | 4 | +------------------------+-------+ 1 row in set (0.00 sec) conn_id和os_thread_id如何对应（mysql5.7以上）
通过sql关联查询：
mysql> select a.thd_id, a.conn_id, b.thread_os_id, b.name from sys.processlist a ,
-> performance_schema.threads b where a.thd_id =b.thread_id and
-> conn_id >0;
+--------+---------+--------------+--------------------------------+
| thd_id | conn_id | thread_os_id | name |
+--------+---------+--------------+--------------------------------+
| 40 | 1 | 23863 | thread/sql/slave_io |
| 41 | 2 | 23864 | thread/sql/slave_sql |
| 42 | 3 | 23865 | thread/sql/slave_worker |
| 43 | 4 | 23866 | thread/sql/slave_worker |
| 44 | 5 | 23867 | thread/sql/slave_worker |
| 45 | 6 | 23868 | thread/sql/slave_worker |
| 47 | 7 | 23870 | thread/sql/compress_gtid_table |
| 550 | 510 | 23933 | thread/sql/one_connection |
+--------+---------+--------------+--------------------------------+
8 rows in set (0.14 sec)
假如要跟踪一下one_connection这个连接进来都在做什么 另外开启一个OS命令窗口：
[root@mysql-119 ~]# strace -p 23933 strace: Process 23933 attached restart_syscall(<…
然后在当前sql命令行窗口执行一个命令：
mysql> show databases; +--------------------+ | Database | +--------------------+ | information_schema | | meta | | mgr1 | | mysql | | performance_schema | | sys | +--------------------+ 6 rows in set (0.00 sec)
OS命令行窗口即可看到执行show databases命令的一系列跟踪输出：
[root@mysql-119 ~]# strace -p 23933
strace: Process 23933 attached
restart_syscall(<... resuming interrupted poll ...>) = 1
recvfrom(53, "\17\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
recvfrom(53, "\3show databases", 15, MSG_DONTWAIT, NULL, NULL) = 15
openat(AT_FDCWD, "./", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 62
getdents(62, /* 26 entries */, 32768) = 872
stat("./client-cert.pem", {st_mode=S_IFREG|0644, st_size=1120, ...}) = 0
stat("./ca.pem", {st_mode=S_IFREG|0644, st_size=1120, ...}) = 0
stat("./tikv3.pid", {st_mode=S_IFREG|0640, st_size=6, ...}) = 0
stat("./ibtmp1", {st_mode=S_IFREG|0640, st_size=12582912, ...}) = 0
stat("./ib_logfile1", {st_mode=S_IFREG|0640, st_size=104857600, ...}) = 0
stat("./client-key.pem", {st_mode=S_IFREG|0600, st_size=1680, ...}) = 0
stat("./xb_doublewrite", {st_mode=S_IFREG|0640, st_size=15728640, ...}) = 0
stat("./private_key.pem", {st_mode=S_IFREG|0600, st_size=1680, ...}) = 0
stat("./auto.cnf", {st_mode=S_IFREG|0640, st_size=56, ...}) = 0
stat("./..", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("./mgr1", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
stat("./sys", {st_mode=S_IFDIR|0750, st_size=12288, ...}) = 0
stat("./mysql", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
stat("./.", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("./ib_logfile3", {st_mode=S_IFREG|0640, st_size=104857600, ...}) = 0
stat("./performance_schema", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
stat("./public_key.pem", {st_mode=S_IFREG|0644, st_size=452, ...}) = 0
stat("./ibdata1", {st_mode=S_IFREG|0640, st_size=12582912, ...}) = 0
stat("./ib_buffer_pool", {st_mode=S_IFREG|0640, st_size=528, ...}) = 0
stat("./mysql-119.pid", {st_mode=S_IFREG|0640, st_size=6, ...}) = 0
stat("./ib_logfile2", {st_mode=S_IFREG|0640, st_size=104857600, ...}) = 0
stat("./ib_logfile0", {st_mode=S_IFREG|0640, st_size=104857600, ...}) = 0
stat("./meta", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
stat("./ca-key.pem", {st_mode=S_IFREG|0600, st_size=1680, ...}) = 0
stat("./server-key.pem", {st_mode=S_IFREG|0600, st_size=1676, ...}) = 0
stat("./server-cert.pem", {st_mode=S_IFREG|0644, st_size=1120, ...}) = 0
getdents(62, /* 0 entries */, 32768) = 0
close(62) = 0
open("./mgr1/db.opt", O_RDONLY) = 62
getcwd("/data/my4406/data", 4096) = 18
lstat("/data/my4406/data/mgr1", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
lseek(62, 0, SEEK_CUR) = 0
lseek(62, 0, SEEK_END) = 67
lseek(62, 0, SEEK_SET) = 0
read(62, "default-character-set=utf8mb4\nde"..., 67) = 67
close(62) = 0
open("./mysql/db.opt", O_RDONLY) = 62
getcwd("/data/my4406/data", 4096) = 18
lstat("/data/my4406/data/mysql", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
lseek(62, 0, SEEK_CUR) = 0
lseek(62, 0, SEEK_END) = 65
lseek(62, 0, SEEK_SET) = 0
read(62, "default-character-set=latin1\ndef"..., 65) = 65
close(62) = 0
open("./performance_schema/db.opt", O_RDONLY) = 62
getcwd("/data/my4406/data", 4096) = 18
lstat("/data/my4406/data/performance_schema", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
lseek(62, 0, SEEK_CUR) = 0
lseek(62, 0, SEEK_END) = 61
lseek(62, 0, SEEK_SET) = 0
read(62, "default-character-set=utf8\ndefau"..., 61) = 61
close(62) = 0
madvise(0x7fb0ab709000, 73728, MADV_DONTNEED) = 0
madvise(0x7fb0ab732000, 16384, MADV_DONTNEED) = 0
madvise(0x7fb086006000, 1679360, MADV_DONTNEED) = 0
sendto(53, "\1\0\0\1\1K\0\0\2\3def\22information_schema"..., 177, MSG_DONTWAIT, NULL, 0) = 177
recvfrom(53, 0x7fb0ab488020, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=53, events=POLLIN|POLLPRI}], 1, 6000000
利用strace跟踪客户端sql执行 先到processlist中查询客户端的pid，然后到客户端上进行跟踪
mysql> select thd_id, conn_id,user, pid, -> program_name,command,current_statement from sys.processlist where -> conn_id>0 and pid>0; +--------+---------+-----------------------------+-------+--------------+---------+-------------------------------------------------------------------+ | thd_id | conn_id | user | pid | program_name | command | current_statement | +--------+---------+-----------------------------+-------+--------------+---------+-------------------------------------------------------------------+ | 551 | 511 | orchestrator@192.168.30.118 | 2270 | mysql | Sleep | NULL | | 550 | 510 | root@localhost | 10474 | mysql | Query | select thd_id, conn_id,user, p ... list where conn_id>0 and pid>0 | +--------+---------+-----------------------------+-------+--------------+---------+-------------------------------------------------------------------+ 2 rows in set (0.12 sec)
这里可以看到192.168.30.118的pid是2270，到118上执行strace：
[root@mysql-118 ~]# ps -ef|grep 2270
root 2270 31643 0 18:31 pts/0 00:00:00 mysql -uorchestrator -px xxxx -h192.168.30.119 -P4406
root 2288 2271 0 18:32 pts/2 00:00:00 grep --color=auto 2270
[root@mysql-118 ~]# strace -T -tt -s 100 -o /tmp/strace.log -p 2270
strace: Process 2270 attached
查看日志，就可以看到执行的细节及耗时：
[root@mysql-118 ~]# more /tmp/strace.log
18:33:09.883979 read(0, "\33", 1) = 1 <4.819426>
18:33:14.703966 read(0, "[", 1) = 1 <0.000021>
18:33:14.704162 read(0, "A", 1) = 1 <0.000017>
18:33:14.704385 write(1, "select 1;", 9) = 9 <0.000074>
18:33:14.704599 read(0, "\33", 1) = 1 <0.382839>
18:33:15.087885 read(0, "[", 1) = 1 <0.000102>
18:33:15.088450 read(0, "D", 1) = 1 <0.000026>
18:33:15.088585 write(1, "\10", 1) = 1 <0.000148>
18:33:15.088823 read(0, "\10", 1) = 1 <0.558707>
18:33:15.647761 write(1, "\10;\33[K\10", 6) = 6 <0.000045>
18:33:15.647906 read(0, "2", 1) = 1 <0.096305>
18:33:15.744375 write(1, "2;\10", 3) = 3 <0.000048>
18:33:15.744584 read(0, "\n", 1) = 1 <0.742984>
18:33:16.487718 write(1, "\n", 1) = 1 <0.000056>
18:33:16.487910 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0 <0.000022>
18:33:16.488088 rt_sigprocmask(SIG_BLOCK, [HUP INT QUIT TERM CONT TSTP WINCH], [], 8) = 0 <0.000015>
18:33:16.488252 rt_sigaction(SIGINT, {sa_handler=0x432aa0, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6caf4095e0}, NULL, 8) = 0 <0.000012>
18:33:16.488328 rt_sigaction(SIGTSTP, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, NULL, 8) = 0 <0.000011>
18:33:16.488385 rt_sigaction(SIGQUIT, {sa_handler=0x434c70, sa_mask=[QUIT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6caf4095e0}, NULL, 8) = 0 <0.000014>
18:33:16.488489 rt_sigaction(SIGHUP, {sa_handler=0x434f70, sa_mask=[HUP], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6caf4095e0}, NULL, 8) = 0 <0.000011>
18:33:16.488549 rt_sigaction(SIGTERM, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, NULL, 8) = 0 <0.000011>
18:33:16.488606 rt_sigaction(SIGCONT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, NULL, 8) = 0 <0.000012>
18:33:16.488663 rt_sigaction(SIGWINCH, {sa_handler=0x430db0, sa_mask=[WINCH], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f6caf4095e0}, NULL, 8) = 0 <0.000011>
18:33:16.488718 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000011>
18:33:16.488882 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 709457680 <0.000014>
18:33:16.488999 write(3, "\27\3\3\0%\221\276\366\215\360\223\177\231\200\5\311[s{b,z\317\312\335^\366\331[\34\310M\227W9\25\3\232n\257\267\260", 42) = 42 <0.000092>
18:33:16.489164 read(3, "\27\3\3\0I", 5) = 5 <0.000392>
18:33:16.489651 read(3, "\274\276V\213\302Y^e\367\311B:\3706\215\265\261\214\35\31at\345;\274\356\17\361{\277\335i\371\\Q\222\330\313\v\37<p\273\201\f\335\371\3461y_\317\342&
g\260\342\7W\3037\205&H\230_\32td\3416S\6", 73) = 73 <0.000019>
18:33:16.489780 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 709457680 <0.000023>
18:33:16.489917 write(1, "+---+\n", 6) = 6 <0.000045>
18:33:16.490033 write(1, "| 2 |\n", 6) = 6 <0.000021>
18:33:16.490108 write(1, "+---+\n", 6) = 6 <0.000032>
18:33:16.490195 write(1, "| 2 |\n", 6) = 6 <0.000021>
18:33:16.490265 write(1, "+---+\n", 6) = 6 <0.000036>
18:33:16.490450 write(1, "1 row in set (0.00 sec)\n", 24) = 24 <0.000041>
18:33:16.490596 write(1, "\n", 1) = 1 <0.000032>
18:33:16.490712 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=388, ...}) = 0 <0.000059>
18:33:16.490962 rt_sigprocmask(SIG_BLOCK, [HUP INT QUIT TERM CONT TSTP WINCH], [], 8) = 0 <0.000013>
18:33:16.491034 rt_sigaction(SIGINT, {sa_handler=0x4ca000, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, {sa_handler=0x432aa0, sa_mask=[INT], sa_flags=SA_RES
TORER|SA_RESTART, sa_restorer=0x7f6caf4095e0}, 8) = 0 <0.000011>
18:33:16.491166 rt_sigaction(SIGTSTP, {sa_handler=0x4ca000, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTOR
ER, sa_restorer=0x7f6caf4095e0}, 8) = 0 <0.000012>
18:33:16.491241 rt_sigaction(SIGQUIT, {sa_handler=0x4ca000, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, {sa_handler=0x434c70, sa_mask=[QUIT], sa_flags=SA_R
ESTORER|SA_RESTART, sa_restorer=0x7f6caf4095e0}, 8) = 0 <0.000011>
18:33:16.491327 rt_sigaction(SIGHUP, {sa_handler=0x4ca000, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, {sa_handler=0x434f70, sa_mask=[HUP], sa_flags=SA_RES
TORER|SA_RESTART, sa_restorer=0x7f6caf4095e0}, 8) = 0 <0.000012>
18:33:16.491415 rt_sigaction(SIGTERM, {sa_handler=0x4ca000, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTOR
ER, sa_restorer=0x7f6caf4095e0}, 8) = 0 <0.000013>
18:33:16.491488 rt_sigaction(SIGCONT, {sa_handler=0x4ca000, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTOR
ER, sa_restorer=0x7f6caf4095e0}, 8) = 0 <0.000011>
18:33:16.491549 rt_sigaction(SIGWINCH, {sa_handler=0x4ca000, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6caf4095e0}, {sa_handler=0x430db0, sa_mask=[WINCH], sa_flags=SA
_RESTORER|SA_RESTART, sa_restorer=0x7f6caf4095e0}, 8) = 0 <0.000010>
18:33:16.491610 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000011>
18:33:16.491666 rt_sigprocmask(SIG_BLOCK, [WINCH], [], 8) = 0 <0.000011>
18:33:16.491728 ioctl(0, TIOCGWINSZ, {ws_row=31, ws_col=174, ws_xpixel=0, ws_ypixel=0}) = 0 <0.000012>
18:33:16.491806 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000023>
18:33:16.491934 write(1, "mysql> ", 7) = 7 <0.000054>
18:33:16.492087 ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0 <0.000017>
18:33:16.492194 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig -icanon -echo ...}) = 0 <0.000030>
18:33:16.492341 read(0, <detached ...>
[root@mysql-118 ~]#
注意：针对线上环境比较繁忙的时候，如果直接strace可能会导致线上环境更慢，因此不建议直接在生产环境进行跟踪。 我们可以将某台出问题的客户端的线上流量导入到测试环境进行回放分析。
利用strace跟踪mysql server端的sql执行过程 首先找到连接线程的thread_os_id：23933
ysql> select a.thd_id, a.conn_id, b.thread_os_id, b.name from sys.processlist a , > performance_schema.threads b where a.thd_id =b.thread_id and > conn_id >0; ——–+———+————–+——————————–+ thd_id | conn_id | thread_os_id | name | ——–+———+————–+——————————–+ 40 | 1 | 23863 | thread/sql/slave_io | 41 | 2 | 23864 | thread/sql/slave_sql | 42 | 3 | 23865 | thread/sql/slave_worker | 43 | 4 | 23866 | thread/sql/slave_worker | 44 | 5 | 23867 | thread/sql/slave_worker | 45 | 6 | 23868 | thread/sql/slave_worker | 47 | 7 | 23870 | thread/sql/compress_gtid_table | 550 | 510 | 23933 | thread/sql/one_connection | ——–+———+————–+——————————–+ rows in set (0.14 sec)
然后跟踪该线程：strace -p 23933 然后输入SQL1：use mgr1; 跟踪输出：
[root@mysql-119 ~]# strace -p 23933
strace: Process 23933 attached
restart_syscall(<... resuming interrupted poll ...>
) = 1
recvfrom(53, "\22\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
recvfrom(53, "\3SELECT DATABASE()", 18, MSG_DONTWAIT, NULL, NULL) = 18
sendto(53, "\1\0\0\1\1 \0\0\2\3def\0\0\0\nDATABASE()\0\f!\0f"..., 57, MSG_DONTWAIT, NULL, 0) = 57
recvfrom(53, "\5\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
recvfrom(53, "\2mgr1", 5, MSG_DONTWAIT, NULL, NULL) = 5
access("./mgr1", F_OK) = 0
sendto(53, "\20\0\0\1\0\0\0\2@\0\0\0\7\1\5\4mgr1", 20, MSG_DONTWAIT, NULL, 0) = 20
recvfrom(53, "\17\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
recvfrom(53, "\3show databases", 15, MSG_DONTWAIT, NULL, NULL) = 15
openat(AT_FDCWD, "./", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 64
getdents(64, /* 26 entries */, 32768) = 872
stat("./client-cert.pem", {st_mode=S_IFREG|0644, st_size=1120, ...}) = 0
stat("./ca.pem", {st_mode=S_IFREG|0644, st_size=1120, ...}) = 0
stat("./tikv3.pid", {st_mode=S_IFREG|0640, st_size=6, ...}) = 0
stat("./ibtmp1", {st_mode=S_IFREG|0640, st_size=12582912, ...}) = 0
stat("./ib_logfile1", {st_mode=S_IFREG|0640, st_size=104857600, ...}) = 0
stat("./client-key.pem", {st_mode=S_IFREG|0600, st_size=1680, ...}) = 0
stat("./xb_doublewrite", {st_mode=S_IFREG|0640, st_size=15728640, ...}) = 0
stat("./private_key.pem", {st_mode=S_IFREG|0600, st_size=1680, ...}) = 0
stat("./auto.cnf", {st_mode=S_IFREG|0640, st_size=56, ...}) = 0
stat("./..", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("./mgr1", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
stat("./sys", {st_mode=S_IFDIR|0750, st_size=12288, ...}) = 0
stat("./mysql", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
stat("./.", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("./ib_logfile3", {st_mode=S_IFREG|0640, st_size=104857600, ...}) = 0
stat("./performance_schema", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
stat("./public_key.pem", {st_mode=S_IFREG|0644, st_size=452, ...}) = 0
stat("./ibdata1", {st_mode=S_IFREG|0640, st_size=12582912, ...}) = 0
stat("./ib_buffer_pool", {st_mode=S_IFREG|0640, st_size=528, ...}) = 0
stat("./mysql-119.pid", {st_mode=S_IFREG|0640, st_size=6, ...}) = 0
stat("./ib_logfile2", {st_mode=S_IFREG|0640, st_size=104857600, ...}) = 0
stat("./ib_logfile0", {st_mode=S_IFREG|0640, st_size=104857600, ...}) = 0
stat("./meta", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
stat("./ca-key.pem", {st_mode=S_IFREG|0600, st_size=1680, ...}) = 0
stat("./server-key.pem", {st_mode=S_IFREG|0600, st_size=1676, ...}) = 0
stat("./server-cert.pem", {st_mode=S_IFREG|0644, st_size=1120, ...}) = 0
getdents(64, /* 0 entries */, 32768) = 0
close(64) = 0
madvise(0x7fb0ab743000, 73728, MADV_DONTNEED) = 0
madvise(0x7fb08a006000, 1679360, MADV_DONTNEED) = 0
sendto(53, "\1\0\0\1\1K\0\0\2\3def\22information_schema"..., 177, MSG_DONTWAIT, NULL, 0) = 177
输入SQL2：show tables;跟踪输出：
recvfrom(53, "\f\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
recvfrom(53, "\3show tables", 12, MSG_DONTWAIT, NULL, NULL) = 12
openat(AT_FDCWD, "./mgr1/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 64
getdents(64, /* 5 entries */, 32768) = 144
getdents(64, /* 0 entries */, 32768) = 0
close(64) = 0
madvise(0x7fb0ab743000, 73728, MADV_DONTNEED) = 0
madvise(0x7fb08a006000, 1679360, MADV_DONTNEED) = 0
sendto(53, "\1\0\0\1\1V\0\0\2\3def\22information_schema"..., 113, MSG_DONTWAIT, NULL, 0) = 113
recvfrom(53, "\4\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
recvfrom(53, "\4t1\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
open("./mgr1/t1.frm", O_RDONLY) = 64
getcwd("/data/my4406/data", 4096) = 18
lstat("/data/my4406/data/mgr1", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
read(64, "\376\1\n\f\3\0\0\20\1\0\0000\0\0i\1\237\0\0\0\0\0\0\0\0\0\0\2!\0\t\0"..., 64) = 64
lseek(64, 64, SEEK_SET) = 64
read(64, "//\0\0 \0\0", 7) = 7
lseek(64, 8192, SEEK_SET) = 8192
read(64, "\252\1\0\20\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 288) = 288
lseek(64, 4096, SEEK_SET) = 4096
read(64, "\1\1\0\0\n\0\0\0\4\0\1\0\0\0\1\200\2\0\0\33@\4\0\377PRIMARY\377"..., 33) = 33
pread64(64, "\0\0\6\0InnoDB\0\0\0\0\0\0\f\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32, 4616) = 32
pread64(64, "\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 159, 4457) = 159
lseek(64, 8480, SEEK_SET) = 8480
read(64, "D\0\4\3\2\24) "..., 138) = 138
close(64) = 0
stat("./mgr1/t1.frm", {st_mode=S_IFREG|0640, st_size=8618, ...}) = 0
access("./mgr1/t1.TRG", F_OK) = -1 ENOENT (No such file or directory)
sendto(53, "$\0\0\1\3def\4mgr1\2t1\2t1\2id\2id\f?\0\v\0\0\0"..., 133, MSG_DONTWAIT, NULL, 0) = 133
recvfrom(53, 0x7fb0ab488020, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=53, events=POLLIN|POLLPRI}], 1, 6000000) = 1 ([{fd=53, revents=POLLIN}])
recvfrom(53, "\f\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
recvfrom(53, "\3show tables", 12, MSG_DONTWAIT, NULL, NULL) = 12
openat(AT_FDCWD, "./mgr1/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 64
getdents(64, /* 5 entries */, 32768) = 144
getdents(64, /* 0 entries */, 32768) = 0
close(64) = 0
madvise(0x7fb0ab743000, 73728, MADV_DONTNEED) = 0
madvise(0x7fb08a006000, 1679360, MADV_DONTNEED) = 0
sendto(53, "\1\0\0\1\1V\0\0\2\3def\22information_schema"..., 113, MSG_DONTWAIT, NULL, 0) = 113
输入SQL3：select * from t1;跟踪输出：
recvfrom(53, 0x7fb0ab488020, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=53, events=POLLIN|POLLPRI}], 1, 6000000) = 1 ([{fd=53, revents=POLLIN}])
recvfrom(53, "\21\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
recvfrom(53, "\3select * from t1", 17, MSG_DONTWAIT, NULL, NULL) = 17
open("./mgr1/t1.ibd", O_RDONLY) = 64
getcwd("/data/my4406/data", 4096) = 18
lstat("/data/my4406/data/mgr1", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
lseek(64, 0, SEEK_CUR) = 0
lseek(64, 0, SEEK_END) = 98304
lseek(64, 0, SEEK_SET) = 0
pread64(64, "\374\214\325\326\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0)\36\312\0\10\0\0\0\0\0\0"..., 16384, 0) = 16384
close(64) = 0
open("./mgr1/t1.ibd", O_RDWR) = 64
fcntl(64, F_SETFL, O_RDONLY|O_DIRECT) = 0
fcntl(64, F_SETLK, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
getcwd("/data/my4406/data", 4096) = 18
lstat("/data/my4406/data/mgr1", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
pread64(64, "\2554\2157\0\0\0\3\377\377\377\377\377\377\377\377\0\0\0\0\0)\36\312E\277\0\0\0\0\0\0"..., 16384, 49152) = 16384
pread64(64, "\3408`m\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0)\21\331\0\5\0\0\0\0\0\0"..., 16384, 16384) = 16384
sendto(53, "\1\0\0\1\3\"\0\0\2\3def\4mgr1\2t1\2t1\2id\2id\f?"..., 161, MSG_DONTWAIT, NULL, 0) = 161
recvfrom(53, 0x7fb0ab488020, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=53, events=POLLIN|POLLPRI}], 1, 6000000^Cstrace: Process 23933 detached
<detached ...>
以上strace的输出中，可以看到： 输入SQL1时，出现多次recvfrom(53和sendto(53： recvfrom(53, “\3SELECT DATABASE()”, 18, MSG_DONTWAIT, NULL, NULL) = 18 sendto(53, “\1\0\0\1\1 \0\0\2\3def\0\0\0\nDATABASE()\0\f!\0f”…, 57, MSG_DONTWAIT, NULL, 0) = 57 查看proc下面的连接符软连接： [root@mysql-119 ~]# ls -lrt /proc/23933/fd/53 lrwx—— 1 root root 64 3月 18 09:30 /proc/23933/fd/53 -> socket:[4524969] 可以看到这个53就是我们这次执行SQL命令的连接会话（即mysql -u -p -h -P…创建的socket连接）。 从这个53的socket连接接受指令，并向53返回结果，不断进行交互。
输入SQL2时，可以看到从t1.frm中读取数据字典信息，获取表结构：
open(“./mgr1/t1.frm”, O_RDONLY) = 64
getcwd(“/data/my4406/data”, 4096) = 18
lstat(“/data/my4406/data/mgr1”, {st_mode=S_IFDIR|0750, st_size=4096, …}) = 0
如果是mysql8.0，将会看到是从mysql.ibd中读取数据字典。
read(64, “\376\1\n\f\3\0\0\20\1\0\0000\0\0i\1\237\0\0\0\0\0\0\0\0\0\0\2!\0\t\0”…, 64) = 64 lseek(64, 64, SEEK_SET) = 64 read(64, “//\0\0 \0\0”, 7) = 7
然后出现多次read(64, 和lseek(64，可以看到，64对应的是t1表：
[root@mysql-119 ~]# ls -lrt /proc/23933/fd/64 lrwx—— 1 root root 64 3月 18 11:32 /proc/23933/fd/64 -> /data/my4406/data/mgr1/t1.ibd
输入SQL3时，可以看到打开数据文件：open(“./mgr1/t1.ibd”, O_RDONLY) 然后读取64表的数据，返回给53连接。
利用strace跟踪IO情况
[root@mysql-119 ~]# strace -T -tt -f -e trace=read,open,write,pwrite64,pread64 -o /tmp/strace1.log -p pidof mysqld strace: Process 23821 attached with 67 threads
执行SQL：mysql> insert into t1 values(5,’e’,’ee’);
Query OK, 1 row affected (0.00 sec)
查看跟踪输出：
[root@mysql-119 ~]# vi /tmp/strace1.log
23933 12:20:03.636326 pwrite64(10, "\200\6\177\371\2\0\0\227\0\4,\235\214\0\36\0\201U\0\220\0\200MySQLXid\2469"..., 1536, 5792768 <unfinished ...>
23859 12:20:03.636505 pread64(64, <unfinished ...>
23933 12:20:03.636545 <... pwrite64 resumed> ) = 1536 <0.000047>
23933 12:20:03.636614 write(28, "s\34\217\\!\2469\22\0A\0\0\0$\201\354\v\0\0\0{\215\1\356\10\35\21\351\224\241\0P"..., 321) = 321 <0.000023>
23859 12:20:03.642756 <... pread64 resumed> "\334\211\260b\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0)\36\312\0\3\0\0\0\0\0\0"..., 16384, 32768) = 16384 <0.006230>
23859 12:20:03.643204 pwrite64(10, "\200\6\177\373\2\0\0$\0\4,\235\20eee7!\0\0\16./mgr1/t1.i"..., 1024, 5793792) = 1024 <0.000027>
23859 12:20:03.643559 pwrite64(10, "\200\6\177\374\2\0\0^\0\4,\2352\201\212\2\0\200\350\0006\234q\4\0\200\350\0008\201\212\2"..., 1536, 5794304) = 1536 <0.000084>
23841 12:20:04.717848 pwrite64(13, "\212\2635\354\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\f\377\363\315\0\10\0\0\0\0\0G"..., 49152, 1966080) = 49152 <0.000259>
23841 12:20:04.719229 pwrite64(13, "\177\377\23\260\0\0\1V\0\0\0\0\0\0\0\0\0\0\0\0\f\377\364\341\0\2\0\0\0\0\0\0"..., 49152, 5898240) = 49152 <0.000168>
23841 12:20:04.720440 pwrite64(13, "\3434b\313\0\0\1\212\0\0\0\0\0\0\0\0\0\0\0\0\f\377\366^\0\2\0\0\0\0\0\0"..., 49152, 9830400) = 49152 <0.000166>
23841 12:20:04.721697 pwrite64(13, "\256:9\22\0\0\0\347\0\0\0\0\0\0\0\0\0\0\0\0\f\377\363\315\0\6\0\0\0\0\0\0"..., 49152, 13762560) = 49152 <0.000143>
23853 12:20:05.522421 pwrite64(10, "\200\6\177\376\0\270\0S\0\4,\235\4\0\200\351\0008\201\260\2\0\200\351\0<\213\252\4\0\201\260"..., 512, 5795328) = 512 <0.000036>
23853 12:20:06.523494 pwrite64(10, "\200\6\177\376\0\301\0S\0\4,\236\4\0\200\351\0008\201\260\2\0\200\351\0<\213\252\4\0\201\260"..., 512, 5795328) = 512 <0.000117>
看下fd对应的具体文件：
[root@mysql-119 ~]# ls -lrt /proc/23933/fd/10 lrwx------ 1 root root 64 3月 18 11:32 /proc/23933/fd/10 -> /data/my4406/data/ib_logfile2 [root@mysql-119 ~]# ls -lrt /proc/23933/fd/64 lrwx------ 1 root root 64 3月 18 11:32 /proc/23933/fd/64 -> /data/my4406/data/mgr1/t1.ibd [root@mysql-119 ~]# ls -lrt /proc/23933/fd/28 l-wx------ 1 root root 64 3月 18 11:32 /proc/23933/fd/28 -> /data/my4406/log/mysql-bin.000002 [root@mysql-119 ~]# ls -lrt /proc/23933/fd/13 lrwx------ 1 root root 64 3月 18 11:32 /proc/23933/fd/13 -> /data/my4406/data/xb_doublewrite
可以看到先写10是redo，再写28是binlog，最后写undo。 mysql8.0上执行：insert into a values(4,’aba’); 跟踪结果：
[root@mysql-118 ~]# strace -T -tt -f -e trace=read,open,write,pwrite64,pread64 -p 2022 strace: Process 2022 attached with 39 threads [pid 2053] 20:17:43.030704 pread64(38, ";\200\232\230\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\1\"\362\210\0\3\0\0\0\0\0\0"..., 16384, 32768) = 16384 <0.000127> [pid 2041] 20:17:43.121801 pwrite64(10, "\200\1\276\366\2\0\0009\0\0\0\337\357\201\3\0\0\1\223\r\2\360\377\377\377\357\201\3\0(\201\20"..., 1024, 8247808) = 1024 <0.000118> [pid 2041] 20:17:43.122215 pwrite64(10, "\200\1\276\370\0009\0009\0\0\0\337\357\201;\0x\201;\2\360\377\377\377\357\201;\0|\206\30\4"..., 512, 8248832) = 512 <0.000078> [pid 2089] 20:17:43.124133 write(30, "g\214\217\\\"\1\0\0\0K\0\0\0\4\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 286) = 286 <0.000126> [pid 2053] 20:17:43.124885 pread64(13, "\223\t\373(\0\0\0\0\0\0018\215\0\0\0\1\0\0\0\0\3}V\241\0\10\0\0\0\0\0\0"..., 16384, 0) = 16384 <0.000253> [pid 2053] 20:17:43.125520 pread64(13, "S\325~,\0\0\1\4\0\0\0\0\0\0\0\0\0\0\0\0\3}V\241\0\3\0\0\0\0\0\0"..., 16384, 4259840) = 16384 <0.000133> [pid 2053] 20:17:43.125978 pread64(13, <unfinished ...> [pid 2041] 20:17:43.126046 pwrite64(10, "\200\1\276\370\0L\0009\0\0\0\337\357\201;\0x\201;\2\360\377\377\377\357\201;\0|\206\30\4"..., 512, 8248832) = 512 <0.000199> [pid 2053] 20:17:43.126417 <... pread64 resumed> "\244\17\203\316\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0q$\0\5\0\0\0\0\0\0"..., 16384, 16384) = 16384 <0.000404> [pid 2041] 20:17:43.127282 pwrite64(10, "\200\1\276\370\2\0\0009\0\0\0\337\357\201;\0x\201;\2\360\377\377\377\357\201;\0|\206\30\4"..., 2048, 8248832) = 2048 <0.000348> [pid 2041] 20:17:43.127802 pwrite64(10, "\200\1\276\374\0\261\0.\0\0\0\337\200\7\200\4\200\10\0\10\377\377\0\4\2\0\0\0014\2\313\0"..., 512, 8250880) = 512 <0.000156> [pid 2037] 20:17:44.775978 pwrite64(9, "\305y\250F\0\0\1\5\0\0\0\0\0\0\0\0\0\0\0\0\3}\356L\0\2\0\0\0\0\0\0"..., 180224, 1048576) = 180224 <0.000385> [pid 2039] 20:17:44.789352 pwrite64(4, "\0\0\0\0\0\0\0\337\0\0\0\0\3}\366\261\0\0\0\0\3}\346\261\0\0\0\0\1\0\0\0"..., 512, 1536) = 512 <0.000146>
依次是：pread64(38–pwrite64(10–write(30–pread64(13–pwrite64(9–pwrite64(4 写数据之前先读取buffer pool看是否存在该数据，如果没在，则进行写入： 先写redo[pwrite64(10]、再写binlog[write(30]、再写undo[pwrite64(9,将binlog的filename和position写进ibdata] 每个fd对应的文件：
[root@mysql-118 ~]# ls -lrt /proc/2022/fd/38 lrwx—— 1 root root 64 3月 18 20:19 /proc/2022/fd/38 -> /data/mysql/data/testdb/a.ibd [root@mysql-118 ~]# ls -lrt /proc/2022/fd/10 lrwx—— 1 root root 64 3月 18 20:19 /proc/2022/fd/10 -> /data/mysql/data/ib_logfile1 [root@mysql-118 ~]# ls -lrt /proc/2022/fd/30 l-wx—— 1 root root 64 3月 18 20:22 /proc/2022/fd/30 -> /data/mysql/data/binlog.000004 [root@mysql-118 ~]# ls -lrt /proc/2022/fd/13 lrwx—— 1 root root 64 3月 18 20:22 /proc/2022/fd/13 -> /data/mysql/data/undo_002 [root@mysql-118 ~]# ls -lrt /proc/2022/fd/9 lrwx—— 1 root root 64 3月 18 20:22 /proc/2022/fd/9 -> /data/mysql/data/ibdata1 [root@mysql-118 ~]# ls -lrt /proc/2022/fd/4 lrwx—— 1 root root 64 3月 18 20:22 /proc/2022/fd/4 -> /data/mysql/data/ib_logfile0
