* Linux 2.6.9 latencies: 253ms in ip_tables.c:copy_entries_to_user(), 200ms in reiserfs/bitmap.c:scan_bitmap_block(), 4ms in i2c-algo-bit.c:bit_xfer()
@ 2004-10-24 21:26 Sami Farin
2004-10-25 12:00 ` Linux 2.6.9 latencies: scheduler bug? Sami Farin
0 siblings, 1 reply; 6+ messages in thread
From: Sami Farin @ 2004-10-24 21:26 UTC (permalink / raw)
To: linux-kernel Mailing List
there's a script which does
grep -Fh "^[0-9]" $BLOCKLISTS | aggregate | \
while read blocked; do
iptables -A DROP_evil_in -s $blocked -j LDROPEVILIN
iptables -A DROP_evil_out -d $blocked -j LDROPEVILOUT
done
while that's running, "rtc_latencytest 1024" has max latencies of 253ms.
$BLOCKLIST has around two thousand lines.
http://safari.iki.fi/ip_tables_original_maxlat_253ms.png
from pressing sysrq+p while it was running, I guesstimated one evil spot
and added cond_resched() in there :)
http://safari.iki.fi/ip_tables_cond_resched.png
at 5s I started the script.
then there's this 200ms latency when doing "cp /dev/zero ." on reiserfs.
http://safari.iki.fi/2.6.9-no_reiserfs_cond_resched.png
sysrq+p pointed to scan_bitmap_block ... :) (I also used profile=2)
after adding cond_resched in there, max latency 2.4ms
http://safari.iki.fi/2.6.9-with_reiserfs_cond_resched.png
"cp /dev/zero ." consumes 90% CPU time in system...
reading the same file from disk needs 8% CPU.
is my partition just so fragmented or full?
EIP is at reiserfs_in_journal+0x82/0x168
EFLAGS: 00000206 Not tainted (2.6.9-exec-shield)
EAX: 00008000 EBX: 00408000 ECX: 000011b3 EDX: cf202e00
ESI: 00000005 EDI: 0000011c EBP: c73a7c2c DS: 007b ES: 007b
CR0: 8005003b CR2: b7fda000 CR3: 091cb000 CR4: 000002d0
[<c010425d>] show_regs+0x115/0x120
[<c02768b8>] sysrq_handle_showregs+0x10/0x14
[<c0276a3b>] __handle_sysrq+0x5f/0xe8
[<c0276ae1>] handle_sysrq+0x1d/0x21
[<c02709ee>] kbd_keycode+0x12e/0x2d8
[<c0270c1c>] kbd_event+0x84/0xbc
[<c02d883c>] input_event+0x3ac/0x3d0
[<c02db9da>] atkbd_report_key+0x3a/0x5c
[<c02dbf3b>] atkbd_interrupt+0x53f/0x5b8
[<c0282fb0>] serio_interrupt+0x30/0x65
[<c028357b>] i8042_interrupt+0x14b/0x15c
[<c0108230>] handle_IRQ_event+0x28/0x5c
[<c010852e>] do_IRQ+0xa2/0x114
[<c010679c>] common_interrupt+0x18/0x20
[<c01816c8>] scan_bitmap_block+0xb8/0x28c
[<c0181ac0>] scan_bitmap+0x15c/0x1ac
[<c0182ce5>] reiserfs_allocate_blocknrs+0x415/0x4f8
[<c018cf17>] reiserfs_allocate_blocks_for_region+0x187/0x1314
[<c018f356>] reiserfs_file_write+0x482/0x630
[<c014e659>] vfs_write+0xb5/0xec
[<c014e734>] sys_write+0x3c/0x68
[<c0105e2f>] syscall_call+0x7/0xb
also, there's 4ms latency every five seconds, when I am running xawtv
in stereo mode. I have BT878 and MSP3400.
http://safari.iki.fi/3.7ms-with-xawtv.png
http://safari.iki.fi/1.6ms-without-xawtv.png
turned out the culprit is msp3400 -- it checks every five secs
audio state (stereo/mono/...) which calls i2c_master_send.
http://safari.iki.fi/i2c-msp3400-cond_resched.png
http://safari.iki.fi/i2c-msp3400-cond_resched-switching_channels.png
WARNING: I don't know are those cond_rescheds safe to call,
but I haven't gotten panics because of them yet.
Someone who actually has a clue might want to tell are they safe
or where would be a better place to do cond_resched.
...uhhh, and I have low-end Celeron system running UP non-preempt kernel.
--- linux/net/ipv4/netfilter/ip_tables.c.bak 2004-10-19 23:40:28.000000000 +0300
+++ linux/net/ipv4/netfilter/ip_tables.c 2004-10-24 19:15:54.000000000 +0300
@@ -976,6 +976,7 @@ copy_entries_to_user(unsigned int total_
struct ipt_entry_match *m;
struct ipt_entry_target *t;
+ cond_resched();
e = (struct ipt_entry *)(table->private->entries + off);
if (copy_to_user(userptr + off
+ offsetof(struct ipt_entry, counters),
--- linux/fs/reiserfs/bitmap.c.condresched 2004-08-14 08:37:25.000000000 +0300
+++ linux/fs/reiserfs/bitmap.c 2004-10-20 18:12:31.000000000 +0300
@@ -155,6 +155,7 @@ static int scan_bitmap_block (struct rei
while (1) {
cont:
+ cond_resched();
if (bi->free_count < min)
return 0; // No free blocks in this bitmap
--- linux/drivers/i2c/algos/i2c-algo-bit.c.bak 2004-10-19 23:38:52.000000000 +0300
+++ linux/drivers/i2c/algos/i2c-algo-bit.c 2004-10-24 23:29:12.000000000 +0300
@@ -153,6 +153,7 @@ static int i2c_outb(struct i2c_adapter *
int ack;
struct i2c_algo_bit_data *adap = i2c_adap->algo_data;
+ cond_resched();
/* assert: scl is low */
for ( i=7 ; i>=0 ; i-- ) {
sb = c & ( 1 << i );
@@ -195,6 +196,7 @@ static int i2c_inb(struct i2c_adapter *i
unsigned char indata=0;
struct i2c_algo_bit_data *adap = i2c_adap->algo_data;
+ cond_resched();
/* assert: scl is low */
sdahi(adap);
for (i=0;i<8;i++) {
--
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: Linux 2.6.9 latencies: scheduler bug?
2004-10-24 21:26 Linux 2.6.9 latencies: 253ms in ip_tables.c:copy_entries_to_user(), 200ms in reiserfs/bitmap.c:scan_bitmap_block(), 4ms in i2c-algo-bit.c:bit_xfer() Sami Farin
@ 2004-10-25 12:00 ` Sami Farin
2004-10-25 12:43 ` Nick Piggin
2004-10-25 12:58 ` Ingo Molnar
0 siblings, 2 replies; 6+ messages in thread
From: Sami Farin @ 2004-10-25 12:00 UTC (permalink / raw)
To: linux-kernel Mailing List; +Cc: Ingo Molnar
On Mon, Oct 25, 2004 at 12:26:18AM +0300, Sami Farin wrote:
...
> while that's running, "rtc_latencytest 1024" has max latencies of 253ms.
> $BLOCKLIST has around two thousand lines.
> http://safari.iki.fi/ip_tables_original_maxlat_253ms.png
> from pressing sysrq+p while it was running, I guesstimated one evil spot
> and added cond_resched() in there :)
> http://safari.iki.fi/ip_tables_cond_resched.png
> at 5s I started the script.
forget this stupid ip_tables.c patch, latencies have nothing to do with
netfilter code, but bad interaction between xmms, rtc_latencytest
and iptables. I now get at max 3.1s (yup, 3100000us) latencies.
http://safari.iki.fi/2.6.9-xmms-fun-1.png
if you want to reproduce this:
1) run "rtc_latencytest 1024" (can't reproduce with "rtc_latencytest 512")
2) press play in xmms
3) start iptables-script
xmms has to be prepared first.
a) put it in repeat mode
b) start playing >= 2 files (like that short testcase.mp3 from lame)
c) remove the files while xmms is playing
d) wait till xmms has played all of the selected files
e) press stop [now then you press play in 2), xmms does silly infinite
loop without delays while trying to open the songs]
please give me patches to try, 3.1s is really evil 8-)
the iptables-loop is
iptables -N FSCKMEHARDER
cat /service/rbldnsd/dsbl.org/rbldns-list.dsbl.org | while read ip;
do iptables -A FSCKMEHARDER -p tcp -s $ip -j DROP;
done
alternatively, you can generate random IPs, doesn't probably
make any difference.
I have xorg-x11-6.8.1-12 and Matrox G200, if that matters.
xmms is doing these system calls...
$ awk '{print $3}' xmms-strace.txt |sort|uniq -c|sort -n
1 close(-1
1 setup(
7 nanosleep({0,
18 gettimeofday({1098704731,
35 select(5,
43 gettimeofday({1098704728,
47 gettimeofday({1098704729,
47 gettimeofday({1098704730,
83 <...
154 close(-1)
155 ioctl(3,
155 poll([{fd=3,
155 readv(3,
312 open("/var/temp/testcase.mp3",
385 open("/var/temp/testcase.mp3.wav",
465 write(3,
466 select(4,
930 read(3,
/proc/vmstat before and after running rtc_latencytest.
before
nr_dirty 0
nr_writeback 0
nr_unstable 0
nr_page_table_pages 919
nr_mapped 46485
nr_slab 4320
pgpgin 1235396
pgpgout 532242
pswpin 9795
pswpout 32253
pgalloc_high 0
pgalloc_normal 30934240
pgalloc_dma 18350
pgfree 30955504
pgactivate 187837
pgdeactivate 157183
pgfault 19090447
pgmajfault 7616
pgrefill_high 0
pgrefill_normal 3472213
pgrefill_dma 76329
pgsteal_high 0
pgsteal_normal 341889
pgsteal_dma 4460
pgscan_kswapd_high 0
pgscan_kswapd_normal 423918
pgscan_kswapd_dma 5894
pgscan_direct_high 0
pgscan_direct_normal 14982
pgscan_direct_dma 0
pginodesteal 0
slabs_scanned 397568
kswapd_steal 343850
kswapd_inodesteal 35158
pageoutrun 11989
allocstall 49
pgrotated 29549
after
nr_dirty 0
nr_writeback 0
nr_unstable 0
nr_page_table_pages 919
nr_mapped 46496
nr_slab 4334
pgpgin 1235396
pgpgout 532286
pswpin 9795
pswpout 32253
pgalloc_high 0
pgalloc_normal 31500853
pgalloc_dma 18771
pgfree 31522633
pgactivate 188101
pgdeactivate 157185
pgfault 19627511
pgmajfault 7616
pgrefill_high 0
pgrefill_normal 3474226
pgrefill_dma 76395
pgsteal_high 0
pgsteal_normal 342045
pgsteal_dma 4460
pgscan_kswapd_high 0
pgscan_kswapd_normal 424347
pgscan_kswapd_dma 5894
pgscan_direct_high 0
pgscan_direct_normal 14982
pgscan_direct_dma 0
pginodesteal 0
slabs_scanned 397696
kswapd_steal 344006
kswapd_inodesteal 35158
pageoutrun 11994
allocstall 49
pgrotated 29549
vmstat 1 wasn't very special.
procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
4 1 119480 10384 11444 45444 0 0 0 4 2100 1837 49 51 0 0
3 1 119480 10264 11444 45444 0 0 0 0 2095 2238 41 59 0 0
3 1 119480 9424 11444 45444 0 0 0 0 2088 1923 37 63 0 0
3 1 119480 10804 11444 45444 0 0 0 0 2087 998 40 60 0 0
--
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: Linux 2.6.9 latencies: scheduler bug?
2004-10-25 12:00 ` Linux 2.6.9 latencies: scheduler bug? Sami Farin
@ 2004-10-25 12:43 ` Nick Piggin
2004-10-25 12:53 ` Sami Farin
2004-10-25 12:58 ` Ingo Molnar
1 sibling, 1 reply; 6+ messages in thread
From: Nick Piggin @ 2004-10-25 12:43 UTC (permalink / raw)
To: Sami Farin; +Cc: linux-kernel Mailing List, Ingo Molnar
Sami Farin wrote:
> On Mon, Oct 25, 2004 at 12:26:18AM +0300, Sami Farin wrote:
> ...
>
>>while that's running, "rtc_latencytest 1024" has max latencies of 253ms.
>>$BLOCKLIST has around two thousand lines.
>>http://safari.iki.fi/ip_tables_original_maxlat_253ms.png
>>from pressing sysrq+p while it was running, I guesstimated one evil spot
>>and added cond_resched() in there :)
>>http://safari.iki.fi/ip_tables_cond_resched.png
>>at 5s I started the script.
>
>
> forget this stupid ip_tables.c patch, latencies have nothing to do with
> netfilter code, but bad interaction between xmms, rtc_latencytest
> and iptables. I now get at max 3.1s (yup, 3100000us) latencies.
> http://safari.iki.fi/2.6.9-xmms-fun-1.png
> if you want to reproduce this:
> 1) run "rtc_latencytest 1024" (can't reproduce with "rtc_latencytest 512")
> 2) press play in xmms
> 3) start iptables-script
>
> xmms has to be prepared first.
> a) put it in repeat mode
> b) start playing >= 2 files (like that short testcase.mp3 from lame)
> c) remove the files while xmms is playing
> d) wait till xmms has played all of the selected files
> e) press stop [now then you press play in 2), xmms does silly infinite
> loop without delays while trying to open the songs]
>
> please give me patches to try, 3.1s is really evil 8-)
>
Don't think I've tried rtc_latency test. A quick search didn't turn
up its source code...
So... stupid question, is rtc_latencytest running with a realtime
scheduling policy?
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Linux 2.6.9 latencies: scheduler bug?
2004-10-25 12:00 ` Linux 2.6.9 latencies: scheduler bug? Sami Farin
2004-10-25 12:43 ` Nick Piggin
@ 2004-10-25 12:58 ` Ingo Molnar
2004-10-25 13:11 ` Sami Farin
1 sibling, 1 reply; 6+ messages in thread
From: Ingo Molnar @ 2004-10-25 12:58 UTC (permalink / raw)
To: linux-kernel Mailing List; +Cc: Sami Farin
* Sami Farin <7atbggg02@sneakemail.com> wrote:
> forget this stupid ip_tables.c patch, latencies have nothing to do with
> netfilter code, but bad interaction between xmms, rtc_latencytest
> and iptables. I now get at max 3.1s (yup, 3100000us) latencies.
> http://safari.iki.fi/2.6.9-xmms-fun-1.png
> if you want to reproduce this:
> 1) run "rtc_latencytest 1024" (can't reproduce with "rtc_latencytest 512")
> 2) press play in xmms
> 3) start iptables-script
to further debug any latencies please apply the -RT patchset and enable
PREEMPT_TIMING (and LATENCY_TRACING), that enables us to tell us more
about the latencies. You dont have to enable PREEMPT_REALTIME (the most
experimental feature of the patchset) to measure latencies.
Ingo
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Linux 2.6.9 latencies: scheduler bug?
2004-10-25 12:58 ` Ingo Molnar
@ 2004-10-25 13:11 ` Sami Farin
0 siblings, 0 replies; 6+ messages in thread
From: Sami Farin @ 2004-10-25 13:11 UTC (permalink / raw)
To: linux-kernel Mailing List
On Mon, Oct 25, 2004 at 02:58:07PM +0200, Ingo Molnar wrote:
>
> * Sami Farin <7atbggg02@sneakemail.com> wrote:
>
> > forget this stupid ip_tables.c patch, latencies have nothing to do with
> > netfilter code, but bad interaction between xmms, rtc_latencytest
> > and iptables. I now get at max 3.1s (yup, 3100000us) latencies.
> > http://safari.iki.fi/2.6.9-xmms-fun-1.png
> > if you want to reproduce this:
> > 1) run "rtc_latencytest 1024" (can't reproduce with "rtc_latencytest 512")
> > 2) press play in xmms
> > 3) start iptables-script
>
> to further debug any latencies please apply the -RT patchset
which includes also -mm1...
> and enable PREEMPT_TIMING (and LATENCY_TRACING), that enables us to tell us more
I guess those are not available as individual patches which could be
applied to 2.6.9?
Could someone with LATENCY_TRACING+PREEMPT_TIMING try to reproduce
that xmms/rtc_latencytest/iptables thing... takes only a minute.
Pretty please?
> about the latencies. You dont have to enable PREEMPT_REALTIME (the most
> experimental feature of the patchset) to measure latencies.
>
> Ingo
--
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2004-10-25 13:11 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2004-10-24 21:26 Linux 2.6.9 latencies: 253ms in ip_tables.c:copy_entries_to_user(), 200ms in reiserfs/bitmap.c:scan_bitmap_block(), 4ms in i2c-algo-bit.c:bit_xfer() Sami Farin
2004-10-25 12:00 ` Linux 2.6.9 latencies: scheduler bug? Sami Farin
2004-10-25 12:43 ` Nick Piggin
2004-10-25 12:53 ` Sami Farin
2004-10-25 12:58 ` Ingo Molnar
2004-10-25 13:11 ` Sami Farin
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
