Messages in this thread | | | From | Tvrtko Ursulin <> | Subject | inotify/fanotify (fsnotify) dead/live lock on 2.6.37 | Date | Tue, 1 Feb 2011 16:08:57 +0000 |
| |
Hi Eric,
We are seeing occasional dead/live locks between processes using inotify and a trivial fanotify client.
detectFanotify is the name of our trivial probe which looks like this:
int main() { int fd;
fd = fanotify_init(0, 0); if (fd >= 0) { close(fd); return 0; }
return 1; }
After a live lock was spotted I found the following in logs which looks like an earlier (not from today) deadlock:
[30723.132262] INFO: task gedit:22430 blocked for more than 120 seconds. [30723.132267] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [30723.132270] gedit D eed2b590 0 22430 1 0x00000000 eeebde48 00200046 eeebddc0 eed2b590 eed2b58c eeebddac c01aea72 eeebdde8 c035e9c5 c0138b06 ef4ae000 eee6bf20 c08cc800 eee6c1a8 eee6c1ac c08cc800 b9fa57ca 00001bc2 c08cc800 c08cc800 c08cc800 00000000 00001bc2 eeeb51c0 Call Trace: [<c01aea72>] ? call_rcu_sched+0x12/0x20 [<c035e9c5>] ? idr_remove+0x125/0x1b0 [<c0138b06>] ? __dequeue_entity+0x26/0x50 [<c024dd53>] ? fsnotify_add_notify_event+0x143/0x1a0 [<c05d8e36>] __mutex_lock_slowpath+0xd6/0x140 [<c05d8d45>] mutex_lock+0x25/0x40 [<c016d000>] __synchronize_srcu+0x20/0xd0 [<c01af170>] ? synchronize_sched+0x0/0x50 [<c016d0e2>] synchronize_srcu+0x12/0x20 [<c024de09>] fsnotify_put_group+0x29/0x40 [<c024f786>] inotify_release+0x26/0x40 [<c021e756>] fput+0xb6/0x230 [<c021b22c>] filp_close+0x4c/0x80 [<c0301c40>] ? exit_sem+0x220/0x230 [<c014c3fb>] put_files_struct+0x6b/0xb0 [<c014c488>] exit_files+0x48/0x60 [<c014e259>] do_exit+0x139/0x730 [<c0143e6f>] ? wake_up_state+0xf/0x20 [<c015b578>] ? signal_wake_up+0x28/0x40 [<c015b5f3>] ? zap_other_threads+0x63/0x80 [<c014e88e>] do_group_exit+0x3e/0xa0 [<c014e908>] sys_exit_group+0x18/0x20 [<c01030df>] sysenter_do_call+0x12/0x28 INFO: task detectFanotify:22490 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. detectFanotif D c08083e4 0 22490 22441 0x00000004 eee73ebc 00000082 c0808a44 c08083e4 f1d23b00 eeea9300 eee73e3c c01dcd52 f77f6d24 000000bf f1d23bbc eee89940 c08cc800 eee89bc8 eee89bcc c08cc800 d86f8029 00001bca c08cc800 c08cc800 c08cc800 d8686840 00001bca ef774a80 Call Trace: [<c01dcd52>] ? find_get_page+0x22/0x90 [<c01dd0d8>] ? unlock_page+0x48/0x50 [<c01f86a8>] ? __do_fault+0x3d8/0x4f0 [<c05d8e36>] __mutex_lock_slowpath+0xd6/0x140 [<c05d8d45>] mutex_lock+0x25/0x40 [<c016d000>] __synchronize_srcu+0x20/0xd0 [<c01af170>] ? synchronize_sched+0x0/0x50 [<c016d0e2>] synchronize_srcu+0x12/0x20 [<c024de09>] fsnotify_put_group+0x29/0x40 [<c02506d9>] fanotify_release+0x99/0xb0 [<c021e756>] fput+0xb6/0x230 [<c021b22c>] filp_close+0x4c/0x80 [<c021b2d5>] sys_close+0x75/0xc0 [<c01030df>] sysenter_do_call+0x12/0x28
Coming back to the live lock spotted today, it looked like this:
detectFanotif R running 0 4184 4121 0x00000004 f477be8c 00000086 00000000 00000000 88383e77 000003dd f6803504 88383e77 000003dd 00000000 f65b6000 f461b280 c08cc800 f461b508 f461b50c c08cc800 88b23324 000003dd c08cc800 c08cc800 c08cc800 00000000 000003dd f43748c0 Call Trace: [<c012b738>] ? default_spin_lock_flags+0x8/0x10 [<c05d9f9f>] ? _raw_spin_lock_irqsave+0x2f/0x50 [<c0157bdc>] ? lock_timer_base+0x2c/0x60 [<c012b738>] ? default_spin_lock_flags+0x8/0x10 [<c05d9f9f>] ? _raw_spin_lock_irqsave+0x2f/0x50 [<c0157bdc>] ? lock_timer_base+0x2c/0x60 [<c05d869f>] schedule_timeout+0x12f/0x260 [<c0150899>] ? irq_exit+0x39/0x70 [<c0157cd0>] ? process_timeout+0x0/0x10 [<c05d882a>] schedule_timeout_interruptible+0x1a/0x20 [<c016d077>] __synchronize_srcu+0x97/0xd0 [<c01af170>] ? synchronize_sched+0x0/0x50 [<c016d0e2>] synchronize_srcu+0x12/0x20 [<c024de09>] fsnotify_put_group+0x29/0x40 [<c02506d9>] fanotify_release+0x99/0xb0 [<c021e756>] fput+0xb6/0x230 [<c021b22c>] filp_close+0x4c/0x80 [<c021b2d5>] sys_close+0x75/0xc0 [<c01030df>] sysenter_do_call+0x12/0x28
What else was involved is a bit hard to say because start of "echo t > /proc/sysrq-trigger" output was lost in transit.
At the same time python version of detectFanotify is stuck:
python D f2ea9e24 0 4265 4255 0x00000000 f2ea9ebc 00000082 00000000 f2ea9e24 f3a62c90 f4555780 f2ea9e3c c01dcd52 f7511ce4 000000ae f477a000 f3c44bc0 c08cc800 f3c44e48 f3c44e4c c08cc800 ef822cf5 00000313 c08cc800 c08cc800 c08cc800 00000000 00000313 f3313380 Call Trace: [<c01dcd52>] ? find_get_page+0x22/0x90 [<c01dd0d8>] ? unlock_page+0x48/0x50 [<c01f86a8>] ? __do_fault+0x3d8/0x4f0 [<c05d8e36>] __mutex_lock_slowpath+0xd6/0x140 [<c05d8d45>] mutex_lock+0x25/0x40 [<c016d000>] __synchronize_srcu+0x20/0xd0 [<c01af170>] ? synchronize_sched+0x0/0x50 [<c016d0e2>] synchronize_srcu+0x12/0x20 [<c024de09>] fsnotify_put_group+0x29/0x40 [<c02506d9>] fanotify_release+0x99/0xb0 [<c021e756>] fput+0xb6/0x230 [<c021b22c>] filp_close+0x4c/0x80 [<c021b2d5>] sys_close+0x75/0xc0 [<c01030df>] sysenter_do_call+0x12/0x28
There are several processes in fsnotify_clear_marks_by_inode:
notification- S 00000082 0 1596 1 0x00000000 f3e97b50 00000082 00000001 00000082 f4326500 00000000 00000000 f3e97abc c0143e50 f3e97ae4 f364c000 f3e7f1a0 c08cc800 f3e7f428 f3e7f42c c08cc800 a46641d6 00000009 c08cc800 c08cc800 c08cc800 00000000 00000009 f454c380 Call Trace: [<c0143e50>] ? default_wake_function+0x10/0x20 [<c05d9f6d>] ? _raw_spin_lock+0xd/0x10 [<c020fea5>] ? add_partial+0x45/0x70 [<c0212173>] ? __slab_free+0x83/0xf0 [<c04ef0c8>] ? sock_destroy_inode+0x28/0x30 [<c022ddbf>] ? __d_free+0x2f/0x50 [<c05d914d>] schedule_hrtimeout_range_clock+0x10d/0x130 [<c022de40>] ? d_free+0x60/0x70 [<c012b738>] ? default_spin_lock_flags+0x8/0x10 [<c05d9f9f>] ? _raw_spin_lock_irqsave+0x2f/0x50 [<c01680f0>] ? add_wait_queue+0x40/0x50 [<c022c465>] ? __pollwait+0x65/0xe0 [<c05d9187>] schedule_hrtimeout_range+0x17/0x20 [<c022c33e>] poll_schedule_timeout+0x3e/0x60 [<c022d086>] do_sys_poll+0x3e6/0x490 [<c0143e40>] ? default_wake_function+0x0/0x20 [<c022c400>] ? __pollwait+0x0/0xe0 [<c022c4e0>] ? pollwake+0x0/0x60 peated 2 times [<c04f6c1d>] ? __kfree_skb+0x3d/0x90 [<c04f6ca9>] ? consume_skb+0x39/0x80 [<c057dc66>] ? unix_stream_recvmsg+0x286/0x5c0 [<c01380c5>] ? update_curr+0x175/0x290 [<c03629d3>] ? rb_insert_color+0xd3/0x110 [<c0138d34>] ? enqueue_entity+0x174/0x440 [<c014401b>] ? check_preempt_wakeup+0x17b/0x250 [<c01354ba>] ? check_preempt_curr+0x6a/0x80 [<c0143af9>] ? try_to_wake_up+0xa9/0x3f0 [<c0143e50>] ? default_wake_function+0x10/0x20 [<c022c534>] ? pollwake+0x54/0x60 [<c0143e40>] ? default_wake_function+0x0/0x20 [<c01347f8>] ? __wake_up_common+0x48/0x70 [<c0230d5d>] ? file_update_time+0xbd/0x130 [<c0212bd9>] ? kmem_cache_alloc_notrace+0x89/0xa0 [<c05d9f6d>] ? _raw_spin_lock+0xd/0x10 [<c024e453>] ? fsnotify_clear_marks_by_inode+0x73/0xb0 [<c0231644>] ? destroy_inode+0x44/0x50 [<c0231644>] ? destroy_inode+0x44/0x50 [<c0231aa7>] ? iput+0x167/0x280 [<c022ddbf>] ? __d_free+0x2f/0x50 [<c022de40>] ? d_free+0x60/0x70 [<c022fad7>] ? dput+0x67/0x120 [<c021e82c>] ? fput+0x18c/0x230 [<c022d2a9>] sys_poll+0x59/0xc0 [<c021b2d5>] ? sys_close+0x75/0xc0 [<c01030df>] sysenter_do_call+0x12/0x28
indicator-ses S 00000001 0 1633 1 0x00000000 f338db50 00000082 3bb51d68 00000001 3bb51d68 f6806800 f4264bc0 f338db6c c05d7b76 f338dae4 f3e38000 f4264bc0 c08cc800 f4264e48 f4264e4c c08cc800 b9bc1b3b 0000000a c08cc800 c08cc800 c08cc800 00000000 0000000a f3deea80 Call Trace: [<c05d7b76>] ? schedule+0x3f6/0xa30 [<c04ef0c8>] ? sock_destroy_inode+0x28/0x30 [<c022ddbf>] ? __d_free+0x2f/0x50 [<c05d914d>] schedule_hrtimeout_range_clock+0x10d/0x130 [<c022de40>] ? d_free+0x60/0x70 [<c012b738>] ? default_spin_lock_flags+0x8/0x10 [<c05d9f9f>] ? _raw_spin_lock_irqsave+0x2f/0x50 [<c01680f0>] ? add_wait_queue+0x40/0x50 [<c022c465>] ? __pollwait+0x65/0xe0 [<c05d9187>] schedule_hrtimeout_range+0x17/0x20 [<c022c33e>] poll_schedule_timeout+0x3e/0x60 [<c022d086>] do_sys_poll+0x3e6/0x490 [<c0143e40>] ? default_wake_function+0x0/0x20 [<c022c400>] ? __pollwait+0x0/0xe0 [<c022c4e0>] ? pollwake+0x0/0x60 peated 2 times [<c04f6c1d>] ? __kfree_skb+0x3d/0x90 [<c04f6ca9>] ? consume_skb+0x39/0x80 [<c057dc66>] ? unix_stream_recvmsg+0x286/0x5c0 [<c01380c5>] ? update_curr+0x175/0x290 [<c0138d34>] ? enqueue_entity+0x174/0x440 [<c014401b>] ? check_preempt_wakeup+0x17b/0x250 [<c01354ba>] ? check_preempt_curr+0x6a/0x80 [<c0143af9>] ? try_to_wake_up+0xa9/0x3f0 [<c0143e50>] ? default_wake_function+0x10/0x20 [<c022c534>] ? pollwake+0x54/0x60 [<c0143e40>] ? default_wake_function+0x0/0x20 [<c01347f8>] ? __wake_up_common+0x48/0x70 [<c014f5db>] ? current_fs_time+0x1b/0x20 [<c0230ce8>] ? file_update_time+0x48/0x130 [<c05d9f6d>] ? _raw_spin_lock+0xd/0x10 [<c05d9f6d>] ? _raw_spin_lock+0xd/0x10 [<c024e453>] ? fsnotify_clear_marks_by_inode+0x73/0xb0 [<c0231644>] ? destroy_inode+0x44/0x50 [<c0231aa7>] ? iput+0x167/0x280 [<c022ddbf>] ? __d_free+0x2f/0x50 [<c022de40>] ? d_free+0x60/0x70 [<c022fad7>] ? dput+0x67/0x120 [<c021e82c>] ? fput+0x18c/0x230 [<c022d2a9>] sys_poll+0x59/0xc0 [<c021b2d5>] ? sys_close+0x75/0xc0 [<c01030df>] sysenter_do_call+0x12/0x28
gedit S 00000001 0 3551 1 0x00000000 f1875b50 00000082 343c5c9e 00000001 343c5c9e f6806800 ef838ca0 f1875b6c c05d7b76 f1875ae4 f6468000 ef838ca0 c08cc800 ef838f28 ef838f2c c08cc800 16cc3c27 0000009d c08cc800 c08cc800 c08cc800 00000000 0000009d f44ff540 Call Trace: [<c05d7b76>] ? schedule+0x3f6/0xa30 [<c04ef0c8>] ? sock_destroy_inode+0x28/0x30 [<c023162e>] ? destroy_inode+0x2e/0x50 [<c0231aa7>] ? iput+0x167/0x280 [<c05d914d>] schedule_hrtimeout_range_clock+0x10d/0x130 [<c022de40>] ? d_free+0x60/0x70 [<c012b738>] ? default_spin_lock_flags+0x8/0x10 [<c05d9f9f>] ? _raw_spin_lock_irqsave+0x2f/0x50 [<c01680f0>] ? add_wait_queue+0x40/0x50 [<c022c465>] ? __pollwait+0x65/0xe0 [<c05d9187>] schedule_hrtimeout_range+0x17/0x20 [<c022c33e>] poll_schedule_timeout+0x3e/0x60 [<c022d086>] do_sys_poll+0x3e6/0x490 [<c0143e40>] ? default_wake_function+0x0/0x20 [<c022c400>] ? __pollwait+0x0/0xe0 [<c022c4e0>] ? pollwake+0x0/0x60 peated 2 times [<c04f6c1d>] ? __kfree_skb+0x3d/0x90 [<c04f6ca9>] ? consume_skb+0x39/0x80 [<c057dc66>] ? unix_stream_recvmsg+0x286/0x5c0 [<c01380c5>] ? update_curr+0x175/0x290 [<c0138d34>] ? enqueue_entity+0x174/0x440 [<c014401b>] ? check_preempt_wakeup+0x17b/0x250 [<c01354ba>] ? check_preempt_curr+0x6a/0x80 [<c0143af9>] ? try_to_wake_up+0xa9/0x3f0 [<c0143e50>] ? default_wake_function+0x10/0x20 [<c022c534>] ? pollwake+0x54/0x60 [<c0143e40>] ? default_wake_function+0x0/0x20 [<c01347f8>] ? __wake_up_common+0x48/0x70 [<c014f5db>] ? current_fs_time+0x1b/0x20 [<c0230ce8>] ? file_update_time+0x48/0x130 [<c05d9f6d>] ? _raw_spin_lock+0xd/0x10 [<c05d9f6d>] ? _raw_spin_lock+0xd/0x10 [<c024e453>] ? fsnotify_clear_marks_by_inode+0x73/0xb0 [<c0231644>] ? destroy_inode+0x44/0x50 [<c0231aa7>] ? iput+0x167/0x280 [<c022ddbf>] ? __d_free+0x2f/0x50 [<c022de40>] ? d_free+0x60/0x70 [<c022fad7>] ? dput+0x67/0x120 [<c021e82c>] ? fput+0x18c/0x230 [<c022d2a9>] sys_poll+0x59/0xc0 [<c021b2d5>] ? sys_close+0x75/0xc0 [<c01030df>] sysenter_do_call+0x12/0x28
Tvrtko
Sophos Limited, The Pentagon, Abingdon Science Park, Abingdon, OX14 3YP, United Kingdom. Company Reg No 2096520. VAT Reg No GB 991 2418 08.
| |