Wrong TAG used by by mmp_write_uberblock() for spa_config_enter()

[sanjeevbagewadi]

System information

Type	Version/Name
Distribution Name	Centos
Distribution Version
Linux Kernel	4.4.14-1.el6
Architecture	x86_64
ZFS Version	0.7.1-1
SPL Version	0.7.1-3_gce8260d

Describe the problem you're observing

Saw the following panic with debug bits while running zfs-testsuite

-- snip --
[    2.668699] Kernel panic - not syncing: No such hold ffffffffa0a017a1 on refcount ffff88028da65a38
[    2.668892] CPU: 0 PID: 24257 Comm: z_null_int Tainted: P           OE   4.4.14-1.el6.nutanix.10272016.x86_64 #1
[    2.669018] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/21/2015
[    2.669161]  0000000000000000 ffff88027d27fb88 ffffffff81319ae3 00000000ffffffff
[    2.669303]  0000000000000038 ffffffffa0a45d08 0000000000000001 ffff88027d27fc08
[    2.669403]  ffffffff811825c9 0000000000000018 ffff88027d27fc18 ffff88027d27fbb8
[    2.669502] Call Trace:
[    2.669547]  [<ffffffff81319ae3>] dump_stack+0x67/0x94
[    2.669607]  [<ffffffff811825c9>] panic+0xc1/0x219
[    2.669664]  [<ffffffff816cd4de>] ? mutex_lock+0xe/0x40
[    2.669793]  [<ffffffffa09180ee>] refcount_remove_many+0x20e/0x240 [zfs]
[    2.669897]  [<ffffffffa0918136>] refcount_remove+0x16/0x20 [zfs]
[    2.669999]  [<ffffffffa093843f>] spa_config_exit+0xaf/0x1e0 [zfs]
[    2.670099]  [<ffffffffa09153e5>] mmp_write_done+0xc5/0x1a0 [zfs]
[    2.670207]  [<ffffffffa09b2bb9>] zio_done+0x709/0x16b0 [zfs]
[    2.670272]  [<ffffffff816cbba9>] ? _cond_resched+0x9/0x30
[    2.670336]  [<ffffffff816ccf19>] ? mutex_unlock+0x9/0x20
[    2.670398]  [<ffffffff816ccf19>] ? mutex_unlock+0x9/0x20
[    2.670519]  [<ffffffffa09aade5>] ? zio_wait_for_children+0xc5/0x180 [zfs]
[    2.670637]  [<ffffffffa09ad11d>] zio_execute+0xed/0x2e0 [zfs]
[    2.670711]  [<ffffffffa07cd76c>] taskq_thread+0x2bc/0x4b0 [spl]
[    2.670797]  [<ffffffff810ad830>] ? try_to_wake_up+0x270/0x270
[    2.670863]  [<ffffffff810a2462>] ? __kthread_parkme+0x12/0x80
[    2.670930]  [<ffffffffa07cd4b0>] ? param_set_taskq_kick+0xf0/0xf0 [spl]
[    2.671000]  [<ffffffff810a263c>] kthread+0xcc/0xf0
[    2.671058]  [<ffffffff810aa5e1>] ? finish_task_switch+0x21/0x270
[    2.671124]  [<ffffffff810abd4e>] ? schedule_tail+0x1e/0xc0
[    2.671186]  [<ffffffff810a2570>] ? kthread_freezable_should_stop+0x70/0x70
[    2.671258]  [<ffffffff816cfacf>] ret_from_fork+0x3f/0x70
[    2.671320]  [<ffffffff810a2570>] ? kthread_freezable_should_stop+0x70/0x70
-- snip --

Describe how to reproduce the problem

Run the mmp setup test of zfs-testsuite.

Include any warning/errors/backtraces from the system logs

[sanjeevbagewadi]

