Re: [RFC PATCH] perf session: Fixup timestamp for ordered events
From: Leo Yan
Date: Wed Nov 18 2020 - 06:43:32 EST
Hi Adrian,
On Wed, Nov 18, 2020 at 01:15:32PM +0200, Adrian Hunter wrote:
> On 18/11/20 12:55 pm, Leo Yan wrote:
> > Perf tool relies on MMAP/MMAP2 events to prepare DSO maps, it allocates
> > DSO maps for MMAP/MMAP2 events which is used for parsing symbol. Thus,
> > during the recording, perf tool implictly expects the MMAP/MMAP2 events
> > should arrive before AUX event,
>
> No it doesn't. There is an index and queues to queue PERF_RECORD_AUXTRACE
> events in advance so that they can be processed in time order.
>
> in other words, MMAP/MMAP2's timestamp
> > should less than AUX event's timestamp, and the MMAP/MMAP2 events will
> > be added into the front of ordered event list; this can allow the DSO
> > maps to be prepared and can be consumed when process AUX event.
> >
> > See the function perf_evlist__prepare_workload(), though it uses pipes
> > to handshake before perf process (the parent process) and forked process
> > for the profiled program, it cannot promise the timing between
> > MMAP/MMAP2 events and AUX event.
> >
> > On Arm Juno board, the AUX event can be observed to arrive ahead than
> > MMAP2 event, with the command:
> >
> > perf record -e cs_etm/@tmc_etr0/ -S -- dd if=/dev/zero of=/dev/null
> >
> > The follow diagram depicts the flow for how the AUX event is arriving
> > ahead than MMAP2 event:
> >
> > T1: T3: T4:
> > perf process Open PMU device Perf is scheduled out;
> > invoke perf_aux_output_end()
> > and generate AUX event
> > ^ ^ ^
> > | | |
> > CPU0 ---------------------------------------------------> (T)
> > \
> > \ Forked process is placed on another CPU
> > V
> > CPU1 ---------------------------------------------------> (T)
> > | |
> > V V
> > T2: T5:
> > Invoke execvp() for profiled Record MMAP2 event
> > program
>
> I don't understand. An MMAP at T5 cannot affect data recorded before T5
> (e.g. T4).
> Are you saying the timestamps from different CPUs are not in time order? Ot
> are you saying the data is actually recorded after T5?
Here refers to the later one.
I observed the PMU device is opened and closed for multiple times, so
the AUX events and MMAP2 events are interleave with each other. Below
is the dumping with debugging option "--debug ordered-events=1" (and I
added code for printing out event type value).
When perf tool starts to decode the trace data for the first AUX event
(its timestamp is 160.767623) and try to synthesize samples, it doesn't
give chance for handling the sequential MMAP2 events (ts: 160.770223,
160.770451, 160.773111).
[ 160.765623] queue_event nr_events 1
[ 160.765623] new event on queue: type=12
[ 160.765714] queue_event nr_events 2
[ 160.765714] new event on queue: type=3
[ 160.765822] queue_event nr_events 3
[ 160.765822] new event on queue: type=10 ==> MMAP2 event
[ 160.766180] queue_event nr_events 4
[ 160.766180] new event on queue: type=14
[ 160.767623] queue_event nr_events 5
[ 160.767623] new event on queue: type=11 ==> AUX event
[ 160.769710] queue_event nr_events 6
[ 160.769710] new event on queue: type=12
[ 160.769762] queue_event nr_events 7
[ 160.769762] new event on queue: type=14
[ 160.769810] queue_event nr_events 8
[ 160.769810] new event on queue: type=14
[ 160.769943] queue_event nr_events 9
[ 160.769943] new event on queue: type=11 ==> AUX event
[ 160.770028] queue_event nr_events 10
[ 160.770028] new event on queue: type=12
[ 160.770073] queue_event nr_events 11
[ 160.770073] new event on queue: type=14
[ 160.770223] queue_event nr_events 12
[ 160.770223] new event on queue: type=10 ==> MMAP2 event
[ 160.770451] queue_event nr_events 13
[ 160.770451] new event on queue: type=10 ==> MMAP2 event
[ 160.770628] queue_event nr_events 14
[ 160.770628] new event on queue: type=14
[ 160.771650] queue_event nr_events 15
[ 160.771650] new event on queue: type=11 ==> AUX event
[ 160.771752] queue_event nr_events 16
[ 160.771752] new event on queue: type=12
[ 160.771798] queue_event nr_events 17
[ 160.771798] new event on queue: type=14
[ 160.773111] queue_event nr_events 18
[ 160.773111] new event on queue: type=10 ==> MMAP2 event
[ 160.782613] queue_event nr_events 19
[ 160.782613] new event on queue: type=14
Thanks for the reviewing,
Leo
> > In this scenario, the perf main process runs on CPU0 and the profiled
> > program (which is forked child process) runs on CPU1. The main process
> > opens PMU device for AUX trace (T3) and it will generate AUX event until
> > the perf process is scheduled out (T4); the profiled program will be
> > launched by execvp() (T2) and later will record MMAP event for memory
> > mapping (T5).
> >
> > Usually, the AUX event will be later than MMAP2 event, but on the Arm
> > Juno platform, it has chance that AUX event occurs prior to MMAP2 event
> > with two reasons:
> >
> > - Arm Juno platform is big.LITTLE architecture, so CPU0 is big CPU and
> > CPU1 is LITTLE CPU, the performance between big CPU and LITTLE CPU is
> > significant, this gives chance for the perf main process to run much
> > faster than the profiled program;
> >
> > - In the kernel, the RT thread (like kernel's CPUFreq thread) has chance
> > to preempt perf main thread, so when the perf main thread is
> > switched out, the AUX event will be generated and it might be early
> > than profiled program's MMAP2 event.
> >
> > To fix this issue, this patch records the first AUX event's timestamp
> > into 'aux_timestamp', if find any MMAP/MMAP2 event is late coming, it
> > fixes up the MMAP/MMAP2 events' timestamp as 'aux_timestamp-1', so the
> > MMAP/MMAP2 event will be inserted into ordered list ahead than AUX event
> > and also will be handled before AUX event.
> >
> > Signed-off-by: Leo Yan <leo.yan@xxxxxxxxxx>
> > ---
> > tools/perf/util/session.c | 25 +++++++++++++++++++++++++
> > 1 file changed, 25 insertions(+)
> >
> > diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
> > index 098080287c68..1aa54941bf81 100644
> > --- a/tools/perf/util/session.c
> > +++ b/tools/perf/util/session.c
> > @@ -1753,11 +1753,36 @@ static s64 perf_session__process_event(struct perf_session *session,
> >
> > if (tool->ordered_events) {
> > u64 timestamp = -1ULL;
> > + static u64 aux_timestamp = -1ULL;
> >
> > ret = perf_evlist__parse_sample_timestamp(evlist, event, ×tamp);
> > if (ret && ret != -1)
> > return ret;
> >
> > + /*
> > + * Cache the first AUX event's timestamp into 'aux_timestamp',
> > + * which is used to fixup MMAP/MMAP2's timestamp.
> > + */
> > + if ((event->header.type == PERF_RECORD_AUX) &&
> > + (aux_timestamp == -1ULL))
> > + aux_timestamp = timestamp;
> > +
> > + /*
> > + * If the AUX event arrives prior to MMAP/MMAP2 events, it's
> > + * possible to have no chance to create DSOs when decode AUX
> > + * trace data, thus the symbol cannot be parsed properly.
> > + * To allow the DSOs are prepared before process AUX event,
> > + * fixup the MMAP/MMAP2 events' timestamp to be prior to any
> > + * AUX event's timestamp, so MMAP/MMAP2 events will be
> > + * handled ahead and the DSO map will be prepared before AUX
> > + * event handling.
> > + */
> > + if (event->header.type == PERF_RECORD_MMAP2 ||
> > + event->header.type == PERF_RECORD_MMAP) {
> > + if (timestamp > aux_timestamp)
> > + timestamp = aux_timestamp - 1;
> > + }
> > +
> > ret = perf_session__queue_event(session, event, timestamp, file_offset);
> > if (ret != -ETIME)
> > return ret;
> >
>