Re: [PATCH v2] perf record: Synthesize COMM event for a command line workload
From: Arnaldo Carvalho de Melo
Date: Tue Sep 22 2015 - 15:25:47 EST
Em Tue, Sep 22, 2015 at 09:24:55AM +0900, Namhyung Kim escreveu:
> When perf creates a new child to profile, the events are enabled on
> exec(). And in this case, it doesn't synthesize any event for the
> child since they'll be generated during exec(). But there's an window
> between the enabling and the event generation.
>
> It used to be overcome since samples are only in kernel (so we always
> have the map) and the comm is overridden by a later COMM event.
> However it won't work if events are processed and displayed before the
> COMM event overrides like in 'perf script'. This leads to those early
> samples (like native_write_msr_safe) not having a comm but pid (like
> ':15328').
>
> So it needs to synthesize COMM event for the child explicitly before
> enabling so that it can have a correct comm. But at this time, the
> comm will be "perf" since it's not exec-ed yet.
Don't we use enable-on-exec?
# perf record usleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.017 MB perf.data (7 samples) ]
# perf evlist -v
cycles: size: 112, { sample_period, sample_freq }: 4000, sample_type:
IP|TID|TIME|PERIOD, disabled: 1, inherit: 1, mmap: 1, comm: 1, freq: 1,
enable_on_exec: 1, task: 1, sample_id_all: 1, exclude_guest: 1, mmap2:
1, comm_exec: 1
#
Ok, but even then, if we use --show-task-events, we see that the comm
appears only later...
# perf script --show-task-events
:4429 4429 27909.079372: 1 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
:4429 4429 27909.079375: 1 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
:4429 4429 27909.079376: 10 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
:4429 4429 27909.079377: 223 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
:4429 4429 27909.079378: 6571 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
usleep 4429 27909.079380: PERF_RECORD_COMM exec: usleep:4429/4429
usleep 4429 27909.079381: 185403 cycles: ffffffff810a72d3 flush_signal_handlers (/lib/modules/4.
usleep 4429 27909.079444: 2241110 cycles: 7fc575355be3 _dl_start (/usr/lib64/ld-2.20.so)
usleep 4429 27909.079875: PERF_RECORD_EXIT(4429:4429):(4429:4429)
While with your patch we see:
# perf record usleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.017 MB perf.data (7 samples) ]
# perf script --show-task-events
perf 0 0.000000: PERF_RECORD_COMM: perf:6571/6571
perf 6571 28378.609330: 1 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
perf 6571 28378.609334: 1 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
perf 6571 28378.609335: 7 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
perf 6571 28378.609336: 163 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
perf 6571 28378.609337: 4795 cycles: ffffffff8105f45a native_write_msr_safe (/lib/modules/4.
perf 6571 28378.609340: 119283 cycles: ffffffff81189bdd perf_event_comm_output (/lib/modules/4
usleep 6571 28378.609340: PERF_RECORD_COMM exec: usleep:6571/6571
usleep 6571 28378.609380: 1900804 cycles: ffffffff810a0b40 find_next_iomem_res (/lib/modules/4.3.
usleep 6571 28378.609879: PERF_RECORD_EXIT(6571:6571):(6571:6571)
Better indeed, I'm adding this before/after so that the changeset comment
can fully illustrate what happens.
But you see there is still a problem with that synthesized COMM, right? the one
coming from the kernel has the 6571 there, while the synthesized one doesn't...
Checking...
But I'll apply your patch.
- Arnaldo
> Signed-off-by: Namhyung Kim <namhyung@xxxxxxxxxx>
> ---
> tools/perf/builtin-record.c | 16 +++++++++++++++-
> tools/perf/util/event.c | 2 +-
> tools/perf/util/event.h | 5 +++++
> 3 files changed, 21 insertions(+), 2 deletions(-)
>
> diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
> index 142eeb341b29..6d8302d4612f 100644
> --- a/tools/perf/builtin-record.c
> +++ b/tools/perf/builtin-record.c
> @@ -636,8 +636,22 @@ static int __cmd_record(struct record *rec, int argc, const char **argv)
> /*
> * Let the child rip
> */
> - if (forks)
> + if (forks) {
> + union perf_event event;
> +
> + /*
> + * Some H/W events are generated before COMM event
> + * which is emitted during exec(), so perf script
> + * cannot see a correct process name for those events.
> + * Synthesize COMM event to prevent it.
> + */
> + perf_event__synthesize_comm(tool, &event,
> + rec->evlist->workload.pid,
> + process_synthesized_event,
> + &session->machines.host);
> +
> perf_evlist__start_workload(rec->evlist);
> + }
>
> if (opts->initial_delay) {
> usleep(opts->initial_delay * 1000);
> diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
> index 497157affc9c..6214ad47d554 100644
> --- a/tools/perf/util/event.c
> +++ b/tools/perf/util/event.c
> @@ -167,7 +167,7 @@ static int perf_event__prepare_comm(union perf_event *event, pid_t pid,
> return 0;
> }
>
> -static pid_t perf_event__synthesize_comm(struct perf_tool *tool,
> +pid_t perf_event__synthesize_comm(struct perf_tool *tool,
> union perf_event *event, pid_t pid,
> perf_event__handler_t process,
> struct machine *machine)
> diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
> index f729df5e25e6..be5cbc7be889 100644
> --- a/tools/perf/util/event.h
> +++ b/tools/perf/util/event.h
> @@ -478,6 +478,11 @@ int perf_event__synthesize_sample(union perf_event *event, u64 type,
> const struct perf_sample *sample,
> bool swapped);
>
> +pid_t perf_event__synthesize_comm(struct perf_tool *tool,
> + union perf_event *event, pid_t pid,
> + perf_event__handler_t process,
> + struct machine *machine);
> +
> int perf_event__synthesize_mmap_events(struct perf_tool *tool,
> union perf_event *event,
> pid_t pid, pid_t tgid,
> --
> 2.5.0
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/