All of lore.kernel.org
 help / color / mirror / Atom feed
* [BUG] perf: perf sched warning possibly due to clock granularity on AMD
@ 2012-02-06 13:25 Stephane Eranian
  2012-02-06 14:26 ` Peter Zijlstra
                   ` (3 more replies)
  0 siblings, 4 replies; 34+ messages in thread
From: Stephane Eranian @ 2012-02-06 13:25 UTC (permalink / raw)
  To: linux-kernel; +Cc: acme, peterz, mingo, robert.richter, eric.dumazet

Hi,

I am running 3.3.30-rc2 on an AMD Bulldozer system in 64-bit mode.
I was testing perf sched and I ran into an issue. That issue seems
to exist only on AMD and not on Intel systems. It is not PMU related
because I am doing tracing.

I am running a simple ping pong test to stress the context switch
code. Two processes exchanging a byte through a pipe (program provided
below).

Then, I capture a trace using perf sched, and I run sched lat, but
on certain runs, I get:

   $ perf sched rec pong 2
   $ perf sched lat
     Warning: Timestamp below last timeslice flush
     Warning: Timestamp below last timeslice flush
     Warning: Timestamp below last timeslice flush
     Warning: Timestamp below last timeslice flush
     Warning: Timestamp below last timeslice flush
     Warning: Timestamp below last timeslice flush
     Warning: Timestamp below last timeslice flush
     Warning: Timestamp below last timeslice flush
     Warning: TimesFound 4934 unknown events!
     Is this an older tool processing a perf.data file generated by a more recent tool?

I did some investigation in the kernel to figure out what
could cause this problem. I found out that with this measurement, it is
possible to get multiple consecutive samples with the SAME timestamp.
That is possible on AMD because, apparently, local_clock() ends up calling,
a sched_clock() function that is only based on jiffies. That means, the
granularity is a tick (1ms in my case). On Intel systems, at least on mines,
local_clock() ends up calling a routine which uses TSC and thus has a much
greater precision. This is all decided by the sched_clock_stable variable. It
is set at init time for Intel and not used on AMD. Yet, recent AMD systems do
have support for NONSTOP_TSC. It is not clear to me why that would not be enough
(unless it is a cross-socket synchronization issue).

One thing is clear, is that if I enable sched_clock_stable on my AMD system, then
the perf sched warning disappears.

I believe there is really a bug in perf. I am sure there are systems out there
which cannot provide a very fine grain timestamp, thus it is possible to get samples
with identical timestamps. I don't quite understand the sample re-ordering code in
perf but it seems sensitive to timer granularity. I think it should not.

In summary, two issues:
  - Why is sched_clock_stable not set or even tested on recent AMD systems?
  - perf should not rely on fine granularity timestamps in the re-ordering code

Any comments?

#include <sys/types.h>
#include <inttypes.h>
#include <stdio.h>
#include <stdlib.h>
#include <stdarg.h>
#include <errno.h>
#include <unistd.h>
#include <string.h>
#include <signal.h>
#include <syscall.h>
#include <err.h>

#define MAX_CPUS	64
#define NR_CPU_BITS	(MAX_CPUS>>3)
int
pin_cpu(pid_t pid, unsigned int cpu)
{
	uint64_t my_mask[NR_CPU_BITS];

	if (cpu >= MAX_CPUS)
		errx(1, "this program supports only up to %d CPUs", MAX_CPUS);

	my_mask[cpu>>6] = 1ULL << (cpu&63);

	return syscall(__NR_sched_setaffinity, pid, sizeof(my_mask), &my_mask);
}

static volatile int quit;
void sig_handler(int n)
{
	quit = 1;
}

static void
do_child(int fr, int fw)
{
	char c;
	ssize_t ret;

	for(;;) {
		ret = read(fr, &c, 1);	
		if (ret < 0)
			break;
		ret = write(fw, "c", 1);
		if (ret < 0)
			break;
		
	}
	printf("child exited\n");
	exit(0);
}


