← Back to branch summary

~ubuntu-branches/ubuntu/wily/perf-tools-unstable/wily

« back to all changes in this revision

Viewing changes to examples/kprobe_example.txt

  • Committer: Package Import Robot
  • Author(s): Sebastien Delafond
  • Date: 2014-07-23 23:35:17 UTC
  • Revision ID: package-import@ubuntu.com-20140723233517-75t21rktor3l59ak
Tags: upstream-0.0.1~20140723+git942be0b
Import upstream version 0.0.1~20140723+git942be0b

Show diffs side-by-side

added added

removed removed

Lines of Context:
examples/kprobe_example.txt
 
1
Demonstrations of kprobe, the Linux ftrace version.
 
2
 
 
3
This traces do_sys_open() returns, showing the return value:
 
4
 
 
5
# ./kprobe 'r:myopen do_sys_open $retval'
 
6
Tracing kprobe myopen. Ctrl-C to end.
 
7
          kprobe-26386 [001] d... 6593278.858754: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x3
 
8
           <...>-26387 [001] d... 6593278.860043: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x3
 
9
           <...>-26387 [001] d... 6593278.860064: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x3
 
10
           <...>-26387 [001] d... 6593278.860433: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x3
 
11
           <...>-26387 [001] d... 6593278.860521: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x3
 
12
       supervise-1685  [001] d... 6593279.178806: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
13
       supervise-1689  [001] d... 6593279.228756: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
14
       supervise-1689  [001] d... 6593279.229106: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
15
       supervise-1688  [000] d... 6593279.229501: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
16
       supervise-1695  [000] d... 6593279.229944: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
17
       supervise-1685  [001] d... 6593279.230104: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
18
       supervise-1687  [001] d... 6593279.230293: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
19
       supervise-1699  [000] d... 6593279.230381: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
20
       supervise-1692  [000] d... 6593279.230825: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
21
       supervise-1698  [000] d... 6593279.230915: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
22
       supervise-1698  [000] d... 6593279.231277: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
23
       supervise-1690  [000] d... 6593279.231703: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) arg1=0x9
 
24
^C
 
25
Ending tracing...
 
26
 
 
27
The syntax for the kprobe definition is the same as can be written to the
 
28
/sys/kernel/debug/tracing/kprobe_events file, and is documented in the Linux
 
29
kernel source under Documentation/trace/kprobetrace.txt.
 
30
 
 
31
This example probe was named "myopen" (which is arbitrary). You can also provide
 
32
arbitrary names for arguments. Eg:
 
33
 
 
34
# ./kprobe 'r:myopen do_sys_open rval=$retval'
 
35
Tracing kprobe myopen. Ctrl-C to end.
 
36
          kprobe-27454 [001] d... 6593356.250019: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) rval=0x3
 
37
           <...>-27455 [001] d... 6593356.251280: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) rval=0x3
 
38
           <...>-27455 [001] d... 6593356.251301: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) rval=0x3
 
39
           <...>-27455 [001] d... 6593356.251672: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) rval=0x3
 
40
           <...>-27455 [001] d... 6593356.251769: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) rval=0x3
 
41
       supervise-1689  [000] d... 6593356.859758: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) rval=0x9
 
42
       supervise-1689  [000] d... 6593356.860143: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) rval=0x9
 
43
       supervise-1696  [000] d... 6593356.862682: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) rval=0x9
 
44
       supervise-1685  [001] d... 6593356.862684: myopen: (SyS_open+0x1e/0x20 <- do_sys_open) rval=0x9
 
45
[...]
 
46
 
 
47
That's a bit better.
 
48
 
 
49
 
 
50
Tracing the open() mode:
 
51
 
 
52
# ./kprobe 'p:myopen do_sys_open mode=%cx:u16'
 
53
Tracing kprobe myopen. Ctrl-C to end.
 
54
          kprobe-29572 [001] d... 6593503.353923: myopen: (do_sys_open+0x0/0x220) mode=0x1
 
