Re: Sleeping function called from illegal context at slab.c:1378

Re: Sleeping function called from illegal context at slab.c:1378

[Andrew Morton]

That's a bug in ip_fw_ctl().  It's calling convert_ipfw()
inside FWC_WRITE_LOCK_IRQ(&ip_fw_lock, flags);

But convert_ipfw() does kmalloc(GFP_KERNEL).


Steven Cole wrote:
> 
> Hi Andrew,
> 
> Are these traced warnings of any use to you?
> 
> If so, here is one.  This one was from
> 
> "Sleeping function called from illegal context at slab.c:1378"
> 
> on bootup of 2.5.38-mm2:
> 
> Trace; c0119986 <__might_sleep+56/5d>
> Trace; c0135166 <kmalloc+66/1f0>
> Trace; c0271e03 <convert_ipfw+63/130>
> Trace; c02721c0 <ip_fw_ctl+2f0/4d0>
> Trace; c026a023 <sock_fn+63/80>
> Trace; c012ff2e <find_get_page+2e/60>
> Trace; c0130db5 <filemap_nopage+115/310>
> Trace; c012d8ef <do_no_page+2ef/390>
> Trace; c012b5ba <pte_alloc_map+ea/150>
> Trace; c023471a <nf_sockopt+fa/150>
> Trace; c0234790 <nf_setsockopt+20/30>
> Trace; c0242fda <ip_setsockopt+74a/910>
> Trace; c02255de <sock_map_fd+be/120>
> Trace; c022562a <sock_map_fd+10a/120>
> Trace; c0263995 <inet_setsockopt+25/30>
> Trace; c02269d6 <sys_setsockopt+56/70>
> Trace; c0227026 <sys_socketcall+1a6/200>
> Trace; c0114ea0 <do_page_fault+0/436>
> Trace; c01099b1 <error_code+2d/38>
> Trace; c0108f6f <syscall_call+7/b>
> 
> Steven

Re: Sleeping function called from illegal context at slab.c:1378

[Steven Cole]

On Mon, 2002-09-23 at 12:30, Andrew Morton wrote:
> That's a bug in ip_fw_ctl().  It's calling convert_ipfw()
> inside FWC_WRITE_LOCK_IRQ(&ip_fw_lock, flags);
> 
> But convert_ipfw() does kmalloc(GFP_KERNEL).
> 
> 
> Steven Cole wrote:
> > 
> > Hi Andrew,
> > 
> > Are these traced warnings of any use to you?

I guess that traced warning was of interest, so here are two 
more from 2.5.38-mm2.

( I got a total of four warnings; the first was identical to that posted
by Grega Fajdiga here:
http://marc.theaimsgroup.com/?l=linux-kernel&m=103278825525479&w=2
and the fourth slabc:1378 warning was the one referred to above.)

Here is the second slabc:1378 warning traced with ksymoops:

Trace; c0119986 <__might_sleep+56/5d>
Trace; c0135166 <kmalloc+66/1f0>
Trace; c0120048 <__request_region+18/c0>
Trace; c0215ca2 <eata2x_detect+142/d60>
Trace; c02037a4 <ahc_linux_alloc_device+14/70>
Trace; c020298c <ahc_linux_queue+16c/1a0>
Trace; c0117c71 <schedule+351/3e0>
Trace; c01f1c6a <scsi_request_fn+13a/450>
Trace; c0117fe2 <wait_for_completion+b2/110>
Trace; c01f149d <scsi_queue_next_request+5d/140>
Trace; c01ea9da <scsi_release_command+13a/150>
Trace; c013432d <kmem_slab_destroy+dd/110>
Trace; c0134f07 <free_block+b7/120>
Trace; c013533a <kmem_cache_free+4a/80>
Trace; c01c7b43 <elevator_exit+13/20>
Trace; c01f3c06 <scan_scsis+96/a0>
Trace; c01ec218 <scsi_register_host+48/340>
Trace; c01b0133 <put_bus+13/57>
Trace; c01050b1 <init+51/1d0>
Trace; c0105060 <init+0/1d0>
Trace; c01070b9 <kernel_thread_helper+5/c>

Here is the third slabc:1378 warning traced with ksymoops:

