examples/usdt_sample/usdt_sample.md

   1 Tested on Fedora25 4.11.3-200.fc25.x86_64, gcc (GCC) 6.3.1 20161221 (Red Hat 6.3.1-1)
   2
   3 As an alternative to using ...bcc/tests/python/include/folly/tracing/StaticTracepoint.h,
   4 it's possible to use systemtap-sdt-devel.
   5 However, this is *not* required for this sample.
   6 ```bash
   7 $ sudo dnf install systemtap-sdt-devel  # For Fedora25, other distro's might have differently named packages.
   8 ```
   9
  10 If using systemtap-sdt-devel, the following commands can be used to generate the corresponding header and object files:
  11 Also see the CMakeLists.txt file for an example how to do this using cmake.
  12 ```bash
  13 $ dtrace -h -s usdt_sample_lib1/src/lib1_sdt.d -o usdt_sample_lib1/include/usdt_sample_lib1/lib1_sdt.h
  14 $ dtrace -G -s usdt_sample_lib1/src/lib1_sdt.d -o lib1_sdt.o
  15 ```
  16
  17 Build the sample:
  18 ```bash
  19 $ pwd
  20 ~/src/bcc
  21 $ mkdir -p examples/usdt_sample/build && pushd examples/usdt_sample/build
  22 $ cmake .. && make
  23 $ popd
  24 ```
  25
  26 After building, you should see the available probes:
  27 ```bash
  28 $ python tools/tplist.py -l examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so
  29 examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_end
  30 examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_start
  31 $ readelf -n examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so
  32
  33 Displaying notes found at file offset 0x000001c8 with length 0x00000024:
  34   Owner                 Data size       Description
  35   GNU                  0x00000014       NT_GNU_BUILD_ID (unique build ID bitstring)
  36     Build ID: 3930c19f654990159563394669f2ed5281513302
  37
  38 Displaying notes found at file offset 0x0001b9ec with length 0x000000c0:
  39   Owner                 Data size       Description
  40   stapsdt              0x00000047       NT_STAPSDT (SystemTap probe descriptors)
  41     Provider: usdt_sample_lib1
  42     Name: operation_end
  43     Location: 0x000000000000ed6d, Base: 0x0000000000000000, Semaphore: 0x0000000000000000
  44     Arguments: -8@%rbx -8@%rax
  45   stapsdt              0x0000004e       NT_STAPSDT (SystemTap probe descriptors)
  46     Provider: usdt_sample_lib1
  47     Name: operation_start
  48     Location: 0x000000000000ee2c, Base: 0x0000000000000000, Semaphore: 0x0000000000000000
  49     Arguments: -8@-24(%rbp) -8@%rax
  50 ```
  51
  52 Start the usdt sample application:
  53 ```bash
  54 $ examples/usdt_sample/build/usdt_sample_app1/usdt_sample_app1 "pf" 1 30 10 1 50
  55 Applying the following parameters:
  56 Input prefix: pf.
  57 Input range: [1, 30].
  58 Calls Per Second: 10.
  59 Latency range: [1, 50] ms.
  60 You can now run the bcc scripts, see usdt_sample.md for examples.
  61 pid: 25433
  62 Press ctrl-c to exit.
  63 ```
  64
  65 Use argdist.py on the individual probes:
  66 ```bash
  67 $ sudo python tools/argdist.py -p 25433 -i 5 -C 'u:usdt_sample_lib1:operation_start():char*:arg2#input' -z 32
  68 [11:18:29]
  69 input
  70         COUNT      EVENT
  71         1          arg2 = pf_10
  72         1          arg2 = pf_5
  73         1          arg2 = pf_12
  74         1          arg2 = pf_1
  75         1          arg2 = pf_11
  76         1          arg2 = pf_28
  77         1          arg2 = pf_16
  78         1          arg2 = pf_19
  79         1          arg2 = pf_15
  80         1          arg2 = pf_2
  81         2          arg2 = pf_17
  82         2          arg2 = pf_3
  83         2          arg2 = pf_25
  84         2          arg2 = pf_30
  85         2          arg2 = pf_13
  86         2          arg2 = pf_18
  87         2          arg2 = pf_7
  88         2          arg2 = pf_29
  89         2          arg2 = pf_26
  90         3          arg2 = pf_8
  91         3          arg2 = pf_21
  92         3          arg2 = pf_14
  93         4          arg2 = pf_6
  94         4          arg2 = pf_23
  95         5          arg2 = pf_24
  96 ```
  97
  98 Use latency.py to trace the operation latencies:
  99 ```bash
 100 $ sudo python examples/usdt_sample/scripts/latency.py -p=25433 -f="pf_2"
 101 Attaching probes to pid 25433
 102 Tracing... Hit Ctrl-C to end.
 103 time(s)            id         input                            output                                 start (ns)         end (ns)    duration (us)
 104 0.000000000        7204       pf_28                            resp_pf_28                         11949439999644   11949489234565            49234
 105 0.100211886        7205       pf_28                            resp_pf_28                         11949540211530   11949574403064            34191
 106 0.300586675        7207       pf_21                            resp_pf_21                         11949740586319   11949742773571             2187
 107 0.400774366        7208       pf_28                            resp_pf_28                         11949840774010   11949859965498            19191
 108 0.701365719        7211       pf_21                            resp_pf_21                         11950141365363   11950152551131            11185
 109 0.901736620        7213       pf_25                            resp_pf_25                         11950341736264   11950347924333             6188
 110 1.102162217        7215       pf_21                            resp_pf_21                         11950542161861   11950567484183            25322
 111 1.302595998        7217       pf_23                            resp_pf_23                         11950742595642   11950761841242            19245
 112 1.503047601        7219       pf_2                             resp_pf_2                          11950943047245   11950951213474             8166
 113 1.703371457        7221       pf_27                            resp_pf_27                         11951143371101   11951176568051            33196
 114 2.104228899        7225       pf_24                            resp_pf_24                         11951544228543   11951588432769            44204
 115 2.304608175        7227       pf_21                            resp_pf_21                         11951744607819   11951790796068            46188
 116 2.404796703        7228       pf_21                            resp_pf_21                         11951844796347   11951877984160            33187
 117 2.605134923        7230       pf_27                            resp_pf_27                         11952045134567   11952065327660            20193
 118 3.206291642        7236       pf_29                            resp_pf_29                         11952646291286   11952660443343            14152
 119 3.506887492        7239       pf_21                            resp_pf_21                         11952946887136   11952995060987            48173
 120 ```
 121
 122 Use lat_dist.py to trace the latency distribution:
 123 ```bash
 124 $ sudo python examples/usdt_sample/scripts/lat_dist.py -p=25433 -i=30 -f="pf_20"
 125 Attaching probes to pid 25433
 126 [11:23:47]
 127
 128 Bucket ptr = 'pf_20'
 129      latency (us)        : count     distribution
 130          0 -> 1          : 0        |                                        |
 131          2 -> 3          : 0        |                                        |
 132          4 -> 7          : 0        |                                        |
 133          8 -> 15         : 0        |                                        |
 134         16 -> 31         : 0        |                                        |
 135         32 -> 63         : 0        |                                        |
 136         64 -> 127        : 0        |                                        |
 137        128 -> 255        : 0        |                                        |
 138        256 -> 511        : 0        |                                        |
 139        512 -> 1023       : 0        |                                        |
 140       1024 -> 2047       : 1        |**********                              |
 141       2048 -> 4095       : 1        |**********                              |
 142       4096 -> 8191       : 0        |                                        |
 143       8192 -> 16383      : 1        |**********                              |
 144      16384 -> 32767      : 4        |****************************************|
 145      32768 -> 65535      : 3        |******************************          |
 146 ```
 147
 148 Use lat_avg.py to trace the moving average of the latencies:
 149 ```bash
 150 $ sudo python examples/usdt_sample/scripts/lat_avg.py -p=25433 -i=5 -c=10 -f="pf_2"
 151 Attaching probes to pid 25433
 152 Tracing... Hit Ctrl-C to end.
 153 [11:28:32]
 154 input                                                               count     latency (us)
 155 pf_22                                                                   3             7807
 156 pf_23                                                                   4            36914
 157 pf_25                                                                   3            31473
 158 pf_28                                                                   2            10627
 159 pf_27                                                                   1            47174
 160 pf_29                                                                   1             8138
 161 pf_26                                                                   1            49121
 162 pf_20                                                                   2            29158
 163 ```