int
main(int argc, char **argv)
{
	int ret;
	int pr[2], pw[2];
	int which_cpu;
	pid_t pid;
	uint64_t nctx = 0;
	ssize_t nbytes;
	char c = '0';
	int delay;

	delay = argc > 1 ? atoi(argv[1]) : 10;
	
	srandom(getpid());
	which_cpu = random() % sysconf(_SC_NPROCESSORS_ONLN);

	ret = pipe(pr);
	if (ret)
		err(1, "cannot create read pipe");

	ret = pipe(pw);
	if (ret)
		err(1, "cannot create write pipe");

	ret = pin_cpu(getpid(), which_cpu);
	if (ret)
		err(1, "cannot pin to CPU%d", which_cpu);

	printf("Both processes pinned to CPU%d, running for %ds\n", which_cpu, delay);

	switch(pid=fork()) {
		case -1:
			err(1, "cannot create child");
		case 0:
			close(pr[1]); close(pw[0]);
			do_child(pr[0], pw[1]);
			exit(1);
	}

	close(pr[0]);
	close(pw[1]);

	signal(SIGALRM, sig_handler);
	alarm(delay);

	while(!quit) {
		nbytes = write(pr[1], "c", 1);
		nbytes = read(pw[0], &c, 1);	
		nctx++;
	}
	close(pr[1]);
	close(pw[0]);
	return 0;
}

