浅谈动态追踪技术

想要查看可触发的采样事件可以通过 perf list 去展示

$ perf list

List of pre-defined events (to be used in -e):

branch-instructions OR cpu/branch-instructions/ [Kernel PMU event]
branch-misses OR cpu/branch-misses/ [Kernel PMU event]

... ...

$ perf list | wc -l
1196

#include <sys/sdt.h>
...

void
main_look(void)
{
    ...
    query = wait_for_new_query();
    DTRACE_PROBE2(myserv, query__receive, query->clientname, query->msg);
    process_query(query)
    ...
}

$ perf probe --add 'do_sys_open filename:string'$ perf record -e probe:do_sys_open -aR -p  ${Service PID}

$ perf script -i perf.data

# perf stat -e 'syscalls:sys_enter_*' gzip file 2>&1 | awk '$1 != 0'

 Performance counter stats for 'gzip file':

                 1      syscalls:sys_enter_utimensat
                 1      syscalls:sys_enter_unlink
                 3      syscalls:sys_enter_newfstat
                 1      syscalls:sys_enter_lseek
             2,180      syscalls:sys_enter_read
             4,337      syscalls:sys_enter_write
                 3      syscalls:sys_enter_access
                 1      syscalls:sys_enter_fchmod
                 1      syscalls:sys_enter_fchown


            ...

       2.309268546 seconds time elapsed

# time strace -c gzip file
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 67.69    0.125751          29      4337           write
 27.36    0.050826          23      2180           read
  4.12    0.007661        7661         1           unlink
  0.20    0.000377          94         4           openat
  0.12    0.000231          77         3         3 access
  0.08    0.000157          22         7           close
  ...
------ ----------- ----------- --------- --------- ----------------
100.00    0.185767                  6568         4 total

real    0m2.919s
user    0m0.669s
sys    0m2.263s

$ perf record -e block:block_rq_issue -ag -p ${Service PID}

$ perf report -i perf.data

Samples: 105  of event 'block:block_rq_issue', Event count (approx.): 105
  Children      Self  Trace output
-    0.95%     0.95%  8,0 R 0 () 24895224 + 1024 [python]
     0
     __GI___libc_read
     tracesys
     sys_read
     vfs_read
     do_sync_read
     xfs_file_aio_read
     xfs_file_buffered_aio_read
     generic_file_aio_read
     page_cache_async_readahead


   ondemand_readahead
     __do_page_cache_readahead
     ... ...

Samples: 21  of event 'cpu-clock', Event count (approx.): 5250000
  Children      Self  Command  Shared Object        Symbol
-   76.19%     0.00%  python   [kernel.vmlinux]     [k] system_call
   - system_call
      - 28.57% sys_recvfrom
           SYSC_recvfrom
         - sock_recvmsg
            + 23.81% inet_recvmsg
            - 4.76% security_socket_recvmsg
                 selinux_socket_recvmsg
                 sock_has_perm
                 avc_has_perm_flags
      + 23.81% sys_sendto
      + 19.05% sys_shutdown
      + 4.76% sys_newstat

void longa(){  int i,j;  for(i = 0; i < 10000000000000000; i++)
  j=i;
}void foo1(){  int i;  for(i = 0; i< 1000; i++)
     longa();
}int main(void){
  foo1();
}

编译后使用一下 perf stat 

$ perf stat ./a.out

 Performance counter stats for './a.out':

      30249.723058      task-clock (msec)         #    1.000 CPUs utilized
               150      context-switches          #    0.005 K/sec
                 2      cpu-migrations            #    0.000 K/sec
               113      page-faults               #    0.004 K/sec
   <not supported>      cycles
   <not supported>      instructions
   <not supported>      branches
   <not supported>      branch-misses

      30.260523538 seconds time elapsed

git clone --depth=1 https://github.com/brendangregg/FlameGraphperf record -F 99 -a -g -- sleep 30; ./FlameGraph/jmaps
perf script > out.stacks01
cat out.stacks01 | ./FlameGraph/stackcollapse-perf.pl | grep -v cpu_idle | \
    ./FlameGraph/flamegraph.pl --color=java --hash > out.stacks01.svg