55
          kprobe-29572 [001] d... 6593503.353945: myopen: (do_sys_open+0x0/0x220) mode=0x0
 
56
          kprobe-29572 [001] d... 6593503.354307: myopen: (do_sys_open+0x0/0x220) mode=0x5c00
 
57
          kprobe-29572 [001] d... 6593503.354401: myopen: (do_sys_open+0x0/0x220) mode=0x0
 
58
       supervise-1689  [000] d... 6593503.944125: myopen: (do_sys_open+0x0/0x220) mode=0x1a4
 
59
       supervise-1688  [001] d... 6593503.944125: myopen: (do_sys_open+0x0/0x220) mode=0x1a4
 
60
       supervise-1688  [001] d... 6593503.944606: myopen: (do_sys_open+0x0/0x220) mode=0x1a4
 
61
       supervise-1689  [000] d... 6593503.944606: myopen: (do_sys_open+0x0/0x220) mode=0x1a4
 
62
       supervise-1698  [000] d... 6593503.944728: myopen: (do_sys_open+0x0/0x220) mode=0x1a4
 
63
       supervise-1698  [000] d... 6593503.945077: myopen: (do_sys_open+0x0/0x220) mode=0x1a4
 
64
[...]
 
65
 
 
66
Here I guessed that the mode was in register %cx, and cast it as a 16-bit
 
67
unsigned integer (":u16"). Your platform and kernel may be different, and the
 
68
mode may be in a different register. If fiddling with such registers becomes too
 
69
painful or unreliable for you, consider installing kernel debuginfo and using
 
70
the named variables with perf_events "perf probe".
 
71
 
 
72
 
 
73
Tracing the open() filename:
 
74
 
 
75
# ./kprobe 'p:myopen do_sys_open filename=+0(%si):string'
 
76
Tracing kprobe myopen. Ctrl-C to end.
 
77
          kprobe-32369 [001] d... 6593706.999728: myopen: (do_sys_open+0x0/0x220) filename="/etc/ld.so.cache"
 
78
          kprobe-32369 [001] d... 6593706.999748: myopen: (do_sys_open+0x0/0x220) filename="/lib/x86_64-linux-gnu/libc.so.6"
 
79
          kprobe-32369 [001] d... 6593707.000092: myopen: (do_sys_open+0x0/0x220) filename="/usr/lib/locale/locale-archive"
 
80
          kprobe-32369 [001] d... 6593707.000176: myopen: (do_sys_open+0x0/0x220) filename="trace_pipe"
 
81
       supervise-1699  [000] d... 6593707.254970: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
82
       supervise-1689  [001] d... 6593707.254970: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
83
       supervise-1689  [001] d... 6593707.255432: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
84
       supervise-1699  [000] d... 6593707.255432: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
85
       supervise-1695  [001] d... 6593707.258805: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
86
[...]
 
87
 
 
88
As mentioned previously, the %si register may be different on your platform.
 
89
In this example, I cast it as a string.
 
90
 
 
91
 
 
92
The -H option will show the headings:
 
93
 
 
94
# ./kprobe -H 'p:myopen do_sys_open filename=+0(%si):string' 
 
95
Tracing kprobe myopen. Ctrl-C to end.
 
96
# tracer: nop
 
97
#
 
98
# entries-in-buffer/entries-written: 4/4   #P:2
 
99
#
 
100
#                              _-----=> irqs-off
 
101
#                             / _----=> need-resched
 
102
#                            | / _---=> hardirq/softirq
 
103
#                            || / _--=> preempt-depth
 
104
#                            ||| /     delay
 
105
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
 
106
#              | |       |   ||||       |         |
 
107
          kprobe-1460  [001] d... 6593814.070876: myopen: (do_sys_open+0x0/0x220) filename="/etc/ld.so.cache"
 
108
          kprobe-1460  [001] d... 6593814.070898: myopen: (do_sys_open+0x0/0x220) filename="/lib/x86_64-linux-gnu/libc.so.6"
 
