Messages in this thread | | | Date | Wed, 23 Sep 2015 11:49:59 +0900 | From | Namhyung Kim <> | Subject | Re: [PATCH v2] perf record: Synthesize COMM event for a command line workload |
| |
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
| |