lkml.org 
[lkml]   [2009]   [Oct]   [7]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    From
    SubjectRe: [.32-rc3] scheduler: iwlagn consistently high in "waiting for CPU"
    Date
    On Tuesday 06 October 2009, Frans Pop wrote:
    > I've checked for 2.6.31.1 now and iwlagn is listed high there too when
    > the system is idle, but with normal values of 60-100 ms. And phy0 has
    > normal values of below 10 ms.
    > I've now rebooted with today's mainline git; phy0 now frequently shows
    > with values of around 100 ms too (i.e. higher than last time).
    >
    > Both still go way down as soon as the system is given work to do.
    >
    > With a 5 second sleep I was unable to get any significant latencies (I
    > started perf on a latencytop refresh and did a manual refresh as it
    > finished to see what happened during the perf run). The perf run does
    > seem to affect the latencies.
    > I've uploaded a chart for a 10s sleep during which I got latencies of
    > 101ms for iwlagn and 77ms for phy0:
    > http://people.debian.org/~fjp/tmp/kernel/.

    Mike privately sent me a script to try to capture the latencies with perf,
    but the perf output does not show any high latencies at all. It looks as if
    we may have found a bug in latencytop here instead.

    Below a relevant quote from our private mails and the data I captured with
    Mike's script.

    Cheers,
    FJP

    On Wednesday 07 October 2009, Mike Galbraith wrote:
    > On Wed, 2009-10-07 at 17:53 +0200, Frans Pop wrote:
    > > I had latencytop running at the same time and that happily showed
    > > values of 160 and 102 ms for iwlagn during the same period.
    > > The highest values I see from your script for any process are ~12 ms.
    > >
    > > Does this mean there is a bug in latencytop somewhere? Or is there
    > > something else going on?
    >
    > I suspect a bug in latencytop.. Arjan might suspect perf ;-)
    >
    > The only way you can get a 100+ ms latency hit on a mostly idle box is
    > for there to be a problem with the clock, _and_ have multiple runnable
    > heavy cpu using tasks on the runqueue so you can have a wide vruntime
    > spread. Peter's been all over the vruntime update logic, and if it or
    > the clock were generally screwed, you'd see latency spikes all over
    > creation. It _could_ be some rare event though, why I hacked script
    > together to chop off bite sized chunks for analysis. Since nothing
    > showed up there, and nothing's showing up here doing the same amarok+nfs
    > thing, I'll place my bet on latencytop.. for now.
    >
    > > At the bottom a sample from your unmodified script. That one is fairly
    > > typical, although it has does have about the highest value I've seen
    > > for iwlagn.
    >
    > Yeah, looks perfectly normal. Which leaves us at square one :-/



    Typical output from perf (with fairly high phy0 and iwlagn):
    -----------------------------------------------------------------------------------------
    Task | Runtime ms | Switches | Average delay ms | Maximum delay ms |
    -----------------------------------------------------------------------------------------
    kondemand/0:282 | 2.085 ms | 123 | avg: 0.152 ms | max: 7.007 ms |
    amarokapp:5485 | 123.867 ms | 240 | avg: 0.120 ms | max: 5.260 ms |
    kondemand/1:283 | 1.977 ms | 119 | avg: 0.107 ms | max: 4.781 ms |
    phy0:2750 | 0.684 ms | 28 | avg: 0.181 ms | max: 3.921 ms |
    iwlagn:2749 | 0.668 ms | 28 | avg: 0.196 ms | max: 3.697 ms |
    Xorg:4147 | 40.570 ms | 224 | avg: 0.109 ms | max: 3.615 ms |
    kblockd/0:78 | 0.013 ms | 1 | avg: 3.121 ms | max: 3.121 ms |
    kcryptd:1520 | 64.962 ms | 11 | avg: 0.347 ms | max: 2.812 ms |
    perf:9451 | 322.937 ms | 40 | avg: 0.144 ms | max: 2.198 ms |
    :5662:5662 | 50.572 ms | 147 | avg: 0.087 ms | max: 2.141 ms |
    head:9452 | 2.589 ms | 4 | avg: 0.454 ms | max: 1.648 ms |
    :9439:9439 | 6.670 ms | 225 | avg: 0.127 ms | max: 1.574 ms |
    kicker:5451 | 24.650 ms | 102 | avg: 0.158 ms | max: 1.465 ms |
    ksysguardd:5454 | 6.614 ms | 7 | avg: 0.283 ms | max: 1.218 ms |
    :5661:5661 | 0.208 ms | 9 | avg: 0.130 ms | max: 1.024 ms |
    latencytop:7776 | 2.010 ms | 4 | avg: 0.256 ms | max: 0.980 ms |

    Series of greps from that output for only iwlagn and phy0:
    Oct 07 17:23:39 iwlagn:2749 | 0.721 ms | 35 | avg: 0.050 ms | max: 0.083 ms |
    Oct 07 17:23:39 phy0:2750 | 0.779 ms | 35 | avg: 0.032 ms | max: 0.036 ms |
    Oct 07 17:23:46 iwlagn:2749 | 0.617 ms | 32 | avg: 0.107 ms | max: 1.753 ms |
    Oct 07 17:23:46 phy0:2750 | 0.783 ms | 32 | avg: 0.123 ms | max: 1.745 ms |
    Oct 07 17:23:53 iwlagn:2749 | 0.629 ms | 31 | avg: 0.055 ms | max: 0.109 ms |
    Oct 07 17:23:53 phy0:2750 | 0.774 ms | 31 | avg: 0.029 ms | max: 0.050 ms |
    Oct 07 17:24:01 iwlagn:2749 | 0.908 ms | 35 | avg: 0.054 ms | max: 0.097 ms |
    Oct 07 17:24:01 phy0:2750 | 0.839 ms | 35 | avg: 0.033 ms | max: 0.056 ms |
    Oct 07 17:24:08 phy0:2750 | 0.742 ms | 32 | avg: 0.033 ms | max: 0.124 ms |
    Oct 07 17:24:08 iwlagn:2749 | 0.734 ms | 32 | avg: 0.050 ms | max: 0.083 ms |
    Oct 07 17:24:15 phy0:2750 | 0.963 ms | 41 | avg: 0.034 ms | max: 0.164 ms |
    Oct 07 17:24:15 iwlagn:2749 | 0.721 ms | 41 | avg: 0.049 ms | max: 0.118 ms |
    Oct 07 17:24:23 iwlagn:2749 | 6.434 ms | 73 | avg: 0.052 ms | max: 0.153 ms |
    Oct 07 17:24:23 phy0:2750 | 0.620 ms | 22 | avg: 0.023 ms | max: 0.094 ms |
    Oct 07 17:24:30 iwlagn:2749 | 0.934 ms | 38 | avg: 0.055 ms | max: 0.194 ms |
    Oct 07 17:24:30 phy0:2750 | 0.941 ms | 37 | avg: 0.033 ms | max: 0.123 ms |
    Oct 07 17:24:37 iwlagn:2749 | 5.324 ms | 74 | avg: 0.054 ms | max: 0.106 ms |
    Oct 07 17:24:37 phy0:2750 | 0.993 ms | 36 | avg: 0.030 ms | max: 0.050 ms |
    Oct 07 17:24:45 iwlagn:2749 | 0.844 ms | 36 | avg: 0.049 ms | max: 0.080 ms |
    Oct 07 17:24:45 phy0:2750 | 0.770 ms | 34 | avg: 0.032 ms | max: 0.043 ms |
    Oct 07 17:24:52 phy0:2750 | 0.832 ms | 36 | avg: 0.044 ms | max: 0.185 ms |
    Oct 07 17:24:52 iwlagn:2749 | 0.923 ms | 36 | avg: 0.050 ms | max: 0.081 ms |
    Oct 07 17:24:59 iwlagn:2749 | 0.778 ms | 35 | avg: 0.054 ms | max: 0.104 ms |
    Oct 07 17:24:59 phy0:2750 | 0.778 ms | 34 | avg: 0.025 ms | max: 0.041 ms |
    Oct 07 17:25:07 iwlagn:2749 | 0.854 ms | 34 | avg: 0.056 ms | max: 0.103 ms |
    Oct 07 17:25:07 phy0:2750 | 0.780 ms | 34 | avg: 0.027 ms | max: 0.040 ms |
    Oct 07 17:25:14 phy0:2750 | 0.762 ms | 33 | avg: 0.035 ms | max: 0.168 ms |
    Oct 07 17:25:14 iwlagn:2749 | 0.853 ms | 33 | avg: 0.051 ms | max: 0.080 ms |
    Oct 07 17:25:21 iwlagn:2749 | 0.892 ms | 34 | avg: 0.053 ms | max: 0.144 ms |
    Oct 07 17:25:21 phy0:2750 | 0.780 ms | 34 | avg: 0.029 ms | max: 0.040 ms |
    Oct 07 17:25:29 iwlagn:2749 | 0.972 ms | 39 | avg: 0.046 ms | max: 0.079 ms |
    Oct 07 17:25:29 phy0:2750 | 0.843 ms | 38 | avg: 0.031 ms | max: 0.040 ms |
    Oct 07 17:25:36 iwlagn:2749 | 0.896 ms | 39 | avg: 0.054 ms | max: 0.106 ms |
    Oct 07 17:25:36 phy0:2750 | 0.873 ms | 37 | avg: 0.032 ms | max: 0.070 ms |
    Oct 07 17:25:43 phy0:2750 | 0.919 ms | 39 | avg: 0.083 ms | max: 2.161 ms |
    Oct 07 17:25:43 iwlagn:2749 | 0.950 ms | 40 | avg: 0.050 ms | max: 0.102 ms |


    \
     
     \ /
      Last update: 2009-10-07 19:15    [W:0.031 / U:30.816 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site