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

[Arnaldo Carvalho de Melo]

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

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

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

But have some other stuff to do first :-)

- Arnaldo
--
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/