Trace; c0119986 <__might_sleep+56/5d>
Trace; c0135166 <kmalloc+66/1f0>
Trace; c0271e03 <convert_ipfw+63/130>
Trace; c027216a <ip_fw_ctl+29a/4d0>
Trace; c017ab91 <ext3_reserve_inode_write+31/b0>
Trace; c026a023 <sock_fn+63/80>
Trace; c012ff2e <find_get_page+2e/60>
Trace; c0130db5 <filemap_nopage+115/310>
Trace; c012d8ef <do_no_page+2ef/390>
Trace; c012b5ba <pte_alloc_map+ea/150>
Trace; c023471a <nf_sockopt+fa/150>
Trace; c0234790 <nf_setsockopt+20/30>
Trace; c0242fda <ip_setsockopt+74a/910>
Trace; c02255de <sock_map_fd+be/120>
Trace; c022562a <sock_map_fd+10a/120>
Trace; c0263995 <inet_setsockopt+25/30>
Trace; c02269d6 <sys_setsockopt+56/70>
Trace; c0227026 <sys_socketcall+1a6/200>
Trace; c0114ea0 <do_page_fault+0/436>
Trace; c01099b1 <error_code+2d/38>
Trace; c0108f6f <syscall_call+7/b>

Steven

Re: Sleeping function called from illegal context at slab.c:1378

[Andrew Morton]

Steven Cole wrote:
> 
> ...
> I guess that traced warning was of interest, so here are two
> more from 2.5.38-mm2.

Well this is fun.
 
> 
> Trace; c0119986 <__might_sleep+56/5d>
> Trace; c0135166 <kmalloc+66/1f0>
> Trace; c0120048 <__request_region+18/c0>
> Trace; c0215ca2 <eata2x_detect+142/d60>
> Trace; c02037a4 <ahc_linux_alloc_device+14/70>
> Trace; c020298c <ahc_linux_queue+16c/1a0>
> Trace; c0117c71 <schedule+351/3e0>
> Trace; c01f1c6a <scsi_request_fn+13a/450>
> Trace; c0117fe2 <wait_for_completion+b2/110>
> Trace; c01f149d <scsi_queue_next_request+5d/140>
> Trace; c01ea9da <scsi_release_command+13a/150>
> Trace; c013432d <kmem_slab_destroy+dd/110>
> Trace; c0134f07 <free_block+b7/120>
> Trace; c013533a <kmem_cache_free+4a/80>
> Trace; c01c7b43 <elevator_exit+13/20>
> Trace; c01f3c06 <scan_scsis+96/a0>
> Trace; c01ec218 <scsi_register_host+48/340>
> Trace; c01b0133 <put_bus+13/57>
> Trace; c01050b1 <init+51/1d0>
> Trace; c0105060 <init+0/1d0>
> Trace; c01070b9 <kernel_thread_helper+5/c>
> 

eata2x_detect() calls port_detect() under driver_lock.
port_detect() calls request_region(), which can sleep.

> 
> Trace; c0119986 <__might_sleep+56/5d>
> Trace; c0135166 <kmalloc+66/1f0>
> Trace; c0271e03 <convert_ipfw+63/130>
> Trace; c027216a <ip_fw_ctl+29a/4d0>
> Trace; c017ab91 <ext3_reserve_inode_write+31/b0>
> Trace; c026a023 <sock_fn+63/80>
> Trace; c012ff2e <find_get_page+2e/60>
> Trace; c0130db5 <filemap_nopage+115/310>
> Trace; c012d8ef <do_no_page+2ef/390>
> Trace; c012b5ba <pte_alloc_map+ea/150>
> Trace; c023471a <nf_sockopt+fa/150>
> Trace; c0234790 <nf_setsockopt+20/30>
> Trace; c0242fda <ip_setsockopt+74a/910>
> Trace; c02255de <sock_map_fd+be/120>
> Trace; c022562a <sock_map_fd+10a/120>
> Trace; c0263995 <inet_setsockopt+25/30>
> Trace; c02269d6 <sys_setsockopt+56/70>
> Trace; c0227026 <sys_socketcall+1a6/200>
> Trace; c0114ea0 <do_page_fault+0/436>
> Trace; c01099b1 <error_code+2d/38>
> Trace; c0108f6f <syscall_call+7/b>
> 

That's the ip_fw_ctl() one.

Re: Sleeping function called from illegal context at slab.c:1378

[Steven Cole]

