| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20150923024959.GA13029@sejong>
Date: Wed, 23 Sep 2015 11:49:59 +0900
From: Namhyung Kim <namhyung@...nel.org>
To: Arnaldo Carvalho de Melo <acme@...nel.org>
Cc: Ingo Molnar <mingo@...nel.org>,
Peter Zijlstra <a.p.zijlstra@...llo.nl>,
Jiri Olsa <jolsa@...hat.com>,
LKML <linux-kernel@...r.kernel.org>,
David Ahern <dsahern@...il.com>
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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists