Re: ksoftirqd using mysteriously high amounts of CPU time

Re: ksoftirqd using mysteriously high amounts of CPU time

[Brad Laue]

Hmamouche, Youssef wrote:
  > Is there any way you could replace one of the network cards and 
test? I have a
> feeling it's a hardware problem where the interrupt never gets acknowledged in
> some situations - ksoftirq gets crazy.
> 
> you

This has occurred on any combination of the following six things:

Network cards:
Realtek 8139
SiS 900 Integrated
NE2K
3Com 3c905b

Motherboard chipsets:
ALI M1541
SiS 740
AMD 760

On the following kernel versions: 2.4.20, 2.4.21, 2.4.22, 2.4.23 (and 
-aa variants of 2.4.22, .23), 2.6.1, 2.6.2, 2.6.3.

It could well be a BIOS setting I'm habitually setting and forgetting 
about which is common to all motherboards, I'll have to check on that. 
Are there any of these I should be looking out for?

ksoftirqd using mysteriously high amounts of CPU time

[Brad Laue]

Greetings, all

I'm running into an issue where ksoftirqd/0 consumes a considerably 
larger amount of CPU time  than it should, and begins to actively 
consume 99% CPU time during network operations.

I've done my best to diagnose this, but it has followed me from kernel 
2.4.20 to 2.6.3 and all versions in between, on three different server 
systems with distinct hardware configurations.

The latest system to be affected by this takes considerably longer to 
have trouble, but this is only due to its sheer muscle to begin with (2x 
MP 2800+), but does indeed appear. After 55 days of uptime:

5 root      34  19     0    0    0 S  0.0  0.0   0:21.40 ksoftirqd_CPU0
6 root      34  19     0    0    0 S  0.0  0.0   0:36.31 ksoftirqd_CPU1

Compare this to another machine which I don't run myself:

3 root      19  19     0    0    0 S  0.0  0.0   0:09.86 ksoftirqd_CPU0

There are peculiarities to my configuration which are shared on all the 
affected machines - the use of PPPoE to connect is one example. However 
on one of the affected systems a second network interface was subjected 
to heavy NFS traffic over simple ethernet and exhibited the same 
behavior. Another shared trait is a firewall ruleset I've written for 
the machines, which I can attach if someone would like to see them.

The three configurations include:

K6-2 500MHz
Ne2K, RealTek 8139

Duron 900MHz
SiS 900, RealTek 8139

2x Athlon MP 2800+
3com 3c905b 10/100+

The issue begins with ksoftirqd consuming more time than usual, and ends 
after four to twelve weeks depending on how powerful the machine, with 
the machine crippled and unable to sustain network traffic of any kind. 
Any assistance on where to look for solutions to this kind of problem 
would be GREATLY appreciated.

Thanks in advance!

Brad

Re: ksoftirqd using mysteriously high amounts of CPU time

[Andrew Morton]

Brad Laue <brad@brad-x.com> wrote:
>
> I'm running into an issue where ksoftirqd/0 consumes a considerably 
> larger amount of CPU time  than it should, and begins to actively 
> consume 99% CPU time during network operations.

Please ensure that the machine was booted with `profile=1' on
the kernel boot command line.  The cost of this is negligible.

When the problem starts happening, run:

sudo readprofile -r
sleep 10
sudo readprofile -n -v -m /boot/System.map | sort -n +2 | tail -40

(make sure that /boot/System.map refers to the currently-running kernel)

Re: ksoftirqd using mysteriously high amounts of CPU time

[Brad Laue]

Andrew Morton wrote:
> Please ensure that the machine was booted with `profile=1' on
> the kernel boot command line.  The cost of this is negligible.
> 
> When the problem starts happening, run:
> 
> sudo readprofile -r
> sleep 10
> sudo readprofile -n -v -m /boot/System.map | sort -n +2 | tail -40
> 
> (make sure that /boot/System.map refers to the currently-running kernel)


