转《Linux调优工具oprofile的演示分析》

《Linux调优工具oprofile的演示分析》

oprofile是最近添加到Linux内核的一个内部数据统计功能.

一)用opcontrol控制profile

要打开oprofile,需要用start选项来调用opconrol,当第一次调用opcontrol时,必须告诉它想统计内核还是用户空间数据.

因为我们的例子是在用户空间工作,应该用--no-vmlinux选项来取消内核统计,如下:

opcontrol --start --no-vmlinux

Using default event: CPU_CLK_UNHALTED:100000:0:1:1

Using 2.6+ OProfile kernel interface.

Using log file /var/lib/oprofile/samples/oprofiled.log

Daemon started.

Profiler running.

每次启动都会在/root/.oprofile/目录下生成一个配置文件daemonrc,如下:

cat /root/.oprofile/daemonrc 

SESSION_DIR=/var/lib/oprofile

NR_CHOSEN=0

SEPARATE_LIB=0

SEPARATE_KERNEL=0

SEPARATE_THREAD=0

SEPARATE_CPU=0

VMLINUX=none

IMAGE_FILTER=

CPU_BUF_SIZE=0

CALLGRAPH=0

XENIMAGE=none

注:

以上的每个配置项是通过启动oprofile时加的参数生成的.

我们看一下oprofile进程,如下:

ps -ef|grep oprofile

root     30673     1  0 22:02 ?        00:00:00 /usr/bin/oprofiled --session-dir=/var/lib/oprofile --separate-lib=0 --separate-kernel=0 --separate-thread=0 --separate-cpu=0 --events=CPU_CLK_UNHALTED:60:0:100000:0:1:1, --no-vmlinux

接下来我们用--dump选项告诉oprofiled输出统计量,如下:

opcontrol --dump

再下来我们就可以用opreport,opgprof或者opannotate来观察它们,任何用户都可以看到输出,下面我们用opreport来查看统计量,如下:

opreport 

Overflow stats not available

CPU: Core 2, speed 1203 MHz (estimated)

Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 100000

CPU_CLK_UNHALT...|

  samples|      %|

------------------

      125 51.0204 no-vmlinux

       18  7.3469 libpthread-2.11.1.so

       17  6.9388 libc-2.11.1.so

       14  5.7143 libxul.so

        9  3.6735 libglib-2.0.so.0.2400.1

        9  3.6735 VBoxVMM.so

        7  2.8571 libQtCore.so.4.6.2

        6  2.4490 libpulsecore-0.9.21.so

        5  2.0408 libpulse.so.0.12.2

        4  1.6327 libpulsecommon-0.9.21.so

        3  1.2245 libmozjs.so

        2  0.8163 bash

        2  0.8163 compiz

        2  0.8163 firefox-bin

        CPU_CLK_UNHALT...|

          samples|      %|

        ------------------

                1 50.0000 firefox-bin

                1 50.0000 [vdso] (tgid:20061 range:0x7fff713ff000-0x7fff71400000)

        2  0.8163 libnspr4.so

        2  0.8163 VBoxRT.so

        1  0.4082 ld-2.11.1.so

        1  0.4082 libdrm_intel.so.1.0.0

        1  0.4082 librt-2.11.1.so

        1  0.4082 libpthread-2.11.1.so

        1  0.4082 Xorg

        1  0.4082 libfade.so

        1  0.4082 i965_dri.so

        1  0.4082 libgstxvimagesink.so

        1  0.4082 libQtGui.so.4.6.2

        1  0.4082 libXdamage.so.1.1.0

        1  0.4082 libasound.so.2.0.0

        1  0.4082 libntop-3.3.so

        1  0.4082 libxcb.so.1.1.0

        1  0.4082 libalsa-util.so

        1  0.4082 VBoxDD.so

        1  0.4082 VirtualBox.so

        1  0.4082 libX11.so.6.3.0

        1  0.4082 sshd

        

注:

输出显示了一系列对象文件,文件包含了当profile测试时正在运行的代码.

oprofiled从调用opcontrol --start时开始记录,到调用opcontrol --dump时会截取当前的统计量,但是oprofiled仍会继续搜集并积累统计数据,之后再调用opconrol --dump就会有旧的积累数据产生.直到调用opcontrol --stop时,才会停止搜集.

二)用oprofile统计一个应用程序

统计一个应用程序的过程并不复杂,但要适时地消除和统计数据,一般的步骤是:

1)打开后台程序/开始收集数据

opcontrol --start --no-vmlinux

2)重置统计量

opcontrol --reset

3)运行应用程序

./program

4)截取统计数据或停止后台程序

opcontrol --dump

opcontrol --shutdown

我们用下面的程序进行测试:

#include <stdio.h>

