From: "Dieter Nützel" <Dieter.Nuetzel@hamburg.de>
To: Robert Love <rml@tech9.net>, Roger Larsson <roger.larsson@norran.net>
Cc: Andrea Arcangeli <andrea@suse.de>,
linux-kernel@vger.kernel.org,
ReiserFS List <reiserfs-list@namesys.com>
Subject: Re: [PATCH] Preemption Latency Measurement Tool
Date: Thu, 20 Sep 2001 23:53:20 +0200 [thread overview]
Message-ID: <20010920215309Z274666-760+14624@vger.kernel.org> (raw)
In-Reply-To: <1000939458.3853.17.camel@phantasy> <200109201742.f8KHgJH04518@maild.telia.com> <1001021365.6048.187.camel@phantasy>
In-Reply-To: <1001021365.6048.187.camel@phantasy>
Am Donnerstag, 20. September 2001 23:29 schrieb Robert Love:
> On Thu, 2001-09-20 at 13:37, Roger Larsson wrote:
> > > 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
> >
> > This is fantastic! It REALLY is!
> > When we started with the low latency work we aimed at 10 ms.
> > (in all situations, not only when running dbench... but still)
>
> Yes it really is, especially noting that that 4.6ms lock is the
> _longest_ held lock on the system.
>
> I am seeing 90% of the reported locks under 15ms, and this means that
> almost all the locks on the system are even less.
>
> However, I am also seeing some stray 20-50ms and even 60-70ms latencies
> and those bother me. I am looking into another solution, perhaps
> conditional scheduling for now.
>
> > Lets see - no swap used? - not swapped out
swap is enabled but not used by artsd (only 8 MB for X and some kdeinit stuff)
810 nuetzel -1 -20 6820 0 6820 4380 S < 0.0 1.0 0:31 artsd
2724 nuetzel 8 0 6820 0 6820 4380 S 0.0 1.0 0:00 artsd
SunWave1>cat /proc/meminfo
total: used: free: shared: buffers: cached:
Mem: 658395136 437657600 220737536 0 6656000 287236096
Swap: 1052794880 8990720 1043804160
MemTotal: 642964 kB
MemFree: 215564 kB
MemShared: 0 kB
Buffers: 6500 kB
Cached: 278396 kB
SwapCached: 2108 kB
Active: 265108 kB
Inactive: 21896 kB
HighTotal: 0 kB
HighFree: 0 kB
LowTotal: 642964 kB
LowFree: 215564 kB
SwapTotal: 1028120 kB
SwapFree: 1019340 kB
> > But with priority altered - it is unlikely that it would not be scheduled
> > in for such a long time.
> >
> > Might it be that the disk is busy to handle dbench requests. 16 threads
> > -> 16 read and several (async) write requests at different disk locations
> > in queue - make it 20. Seek time 10 ms => queue length 200 ms...
> > probable??? Do you have more than one disk? Try to run dbench on one and
> > the player from the other.
OK, I moved my video and sound files to one of my "older" IBM DDRS-9GB UW
disks (read max ~12.8 MB/s).
Did NOT help. With and without renice -20.
Same hiccup (0.5~3 sec) during the first few seconds of dbench. The hiccup
ONLY occur at the beginning of every dbench run.
-Dieter
PS At the bottom you can find the latency and time for this copy job.
Throughput 23.7919 MB/sec (NB=29.7399 MB/sec 237.919 MBit/sec)
7.470u 29.740s 1:29.79 41.4% 0+0k 0+0io 511pf+0w
load: 1300
SunWave1>cat /proc/latencytimes
Worst 20 latency times of 5890 measured in this period.
usec cause mask start line/file address end line/file
13990 spin_lock 9 2043/tcp_ipv6.c e9072837 119/softirq.c
11596 spin_lock 1 2111/tcp_ipv4.c c0207287 119/softirq.c
4616 reacqBKL 1 1375/sched.c c0114d94 1381/sched.c
4478 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
2187 BKL 1 1302/inode.c c016f359 697/sched.c
2172 reacqBKL 1 1375/sched.c c0114d94 929/namei.c
1991 BKL 0 1302/inode.c c016f359 1381/sched.c
1966 BKL 1 1302/inode.c c016f359 842/inode.c
1934 BKL 0 1437/namei.c c014c42f 1380/sched.c
1891 BKL 0 30/inode.c c016ce51 697/sched.c
1879 spin_lock 0 547/sched.c c0112fe4 1381/sched.c
1865 spin_lock 0 1376/sched.c c0114db3 1380/sched.c
1833 spin_lock 1 1376/sched.c c0114db3 697/sched.c
1828 BKL 0 30/inode.c c016ce51 1380/sched.c
1812 BKL 0 1302/inode.c c016f359 1380/sched.c
1792 BKL 0 1437/namei.c c014c42f 1381/sched.c
1782 spin_lock 1 547/sched.c c0112fe4 697/sched.c
1776 BKL 0 1437/namei.c c014c42f 929/namei.c
1772 BKL 1 1437/namei.c c014c42f 697/sched.c
1767 BKL 0 129/attr.c c01576bd 1380/sched.c
SunWave1>cat /proc/latencytimes
Worst 20 latency times of 2260 measured in this period.
usec cause mask start line/file address end line/file
583 BKL 6 712/tty_io.c c018cfcb 714/tty_io.c
284 BKL 0 83/file.c c0171024 1381/sched.c
245 BKL 0 2763/buffer.c c01410aa 1381/sched.c
209 BKL 0 2763/buffer.c c01410aa 697/sched.c
204 eth1 0 585/irq.c c010886f 647/irq.c
193 reacqBKL 0 1375/sched.c c0114d94 1381/sched.c
142 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
111 reacqBKL 0 1375/sched.c c0114d94 98/file.c
109 BKL 0 452/exit.c c011af61 1380/sched.c
109 BKL 0 927/namei.c c014b2bf 929/namei.c
95 BKL 0 533/inode.c c016d9cd 842/inode.c
91 BKL 0 1870/namei.c c014d420 1873/namei.c
85 unknown 3 76/softirq.c c011c634 119/softirq.c
76 BKL 0 30/inode.c c016ce51 52/inode.c
64 BKL 1 26/readdir.c c014ed07 28/readdir.c
62 spin_lock 0 1715/dev.c c01dc513 1728/dev.c
54 spin_lock 2 468/netfilter.c c01e4363 119/softirq.c
49 spin_lock 0 991/dev.c c01db583 998/dev.c
47 spin_lock 0 547/sched.c c0112fe4 1381/sched.c
45 BKL 0 1302/inode.c c016f359 1306/inode.c
renice -20 artsd
Throughput 27.6322 MB/sec (NB=34.5402 MB/sec 276.322 MBit/sec)
7.180u 30.180s 1:17.44 48.2% 0+0k 0+0io 511pf+0w
load: 1222
Worst 20 latency times of 6170 measured in this period.
usec cause mask start line/file address end line/file
4883 spin_lock 1 547/sched.c c0112fe4 697/sched.c
3590 BKL 0 2763/buffer.c c01410aa 1381/sched.c
3192 reacqBKL 1 1375/sched.c c0114d94 697/sched.c
2647 BKL 0 1302/inode.c c016f359 697/sched.c
2286 BKL 0 1302/inode.c c016f359 1381/sched.c
2011 BKL 1 1437/namei.c c014c42f 697/sched.c
1795 BKL 1 452/exit.c c011af61 697/sched.c
1790 BKL 1 1302/inode.c c016f359 1380/sched.c
1725 reacqBKL 0 1375/sched.c c0114d94 1381/sched.c
1700 spin_lock 0 547/sched.c c0112fe4 1381/sched.c
1685 BKL 1 1437/namei.c c014c42f 1380/sched.c
1673 BKL 0 1437/namei.c c014c42f 1381/sched.c
1662 BKL 0 30/inode.c c016ce51 1381/sched.c
1575 spin_lock 0 1376/sched.c c0114db3 1380/sched.c
1565 BKL 0 533/inode.c c016d9cd 1381/sched.c
1452 BKL 0 30/inode.c c016ce51 697/sched.c
1452 BKL 0 533/inode.c c016d9cd 1380/sched.c
1445 BKL 0 927/namei.c c014b2bf 1380/sched.c
1423 BKL 0 129/attr.c c01576bd 1381/sched.c
1413 BKL 1 927/namei.c c014b2bf 697/sched.c
SunWave1#du -s /usr/data/sounds/
263404 /usr/data/sounds
SunWave1#time cp -a /usr/data/sounds/ /database/db1/data/
0.080u 5.800s 1:03.06 9.3% 0+0k 0+0io 127pf+0w
SunWave1#du -s /database/db1/data/sounds/
263404 /database/db1/data/sounds
Worst 20 latency times of 3398 measured in this period.
usec cause mask start line/file address end line/file
10155 spin_lock 1 291/buffer.c c014151c 285/buffer.c
9028 BKL 8 152/devices.c c013c282 154/devices.c
7007 keyboard 9 76/softirq.c c011c634 119/softirq.c
5999 spin_lock 8 86/softirq.c c011c66c 112/softirq.c
4201 spin_lock 1 257/vmscan.c c01331e6 286/vmscan.c
4009 spin_lock 0 978/pc_keyb.c c01a0787 983/pc_keyb.c
3000 spin_lock 1 375/memory.c c0127abf 389/memory.c
1715 spin_lock 0 468/vmscan.c c0133c35 431/vmscan.c
1387 spin_lock 0 678/inode.c c01566d7 704/inode.c
1234 reacqBKL 1 1375/sched.c c0114d94 1381/sched.c
1071 BKL 1 1302/inode.c c016f359 1380/sched.c
1049 spin_lock 1 305/dcache.c c0153acd 86/dcache.c
1049 spin_lock 1 468/vmscan.c c0133c35 344/vmscan.c
968 spin_lock 1 547/sched.c c0112fe4 697/sched.c
950 reacqBKL 0 1375/sched.c c0114d94 697/sched.c
858 eth1 0 585/irq.c c010886f 647/irq.c
803 BKL 4 927/namei.c c014b2bf 929/namei.c
736 BKL 0 452/exit.c c011af61 697/sched.c
696 BKL 4 1870/namei.c c014d420 1873/namei.c
694 BKL 0 2763/buffer.c c01410aa 1381/sched.c
c0141400 T kupdate
c014151c ..... <<<<<
c0141610 T set_buffer_async_io
next prev parent reply other threads:[~2001-09-20 21:53 UTC|newest]
Thread overview: 72+ messages / expand[flat|nested] mbox.gz Atom feed top
2001-09-19 22:44 [PATCH] Preemption Latency Measurement Tool Robert Love
2001-09-20 1:40 ` Ignacio Vazquez-Abrams
2001-09-20 2:23 ` safemode
2001-09-20 1:13 ` David Lang
2001-09-20 2:57 ` Robert Love
2001-09-20 2:38 ` Robert Love
2001-09-20 6:31 ` Dieter Nützel
2001-09-20 6:31 ` Dieter Nützel
2001-09-20 20:27 ` Robert Love
[not found] ` <200109202111.f8KLBgG16833@zero.tech9.net>
2001-09-20 22:09 ` [PATCH] Preemption patch 2.4.9-ac12 Robert Love
[not found] ` <20010920063143.424BD1E41A@Cantor.suse.de>
2001-09-20 6:41 ` [PATCH] Preemption Latency Measurement Tool Andrea Arcangeli
2001-09-20 7:57 ` Dieter Nützel
[not found] ` <20010920075751.6CA791E6B2@Cantor.suse.de>
2001-09-20 8:21 ` Andrea Arcangeli
2001-09-20 20:13 ` george anzinger
2001-09-20 20:38 ` Randy.Dunlap
2001-09-20 21:10 ` Robert Love
2001-09-20 21:35 ` Dieter Nützel
2001-09-20 22:03 ` Oliver Xymoron
2001-09-20 22:51 ` Dieter Nützel
[not found] ` <200109202252.f8KMqLG17327@zero.tech9.net>
2001-09-21 3:17 ` Robert Love
2001-09-21 15:48 ` george anzinger
2001-09-22 21:09 ` Dieter Nützel
2001-09-22 23:40 ` safemode
2001-09-22 23:46 ` Dieter Nützel
2001-09-23 0:15 ` safemode
[not found] ` <200109222340.BAA37547@blipp.internet5.net>
2001-09-23 0:38 ` Roger Larsson
2001-09-23 1:42 ` safemode
2001-09-23 3:02 ` Robert Love
2001-09-23 16:43 ` Roger Larsson
2001-09-23 0:42 ` Dieter Nützel
[not found] ` <200109222341.f8MNfnG25152@zero.tech9.net>
2001-09-23 2:50 ` Robert Love
2001-09-23 3:14 ` george anzinger
2001-09-23 4:06 ` Dieter Nützel
[not found] ` <200109222347.f8MNlMG25157@zero.tech9.net>
2001-09-23 2:54 ` Robert Love
2001-09-27 0:02 ` [reiserfs-list] " Dieter Nützel
[not found] ` <200109230016.f8N0G6G25222@zero.tech9.net>
2001-09-23 2:58 ` Robert Love
[not found] ` <200109222120.f8MLKYG24859@zero.tech9.net>
2001-09-23 2:44 ` Robert Love
[not found] ` <200109200757.JAA60995@blipp.internet5.net>
2001-09-20 17:37 ` Roger Larsson
2001-09-20 21:29 ` Robert Love
2001-09-20 21:53 ` Dieter Nützel [this message]
[not found] ` <200109200758.f8K7wEG13675@zero.tech9.net>
2001-09-20 21:09 ` Robert Love
2001-09-20 20:01 ` Tobias Diedrich
2001-09-20 22:01 ` Robert Love
2001-09-22 3:57 ` Andre Pang
2001-09-22 6:10 ` Robert Love
2001-09-22 7:22 ` Andre Pang
2001-09-23 3:18 ` george anzinger
2001-09-23 3:21 ` Robert Love
2001-09-23 7:05 ` Robert Love
2001-09-23 12:03 ` Andre Pang
2001-09-23 18:31 ` Robert Love
2001-09-22 12:56 ` ksoftirqd? (Was: Re: [PATCH] Preemption Latency Measurement Tool) Roger Larsson
2001-09-22 13:14 ` Andrea Arcangeli
2001-09-22 20:51 ` Roger Larsson
2001-09-22 21:33 ` Andrea Arcangeli
[not found] <200109202253.RAA21082@waste.org>
2001-09-20 23:15 ` [PATCH] Preemption Latency Measurement Tool Oliver Xymoron
2001-09-21 0:42 ` Roger Larsson
2001-09-21 1:03 ` Alan Cox
2001-09-21 1:22 ` Andrea Arcangeli
2001-09-21 1:51 ` Rik van Riel
2001-09-21 1:38 ` Roger Larsson
2001-09-21 1:53 ` Roger Larsson
2001-09-21 2:08 ` Roger Larsson
2001-09-21 2:29 ` Rik van Riel
2001-09-21 16:24 ` Jussi Laako
2001-09-21 16:36 ` Alan Cox
2001-09-21 18:46 ` Thomas Sailer
2001-09-22 10:30 ` Jussi Laako
2001-09-21 16:18 ` Stefan Westerfeld
2001-09-21 20:18 ` Dieter Nützel
[not found] ` <200109212018.f8LKImG21229@zero.tech9.net>
2001-09-21 21:47 ` Robert Love
-- strict thread matches above, loose matches on Subject: below --
2002-04-09 5:23 [PATCH] preemption latency measurement tool Robert Love
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20010920215309Z274666-760+14624@vger.kernel.org \
--to=dieter.nuetzel@hamburg.de \
--cc=andrea@suse.de \
--cc=linux-kernel@vger.kernel.org \
--cc=reiserfs-list@namesys.com \
--cc=rml@tech9.net \
--cc=roger.larsson@norran.net \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox