Skip to content

Commit

Permalink
perf trace: Introduce per-event maximum number of events property
Browse files Browse the repository at this point in the history 
Call it 'nr', as in this context it should be expressive enough, i.e.:

  # perf trace -e sched:*waking/nr=8,call-graph=fp/
     0.000 :0/0 sched:sched_waking:comm=rcu_sched pid=10 prio=120 target_cpu=001
                                       try_to_wake_up ([kernel.kallsyms])
                                       sched_clock ([kernel.kallsyms])
     3.933 :0/0 sched:sched_waking:comm=rcu_sched pid=10 prio=120 target_cpu=001
                                       try_to_wake_up ([kernel.kallsyms])
                                       sched_clock ([kernel.kallsyms])
     3.970 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                       try_to_wake_up ([kernel.kallsyms])
                                       __libc_write (/usr/lib64/libpthread-2.26.so)
    20.069 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                       try_to_wake_up ([kernel.kallsyms])
                                       __libc_write (/usr/lib64/libpthread-2.26.so)
    37.170 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                       try_to_wake_up ([kernel.kallsyms])
                                       __libc_write (/usr/lib64/libpthread-2.26.so)
    53.267 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                       try_to_wake_up ([kernel.kallsyms])
                                       __libc_write (/usr/lib64/libpthread-2.26.so)
    70.365 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                       try_to_wake_up ([kernel.kallsyms])
                                       __libc_write (/usr/lib64/libpthread-2.26.so)
    75.781 Web Content/3649 sched:sched_waking:comm=JS Helper pid=3670 prio=120 target_cpu=000
                                       try_to_wake_up ([kernel.kallsyms])
                                       try_to_wake_up ([kernel.kallsyms])
                                       wake_up_q ([kernel.kallsyms])
                                       futex_wake ([kernel.kallsyms])
                                       do_futex ([kernel.kallsyms])
                                       __x64_sys_futex ([kernel.kallsyms])
                                       do_syscall_64 ([kernel.kallsyms])
                                       entry_SYSCALL_64_after_hwframe ([kernel.kallsyms])
                                       pthread_cond_signal@@GLIBC_2.3.2 (/usr/lib64/libpthread-2.26.so)
  #

  # perf trace -e sched:*switch/nr=2/,block:*_plug/nr=4/,block:*_unplug/nr=1/,net:*dev_queue/nr=3,max-stack=16/
     0.000 :0/0 sched:sched_switch:swapper/0:0 [120] S ==> trace:3367 [120]
     0.046 :0/0 sched:sched_switch:swapper/1:0 [120] S ==> kworker/u16:58:2722 [120]
   570.670 irq/50-iwlwifi/680 net:net_dev_queue:dev=wlp3s0 skbaddr=0xffff93498051ef00 len=66
                                       __dev_queue_xmit ([kernel.kallsyms])
  1106.141 jbd2/dm-0-8/476 block:block_plug:[jbd2/dm-0-8]
  1106.175 jbd2/dm-0-8/476 block:block_unplug:[jbd2/dm-0-8] 1
  1618.088 kworker/u16:30/2694 block:block_plug:[kworker/u16:30]
  1810.000 :0/0 net:net_dev_queue:dev=vnet0 skbaddr=0xffff93498051ef00 len=52
                                       __dev_queue_xmit ([kernel.kallsyms])
  3857.974 :0/0 net:net_dev_queue:dev=vnet0 skbaddr=0xffff93498051f900 len=52
                                       __dev_queue_xmit ([kernel.kallsyms])
  4790.277 jbd2/dm-2-8/748 block:block_plug:[jbd2/dm-2-8]
  4790.448 jbd2/dm-2-8/748 block:block_plug:[jbd2/dm-2-8]
  #

The global --max-events has precendence:

  # trace --max-events 3 -e sched:*switch/nr=2/,block:*_plug/nr=4/,block:*_unplug/nr=1/,net:*dev_queue/nr=3,max-stack=16/
     0.000 :0/0 sched:sched_switch:swapper/0:0 [120] S ==> qemu-system-x86:2252 [120]
     0.029 qemu-system-x8/2252 sched:sched_switch:qemu-system-x86:2252 [120] D ==> swapper/0:0 [120]
    58.047 DNS Res~er #14/31661 net:net_dev_queue:dev=wlp3s0 skbaddr=0xffff9346966af100 len=84
                                       __dev_queue_xmit ([kernel.kallsyms])
                                       __libc_send (/usr/lib64/libpthread-2.26.so)
  #

