MySQL黑盒子研究工具 strace

strace是什么？
按照 strace 官網的描述, strace 是一個可用于診斷、調試和教學的 Linux 用戶空間跟蹤器。我們用它來監控用戶空間進程和內核的交互，比如系統調用、信號傳遞、進程狀態變更等。

strace 底層使用內核的 ptrace 特性來實現其功能。
strace能做什么？

strace 常用來跟蹤進程執行時的系統調用和所接收的信號。

在 Linux 世界，進程不能直接訪問硬件設備，當進程需要訪問硬件設備(比如讀取磁盤文件，接收網絡數據等等)時，必須由用戶態模式切換至內核態模式，通過系統調用訪問硬件設備。strace 可以跟蹤到一個進程產生的系統調用，包括參數，返回值，執行消耗的時間。

在運維的日常工作中，故障處理和問題診斷是個主要的內容，也是必備的技能。strace 作為一種動態跟蹤工具，能夠幫助運維高效地定位進程和服務故障。它像是一個偵探，通過系統調用的蛛絲馬跡，告訴你異常的真相。

輸出參數的含義

每一行都是一條系統調用，等號左邊是系統調用的函數名及其參數，右邊是該調用的返回值。strace 顯示這些調用的參數并返回符號形式的值。strace 從內核接收信息，而且不需要以任何特殊的方式來構建內核。

strace cat /dev/null
execve("/usr/bin/cat", ["cat", "/dev/null"], 0x7ffe33612c58 /* 28 vars */) = 0
brk(NULL)                               = 0x716000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3cd8f60000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=33439, ...}) = 0
mmap(NULL, 33439, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3cd8f57000
close(3)                                = 0
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`&\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2156592, ...}) = 0
mmap(NULL, 3985920, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f3cd8972000
mprotect(0x7f3cd8b36000, 2093056, PROT_NONE) = 0
mmap(0x7f3cd8d35000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c3000) = 0x7f3cd8d35000
mmap(0x7f3cd8d3b000, 16896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3cd8d3b000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3cd8f56000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3cd8f54000
arch_prctl(ARCH_SET_FS, 0x7f3cd8f54740) = 0
access("/etc/sysconfig/strcasecmp-nonascii", F_OK) = -1 ENOENT (No such file or directory)
access("/etc/sysconfig/strcasecmp-nonascii", F_OK) = -1 ENOENT (No such file or directory)
mprotect(0x7f3cd8d35000, 16384, PROT_READ) = 0
mprotect(0x60b000, 4096, PROT_READ)     = 0
mprotect(0x7f3cd8f61000, 4096, PROT_READ) = 0
munmap(0x7f3cd8f57000, 33439)           = 0
brk(NULL)                               = 0x716000
brk(0x737000)                           = 0x737000
brk(NULL)                               = 0x737000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=106176928, ...}) = 0
mmap(NULL, 106176928, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3cd242f000
close(3)                                = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 2), ...}) = 0
open("/dev/null", O_RDONLY)             = 3
fstat(3, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
read(3, "", 65536)                      = 0
close(3)                                = 0
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

參數

-c 統計每一系統調用的所執行的時間,次數和出錯的次數等.
-d 輸出strace關于標準錯誤的調試信息.
-f 跟蹤由fork調用所產生的子進程.
-ff 如果提供-o filename,則所有進程的跟蹤結果輸出到相應的filename.pid中,pid是各進程的進程號.
-F 嘗試跟蹤vfork調用.在-f時,vfork不被跟蹤.
-h 輸出簡要的幫助信息.
-i 輸出系統調用的入口指針.
-q 禁止輸出關于脫離的消息.
-r 打印出相對時間關于,,每一個系統調用.
-t 在輸出中的每一行前加上時間信息.
-tt 在輸出中的每一行前加上時間信息,微秒級.
-ttt 微秒級輸出,以秒了表示時間.
-T 顯示每一調用所耗的時間.
-v 輸出所有的系統調用.一些調用關于環境變量,狀態,輸入輸出等調用由于使用頻繁,默認不輸出.
-V 輸出strace的版本信息.
-x 以十六進制形式輸出非標準字符串
-xx 所有字符串以十六進制形式輸出.
-a column
設置返回值的輸出位置.默認 為40.
-e expr
指定一個表達式,用來控制如何跟蹤.格式如下:
[qualifier=][!]value1[,value2]...
qualifier只能是 trace,abbrev,verbose,raw,signal,read,write其中之一.value是用來限定的符號或數字.默認的 qualifier是 trace.感嘆號是否定符號.例如:
-eopen等價于 -e trace=open,表示只跟蹤open調用.而-etrace!=open表示跟蹤除了open以外的其他調用.有兩個特殊的符號 all 和 none.
注意有些shell使用!來執行歷史記錄里的命令,所以要使用\\.
-e trace=set
只跟蹤指定的系統 調用.例如:-e trace=open,close,rean,write表示只跟蹤這四個系統調用.默認的為set=all.
-e trace=file
只跟蹤有關文件操作的系統調用.
-e trace=process
只跟蹤有關進程控制的系統調用.
-e trace=network
跟蹤與網絡有關的所有系統調用.
-e strace=signal
跟蹤所有與系統信號有關的 系統調用
-e trace=ipc
跟蹤所有與進程通訊有關的系統調用
-e abbrev=set
設定 strace輸出的系統調用的結果集.-v 等與 abbrev=none.默認為abbrev=all.
-e raw=set
將指 定的系統調用的參數以十六進制顯示.
-e signal=set
指定跟蹤的系統信號.默認為all.如 signal=!SIGIO(或者signal=!io),表示不跟蹤SIGIO信號.
-e read=set
輸出從指定文件中讀出 的數據.例如:
-e read=3,5
-e write=set
輸出寫入到指定文件中的數據.
-o filename
將strace的輸出寫入文件filename
-p pid
跟蹤指定的進程pid.
-s strsize
指定輸出的字符串的最大長度.默認為32.文件名一直全部輸出.
-u username
以username 的UID和GID執行被跟蹤的命令

安裝

yum list|grep strace
strace.x86_64 4.24-6.el7 base

yum -y install strace.x86_64
主要用法有兩種:

1.從命令行調試一個新開始的程序
strace /etc/init.d/mysqld start

2.綁定到一個已有的PID上來調試一個正在運行的程序
strace -c -p 12541

3.strace -T -tt -s 100 -o /tmp/strace.log CMD

常用命令舉例:

strace -o ~/mysqld.strace -T -tt -e trace=all -p
strace -p
strace -cp

實用例子:
一、mysqld啟動時讀了的哪個配置文件？

我們學習 MySQL 時，從官方文檔（https://dev.mysql.com/doc/refman/5.7/en/option-files.html）知道，MySQL5.7 如果不指定讀取的配置文件，他是會按次序搜尋和讀取加載 my.cnf 的，如下:

sequence	File Name	Purpose
1	/etc/my.cnf	Global options
2	/etc/mysql/my.cnf	Global options
3	`SYSCONFDIR` /my.cnf	Global options
4	`$MYSQL_HOME` /my.cnf	Server-specific options (server only)
5	defaults-extra-file	The file specified with --defaults-extra-file, if any
6	~/.my.cnf	User-specific options
7	~/.mylogin.cnf	User-specific login path options (clients only)

上面這個表格包含了 server(mysqld)、client(mysqladmin、mysqldump、mysql、mysqlbinlog 等等)的 my.cnf 搜尋順序，還包含了編譯版安裝，特殊參數下的路徑搜尋順序，更準確的 mysqld 搜尋路徑見下面這個:

mysqld --verbose --help |less
…

在第一頁找到以下這兩行

Default options are read from the following files in the given order:
/etc/my.cnf /etc/mysql/my.cnf /usr/local/mysql/etc/my.cnf ~/.my.cnf
…

能看出 mysqld 對 my.cnf 文件的搜尋和載入順序如下:

序號	文件路徑
1	/etc/my.cnf
2	/etc/mysql/my.cnf
3	/usr/local/mysql/etc/my.cnf
4	~/.my.cnf

下面我們用 strace 來調試一下看是不是，見標藍色部分，完全一致。

[root@host-1x2-1x-1x-179 bin]# pwd
/usr/local/mysql/bin
[root@host-1x2-1x-1x-179 bin]#
[root@host-1x2-1x-1x-179 bin]# ./mysqld --version
/opt/mysql-8.0.28-linux-glibc2.12-x86_64/bin/mysqld Ver 8.0.28 for Linux on x86_64 (MySQL Community Server - GPL)
[root@host-1x2-1x-1x-179 bin]#
[root@host-1x2-1x-1x-179 bin]# strace ./mysqld 2>&1|grep my.cnf
stat(“/etc/my.cnf”, {st_mode=S_IFREG|0644, st_size=5539, …}) = 0
open(“/etc/my.cnf”, O_RDONLY) = 3
stat(“/etc/mysql/my.cnf”, 0x7ffe1c295180) = -1 ENOENT (No such file or directory)
stat(“/usr/local/mysql/etc/my.cnf”, 0x7ffe1c295180) = -1 ENOENT (No such file or directory)
stat(“/root/.my.cnf”, 0x7ffe1c295180) = -1 ENOENT (No such file or directory)
二、利?strace觀察client端SQL執?

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

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

10:51:49.814118 gettimeofday({1524192709, 814130}, NULL) = 0 <0.000009>
10:51:49.814266 write(4, "<158>2018-04-20 10:51:49 worker001 info[9185]: topic=log.xxx.xxxx_sync EAGAIN (Resource temporarily unavailable) <0.099912>
10:51:49.914265 write(4, “\n”, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.100881>
10:51:50.015595 sendto(38, “|\0\0\0\3/master/SELECT * FROM idx_update_time WHERE 1 and order_no = ‘20180420104827060300005’ and kdt_id = ‘110’”, 128, MSG_DONTWAIT, NULL, 0) = 128 <0.000023>
10:51:50.015655 poll([{fd=38, events=POLLIN|POLLERR|POLLHUP}], 1, 12000) = 1 ([{fd=38, revents=POLLIN}]) <0.000526>
10:51:50.016213 recvfrom(38, “\1\0\0\1\7I\0\0\2\3def\5db”, 24, MSG_DONTWAIT, NULL, NULL) = 24 <0.000007> 10:51:50.016243 poll([{fd=38, events=POLLIN|POLLERR|POLLHUP}], 1, 12000) = 1 ([{fd=38, revents=POLLIN}]) <0.000006>
10:51:50.016262 recvfrom(38, “idx_update_time\25idx_update_time\2id\2id\f? \0\n\0\0\0\3\3B\0\0\0Q\0\0\3\3def\5xxx\25idx_update_time\25idx_update_time\6kdt_id\6kdt_id\f? \0\v\0\0\0\3)@\0\0\0U\0\0\4\3def\5xxx\25idx_update_time\25order_idx_upd”, 193, MSG_DONTWAIT, NULL, NULL) = 193 <0.000005> 10:51:50.016282 poll([{fd=38, events=POLLIN|POLLERR|POLLHUP}], 1, 12000) = 1 ([{fd=38, revents=POLLIN}]) <0.000005>