Messages in this thread Patch in this message | | | Date | Tue, 22 Sep 2015 16:25:34 -0300 | From | Arnaldo Carvalho de Melo <> | Subject | Re: [PATCH v2] perf record: Synthesize COMM event for a command line workload |
| |
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@kernel.org> > --- > 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
| |