[Home]

Summary:ASTERISK-01200: Zaptel driver memory management debug warning
Reporter:capouch (capouch)Labels:
Date Opened:2004-03-11 22:49:44.000-0600Date Closed:2008-06-07 10:40:32
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Running asterisk CVS from 3/10/04

A variety of Zaptel function calls spawn kernel debug messages of this sort, dmesg shows them happening over and over. .

Debug: sleeping function called from invalid context

****** ADDITIONAL INFORMATION ******

There seem to be two primary culprits:

Debug: sleeping function called from invalid context at /usr/src/zaptel/zaptel.c:3366
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0116fb5>] __might_sleep+0x85/0xa0
[<e00d7de7>] zt_chanandpseudo_ioctl+0x9f7/0x1730 [zaptel]
[<c030797f>] tcp_v4_do_rcv+0xef/0x100
[<c0307f67>] tcp_v4_rcv+0x5d7/0x7a0
[<c0114f56>] recalc_task_prio+0xa6/0x200
[<c0115149>] try_to_wake_up+0x99/0x140
[<c0115fc6>] __wake_up_common+0x26/0x50
[<c0116001>] __wake_up+0x11/0x20
[<c02d46f1>] sock_def_readable+0x51/0x60
[<c030ea4b>] udp_queue_rcv_skb+0x15b/0x250
[<c0131819>] buffered_rmqueue+0xa9/0x110
[<c0131918>] __alloc_pages+0x98/0x350
[<c0115d51>] schedule+0x2f1/0x520
[<c0131bf2>] __get_free_pages+0x22/0x60
[<e00d8b90>] zt_chan_ioctl+0x70/0xa60 [zaptel]
[<c015677a>] poll_freewait+0x3a/0x50
[<c0156acb>] do_select+0x18b/0x2a0
[<c0156790>] __pollwait+0x0/0xb0
[<e00d4a99>] zt_ioctl+0x49/0xc0 [zaptel]
[<c015602b>] sys_ioctl+0xab/0x220
[<c011ba4e>] sys_time+0x1e/0x50
[<c0108ca7>] syscall_call+0x7/0xb

Debug: sleeping function called from invalid context at mm/slab.c:1900
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0116fb5>] __might_sleep+0x85/0xa0
[<c0134b21>] kmem_cache_alloc+0x51/0x60
[<e00d992b>] zt_timing_open+0x1b/0x60 [zaptel]
[<e00d4690>] zt_open+0x0/0x20 [zaptel]
[<e00d46a4>] zt_open+0x14/0x20 [zaptel]
[<c014e2aa>] chrdev_open+0x8a/0x120
[<c014592a>] dentry_open+0x10a/0x1a0
[<c014581e>] filp_open+0x4e/0x50
[<c0145bcf>] sys_open+0x3f/0x70
[<c0108ca7>] syscall_call+0x7/0xb

Comments:By: capouch (capouch) 2004-03-11 22:50:32.000-0600

Arrrgghhhh.  How could I have failed to note that this is under kernel 2.6.4?
Sorry.
By: James Golovich (jamesgolovich) 2004-03-12 14:12:10.000-0600

As well as what kind of zaptel devices you have installed
By: capouch (capouch) 2004-03-13 17:10:15.000-0600

Just the wcfxo device for the X100P
By: Mark Spencer (markster) 2004-04-12 11:18:17

Can you still duplicate this problem?  If so, can you give me an updated trace?
By: Mark Spencer (markster) 2004-04-15 16:44:20

Brian, can you please duplicate this with recent CVS.  Thanks
By: capouch (capouch) 2004-04-16 02:31:03

Sorry for the delay; I had sold the server that was running 2.6 :-)

Still the same:

Debug: sleeping function called from invalid context at mm/slab.c:1931
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<c01325c1>] kmem_cache_alloc+0x51/0x60
[<e00bcb25>] __zt_open+0x85/0x120 [zaptel]
[<e00b9c44>] zt_open+0x14/0x20 [zaptel]
[<c014c52a>] chrdev_open+0x9a/0x130
[<c0143934>] dentry_open+0x124/0x1c0
[<c0143801>] filp_open+0x51/0x60
[<c0143bdf>] sys_open+0x3f/0x70
[<c0106e97>] syscall_call+0x7/0xb

Debug: sleeping function called from invalid context at mm/slab.c:1931
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<c01325c1>] kmem_cache_alloc+0x51/0x60
[<e00c063b>] zt_timing_open+0x1b/0x60 [zaptel]
[<c014c65c>] exact_lock+0xc/0x20
[<c0271107>] kobj_lookup+0x127/0x160
[<e00b9c44>] zt_open+0x14/0x20 [zaptel]
[<c014c52a>] chrdev_open+0x9a/0x130
[<c0143934>] dentry_open+0x124/0x1c0
[<c0143801>] filp_open+0x51/0x60
[<c0143bdf>] sys_open+0x3f/0x70
[<c0106e97>] syscall_call+0x7/0xb