On Mon, 2002-09-23 at 14:21, Andrew Morton wrote:
> Steven Cole wrote:
> > 
> > ...
> > I guess that traced warning was of interest, so here are two
> > more from 2.5.38-mm2.
> 
> Well this is fun.
>  
> > 
> > Trace; c0119986 <__might_sleep+56/5d>
> > Trace; c0135166 <kmalloc+66/1f0>
> > Trace; c0120048 <__request_region+18/c0>
> > Trace; c0215ca2 <eata2x_detect+142/d60>
> > Trace; c02037a4 <ahc_linux_alloc_device+14/70>
> > Trace; c020298c <ahc_linux_queue+16c/1a0>
> > Trace; c0117c71 <schedule+351/3e0>
> > Trace; c01f1c6a <scsi_request_fn+13a/450>
> > Trace; c0117fe2 <wait_for_completion+b2/110>
> > Trace; c01f149d <scsi_queue_next_request+5d/140>
> > Trace; c01ea9da <scsi_release_command+13a/150>
> > Trace; c013432d <kmem_slab_destroy+dd/110>
> > Trace; c0134f07 <free_block+b7/120>
> > Trace; c013533a <kmem_cache_free+4a/80>
> > Trace; c01c7b43 <elevator_exit+13/20>
> > Trace; c01f3c06 <scan_scsis+96/a0>
> > Trace; c01ec218 <scsi_register_host+48/340>
> > Trace; c01b0133 <put_bus+13/57>
> > Trace; c01050b1 <init+51/1d0>
> > Trace; c0105060 <init+0/1d0>
> > Trace; c01070b9 <kernel_thread_helper+5/c>
> > 
> 
> eata2x_detect() calls port_detect() under driver_lock.
> port_detect() calls request_region(), which can sleep.

Here is the output from dmesg just before that warning:

SCSI subsystem driver Revision: 1.00
scsi0 : Adaptec AIC7XXX EISA/VLB/PCI SCSI HBA DRIVER, Rev 6.2.4
        <Adaptec aic7899 Ultra160 SCSI adapter>
        aic7899: Ultra160 Wide Channel A, SCSI Id=7, 32/253 SCBs

scsi1 : Adaptec AIC7XXX EISA/VLB/PCI SCSI HBA DRIVER, Rev 6.2.4
        <Adaptec aic7899 Ultra160 SCSI adapter>
        aic7899: Ultra160 Wide Channel B, SCSI Id=7, 32/253 SCBs

blk: queue f1a15018, I/O limit 4095Mb (mask 0xffffffff)
(scsi0:A:0): 160.000MB/s transfers (80.000MHz DT, offset 126, 16bit)
blk: queue f1a15418, I/O limit 4095Mb (mask 0xffffffff)
  Vendor: HITACHI   Model: DK32CJ-36MW       Rev: JBBB
  Type:   Direct-Access                      ANSI SCSI revision: 03
(scsi0:A:1): 160.000MB/s transfers (80.000MHz DT, offset 126, 16bit)
blk: queue f1a15818, I/O limit 4095Mb (mask 0xffffffff)
  Vendor: HITACHI   Model: DK32CJ-36MW       Rev: JBBB
  Type:   Direct-Access                      ANSI SCSI revision: 03
scsi0:A:0:0: Tagged Queuing enabled.  Depth 8
scsi0:A:1:0: Tagged Queuing enabled.  Depth 8
blk: queue f1a15018, I/O limit 4095Mb (mask 0xffffffff)
PCI: Enabling device 01:04.0 (0116 -> 0117)
PCI: Enabling device 01:04.1 (0116 -> 0117)
Sleeping function called from illegal context at slab.c:1378


> > Trace; c0119986 <__might_sleep+56/5d>
> > Trace; c0135166 <kmalloc+66/1f0>
> > Trace; c0271e03 <convert_ipfw+63/130>
> > Trace; c027216a <ip_fw_ctl+29a/4d0>
> 
> That's the ip_fw_ctl() one.

Oops, sorry for the double report on that one.  I'm lost in a maze of
twisty traces, all alike.

Steven

Re: Sleeping function called from illegal context at slab.c:1378

[Nuno Monteiro]

On 23.09.02 21:21 Andrew Morton wrote:

<snip snip>

I got two more. Its 2.5.38-mm2 too. Just thought I'd throw them in:

Sleeping function called from illegal context at slab.c:1378
c2e73f6c c0110251 c020b800 c020faf0 00000562 000001d0 c0129080 c020faf0
        00000562 00000060 00000008 0000012c c11e3560 c010ac77 00000080 
000001d0
        c2e72000 00000000 0000012c bffff948 00000000 c0106ff7 00000060 
00000008
Call Trace: [<c0110251>] [<c0129080>] [<c010ac77>] [<c0106ff7>]

Trace; c0110251 <__might_sleep+55/64>
Trace; c0129080 <kmalloc+4c/130>
Trace; c010ac77 <sys_ioperm+7f/124>
Trace; c0106ff7 <syscall_call+7/b>

this one happens right after boot, it appears on dmesg right after the 
ethernet driver being loaded (modular, ne2k-pci), but thats probably not 
whats triggering it anyway.

-------------------------------------------

Sleeping function called from illegal context at page_alloc.c:326
c3919eb4 c0110251 c020b800 c0210500 00000146 00000000 c012ba45 c0210500
        00000146 00000000 000001d0 c3eef340 c391fca8 00007fff 000001d0 
