Sporadic system hang

[nivedita76]

System information

Type	Version/Name
Distribution Name	Gentoo
Distribution Version
Linux Kernel	4.16.1
Architecture	x86_64
ZFS Version	git 421_gbdc0b4bf1
SPL Version	git 32_g581bc01

SPL/ZFS are builtin to the kernel

Describe the problem you're observing

Kernel triggers hung task timeout. System kind of works after that but many commands hang.

Describe how to reproduce the problem

This happens when running a full system recompile along with folding @ home client, no easy repro known.
hung.log

Include any warning/errors/backtraces from the system logs

[RubenKelevra]

Can you provide your settings?

zfs get all $pool/$volume

[nivedita76]

pool.txt

[RubenKelevra]

Might be a skein issue ... did anyone do a benchmark with skein on? I use edonr which is the fastest apart from fletcher, which isn't actually very good at detecting multiple bitflips. So edonr should do the trick here.

You might want to provoke the system hang with an IO-Benchmark and take a look at atop 1 which resource is actually limiting the performance.

[rincebrain]

@nivedita76 Can you share what zpool status looks like? Also, you could try kicking (writing nonzero) to /sys/module/spl/parameters/spl_taskq_kick and it'll try spawning more threads to handle any taskq that's waited for longer than...I forget, 30s?

Is this a regression, or did you have his problem before? If it's a regression, bisecting it would be the most straightforward way to try and find the problematic area without more of a smoking gun.

SysRq-T's output might also be useful, though that's quite a lot (I think that's the one for all tasks...maybe l or d would be more useful and terse)

[nivedita76]

The docs say skein is supposed to be relatively fast as well.
This is a fairly new pool only a couple months I think so it’s always been on recent zfs git. I’ve been having a different race condition that just got fixed so noticed this hang only recently.
I’ll try to get that other data while it is hung. The pool status itself is clean with no errors. Scrubs don’t find anything to fix so it doesn’t seem like it corrupts anything.
I’m also trying with lock debugging i’ll Post a few things about that once I get home.

[rincebrain]

@nivedita76 I should have been more clear, sorry. I meant that I wanted to see all of zpool status's output to know whether this is 2 or 50 disks, whether there's a dedicated log device, etc.

[nivedita76]

Ah sorry. This is a mirror of two nvme partitions. No dedicated zlog.

[RubenKelevra]

Do setting sync to disabled change anything on your issue? Maybe the nvme's are slow on synchronous operations.

The docs say skein is supposed to be relatively fast as well.

I know that, but I was more curious if someone actually tested the implementation. Since those are pretty new, this might not be the case. I can only speak for edonr, which is a fast as fletcher on subjectively perceived performance while sha256 was, on slower machines with high throughput, noticeably slower

[nivedita76]

This is not a performance problem. The system hung at night and was still hung in the morning. There’s a deadlock or something like that.

[rincebrain]

@nivedita76 Then you probably want to get the output of SysRq-D and/or L a/o T, though I think your dmesg output says you'd need to build a kernel with CONFIG_LOCKDEP enabled to get D. I guess W would also do pretty well depending on what kind of deadlock it is, since any deadlock for a long enough time should log to dmesg about being stuck (more than once), unless there's a "suppressed duplicates" message somewhere.

[nivedita76]

I'm trying to turn on the lock validator but running into some issues. First couple I managed to work around with attached patch.
lockpatch.txt

But I still get a lock inversion warning pretty quickly and then it turns itself off.

kern.log

So for now I turned off the lock validator and am trying to reproduce the hang.

[nivedita76]

I got a list of locks held this time, although not sure I understand it, it shows zl_issuer_lock held by two processes. SysRq-d/w/t/l didn't print out anything on the console, not sure why.
hung.log

I forgot to try the taskq kick thing before rebooting unfortunately.

[rincebrain]

@nivedita76 Hm, it might be useful to have a version of ZFS with --enable-debug and zfs_dbgmsg enabled, since it's not an obvious cause of the deadlock (I mean, other than the tautological one, they're both trying to take the same lock).

[nivedita76]

I do have enable debug. Should I just grab the contents of dbgmsg or do I have to set something to make it more verbose

[rincebrain]

You need to set zfs_flags=[integer value corresponding to the bitmask of messages you want] cf. https://github.com/zfsonlinux/zfs/blob/master/include/sys/zfs_debug.h#L46

We could just start with 1 and go from there.