perf top: Rework processing code

PATCH In review Jiri Olsa 4 participants 21 messages Nov 19, 2018 – Nov 20, 2018 perf events

Share & tools

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #0 lore raw

cover perf top: Rework processing code

hi,
David reported issues with perf top loosing side band events so we moved mmap reading and hists processing into separated threads.

This patchset also adds dropping sample logic when the processing falls behind the reader thread. This way we get incomplete but current data in perf top.

Also available in:
git://git.kernel.org/pub/scm/linux/kernel/git/jolsa/perf.git
perf/fixes

thanks,
jirka

---
David Miller (1):
perf tools: Fix build on sparc

Jiri Olsa (11):
perf tools: Rework show_progress for __ordered_events__flush perf tools: Add private data to struct ordered_events perf top: Save and display the lost count stats
perf top: Moving lost events warning to helpline
perf top: Add processing thread
perf top: Use cond variable instead of the lock
perf top: Set session_done when exiting
perf top: Drop samples which are behind more than refresh rate perf top: Save and display the drop count stats
perf top: Display slow reader warning for when droping samples perf top: Move perf_top__reset_sample_counters after counts display

 tools/perf/bench/epoll-ctl.c     |   7 +--
 tools/perf/bench/epoll-wait.c    |   6 ++-
 tools/perf/builtin-top.c         | 281 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-------------------------------
 tools/perf/ui/browsers/hists.c   |  11 +++++
 tools/perf/util/ordered-events.c |  16 ++++---
 tools/perf/util/ordered-events.h |   5 ++-
 tools/perf/util/session.c        |   3 +-
 tools/perf/util/top.c            |   8 ++--
 tools/perf/util/top.h            |  10 ++++-
 9 files changed, 258 insertions(+), 89 deletions(-)

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #1 lore raw

PATCH 1/12 perf tools: Fix build on sparc

From: David Miller <[email protected]>

A lot of warnings on sparc, this is the patch I'm using.

Cc Davidlohr Bueso <[email protected]>

Link http://lkml.kernel.org/n/[email protected] open here

Signed-off-by David Miller <[email protected]>

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

---
 tools/perf/bench/epoll-ctl.c  | 7 ++++---
 tools/perf/bench/epoll-wait.c | 6 ++++--
 2 files changed, 8 insertions(+), 5 deletions(-)

tools/perf/bench/epoll-ctl.c +4 -3

index b6f6fc4a7129..5b6ecfcc8c3a 100644
@@ -19,6 +19,7 @@
 #include <sys/resource.h>
 #include <sys/epoll.h>
 #include <sys/eventfd.h>
+#include <inttypes.h>
 
 #include "../util/stat.h"
 #include <subcmd/parse-options.h>