^ permalink raw reply	[flat|nested] 34+ messages in thread
* [PATCH] perf tools: Fix ordering with unstable tsc
@ 2012-10-05 15:22 David Ahern
  2012-10-06 15:17 ` David Ahern
  0 siblings, 1 reply; 34+ messages in thread
From: David Ahern @ 2012-10-05 15:22 UTC (permalink / raw)
  To: acme, linux-kernel
  Cc: David Ahern, Frederic Weisbecker, Peter Zijlstra,
	Stephane Eranian, Ingo Molnar, Arnaldo Carvalho de Melo

Rebased to acme's perf/core branch. Changed realloc to handle failure.
Remainder is based on what Frederic posted in February.

From: Frederic Weisbecker <fweisbec@gmail.com>

On a system with a TSC considered as unstable, one can encounter this
kind of warning:

     $ perf sched rec pong 2
     $ perf sched lat
     Warning: Timestamp below last timeslice flush

This happens when trace events trigger with a potentially high period,
such as sched_stat_sleep, sched_stat_runtime, sched_stat_wait, etc...
The perf event core then implement that weight by sending as many events
as the given period. For example as many as the time the task has been
sleeping in sched_stat_sleep event.

If this happens while irqs are disabled with an unstable tsc and this takes
more time than a jiffy, then the timestamps of the events get stuck to
the value of that next jiffy because sched_clock_local() bounds the timestamp
to that maximum. The local timer tick is supposed to update that boundary but
it can't given that irqs are disabled.

We can then meet this kind of scenario in perf record:

===== CPU 0 =====      ==== CPU 1 ====

              PASS n
     ...                    ...
      1                      1
      1                      2
      1                      3 <-- max recorded

           finished round event
            PASS n + 1

      1                      4
      1                      5
      1                      6

           finished round event
            PASS n + 2

      1                      7
     ...                    ...

CPU 0 is stuck sending events with irqs disabled and with the stale
timestamp. When we do the events reordering for perf script for example,
we flush all the events before timestamp 3 when we reach PASS n + 2,
considering we can't anymore have timestamps below 3 now.
But we still do have timestamps below 3 on PASS n + 2.

To solve that issue, instead of considering that timestamps are globally
monotonic, we assume they are locally monotonic. Instead of recording
the max timestamp on each pass, we check the max one per CPU on each
pass and keep the smallest over these as the new barrier up to which
we flush the events on the PASS n + 2. This still relies on a bit of
global monotonicity because if some CPU doesn't have events in PASS n,
we expect it not to have event in PASS n + 2 past the barrier recorded
in PASS n. So this is still not a totally robust ordering but it's still
better than what we had before.

The only way to have a deterministic and solid ordering will be to use
per cpu perf.data files.

Reported-by: Stephane Eranian <eranian@google.com>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Link: https://lkml.org/lkml/2012/2/18/53
---
 tools/perf/util/evsel.c   |    5 +-
 tools/perf/util/session.c |  161 +++++++++++++++++++++++++++++++++------------
 tools/perf/util/session.h |    3 +-
 3 files changed, 126 insertions(+), 43 deletions(-)

diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
index ffdd94e..b6ca970 100644
--- a/tools/perf/util/evsel.c
+++ b/tools/perf/util/evsel.c
@@ -471,9 +471,12 @@ void perf_evsel__config(struct perf_evsel *evsel, struct perf_record_opts *opts,
 	if (opts->raw_samples) {
 		attr->sample_type	|= PERF_SAMPLE_TIME;
 		attr->sample_type	|= PERF_SAMPLE_RAW;
-		attr->sample_type	|= PERF_SAMPLE_CPU;
 	}
 
+	/* Need to know the CPU for tools that need to order events */
+	if (attr->sample_type & PERF_SAMPLE_TIME)
+		attr->sample_type	|= PERF_SAMPLE_CPU;
+
 	if (opts->no_delay) {
 		attr->watermark = 0;
 		attr->wakeup_events = 1;
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 8cdd232..7df586b 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -695,6 +695,8 @@ static void perf_session_free_sample_buffers(struct perf_session *session)
 		list_del(&sq->list);
 		free(sq);
 	}
+
+	free(os->last_cpu_timestamp);
 }
 
 static int perf_session_deliver_event(struct perf_session *session,
@@ -755,57 +757,91 @@ static int flush_sample_queue(struct perf_session *s,
 }
 
 /*
- * When perf record finishes a pass on every buffers, it records this pseudo
- * event.
- * We record the max timestamp t found in the pass n.
- * Assuming these timestamps are monotonic across cpus, we know that if
- * a buffer still has events with timestamps below t, they will be all
- * available and then read in the pass n + 1.
- * Hence when we start to read the pass n + 2, we can safely flush every
- * events with timestamps below t.
+ * We make the assumption that timestamps are not globally monotonic but locally
+ * non-strictly monotonic. In practice, this is because if we are dealing with a
+ * machine with unstable TSC, the kernel bounds the result of the tsc between
+ * last_tick_time < tsc < next_tick_time. Thus, if a CPU disables interrupts for more
+ * than one jiffy, all of its timestamps will be equal to next_tick_time after we
+ * cross that jiffy, without any further progress whereas the other CPU continue
+ * with normal timestamps. This can happen if a CPU sends crazillions of events
+ * while interrupts are disabled. But there are potentially other random scenarios
+ * with unstable TSC that drives us to assume the monotonicity of time only per CPU
+ * and not globally.
+ *
+ * To solve this, when perf record finishes a round of write on every buffers, it
+ * records a pseudo event named "finished round". The frame of events that happen
+ * between two finished rounds is called a "pass".
+ * We record the max timestamp T[cpu] per CPU found over the events in the pass n.
+ * Then when we finish a round, we iterate over these T[cpu]and keep the smallest
+ * one: min(T).
+ *
+ * Assuming these timestamps are locally monotonic (non strictly), we can flush all
+ * queued events having a timestamp below min(T) when we start to process PASS n + 1.
+ * But we actually wait until we start PASS n + 2 in case a CPU did not have any
+ * event in PASS n but came in PASS n + 1 with events below min(T). We truly
+ * hope no CPU will come with events below min(T) after pass n + 1. This
+ * heuristicly rely on some minimal global consistancy. This should work in most
+ * real world case, the only way to ensure a truly safe ordering with regular
+ * flush will be to switch to per CPU record files.
  *
- *    ============ PASS n =================
- *       CPU 0         |   CPU 1
- *                     |
- *    cnt1 timestamps  |   cnt2 timestamps
- *          1          |         2
- *          2          |         3
- *          -          |         4  <--- max recorded
+ *    ========================== PASS n ============================
+ *       CPU 0                   |   CPU 1
+ *                               |
+ *    cnt1 timestamps            |   cnt2 timestamps
+ *          1                    |         2
+ *          2 <--- max recorded  |         3
+ *          -                    |         4 <--- max recorded
+ *                          min(T) = 2
  *
- *    ============ PASS n + 1 ==============
- *       CPU 0         |   CPU 1
- *                     |
- *    cnt1 timestamps  |   cnt2 timestamps
- *          3          |         5
- *          4          |         6
- *          5          |         7 <---- max recorded
+ *    ========================== PASS n + 1 ========================
+ *       CPU 0                   |   CPU 1
+ *                               |
+ *    cnt1 timestamps            |   cnt2 timestamps
+ *          3                    |         5
+ *          4                    |         6
+ *          5 <--- max record    |         7 <---- max recorded
+ *                          min(T) = 5
  *
- *      Flush every events below timestamp 4
+ *                Flush every events below timestamp 2
  *
- *    ============ PASS n + 2 ==============
- *       CPU 0         |   CPU 1
- *                     |
- *    cnt1 timestamps  |   cnt2 timestamps
- *          6          |         8
- *          7          |         9
- *          -          |         10
+ *    ========================== PASS n + 2 ========================
+ *       CPU 0                   |   CPU 1
+ *                               |
+ *    cnt1 timestamps            |   cnt2 timestamps
+ *          6                    |         8
+ *          7                    |         9
+ *          -                    |         10
  *
- *      Flush every events below timestamp 7
- *      etc...
+ *  Flush every events below timestamp 5, etc...
  */
+
 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);
-	if (!ret)
-		session->ordered_samples.next_flush = session->ordered_samples.max_timestamp;
+	unsigned int i, ret;
+	u64 min = ULLONG_MAX;
+	struct ordered_samples *os = &session->ordered_samples;
+
+	ret = flush_sample_queue(session, tool);
+
+	for (i = 0; i < session->nr_cpus; i++) {
+		if (os->last_cpu_timestamp[i] < min)
+			min = os->last_cpu_timestamp[i];
+
+		os->last_cpu_timestamp[i] = ULLONG_MAX;
+	}
+
+	if (min != ULLONG_MAX)
+		os->next_flush = min;
 
 	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 sample_queue *new,
+			  struct perf_session *s,
+			  int cpu)
 {
 	struct ordered_samples *os = &s->ordered_samples;
 	struct sample_queue *sample = os->last_sample;
@@ -814,10 +850,10 @@ static void __queue_event(struct sample_queue *new, struct perf_session *s)
 
 	++os->nr_samples;
 	os->last_sample = new;
+	os->last_cpu_timestamp[cpu] = timestamp;
 
 	if (!sample) {
 		list_add(&new->list, &os->samples);
-		os->max_timestamp = timestamp;
 		return;
 	}
 
@@ -831,7 +867,6 @@ static void __queue_event(struct sample_queue *new, struct perf_session *s)
 			p = sample->list.next;
 			if (p == &os->samples) {
 				list_add_tail(&new->list, &os->samples);
-				os->max_timestamp = timestamp;
 				return;
 			}
 			sample = list_entry(p, struct sample_queue, list);
@@ -850,7 +885,39 @@ static void __queue_event(struct sample_queue *new, struct perf_session *s)
 	}
 }
 
-#define MAX_SAMPLE_BUFFER	(64 * 1024 / sizeof(struct sample_queue))
+static int alloc_cpus_timestamp_array(struct perf_session *s,
+				      struct perf_sample *sample,
+				      struct ordered_samples *os)
+{
+	int i;
+	int nr_cpus;
+	void *last;
+
+	if (sample->cpu < s->nr_cpus)
+		return 0;
+
+	nr_cpus = sample->cpu + 1;
+
+	if (!os->last_cpu_timestamp) {
+		last = os->last_cpu_timestamp;
+		os->last_cpu_timestamp = realloc(os->last_cpu_timestamp,
+						 sizeof(u64) * nr_cpus);
+	}
+	if (!os->last_cpu_timestamp) {
+		if (last)
+			free(last);
+		return -ENOMEM;
+	}
+
+	for (i = s->nr_cpus; i < nr_cpus; i++)
+		os->last_cpu_timestamp[i] = ULLONG_MAX;
+
+	s->nr_cpus = nr_cpus;
+
+	return 0;
+}
+
+#define MAX_SAMPLE_BUFFER	(1024 * 1024 / sizeof(struct sample_queue))
 
 static int perf_session_queue_event(struct perf_session *s, union perf_event *event,
 				    struct perf_sample *sample, u64 file_offset)
@@ -859,6 +926,12 @@ static int perf_session_queue_event(struct perf_session *s, union perf_event *ev
 	struct list_head *sc = &os->sample_cache;
 	u64 timestamp = sample->time;
 	struct sample_queue *new;
+	int err;
+
+	if (!(perf_evlist__sample_type(s->evlist) & PERF_SAMPLE_CPU)) {
+		pr_err("Warning: Need to record CPU on samples for ordering\n");
+		return -EINVAL;
+	}
 
 	if (!timestamp || timestamp == ~0ULL)
 		return -ETIME;
@@ -868,13 +941,19 @@ static int perf_session_queue_event(struct perf_session *s, union perf_event *ev
 		return -EINVAL;
 	}
 
+	err = alloc_cpus_timestamp_array(s, sample, os);
+	if (err)
+		return err;
+
 	if (!list_empty(sc)) {
 		new = list_entry(sc->next, struct sample_queue, 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)
+		if (++os->sample_buffer_idx == MAX_SAMPLE_BUFFER) {
+			pr_debug("sample buffer index hit maximum\n");
 			os->sample_buffer = NULL;
+		}
 	} else {
 		os->sample_buffer = malloc(MAX_SAMPLE_BUFFER * sizeof(*new));
 		if (!os->sample_buffer)
@@ -888,7 +967,7 @@ static int perf_session_queue_event(struct perf_session *s, union perf_event *ev
 	new->file_offset = file_offset;
 	new->event = event;
 
-	__queue_event(new, s);
+	__queue_event(new, s, sample->cpu);
 
 	return 0;
 }
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index aab414f..13cc305 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -16,7 +16,7 @@ struct thread;
 struct ordered_samples {
 	u64			last_flush;
 	u64			next_flush;
-	u64			max_timestamp;
+	u64			*last_cpu_timestamp;
 	struct list_head	samples;
 	struct list_head	sample_cache;
 	struct list_head	to_free;
@@ -45,6 +45,7 @@ struct perf_session {
 	int			cwdlen;
 	char			*cwd;
 	struct ordered_samples	ordered_samples;
+	unsigned int		nr_cpus;
 	char			filename[1];
 };
 
-- 
1.7.10.1


^ permalink raw reply related	[flat|nested] 34+ messages in thread

end of thread, other threads:[~2012-10-06 15:37 UTC | newest]

Thread overview: 34+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2012-02-06 13:25 [BUG] perf: perf sched warning possibly due to clock granularity on AMD Stephane Eranian
2012-02-06 14:26 ` Peter Zijlstra
2012-02-06 14:31   ` Stephane Eranian
2012-02-06 17:17     ` Arnaldo Carvalho de Melo
2012-02-06 15:34   ` Borislav Petkov
2012-02-06 16:37     ` Peter Zijlstra
2012-02-06 16:46       ` Borislav Petkov
2012-02-06 16:54         ` Peter Zijlstra
2012-02-06 20:27           ` Borislav Petkov
2012-02-06 20:31             ` Peter Zijlstra
2012-02-06 20:37               ` Borislav Petkov
2012-02-06 21:19                 ` Venki Pallipadi
2012-02-07  7:51                   ` Peter Zijlstra
2012-02-07  8:32                   ` Ingo Molnar
2012-02-07  9:06                     ` Borislav Petkov
2012-02-07  9:50                       ` Ingo Molnar
2012-02-07 12:08                         ` [PATCH] x86, AMD: Set sched_clock_stable Borislav Petkov
2012-02-15 15:30                           ` Peter Zijlstra
2012-02-07 19:43 ` [tip:perf/core] x86/sched/perf/AMD: " tip-bot for Borislav Petkov
2012-02-08 15:07 ` [BUG] perf: perf sched warning possibly due to clock granularity on AMD Frederic Weisbecker
2012-02-08 15:10   ` Stephane Eranian
2012-02-08 15:22     ` Frederic Weisbecker
2012-02-08 15:23       ` Stephane Eranian
2012-02-18 16:50 ` [PATCH] perf tools: Fix ordering with unstable tsc Frederic Weisbecker
2012-02-22 15:35   ` Stephane Eranian
2012-02-22 15:39     ` David Ahern
2012-03-05 18:43   ` Frederic Weisbecker
2012-03-14 19:55   ` Arnaldo Carvalho de Melo
2012-03-14 20:07     ` David Ahern
2012-03-22  0:10     ` Frederic Weisbecker
2012-03-22 15:28       ` Arnaldo Carvalho de Melo
2012-10-05 15:22 David Ahern
2012-10-06 15:17 ` David Ahern
2012-10-06 15:33   ` Arnaldo Carvalho de Melo

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.