#include <string.h>

#include <stdlib.h>

#include <math.h>

double slow(double x)

{

        return pow(x,1.12345);

}

double slower(double x)

{

        return 1.0/x;

}

double slowest(double x)

{

        return sqrt(x);

}

int main (int argc, char *argv[])

{

        int i;

        double x;

        for (i = 0;i < 3000000; i++){

                x = 100.0;

                x = slow(x);

                x = slower(x);

                x = slowest(x);

        }

}

编译:

gcc -o profme -O2 -lm profme.c

启动oprofile,如下:

opcontrol --start --no-vmlinux

查看当前的oprofiled状态:

opcontrol --status

Daemon running: pid 2747

Separate options: none

vmlinux file: none

Image filter: none

Call-graph depth: 0

清理统计数据,如下:

opcontrol --reset

运行测试程序,如下:

./profme

截取统计数据,如下:

opcontrol --dump

输出统计量,如下:

opreport        

CPU: CPU with timer interrupt, speed 0 MHz (estimated)

Profiling through timer interrupt

          TIMER:0|

  samples|      %|

------------------

     4532 82.7763 no-vmlinux

      697 12.7306 libm-2.5.so

      216  3.9452 profme

       18  0.3288 libc-2.5.so

        5  0.0913 ld-2.5.so

        3  0.0548 bash

        1  0.0183 gawk

        1  0.0183 libdbus-1.so.3.2.0

        1  0.0183 oprofiled

        1  0.0183 sshd

注:

输出的结果显示程序在标准的数学库libm中花费了它大部分时间.

我们可以通过gprof来产生一个gmon.out文件,如下:

opgprof ./profme

不调用图像数据得出gmon.out结果

gprof --no-graph ./profme

Flat profile:

Each sample counts as 1 samples.

  %   cumulative   self              self     total           

 time   samples   samples    calls  T1/call  T1/call  name    

 41.67     90.00    90.00                             slowest

 25.00    144.00    54.00                             slower

 16.67    180.00    36.00                             slow

 15.74    214.00    34.00                             main

  0.93    216.00     2.00                             _init

三)opannotate工具

opannotate可以对程序的每一行所用的时间进行统计,生成详细的时间,而不只是样品统计量和执行次数.

我们用下面这个程序进行测试,如下:

#include <stdio.h>

#include <string.h>

#include <stdlib.h>

#include <time.h>

#include <math.h>

volatile double x;

int

main (int argc, char *argv[])

{

        int i;

        for (i = 0;i < 16000000; i++){

                x = 1000.0;

                int r = i & 0xf;

                if (r <= 8){

                        x = pow(x,1.234);

                }

                else

                        if(r <= 11){

                                x = sqrt(x);

                        }

                        else

                        {

                                x = 1.0/x;

                        }

        }

}

编译:

gcc -g -O2 -o summer-proj summer-proj.c -lm 

首先清理之前的数据,如下:

opcontrol --reset

重新启用oprofiled,如下:

opcontrol --start

执行summer-proj程序:

./summer-proj

截取统计数据:

opcontrol --dump

通过opannotate来查看程序中每行程序所要用到的时间,如下:

opannotate --source ./summer-proj

/* 

 * Command line: opannotate --source ./summer-proj 

 * 

 * Interpretation of command line:

 * Output annotated source file with samples

 * Output all files

 * 

 * CPU: CPU with timer interrupt, speed 0 MHz (estimated)

 * Profiling through timer interrupt

 */

/* 

 * Total samples for file : "/root/summer-proj.c"

 * 

 *    292 97.6589

 */

               :#include <stdio.h>

               :#include <string.h>

               :#include <stdlib.h>

               :#include <time.h>

               :#include <math.h>

               :

               :volatile double x;

               :

               :int

               :main (int argc, char *argv[])

               :{ /* main total:    292 97.6589 */

               :        int i;

   128 42.8094 :        for (i = 0;i < 16000000; i++){

     7  2.3411 :                x = 1000.0;

               :

    11  3.6789 :                int r = i & 0xf;

               :

               :                if (r <= 8){

    24  8.0268 :                        x = pow(x,1.234);

               :                }

               :                else

     8  2.6756 :                        if(r <= 11){

    89 29.7659 :                                x = sqrt(x);

               :                        }

               :                        else

               :                        {

    25  8.3612 :                                x = 1.0/x;

               :                        }

               :        }

               :}

               

四)关于oprofile的最终论述

这里只提到了oprofile的表面功能.

默认情况下,oprofile不支持在虚拟机上进行调试,我们可以通过下面的方法让oprofile可以在虚拟机上跑,如下:

echo "options oprofile timer=1" >> /etc/modprobe.conf

此时再重启虚拟机就可以工作了.