Debug: sleeping function called from invalid context at /usr/src/zaptel/zaptel.c:3394
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<e00bea97>] zt_chanandpseudo_ioctl+0xa77/0x1820 [zaptel]
[<e00bbc68>] __zt_receive_chunk+0x1338/0x14b0 [zaptel]
[<e00b9096>] zt_receive+0x72f6/0x7310 [zaptel]
[<e00ae4eb>] zt_transmit+0x62b/0x3ee0 [zaptel]
[<c019d3a9>] ext3_get_block_handle+0x79/0x300
[<c019d3a9>] ext3_get_block_handle+0x79/0x300
[<c012f281>] buffered_rmqueue+0xd1/0x180
[<c012f3c8>] __alloc_pages+0x98/0x350
[<c0113735>] schedule+0x315/0x540
[<c011d609>] __mod_timer+0x59/0x80
[<c0154caa>] poll_freewait+0x3a/0x50
[<e00bf8af>] zt_chan_ioctl+0x6f/0xa50 [zaptel]
[<c0154cc0>] __pollwait+0x0/0xb0
[<c0155385>] sys_select+0x235/0x510
[<e00ba009>] zt_ioctl+0x49/0xc0 [zaptel]
[<c0154515>] sys_ioctl+0xa5/0x240
[<c0106e97>] syscall_call+0x7/0xb

Debug: sleeping function called from invalid context at /usr/src/zaptel/zaptel.c:2563
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<e00bcdcb>] zt_timer_ioctl+0x9b/0x180 [zaptel]
[<e00ba066>] zt_ioctl+0xa6/0xc0 [zaptel]
[<c0154515>] sys_ioctl+0xa5/0x240
[<c0106e97>] syscall_call+0x7/0xb

Lots and lots of that previous message, then:

Debug: sleeping function called from invalid context at /usr/src/zaptel/zaptel.c:3394
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<e00bea97>] zt_chanandpseudo_ioctl+0xa77/0x1820 [zaptel]
[<e00b9096>] zt_receive+0x72f6/0x7310 [zaptel]
[<e00bbc68>] __zt_receive_chunk+0x1338/0x14b0 [zaptel]
[<e00b9096>] zt_receive+0x72f6/0x7310 [zaptel]
[<c019d3a9>] ext3_get_block_handle+0x79/0x300
[<c019d3a9>] ext3_get_block_handle+0x79/0x300
[<c01469a3>] bh_lru_install+0x83/0xd0
[<c01469b6>] bh_lru_install+0x96/0xd0
[<c014557c>] wake_up_buffer+0xc/0x30
[<c01a9be9>] do_get_write_access+0x269/0x4e0
[<c019f613>] ext3_get_inode_loc+0x53/0x220
[<c019fd36>] ext3_do_update_inode+0x176/0x3a0
[<e00bf8af>] zt_chan_ioctl+0x6f/0xa50 [zaptel]
[<c01aa6e1>] journal_stop+0x171/0x200
[<c01a02f2>] ext3_dirty_inode+0x52/0x70
[<c0160333>] __mark_inode_dirty+0xa3/0xb0
[<c015b16b>] update_atime+0x6b/0xc0
[<e00ba009>] zt_ioctl+0x49/0xc0 [zaptel]
[<c0154515>] sys_ioctl+0xa5/0x240
[<c0106e97>] syscall_call+0x7/0xb

So far server seems to work all right . . .
By: Mark Spencer (markster) 2004-04-26 00:32:37

Okay this should be fixed now.  Can you confirm the messages are gone?
By: capouch (capouch) 2004-04-26 00:43:10

I think it's better (just started the server a few minutes ago) but not gone.  There are still quite a few of these being generated. . . one at the top happens on startup, the bottom one (repeatedly) is logged on an outbound call using the TDM FXS interface.

Debug: sleeping function called from invalid context at mm/slab.c:1931
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<c01325c1>] kmem_cache_alloc+0x51/0x60
[<e00bcb25>] __zt_open+0x85/0x120 [zaptel]
[<e00b9c44>] zt_open+0x14/0x20 [zaptel]
[<c014c52a>] chrdev_open+0x9a/0x130
[<c0143934>] dentry_open+0x124/0x1c0
[<c0143801>] filp_open+0x51/0x60
[<c0143bdf>] sys_open+0x3f/0x70
[<c0106e97>] syscall_call+0x7/0xb