@@ -201,7 +202,7 @@ static void *workerfn(void *arg)
 
 static void init_fdmaps(struct worker *w, int pct)
 {
-	ssize_t i;
+	unsigned int i;
 	int inc;
 	struct epoll_event ev;

@@ -302,7 +303,7 @@ int bench_epoll_ctl(int argc, const char **argv)
 	struct worker *worker = NULL;
 	struct cpu_map *cpu;
 	struct rlimit rl, prevrl;
-	ssize_t i;
+	unsigned int i;
 
 	argc = parse_options(argc, argv, options, bench_epoll_ctl_usage, 0);
 	if (argc) {

@@ -340,7 +341,7 @@ int bench_epoll_ctl(int argc, const char **argv)
 	if (getrlimit(RLIMIT_NOFILE, &prevrl))
 	    err(EXIT_FAILURE, "getrlimit");
 	rl.rlim_cur = rl.rlim_max = nfds * nthreads * 2 + 50;
-	printinfo("Setting RLIMIT_NOFILE rlimit from %lu to: %lu\n",
+	printinfo("Setting RLIMIT_NOFILE rlimit from %" PRIu64 " to: %" PRIu64 "\n",
 		  prevrl.rlim_max, rl.rlim_max);
 	if (setrlimit(RLIMIT_NOFILE, &rl) < 0)
 		err(EXIT_FAILURE, "setrlimit");

tools/perf/bench/epoll-wait.c +4 -2

index 4e4efc5cfe22..595e9833201b 100644
@@ -73,6 +73,7 @@
 #include <sys/epoll.h>
 #include <sys/eventfd.h>
 #include <sys/types.h>
+#include <inttypes.h>
 
 #include "../util/stat.h"
 #include <subcmd/parse-options.h>

@@ -395,7 +396,7 @@ static void *writerfn(void *p)
 		nanosleep(&ts, NULL);
 	}
 
-	printinfo("exiting writer-thread (total full-loops: %ld)\n", iter);
+	printinfo("exiting writer-thread (total full-loops: %ld)\n", (long int) iter);
 	return NULL;
 }

@@ -459,7 +460,8 @@ int bench_epoll_wait(int argc, const char **argv)
 	if (getrlimit(RLIMIT_NOFILE, &prevrl))
 		err(EXIT_FAILURE, "getrlimit");
 	rl.rlim_cur = rl.rlim_max = nfds * nthreads * 2 + 50;
-	printinfo("Setting RLIMIT_NOFILE rlimit from %lu to: %lu\n", prevrl.rlim_max, rl.rlim_max);
+	printinfo("Setting RLIMIT_NOFILE rlimit from %" PRIu64 " to: %" PRIu64" \n",
+		  prevrl.rlim_max, rl.rlim_max);
 	if (setrlimit(RLIMIT_NOFILE, &rl) < 0)
 		err(EXIT_FAILURE, "setrlimit");

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #2 lore raw

PATCH 2/12 perf tools: Rework show_progress for __ordered_events__flush

In reply to Jiri Olsa

Decide to use the progress bar one level higher,
we will need this in following patch.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/util/ordered-events.c | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

tools/perf/util/ordered-events.c +5 -3

index 1904e7f6ec84..28f0f5c95024 100644
@@ -219,13 +219,13 @@ int ordered_events__queue(struct ordered_events *oe, union perf_event *event,
 	return 0;
 }
 
-static int __ordered_events__flush(struct ordered_events *oe)
+static int __ordered_events__flush(struct ordered_events *oe,
+				   bool show_progress)
 {
 	struct list_head *head = &oe->events;
 	struct ordered_event *tmp, *iter;
 	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;

@@ -272,6 +272,7 @@ int ordered_events__flush(struct ordered_events *oe, enum oe_flush how)
 		"HALF ",
 	};
 	int err;
+	bool show_progress = false;
 
 	if (oe->nr_events == 0)
 		return 0;

@@ -279,6 +280,7 @@ int ordered_events__flush(struct ordered_events *oe, enum oe_flush how)
 	switch (how) {
 	case OE_FLUSH__FINAL:
 		oe->next_flush = ULLONG_MAX;
+		show_progress = true;
 		break;
 
 	case OE_FLUSH__HALF:

@@ -308,7 +310,7 @@ int ordered_events__flush(struct ordered_events *oe, enum oe_flush how)
 		   str[how], oe->nr_events);
 	pr_oe_time(oe->max_timestamp, "max_timestamp\n");
 
-	err = __ordered_events__flush(oe);
+	err = __ordered_events__flush(oe, show_progress);
 
 	if (!err) {
 		if (how == OE_FLUSH__ROUND)

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #3 lore raw

PATCH 3/12 perf tools: Add private data to struct ordered_events

In reply to Jiri Olsa

We will need it in following patch, where we can't use the container_of trick to get higher level object.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/util/ordered-events.c | 6 ++++--
 tools/perf/util/ordered-events.h | 4 +++-
 tools/perf/util/session.c        | 3 ++-
 3 files changed, 9 insertions(+), 4 deletions(-)

tools/perf/util/ordered-events.c +4 -2

index 28f0f5c95024..d053aa0a7582 100644
@@ -326,7 +326,8 @@ int ordered_events__flush(struct ordered_events *oe, enum oe_flush how)
 	return err;
 }
 
-void ordered_events__init(struct ordered_events *oe, ordered_events__deliver_t deliver)
+void ordered_events__init(struct ordered_events *oe, ordered_events__deliver_t deliver,
+			  void *data)
 {
 	INIT_LIST_HEAD(&oe->events);
 	INIT_LIST_HEAD(&oe->cache);

@@ -334,6 +335,7 @@ void ordered_events__init(struct ordered_events *oe, ordered_events__deliver_t d
 	oe->max_alloc_size = (u64) -1;
 	oe->cur_alloc_size = 0;
 	oe->deliver	   = deliver;
+	oe->data	   = data;
 }
 
 static void

@@ -377,5 +379,5 @@ void ordered_events__reinit(struct ordered_events *oe)
 
 	ordered_events__free(oe);
 	memset(oe, '\0', sizeof(*oe));
-	ordered_events__init(oe, old_deliver);
+	ordered_events__init(oe, old_deliver, oe->data);
 }

tools/perf/util/ordered-events.h +3 -1

index 1338d5c345dc..507b4e4df79e 100644
@@ -47,13 +47,15 @@ struct ordered_events {
 	enum oe_flush			 last_flush_type;
 	u32				 nr_unordered_events;
 	bool				 copy_on_queue;
+	void				*data;
 };
 
 int ordered_events__queue(struct ordered_events *oe, union perf_event *event,
 			  u64 timestamp, u64 file_offset);
 void ordered_events__delete(struct ordered_events *oe, struct ordered_event *event);
 int ordered_events__flush(struct ordered_events *oe, enum oe_flush how);
-void ordered_events__init(struct ordered_events *oe, ordered_events__deliver_t deliver);
+void ordered_events__init(struct ordered_events *oe, ordered_events__deliver_t deliver,
+			  void *data);
 void ordered_events__free(struct ordered_events *oe);
 void ordered_events__reinit(struct ordered_events *oe);

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

index df5e12b22905..922d24cfba6a 100644
@@ -125,7 +125,8 @@ struct perf_session *perf_session__new(struct perf_data *data,
 	session->tool   = tool;
 	INIT_LIST_HEAD(&session->auxtrace_index);
 	machines__init(&session->machines);
-	ordered_events__init(&session->ordered_events, ordered_events__deliver_event);
+	ordered_events__init(&session->ordered_events,
+			     ordered_events__deliver_event, NULL);
 
 	if (data) {
 		if (perf_data__open(data))

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #4 lore raw

PATCH 4/12 perf top: Save and display the lost count stats

In reply to Jiri Olsa

Adding lost count to perf top headers:

  # perf top --stdio
   PerfTop:    3850 irqs/sec  kernel:49.0%  exact: 100.0% lost: 0/0 [4000Hz cycles:ppp],  (all, 8 CPUs)

  # perf top
  Samples: 0  of event 'cycles:ppp', 4000 Hz, Event count (approx.): 0 lost: 0/0

The format is: <current period lost>/<total lost>

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c       | 27 +++++++++++++++++++++++++++
 tools/perf/ui/browsers/hists.c |  4 ++++
 tools/perf/util/top.c          |  6 +++---
 tools/perf/util/top.h          |  2 +-
 4 files changed, 35 insertions(+), 4 deletions(-)

tools/perf/builtin-top.c +27 -0

index aa0c73e57924..047e99de09f3 100644
@@ -800,6 +800,29 @@ static void perf_event__process_sample(struct perf_tool *tool,
 	addr_location__put(&al);
 }
 
+static void
+perf_top__process_lost(struct perf_top *top, union perf_event *event,
+		       struct perf_evsel *evsel)
+{
+	struct hists *hists = evsel__hists(evsel);
+
+	top->lost += event->lost.lost;
+	top->lost_total += event->lost.lost;
+	hists->stats.total_lost += event->lost.lost;
+}
+
+static void
+perf_top__process_lost_samples(struct perf_top *top,
+			       union perf_event *event,
+			       struct perf_evsel *evsel)
+{
+	struct hists *hists = evsel__hists(evsel);
+
+	top->lost += event->lost_samples.lost;
+	top->lost_total += event->lost_samples.lost;
+	hists->stats.total_lost_samples += event->lost_samples.lost;
+}
+
 static void perf_top__mmap_read_idx(struct perf_top *top, int idx)
 {
 	struct record_opts *opts = &top->record_opts;

@@ -865,6 +888,10 @@ static void perf_top__mmap_read_idx(struct perf_top *top, int idx)
 		if (event->header.type == PERF_RECORD_SAMPLE) {
 			perf_event__process_sample(&top->tool, event, evsel,
 						   &sample, machine);
+		} else if (event->header.type == PERF_RECORD_LOST) {
+			perf_top__process_lost(top, event, evsel);
+		} else if (event->header.type == PERF_RECORD_LOST_SAMPLES) {
+			perf_top__process_lost_samples(top, event, evsel);
 		} else if (event->header.type < PERF_RECORD_MAX) {
 			hists__inc_nr_events(evsel__hists(evsel), event->header.type);
 			machine__process_event(machine, event, &sample);

tools/perf/ui/browsers/hists.c +4 -0

index a96f62ca984a..ae208c16c8a3 100644
@@ -2219,6 +2219,10 @@ static int hists_browser__scnprintf_title(struct hist_browser *browser, char *bf
 	if (!is_report_browser(hbt)) {
 		struct perf_top *top = hbt->arg;
 
+		printed += scnprintf(bf + printed, size - printed,
+				     " lost: %" PRIu64 "/%" PRIu64,
+				     top->lost, top->lost_total);
+
 		if (top->zero)
 			printed += scnprintf(bf + printed, size - printed, " [z]");
 	}

tools/perf/util/top.c +3 -3

index 8e517def925b..e6582fa6a4db 100644
@@ -46,8 +46,8 @@ size_t perf_top__header_snprintf(struct perf_top *top, char *bf, size_t size)
 							samples_per_sec;
 		ret = SNPRINTF(bf, size,
 			       "   PerfTop:%8.0f irqs/sec  kernel:%4.1f%%"
-			       "  exact: %4.1f%% [", samples_per_sec,
-			       ksamples_percent, esamples_percent);
+			       "  exact: %4.1f%% lost: %" PRIu64 "/%" PRIu64 " [", samples_per_sec,
+			       ksamples_percent, esamples_percent, top->lost, top->lost_total);
 	} else {
 		float us_samples_per_sec = top->us_samples / top->delay_secs;
 		float guest_kernel_samples_per_sec = top->guest_kernel_samples / top->delay_secs;

@@ -113,5 +113,5 @@ void perf_top__reset_sample_counters(struct perf_top *top)
 {
 	top->samples = top->us_samples = top->kernel_samples =
 	top->exact_samples = top->guest_kernel_samples =
-	top->guest_us_samples = 0;
+	top->guest_us_samples = top->lost = 0;
 }

tools/perf/util/top.h +1 -1

index 9add1f72ce95..1fbcbd79720a 100644
@@ -22,7 +22,7 @@ struct perf_top {
 	 * Symbols will be added here in perf_event__process_sample and will
 	 * get out after decayed.
 	 */
-	u64		   samples;
+	u64		   samples, lost, lost_total;
 	u64		   kernel_samples, us_samples;
 	u64		   exact_samples;
 	u64		   guest_us_samples, guest_kernel_samples;

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #5 lore raw

PATCH 5/12 perf top: Moving lost events warning to helpline

In reply to Jiri Olsa

We can't display the UI box saying that we are slow in reader thread. That will make perf top even slower and user even more angry ;-)

Moving the UI box message out of the reader thread into UI thread and changing it into helpline, so there's no 'press any key' necessary.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c | 16 +++++-----------
 1 file changed, 5 insertions(+), 11 deletions(-)

tools/perf/builtin-top.c +5 ~~-11~~

index 047e99de09f3..1d77aa7650da 100644
@@ -553,8 +553,6 @@ static void perf_top__sort_new_samples(void *arg)
 	struct perf_evsel *evsel = t->sym_evsel;
 	struct hists *hists;
 
-	perf_top__reset_sample_counters(t);
-
 	if (t->evlist->selected != NULL)
 		t->sym_evsel = t->evlist->selected;

@@ -571,6 +569,11 @@ static void perf_top__sort_new_samples(void *arg)
 
 	hists__collapse_resort(hists, NULL);
 	perf_evsel__output_resort(evsel, NULL);
+
+	if (t->lost)
+		ui_helpline__fpush("Too slow to read ring buffer (change period (-c/-F) or limit CPUs (-C)\n");
+
+	perf_top__reset_sample_counters(t);
 }
 
 static void *display_thread_tui(void *arg)

@@ -908,10 +911,8 @@ static void perf_top__mmap_read(struct perf_top *top)
 {
 	bool overwrite = top->record_opts.overwrite;
 	struct perf_evlist *evlist = top->evlist;
-	unsigned long long start, end;
 	int i;
 
-	start = rdclock();
 	if (overwrite)
 		perf_evlist__toggle_bkw_mmap(evlist, BKW_MMAP_DATA_PENDING);

@@ -922,13 +923,6 @@ static void perf_top__mmap_read(struct perf_top *top)
 		perf_evlist__toggle_bkw_mmap(evlist, BKW_MMAP_EMPTY);
 		perf_evlist__toggle_bkw_mmap(evlist, BKW_MMAP_RUNNING);
 	}
-	end = rdclock();
-
-	if ((end - start) > (unsigned long long)top->delay_secs * NSEC_PER_SEC)
-		ui__warning("Too slow to read ring buffer.\n"
-			    "Please try increasing the period (-c) or\n"
-			    "decreasing the freq (-F) or\n"
-			    "limiting the number of CPUs (-C)\n");
 }
 
 /*

Signature · 1 line

2.17.2

Namhyung Kim

maintainer

2018-11-20 02:04 UTC #6 lore raw

Re: [PATCH 05/12] perf top: Moving lost events warning to helpline

Quoted 28 lines · Jiri Olsa

We can't display the UI box saying that we are slow in reader thread. That will make perf top even slower and user even more angry ;-)
Moving the UI box message out of the reader thread into UI thread and changing it into helpline, so there's no 'press any key' necessary.
Link http://lkml.kernel.org/n/[email protected] open here
Signed-off-by Jiri Olsa <[email protected]>
---
 tools/perf/builtin-top.c | 16 +++++-----------
 1 file changed, 5 insertions(+), 11 deletions(-)
tools/perf/builtin-top.c +0 -2
index 047e99de09f3..1d77aa7650da 100644
@@ -553,8 +553,6 @@ static void perf_top__sort_new_samples(void *arg)
 	struct perf_evsel *evsel = t->sym_evsel;
 	struct hists *hists;
 
-	perf_top__reset_sample_counters(t);
-
 	if (t->evlist->selected != NULL)
 		t->sym_evsel = t->evlist->selected;
 

tools/perf/builtin-top.c static void perf_top__sort_new_samples(void *arg) · line 574

Quoted 6 lines

tools/perf/builtin-top.c +3 -0

@@ -571,6 +569,11 @@ static void perf_top__sort_new_samples(void *arg)
 
 	hists__collapse_resort(hists, NULL);
 	perf_evsel__output_resort(evsel, NULL);
+
+	if (t->lost)
+		ui_helpline__fpush("Too slow to read ring buffer (change period (-c/-F) or limit CPUs (-C)\n");

In general, ui_helpline__[f]push() requires corresponding __pop() which handles timeout logic (or something can dismiss the message). The ui_helpline__show() is to show the message and overwrite the old one.

But we don't use it strictly and I think just pr_err() or pr_warning() is ok here (which call ui_helpline__show() internally).

Anyway, I found that tui_helpline__push() should use ui__lock. Otherwise it could race with display thread and break rendering. A bug from the beginning but no one reported... :)

Thanks,
Namhyung

From a5c3a0c88b9d13fedc65b61a45d99fc3abef0089 Mon Sep 17 00:00:00 2001
From: Namhyung Kim <[email protected]>
Date: Tue, 20 Nov 2018 10:56:03 +0900
Subject: [PATCH] perf ui/tui: Fix possible UI rendering breakage

The tui_helpline__push() should acquire/release the ui__lock when it deals with screen setting. Otherwise it could race with display thread and screen rendering would not be handled properly.

Fixes e6e904687949 ("perf ui: Introduce struct ui_helpline")

Signed-off-by Namhyung Kim <[email protected]>

---
 tools/perf/ui/tui/helpline.c | 2 ++
 1 file changed, 2 insertions(+)

tools/perf/ui/tui/helpline.c +2 -0

index 4ca799aadb4e..ff38b997f457 100644
@@ -20,11 +20,13 @@ static void tui_helpline__push(const char *msg)
 {
 	const size_t sz = sizeof(ui_helpline__current);
 
+	pthread_mutex_lock(&ui__lock);
 	SLsmg_gotorc(SLtt_Screen_Rows - 1, 0);
 	SLsmg_set_color(0);
 	SLsmg_write_nstring((char *)msg, SLtt_Screen_Cols);
 	SLsmg_refresh();
 	strncpy(ui_helpline__current, msg, sz)[sz - 1] = '\0';
+	pthread_mutex_unlock(&ui__lock);
 }
 
 static int tui_helpline__show(const char *format, va_list ap)

Signature · 1 line

2.19.0

Namhyung Kim

maintainer

2018-11-20 11:33 UTC #7 lore raw

Re: [PATCH 05/12] perf top: Moving lost events warning to helpline

Quoted 41 lines · Namhyung Kim

Quoted 28 lines · Jiri Olsa
We can't display the UI box saying that we are slow in reader thread. That will make perf top even slower and user even more angry ;-)
Moving the UI box message out of the reader thread into UI thread and changing it into helpline, so there's no 'press any key' necessary.
Link http://lkml.kernel.org/n/[email protected] open here
Signed-off-by Jiri Olsa <[email protected]>
---
 tools/perf/builtin-top.c | 16 +++++-----------
 1 file changed, 5 insertions(+), 11 deletions(-)
tools/perf/builtin-top.c +0 -2
index 047e99de09f3..1d77aa7650da 100644
@@ -553,8 +553,6 @@ static void perf_top__sort_new_samples(void *arg)
 	struct perf_evsel *evsel = t->sym_evsel;
 	struct hists *hists;
 
-	perf_top__reset_sample_counters(t);
-
 	if (t->evlist->selected != NULL)
 		t->sym_evsel = t->evlist->selected;
 
tools/perf/builtin-top.c static void perf_top__sort_new_samples(void *arg) · line 574
Quoted 6 lines
tools/perf/builtin-top.c +3 -0
@@ -571,6 +569,11 @@ static void perf_top__sort_new_samples(void *arg)
 
 	hists__collapse_resort(hists, NULL);
 	perf_evsel__output_resort(evsel, NULL);
+
+	if (t->lost)
+		ui_helpline__fpush("Too slow to read ring buffer (change period (-c/-F) or limit CPUs (-C)\n");
In general, ui_helpline__[f]push() requires corresponding __pop() which handles timeout logic (or something can dismiss the message). The ui_helpline__show() is to show the message and overwrite the old one.

Quoted 6 lines

But we don't use it strictly and I think just pr_err() or pr_warning() is ok here (which call ui_helpline__show() internally).
Anyway, I found that tui_helpline__push() should use ui__lock. Otherwise it could race with display thread and break rendering. A bug from the beginning but no one reported... :)

Hmm.. wait. it caused a deadlock since it calls itself internally.. Will take a deeper look at it..

Thanks,
Namhyung

Namhyung Kim

maintainer

2018-11-20 11:51 UTC #8 lore raw

PATCH v2 1/1 perf ui/tui: Fix possible UI rendering breakage

The tui_helpline__push() should acquire/release the ui__lock when it deals with screen setting. Otherwise it could race with display thread and screen rendering would not be handled properly.

Also move helpline__push/pop out of ui__lock to prevent deadlock.

Fixes e6e904687949 ("perf ui: Introduce struct ui_helpline")

Signed-off-by Namhyung Kim <[email protected]>

---
 tools/perf/ui/browser.c      |  7 ++++---
 tools/perf/ui/tui/helpline.c | 17 ++++++++++++-----
 2 files changed, 16 insertions(+), 8 deletions(-)

tools/perf/ui/browser.c +4 -3

index 4f75561424ed..2a99a0fbbcf6 100644
@@ -294,16 +294,17 @@ int ui_browser__show(struct ui_browser *browser, const char *title,
 	va_start(ap, helpline);
 	err = vasprintf(&browser->helpline, helpline, ap);
 	va_end(ap);
-	if (err > 0)
-		ui_helpline__push(browser->helpline);
 	pthread_mutex_unlock(&ui__lock);
+
+	if (err > 0)
+		ui_helpline__push(helpline);
 	return err ? 0 : -1;
 }
 
 void ui_browser__hide(struct ui_browser *browser)
 {
-	pthread_mutex_lock(&ui__lock);
 	ui_helpline__pop();
+	pthread_mutex_lock(&ui__lock);
 	zfree(&browser->helpline);
 	pthread_mutex_unlock(&ui__lock);
 }

tools/perf/ui/tui/helpline.c +12 -5

index 4ca799aadb4e..83b6eebb451a 100644
@@ -12,6 +12,14 @@
 char ui_helpline__last_msg[1024];
 bool tui_helpline__set;
 
+static void tui_helpline__puts(const char *msg)
+{
+	SLsmg_gotorc(SLtt_Screen_Rows - 1, 0);
+	SLsmg_set_color(0);
+	SLsmg_write_nstring((char *)msg, SLtt_Screen_Cols);
+	SLsmg_refresh();
+}
+
 static void tui_helpline__pop(void)
 {
 }

@@ -20,11 +28,10 @@ static void tui_helpline__push(const char *msg)
 {
 	const size_t sz = sizeof(ui_helpline__current);
 
-	SLsmg_gotorc(SLtt_Screen_Rows - 1, 0);
-	SLsmg_set_color(0);
-	SLsmg_write_nstring((char *)msg, SLtt_Screen_Cols);
-	SLsmg_refresh();
+	pthread_mutex_lock(&ui__lock);
 	strncpy(ui_helpline__current, msg, sz)[sz - 1] = '\0';
+	tui_helpline__puts(msg);
+	pthread_mutex_unlock(&ui__lock);
 }
 
 static int tui_helpline__show(const char *format, va_list ap)

@@ -40,7 +47,7 @@ static int tui_helpline__show(const char *format, va_list ap)
 	tui_helpline__set = true;
 
 	if (ui_helpline__last_msg[backlog - 1] == '\n') {
-		ui_helpline__puts(ui_helpline__last_msg);
+		tui_helpline__puts(ui_helpline__last_msg);
 		SLsmg_refresh();
 		backlog = 0;
 	}

Signature · 1 line

2.19.0

Namhyung Kim

maintainer

2018-11-20 12:07 UTC #9 lore raw

PATCH 1/1 perf ui/tui: Fix possible UI rendering breakage

The tui_helpline__push() should acquire/release the ui__lock when it deals with screen setting. Otherwise it could race with display thread and screen rendering would not be handled properly.

Also move helpline__push/pop out of ui__lock to prevent deadlock.

Fixes e6e904687949 ("perf ui: Introduce struct ui_helpline")

Signed-off-by Namhyung Kim <[email protected]>

---
* use browser->helpline for display instead of helpline (format)

 tools/perf/ui/browser.c      |  7 ++++---
 tools/perf/ui/tui/helpline.c | 17 ++++++++++++-----
 2 files changed, 16 insertions(+), 8 deletions(-)

tools/perf/ui/browser.c +4 -3

index 4f75561424ed..2a99a0fbbcf6 100644
@@ -294,16 +294,17 @@ int ui_browser__show(struct ui_browser *browser, const char *title,
 	va_start(ap, helpline);
 	err = vasprintf(&browser->helpline, helpline, ap);
 	va_end(ap);
-	if (err > 0)
-		ui_helpline__push(browser->helpline);
 	pthread_mutex_unlock(&ui__lock);
+
+	if (err > 0)
+		ui_helpline__push(browser->helpline);
 	return err ? 0 : -1;
 }
 
 void ui_browser__hide(struct ui_browser *browser)
 {
-	pthread_mutex_lock(&ui__lock);
 	ui_helpline__pop();
+	pthread_mutex_lock(&ui__lock);
 	zfree(&browser->helpline);
 	pthread_mutex_unlock(&ui__lock);
 }

tools/perf/ui/tui/helpline.c +12 -5

index 4ca799aadb4e..83b6eebb451a 100644
@@ -12,6 +12,14 @@
 char ui_helpline__last_msg[1024];
 bool tui_helpline__set;
 
+static void tui_helpline__puts(const char *msg)
+{
+	SLsmg_gotorc(SLtt_Screen_Rows - 1, 0);
+	SLsmg_set_color(0);
+	SLsmg_write_nstring((char *)msg, SLtt_Screen_Cols);
+	SLsmg_refresh();
+}
+
 static void tui_helpline__pop(void)
 {
 }

@@ -20,11 +28,10 @@ static void tui_helpline__push(const char *msg)
 {
 	const size_t sz = sizeof(ui_helpline__current);
 
-	SLsmg_gotorc(SLtt_Screen_Rows - 1, 0);
-	SLsmg_set_color(0);
-	SLsmg_write_nstring((char *)msg, SLtt_Screen_Cols);
-	SLsmg_refresh();
+	pthread_mutex_lock(&ui__lock);
 	strncpy(ui_helpline__current, msg, sz)[sz - 1] = '\0';
+	tui_helpline__puts(msg);
+	pthread_mutex_unlock(&ui__lock);
 }
 
 static int tui_helpline__show(const char *format, va_list ap)

@@ -40,7 +47,7 @@ static int tui_helpline__show(const char *format, va_list ap)
 	tui_helpline__set = true;
 
 	if (ui_helpline__last_msg[backlog - 1] == '\n') {
-		ui_helpline__puts(ui_helpline__last_msg);
+		tui_helpline__puts(ui_helpline__last_msg);
 		SLsmg_refresh();
 		backlog = 0;
 	}

Signature · 1 line

2.19.0

Jiri Olsa

2018-11-20 11:38 UTC #10 lore raw

PATCH v2 5/12 perf top: Moving lost events warning to helpline

In reply to Namhyung Kim

Quoted 41 lines · Namhyung Kim

Quoted 28 lines · Jiri Olsa
We can't display the UI box saying that we are slow in reader thread. That will make perf top even slower and user even more angry ;-)
Moving the UI box message out of the reader thread into UI thread and changing it into helpline, so there's no 'press any key' necessary.
Link http://lkml.kernel.org/n/[email protected] open here
Signed-off-by Jiri Olsa <[email protected]>
---
 tools/perf/builtin-top.c | 16 +++++-----------
 1 file changed, 5 insertions(+), 11 deletions(-)
tools/perf/builtin-top.c +0 -2
index 047e99de09f3..1d77aa7650da 100644
@@ -553,8 +553,6 @@ static void perf_top__sort_new_samples(void *arg)
 	struct perf_evsel *evsel = t->sym_evsel;
 	struct hists *hists;
 
-	perf_top__reset_sample_counters(t);
-
 	if (t->evlist->selected != NULL)
 		t->sym_evsel = t->evlist->selected;
 
tools/perf/builtin-top.c static void perf_top__sort_new_samples(void *arg) · line 574
Quoted 6 lines
tools/perf/builtin-top.c +3 -0
@@ -571,6 +569,11 @@ static void perf_top__sort_new_samples(void *arg)
 
 	hists__collapse_resort(hists, NULL);
 	perf_evsel__output_resort(evsel, NULL);
+
+	if (t->lost)
+		ui_helpline__fpush("Too slow to read ring buffer (change period (-c/-F) or limit CPUs (-C)\n");
In general, ui_helpline__[f]push() requires corresponding __pop() which handles timeout logic (or something can dismiss the message). The ui_helpline__show() is to show the message and overwrite the old one.

Quoted 2 lines

But we don't use it strictly and I think just pr_err() or pr_warning() is ok here (which call ui_helpline__show() internally).

right, v2 attached

there were some small conflicts in follow up patches, I pushed new version with resolved conflicts in perf/fixes branch

thanks,
jirka

---
We can't display the UI box saying that we are slow in reader thread. That will make perf top even slower and user even more angry ;-)

Moving the UI box message out of the reader thread into UI thread and changing it into helpline, so there's no 'press any key' necessary.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c | 16 +++++-----------
 1 file changed, 5 insertions(+), 11 deletions(-)

tools/perf/builtin-top.c +5 ~~-11~~

index 047e99de09f3..d4105ba8510c 100644
@@ -553,8 +553,6 @@ static void perf_top__sort_new_samples(void *arg)
 	struct perf_evsel *evsel = t->sym_evsel;
 	struct hists *hists;
 
-	perf_top__reset_sample_counters(t);
-
 	if (t->evlist->selected != NULL)
 		t->sym_evsel = t->evlist->selected;

@@ -571,6 +569,11 @@ static void perf_top__sort_new_samples(void *arg)
 
 	hists__collapse_resort(hists, NULL);
 	perf_evsel__output_resort(evsel, NULL);
+
+	if (t->lost)
+		pr_warning("Too slow to read ring buffer (change period (-c/-F) or limit CPUs (-C)\n");
+
+	perf_top__reset_sample_counters(t);
 }
 
 static void *display_thread_tui(void *arg)

@@ -908,10 +911,8 @@ static void perf_top__mmap_read(struct perf_top *top)
 {
 	bool overwrite = top->record_opts.overwrite;
 	struct perf_evlist *evlist = top->evlist;
-	unsigned long long start, end;
 	int i;
 
-	start = rdclock();
 	if (overwrite)
 		perf_evlist__toggle_bkw_mmap(evlist, BKW_MMAP_DATA_PENDING);

@@ -922,13 +923,6 @@ static void perf_top__mmap_read(struct perf_top *top)
 		perf_evlist__toggle_bkw_mmap(evlist, BKW_MMAP_EMPTY);
 		perf_evlist__toggle_bkw_mmap(evlist, BKW_MMAP_RUNNING);
 	}
-	end = rdclock();
-
-	if ((end - start) > (unsigned long long)top->delay_secs * NSEC_PER_SEC)
-		ui__warning("Too slow to read ring buffer.\n"
-			    "Please try increasing the period (-c) or\n"
-			    "decreasing the freq (-F) or\n"
-			    "limiting the number of CPUs (-C)\n");
 }
 
 /*

Signature · 1 line

2.17.2

Jiri Olsa

2018-11-20 11:41 UTC #11 lore raw

Re: [PATCH 05/12] perf top: Moving lost events warning to helpline

In reply to Namhyung Kim

Quoted 72 lines · Namhyung Kim

Quoted 28 lines · Jiri Olsa
We can't display the UI box saying that we are slow in reader thread. That will make perf top even slower and user even more angry ;-)
Moving the UI box message out of the reader thread into UI thread and changing it into helpline, so there's no 'press any key' necessary.
Link http://lkml.kernel.org/n/[email protected] open here
Signed-off-by Jiri Olsa <[email protected]>
---
 tools/perf/builtin-top.c | 16 +++++-----------
 1 file changed, 5 insertions(+), 11 deletions(-)
tools/perf/builtin-top.c +0 -2
index 047e99de09f3..1d77aa7650da 100644
@@ -553,8 +553,6 @@ static void perf_top__sort_new_samples(void *arg)
 	struct perf_evsel *evsel = t->sym_evsel;
 	struct hists *hists;
 
-	perf_top__reset_sample_counters(t);
-
 	if (t->evlist->selected != NULL)
 		t->sym_evsel = t->evlist->selected;
 
tools/perf/builtin-top.c static void perf_top__sort_new_samples(void *arg) · line 574
Quoted 6 lines
tools/perf/builtin-top.c +3 -0
@@ -571,6 +569,11 @@ static void perf_top__sort_new_samples(void *arg)
 
 	hists__collapse_resort(hists, NULL);
 	perf_evsel__output_resort(evsel, NULL);
+
+	if (t->lost)
+		ui_helpline__fpush("Too slow to read ring buffer (change period (-c/-F) or limit CPUs (-C)\n");
In general, ui_helpline__[f]push() requires corresponding __pop() which handles timeout logic (or something can dismiss the message). The ui_helpline__show() is to show the message and overwrite the old one.
But we don't use it strictly and I think just pr_err() or pr_warning() is ok here (which call ui_helpline__show() internally).
Anyway, I found that tui_helpline__push() should use ui__lock. Otherwise it could race with display thread and break rendering. A bug from the beginning but no one reported... :)
Thanks,
Namhyung
From a5c3a0c88b9d13fedc65b61a45d99fc3abef0089 Mon Sep 17 00:00:00 2001
From: Namhyung Kim <[email protected]>
Date: Tue, 20 Nov 2018 10:56:03 +0900
Subject: [PATCH] perf ui/tui: Fix possible UI rendering breakage
The tui_helpline__push() should acquire/release the ui__lock when it deals with screen setting. Otherwise it could race with display thread and screen rendering would not be handled properly.
Fixes e6e904687949 ("perf ui: Introduce struct ui_helpline")
Signed-off-by Namhyung Kim <[email protected]>
---
 tools/perf/ui/tui/helpline.c | 2 ++
 1 file changed, 2 insertions(+)
tools/perf/ui/tui/helpline.c +0 -0
index 4ca799aadb4e..ff38b997f457 100644

tools/perf/ui/tui/helpline.c static void tui_helpline__push(const char *msg) · line 23

Quoted 4 lines

tools/perf/ui/tui/helpline.c +1 -0

@@ -20,11 +20,13 @@ static void tui_helpline__push(const char *msg)
 {
 	const size_t sz = sizeof(ui_helpline__current);
 
+	pthread_mutex_lock(&ui__lock);

hum, I haven't tested but in ui_browser__show there's ui_helpline__push call under locked ui__lock

jirka

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #12 lore raw

PATCH 6/12 perf top: Add processing thread

In reply to Jiri Olsa

Adding new thread that takes care of the hist creating to alleviate the main reader thread so it can keep perf mmaps served in time and we won't lose events.

The perf top command now spawns 2 extra threads, the data processing is following:

1) main thread reads the data from mmaps and queues them to ordered events object
2) processing threads takes the data from the ordered events object and create initial histogram
3) gui thread periodically sorts the initial histogram and presents it

Passing the data between threads 1 and 2 is dont by having 2 ordered events queues. One is always being stored to by thread 1 while the other is flushed out in thread 2.

Passing the data between threads 2 and 3 stays the same as was initialy for threads 1 and 3.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c         | 202 +++++++++++++++++++++----------
 tools/perf/util/ordered-events.c |   4 +-
 tools/perf/util/ordered-events.h |   1 +
 tools/perf/util/top.h            |   6 +
 4 files changed, 151 insertions(+), 62 deletions(-)

tools/perf/builtin-top.c +141 ~~-61~~

index 1d77aa7650da..f8dcdf0f54e1 100644
@@ -46,6 +46,7 @@
 #include "arch/common.h"
 
 #include "util/debug.h"
+#include "util/ordered-events.h"
 
 #include <assert.h>
 #include <elf.h>

@@ -830,78 +831,28 @@ static void perf_top__mmap_read_idx(struct perf_top *top, int idx)
 {
 	struct record_opts *opts = &top->record_opts;
 	struct perf_evlist *evlist = top->evlist;
-	struct perf_sample sample;
-	struct perf_evsel *evsel;
 	struct perf_mmap *md;
-	struct perf_session *session = top->session;
 	union perf_event *event;
-	struct machine *machine;
-	int ret;
 
 	md = opts->overwrite ? &evlist->overwrite_mmap[idx] : &evlist->mmap[idx];
 	if (perf_mmap__read_init(md) < 0)
 		return;
 
 	while ((event = perf_mmap__read_event(md)) != NULL) {
-		ret = perf_evlist__parse_sample(evlist, event, &sample);
-		if (ret) {
-			pr_err("Can't parse sample, err = %d\n", ret);
-			goto next_event;
-		}
-
-		evsel = perf_evlist__id2evsel(session->evlist, sample.id);
-		assert(evsel != NULL);
+		u64 timestamp = -1ULL;
+		int ret;
 
-		if (event->header.type == PERF_RECORD_SAMPLE)
-			++top->samples;
-
-		switch (sample.cpumode) {
-		case PERF_RECORD_MISC_USER:
-			++top->us_samples;
-			if (top->hide_user_symbols)
-				goto next_event;
-			machine = &session->machines.host;
-			break;
-		case PERF_RECORD_MISC_KERNEL:
-			++top->kernel_samples;
-			if (top->hide_kernel_symbols)
-				goto next_event;
-			machine = &session->machines.host;
+		ret = perf_evlist__parse_sample_timestamp(evlist, event, &timestamp);
+		if (ret && ret != -1)
 			break;
-		case PERF_RECORD_MISC_GUEST_KERNEL:
-			++top->guest_kernel_samples;
-			machine = perf_session__find_machine(session,
-							     sample.pid);
-			break;
-		case PERF_RECORD_MISC_GUEST_USER:
-			++top->guest_us_samples;
-			/*
-			 * TODO: we don't process guest user from host side
-			 * except simple counting.
-			 */
-			goto next_event;
-		default:
-			if (event->header.type == PERF_RECORD_SAMPLE)
-				goto next_event;
-			machine = &session->machines.host;
-			break;
-		}
 
+		pthread_mutex_lock(&top->qe.lock);
+		ret = ordered_events__queue(top->qe.in, event, timestamp, 0);
+		pthread_mutex_unlock(&top->qe.lock);
 
-		if (event->header.type == PERF_RECORD_SAMPLE) {
-			perf_event__process_sample(&top->tool, event, evsel,
-						   &sample, machine);
-		} else if (event->header.type == PERF_RECORD_LOST) {
-			perf_top__process_lost(top, event, evsel);
-		} else if (event->header.type == PERF_RECORD_LOST_SAMPLES) {
-			perf_top__process_lost_samples(top, event, evsel);
-		} else if (event->header.type < PERF_RECORD_MAX) {
-			hists__inc_nr_events(evsel__hists(evsel), event->header.type);
-			machine__process_event(machine, event, &sample);
-		} else
-			++session->evlist->stats.nr_unknown_events;
-next_event:
 		perf_mmap__consume(md);
+		if (ret)
+			break;
 	}
 
 	perf_mmap__read_done(md);

@@ -1084,6 +1035,125 @@ static int callchain_param__setup_sample_type(struct callchain_param *callchain)
 	return 0;
 }
 
+static struct ordered_events *rotate_queues(struct perf_top *top)
+{
+	struct ordered_events *in = top->qe.in;
+
+	if (top->qe.in == &top->qe.data[1])
+		top->qe.in = &top->qe.data[0];
+	else
+		top->qe.in = &top->qe.data[1];
+
+	return in;
+}
+
+static void *process_thread(void *arg)
+{
+	struct perf_top *top = arg;
+
+	while (!done) {
+		struct ordered_events *out, *in = top->qe.in;
+
+		if (!in->nr_events) {
+			usleep(100);
+			continue;
+		}
+
+		pthread_mutex_lock(&top->qe.lock);
+		out = rotate_queues(top);
+		pthread_mutex_unlock(&top->qe.lock);
+
+		if (ordered_events__flush(out, OE_FLUSH__TOP))
+			pr_err("failed to process events\n");
+	}
+
+	return NULL;
+}
+
+static int deliver_event(struct ordered_events *qe,
+			 struct ordered_event *qevent)
+{
+	struct perf_top *top = qe->data;
+	struct perf_evlist *evlist = top->evlist;
+	struct perf_session *session = top->session;
+	union perf_event *event = qevent->event;
+	struct perf_sample sample;
+	struct perf_evsel *evsel;
+	struct machine *machine;
+	int ret = -1;
+
+	ret = perf_evlist__parse_sample(evlist, event, &sample);
+	if (ret) {
+		pr_err("Can't parse sample, err = %d\n", ret);
+		goto next_event;
+	}
+
+	evsel = perf_evlist__id2evsel(session->evlist, sample.id);
+	assert(evsel != NULL);
+
+	if (event->header.type == PERF_RECORD_SAMPLE)
+		++top->samples;
+
+	switch (sample.cpumode) {
+	case PERF_RECORD_MISC_USER:
+		++top->us_samples;
+		if (top->hide_user_symbols)
+			goto next_event;
+		machine = &session->machines.host;
+		break;
+	case PERF_RECORD_MISC_KERNEL:
+		++top->kernel_samples;
+		if (top->hide_kernel_symbols)
+			goto next_event;
+		machine = &session->machines.host;
+		break;
+	case PERF_RECORD_MISC_GUEST_KERNEL:
+		++top->guest_kernel_samples;
+		machine = perf_session__find_machine(session,
+						     sample.pid);
+		break;
+	case PERF_RECORD_MISC_GUEST_USER:
+		++top->guest_us_samples;
+		/*
+		 * TODO: we don't process guest user from host side
+		 * except simple counting.
+		 */
+		goto next_event;
+	default:
+		if (event->header.type == PERF_RECORD_SAMPLE)
+			goto next_event;
+		machine = &session->machines.host;
+		break;
+	}
+
+	if (event->header.type == PERF_RECORD_SAMPLE) {
+		perf_event__process_sample(&top->tool, event, evsel,
+					   &sample, machine);
+	} else if (event->header.type == PERF_RECORD_LOST) {
+		perf_top__process_lost(top, event, evsel);
+	} else if (event->header.type == PERF_RECORD_LOST_SAMPLES) {
+		perf_top__process_lost_samples(top, event, evsel);
+	} else if (event->header.type < PERF_RECORD_MAX) {
+		hists__inc_nr_events(evsel__hists(evsel), event->header.type);
+		machine__process_event(machine, event, &sample);
+	} else
+		++session->evlist->stats.nr_unknown_events;
+
+	ret = 0;
+next_event:
+	return ret;
+}
+
+static void init_process_thread(struct perf_top *top)
+{
+	ordered_events__init(&top->qe.data[0], deliver_event, top);
+	ordered_events__init(&top->qe.data[1], deliver_event, top);
+	ordered_events__set_copy_on_queue(&top->qe.data[0], true);
+	ordered_events__set_copy_on_queue(&top->qe.data[1], true);
+	top->qe.in = &top->qe.data[0];
+	pthread_mutex_init(&top->qe.lock, NULL);
+}
+
 static int __cmd_top(struct perf_top *top)
 {
 	char msg[512];

@@ -1091,7 +1161,7 @@ static int __cmd_top(struct perf_top *top)
 	struct perf_evsel_config_term *err_term;
 	struct perf_evlist *evlist = top->evlist;
 	struct record_opts *opts = &top->record_opts;
-	pthread_t thread;
+	pthread_t thread, thread_process;
 	int ret;
 
 	top->session = perf_session__new(NULL, false, NULL);

@@ -1115,6 +1185,8 @@ static int __cmd_top(struct perf_top *top)
 	if (top->nr_threads_synthesize > 1)
 		perf_set_multithreaded();
 
+	init_process_thread(top);
+
 	machine__synthesize_threads(&top->session->machines.host, &opts->target,
 				    top->evlist->threads, false,
 				    opts->proc_map_timeout,

@@ -1156,10 +1228,15 @@ static int __cmd_top(struct perf_top *top)
                 perf_evlist__enable(top->evlist);
 
 	ret = -1;
+	if (pthread_create(&thread_process, NULL, process_thread, top)) {
+		ui__error("Could not create process thread.\n");
+		goto out_delete;
+	}
+
 	if (pthread_create(&thread, NULL, (use_browser > 0 ? display_thread_tui :
 							    display_thread), top)) {
 		ui__error("Could not create display thread.\n");
-		goto out_delete;
+		goto out_join_thread;
 	}
 
 	if (top->realtime_prio) {

@@ -1194,6 +1271,8 @@ static int __cmd_top(struct perf_top *top)
 	ret = 0;
 out_join:
 	pthread_join(thread, NULL);
+out_join_thread:
+	pthread_join(thread_process, NULL);
 out_delete:
 	perf_session__delete(top->session);
 	top->session = NULL;

@@ -1286,6 +1365,7 @@ int cmd_top(int argc, const char **argv)
 			 * stays in overwrite mode. -acme
 			 * */
 			.overwrite	= 0,
+			.sample_time	= true,
 		},
 		.max_stack	     = sysctl__max_stack(),
 		.annotation_opts     = annotation__default_options,

tools/perf/util/ordered-events.c +3 -1

index d053aa0a7582..c5412db05683 100644
@@ -279,8 +279,10 @@ int ordered_events__flush(struct ordered_events *oe, enum oe_flush how)
 
 	switch (how) {
 	case OE_FLUSH__FINAL:
-		oe->next_flush = ULLONG_MAX;
 		show_progress = true;
+		__fallthrough;
+	case OE_FLUSH__TOP:
+		oe->next_flush = ULLONG_MAX;
 		break;
 
 	case OE_FLUSH__HALF:

tools/perf/util/ordered-events.h +1 -0

index 507b4e4df79e..0c6e26aec0e3 100644
@@ -18,6 +18,7 @@ enum oe_flush {
 	OE_FLUSH__FINAL,
 	OE_FLUSH__ROUND,
 	OE_FLUSH__HALF,
+	OE_FLUSH__TOP,
 };
 
 struct ordered_events;

tools/perf/util/top.h +6 -0

index 1fbcbd79720a..5f503293cfd8 100644
@@ -40,6 +40,12 @@ struct perf_top {
 	const char	   *sym_filter;
 	float		   min_percent;
 	unsigned int	   nr_threads_synthesize;
+
+	struct {
+		struct ordered_events	*in;
+		struct ordered_events	 data[2];
+		pthread_mutex_t		 lock;
+	} qe;
 };
 
 #define CONSOLE_CLEAR "[H[2J"

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #13 lore raw

PATCH 7/12 perf top: Use cond variable instead of the lock

In reply to Jiri Olsa

Using conditional variable logic to synchronize between reading and processing threads. Currently it's done by having mutex around rotation code.

Using posix cond variable to sync both threads after queues rotation:

process thread:
- detects data
- switches queues
- set rotate variable
- waits in pthread_cond_wait

read thread:
- detects rotate is set
- kicks process thread with pthread_cond_signal

After this rotation is safely completed and both threads can continue with the new queue.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c | 24 +++++++++++++++++-------
 tools/perf/util/top.h    |  4 +++-
 2 files changed, 20 insertions(+), 8 deletions(-)

tools/perf/builtin-top.c +17 -7

index f8dcdf0f54e1..ca2a1557ac07 100644
@@ -846,13 +846,18 @@ static void perf_top__mmap_read_idx(struct perf_top *top, int idx)
 		if (ret && ret != -1)
 			break;
 
-		pthread_mutex_lock(&top->qe.lock);
 		ret = ordered_events__queue(top->qe.in, event, timestamp, 0);
-		pthread_mutex_unlock(&top->qe.lock);
-
-		perf_mmap__consume(md);
 		if (ret)
 			break;
+
+		perf_mmap__consume(md);
+
+		if (top->qe.rotate) {
+			pthread_mutex_lock(&top->qe.mutex);
+			top->qe.rotate = false;
+			pthread_cond_signal(&top->qe.cond);
+			pthread_mutex_unlock(&top->qe.mutex);
+		}
 	}
 
 	perf_mmap__read_done(md);

@@ -1059,9 +1064,12 @@ static void *process_thread(void *arg)
 			continue;
 		}
 
-		pthread_mutex_lock(&top->qe.lock);
 		out = rotate_queues(top);
-		pthread_mutex_unlock(&top->qe.lock);
+
+		pthread_mutex_lock(&top->qe.mutex);
+		top->qe.rotate = true;
+		pthread_cond_wait(&top->qe.cond, &top->qe.mutex);
+		pthread_mutex_unlock(&top->qe.mutex);
 
 		if (ordered_events__flush(out, OE_FLUSH__TOP))
 			pr_err("failed to process events\n");

@@ -1151,7 +1159,8 @@ static void init_process_thread(struct perf_top *top)
 	ordered_events__set_copy_on_queue(&top->qe.data[0], true);
 	ordered_events__set_copy_on_queue(&top->qe.data[1], true);
 	top->qe.in = &top->qe.data[0];
-	pthread_mutex_init(&top->qe.lock, NULL);
+	pthread_mutex_init(&top->qe.mutex, NULL);
+	pthread_cond_init(&top->qe.cond, NULL);
 }
 
 static int __cmd_top(struct perf_top *top)

@@ -1272,6 +1281,7 @@ static int __cmd_top(struct perf_top *top)
 out_join:
 	pthread_join(thread, NULL);
 out_join_thread:
+	pthread_cond_signal(&top->qe.cond);
 	pthread_join(thread_process, NULL);
 out_delete:
 	perf_session__delete(top->session);

tools/perf/util/top.h +3 -1

index 5f503293cfd8..5bce62ebcf14 100644
@@ -44,7 +44,9 @@ struct perf_top {
 	struct {
 		struct ordered_events	*in;
 		struct ordered_events	 data[2];
-		pthread_mutex_t		 lock;
+		bool			 rotate;
+		pthread_mutex_t		 mutex;
+		pthread_cond_t		 cond;
 	} qe;
 };

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #14 lore raw

PATCH 8/12 perf top: Set session_done when exiting

In reply to Jiri Olsa

So we can get out of hist processing ASAP on user request.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c | 12 +++++++++---
 1 file changed, 9 insertions(+), 3 deletions(-)

tools/perf/builtin-top.c +9 -3

index ca2a1557ac07..ce542cc1e84f 100644
@@ -577,6 +577,12 @@ static void perf_top__sort_new_samples(void *arg)
 	perf_top__reset_sample_counters(t);
 }
 
