Re: [PATCH v2] perf record: Synthesize COMM event for a command line workload

[Namhyung Kim]

Hi Arnaldo,

On Tue, Sep 22, 2015 at 04:48:25PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Tue, Sep 22, 2015 at 04:25:34PM -0300, Arnaldo Carvalho de Melo escreveu:
> > 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.

OK

> > 
> > 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.

Thanks

> 
> Humm, I think it is working by accident, as you're not allocating space
> for machine->id_hdr_size, please take a look at
> perf_event__synthesize_thread_map().
> 
> Right now its not a problem this line in perf_event__prepare_comm():
> 
>         memset(event->comm.comm + size, 0, machine->id_hdr_size);
> 
> Because perf_event is an union and some of its elements, like mmap/mmap2
> have that PATH_MAX part, but its just a matter of the id_hdr_size
> becoming bigger than that and we'll have a problem...

Right. I'll send a fix to include the id_hdr part.


> 
> That zero there is probably because we're not synthesizing the
> PERF_SAMPLE_ part, that would be encoded in this id_hdr_size area, we're
> zeroing it all and then when showing it in perf script, we see zeros.
> 
> Would be good to do that, will try if you don't do it first 8-)

So do you want to generate the PERF_SAMPLE_ part for all synthesized events?

> 
> But have some other stuff to do first :-)

:)

Thanks,
Namhyung
--
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/