lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Date:	Fri, 09 Oct 2009 05:35:18 +0200
From:	Mike Galbraith <efault@....de>
To:	Markus Trippelsdorf <markus@...ppelsdorf.de>
Cc:	Frans Pop <elendil@...net.nl>,
	Arjan van de Ven <arjan@...radead.org>,
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
	Ingo Molnar <mingo@...e.hu>,
	Peter Zijlstra <peterz@...radead.org>,
	linux-wireless@...r.kernel.org
Subject: Re: [.32-rc3] scheduler: iwlagn consistently high in "waiting for
 CPU"

On Thu, 2009-10-08 at 22:34 +0200, Markus Trippelsdorf wrote:
> On Thu, Oct 08, 2009 at 08:23:37PM +0200, Mike Galbraith wrote:
> > On Thu, 2009-10-08 at 16:55 +0200, Frans Pop wrote:
> > > On Thursday 08 October 2009, Arjan van de Ven wrote:
> > > > From: Arjan van de Ven <arjan@...ux.intel.com>
> > > > Date: Thu, 24 Sep 2009 13:24:16 +0200
> > > > Subject: [PATCH] x86, timers: check for pending timers after (device)
> > > > interrupts
> > > >
> > > > Now that range timers and deferred timers are common, I found a
> > > > problem with these using the "perf timechart" tool.
> > > >
> > > > It turns out that on x86, these two 'opportunistic' timers only
> > > > get checked when another "real" timer happens.
> > > > These opportunistic timers have the objective to save power by
> > > > hitchhiking on other wakeups, as to avoid CPU wakeups by themselves
> > > > as much as possible.
> > > 
> > > This patch makes quite a difference for me. iwlagn and phy0 now 
> > > consistently show at ~10 ms or lower.
> > > 
> > > I do still get occasional high latencies, but those are for things like
> > > "[rpc_wait_bit_killable]" or "Writing a page to disk", where I guess you'd 
> > > expect them. Those high latencies are mostly only listed for "Global" and 
> > > don't translate to individual processes.
> > 
> > I still see very high latencies coming out of idle (last noted was >
> > 300ms, NO_HZ) with this patch, and wonder if the hunk below makes any
> > difference whatsoever for you.  Here, it definitely does. (shouldn't)
> 
> I'm also seeing these strange, very high latencies here. Your patch
> didn't help unfortunately.
> 
> This is from an otherwise idle NO_NZ system:
> 
> # ./perf sched latency
> 
>  -----------------------------------------------------------------------------------------
>   Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms |
>  -----------------------------------------------------------------------------------------
>   ksoftirqd/0:4         |      2.216 ms |      170 | avg:   24.235 ms | max:  808.356 ms |
>   ksoftirqd/1:6         |      2.611 ms |      205 | avg:    4.334 ms | max:  165.553 ms |
>   migration/2:7         |      0.000 ms |        1 | avg:    3.060 ms | max:    3.060 ms |
> 
> With latencytop the ksoftirqd latency is over 1 sec frequently. (Could be
> ondemand CPUfreq governor related?)

That's a separate issue, which Arjan was nice enough to fix for me.  He
even wrote the changelog, and used my mouse to do so ;-)

Watch.

Virgin tip pulled this morning, perf sched record sleep 1 on idle box.

 -----------------------------------------------------------------------------------------
  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms |
 -----------------------------------------------------------------------------------------
  kicker:5845           |      0.000 ms |        1 | avg:  999.406 ms | max:  999.406 ms |
  rt2870TimerQHan:4952  |      0.008 ms |        3 | avg:    0.087 ms | max:    0.131 ms |
  Xorg:4913             |      0.099 ms |        2 | avg:    0.027 ms | max:    0.044 ms |
  kondemand/3:3106      |      0.014 ms |        2 | avg:    0.013 ms | max:    0.018 ms |
  perf:7229             |      3.986 ms |        1 | avg:    0.017 ms | max:    0.017 ms |
  events/3:14           |      0.038 ms |        1 | avg:    0.017 ms | max:    0.017 ms |
  kondemand/2:3105      |      0.017 ms |        1 | avg:    0.008 ms | max:    0.008 ms |
  kondemand/1:3104      |      0.041 ms |        1 | avg:    0.007 ms | max:    0.007 ms |
  konsole:5855          |      0.362 ms |        3 | avg:    0.004 ms | max:    0.006 ms |
  kondemand/0:3103      |      0.000 ms |        1 | avg:    0.000 ms | max:    0.000 ms |
 -----------------------------------------------------------------------------------------
  TOTAL:                |      4.565 ms |       16 |
 ---------------------------------------------------
  INFO: 40.741% state machine bugs (11 out of 27)
  INFO: 51.852% context switch bugs (14 out of 27)

