All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH] perf: fix interrupt handler timing harness
@ 2013-07-04 22:30 Stephane Eranian
  2013-07-05  6:54 ` Ingo Molnar
                   ` (2 more replies)
  0 siblings, 3 replies; 10+ messages in thread
From: Stephane Eranian @ 2013-07-04 22:30 UTC (permalink / raw)
  To: linux-kernel; +Cc: peterz, mingo, dave.hansen, ak, jolsa


This patch fixes a serious bug in:

commit 14c63f17b1fde5a575a28e96547a22b451c71fb5
Author: Dave Hansen <dave.hansen@linux.intel.com>
Date:   Fri Jun 21 08:51:36 2013 -0700

    perf: Drop sample rate when sampling is too slow
    

There was an misunderstanding on the API of the do_div()
macro. It returns the remainder of the division and this
was not what the function expected leading to disabling the
interrupt latency watchdog.

This patch also remove a duplicate assignment in
perf_sample_event_took().

Signed-off-by: Stephane Eranian <eranian@google.com>
---

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 1db3af9..1833bc5 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -182,7 +182,7 @@ void update_perf_cpu_limits(void)
 	u64 tmp = perf_sample_period_ns;
 
 	tmp *= sysctl_perf_cpu_time_max_percent;
-	tmp = do_div(tmp, 100);
+	do_div(tmp, 100);
 	atomic_set(&perf_sample_allowed_ns, tmp);
 }
 
@@ -232,7 +232,7 @@ DEFINE_PER_CPU(u64, running_sample_length);
 void perf_sample_event_took(u64 sample_len_ns)
 {
 	u64 avg_local_sample_len;
-	u64 local_samples_len = __get_cpu_var(running_sample_length);
+	u64 local_samples_len;
 
 	if (atomic_read(&perf_sample_allowed_ns) == 0)
 		return;

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

* Re: [PATCH] perf: fix interrupt handler timing harness
  2013-07-04 22:30 [PATCH] perf: fix interrupt handler timing harness Stephane Eranian
@ 2013-07-05  6:54 ` Ingo Molnar
  2013-07-05  9:54 ` [tip:perf/urgent] perf: Fix " tip-bot for Stephane Eranian
  2013-07-08 14:34 ` [PATCH] perf: fix " Dave Hansen
  2 siblings, 0 replies; 10+ messages in thread
From: Ingo Molnar @ 2013-07-05  6:54 UTC (permalink / raw)
  To: Stephane Eranian; +Cc: linux-kernel, peterz, mingo, dave.hansen, ak, jolsa


* Stephane Eranian <eranian@google.com> wrote:

> This patch fixes a serious bug in:
> 
> commit 14c63f17b1fde5a575a28e96547a22b451c71fb5
> Author: Dave Hansen <dave.hansen@linux.intel.com>
> Date:   Fri Jun 21 08:51:36 2013 -0700
> 
>     perf: Drop sample rate when sampling is too slow
>     
> 
> There was an misunderstanding on the API of the do_div()
> macro. It returns the remainder of the division and this
> was not what the function expected leading to disabling the
> interrupt latency watchdog.
> 
> This patch also remove a duplicate assignment in
> perf_sample_event_took().
> 
> Signed-off-by: Stephane Eranian <eranian@google.com>

Thanks Stephane - I've applied this to perf/urgent and will get it to 
Linus ASAP.

	Ingo

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

* [tip:perf/urgent] perf: Fix interrupt handler timing harness
  2013-07-04 22:30 [PATCH] perf: fix interrupt handler timing harness Stephane Eranian
  2013-07-05  6:54 ` Ingo Molnar
@ 2013-07-05  9:54 ` tip-bot for Stephane Eranian
  2013-07-08 14:34 ` [PATCH] perf: fix " Dave Hansen
  2 siblings, 0 replies; 10+ messages in thread
From: tip-bot for Stephane Eranian @ 2013-07-05  9:54 UTC (permalink / raw)
  To: linux-tip-commits; +Cc: linux-kernel, eranian, hpa, mingo, tglx

Commit-ID:  e5302920da9ef23f9d19d4e9ac85704cc25bee7a
Gitweb:     http://git.kernel.org/tip/e5302920da9ef23f9d19d4e9ac85704cc25bee7a
Author:     Stephane Eranian <eranian@google.com>
AuthorDate: Fri, 5 Jul 2013 00:30:11 +0200
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Fri, 5 Jul 2013 08:54:43 +0200

perf: Fix interrupt handler timing harness

This patch fixes a serious bug in:

  14c63f17b1fd perf: Drop sample rate when sampling is too slow

There was an misunderstanding on the API of the do_div()
macro. It returns the remainder of the division and this
was not what the function expected leading to disabling the
interrupt latency watchdog.

This patch also remove a duplicate assignment in
perf_sample_event_took().

Signed-off-by: Stephane Eranian <eranian@google.com>
Cc: peterz@infradead.org
Cc: dave.hansen@linux.intel.com
Cc: ak@linux.intel.com
Cc: jolsa@redhat.com
Link: http://lkml.kernel.org/r/20130704223010.GA30625@quad
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 kernel/events/core.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 1db3af9..1833bc5 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -182,7 +182,7 @@ void update_perf_cpu_limits(void)
 	u64 tmp = perf_sample_period_ns;
 
 	tmp *= sysctl_perf_cpu_time_max_percent;
-	tmp = do_div(tmp, 100);
+	do_div(tmp, 100);
 	atomic_set(&perf_sample_allowed_ns, tmp);
 }
 
