My Oracle Support Banner

ACFS snap hanging on high IO load (Doc ID 2541842.1)

Last updated on JANUARY 07, 2020

Applies to:

Oracle Database - Enterprise Edition - Version 18.3.0.0.0 and later
Information in this document applies to any platform.

Symptoms

ACFS related snap command was getting hang.

acfsutil snap info /<mount path>/datastore

When a heavy direct i/o workload is running the snap delete command can experience long delays in a multiple node environment.

U 5343244.094/181203001114 oks_comm[52894] OKSK-00035: 6 L
LH_SnapMapLockDLMLock state:held elapsed_secs:1
blocked_ticks:2 held_ticks:1643 seq_num:1988896935
U 5343244.094/181203001114 oks_comm[52894] OKSK-00035: 7 L
LH_ResizeDeferLock type: 87 LHV:LH_ResizeDeferLock:87
LHV2:LH_NOTHING:0 mode:0x24:LH_KSRWLOCK,LH_SHARED
U 5343244.094/181203001114 oks_comm[52894] OKSK-00035: 7 L
LH_ResizeDeferLock id1:0xffff881fa884a550 id2:0x0000000000000000
ofsgensnap.c line:40882 prev_tid:0xffff881dd6378e00
U 5343244.094/181203001114 oks_comm[52894] OKSK-00035: 7 L
LH_ResizeDeferLock state:held elapsed_secs:268
blocked_ticks:196252 held_ticks:71859 seq_num:1988890333
U 5343244.094/181203001114 oks_comm[52894] OKSK-00035: 8 F
ofs_snap_COW_map_marker_hand ofsgensnap.c line:40738
elapsed_secs:1048400 seq_num: 1 <<-------
U 5343244.094/181203001114 oks_comm[52894] OKSK-00043: WARNING. Possible DLM
lock contention. tid:0xffff881e45e39c00 name:acfsds2 pid:28160
tsd:0xffff881d9ff989f8 Volume Number:2 record sequence count:10889671341

File_name:: acfs.log.0

