Tuesday, August 25, 2015

operf / oprofile on fedora 21



Using iperf as code to profile
sudo yum install iperf
sudo debuginfo-install iperf

Install oprofile
sudo yum install oprofile

Profile particular pid

[steve@steve-GA-880GMA-UD2H operf]$ pgrep iperf
2807
[steve@steve-GA-880GMA-UD2H operf]$ operf --pid 2807
operf: Press Ctl-c or 'kill -SIGINT 3924' to stop profiling
operf: Profiler started
^C
Profiling done.


[steve@steve-GA-880GMA-UD2H operf]$ opreport -l -dg  |less
CPU: AMD64 family10, speed 3200 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
vma      samples  %        linenr info                 image name               symbol name
00408700 261      30.9242  Reporter.c:710              iperf                    reporter_handle_packet
...
  004089af 121      46.3602  Reporter.c:814

[steve@steve-GA-880GMA-UD2H operf]$ opannotate --source |less
 * Total samples for file : "/usr/src/debug/iperf-2.0.8/src/Reporter.c"
 * 
 *    402 47.6303
...
    809             } else if (reporthdr->report.mThreadMode == kMode_Server && (packet->packetLen > 0)) {
    810                 int bin;
    811                 // mean min max tests
    812                 stats->tcp.read.cntRead++;
    813                 stats->tcp.read.totcntRead++;
    814                 bin = (int)floor((packet->packetLen -1)/stats->tcp.read.binsize);
    815                 stats->tcp.read.bins[bin]++;
    816                 stats->tcp.read.totbins[bin]++;
    817             } else if (reporthdr->report.mThreadMode == kMode_Client) {


Profile system wide

[steve@steve-GA-880GMA-UD2H operf]$ sudo operf -s
operf: Press Ctl-c or 'kill -SIGINT 4003' to stop profiling
operf: Profiler started
^C* * * * WARNING: Profiling rate was throttled back by the kernel * * * *
The number of samples actually recorded is less than expected, but is
probably still statistically valid.  Decreasing the sampling rate is the
best option if you want to avoid throttling.

Profiling done.


[steve@steve-GA-880GMA-UD2H operf]$ opreport  |less

CPU: AMD64 family10, speed 3200 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
CPU_CLK_UNHALT...|
  samples|      %|
------------------
   298879 83.0667 iperf
        CPU_CLK_UNHALT...|
          samples|      %|
        ------------------
           286580 95.8850 kallsyms
             6738  2.2544 nf_conntrack
             1279  0.4279 nf_nat_ipv4
              742  0.2483 libpthread-2.20.so
              740  0.2476 nf_conntrack_ipv4
              667  0.2232 iptable_mangle
              634  0.2121 iperf
              533  0.1783 [vdso] (tgid:2807 range:0x7fffd53fc000-0x7fffd53fdfff)

[steve@steve-GA-880GMA-UD2H operf]$ opreport -l -d -g /usr/bin/iperf -f |less
...
004092e0 293       0.0980  /usr/src/debug/iperf-2.0.8/src/Server.cpp:104 /usr/bin/iperf           Server::Run()
  004093d2 2         0.6826  /usr/src/debug/iperf-2.0.8/src/Server.cpp:182
  004093d9 5         1.7065  /usr/src/debug/iperf-2.0.8/src/Server.cpp:179
  004093ec 121      41.2969  /usr/src/debug/iperf-2.0.8/src/Server.cpp:182
  004093f5 2         0.6826  /usr/src/debug/iperf-2.0.8/src/Server.cpp:201
  00409416 12        4.0956  /usr/src/debug/iperf-2.0.8/src/Server.cpp:243
  0040941c 7         2.3891  /usr/src/debug/iperf-2.0.8/src/Server.cpp:244
  00409427 2         0.6826  /usr/src/debug/iperf-2.0.8/src/Server.cpp:248
  00409443 19        6.4846  /usr/src/debug/iperf-2.0.8/src/Server.cpp:178
  00409446 11        3.7543  /usr/src/debug/iperf-2.0.8/src/Server.cpp:178
  00409510 3         1.0239  /usr/src/debug/iperf-2.0.8/src/Server.cpp:259
  00409512 12        4.0956  /usr/src/debug/iperf-2.0.8/src/Server.cpp:259
  00409521 4         1.3652  /usr/src/debug/iperf-2.0.8/src/Server.cpp:260
  0040952d 1         0.3413  /usr/src/debug/iperf-2.0.8/src/Server.cpp:260
  00409538 4         1.3652  /usr/src/debug/iperf-2.0.8/src/Server.cpp:260
  0040953b 14        4.7782  /usr/src/debug/iperf-2.0.8/src/Server.cpp:201
  00409541 19        6.4846  /usr/src/debug/iperf-2.0.8/src/Server.cpp:201
  0040954a 4         1.3652  /usr/src/debug/iperf-2.0.8/src/Server.cpp:201
  004095bb 27        9.2150  /usr/src/debug/iperf-2.0.8/src/Server.cpp:242
  004095c4 24        8.1911  /usr/src/debug/iperf-2.0.8/src/Server.cpp:242

vi /usr/src/debug/iperf-2.0.8/src/Server.cpp
    177         gettimeofday( &watchdog, NULL );
    178         do {
    179             reportstruct->emptyreport=0;
    180 #if HAVE_DECL_SO_TIMESTAMP
    181             // perform read
    182             currLen = recvmsg( mSettings->mSock, &message, 0 );
    183             if (currLen <= 0) {
    184                 // Socket read timeout or read error
    185                 reportstruct->emptyreport=1;
    186                 gettimeofday( &(reportstruct->packetTime), NULL );


[steve@steve-GA-880GMA-UD2H operf]$ opannotate --source |less
...
/* 
 * Total samples for file : "/usr/src/debug/iperf-2.0.8/src/Server.cpp"
 * 
 *    293  0.0814
 */
...
    30  0.0083 :        do {
     5  0.0014 :            reportstruct->emptyreport=0;
               :#if HAVE_DECL_SO_TIMESTAMP
               :            // perform read 
   123  0.0342 :            currLen = recvmsg( mSettings->mSock, &message, 0 );
               :            if (currLen <= 0) {
               :                // Socket read timeout or read error
               :                reportstruct->emptyreport=1;
               :                gettimeofday( &(reportstruct->packetTime), NULL );




No comments: