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
Brad Laue <[email protected]> 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)
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
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
Brad Laue <[email protected]> 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);
+ }
}
/*
_
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
On Thu, 2004-03-11 at 12:08, Andrew Morton wrote:
> Brad Laue <[email protected]> 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 [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
--
umka
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
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 [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
--
umka
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
Andrew Morton wrote:
> Brad Laue <[email protected]> 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
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?
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