@@ -232,7 +232,7 @@ DEFINE_PER_CPU(u64, running_sample_length);
 void perf_sample_event_took(u64 sample_len_ns)
 {
 	u64 avg_local_sample_len;
-	u64 local_samples_len = __get_cpu_var(running_sample_length);
+	u64 local_samples_len;
 
 	if (atomic_read(&perf_sample_allowed_ns) == 0)
 		return;

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

* Re: [PATCH] perf: fix interrupt handler timing harness
  2013-07-04 22:30 [PATCH] perf: fix interrupt handler timing harness Stephane Eranian
  2013-07-05  6:54 ` Ingo Molnar
  2013-07-05  9:54 ` [tip:perf/urgent] perf: Fix " tip-bot for Stephane Eranian
@ 2013-07-08 14:34 ` Dave Hansen
  2013-07-08 18:08   ` Stephane Eranian
  2 siblings, 1 reply; 10+ messages in thread
From: Dave Hansen @ 2013-07-08 14:34 UTC (permalink / raw)
  To: Stephane Eranian; +Cc: linux-kernel, peterz, mingo, dave.hansen, ak, jolsa

On 07/04/2013 03:30 PM, Stephane Eranian wrote:
> There was an misunderstanding on the API of the do_div()
> macro. It returns the remainder of the division and this
> was not what the function expected leading to disabling the
> interrupt latency watchdog.

"Misunderstanding" is a very kind term for what I did there.  Stephane,
were you actually running in to the new cpu limit, or were you just
trying to update kernel.perf_event_max_sample_rate?

BTW, I also did the same thing in 2ab00456:

https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=2ab00456ea8a0d79acb1390659b98416111880b2

I'll have a patch out shortly for that one, but its damage would be
limited to a bogus printk.

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

* Re: [PATCH] perf: fix interrupt handler timing harness
  2013-07-08 14:34 ` [PATCH] perf: fix " Dave Hansen
@ 2013-07-08 18:08   ` Stephane Eranian
  2013-07-08 20:05     ` Dave Hansen
  0 siblings, 1 reply; 10+ messages in thread
From: Stephane Eranian @ 2013-07-08 18:08 UTC (permalink / raw)
  To: Dave Hansen; +Cc: LKML, Peter Zijlstra, mingo, dave.hansen, ak, Jiri Olsa

On Mon, Jul 8, 2013 at 4:34 PM, Dave Hansen <dave.hansen@intel.com> wrote:
> On 07/04/2013 03:30 PM, Stephane Eranian wrote:
>> There was an misunderstanding on the API of the do_div()
>> macro. It returns the remainder of the division and this
>> was not what the function expected leading to disabling the
>> interrupt latency watchdog.
>
> "Misunderstanding" is a very kind term for what I did there.  Stephane,
> were you actually running in to the new cpu limit, or were you just
> trying to update kernel.perf_event_max_sample_rate?
>
I am chasing a problem on HSW desktop where your code triggers the throttling.
It happens systematically on my system first time I run perf record usually the
first time.

I admit I have some issues with your patch and what it is trying to avoid.
There is already interrupt throttling. Your code seems to address latency
issues on the handler rather than rate issues. Yet to mitigate the latency
it is modify the throttling.

For some unknown reasons, my HSW interrupt handler goes crazy for
a while running a very simple:
   $ perf record -e cycles branchy_loop

And I do see in the log:
perf samples too long (2546 > 2500), lowering
kernel.perf_event_max_sample_rate to 50000

Which is an enormous latency. I instrumented the code, and under
normal conditions the latency
of the handler for this perf run, is about 500ns and it is consistent
with what I see on SNB.
However, on HSW, it is sometimes 5x longer. I have no explanation for
this. Andi's patch
to delay the NMI ack is enabled but it does not alleviate this
problem. There is something
else going on possibly with the HW, and I don't know what it is. This
is not a one off. It lasts for
several calls because it fires your watchdog which averages out over
multiple calls.
So one cannot blame this on the case where the samping buffer gets
full, for instance.

My model is:
processor : 6
vendor_id : GenuineIntel
cpu family : 6
model : 60
model name : Intel(R) Core(TM) i7-4770 CPU @ 3.40GHz
stepping : 3
microcode : 0x7

So something is not right and I would like to know what it is.
I will keep investigating.

> BTW, I also did the same thing in 2ab00456:
>
> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=2ab00456ea8a0d79acb1390659b98416111880b2
>
> I'll have a patch out shortly for that one, but its damage would be
> limited to a bogus printk.

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

* Re: [PATCH] perf: fix interrupt handler timing harness
  2013-07-08 18:08   ` Stephane Eranian
@ 2013-07-08 20:05     ` Dave Hansen
  2013-07-08 20:20       ` Stephane Eranian
  0 siblings, 1 reply; 10+ messages in thread
From: Dave Hansen @ 2013-07-08 20:05 UTC (permalink / raw)
  To: Stephane Eranian; +Cc: LKML, Peter Zijlstra, mingo, dave.hansen, ak, Jiri Olsa

On 07/08/2013 11:08 AM, Stephane Eranian wrote:
> I admit I have some issues with your patch and what it is trying to avoid.
> There is already interrupt throttling. Your code seems to address latency
> issues on the handler rather than rate issues. Yet to mitigate the latency
> it is modify the throttling.

If we have too many interrupts, we need to drop the rate (existing
throttling).

If the interrupts _consistently_ take too long individually they can
starve out all the other CPU users.  I saw no way to make them finish
faster, so the only recourse is to also drop the rate.

> For some unknown reasons, my HSW interrupt handler goes crazy for
> a while running a very simple:
>    $ perf record -e cycles branchy_loop
> 
> And I do see in the log:
> perf samples too long (2546 > 2500), lowering
> kernel.perf_event_max_sample_rate to 50000
> 
> Which is an enormous latency. I instrumented the code, and under
> normal conditions the latency
> of the handler for this perf run, is about 500ns and it is consistent
> with what I see on SNB.

I was seeing latencies near 1 second from time to time, but
_consistently_ in the hundreds of milliseconds.

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

* Re: [PATCH] perf: fix interrupt handler timing harness
  2013-07-08 20:05     ` Dave Hansen
@ 2013-07-08 20:20       ` Stephane Eranian
  2013-07-08 20:34         ` Dave Hansen
  0 siblings, 1 reply; 10+ messages in thread
From: Stephane Eranian @ 2013-07-08 20:20 UTC (permalink / raw)
  To: Dave Hansen; +Cc: LKML, Peter Zijlstra, mingo, dave.hansen, ak, Jiri Olsa

On Mon, Jul 8, 2013 at 10:05 PM, Dave Hansen <dave.hansen@intel.com> wrote:
> On 07/08/2013 11:08 AM, Stephane Eranian wrote:
>> I admit I have some issues with your patch and what it is trying to avoid.
>> There is already interrupt throttling. Your code seems to address latency
>> issues on the handler rather than rate issues. Yet to mitigate the latency
>> it is modify the throttling.
>
> If we have too many interrupts, we need to drop the rate (existing
> throttling).
>
> If the interrupts _consistently_ take too long individually they can
> starve out all the other CPU users.  I saw no way to make them finish
> faster, so the only recourse is to also drop the rate.
>
I think we need to investigate why some interrupts take so much time.
Could be HW, could be SW. Not talking about old hardware here.
Once we understand this, then we know maybe adjust the timing on
our patch.

>> For some unknown reasons, my HSW interrupt handler goes crazy for
>> a while running a very simple:
>>    $ perf record -e cycles branchy_loop
>>
>> And I do see in the log:
>> perf samples too long (2546 > 2500), lowering
>> kernel.perf_event_max_sample_rate to 50000
>>
>> Which is an enormous latency. I instrumented the code, and under
>> normal conditions the latency
>> of the handler for this perf run, is about 500ns and it is consistent
>> with what I see on SNB.
>
> I was seeing latencies near 1 second from time to time, but
> _consistently_ in the hundreds of milliseconds.

On my systems, I see 500ns with one session running. But on HSW,
something else is going on with bursts at 2500ns. That's not normal.
I want an explanation for this.

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

* Re: [PATCH] perf: fix interrupt handler timing harness
  2013-07-08 20:20       ` Stephane Eranian
@ 2013-07-08 20:34         ` Dave Hansen
  2013-07-08 20:54           ` Andi Kleen
  0 siblings, 1 reply; 10+ messages in thread
From: Dave Hansen @ 2013-07-08 20:34 UTC (permalink / raw)
  To: Stephane Eranian
  Cc: Dave Hansen, LKML, Peter Zijlstra, mingo, dave.hansen, ak, Jiri Olsa

On 07/08/2013 01:20 PM, Stephane Eranian wrote:
> On Mon, Jul 8, 2013 at 10:05 PM, Dave Hansen <dave.hansen@intel.com> wrote:
>> If the interrupts _consistently_ take too long individually they can
>> starve out all the other CPU users.  I saw no way to make them finish
>> faster, so the only recourse is to also drop the rate.
>>
> I think we need to investigate why some interrupts take so much time.
> Could be HW, could be SW. Not talking about old hardware here.
> Once we understand this, then we know maybe adjust the timing on
> our patch.

I spent quite a while looking at it on my hardware.  It's difficult to
profile in NMIs, but I'm fairly satisfied (for me) it is a NUMA issue
which gets worse as I add cores.

I did a quite a bit of ftracing to look for spots inside the handler
which were taking large amounts of time.  There were none.  The
execution time was spread very evenly over the entire nmi handler.  It
didn't appear to be any individual hot cachelines or doing something
silly like sitting in a loop handling lots of PMU events.


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

* Re: [PATCH] perf: fix interrupt handler timing harness
  2013-07-08 20:34         ` Dave Hansen
@ 2013-07-08 20:54           ` Andi Kleen
  2013-07-08 20:56             ` Stephane Eranian
  0 siblings, 1 reply; 10+ messages in thread
From: Andi Kleen @ 2013-07-08 20:54 UTC (permalink / raw)
  To: Dave Hansen
  Cc: Stephane Eranian, Dave Hansen, LKML, Peter Zijlstra, mingo,
	dave.hansen, Jiri Olsa

> I did a quite a bit of ftracing to look for spots inside the handler
> which were taking large amounts of time.  There were none.  The
> execution time was spread very evenly over the entire nmi handler.  It
> didn't appear to be any individual hot cachelines or doing something
> silly like sitting in a loop handling lots of PMU events.

In some cases callgraphs seemed to be quite expensive (large fraction
of the handler time)

-Andi

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

* Re: [PATCH] perf: fix interrupt handler timing harness
  2013-07-08 20:54           ` Andi Kleen
@ 2013-07-08 20:56             ` Stephane Eranian
  0 siblings, 0 replies; 10+ messages in thread
From: Stephane Eranian @ 2013-07-08 20:56 UTC (permalink / raw)
  To: Andi Kleen
  Cc: Dave Hansen, Dave Hansen, LKML, Peter Zijlstra, mingo,
	dave.hansen, Jiri Olsa

On Mon, Jul 8, 2013 at 10:54 PM, Andi Kleen <ak@linux.jf.intel.com> wrote:
>> I did a quite a bit of ftracing to look for spots inside the handler
>> which were taking large amounts of time.  There were none.  The
>> execution time was spread very evenly over the entire nmi handler.  It
>> didn't appear to be any individual hot cachelines or doing something
>> silly like sitting in a loop handling lots of PMU events.
>
> In some cases callgraphs seemed to be quite expensive (large fraction
> of the handler time)
>
In my case, I am not doing callgraphs, just regular cycles.

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

end of thread, other threads:[~2013-07-08 20:56 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2013-07-04 22:30 [PATCH] perf: fix interrupt handler timing harness Stephane Eranian
2013-07-05  6:54 ` Ingo Molnar
2013-07-05  9:54 ` [tip:perf/urgent] perf: Fix " tip-bot for Stephane Eranian
2013-07-08 14:34 ` [PATCH] perf: fix " Dave Hansen
2013-07-08 18:08   ` Stephane Eranian
2013-07-08 20:05     ` Dave Hansen
2013-07-08 20:20       ` Stephane Eranian
2013-07-08 20:34         ` Dave Hansen
2013-07-08 20:54           ` Andi Kleen
2013-07-08 20:56             ` Stephane Eranian

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.