+static void stop_top(void)
+{
+	session_done = 1;
+	done = 1;
+}
+
 static void *display_thread_tui(void *arg)
 {
 	struct perf_evsel *pos;

@@ -613,13 +619,13 @@ static void *display_thread_tui(void *arg)
 				      !top->record_opts.overwrite,
 				      &top->annotation_opts);
 
-	done = 1;
+	stop_top();
 	return NULL;
 }
 
 static void display_sig(int sig __maybe_unused)
 {
-	done = 1;
+	stop_top();
 }
 
 static void display_setup_sig(void)

@@ -672,7 +678,7 @@ static void *display_thread(void *arg)
 
 			if (perf_top__handle_keypress(top, c))
 				goto repeat;
-			done = 1;
+			stop_top();
 		}
 	}

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #15 lore raw

PATCH 9/12 perf top: Drop samples which are behind more than refresh rate

In reply to Jiri Olsa

Dropping samples from processing thread if they get behind the latest event read from kernel maps. If it gets behind more than the refresh rate (-d option), dropping the sample.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c | 25 ++++++++++++++++++++++---
 1 file changed, 22 insertions(+), 3 deletions(-)

tools/perf/builtin-top.c +22 -3

index ce542cc1e84f..a509d8c0a846 100644
@@ -833,6 +833,8 @@ perf_top__process_lost_samples(struct perf_top *top,
 	hists->stats.total_lost_samples += event->lost_samples.lost;
 }
 