Gave the machine a bit of a workout to create the problem sooner than 
usual, albeit on a smaller scale. ksoftirqd consumed about 4.7% of the 
CPU according to top after several concurrent wget operations, and had 
accumulated about 6 seconds of runtime, unheard of for a system uptime 
of 15 minutes; the output attached is during this.

Hopefully I'm right in assuming that; on all other systems I've 
experimented with ksoftirqd doesn't even flinch unless subjected to 
extremes.

Did some further testing with a machine of identical configuration 
(suffers the same issue too); removed iptables from the suspects list, 
as the issue exists sans those modules.

Hopefully the attached shows some irregularity. If not, I'll have to 
reply back in a few weeks when the problem recurs over the course of time.

Cheers,
Brad

Re: ksoftirqd using mysteriously high amounts of CPU time

[Brad Laue]

[-- Attachment #1: Type: text/plain, Size: 239 bytes --]

Brad Laue wrote:
> Hopefully the attached shows some irregularity. If not, I'll have to 
> reply back in a few weeks when the problem recurs over the course of time.

And without further ado, the attachment. It's been a long day. :)

Brad

[-- Attachment #2: profile.txt --]
[-- Type: text/plain, Size: 2640 bytes --]

c0122bf0 current_kernel_time                           2   0.0312
c0122d20 local_bh_enable                               2   0.0139
c0137800 unlock_page                                   2   0.0208
c013ef10 __kmalloc                                     2   0.0156
c0155630 mark_buffer_dirty                             2   0.0250
c0165760 poll_freewait                                 2   0.0250
c01df2b0 xfs_ichgtime                                  2   0.0075
c0202780 linvfs_get_block_core                         2   0.0027
c0205310 linvfs_write                                  2   0.0069
c0216e90 fast_copy_page                                2   0.0078
c0244b90 tty_write                                     2   0.0030
c0246020 tty_poll                                      2   0.0156
c0248670 n_tty_receive_buf                             2   0.0005
c024b1e0 pty_unthrottle                                2   0.0208
c024b240 pty_write                                     2   0.0043
c0109354 system_call                                   3   0.0682
c0152e70 vfs_write                                     3   0.0099
c0157cd0 alloc_buffer_head                             3   0.0312
c01657b0 __pollwait                                    3   0.0144
c016e100 dnotify_parent                                3   0.0156
c01b1e50 xfs_bmapi                                     3   0.0006
c024a3a0 normal_poll                                   3   0.0088
c0107090 cpu_idle                                      4   0.0625
c0153e60 fget                                          4   0.0625
c0165c60 sys_select                                    4   0.0032
c0216e30 fast_clear_page                               4   0.0417
c0139280 generic_file_aio_write_nolock                 5   0.0019
c0209d60 xfs_write                                     6   0.0028
c011ba10 __wake_up                                     7   0.0729
c0165960 do_select                                     8   0.0111
c0249920 read_chan                                     9   0.0042
c0156170 __block_prepare_write                        12   0.0117
c02173c0 __copy_from_user_ll                          12   0.0938
c010b570 handle_IRQ_event                             13   0.1161
c0187210 write_profile                                14   0.2188
c011b3c0 schedule                                     15   0.0107
c0217350 __copy_to_user_ll                            47   0.4196
c0122c80 do_softirq                                  136   0.8500
c0107030 default_idle                               9222 192.1250
00000000 total                                      9611   0.0063

Re: ksoftirqd using mysteriously high amounts of CPU time

[Andrew Morton]

Brad Laue <brad@brad-x.com> wrote:
>
>  Brad Laue wrote:
>  > Hopefully the attached shows some irregularity. If not, I'll have to 
>  > reply back in a few weeks when the problem recurs over the course of time.
> 
>  And without further ado, the attachment. It's been a long day. :)

It beats me.  Something must be waking up ksoftirqd all the time.

If you have time, could you please apply the below, then wait for ksoftirqd
to go bad again and then run:


	dmesg -c
	echo 1 > /proc/sys/debug/0 ; sleep 1; echo 0 > /proc/sys/debug/0
	dmesg -s 1000000 > /tmp/foo

and then send foo?


diff -puN include/linux/kernel.h~proc-sys-debug include/linux/kernel.h
--- 25/include/linux/kernel.h~proc-sys-debug	2004-02-25 23:12:56.000000000 -0800
+++ 25-akpm/include/linux/kernel.h	2004-02-25 23:12:57.000000000 -0800
@@ -214,6 +214,8 @@ extern void dump_stack(void);
 	1; \
 })
 
