zil_itx_needcopy_bytes kstat counter is corrupted

[dechamps]

System information

Type	Version/Name
Distribution Name	Debian
Distribution Version	Unstable
Linux Kernel	4.13.0-1-amd64
Architecture	amd64
ZFS Version	0.7.3-3
SPL Version	0.7.3-1

Describe the problem you're observing

$ cat /proc/spl/kstat/zfs/zil
15 1 0x01 13 624 31503034653 382758011634377
name                            type data
zil_commit_count                4    197902
zil_commit_writer_count         4    197884
zil_itx_count                   4    611431070
zil_itx_indirect_count          4    0
zil_itx_indirect_bytes          4    0
zil_itx_copied_count            4    0
zil_itx_copied_bytes            4    0
zil_itx_needcopy_count          4    611266365
zil_itx_needcopy_bytes          4    18446744072731425348
zil_itx_metaslab_normal_count   4    0
zil_itx_metaslab_normal_bytes   4    0
zil_itx_metaslab_slog_count     4    1169526
zil_itx_metaslab_slog_bytes     4    140983216376

The zil_itx_needcopy_bytes counter is blatantly wrong - I'm pretty sure I did not write 16 exabytes of data in that pool :) Its value is quite close to UINT64_MAX, which suggests some kind of overflow or memory corruption.

Describe how to reproduce the problem

Not sure. However I can tell that it started after I did a system upgrade, which included the following version changes:

• Kernel: 4.12 → 4.13
• SPL: 0.6.5 → 0.7.3
• ZFS: 0.6.5 → 0.7.3

For this reason I suspect this might be a regression introduced between SPL/ZFS 0.6.5 and SPL/ZFS 0.7.3.

This issue might seem benign, but in my case it's really not because it prevents Prometheus Node exporter from exporting ZFS metrics correctly. Here's the log message from the node exporter in an attempt to make this issue easier to search for:

time="2017-12-20T22:32:39Z" level=error msg="ERROR: zfs collector failed after 0.000693s: could not parse expected integer value for \"kstat.zfs.misc.zil.zil_itx_needcopy_bytes\"" source="node_exporter.go:95"

[dechamps]

The only place where that counter gets written to in the code is:

https://github.com/zfsonlinux/zfs/blob/1b2b0acab54ad4320e9fab9f46612fdb2a71cf87/module/zfs/zil.c#L1489

It looks like the only way that can happen is if lrw->lr_length itself is corrupted (overflow?), which actually sounds quite scary.

[behlendorf]

That is scary! So it's possible this was fixed in 0.7.4 by commit 4a98780 which is a backport from master. The patch resolves a potential issue where an itx, and thus an lrw->lr_length, might be corrupted under exactly the right circumstances. I've never actually been able to reproduce this specific issue but it's a plausible way to explain the zilstats. And it would only need to have happened once to trash that counter.

If you're able to reproduce the issue I'd suggest updating to 0.7.4 or newer which includes the fix. Locally I haven't been able to reproduce this issue.

[dechamps]

Interesting. I might just try that. I tried to reproduce it by adding a tactical VERIFY3U() before that line and then running ztest, but no luck.

On my live production pool, I know from my Prometheus timeseries that it happens very quickly (< minutes) after the pool comes up, but I have no idea what triggers it specifically. Once I'm back from the holidays I'll try updating to 0.7.4 (or just cherry-picking your patch) and see what happens.

[cwedgwood]

@dechamps underflow?

18446744072731425348 has most MSB set

'-18446744072731425348' is 978126267 which isn't outrageous

[dechamps]

I have upgraded to 0.7.4, and that appears to have fixed the issue.

[dechamps]

Strike my last. It looks like I spoke too fast. The issue is still there in 0.7.4-1. The counter started showing corruption again after about 5 days of uptime.

[nightah]

It appears that I'm having the same issue.

System information

