Re: [PATCH] Preemption Latency Measurement Tool

Robert Love
2001-09-20T20:28:07Z

On Thu, 2001-09-20 at 02:31, Dieter Nützel wrote:
> Here are some results for 2.4.10-pre12 (Andrea's VM :-)
>
> Athlon II 1 GHz (0.18 µm)
> MSI MS-6167 Rev 1.0B (Irongate C4)
> 640 MB PC100-2-2-2 SDRAM
> IBM DDYS 18 GB U160 (on AHA-2940UW)
> ReiserFS 3.6 on all partitions
>
> Sound driver is the new kernel one for SB Live! (not ALSA).
> No swap used during whole test.

Good. I use that sound driver too (I was the one who updated it and
caused the commotion back in 2.4.9 :)

I am interested if you see any different times if you switch to ALSA,
though.

> 2.4.10-pre12 + patch-rml-2.4.10-pre12-preempt-kernel-1 +
> patch-rml-2.4.10-pre12-preempt-stats-1
>
> Hope my numbers help to find the right reason for the hiccups.
> ReiserFS seems _NOT_ to be the culprit for this.
> Maybe the scheduler it self?

The scheduler does hold some spinlocks. So does VM. I am working on
some ideas to tackle the highest of the worst-case spinlocks. Stay
tuned.

> KDE-2.2.1 noatun running MP3/Ogg-Vorbis
>
> time ./dbench 16
> Throughput 29.3012 MB/sec (NB=36.6265 MB/sec 293.012 MBit/sec)
> 7.450u 28.830s 1:13.10 49.6% 0+0k 0+0io 511pf+0w
> load: 1140
>
> Worst 20 latency times of 5583 measured in this period.
> usec cause mask start line/file address end line/file
> 5664 spin_lock 1 1376/sched.c c0114db3 697/sched.c
> <snip>

5ms is not an issue at all, especially for a worst case spinlock... no
problem here.

> time ./dbench 40
> Throughput 24.664 MB/sec (NB=30.83 MB/sec 246.64 MBit/sec)
> 18.690u 77.980s 3:35.09 44.9% 0+0k 0+0io 1111pf+0w
> load: 3734
>
> Worst 20 latency times of 7340 measured in this period.
> usec cause mask start line/file address end line/file
> 9313 spin_lock 1 1376/sched.c c0114db3 697/sched.c
> <snip>

We are getting higher, but still not an issue. I'll theorize below why
I think it is increasing...

> time ./dbench 48
> Throughput 24.5409 MB/sec (NB=30.6761 MB/sec 245.409 MBit/sec)
> 22.080u 97.560s 4:19.19 46.1% 0+0k 0+0io 1311pf+0w
> load: 4622
>
> Worst 20 latency times of 10544 measured in this period.
> usec cause mask start line/file address end line/file
> 12831 BKL 1 30/inode.c c016cdf1 52/inode.c
> 10869 reacqBKL 1 1375/sched.c c0114d94 1381/sched.c
> <snip>

Now we are above what I consider perfect (10ms), but I still am not
concenrned until 15-20ms times. The list I am compiling is of much
higher problems, so you are fine here too.

The reason I think it jumps during the higher threaded dbenchs is for
the obvious reason - more I/O. This is causing more seeks and longer
tranversing of the I/O queue.

> KDE-2.2.1 noatun running MP3/Ogg-Vorbis
>
> Worst 20 latency times of 2252 measured in this period.
> usec cause mask start line/file address end line/file
> 237 BKL 0 2763/buffer.c c01410aa 697/sched.c
> <snip>

0.2ms is ideal for any system :)

> Renice -20 both artsd prozesses (the KDE-2.2.1 noatun sound daemon)
> help a little bit but there are still some hiccups (1~3 sec)
> remaining.

You see 1-3second skips in the audio? With the 0.2ms latencies? Grr,
odd.

> But the system is very responsive (mouse, keyboard).
>
> time ./dbench 16
> Throughput 30.8602 MB/sec (NB=38.5752 MB/sec 308.602 MBit/sec)
> 7.490u 29.350s 1:09.44 53.0% 0+0k 0+0io 511pf+0w
>
> Worst 20 latency times of 5851 measured in this period.
> usec cause mask start line/file address end line/file
> 5518 spin_lock 1 1376/sched.c c0114db3 1380/sched.c
> <snip>
>
> time ./dbench 48
> Throughput 22.85 MB/sec (NB=28.5626 MB/sec 228.5 MBit/sec)
> 21.840u 98.560s 4:38.30 43.2% 0+0k 0+0io 1311pf+0w
>
> Worst 20 latency times of 8664 measured in this period.
> usec cause mask start line/file address end line/file
> 11179 spin_lock 1 547/sched.c c0112fe4 697/sched.c
> <snip>

Still OK.

Thanks for the feedback.

--
Robert M. Love
rml at ufl.edu
rml at tech9.net