Repeatable.  Apply patchlet, and the numbers below become repeatable.

perf_counter tools: make perf sched pass -F 0 to record

Commit 42e59d7d19dc4b4 introduced a sample frequency framework..
.. however it unfortunately changed how perf events get recorded,
and caused sched to miss events.

This patch causes the sched code to use -F 0 to not use the
new framework when recording sched data.

Signed-off-by: Mike Galbraith <efault@....de>
Cc: Ingo Molnar <mingo@...e.hu>
Cc: Peter Zijlstra <a.p.zijlstra@...llo.nl>
Cc: Arjan The Wise <arjan@...ux.intel.com>
LKML-Reference: <new-submission>

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

Index: linux-2.6/tools/perf/builtin-sched.c
===================================================================
--- linux-2.6.orig/tools/perf/builtin-sched.c
+++ linux-2.6/tools/perf/builtin-sched.c
@@ -1902,6 +1902,7 @@ static const char *record_args[] = {
 	"-f",
 	"-m", "1024",
 	"-c", "1",
+	"-F", "0",
 	"-e", "sched:sched_switch:r",
 	"-e", "sched:sched_stat_wait:r",
 	"-e", "sched:sched_stat_sleep:r",


 
 -----------------------------------------------------------------------------------------
  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms |
 -----------------------------------------------------------------------------------------
  Xorg:4913             |      2.296 ms |       43 | avg:    0.075 ms | max:    0.686 ms |
  kicker:5845           |      3.106 ms |       28 | avg:    0.017 ms | max:    0.307 ms |
  perf:7419             |    147.147 ms |       16 | avg:    0.028 ms | max:    0.261 ms |
  klipper:6404          |      0.035 ms |        1 | avg:    0.256 ms | max:    0.256 ms |
  kondemand/3:3106      |      0.139 ms |       18 | avg:    0.039 ms | max:    0.192 ms |
  rt2870TimerQHan:4952  |      0.726 ms |      107 | avg:    0.010 ms | max:    0.165 ms |
  konsole:5856          |      0.180 ms |        2 | avg:    0.050 ms | max:    0.094 ms |
  kded:5831             |      0.044 ms |        1 | avg:    0.055 ms | max:    0.055 ms |
  events/3:14           |      0.066 ms |        3 | avg:    0.018 ms | max:    0.031 ms |
  kondemand/2:3105      |      0.015 ms |        2 | avg:    0.020 ms | max:    0.029 ms |
  ksoftirqd/3:10        |      0.326 ms |        3 | avg:    0.018 ms | max:    0.027 ms |
  kondemand/1:3104      |      0.142 ms |       24 | avg:    0.008 ms | max:    0.023 ms |
  rt2870MlmeThrea:4950  |      0.095 ms |       13 | avg:    0.012 ms | max:    0.022 ms |
  kondemand/0:3103      |      0.259 ms |       36 | avg:    0.013 ms | max:    0.020 ms |
  kwin:5841             |      0.038 ms |        1 | avg:    0.018 ms | max:    0.018 ms |
  sync_supers:92        |      0.008 ms |        1 | avg:    0.018 ms | max:    0.018 ms |
  events/0:11           |      0.005 ms |        1 | avg:    0.015 ms | max:    0.015 ms |
  konsole:5855          |      0.709 ms |       10 | avg:    0.007 ms | max:    0.013 ms |
  events/2:13           |      0.009 ms |        1 | avg:    0.011 ms | max:    0.011 ms |
  events/1:12           |      0.006 ms |        1 | avg:    0.010 ms | max:    0.010 ms |
  mysqld:5030           |      0.185 ms |        1 | avg:    0.009 ms | max:    0.009 ms |
  hald-addon-inpu:3191  |      0.006 ms |        1 | avg:    0.006 ms | max:    0.006 ms |
  mono:6472             |      0.144 ms |       11 | avg:    0.005 ms | max:    0.006 ms |
  ntpd:6020             |      0.030 ms |        1 | avg:    0.005 ms | max:    0.005 ms |
  gpg-agent:5783        |      0.047 ms |        1 | avg:    0.005 ms | max:    0.005 ms |
  sleep:7420            |      0.973 ms |        2 | avg:    0.003 ms | max:    0.005 ms |
  httpd2-prefork:6416   |      0.013 ms |        1 | avg:    0.005 ms | max:    0.005 ms |
  mysqld:5031           |      0.172 ms |        1 | avg:    0.005 ms | max:    0.005 ms |
  kwrapper:5838         |      0.010 ms |        1 | avg:    0.005 ms | max:    0.005 ms |
 -----------------------------------------------------------------------------------------
  TOTAL:                |    156.930 ms |      332 |
 ---------------------------------------------------




--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Powered by blists - more mailing lists