* [Ocfs2-devel] Find one ocfs2 hang between reflink and ocfs2_complete_recovery
@ 2021-07-01 10:56 Gang He
2021-07-07 2:11 ` Joseph Qi
0 siblings, 1 reply; 5+ messages in thread
From: Gang He @ 2021-07-01 10:56 UTC (permalink / raw)
To: ocfs2-devel
Hi Guys,
There are three node ocfs2 cluster, when the user run reflink command during ocfs2 node does recovery(e.g. one node is fenced).
The hang problem was caused dlm dead lock between rksaph18 and rksaph19, the detailed processes are as below,
Jun 01 12:33:10 rksaph18 kernel: task:reflink state:D stack: 0 pid: 7515 ppid: 7439 flags:0x00004000
Jun 01 12:33:10 rksaph18 kernel: Call Trace:
Jun 01 12:33:10 rksaph18 kernel: __schedule+0x2fd/0x750
Jun 01 12:33:10 rksaph18 kernel: schedule+0x2f/0xa0
Jun 01 12:33:10 rksaph18 kernel: schedule_timeout+0x1cc/0x310
Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
Jun 01 12:33:10 rksaph18 kernel: ? 0xffffffffc08f7000
Jun 01 12:33:10 rksaph18 kernel: wait_for_completion+0xba/0x140
Jun 01 12:33:10 rksaph18 kernel: ? wake_up_q+0xa0/0xa0
Jun 01 12:33:10 rksaph18 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_mv_orphaned_inode_to_new+0x346/0x7e0 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ? _raw_spin_unlock_irqrestore+0x14/0x20
Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink+0x335/0x4c0 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_ioctl+0x25e/0x670 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: do_vfs_ioctl+0xa0/0x680
Jun 01 12:33:10 rksaph18 kernel: ksys_ioctl+0x70/0x80
Jun 01 12:33:10 rksaph18 kernel: __x64_sys_ioctl+0x16/0x20
Jun 01 12:33:10 rksaph18 kernel: do_syscall_64+0x5b/0x1e0
Jun 01 12:33:10 rksaph18 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jun 01 12:33:10 rksaph18 kernel: RIP: 0033:0x7f1bb2aaf9e7
The reflink process is geting orphan_dir_inode(ocfs2 system file per node) dlm lock after it has acquired the reflink target file inode dlm lock, the reflink target file is put in orphan_dir_inode directory during the reflink operation.
Jun 01 12:33:17 rksaph19 kernel: Workqueue: ocfs2_wq ocfs2_complete_recovery [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: Call Trace:
Jun 01 12:33:17 rksaph19 kernel: __schedule+0x2fd/0x750
Jun 01 12:33:17 rksaph19 kernel: schedule+0x2f/0xa0
Jun 01 12:33:17 rksaph19 kernel: schedule_timeout+0x1cc/0x310
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
Jun 01 12:33:17 rksaph19 kernel: ? 0xffffffffc0862000
Jun 01 12:33:17 rksaph19 kernel: wait_for_completion+0xba/0x140
Jun 01 12:33:17 rksaph19 kernel: ? wake_up_q+0xa0/0xa0
Jun 01 12:33:17 rksaph19 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_evict_inode+0x18a/0x810 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: evict+0xca/0x1b0
Jun 01 12:33:17 rksaph19 kernel: ocfs2_orphan_filldir+0x92/0x140 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach_blk+0x4b2/0x570 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x487/0x960 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach+0x54/0x80 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_queue_orphans+0xf2/0x1f0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? __ocfs2_recovery_map_test+0x50/0x50 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? chacha_block_generic+0x6c/0xb0
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? internal_add_timer+0x4e/0x70
Jun 01 12:33:17 rksaph19 kernel: ocfs2_complete_recovery+0x19a/0x450 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? queue_delayed_work_on+0x2a/0x40
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_orphan_scan_work+0x110/0x2c0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: process_one_work+0x1f4/0x3e0
Jun 01 12:33:17 rksaph19 kernel: worker_thread+0x2d/0x3e0
Jun 01 12:33:17 rksaph19 kernel: ? process_one_work+0x3e0/0x3e0
Jun 01 12:33:17 rksaph19 kernel: kthread+0x10d/0x130
Jun 01 12:33:17 rksaph19 kernel: ? kthread_park+0xa0/0xa0
Jun 01 12:33:17 rksaph19 kernel: ret_from_fork+0x22/0x40
The ocfs2_complete_recovery routine is geting that orphan file inode dlm lock after it has acquired orphan_dir_inode dlm lock.
Then, the hang looks like ABBA dead lock.
So far, I cannot reproduce this race condition, but according to the backtraces and the related source code, this problem does exist.
The triggering conditions are related to, the node is runing reflink command when
one node is fenced/down (the dlm recovery routine is triggered).
Any comments?
Thanks
Gang
_______________________________________________
Ocfs2-devel mailing list
Ocfs2-devel@oss.oracle.com
https://oss.oracle.com/mailman/listinfo/ocfs2-devel
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [Ocfs2-devel] Find one ocfs2 hang between reflink and ocfs2_complete_recovery
2021-07-01 10:56 [Ocfs2-devel] Find one ocfs2 hang between reflink and ocfs2_complete_recovery Gang He
@ 2021-07-07 2:11 ` Joseph Qi
2021-07-07 16:44 ` Wengang Wang
2021-07-08 15:49 ` Gang He
0 siblings, 2 replies; 5+ messages in thread
From: Joseph Qi @ 2021-07-07 2:11 UTC (permalink / raw)
To: Gang He, ocfs2-devel
Hi Gang,
Could you please describe the issue in the following way?
Node 1 Node 2 Node 3
...
...
...
That would be more clearly for discussing.
Thanks,
Joseph
On 7/1/21 6:56 PM, Gang He wrote:
> Hi Guys,
>
> There are three node ocfs2 cluster, when the user run reflink command during ocfs2 node does recovery(e.g. one node is fenced).
>
> The hang problem was caused dlm dead lock between rksaph18 and rksaph19, the detailed processes are as below,
>
> Jun 01 12:33:10 rksaph18 kernel: task:reflink state:D stack: 0 pid: 7515 ppid: 7439 flags:0x00004000
> Jun 01 12:33:10 rksaph18 kernel: Call Trace:
> Jun 01 12:33:10 rksaph18 kernel: __schedule+0x2fd/0x750
> Jun 01 12:33:10 rksaph18 kernel: schedule+0x2f/0xa0
> Jun 01 12:33:10 rksaph18 kernel: schedule_timeout+0x1cc/0x310
> Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
> Jun 01 12:33:10 rksaph18 kernel: ? 0xffffffffc08f7000
> Jun 01 12:33:10 rksaph18 kernel: wait_for_completion+0xba/0x140
> Jun 01 12:33:10 rksaph18 kernel: ? wake_up_q+0xa0/0xa0
> Jun 01 12:33:10 rksaph18 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_mv_orphaned_inode_to_new+0x346/0x7e0 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ? _raw_spin_unlock_irqrestore+0x14/0x20
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink+0x335/0x4c0 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_ioctl+0x25e/0x670 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: do_vfs_ioctl+0xa0/0x680
> Jun 01 12:33:10 rksaph18 kernel: ksys_ioctl+0x70/0x80
> Jun 01 12:33:10 rksaph18 kernel: __x64_sys_ioctl+0x16/0x20
> Jun 01 12:33:10 rksaph18 kernel: do_syscall_64+0x5b/0x1e0
> Jun 01 12:33:10 rksaph18 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
> Jun 01 12:33:10 rksaph18 kernel: RIP: 0033:0x7f1bb2aaf9e7
>
> The reflink process is geting orphan_dir_inode(ocfs2 system file per node) dlm lock after it has acquired the reflink target file inode dlm lock, the reflink target file is put in orphan_dir_inode directory during the reflink operation.
>
> Jun 01 12:33:17 rksaph19 kernel: Workqueue: ocfs2_wq ocfs2_complete_recovery [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: Call Trace:
> Jun 01 12:33:17 rksaph19 kernel: __schedule+0x2fd/0x750
> Jun 01 12:33:17 rksaph19 kernel: schedule+0x2f/0xa0
> Jun 01 12:33:17 rksaph19 kernel: schedule_timeout+0x1cc/0x310
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
> Jun 01 12:33:17 rksaph19 kernel: ? 0xffffffffc0862000
> Jun 01 12:33:17 rksaph19 kernel: wait_for_completion+0xba/0x140
> Jun 01 12:33:17 rksaph19 kernel: ? wake_up_q+0xa0/0xa0
> Jun 01 12:33:17 rksaph19 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_evict_inode+0x18a/0x810 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: evict+0xca/0x1b0
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_orphan_filldir+0x92/0x140 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach_blk+0x4b2/0x570 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x487/0x960 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach+0x54/0x80 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_queue_orphans+0xf2/0x1f0 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? __ocfs2_recovery_map_test+0x50/0x50 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? chacha_block_generic+0x6c/0xb0
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? internal_add_timer+0x4e/0x70
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_complete_recovery+0x19a/0x450 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? queue_delayed_work_on+0x2a/0x40
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_orphan_scan_work+0x110/0x2c0 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: process_one_work+0x1f4/0x3e0
> Jun 01 12:33:17 rksaph19 kernel: worker_thread+0x2d/0x3e0
> Jun 01 12:33:17 rksaph19 kernel: ? process_one_work+0x3e0/0x3e0
> Jun 01 12:33:17 rksaph19 kernel: kthread+0x10d/0x130
> Jun 01 12:33:17 rksaph19 kernel: ? kthread_park+0xa0/0xa0
> Jun 01 12:33:17 rksaph19 kernel: ret_from_fork+0x22/0x40
>
> The ocfs2_complete_recovery routine is geting that orphan file inode dlm lock after it has acquired orphan_dir_inode dlm lock.
> Then, the hang looks like ABBA dead lock.
>
> So far, I cannot reproduce this race condition, but according to the backtraces and the related source code, this problem does exist.
> The triggering conditions are related to, the node is runing reflink command when
> one node is fenced/down (the dlm recovery routine is triggered).
>
> Any comments?
>
> Thanks
> Gang
> _______________________________________________
> Ocfs2-devel mailing list
> Ocfs2-devel@oss.oracle.com
> https://oss.oracle.com/mailman/listinfo/ocfs2-devel
>
_______________________________________________
Ocfs2-devel mailing list
Ocfs2-devel@oss.oracle.com
https://oss.oracle.com/mailman/listinfo/ocfs2-devel
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [Ocfs2-devel] Find one ocfs2 hang between reflink and ocfs2_complete_recovery
2021-07-07 2:11 ` Joseph Qi
@ 2021-07-07 16:44 ` Wengang Wang
2021-07-11 9:22 ` Gang He
2021-07-08 15:49 ` Gang He
1 sibling, 1 reply; 5+ messages in thread
From: Wengang Wang @ 2021-07-07 16:44 UTC (permalink / raw)
To: Joseph Qi; +Cc: ocfs2-devel, Gang He
[-- Attachment #1.1: Type: text/plain, Size: 5868 bytes --]
On Jul 6, 2021, at 7:11 PM, Joseph Qi <jiangqi903@gmail.com<mailto:jiangqi903@gmail.com>> wrote:
Hi Gang,
Could you please describe the issue in the following way?
Node 1 Node 2 Node 3
...
...
...
That would be more clearly for discussing.
Thanks,
Joseph
On 7/1/21 6:56 PM, Gang He wrote:
Hi Guys,
There are three node ocfs2 cluster, when the user run reflink command during ocfs2 node does recovery(e.g. one node is fenced).
The hang problem was caused dlm dead lock between rksaph18 and rksaph19, the detailed processes are as below,
Jun 01 12:33:10 rksaph18 kernel: task:reflink state:D stack: 0 pid: 7515 ppid: 7439 flags:0x00004000
Jun 01 12:33:10 rksaph18 kernel: Call Trace:
Jun 01 12:33:10 rksaph18 kernel: __schedule+0x2fd/0x750
Jun 01 12:33:10 rksaph18 kernel: schedule+0x2f/0xa0
Jun 01 12:33:10 rksaph18 kernel: schedule_timeout+0x1cc/0x310
Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
Jun 01 12:33:10 rksaph18 kernel: ? 0xffffffffc08f7000
Jun 01 12:33:10 rksaph18 kernel: wait_for_completion+0xba/0x140
Jun 01 12:33:10 rksaph18 kernel: ? wake_up_q+0xa0/0xa0
Jun 01 12:33:10 rksaph18 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_mv_orphaned_inode_to_new+0x346/0x7e0 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ? _raw_spin_unlock_irqrestore+0x14/0x20
Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink+0x335/0x4c0 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_ioctl+0x25e/0x670 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: do_vfs_ioctl+0xa0/0x680
Jun 01 12:33:10 rksaph18 kernel: ksys_ioctl+0x70/0x80
Jun 01 12:33:10 rksaph18 kernel: __x64_sys_ioctl+0x16/0x20
Jun 01 12:33:10 rksaph18 kernel: do_syscall_64+0x5b/0x1e0
Jun 01 12:33:10 rksaph18 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jun 01 12:33:10 rksaph18 kernel: RIP: 0033:0x7f1bb2aaf9e7
The reflink process is geting orphan_dir_inode(ocfs2 system file per node) dlm lock after it has acquired the reflink target file inode dlm lock, the reflink target file is put in orphan_dir_inode directory during the reflink operation.
Jun 01 12:33:17 rksaph19 kernel: Workqueue: ocfs2_wq ocfs2_complete_recovery [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: Call Trace:
Jun 01 12:33:17 rksaph19 kernel: __schedule+0x2fd/0x750
Jun 01 12:33:17 rksaph19 kernel: schedule+0x2f/0xa0
Jun 01 12:33:17 rksaph19 kernel: schedule_timeout+0x1cc/0x310
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
Jun 01 12:33:17 rksaph19 kernel: ? 0xffffffffc0862000
Jun 01 12:33:17 rksaph19 kernel: wait_for_completion+0xba/0x140
Jun 01 12:33:17 rksaph19 kernel: ? wake_up_q+0xa0/0xa0
Jun 01 12:33:17 rksaph19 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_evict_inode+0x18a/0x810 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: evict+0xca/0x1b0
Jun 01 12:33:17 rksaph19 kernel: ocfs2_orphan_filldir+0x92/0x140 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach_blk+0x4b2/0x570 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x487/0x960 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach+0x54/0x80 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_queue_orphans+0xf2/0x1f0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? __ocfs2_recovery_map_test+0x50/0x50 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? chacha_block_generic+0x6c/0xb0
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? internal_add_timer+0x4e/0x70
Jun 01 12:33:17 rksaph19 kernel: ocfs2_complete_recovery+0x19a/0x450 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? queue_delayed_work_on+0x2a/0x40
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_orphan_scan_work+0x110/0x2c0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: process_one_work+0x1f4/0x3e0
Jun 01 12:33:17 rksaph19 kernel: worker_thread+0x2d/0x3e0
Jun 01 12:33:17 rksaph19 kernel: ? process_one_work+0x3e0/0x3e0
Jun 01 12:33:17 rksaph19 kernel: kthread+0x10d/0x130
Jun 01 12:33:17 rksaph19 kernel: ? kthread_park+0xa0/0xa0
Jun 01 12:33:17 rksaph19 kernel: ret_from_fork+0x22/0x40
The stack on rksaph19 doesn’t look reasonable. The iput() shouldn’t drop the last reference.
I am wondering if f5785283dd64867a711ca1fb1f5bb172f252ecdf fixes your problem.
thanks,
wengang
The ocfs2_complete_recovery routine is geting that orphan file inode dlm lock after it has acquired orphan_dir_inode dlm lock.
Then, the hang looks like ABBA dead lock.
So far, I cannot reproduce this race condition, but according to the backtraces and the related source code, this problem does exist.
The triggering conditions are related to, the node is runing reflink command when
one node is fenced/down (the dlm recovery routine is triggered).
Any comments?
Thanks
Gang
_______________________________________________
Ocfs2-devel mailing list
Ocfs2-devel@oss.oracle.com<mailto:Ocfs2-devel@oss.oracle.com>
https://oss.oracle.com/mailman/listinfo/ocfs2-devel
_______________________________________________
Ocfs2-devel mailing list
Ocfs2-devel@oss.oracle.com<mailto:Ocfs2-devel@oss.oracle.com>
https://oss.oracle.com/mailman/listinfo/ocfs2-devel
[-- Attachment #1.2: Type: text/html, Size: 9005 bytes --]
[-- Attachment #2: Type: text/plain, Size: 151 bytes --]
_______________________________________________
Ocfs2-devel mailing list
Ocfs2-devel@oss.oracle.com
https://oss.oracle.com/mailman/listinfo/ocfs2-devel
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [Ocfs2-devel] Find one ocfs2 hang between reflink and ocfs2_complete_recovery
2021-07-07 2:11 ` Joseph Qi
2021-07-07 16:44 ` Wengang Wang
@ 2021-07-08 15:49 ` Gang He
1 sibling, 0 replies; 5+ messages in thread
From: Gang He @ 2021-07-08 15:49 UTC (permalink / raw)
To: Joseph Qi, ocfs2-devel
Hello Guys,
The detailed process among nodes as below,
Node 1 Node2
reflink command ocfs2_complete_recovery routine
ocfs2_reflink_ioctl ocfs2_complete_recovery
ocfs2_reflink
acquired the target file inode dlm lock ... acquired orphan_dir_inode dlm lock.
ocfs2_mv_orphaned_inode_to_new
blocked at geting orphan_dir_inode dlm lock
ocfs2_evict_inode
blocked at geting the target file inode dlm lock
Thanks
Gang
> Hi Guys,
>
> There are three node ocfs2 cluster, when the user run reflink command during ocfs2 node does recovery(e.g. one node is fenced).
>
> The hang problem was caused dlm dead lock between rksaph18 and rksaph19, the detailed processes are as below,
>
> Jun 01 12:33:10 rksaph18 kernel: task:reflink state:D stack: 0 pid: 7515 ppid: 7439 flags:0x00004000
> Jun 01 12:33:10 rksaph18 kernel: Call Trace:
> Jun 01 12:33:10 rksaph18 kernel: __schedule+0x2fd/0x750
> Jun 01 12:33:10 rksaph18 kernel: schedule+0x2f/0xa0
> Jun 01 12:33:10 rksaph18 kernel: schedule_timeout+0x1cc/0x310
> Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
> Jun 01 12:33:10 rksaph18 kernel: ? 0xffffffffc08f7000
> Jun 01 12:33:10 rksaph18 kernel: wait_for_completion+0xba/0x140
> Jun 01 12:33:10 rksaph18 kernel: ? wake_up_q+0xa0/0xa0
> Jun 01 12:33:10 rksaph18 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_mv_orphaned_inode_to_new+0x346/0x7e0 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ? _raw_spin_unlock_irqrestore+0x14/0x20
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink+0x335/0x4c0 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: ocfs2_ioctl+0x25e/0x670 [ocfs2]
> Jun 01 12:33:10 rksaph18 kernel: do_vfs_ioctl+0xa0/0x680
> Jun 01 12:33:10 rksaph18 kernel: ksys_ioctl+0x70/0x80
> Jun 01 12:33:10 rksaph18 kernel: __x64_sys_ioctl+0x16/0x20
> Jun 01 12:33:10 rksaph18 kernel: do_syscall_64+0x5b/0x1e0
> Jun 01 12:33:10 rksaph18 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
> Jun 01 12:33:10 rksaph18 kernel: RIP: 0033:0x7f1bb2aaf9e7
>
> The reflink process is geting orphan_dir_inode(ocfs2 system file per node) dlm lock after it has acquired the reflink target file inode dlm lock, the reflink target file is put in orphan_dir_inode directory during the reflink operation.
>
> Jun 01 12:33:17 rksaph19 kernel: Workqueue: ocfs2_wq ocfs2_complete_recovery [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: Call Trace:
> Jun 01 12:33:17 rksaph19 kernel: __schedule+0x2fd/0x750
> Jun 01 12:33:17 rksaph19 kernel: schedule+0x2f/0xa0
> Jun 01 12:33:17 rksaph19 kernel: schedule_timeout+0x1cc/0x310
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
> Jun 01 12:33:17 rksaph19 kernel: ? 0xffffffffc0862000
> Jun 01 12:33:17 rksaph19 kernel: wait_for_completion+0xba/0x140
> Jun 01 12:33:17 rksaph19 kernel: ? wake_up_q+0xa0/0xa0
> Jun 01 12:33:17 rksaph19 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_evict_inode+0x18a/0x810 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: evict+0xca/0x1b0
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_orphan_filldir+0x92/0x140 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach_blk+0x4b2/0x570 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x487/0x960 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach+0x54/0x80 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_queue_orphans+0xf2/0x1f0 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? __ocfs2_recovery_map_test+0x50/0x50 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? chacha_block_generic+0x6c/0xb0
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? internal_add_timer+0x4e/0x70
> Jun 01 12:33:17 rksaph19 kernel: ocfs2_complete_recovery+0x19a/0x450 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: ? queue_delayed_work_on+0x2a/0x40
> Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_orphan_scan_work+0x110/0x2c0 [ocfs2]
> Jun 01 12:33:17 rksaph19 kernel: process_one_work+0x1f4/0x3e0
> Jun 01 12:33:17 rksaph19 kernel: worker_thread+0x2d/0x3e0
> Jun 01 12:33:17 rksaph19 kernel: ? process_one_work+0x3e0/0x3e0
> Jun 01 12:33:17 rksaph19 kernel: kthread+0x10d/0x130
> Jun 01 12:33:17 rksaph19 kernel: ? kthread_park+0xa0/0xa0
> Jun 01 12:33:17 rksaph19 kernel: ret_from_fork+0x22/0x40
>
> The ocfs2_complete_recovery routine is geting that orphan file inode dlm lock after it has acquired orphan_dir_inode dlm lock.
> Then, the hang looks like ABBA dead lock.
>
> So far, I cannot reproduce this race condition, but according to the backtraces and the related source code, this problem does exist.
> The triggering conditions are related to, the node is runing reflink command when
> one node is fenced/down (the dlm recovery routine is triggered).
>
> Any comments?
>
> Thanks
> Gang
> _______________________________________________
> Ocfs2-devel mailing list
> Ocfs2-devel@oss.oracle.com
> https://oss.oracle.com/mailman/listinfo/ocfs2-devel
>
_______________________________________________
Ocfs2-devel mailing list
Ocfs2-devel@oss.oracle.com
https://oss.oracle.com/mailman/listinfo/ocfs2-devel
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [Ocfs2-devel] Find one ocfs2 hang between reflink and ocfs2_complete_recovery
2021-07-07 16:44 ` Wengang Wang
@ 2021-07-11 9:22 ` Gang He
0 siblings, 0 replies; 5+ messages in thread
From: Gang He @ 2021-07-11 9:22 UTC (permalink / raw)
To: Wengang Wang, Joseph Qi; +Cc: ocfs2-devel
Hello Wengang,
Thank for your information.
That patch looks very similar with the problem.
I will verify it with the patch.
Thanks
Gang
________________________________________
From: Wengang Wang <wen.gang.wang@oracle.com>
Sent: Thursday, July 8, 2021 0:44
To: Joseph Qi
Cc: Gang He; ocfs2-devel@oss.oracle.com
Subject: Re: [Ocfs2-devel] Find one ocfs2 hang between reflink and ocfs2_complete_recovery
On Jul 6, 2021, at 7:11 PM, Joseph Qi <jiangqi903@gmail.com<mailto:jiangqi903@gmail.com>> wrote:
Hi Gang,
Could you please describe the issue in the following way?
Node 1 Node 2 Node 3
...
...
...
That would be more clearly for discussing.
Thanks,
Joseph
On 7/1/21 6:56 PM, Gang He wrote:
Hi Guys,
There are three node ocfs2 cluster, when the user run reflink command during ocfs2 node does recovery(e.g. one node is fenced).
The hang problem was caused dlm dead lock between rksaph18 and rksaph19, the detailed processes are as below,
Jun 01 12:33:10 rksaph18 kernel: task:reflink state:D stack: 0 pid: 7515 ppid: 7439 flags:0x00004000
Jun 01 12:33:10 rksaph18 kernel: Call Trace:
Jun 01 12:33:10 rksaph18 kernel: __schedule+0x2fd/0x750
Jun 01 12:33:10 rksaph18 kernel: schedule+0x2f/0xa0
Jun 01 12:33:10 rksaph18 kernel: schedule_timeout+0x1cc/0x310
Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
Jun 01 12:33:10 rksaph18 kernel: ? 0xffffffffc08f7000
Jun 01 12:33:10 rksaph18 kernel: wait_for_completion+0xba/0x140
Jun 01 12:33:10 rksaph18 kernel: ? wake_up_q+0xa0/0xa0
Jun 01 12:33:10 rksaph18 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_mv_orphaned_inode_to_new+0x346/0x7e0 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ? _raw_spin_unlock_irqrestore+0x14/0x20
Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink+0x335/0x4c0 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ? ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_reflink_ioctl+0x2ca/0x360 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: ocfs2_ioctl+0x25e/0x670 [ocfs2]
Jun 01 12:33:10 rksaph18 kernel: do_vfs_ioctl+0xa0/0x680
Jun 01 12:33:10 rksaph18 kernel: ksys_ioctl+0x70/0x80
Jun 01 12:33:10 rksaph18 kernel: __x64_sys_ioctl+0x16/0x20
Jun 01 12:33:10 rksaph18 kernel: do_syscall_64+0x5b/0x1e0
Jun 01 12:33:10 rksaph18 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jun 01 12:33:10 rksaph18 kernel: RIP: 0033:0x7f1bb2aaf9e7
The reflink process is geting orphan_dir_inode(ocfs2 system file per node) dlm lock after it has acquired the reflink target file inode dlm lock, the reflink target file is put in orphan_dir_inode directory during the reflink operation.
Jun 01 12:33:17 rksaph19 kernel: Workqueue: ocfs2_wq ocfs2_complete_recovery [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: Call Trace:
Jun 01 12:33:17 rksaph19 kernel: __schedule+0x2fd/0x750
Jun 01 12:33:17 rksaph19 kernel: schedule+0x2f/0xa0
Jun 01 12:33:17 rksaph19 kernel: schedule_timeout+0x1cc/0x310
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_control_cfu+0x50/0x50 [ocfs2_stack_user]
Jun 01 12:33:17 rksaph19 kernel: ? 0xffffffffc0862000
Jun 01 12:33:17 rksaph19 kernel: wait_for_completion+0xba/0x140
Jun 01 12:33:17 rksaph19 kernel: ? wake_up_q+0xa0/0xa0
Jun 01 12:33:17 rksaph19 kernel: __ocfs2_cluster_lock.isra.41+0x3b5/0x820 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_inode_lock_full_nested+0x1fc/0x960 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_evict_inode+0x18a/0x810 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: evict+0xca/0x1b0
Jun 01 12:33:17 rksaph19 kernel: ocfs2_orphan_filldir+0x92/0x140 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach_blk+0x4b2/0x570 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_inode_lock_full_nested+0x487/0x960 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_dir_foreach+0x54/0x80 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_queue_orphans+0xf2/0x1f0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? __ocfs2_recovery_map_test+0x50/0x50 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? chacha_block_generic+0x6c/0xb0
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ocfs2_recover_orphans+0x12d/0x4f0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? internal_add_timer+0x4e/0x70
Jun 01 12:33:17 rksaph19 kernel: ocfs2_complete_recovery+0x19a/0x450 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: ? queue_delayed_work_on+0x2a/0x40
Jun 01 12:33:17 rksaph19 kernel: ? ocfs2_orphan_scan_work+0x110/0x2c0 [ocfs2]
Jun 01 12:33:17 rksaph19 kernel: process_one_work+0x1f4/0x3e0
Jun 01 12:33:17 rksaph19 kernel: worker_thread+0x2d/0x3e0
Jun 01 12:33:17 rksaph19 kernel: ? process_one_work+0x3e0/0x3e0
Jun 01 12:33:17 rksaph19 kernel: kthread+0x10d/0x130
Jun 01 12:33:17 rksaph19 kernel: ? kthread_park+0xa0/0xa0
Jun 01 12:33:17 rksaph19 kernel: ret_from_fork+0x22/0x40
The stack on rksaph19 doesn’t look reasonable. The iput() shouldn’t drop the last reference.
I am wondering if f5785283dd64867a711ca1fb1f5bb172f252ecdf fixes your problem.
thanks,
wengang
The ocfs2_complete_recovery routine is geting that orphan file inode dlm lock after it has acquired orphan_dir_inode dlm lock.
Then, the hang looks like ABBA dead lock.
So far, I cannot reproduce this race condition, but according to the backtraces and the related source code, this problem does exist.
The triggering conditions are related to, the node is runing reflink command when
one node is fenced/down (the dlm recovery routine is triggered).
Any comments?
Thanks
Gang
_______________________________________________
Ocfs2-devel mailing list
Ocfs2-devel@oss.oracle.com<mailto:Ocfs2-devel@oss.oracle.com>
https://oss.oracle.com/mailman/listinfo/ocfs2-devel
_______________________________________________
Ocfs2-devel mailing list
Ocfs2-devel@oss.oracle.com<mailto:Ocfs2-devel@oss.oracle.com>
https://oss.oracle.com/mailman/listinfo/ocfs2-devel
_______________________________________________
Ocfs2-devel mailing list
Ocfs2-devel@oss.oracle.com
https://oss.oracle.com/mailman/listinfo/ocfs2-devel
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2021-07-11 9:23 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-07-01 10:56 [Ocfs2-devel] Find one ocfs2 hang between reflink and ocfs2_complete_recovery Gang He
2021-07-07 2:11 ` Joseph Qi
2021-07-07 16:44 ` Wengang Wang
2021-07-11 9:22 ` Gang He
2021-07-08 15:49 ` Gang He
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.