Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753443AbaKZPkE (ORCPT ); Wed, 26 Nov 2014 10:40:04 -0500 Received: from mx1.redhat.com ([209.132.183.28]:45544 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753355AbaKZPkB (ORCPT ); Wed, 26 Nov 2014 10:40:01 -0500 From: Jiri Olsa To: linux-kernel@vger.kernel.org Cc: Jiri Olsa , Linus Torvalds , Andi Kleen , Corey Ashford , David Ahern , Frederic Weisbecker , Ingo Molnar , Matt Fleming , Namhyung Kim , Paul Mackerras , Peter Zijlstra , Stephane Eranian , Arnaldo Carvalho de Melo Subject: [PATCH] perf tools: Do not fail on processing out of order event Date: Wed, 26 Nov 2014 16:39:31 +0100 Message-Id: <1417016371-30249-1-git-send-email-jolsa@kernel.org> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 Cc: Linus Torvalds Cc: Andi Kleen Cc: Corey Ashford Cc: David Ahern Cc: Frederic Weisbecker Cc: Ingo Molnar Cc: Matt Fleming Cc: Namhyung Kim Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Stephane Eranian Cc: Arnaldo Carvalho de Melo Signed-off-by: Jiri Olsa --- tools/perf/util/event.h | 1 + tools/perf/util/session.c | 13 +++++++------ 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h index 09b9e8d3fcf7..c4ffe2bd0738 100644 --- a/tools/perf/util/event.h +++ b/tools/perf/util/event.h @@ -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 { diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c index 6ac62ae6b8fa..17a85f527bfc 100644 --- a/tools/perf/util/session.c +++ b/tools/perf/util/session.c @@ -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; -- 1.9.3 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/