使用穷人版profiler定位调试MySQL

此文已由作者温正湖授权网易云社区发布。

欢迎访问网易云社区，了解更多网易技术产品运营经验。

  周末闲得蛋疼，来英飞特做人工空气净化器。开了电脑后，习惯性得点击xshell按钮，进入InnoSQL稳定性测试机。show processlist几次，发现不对劲啊。我跑的是oltp加oltp_simple（select）测试，怎么好像没有update/delete/insert了，似乎只有select了。因为改了InnoDB层持锁相关的代码，莫非死锁（非事务死锁，而是latch死锁）了，但死锁怎么还能select呢。进一步打开oltp和oltp_simple两个screen的输出report，果然是oltp_simple正常，oltp的tps为0。为了调试方便，把oltp_simple停了。在此show processlist，发现10个线程齐刷刷地处于commit阶段。至此，通过mysql客户端似乎看不出什么了。

 

 按照正常的定位思路，这个时候应该先看下mysqld进程输出的error log，但阴差阳错，我并没有这么做。直接想到了上gdb，但多线程情况下gdb其实挺烦，你懂点。之前在看MongoDB存储引擎WiredTiger WAL日志性能优化文章（1,2 写到不错，推荐看看）的时候提到了一个工具，叫做穷人版profiler，打算试用下。简单过滤后，摘取的10个线程信息如下：

8pthread_cond_wait@@GLIBC_2.3.2,native_cond_wait,cond=<optimized,mutex=<optimized,stage=<optimized,MYSQL_BIN_LOG::change_stage,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit,mysql_execute_command,mysql_parse,dispatch_command,do_command,threadpool_process_request,handle_event,at,pfs_spawn_thread,start_thread,clone,??

1__lll_lock_wait,_L_lock_926,pthread_mutex_lock,native_mutex_lock,at,src_line=src_line@entry=8845,,change_stage,thd=<optimized,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit,mysql_execute_command,mysql_parse,dispatch_command,do_command,threadpool_process_request,handle_event,at,pfs_spawn_thread,start_thread,clone,??

1nanosleep,sleep,wait_for_free_space,my_write,inline_mysql_file_write,need_append_buffer_lock=<optimized,MYSQL_BIN_LOG::flush_cache_to_file,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit,mysql_execute_command,mysql_parse,dispatch_command,do_command,threadpool_process_request,handle_event,at,pfs_spawn_thread,start_thread,clone,??

每行的第一列是拥有同样内容的线程个数。可以看到有8个线程在提交阶段等mutex latch，有一个线程在等rwlock latch，还有一个，他竟然在commit阶段sleep，在往后看，竟然是wait_for_free_space。理一理，在commit阶段flush_cache_to_file函数中在wait_for_free_space进行sleep，那么很显然，磁盘满了呗。直接用df -h看了下，数据盘果然满了。盘有100G，数据量才10G左右，咋会满。看了下数据目录，全是binlog文件。好吧，那应该是binlog过期没删。在MySQL客户端使用show variables like "%expire%"看下，发现该值为空啊，那就很显然了。这次问题是由于在MySQL主从复制环境下跑稳定性测试，没有设置binlog过期时间导致binlog堆积占满了数据盘，引起读写事务无法正常提交。 最后查看了而error log确认了下：

2017-11-12T03:35:39.653002Z 105 [ERROR] Disk is full writing './innosql-dev-bin.000099' (Errcode: 16685152 - No space left on device). Waiting for someone to free space... 
2017-11-12T03:35:39.653034Z 105 [ERROR] Retry in 60 secs. Message reprinted in 600 secs

果然如此啊。那么执行set global expire_logs_days = 1设置binlog过期时间为一天，然后flush logs。迅速把磁盘空间降下来，再次show processlist，ok了！

 这是一个很简单的MySQL使用问题。作为一个有经验的MySQL研发或运维人员都能够快速定位。在此只是作为一个例子来说明穷人版profiler的使用方式。我觉得他使用gdb attach到进程后快速获取各个线程的调用栈信息后后迅速detach，并将调用栈信息按照层级快速合并汇总并统计处于同样调用栈的线程个数。这样有如下优点：

 1、attach后获取信息就快速detach，对MySQL进程影响较少，甚至在线上环境也能够使用。比靠人工操作高效很多；

 2、自动统计和整理调用栈信息，提供直观的信息和每个线程的函数调用关系，便以形成对问题的初步了解；对于简单的问题，直接可以通过函数调用关系来知道问题所在。

 3、当然，其还可以通过周期性多次采样，这样能够直观反映进程一段时间内的运行情况。

 其实类似的工具不止一个。比如pstack等也有类似功能。但不管如何，这是一个不错的工具。对于c/c++多线程开发的同学，一定还是有些用处的。最后，贴上该工具的脚本，非常简单易懂：

   
#!/bin/bashnsamples=1sleeptime=0pid=$(pidof mysqld)for x in $(seq 1 $nsamples)  do
// 获取调用栈信息
    gdb -ex "set pagination 0" -ex "thread apply all bt" -batch -p $pid
    sleep $sleeptime
  done | \

//处理脚本
awk '  BEGIN { s = ""; } 
  /^Thread/ { print s; s = ""; } 
  /^\#/ { if (s != "" ) { s = s "," $4} else { s = $4 } } 
  END { print s }' | \
sort | uniq -c | sort -r -n -k 1,1

网易云免费体验馆，0成本体验20+款云产品！ 

更多网易技术、产品、运营经验分享请点击。

相关文章：
【推荐】 用双十一的故事串起碎片的网络协议（上）
【推荐】 git 使用那些事儿