The mmp_write_done() is trying to release the spa_config_lock SCL_CONF.
This lock should have been taken when mmp_write_uberblock() is called when the zio is created:
-- snip --
317 mmp_write_uberblock(spa_t *spa)
318 {
....
325
326 spa_config_enter(spa, SCL_STATE, FTAG, RW_READER);
....
355 label = spa_get_random(VDEV_LABELS);
356 vdev_label_write(zio, vd, label, ub_abd, offset,
357 VDEV_UBERBLOCK_SIZE(vd), mmp_write_done, mmp,
358 flags | ZIO_FLAG_DONT_PROPAGATE);
-- snip --

And that lock is then dropped by the mmp_write_done() in the zio_done() path.
So, it is not quite clear why the hold is missing.

Looking at the panic message :
-- snip --
[10929.065500] Kernel panic - not syncing: No such hold ffffffffa0a017a1 on refcount ffff88028da65a38
-- snip --

The current hold is :
-- snip --
crash> reference_t 0xffff88025e9a1a00
struct reference_t {
ref_link = {
next = 0xffff88028da65a88,
prev = 0xffff88028da65a88
},
ref_holder = 0xffffffffa0a01770 <func.63442>,
ref_number = 1,
ref_removed = 0xffff8801dca80600 "\370\005\250\334\001\210\377\377X\b\250\334\001\210\377\377\300\017\250\334\001\210\377\377\310\001\250\334\001\210\377\377\230\n\250\334\001\210\377\377"
}
-- snip --

Looking at the disassembly of mmp_write_uberblock where the spa_config_enter() is called :
-- snip --
11 0xffffffffa0914a0b <mmp_write_uberblock+27>: mov $0xffffffffa0a01770,%rdx
12 0xffffffffa0914a12 <mmp_write_uberblock+34>: mov $0x2,%esi
13 0xffffffffa0914a17 <mmp_write_uberblock+39>: mov %rdi,%rbx
14 0xffffffffa0914a1a <mmp_write_uberblock+42>: callq 0xffffffffa0938770 <spa_config_enter>
-- snip --

Notice above that "0xffffffffa0a01770" is the value set for holder. And that's the hold present
in the reference_t. So, we have the right hold.
It is the essentially the func value of the caller which is that of mmp_write_uberblock() when
the hold is taken.

However, when the spa_config_exit() is called by mmp_write_done() we endup passing the func of
mmp_write_done(). And hence, the panic.

-- snip --
crash> rd -a 0xffffffffa0a01770 20
ffffffffa0a01770: mmp_write_uberblock <- The current hold is by mmp_write_uberblock

crash> rd -a ffffffffa0a017a1 15
ffffffffa0a017a1: mmp_write_done <- But, in the return path we are checking for mmp_write_done
-- snip --

The fix would be to use a unique tag instead of FTAG for spa_config_enter() in mmp_write_uberblock() and mmp_write_done().

[behlendorf]

@ofaaland can you take a look at this.

[ofaaland]

@sanjeevbagewadi ,
Thanks for your report. Your analysis makes sense to me, but I'm unable to reproduce the panic you get. I notice your SPL build has some additional patches beyond spl-0.7.1. What are those patches?

Also, I notice that your kernel version is later than the one supplied with CentOS 7.3. What is the source of that kernel?

And finally, what configure options were used when you built ZFS? Did you install packages or were you running in-tree?

thanks,
Olaf

[sanjeevbagewadi]

Olaf, I was running the zfs-testsuite with debug bits and it failed in : "Test: /usr/share/zfs/zfs-tests/tests/functional/mmp/mmp_on_thread" Here is a patch that I tested yesterday and that worked well : ```diff diff --git a/module/zfs/mmp.c b/module/zfs/mmp.c index 00478a3..a85c113 100644 --- a/module/zfs/mmp.c +++ b/module/zfs/mmp.c @@ -123,6 +123,7 @@ uint_t zfs_multihost_import_intervals = MMP_DEFAULT_IMPORT_INTERVALS; */ uint_t zfs_multihost_fail_intervals = MMP_DEFAULT_FAIL_INTERVALS; +char *mmp_tag = "mmp_write_uberblock"; static void mmp_thread(spa_t *spa); void @@ -287,7 +288,7 @@ mmp_write_done(zio_t *zio) unlock: mutex_exit(&mts->mmp_io_lock); - spa_config_exit(spa, SCL_STATE, FTAG); + spa_config_exit(spa, SCL_STATE, mmp_tag); abd_free(zio->io_abd); } @@ -323,10 +324,10 @@ mmp_write_uberblock(spa_t *spa) int label; uint64_t offset; - spa_config_enter(spa, SCL_STATE, FTAG, RW_READER); + spa_config_enter(spa, SCL_STATE, mmp_tag, RW_READER); vd = vdev_random_leaf(spa); if (vd == NULL || !vdev_writeable(vd)) { - spa_config_exit(spa, SCL_STATE, FTAG); + spa_config_exit(spa, SCL_STATE, mmp_tag); return; } ``` Thanks and regards, Sanjeev

…

On Tue, Aug 22, 2017 at 2:07 AM, Olaf Faaland ***@***.***> wrote: @sanjeevbagewadi <https://github.com/sanjeevbagewadi> , Thanks for your report. Your analysis makes sense to me, but I'm unable to reproduce the panic you get. I notice your SPL build has some additional patches beyond spl-0.7.1. What are those patches? thanks, Olaf — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#6530 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AK9qqPM1kxr0jxklXxYM8bIjdLX87f2lks5saeqEgaJpZM4O7Spy> .

[ofaaland]

@sanjeevbagewadi ,
Thanks for the suggested patch, but I really want to reproduce your panic before I submit a PR. When you say

I was running the zfs-testsuite with debug bits

Can you be more specific?
thanks

[sanjeevbagewadi]

Olaf, The zfs modules were built with debug flags (aka. --enable-debug) which enabled the ASSERT(). Thanks and regards, Sanjeev

…

On Tue, Aug 22, 2017 at 10:30 PM, Olaf Faaland ***@***.***> wrote: @sanjeevbagewadi <https://github.com/sanjeevbagewadi> , Thanks for the suggested patch, but I really want to reproduce your panic before I submit a PR. When you say I was running the zfs-testsuite with debug bits Can you be more specific? thanks — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#6530 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AK9qqDenpi4kcAl6gsWoYGA3i8_yKGtEks5sawkZgaJpZM4O7Spy> .

[behlendorf]

@sanjeevbagewadi is this still and issue your able to reproduce? And if so can you open a PR with the proposed fix for review and comment.

[sanjeevbagewadi]

Sure. Will do it.