strace 命令分析mysql的相關的問題

strace 命令分析mysql的相關的問題

使用方式： strace -p pid or strace command

本篇博文主要簡單介紹下面關於MySQL的5個問題：

利用strace觀察mysqld對my.cnf 配置文件的加載順序
MySQL啓動後默認會啓動多少線程
如何匹配conn_id和os_thread_id
利用strace觀察client的SQL執行
利用strace觀察server端執行

1.strace觀察mysqld對my.cnf 配置文件的加載順序

命令以下：

strace -T -tt -s 100 -o start.log /usr/local/mysql/bin/mysqld

[root@mgr04 ~]#  cat -n start.log |sed -n '152,165p'
   152  03:43:41.399411 futex(0x7fb060f058b8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000013>
   153  03:43:41.400839 stat("/etc/my.cnf", {st_mode=S_IFREG|0644, st_size=11064, ...}) = 0 <0.000015>
   154  03:43:41.400951 open("/etc/my.cnf", O_RDONLY) = 3 <0.000024>
   155  03:43:41.401026 fstat(3, {st_mode=S_IFREG|0644, st_size=11064, ...}) = 0 <0.000009>
   156  03:43:41.401068 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb061d94000 <0.000016>
   157  03:43:41.401116 read(3, "[client]\nport            = 3306\n\n[mysql]\nauto-rehash\nprompt=\"\\\\u@\\\\h [\\\\d]>\"\n#pager=\"less -i -n -S\"\n"..., 4096) = 4096 <0.000016>
   158  03:43:41.401211 read(3, " #    0\n#rpl_semi_sync_master_timeout        =1000                          #    1000(1 second)\n#plu"..., 4096) = 4096 <0.000011>
   159  03:43:41.401303 read(3, "       #\ton\ninnodb_change_buffering                         =all                        #\tall\ninnodb"..., 4096) = 2872 <0.000011>
   160  03:43:41.401376 read(3, "", 4096)       = 0 <0.000010>
   161  03:43:41.401423 close(3)                = 0 <0.000052>
   162  03:43:41.401564 munmap(0x7fb061d94000, 4096) = 0 <0.000080>
   163  03:43:41.401777 stat("/etc/mysql/my.cnf", 0x7fff5ec1c170) = -1 ENOENT (No such file or directory) <0.000022>
   164  03:43:41.402070 stat("/usr/local/mysql/etc/my.cnf", 0x7fff5ec1c170) = -1 ENOENT (No such file or directory) <0.000016>
   165  03:43:41.402134 stat("/root/.my.cnf", 0x7fff5ec1c170) = -1 ENOENT (No such file or directory) <0.000012>

2. 查看mysql啓動的線程數

操做系統查看：
ps -T pidof mysqld

[root@mgr04 opt]# ps -T `pidof mysqld`|sed '1d'
 59592  59592 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59593 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59594 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59595 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59596 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59597 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59598 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59599 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59600 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59601 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59602 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59603 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59604 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59607 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59608 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59609 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59610 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59611 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59612 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59613 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59614 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59615 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59616 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59617 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59618 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59619 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld
 59592  59620 pts/0    Sl     0:00 /usr/local/mysql/bin/mysqld

利用pstack

pstack `pidof mysql`  或者pstack `pidof mysqld` 2>&1|tee  /tmp/pstack.log

下面的這個過程特別的慢。會致使mysql夯築，不要線上直接使用
MySQL默認的啓動線程數是28

推薦MySQL 5.7以上的版本查看mysql默認啓動的線程數爲28個

select thread_id, name from performance_schema.threads;

select name,count(*) from  performance_schema.threads group by name;

root@localhost [(none)]>select name,count(*) from  performance_schema.threads group by name;
+----------------------------------------+----------+
| name                                   | count(*) |
+----------------------------------------+----------+
| thread/innodb/buf_dump_thread          |        1 |
| thread/innodb/dict_stats_thread        |        1 |
| thread/innodb/io_ibuf_thread           |        1 |
| thread/innodb/io_log_thread            |        1 |
| thread/innodb/io_read_thread           |        4 |
| thread/innodb/io_write_thread          |        4 |
| thread/innodb/page_cleaner_thread      |        1 |
| thread/innodb/srv_error_monitor_thread |        1 |
| thread/innodb/srv_lock_timeout_thread  |        1 |
| thread/innodb/srv_master_thread        |        1 |
| thread/innodb/srv_monitor_thread       |        1 |
| thread/innodb/srv_purge_thread         |        1 |
| thread/innodb/srv_worker_thread        |        3 |
| thread/sql/compress_gtid_table         |        1 |
| thread/sql/main                        |        1 |
| thread/sql/one_connection              |        1 |
| thread/sql/signal_handler              |        1 |
| thread/sql/thread_timer_notifier       |        1 |
+----------------------------------------+----------+
18 rows in set (0.00 sec)

root@localhost [(none)]>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_read_thread           |
|         5 | thread/innodb/io_read_thread           |
|         6 | thread/innodb/io_read_thread           |
|         7 | thread/innodb/io_read_thread           |
|         8 | thread/innodb/io_log_thread            |
|         9 | thread/innodb/io_write_thread          |
|        10 | thread/innodb/io_write_thread          |
|        11 | thread/innodb/io_write_thread          |
|        12 | thread/innodb/io_write_thread          |
|        13 | thread/innodb/page_cleaner_thread      |
|        16 | thread/innodb/srv_lock_timeout_thread  |
|        17 | thread/innodb/srv_error_monitor_thread |
|        18 | thread/innodb/srv_monitor_thread       |
|        19 | thread/innodb/srv_master_thread        |
|        20 | thread/innodb/srv_purge_thread         |
|        21 | thread/innodb/srv_worker_thread        |
|        22 | thread/innodb/srv_worker_thread        |
|        23 | thread/innodb/srv_worker_thread        |
|        24 | thread/innodb/buf_dump_thread          |
|        25 | thread/innodb/dict_stats_thread        |
|        26 | thread/sql/signal_handler              |
|        27 | thread/sql/compress_gtid_table         |
|        29 | thread/sql/one_connection              |
+-----------+----------------------------------------+
26 rows in set (0.00 sec)

如何匹配conn_id和os_thread_id

MySQL 5.6時代採用的方法：

gdb attach  11646
strace -T -tt -s 100 -p11646

MySQL 5.7 & 8.0時代採用的方法：

能夠利用sys.processlist 和performance_schema.threads進行關聯

select thd_id, conn_id, thread_os_id, name from sys.processlist a ,performance_schema.threads b where a.thd_id =b.thread_id and conn_id >0;

查詢報錯：

root@localhost [sys]>select thd_id, conn_id, thread_os_id, name from sys.processlist a , performance_schema.threads b where a.thd_id =b.thread_id and conn_id >0;
ERROR 1104 (42000): The SELECT would examine more than MAX_JOIN_SIZE rows; check your WHERE and use SET SQL_BIG_SELECTS=1 or SET MAX_JOIN_SIZE=# if the SELECT is okay

解決辦法:

root@localhost [sys]>
root@localhost [sys]>SET SQL_BIG_SELECTS=1 ;
Query OK, 0 rows affected (0.00 sec)

root@localhost [sys]>select thd_id, conn_id, thread_os_id, 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                           |
+--------+---------+--------------+--------------------------------+
|     26 |       1 |        13068 | thread/sql/compress_gtid_table |
|     27 |       2 |        13071 | thread/sql/one_connection      |
+--------+---------+--------------+--------------------------------+
2 rows in set (0.07 sec)
root@localhost [sys]>

strace追蹤當前鏈接的線程ID，來查看對系統os的操做

strace -T -tt -e trace=write,access,read,open,pwrite64,pread64 -p 13071 2>&1 |tee >/tmp/strace.log

演示：
數據庫操做：

show databases；
use test01;
use tets02;
create table tutorials_tbl(
tutorial_id INT NOT NULL AUTO_INCREMENT,
 tutorial_title VARCHAR(100) NOT NULL,
 tutorial_author VARCHAR(40) NOT NULL,
submission_date DATE,
PRIMARY KEY ( tutorial_id )
 );;
insert into tutorials_tbl(tutorial_id,tutorial_title,tutorial_author,submission_date) values('1','做文','三毛','2019-03-10');
select * from tutorials_tbl;

利用strace觀察client端SQL執行，也就是跟蹤進程輸出：

strace -T -tt -e trace=recvfrom,write,access,read,open,pwrite64,pread64 -p 13071

[root@mgr04 ~]# strace -T -tt -e trace=recvfrom,write,access,read,open,pwrite64,pread64 -p 13071
strace: Process 13071 attached

06:05:20.074087 recvfrom(59, "\22\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000138>
06:05:20.074539 recvfrom(59, "\3SELECT DATABASE()", 18, MSG_DONTWAIT, NULL, NULL) = 18 <0.000119>
06:05:20.074891 write(35, "2019-03-17T06:05:20.074757+08:00"..., 63) = 63 <0.000345>
06:05:20.075510 recvfrom(59, "\7\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000097>
06:05:20.075749 recvfrom(59, "\2test01", 7, MSG_DONTWAIT, NULL, NULL) = 7 <0.000109>
06:05:20.076098 access("./test01", F_OK) = 0 <0.000102>
06:05:20.076372 write(35, "2019-03-17T06:05:20.076273+08:00"..., 54) = 54 <0.000115>
06:05:20.076877 recvfrom(59, 0x7f2e48007990, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000217>
06:05:46.672935 recvfrom(59, "\17\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000117>
06:05:46.673241 recvfrom(59, "\3show databases", 15, MSG_DONTWAIT, NULL, NULL) = 15 <0.000099>
06:05:46.673547 write(35, "2019-03-17T06:05:46.673430+08:00"..., 60) = 60 <0.000189>
06:05:46.675841 recvfrom(59, 0x7f2e48007990, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000117>
06:06:05.768163 recvfrom(59, "\22\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000260>
06:06:05.768871 recvfrom(59, "\3SELECT DATABASE()", 18, MSG_DONTWAIT, NULL, NULL) = 18 <0.000376>
06:06:05.769551 write(35, "2019-03-17T06:06:05.769412+08:00"..., 63) = 63 <0.000137>
06:06:05.770088 recvfrom(59, "\7\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000130>
06:06:05.770362 recvfrom(59, "\2test02", 7, MSG_DONTWAIT, NULL, NULL) = 7 <0.000096>
06:06:05.770599 access("./test02", F_OK) = 0 <0.000114>
06:06:05.770882 write(35, "2019-03-17T06:06:05.770766+08:00"..., 54) = 54 <0.000191>
06:06:05.772482 recvfrom(59, "\17\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000167>
06:06:05.772843 recvfrom(59, "\3show databases", 15, MSG_DONTWAIT, NULL, NULL) = 15 <0.000095>
06:06:05.773231 write(35, "2019-03-17T06:06:05.773085+08:00"..., 60) = 60 <0.000115>
06:06:05.775112 recvfrom(59, "\f\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000274>
06:06:05.775585 recvfrom(59, "\3show tables", 12, MSG_DONTWAIT, NULL, NULL) = 12 <0.000100>
06:06:05.775908 write(35, "2019-03-17T06:06:05.775782+08:00"..., 57) = 57 <0.000290>
06:06:05.776987 recvfrom(59, 0x7f2e48007990, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000198>
06:07:14.887093 recvfrom(59, "\324\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000016>
06:07:14.887219 recvfrom(59, "\3create table tutorials_tbl(\n   "..., 212, MSG_DONTWAIT, NULL, NULL) = 212 <0.000016>
06:07:14.887395 write(35, "2019-03-17T06:07:14.887364+08:00"..., 257) = 257 <0.000050>
06:07:14.887562 access("./test02/tutorials_tbl.frm", F_OK) = -1 ENOENT (No such file or directory) <0.000306>
06:07:14.888180 access("./test02/tutorials_tbl.frm", F_OK) = -1 ENOENT (No such file or directory) <0.000144>
06:07:14.888411 open("./test02/tutorials_tbl.frm", O_RDWR|O_CREAT|O_TRUNC, 0640) = 83 <0.000877>
06:07:14.889915 write(83, "\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\0"..., 4096) = 4096 <0.000226>
06:07:14.890372 write(83, "//\0", 3)    = 3 <0.000135>
06:07:14.890799 write(83, "\0 \0\0", 4) = 4 <0.000024>
06:07:14.890906 write(83, "\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\0"..., 4096) = 4096 <0.000035>
06:07:14.890993 pwrite64(83, "\376\1\n\f\3\0\0\20\1\0\0000\0\0i\1\257\1\0\0\0\0\0\0\0\0\0\2!\0\t\0"..., 64, 0) = 64 <0.000020>
06:07:14.891073 pwrite64(83, "\1\1\0\0\n\0\0\0\4\0\1\0\0\0\1\200\2\0\0\33\0\4\0\377PRIMARY\377"..., 33, 4096) = 33 <0.000019>
06:07:14.891183 write(83, "\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"..., 431) = 431 <0.000020>
06:07:14.891448 write(83, "\0\0", 2)    = 2 <0.000028>
06:07:14.891732 write(83, "\6\0", 2)    = 2 <0.000023>
06:07:14.891814 write(83, "InnoDB", 6)  = 6 <0.000019>
06:07:14.891881 write(83, "\0\0\0\0\0\0", 6) = 6 <0.000018>
06:07:14.891948 write(83, "\r\0\0\0\0\0\0\0\0\0\0\0\0", 13) = 13 <0.000018>
06:07:14.892015 write(83, "\0\0", 2)    = 2 <0.000019>
06:07:14.892078 write(83, "\0\0", 2)    = 2 <0.000205>
06:07:14.892358 write(83, "\30\2\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 <0.000039>
06:07:14.892453 write(83, "w\0\5\4\2\24)                         "..., 119) = 119 <0.000023>
06:07:14.892526 write(83, "\4\f\v\v\0\2\0\0\33\0\17\0\0\3!\0\0", 17) = 17 <0.000281>
06:07:14.892864 write(83, "\5\17,,\1\6\0\0\0@\0\0\0\17!\0\0", 17) = 17 <0.000027>
06:07:14.892949 write(83, "\6\20?x\0004\1\0\0@\0\0\0\17!\0\0", 17) = 17 <0.000022>
06:07:14.893021 write(83, "\7\20\n\n\0\255\1\0p\200\0\0\0\16\10\0\0", 17) = 17 <0.000022>
06:07:14.893093 write(83, "\377", 1)    = 1 <0.000021>
06:07:14.893162 write(83, "tutorial_id\377", 12) = 12 <0.000188>
06:07:14.893407 write(83, "tutorial_title\377", 15) = 15 <0.000027>
06:07:14.893491 write(83, "tutorial_author\377", 16) = 16 <0.000021>
06:07:14.893559 write(83, "submission_date\377\0", 17) = 17 <0.000376>
06:07:14.911739 open("./test02/", O_RDONLY) = 84 <0.000037>
06:07:14.912031 open("./test02/tutorials_tbl.frm", O_RDONLY) = 83 <0.000026>
06:07:14.912188 read(83, "\376\1\n\f\3\0\0\20\1\0\0000\0\0i\1\257\1\0\0\0\0\0\0\0\0\0\2!\0\t\0"..., 64) = 64 <0.000036>
06:07:14.912772 read(83, "//\0\0 \0\0", 7) = 7 <0.000227>
06:07:14.913170 read(83, "\30\2\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 <0.000018>
06:07:14.913272 read(83, "\1\1\0\0\n\0\0\0\4\0\1\0\0\0\1\200\2\0\0\33\0\4\0\377PRIMARY\377"..., 33) = 33 <0.000015>
06:07:14.913485 pread64(83, "\0\0\6\0InnoDB\0\0\0\0\0\0\r\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 33, 4888) = 33 <0.000019>
06:07:14.913579 pread64(83, "\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"..., 431, 4457) = 431 <0.000252>
06:07:14.914061 read(83, "w\0\5\4\2\24)                         "..., 248) = 248 <0.000137>
06:07:14.914505 open("./test02/tutorials_tbl.ibd", O_RDWR|O_CREAT|O_EXCL, 0640) = 83 <0.000603>
06:07:14.915312 pwrite64(83, "\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\0"..., 65536, 0) = 65536 <0.000124>
06:07:14.925026 pwrite64(83, "\315\331\225\240\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"..., 16384, 0) = 16384 <0.000227>
06:07:14.929051 open("./test02/tutorials_tbl.ibd", O_RDWR) = 83 <0.000251>
06:07:14.929985 pwrite64(83, "\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\0"..., 32768, 65536) = 32768 <0.000175>
06:07:14.932909 pwrite64(4, "\200\0\24\211\2\0\0A\0\0\0^)\242\0\0\1\25\1A\\\215q\213\0\0\0\0\0\0\0\1"..., 10752, 2684416) = 10752 <0.000223>
06:07:14.935588 pwrite64(4, "\200\0\24\220\1\262\0\356\0\0\0^\377\4-\2\1r\360\377\377\377\377\4-\2\1v\360\377\377\377"..., 512, 2688000) = 512 <0.000191>
06:07:14.938442 pwrite64(4, "\200\0\24\220\2\0\0\356\0\0\0^\377\4-\2\1r\360\377\377\377\377\4-\2\1v\360\377\377\377"..., 1536, 2688000) = 1536 <0.000213>
06:07:14.942039 pwrite64(4, "\200\0\24\222\0C\0006\0\0\0^\1r\\\215s\222\0\0\0\0\0\0\0\1Number"..., 512, 2689024) = 512 <0.000406>
06:07:14.944196 write(37, "\222s\215\\!\372\273\23\0=\0\0\0\23\r\0\0\0\0\1\232-\217\206\32\271\21\351\263x\0\f"..., 346) = 346 <0.000176>
06:07:14.955507 recvfrom(59, 0x7f2e48007990, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000233>
06:10:27.191228 recvfrom(59, "\201\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000014>
06:10:27.191364 recvfrom(59, "\3insert into tutorials_tbl(tutor"..., 129, MSG_DONTWAIT, NULL, NULL) = 129 <0.000012>
06:10:27.191504 write(35, "2019-03-17T06:10:27.191478+08:00"..., 174) = 174 <0.000040>
06:10:27.191627 open("./test02/tutorials_tbl.frm", O_RDONLY) = 84 <0.000020>
06:10:27.191738 read(84, "\376\1\n\f\3\0\0\20\1\0\0000\0\0i\1\257\1\0\0\0\0\0\0\0\0\0\2!\0\t\0"..., 64) = 64 <0.000012>
06:10:27.191799 read(84, "//\0\0 \0\0", 7) = 7 <0.000010>
06:10:27.191856 read(84, "\30\2\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 <0.000010>
06:10:27.191913 read(84, "\1\1\0\0\n\0\0\0\4\0\1\0\0\0\1\200\2\0\0\33\0\4\0\377PRIMARY\377"..., 33) = 33 <0.000022>
06:10:27.191973 pread64(84, "\0\0\6\0InnoDB\0\0\0\0\0\0\r\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 33, 4888) = 33 <0.000010>
06:10:27.192176 pread64(84, "\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"..., 431, 4457) = 431 <0.000012>
06:10:27.192248 read(84, "w\0\5\4\2\24)                         "..., 248) = 248 <0.000010>
06:10:27.192584 access("./test02/tutorials_tbl.TRG", F_OK) = -1 ENOENT (No such file or directory) <0.000025>
06:10:27.192854 pwrite64(4, "\200\0\24\222\2\0\0006\0\0\0`\1r\\\215s\222\0\0\0\0\0\0\0\1Number"..., 1024, 2689024) = 1024 <0.000281>
06:10:27.221914 write(37, "St\215\\!\372\273\23\0=\0\0\0m\16\0\0\0\0\0\232-\217\206\32\271\21\351\263x\0\f"..., 421) = 421 <0.000313>
06:10:27.245928 recvfrom(59, 0x7f2e48007990, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000232>
submission_date 

06:20:22.957977 recvfrom(59, "\34\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000016>
06:20:22.958107 recvfrom(59, "\3select * from tutorials_tbl", 28, MSG_DONTWAIT, NULL, NULL) = 28 <0.000016>
06:20:22.958258 write(35, "2019-03-17T06:20:22.958225+08:00"..., 73) = 73 <0.000052>
06:20:22.958649 recvfrom(59, 0x7f2e48007990, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000014>
^Cstrace: Process 13071 detached

MySQL 5.7後能夠利用sys.processlist:

select thd_id, conn_id,user, pid,program_name,command,current_statement from processlist where conn_id>0 and pid>0;

root@localhost [sys]>use sys;
Database changed
root@localhost [sys]>select thd_id, conn_id,user, pid,program_name,command,current_statement from processlist where conn_id>0 and pid>0;
+--------+---------+----------------+-------+--------------+---------+-------------------------------------------------------------------+
| thd_id | conn_id | user           | pid   | program_name | command | current_statement                                                 |
+--------+---------+----------------+-------+--------------+---------+-------------------------------------------------------------------+
|     29 |       3 | root@localhost | 59903 | mysql        | Query   | select thd_id, conn_id,user, p ... list where conn_id>0 and pid>0 |
+--------+---------+----------------+-------+--------------+---------+-------------------------------------------------------------------+
1 row in set (0.08 sec)

root@localhost [sys]>

strace -T -tt -s 100 -o /tmp/strace.log -p $PID

這裏就須要看看mysqld相關的io操做：

mysql: read, write, open
 Innodb: pread64, pwrite64
strace -o /tmp/strace.log -T -tt -f -e trace=read,open,write,pwrite64,pread64 -p `pidof mysqld`

strace -o /tmp/test.log -T -tt -ff -p `pidof mysqld`
-ff 參數，在跟蹤的線程fork出新的thread時，會產生一個新文件存放

利用獲取的線程id在MySQL查詢，看看都是幹什麼的？

select thread_id, thread_os_id,name from threads where thread_os_id in (15871,15872,15874,15901);

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
strace -T -tt -s 100 -e trace=XXXX -o /tmp/strace.log CMD
strace -T -tt -s 100 -ff -o /root/strace.log /usr/local/mysql/bin/mysqld
strace -T -tt -s 100 -e trace=write -o /root/strace.log /usr/local/mysql/bin/mysqld

本博文是學習騰訊視屏中的課程總結於此。
內容課程地址以下：
https://ke.qq.com/course/384101

strace 故障分析MySQL案例以下：
https://ke.qq.com/course/331538 《MySQL運維之我踩過的那些坑》
https://www.percona.com/blog/2010/07/16/analyzing-the-distribution-of-innodb-log-filewrites/
https://mp.weixin.qq.com/s/wP_ivItVKbodkV1FluTcsg （楊奇?龍的公衆號：系統調?用跟蹤
分析神器?--strace）
https://www.actionsky.com/index.php?id=2393 （binlog rotate引起的MySQL阻塞事件）