基于uftrace的应用性能侧写

常用的应用侧写方法

开源编译器gcc提供了-pg编译选项，会修改生成的目柡文件，在各个函数入口处加入对函数_mcount的调用。通过实现不同的_mcout函数，该机制可以对应用运行时进行侧写(profiling)，生成侧写文件（文件名通常是gmon.out)；之后调用gprof等工具读取侧写文件，从而可以得到程序运行时的代码覆盖率、各函数调用的次数以及各函数的运行时间等：

echo 'int hello(int x, int y) { return x * y; }' | gcc -fPIC -c -ggdb -pg -O2 -o a.out -x c -
objdump -d a.out

上面对目柡文件a.out的反汇编结果如下，可看到编译器在hello函数代码里插入了对_mcount函数的调用：

Disassembly of section .text:
0000000000000000 <hello>:
   0:	a9be7bfd 	stp	x29, x30, [sp, #-32]!
   4:	910003fd 	mov	x29, sp
   8:	a90153f3 	stp	x19, x20, [sp, #16]
   c:	2a0103f3 	mov	w19, w1
  10:	d50320ff 	xpaclri
  14:	2a0003f4 	mov	w20, w0
  18:	aa1e03e0 	mov	x0, x30
  1c:	94000000 	bl	0 <_mcount>
  20:	1b137e80 	mul	w0, w20, w19
  24:	a94153f3 	ldp	x19, x20, [sp, #16]
  28:	a8c27bfd 	ldp	x29, x30, [sp], #32
  2c:	d65f03c0 	ret

该应用性能的探测方法的弊端是，生成的可执行文件、动态库在默认运行环境下也会生成gmon.out侧写文件（构建结果只能用于测试，不能用于发布），而且需要glibc库的支持（glibc提供了默认的_mcount函数实现）。例如对于musl库，因其未定义_mcount函数且缺少相关的侧写运行时功能（由目柡文件gcrt1.o提供），若开发者未定义_mcount函数，编译链接会失败：

$ mipsel-openwrt-linux-musl-gcc -pg -o hello hello.c    
/opt/toolchain-mipsel_24kc_gcc-7.3.0_musl/bin/../lib/gcc/mipsel-openwrt-linux-musl/7.3.0/../../../../mipsel-openwrt-linux-musl/bin/ld: cannot find gcrt1.o: No such file or directory
collect2: error: ld returned 1 exit status

另一种常用的应用性能探测方法是使用perf，长期以来它是Linux内核中重要的性能分析工具。它不仅仅可以对内核性能进行记录，也可以通过--all-user和-p参数指定对某个用户态的进程进行性能采样、记录，并生成性能分析数据。与本文介绍的uftrace工具相近，perf也依赖elfutils库，可以对可执行应用和动态库的符号解析，在呈现性能汇报结果时，可以直接定位到耗时久、调用频繁的函数，方便应用开发人员对应用进行必要的性能优化；其用法这里不讨论。

uftrace工具的编译

这里简要记录笔者编译uftrace的操作，方便以后参考。其中忽略了luajit的编译过程，因为本文不关注uftrace内置的对侧写数据使用lua脚本的解析功能。首先，笔者编译了elfutils开源库：

~/elfutils-0.187$ export PREFIX_DIR=/opt/uftrace
~/elfutils-0.187$ ./configure --prefix=${PREFIX_DIR} CC=gcc CFLAGS='-Wall -fPIC -O2 -m64 -D_GNU_SOURCE' --disable-nls --with-zlib --enable-libdebuginfod=dummy --disable-debuginfod --with-zlib LDFLAGS="-Wl,-rpath=${PREFIX_DIR}/lib -L${PREFIX_DIR}/lib"

接下来，编译uftrace的配置如下：

~/uftrace$ ./configure --prefix=${PREFIX_DIR} --with-elfutils=${PREFIX_DIR} --cflags="-I${PREFIX_DIR}/include/luajit-2.1 -I${PREFIX_DIR}/include -Wall -fPIC -O3 -ggdb -m64 -D_GNU_SOURCE" --ldflags="-L${PREFIX_DIR}/lib -Wl,-rpath=${PREFIX_DIR}/lib -lluajit-5.1" --with-libluajit=${PREFIX_DIR} --without-libpython --with-libdw=${PREFIX_DIR} --with-libelf=${PREFIX_DIR}

uftrace detected system features:
...         prefix: /opt/uftrace
...         libelf: [ on  ] - more flexible ELF data handling
...          libdw: [ on  ] - DWARF debug info support
...      libpython: [ OFF ] - python scripting support
...      libluajit: [ on  ] - luajit scripting support
...    libncursesw: [ OFF ] - TUI support
...   cxa_demangle: [ on  ] - full demangler support with libstdc++
...     perf_event: [ on  ] - perf (PMU) event support
...       schedule: [ on  ] - scheduler event support
...       capstone: [ OFF ] - full dynamic tracing support
...      libunwind: [ OFF ] - libunwind support

之后执行make install，uftrace就安装完成了。

对djpeg进行性能分析

为了演示uftrace的性能分析效果，笔者四次编译了jpegsrc.v9e.tar.gz，编译的配置不同，安装的路径也不同。选择该开源软件做为应用性能跟踪的对象，主要其代码量少，且性能瓶颈较为明确。首先，笔者以静态链接的方式，不加侧写(profiling)相关的编译选项（本文后面会作说明）：

./configure --prefix=${PREFIX_DIR}/jpeg_default CC=gcc \
    CFLAGS='-Wall -fPIC -O2 -m64 -D_GNU_SOURCE -ggdb -fno-omit-frame-pointer' \
    --enable-static=yes --enable-shared=no

第二次编译jpegsrc.v9e.tar.gz，以静态链接，但带有可补丁函数入口（patchable-function-entry）编译选项（这一编译选项仅8.1.0版本及以上的gcc编译器支持）：

./configure --prefix=${PREFIX_DIR}/jpeg_static CC=gcc \
    CFLAGS='-Wall -fPIC -O2 -D_GNU_SOURCE -ggdb -fno-omit-frame-pointer -fpatchable-function-entry=5' \
    --enable-static=yes --enable-shared=no

第三次编译，使能动态链接，且带有-finstrument-functions编译选项：

./configure --prefix=${PREFIX_DIR}/jpeg_inst CC=gcc \
    CFLAGS='-Wall -fPIC -O2 -D_GNU_SOURCE -ggdb -fno-omit-frame-pointer -finstrument-functions' \
    --enable-static=no --enable-shared=yes \
    LDFLAGS="-Wl,-rpath=${PREFIX_DIR}/jpeg_inst/lib -L${PREFIX_DIR}/jpeg_inst/lib"

第四次编译，使能动态链接，且带有-fpatchable-function-entry编译选项：

./configure --prefix=${PREFIX_DIR}/jpeg_patch CC=gcc \
    CFLAGS='-Wall -fPIC -O2 -D_GNU_SOURCE -ggdb -fno-omit-frame-pointer -fpatchable-function-entry=5' \
    --enable-static=no --enable-shared=yes \
    LDFLAGS="-Wl,-rpath=${PREFIX_DIR}/jpeg_patch/lib -L${PREFIX_DIR}/jpeg_patch/lib"

之后笔者编写了以下简单脚本(uftrace-djpeg.sh)，使用一张图片对djpeg解码JPEG的性能进行侧写。该脚本会生成uftrace的告文件以及Flamegraph的svg格式的图片文件，以图形化的方式展示侧写结果，以直观地对比各种不同的编译方式的性能报告：

#!/bin/bash
# uftrace-djpeg.sh
export PREFIX_DIR=/opt/uftrace
IMG_FILE=input.jpeg
profile_djpeg() {
	local pdir="$1"
	shift 1 # remove first argument
	local traceargs="$@"

	echo -n "profiling \${PREFIX_DIR}/${pdir}/bin/djpeg, time spent: "
	command time -f '%U' ${PREFIX_DIR}/${pdir}/bin/djpeg \
		-dct float -outfile /dev/null "${IMG_FILE}"

	rm -rf "${pdir}.data"
	uftrace record -a -l ${traceargs} -d "${pdir}.data" \
		${PREFIX_DIR}/${pdir}/bin/djpeg \
		-dct float -outfile /dev/null "${IMG_FILE}"

	uftrace report -d "${pdir}.data" > "${pdir}.report"
	echo "    Number of functions traced: `wc -l ${pdir}.report | awk '{print $1}'`"
	uftrace dump -d "${pdir}.data" --flame-graph | perl ./flamegraph.pl > "${pdir}.svg"
	return $?
}

PATCH_FUNCS="-P jpeg_read_scanlines -P process_data_simple_main"
PATCH_FUNCS="${PATCH_FUNCS} -P decompress_onepass -P decode_mcu"
PATCH_FUNCS="${PATCH_FUNCS} -P jpeg_idct_float -P jpeg_fill_bit_buffer"
PATCH_FUNCS="${PATCH_FUNCS} -P sep_upsample -P ycc_rgb_convert -P memset"
PATCH_FUNCS="${PATCH_FUNCS} -P put_pixel_rows -P fwrite -P jpeg_huff_decode"
profile_djpeg jpeg_default --force ${PATCH_FUNCS}
profile_djpeg jpeg_static --force ${PATCH_FUNCS}
profile_djpeg jpeg_inst
profile_djpeg jpeg_patch --force ${PATCH_FUNCS}

以上脚本执行的结果如下：

$ ./uftrace-djpeg.sh
profiling ${PREFIX_DIR}/jpeg_default/bin/djpeg, time spent: 0.10
    Number of functions traced: 15
profiling ${PREFIX_DIR}/jpeg_static/bin/djpeg, time spent: 0.10
    Number of functions traced: 25
profiling ${PREFIX_DIR}/jpeg_inst/bin/djpeg, time spent: 0.10
    Number of functions traced: 112
profiling ${PREFIX_DIR}/jpeg_patch/bin/djpeg, time spent: 0.10
    Number of functions traced: 50

可见，四种编译方案的djpeg对同一图片解码的耗时几乎相同（正常运行时，侧写的编译选项引入的性能损失可以忽略不计）。第一次和第二次编译的djpeg（都以静态链接，第二次编译带有-fpatchable-function-entry=5选项），前者跟踪到了15个函数，后者跟踪到了25个函数；而第三次编译和第四次编译的djpeg分别跟踪到了112个函数和50个函数（都以动态链接，但前者有-finstrument-functions编译选项，后者有-fpatchable-function-entry编译选项）。下面对比四次性能跟踪分析的结果；笔者为了简单直观，使用Flamegraph图来展示（在最上层的函数越宽，其占用的CPU时间越多），四个Flamegraph图分别为：

第一，jpeg_default：默认编译选项-fPIC -O2 -ggdb、静态链接，djpeg性能瓶颈：

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-xvg5R6s2-1654242317687)(./jpeg_default.png)]

第二，jpeg_static：编译选项-fPIC -O2 -ggdb -fpatchable-function-entry=5，静态链接，djpeg性能瓶颈：

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-ieMWVRo9-1654242317693)(./jpeg_static.png)]

