Commit 434a83c3fbb951908a3a52040f7f0e0b8ba00dd0

Authored by Ingo Molnar
1 parent a66abe7fbf

events: Harmonize event field names and print output names

Now that we can filter based on fields via perf record, people
will start using filter expressions and will expect them to
be obvious.

The primary way to see which fields are available is by looking
at the trace output, such as:

  gcc-18676 [000]   343.011728: irq_handler_entry: irq=0 handler=timer
  cc1-18677 [000]   343.012727: irq_handler_entry: irq=0 handler=timer
  cc1-18677 [000]   343.032692: irq_handler_entry: irq=0 handler=timer
  cc1-18677 [000]   343.033690: irq_handler_entry: irq=0 handler=timer
  cc1-18677 [000]   343.034687: irq_handler_entry: irq=0 handler=timer
  cc1-18677 [000]   343.035686: irq_handler_entry: irq=0 handler=timer
  cc1-18677 [000]   343.036684: irq_handler_entry: irq=0 handler=timer

While 'irq==0' filters work, the 'handler==<x>' filter expression
does not work:

  $ perf record -R -f -a -e irq:irq_handler_entry --filter handler=timer sleep 1
   Error: failed to set filter with 22 (Invalid argument)

The problem is that while an 'irq' field exists and is recognized
as a filter field - 'handler' does not exist - its name is 'name'
in the output.

To solve this, we need to synchronize the printout and the field
names, wherever possible.

In cases where the printout prints a non-field, we enclose
that information in square brackets, such as:

  perf-1380  [013]   724.903505: softirq_exit: vec=9 [action=RCU]
  perf-1380  [013]   724.904482: softirq_exit: vec=1 [action=TIMER]

This way users can use filter expressions more intuitively: all
fields that show up as 'primary' (non-bracketed) information is
filterable.

This patch harmonizes the field names for all irq, bkl, power,
sched and timer events.

We might in fact think about dropping the print format bit of
generic tracepoints altogether, and just print the fields that
are being recorded.

Cc: Li Zefan <lizf@cn.fujitsu.com>
Cc: Tom Zanussi <tzanussi@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>

Showing 5 changed files with 74 additions and 77 deletions Side-by-side Diff

include/trace/events/bkl.h
... ... @@ -13,7 +13,7 @@
13 13 TP_ARGS(func, file, line),
14 14  
15 15 TP_STRUCT__entry(
16   - __field( int, lock_depth )
  16 + __field( int, depth )
17 17 __field_ext( const char *, func, FILTER_PTR_STRING )
18 18 __field_ext( const char *, file, FILTER_PTR_STRING )
19 19 __field( int, line )
20 20  
... ... @@ -21,13 +21,13 @@
21 21  
22 22 TP_fast_assign(
23 23 /* We want to record the lock_depth after lock is acquired */
24   - __entry->lock_depth = current->lock_depth + 1;
  24 + __entry->depth = current->lock_depth + 1;
25 25 __entry->func = func;
26 26 __entry->file = file;
27 27 __entry->line = line;
28 28 ),
29 29  
30   - TP_printk("depth: %d, %s:%d %s()", __entry->lock_depth,
  30 + TP_printk("depth=%d file:line=%s:%d func=%s()", __entry->depth,
31 31 __entry->file, __entry->line, __entry->func)
32 32 );
33 33  
34 34  
35 35  
... ... @@ -38,20 +38,20 @@
38 38 TP_ARGS(func, file, line),
39 39  
40 40 TP_STRUCT__entry(
41   - __field(int, lock_depth)
42   - __field(const char *, func)
43   - __field(const char *, file)
44   - __field(int, line)
  41 + __field(int, depth )
  42 + __field(const char *, func )
  43 + __field(const char *, file )
  44 + __field(int, line )
45 45 ),
46 46  
47 47 TP_fast_assign(
48   - __entry->lock_depth = current->lock_depth;
  48 + __entry->depth = current->lock_depth;
49 49 __entry->func = func;
50 50 __entry->file = file;
51 51 __entry->line = line;
52 52 ),
53 53  
54   - TP_printk("depth: %d, %s:%d %s()", __entry->lock_depth,
  54 + TP_printk("depth=%d file:line=%s:%d func=%s()", __entry->depth,
55 55 __entry->file, __entry->line, __entry->func)
56 56 );
57 57  
include/trace/events/irq.h
... ... @@ -48,7 +48,7 @@
48 48 __assign_str(name, action->name);
49 49 ),
50 50  
51   - TP_printk("irq=%d handler=%s", __entry->irq, __get_str(name))
  51 + TP_printk("irq=%d name=%s", __entry->irq, __get_str(name))
