Commit f61ff6c0 authored by Jiri Olsa's avatar Jiri Olsa Committed by Arnaldo Carvalho de Melo

perf session: Do not fail on processing out of order event

Linus reported perf report command being interrupted due to processing
of 'out of order' event, with following error:

  Timestamp below last timeslice flush
  0x5733a8 [0x28]: failed to process type: 3

I could reproduce the issue and in my case it was caused by one CPU
(mmap) being behind during record and userspace mmap reader seeing the
data after other CPUs data were already stored.

This is expected under some circumstances because we need to limit the
number of events that we queue for reordering when we receive a
PERF_RECORD_FINISHED_ROUND or when we force flush due to memory
pressure.
Reported-by: default avatarLinus Torvalds <torvalds@linux-foundation.org>
Signed-off-by: default avatarJiri Olsa <jolsa@kernel.org>
Acked-by: default avatarIngo Molnar <mingo@kernel.org>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Corey Ashford <cjashfor@linux.vnet.ibm.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Matt Fleming <matt.fleming@intel.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/1417016371-30249-1-git-send-email-jolsa@kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
parent 7ddc6a21
...@@ -214,6 +214,7 @@ struct events_stats { ...@@ -214,6 +214,7 @@ struct events_stats {
u32 nr_invalid_chains; u32 nr_invalid_chains;
u32 nr_unknown_id; u32 nr_unknown_id;
u32 nr_unprocessable_samples; u32 nr_unprocessable_samples;
u32 nr_unordered_events;
}; };
struct attr_event { struct attr_event {
......
...@@ -521,15 +521,11 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event, ...@@ -521,15 +521,11 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
return -ETIME; return -ETIME;
if (timestamp < oe->last_flush) { if (timestamp < oe->last_flush) {
WARN_ONCE(1, "Timestamp below last timeslice flush\n"); pr_oe_time(timestamp, "out of order event\n");
pr_oe_time(timestamp, "out of order event");
pr_oe_time(oe->last_flush, "last flush, last_flush_type %d\n", pr_oe_time(oe->last_flush, "last flush, last_flush_type %d\n",
oe->last_flush_type); oe->last_flush_type);
/* We could get out of order messages after forced flush. */ s->stats.nr_unordered_events++;
if (oe->last_flush_type != OE_FLUSH__HALF)
return -EINVAL;
} }
new = ordered_events__new(oe, timestamp, event); new = ordered_events__new(oe, timestamp, event);
...@@ -1057,6 +1053,9 @@ static void perf_session__warn_about_errors(const struct perf_session *session, ...@@ -1057,6 +1053,9 @@ static void perf_session__warn_about_errors(const struct perf_session *session,
"Do you have a KVM guest running and not using 'perf kvm'?\n", "Do you have a KVM guest running and not using 'perf kvm'?\n",
session->stats.nr_unprocessable_samples); session->stats.nr_unprocessable_samples);
} }
if (session->stats.nr_unordered_events != 0)
ui__warning("%u out of order events recorded.\n", session->stats.nr_unordered_events);
} }
volatile int session_done; volatile int session_done;
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment