Re: [PATCH] Preemption Latency Measurement Tool

Dieter Nützel
2001-09-20T07:58:05Z

Am Donnerstag, 20. September 2001 08:41 schrieb Andrea Arcangeli:
> Those inodes lines reminded me one thing, you may want to give it a try:
>
> --- 2.4.10pre12aa1/fs/inode.c.~1~ Thu Sep 20 01:44:07 2001
> +++ 2.4.10pre12aa1/fs/inode.c Thu Sep 20 08:37:33 2001
> @@ -295,6 +295,12 @@
> * so we have to start looking from the list head.
> */
> tmp = head;
> +
> + if (unlikely(current->need_resched)) {
> + spin_unlock(&inode_lock);
> + schedule();
> + spin_lock(&inode_lock);
> + }
> }
> }
>

You've forgotten a one liner.

#include <linux/locks.h>
+#include <linux/compiler.h>

But this is not enough. Even with reniced artsd (-20).
Some shorter hiccups (0.5~1 sec).

-Dieter

dbench 16 (without renice)
Throughput 31.0483 MB/sec (NB=38.8104 MB/sec 310.483 MBit/sec)
7.270u 29.290s 1:09.03 52.9% 0+0k 0+0io 511pf+0w
load: 1034

Worst 20 latency times of 4261 measured in this period.
usec cause mask start line/file address end line/file
4617 reacqBKL 0 1375/sched.c c0114d94 1381/sched.c
2890 spin_lock 1 1376/sched.c c0114db3 697/sched.c
2072 BKL 1 533/inode.c c016d9cd 697/sched.c
2062 BKL 1 1302/inode.c c016f359 52/inode.c
2039 BKL 1 1302/inode.c c016f359 697/sched.c
1908 BKL 0 1302/inode.c c016f359 929/namei.c
1870 BKL 0 1302/inode.c c016f359 1381/sched.c
1859 spin_lock 0 547/sched.c c0112fe4 697/sched.c
1834 BKL 0 30/inode.c c016ce51 1381/sched.c
1834 BKL 1 1302/inode.c c016f359 1380/sched.c
1833 BKL 1 1437/namei.c c014c42f 697/sched.c
1831 BKL 1 452/exit.c c011af61 697/sched.c
1820 BKL 1 1437/namei.c c014c42f 842/inode.c
1797 BKL 0 1302/inode.c c016f359 842/inode.c
1741 spin_lock 0 547/sched.c c0112fe4 1380/sched.c
1696 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
1690 BKL 1 1437/namei.c c014c42f 1380/sched.c
1652 BKL 1 533/inode.c c016d9cd 1380/sched.c
1648 BKL 1 1870/namei.c c014d420 1381/sched.c
1643 BKL 0 927/namei.c c014b2bf 1381/sched.c

dbench 16 (artsd renice -20)
Throughput 32.8102 MB/sec (NB=41.0127 MB/sec 328.102 MBit/sec)
7.490u 28.570s 1:05.38 55.1% 0+0k 0+0io 511pf+0w
load: 963

Worst 20 latency times of 4649 measured in this period.
usec cause mask start line/file address end line/file
4828 spin_lock 1 1376/sched.c c0114db3 697/sched.c
2446 spin_lock 1 1376/sched.c c0114db3 1380/sched.c
2237 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
2205 reacqBKL 1 1375/sched.c c0114d94 1381/sched.c
2205 BKL 1 1302/inode.c c016f359 1380/sched.c
2076 BKL 0 1302/inode.c c016f359 1381/sched.c
2065 spin_lock 0 547/sched.c c0112fe4 697/sched.c
2048 BKL 0 30/inode.c c016ce51 697/sched.c
2040 BKL 1 452/exit.c c011af61 697/sched.c
1982 BKL 0 1437/namei.c c014c42f 1381/sched.c
1953 BKL 0 1437/namei.c c014c42f 1380/sched.c
1942 BKL 1 1302/inode.c c016f359 697/sched.c
1847 BKL 0 1302/inode.c c016f359 842/inode.c
1761 BKL 0 1437/namei.c c014c42f 697/sched.c
1734 reacqBKL 1 1375/sched.c c0114d94 52/inode.c
1708 BKL 0 30/inode.c c016ce51 1306/inode.c
1705 BKL 0 927/namei.c c014b2bf 1381/sched.c
1688 BKL 0 1302/inode.c c016f359 929/namei.c
1679 BKL 1 1437/namei.c c014c42f 842/inode.c
1648 BKL 1 1302/inode.c c016f359 1439/namei.c

dbench 48 looks like this (without renice)
Throughput 24.5736 MB/sec (NB=30.717 MB/sec 245.736 MBit/sec)
23.250u 89.760s 4:18.85 43.6% 0+0k 0+0io 1311pf+0w
load: 4429

Worst 20 latency times of 8033 measured in this period.
usec cause mask start line/file address end line/file
10856 spin_lock 1 1376/sched.c c0114db3 697/sched.c
10705 BKL 1 1302/inode.c c016f359 697/sched.c
10577 spin_lock 1 1376/sched.c c0114db3 303/namei.c
9427 spin_lock 1 547/sched.c c0112fe4 697/sched.c
8526 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
4492 reacqBKL 1 1375/sched.c c0114d94 1381/sched.c
4171 BKL 1 1302/inode.c c016f359 1381/sched.c
3902 reacqBKL 0 1375/sched.c c0114d94 1306/inode.c
3376 spin_lock 0 1376/sched.c c0114db3 1380/sched.c
3132 BKL 0 1302/inode.c c016f359 1380/sched.c
3096 spin_lock 1 547/sched.c c0112fe4 1380/sched.c
2808 BKL 0 30/inode.c c016ce51 1381/sched.c
2807 spin_lock 0 547/sched.c c0112fe4 1381/sched.c
2782 BKL 0 452/exit.c c011af61 1380/sched.c
2631 spin_lock 0 483/dcache.c c0153efa 520/dcache.c
2533 BKL 0 533/inode.c c016d9cd 1380/sched.c
2489 BKL 0 927/namei.c c014b2bf 1380/sched.c
2389 BKL 1 452/exit.c c011af61 52/inode.c
2369 BKL 1 1302/inode.c c016f359 842/inode.c
2327 BKL 1 30/inode.c c016ce51 1380/sched.c