第三，jpeg_inst：编译选项-fPIC -O2 -ggdb -finstrument-functions，动态链接，djpeg性能瓶颈：

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-rx34OmX3-1654242317696)(./jpeg_inst.png)]

上面这张图展示的侧写结果是四者中最为精确的；与其相应的侧写文本结果部分如下，主要是性能瓶颈(overhead)相关函数的调用次数及执行的时间：

  Total time   Self time       Calls  Function
  ==========  ==========  ==========  ====================
  720.544 ms    1.405 ms        3332  jpeg_read_scanlines
  367.390 ms    1.222 ms           1  main
  359.295 ms  613.673 us        1666  process_data_simple_main
  335.405 ms   89.070 ms         209  decompress_onepass
  144.469 ms  113.088 ms       65417  decode_mcu
   84.341 ms   84.341 ms      196251  jpeg_idct_float
   29.041 ms   27.710 ms      246069  jpeg_fill_bit_buffer
   23.276 ms    2.200 ms        1666  sep_upsample
   20.651 ms   20.651 ms        1666  ycc_rgb_convert
   17.505 ms   17.505 ms       65417  memset
    4.799 ms    1.037 ms        1666  put_pixel_rows
    3.761 ms    3.761 ms        1666  fwrite
    2.482 ms    2.339 ms       15488  jpeg_huff_decode
    1.353 ms  216.535 us         183  fill_input_buffer
    1.137 ms    1.137 ms         183  fread
  592.879 us    9.939 us           2  jpeg_CreateDecompress
  424.047 us  424.047 us        4998  fullsize_upsample
  281.349 us    6.659 us           1  jinit_memory_mgr

