原创:打码日记(微信公众号ID:codelogs),欢迎分享,转载请保留出处。
简介
这是Linux命令拾遗系列的第五篇,本篇主要介绍Linux中常用的线程与内存剖析工具,以及更高级的perf性能分析工具等。
本系列文章索引
像vmstat,top等资源观测命令,只能观测到资源整体使用情况,以及在各进程/线程上的使用情况,但没法了解到进程/线程为什么会使用这么多资源?
这种情况下,可以通过剖析(profile)工具做进一步分析,如jstack,jmap,pstack,gcore,perf等。
jstack
jstack是JVM下的线程剖析工具,可以打印出当前时刻各线程的调用栈,这样就可以了解到jvm中各线程都在干什么了,如下:
1 | bash复制代码$ jstack 3051 |
实例:找占用CPU较高问题代码
如果你发现你的java进程CPU占用一直都很高,可以用如下方法找到问题代码:
1,找出占用cpu的线程号pid
1 | bash复制代码# -H表示看线程,其中312是java进程的pid |
2,转换线程号为16进制
1 | bash复制代码# 其中62是从top中获取的高cpu的线程pid |
3,获取进程中所有线程栈,提取对应高cpu线程栈
1 | bash复制代码$ jstack 312 | awk -v RS= '/0x13a/' |
通过这种方法,可以很容易找到类似大循环或死循环之类性能极差的代码。
实例:查看各线程数量
1 | bash复制代码$ jstack 10235|grep -oP '"[^"]+"'|sed -E 's/[0-9]+/n/g'|sort|uniq -c|sort -nr |
如上,通过uniq等统计jvm各线程数量,可用于快速确认业务线程池中线程数量是否正常。
jmap
jmap是JVM下的内存剖析工具,用来分析或导出JVM堆数据,如下:
1 | bash复制代码# 查看对象分布直方图,其中3051是java进程的pid |
也可以直接将整个堆内存转储为文件,如下:
1 | bash复制代码$ jmap -dump:format=b,file=heap.hprof 3051 |
堆转储文件是二进制文件,没法直接查看,一般是配合mat(Memory Analysis Tool)等堆可视化工具来进行分析,如下:
mat打开hprof文件后,会看下如下一个概要界面。
点击Histogram可以按类维度查询内存占用大小
点击Dominator Tree可以看到各对象总大小(Retained Heap,包含引用的子对象),以及所占内存比例,可以看到一个ArrayList对象占用99.31%,看来是个bug,找到创建ArrayList的代码,修改即可。
可以看到,使用jmap+mat很容易分析内存泄露bug,但需要注意的是,jmap执行时会让jvm暂停,对于高并发的服务,最好先将问题节点摘除流量后再操作。
另外,可以在jvm上添加参数-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./dump/
,使得在发生内存溢出时,自动生成堆转储文件到dump目录。
mat下载地址:www.eclipse.org/mat/
pstack
pstack是c/c++等原生程序的线程剖析工具,类似jstack,不过是面向原生程序的,用法如下:
1 | bash复制代码$ pstack $pid |
例如,mysql是用c/c++写的,当mysql运行hang住时,可以通过pstack来查看线程栈。
如下,执行一个update SQL卡住了,我们来分析分析为啥?
1,使用processlist找出问题SQL的线程id
1 | bash复制代码mysql> select t.thread_id,t.thread_os_id,pl.* from information_schema.processlist pl |
可以看到,处理update SQL的线程的thread_os_id是5185
2,使用pstack获取线程栈
1 | bash复制代码# 其中3287是mysqld进程的pid |
3,在线程栈中找到卡住线程
1 | bash复制代码$ cat mysqld_stack.log | awk -v RS= '$1 ~ /5185/' |
从调用栈不难了解到,ha_innobase::index_read
应该是读取索引数据的函数,调用row_search_mvcc
时,走到一个lock_wait_suspend_thread
函数中去了,看起来SQL执行过程中好像由于等待什么锁,被阻塞住了。
接下来,通过如下语句获取一下锁等待信息:
1 | bash复制代码mysql> SELECT r.trx_mysql_thread_id waiting_thread,r.trx_query waiting_query, |
喔,原来有个for update查询语句,对这条数据加了锁,导致这个update SQL阻塞了。
注:ubuntu中pstack包年久失修,基本无法使用,想在ubuntu中使用,可以将centos中的pstack命令复制过来
gcore
gcore是原生程序的内存转储工具,类似jmap,可以将程序的整个内存空间转储为文件,如下:
1 | bash复制代码# 其中10235是进程的pid |
转储出来的dump文件,可以直接使用gdb进行调试,如下:
1 | bash复制代码$ gdb java coredump.10235 |
另外,可以如下配置内核参数,使得程序发生内存访问越界/段错误时,自动生成coredump文件。
1 | bash复制代码# 开启coredump |
有时,在java进程上执行jmap时,会无法执行成功,这时可以使用gcore替代生成coredump,然后使用jmap转换为mat可以分析的hprof文件。
1 | bash复制代码$ jmap -dump:format=b,file=heap.hprof `which java` coredump.10235 |
线程栈分析方法
一般来说,jstack配合top只能定位类似死循环这种非常严重的性能问题,由于cpu速度太快了,对于性能稍差但又不非常差的代码,单次jstack很难从线程栈中捕捉到问题代码。
因为性能稍差的代码可能只会比好代码多耗1ms的cpu时间,但这1ms就比我们的手速快多了,当执行jstack时线程早已执行到非问题代码了。
既然手动执行jstack不行,那就让脚本来,快速执行jstack多次,虽然问题代码对于人来说执行太快,但对于正常代码来说,它还是慢一些的,因此当我快速捕捉多次线程栈时,问题代码出现的次数肯定比正常代码出现的次数要多。
1 | bash复制代码# 每0.2s执行一次jstack,并将线程栈数据保存到jstacklog.log |
抓了这么多线程栈,如何分析呢?我们可以使用linux中的文本命令来处理,按线程栈分组计数即可,如下:
1 | bash复制代码$ cat jstacklog.log \ |
出现次数最多的线程栈,大概率就是性能不佳或阻塞住的代码,上图中com.example.demo.web.controller.TestController.select
方法栈抓取到2053次,是因为我一直在压测这一个接口,所以它被抓出来最多。
火焰图
可以发现,用文本命令分析线程栈并不直观,好在性能优化大师Brendan Gregg
发明了火焰图,并开发了一套火焰图生成工具。
工具下载地址:github.com/brendangreg…
将jstack抓取的一批线程栈,生成一个火焰图,如下:
1 | bash复制代码$ cat jstacklog.log \ |
如上,生成的火焰图是svg文件,使用浏览器打开即可,在火焰图中,颜色并没有实际含义,它将相同的线程栈聚合在一起显示,因此,图中越宽的栈表示此栈在运行过程中,被抓取到的次数越多,也是我们需要重点优化的地方。
perf
perf是Linux官方维护的性能分析工具,它可以观测很多非常细非常硬核的指标,如IPC,cpu缓存命中率等,如下:
1 | bash复制代码# ubuntu安装perf,包名和内核版本相关,可以直接输入perf命令会给出安装提示 |
当然,它也可以用来抓取线程栈,并生成火焰图,如下:
1 | bash复制代码# 抓取60s的线程栈,其中1892是mysql的进程pid |
如上所示,使用perf生成的mysql的火焰图,perf抓取线程栈相比jstack的优点是,抓取精度比jstack更高,运行开销比jstack更小,并且还可以抓到Linux内核调用栈!
当然,如此强大的它,也需要像root这样至高无上的权限才能使用。
注:perf抓取线程栈,是顺着cpu上的栈寄存器找到当前线程的调用栈的,因此它只能抓到当前正在cpu上运行线程的线程栈,因此通过perf可以非常容易做oncpu分析,分析high cpu问题。
注意:某些情况下,perf获取到的mysql线程栈是破碎的,类似_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command
这种,非常难读,这种情况下,可以先使用sudo perf script | c++filt
命令处理下c++函数命名问题,再将输出给到stackcollapse-perf.pl
脚本,c++filt使用效果如下:
1 | bash复制代码# 破碎的函数名 |
offcpu火焰图
线程在运行的过程中,要么在CPU上执行,要么被锁或io操作阻塞,从而离开CPU进去睡眠状态,待被解锁或io操作完成,线程会被唤醒而变成运行态。
如下:
当线程在cpu上运行时,我们称其为oncpu,当线程阻塞而离开cpu后,称其为offcpu。
而线程离开CPU和之后被唤醒,就是我们常说的线程上下文切换,如果线程是因为io或锁等待而主动让出cpu,称为自愿上下文切换,如果是时间片用尽而让出cpu,称为非自愿上下文切换。
如果当线程在睡眠之前记录一下当前时间,然后被唤醒时记录当前线程栈与阻塞时间,再使用FlameGraph工具将线程栈绘制成一张火焰图,这样我们就得到了一张offcpu火焰图,火焰图宽的部分就是线程阻塞较多的点了,这就需要再介绍一下bcc工具了。
bcc
bcc是使用Linux ebpf机制实现的一套工具集,包含非常多的底层分析工具,如查看文件缓存命中率,tcp重传情况,mysql慢查询等等,如下:
另外,它还可以做offcpu分析,生成offcpu火焰图,如下:
1 | bash复制代码# ubuntu安装bcc工具集 |
如上图,我绘制了一张mysql的offcpu火焰图,可以发现大多数线程的offcpu都是由锁引起的,另外,offcpu火焰图与oncpu火焰图稍有不同,oncpu火焰图宽度代表线程栈出现次数,而offcpu火焰图宽度代表线程栈阻塞时间。
在我分析此图的过程中,发现JOIN::make_join_plan()
函数最终竟然去调用了btr_estimate_n_rows_in_range_low
这个函数,显然JOIN::make_join_plan()
应该是用于制定SQL执行计划的,为啥好像去读磁盘数据了?经过在网上尝试搜索btr_estimate_n_rows_in_range_low
,发现mysql有个机制,当使用非唯一索引查询数据时,mysql为了执行计划的准确性,会实际去访问一些索引数据,来辅助评估当前索引是否应该使用,避免索引统计信息不准导致的SQL执行计划不优。
我看了看相关表与SQL,发现当前使用的索引,由于之前研究分区表而弄成了非唯一索引了,实际上它可以设置为唯一索引的,于是我把索引调整成唯一索引,再次压测SQL,发现QPS从2300增加到了2700左右。
这里,也可以看出,对于一些没读过源码的中间件(如mysql),也是可以尝试使用perf或bcc生成火焰图来分析的,不知道各函数是干啥用的,可以直接把函数名拿到baidu、google去搜索,瞄一瞄别人源码解析的文章了解其作用。
bcc项目地址:github.com/iovisor/bcc
往期内容
本文转载自: 掘金