[PATCHv3 00/19] perf tools: Factor ordered samples queue

[PATCHv3 00/19] perf tools: Factor ordered samples queue

[Jiri Olsa]

hi,
this patchset factors session's ordered samples queue,
and allows to limit the size of this queue.

v3 changes:
  - rebased to latest tip/perf/core
  - add comment for WARN in patch 8 (David)
  - added ordered-events debug variable (David)
  - renamed ordered_events_(get|put) to ordered_events_(new|delete)
  - renamed struct ordered_events_queue to struct ordered_events

v2 changes:
  - several small changes for review comments (Namhyung)


The report command queues events till any of following
conditions is reached:
  - PERF_RECORD_FINISHED_ROUND event is processed
  - end of the file is reached

Any of above conditions will force the queue to flush some
events while keeping all allocated memory for next events.

If PERF_RECORD_FINISHED_ROUND is missing the queue will
allocate memory for every single event in the perf.data.
This could lead to enormous memory consuption and speed
degradation of report command for huge perf.data files.

With the quue allocation limit of 100 MB, I've got around
15% speedup on reporting of ~10GB perf.data file.

current code:
 Performance counter stats for './perf.old report --stdio -i perf-test.data' (3 runs):

   621,685,704,665      cycles                    ( +-  0.52% )
   873,397,467,969      instructions              ( +-  0.00% )

     286.133268732 seconds time elapsed           ( +-  1.13% )

with patches:
 Performance counter stats for './perf report --stdio -i perf-test.data' (3 runs):

   603,933,987,185      cycles                    ( +-  0.45% )
   869,139,445,070      instructions              ( +-  0.00% )

     245.337510637 seconds time elapsed           ( +-  0.49% )


The speed up seems to be mainly in less cycles spent in servicing
page faults:

current code:
     4.44%     0.01%  perf.old  [kernel.kallsyms]   [k] page_fault                                   

with patches:
     1.45%     0.00%      perf  [kernel.kallsyms]   [k] page_fault                                   

current code (faults event):
         6,643,807      faults                    ( +-  0.36% )

with patches (faults event):
         2,214,756      faults                    ( +-  3.03% )


Also now we have one of our big memory spender under control
and the ordered events queue code is put in separated object
with clear interface ready to be used by another command
like script.

Also reachable in here:
  git://git.kernel.org/pub/scm/linux/kernel/git/jolsa/perf.git
  perf/core_ordered_events

thanks,
jirka


Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---

[PATCH 01/19] perf tools: Fix accounting of ordered samples queue

[Jiri Olsa]

Properly account flushed samples within the ordered
samples queue.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/session.c | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index eac14ce0ae8d..ff6a69afe045 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -511,6 +511,7 @@ static int flush_sample_queue(struct perf_session *s,
 		os->last_flush = iter->timestamp;
 		list_del(&iter->list);
 		list_add(&iter->list, &os->sample_cache);
+		os->nr_samples--;
 
 		if (show_progress)
 			ui_progress__update(&prog, 1);
@@ -523,8 +524,6 @@ static int flush_sample_queue(struct perf_session *s,
 			list_entry(head->prev, struct sample_queue, list);
 	}
 
-	os->nr_samples = 0;
-
 	return 0;
 }
 
-- 
1.8.3.1

[PATCH 02/19] perf tools: Rename ordered_samples bool to ordered_events

[Jiri Olsa]

The time ordering is generic for all kinds of events, so using
generic name 'ordered_events' for ordered_samples bool in
perf_tool struct.

No functional change was intended.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-annotate.c  |  2 +-
 tools/perf/builtin-diff.c      |  2 +-
 tools/perf/builtin-inject.c    |  2 +-
 tools/perf/builtin-kmem.c      |  2 +-
 tools/perf/builtin-kvm.c       |  4 ++--
 tools/perf/builtin-lock.c      |  2 +-
 tools/perf/builtin-mem.c       |  2 +-
 tools/perf/builtin-report.c    |  2 +-
 tools/perf/builtin-sched.c     |  2 +-
 tools/perf/builtin-script.c    |  2 +-
 tools/perf/builtin-timechart.c |  2 +-
 tools/perf/builtin-trace.c     |  2 +-
 tools/perf/util/session.c      | 10 +++++-----
 tools/perf/util/tool.h         |  2 +-
 14 files changed, 19 insertions(+), 19 deletions(-)

diff --git a/tools/perf/builtin-annotate.c b/tools/perf/builtin-annotate.c
index 1ec429fef2be..952b5ece6740 100644
--- a/tools/perf/builtin-annotate.c
+++ b/tools/perf/builtin-annotate.c
@@ -297,7 +297,7 @@ int cmd_annotate(int argc, const char **argv, const char *prefix __maybe_unused)
 			.comm	= perf_event__process_comm,
 			.exit	= perf_event__process_exit,
 			.fork	= perf_event__process_fork,
-			.ordered_samples = true,
+			.ordered_events = true,
 			.ordering_requires_timestamps = true,
 		},
 	};
diff --git a/tools/perf/builtin-diff.c b/tools/perf/builtin-diff.c
index 9a5a035cb426..c10cc44bae19 100644
--- a/tools/perf/builtin-diff.c
+++ b/tools/perf/builtin-diff.c
@@ -360,7 +360,7 @@ static struct perf_tool tool = {
 	.exit	= perf_event__process_exit,
 	.fork	= perf_event__process_fork,
 	.lost	= perf_event__process_lost,
-	.ordered_samples = true,
+	.ordered_events = true,
 	.ordering_requires_timestamps = true,
 };
 
diff --git a/tools/perf/builtin-inject.c b/tools/perf/builtin-inject.c
index cf6a605a13e8..cbfd1a020b74 100644
--- a/tools/perf/builtin-inject.c
+++ b/tools/perf/builtin-inject.c
@@ -366,7 +366,7 @@ static int __cmd_inject(struct perf_inject *inject)
 	} else if (inject->sched_stat) {
 		struct perf_evsel *evsel;
 
-		inject->tool.ordered_samples = true;
+		inject->tool.ordered_events = true;
 
 		evlist__for_each(session->evlist, evsel) {
 			const char *name = perf_evsel__name(evsel);
diff --git a/tools/perf/builtin-kmem.c b/tools/perf/builtin-kmem.c
index bef3376bfaf3..b5721116713b 100644
--- a/tools/perf/builtin-kmem.c
+++ b/tools/perf/builtin-kmem.c
@@ -256,7 +256,7 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused,
 static struct perf_tool perf_kmem = {
 	.sample		 = process_sample_event,
 	.comm		 = perf_event__process_comm,
-	.ordered_samples = true,
+	.ordered_events	 = true,
 };
 
 static double fragmentation(unsigned long n_req, unsigned long n_alloc)
diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index 43367eb00510..25f0c287c5c5 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -1058,7 +1058,7 @@ static int read_events(struct perf_kvm_stat *kvm)
 	struct perf_tool eops = {
 		.sample			= process_sample_event,
 		.comm			= perf_event__process_comm,
-		.ordered_samples	= true,
+		.ordered_events		= true,
 	};
 	struct perf_data_file file = {
 		.path = kvm->file_name,
@@ -1311,7 +1311,7 @@ static int kvm_events_live(struct perf_kvm_stat *kvm,
 	kvm->tool.exit   = perf_event__process_exit;
 	kvm->tool.fork   = perf_event__process_fork;
 	kvm->tool.lost   = process_lost_event;
-	kvm->tool.ordered_samples = true;
+	kvm->tool.ordered_events = true;
 	perf_tool__fill_defaults(&kvm->tool);
 
 	/* set defaults */
diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 6148afc995c6..c8122d323621 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -852,7 +852,7 @@ static int __cmd_report(bool display_info)
 	struct perf_tool eops = {
 		.sample		 = process_sample_event,
 		.comm		 = perf_event__process_comm,
-		.ordered_samples = true,
+		.ordered_events	 = true,
 	};
 	struct perf_data_file file = {
 		.path = input_name,
diff --git a/tools/perf/builtin-mem.c b/tools/perf/builtin-mem.c
index 4a1a6c94a5eb..80e57c84adef 100644
--- a/tools/perf/builtin-mem.c
+++ b/tools/perf/builtin-mem.c
@@ -194,7 +194,7 @@ int cmd_mem(int argc, const char **argv, const char *prefix __maybe_unused)
 			.lost		= perf_event__process_lost,
 			.fork		= perf_event__process_fork,
 			.build_id	= perf_event__process_build_id,
-			.ordered_samples = true,
+			.ordered_events	= true,
 		},
 		.input_name		 = "perf.data",
 	};
diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 21d830bafff3..c72cc5a12144 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -578,7 +578,7 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
 			.attr		 = perf_event__process_attr,
 			.tracing_data	 = perf_event__process_tracing_data,
 			.build_id	 = perf_event__process_build_id,
-			.ordered_samples = true,
+			.ordered_events	 = true,
 			.ordering_requires_timestamps = true,
 		},
 		.max_stack		 = PERF_MAX_STACK_DEPTH,
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index f83c08c0dd87..7c16aeb6b675 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -1662,7 +1662,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 			.comm		 = perf_event__process_comm,
 			.lost		 = perf_event__process_lost,
 			.fork		 = perf_sched__process_fork_event,
-			.ordered_samples = true,
+			.ordered_events = true,
 		},
 		.cmp_pid	      = LIST_HEAD_INIT(sched.cmp_pid),
 		.sort_list	      = LIST_HEAD_INIT(sched.sort_list),
diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 9e9c91f5b7fa..ba4162e707e0 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -1510,7 +1510,7 @@ int cmd_script(int argc, const char **argv, const char *prefix __maybe_unused)
 			.attr		 = process_attr,
 			.tracing_data	 = perf_event__process_tracing_data,
 			.build_id	 = perf_event__process_build_id,
-			.ordered_samples = true,
+			.ordered_events	 = true,
 			.ordering_requires_timestamps = true,
 		},
 	};
diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c
index 2f1a5220c090..912e3b5bb22b 100644
--- a/tools/perf/builtin-timechart.c
+++ b/tools/perf/builtin-timechart.c
@@ -1920,7 +1920,7 @@ int cmd_timechart(int argc, const char **argv,
 			.fork		 = process_fork_event,
 			.exit		 = process_exit_event,
 			.sample		 = process_sample_event,
-			.ordered_samples = true,
+			.ordered_events	 = true,
 		},
 		.proc_num = 15,
 		.min_time = 1000000,
diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index c4a5a7d7b2cf..552831ad88dc 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -2209,7 +2209,7 @@ static int trace__replay(struct trace *trace)
 	trace->tool.tracing_data = perf_event__process_tracing_data;
 	trace->tool.build_id	  = perf_event__process_build_id;
 
-	trace->tool.ordered_samples = true;
+	trace->tool.ordered_events = true;
 	trace->tool.ordering_requires_timestamps = true;
 
 	/* add tid to output */
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index ff6a69afe045..0362cfcfb0a5 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -105,9 +105,9 @@ struct perf_session *perf_session__new(struct perf_data_file *file,
 	}
 
 	if (tool && tool->ordering_requires_timestamps &&
-	    tool->ordered_samples && !perf_evlist__sample_id_all(session->evlist)) {
+	    tool->ordered_events && !perf_evlist__sample_id_all(session->evlist)) {
 		dump_printf("WARNING: No sample_id_all support, falling back to unordered processing\n");
-		tool->ordered_samples = false;
+		tool->ordered_events = false;
 	}
 
 	return session;
