如何使用gprof对软件做profiling （一） 控制器, 以太网, FLASH, 如何, 软件

一．Xilinx Zynq-7000带来新的设计思路
在以前，我们的单板上往往有CPU和多片FPGA，由CPU完成系统的配置和管理，FPGA完成特定算法的硬件加速，受限于CPU和FPGA之间的通信带宽和延迟，CPU和FPGA之间的接口大多是用于配置和管理，无法传输大量的数据。
Xilinx推出的Zynq-7000系列芯片很好的解决了这一问题。它内含硬化好的CPU核和常见的外设（DRAM控制器，千兆以太网，USB 2.0 OTG，SD card控制器，FLASH控制器，UART，CAN，SPI，I2C等等 ），这一部分被称为Processing System（简称PS），它可以完全独立于FPGA运行；Zynq-7000芯片内部还有容量不等的FPGA资源，被称为Programmable Logic（简称PL），可以支持不同复杂度的逻辑设计。最重要的是，在PS和PL之间，有超过3000根的互联信号，包括9路AXI通道，可以提供大约100Gb/s的通信带宽，同时在PS和PL之间还有DMA，Interrupt和EMIO等多种资源。这就使得数据可以在PS和PL之间灵活高效的迁移，从系统设计的角度上来讲，任务可以在软件和硬件之间灵活的分割，实现高度优化的系统设计。这也给嵌入式系统的开发方法提供了新的思路和流程：首先利用软件可以快速灵活编程的特点，快速的用软件实现系统的原型；然后通过对软件进行profiling找出对系统性能影响最大的代码，将这部分代码用FPGA来硬件加速，实现高度优化的嵌入式系统；Xilinx还提供了HLS（High Level Synthesis）工具可以方便快速的把软件代码转化成RTL代码，帮助开发者快速的实现基于FPGA的硬件加速器。
在这一流程中，重要的一环是如何找出软件中对性能影响最大的那部分代码。对于简单的应用，我们可以很容易的判断出来，例如对频谱分析来说，FFT算法就是最至关重要的需要优化的算法。但是在很多时候，软件非常复杂，有很多的复杂的函数调用，很难通过静态的观察和分析找出对性能影响最大的那部分代码，这时就需要通过profiling工具，在软件动态运行中收集数据，通过统计的方法找出核心代码了。
二．Profiling的对象
在Linux下有很多profiling工具，各自有自己的优势和劣势。在这里我们重点研究一下如何使用gprof对软件做profiling。
很多介绍profiling工具的文章都是开发者自己写一个简单源文件，里面有简单的函数调用。
为了更好的展示profiling的效果，这里我们没有采用这种方法，而是采用了一个相对比较复杂的软件包libjpeg。
libjpeg 是一个完全用C语言编写的库，包含了被广泛使用的JPEG解码、JPEG编码和其他的JPEG功能的实现。这个库由独立JPEG工作组维护。编译完成后除了相应的.a和.so库文件之外，还会生成以下工具程序：
cjpeg和djpeg：用于JPEG的压缩和解压缩，可以和一些其他格式的图形文件进行转换。
rdjpgcom和wrjpgcom：用于在JFIF文件中插入和提取文字信息。
jpegtran：一个用于在不同的JPEG格式之间进行无损转换的工具。
在这里cjpeg和djpeg就是很不错的profiling对象，有一定的复杂度，但又没有复杂到令人生畏。JPEG图像文件可以在互联网上灵活选取，基本原则是足够大，这样可以有比较长的运行时间来收集profiling数据，同时有足够的细节可以让软件充分的运行起来。网站 http://www.hdwallpapers.in/上有很多大的图片，笔者选择的是一个2880x1800的JPEG文件。
Libjpeg可以在 http://www.ijg.org/ 上找到。这里使用的版本是13-Jan-2013发布的release 9。下载后的源文件是jpegsrc.v9.tar.gz
三. GNU profiler（gprof）简介
GNU profiler（gprof）是GNU Binutils（ https://sourceware.org/binutils/ ）的一个组成部分，详细的文档可以在 https://sourceware.org/binutils/docs/gprof/ 找到，默认情况下Linux系统当中都带有这个工具，不过如果打算在嵌入式开发板上用还是需要对GNU Binutils做交叉编译的。
Gprof的功能：
1. 生成“flat profile”，包括每个函数的调用次数，每个函数消耗的处理器时间，
2. 生成“Call graph”，包括函数的调用关系，每个函数调用花费了多少时间。
3. 生成“注释的源代码”，即是程序源代码的一个复本，标记有程序中每行代码的执行次数。
Gprof的原理：
通过在编译和链接时使用 -pg选项，gcc 在应用程序的每个函数中都加入了一个名为mcount (也可能是”_mcount”或者”__mcount”, 依赖于编译器或操作系统)的函数，这样应用程序里的每一个函数都会调用mcount, 而mcount 会在内存中保存一张函数调用图，记录通过函数调用堆栈找到的子函数和父函数的地址，以及所有与函数相关的调用时间，调用次数等信息。
Gprof基本使用流程
1. 在编译和链接时加上-pg选项。一般可以加在 Makefile 中的CFLAGS和LDFLAGS中。
2. 执行编译的二进制程序。执行参数和方式同以前。
3. 正常结束进程。这时内存中的信息会被写入到程序运行目录下的gmon.out 文件中。
4. 用 gprof 工具分析 gmon.out 文件。
Gprof参数说明
Ÿ -b 不再输出统计图表中每个字段的详细描述。
Ÿ -p 只输出函数的调用图（Call graph的那部分信息）。
Ÿ -q 只输出函数的时间消耗列表。
Ÿ -e Name 不输出函数Name 及其子函数的调用图（除非它们有未被限制的其它父函数）。可以给定多个-e 标志。一个 -e 标志只能指定一个函数。
Ÿ -E Name 不输出函数Name 及其子函数的调用图，此标志类似于 -e 标志，但它在总时间和百分比时间的计算中排除了由函数Name 及其子函数所用的时间。
Ÿ -f Name 输出函数Name 及其子函数的调用图。可以指定多个 -f 标志。一个 -f 标志只能指定一个函数。
Ÿ -F Name 输出函数Name 及其子函数的调用图，它类似于 -f 标志，但它在总时间和百分比时间计算中仅使用所打印的例程的时间。可以指定多个 -F 标志。一个 -F 标志只能指定一个函数。-F 标志覆盖 -E 标志。
一般用法：
gprof -b ELF_file_name gmon.out >report.txt
Gprof报告中flat profile表格各列的说明：
%time: 该函数消耗时间占程序所有时间百分比，全部相加应该是100%。
Cumulative seconds: 程序的累积执行时间，包括表格内该函数所在行之上的所有函数的执行时间
Self Seconds: 该函数本身的全部执行时间。表格会依照这列的数值按照降序排序所有行
Calls: 函数被调用次数, 如果无法确定则为空。
Self ms/call: 函数平均执行时间。
Total ms/call: 函数平均执行时间, 包括其内部调用。
Name: 函数名。在按照self seconds和calls排序后再依照这列进行字母排序。
Gprof报告中Call Graph表格各列的说明：
Index: 索引值
%time: 函数消耗时间占所有时间百分比
Self: 函数本身执行时间
Children: 执行子函数所用时间
Called: 被调用次数
Name: 函数名
Gprof的优势：
1. 简单易用。只需要在编译和链接是增加-pg选项。gprof对于代码大部分是用户空间的CPU密集型的应用程序用处明显，对于大部分时间运行在内核空间或者由于外部因素（例如操作系统的 I/O 子系统过载）而运行缓慢的应用程序则意义不大。
2. GNU Binutils的组成部分，基本上任何Linux里面都有。可以把生成的gmon.out拷贝到host上进行分析，省掉了一部分交叉编译的工作量。
Gprof的劣势：
1. Gprof只够监控到编译和链接时有-pg选项的函数，工作在内核态的函数和没有加-pg编译的第三方库函数是无法被gprof监控到的。因此Gprof比较适合执行时间大部分在用户态的应用。在使用Gprof前最好用Linux下的time命令来确认应用程序的实际运行时间、用户空间运行时间、内核空间运行时间，以判断是否合适用gprof。Oprofile可以解决这一问题。
2. Gprof不能监控shared library，即.so的文件。
http://www.cnblogs.com/lenolix/archive/2010/12/13/1904868.html 对此有详细的分析。对这类文件可以用sprof，不过并不好用。变通的办法是将library静态链接到应用中，这样会增加应用程序的code size。
3. Gprof 不支持多线程应用，多线程下只能采集主线程性能数据。原因是在多线程内只有主线程才能响应gprof采用的ITIMER_PROF信号。有一个简单的方法可以解决这一问题：http://sam.zoy.org/writings/programming/gprof.html
4. gprof只能在程序正常结束退出，或者通过系统调用exit()退出之后才能生成报告（gmon.out）。原因是gprof通过在atexit()里注册了一个函数来产生结果信息，任何非正常退出都不会执行atexit()的动作，所以不会产生gmon.out文件。
5. 函数执行时间是估计值。函数执行时间是通过采样估算的, 在执行时间足够长的情况下，这个不是什么大的问题，一般估算值与实际值相差不大。
四．Gprof在Zynq-7000开发板上的实验：
Hardware: ZC706 evaluation board(其他开发板亦可，只是细节上会略有不同)
Software: Xilinx 14.7 Linux pre-built
Tool chain: PetaLinux 2013.04 tool chain
为了简单起见，笔者没有重新编译Linux，而是使用的Xilinx 14.7 Linux pre-built。
在Linux Host上下载libjpeg后执行以下命令即可完成编译：
cd
tar zxvf /path/to/jpegsrc.v9.tar.gz
cd jpeg-9
./configure --prefix=/home/wave/xilinx/libjpeg/jpeg-bin --host=arm-xilinx-linux-gnueabi
Note: 参数--prefix指明编译结果的安装位置，参数--host指明交叉编译工具链的前缀。在使用PetaLinux 2013.04 tool chain之前需要先到其目录下source settings.sh
这里需要编辑Makefile，在CFLAGS和LDFLAGS中增加-pg选项。
make
make install
这时编译完成后的可执行程序cjpeg和djpeg使用到了.so文件，不适合用gprof。关于这一点可以用ldd命令确认。所以还需要用以下命令手工编译出statically linked binary，拷贝到libjpeg安装目录下的bin目录下，方便后期的profiling。这些命令可以通过观察libjpeg的make过程得到。
arm-xilinx-linux-gnueabi-gcc -std=gnu99 -g -O2 -pg -o djpeg-s djpeg.c wrppm.c wrgif.c wrtarga.c wrrle.c wrbmp.c rdcolmap.c cdjpeg.c ../jpeg-bin/lib/libjpeg.a
arm-xilinx-linux-gnueabi-gcc -std=gnu99 -g -O2 -pg -o cjpeg-s cjpeg.c rdppm.c rdgif.c rdtarga.c rdrle.c rdbmp.c rdswitch.c cdjpeg.c ../jpeg-bin/lib/libjpeg.a
然后将jpeg-bin下的所有内容打包，和Xilinx 14.7 Linux pre-built image files，以及数据文件park-2880x1800.jpg拷贝到SD卡中，从SD卡启动ZC706开发板。
在开发板的console上，执行以下命令
mount /dev/mmcblk0p1 /mnt
mkdir work
cd work
tar zxvf /mnt/jpeg-bin.tar.gz
cd jpeg-bin/bin
cp /mnt/park-2880x1800.jpg .
export LD_LIBRARY_PATH=/home/root/work/jpeg-bin/lib
time ./djpeg-s -bmp park-2880x1800.jpg > result.bmp
mv gmon.out gmon-ds.out
time ./cjpeg-s ./result.bmp > ./result.jpg
mv gmon.out gmon-cs.out
对于djpeg-s和cjpeg-s，执行时间如下所示。我们可以看到这两个应用程序的主要执行时间实在用户空间的，还是比较适合用gprof来做profiling的。
real 0m4.258s
user 0m4.200s
sys 0m0.050s
real 0m4.289s
user 0m4.230s
sys 0m0.050s
然后我们可以把执行结果拷贝到SD卡中，准备拿到Linux Host上进行分析。
cp result.* /mnt
cp gmon*.out /mnt
umount /mnt
在Linux Host上，我们可以通过以下命令看到profiling的结果：
gprof -b djpeg-s gmon-ds.out >report-ds.txt
gprof -b cjpeg-s gmon-cs.out >report-cs.txt
关于JPEG解码Profiling结果的主要部分如下：
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
20.95 0.31 0.31 1800 0.17 0.17 ycc_rgb_convert
19.60 0.60 0.29 40680 0.01 0.01 jpeg_idct_16x16
17.57 0.86 0.26 20340 0.01 0.02 decode_mcu
14.87 1.08 0.22 81000 0.00 0.00 jpeg_idct_islow
13.51 1.28 0.20 finish_output_bmp
6.08 1.37 0.09 1175224 0.00 0.00 jpeg_fill_bit_buffer
5.41 1.45 0.08 put_pixel_rows
2.03 1.48 0.03 127506 0.00 0.00 jpeg_huff_decode
关于JPEG编码Profiling结果的主要部分如下：
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
24.63 0.50 0.50 preload_image
21.18 0.93 0.43 20340 0.02 0.02 encode_mcu_huff
13.79 1.21 0.28 40680 0.01 0.01 jpeg_fdct_16x16
12.81 1.47 0.26 81180 0.00 0.01 forward_DCT
8.87 1.65 0.18 81000 0.00 0.00 jpeg_fdct_islow
8.37 1.82 0.17 1800 0.09 0.09 rgb_ycc_convert
5.42 1.93 0.11 1 110.00 110.00 get_24bit_row
3.45 2.00 0.07 __divsi3
0.49 2.01 0.01 113 0.09 10.27 compress_data
0.49 2.02 0.01 __aeabi_uidivmod
0.49 2.03 0.01 jpeg_fdct_ifast
怎么样？是不是很容易？
如果反复profiling几次，就会注意到profiling结果里面的顺序会有所变化。主要原因还是采样的时间太短，只有4.2秒，如果延长profiling的时间，得到的结果会更加逼近真实值。
五．关于sprof：
sprof主要用于Gprof的补充，分析程序的共享库(需要-g编译)。一般的使用步骤：
1. export LD_PROFILE_OUTPUT=${PWD}
2. export LD_PROFILE=abc.so.A.B
3. export LD_LIBRARY_PATH=/path/to/lib/
4. 执行使用该so的主程序
5. 执行sprof so_file_name.so so_file_name.so.profile
注意：在实际执行时发现LD_PROFILE指向的文件名后有可能需要加上实际的数字才可以。
在本次实验中，在生成profiling report的时候会发生错误：
sprof libjpeg.so.9 libjpeg.so.9.profile
Inconsistency detected by ld.so: dl-open.c: 611: _dl_open: Assertion `_dl_debug_initialize (0, args.nsid)->r_state == RT_CONSISTENT' failed!
按照Google Search Result的说法，在老版本的glibc里面会有这个问题，新版本有可能已经解决了。不过因为oprofile完全可以profiling shared library，所以只是简单的尝试了一下，没有继续深入研究这个话题。上面的经验或许会对有兴趣的开发者有所借鉴。
六．小结:
尽管gprof有各种这样那样的限制和不足，如果能够合理规避，对于代码执行时间大部分是在用户空间的计算密集型的应用程序，gprof还是非常方便好用的。