Perf火焰图(by quqi99)

quqi99

已于 2023-12-01 12:40:09 修改

阅读量3.9k

点赞数

分类专栏： Linux Application 文章标签： perf flamegraph

于 2017-07-28 19:08:46 首次发布

本文链接：https://blog.csdn.net/quqi99/article/details/76275804

版权

Linux Application 专栏收录该内容

77 篇文章 1 订阅

订阅专栏

Perf example

# NOTE: 如果编译ovs时指定了libunwind/libdwarf，则可以不用安装openvswitch-dbg
# 另外，perf指定dwarf时会也像core dump一样收集call strace，另外5秒已经能产生很大的数据量。
#sudo add-apt-repository ppa:canonical-kernel-team/ppa
sudo apt install linux-tools-`uname -r`
sudo apt install linux-tools-common
sudo apt install openvswitch-dbg libc6-dbg -y
git clone https://github.com/bboymimi/easy-flamegraph.git
cd easy-flamegraph
sudo tail -n0 -f /var/log/openvswitch/ovs-vswitchd.log | awk '/blocked 1000 ms waiting for main to quiesce/ { system("sudo /usr/bin/perf record -p `pidof ovs-vswitchd` -g --call-graph dwarf sleep 5"); system("sudo pkill tail"); }'
sudo ./gen-flamegraph.sh -i ./perf.data
sudo tar -czvf perf-output.tar.gz ./perf.data perf-output/

perf不会造成ovs服务中断，而下面的core dump则会造成服务中断，因为是ovs deadlock而不是crash, 如果只是crash则直接去/var/crash目录去找core dump即可也就不存在服务中断的问题了。
sudo tail -f /var/log/openvswitch/ovs-vswitchd.log | awk '/blocked 1000 ms waiting for main to quiesce/ {system("sudo /usr/bin/killall -SIGSEGV ovs-vswitchd")}'

注意：
1, tail中使用了 -n0 来从日志文件已有的最后一行开始
2, 这种日志之前的间隔应该大于5s
3, 有的可能抓整个系统的perf更有效 - perf record -a -g -F 997 --call-graph dwarf
4, perf产生的数据非常大，如抓10秒基本就能产生67M左右的数据。注意，运行perf的时间长度哦。
另外，一定得使用'--call-graph dwarf', 不能使用'--call-graph fp', 因为在用户态如ovs中一般都在makefile里通过　“ -fomit-frame-pointer”将folmit-frame-pointer给禁用了，这样导致在用户态使用'--call-graph fp'抓到的都是unknown. 最后，应用态使用perf一定要将符号表，对ovs感兴趣就得装ovs的符号表。