Debug: sleeping function called from invalid context at /usr/src/zaptel/zaptel.c:3394
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<e00bea97>] zt_chanandpseudo_ioctl+0xa77/0x1820 [zaptel]
[<e00bbc68>] __zt_receive_chunk+0x1338/0x14b0 [zaptel]
[<e00ae4eb>] zt_transmit+0x62b/0x3ee0 [zaptel]
[<e00b9096>] zt_receive+0x72f6/0x7310 [zaptel]
[<c019d3a9>] ext3_get_block_handle+0x79/0x300
[<e0038a3b>] wcfxo_interrupt+0x3db/0x6e0 [wcfxo]
[<c012f281>] buffered_rmqueue+0xd1/0x180
[<c012f3c8>] __alloc_pages+0x98/0x350
[<c0113735>] schedule+0x315/0x540
[<c011d609>] __mod_timer+0x59/0x80
[<c0154caa>] poll_freewait+0x3a/0x50
[<e00bf8af>] zt_chan_ioctl+0x6f/0xa50 [zaptel]
[<c0154cc0>] __pollwait+0x0/0xb0
[<c0155385>] sys_select+0x235/0x510
[<e00ba009>] zt_ioctl+0x49/0xc0 [zaptel]
[<c0154515>] sys_ioctl+0xa5/0x240
[<c0106e97>] syscall_call+0x7/0xb

Debug: sleeping function called from invalid context at /usr/src/zaptel/zaptel.c:2563
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<e00bcdcb>] zt_timer_ioctl+0x9b/0x180 [zaptel]
[<e00ba066>] zt_ioctl+0xa6/0xc0 [zaptel]
[<c0154515>] sys_ioctl+0xa5/0x240
[<c0106e97>] syscall_call+0x7/0xb
By: Mark Spencer (markster) 2004-04-26 00:52:20

You still don't have latest CVS.  These line numbers don't jive with reality.  Are you sure you updated zaptel and not asterisk?
By: Mark Spencer (markster) 2004-04-26 00:59:50

Also might need to use:

cvs -d:pserver:anoncvs@origcvs.digium.com:/usr/cvsroot login
cvs -d:pserver:anoncvs@origcvs.digium.com:/usr/cvsroot update -d
By: Mark Spencer (markster) 2004-04-26 09:49:08

Any more updates?
By: capouch (capouch) 2004-04-26 10:09:31

Appears to be now only one place causing a problem.

This is exactly what I got when I did a cold start and then made one call using a Zap TDM interface.  Fresh CVS as of a few minutes ago.

Debug: sleeping function called from invalid context at mm/slab.c:1931
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<c01325c1>] kmem_cache_alloc+0x51/0x60
[<e00bcb85>] __zt_open+0x85/0x120 [zaptel]
[<e00b9c74>] zt_open+0x14/0x20 [zaptel]
[<c014c52a>] chrdev_open+0x9a/0x130
[<c0143934>] dentry_open+0x124/0x1c0
[<c0143801>] filp_open+0x51/0x60
[<c0143bdf>] sys_open+0x3f/0x70
[<c0106e97>] syscall_call+0x7/0xb

Debug: sleeping function called from invalid context at mm/slab.c:1931
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<c01325c1>] kmem_cache_alloc+0x51/0x60
[<e00c05fb>] zt_timing_open+0x1b/0x60 [zaptel]
[<e00b9c74>] zt_open+0x14/0x20 [zaptel]
[<c014c52a>] chrdev_open+0x9a/0x130
[<c0143934>] dentry_open+0x124/0x1c0
[<c0143801>] filp_open+0x51/0x60
[<c0143bdf>] sys_open+0x3f/0x70
[<c0106e97>] syscall_call+0x7/0xb

Debug: sleeping function called from invalid context at mm/slab.c:1931
in_atomic():0, irqs_disabled():1
Call Trace:
[<c0114a06>] __might_sleep+0x86/0xa0
[<c01325c1>] kmem_cache_alloc+0x51/0x60
[<e00c05fb>] zt_timing_open+0x1b/0x60 [zaptel]
[<e00b9c74>] zt_open+0x14/0x20 [zaptel]
[<c014c52a>] chrdev_open+0x9a/0x130
[<c0143934>] dentry_open+0x124/0x1c0
[<c0143801>] filp_open+0x51/0x60
[<c0143bdf>] sys_open+0x3f/0x70
[<c0106e97>] syscall_call+0x7/0xb
By: Mark Spencer (markster) 2004-05-01 13:29:33

Should be good now.  Please cvs update after an hour or so and let me know that it's good
By: capouch (capouch) 2004-05-01 18:37:41

It seems it's fixed now.  I updated about 1.5 hrs ago, and so far no messages under moderate use.

I'll keep an eye on it closely, and post here if I see anything untowards.
By: Mark Spencer (markster) 2004-05-01 19:09:36

Fixed in CVS
By: Digium Subversion (svnbot) 2008-06-07 10:40:32

Repository: dahdi
Revision: 379

U   trunk/zaptel.c

------------------------------------------------------------------------
r379 | markster | 2008-06-07 10:40:29 -0500 (Sat, 07 Jun 2008) | 2 lines

Don't hold big zap lock in open (bug ASTERISK-1200)

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

http://svn.digium.com/view/dahdi?view=rev&revision=379