+extern int proc_sys_debug[8];
+
 #endif /* __KERNEL__ */
 
 #define SI_LOAD_SHIFT	16
diff -puN -L kernel/ksyms.c /dev/null /dev/null
diff -puN kernel/sysctl.c~proc-sys-debug kernel/sysctl.c
--- 25/kernel/sysctl.c~proc-sys-debug	2004-02-25 23:12:56.000000000 -0800
+++ 25-akpm/kernel/sysctl.c	2004-02-25 23:21:37.000000000 -0800
@@ -849,7 +849,26 @@ static ctl_table fs_table[] = {
 	{ .ctl_name = 0 }
 };
 
+int proc_sys_debug[8];
+EXPORT_SYMBOL(proc_sys_debug);
+
 static ctl_table debug_table[] = {
+	{1, "0", &proc_sys_debug[0], sizeof(int), 0644, NULL,
+	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
+	{2, "1", &proc_sys_debug[1], sizeof(int), 0644, NULL,
+	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
+	{3, "2", &proc_sys_debug[2], sizeof(int), 0644, NULL,
+	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
+	{4, "3", &proc_sys_debug[3], sizeof(int), 0644, NULL,
+	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
+	{5, "4", &proc_sys_debug[4], sizeof(int), 0644, NULL,
+	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
+	{6, "5", &proc_sys_debug[5], sizeof(int), 0644, NULL,
+	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
+	{7, "6", &proc_sys_debug[6], sizeof(int), 0644, NULL,
+	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
+	{8, "7", &proc_sys_debug[7], sizeof(int), 0644, NULL,
+	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
 	{ .ctl_name = 0 }
 };
 

_
 kernel/softirq.c |    7 ++++++-
 1 files changed, 6 insertions(+), 1 deletion(-)

diff -puN kernel/softirq.c~a kernel/softirq.c
--- 25/kernel/softirq.c~a	2004-03-11 02:05:20.000000000 -0800
+++ 25-akpm/kernel/softirq.c	2004-03-11 02:06:02.000000000 -0800
@@ -54,8 +54,13 @@ static inline void wakeup_softirqd(void)
 	/* Interrupts are disabled: no need to stop preemption */
 	struct task_struct *tsk = __get_cpu_var(ksoftirqd);
 
-	if (tsk && tsk->state != TASK_RUNNING)
+	if (tsk && tsk->state != TASK_RUNNING) {
+		if (proc_sys_debug[0]) {
+			printk("%s wakes ksoftirqd\n", current->comm);
+			dump_stack();
+		}
 		wake_up_process(tsk);
+	}
 }
 
 /*

_

Re: ksoftirqd using mysteriously high amounts of CPU time

[Yury V. Umanets]

On Thu, 2004-03-11 at 12:08, Andrew Morton wrote:
> Brad Laue <brad@brad-x.com> wrote:
> >
> >  Brad Laue wrote:
> >  > Hopefully the attached shows some irregularity. If not, I'll have to 
> >  > reply back in a few weeks when the problem recurs over the course of time.
> > 
> >  And without further ado, the attachment. It's been a long day. :)
> 
> It beats me.  Something must be waking up ksoftirqd all the time.

Hello,

I have impression, that it is somehow related to ACPI and CPU
temperature. When CPU gets more hot ksoftirqd starts to eat 99% of CPU.

It may be checked by disabling ACPI (if enabled) and/or monitoring
/proc/acpi/thermal_zone/THRM/temperature (if any).

> 
> If you have time, could you please apply the below, then wait for ksoftirqd
> to go bad again and then run:
> 
> 
> 	dmesg -c
> 	echo 1 > /proc/sys/debug/0 ; sleep 1; echo 0 > /proc/sys/debug/0
> 	dmesg -s 1000000 > /tmp/foo
> 
> and then send foo?
> 
> 
> diff -puN include/linux/kernel.h~proc-sys-debug include/linux/kernel.h
> --- 25/include/linux/kernel.h~proc-sys-debug	2004-02-25 23:12:56.000000000 -0800
> +++ 25-akpm/include/linux/kernel.h	2004-02-25 23:12:57.000000000 -0800
> @@ -214,6 +214,8 @@ extern void dump_stack(void);
>  	1; \
>  })
>  
> +extern int proc_sys_debug[8];
> +
>  #endif /* __KERNEL__ */
>  
>  #define SI_LOAD_SHIFT	16
> diff -puN -L kernel/ksyms.c /dev/null /dev/null
> diff -puN kernel/sysctl.c~proc-sys-debug kernel/sysctl.c
> --- 25/kernel/sysctl.c~proc-sys-debug	2004-02-25 23:12:56.000000000 -0800
> +++ 25-akpm/kernel/sysctl.c	2004-02-25 23:21:37.000000000 -0800
> @@ -849,7 +849,26 @@ static ctl_table fs_table[] = {
>  	{ .ctl_name = 0 }
>  };
>  
> +int proc_sys_debug[8];
> +EXPORT_SYMBOL(proc_sys_debug);
> +
>  static ctl_table debug_table[] = {
> +	{1, "0", &proc_sys_debug[0], sizeof(int), 0644, NULL,
> +	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
> +	{2, "1", &proc_sys_debug[1], sizeof(int), 0644, NULL,
> +	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
> +	{3, "2", &proc_sys_debug[2], sizeof(int), 0644, NULL,
> +	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
> +	{4, "3", &proc_sys_debug[3], sizeof(int), 0644, NULL,
> +	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
> +	{5, "4", &proc_sys_debug[4], sizeof(int), 0644, NULL,
> +	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
> +	{6, "5", &proc_sys_debug[5], sizeof(int), 0644, NULL,
> +	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
> +	{7, "6", &proc_sys_debug[6], sizeof(int), 0644, NULL,
> +	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
> +	{8, "7", &proc_sys_debug[7], sizeof(int), 0644, NULL,
> +	 &proc_dointvec_minmax, &sysctl_intvec, NULL, NULL, NULL},
>  	{ .ctl_name = 0 }
>  };
>  
> 
> _
>  kernel/softirq.c |    7 ++++++-
>  1 files changed, 6 insertions(+), 1 deletion(-)
> 
> diff -puN kernel/softirq.c~a kernel/softirq.c
> --- 25/kernel/softirq.c~a	2004-03-11 02:05:20.000000000 -0800
> +++ 25-akpm/kernel/softirq.c	2004-03-11 02:06:02.000000000 -0800
> @@ -54,8 +54,13 @@ static inline void wakeup_softirqd(void)
>  	/* Interrupts are disabled: no need to stop preemption */
>  	struct task_struct *tsk = __get_cpu_var(ksoftirqd);
>  
> -	if (tsk && tsk->state != TASK_RUNNING)
> +	if (tsk && tsk->state != TASK_RUNNING) {
> +		if (proc_sys_debug[0]) {
> +			printk("%s wakes ksoftirqd\n", current->comm);
> +			dump_stack();
> +		}
>  		wake_up_process(tsk);
> +	}
>  }
>  
>  /*
> 
> _
> 
> -
> 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/
-- 
umka

Re: ksoftirqd using mysteriously high amounts of CPU time

[Brad Laue]

Yury V. Umanets wrote:
> Hello,
> 
> I have impression, that it is somehow related to ACPI and CPU
> temperature. When CPU gets more hot ksoftirqd starts to eat 99% of CPU.
> 
> It may be checked by disabling ACPI (if enabled) and/or monitoring
> /proc/acpi/thermal_zone/THRM/temperature (if any).

Happens on a system without ACPI or Power Management of any kind enabled 
though.

Brad

Re: ksoftirqd using mysteriously high amounts of CPU time

[Yury V. Umanets]

On Thu, 2004-03-11 at 19:22, Brad Laue wrote:
> Yury V. Umanets wrote:
> > Hello,
> > 
> > I have impression, that it is somehow related to ACPI and CPU
> > temperature. When CPU gets more hot ksoftirqd starts to eat 99% of CPU.
> > 
> > It may be checked by disabling ACPI (if enabled) and/or monitoring
> > /proc/acpi/thermal_zone/THRM/temperature (if any).
> 
> Happens on a system without ACPI or Power Management of any kind enabled 
> though.
> 
> Brad
Then have you seen clear dependence of ksoftirqd getting crazy on system
load? Or something else?

> -
> 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/
-- 
umka

Re: ksoftirqd using mysteriously high amounts of CPU time

[Brad Laue]

Yury V. Umanets wrote:
> On Thu, 2004-03-11 at 19:22, Brad Laue wrote:
> 
>>Yury V. Umanets wrote:
>>
>>>Hello,
>>>
>>>I have impression, that it is somehow related to ACPI and CPU
>>>temperature. When CPU gets more hot ksoftirqd starts to eat 99% of CPU.
>>>
>>>It may be checked by disabling ACPI (if enabled) and/or monitoring
>>>/proc/acpi/thermal_zone/THRM/temperature (if any).
>>
>>Happens on a system without ACPI or Power Management of any kind enabled 
>>though.
>>
>>Brad
> 
> Then have you seen clear dependence of ksoftirqd getting crazy on system
> load? Or something else?

Not sure what you mean; when the problem begins to get bad, anything 
that tries to use a network interface causes ksoftirqd to jump to 99% 
CPU, and eventually it just stays there at idle. The process trying to 
use the network uses abnormal amounts of CPU time as well.

Brad

Re: ksoftirqd using mysteriously high amounts of CPU time

[Brad Laue]

Andrew Morton wrote:
> Brad Laue <brad@brad-x.com> wrote:
> 
>> Brad Laue wrote:
>> > Hopefully the attached shows some irregularity. If not, I'll have to 
>> > reply back in a few weeks when the problem recurs over the course of time.
>>
>> And without further ado, the attachment. It's been a long day. :)
> 
> 
> It beats me.  Something must be waking up ksoftirqd all the time.
> 
> If you have time, could you please apply the below, then wait for ksoftirqd
> to go bad again and then run:
> 
> 
> 	dmesg -c
> 	echo 1 > /proc/sys/debug/0 ; sleep 1; echo 0 > /proc/sys/debug/0
> 	dmesg -s 1000000 > /tmp/foo
> 
> and then send foo?

Will do. I think the profile output I generated was a bit premature. 
I'll wait a few days until the problem resurfaces in earnest and attach 
some more output then.

For now, it looks like the 'pppoe' process itself is waking up ksoftirqd 
the most according to the output of dmesg, but that may change with time.

Will keep you posted.

Brad

Re: ksoftirqd using mysteriously high amounts of CPU time

[Brad Laue]

[-- Attachment #1: Type: text/plain, Size: 1264 bytes --]

Andrew Morton wrote:
> Brad Laue <brad@brad-x.com> wrote:
> 
>> Brad Laue wrote:
>> > Hopefully the attached shows some irregularity. If not, I'll have to 
>> > reply back in a few weeks when the problem recurs over the course of time.
>>
>> And without further ado, the attachment. It's been a long day. :)
> 
> 
> It beats me.  Something must be waking up ksoftirqd all the time.
> 
> If you have time, could you please apply the below, then wait for ksoftirqd
> to go bad again and then run:
> 
> 
> 	dmesg -c
> 	echo 1 > /proc/sys/debug/0 ; sleep 1; echo 0 > /proc/sys/debug/0
> 	dmesg -s 1000000 > /tmp/foo
> 
> and then send foo?
> 

Okay, it looks like the 'pppoe' process is definitely causing all the
soft interrupts. Puzzling, because on other systems with similar
hardware this doesn't happen. Ran the machine without iptables running
(eek!!!) just to make sure, and the same result occurred, so it doesn't
seem to be the fact that packets are going through an elaborate ruleset
that's causing it. Kernel mode PPPoE doesn't seem to change things much.

Hard to figure out from a kernel perspective why this many soft 
interrupts are being used, but I'm just getting a grasp on what their 
purpose is to begin with.

Hope this offers some insight.

Brad

[-- Attachment #2: wakes_softirqd --]
[-- Type: text/plain, Size: 15050 bytes --]

ction+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c02978b3>] net_tx_action+0x83/0xd0
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c02978b3>] net_tx_action+0x83/0xd0
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb

pppoe wakes ksoftirqd
Call Trace:
 [<c0121e6c>] __tasklet_schedule+0x7c/0x80
 [<d084656c>] ppp_asynctty_receive+0xbc/0xd0 [ppp_async]
 [<c024a342>] pty_write+0x142/0x1d0
 [<c0249333>] write_chan+0x1f3/0x220
 [<c011a910>] default_wake_function+0x0/0x20
 [<c011a910>] default_wake_function+0x0/0x20
 [<c0243d38>] tty_write+0x1e8/0x290
 [<c0249140>] write_chan+0x0/0x220
 [<c0243b50>] tty_write+0x0/0x290
 [<c0151fa8>] vfs_write+0xb8/0x130
 [<c01520d2>] sys_write+0x42/0x70
 [<c0109387>] syscall_call+0x7/0xb



[-- Attachment #3: profile --]
[-- Type: text/plain, Size: 2641 bytes --]

c013df00 kmem_cache_alloc                              2   0.0312
c013df90 __kmalloc                                     2   0.0156
c01d8900 xfs_ilock                                     2   0.0114
c0204390 linvfs_write                                  2   0.0069
c02475f0 n_tty_write_wakeup                            2   0.0312
c0247630 n_tty_receive_buf                             2   0.0005
c024a200 pty_write                                     2   0.0043
c0121cc0 local_bh_enable                               3   0.0208
c016d180 dnotify_parent                                3   0.0156
c0215eb0 fast_clear_page                               3   0.0312
c0109354 system_call                                   4   0.0909
c0138300 generic_file_aio_write_nolock                 4   0.0015
c0151e30 do_sync_write                                 4   0.0208
c0151ef0 vfs_write                                     4   0.0132
c0155e10 generic_commit_write                          4   0.0227
c0164ce0 sys_select                                    4   0.0032
c016bde0 inode_update_time                             4   0.0192
c0243a00 tty_read                                      4   0.0119
c0243b50 tty_write                                     4   0.0061
c0126040 run_timer_softirq                             5   0.0116
c013a580 free_hot_cold_page                            5   0.0195
c0164900 max_select_fd                                 5   0.0223
c0215974 csum_partial                                  5   0.0174
c02488e0 read_chan                                     5   0.0023
c0152ee0 fget                                          6   0.0938
c01551f0 __block_prepare_write                         6   0.0059
c01649e0 do_select                                     6   0.0083
c0213930 radix_tree_lookup                             6   0.0750
c011a990 __wake_up                                     8   0.0833
c013e060 kfree                                         9   0.0804
c01b0ed0 xfs_bmapi                                     9   0.0018
c01862a0 write_profile                                10   0.1562
c0208de0 xfs_write                                    10   0.0047
c0216440 __copy_from_user_ll                          17   0.1328
c011a340 schedule                                     18   0.0128
c010ad50 handle_IRQ_event                             21   0.1875
c02163d0 __copy_to_user_ll                            27   0.2411
c0121c00 do_softirq                                  144   0.7500
c0107030 default_idle                               8696 181.1667
00000000 total                                      9144   0.0060

Re: ksoftirqd using mysteriously high amounts of CPU time

[Yury V. Umanets]

On Thu, 2004-03-11 at 11:28, Brad Laue wrote:
> Brad Laue wrote:
> > Hopefully the attached shows some irregularity. If not, I'll have to 
> > reply back in a few weeks when the problem recurs over the course of time.
> 
> And without further ado, the attachment. It's been a long day. :)
> 
> Brad
> 
> ______________________________________________________________________
> c0122bf0 current_kernel_time                           2   0.0312
> c0122d20 local_bh_enable                               2   0.0139
> c0137800 unlock_page                                   2   0.0208
> c013ef10 __kmalloc                                     2   0.0156
> c0155630 mark_buffer_dirty                             2   0.0250
> c0165760 poll_freewait                                 2   0.0250
> c01df2b0 xfs_ichgtime                                  2   0.0075
> c0202780 linvfs_get_block_core                         2   0.0027
> c0205310 linvfs_write                                  2   0.0069
> c0216e90 fast_copy_page                                2   0.0078
> c0244b90 tty_write                                     2   0.0030
> c0246020 tty_poll                                      2   0.0156
> c0248670 n_tty_receive_buf                             2   0.0005
> c024b1e0 pty_unthrottle                                2   0.0208
> c024b240 pty_write                                     2   0.0043
> c0109354 system_call                                   3   0.0682
> c0152e70 vfs_write                                     3   0.0099
> c0157cd0 alloc_buffer_head                             3   0.0312
> c01657b0 __pollwait                                    3   0.0144
> c016e100 dnotify_parent                                3   0.0156
> c01b1e50 xfs_bmapi                                     3   0.0006
> c024a3a0 normal_poll                                   3   0.0088
> c0107090 cpu_idle                                      4   0.0625
> c0153e60 fget                                          4   0.0625
> c0165c60 sys_select                                    4   0.0032
> c0216e30 fast_clear_page                               4   0.0417
> c0139280 generic_file_aio_write_nolock                 5   0.0019
> c0209d60 xfs_write                                     6   0.0028
> c011ba10 __wake_up                                     7   0.0729
> c0165960 do_select                                     8   0.0111
> c0249920 read_chan                                     9   0.0042
> c0156170 __block_prepare_write                        12   0.0117
> c02173c0 __copy_from_user_ll                          12   0.0938
> c010b570 handle_IRQ_event                             13   0.1161
> c0187210 write_profile                                14   0.2188
> c011b3c0 schedule                                     15   0.0107
> c0217350 __copy_to_user_ll                            47   0.4196
> c0122c80 do_softirq                                  136   0.8500
> c0107030 default_idle                               9222 192.1250
> 00000000 total            
Hello,

IMHO this does not look like profile results related to the problem. Or
it is inside big critical section with disabled irqs and profiler has no
hits there.

I guess it might be useful to try SysRq to catch the problem.

Do not forget to enable it in kernel config and run

echo "1" > /proc/sys/kernel/sysrq

then press Alt-SysRq-t when ksoftirqd starts to eat cpu time

This will dump a list of current tasks and their information to console.
Probably there will be some hint...

>                           9611   0.0063
-- 
umka