又例如抓ovn-host的call trace (死锁可以抓call trace, 真死了就是crashdump了）
# https://wiki.ubuntu.com/DebuggingProgramCrash#Debug_Symbol_Packages
echo "deb http://ddebs.ubuntu.com $(lsb_release -cs)-updates main restricted universe multiverse" | sudo tee -a /etc/apt/sources.list.d/debuginfo_debs.list
sudo apt-key adv --keyserver keyserver.ubuntu.com --recv-keys C8CAB6595FDFF622
sudo apt update
sudo apt-cache policy ovn-host-dbgsym
sudo apt install openvswitch-dbg libc6-dbg -y
wget http://launchpadlibrarian.net/468769213/ovn-host-dbgsym_20.03.0-0ubuntu1_amd64.ddeb
sudo dpkg -i ./ovn-host-dbgsym_20.03.0-0ubuntu1_amd64.ddeb
# sudo apt install ovn-host-dbgsym=20.03.2-0ubuntu0.20.04.2
sudo apt install linux-tools-`uname -r` linux-tools-common -y
sudo apt install sysstat -y
git clone https://github.com/bboymimi/easy-flamegraph.git
cd easy-flamegraph
sudo tail -f -n0 /var/log/ovn/ovn-controller.log | awk '/wakeup due to/ match($11, /\(([0-9]+)%/, col) && col[1]>99 { system("sudo /usr/bin/perf record -p `pidof ovn-controller` -g --call-graph dwarf sleep 5"); system("mpstat -P ALL"); system("sudo pkill tail"); }' > tailresult.log 2>&1
sudo ./gen-flamegraph.sh -i ./perf.data
sudo tar -czvf perf-output.tar.gz ./perf.data perf-output/

注意：上面的awk + match是work的，但下面的awk + substr是不work的，不知道为什么
substr($11,2,length($11)-2) 相当于将 (100% 变成 100
# awk从field中提取数据 - https://unix.stackexchange.com/questions/468010/awk-extract-string-from-a-field
sudo tail -f -n0 /var/log/ovn/ovn-controller.log | awk '/wakeup due to/ && substr($11,2,length($11)-2)>99 { system("mpstat -P ALL"); system("sudo pkill tail"); }'

注意点

火焰图看最宽的那条, 最宽的显示最耗时的, 上下最高则表示调用深度最长
如若抓应用态的(如ovs)则应添加" --call-graph dwarf " 参数, ovs最好也安装符号表
如ovs隔六七秒就死, 可以使用它来抓这六七秒内的调用栈 - sudo perf record -a --call-graph dwarf – sleep 12
ideal的占一成的话, 那cpu占用率就是9成左右. 如果所有进程耗时都比较平均, 那只能说明整体性能不够
使用Ctrl + F可以搜索
offcpuflamegraphs.html 可以用来分析cpu为什么会睡那么久soft-lock相关的问题
之前使用systemtap, 但这东西需要脚本, 同时也不方便online debug session时安装. 现在主要使用perf, 另外也可以学习ebpf

Perf Flame Graph

git clone https://github.com/cobblau/FlameGraph
sudo perf record --call-graph dwarf -p $(pidof qemu-system-x86_64)
sudo perf script | FlameGraph/stackcollapse-perf.pl | FlameGraph/flamegraph.pl > process.svg

分解

sudo perf record -F 99 -g -- sleep 30 $(pidof qemu-system-x86_64)
sudo perf report -n --stdio
sudo perf script | gzip > out.perf01.gz
git clone https://github.com/cobblau/FlameGraph
; http://svgshare.com can be used to share svg
sudo perf script | ./FlameGraph/stackcollapse-perf.pl | sed '/cpu_idle/d;s/\[unknown\];//g' | ./FlameGraph/flamegraph.pl --width 1000 > perf.svg
google-chrome-stable ./perf.svg

其他一

参考： https://github.com/bboymimi/perf-utils

# To get the all CPUs profiling callstack from user space to kernel space (both kernel and user space)
sudo perf record -a --call-graph dwarf
# To get the all CPUs profiling of kernel space callstack (just kernel space)
sudo perf record -a -g
git clone https://github.com/bboymimi/perf-utils.git
sudo ./perf-utils/easy-flamegraph.sh -i perf.data
google-chrome-stable ./perf-output/2018-01-04_14:18:15.perf.data.svg

其他二##

# Enable the sysrq 
sudo sysctl -w kernel.sysrq=1 
# Dump all active tasks stack - https://www.kernel.org/doc/html/latest/admin-guide/sysrq.html
echo l | sudo tee /proc/sysrq-trigger 
# Dumps tasks that are in uninterruptable (blocked) state. 
echo p | sudo tee /proc/sysrq-trigger 
# Performance profiling and get the flame-graph to see if there is 
any performance bottleneck when the problem happened
git clone git://kernel.ubuntu.com/gavinguo/perf-production.git 
sudo perf record -a -g sleep 5 
sudo ./easy-flamegraph.sh -i ./perf.data -t

Profile Java with Perf
默认的perf只能分析c与c++程序, 其他用户态的perf-java, perf-python, perf-go应当分别学习, 这里说的是perf-java

Profile Java with Perf
# https://cloud.tencent.com/developer/article/1416234
# https://my.oschina.net/u/150599/blog/3023394
sudo apt install -y linux-tools-common linux-tools-generic bindfs
mkdir /tmp/containerrootfs
PID=$(docker inspect --format {{.State.Pid}} cas1)
sudo perf record -g -p $PID
sudo perf report
#fix symbols in container
cp perf.data /tmp/containerrootfs/
bindfs /proc/$PID/root /tmp/containerrootfs
perf report --symfs /tmp/containerrootfs
umount /tmp/containerrootfs

# install java
sudo apt install -y openjdk-8-jdk
dpkg-query -L openjdk-8-jdk
export JAVA_HOME=/usr/lib/jvm/java-8-openjdk-amd64
# install perf-map-agent to help generate symbols with FlameGraph
sudo apt install -y cmake pkg-config libfuse-dev libfuse2 autoconf
git clone https://github.com/brendangregg/FlameGraph.git
export FLAMEGRAPH_DIR=/home/ubuntu/FlameGraph
git clone https://github.com/jvm-profiling-tools/perf-map-agent.git
cd perf-map-agent/
cmake .
make
sudo bin/create-links-in /usr/local/bin

# Use perf-java-flames (
# Need to add one jvm option in java process: -XX:+PreserveFramePointer
perf-java-flames $PID -g
#perf-java-record-stack $PID -g
chromium-browser /bak/work/perf-map-agent/flamegraph-10286.svg

上下文切换高
启用sar，

sudo apt install sysstat
sudo sed -i 's/^ENABLED="false"/ENABLED="true"/' /etc/default/sysstat
sudo sed -i 's/^5-55\/10/*\/2/' /etc/cron.d/sysstat
sudo systemctl restart sysstat

后可以观测如上文文切换过高

00:00:01       proc/s   cswch/s
Average:       143.82  59339.01

可以搜索火焰图（用户态内核态一起收集)

git clone git://kernel.ubuntu.com/gavinguo/perf-production.git
cd perf-production
sudo perf record -a --call-graph dwarf sleep 5
sudo ./easy-flamegraph.sh -i ./perf.data -t

也可以使用pidstat -w 1来确定哪个进程的上下文切换高，或者:

# https://serverfault.com/questions/190049/find-out-which-task-is-generating-a-lot-of-context-switches-on-linux
sudo perf record -e context-switches -a -g
# then ctrl+c
sudo perf report # inspect the result

**Appendix - error - ERROR: No stack counts found **
遇到下面error是需要: sudo chown -R root:root perf.data, 必须使用root用户, 而非它说的普通用户.

hua@t440p:/bak/work/perf-utils$ sudo ./easy-flamegraph.sh perf.data  -f
Use the /bak/work/perf-utils/perf.data as the source of the FlameGraph.
File /bak/work/perf-utils/perf.data not owned by current user or root (use -f to override)
ERROR: No stack counts found

tool - poormansprofiler

#see what [multithreaded] programs are blocking on - https://poormansprofiler.org/
sudo gdb -ex “set pagination 0” -ex “thread apply all bt” --batch -p $(pidof ovs-vswitchd)

mkdir gdb_ovs; cd gdb_ovs; for i in $(seq 1 600); do gdb -ex “set pagination 0” -ex “thread apply all bt” -batch -p $KaTeX parse error: Expected 'EOF', got '&' at position 5: pid &̲> gdb.ovs-vswit\dots$ (date -Is) ; sleep 0.1; done

tool - tmate

tmate is used to share ssh with others

收集符号表

内核符号表可以通过’sudo cat /proc/kallsyms | tee $(uname -r).kallsyms’命令收集,然后使用’per script --kallsyms’命令使用它.
用户态符号表在gavin的工具中已得到处理, 非要人工安装的话可以安装到/usr/lib/debug目录, 这也是ddeb包安装的目录
libunwind是一种符号表新标准.在build包时指定它生成的包体积小, 同时也能找到符号表

wget https://raw.githubusercontent.com/torvalds/linux/master/tools/perf/perf-archive.sh -O perf-archive.sh 
chmod +x perf-archive.sh 
./perf-archive.sh # this can take a while, a few minutes

#sudo cat /proc/kallsyms | tee $(uname -r).kallsyms

新工具

hostspot, 把perf数据用时间轴的方式图像化, 细致到时间点, 能以"Bottom Up" “top Down” Flame Graph", "Caller/Callee"的方式看, 且能放大 hotspot --kallsyms …/xx-kallsyms
flamescope, 把perf数据用时间轴时间用热点的方式表示
speedscope, 把perf数据用

perf debian

#分文件存放, cpu_50p(cpu > 50%), mem_5G(mem > 5G)
sudo add-apt-repository ppa:mimi0213kimo/easyflamegraph
sudo apt-get update
ls /var/log/easy-flamegraph/mem/
grep -r 'USE_EASY_FLAMEGRAPH' /etc/default/easy-flamegraph

其他 - 收集call trace

pidstat -u -t -p `pidof ovs-vswitchd`,`pidof ovsdb-server` 5 12 > ovs_pidstat.txt &

sudo add-apt-repository ppa:canonical-kernel-team/ppa && sudo apt install linux-tools-$(uname -r) -y
sudo perf record -p `pidof ovs-vswitchd` -g --call-graph dwarf sleep 60

# it will restart ovs-switchd as well
sudo apt install gdb openvswitch-dbg libc6-dbg -y
sudo /usr/bin/gdb --batch -p $(pidof ovs-vswitchd) --ex bt --ex quit
sudo tail -f /var/log/openvswitch/ovs-vswitchd.log | awk '/Unreasonably/ {system("sudo /usr/bin/gdb --batch -p $(pidof ovs-vswitchd) --ex bt --ex quit")}'

#it will restart ovs, but core dump can be found in the dir /var/crash directly if it's crash rather than deadlock
sudo killall -SIGSEGV ovs-vswitchd

20210226更新 - easy-flmegraph分析性能问题实例

客户在做冷迁移时虚机在目的机无响应，这种性能问题必须有时间轴的概念，事后的sosreport是无法反应犯罪现场的。
支持人员用easy-flmegraph(https://github.com/bboymimi/easy-flamegraph)工具在从一台机器往另一台机器scp拷贝镜像时（冷迁移也需要拷贝镜像的）抓了一些perf数据，这些数据是在一个时间段抽样的。

1, 分析cpu数据，找到easy-flamegraph/cpu/2021-02-25_133340.cpu.t25.u100.svg　（t25的25代表阀值，u100代表cpu利用率是100%, 如图，宽带很均匀，最宽的是swapper那是空闲进程，所以cpu这块似乎没问题。
在这里插入图片描述
2, 分析mem数据，查看里面的/proc/zoneinfo（easy-flamegraph/sysinfo/mem-stat/zoneinfo.log）数据，里面的free值小于low值时会触发内存回收，这样/proc/meminfo里就会看到SwapTotal与SwapFree. 找到free最小的时间值的前一个时间点这样就从easy-flamegraph/mem目录找到了相应的perf数据(或者打开所有svg文件，然后找到那种有宽度不均匀有那种明显存在最宽的那种图像）。
在这里插入图片描述
上图提到了xfs_file_buffered_aio_write, sosreport显示只有一个xfs, 显示它们是往/var/lib/nova/instances目录scp的。

$ grep -r 'xfs' sos_commands/block/blkid_-c_.dev.null
/dev/mapper/crypt-65389115-b882-44f6-87c5-3e574f220805: UUID="92a17bf2-78dd-4f9a-8df5-9b1d8d087f00" TYPE="xfs"

vim sos_commands/block/lsblk

|-sdh3                                                                                                         8:115   0   2.7T  0 part
| `-bcache7                                                                                                  252:896   0   2.7T  0 disk
|   `-crypt-65389115-b882-44f6-87c5-3e574f220805                                                             253:4     0   2.7T  0 crypt /var/lib/nova/instances
`-sdh4                                                                                                         8:116   0 926.7G  0 part
  `-bcache6                                                                                                  252:768   0 926.7G  0 disk  /


nvme0n1                                                                                                      259:0     0   1.5T  0 disk
|-nvme0n1p1                                                                                                  259:1     0  93.1G  0 part
| |-bcache6                                                                                                  252:768   0 926.7G  0 disk  /
| `-bcache7                                                                                                  252:896   0   2.7T  0 disk
|   `-crypt-65389115-b882-44f6-87c5-3e574f220805                                                             253:4     0   2.7T  0 crypt /var/lib/nova/instances

但是/var/lib/nova/instances的目录为2.7T，但93G的nvme却同时为2.7T与926G提供bcache

如果要拷贝的文件大于bcache中的nvme/ssd大小，会报"No space left on device",　所以我们暂时不考虑是否可以从bcache端调优。
现在应该是scp速度大于写bcache的速度，从而导致page cache一直占用内存进而free小于了low值触发了swap.

一般复制了文件后,可用内存会变少，都被cached占用了，这是linux为了提高文件读取效率的做法：为了提高磁盘存取效率, Linux做了一些精心的设计, 除了对dentry进行缓存(用于VFS,加速文件路径名到inode的转换), 还采取了两种主要Cache方式：Buffer Cache和Page Cache。前者针对磁盘块的读写，后者针对文件inode的读写。这些Cache有效缩短了 I/O系统调用(比如read,write,getdents)的时间。"
openstack server migrate --live host --block-migration --disk-overcommit i1 --debug

解决办法有可能是：

应该使用O_DIRECT绕开page cache，但是虽然qemu虽然有O_DIRECT（directsync）这个读写磁盘的cache模式，但这只是针对虚机的，并没有针对迁移的direct模式（block_migration_flag = VIR_MIGRATE_UNDEFINE_SOURCE,VIR_MIGRATE_PEER2PEER, VIR_MIGRATE_LIVE,VIR_MIGRATE_TUNNELLED,VIR_MIGRATE_NON_SHARED_INC)
migration时设置migrate_set_speed限速，但它能减小page cache吗？
设置drop_caches=1 (echo 1 > /proc/sys/vm/drop_caches), ０代表不释放，１释放页缓存，２释放dentries和inodes,3释放所有缓存。注意：这个值只能及时设置，如设置它为１之后马上将会clean(已经写到磁盘)的页缓存释放。IO被缓存到页缓存后是dirty状态，被写到磁盘就变为clean状态，如sync命令只是写dirty页到磁盘。所以如果先运行sync再设置drop_caches=1是将所有内存页写到磁盘后然后全释放。
将上面说的low值(watermark_scale_factor)调大一点, 这样内存及时回收，不至于在内存快完的时候或者OOM或者不响应了。/proc/ sys/vm/watermark_scale_factor默认是10，意为0.1%(10/10000)，最大可设置为1000

rsync是可以通过nocache (https://github.com/Feh/nocache)来disable page cache的( nocache rsync -aiv --rsync-path=‘nocache rsync’ /src/ host:/dest/ ), 但是nova无法配置使用它（https://github.com/openstack/nova/blob/stable/ussuri/nova/virt/libvirt/volume/remotefs.py#L312），用drop_caches=1作为workaround的话，在运行migration之前在source 与dest两台机器均应运行。

但是如果image比物理内存还大的话，设置drop_caches可能需要隔30秒左右就设置一次，改设置watermark_scale_factor=162，为什么是162呢？根据下列算法：
在这里插入图片描述
/proc/zoneinfo中针对normal zone有下列数据：

Node 0, zone   Normal                                                                                                                                                                  
  pages free     251571
        min      121441
        low      151801
        high     182161
        spanned  16252928
        present  16252928
        managed  15990835

上面算法中的tmp就是指min, tmp>>2就是除了4=30360
managed=15990835, 默认的watermark_scale_factor是10, 1599083510/10000=15990
30360与15990再取最大的就是30360
那30360就是间隔，121441+30360=151801 (low), 151801+30360=182161(high)
注意：zoneinfo中的单位是block(4k), 所以间隔303604K=120M

内存低于low值时就启用kswapd进程来回收页，此时还能分配页，但如果碎片化严重也会失败（如系统有大页的时候会更严重）
低于min值时就暂停所有进程kswapd进程到前台直接回收，这样进程就会在等待I/O会变得很慢系统无响应
直接回收还收不回来，就OOM了，我们这次在内核日志里没有发现OOM错误。

这个间隔30360(120M)应该调大的，按经验得1G左右，如果scp拷贝一秒拷200M也至少得撑5秒啊。这样希望kwapd在启动回收的5秒内尽量能多回收些（如果dirty页过多也无法回收）　
注：上面的perf数据中显示pagecache_get_page在5秒的采样在160M左右。

现在将间隔从303604K=120M提高到1G, 1024M/120M=8.5, 8.530360=259072 (此时tmp仍然为min是30360), 即 1590835*watermark_scale_factor/10000=259072, 所以watermark_scale_factor＝162

watermark_scale_factor=165是及时清non-dirty page cache，有时也需要设置dirty_background_ratio与dirty_ratio(mm/page-writeback.c)及时回刷dirty page cache到bcache中。
根据文档（https://lonesysadmin.net/2013/12/22/better-linux-disk-caching-performance-vm-dirty_ratio/）设置下列两个参数，减小使用page cache,　dirty_background_ratio=5(default=10)意为当脏数据达到可用内存的5%时唤醒回刷进程。dirty_ratio=10(default=20)当脏数据达到可用内存的10%时，应为每一笔数据都必须同步等待。
vm.dirty_background_ratio = 5
vm.dirty_ratio = 10

注意：watermark_scale_factor值的计算是针对每一个zone(Normal zone)的，上面相当是每个zone相当于减小了1G，这1G不能用，内存低到只有1G了就开始回收了.

目前page cache里有155963个脏页等待flush，并不算多，所以这个case主要要清理non-dirty page cache
$ cat proc/vmstat |egrep “dirty|writeback”
nr_dirty 155963
nr_writeback 0
nr_writeback_temp 0
nr_dirty_threshold 11919167
nr_dirty_background_threshold 5952306

bcache中可以监测有多少dirty data, 如果nvme中满了的话bcache可能会直接写HDD从页速度变慢，这样memory往bcache中写慢了会导致memory中有更多的dirty data. 可监控这个值/sys/block//bcache/cache/cache_available_percent，它之前应该是100，如果降到30就能说明nvme快用得差不多了。- https://lkml.org/lkml/2021/1/8/110

while true; do echo `date`; cat /sys/block/bcache0/bcache/cache/cache_available_percent; cat /sys/block/bcache0/bcache/dirty_data; cat /sys/block/bcache0/bcache/writeback_rate; sleep 5; done;

20220620

apt install gdb python3-dbg
gdb -p GLANCE_PID (pick one of the sub-workers)
info threads
py-bt
for p in $(pgrep glance-api); do echo ===== $p; gdb  -ex "set pagination 0" -ex "info threads" -ex "py-bt" --batch -p $p; done
10:36