+static u64 last_timestamp;
+
 static void perf_top__mmap_read_idx(struct perf_top *top, int idx)
 {
 	struct record_opts *opts = &top->record_opts;

@@ -845,14 +847,13 @@ static void perf_top__mmap_read_idx(struct perf_top *top, int idx)
 		return;
 
 	while ((event = perf_mmap__read_event(md)) != NULL) {
-		u64 timestamp = -1ULL;
 		int ret;
 
-		ret = perf_evlist__parse_sample_timestamp(evlist, event, &timestamp);
+		ret = perf_evlist__parse_sample_timestamp(evlist, event, &last_timestamp);
 		if (ret && ret != -1)
 			break;
 
-		ret = ordered_events__queue(top->qe.in, event, timestamp, 0);
+		ret = ordered_events__queue(top->qe.in, event, last_timestamp, 0);
 		if (ret)
 			break;

@@ -1084,6 +1085,21 @@ static void *process_thread(void *arg)
 	return NULL;
 }
 
+/*
+ * Allow only 'top->delay_secs' seconds behind samples.
+ */
+static int should_drop(struct ordered_event *qevent, struct perf_top *top)
+{
+	union perf_event *event = qevent->event;
+	u64 delay_timestamp;
+
+	if (event->header.type != PERF_RECORD_SAMPLE)
+		return false;
+
+	delay_timestamp = qevent->timestamp + top->delay_secs * NSEC_PER_SEC;
+	return delay_timestamp < last_timestamp;
+}
+
 static int deliver_event(struct ordered_events *qe,
 			 struct ordered_event *qevent)
 {

@@ -1096,6 +1112,9 @@ static int deliver_event(struct ordered_events *qe,
 	struct machine *machine;
 	int ret = -1;
 
+	if (should_drop(qevent, top))
+		return 0;
+
 	ret = perf_evlist__parse_sample(evlist, event, &sample);
 	if (ret) {
 		pr_err("Can't parse sample, err = %d\n", ret);

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #16 lore raw

PATCH 10/12 perf top: Save and display the drop count stats

In reply to Jiri Olsa

Adding drop count to perf top headers:

  # perf top --stdio
   PerfTop:    3549 irqs/sec  kernel:51.8%  exact: 100.0% lost: 0/0 drop: 0/0 [4000Hz cycles:ppp],  (all, 8 CPUs)

  # perf top
  Samples: 0  of event 'cycles:ppp', 4000 Hz, Event count (approx.): 0 lost: 0/0 drop: 0/0

The format is: <current period drop>/<total drop>

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c       | 5 ++++-
 tools/perf/ui/browsers/hists.c | 4 ++++
 tools/perf/util/top.c          | 7 ++++---
 tools/perf/util/top.h          | 2 +-
 4 files changed, 13 insertions(+), 5 deletions(-)

tools/perf/builtin-top.c +4 -1

index a509d8c0a846..7c60bd4419be 100644
@@ -1112,8 +1112,11 @@ static int deliver_event(struct ordered_events *qe,
 	struct machine *machine;
 	int ret = -1;
 
-	if (should_drop(qevent, top))
+	if (should_drop(qevent, top)) {
+		top->drop++;
+		top->drop_total++;
 		return 0;
+	}
 
 	ret = perf_evlist__parse_sample(evlist, event, &sample);
 	if (ret) {

tools/perf/ui/browsers/hists.c +4 -0

index ae208c16c8a3..36b262c49f51 100644
@@ -2223,6 +2223,10 @@ static int hists_browser__scnprintf_title(struct hist_browser *browser, char *bf
 				     " lost: %" PRIu64 "/%" PRIu64,
 				     top->lost, top->lost_total);
 
+		printed += scnprintf(bf + printed, size - printed,
+				     " drop: %" PRIu64 "/%" PRIu64,
+				     top->drop, top->drop_total);
+
 		if (top->zero)
 			printed += scnprintf(bf + printed, size - printed, " [z]");
 	}

tools/perf/util/top.c +4 -3

index e6582fa6a4db..31a8dee9af69 100644
@@ -46,8 +46,9 @@ size_t perf_top__header_snprintf(struct perf_top *top, char *bf, size_t size)
 							samples_per_sec;
 		ret = SNPRINTF(bf, size,
 			       "   PerfTop:%8.0f irqs/sec  kernel:%4.1f%%"
-			       "  exact: %4.1f%% lost: %" PRIu64 "/%" PRIu64 " [", samples_per_sec,
-			       ksamples_percent, esamples_percent, top->lost, top->lost_total);
+			       "  exact: %4.1f%% lost: %" PRIu64 "/%" PRIu64 " drop: %" PRIu64 "/%" PRIu64 " [",
+			       samples_per_sec, ksamples_percent, esamples_percent,
+			       top->lost, top->lost_total, top->drop, top->drop_total);
 	} else {
 		float us_samples_per_sec = top->us_samples / top->delay_secs;
 		float guest_kernel_samples_per_sec = top->guest_kernel_samples / top->delay_secs;

@@ -113,5 +114,5 @@ void perf_top__reset_sample_counters(struct perf_top *top)
 {
 	top->samples = top->us_samples = top->kernel_samples =
 	top->exact_samples = top->guest_kernel_samples =
-	top->guest_us_samples = top->lost = 0;
+	top->guest_us_samples = top->lost = top->drop = 0;
 }

tools/perf/util/top.h +1 -1

index 5bce62ebcf14..19f95eaf75c8 100644
@@ -22,7 +22,7 @@ struct perf_top {
 	 * Symbols will be added here in perf_event__process_sample and will
 	 * get out after decayed.
 	 */
-	u64		   samples, lost, lost_total;
+	u64		   samples, lost, lost_total, drop, drop_total;
 	u64		   kernel_samples, us_samples;
 	u64		   exact_samples;
 	u64		   guest_us_samples, guest_kernel_samples;

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #17 lore raw

PATCH 11/12 perf top: Display slow reader warning for when droping samples

In reply to Jiri Olsa

Currently we display the "Too slow to read ring buffer.." helpline only for slow reader thread. This patch triggers it also when the processing thread drops samples, because it has the same reason, which is too many data on input.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

tools/perf/builtin-top.c +1 -1

index 7c60bd4419be..5d6e30f69d85 100644
@@ -571,7 +571,7 @@ static void perf_top__sort_new_samples(void *arg)
 	hists__collapse_resort(hists, NULL);
 	perf_evsel__output_resort(evsel, NULL);
 
-	if (t->lost)
+	if (t->lost || t->drop)
 		ui_helpline__fpush("Too slow to read ring buffer (change period (-c/-F) or limit CPUs (-C)\n");
 
 	perf_top__reset_sample_counters(t);

Signature · 1 line

2.17.2

Jiri Olsa

author reviewer

2018-11-19 12:20 UTC #18 lore raw

PATCH 12/12 perf top: Move perf_top__reset_sample_counters after counts display

In reply to Jiri Olsa

Move perf_top__reset_sample_counters call right after we display the counters so we can see the updated numbers longer.

Link http://lkml.kernel.org/n/[email protected] open here

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

---
 tools/perf/builtin-top.c       | 4 ----
 tools/perf/ui/browsers/hists.c | 3 +++
 tools/perf/util/top.c          | 1 +
 3 files changed, 4 insertions(+), 4 deletions(-)

tools/perf/builtin-top.c +0 -4

index 5d6e30f69d85..af4aaf8edb06 100644
@@ -273,8 +273,6 @@ static void perf_top__print_sym_table(struct perf_top *top)
 	perf_top__header_snprintf(top, bf, sizeof(bf));
 	printf("%s\n", bf);
 
-	perf_top__reset_sample_counters(top);
-
 	printf("%-*.*s\n", win_width, win_width, graph_dotted_line);
 
 	if (!top->record_opts.overwrite &&

@@ -573,8 +571,6 @@ static void perf_top__sort_new_samples(void *arg)
 
 	if (t->lost || t->drop)
 		ui_helpline__fpush("Too slow to read ring buffer (change period (-c/-F) or limit CPUs (-C)\n");
-
-	perf_top__reset_sample_counters(t);
 }
 
 static void stop_top(void)

tools/perf/ui/browsers/hists.c +3 -0

index 36b262c49f51..ffac1d54a3d4 100644
@@ -2229,8 +2229,11 @@ static int hists_browser__scnprintf_title(struct hist_browser *browser, char *bf
 
 		if (top->zero)
 			printed += scnprintf(bf + printed, size - printed, " [z]");
+
+		perf_top__reset_sample_counters(top);
 	}
 
+
 	return printed;
 }

tools/perf/util/top.c +1 -0

index 31a8dee9af69..4c8da8c4435f 100644
@@ -107,6 +107,7 @@ size_t perf_top__header_snprintf(struct perf_top *top, char *bf, size_t size)
 					top->evlist->cpus->nr > 1 ? "s" : "");
 	}
 
+	perf_top__reset_sample_counters(top);
 	return ret;
 }

Signature · 1 line

2.17.2

David Miller

Acked-by on the v1 series

2018-11-20 01:26 UTC #19 lore raw

In reply to Jiri Olsa

From: Jiri Olsa <[email protected]>
Date: Mon, 19 Nov 2018 13:20:04 +0100

Quoted 11 lines

David reported issues with perf top loosing side band events so we moved mmap reading and hists processing into separated threads.
This patchset also adds dropping sample logic when the processing falls behind the reader thread. This way we get incomplete but current data in perf top.
Also available in:
git://git.kernel.org/pub/scm/linux/kernel/git/jolsa/perf.git
perf/fixes

For series:

Acked-by David S. Miller <[email protected]>

With this plus my mmap by-hand parsing and mmap parsing timeout removal changes, we've made serious progress.

Thanks!

Namhyung Kim

maintainer Acked-by on the v1 series

2018-11-20 02:29 UTC #20 lore raw

In reply to Jiri Olsa

Hi Jirka,

Quoted 5 lines · Jiri Olsa

hi,
David reported issues with perf top loosing side band events so we moved mmap reading and hists processing into separated threads.

Quoted 7 lines

This patchset also adds dropping sample logic when the processing falls behind the reader thread. This way we get incomplete but current data in perf top.
Also available in:
git://git.kernel.org/pub/scm/linux/kernel/git/jolsa/perf.git
perf/fixes

Beside the simple comment in 05/12 (and the related fix), it looks good to me. And I think we can do similar for hists->lock as well.

Acked-by Namhyung Kim <[email protected]>

Thanks,
Namhyung