[LU-5264] ASSERTION( info->oti_r_locks == 0 ) at OST umount

• Type: Bug
• Resolution: Fixed
• Priority: Minor
• Fix Version/s: Lustre 2.8.0
• Affects Version/s: Lustre 2.4.3
• Labels: p4b
• Environment: RHEL6 w/ kernel 2.6.32-431.17.1.el6.x86_64
• Severity: 3
• Assignee: Bruno Faccini (Inactive)
• Reporter: Bruno Travouillon (Inactive)

Description

While stopping a Lustre filesystem, the following LBUG occurred on an OSS:

----8< ----
LustreError: 4581:0:(osd_handler.c:5343:osd_key_exit()) ASSERTION( info->oti_r_locks == 0 ) failed:
Lustre: server umount scratch3-OST0130 complete
LustreError: 4581:0:(osd_handler.c:5343:osd_key_exit()) LBUG
Pid: 4581, comm: ll_ost00_070

Call Trace:
[<ffffffffa0d8c895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
[<ffffffffa0d8ce97>] lbug_with_loc+0x47/0xb0 [libcfs]
[<ffffffffa14da67b>] osd_key_exit+0x5b/0xc0 [osd_ldiskfs]
[<ffffffffa0e5d9f8>] lu_context_exit+0x58/0xa0 [obdclass]
[<ffffffffa0ffd749>] ptlrpc_main+0xa59/0x1700 [ptlrpc]
[<ffffffffa0ffccf0>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
[<ffffffff8100c20a>] child_rip+0xa/0x20
[<ffffffffa0ffccf0>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
[<ffffffffa0ffccf0>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
[<ffffffff8100c200>] ? child_rip+0x0/0x20

Kernel panic - not syncing: LBUG
Pid: 4581, comm: ll_ost00_070 Tainted: G W --------------- 2.6.32-431.11.2.el6.Bull.48.x86_64 #1
Call Trace:
[<ffffffff81528393>] ? panic+0xa7/0x16f
[<ffffffffa0d8ceeb>] ? lbug_with_loc+0x9b/0xb0 [libcfs]
[<ffffffffa14da67b>] ? osd_key_exit+0x5b/0xc0 [osd_ldiskfs]
[<ffffffffa0e5d9f8>] ? lu_context_exit+0x58/0xa0 [obdclass]
[<ffffffffa0ffd749>] ? ptlrpc_main+0xa59/0x1700 [ptlrpc]
[<ffffffffa0ffccf0>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
[<ffffffff8100c20a>] ? child_rip+0xa/0x20
[<ffffffffa0ffccf0>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
[<ffffffffa0ffccf0>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
[<ffffffff8100c200>] ? child_rip+0x0/0x20
----8< ----

There were 15 OSTs mounted on the OSS. One umount process has completed while others were still present at crash time. All umount processes were running in parallel because of Shine (shine stop -f scratch3 -n @io)

----8< ----
crash> ps | grep umount
21639 21636 25 ffff88084445e080 IN 0.0 105176 760 umount
21642 21638 25 ffff8807e0f86b40 IN 0.0 105176 760 umount
21643 21637 26 ffff880b6a78e100 IN 0.0 105176 760 umount
21646 21640 25 ffff880c789fcb40 IN 0.0 106068 756 umount
21649 21644 2 ffff880f9c9740c0 IN 0.0 105176 760 umount
21651 21645 17 ffff88083ecfb580 IN 0.0 106068 756 umount
21653 21648 15 ffff880f97935580 IN 0.0 105176 760 umount
21655 21650 6 ffff880fc5c554c0 IN 0.0 105176 760 umount
21657 21652 25 ffff881076294080 IN 0.0 105176 756 umount
21659 21654 19 ffff880f8f245500 IN 0.0 106068 760 umount
21661 21656 11 ffff8807ec1214c0 IN 0.0 105176 764 umount
21663 21660 30 ffff8808122a9500 IN 0.0 106068 764 umount
21664 21658 3 ffff880b3d1d7500 IN 0.0 105176 764 umount
21665 21662 5 ffff8807ec120a80 IN 0.0 106068 764 umount
----8< ----

Backtrace of the process:

----8< ----
crash> bt
PID: 4581 TASK: ffff881004af1540 CPU: 8 COMMAND: "ll_ost00_070"
#0 [ffff881004af3cb8] machine_kexec at ffffffff8103915b
#1 [ffff881004af3d18] crash_kexec at ffffffff810c5e42
#2 [ffff881004af3de8] panic at ffffffff8152839a
#3 [ffff881004af3e68] lbug_with_loc at ffffffffa0d8ceeb [libcfs]
#4 [ffff881004af3e88] osd_key_exit at ffffffffa14da67b [osd_ldiskfs]
#5 [ffff881004af3e98] lu_context_exit at ffffffffa0e5d9f8 [obdclass]
#6 [ffff881004af3eb8] ptlrpc_main at ffffffffa0ffd749 [ptlrpc]
#7 [ffff881004af3f48] kernel_thread at ffffffff8100c20a
crash> bt -l 4581
PID: 4581 TASK: ffff881004af1540 CPU: 8 COMMAND: "ll_ost00_070"
#0 [ffff881004af3cb8] machine_kexec at ffffffff8103915b
/usr/src/debug/kernel-2.6/linux-2.6.32-431.11.2.el6.Bull.48.x86_64/arch/x86/kernel/machine_kexec_64.c: 336
#1 [ffff881004af3d18] crash_kexec at ffffffff810c5e42
/usr/src/debug/kernel-2.6/linux-2.6.32-431.11.2.el6.Bull.48.x86_64/kernel/kexec.c: 1106
#2 [ffff881004af3de8] panic at ffffffff8152839a
/usr/src/debug/kernel-2.6/linux-2.6.32-431.11.2.el6.Bull.48.x86_64/kernel/panic.c: 111
#3 [ffff881004af3e68] lbug_with_loc at ffffffffa0d8ceeb [libcfs]
/usr/src/debug/lustre-2.4.3/libcfs/libcfs/linux/linux-debug.c: 176
#4 [ffff881004af3e88] osd_key_exit at ffffffffa14da67b [osd_ldiskfs]
/usr/src/debug/lustre-2.4.3/lustre/osd-ldiskfs/osd_handler.c: 5345
#5 [ffff881004af3e98] lu_context_exit at ffffffffa0e5d9f8 [obdclass]
/usr/src/debug/lustre-2.4.3/lustre/obdclass/lu_object.c: 1662
#6 [ffff881004af3eb8] ptlrpc_main at ffffffffa0ffd749 [ptlrpc]
/usr/src/debug/lustre-2.4.3/lustre/ptlrpc/service.c: 2514
#7 [ffff881004af3f48] kernel_thread at ffffffff8100c20a
/usr/src/debug//////////////////////////////////////////////////////////////////kernel-2.6/linux-2.6.32-431.11.2.el6.Bull.48.x86_64/arch/x86/kernel/entry_64.S: 1235
----8< ----

You can find attached:

• dmesg.txt: log from the crash
• bt-all.merged.txt: merged foreach bt from the crash

Issue Links

• is related to: LU-4776 suite sanity-scrub: ASSERTION( info->oti_r_locks == 0 )
• is related to: LU-6800 Significant performance regression with patch LU-5264

Comments

[Bruno Travouillon (Inactive)]

I mean 14 umount processes running for 15 OSTs previously mounted, ie 1 OST has been successfully unmounted for first crash and 5 OSTs have been successfully unmounted for the second one.

[Bruno Travouillon (Inactive)]

Hi Bruno,

I was just looking at the dumps at the customer site. For the first crash, there were still 14 umount processes running for 15 OSTs. For the second, 3 umount processes were remaining for 8 OSTs.

[Bruno Faccini (Inactive)]

After more debugging on my own crash-dump, I think problem comes from the fact that upon umount, presumably of last device using same OSD back-end, to prepare for module unload, lu_context_key_quiesce() is run to remove all module's key reference in any context linked on lu_context_remembered list. Thus threads must protect against such transversal processing when exiting from their context.
Master patch to implement this is at http://review.whamcloud.com/13103.

[Gerrit Updater]

Faccini Bruno ([e-mail]) uploaded a new patch: http://review.whamcloud.com/13103
Subject: LU-5264 obdclass: fix race during key quiescency
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 66dcaa9824f4ae35fb375bc9f9da18c481b7a8f7

[Bruno Faccini (Inactive)]

I have spent sometime this week doing more analysis on my own crash-dump and I should be able to push a patch soon now to fix the suspected race during umounts.

BTW, can you check in your on-site crash-dump/logs that this was the last OST to be unmounted ?

[Bruno Faccini (Inactive)]

Yes, this is strange because you should have crashed with a Kernel Oops/BUG() instead of an LBUG ...
But this may also be the result of a race where lc_value[21] should have still been populated when referenced, causing the LBUG thread to trigger the Assert when the concurent/racing thread may the have zero'ed it ...
BTW, the "good" news is that during the testing of an other patch where I was running MDT/OST mount/umounts in a loop, I have triggered the same LBUG. And its 1st crash analysis steps show the same strange behavior !!! More to come soon.

[Bruno Travouillon (Inactive)]

Hi Bruno,

Here is the requested output. Sorry for the delay.

crash> p/x lu_keys
$8 = {0xffffffffa0ec53e0, 0xffffffffa0ec7aa0, 0xffffffffa0ec6280, 0xffffffffa0ecd720, 0xffffffffa0eb2a20, 0xffffffffa10a39c0, 0xffffffffa0820ac0, 0xffffffffa090d320, 0xffffffffa11b77a0, 0xffffffffa11beac0, 0
xffffffffa11b9c60, 0xffffffffa1254960, 0xffffffffa12549a0, 0xffffffffa12ca080, 0xffffffffa12ca0c0, 0xffffffffa1391f20, 0xffffffffa1391f60, 0xffffffffa1393220, 0xffffffffa1393260, 0xffffffffa1438700, 0xffffff
ffa14386c0, 0xffffffffa15197e0, 0xffffffffa1594f60, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}
crash> lu_env 0xffff88041e7c5d80
struct lu_env {
  le_ctx = {
    lc_tags = 2952790018, 
    lc_state = LCS_LEFT, 
    lc_thread = 0xffff88041227f140, 
    lc_value = 0xffff88041e7c8e00, 
    lc_remember = {
      next = 0xffff881057a58ac0, 
      prev = 0xffff880848277d58
    }, 
    lc_version = 25, 
    lc_cookie = 6
  }, 
  le_ses = 0x0
}
crash> p/x *lu_keys[21]
$9 = {
  lct_tags = 0x400000c3, 
  lct_init = 0xffffffffa14e0330, 
  lct_fini = 0xffffffffa14db1a0, 
  lct_exit = 0xffffffffa14da620, 
  lct_index = 0x15, 
  lct_used = {
    counter = 0x2
  }, 
  lct_owner = 0xffffffffa1526680, 
  lct_reference = {<No data fields>}
}
crash> rd 0xffff88041e7c8e00 40
ffff88041e7c8e00:  ffff88041e7c8c00 0000000000000000   ..|.............
ffff88041e7c8e10:  ffff88041e7c9800 0000000000000000   ..|.............
ffff88041e7c8e20:  0000000000000000 ffff88041e7cac00   ..........|.....
ffff88041e7c8e30:  ffff880418c30d40 ffff88041e7c5cc0   @........\|.....
ffff88041e7c8e40:  ffff88041e7c7dc0 0000000000000000   .}|.............
ffff88041e7c8e50:  ffff88041e7c8a00 0000000000000000   ..|.............
ffff88041e7c8e60:  0000000000000000 0000000000000000   ................
ffff88041e7c8e70:  0000000000000000 0000000000000000   ................
ffff88041e7c8e80:  0000000000000000 0000000000000000   ................
ffff88041e7c8e90:  0000000000000000 0000000000000000   ................
ffff88041e7c8ea0:  0000000000000000 0000000000000000   ................
ffff88041e7c8eb0:  0000000000000000 0000000000000000   ................
ffff88041e7c8ec0:  0000000000000000 0000000000000000   ................
ffff88041e7c8ed0:  0000000000000000 0000000000000000   ................
ffff88041e7c8ee0:  0000000000000000 0000000000000000   ................
ffff88041e7c8ef0:  0000000000000000 0000000000000000   ................
ffff88041e7c8f00:  0000000000000000 0000000000000000   ................
ffff88041e7c8f10:  0000000000000000 0000000000000000   ................
ffff88041e7c8f20:  0000000000000000 0000000000000000   ................
ffff88041e7c8f30:  0000000000000000 0000000000000000   ................

There is no <lc_value[21] pointer value> here... Did I miss something?

We had a new occurrence of this bug last week on the same OSS. I will try to get the output from the new dump.

[Bruno Faccini (Inactive)]

Hello Bruno, can you get me more infos out from the crash-dump+site ?

If yes, here is what I need :

p/x lu_keys
lu_env 0xffff88041e7c5d80

This last command will print you the lu_env struct containing the context ant its lc_value array of pointers address.

And since current index of interest, in both lu_keys[] and lc_value, seems to be #21 ... :

p/x *lu_keys[21]
rd <lc_value address> 40
osd_thread_info <lc_value[21] pointer value> 

Don't forget to load the Lustre modules containing debuginfo stuff before with "mod -S <[debuginfo,modules] root dir>".

[Bruno Travouillon (Inactive)]

Hi Bruno,

You will find attached both 'bt -f' and 'bt -F' from the crash dump.

HTH,

Bruno

[Bruno Faccini (Inactive)]

Humm after having a look to the assembly code of the routines in panic/LBUG stack, it will be difficult/painful for me to really detail the actions/crash-subcommands to get what I need from the crash-dump ... But let's try and 1st I would like to get both the "bt -f" and "bt -F" output for the panic/LBUG task, is it possible ?

Also, this ticket duplicates LU-4776, generated from auto-tests similar failures...

[Bruno Travouillon (Inactive)]

Hi Bruno,

Yes, AFAIK, this is a one shot.
I won't be able to provide the crash-dump because the LBUG occurred on a blacksite. However, please tell me if you need some input, I will try to extract it from the dump.