52 52 );
53 53  
54 54 /**
... ... @@ -78,7 +78,7 @@
78 78 __entry->ret = ret;
79 79 ),
80 80  
81   - TP_printk("irq=%d return=%s",
  81 + TP_printk("irq=%d ret=%s",
82 82 __entry->irq, __entry->ret ? "handled" : "unhandled")
83 83 );
84 84  
... ... @@ -107,7 +107,7 @@
107 107 __entry->vec = (int)(h - vec);
108 108 ),
109 109  
110   - TP_printk("softirq=%d action=%s", __entry->vec,
  110 + TP_printk("vec=%d [action=%s]", __entry->vec,
111 111 show_softirq_name(__entry->vec))
112 112 );
113 113  
... ... @@ -136,7 +136,7 @@
136 136 __entry->vec = (int)(h - vec);
137 137 ),
138 138  
139   - TP_printk("softirq=%d action=%s", __entry->vec,
  139 + TP_printk("vec=%d [action=%s]", __entry->vec,
140 140 show_softirq_name(__entry->vec))
141 141 );
142 142  
include/trace/events/power.h
... ... @@ -16,8 +16,6 @@
16 16 };
17 17 #endif
18 18  
19   -
20   -
21 19 TRACE_EVENT(power_start,
22 20  
23 21 TP_PROTO(unsigned int type, unsigned int state),
include/trace/events/sched.h
... ... @@ -26,7 +26,7 @@
26 26 __entry->pid = t->pid;
27 27 ),
28 28  
29   - TP_printk("task %s:%d", __entry->comm, __entry->pid)
  29 + TP_printk("comm=%s pid=%d", __entry->comm, __entry->pid)
30 30 );
31 31  
32 32 /*
... ... @@ -46,7 +46,7 @@
46 46 __entry->ret = ret;
47 47 ),
48 48  
49   - TP_printk("ret %d", __entry->ret)
  49 + TP_printk("ret=%d", __entry->ret)
50 50 );
51 51  
52 52 /*
... ... @@ -73,7 +73,7 @@
73 73 __entry->prio = p->prio;
74 74 ),
75 75  
76   - TP_printk("task %s:%d [%d]",
  76 + TP_printk("comm=%s pid=%d prio=%d",
77 77 __entry->comm, __entry->pid, __entry->prio)
78 78 );
79 79  
... ... @@ -94,7 +94,7 @@
94 94 __field( pid_t, pid )
95 95 __field( int, prio )
96 96 __field( int, success )
97   - __field( int, cpu )
  97 + __field( int, target_cpu )
98 98 ),
99 99  
100 100 TP_fast_assign(
101 101  
102 102  
... ... @@ -102,12 +102,12 @@
102 102 __entry->pid = p->pid;
103 103 __entry->prio = p->prio;
104 104 __entry->success = success;
105   - __entry->cpu = task_cpu(p);
  105 + __entry->target_cpu = task_cpu(p);
106 106 ),
107 107  
108   - TP_printk("task %s:%d [%d] success=%d [%03d]",
  108 + TP_printk("comm=%s pid=%d prio=%d success=%d target_cpu=%03d",
109 109 __entry->comm, __entry->pid, __entry->prio,
110   - __entry->success, __entry->cpu)
  110 + __entry->success, __entry->target_cpu)
111 111 );
112 112  
113 113 /*
... ... @@ -127,7 +127,7 @@
127 127 __field( pid_t, pid )
128 128 __field( int, prio )
129 129 __field( int, success )
130   - __field( int, cpu )
  130 + __field( int, target_cpu )
131 131 ),
132 132  
133 133 TP_fast_assign(
134 134  
135 135  
... ... @@ -135,12 +135,12 @@
135 135 __entry->pid = p->pid;
136 136 __entry->prio = p->prio;
137 137 __entry->success = success;
138   - __entry->cpu = task_cpu(p);
  138 + __entry->target_cpu = task_cpu(p);
139 139 ),
140 140  
141   - TP_printk("task %s:%d [%d] success=%d [%03d]",
  141 + TP_printk("comm=%s pid=%d prio=%d success=%d target_cpu=%03d",
142 142 __entry->comm, __entry->pid, __entry->prio,
143   - __entry->success, __entry->cpu)
  143 + __entry->success, __entry->target_cpu)
144 144 );
145 145  
146 146 /*
... ... @@ -176,7 +176,7 @@
176 176 __entry->next_prio = next->prio;
177 177 ),
178 178  
179   - TP_printk("task %s:%d [%d] (%s) ==> %s:%d [%d]",
  179 + TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s ==> next_comm=%s next_pid=%d next_prio=%d",
180 180 __entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
181 181 __entry->prev_state ?
182 182 __print_flags(__entry->prev_state, "|",
... ... @@ -211,7 +211,7 @@
211 211 __entry->dest_cpu = dest_cpu;
212 212 ),
213 213  
214   - TP_printk("task %s:%d [%d] from: %d to: %d",
  214 + TP_printk("comm=%s pid=%d prio=%d orig_cpu=%d dest_cpu=%d",
215 215 __entry->comm, __entry->pid, __entry->prio,
216 216 __entry->orig_cpu, __entry->dest_cpu)
217 217 );
... ... @@ -237,7 +237,7 @@
237 237 __entry->prio = p->prio;
238 238 ),
239 239  
240   - TP_printk("task %s:%d [%d]",
  240 + TP_printk("comm=%s pid=%d prio=%d",
241 241 __entry->comm, __entry->pid, __entry->prio)
242 242 );
243 243  
... ... @@ -262,7 +262,7 @@
262 262 __entry->prio = p->prio;
263 263 ),
264 264  
265   - TP_printk("task %s:%d [%d]",
  265 + TP_printk("comm=%s pid=%d prio=%d",
266 266 __entry->comm, __entry->pid, __entry->prio)
267 267 );
268 268  
... ... @@ -287,7 +287,7 @@
287 287 __entry->prio = current->prio;
288 288 ),
289 289  
290   - TP_printk("task %s:%d [%d]",
  290 + TP_printk("comm=%s pid=%d prio=%d",
291 291 __entry->comm, __entry->pid, __entry->prio)
292 292 );
293 293  
... ... @@ -314,7 +314,7 @@
314 314 __entry->child_pid = child->pid;
315 315 ),
316 316  
317   - TP_printk("parent %s:%d child %s:%d",
  317 + TP_printk("comm=%s pid=%d child_comm=%s child_pid=%d",
318 318 __entry->parent_comm, __entry->parent_pid,
319 319 __entry->child_comm, __entry->child_pid)
320 320 );
... ... @@ -340,7 +340,7 @@
340 340 __entry->sig = sig;
341 341 ),
342 342  
343   - TP_printk("sig: %d task %s:%d",
  343 + TP_printk("sig=%d comm=%s pid=%d",
344 344 __entry->sig, __entry->comm, __entry->pid)
345 345 );
346 346  
... ... @@ -374,7 +374,7 @@
374 374 __perf_count(delay);
375 375 ),
376 376  
377   - TP_printk("task: %s:%d wait: %Lu [ns]",
  377 + TP_printk("comm=%s pid=%d delay=%Lu [ns]",
378 378 __entry->comm, __entry->pid,
379 379 (unsigned long long)__entry->delay)
380 380 );
... ... @@ -406,7 +406,7 @@
406 406 __perf_count(runtime);
407 407 ),
408 408  
409   - TP_printk("task: %s:%d runtime: %Lu [ns], vruntime: %Lu [ns]",
  409 + TP_printk("comm=%s pid=%d runtime=%Lu [ns] vruntime=%Lu [ns]",
410 410 __entry->comm, __entry->pid,
411 411 (unsigned long long)__entry->runtime,
412 412 (unsigned long long)__entry->vruntime)
... ... @@ -437,7 +437,7 @@
437 437 __perf_count(delay);
438 438 ),
439 439  
440   - TP_printk("task: %s:%d sleep: %Lu [ns]",
  440 + TP_printk("comm=%s pid=%d delay=%Lu [ns]",
441 441 __entry->comm, __entry->pid,
442 442 (unsigned long long)__entry->delay)
443 443 );
... ... @@ -467,7 +467,7 @@
467 467 __perf_count(delay);
468 468 ),
469 469  
470   - TP_printk("task: %s:%d iowait: %Lu [ns]",
  470 + TP_printk("comm=%s pid=%d delay=%Lu [ns]",
471 471 __entry->comm, __entry->pid,
472 472 (unsigned long long)__entry->delay)
473 473 );
include/trace/events/timer.h
... ... @@ -26,7 +26,7 @@
26 26 __entry->timer = timer;
27 27 ),
28 28  
29   - TP_printk("timer %p", __entry->timer)
  29 + TP_printk("timer=%p", __entry->timer)
30 30 );
31 31  
32 32 /**
... ... @@ -54,7 +54,7 @@
54 54 __entry->now = jiffies;
55 55 ),
56 56  
57   - TP_printk("timer %p: func %pf, expires %lu, timeout %ld",
  57 + TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld]",
58 58 __entry->timer, __entry->function, __entry->expires,
59 59 (long)__entry->expires - __entry->now)
60 60 );
... ... @@ -81,7 +81,7 @@
81 81 __entry->now = jiffies;
82 82 ),
83 83  
84   - TP_printk("timer %p: now %lu", __entry->timer, __entry->now)
  84 + TP_printk("timer=%p now=%lu", __entry->timer, __entry->now)
85 85 );
86 86  
87 87 /**
... ... @@ -108,7 +108,7 @@
108 108 __entry->timer = timer;
109 109 ),
110 110  
111   - TP_printk("timer %p", __entry->timer)
  111 + TP_printk("timer=%p", __entry->timer)
112 112 );
113 113  
114 114 /**
... ... @@ -129,7 +129,7 @@
129 129 __entry->timer = timer;
130 130 ),
131 131  
132   - TP_printk("timer %p", __entry->timer)
  132 + TP_printk("timer=%p", __entry->timer)
133 133 );
134 134  
135 135 /**
136 136  
137 137  
138 138  
139 139  
... ... @@ -140,24 +140,24 @@
140 140 */
141 141 TRACE_EVENT(hrtimer_init,
142 142  
143   - TP_PROTO(struct hrtimer *timer, clockid_t clockid,
  143 + TP_PROTO(struct hrtimer *hrtimer, clockid_t clockid,
144 144 enum hrtimer_mode mode),
145 145  
146   - TP_ARGS(timer, clockid, mode),
  146 + TP_ARGS(hrtimer, clockid, mode),
147 147  
148 148 TP_STRUCT__entry(
149   - __field( void *, timer )
  149 + __field( void *, hrtimer )
150 150 __field( clockid_t, clockid )
151 151 __field( enum hrtimer_mode, mode )
152 152 ),
153 153  
154 154 TP_fast_assign(
155   - __entry->timer = timer;
  155 + __entry->hrtimer = hrtimer;
156 156 __entry->clockid = clockid;
157 157 __entry->mode = mode;
158 158 ),
159 159  
160   - TP_printk("hrtimer %p, clockid %s, mode %s", __entry->timer,
  160 + TP_printk("hrtimer=%p clockid=%s mode=%s", __entry->hrtimer,
161 161 __entry->clockid == CLOCK_REALTIME ?
162 162 "CLOCK_REALTIME" : "CLOCK_MONOTONIC",
163 163 __entry->mode == HRTIMER_MODE_ABS ?
164 164  
165 165  
166 166  
167 167  
... ... @@ -170,26 +170,26 @@
170 170 */
171 171 TRACE_EVENT(hrtimer_start,
172 172  
173   - TP_PROTO(struct hrtimer *timer),
  173 + TP_PROTO(struct hrtimer *hrtimer),
174 174  
175   - TP_ARGS(timer),
  175 + TP_ARGS(hrtimer),
176 176  
177 177 TP_STRUCT__entry(
178   - __field( void *, timer )
  178 + __field( void *, hrtimer )
179 179 __field( void *, function )
180 180 __field( s64, expires )
181 181 __field( s64, softexpires )
182 182 ),
183 183  
184 184 TP_fast_assign(
185   - __entry->timer = timer;
186   - __entry->function = timer->function;
187   - __entry->expires = hrtimer_get_expires(timer).tv64;
188   - __entry->softexpires = hrtimer_get_softexpires(timer).tv64;
  185 + __entry->hrtimer = hrtimer;
  186 + __entry->function = hrtimer->function;
  187 + __entry->expires = hrtimer_get_expires(hrtimer).tv64;
  188 + __entry->softexpires = hrtimer_get_softexpires(hrtimer).tv64;
189 189 ),
190 190  
191   - TP_printk("hrtimer %p, func %pf, expires %llu, softexpires %llu",
192   - __entry->timer, __entry->function,
  191 + TP_printk("hrtimer=%p function=%pf expires=%llu softexpires=%llu",
  192 + __entry->hrtimer, __entry->function,
193 193 (unsigned long long)ktime_to_ns((ktime_t) {
194 194 .tv64 = __entry->expires }),
195 195 (unsigned long long)ktime_to_ns((ktime_t) {
196 196  
197 197  
198 198  
199 199  
... ... @@ -206,23 +206,22 @@
206 206 */
207 207 TRACE_EVENT(hrtimer_expire_entry,
208 208  
209   - TP_PROTO(struct hrtimer *timer, ktime_t *now),
  209 + TP_PROTO(struct hrtimer *hrtimer, ktime_t *now),
210 210  
211   - TP_ARGS(timer, now),
  211 + TP_ARGS(hrtimer, now),
212 212  
213 213 TP_STRUCT__entry(
214   - __field( void *, timer )
  214 + __field( void *, hrtimer )
215 215 __field( s64, now )
216 216 ),
217 217  
218 218 TP_fast_assign(
219   - __entry->timer = timer;
220   - __entry->now = now->tv64;
  219 + __entry->hrtimer = hrtimer;
  220 + __entry->now = now->tv64;
221 221 ),
222 222  
223   - TP_printk("hrtimer %p, now %llu", __entry->timer,
224   - (unsigned long long)ktime_to_ns((ktime_t) {
225   - .tv64 = __entry->now }))
  223 + TP_printk("hrtimer=%p now=%llu", __entry->hrtimer,
  224 + (unsigned long long)ktime_to_ns((ktime_t) { .tv64 = __entry->now }))
226 225 );
227 226  
228 227 /**
229 228  
230 229  
231 230  
232 231  
233 232  
234 233  
235 234  
236 235  
237 236  
238 237  
... ... @@ -234,40 +233,40 @@
234 233 */
235 234 TRACE_EVENT(hrtimer_expire_exit,
236 235  
237   - TP_PROTO(struct hrtimer *timer),
  236 + TP_PROTO(struct hrtimer *hrtimer),
238 237  
239   - TP_ARGS(timer),
  238 + TP_ARGS(hrtimer),
240 239  
241 240 TP_STRUCT__entry(
242   - __field( void *, timer )
  241 + __field( void *, hrtimer )
243 242 ),
244 243  
245 244 TP_fast_assign(
246   - __entry->timer = timer;
  245 + __entry->hrtimer = hrtimer;
247 246 ),
248 247  
249   - TP_printk("hrtimer %p", __entry->timer)
  248 + TP_printk("hrtimer=%p", __entry->hrtimer)
250 249 );
251 250  
252 251 /**
253 252 * hrtimer_cancel - called when the hrtimer is canceled
254   - * @timer: pointer to struct hrtimer
  253 + * @hrtimer: pointer to struct hrtimer
255 254 */
256 255 TRACE_EVENT(hrtimer_cancel,
257 256  
258   - TP_PROTO(struct hrtimer *timer),
  257 + TP_PROTO(struct hrtimer *hrtimer),
259 258  
260   - TP_ARGS(timer),
  259 + TP_ARGS(hrtimer),
261 260  
262 261 TP_STRUCT__entry(
263   - __field( void *, timer )
  262 + __field( void *, hrtimer )
264 263 ),
265 264  
266 265 TP_fast_assign(
267   - __entry->timer = timer;
  266 + __entry->hrtimer = hrtimer;
268 267 ),
269 268  
270   - TP_printk("hrtimer %p", __entry->timer)
  269 + TP_printk("hrtimer=%p", __entry->hrtimer)
271 270 );
272 271  
273 272 /**
... ... @@ -302,7 +301,7 @@
302 301 __entry->interval_usec = value->it_interval.tv_usec;
303 302 ),
304 303  
305   - TP_printk("which %d, expires %lu, it_value %lu.%lu, it_interval %lu.%lu",
  304 + TP_printk("which=%d expires=%lu it_value=%lu.%lu it_interval=%lu.%lu",
306 305 __entry->which, __entry->expires,
307 306 __entry->value_sec, __entry->value_usec,
308 307 __entry->interval_sec, __entry->interval_usec)
... ... @@ -332,7 +331,7 @@
332 331 __entry->pid = pid_nr(pid);
333 332 ),
334 333  
335   - TP_printk("which %d, pid %d, now %lu", __entry->which,
  334 + TP_printk("which=%d pid=%d now=%lu", __entry->which,
336 335 (int) __entry->pid, __entry->now)
337 336 );
338 337