Skip to content

Commit

Permalink
events: Harmonize event field names and print output names
Browse files Browse the repository at this point in the history 
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>
  • Loading branch information
Ingo Molnar committed Oct 15, 2009
1 parent a66abe7 commit 434a83c
Show file tree
Hide file tree
Showing 5 changed files with 74 additions and 77 deletions.
18 changes: 9 additions & 9 deletions include/trace/events/bkl.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -13,21 +13,21 @@ TRACE_EVENT(lock_kernel,
TP_ARGS(func, file, line),

TP_STRUCT__entry(
__field( int, lock_depth )
__field( int, depth )
__field_ext( const char *, func, FILTER_PTR_STRING )
__field_ext( const char *, file, FILTER_PTR_STRING )
__field( int, line )
),

TP_fast_assign(
/* We want to record the lock_depth after lock is acquired */
__entry->lock_depth = current->lock_depth + 1;
__entry->depth = current->lock_depth + 1;
__entry->func = func;
__entry->file = file;
__entry->line = line;
),

TP_printk("depth: %d, %s:%d %s()", __entry->lock_depth,
TP_printk("depth=%d file:line=%s:%d func=%s()", __entry->depth,
__entry->file, __entry->line, __entry->func)
);

Expand All @@ -38,20 +38,20 @@ TRACE_EVENT(unlock_kernel,
TP_ARGS(func, file, line),

TP_STRUCT__entry(
__field(int, lock_depth)
__field(const char *, func)
__field(const char *, file)
__field(int, line)
__field(int, depth )
__field(const char *, func )
__field(const char *, file )
__field(int, line )
),

TP_fast_assign(
__entry->lock_depth = current->lock_depth;
__entry->depth = current->lock_depth;
__entry->func = func;
__entry->file = file;
__entry->line = line;
),

TP_printk("depth: %d, %s:%d %s()", __entry->lock_depth,
TP_printk("depth=%d file:line=%s:%d func=%s()", __entry->depth,
__entry->file, __entry->line, __entry->func)
);

Expand Down
8 changes: 4 additions & 4 deletions include/trace/events/irq.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,7 @@ TRACE_EVENT(irq_handler_entry,
__assign_str(name, action->name);
),

TP_printk("irq=%d handler=%s", __entry->irq, __get_str(name))
TP_printk("irq=%d name=%s", __entry->irq, __get_str(name))
);

/**
Expand Down Expand Up @@ -78,7 +78,7 @@ TRACE_EVENT(irq_handler_exit,
__entry->ret = ret;
),

TP_printk("irq=%d return=%s",
TP_printk("irq=%d ret=%s",
__entry->irq, __entry->ret ? "handled" : "unhandled")
);

Expand Down Expand Up @@ -107,7 +107,7 @@ TRACE_EVENT(softirq_entry,
__entry->vec = (int)(h - vec);
),

TP_printk("softirq=%d action=%s", __entry->vec,
TP_printk("vec=%d [action=%s]", __entry->vec,
show_softirq_name(__entry->vec))
);

Expand Down Expand Up @@ -136,7 +136,7 @@ TRACE_EVENT(softirq_exit,
__entry->vec = (int)(h - vec);
),

TP_printk("softirq=%d action=%s", __entry->vec,
TP_printk("vec=%d [action=%s]", __entry->vec,
show_softirq_name(__entry->vec))
);

Expand Down
2 changes: 0 additions & 2 deletions include/trace/events/power.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,8 +16,6 @@ enum {
};
#endif



TRACE_EVENT(power_start,

TP_PROTO(unsigned int type, unsigned int state),
Expand Down
44 changes: 22 additions & 22 deletions include/trace/events/sched.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,7 +26,7 @@ TRACE_EVENT(sched_kthread_stop,
__entry->pid = t->pid;
),

TP_printk("task %s:%d", __entry->comm, __entry->pid)
TP_printk("comm=%s pid=%d", __entry->comm, __entry->pid)
);

/*
Expand All @@ -46,7 +46,7 @@ TRACE_EVENT(sched_kthread_stop_ret,
__entry->ret = ret;
),

TP_printk("ret %d", __entry->ret)
TP_printk("ret=%d", __entry->ret)
);

/*
Expand All @@ -73,7 +73,7 @@ TRACE_EVENT(sched_wait_task,
__entry->prio = p->prio;
),

TP_printk("task %s:%d [%d]",
TP_printk("comm=%s pid=%d prio=%d",
__entry->comm, __entry->pid, __entry->prio)
);

Expand All @@ -94,20 +94,20 @@ TRACE_EVENT(sched_wakeup,
__field( pid_t, pid )
__field( int, prio )
__field( int, success )
__field( int, cpu )
__field( int, target_cpu )
),

TP_fast_assign(
memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
__entry->pid = p->pid;
__entry->prio = p->prio;
__entry->success = success;
__entry->cpu = task_cpu(p);
__entry->target_cpu = task_cpu(p);
),

TP_printk("task %s:%d [%d] success=%d [%03d]",
TP_printk("comm=%s pid=%d prio=%d success=%d target_cpu=%03d",
__entry->comm, __entry->pid, __entry->prio,
__entry->success, __entry->cpu)
__entry->success, __entry->target_cpu)
);

/*
Expand All @@ -127,20 +127,20 @@ TRACE_EVENT(sched_wakeup_new,
__field( pid_t, pid )
__field( int, prio )
__field( int, success )
__field( int, cpu )
__field( int, target_cpu )
),

TP_fast_assign(
memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
__entry->pid = p->pid;
__entry->prio = p->prio;
__entry->success = success;
__entry->cpu = task_cpu(p);
__entry->target_cpu = task_cpu(p);
),

TP_printk("task %s:%d [%d] success=%d [%03d]",
TP_printk("comm=%s pid=%d prio=%d success=%d target_cpu=%03d",
__entry->comm, __entry->pid, __entry->prio,
__entry->success, __entry->cpu)
__entry->success, __entry->target_cpu)
);

/*
Expand Down Expand Up @@ -176,7 +176,7 @@ TRACE_EVENT(sched_switch,
__entry->next_prio = next->prio;
),

TP_printk("task %s:%d [%d] (%s) ==> %s:%d [%d]",
TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s ==> next_comm=%s next_pid=%d next_prio=%d",
__entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
__entry->prev_state ?
__print_flags(__entry->prev_state, "|",
Expand Down Expand Up @@ -211,7 +211,7 @@ TRACE_EVENT(sched_migrate_task,
__entry->dest_cpu = dest_cpu;
),

TP_printk("task %s:%d [%d] from: %d to: %d",
TP_printk("comm=%s pid=%d prio=%d orig_cpu=%d dest_cpu=%d",
__entry->comm, __entry->pid, __entry->prio,
__entry->orig_cpu, __entry->dest_cpu)
);
Expand All @@ -237,7 +237,7 @@ TRACE_EVENT(sched_process_free,
__entry->prio = p->prio;
),

TP_printk("task %s:%d [%d]",
TP_printk("comm=%s pid=%d prio=%d",
__entry->comm, __entry->pid, __entry->prio)
);

Expand All @@ -262,7 +262,7 @@ TRACE_EVENT(sched_process_exit,
__entry->prio = p->prio;
),

TP_printk("task %s:%d [%d]",
TP_printk("comm=%s pid=%d prio=%d",
__entry->comm, __entry->pid, __entry->prio)
);

Expand All @@ -287,7 +287,7 @@ TRACE_EVENT(sched_process_wait,
__entry->prio = current->prio;
),

TP_printk("task %s:%d [%d]",
TP_printk("comm=%s pid=%d prio=%d",
__entry->comm, __entry->pid, __entry->prio)
);

Expand All @@ -314,7 +314,7 @@ TRACE_EVENT(sched_process_fork,
__entry->child_pid = child->pid;
),

TP_printk("parent %s:%d child %s:%d",
TP_printk("comm=%s pid=%d child_comm=%s child_pid=%d",
__entry->parent_comm, __entry->parent_pid,
__entry->child_comm, __entry->child_pid)
);
Expand All @@ -340,7 +340,7 @@ TRACE_EVENT(sched_signal_send,
__entry->sig = sig;
),

TP_printk("sig: %d task %s:%d",
TP_printk("sig=%d comm=%s pid=%d",
__entry->sig, __entry->comm, __entry->pid)
);

Expand Down Expand Up @@ -374,7 +374,7 @@ TRACE_EVENT(sched_stat_wait,
__perf_count(delay);
),

TP_printk("task: %s:%d wait: %Lu [ns]",
TP_printk("comm=%s pid=%d delay=%Lu [ns]",
__entry->comm, __entry->pid,
(unsigned long long)__entry->delay)
);
Expand Down Expand Up @@ -406,7 +406,7 @@ TRACE_EVENT(sched_stat_runtime,
__perf_count(runtime);
),

TP_printk("task: %s:%d runtime: %Lu [ns], vruntime: %Lu [ns]",
TP_printk("comm=%s pid=%d runtime=%Lu [ns] vruntime=%Lu [ns]",
__entry->comm, __entry->pid,
(unsigned long long)__entry->runtime,
(unsigned long long)__entry->vruntime)
Expand Down Expand Up @@ -437,7 +437,7 @@ TRACE_EVENT(sched_stat_sleep,
__perf_count(delay);
),

TP_printk("task: %s:%d sleep: %Lu [ns]",
TP_printk("comm=%s pid=%d delay=%Lu [ns]",
__entry->comm, __entry->pid,
(unsigned long long)__entry->delay)
);
Expand Down Expand Up @@ -467,7 +467,7 @@ TRACE_EVENT(sched_stat_iowait,
__perf_count(delay);
),

TP_printk("task: %s:%d iowait: %Lu [ns]",
TP_printk("comm=%s pid=%d delay=%Lu [ns]",
__entry->comm, __entry->pid,
(unsigned long long)__entry->delay)
);
Expand Down
Loading

0 comments on commit 434a83c

Please sign in to comment.