Cc: Adrian Hunter <[email protected]>
Cc: David Ahern <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Cc: Wang Nan <[email protected]>
Link: https://lkml.kernel.org/n/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
  • Loading branch information
@acmel
acmel committed Oct 22, 2018
1 parent 7ee4067 commit a9c5e6c
Show file tree
Hide file tree
Showing 3 changed files with 38 additions and 2 deletions.
20 changes: 20 additions & 0 deletions tools/perf/Documentation/perf-trace.txt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -285,6 +285,26 @@ Trace the next min page page fault to take place on the first CPU:
[0x18b26e6bc2bd] (/tmp/perf-17136.map)
#

Trace the next two sched:sched_switch events, four block:*_plug events, the
next block:*_unplug and the next three net:*dev_queue events, this last one
with a backtrace of at most 16 entries, system wide:

# perf trace -e sched:*switch/nr=2/,block:*_plug/nr=4/,block:*_unplug/nr=1/,net:*dev_queue/nr=3,max-stack=16/
0.000 :0/0 sched:sched_switch:swapper/2:0 [120] S ==> rcu_sched:10 [120]
0.015 rcu_sched/10 sched:sched_switch:rcu_sched:10 [120] R ==> swapper/2:0 [120]
254.198 irq/50-iwlwifi/680 net:net_dev_queue:dev=wlp3s0 skbaddr=0xffff93498051f600 len=66
__dev_queue_xmit ([kernel.kallsyms])
273.977 :0/0 net:net_dev_queue:dev=wlp3s0 skbaddr=0xffff93498051f600 len=78
__dev_queue_xmit ([kernel.kallsyms])
274.007 :0/0 net:net_dev_queue:dev=wlp3s0 skbaddr=0xffff93498051ff00 len=78
__dev_queue_xmit ([kernel.kallsyms])
2930.140 kworker/u16:58/2722 block:block_plug:[kworker/u16:58]
2930.162 kworker/u16:58/2722 block:block_unplug:[kworker/u16:58] 1
4466.094 jbd2/dm-2-8/748 block:block_plug:[jbd2/dm-2-8]
8050.123 kworker/u16:30/2694 block:block_plug:[kworker/u16:30]
8050.271 kworker/u16:30/2694 block:block_plug:[kworker/u16:30]
#

SEE ALSO
--------
linkperf:perf-record[1], linkperf:perf-script[1]
19 changes: 17 additions & 2 deletions tools/perf/builtin-trace.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2092,8 +2092,18 @@ static int trace__event_handler(struct trace *trace, struct perf_evsel *evsel,
union perf_event *event __maybe_unused,
struct perf_sample *sample)
{
struct thread *thread = machine__findnew_thread(trace->host, sample->pid, sample->tid);
struct thread *thread;
int callchain_ret = 0;
/*
* Check if we called perf_evsel__disable(evsel) due to, for instance,
* this event's max_events having been hit and this is an entry coming
* from the ring buffer that we should discard, since the max events
* have already been considered/printed.
*/
if (evsel->disabled)
return 0;

thread = machine__findnew_thread(trace->host, sample->pid, sample->tid);

if (sample->callchain) {
callchain_ret = trace__resolve_callchain(trace, evsel, sample, &callchain_cursor);
Expand Down Expand Up @@ -2142,6 +2152,11 @@ static int trace__event_handler(struct trace *trace, struct perf_evsel *evsel,
sample->raw_data, sample->raw_size,
trace->output);
++trace->nr_events_printed;

if (evsel->max_events != ULONG_MAX && ++evsel->nr_events_printed == evsel->max_events) {
perf_evsel__disable(evsel);
perf_evsel__close(evsel);
}
}
}

Expand Down Expand Up @@ -2726,7 +2741,7 @@ static int trace__run(struct trace *trace, int argc, const char **argv)
int timeout = done ? 100 : -1;

if (!draining && perf_evlist__poll(evlist, timeout) > 0) {
if (perf_evlist__filter_pollfd(evlist, POLLERR | POLLHUP) == 0)
if (perf_evlist__filter_pollfd(evlist, POLLERR | POLLHUP | POLLNVAL) == 0)
draining = true;

goto again;
Expand Down
1 change: 1 addition & 0 deletions tools/perf/util/evsel.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -102,6 +102,7 @@ struct perf_evsel {
int idx;
u32 ids;
unsigned long max_events;
unsigned long nr_events_printed;
char *name;
double scale;
const char *unit;
Expand Down

0 comments on commit a9c5e6c

Please sign in to comment.