109
          kprobe-1460  [001] d... 6593814.071256: myopen: (do_sys_open+0x0/0x220) filename="/usr/lib/locale/locale-archive"
 
110
          kprobe-1460  [001] d... 6593814.071355: myopen: (do_sys_open+0x0/0x220) filename="trace"
 
111
          kprobe-1460  [001] d... 6593814.070876: myopen: (do_sys_open+0x0/0x220) filename="/etc/ld.so.cache"
 
112
[...]
 
113
 
 
114
 
 
115
Specifying a duration will buffer in-kernel (reducing overhead), and write at
 
116
the end. Here's tracing for 10 seconds, and writing to the "out" file:
 
117
 
 
118
# ./kprobe -d 10 'p:myopen do_sys_open filename=+0(%si):string' > out
 
119
 
 
120
 
 
121
You can match on a single PID only:
 
122
 
 
123
# ./kprobe -p 1696 'p:myopen do_sys_open filename=+0(%si):string' 
 
124
Tracing kprobe myopen. Ctrl-C to end.
 
125
       supervise-1696  [001] d... 6593773.677033: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
126
       supervise-1696  [001] d... 6593773.677332: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
127
       supervise-1696  [001] d... 6593774.697144: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
128
       supervise-1696  [001] d... 6593774.697675: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
129
       supervise-1696  [001] d... 6593775.717986: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
130
       supervise-1696  [001] d... 6593775.718499: myopen: (do_sys_open+0x0/0x220) filename="supervise/status.new"
 
131
^C
 
132
Ending tracing...
 
133
 
 
134
This will only show events when that PID is on-CPU.
 
135
 
 
136
 
 
137
The -v option will show you the available variables you can use in custom
 
138
filters:
 
139
 
 
140
# ./kprobe -v 'p:myopen do_sys_open filename=+0(%si):string' 
 
141
name: myopen
 
142
ID: 1443
 
143
format:
 
144
        field:unsigned short common_type;       offset:0;       size:2; signed:0;
 
145
        field:unsigned char common_flags;       offset:2;       size:1; signed:0;
 
146
        field:unsigned char common_preempt_count;       offset:3;       size:1; signed:0;
 
147
        field:int common_pid;   offset:4;       size:4; signed:1;
 
148
 
 
149
        field:unsigned long __probe_ip; offset:8;       size:8; signed:0;
 
150
        field:__data_loc char[] filename;       offset:16;      size:4; signed:1;
 
151
 
 
152
print fmt: "(%lx) filename=\"%s\"", REC->__probe_ip, __get_str(filename)
 
153
 
 
154
 
 
155
Tracing filenames that end in "stat", by adding a filter:
 
156
 
 
157
# ./kprobe 'p:myopen do_sys_open filename=+0(%si):string' 'filename ~ "*stat"'
 
158
Tracing kprobe myopen. Ctrl-C to end.
 
159
        postgres-1172  [000] d... 6594028.787166: myopen: (do_sys_open+0x0/0x220) filename="pg_stat_tmp/pgstat.stat"
 
160
        postgres-1172  [001] d... 6594028.797410: myopen: (do_sys_open+0x0/0x220) filename="pg_stat_tmp/pgstat.stat"
 
161
        postgres-1172  [001] d... 6594028.797467: myopen: (do_sys_open+0x0/0x220) filename="pg_stat_tmp/pgstat.stat"
 
162
        postgres-4443  [001] d... 6594028.800908: myopen: (do_sys_open+0x0/0x220) filename="pg_stat_tmp/pgstat.stat"
 
163
        postgres-4443  [000] d... 6594028.811237: myopen: (do_sys_open+0x0/0x220) filename="pg_stat_tmp/pgstat.stat"
 
164
        postgres-4443  [000] d... 6594028.811290: myopen: (do_sys_open+0x0/0x220) filename="pg_stat_tmp/pgstat.stat"
 
165
^C
 
166
Ending tracing...
 
167
 
 
168
This filtering is done in-kernel context.