MySQL DBA如何利用strace/pstack/gdb来定位问题

 strace简介

strace是何利Linux环境下的一款程序调试工具，用来监察一个应用程序所使用的定位系统调用。

Strace是问题一个简单的跟踪系统调用执行的工具。在其最简单的何利形式中，它可以从开始到结束跟踪二进制的定位执行，并在进程的问题生命周期中输出一行具有系统调用名称，每个系统调用的何利参数和返回值的文本行。b2b信息网

常用选项

-T：strace输出显示时间  -t：可以在每行的定位输出之前添加时间戳，-tt可以精确到微妙级别，问题-ttt也可以精确到微妙级，何利但是定位它并不是打印当前时间，而是问题显示自从epoch以来的所经过的秒数  -s：指定输出的字符串的最大长度，默认为32，何利如果输出到文件的定位话会全部输出  -o：指定将strace输出到文件  -ff：如果提供-o filename，则所有进程的服务器租用问题跟踪结果输出到相应的filename.pid中，pid是各进程的进程号.  -e：指定跟踪某个行为，例如-e trace=open指定只跟踪open行为  -y：将文件句柄用文件路径代替显示

正确姿势

简单使用 

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观察客户端client执行SQL 

#通过sys.processlist表中pid可以知道客户端连接pid  MySQL [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 |  +--------+---------+------------------+------+--------------+---------+-------------------+  |     78 |      22 | xucl@172.17.0.11 | 8656 | mysql        | Sleep   | select * from t1  |  +--------+---------+------------------+------+--------------+---------+-------------------+  1 row in set (0.05 sec)  #session1  [root@VM_0_11_centos ~]# strace -T -tt -s 100 -o /tmp/strace.log -p 5841  strace: Process 5841 attached  ^Cstrace: Process 5841 detached  #session进行数据查询   MySQL [(none)]> use xucl  Reading table information for completion of table and column names  You can turn off this feature to get a quicker startup with -A  Database changed  MySQL [xucl]> select * from t1;  +----+----+  | id | c1 |  +----+----+  |  1 |    |  +----+----+  1 row in set (0.00 sec)

需要提醒一下的是从客户端连接到MySQL的时候需要注意客户端的版本，例如我用mariadb的客户端连接官方版本8.0就无法获取到pid

查看strace文件 

