Hung system call

Question

So I'm working with a custom kernel module that I'm writing a python front end for. The kernel module works, and it adds a framebuffer device file to /dev/fb1. I can read and write to it fine. I've been using python's mmap module to map the device buffer and that seems to work great.

Now I'm trying to implement numpy, and I'm using numpy's memmap function which, my assumption is, should work similarly. The problem is that opening the device file using numpy's memmap function hangs the kernel (I think).

This is what I'm doing to initially open the file

self.surface = np.memmap(dev, dtype=np.uint16, mode='r+', shape=(320,240))

The process hangs, and I can't kill python except through killall python which presumably leaves the file resource open. Any subsequent accesses to open the file again hang indefinitely, simply doing

f = open('/dev/fb1', 'r+b')

and I get this in dmesg

[ 1081.480104] INFO: task python2.6:2834 blocked for more than 120 seconds.
[ 1081.480109] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1081.480113] python2.6     D 0000000100004eec     0  2834      1 0x00000004
[ 1081.480118]  ffff88020a175db8 0000000000000086 0000000000000000 0000000000015980
[ 1081.480122]  ffff88020a175fd8 0000000000015980 ffff88020a175fd8 ffff88022b69adc0
[ 1081.480127]  0000000000015980 0000000000015980 ffff88020a175fd8 0000000000015980
[ 1081.480131] Call Trace:
[ 1081.480142]  [<ffffffff81049b17>] ? mutex_spin_on_owner+0x97/0xc0
[ 1081.480148]  [<ffffffff81589477>] __mutex_lock_slowpath+0xf7/0x180
[ 1081.480151]  [<ffffffff8158935b>] mutex_lock+0x2b/0x50
[ 1081.480157]  [<ffffffff812f3bcf>] fb_release+0x1f/0x60
[ 1081.480161]  [<ffffffff81154825>] __fput+0xf5/0x210
[ 1081.480164]  [<ffffffff81154965>] fput+0x25/0x30
[ 1081.480168]  [<ffffffff81123d35>] remove_vma+0x45/0x90
[ 1081.480171]  [<ffffffff81126179>] do_munmap+0x309/0x3a0
[ 1081.480174]  [<ffffffff81126266>] sys_munmap+0x56/0x80
[ 1081.480180]  [<ffffffff8100a0f2>] system_call_fastpath+0x16/0x1b
[ 1081.480183] INFO: task ipython:2856 blocked for more than 120 seconds.
[ 1081.480185] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1081.480187] ipython       D ffff880256e92018     0  2856   1841 0x00000000
[ 1081.480191]  ffff88022341fb58 0000000000000086 ffffffff81625f10 0000000000015980
[ 1081.480196]  ffff88022341ffd8 0000000000015980 ffff88022341ffd8 ffff88022b7c16e0
[ 1081.480200]  0000000000015980 0000000000015980 ffff88022341ffd8 0000000000015980
[ 1081.480204] Call Trace:
[ 1081.480207]  [<ffffffff81589477>] __mutex_lock_slowpath+0xf7/0x180
[ 1081.480210]  [<ffffffff8158935b>] mutex_lock+0x2b/0x50
[ 1081.480214]  [<ffffffff812f3cd8>] fb_open+0xc8/0x200
[ 1081.480217]  [<ffffffff8115657d>] ? cdev_get+0x2d/0xb0
[ 1081.480221]  [<ffffffff81156e6a>] chrdev_open+0x10a/0x200
[ 1081.480225]  [<ffffffff810878a1>] ? in_group_p+0x31/0x40
[ 1081.480228]  [<ffffffff81156d60>] ? chrdev_open+0x0/0x200
[ 1081.480232]  [<ffffffff811512c5>] __dentry_open+0xe5/0x330
[ 1081.480237]  [<ffffffff81260e4f>] ? security_inode_permission+0x1f/0x30
[ 1081.480240]  [<ffffffff81151624>] nameidata_to_filp+0x54/0x70
[ 1081.480244]  [<ffffffff8115e398>] finish_open+0xe8/0x1d0
[ 1081.480248]  [<ffffffff8116701f>] ? dput+0xdf/0x1b0
[ 1081.480251]  [<ffffffff8115f7f6>] do_last+0x86/0x460
[ 1081.480254]  [<ffffffff81161b2b>] do_filp_open+0x21b/0x660
[ 1081.480259]  [<ffffffff8112117f>] ? handle_mm_fault+0x32f/0x440
[ 1081.480263]  [<ffffffff8116d33a>] ? alloc_fd+0x10a/0x150
[ 1081.480266]  [<ffffffff81151069>] do_sys_open+0x69/0x170
[ 1081.480270]  [<ffffffff811511b0>] sys_open+0x20/0x30
[ 1081.480273]  [<ffffffff8100a0f2>] system_call_fastpath+0x16/0x1b

I guess my question is, can I manually kill the system call? Or somehow get the mutex unlocked? Or am I totally missing what the error is telling me.

The weird thing is that even just the memmap call corrupts the framebuffer and writes garbage to my display. I'm guessing this is just numpy not working well with device files.

Update:

Tis is the output from ps -l. The first python is the one that originally ran the numpy memmap call (at least I'm fairly sure). The second ipython is after the first process hung running a simple plain python open call.

0 D  1000  2834     1  0  80   0 - 22101 fb_rel ?        00:00:00 python2.6
0 D  1000  2856  1841  0  80   0 - 15065 fb_ope pts/1    00:00:00 ipython

Answer 1

The stack trace is saying that the previous python command got wedged in spinlock trying to free the mutex on exit (something has gone horribly wrong). POSIX states you can't free the mutex from a different thread than the one that entered it. The next step is to figure out what resource is causing the mutex to be held on exit. From:

linux-source-2.6.38/kernel/mutex.c:
     69  * The mutex must later on be released by the same task that
     70  * acquired it. Recursive locking is not allowed. The task
     71  * may not exit without first unlocking the mutex. Also, kernel
     72  * memory where the mutex resides mutex must not be freed with
     73  * the mutex still locked. The mutex must first be initialized
     74  * (or statically defined) before it can be locked. memset()-ing
     75  * the mutex to 0 is not allowed.

You could start by stracing the python or by enabling dtrace on the driver.