第四，jpeg_patch，编译选项-fPIC -O2 -ggdb -fpatchable-funtion-entry=5，动态链接，djpeg性能瓶颈：

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-N3BFAay3-1654242317699)(./jpeg_patch.png)]

可见，第三种djpeg的编译的方式，可以得到最精细的Flamegraph，第二种编译方式的侧写细节次之，二者都指出了对JPEG文件解码时，执行时间最长的四个函数分别为decompress_onepass/decode_mcu/jpeg_fill_bit_buffer以及jpeg_idct_float。第一种和第四种djpeg的编译方式得了不到可靠的结果。

Instrumentation (profiling，侧写)相关的编译选项

gcc编译器提供了多种不同的侧写相关的编译选项，侧写常常需要动态地修改运行中的内核、应用的代码，这个过程称为Instrumentation。官方文档对这些编译选项作了说明，感兴趣的可以参考。笔者在上面提到了在函数入口外插入_mcount函数调用的-pg编译选项，之后又提到-finstrument-functions编译选项。与前者不同的是，后者在函数入口和退出前都会插入对特定函数的调用：

echo 'int hello(int x, int y) { return x * y; }' | gcc -fPIC -c -ggdb -finstrument-functions -O2 -o a.out -x c -
objdump -d a.out

反汇编的结果如下，可见这两个函数分别为__cyg_profile_func_enter/__cyg_profile_func_exit：