@@ -240,7 +240,7 @@ void perf_tool__fill_defaults(struct perf_tool *tool)
 	if (tool->build_id == NULL)
 		tool->build_id = process_finished_round_stub;
 	if (tool->finished_round == NULL) {
-		if (tool->ordered_samples)
+		if (tool->ordered_events)
 			tool->finished_round = process_finished_round;
 		else
 			tool->finished_round = process_finished_round_stub;
@@ -485,7 +485,7 @@ static int flush_sample_queue(struct perf_session *s,
 	struct ui_progress prog;
 	int ret;
 
-	if (!tool->ordered_samples || !limit)
+	if (!tool->ordered_events || !limit)
 		return 0;
 
 	if (show_progress)
@@ -1062,7 +1062,7 @@ static int perf_session__process_event(struct perf_session *session,
 	if (ret)
 		return ret;
 
-	if (tool->ordered_samples) {
+	if (tool->ordered_events) {
 		ret = perf_session_queue_event(session, event, &sample,
 					       file_offset);
 		if (ret != -ETIME)
diff --git a/tools/perf/util/tool.h b/tools/perf/util/tool.h
index 4385816d3d49..f11636966a0f 100644
--- a/tools/perf/util/tool.h
+++ b/tools/perf/util/tool.h
@@ -40,7 +40,7 @@ struct perf_tool {
 	event_op2	tracing_data;
 	event_op2	finished_round,
 			build_id;
-	bool		ordered_samples;
+	bool		ordered_events;
 	bool		ordering_requires_timestamps;
 };
 
-- 
1.8.3.1

[PATCH 03/19] perf tools: Rename ordered_samples struct to ordered_events

[Jiri Olsa]

Following up with ordered_samples rename for ordered_samples
and sample_queue structs to ordered_events and ordered_event
structs respectively.

Also changing flush_sample_queue function name to ordered_events_flush.

No functional change was intended.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-kvm.c  |   2 +-
 tools/perf/util/session.c | 116 +++++++++++++++++++++++-----------------------
 tools/perf/util/session.h |  10 ++--
 3 files changed, 64 insertions(+), 64 deletions(-)

diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index 25f0c287c5c5..f8a561643753 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -785,7 +785,7 @@ static int perf_kvm__mmap_read(struct perf_kvm_stat *kvm)
 
 	/* flush queue after each round in which we processed events */
 	if (ntotal) {
-		kvm->session->ordered_samples.next_flush = flush_time;
+		kvm->session->ordered_events.next_flush = flush_time;
 		err = kvm->tool.finished_round(&kvm->tool, NULL, kvm->session);
 		if (err) {
 			if (kvm->lost_events)
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 0362cfcfb0a5..1bfd2a04143b 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -76,9 +76,9 @@ struct perf_session *perf_session__new(struct perf_data_file *file,
 		goto out;
 
 	session->repipe = repipe;
-	INIT_LIST_HEAD(&session->ordered_samples.samples);
-	INIT_LIST_HEAD(&session->ordered_samples.sample_cache);
-	INIT_LIST_HEAD(&session->ordered_samples.to_free);
+	INIT_LIST_HEAD(&session->ordered_events.samples);
+	INIT_LIST_HEAD(&session->ordered_events.sample_cache);
+	INIT_LIST_HEAD(&session->ordered_events.to_free);
 	machines__init(&session->machines);
 
 	if (file) {
@@ -446,7 +446,7 @@ static perf_event__swap_op perf_event__swap_ops[] = {
 	[PERF_RECORD_HEADER_MAX]	  = NULL,
 };
 
-struct sample_queue {
+struct ordered_event {
 	u64			timestamp;
 	u64			file_offset;
 	union perf_event	*event;
@@ -455,14 +455,14 @@ struct sample_queue {
 
 static void perf_session_free_sample_buffers(struct perf_session *session)
 {
-	struct ordered_samples *os = &session->ordered_samples;
+	struct ordered_events *oe = &session->ordered_events;
 
-	while (!list_empty(&os->to_free)) {
-		struct sample_queue *sq;
+	while (!list_empty(&oe->to_free)) {
+		struct ordered_event *event;
 
-		sq = list_entry(os->to_free.next, struct sample_queue, list);
-		list_del(&sq->list);
-		free(sq);
+		event = list_entry(oe->to_free.next, struct ordered_event, list);
+		list_del(&event->list);
+		free(event);
 	}
 }
 
@@ -472,15 +472,15 @@ static int perf_session_deliver_event(struct perf_session *session,
 				      struct perf_tool *tool,
 				      u64 file_offset);
 
-static int flush_sample_queue(struct perf_session *s,
+static int ordered_events_flush(struct perf_session *s,
 		       struct perf_tool *tool)
 {
-	struct ordered_samples *os = &s->ordered_samples;
-	struct list_head *head = &os->samples;
-	struct sample_queue *tmp, *iter;
+	struct ordered_events *oe = &s->ordered_events;
+	struct list_head *head = &oe->samples;
+	struct ordered_event *tmp, *iter;
 	struct perf_sample sample;
-	u64 limit = os->next_flush;
-	u64 last_ts = os->last_sample ? os->last_sample->timestamp : 0ULL;
+	u64 limit = oe->next_flush;
+	u64 last_ts = oe->last_sample ? oe->last_sample->timestamp : 0ULL;
 	bool show_progress = limit == ULLONG_MAX;
 	struct ui_progress prog;
 	int ret;
@@ -489,7 +489,7 @@ static int flush_sample_queue(struct perf_session *s,
 		return 0;
 
 	if (show_progress)
-		ui_progress__init(&prog, os->nr_samples, "Processing time ordered events...");
+		ui_progress__init(&prog, oe->nr_samples, "Processing time ordered events...");
 
 	list_for_each_entry_safe(iter, tmp, head, list) {
 		if (session_done())
@@ -508,20 +508,20 @@ static int flush_sample_queue(struct perf_session *s,
 				return ret;
 		}
 
-		os->last_flush = iter->timestamp;
+		oe->last_flush = iter->timestamp;
 		list_del(&iter->list);
-		list_add(&iter->list, &os->sample_cache);
-		os->nr_samples--;
+		list_add(&iter->list, &oe->sample_cache);
+		oe->nr_samples--;
 
 		if (show_progress)
 			ui_progress__update(&prog, 1);
 	}
 
 	if (list_empty(head)) {
-		os->last_sample = NULL;
+		oe->last_sample = NULL;
 	} else if (last_ts <= limit) {
-		os->last_sample =
-			list_entry(head->prev, struct sample_queue, list);
+		oe->last_sample =
+			list_entry(head->prev, struct ordered_event, list);
 	}
 
 	return 0;
@@ -570,27 +570,27 @@ static int process_finished_round(struct perf_tool *tool,
 				  union perf_event *event __maybe_unused,
 				  struct perf_session *session)
 {
-	int ret = flush_sample_queue(session, tool);
+	int ret = ordered_events_flush(session, tool);
 	if (!ret)
-		session->ordered_samples.next_flush = session->ordered_samples.max_timestamp;
+		session->ordered_events.next_flush = session->ordered_events.max_timestamp;
 
 	return ret;
 }
 
 /* The queue is ordered by time */
-static void __queue_event(struct sample_queue *new, struct perf_session *s)
+static void __queue_event(struct ordered_event *new, struct perf_session *s)
 {
-	struct ordered_samples *os = &s->ordered_samples;
-	struct sample_queue *sample = os->last_sample;
+	struct ordered_events *oe = &s->ordered_events;
+	struct ordered_event *sample = oe->last_sample;
 	u64 timestamp = new->timestamp;
 	struct list_head *p;
 
-	++os->nr_samples;
-	os->last_sample = new;
+	++oe->nr_samples;
+	oe->last_sample = new;
 
 	if (!sample) {
-		list_add(&new->list, &os->samples);
-		os->max_timestamp = timestamp;
+		list_add(&new->list, &oe->samples);
+		oe->max_timestamp = timestamp;
 		return;
 	}
 
@@ -602,59 +602,59 @@ static void __queue_event(struct sample_queue *new, struct perf_session *s)
 	if (sample->timestamp <= timestamp) {
 		while (sample->timestamp <= timestamp) {
 			p = sample->list.next;
-			if (p == &os->samples) {
-				list_add_tail(&new->list, &os->samples);
-				os->max_timestamp = timestamp;
+			if (p == &oe->samples) {
+				list_add_tail(&new->list, &oe->samples);
+				oe->max_timestamp = timestamp;
 				return;
 			}
-			sample = list_entry(p, struct sample_queue, list);
+			sample = list_entry(p, struct ordered_event, list);
 		}
 		list_add_tail(&new->list, &sample->list);
 	} else {
 		while (sample->timestamp > timestamp) {
 			p = sample->list.prev;
-			if (p == &os->samples) {
-				list_add(&new->list, &os->samples);
+			if (p == &oe->samples) {
+				list_add(&new->list, &oe->samples);
 				return;
 			}
-			sample = list_entry(p, struct sample_queue, list);
+			sample = list_entry(p, struct ordered_event, list);
 		}
 		list_add(&new->list, &sample->list);
 	}
 }
 
-#define MAX_SAMPLE_BUFFER	(64 * 1024 / sizeof(struct sample_queue))
+#define MAX_SAMPLE_BUFFER	(64 * 1024 / sizeof(struct ordered_event))
 
 int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 				    struct perf_sample *sample, u64 file_offset)
 {
-	struct ordered_samples *os = &s->ordered_samples;
-	struct list_head *sc = &os->sample_cache;
+	struct ordered_events *oe = &s->ordered_events;
+	struct list_head *sc = &oe->sample_cache;
 	u64 timestamp = sample->time;
-	struct sample_queue *new;
+	struct ordered_event *new;
 
 	if (!timestamp || timestamp == ~0ULL)
 		return -ETIME;
 
-	if (timestamp < s->ordered_samples.last_flush) {
+	if (timestamp < s->ordered_events.last_flush) {
 		printf("Warning: Timestamp below last timeslice flush\n");
 		return -EINVAL;
 	}
 
 	if (!list_empty(sc)) {
-		new = list_entry(sc->next, struct sample_queue, list);
+		new = list_entry(sc->next, struct ordered_event, list);
 		list_del(&new->list);
-	} else if (os->sample_buffer) {
-		new = os->sample_buffer + os->sample_buffer_idx;
-		if (++os->sample_buffer_idx == MAX_SAMPLE_BUFFER)
-			os->sample_buffer = NULL;
+	} else if (oe->sample_buffer) {
+		new = oe->sample_buffer + oe->sample_buffer_idx;
+		if (++oe->sample_buffer_idx == MAX_SAMPLE_BUFFER)
+			oe->sample_buffer = NULL;
 	} else {
-		os->sample_buffer = malloc(MAX_SAMPLE_BUFFER * sizeof(*new));
-		if (!os->sample_buffer)
+		oe->sample_buffer = malloc(MAX_SAMPLE_BUFFER * sizeof(*new));
+		if (!oe->sample_buffer)
 			return -ENOMEM;
-		list_add(&os->sample_buffer->list, &os->to_free);
-		os->sample_buffer_idx = 2;
-		new = os->sample_buffer + 1;
+		list_add(&oe->sample_buffer->list, &oe->to_free);
+		oe->sample_buffer_idx = 2;
+		new = oe->sample_buffer + 1;
 	}
 
 	new->timestamp = timestamp;
@@ -1222,8 +1222,8 @@ more:
 		goto more;
 done:
 	/* do the final flush for ordered samples */
-	session->ordered_samples.next_flush = ULLONG_MAX;
-	err = flush_sample_queue(session, tool);
+	session->ordered_events.next_flush = ULLONG_MAX;
+	err = ordered_events_flush(session, tool);
 out_err:
 	free(buf);
 	perf_session__warn_about_errors(session, tool);
@@ -1364,8 +1364,8 @@ more:
 
 out:
 	/* do the final flush for ordered samples */
-	session->ordered_samples.next_flush = ULLONG_MAX;
-	err = flush_sample_queue(session, tool);
+	session->ordered_events.next_flush = ULLONG_MAX;
+	err = ordered_events_flush(session, tool);
 out_err:
 	ui_progress__finish();
 	perf_session__warn_about_errors(session, tool);
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index 0321013bd9fd..f6baf935917a 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -12,19 +12,19 @@
 #include <linux/rbtree.h>
 #include <linux/perf_event.h>
 
-struct sample_queue;
+struct ordered_event;
 struct ip_callchain;
 struct thread;
 
-struct ordered_samples {
+struct ordered_events {
 	u64			last_flush;
 	u64			next_flush;
 	u64			max_timestamp;
 	struct list_head	samples;
 	struct list_head	sample_cache;
 	struct list_head	to_free;
-	struct sample_queue	*sample_buffer;
-	struct sample_queue	*last_sample;
+	struct ordered_event	*sample_buffer;
+	struct ordered_event	*last_sample;
 	int			sample_buffer_idx;
 	unsigned int		nr_samples;
 };
@@ -39,7 +39,7 @@ struct perf_session {
 	bool			one_mmap;
 	void			*one_mmap_addr;
 	u64			one_mmap_offset;
-	struct ordered_samples	ordered_samples;
+	struct ordered_events	ordered_events;
 	struct perf_data_file	*file;
 };
 
-- 
1.8.3.1

[PATCH 04/19] perf tools: Rename ordered_events members

[Jiri Olsa]

Rename 'struct ordered_events_queue' members to fit
better the ordered events style.

No functional change was intended.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/session.c | 86 +++++++++++++++++++++++------------------------
 tools/perf/util/session.h | 12 +++----
 2 files changed, 48 insertions(+), 50 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 1bfd2a04143b..ab7a2084d0bf 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -76,8 +76,8 @@ struct perf_session *perf_session__new(struct perf_data_file *file,
 		goto out;
 
 	session->repipe = repipe;
-	INIT_LIST_HEAD(&session->ordered_events.samples);
-	INIT_LIST_HEAD(&session->ordered_events.sample_cache);
+	INIT_LIST_HEAD(&session->ordered_events.events);
+	INIT_LIST_HEAD(&session->ordered_events.cache);
 	INIT_LIST_HEAD(&session->ordered_events.to_free);
 	machines__init(&session->machines);
 
@@ -476,11 +476,11 @@ static int ordered_events_flush(struct perf_session *s,
 		       struct perf_tool *tool)
 {
 	struct ordered_events *oe = &s->ordered_events;
-	struct list_head *head = &oe->samples;
+	struct list_head *head = &oe->events;
 	struct ordered_event *tmp, *iter;
 	struct perf_sample sample;
 	u64 limit = oe->next_flush;
-	u64 last_ts = oe->last_sample ? oe->last_sample->timestamp : 0ULL;
+	u64 last_ts = oe->last ? oe->last->timestamp : 0ULL;
 	bool show_progress = limit == ULLONG_MAX;
 	struct ui_progress prog;
 	int ret;
@@ -489,7 +489,7 @@ static int ordered_events_flush(struct perf_session *s,
 		return 0;
 
 	if (show_progress)
-		ui_progress__init(&prog, oe->nr_samples, "Processing time ordered events...");
+		ui_progress__init(&prog, oe->nr_events, "Processing time ordered events...");
 
 	list_for_each_entry_safe(iter, tmp, head, list) {
 		if (session_done())
@@ -510,19 +510,17 @@ static int ordered_events_flush(struct perf_session *s,
 
 		oe->last_flush = iter->timestamp;
 		list_del(&iter->list);
-		list_add(&iter->list, &oe->sample_cache);
-		oe->nr_samples--;
+		list_add(&iter->list, &oe->cache);
+		oe->nr_events--;
 
 		if (show_progress)
 			ui_progress__update(&prog, 1);
 	}
 
-	if (list_empty(head)) {
-		oe->last_sample = NULL;
-	} else if (last_ts <= limit) {
-		oe->last_sample =
-			list_entry(head->prev, struct ordered_event, list);
-	}
+	if (list_empty(head))
+		oe->last = NULL;
+	else if (last_ts <= limit)
+		oe->last = list_entry(head->prev, struct ordered_event, list);
 
 	return 0;
 }
@@ -581,45 +579,45 @@ static int process_finished_round(struct perf_tool *tool,
 static void __queue_event(struct ordered_event *new, struct perf_session *s)
 {
 	struct ordered_events *oe = &s->ordered_events;
-	struct ordered_event *sample = oe->last_sample;
+	struct ordered_event *last = oe->last;
 	u64 timestamp = new->timestamp;
 	struct list_head *p;
 
-	++oe->nr_samples;
-	oe->last_sample = new;
+	++oe->nr_events;
+	oe->last = new;
 
-	if (!sample) {
-		list_add(&new->list, &oe->samples);
+	if (!last) {
+		list_add(&new->list, &oe->events);
 		oe->max_timestamp = timestamp;
 		return;
 	}
 
 	/*
-	 * last_sample might point to some random place in the list as it's
+	 * last event might point to some random place in the list as it's
 	 * the last queued event. We expect that the new event is close to
 	 * this.
 	 */
-	if (sample->timestamp <= timestamp) {
-		while (sample->timestamp <= timestamp) {
-			p = sample->list.next;
-			if (p == &oe->samples) {
-				list_add_tail(&new->list, &oe->samples);
+	if (last->timestamp <= timestamp) {
+		while (last->timestamp <= timestamp) {
+			p = last->list.next;
+			if (p == &oe->events) {
+				list_add_tail(&new->list, &oe->events);
 				oe->max_timestamp = timestamp;
 				return;
 			}
-			sample = list_entry(p, struct ordered_event, list);
+			last = list_entry(p, struct ordered_event, list);
 		}
-		list_add_tail(&new->list, &sample->list);
+		list_add_tail(&new->list, &last->list);
 	} else {
-		while (sample->timestamp > timestamp) {
-			p = sample->list.prev;
-			if (p == &oe->samples) {
-				list_add(&new->list, &oe->samples);
+		while (last->timestamp > timestamp) {
+			p = last->list.prev;
+			if (p == &oe->events) {
+				list_add(&new->list, &oe->events);
 				return;
 			}
-			sample = list_entry(p, struct ordered_event, list);
+			last = list_entry(p, struct ordered_event, list);
 		}
-		list_add(&new->list, &sample->list);
+		list_add(&new->list, &last->list);
 	}
 }
 
@@ -629,7 +627,7 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 				    struct perf_sample *sample, u64 file_offset)
 {
 	struct ordered_events *oe = &s->ordered_events;
-	struct list_head *sc = &oe->sample_cache;
+	struct list_head *cache = &oe->cache;
 	u64 timestamp = sample->time;
 	struct ordered_event *new;
 
@@ -641,20 +639,20 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 		return -EINVAL;
 	}
 
-	if (!list_empty(sc)) {
-		new = list_entry(sc->next, struct ordered_event, list);
+	if (!list_empty(cache)) {
+		new = list_entry(cache->next, struct ordered_event, list);
 		list_del(&new->list);
-	} else if (oe->sample_buffer) {
-		new = oe->sample_buffer + oe->sample_buffer_idx;
-		if (++oe->sample_buffer_idx == MAX_SAMPLE_BUFFER)
-			oe->sample_buffer = NULL;
+	} else if (oe->buffer) {
+		new = oe->buffer + oe->buffer_idx;
+		if (++oe->buffer_idx == MAX_SAMPLE_BUFFER)
+			oe->buffer = NULL;
 	} else {
-		oe->sample_buffer = malloc(MAX_SAMPLE_BUFFER * sizeof(*new));
-		if (!oe->sample_buffer)
+		oe->buffer = malloc(MAX_SAMPLE_BUFFER * sizeof(*new));
+		if (!oe->buffer)
 			return -ENOMEM;
-		list_add(&oe->sample_buffer->list, &oe->to_free);
-		oe->sample_buffer_idx = 2;
-		new = oe->sample_buffer + 1;
+		list_add(&oe->buffer->list, &oe->to_free);
+		oe->buffer_idx = 2;
+		new = oe->buffer + 1;
 	}
 
 	new->timestamp = timestamp;
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index f6baf935917a..419eb50e1cd3 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -20,13 +20,13 @@ struct ordered_events {
 	u64			last_flush;
 	u64			next_flush;
 	u64			max_timestamp;
-	struct list_head	samples;
-	struct list_head	sample_cache;
+	struct list_head	events;
+	struct list_head	cache;
 	struct list_head	to_free;
-	struct ordered_event	*sample_buffer;
-	struct ordered_event	*last_sample;
-	int			sample_buffer_idx;
-	unsigned int		nr_samples;
+	struct ordered_event	*buffer;
+	struct ordered_event	*last;
+	int			buffer_idx;
+	unsigned int		nr_events;
 };
 
 struct perf_session {
-- 
1.8.3.1

[PATCH 05/19] perf tools: Add ordered_events_(new|delete) interface

[Jiri Olsa]

Adding new ordered events interface to new|delete event buffer:
  ordered_events_new    - allocate event buffer from the cache
  ordered_events_delete - return event buffer to the cache

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/session.c | 169 +++++++++++++++++++++++++++-------------------
 1 file changed, 98 insertions(+), 71 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index ab7a2084d0bf..12b72bc90125 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -466,6 +466,100 @@ static void perf_session_free_sample_buffers(struct perf_session *session)
 	}
 }
 
+/* The queue is ordered by time */
+static void queue_event(struct ordered_events *oe, struct ordered_event *new)
+{
+	struct ordered_event *last = oe->last;
+	u64 timestamp = new->timestamp;
+	struct list_head *p;
+
+	++oe->nr_events;
+	oe->last = new;
+
+	if (!last) {
+		list_add(&new->list, &oe->events);
+		oe->max_timestamp = timestamp;
+		return;
+	}
+
+	/*
+	 * last event might point to some random place in the list as it's
+	 * the last queued event. We expect that the new event is close to
+	 * this.
+	 */
+	if (last->timestamp <= timestamp) {
+		while (last->timestamp <= timestamp) {
+			p = last->list.next;
+			if (p == &oe->events) {
+				list_add_tail(&new->list, &oe->events);
+				oe->max_timestamp = timestamp;
+				return;
+			}
+			last = list_entry(p, struct ordered_event, list);
+		}
+		list_add_tail(&new->list, &last->list);
+	} else {
+		while (last->timestamp > timestamp) {
+			p = last->list.prev;
+			if (p == &oe->events) {
+				list_add(&new->list, &oe->events);
+				return;
+			}
+			last = list_entry(p, struct ordered_event, list);
+		}
+		list_add(&new->list, &last->list);
+	}
+}
+
+#define MAX_SAMPLE_BUFFER	(64 * 1024 / sizeof(struct ordered_event))
+static struct ordered_event *alloc_event(struct ordered_events *oe)
+{
+	struct list_head *cache = &oe->cache;
+	struct ordered_event *new;
+
+	if (!list_empty(cache)) {
+		new = list_entry(cache->next, struct ordered_event, list);
+		list_del(&new->list);
+	} else if (oe->buffer) {
+		new = oe->buffer + oe->buffer_idx;
+		if (++oe->buffer_idx == MAX_SAMPLE_BUFFER)
+			oe->buffer = NULL;
+	} else {
+		oe->buffer = malloc(MAX_SAMPLE_BUFFER * sizeof(*new));
+		if (!oe->buffer)
+			return NULL;
+		list_add(&oe->buffer->list, &oe->to_free);
+
+		/* First entry is abused to maintain the to_free list. */
+		oe->buffer_idx = 2;
+		new = oe->buffer + 1;
+	}
+
+	return new;
+}
+
+static struct ordered_event*
+ordered_events_new(struct ordered_events *oe, u64 timestamp)
+{
+	struct ordered_event *new;
+
+	new = alloc_event(oe);
+	if (new) {
+		new->timestamp = timestamp;
+		queue_event(oe, new);
+	}
+
+	return new;
+}
+
+static void
+ordered_events_delete(struct ordered_events *oe, struct ordered_event *event)
+{
+	list_del(&event->list);
+	list_add(&event->list, &oe->cache);
+	oe->nr_events--;
+}
+
 static int perf_session_deliver_event(struct perf_session *session,
 				      union perf_event *event,
 				      struct perf_sample *sample,
@@ -508,10 +602,8 @@ static int ordered_events_flush(struct perf_session *s,
 				return ret;
 		}
 
+		ordered_events_delete(oe, iter);
 		oe->last_flush = iter->timestamp;
-		list_del(&iter->list);
-		list_add(&iter->list, &oe->cache);
-		oe->nr_events--;
 
 		if (show_progress)
 			ui_progress__update(&prog, 1);
@@ -575,59 +667,10 @@ static int process_finished_round(struct perf_tool *tool,
 	return ret;
 }
 
-/* The queue is ordered by time */
-static void __queue_event(struct ordered_event *new, struct perf_session *s)
-{
-	struct ordered_events *oe = &s->ordered_events;
-	struct ordered_event *last = oe->last;
-	u64 timestamp = new->timestamp;
-	struct list_head *p;
-
-	++oe->nr_events;
-	oe->last = new;
-
-	if (!last) {
-		list_add(&new->list, &oe->events);
-		oe->max_timestamp = timestamp;
-		return;
-	}
-
-	/*
-	 * last event might point to some random place in the list as it's
-	 * the last queued event. We expect that the new event is close to
-	 * this.
-	 */
-	if (last->timestamp <= timestamp) {
-		while (last->timestamp <= timestamp) {
-			p = last->list.next;
-			if (p == &oe->events) {
-				list_add_tail(&new->list, &oe->events);
-				oe->max_timestamp = timestamp;
-				return;
-			}
-			last = list_entry(p, struct ordered_event, list);
-		}
-		list_add_tail(&new->list, &last->list);
-	} else {
-		while (last->timestamp > timestamp) {
-			p = last->list.prev;
-			if (p == &oe->events) {
-				list_add(&new->list, &oe->events);
-				return;
-			}
-			last = list_entry(p, struct ordered_event, list);
-		}
-		list_add(&new->list, &last->list);
-	}
-}
-
-#define MAX_SAMPLE_BUFFER	(64 * 1024 / sizeof(struct ordered_event))
-
 int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 				    struct perf_sample *sample, u64 file_offset)
 {
 	struct ordered_events *oe = &s->ordered_events;
-	struct list_head *cache = &oe->cache;
 	u64 timestamp = sample->time;
 	struct ordered_event *new;
 
@@ -639,28 +682,12 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 		return -EINVAL;
 	}
 
-	if (!list_empty(cache)) {
-		new = list_entry(cache->next, struct ordered_event, list);
-		list_del(&new->list);
-	} else if (oe->buffer) {
-		new = oe->buffer + oe->buffer_idx;
-		if (++oe->buffer_idx == MAX_SAMPLE_BUFFER)
-			oe->buffer = NULL;
-	} else {
-		oe->buffer = malloc(MAX_SAMPLE_BUFFER * sizeof(*new));
-		if (!oe->buffer)
-			return -ENOMEM;
-		list_add(&oe->buffer->list, &oe->to_free);
-		oe->buffer_idx = 2;
-		new = oe->buffer + 1;
-	}
+	new = ordered_events_new(oe, timestamp);
+	if (!new)
+		return -ENOMEM;
 
-	new->timestamp = timestamp;
 	new->file_offset = file_offset;
 	new->event = event;
-
-	__queue_event(new, s);
-
 	return 0;
 }
 
-- 
1.8.3.1

[PATCH 06/19] perf tools: Factor ordered_events_flush to be more generic

[Jiri Olsa]

Centralizing the next_flush calculation under the
ordered_events_flush function.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/session.c | 47 ++++++++++++++++++++++++++++++++++++-----------
 1 file changed, 36 insertions(+), 11 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 12b72bc90125..f94ec7e55749 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -453,6 +453,11 @@ struct ordered_event {
 	struct list_head	list;
 };
 
+enum oe_flush {
+	OE_FLUSH__FINAL,
+	OE_FLUSH__ROUND,
+};
+
 static void perf_session_free_sample_buffers(struct perf_session *session)
 {
 	struct ordered_events *oe = &session->ordered_events;
@@ -566,8 +571,8 @@ static int perf_session_deliver_event(struct perf_session *session,
 				      struct perf_tool *tool,
 				      u64 file_offset);
 
-static int ordered_events_flush(struct perf_session *s,
-		       struct perf_tool *tool)
+static int __ordered_events_flush(struct perf_session *s,
+				  struct perf_tool *tool)
 {
 	struct ordered_events *oe = &s->ordered_events;
 	struct list_head *head = &oe->events;
@@ -617,6 +622,32 @@ static int ordered_events_flush(struct perf_session *s,
 	return 0;
 }
 
+static int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
+				enum oe_flush how)
+{
+	struct ordered_events *oe = &s->ordered_events;
+	int err;
+
+	switch (how) {
+	case OE_FLUSH__FINAL:
+		oe->next_flush = ULLONG_MAX;
+		break;
+
+	case OE_FLUSH__ROUND:
+	default:
+		break;
+	};
+
+	err = __ordered_events_flush(s, tool);
+
+	if (!err) {
+		if (how == OE_FLUSH__ROUND)
+			oe->next_flush = oe->max_timestamp;
+	}
+
+	return err;
+}
+
 /*
  * When perf record finishes a pass on every buffers, it records this pseudo
  * event.
@@ -660,11 +691,7 @@ static int process_finished_round(struct perf_tool *tool,
 				  union perf_event *event __maybe_unused,
 				  struct perf_session *session)
 {
-	int ret = ordered_events_flush(session, tool);
-	if (!ret)
-		session->ordered_events.next_flush = session->ordered_events.max_timestamp;
-
-	return ret;
+	return ordered_events_flush(session, tool, OE_FLUSH__ROUND);
 }
 
 int perf_session_queue_event(struct perf_session *s, union perf_event *event,
@@ -1247,8 +1274,7 @@ more:
 		goto more;
 done:
 	/* do the final flush for ordered samples */
-	session->ordered_events.next_flush = ULLONG_MAX;
-	err = ordered_events_flush(session, tool);
+	err = ordered_events_flush(session, tool, OE_FLUSH__FINAL);
 out_err:
 	free(buf);
 	perf_session__warn_about_errors(session, tool);
@@ -1389,8 +1415,7 @@ more:
 
 out:
 	/* do the final flush for ordered samples */
-	session->ordered_events.next_flush = ULLONG_MAX;
-	err = ordered_events_flush(session, tool);
+	err = ordered_events_flush(session, tool, OE_FLUSH__FINAL);
 out_err:
 	ui_progress__finish();
 	perf_session__warn_about_errors(session, tool);
-- 
1.8.3.1

[PATCH 07/19] perf tools: Limit ordered events queue size

[Jiri Olsa]

Add limit to the ordered events queue allocation. This way
we will be able to control the size of the queue buffers.

There's no limit at the moment (it's set to (u64) -1). The config
code will come in following patches.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/session.c | 12 +++++++++---
 tools/perf/util/session.h |  2 ++
 2 files changed, 11 insertions(+), 3 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index f94ec7e55749..ebb87318c073 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -79,6 +79,8 @@ struct perf_session *perf_session__new(struct perf_data_file *file,
 	INIT_LIST_HEAD(&session->ordered_events.events);
 	INIT_LIST_HEAD(&session->ordered_events.cache);
 	INIT_LIST_HEAD(&session->ordered_events.to_free);
+	session->ordered_events.max_alloc_size = (u64) -1;
+	session->ordered_events.cur_alloc_size = 0;
 	machines__init(&session->machines);
 
 	if (file) {
@@ -520,7 +522,7 @@ static void queue_event(struct ordered_events *oe, struct ordered_event *new)
 static struct ordered_event *alloc_event(struct ordered_events *oe)
 {
 	struct list_head *cache = &oe->cache;
-	struct ordered_event *new;
+	struct ordered_event *new = NULL;
 
 	if (!list_empty(cache)) {
 		new = list_entry(cache->next, struct ordered_event, list);
@@ -529,10 +531,14 @@ static struct ordered_event *alloc_event(struct ordered_events *oe)
 		new = oe->buffer + oe->buffer_idx;
 		if (++oe->buffer_idx == MAX_SAMPLE_BUFFER)
 			oe->buffer = NULL;
-	} else {
-		oe->buffer = malloc(MAX_SAMPLE_BUFFER * sizeof(*new));
+	} else if (oe->cur_alloc_size < oe->max_alloc_size) {
+		size_t size = MAX_SAMPLE_BUFFER * sizeof(*new);
+
+		oe->buffer = malloc(size);
 		if (!oe->buffer)
 			return NULL;
+
+		oe->cur_alloc_size += size;
 		list_add(&oe->buffer->list, &oe->to_free);
 
 		/* First entry is abused to maintain the to_free list. */
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index 419eb50e1cd3..e2fbaf2567e1 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -20,6 +20,8 @@ struct ordered_events {
 	u64			last_flush;
 	u64			next_flush;
 	u64			max_timestamp;
+	u64			max_alloc_size;
+	u64			cur_alloc_size;
 	struct list_head	events;
 	struct list_head	cache;
 	struct list_head	to_free;
-- 
1.8.3.1

[PATCH 08/19] perf tools: Flush ordered events in case of allocation failure

[Jiri Olsa]

In previous patches we added a limit for ordered events
queue allocation size. If we reach this size we need to
flush (part of) the queue to get some free buffers.

The current functionality is not affected, because the
limit is hard coded to (u64) -1. The configuration code
for size will come in following patches.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-kvm.c  |  2 +-
 tools/perf/util/session.c | 29 +++++++++++++++++++++++++++--
 tools/perf/util/session.h |  3 ++-
 3 files changed, 30 insertions(+), 4 deletions(-)

diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index f8a561643753..f687228850d2 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -732,7 +732,7 @@ static s64 perf_kvm__mmap_read_idx(struct perf_kvm_stat *kvm, int idx,
 			return -1;
 		}
 
-		err = perf_session_queue_event(kvm->session, event, &sample, 0);
+		err = perf_session_queue_event(kvm->session, event, &kvm->tool, &sample, 0);
 		/*
 		 * FIXME: Here we can't consume the event, as perf_session_queue_event will
 		 *        point to it, and it'll get possibly overwritten by the kernel.
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index ebb87318c073..64c58e6f0923 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -15,6 +15,7 @@
 #include "cpumap.h"
 #include "perf_regs.h"
 #include "vdso.h"
+#include "asm/bug.h"
 
 static int perf_session__open(struct perf_session *session)
 {
@@ -458,6 +459,7 @@ struct ordered_event {
 enum oe_flush {
 	OE_FLUSH__FINAL,
 	OE_FLUSH__ROUND,
+	OE_FLUSH__HALF,
 };
 
 static void perf_session_free_sample_buffers(struct perf_session *session)
@@ -639,6 +641,23 @@ static int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 		oe->next_flush = ULLONG_MAX;
 		break;
 
+	case OE_FLUSH__HALF:
+	{
+		struct ordered_event *first, *last;
+		struct list_head *head = &oe->events;
+
+		first = list_entry(head->next, struct ordered_event, list);
+		last = oe->last;
+
+		/* Warn if we are called before any event got allocated. */
+		if (WARN_ONCE(!last || list_empty(head), "empty queue"))
+			return 0;
+
+		oe->next_flush  = first->timestamp;
+		oe->next_flush += (last->timestamp - first->timestamp) / 2;
+		break;
+	}
+
 	case OE_FLUSH__ROUND:
 	default:
 		break;
@@ -701,7 +720,8 @@ static int process_finished_round(struct perf_tool *tool,
 }
 
 int perf_session_queue_event(struct perf_session *s, union perf_event *event,
-				    struct perf_sample *sample, u64 file_offset)
+			     struct perf_tool *tool, struct perf_sample *sample,
+			     u64 file_offset)
 {
 	struct ordered_events *oe = &s->ordered_events;
 	u64 timestamp = sample->time;
@@ -716,6 +736,11 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 	}
 
 	new = ordered_events_new(oe, timestamp);
+	if (!new) {
+		ordered_events_flush(s, tool, OE_FLUSH__HALF);
+		new = ordered_events_new(oe, timestamp);
+	}
+
 	if (!new)
 		return -ENOMEM;
 
@@ -1121,7 +1146,7 @@ static int perf_session__process_event(struct perf_session *session,
 		return ret;
 
 	if (tool->ordered_events) {
-		ret = perf_session_queue_event(session, event, &sample,
+		ret = perf_session_queue_event(session, event, tool, &sample,
 					       file_offset);
 		if (ret != -ETIME)
 			return ret;
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index e2fbaf2567e1..a09e3c8d825a 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -67,7 +67,8 @@ int perf_session__process_events(struct perf_session *session,
 				 struct perf_tool *tool);
 
 int perf_session_queue_event(struct perf_session *s, union perf_event *event,
-			     struct perf_sample *sample, u64 file_offset);
+			     struct perf_tool *tool, struct perf_sample *sample,
+			     u64 file_offset);
 
 void perf_tool__fill_defaults(struct perf_tool *tool);
 
-- 
1.8.3.1

[PATCH 09/19] perf tools: Make perf_session_deliver_event global

[Jiri Olsa]

Making perf_session_deliver_event global function, as it will
be called from another object in following patch.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/session.c | 16 +++++-----------
 tools/perf/util/session.h |  6 ++++++
 2 files changed, 11 insertions(+), 11 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 64c58e6f0923..a601f2aa8990 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -573,12 +573,6 @@ ordered_events_delete(struct ordered_events *oe, struct ordered_event *event)
 	oe->nr_events--;
 }
 
-static int perf_session_deliver_event(struct perf_session *session,
-				      union perf_event *event,
-				      struct perf_sample *sample,
-				      struct perf_tool *tool,
-				      u64 file_offset);
-
 static int __ordered_events_flush(struct perf_session *s,
 				  struct perf_tool *tool)
 {
@@ -1005,11 +999,11 @@ perf_session__deliver_sample(struct perf_session *session,
 					    &sample->read.one, machine);
 }
 
-static int perf_session_deliver_event(struct perf_session *session,
-				      union perf_event *event,
-				      struct perf_sample *sample,
-				      struct perf_tool *tool,
-				      u64 file_offset)
+int perf_session_deliver_event(struct perf_session *session,
+			       union perf_event *event,
+			       struct perf_sample *sample,
+			       struct perf_tool *tool,
+			       u64 file_offset)
 {
 	struct perf_evsel *evsel;
 	struct machine *machine;
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index a09e3c8d825a..07d1a6d94f67 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -72,6 +72,12 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 
 void perf_tool__fill_defaults(struct perf_tool *tool);
 
+int perf_session_deliver_event(struct perf_session *session,
+			       union perf_event *event,
+			       struct perf_sample *sample,
+			       struct perf_tool *tool,
+			       u64 file_offset);
+
 int perf_session__resolve_callchain(struct perf_session *session,
 				    struct perf_evsel *evsel,
 				    struct thread *thread,
-- 
1.8.3.1

[PATCH 10/19] perf tools: Create ordered-events object

[Jiri Olsa]

Move ordered events code into separated object ordered-events.[ch].

No functional change was intended.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/Makefile.perf         |   2 +
 tools/perf/util/ordered-events.c | 196 +++++++++++++++++++++++++++++++++++++
 tools/perf/util/ordered-events.h |  41 ++++++++
 tools/perf/util/session.c        | 206 ---------------------------------------
 tools/perf/util/session.h        |  17 +---
 5 files changed, 240 insertions(+), 222 deletions(-)
 create mode 100644 tools/perf/util/ordered-events.c
 create mode 100644 tools/perf/util/ordered-events.h

diff --git a/tools/perf/Makefile.perf b/tools/perf/Makefile.perf
index 2240974b7745..1ea31e275b4d 100644
--- a/tools/perf/Makefile.perf
+++ b/tools/perf/Makefile.perf
@@ -263,6 +263,7 @@ LIB_H += util/xyarray.h
 LIB_H += util/header.h
 LIB_H += util/help.h
 LIB_H += util/session.h
+LIB_H += util/ordered-events.h
 LIB_H += util/strbuf.h
 LIB_H += util/strlist.h
 LIB_H += util/strfilter.h
@@ -347,6 +348,7 @@ LIB_OBJS += $(OUTPUT)util/machine.o
 LIB_OBJS += $(OUTPUT)util/map.o
 LIB_OBJS += $(OUTPUT)util/pstack.o
 LIB_OBJS += $(OUTPUT)util/session.o
+LIB_OBJS += $(OUTPUT)util/ordered-events.o
 LIB_OBJS += $(OUTPUT)util/comm.o
 LIB_OBJS += $(OUTPUT)util/thread.o
 LIB_OBJS += $(OUTPUT)util/thread_map.o
diff --git a/tools/perf/util/ordered-events.c b/tools/perf/util/ordered-events.c
new file mode 100644
index 000000000000..fb94f8b07515
--- /dev/null
+++ b/tools/perf/util/ordered-events.c
@@ -0,0 +1,196 @@
+#include <linux/list.h>
+#include "ordered-events.h"
+#include "evlist.h"
+#include "session.h"
+#include "asm/bug.h"
+#include "debug.h"
+
+static void queue_event(struct ordered_events *oe, struct ordered_event *new)
+{
+	struct ordered_event *last = oe->last;
+	u64 timestamp = new->timestamp;
+	struct list_head *p;
+
+	++oe->nr_events;
+	oe->last = new;
+
+	if (!last) {
+		list_add(&new->list, &oe->events);
+		oe->max_timestamp = timestamp;
+		return;
+	}
+
+	/*
+	 * last event might point to some random place in the list as it's
+	 * the last queued event. We expect that the new event is close to
+	 * this.
+	 */
+	if (last->timestamp <= timestamp) {
+		while (last->timestamp <= timestamp) {
+			p = last->list.next;
+			if (p == &oe->events) {
+				list_add_tail(&new->list, &oe->events);
+				oe->max_timestamp = timestamp;
+				return;
+			}
+			last = list_entry(p, struct ordered_event, list);
+		}
+		list_add_tail(&new->list, &last->list);
+	} else {
+		while (last->timestamp > timestamp) {
+			p = last->list.prev;
+			if (p == &oe->events) {
+				list_add(&new->list, &oe->events);
+				return;
+			}
+			last = list_entry(p, struct ordered_event, list);
+		}
+		list_add(&new->list, &last->list);
+	}
+}
+
+#define MAX_SAMPLE_BUFFER	(64 * 1024 / sizeof(struct ordered_event))
+static struct ordered_event *alloc_event(struct ordered_events *oe)
+{
+	struct list_head *cache = &oe->cache;
+	struct ordered_event *new = NULL;
+
+	if (!list_empty(cache)) {
+		new = list_entry(cache->next, struct ordered_event, list);
+		list_del(&new->list);
+	} else if (oe->buffer) {
+		new = oe->buffer + oe->buffer_idx;
+		if (++oe->buffer_idx == MAX_SAMPLE_BUFFER)
+			oe->buffer = NULL;
+	} else if (oe->cur_alloc_size < oe->max_alloc_size) {
+		size_t size = MAX_SAMPLE_BUFFER * sizeof(*new);
+
+		oe->buffer = malloc(size);
+		if (!oe->buffer)
+			return NULL;
+
+		oe->cur_alloc_size += size;
+		list_add(&oe->buffer->list, &oe->to_free);
+
+		/* First entry is abused to maintain the to_free list. */
+		oe->buffer_idx = 2;
+		new = oe->buffer + 1;
+	}
+
+	return new;
+}
+
+struct ordered_event*
+ordered_events_new(struct ordered_events *oe, u64 timestamp)
+{
+	struct ordered_event *new;
+
+	new = alloc_event(oe);
+	if (new) {
+		new->timestamp = timestamp;
+		queue_event(oe, new);
+	}
+
+	return new;
+}
+
+void ordered_events_delete(struct ordered_events *oe, struct ordered_event *event)
+{
+	list_del(&event->list);
+	list_add(&event->list, &oe->cache);
+	oe->nr_events--;
+}
+
+static int __ordered_events_flush(struct perf_session *s,
+				  struct perf_tool *tool)
+{
+	struct ordered_events *oe = &s->ordered_events;
+	struct list_head *head = &oe->events;
+	struct ordered_event *tmp, *iter;
+	struct perf_sample sample;
+	u64 limit = oe->next_flush;
+	u64 last_ts = oe->last ? oe->last->timestamp : 0ULL;
+	bool show_progress = limit == ULLONG_MAX;
+	struct ui_progress prog;
+	int ret;
+
+	if (!tool->ordered_events || !limit)
+		return 0;
+
+	if (show_progress)
+		ui_progress__init(&prog, oe->nr_events, "Processing time ordered events...");
+
+	list_for_each_entry_safe(iter, tmp, head, list) {
+		if (session_done())
+			return 0;
+
+		if (iter->timestamp > limit)
+			break;
+
+		ret = perf_evlist__parse_sample(s->evlist, iter->event, &sample);
+		if (ret)
+			pr_err("Can't parse sample, err = %d\n", ret);
+		else {
+			ret = perf_session_deliver_event(s, iter->event, &sample, tool,
+							 iter->file_offset);
+			if (ret)
+				return ret;
+		}
+
+		ordered_events_delete(oe, iter);
+		oe->last_flush = iter->timestamp;
+
+		if (show_progress)
+			ui_progress__update(&prog, 1);
+	}
+
+	if (list_empty(head))
+		oe->last = NULL;
+	else if (last_ts <= limit)
+		oe->last = list_entry(head->prev, struct ordered_event, list);
+
+	return 0;
+}
+
+int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
+			 enum oe_flush how)
+{
+	struct ordered_events *oe = &s->ordered_events;
+	int err;
+
+	switch (how) {
+	case OE_FLUSH__FINAL:
+		oe->next_flush = ULLONG_MAX;
+		break;
+
+	case OE_FLUSH__HALF:
+	{
+		struct ordered_event *first, *last;
+		struct list_head *head = &oe->events;
+
+		first = list_entry(head->next, struct ordered_event, list);
+		last = oe->last;
+
+		/* Warn if we are called before any event got allocated. */
+		if (WARN_ONCE(!last || list_empty(head), "empty queue"))
+			return 0;
+
+		oe->next_flush  = first->timestamp;
+		oe->next_flush += (last->timestamp - first->timestamp) / 2;
+		break;
+	}
+
+	case OE_FLUSH__ROUND:
+	default:
+		break;
+	};
+
+	err = __ordered_events_flush(s, tool);
+
+	if (!err) {
+		if (how == OE_FLUSH__ROUND)
+			oe->next_flush = oe->max_timestamp;
+	}
+
+	return err;
+}
diff --git a/tools/perf/util/ordered-events.h b/tools/perf/util/ordered-events.h
new file mode 100644
index 000000000000..30e39aa825ef
--- /dev/null
+++ b/tools/perf/util/ordered-events.h
@@ -0,0 +1,41 @@
+#ifndef __ORDERED_EVENTS_H
+#define __ORDERED_EVENTS_H
+
+#include <linux/types.h>
+#include "tool.h"
+
+struct perf_session;
+
+struct ordered_event {
+	u64			timestamp;
+	u64			file_offset;
+	union perf_event	*event;
+	struct list_head	list;
+};
+
+enum oe_flush {
+	OE_FLUSH__FINAL,
+	OE_FLUSH__ROUND,
+	OE_FLUSH__HALF,
+};
+
+struct ordered_events {
+	u64			last_flush;
+	u64			next_flush;
+	u64			max_timestamp;
+	u64			max_alloc_size;
+	u64			cur_alloc_size;
+	struct list_head	events;
+	struct list_head	cache;
+	struct list_head	to_free;
+	struct ordered_event	*buffer;
+	struct ordered_event	*last;
+	int			buffer_idx;
+	unsigned int		nr_events;
+};
+
+struct ordered_event *ordered_events_new(struct ordered_events *oe, u64 timestamp);
+void ordered_events_delete(struct ordered_events *oe, struct ordered_event *event);
+int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
+			 enum oe_flush how);
+#endif /* __ORDERED_EVENTS_H */
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index a601f2aa8990..b67ea4b78478 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -15,7 +15,6 @@
 #include "cpumap.h"
 #include "perf_regs.h"
 #include "vdso.h"
-#include "asm/bug.h"
 
 static int perf_session__open(struct perf_session *session)
 {
@@ -449,19 +448,6 @@ static perf_event__swap_op perf_event__swap_ops[] = {
 	[PERF_RECORD_HEADER_MAX]	  = NULL,
 };
 
-struct ordered_event {
-	u64			timestamp;
-	u64			file_offset;
-	union perf_event	*event;
-	struct list_head	list;
-};
-
-enum oe_flush {
-	OE_FLUSH__FINAL,
-	OE_FLUSH__ROUND,
-	OE_FLUSH__HALF,
-};
-
 static void perf_session_free_sample_buffers(struct perf_session *session)
 {
 	struct ordered_events *oe = &session->ordered_events;
@@ -475,198 +461,6 @@ static void perf_session_free_sample_buffers(struct perf_session *session)
 	}
 }
 
-/* The queue is ordered by time */
-static void queue_event(struct ordered_events *oe, struct ordered_event *new)
-{
-	struct ordered_event *last = oe->last;
-	u64 timestamp = new->timestamp;
-	struct list_head *p;
-
-	++oe->nr_events;
-	oe->last = new;
-
-	if (!last) {
-		list_add(&new->list, &oe->events);
-		oe->max_timestamp = timestamp;
-		return;
-	}
-
-	/*
-	 * last event might point to some random place in the list as it's
-	 * the last queued event. We expect that the new event is close to
-	 * this.
-	 */
-	if (last->timestamp <= timestamp) {
-		while (last->timestamp <= timestamp) {
-			p = last->list.next;
-			if (p == &oe->events) {
-				list_add_tail(&new->list, &oe->events);
-				oe->max_timestamp = timestamp;
-				return;
-			}
-			last = list_entry(p, struct ordered_event, list);
-		}
-		list_add_tail(&new->list, &last->list);
-	} else {
-		while (last->timestamp > timestamp) {
-			p = last->list.prev;
-			if (p == &oe->events) {
-				list_add(&new->list, &oe->events);
-				return;
-			}
-			last = list_entry(p, struct ordered_event, list);
-		}
-		list_add(&new->list, &last->list);
-	}
-}
-
-#define MAX_SAMPLE_BUFFER	(64 * 1024 / sizeof(struct ordered_event))
-static struct ordered_event *alloc_event(struct ordered_events *oe)
-{
-	struct list_head *cache = &oe->cache;
-	struct ordered_event *new = NULL;
-
-	if (!list_empty(cache)) {
-		new = list_entry(cache->next, struct ordered_event, list);
-		list_del(&new->list);
-	} else if (oe->buffer) {
-		new = oe->buffer + oe->buffer_idx;
-		if (++oe->buffer_idx == MAX_SAMPLE_BUFFER)
-			oe->buffer = NULL;
-	} else if (oe->cur_alloc_size < oe->max_alloc_size) {
-		size_t size = MAX_SAMPLE_BUFFER * sizeof(*new);
-
-		oe->buffer = malloc(size);
-		if (!oe->buffer)
-			return NULL;
-
-		oe->cur_alloc_size += size;
-		list_add(&oe->buffer->list, &oe->to_free);
-
-		/* First entry is abused to maintain the to_free list. */
-		oe->buffer_idx = 2;
-		new = oe->buffer + 1;
-	}
-
-	return new;
-}
-
-static struct ordered_event*
-ordered_events_new(struct ordered_events *oe, u64 timestamp)
-{
-	struct ordered_event *new;
-
-	new = alloc_event(oe);
-	if (new) {
-		new->timestamp = timestamp;
-		queue_event(oe, new);
-	}
-
-	return new;
-}
-
-static void
-ordered_events_delete(struct ordered_events *oe, struct ordered_event *event)
-{
-	list_del(&event->list);
-	list_add(&event->list, &oe->cache);
-	oe->nr_events--;
-}
-
-static int __ordered_events_flush(struct perf_session *s,
-				  struct perf_tool *tool)
-{
-	struct ordered_events *oe = &s->ordered_events;
-	struct list_head *head = &oe->events;
-	struct ordered_event *tmp, *iter;
-	struct perf_sample sample;
-	u64 limit = oe->next_flush;
-	u64 last_ts = oe->last ? oe->last->timestamp : 0ULL;
-	bool show_progress = limit == ULLONG_MAX;
-	struct ui_progress prog;
-	int ret;
-
-	if (!tool->ordered_events || !limit)
-		return 0;
-
-	if (show_progress)
-		ui_progress__init(&prog, oe->nr_events, "Processing time ordered events...");
-
-	list_for_each_entry_safe(iter, tmp, head, list) {
-		if (session_done())
-			return 0;
-
-		if (iter->timestamp > limit)
-			break;
-
-		ret = perf_evlist__parse_sample(s->evlist, iter->event, &sample);
-		if (ret)
-			pr_err("Can't parse sample, err = %d\n", ret);
-		else {
-			ret = perf_session_deliver_event(s, iter->event, &sample, tool,
-							 iter->file_offset);
-			if (ret)
-				return ret;
-		}
-
-		ordered_events_delete(oe, iter);
-		oe->last_flush = iter->timestamp;
-
-		if (show_progress)
-			ui_progress__update(&prog, 1);
-	}
-
-	if (list_empty(head))
-		oe->last = NULL;
-	else if (last_ts <= limit)
-		oe->last = list_entry(head->prev, struct ordered_event, list);
-
-	return 0;
-}
-
-static int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
-				enum oe_flush how)
-{
-	struct ordered_events *oe = &s->ordered_events;
-	int err;
-
-	switch (how) {
-	case OE_FLUSH__FINAL:
-		oe->next_flush = ULLONG_MAX;
-		break;
-
-	case OE_FLUSH__HALF:
-	{
-		struct ordered_event *first, *last;
-		struct list_head *head = &oe->events;
-
-		first = list_entry(head->next, struct ordered_event, list);
-		last = oe->last;
-
-		/* Warn if we are called before any event got allocated. */
-		if (WARN_ONCE(!last || list_empty(head), "empty queue"))
-			return 0;
-
-		oe->next_flush  = first->timestamp;
-		oe->next_flush += (last->timestamp - first->timestamp) / 2;
-		break;
-	}
-
-	case OE_FLUSH__ROUND:
-	default:
-		break;
-	};
-
-	err = __ordered_events_flush(s, tool);
-
-	if (!err) {
-		if (how == OE_FLUSH__ROUND)
-			oe->next_flush = oe->max_timestamp;
-	}
-
-	return err;
-}
-
 /*
  * When perf record finishes a pass on every buffers, it records this pseudo
  * event.
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index 07d1a6d94f67..93f61f02c2d4 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -9,28 +9,13 @@
 #include "symbol.h"
 #include "thread.h"
 #include "data.h"
+#include "ordered-events.h"
 #include <linux/rbtree.h>
 #include <linux/perf_event.h>
 
-struct ordered_event;
 struct ip_callchain;
 struct thread;
 
-struct ordered_events {
-	u64			last_flush;
-	u64			next_flush;
-	u64			max_timestamp;
-	u64			max_alloc_size;
-	u64			cur_alloc_size;
-	struct list_head	events;
-	struct list_head	cache;
-	struct list_head	to_free;
-	struct ordered_event	*buffer;
-	struct ordered_event	*last;
-	int			buffer_idx;
-	unsigned int		nr_events;
-};
-
 struct perf_session {
 	struct perf_header	header;
 	struct machines		machines;
-- 
1.8.3.1

[PATCH 11/19] perf tools: Use list_move in ordered_events_delete function

[Jiri Olsa]

As Namhyung pointed out we can use list_move in ordered_events_delete.

Suggested-by: Namhyung Kim <namhyung@kernel.org>
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/ordered-events.c | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/tools/perf/util/ordered-events.c b/tools/perf/util/ordered-events.c
index fb94f8b07515..ecdc9012cadd 100644
--- a/tools/perf/util/ordered-events.c
+++ b/tools/perf/util/ordered-events.c
@@ -96,8 +96,7 @@ ordered_events_new(struct ordered_events *oe, u64 timestamp)
 
 void ordered_events_delete(struct ordered_events *oe, struct ordered_event *event)
 {
-	list_del(&event->list);
-	list_add(&event->list, &oe->cache);
+	list_move(&event->list, &oe->cache);
 	oe->nr_events--;
 }
 
-- 
1.8.3.1

[PATCH 12/19] perf tools: Add ordered_events_init function

[Jiri Olsa]

Adding ordered_events_init function for struct
ordered_events struct initialization.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/ordered-events.c | 9 +++++++++
 tools/perf/util/ordered-events.h | 1 +
 tools/perf/util/session.c        | 6 +-----
 3 files changed, 11 insertions(+), 5 deletions(-)

diff --git a/tools/perf/util/ordered-events.c b/tools/perf/util/ordered-events.c
index ecdc9012cadd..42d63396600c 100644
--- a/tools/perf/util/ordered-events.c
+++ b/tools/perf/util/ordered-events.c
@@ -193,3 +193,12 @@ int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 
 	return err;
 }
+
+void ordered_events_init(struct ordered_events *oe)
+{
+	INIT_LIST_HEAD(&oe->events);
+	INIT_LIST_HEAD(&oe->cache);
+	INIT_LIST_HEAD(&oe->to_free);
+	oe->max_alloc_size = (u64) -1;
+	oe->cur_alloc_size = 0;
+}
diff --git a/tools/perf/util/ordered-events.h b/tools/perf/util/ordered-events.h
index 30e39aa825ef..ce3f7f37b188 100644
--- a/tools/perf/util/ordered-events.h
+++ b/tools/perf/util/ordered-events.h
@@ -38,4 +38,5 @@ struct ordered_event *ordered_events_new(struct ordered_events *oe, u64 timestam
 void ordered_events_delete(struct ordered_events *oe, struct ordered_event *event);
 int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 			 enum oe_flush how);
+void ordered_events_init(struct ordered_events *oe);
 #endif /* __ORDERED_EVENTS_H */
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index b67ea4b78478..40956a3164e8 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -76,11 +76,7 @@ struct perf_session *perf_session__new(struct perf_data_file *file,
 		goto out;
 
 	session->repipe = repipe;
-	INIT_LIST_HEAD(&session->ordered_events.events);
-	INIT_LIST_HEAD(&session->ordered_events.cache);
-	INIT_LIST_HEAD(&session->ordered_events.to_free);
-	session->ordered_events.max_alloc_size = (u64) -1;
-	session->ordered_events.cur_alloc_size = 0;
+	ordered_events_init(&session->ordered_events);
 	machines__init(&session->machines);
 
 	if (file) {
-- 
1.8.3.1

[PATCH 13/19] perf tools: Add ordered_events_free function

[Jiri Olsa]

Adding ordered_events_free function to release all the
struct ordered_events data. It's replacement for former
perf_session_free_sample_buffers function.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/ordered-events.c | 11 +++++++++++
 tools/perf/util/ordered-events.h |  1 +
 tools/perf/util/session.c        | 17 ++---------------
 3 files changed, 14 insertions(+), 15 deletions(-)

diff --git a/tools/perf/util/ordered-events.c b/tools/perf/util/ordered-events.c
index 42d63396600c..6c48dfe24dc4 100644
--- a/tools/perf/util/ordered-events.c
+++ b/tools/perf/util/ordered-events.c
@@ -202,3 +202,14 @@ void ordered_events_init(struct ordered_events *oe)
 	oe->max_alloc_size = (u64) -1;
 	oe->cur_alloc_size = 0;
 }
+
+void ordered_events_free(struct ordered_events *oe)
+{
+	while (!list_empty(&oe->to_free)) {
+		struct ordered_event *event;
+
+		event = list_entry(oe->to_free.next, struct ordered_event, list);
+		list_del(&event->list);
+		free(event);
+	}
+}
diff --git a/tools/perf/util/ordered-events.h b/tools/perf/util/ordered-events.h
index ce3f7f37b188..de40a8bb6466 100644
--- a/tools/perf/util/ordered-events.h
+++ b/tools/perf/util/ordered-events.h
@@ -39,4 +39,5 @@ void ordered_events_delete(struct ordered_events *oe, struct ordered_event *even
 int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 			 enum oe_flush how);
 void ordered_events_init(struct ordered_events *oe);
+void ordered_events_free(struct ordered_events *oe);
 #endif /* __ORDERED_EVENTS_H */
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 40956a3164e8..4e748142a13f 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -444,19 +444,6 @@ static perf_event__swap_op perf_event__swap_ops[] = {
 	[PERF_RECORD_HEADER_MAX]	  = NULL,
 };
 
-static void perf_session_free_sample_buffers(struct perf_session *session)
-{
-	struct ordered_events *oe = &session->ordered_events;
-
-	while (!list_empty(&oe->to_free)) {
-		struct ordered_event *event;
-
-		event = list_entry(oe->to_free.next, struct ordered_event, list);
-		list_del(&event->list);
-		free(event);
-	}
-}
-
 /*
  * When perf record finishes a pass on every buffers, it records this pseudo
  * event.
@@ -1093,7 +1080,7 @@ done:
 out_err:
 	free(buf);
 	perf_session__warn_about_errors(session, tool);
-	perf_session_free_sample_buffers(session);
+	ordered_events_free(&session->ordered_events);
 	return err;
 }
 
@@ -1234,7 +1221,7 @@ out:
 out_err:
 	ui_progress__finish();
 	perf_session__warn_about_errors(session, tool);
-	perf_session_free_sample_buffers(session);
+	ordered_events_free(&session->ordered_events);
 	session->one_mmap = false;
 	return err;
 }
-- 
1.8.3.1

[PATCH 14/19] perf tools: Add perf_config_u64 function

[Jiri Olsa]

Adding perf_config_u64 function to be able to parse
'llong' values out of config file.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/cache.h  |  1 +
 tools/perf/util/config.c | 24 ++++++++++++++++++++++++
 2 files changed, 25 insertions(+)

diff --git a/tools/perf/util/cache.h b/tools/perf/util/cache.h
index 7b176dd02e1a..5cf9e1b5989d 100644
--- a/tools/perf/util/cache.h
+++ b/tools/perf/util/cache.h
@@ -22,6 +22,7 @@ typedef int (*config_fn_t)(const char *, const char *, void *);
 extern int perf_default_config(const char *, const char *, void *);
 extern int perf_config(config_fn_t fn, void *);
 extern int perf_config_int(const char *, const char *);
+extern u64 perf_config_u64(const char *, const char *);
 extern int perf_config_bool(const char *, const char *);
 extern int config_error_nonbool(const char *);
 extern const char *perf_config_dirname(const char *, const char *);
diff --git a/tools/perf/util/config.c b/tools/perf/util/config.c
index 1e5e2e5af6b1..9970b8b0190b 100644
--- a/tools/perf/util/config.c
+++ b/tools/perf/util/config.c
@@ -286,6 +286,21 @@ static int parse_unit_factor(const char *end, unsigned long *val)
 	return 0;
 }
 
+static int perf_parse_llong(const char *value, long long *ret)
+{
+	if (value && *value) {
+		char *end;
+		long long val = strtoll(value, &end, 0);
+		unsigned long factor = 1;
+
+		if (!parse_unit_factor(end, &factor))
+			return 0;
+		*ret = val * factor;
+		return 1;
+	}
+	return 0;
+}
+
 static int perf_parse_long(const char *value, long *ret)
 {
 	if (value && *value) {
@@ -307,6 +322,15 @@ static void die_bad_config(const char *name)
 	die("bad config value for '%s'", name);
 }
 
+u64 perf_config_u64(const char *name, const char *value)
+{
+	long long ret = 0;
+
+	if (!perf_parse_llong(value, &ret))
+		die_bad_config(name);
+	return (u64) ret;
+}
+
 int perf_config_int(const char *name, const char *value)
 {
 	long ret = 0;
-- 
1.8.3.1

[PATCH 15/19] perf tools: Add report.queue-size config file option

[Jiri Olsa]

Adding report.queue-size config file option to setup
the maximum allocation size for session's struct
ordered_events_queue object.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-report.c      | 13 ++++++++++++-
 tools/perf/util/ordered-events.h |  6 ++++++
 2 files changed, 18 insertions(+), 1 deletion(-)

diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index c72cc5a12144..ff6ab6184745 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -58,17 +58,19 @@ struct report {
 	const char		*symbol_filter_str;
 	float			min_percent;
 	u64			nr_entries;
+	u64			queue_size;
 	DECLARE_BITMAP(cpu_bitmap, MAX_NR_CPUS);
 };
 
 static int report__config(const char *var, const char *value, void *cb)
 {
+	struct report *rep = cb;
+
 	if (!strcmp(var, "report.group")) {
 		symbol_conf.event_group = perf_config_bool(var, value);
 		return 0;
 	}
 	if (!strcmp(var, "report.percent-limit")) {
-		struct report *rep = cb;
 		rep->min_percent = strtof(value, NULL);
 		return 0;
 	}
@@ -76,6 +78,10 @@ static int report__config(const char *var, const char *value, void *cb)
 		symbol_conf.cumulate_callchain = perf_config_bool(var, value);
 		return 0;
 	}
+	if (!strcmp(var, "report.queue-size")) {
+		rep->queue_size = perf_config_u64(var, value);
+		return 0;
+	}
 
 	return perf_default_config(var, value, cb);
 }
@@ -714,6 +720,11 @@ repeat:
 	if (session == NULL)
 		return -ENOMEM;
 
+	if (report.queue_size) {
+		ordered_events_alloc_size(&session->ordered_events,
+					  report.queue_size);
+	}
+
 	report.session = session;
 
 	has_br_stack = perf_header__has_feat(&session->header,
diff --git a/tools/perf/util/ordered-events.h b/tools/perf/util/ordered-events.h
index de40a8bb6466..a4fc435f0fc6 100644
--- a/tools/perf/util/ordered-events.h
+++ b/tools/perf/util/ordered-events.h
@@ -40,4 +40,10 @@ int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 			 enum oe_flush how);
 void ordered_events_init(struct ordered_events *oe);
 void ordered_events_free(struct ordered_events *oe);
+
+static inline void
+ordered_events_alloc_size(struct ordered_events *oe, u64 size)
+{
+	oe->max_alloc_size = size;
+}
 #endif /* __ORDERED_EVENTS_H */
-- 
1.8.3.1

[PATCH 16/19] perf tools: Add debug prints for ordered events queue

[Jiri Olsa]

Adding some prints for ordered events queue, to help
debug issues.

Adding debug_ordered_events debug variable to be able
to enable ordered events debug messages using:
  $ perf --debug ordered-events=2 report ...

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/debug.c          |  4 +++-
 tools/perf/util/debug.h          |  1 +
 tools/perf/util/ordered-events.c | 44 ++++++++++++++++++++++++++++++++++++++++
 3 files changed, 48 insertions(+), 1 deletion(-)

diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
index 71d419362634..5c30f80f6295 100644
--- a/tools/perf/util/debug.c
+++ b/tools/perf/util/debug.c
@@ -15,6 +15,7 @@
 
 int verbose;
 bool dump_trace = false, quiet = false;
+int debug_ordered_events;
 
 static int _eprintf(int level, int var, const char *fmt, va_list args)
 {
@@ -110,7 +111,8 @@ static struct debug_variable {
 	const char *name;
 	int *ptr;
 } debug_variables[] = {
-	{ .name = "verbose", .ptr = &verbose },
+	{ .name = "verbose",		.ptr = &verbose },
+	{ .name = "ordered-events",	.ptr = &debug_ordered_events},
 	{ .name = NULL, }
 };
 
diff --git a/tools/perf/util/debug.h b/tools/perf/util/debug.h
index 89fb6b0f7ab2..69340d3408e2 100644
--- a/tools/perf/util/debug.h
+++ b/tools/perf/util/debug.h
@@ -10,6 +10,7 @@
 
 extern int verbose;
 extern bool quiet, dump_trace;
+extern int debug_ordered_events;
 
 #ifndef pr_fmt
 #define pr_fmt(fmt) fmt
diff --git a/tools/perf/util/ordered-events.c b/tools/perf/util/ordered-events.c
index 6c48dfe24dc4..1a699fc16b92 100644
--- a/tools/perf/util/ordered-events.c
+++ b/tools/perf/util/ordered-events.c
@@ -1,10 +1,27 @@
 #include <linux/list.h>
+#include <linux/compiler.h>
 #include "ordered-events.h"
 #include "evlist.h"
 #include "session.h"
 #include "asm/bug.h"
 #include "debug.h"
 
+#define pr_N(n, fmt, ...) \
+	eprintf(n, debug_ordered_events, fmt, ##__VA_ARGS__)
+
+#define pr(fmt, ...)   pr_N(1, pr_fmt(fmt), ##__VA_ARGS__)
+
+static int pr_time(const char *str, u64 t)
+{
+	u64 secs, usecs, nsecs = t;
+
+	secs   = nsecs / NSECS_PER_SEC;
+	nsecs -= secs * NSECS_PER_SEC;
+	usecs  = nsecs / NSECS_PER_USEC;
+	return fprintf(stderr, "\t[%13" PRIu64 ".%06" PRIu64 "] %s\n",
+		       secs, usecs, str);
+}
+
 static void queue_event(struct ordered_events *oe, struct ordered_event *new)
 {
 	struct ordered_event *last = oe->last;
@@ -14,6 +31,9 @@ static void queue_event(struct ordered_events *oe, struct ordered_event *new)
 	++oe->nr_events;
 	oe->last = new;
 
+	if (unlikely(debug_ordered_events > 1))
+		pr_time("queue_event", timestamp);
+
 	if (!last) {
 		list_add(&new->list, &oe->events);
 		oe->max_timestamp = timestamp;
@@ -69,12 +89,17 @@ static struct ordered_event *alloc_event(struct ordered_events *oe)
 		if (!oe->buffer)
 			return NULL;
 
+		pr("alloc size %" PRIu64 "B (+%zu), max %" PRIu64 "B\n",
+		   oe->cur_alloc_size, size, oe->max_alloc_size);
+
 		oe->cur_alloc_size += size;
 		list_add(&oe->buffer->list, &oe->to_free);
 
 		/* First entry is abused to maintain the to_free list. */
 		oe->buffer_idx = 2;
 		new = oe->buffer + 1;
+	} else {
+		pr("allocation limit reached %" PRIu64 "B\n", oe->max_alloc_size);
 	}
 
 	return new;
@@ -155,6 +180,11 @@ int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 			 enum oe_flush how)
 {
 	struct ordered_events *oe = &s->ordered_events;
+	static const char * const str[] = {
+		"FINAL",
+		"ROUND",
+		"HALF ",
+	};
 	int err;
 
 	switch (how) {
@@ -184,6 +214,13 @@ int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 		break;
 	};
 
+	if (unlikely(debug_ordered_events)) {
+		fprintf(stderr, "ordered_events_flush PRE  %s, nr_events %u\n",
+			str[how], oe->nr_events);
+		pr_time("next_flush",    oe->next_flush);
+		pr_time("max_timestamp", oe->max_timestamp);
+	}
+
 	err = __ordered_events_flush(s, tool);
 
 	if (!err) {
@@ -191,6 +228,13 @@ int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 			oe->next_flush = oe->max_timestamp;
 	}
 
+	if (unlikely(debug_ordered_events)) {
+		fprintf(stderr, "ordered_events_flush POST %s, nr_events %u\n",
+			str[how], oe->nr_events);
+		pr_time("next_flush", oe->next_flush);
+		pr_time("last_flush", oe->last_flush);
+	}
+
 	return err;
 }
 
-- 
1.8.3.1

[PATCH 17/19] perf tools: Always force PERF_RECORD_FINISHED_ROUND event

[Jiri Olsa]

The PERF_RECORD_FINISHED_ROUND governs queue flushing in
reporting, so it needs to be stored for any kind of event.

Forcing the PERF_RECORD_FINISHED_ROUND event to be stored any
time we finish the round and wrote at least one event.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-record.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index 378b85b731a7..4869050e7194 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -238,6 +238,7 @@ static struct perf_event_header finished_round_event = {
 
 static int record__mmap_read_all(struct record *rec)
 {
+	u64 bytes_written = rec->bytes_written;
 	int i;
 	int rc = 0;
 
@@ -250,7 +251,11 @@ static int record__mmap_read_all(struct record *rec)
 		}
 	}
 
-	if (perf_header__has_feat(&rec->session->header, HEADER_TRACING_DATA))
+	/*
+	 * Mark the round finished in case we wrote
+	 * at least one event.
+	 */
+	if (bytes_written != rec->bytes_written)
 		rc = record__write(rec, &finished_round_event, sizeof(finished_round_event));
 
 out:
-- 
1.8.3.1

[PATCH 18/19] perf tools: Limit the ordered events queue by default to 100MB

[Jiri Olsa]

It's still configurable by report.queue-size config option,
but looks like 100MB limit is more sane than no limit at all.

There's some speedup for report on huge data files:

With the limit of 100 MB, I've got around 15% speedup on reporting
of ~10GB perf.data file.

  current code:
   621,685,704,665      cycles                    ( +-  0.52% )
   873,397,467,969      instructions              ( +-  0.00% )

     286.133268732 seconds time elapsed           ( +-  1.13% )

  with patches:
   603,933,987,185      cycles                    ( +-  0.45% )
   869,139,445,070      instructions              ( +-  0.00% )

     245.337510637 seconds time elapsed           ( +-  0.49% )

The speed up seems to be mainly in less cycles spent in servicing
page faults.

  current code:
     4.44%     0.01%  perf.old  [kernel.kallsyms]   [k] page_fault

  with patches:
     1.45%     0.00%      perf  [kernel.kallsyms]   [k] page_fault

  current code (faults event):
         6,643,807      faults                    ( +-  0.36% )

  with patches (faults event):
         2,214,756      faults                    ( +-  3.03% )

Also there's lower memory consuption.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/ordered-events.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/tools/perf/util/ordered-events.c b/tools/perf/util/ordered-events.c
index 1a699fc16b92..d7ee387cad51 100644
--- a/tools/perf/util/ordered-events.c
+++ b/tools/perf/util/ordered-events.c
@@ -243,7 +243,8 @@ void ordered_events_init(struct ordered_events *oe)
 	INIT_LIST_HEAD(&oe->events);
 	INIT_LIST_HEAD(&oe->cache);
 	INIT_LIST_HEAD(&oe->to_free);
-	oe->max_alloc_size = (u64) -1;
+	/* 100MB limitation by default */
+	oe->max_alloc_size = 100 * 1024 * 1024;
 	oe->cur_alloc_size = 0;
 }
 
-- 
1.8.3.1

[PATCH 19/19] perf tools: Allow out of order messages in forced flush

[Jiri Olsa]

In forced flush (OE_FLUSH__HALF) we break the rules of the
flush timestamp via PERF_RECORD_FINISHED_ROUND event, so
we could get out of order event.

Do not force error in this case plus changing the
output warning to use WARN_ONCE.

Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/ordered-events.c | 4 ++++
 tools/perf/util/ordered-events.h | 2 ++
 tools/perf/util/session.c        | 8 ++++++--
 3 files changed, 12 insertions(+), 2 deletions(-)

diff --git a/tools/perf/util/ordered-events.c b/tools/perf/util/ordered-events.c
index d7ee387cad51..5dbde56d69f6 100644
--- a/tools/perf/util/ordered-events.c
+++ b/tools/perf/util/ordered-events.c
@@ -181,6 +181,7 @@ int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 {
 	struct ordered_events *oe = &s->ordered_events;
 	static const char * const str[] = {
+		"NONE",
 		"FINAL",
 		"ROUND",
 		"HALF ",
@@ -210,6 +211,7 @@ int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 	}
 
 	case OE_FLUSH__ROUND:
+	case OE_FLUSH__NONE:
 	default:
 		break;
 	};
@@ -226,6 +228,8 @@ int ordered_events_flush(struct perf_session *s, struct perf_tool *tool,
 	if (!err) {
 		if (how == OE_FLUSH__ROUND)
 			oe->next_flush = oe->max_timestamp;
+
+		oe->last_flush_type = how;
 	}
 
 	if (unlikely(debug_ordered_events)) {
diff --git a/tools/perf/util/ordered-events.h b/tools/perf/util/ordered-events.h
index a4fc435f0fc6..6dd36dd01be6 100644
--- a/tools/perf/util/ordered-events.h
+++ b/tools/perf/util/ordered-events.h
@@ -14,6 +14,7 @@ struct ordered_event {
 };
 
 enum oe_flush {
+	OE_FLUSH__NONE,
 	OE_FLUSH__FINAL,
 	OE_FLUSH__ROUND,
 	OE_FLUSH__HALF,
@@ -32,6 +33,7 @@ struct ordered_events {
 	struct ordered_event	*last;
 	int			buffer_idx;
 	unsigned int		nr_events;
+	enum oe_flush		last_flush_type;
 };
 
 struct ordered_event *ordered_events_new(struct ordered_events *oe, u64 timestamp);
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 4e748142a13f..3db8ab12f12d 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -15,6 +15,7 @@
 #include "cpumap.h"
 #include "perf_regs.h"
 #include "vdso.h"
+#include "asm/bug.h"
 
 static int perf_session__open(struct perf_session *session)
 {
@@ -502,8 +503,11 @@ int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 		return -ETIME;
 
 	if (timestamp < s->ordered_events.last_flush) {
-		printf("Warning: Timestamp below last timeslice flush\n");
-		return -EINVAL;
+		WARN_ONCE(1, "Timestamp below last timeslice flush\n");
+
+		/* We could get out of order messages after forced flush. */
+		if (oe->last_flush_type != OE_FLUSH__HALF)
+			return -EINVAL;
 	}
 
 	new = ordered_events_new(oe, timestamp);
-- 
1.8.3.1

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Adrian Hunter]

On 07/21/2014 12:55 AM, Jiri Olsa wrote:
> hi,
> this patchset factors session's ordered samples queue,
> and allows to limit the size of this queue.
> 
> v3 changes:
>   - rebased to latest tip/perf/core
>   - add comment for WARN in patch 8 (David)
>   - added ordered-events debug variable (David)
>   - renamed ordered_events_(get|put) to ordered_events_(new|delete)
>   - renamed struct ordered_events_queue to struct ordered_events
> 
> v2 changes:
>   - several small changes for review comments (Namhyung)
> 
> 
> The report command queues events till any of following
> conditions is reached:
>   - PERF_RECORD_FINISHED_ROUND event is processed
>   - end of the file is reached
> 
> Any of above conditions will force the queue to flush some
> events while keeping all allocated memory for next events.
> 
> If PERF_RECORD_FINISHED_ROUND is missing the queue will

Why is it missing?

> allocate memory for every single event in the perf.data.
> This could lead to enormous memory consuption and speed
> degradation of report command for huge perf.data files.
> 
> With the quue allocation limit of 100 MB, I've got around
> 15% speedup on reporting of ~10GB perf.data file.

How do you know the results are still valid?  Wouldn't it
be better to wait that extra 15% and know that the data has
been processed correctly?

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Jiri Olsa]

On Mon, Jul 21, 2014 at 09:43:58AM +0300, Adrian Hunter wrote:
> On 07/21/2014 12:55 AM, Jiri Olsa wrote:
> > hi,
> > this patchset factors session's ordered samples queue,
> > and allows to limit the size of this queue.
> > 
> > v3 changes:
> >   - rebased to latest tip/perf/core
> >   - add comment for WARN in patch 8 (David)
> >   - added ordered-events debug variable (David)
> >   - renamed ordered_events_(get|put) to ordered_events_(new|delete)
> >   - renamed struct ordered_events_queue to struct ordered_events
> > 
> > v2 changes:
> >   - several small changes for review comments (Namhyung)
> > 
> > 
> > The report command queues events till any of following
> > conditions is reached:
> >   - PERF_RECORD_FINISHED_ROUND event is processed
> >   - end of the file is reached
> > 
> > Any of above conditions will force the queue to flush some
> > events while keeping all allocated memory for next events.
> > 
> > If PERF_RECORD_FINISHED_ROUND is missing the queue will
> 
> Why is it missing?

it's stored only for tracepoints now patch 17 fixies that

> 
> > allocate memory for every single event in the perf.data.
> > This could lead to enormous memory consuption and speed
> > degradation of report command for huge perf.data files.
> > 
> > With the quue allocation limit of 100 MB, I've got around
> > 15% speedup on reporting of ~10GB perf.data file.
> 
> How do you know the results are still valid?  Wouldn't it
> be better to wait that extra 15% and know that the data has
> been processed correctly?

The HALF flush could cause the out of order message
(which I get occasionaly anyway). Patch 19 allows
out of order events after HALF flush.

The main reason for me was to control the memory allocation,
which could get enormous without ROUND events being stored.
The 100MB queue limit seems to be enough not to hit out of
order event due to the HALF flush.

jirka

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Adrian Hunter]

On 07/21/2014 11:02 AM, Jiri Olsa wrote:
> On Mon, Jul 21, 2014 at 09:43:58AM +0300, Adrian Hunter wrote:
>> On 07/21/2014 12:55 AM, Jiri Olsa wrote:
>>> hi,
>>> this patchset factors session's ordered samples queue,
>>> and allows to limit the size of this queue.
>>>
>>> v3 changes:
>>>   - rebased to latest tip/perf/core
>>>   - add comment for WARN in patch 8 (David)
>>>   - added ordered-events debug variable (David)
>>>   - renamed ordered_events_(get|put) to ordered_events_(new|delete)
>>>   - renamed struct ordered_events_queue to struct ordered_events
>>>
>>> v2 changes:
>>>   - several small changes for review comments (Namhyung)
>>>
>>>
>>> The report command queues events till any of following
>>> conditions is reached:
>>>   - PERF_RECORD_FINISHED_ROUND event is processed
>>>   - end of the file is reached
>>>
>>> Any of above conditions will force the queue to flush some
>>> events while keeping all allocated memory for next events.
>>>
>>> If PERF_RECORD_FINISHED_ROUND is missing the queue will
>>
>> Why is it missing?
> 
> it's stored only for tracepoints now patch 17 fixies that

Wouldn't that make a huge difference all by itself?

I would make that the first patch, and measure the difference
that it makes by itself.

> 
>>
>>> allocate memory for every single event in the perf.data.
>>> This could lead to enormous memory consuption and speed
>>> degradation of report command for huge perf.data files.
>>>
>>> With the quue allocation limit of 100 MB, I've got around
>>> 15% speedup on reporting of ~10GB perf.data file.
>>
>> How do you know the results are still valid?  Wouldn't it
>> be better to wait that extra 15% and know that the data has
>> been processed correctly?
> 
> The HALF flush could cause the out of order message
> (which I get occasionaly anyway). Patch 19 allows

Occasional out-of-order messages would be worth investigating
IMHO.  Either there is a bug or there is some "interesting"
data being recorded.

> out of order events after HALF flush.
> 
> The main reason for me was to control the memory allocation,
> which could get enormous without ROUND events being stored.

But now you are storing them...

> The 100MB queue limit seems to be enough not to hit out of
> order event due to the HALF flush.

...so is the 100MB limit needed at all if you have ROUND
events?

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Jiri Olsa]

On Mon, Jul 21, 2014 at 11:47:35AM +0300, Adrian Hunter wrote:

SNIP

> >>> If PERF_RECORD_FINISHED_ROUND is missing the queue will
> >>
> >> Why is it missing?
> > 
> > it's stored only for tracepoints now patch 17 fixies that
> 
> Wouldn't that make a huge difference all by itself?
> 
> I would make that the first patch, and measure the difference
> that it makes by itself.

yes, that makes the difference.. still I think it's good to control
perf memory allocation and do not let it take gigabytes just because
this event is missing

> >> How do you know the results are still valid?  Wouldn't it
> >> be better to wait that extra 15% and know that the data has
> >> been processed correctly?
> > 
> > The HALF flush could cause the out of order message
> > (which I get occasionaly anyway). Patch 19 allows
> 
> Occasional out-of-order messages would be worth investigating
> IMHO.  Either there is a bug or there is some "interesting"
> data being recorded.

I've got it via 'perf timechart record -I' sometimes:

[jolsa@ibm-x3650m4-01 perf]$ sudo ./perf timechart record -I
^C[ perf record: Woken up 337 times to write data ]
[ perf record: Captured and wrote 290.256 MB perf.data (~12681486 samples) ]
Warning:
Processed 3365931 events and lost 1 chunks!

Check IO/CPU overload!

[jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
Timestamp below last timeslice flush
0x2276f58 [0x68]: failed to process type: 9
# To display the perf.data header info, please use --header/--header-only options.
#

I think the reaon might be that one of the CPU mmap buffer
is behind and got data after the round finishes for its
timestamp.. but I haven't checked deeply on this yet

> 
> > out of order events after HALF flush.
> > 
> > The main reason for me was to control the memory allocation,
> > which could get enormous without ROUND events being stored.
> 
> But now you are storing them...
> 
> > The 100MB queue limit seems to be enough not to hit out of
> > order event due to the HALF flush.
> 
> ...so is the 100MB limit needed at all if you have ROUND
> events?

for data files captured without the ROUND events fix

jirka

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Adrian Hunter]

On 07/21/2014 12:54 PM, Jiri Olsa wrote:
> On Mon, Jul 21, 2014 at 11:47:35AM +0300, Adrian Hunter wrote:
> 
> SNIP
> 
>>>>> If PERF_RECORD_FINISHED_ROUND is missing the queue will
>>>>
>>>> Why is it missing?
>>>
>>> it's stored only for tracepoints now patch 17 fixies that
>>
>> Wouldn't that make a huge difference all by itself?
>>
>> I would make that the first patch, and measure the difference
>> that it makes by itself.
> 
> yes, that makes the difference.. still I think it's good to control
> perf memory allocation and do not let it take gigabytes just because
> this event is missing
> 
>>>> How do you know the results are still valid?  Wouldn't it
>>>> be better to wait that extra 15% and know that the data has
>>>> been processed correctly?
>>>
>>> The HALF flush could cause the out of order message
>>> (which I get occasionaly anyway). Patch 19 allows
>>
>> Occasional out-of-order messages would be worth investigating
>> IMHO.  Either there is a bug or there is some "interesting"
>> data being recorded.
> 
> I've got it via 'perf timechart record -I' sometimes:
> 
> [jolsa@ibm-x3650m4-01 perf]$ sudo ./perf timechart record -I
> ^C[ perf record: Woken up 337 times to write data ]
> [ perf record: Captured and wrote 290.256 MB perf.data (~12681486 samples) ]
> Warning:
> Processed 3365931 events and lost 1 chunks!
> 
> Check IO/CPU overload!
> 
> [jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
> Timestamp below last timeslice flush
> 0x2276f58 [0x68]: failed to process type: 9
> # To display the perf.data header info, please use --header/--header-only options.
> #
> 
> I think the reaon might be that one of the CPU mmap buffer
> is behind and got data after the round finishes for its
> timestamp.. but I haven't checked deeply on this yet
> 
>>
>>> out of order events after HALF flush.
>>>
>>> The main reason for me was to control the memory allocation,
>>> which could get enormous without ROUND events being stored.
>>
>> But now you are storing them...
>>
>>> The 100MB queue limit seems to be enough not to hit out of
>>> order event due to the HALF flush.
>>
>> ...so is the 100MB limit needed at all if you have ROUND
>> events?
> 
> for data files captured without the ROUND events fix

I am not sure it should be the default then, if it is
not needed going forward.

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Jiri Olsa]

On Mon, Jul 21, 2014 at 03:09:07PM +0300, Adrian Hunter wrote:

SNIP

> >>
> >> ...so is the 100MB limit needed at all if you have ROUND
> >> events?
> > 
> > for data files captured without the ROUND events fix
> 
> I am not sure it should be the default then, if it is
> not needed going forward.

I'd be ok with not setting 100MB limit by default, just need a way
to configure it.. so without following patch:
  perf tools: Limit the ordered events queue by default to 100MB

jirka

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Adrian Hunter]

On 07/21/2014 03:35 PM, Jiri Olsa wrote:
> On Mon, Jul 21, 2014 at 03:09:07PM +0300, Adrian Hunter wrote:
> 
> SNIP
> 
>>>>
>>>> ...so is the 100MB limit needed at all if you have ROUND
>>>> events?
>>>
>>> for data files captured without the ROUND events fix
>>
>> I am not sure it should be the default then, if it is
>> not needed going forward.
> 
> I'd be ok with not setting 100MB limit by default, just need a way
> to configure it.. so without following patch:
>   perf tools: Limit the ordered events queue by default to 100MB

Ok then.  Also it would be good to have a warning if a premature flush
is forced, so that you can distinguish the cause of out-of-order
messages.

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Andi Kleen]

Jiri Olsa <jolsa@redhat.com> writes:
>
> [jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
> Timestamp below last timeslice flush
> 0x2276f58 [0x68]: failed to process type: 9

FWIW we're seeing this frequently too.


-Andi

-- 
ak@linux.intel.com -- Speaking for myself only

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Adrian Hunter]

On 21/07/2014 7:31 p.m., Andi Kleen wrote:
> Jiri Olsa <jolsa@redhat.com> writes:
>>
>> [jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
>> Timestamp below last timeslice flush
>> 0x2276f58 [0x68]: failed to process type: 9
>
> FWIW we're seeing this frequently too.

Jiri's example didn't work for me.  Do you have one?

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[David Ahern]

On 7/21/14, 12:23 PM, Adrian Hunter wrote:
> On 21/07/2014 7:31 p.m., Andi Kleen wrote:
>> Jiri Olsa <jolsa@redhat.com> writes:
>>>
>>> [jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
>>> Timestamp below last timeslice flush
>>> 0x2276f58 [0x68]: failed to process type: 9
>>
>> FWIW we're seeing this frequently too.
>
> Jiri's example didn't work for me.  Do you have one?

$ perf sched record  -m 8192 -- perf bench sched all
# Running sched/messaging benchmark...
# 20 sender and receiver processes per group
# 10 groups == 400 processes run

      Total time: 0.087 [sec]

# Running sched/pipe benchmark...
# Executed 1000000 pipe operations between two processes

      Total time: 12.043 [sec]

       12.043779 usecs/op
           83030 ops/sec

[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 289.549 MB perf.data (~12650569 samples) ]
0x54b4828 [0]: failed to process type: 0

No overload condition, no dropped chunks message - yet can't process events.

David

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Adrian Hunter]

On 21/07/2014 9:36 p.m., David Ahern wrote:
> On 7/21/14, 12:23 PM, Adrian Hunter wrote:
>> On 21/07/2014 7:31 p.m., Andi Kleen wrote:
>>> Jiri Olsa <jolsa@redhat.com> writes:
>>>>
>>>> [jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
>>>> Timestamp below last timeslice flush
>>>> 0x2276f58 [0x68]: failed to process type: 9
>>>
>>> FWIW we're seeing this frequently too.
>>
>> Jiri's example didn't work for me.  Do you have one?
>
> $ perf sched record  -m 8192 -- perf bench sched all
> # Running sched/messaging benchmark...
> # 20 sender and receiver processes per group
> # 10 groups == 400 processes run
>
>       Total time: 0.087 [sec]
>
> # Running sched/pipe benchmark...
> # Executed 1000000 pipe operations between two processes
>
>       Total time: 12.043 [sec]
>
>        12.043779 usecs/op
>            83030 ops/sec
>
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 289.549 MB perf.data (~12650569 samples) ]
> 0x54b4828 [0]: failed to process type: 0
>
> No overload condition, no dropped chunks message - yet can't process events.

Actually, it was the "Timestamp below last timeslice flush"
that I was interested in.

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Andi Kleen]

On Mon, Jul 21, 2014 at 09:23:49PM +0300, Adrian Hunter wrote:
> On 21/07/2014 7:31 p.m., Andi Kleen wrote:
> >Jiri Olsa <jolsa@redhat.com> writes:
> >>
> >>[jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
> >>Timestamp below last timeslice flush
> >>0x2276f58 [0x68]: failed to process type: 9
> >
> >FWIW we're seeing this frequently too.
> 
> Jiri's example didn't work for me.  Do you have one?

Did you try it on a idle system? Do it during some work load
that generates a lot of context switches.

-Andi

-- 
ak@linux.intel.com -- Speaking for myself only.

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Arnaldo Carvalho de Melo]

Em Mon, Jul 21, 2014 at 12:36:54PM -0600, David Ahern escreveu:
> On 7/21/14, 12:23 PM, Adrian Hunter wrote:
> >On 21/07/2014 7:31 p.m., Andi Kleen wrote:
> >>Jiri Olsa <jolsa@redhat.com> writes:
> >>>
> >>>[jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
> >>>Timestamp below last timeslice flush
> >>>0x2276f58 [0x68]: failed to process type: 9
> >>
> >>FWIW we're seeing this frequently too.
> >
> >Jiri's example didn't work for me.  Do you have one?
> 
> $ perf sched record  -m 8192 -- perf bench sched all
> # Running sched/messaging benchmark...
> # 20 sender and receiver processes per group
> # 10 groups == 400 processes run
> 
>      Total time: 0.087 [sec]
> 
> # Running sched/pipe benchmark...
> # Executed 1000000 pipe operations between two processes
> 
>      Total time: 12.043 [sec]
> 
>       12.043779 usecs/op
>           83030 ops/sec
> 
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 289.549 MB perf.data (~12650569 samples) ]
> 0x54b4828 [0]: failed to process type: 0
> 
> No overload condition, no dropped chunks message - yet can't process events.

Appling just the patches 1 and 17 from this series I managed to:

[root@zoo ~]# cat /proc/loadavg 
52.13 13.06 5.04 132/977 29522
[root@zoo ~]# perf sched record  -m 4096 -- perf bench sched all
# Running sched/messaging benchmark...
# 20 sender and receiver processes per group
# 10 groups == 400 processes run

     Total time: 0.692 [sec]

# Running sched/pipe benchmark...
# Executed 1000000 pipe operations between two processes

     Total time: 13.007 [sec]

      13.007582 usecs/op
          76878 ops/sec

[ perf record: Woken up 105 times to write data ]
[ perf record: Captured and wrote 909.513 MB perf.data (~39737216 samples) ]
[root@zoo ~]# cat /proc/loadavg 
80.30 22.82 8.49 132/968 31755
[root@zoo ~]# perf script | wc -l
8308492
[root@zoo ~]# perf cript | head -10
 perf 9897 [01] 1.29678: sched:sched_stat_runtime: comm=perf pid=29897 runtime=916836 [ns] vruntime=1322281938410 [ns]
 perf 9897 [01] 1.29683: sched:sched_wakeup: comm=perf pid=29919 prio=120 success=1 target_cpu=001
 perf 9897 [01] 1.29688: sched:sched_switch: prev_comm=perf prev_pid=29897 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=29919 next_prio=120
 perf 9919 [01] 1.29748: sched:sched_stat_runtime: comm=perf pid=29919 runtime=70430 [ns] vruntime=1322273008840 [ns]
  cc1 7110 [03] 1.29748: sched:sched_stat_runtime: comm=cc1 pid=27110 runtime=992012 [ns] vruntime=702438664528 [ns]
  cc1 9278 [00] 1.29748: sched:sched_stat_runtime: comm=cc1 pid=29278 runtime=979081 [ns] vruntime=583946650623 [ns]
  cc1 7781 [02] 1.29749: sched:sched_stat_runtime: comm=cc1 pid=27781 runtime=989627 [ns] vruntime=714050072391 [ns]
  cc1 9278 [00] 1.29756: sched:sched_switch: prev_comm=cc1 prev_pid=29278 prev_prio=120 prev_state=R ==> next_comm=cc1 next_pid=29128 next_prio=120
  cc1 7110 [03] 1.29757: sched:sched_switch: prev_comm=cc1 prev_pid=27110 prev_prio=120 prev_state=R ==> next_comm=cc1 next_pid=29586 next_prio=120
 perf 9919 [01] 1.29914: sched:sched_wakeup: comm=migration/1 pid=12 prio=0 success=1 target_cpu=001
[root@zoo ~]#

While doing a make -j128 allmodconfig on a 4way machine.

David, can I have your Acked-by for just those two while the rest is debated?

Adrian, can I have yours as well?

- Arnaldo

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Jiri Olsa]

On Thu, Jul 24, 2014 at 11:19:58AM -0300, Arnaldo Carvalho de Melo wrote:
> Em Mon, Jul 21, 2014 at 12:36:54PM -0600, David Ahern escreveu:
> > On 7/21/14, 12:23 PM, Adrian Hunter wrote:
> > >On 21/07/2014 7:31 p.m., Andi Kleen wrote:
> > >>Jiri Olsa <jolsa@redhat.com> writes:
> > >>>
> > >>>[jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
> > >>>Timestamp below last timeslice flush
> > >>>0x2276f58 [0x68]: failed to process type: 9
> > >>
> > >>FWIW we're seeing this frequently too.
> > >
> > >Jiri's example didn't work for me.  Do you have one?
> > 
> > $ perf sched record  -m 8192 -- perf bench sched all
> > # Running sched/messaging benchmark...
> > # 20 sender and receiver processes per group
> > # 10 groups == 400 processes run
> > 
> >      Total time: 0.087 [sec]
> > 
> > # Running sched/pipe benchmark...
> > # Executed 1000000 pipe operations between two processes
> > 
> >      Total time: 12.043 [sec]
> > 
> >       12.043779 usecs/op
> >           83030 ops/sec
> > 
> > [ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 289.549 MB perf.data (~12650569 samples) ]
> > 0x54b4828 [0]: failed to process type: 0
> > 
> > No overload condition, no dropped chunks message - yet can't process events.
> 
> Appling just the patches 1 and 17 from this series I managed to:

ok with me..

I plan to spin new version with better debug messages and without (Adrian):
  perf tools: Limit the ordered events queue by default to 100MB

Anyway, I think the rest without (and the one above):
  perf tools: Add debug prints for ordered events queue

should be good to go..

Namhyung pointed out performance implications for patch 17:
  perf tools: Always force PERF_RECORD_FINISHED_ROUND event

which you seem to test.. but I dont see comparison dow there.. ?

thanks,
jirka

> 
> [root@zoo ~]# cat /proc/loadavg 
> 52.13 13.06 5.04 132/977 29522
> [root@zoo ~]# perf sched record  -m 4096 -- perf bench sched all
> # Running sched/messaging benchmark...
> # 20 sender and receiver processes per group
> # 10 groups == 400 processes run
> 
>      Total time: 0.692 [sec]
> 
> # Running sched/pipe benchmark...
> # Executed 1000000 pipe operations between two processes
> 
>      Total time: 13.007 [sec]
> 
>       13.007582 usecs/op
>           76878 ops/sec
> 
> [ perf record: Woken up 105 times to write data ]
> [ perf record: Captured and wrote 909.513 MB perf.data (~39737216 samples) ]
> [root@zoo ~]# cat /proc/loadavg 
> 80.30 22.82 8.49 132/968 31755
> [root@zoo ~]# perf script | wc -l
> 8308492
> [root@zoo ~]# perf cript | head -10
>  perf 9897 [01] 1.29678: sched:sched_stat_runtime: comm=perf pid=29897 runtime=916836 [ns] vruntime=1322281938410 [ns]
>  perf 9897 [01] 1.29683: sched:sched_wakeup: comm=perf pid=29919 prio=120 success=1 target_cpu=001
>  perf 9897 [01] 1.29688: sched:sched_switch: prev_comm=perf prev_pid=29897 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=29919 next_prio=120
>  perf 9919 [01] 1.29748: sched:sched_stat_runtime: comm=perf pid=29919 runtime=70430 [ns] vruntime=1322273008840 [ns]
>   cc1 7110 [03] 1.29748: sched:sched_stat_runtime: comm=cc1 pid=27110 runtime=992012 [ns] vruntime=702438664528 [ns]
>   cc1 9278 [00] 1.29748: sched:sched_stat_runtime: comm=cc1 pid=29278 runtime=979081 [ns] vruntime=583946650623 [ns]
>   cc1 7781 [02] 1.29749: sched:sched_stat_runtime: comm=cc1 pid=27781 runtime=989627 [ns] vruntime=714050072391 [ns]
>   cc1 9278 [00] 1.29756: sched:sched_switch: prev_comm=cc1 prev_pid=29278 prev_prio=120 prev_state=R ==> next_comm=cc1 next_pid=29128 next_prio=120
>   cc1 7110 [03] 1.29757: sched:sched_switch: prev_comm=cc1 prev_pid=27110 prev_prio=120 prev_state=R ==> next_comm=cc1 next_pid=29586 next_prio=120
>  perf 9919 [01] 1.29914: sched:sched_wakeup: comm=migration/1 pid=12 prio=0 success=1 target_cpu=001
> [root@zoo ~]#
> 
> While doing a make -j128 allmodconfig on a 4way machine.
> 
> David, can I have your Acked-by for just those two while the rest is debated?
> 
> Adrian, can I have yours as well?
> 
> - Arnaldo

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Arnaldo Carvalho de Melo]

Em Thu, Jul 24, 2014 at 04:56:11PM +0200, Jiri Olsa escreveu:
> On Thu, Jul 24, 2014 at 11:19:58AM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Mon, Jul 21, 2014 at 12:36:54PM -0600, David Ahern escreveu:
> > > On 7/21/14, 12:23 PM, Adrian Hunter wrote:
> > > >On 21/07/2014 7:31 p.m., Andi Kleen wrote:
> > > >>Jiri Olsa <jolsa@redhat.com> writes:
> > > >>>
> > > >>>[jolsa@ibm-x3650m4-01 perf]$ sudo ./perf report --stdio
> > > >>>Timestamp below last timeslice flush
> > > >>>0x2276f58 [0x68]: failed to process type: 9
> > > >>
> > > >>FWIW we're seeing this frequently too.
> > > >
> > > >Jiri's example didn't work for me.  Do you have one?
> > > 
> > > $ perf sched record  -m 8192 -- perf bench sched all
> > > # Running sched/messaging benchmark...
> > > # 20 sender and receiver processes per group
> > > # 10 groups == 400 processes run
> > > 
> > >      Total time: 0.087 [sec]
> > > 
> > > # Running sched/pipe benchmark...
> > > # Executed 1000000 pipe operations between two processes
> > > 
> > >      Total time: 12.043 [sec]
> > > 
> > >       12.043779 usecs/op
> > >           83030 ops/sec
> > > 
> > > [ perf record: Woken up 1 times to write data ]
> > > [ perf record: Captured and wrote 289.549 MB perf.data (~12650569 samples) ]
> > > 0x54b4828 [0]: failed to process type: 0
> > > 
> > > No overload condition, no dropped chunks message - yet can't process events.
> > 
> > Appling just the patches 1 and 17 from this series I managed to:
> 
> ok with me..
> 
> I plan to spin new version with better debug messages and without (Adrian):
>   perf tools: Limit the ordered events queue by default to 100MB
> 
> Anyway, I think the rest without (and the one above):
>   perf tools: Add debug prints for ordered events queue
> 
> should be good to go..
> 
> Namhyung pointed out performance implications for patch 17:
>   perf tools: Always force PERF_RECORD_FINISHED_ROUND event

I haven't seen this comment, just saw David, IIUC, having problems using
the whole patchkit, David?

My tests were more to counter what he said, i.e. that:

<quote David Ahern>
No overload condition, no dropped chunks message - yet can't process
events
</>

I see no overload condition, no dropped chunks message, I was pounding
the machine with a big load and could process the events, so all seems
well.

And from the discussion I understood that patch 17 is the most important
one, agreed by you and Adrian, right?

I.e. the other ones are refactorings to make it have better naming and
to allow it being used elsewhere (builtin-trace.c, whee), but still need
some more polishing/testing, is that right?

- Arnaldo
 
> which you seem to test.. but I dont see comparison dow there.. ?
> 
> thanks,
> jirka
> 
> > 
> > [root@zoo ~]# cat /proc/loadavg 
> > 52.13 13.06 5.04 132/977 29522
> > [root@zoo ~]# perf sched record  -m 4096 -- perf bench sched all
> > # Running sched/messaging benchmark...
> > # 20 sender and receiver processes per group
> > # 10 groups == 400 processes run
> > 
> >      Total time: 0.692 [sec]
> > 
> > # Running sched/pipe benchmark...
> > # Executed 1000000 pipe operations between two processes
> > 
> >      Total time: 13.007 [sec]
> > 
> >       13.007582 usecs/op
> >           76878 ops/sec
> > 
> > [ perf record: Woken up 105 times to write data ]
> > [ perf record: Captured and wrote 909.513 MB perf.data (~39737216 samples) ]
> > [root@zoo ~]# cat /proc/loadavg 
> > 80.30 22.82 8.49 132/968 31755
> > [root@zoo ~]# perf script | wc -l
> > 8308492
> > [root@zoo ~]# perf cript | head -10
> >  perf 9897 [01] 1.29678: sched:sched_stat_runtime: comm=perf pid=29897 runtime=916836 [ns] vruntime=1322281938410 [ns]
> >  perf 9897 [01] 1.29683: sched:sched_wakeup: comm=perf pid=29919 prio=120 success=1 target_cpu=001
> >  perf 9897 [01] 1.29688: sched:sched_switch: prev_comm=perf prev_pid=29897 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=29919 next_prio=120
> >  perf 9919 [01] 1.29748: sched:sched_stat_runtime: comm=perf pid=29919 runtime=70430 [ns] vruntime=1322273008840 [ns]
> >   cc1 7110 [03] 1.29748: sched:sched_stat_runtime: comm=cc1 pid=27110 runtime=992012 [ns] vruntime=702438664528 [ns]
> >   cc1 9278 [00] 1.29748: sched:sched_stat_runtime: comm=cc1 pid=29278 runtime=979081 [ns] vruntime=583946650623 [ns]
> >   cc1 7781 [02] 1.29749: sched:sched_stat_runtime: comm=cc1 pid=27781 runtime=989627 [ns] vruntime=714050072391 [ns]
> >   cc1 9278 [00] 1.29756: sched:sched_switch: prev_comm=cc1 prev_pid=29278 prev_prio=120 prev_state=R ==> next_comm=cc1 next_pid=29128 next_prio=120
> >   cc1 7110 [03] 1.29757: sched:sched_switch: prev_comm=cc1 prev_pid=27110 prev_prio=120 prev_state=R ==> next_comm=cc1 next_pid=29586 next_prio=120
> >  perf 9919 [01] 1.29914: sched:sched_wakeup: comm=migration/1 pid=12 prio=0 success=1 target_cpu=001
> > [root@zoo ~]#
> > 
> > While doing a make -j128 allmodconfig on a 4way machine.
> > 
> > David, can I have your Acked-by for just those two while the rest is debated?
> > 
> > Adrian, can I have yours as well?
> > 
> > - Arnaldo

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Jiri Olsa]

On Thu, Jul 24, 2014 at 12:10:09PM -0300, Arnaldo Carvalho de Melo wrote:

SNIP

> > 
> > should be good to go..
> > 
> > Namhyung pointed out performance implications for patch 17:
> >   perf tools: Always force PERF_RECORD_FINISHED_ROUND event
> 
> I haven't seen this comment, just saw David, IIUC, having problems using
> the whole patchkit, David?
> 
> My tests were more to counter what he said, i.e. that:
> 
> <quote David Ahern>
> No overload condition, no dropped chunks message - yet can't process
> events
> </>
> 
> I see no overload condition, no dropped chunks message, I was pounding
> the machine with a big load and could process the events, so all seems
> well.
> 
> And from the discussion I understood that patch 17 is the most important
> one, agreed by you and Adrian, right?

yes, it drives the flush (in report) to happen

Namhyung pointed out, that now we store extra event for
non-tracepoint events sessions.. which might have performance
implications:

  http://marc.info/?l=linux-kernel&m=140266032913387&w=2


> 
> I.e. the other ones are refactorings to make it have better naming and
> to allow it being used elsewhere (builtin-trace.c, whee), but still need
> some more polishing/testing, is that right?

correct.. I plan to polish the debug output patchset,
I dont think I've got comments for the rest

jirka

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[David Ahern]

On 7/24/14, 9:10 AM, Arnaldo Carvalho de Melo wrote:
>
> I haven't seen this comment, just saw David, IIUC, having problems using
> the whole patchkit, David?

The testing I did with the whole patchkit saw no behavior differences.

>
> My tests were more to counter what he said, i.e. that:
>
> <quote David Ahern>
> No overload condition, no dropped chunks message - yet can't process
> events
> </>

Meaning I hit that problem with current code as well as Jiri's changes.

Overall I am fine with the changes. Yes, you can add my Acked-by on all 
of them.

Thanks,
David

Re: [PATCHv3 00/19] perf tools: Factor ordered samples queue

[Adrian Hunter]

On 24/07/2014 5:19 p.m., Arnaldo Carvalho de Melo wrote:
>
> David, can I have your Acked-by for just those two while the rest is debated?
>
> Adrian, can I have yours as well?

Yes you have my Ack for patches 1 and 17

Re: [PATCH 17/19] perf tools: Always force PERF_RECORD_FINISHED_ROUND event

[Arnaldo Carvalho de Melo]

Em Sun, Jul 20, 2014 at 11:56:01PM +0200, Jiri Olsa escreveu:
> The PERF_RECORD_FINISHED_ROUND governs queue flushing in
> reporting, so it needs to be stored for any kind of event.
> 
> Forcing the PERF_RECORD_FINISHED_ROUND event to be stored any
> time we finish the round and wrote at least one event.

This is not just one change, it does two things and it is not clearly
detailed here.

The existing code would write a PERF_RECORD_FINISHED_ROUND per call to
record__mmap_read() for tracepoints were present.

I.e. if tracepoints and any other type of event type was present, then
this syntetic PERF_RECORD_FINISHED_ROUND thing is inserted which will be
handled at report time.

Now you changed it to not check if tracepoints are present, i.e. it will
always insert that after processing N events in
PERF_RECORD_FINISHED_ROUND. (change #1)

The thing is, before it didn't checked if N was zero, needlessly
inserting PERF_RECORD_FINISHED_ROUND events in some corner cases.

Now you, in addition to change #1 you also check that the number of
bytes written before that event processing loop in record__mmap_read()
is the same after the loop, i.e. if some events were written to the
output perf.data file, only inserting the PERF_RECORD_FINISHED_ROUND
events if so. (change #2)

I think both changes are OK, but should be split in different patches,
and while testing comparing having the patch applied versus patch
applied + ignore the PERF_RECORD_FINISHED_ROUND events in the resulting
perf.data file, I get:

[root@zoo /]# perf stat -r 5 perf report --no-ordered-samples > /dev/null
<SNIP symbol stuff>
 Performance counter stats for 'perf report --no-ordered-samples' (5 runs):

      30263.033852      task-clock (msec)         #    1.000 CPUs utilized            ( +-  0.48% )
               346      context-switches          #    0.011 K/sec                    ( +- 54.65% )
               182      cpu-migrations            #    0.006 K/sec                    ( +- 29.94% )
            89,951      page-faults               #    0.003 M/sec                    ( +-  0.05% )
    92,342,939,311      cycles                    #    3.051 GHz                      ( +-  0.46% )
    50,605,250,178      stalled-cycles-frontend   #   54.80% frontend cycles idle     ( +-  0.88% )
   <not supported>      stalled-cycles-backend   
   101,171,572,553      instructions              #    1.10  insns per cycle        
                                                  #    0.50  stalled cycles per insn  ( +-  0.01% )
    22,643,469,804      branches                  #  748.222 M/sec                    ( +-  0.01% )
       284,395,273      branch-misses             #    1.26% of all branches          ( +-  0.45% )

      30.249514999 seconds time elapsed                                          ( +-  0.48% )

[root@zoo /]# perf stat -r 5 perf report --ordered-samples > /dev/null
<SNIP symbol stuff>
 Performance counter stats for 'perf report --ordered-samples' (5 runs):

      32665.828429      task-clock (msec)         #    1.001 CPUs utilized            ( +-  0.41% )
               304      context-switches          #    0.009 K/sec                    ( +- 23.32% )
               102      cpu-migrations            #    0.003 K/sec                    ( +- 21.70% )
            79,405      page-faults               #    0.002 M/sec                    ( +-  0.02% )
   101,761,091,322      cycles                    #    3.115 GHz                      ( +-  0.40% )
    57,627,138,326      stalled-cycles-frontend   #   56.63% frontend cycles idle     ( +-  0.65% )
   <not supported>      stalled-cycles-backend   
   105,982,144,263      instructions              #    1.04  insns per cycle        
                                                  #    0.54  stalled cycles per insn  ( +-  0.01% )
    23,493,670,235      branches                  #  719.212 M/sec                    ( +-  0.01% )
       319,060,575      branch-misses             #    1.36% of all branches          ( +-  0.19% )

      32.636483981 seconds time elapsed                                          ( +-  0.41% )

[root@zoo /]#

The patch used to enable/disable processing of PERF_RECORD_FINISHED_ROUND is this one:

diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 21d830bafff3..8b5410313005 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -675,6 +675,8 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN(0, "demangle", &symbol_conf.demangle,
 		    "Disable symbol demangling"),
 	OPT_BOOLEAN(0, "mem-mode", &report.mem_mode, "mem access profile"),
+	OPT_BOOLEAN(0, "ordered-samples", &report.tool.ordered_samples,
+		    "Make sure samples are ordered by time"),
 	OPT_CALLBACK(0, "percent-limit", &report, "percent",
 		     "Don't show entries under that percent", parse_percent_limit),
 	OPT_CALLBACK(0, "percentage", NULL, "relative|absolute",

---

The workload:

[root@zoo /]# perf report --header-only
# ========
# captured on: Thu Jul 24 17:10:16 2014
# hostname : zoo.ghostprotocols.net
# os release : 3.15.4-200.fc20.x86_64
# perf version : 3.16.rc2.g2b5b8b
# arch : x86_64
# nrcpus online : 4
# nrcpus avail : 4
# cpudesc : Intel(R) Core(TM) i7-3667U CPU @ 2.00GHz
# cpuid : GenuineIntel,6,58,9
# total memory : 8081004 kB
# cmdline : /home/acme/bin/perf record -F 7000 -a -e cache-misses,instructions,cycles sleep 5m 
# event : name = cache-misses, type = 0, config = 0x3, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, attr_mmap2 = 0, attr_mmap  = 1, attr_mmap_data = 0
# event : name = instructions, type = 0, config = 0x1, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, attr_mmap2 = 0, attr_mmap  = 0, attr_mmap_data = 0
# event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, attr_mmap2 = 0, attr_mmap  = 0, attr_mmap_data = 0, id =
# HEADER_CPU_TOPOLOGY info available, use -I to display
# HEADER_NUMA_TOPOLOGY info available, use -I to display
# pmu mappings: cpu = 4, software = 1, power = 9, uncore_imc = 8, tracepoint = 2, uncore_cbox_0 = 6, uncore_cbox_1 = 7, breakpoint = 5
# ========
#

[root@zoo /]# perf evlist -v
cache-misses: sample_freq=7000, config: 3, size: 96, sample_type: IP|TID|TIME|ID|CPU|PERIOD, read_format: ID, disabled: 1, inherit: 1, mmap: 1, comm: 1, freq: 1, sample_id_all: 1, exclude_guest: 1
instructions: sample_freq=7000, config: 1, size: 96, sample_type: IP|TID|TIME|ID|CPU|PERIOD, read_format: ID, disabled: 1, inherit: 1, freq: 1, sample_id_all: 1, exclude_guest: 1
cycles: sample_freq=7000, size: 96, sample_type: IP|TID|TIME|ID|CPU|PERIOD, read_format: ID, disabled: 1, inherit: 1, freq: 1, sample_id_all: 1, exclude_guest: 1
[root@zoo /]#

- Arnaldo

> Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
> 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: Jean Pihet <jean.pihet@linaro.org>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: Paul Mackerras <paulus@samba.org>
> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
> Signed-off-by: Jiri Olsa <jolsa@kernel.org>
> ---
>  tools/perf/builtin-record.c | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
> 
> diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
> index 378b85b731a7..4869050e7194 100644
> --- a/tools/perf/builtin-record.c
> +++ b/tools/perf/builtin-record.c
> @@ -238,6 +238,7 @@ static struct perf_event_header finished_round_event = {
>  
>  static int record__mmap_read_all(struct record *rec)
>  {
> +	u64 bytes_written = rec->bytes_written;
>  	int i;
>  	int rc = 0;
>  
> @@ -250,7 +251,11 @@ static int record__mmap_read_all(struct record *rec)
>  		}
>  	}
>  
> -	if (perf_header__has_feat(&rec->session->header, HEADER_TRACING_DATA))
> +	/*
> +	 * Mark the round finished in case we wrote
> +	 * at least one event.
> +	 */
> +	if (bytes_written != rec->bytes_written)
>  		rc = record__write(rec, &finished_round_event, sizeof(finished_round_event));
>  
>  out:
> -- 
> 1.8.3.1

Re: [PATCH 17/19] perf tools: Always force PERF_RECORD_FINISHED_ROUND event

[Jiri Olsa]

On Thu, Jul 24, 2014 at 06:34:51PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Sun, Jul 20, 2014 at 11:56:01PM +0200, Jiri Olsa escreveu:
> > The PERF_RECORD_FINISHED_ROUND governs queue flushing in
> > reporting, so it needs to be stored for any kind of event.
> > 
> > Forcing the PERF_RECORD_FINISHED_ROUND event to be stored any
> > time we finish the round and wrote at least one event.
> 
> This is not just one change, it does two things and it is not clearly
> detailed here.
> 
> The existing code would write a PERF_RECORD_FINISHED_ROUND per call to
> record__mmap_read() for tracepoints were present.
> 
> I.e. if tracepoints and any other type of event type was present, then
> this syntetic PERF_RECORD_FINISHED_ROUND thing is inserted which will be
> handled at report time.
> 
> Now you changed it to not check if tracepoints are present, i.e. it will
> always insert that after processing N events in
> PERF_RECORD_FINISHED_ROUND. (change #1)
> 
> The thing is, before it didn't checked if N was zero, needlessly
> inserting PERF_RECORD_FINISHED_ROUND events in some corner cases.
> 
> Now you, in addition to change #1 you also check that the number of
> bytes written before that event processing loop in record__mmap_read()
> is the same after the loop, i.e. if some events were written to the
> output perf.data file, only inserting the PERF_RECORD_FINISHED_ROUND
> events if so. (change #2)
> 
> I think both changes are OK, but should be split in different patches,

right, I'll split it

> and while testing comparing having the patch applied versus patch
> applied + ignore the PERF_RECORD_FINISHED_ROUND events in the resulting
> perf.data file, I get:
> 
> [root@zoo /]# perf stat -r 5 perf report --no-ordered-samples > /dev/null
> <SNIP symbol stuff>
>  Performance counter stats for 'perf report --no-ordered-samples' (5 runs):
> 
>       30263.033852      task-clock (msec)         #    1.000 CPUs utilized            ( +-  0.48% )
>                346      context-switches          #    0.011 K/sec                    ( +- 54.65% )
>                182      cpu-migrations            #    0.006 K/sec                    ( +- 29.94% )
>             89,951      page-faults               #    0.003 M/sec                    ( +-  0.05% )
>     92,342,939,311      cycles                    #    3.051 GHz                      ( +-  0.46% )
>     50,605,250,178      stalled-cycles-frontend   #   54.80% frontend cycles idle     ( +-  0.88% )
>    <not supported>      stalled-cycles-backend   
>    101,171,572,553      instructions              #    1.10  insns per cycle        
>                                                   #    0.50  stalled cycles per insn  ( +-  0.01% )
>     22,643,469,804      branches                  #  748.222 M/sec                    ( +-  0.01% )
>        284,395,273      branch-misses             #    1.26% of all branches          ( +-  0.45% )
> 
>       30.249514999 seconds time elapsed                                          ( +-  0.48% )
> 
> [root@zoo /]# perf stat -r 5 perf report --ordered-samples > /dev/null
> <SNIP symbol stuff>
>  Performance counter stats for 'perf report --ordered-samples' (5 runs):
> 
>       32665.828429      task-clock (msec)         #    1.001 CPUs utilized            ( +-  0.41% )
>                304      context-switches          #    0.009 K/sec                    ( +- 23.32% )
>                102      cpu-migrations            #    0.003 K/sec                    ( +- 21.70% )
>             79,405      page-faults               #    0.002 M/sec                    ( +-  0.02% )
>    101,761,091,322      cycles                    #    3.115 GHz                      ( +-  0.40% )
>     57,627,138,326      stalled-cycles-frontend   #   56.63% frontend cycles idle     ( +-  0.65% )
>    <not supported>      stalled-cycles-backend   
>    105,982,144,263      instructions              #    1.04  insns per cycle        
>                                                   #    0.54  stalled cycles per insn  ( +-  0.01% )
>     23,493,670,235      branches                  #  719.212 M/sec                    ( +-  0.01% )
>        319,060,575      branch-misses             #    1.36% of all branches          ( +-  0.19% )
> 
>       32.636483981 seconds time elapsed                                          ( +-  0.41% )
> 
> [root@zoo /]#

so those 2 extra seconds is the ordering time, right? sounds ok

jirka

Re: [PATCH 17/19] perf tools: Always force PERF_RECORD_FINISHED_ROUND event

[Arnaldo Carvalho de Melo]

Em Fri, Jul 25, 2014 at 01:34:26PM +0200, Jiri Olsa escreveu:
> On Thu, Jul 24, 2014 at 06:34:51PM -0300, Arnaldo Carvalho de Melo wrote:
> > I think both changes are OK, but should be split in different patches,
 
> right, I'll split it

Thanks!
 
> > [root@zoo /]# perf stat -r 5 perf report --no-ordered-samples > /dev/null
> >    101,171,572,553      instructions              #    1.10  insns per cycle        
> >       30.249514999 seconds time elapsed                                          ( +-  0.48% )

> > [root@zoo /]# perf stat -r 5 perf report --ordered-samples > /dev/null
> >    105,982,144,263      instructions              #    1.04  insns per cycle        
> >       32.636483981 seconds time elapsed                                          ( +-  0.41% )

> so those 2 extra seconds is the ordering time, right? sounds ok

Yeah, but I think its worth investigating if using it is a strict
requirement in all cases, i.e. is it possible to receive out of order
events when sampling on a single CPU? Or a single CPU socket with a
coherent time source? etc.

Providing a way to disable this ordering to be used in corner cases
where it is not a strict requirement and the volume of samples is so
high that reducing processing time like shown above seems to be a
sensible thing to do.

We're in the business of optimizing stuff, huh? :-)
 
- Arnaldo

Re: [PATCH 17/19] perf tools: Always force PERF_RECORD_FINISHED_ROUND event

[Frederic Weisbecker]

On Fri, Jul 25, 2014 at 11:14:13AM -0300, Arnaldo Carvalho de Melo wrote:
> Em Fri, Jul 25, 2014 at 01:34:26PM +0200, Jiri Olsa escreveu:
> > On Thu, Jul 24, 2014 at 06:34:51PM -0300, Arnaldo Carvalho de Melo wrote:
> > > I think both changes are OK, but should be split in different patches,
>  
> > right, I'll split it
> 
> Thanks!
>  
> > > [root@zoo /]# perf stat -r 5 perf report --no-ordered-samples > /dev/null
> > >    101,171,572,553      instructions              #    1.10  insns per cycle        
> > >       30.249514999 seconds time elapsed                                          ( +-  0.48% )
> 
> > > [root@zoo /]# perf stat -r 5 perf report --ordered-samples > /dev/null
> > >    105,982,144,263      instructions              #    1.04  insns per cycle        
> > >       32.636483981 seconds time elapsed                                          ( +-  0.41% )
> 
> > so those 2 extra seconds is the ordering time, right? sounds ok
> 
> Yeah, but I think its worth investigating if using it is a strict
> requirement in all cases, i.e. is it possible to receive out of order
> events when sampling on a single CPU? Or a single CPU socket with a
> coherent time source? etc.

It's theoretically possible to have out of order events if perf_event_output()
is interrupted between perf_prepare_sample() and perf_output_begin() and the irq
generates an event too.

So the first event saves its timestamp "t1" from perf_prepare_sample(), gets interrupted
before perf_output_begin() so it hasn't reserved room in the ring buffer yet. The
irq generates an event with a timestamp t2 that can be t2 > t1 if the clock has a
high enough resolution (tsc works there).

The IRQ write the event in the buffer, returns to the interrupted event which
record after the irq event.

One possibility to solve this is to fetch perf_clock() only from perf_output_sample().
At that time the event has reserved the buffer space so any irq event is guaranteed
to be written _after_ the interrupted event and thus guarantees some monotonicity.

> 
> Providing a way to disable this ordering to be used in corner cases
> where it is not a strict requirement and the volume of samples is so
> high that reducing processing time like shown above seems to be a
> sensible thing to do.
> 
> We're in the business of optimizing stuff, huh? :-)
>  
> - Arnaldo

Re: [PATCH 17/19] perf tools: Always force PERF_RECORD_FINISHED_ROUND event

[Peter Zijlstra]

[-- Attachment #1: Type: text/plain, Size: 2428 bytes --]

On Fri, Jul 25, 2014 at 05:45:15PM +0200, Frederic Weisbecker wrote:
> On Fri, Jul 25, 2014 at 11:14:13AM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Fri, Jul 25, 2014 at 01:34:26PM +0200, Jiri Olsa escreveu:
> > > On Thu, Jul 24, 2014 at 06:34:51PM -0300, Arnaldo Carvalho de Melo wrote:
> > > > I think both changes are OK, but should be split in different patches,
> >  
> > > right, I'll split it
> > 
> > Thanks!
> >  
> > > > [root@zoo /]# perf stat -r 5 perf report --no-ordered-samples > /dev/null
> > > >    101,171,572,553      instructions              #    1.10  insns per cycle        
> > > >       30.249514999 seconds time elapsed                                          ( +-  0.48% )
> > 
> > > > [root@zoo /]# perf stat -r 5 perf report --ordered-samples > /dev/null
> > > >    105,982,144,263      instructions              #    1.04  insns per cycle        
> > > >       32.636483981 seconds time elapsed                                          ( +-  0.41% )
> > 
> > > so those 2 extra seconds is the ordering time, right? sounds ok
> > 
> > Yeah, but I think its worth investigating if using it is a strict
> > requirement in all cases, i.e. is it possible to receive out of order
> > events when sampling on a single CPU? Or a single CPU socket with a
> > coherent time source? etc.
> 
> It's theoretically possible to have out of order events if perf_event_output()
> is interrupted between perf_prepare_sample() and perf_output_begin() and the irq
> generates an event too.
> 
> So the first event saves its timestamp "t1" from perf_prepare_sample(), gets interrupted
> before perf_output_begin() so it hasn't reserved room in the ring buffer yet. The
> irq generates an event with a timestamp t2 that can be t2 > t1 if the clock has a
> high enough resolution (tsc works there).
> 
> The IRQ write the event in the buffer, returns to the interrupted event which
> record after the irq event.
> 
> One possibility to solve this is to fetch perf_clock() only from perf_output_sample().
> At that time the event has reserved the buffer space so any irq event is guaranteed
> to be written _after_ the interrupted event and thus guarantees some monotonicity.

No, I think the current code is correct in that t1 actually happens
before t2. They end up in the buffer in reverse order but that's
unavoidable.

Artificially fixing that up doesn't make sense.

[-- Attachment #2: Type: application/pgp-signature, Size: 836 bytes --]

[tip:perf/core] perf session: Fix accounting of ordered samples queue

[tip-bot for Jiri Olsa]

Commit-ID:  f1dd1460a40894b00bbeacd753025e9251ec11bd
Gitweb:     http://git.kernel.org/tip/f1dd1460a40894b00bbeacd753025e9251ec11bd
Author:     Jiri Olsa <jolsa@kernel.org>
AuthorDate: Sun, 20 Jul 2014 23:55:45 +0200
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Thu, 24 Jul 2014 16:40:47 -0300

perf session: Fix accounting of ordered samples queue

Properly account flushed samples within the ordered samples queue.

Signed-off-by: Jiri Olsa <jolsa@kernel.org>
Acked-by: Adrian Hunter <adrian.hunter@intel.com>
Acked-by: David Ahern <dsahern@gmail.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: Jean Pihet <jean.pihet@linaro.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Link: http://lkml.kernel.org/r/1405893363-21967-2-git-send-email-jolsa@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/session.c | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index fab5838..88dfef7 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -509,6 +509,7 @@ static int flush_sample_queue(struct perf_session *s,
 		os->last_flush = iter->timestamp;
 		list_del(&iter->list);
 		list_add(&iter->list, &os->sample_cache);
+		os->nr_samples--;
 
 		if (show_progress)
 			ui_progress__update(&prog, 1);
@@ -521,8 +522,6 @@ static int flush_sample_queue(struct perf_session *s,
 			list_entry(head->prev, struct sample_queue, list);
 	}
 
-	os->nr_samples = 0;
-
 	return 0;
 }