2.5.29: bad: schedule() with irqs disabled!

2.5.29: bad: schedule() with irqs disabled!

[Peter Osterlund]

I have seen the "schedule with irqs disabled" message twice now in
2.5.29 on an UP machine. It looks like do_softirq calls
wake_up_process with interrupts disabled:

c1807dd8 c023f540 00000000 c1807e00 c0110648 00000001 00000002 00000001 
       c02c1c18 fffffff8 c1807e10 c011066b c11eb040 00000000 00000246 c01189fe 
       00000007 00000100 c38cf1ac 00000000 c020dc39 c1807e80 00000000 00000000 
Call Trace: [<c0110648>] [<c011066b>] [<c01189fe>] [<c020dc39>] [<c01f26cb>] 
   [<c022a068>] [<c01ef2f2>] [<c019d595>] [<c01ef4ea>] [<c0138036>] [<c01f6217> 
   [<c013813a>] [<c0107127>] 

Trace; c0110648 <global_flush_tlb+1e8/200>
Trace; c011066b <wake_up_process+b/200>
Trace; c01189fe <do_softirq+9e/b0>
Trace; c020dc39 <ip_cmsg_recv+4a89/50a0>
Trace; c01f26cb <alloc_skb+27b/2e0>
Trace; c022a068 <unregister_inetaddr_notifier+1ce8/2080>
Trace; c01ef2f2 <sock_sendmsg+72/90>
Trace; c019d595 <tty_unregister_driver+28e5/2920>
Trace; c01ef4ea <sock_recvmsg+1da/7d0>
Trace; c0138036 <vfs_write+b6/860>
Trace; c01f6217 <netif_rx+277/300>
Trace; c013813a <vfs_write+1ba/860>
Trace; c0107127 <__up_wakeup+10fb/2634>



c1807cac c023f540 00000000 c1807cd4 c0110648 00000001 00000002 00000001 
       c02c1c18 fffffff8 c1807ce4 c011066b c11eb040 00000000 00000246 c01189fe 
       c1806000 00000001 00000100 c0208e60 c01fcf7c 00000000 c02e9b58 00000001 
Call Trace: [<c0110648>] [<c011066b>] [<c01189fe>] [<c0208e60>] [<c01fcf7c>] 
   [<c0205030>] [<c01fcecf>] [<c0207c8f>] [<c0208e60>] [<c0204c69>] [<c0205030> 
   [<c021cb87>] [<c0216ef9>] [<c0217522>] [<c0205170>] [<c011c105>] [<c010bc00> 
   [<c0217ff6>] [<c020daa6>] [<c01f6421>] [<c022a068>] [<c01ef2f2>] [<c019d595> 
   [<c01ef4ea>] [<c0138036>] [<c0118ca0>] [<c013813a>] [<c0107127>] 

Trace; c0110648 <global_flush_tlb+1e8/200>
Trace; c011066b <wake_up_process+b/200>
Trace; c01189fe <do_softirq+9e/b0>
Trace; c0208e60 <ip_finish_output+2b0/600>
Trace; c01fcf7c <nf_hook_slow+16c/190>
Trace; c0205030 <ip_rcv+3b0/1150>
Trace; c01fcecf <nf_hook_slow+bf/190>
Trace; c0207c8f <ip_options_undo+f8f/18d0>
Trace; c0208e60 <ip_finish_output+2b0/600>
Trace; c0204c69 <inet_del_protocol+479/490>
Trace; c0205030 <ip_rcv+3b0/1150>
Trace; c021cb87 <tcp_read_sock+e937/167e0>
Trace; c0216ef9 <tcp_read_sock+8ca9/167e0>
Trace; c0217522 <tcp_read_sock+92d2/167e0>
Trace; c0205170 <ip_rcv+4f0/1150>
Trace; c011c105 <del_timer+835/940>
Trace; c010bc00 <do_settimeofday+300/3d0>
Trace; c0217ff6 <tcp_read_sock+9da6/167e0>
Trace; c020daa6 <ip_cmsg_recv+48f6/50a0>
Trace; c01f6421 <netif_receive_skb+101/390>
Trace; c022a068 <unregister_inetaddr_notifier+1ce8/2080>
Trace; c01ef2f2 <sock_sendmsg+72/90>
Trace; c019d595 <tty_unregister_driver+28e5/2920>
Trace; c01ef4ea <sock_recvmsg+1da/7d0>
Trace; c0138036 <vfs_write+b6/860>
Trace; c0118ca0 <tasklet_kill+70/90>
Trace; c013813a <vfs_write+1ba/860>
Trace; c0107127 <__up_wakeup+10fb/2634>

-- 
Peter Osterlund - petero2@telia.com
http://w1.894.telia.com/~u89404340

2.5.29 bad: schedule() with irqs disabled!

[Muli Ben-Yehuda]

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

2.5.9 (latest bitkeeper, to be precise) dumps this message into
/var/log/messages within a few minutes after startup. Running xmms or
mozilla seems to do the trick. I ran two of the messages through
ksymoops and attach the results here, in case they are meaningful. 
I'll be happy to help debug it further, if necessary. 

Here's one such message: 

Jul 28 22:28:54 tea kernel: bad: schedule() with irqs disabled!
Jul 28 22:28:54 tea kernel: cdf99cb0 c0275680 cf742580 cdf99cd8 c010fbf4 00000001 00000082 00000005 
Jul 28 22:28:54 tea kernel:        c02ffbd8 fffffffa cdf99ce8 c010fc0b cf742580 00000000 00000246 c0117b5f 
Jul 28 22:28:54 tea kernel:        cdf98000 00000001 00000005 c0226170 c021a359 00000000 c032cbf8 cf72ea60 
Jul 28 22:28:54 tea kernel: Call Trace: [<c010fbf4>] [<c010fc0b>] [<c0117b5f>] [<c0226170>] [<c021a359>] 
Jul 28 22:28:54 tea kernel:    [<c01cf5e2>] [<c022507f>] [<c0226170>] [<c01e7195>] [<c01ebad6>] [<c0239488>] 
Jul 28 22:28:54 tea kernel:    [<c023420c>] [<c0234c77>] [<c022ac87>] [<c01257d5>] [<c0110480>] [<c0126500>] 
Jul 28 22:28:54 tea kernel:    [<c0246428>] [<c020c432>] [<c01103ab>] [<c010ee05>] [<c020c629>] [<c0135886>] 
Jul 28 22:28:54 tea kernel:    [<c0117dec>] [<c013597a>] [<c0106fff>] 

And here are two of them passed through ksymoops: 

mulix@tea:~$ ksymoops -m /boot/2.5-mx/System.map < ~/tmp/oops2
ksymoops 2.4.4 on i686 2.5.29.  Options used
     -V (default)
     -k /proc/ksyms (default)
     -l /proc/modules (default)
     -o /lib/modules/2.5.29/ (default)
     -m /boot/2.5-mx/System.map (specified)

cdf99cb0 c0275680 cf742580 cdf99cd8 c010fbf4 00000001 00000082 00000005 
        c02ffbd8 fffffffa cdf99ce8 c010fc0b cf742580 00000000 00000246 c0117b5f 
        cdf98000 00000001 00000005 c0226170 c021a359 00000000 c032cbf8 cf729660 
Call Trace: [<c010fbf4>] [<c010fc0b>] [<c0117b5f>] [<c0226170>] [<c021a359>] 
   [<c01cf5e2>] [<c022507f>] [<c0226170>] [<c01e7195>] [<c01ebad6>] [<c0239488>] 
   [<c023420c>] [<c0234c77>] [<c022ac87>] [<c0126500>] [<c0246428>] [<c020c432>] 
   [<c020f7d3>] [<c010ee05>] [<c020c629>] [<c0135886>] [<c0117dec>] [<c0117d24>] 
   [<c0117b1b>] [<c013597a>] [<c0106fff>] 
Warning (Oops_read): Code line not seen, dumping what data is available

Trace; c010fbf4 <try_to_wake_up+144/150>
Trace; c010fc0b <wake_up_process+b/10>
Trace; c0117b5f <do_softirq+8f/a0>
Trace; c0226170 <ip_queue_xmit2+0/210>
Trace; c021a359 <nf_hook_slow+169/190>
Trace; c01cf5e2 <__elv_add_request+12/20>
Trace; c022507f <ip_queue_xmit+45f/4b0>
Trace; c0226170 <ip_queue_xmit2+0/210>
Trace; c01e7195 <ata_set_handler+75/90>
Trace; c01ebad6 <idedisk_do_request+456/670>
Trace; c0239488 <tcp_v4_send_check+78/c0>
Trace; c023420c <tcp_transmit_skb+55c/610>
Trace; c0234c77 <tcp_write_xmit+157/290>
Trace; c022ac87 <tcp_sendmsg+f67/1250>
Trace; c0126500 <filemap_nopage+f0/1e0>
Trace; c0246428 <inet_sendmsg+38/40>
Trace; c020c432 <sock_sendmsg+72/90>
Trace; c020f7d3 <alloc_skb+d3/1a0>
Trace; c010ee05 <do_page_fault+1a5/4b5>
Trace; c020c629 <sock_write+99/b0>
Trace; c0135886 <vfs_write+b6/140>
Trace; c0117dec <bh_action+1c/30>
Trace; c0117d24 <tasklet_hi_action+44/70>
Trace; c0117b1b <do_softirq+4b/a0>
Trace; c013597a <sys_write+2a/40>
Trace; c0106fff <syscall_call+7/b>


1 warning issued.  Results may not be reliable.
mulix@tea:~$ ksymoops -m /boot/2.5-mx/System.map < ~/tmp/oops
ksymoops 2.4.4 on i686 2.5.29.  Options used
     -V (default)
     -k /proc/ksyms (default)
     -l /proc/modules (default)
     -o /lib/modules/2.5.29/ (default)
     -m /boot/2.5-mx/System.map (specified)

cdf23cd4 c0275680 cf742580 cdf23cfc c010fbf4 00000001 00000096 00000001 
c02ffbd0 fffffffc cdf23d0c c010fc0b cf742580 00000000 00000246 c0117b5f 
cdf22000 00000001 00000003 c0226170 c021a359 00000000 c032cbf8 00000002 
Call Trace: [<c010fbf4>] [<c010fc0b>] [<c0117b5f>] [<c0226170>] [<c021a359>] 
c022507f>] [<c0226170>] [<c0239488>] [<c0239488>] [<c023420c>] [<c020f7d3>] 
c02366d1>] [<c020f99b>] [<c022be04>] [<c02463d9>] [<c020c481>] [<c01c1ba3>] 
c01c0830>] [<c020c585>] [<c0135746>] [<c0117dec>] [<c013593a>] [<c0106fff>] 
Warning (Oops_read): Code line not seen, dumping what data is available

Trace; c010fbf4 <try_to_wake_up+144/150>
Trace; c010fc0b <wake_up_process+b/10>
Trace; c0117b5f <do_softirq+8f/a0>
Trace; c0226170 <ip_queue_xmit2+0/210>
Trace; c021a359 <nf_hook_slow+169/190>


1 warning issued.  Results may not be reliable.

-- 
http://vipe.technion.ac.il/~mulix/
http://syscalltrack.sf.net/

[-- Attachment #2: Type: application/pgp-signature, Size: 189 bytes --]

Re: 2.5.29 bad: schedule() with irqs disabled!

[Heinz Diehl]

On Sun Jul 28 2002, Muli Ben-Yehuda wrote:

> 2.5.9 (latest bitkeeper, to be precise) dumps this message into
> /var/log/messages within a few minutes after startup.
[....]

Just a "me too". Kernel 2.5.29 vanilla, not from bitkeeper.

-- 
# Heinz Diehl, 68259 Mannheim, Germany