Dec 3 06:02:36 xxxxxx01 ntpd[9433]: new interface(s) found:
waking up resolver
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.222191] INFO: task
acfssnap_tmp:7726 blocked for more than 120 seconds.
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.228239] Tainted: P
O 4.1.12-94.8.4.el6uek.x86_64 #2
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.232299] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236888] acfssnap_tmp D
ffffffff81a6d580 0 7726 2 0x00000080
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236892] ffff881a9c1f37f8
0000000000000046 ffff881a9c1f3818 ffff881b07eb0e00
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236895] ffff881ca90415c8
ffff881a9c1f4000 0000000000000000 0000000000000001
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236897] ffff881a9c1f38e8
0000000000000001 ffff881a9c1f3818 ffffffff816abca7
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236899] Call Trace:
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236905]
[<ffffffff816abca7>] schedule+0x37/0x90
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236916]
[<ffffffffa27b5ad9>] KsWaitEvent_OSD+0x3c9/0x570 [oracleoks]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236920]
[<ffffffff810c83c0>] ? wait_woken+0x90/0x90
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236929]
[<ffffffffa27d6ac8>] odlm_wait_on_event+0xd8/0x180 [oracleoks]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236939]
[<ffffffffa28119ae>] convert_lock+0x4bc/0xb0e [oracleoks]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236947]
[<ffffffffa27dd55f>] odlm_cvt+0x1df/0x230 [oracleoks]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236974]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.236994]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237009]
[<ffffffffa2a79185>] OfsAcquireDLMLock_int+0x1475/0x5b90 [oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237021]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237033]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237036]
[<ffffffff811c6c8a>] ? __vunmap+0xca/0x110
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237048]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237065]
[<ffffffffa2ad7ef6>] OfsAcquireLock_int+0x216/0x870 [oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237072]
[<ffffffffa27c9995>] ? KsLHHMRecFnAddInt+0x75/0x230 [oracleoks]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237092]
[<ffffffffa2b0e31d>] ofs_snap_lock_special_locks+0x37d/0xc30 [oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237128]
[<ffffffffa2b54120>] ofs_snap_free_snap_storage+0x190/0x2720 [oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237139]
[<ffffffffa27c5404>] ? KsLHRemove+0x134/0x2e0 [oracleoks]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237145]
[<ffffffff8132d487>] ? call_rwsem_wake+0x17/0x30
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237169]
[<ffffffffa2b56eae>] OfsSnapStorageThread+0x7fe/0xc60 [oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237192]
[<ffffffffa2b566b0>] ? ofs_snap_free_snap_storage+0x2720/0x2720 [oracleacfs]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237197]
[<ffffffffa27b785c>] KsKthreadRun+0x4c/0x90 [oracleoks]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237202]
[<ffffffffa27b7810>] ? KsDelayThreadCommon+0x100/0x100 [oracleoks]
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237204]
[<ffffffff810a304b>] kthread+0xcb/0xf0
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237206]
[<ffffffff810a2f80>] ? kthread_create_on_node+0x180/0x180
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237208]
[<ffffffff816b0752>] ret_from_fork+0x42/0x90
Dec 3 08:30:28 xxxxxx01 kernel: [ 9720.237210]
[<ffffffff810a2f80>] ? kthread_create_on_node+0x180/0x180
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.237143] INFO: task
acfssnap_tmp:7726 blocked for more than 120 seconds.
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.241650] Tainted: P
O 4.1.12-94.8.4.el6uek.x86_64 #2
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.248209] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254736] acfssnap_tmp D
ffffffff81a6d580 0 7726 2 0x00000080
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254740] ffff881a9c1f37f8
0000000000000046 ffff881a9c1f3818 ffff881b07eb0e00
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254742] ffff881ca90415c8
ffff881a9c1f4000 0000000000000000 0000000000000001
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254744] ffff881a9c1f38e8
0000000000000001 ffff881a9c1f3818 ffffffff816abca7
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254747] Call Trace:
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254752]
[<ffffffff816abca7>] schedule+0x37/0x90
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254765]
[<ffffffffa27b5ad9>] KsWaitEvent_OSD+0x3c9/0x570 [oracleoks]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254770]
[<ffffffff810c83c0>] ? wait_woken+0x90/0x90
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254778]
[<ffffffffa27d6ac8>] odlm_wait_on_event+0xd8/0x180 [oracleoks]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254788]
[<ffffffffa28119ae>] convert_lock+0x4bc/0xb0e [oracleoks]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254796]
[<ffffffffa27dd55f>] odlm_cvt+0x1df/0x230 [oracleoks]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254818]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254831]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254845]
[<ffffffffa2a79185>] OfsAcquireDLMLock_int+0x1475/0x5b90 [oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254857]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254869]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254872]
[<ffffffff811c6c8a>] ? __vunmap+0xca/0x110
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254884]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254902]
[<ffffffffa2ad7ef6>] OfsAcquireLock_int+0x216/0x870 [oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254909]
[<ffffffffa27c9995>] ? KsLHHMRecFnAddInt+0x75/0x230 [oracleoks]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254926]
[<ffffffffa2b0e31d>] ofs_snap_lock_special_locks+0x37d/0xc30 [oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254946]
[<ffffffffa2b54120>] ofs_snap_free_snap_storage+0x190/0x2720 [oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254953]
[<ffffffffa27c5404>] ? KsLHRemove+0x134/0x2e0 [oracleoks]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254956]
[<ffffffff8132d487>] ? call_rwsem_wake+0x17/0x30
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254974]
[<ffffffffa2b56eae>] OfsSnapStorageThread+0x7fe/0xc60 [oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254992]
[<ffffffffa2b566b0>] ? ofs_snap_free_snap_storage+0x2720/0x2720 [oracleacfs]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.254997]
[<ffffffffa27b785c>] KsKthreadRun+0x4c/0x90 [oracleoks]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.255004]
[<ffffffffa27b7810>] ? KsDelayThreadCommon+0x100/0x100 [oracleoks]
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.255015]
[<ffffffff810a304b>] kthread+0xcb/0xf0
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.255017]
[<ffffffff810a2f80>] ? kthread_create_on_node+0x180/0x180
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.255021]
[<ffffffff816b0752>] ret_from_fork+0x42/0x90
Dec 3 08:32:28 xxxxxx01 kernel: [ 9840.255023]
[<ffffffff810a2f80>] ? kthread_create_on_node+0x180/0x180
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.255195] INFO: task
acfssnap_tmp:7726 blocked for more than 120 seconds.
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.259231] Tainted: P
O 4.1.12-94.8.4.el6uek.x86_64 #2
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.263097] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267355] acfssnap_tmp D
ffffffff81a6d580 0 7726 2 0x00000080
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267358] ffff881a9c1f37f8
0000000000000046 ffff881a9c1f3818 ffff881b07eb0e00
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267361] ffff881ca90415c8
ffff881a9c1f4000 0000000000000000 0000000000000001
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267363] ffff881a9c1f38e8
0000000000000001 ffff881a9c1f3818 ffffffff816abca7
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267365] Call Trace:
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267371]
[<ffffffff816abca7>] schedule+0x37/0x90
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267382]
[<ffffffffa27b5ad9>] KsWaitEvent_OSD+0x3c9/0x570 [oracleoks]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267387]
[<ffffffff810c83c0>] ? wait_woken+0x90/0x90
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267395]
[<ffffffffa27d6ac8>] odlm_wait_on_event+0xd8/0x180 [oracleoks]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267405]
[<ffffffffa28119ae>] convert_lock+0x4bc/0xb0e [oracleoks]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267414]
[<ffffffffa27dd55f>] odlm_cvt+0x1df/0x230 [oracleoks]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267437]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267450]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267464]
[<ffffffffa2a79185>] OfsAcquireDLMLock_int+0x1475/0x5b90 [oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267476]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267489]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267491]
[<ffffffff811c6c8a>] ? __vunmap+0xca/0x110
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267503]
[<ffffffffa2a5ba90>] ? ofs_dlm_remove_defered_close_lock+0x1a0/0x1a0
[oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267521]
[<ffffffffa2ad7ef6>] OfsAcquireLock_int+0x216/0x870 [oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267528]
[<ffffffffa27c9995>] ? KsLHHMRecFnAddInt+0x75/0x230 [oracleoks]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267546]
[<ffffffffa2b0e31d>] ofs_snap_lock_special_locks+0x37d/0xc30 [oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267565]
[<ffffffffa2b54120>] ofs_snap_free_snap_storage+0x190/0x2720 [oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267572]
[<ffffffffa27c5404>] ? KsLHRemove+0x134/0x2e0 [oracleoks]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267575]
[<ffffffff8132d487>] ? call_rwsem_wake+0x17/0x30
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267594]
[<ffffffffa2b56eae>] OfsSnapStorageThread+0x7fe/0xc60 [oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267612]
[<ffffffffa2b566b0>] ? ofs_snap_free_snap_storage+0x2720/0x2720 [oracleacfs]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267618]
[<ffffffffa27b785c>] KsKthreadRun+0x4c/0x90 [oracleoks]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267622]
[<ffffffffa27b7810>] ? KsDelayThreadCommon+0x100/0x100 [oracleoks]
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267624]
[<ffffffff810a304b>] kthread+0xcb/0xf0
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267626]
[<ffffffff810a2f80>] ? kthread_create_on_node+0x180/0x180
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267628]
[<ffffffff816b0752>] ret_from_fork+0x42/0x90
Dec 3 08:34:28 xxxxxx01 kernel: [ 9960.267630]
[<ffffffff810a2f80>] ? kthread_create_on_node+0x180/0x180

File_name:: messages_xxxxxx01

 

Cause

To view full details, sign in with your My Oracle Support account.

Don't have a My Oracle Support account? Click to get started!


In this Document
Symptoms
Cause
Solution
References


My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.