lkml.org 
[lkml]   [2001]   [Sep]   [20]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    From
    SubjectRe: [PATCH] Preemption Latency Measurement Tool
    Date
    Am Donnerstag, 20. September 2001 00:44 schrieb Robert Love:
    > Available at:
    > http://tech9.net/rml/linux/patch-rml-2.4.9-ac12-preempt-stats-1 and
    > http://tech9.net/rml/linux/patch-rml-2.4.10-pre12-preempt-stats-1
    > for 2.4.9-ac12 and 2.4.10-pre12, respectively.
    >
    > This patch is provided thanks to MontaVista (http://mvista.com).

    Great, thanks.

    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.

    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?

    -Dieter

    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
    2586 BKL 1 1302/inode.c c016f2f9 1381/sched.c
    2329 BKL 0 1302/inode.c c016f2f9 842/inode.c
    2231 BKL 1 1302/inode.c c016f2f9 697/sched.c
    2088 BKL 1 1437/namei.c c014c42f 697/sched.c
    1992 BKL 0 30/inode.c c016cdf1 1381/sched.c
    1953 BKL 1 1302/inode.c c016f2f9 52/inode.c
    1952 BKL 0 1302/inode.c c016f2f9 1380/sched.c
    1947 BKL 1 30/inode.c c016cdf1 697/sched.c
    1923 reacqBKL 0 1375/sched.c c0114d94 1381/sched.c
    1908 BKL 0 1302/inode.c c016f2f9 1306/inode.c
    1904 BKL 1 452/exit.c c011af61 697/sched.c
    1892 BKL 1 129/attr.c c015765d 697/sched.c
    1875 BKL 0 1437/namei.c c014c42f 1381/sched.c
    1823 spin_lock 0 547/sched.c c0112fe4 1381/sched.c
    1790 reacqBKL 0 1375/sched.c c0114d94 1439/namei.c
    1779 BKL 1 1366/namei.c c014c12c 1381/sched.c
    1762 spin_lock 0 547/sched.c c0112fe4 1380/sched.c
    1756 reacqBKL 1 1375/sched.c c0114d94 52/inode.c
    1754 BKL 0 927/namei.c c014b2bf 1381/sched.c


    time ./dbench 32
    Throughput 28.0138 MB/sec (NB=35.0172 MB/sec 280.138 MBit/sec)
    14.570u 61.520s 2:31.80 50.1% 0+0k 0+0io 911pf+0w
    load: 2690

    Worst 20 latency times of 8091 measured in this period.
    usec cause mask start line/file address end line/file
    8347 BKL 1 533/inode.c c016d96d 842/inode.c
    7808 spin_lock 1 1376/sched.c c0114db3 697/sched.c
    6181 BKL 1 1302/inode.c c016f2f9 1381/sched.c
    3325 BKL 1 1302/inode.c c016f2f9 842/inode.c
    3314 spin_lock 1 547/sched.c c0112fe4 697/sched.c
    3014 BKL 1 129/attr.c c015765d 697/sched.c
    2956 BKL 1 1302/inode.c c016f2f9 1380/sched.c
    2954 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
    2795 BKL 1 927/namei.c c014b2bf 697/sched.c
    2750 BKL 1 1302/inode.c c016f2f9 697/sched.c
    2667 BKL 1 30/inode.c c016cdf1 697/sched.c
    2623 spin_lock 0 1376/sched.c c0114db3 1380/sched.c
    2613 spin_lock 0 1376/sched.c c0114db3 1306/inode.c
    2566 reacqBKL 0 1375/sched.c c0114d94 1381/sched.c
    2527 BKL 0 1437/namei.c c014c42f 697/sched.c
    2526 BKL 0 1437/namei.c c014c42f 1380/sched.c
    2525 spin_lock 1 547/sched.c c0112fe4 1380/sched.c
    2513 BKL 0 927/namei.c c014b2bf 1380/sched.c
    2442 BKL 0 30/inode.c c016cdf1 1381/sched.c
    2353 BKL 0 452/exit.c c011af61 1380/sched.c


    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
    9040 BKL 1 1302/inode.c c016f2f9 1306/inode.c
    8530 BKL 1 1302/inode.c c016f2f9 842/inode.c
    8268 reacqBKL 1 1375/sched.c c0114d94 1381/sched.c
    5432 spin_lock 1 547/sched.c c0112fe4 697/sched.c
    3630 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
    3519 BKL 1 1437/namei.c c014c42f 1380/sched.c
    3387 BKL 0 1302/inode.c c016f2f9 697/sched.c
    3194 spin_lock 0 547/sched.c c0112fe4 1380/sched.c
    3180 spin_lock 0 547/sched.c c0112fe4 1381/sched.c
    3015 spin_lock 1 547/sched.c c0112fe4 842/inode.c
    2894 BKL 0 1302/inode.c c016f2f9 1381/sched.c
    2778 spin_lock 1 1376/sched.c c0114db3 1380/sched.c
    2755 BKL 1 1302/inode.c c016f2f9 1380/sched.c
    2676 BKL 1 452/exit.c c011af61 697/sched.c
    2354 BKL 1 533/inode.c c016d96d 697/sched.c
    2237 BKL 0 30/inode.c c016cdf1 697/sched.c
    2104 BKL 0 1437/namei.c c014c42f 1381/sched.c
    2097 spin_lock 0 1376/sched.c c0114db3 1381/sched.c
    2082 BKL 0 30/inode.c c016cdf1 1380/sched.c


    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
    9303 BKL 1 1302/inode.c c016f2f9 697/sched.c
    9145 BKL 1 1302/inode.c c016f2f9 1306/inode.c
    7984 spin_lock 1 547/sched.c c0112fe4 1380/sched.c
    5983 BKL 1 1302/inode.c c016f2f9 842/inode.c
    4947 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
    4497 spin_lock 1 547/sched.c c0112fe4 697/sched.c
    4310 spin_lock 1 1376/sched.c c0114db3 1380/sched.c
    4290 reacqBKL 0 1375/sched.c c0114d94 1306/inode.c
    4002 spin_lock 1 547/sched.c c0112fe4 1381/sched.c
    3822 spin_lock 0 1376/sched.c c0114db3 697/sched.c
    3683 BKL 0 1302/inode.c c016f2f9 1380/sched.c
    3422 spin_lock 1 547/sched.c c0112fe4 1306/inode.c
    3193 BKL 0 1437/namei.c c014c42f 1380/sched.c
    3006 BKL 1 30/inode.c c016cdf1 1380/sched.c
    2990 BKL 1 129/attr.c c015765d 697/sched.c
    2971 BKL 1 1437/namei.c c014c42f 1381/sched.c
    2939 BKL 0 927/namei.c c014b2bf 1381/sched.c
    2862 BKL 0 1302/inode.c c016f2f9 1381/sched.c


    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
    218 spin_lock 0 547/sched.c c0112fe4 1381/sched.c
    215 reacqBKL 0 1375/sched.c c0114d94 1381/sched.c
    215 BKL 0 2763/buffer.c c01410aa 1381/sched.c
    205 BKL 0 359/buffer.c c013d1bc 1381/sched.c
    205 eth1 0 585/irq.c c010886f 647/irq.c
    149 spin_lock 0 547/sched.c c0112fe4 697/sched.c
    147 BKL 0 359/buffer.c c013d1bc 697/sched.c
    135 spin_lock 0 1376/sched.c c0114db3 1380/sched.c
    130 reacqBKL 0 1375/sched.c c0114d94 697/sched.c
    111 BKL 0 452/exit.c c011af61 697/sched.c
    105 unknown 1 76/softirq.c c011c634 119/softirq.c
    86 BKL 4 712/tty_io.c c018cf6b 714/tty_io.c
    61 spin_lock 0 1715/dev.c c01dc4b3 1728/dev.c
    58 BKL 0 301/namei.c c0149db1 303/namei.c
    56 spin_lock 2 468/netfilter.c c01e4303 119/softirq.c
    44 BKL 1 59/ioctl.c c014ea3a 111/ioctl.c
    43 BKL 0 1302/inode.c c016f2f9 1306/inode.c
    43 spin_lock 1 69/i387.c c010ca23 227/mmx.c
    42 BKL 1 26/readdir.c c014ed07 28/readdir.c


    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.

    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
    2553 BKL 1 1302/inode.c c016f2f9 697/sched.c
    2284 BKL 0 1302/inode.c c016f2f9 842/inode.c
    2235 reacqBKL 1 1375/sched.c c0114d94 1381/sched.c
    2227 BKL 0 1302/inode.c c016f2f9 1380/sched.c
    2183 BKL 0 927/namei.c c014b2bf 1306/inode.c
    2055 BKL 1 927/namei.c c014b2bf 697/sched.c
    2037 BKL 1 452/exit.c c011af61 697/sched.c
    2032 BKL 0 30/inode.c c016cdf1 697/sched.c
    2008 BKL 1 1302/inode.c c016f2f9 1381/sched.c
    1943 BKL 0 927/namei.c c014b2bf 1439/namei.c
    1926 BKL 1 452/exit.c c011af61 52/inode.c
    1919 spin_lock 1 1376/sched.c c0114db3 697/sched.c
    1880 BKL 0 1437/namei.c c014c42f 1381/sched.c
    1865 BKL 0 30/inode.c c016cdf1 1380/sched.c
    1858 spin_lock 0 547/sched.c c0112fe4 1380/sched.c
    1849 reacqBKL 0 1375/sched.c c0114d94 1439/namei.c
    1821 reacqBKL 0 1375/sched.c c0114d94 697/sched.c
    1774 BKL 1 129/attr.c c015765d 697/sched.c
    1720 BKL 1 1437/namei.c c014c42f 1380/sched.c


    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
    10943 BKL 1 1302/inode.c c016f2f9 697/sched.c
    10798 spin_lock 1 1376/sched.c c0114db3 697/sched.c
    9367 spin_lock 1 1376/sched.c c0114db3 1306/inode.c
    7230 spin_lock 1 1376/sched.c c0114db3 1381/sched.c
    6870 spin_lock 1 547/sched.c c0112fe4 1381/sched.c
    5610 reacqBKL 1 1375/sched.c c0114d94 1381/sched.c
    5356 spin_lock 0 547/sched.c c0112fe4 1380/sched.c
    4162 reacqBKL 0 1375/sched.c c0114d94 1306/inode.c
    4068 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
    3335 BKL 0 1302/inode.c c016f2f9 1380/sched.c
    3161 spin_lock 1 1376/sched.c c0114db3 1380/sched.c
    3030 BKL 1 1437/namei.c c014c42f 697/sched.c
    2974 BKL 0 1437/namei.c c014c42f 1380/sched.c
    2832 BKL 0 1302/inode.c c016f2f9 1381/sched.c
    2817 BKL 0 927/namei.c c014b2bf 1380/sched.c
    2713 spin_lock 1 483/dcache.c c0153efa 520/dcache.c
    2522 spin_lock 1 547/sched.c c0112fe4 1306/inode.c
    2522 BKL 0 533/inode.c c016d96d 1381/sched.c
    2508 BKL 0 533/inode.c c016d96d 929/namei.c
    -
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

    \
     
     \ /
      Last update: 2005-03-22 13:03    [W:9.154 / U:0.012 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site