perf tools: 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.

It'd be nice to find the source of this hiccup, meanwhile I'm submitting change that does not kill the processing, but only tracks the number of out of order events and warn user.

Reported-by Linus Torvalds <[email protected]>

Cc Linus Torvalds <[email protected]>

Cc Andi Kleen <[email protected]>

Cc Corey Ashford <[email protected]>

Cc David Ahern <[email protected]>

Cc Frederic Weisbecker <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Matt Fleming <[email protected]>

Cc Namhyung Kim <[email protected]>

Cc Paul Mackerras <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc Stephane Eranian <[email protected]>

Cc Arnaldo Carvalho de Melo <[email protected]>

Signed-off-by Jiri Olsa <[email protected]>

---
 tools/perf/util/event.h   |  1 +
 tools/perf/util/session.c | 13 +++++++------
 2 files changed, 8 insertions(+), 6 deletions(-)

tools/perf/util/event.h +1 -0

index 09b9e8d3fcf7..c4ffe2bd0738 100644
@@ -242,6 +242,7 @@ struct events_stats {
 	u32 nr_invalid_chains;
 	u32 nr_unknown_id;
 	u32 nr_unprocessable_samples;
+	u32 nr_unordered_events;
 };
 
 struct attr_event {

tools/perf/util/session.c +7 -6

index 6ac62ae6b8fa..17a85f527bfc 100644
@@ -533,15 +533,11 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 		return -ETIME;
 
 	if (timestamp < oe->last_flush) {
-		WARN_ONCE(1, "Timestamp below last timeslice flush\n");
-
-		pr_oe_time(timestamp,      "out of order event");
+		pr_oe_time(timestamp,      "out of order event\n");
 		pr_oe_time(oe->last_flush, "last flush, last_flush_type %d\n",
 			   oe->last_flush_type);
 
-		/* We could get out of order messages after forced flush. */
-		if (oe->last_flush_type != OE_FLUSH__HALF)
-			return -EINVAL;
+		s->stats.nr_unordered_events++;
 	}
 
 	new = ordered_events__new(oe, timestamp, event);

@@ -1118,6 +1114,11 @@ 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",
 			    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;

Signature · 1 line

1.9.3

Em Wed, Nov 26, 2014 at 04:39:31PM +0100, Jiri Olsa escreveu:

Quoted 10 lines

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.

Quoted 3 lines

It'd be nice to find the source of this hiccup, meanwhile I'm submitting change that does not kill the processing, but only tracks the number of out of order events and warn user.

Works, for me, thanks for the fast response!

Quoted 13 lines

tools/perf/util/session.c +1 -3

@@ -533,15 +533,11 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 		return -ETIME;
 
 	if (timestamp < oe->last_flush) {
-		WARN_ONCE(1, "Timestamp below last timeslice flush\n");
-
-		pr_oe_time(timestamp,      "out of order event");
+		pr_oe_time(timestamp,      "out of order event\n");
 		pr_oe_time(oe->last_flush, "last flush, last_flush_type %d\n",
 			   oe->last_flush_type);
 

tools/perf/util/session.c int perf_session_queue_event(struct perf_session *s, union perf_event *event, · line 540

Quoted 4 lines

tools/perf/util/session.c +1 -3

-		/* We could get out of order messages after forced flush. */
-		if (oe->last_flush_type != OE_FLUSH__HALF)
-			return -EINVAL;
+		s->stats.nr_unordered_events++;

tools/perf/util/session.c static void perf_session__warn_about_errors(const struct perf_session *session, · line 1121

Quoted 4 lines

tools/perf/util/session.c +4 -0

+	if (session->stats.nr_unordered_events != 0) {
+		ui__warning("%u out of order events recorded.\n",
+			    session->stats.nr_unordered_events);
+	}

Quoted 5 lines

Quoted 5 lines

tools/perf/util/session.c +1 -1

-		pr_oe_time(timestamp,      "out of order event");
+		pr_oe_time(timestamp,      "out of order event\n");
 		pr_oe_time(oe->last_flush, "last flush, last_flush_type %d\n",
 			   oe->last_flush_type);

Quoted 4 lines

tools/perf/util/session.c int perf_session_queue_event(struct perf_session *s, union perf_event *event, · line 540

Quoted 4 lines

tools/perf/util/session.c +1 -3

-		/* We could get out of order messages after forced flush. */
-		if (oe->last_flush_type != OE_FLUSH__HALF)
-			return -EINVAL;
+		s->stats.nr_unordered_events++;

Btw., in the forced flush case we'll get out of order events that are 'expected'. Shouldn't we count them separately and not warn about them, or so?

Quoted 5 lines

tools/perf/util/session.c static void perf_session__warn_about_errors(const struct perf_session *session, · line 1121

Quoted 5 lines

tools/perf/util/session.c +4 -0

+	if (session->stats.nr_unordered_events != 0) {
+		ui__warning("%u out of order events recorded.\n",
+			    session->stats.nr_unordered_events);
+	}

Nit: I'd suggest keeping the message printout on a single line:

	if (session->stats.nr_unordered_events != 0) {
		ui__warning("%u out of order events recorded.\n", session->stats.nr_unordered_events);

as IMHO the cure for this col80 linebreak checkpatch warning is worse than the disease! :-)

Barring those details:

Acked-by Ingo Molnar <[email protected]>

SNIP

Quoted 5 lines

Quoted 5 lines

Quoted 5 lines

tools/perf/util/session.c +1 -1

-		pr_oe_time(timestamp,      "out of order event");
+		pr_oe_time(timestamp,      "out of order event\n");
 		pr_oe_time(oe->last_flush, "last flush, last_flush_type %d\n",
 			   oe->last_flush_type);

Quoted 8 lines

Quoted 4 lines

tools/perf/util/session.c int perf_session_queue_event(struct perf_session *s, union perf_event *event, · line 540

Quoted 4 lines

tools/perf/util/session.c +1 -3

-		/* We could get out of order messages after forced flush. */
-		if (oe->last_flush_type != OE_FLUSH__HALF)
-			return -EINVAL;
+		s->stats.nr_unordered_events++;

Btw., in the forced flush case we'll get out of order events that are 'expected'. Shouldn't we count them separately and not warn about them, or so?

hum, we warned about them anyway, we just did not fail processing.. and the impact of both cases should be the same.. it's just at the forced flush we expected/allowed out of order events

so I think it's ok to share the same counter and warn about them the same way

Quoted 8 lines

Quoted 5 lines

tools/perf/util/session.c static void perf_session__warn_about_errors(const struct perf_session *session, · line 1121

Quoted 5 lines

tools/perf/util/session.c +4 -0

+	if (session->stats.nr_unordered_events != 0) {
+		ui__warning("%u out of order events recorded.\n",
+			    session->stats.nr_unordered_events);
+	}

Nit: I'd suggest keeping the message printout on a single line:

Quoted 5 lines

	if (session->stats.nr_unordered_events != 0) {
		ui__warning("%u out of order events recorded.\n", session->stats.nr_unordered_events);

as IMHO the cure for this col80 linebreak checkpatch warning is worse than the disease! :-)

ok ;-)

Quoted 4 lines

Barring those details:

Acked-by Ingo Molnar <[email protected]>

thanks,
jirka

Quoted 12 lines

Em Wed, Nov 26, 2014 at 04:39:31PM +0100, Jiri Olsa escreveu:

Quoted 10 lines

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.

Quoted 5 lines

Quoted 3 lines

It'd be nice to find the source of this hiccup, meanwhile I'm submitting change that does not kill the processing, but only tracks the number of out of order events and warn user.

Works, for me, thanks for the fast response!

Thanks Jiri!

Quoted 13 lines

Quoted 13 lines

tools/perf/util/session.c +1 -3

@@ -533,15 +533,11 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 		return -ETIME;
 
 	if (timestamp < oe->last_flush) {
-		WARN_ONCE(1, "Timestamp below last timeslice flush\n");
-
-		pr_oe_time(timestamp,      "out of order event");
+		pr_oe_time(timestamp,      "out of order event\n");
 		pr_oe_time(oe->last_flush, "last flush, last_flush_type %d\n",
 			   oe->last_flush_type);
 

Quoted 4 lines

tools/perf/util/session.c int perf_session_queue_event(struct perf_session *s, union perf_event *event, · line 540

Quoted 4 lines

tools/perf/util/session.c +1 -3

-		/* We could get out of order messages after forced flush. */
-		if (oe->last_flush_type != OE_FLUSH__HALF)
-			return -EINVAL;
+		s->stats.nr_unordered_events++;

Btw., in the forced flush case we'll get out of order events that are 'expected'. Shouldn't we count them separately and not warn about them, or so?

Quoted 4 lines

tools/perf/util/session.c static void perf_session__warn_about_errors(const struct perf_session *session, · line 1121

Quoted 4 lines

tools/perf/util/session.c +4 -0

+	if (session->stats.nr_unordered_events != 0) {
+		ui__warning("%u out of order events recorded.\n",
+			    session->stats.nr_unordered_events);
+	}

Nit: I'd suggest keeping the message printout on a single line:

	if (session->stats.nr_unordered_events != 0) {
		ui__warning("%u out of order events recorded.\n", session->stats.nr_unordered_events);

as IMHO the cure for this col80 linebreak checkpatch warning is worse than the disease! :-)

Barring those details:

Acked-by Ingo Molnar <[email protected]>

Arnaldo, I suppose the fix will go upstream via your tree, as a pull request for v3.18 fixes?

Em Thu, Nov 27, 2014 at 11:56:03AM +0100, Ingo Molnar escreveu:

Quoted 57 lines · Arnaldo Carvalho de Melo

Quoted 12 lines

Em Wed, Nov 26, 2014 at 04:39:31PM +0100, Jiri Olsa escreveu:

Quoted 10 lines

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.

Quoted 5 lines

Quoted 3 lines

It'd be nice to find the source of this hiccup, meanwhile I'm submitting change that does not kill the processing, but only tracks the number of out of order events and warn user.

Works, for me, thanks for the fast response!

Thanks Jiri!

Quoted 13 lines

Quoted 13 lines

tools/perf/util/session.c +1 -3

@@ -533,15 +533,11 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 		return -ETIME;
 
 	if (timestamp < oe->last_flush) {
-		WARN_ONCE(1, "Timestamp below last timeslice flush\n");
-
-		pr_oe_time(timestamp,      "out of order event");
+		pr_oe_time(timestamp,      "out of order event\n");
 		pr_oe_time(oe->last_flush, "last flush, last_flush_type %d\n",
 			   oe->last_flush_type);
 

Quoted 4 lines

tools/perf/util/session.c int perf_session_queue_event(struct perf_session *s, union perf_event *event, · line 540

Quoted 4 lines

tools/perf/util/session.c +1 -3

-		/* We could get out of order messages after forced flush. */
-		if (oe->last_flush_type != OE_FLUSH__HALF)
-			return -EINVAL;
+		s->stats.nr_unordered_events++;

Btw., in the forced flush case we'll get out of order events that are 'expected'. Shouldn't we count them separately and not warn about them, or so?

Quoted 4 lines

tools/perf/util/session.c static void perf_session__warn_about_errors(const struct perf_session *session, · line 1121

Quoted 4 lines

tools/perf/util/session.c +4 -0

+	if (session->stats.nr_unordered_events != 0) {
+		ui__warning("%u out of order events recorded.\n",
+			    session->stats.nr_unordered_events);
+	}

Nit: I'd suggest keeping the message printout on a single line:

	if (session->stats.nr_unordered_events != 0) {
		ui__warning("%u out of order events recorded.\n", session->stats.nr_unordered_events);

as IMHO the cure for this col80 linebreak checkpatch warning is worse than the disease! :-)

Quoted 6 lines

Barring those details:

Acked-by Ingo Molnar <[email protected]>

Arnaldo, I suppose the fix will go upstream via your tree, as a pull request for v3.18 fixes?

Right, I can do that.

And I agree with the "expected" for events that are out of the current reordering window, i.e. we can't insert something into previous windows, so those are, humm, what would be a good name:
stats->out_of_reordering_window, while stats->reordered, would be for events that were found out of order, but were successfully sorted as part of a flush operation, right?

Quoted 4 lines

Em Thu, Nov 27, 2014 at 11:56:03AM +0100, Ingo Molnar escreveu:

Quoted 2 lines

Arnaldo, I suppose the fix will go upstream via your tree, as a pull request for v3.18 fixes?

Quoted 8 lines

Right, I can do that.

And I agree with the "expected" for events that are out of the current reordering window, i.e. we can't insert something into previous windows, so those are, humm, what would be a good name:
stats->out_of_reordering_window, while stats->reordered, would be for events that were found out of order, but were successfully sorted as part of a flush operation, right?

the forced flush is when we find out we crossed the allowed allocation space for the samples queue.. so we take the half of the sorted queue and flush it.. for this case we break the flushing logic and we might

(probably just in theory) get out of order events

but IMO both cases of out of order event are equal.. we dont do anything special for forced flushed AFAIK

Em Thu, Nov 27, 2014 at 03:07:07PM +0100, Jiri Olsa escreveu:

Quoted 13 lines · Arnaldo Carvalho de Melo

Quoted 12 lines

Em Thu, Nov 27, 2014 at 11:56:03AM +0100, Ingo Molnar escreveu:

Quoted 2 lines

Arnaldo, I suppose the fix will go upstream via your tree, as a pull request for v3.18 fixes?

Right, I can do that.

And I agree with the "expected" for events that are out of the current reordering window, i.e. we can't insert something into previous windows, so those are, humm, what would be a good name:
stats->out_of_reordering_window, while stats->reordered, would be for events that were found out of order, but were successfully sorted as part of a flush operation, right?

Quoted 3 lines

the forced flush is when we find out we crossed the allowed allocation space for the samples queue.. so we take the half of the sorted queue and flush it.. for this case we break the flushing logic and we might

Well, we make it more likely than without a forced flush to find out of order events, because the window suddenly became smaller, its like we found a FLUSH event right there, no?

Quoted 5 lines

(probably just in theory) get out of order events

but IMO both cases of out of order event are equal.. we dont do anything special for forced flushed AFAIK

- Arnaldo

Quoted 19 lines

Em Thu, Nov 27, 2014 at 03:07:07PM +0100, Jiri Olsa escreveu:

Quoted 17 lines · Arnaldo Carvalho de Melo

Quoted 4 lines

Em Thu, Nov 27, 2014 at 11:56:03AM +0100, Ingo Molnar escreveu:

Quoted 2 lines

Arnaldo, I suppose the fix will go upstream via your tree, as a pull request for v3.18 fixes?

Quoted 8 lines

Right, I can do that.

And I agree with the "expected" for events that are out of the current reordering window, i.e. we can't insert something into previous windows, so those are, humm, what would be a good name:
stats->out_of_reordering_window, while stats->reordered, would be for events that were found out of order, but were successfully sorted as part of a flush operation, right?

the forced flush is when we find out we crossed the allowed allocation space for the samples queue.. so we take the half of the sorted queue and flush it.. for this case we break the flushing logic and we might

Quoted 3 lines

Well, we make it more likely than without a forced flush to find out of order events, because the window suddenly became smaller, its like we found a FLUSH event right there, no?

yep, still I dont see the need to count those 2 cases separately, both these types (of out of order event) have same implications for the report

jirka

Quoted 7 lines

Quoted 5 lines

(probably just in theory) get out of order events

but IMO both cases of out of order event are equal.. we dont do anything special for forced flushed AFAIK

- Arnaldo

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.