....  20:54:16.901980 poll([{ fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout) <0.000006>  20:54:16.902001 write(3, "\21\0\0\0\3select * from t1", 21) = 21 <0.000011>  20:54:16.902026 read(3, "\1\0\0\1\2\"\0\0\2\3def\4xucl\2t1\2t1\2id\2id\f?\0\v\0\0\0\3\3P\0\0\0\"\0\0\3\3def\4xucl\2t1\2t1\2c1\2c1\f!\0\36\0\0\0\375\t@\0\0\0\5\0\0\4\376\0\0\2\0\3\0\0\5\0011\0\5\0\0"..., 16384) = 106 <0.000355> 20:54:16.902405 times({ tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 429630696 <0.000005>  20:54:16.902441 write(1, "+----+----+\n", 12) = 12 <0.000026>  20:54:16.902482 write(1, "| id | c1 |\n", 12) = 12 <0.000018>  20:54:16.902514 write(1, "+----+----+\n", 12) = 12 <0.000018>  20:54:16.902549 write(1, "|  1 |    |\n", 12) = 12 <0.000019>  20:54:16.902582 write(1, "+----+----+\n", 12) = 12 <0.000019>  20:54:16.902631 write(1, "\33(B\33[0;1m1 row in set (0.00 sec)\n", 33) = 33 <0.000019>  20:54:16.902666 write(1, "\33(B\33[m\33(B\33[0;1m\n", 16) = 16 <0.000019>  20:54:16.902702 stat("/etc/localtime", { st_mode=S_IFREG|0644, st_size=528, ...}) = 0 <0.000006>  20:54:16.902752 rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0 <0.000004>  20:54:16.902771 ioctl(0, TIOCGWINSZ, { ws_row=42, ws_col=163, ws_xpixel=0, ws_ypixel=0}) = 0 <0.000005>  20:54:16.902789 ioctl(0, TIOCSWINSZ, { ws_row=42, ws_col=163, ws_xpixel=0, ws_ypixel=0}) = 0 <0.000004>  20:54:16.902806 ioctl(0, TCGETS, { B38400 opost isig icanon echo ...}) = 0 <0.000005>  20:54:16.902824 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, { B38400 opost isig -icanon -echo ...}) = 0 <0.000006>  20:54:16.902841 write(1, "\33(B\33[m", 6) = 6 <0.000022>  20:54:16.902877 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000005>  20:54:16.902895 rt_sigprocmask(SIG_BLOCK, [INT QUIT ALRM TSTP TTIN TTOU], [], 8) = 0 <0.000005>  20:54:16.902912 rt_sigaction(SIGINT, { 0x55e19ff48a00, [], SA_RESTORER, 0x7fc3e63585f0}, { 0x55e19fee21d0, [INT], SA_RESTORER|SA_RESTART, 0x7fc3e63585f0}, 8) = 0 <0.000005> 20:54:16.902931 rt_sigaction(SIGTERM, { 0x55e19ff48a00, [], SA_RESTORER, 0x7fc3e63585f0}, { SIG_DFL, [], SA_RESTORER, 0x7fc3e63585f0}, 8) = 0 <0.000005> 20:54:16.902948 rt_sigaction(SIGQUIT, { 0x55e19ff48a00, [], SA_RESTORER, 0x7fc3e63585f0}, { 0x55e19fee1fa0, [QUIT], SA_RESTORER|SA_RESTART, 0x7fc3e63585f0}, 8) = 0 <0.000005> 20:54:16.902966 rt_sigaction(SIGALRM, { 0x55e19ff48a00, [], SA_RESTORER, 0x7fc3e63585f0}, { SIG_DFL, [], SA_RESTORER, 0x7fc3e63585f0}, 8) = 0 <0.000005> 20:54:16.902983 rt_sigaction(SIGTSTP, { 0x55e19ff48a00, [], SA_RESTORER, 0x7fc3e63585f0}, { SIG_DFL, [], SA_RESTORER, 0x7fc3e63585f0}, 8) = 0 <0.000005> 20:54:16.903001 rt_sigaction(SIGTTOU, { 0x55e19ff48a00, [], SA_RESTORER, 0x7fc3e63585f0}, { SIG_DFL, [], SA_RESTORER, 0x7fc3e63585f0}, 8) = 0 <0.000004> 20:54:16.903018 rt_sigaction(SIGTTIN, { 0x55e19ff48a00, [], SA_RESTORER, 0x7fc3e63585f0}, { SIG_DFL, [], SA_RESTORER, 0x7fc3e63585f0}, 8) = 0 <0.000006> 20:54:16.903037 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000005> 20:54:16.903055 rt_sigaction(SIGWINCH, { 0x55e19ff481a0, [], SA_RESTORER|SA_RESTART, 0x7fc3e63585f0}, { 0x55e19fee0760, [WINCH], SA_RESTORER|SA_RESTART, 0x7fc3e63585f0}, 8) = 0 <0.000006> 20:54:16.903088 write(1, "MySQL [xucl]> ", 14) = 14 <0.000032> 20:54:16.903139 read(0,  <detached ...>

利用strace观察server端执行 

#命令  strace -o /tmp/strace.log -T -tt -f  -p `pidof mysqld`  #假设你想看跟IO相关的行为，可以用-e trace来指定  # mysql相关的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/strace.log -T -tt -ff  -p `pidof mysqld`  #然后在本地通过socket登录执行命令  MySQL [performance_schema]> use xucl;  Reading table information for completion of table and column names  You can turn off this feature to get a quicker startup with -A Database changed  MySQL [xucl]> select * from t1;  +------+  | id   |  +------+  |    1 |  |    2 |  |    4 |  |    3 |  |    5 |  |    6 |  +------+  6 rows in set (0.01 sec)  #查看本线程对应的LWP  MySQL [xucl]> show processlist;  +----+------+-----------+------+---------+------+----------+------------------+  | Id | User | Host      | db   | Command | Time | State    | Info             |  +----+------+-----------+------+---------+------+----------+------------------+  | 28 | root | localhost | xucl | Query   |    0 | starting | show processlist |  +----+------+-----------+------+---------+------+----------+------------------+  1 row in set (0.00 sec)  MySQL [xucl]> select * from performance_schema.threads where processlist_id=28\G  

很赞哦!（9876）