Type	Version/Name
Distribution Name	Arch Linux
Distribution Version	n/a
Linux Kernel	4.14.14-1
Architecture	amd64
ZFS Version	0.7.5-1
SPL Version	0.7.5-1

Describe the problem you're observing

# cat /proc/spl/kstat/zfs/zil
15 1 0x01 13 624 1924297609 504195774290
name                            type data
zil_commit_count                4    7137
zil_commit_writer_count         4    6754
zil_itx_count                   4    126774
zil_itx_indirect_count          4    145
zil_itx_indirect_bytes          4    14166783
zil_itx_copied_count            4    0
zil_itx_copied_bytes            4    0
zil_itx_needcopy_count          4    120733
zil_itx_needcopy_bytes          4    18446744073709013048
zil_itx_metaslab_normal_count   4    5581
zil_itx_metaslab_normal_bytes   4    84571112
zil_itx_metaslab_slog_count     4    0
zil_itx_metaslab_slog_bytes     4    0

Similarly I noticed this when my node exporter instance complained about the same issue as the previous report.

[cwedgwood]

@dechamps what about putting some unused (but exported) guard values before and after it? that way when it's corrupted we could dump those (which by default would be 0) and perhaps get some more insight into this

[cwedgwood]

@dechamps furthermore, if the guard values are being corrupted we could look for this in common code-paths and WARN

[chrisrd]

Me too... zfs-0.7.6, linux-4.9.76 (also noticed via node-exporter failing)

# grep zil_itx_needcopy_bytes /proc/spl/kstat/zfs/zil
zil_itx_needcopy_bytes          4    18446744073709537686

[cwedgwood]

@chrisrd @behlendorf note 18446744073709537686 is 0xffffffffffffc996 - again, high bits set as if an underflow (-13930)

[richardelling]

The logic for the length of the data written is incorrect in zil.c line 1165, allowing a negative
increment soon thereafter.

				if (lrwb->lr_length > dnow)
					lrwb->lr_length = dnow;
				lrw->lr_offset += dnow;
				lrw->lr_length -= dnow;
				ZIL_STAT_BUMP(zil_itx_needcopy_count);
				ZIL_STAT_INCR(zil_itx_needcopy_bytes,
				    lrw->lr_length);

I'll take a closer look at this soon.

Regarding node_explorer, the latest version after 16-jan-2018 should handle uint64 to float64 ok. node_explorer and Prometheus only do floats, so we inevitably will lose resolution. If you can reach out to me at Richard.Elling@RichardElling.com with the error message you saw, I think we can make node_explorer get smarter about these things.

[richardelling]

I can see no benefit to incrementing zil_itx_needcopy_bytes after lrw->lr_length is decremented. IMHO, the benefit of tracking the bytes is to see the relative weight of WR_COPY, WR_NEED_COPY, and WR_INDIRECT. With the relative weighting, decisions can be made wrt zfs_immediate_write_sz and logbias

So I propose moving the lrw->lr_length -= dnow; after the ZIL_STAT_* adjustments. Thoughts?

[chrisrd]

It's all pretty opaque to me, but here goes nothing...

It looks like dnow is how much data we're adding "now" to lwb (via lrcb) and writing out in zil_lwb_add_txg(lwb, txg). And this stuff:

        lrw->lr_offset += dnow; 
        lrw->lr_length -= dnow;

...is recording the offset in the buffer (lr_offset) and how much data (lr_length) we need to output next time we come through the goto cont loop,

So this:

        ZIL_STAT_INCR(zil_itx_needcopy_bytes, lrw->lr_length);

...looks like we're incrementing zil_itx_needcopy_bytes by how much data is remaining, each time through the loop, and lrw->lr_length goes negative when we can fit the whole thing with space left over in the current record (which means we won't come through the loop again).

I suspect the correct thing to do is to increment zil_itx_needcopy_bytes by how much we're writing this time through the loop, i.e.:

        ZIL_STAT_INCR(zil_itx_needcopy_bytes, dnow);

But I've no idea how to test this!