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 | -- To unsubscribe from this list: send the line "unsubscribe linux-wireless" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