0000000000000000 <hello>:
   0:	a9bd7bfd 	stp	x29, x30, [sp, #-48]!
   4:	910003fd 	mov	x29, sp
   8:	a90153f3 	stp	x19, x20, [sp, #16]
   c:	90000013 	adrp	x19, 0 <hello>
  10:	2a0103f4 	mov	w20, w1
  14:	f9400273 	ldr	x19, [x19]
  18:	a9025bf5 	stp	x21, x22, [sp, #32]
  1c:	aa1e03f6 	mov	x22, x30
  20:	d50320ff 	xpaclri
  24:	2a0003f5 	mov	w21, w0
  28:	aa1e03e1 	mov	x1, x30
  2c:	aa1303e0 	mov	x0, x19
  30:	94000000 	bl	0 <__cyg_profile_func_enter>
  34:	aa1603fe 	mov	x30, x22
  38:	d50320ff 	xpaclri
  3c:	aa1303e0 	mov	x0, x19
  40:	aa1e03e1 	mov	x1, x30
  44:	94000000 	bl	0 <__cyg_profile_func_exit>
  48:	1b147ea0 	mul	w0, w21, w20
  4c:	a94153f3 	ldp	x19, x20, [sp, #16]
  50:	a9425bf5 	ldp	x21, x22, [sp, #32]
  54:	a8c37bfd 	ldp	x29, x30, [sp], #48
  58:	d65f03c0 	ret

在基于glibc的arm64/Linux系统环境下，glibc动态库提供了这两个函数的定义，但都是空函数：

$ gdb -q /usr/lib/aarch64-linux-gnu/libc-2.31.so 
Reading symbols from /usr/lib/aarch64-linux-gnu/libc-2.31.so...
Reading symbols from /usr/lib/debug/.build-id/c9/6a2b76aab47831ed75a76aaa29d573768329f0.debug...
(gdb) disassemble __cyg_profile_func_enter
Dump of assembler code for function __cyg_profile_func_enter:
   0x00000000000e3670 <+0>:	ret
End of assembler dump.
(gdb) disassemble __cyg_profile_func_exit
Dump of assembler code for function __cyg_profile_func_enter:
   0x00000000000e3670 <+0>:	ret
End of assembler dump.

同样的，一些C语言库未定义这两个函数（或者开发未自定义），通常编译链接会失败。例如，截止目前，musl库未提供这两个函数的定义：

$ mipsel-openwrt-linux-musl-gcc -finstrument-functions -o hello hello.c
/tmp/ccAXFV8u.o: In function `main':
hello.c:(.text+0x34): undefined reference to `__cyg_profile_func_enter'
hello.c:(.text+0x78): undefined reference to `__cyg_profile_func_exit'
collect2: error: ld returned 1 exit status

uftrace正是通过向被跟踪的应用（通常为子进程）加载自已提供动态库重新定义了这两个函数，实现了高效的应用性能的跟踪。这种方案（增加编译选项-finstrument-functions）可以避免如以-pg选项编译的应用在正常运行时生成不必要的侧写(profiling)文件的问题，但因其要频繁时调用这两个函数，也会带来一定的性能损失。另一个很有用的方案是使用-fpatchable-function-entry=N编译选项（详见此处的底部的官方文档），它会在所有函数（似乎除了main函数）的入口处增加指定的N个nop机器指令，这样uftrace在跟踪时（需通过-P指定函数名称）动态地给函数打上补丁，实现一个跳转，从而进入uftrace的性能监测代码中：

$ echo 'int hello(int x, int y) { return x * y; }' | gcc -fPIC -c -ggdb -fpatchable-function-entry=2 -O2 -o a.out -x c -
$ objdump -d a.out
0000000000000000 <hello>:
   0:	d503201f 	nop
   4:	d503201f 	nop
   8:	1b017c00 	mul	w0, w0, w1
   c:	d65f03c0 	ret

值得注意的是，该编译选项需要8.1.0及以上的gcc版本才能够支持。与编译选项-pg、-finstrument-functions相比，这种方案是最不影响应用运行效率的方案，生成的应用可作发行版本。笔者在此前的一篇文章提到，Systemtap的USDT是在应用加增加一个nop指令，运行时会将该nop指令替换了陷入内核(trap-into-kernel)的中断指令（例如 int 3或brk机器指令等）；而对于uftrace而言，它会将函数入口处的nop指令替换为跳转到其他应用代码的指令，因此uftrace的跟踪效率要高一些，因为都是在应户态完成的，不用进行userspace-to-kernelspace的上下文切换。此外，笔者也曾实现了动态修改函数入口的指令的方案（详见该文章），用于应用的内存泄露问题的分析；不过由malloc/free等函数入口没有nop指令，笔者的操作要复杂很多，感兴趣的可以了解一下。

总结

uftrace的应用性能侧写，几乎都需要增加Instrumentation相关的编译选项。uftrace可以基于capstone实现对于没有Instrumentation编译选项的应用的性能跟踪，但笔者未尝试过。此外，Linux内核中的perf也不要求应用使用-pg/-finstrument-functions/fpatchable-function-entry=N编译选项；但以笔者的经验，被跟踪的应用应是带有（调试）符号表的，因为不论是uftrace还是perf，都会用到elfutils库对应用进行符号解析，从而一步到位地确定应用的性能瓶颈相关的函数。