ffffffff
        c012bc60 00000000 c3919f68 c0143cb7 c11bfbc0 c391fc00 00000000 
c3919f68
Call Trace: [<c0110251>] [<c012ba45>] [<c012bc60>] [<c0143cb7>] 
[<c4b28deb>]
    [<c0143ec5>] [<c0144342>] [<c0143707>] [<c0106ff7>]

Trace; c0110251 <__might_sleep+55/64>
Trace; c012ba45 <__alloc_pages+25/218>
Trace; c012bc60 <__get_free_pages+28/78>
Trace; c0143cb7 <__pollwait+33/98>
Trace; c4b28deb <[snd-pcm-oss]snd_pcm_oss_poll+47/108>
Trace; c0143ec5 <do_select+101/210>
Trace; c0144342 <sys_select+346/4a0>
Trace; c0143707 <sys_ioctl+23b/294>
Trace; c0106ff7 <syscall_call+7/b>


I got literally hundreds of this last one -- the whole dmesg buffer is 
filled with them. They go on at furious rate while playing mp3.



		Nuno

Re: Sleeping function called from illegal context at slab.c:1378

[Andrew Morton]

Nuno Monteiro wrote:
> 
> On 23.09.02 21:21 Andrew Morton wrote:
> 
> <snip snip>
> 
> I got two more. Its 2.5.38-mm2 too. Just thought I'd throw them in:
> 
> Sleeping function called from illegal context at slab.c:1378
> c2e73f6c c0110251 c020b800 c020faf0 00000562 000001d0 c0129080 c020faf0
>         00000562 00000060 00000008 0000012c c11e3560 c010ac77 00000080
> 000001d0
>         c2e72000 00000000 0000012c bffff948 00000000 c0106ff7 00000060
> 00000008
> Call Trace: [<c0110251>] [<c0129080>] [<c010ac77>] [<c0106ff7>]
> 
> Trace; c0110251 <__might_sleep+55/64>
> Trace; c0129080 <kmalloc+4c/130>
> Trace; c010ac77 <sys_ioperm+7f/124>
> Trace; c0106ff7 <syscall_call+7/b>

sys_ioperm() is calling kmalloc(GFP_KERNEL) inside preempt_disable()
(via get_cpu()).  That's incorrect because the kmalloc could sleep,
and switch CPUs.

> ...
> 
> Trace; c0110251 <__might_sleep+55/64>
> Trace; c012ba45 <__alloc_pages+25/218>
> Trace; c012bc60 <__get_free_pages+28/78>
> Trace; c0143cb7 <__pollwait+33/98>
> Trace; c4b28deb <[snd-pcm-oss]snd_pcm_oss_poll+47/108>
> Trace; c0143ec5 <do_select+101/210>
> Trace; c0144342 <sys_select+346/4a0>
> Trace; c0143707 <sys_ioctl+23b/294>
> Trace; c0106ff7 <syscall_call+7/b>
> 

snd_pcm_oss_poll() calls poll_wait() inside runtime->lock.
poll_wait() does __get_free_page(GFP_KERNEL).

This is a bug in snd_pcm_oss_poll().

Re: Sleeping function called from illegal context at slab.c:1378

[James Morris]

On Mon, 23 Sep 2002, Andrew Morton wrote:

> That's a bug in ip_fw_ctl().  It's calling convert_ipfw()
> inside FWC_WRITE_LOCK_IRQ(&ip_fw_lock, flags);
> 
> But convert_ipfw() does kmalloc(GFP_KERNEL).
> 

Below a patch to correct this. The bug is also present in 2.2 and 2.4 
(patches to follow on netfilter-devel).

- James
-- 
James Morris
<jmorris@intercode.com.au>

diff -urN -X dontdiff linux-2.5.38.orig/net/ipv4/netfilter/ipchains_core.c linux-2.5.38.w1/net/ipv4/netfilter/ipchains_core.c
--- linux-2.5.38.orig/net/ipv4/netfilter/ipchains_core.c	Tue Sep 10 09:43:30 2002
+++ linux-2.5.38.w1/net/ipv4/netfilter/ipchains_core.c	Tue Sep 24 23:09:50 2002
@@ -1252,7 +1252,7 @@
 		return NULL;
 	}
 
-	fwkern = kmalloc(SIZEOF_STRUCT_IP_FW_KERNEL, GFP_KERNEL);
+	fwkern = kmalloc(SIZEOF_STRUCT_IP_FW_KERNEL, GFP_ATOMIC);
 	if (!fwkern) {
 		duprintf("convert_ipfw: kmalloc failed!\n");
 		*errno = ENOMEM;