zpool iostat reporting 16E free on a ~266G l2arc device

[adamdmoss]

System information

Type	Version/Name
Distribution Name	ubuntu
Distribution Version	18.04
Linux Kernel	Linux version 5.3.0-46-generic (buildd@lcy01-amd64-013) (gcc version 7.5.0 (Ubuntu 7.5.0-3ubuntu118.04)) #3818.04.1-Ubuntu SMP Tue Mar 31 04:17:56 UTC 2020
Architecture	x64
ZFS Version	HEAD (c614fd6) + #9789
SPL Version	HEAD (c614fd6) + #9789

Describe the problem you're observing

My ~266G l2arc cache device is fully utilized and now it's started reporting that it has 16E free when really it has approximately 0 space free. Hopefully this is a cosmetic issue rather than a fundamental accounting error. :)

I've seen l2arc capacity report errors like this in the past though not for a long time. But then, I rarely completely fill my l2arc.

I'm using HEAD + #9789 ; I don't imagine that #9789 has broken accounting but I mention it since it's related to l2arc.

% zpool iostat -v
                                          capacity     operations     bandwidth 
pool                                    alloc   free   read  write   read  write
--------------------------------------  -----  -----  -----  -----  -----  -----
...
--------------------------------------  -----  -----  -----  -----  -----  -----
zfs4-on-8tbgold                         3.34T  3.92T     16      5  13.0M  1001K
  ata-WDC_WD8004FRYZ-01VAEB0_VAKDG3ML   3.34T  3.92T     16      5  13.0M  1001K
cache                                       -      -      -      -      -      -
  nvme0n1p4                              266G  16.0E    125      9   117M  7.85M
--------------------------------------  -----  -----  -----  -----  -----  -----

Describe how to reproduce the problem

Not sure - perhaps just filling a resonably large l2arc.

Include any warning/errors/backtraces from the system logs

n/a

[gamanakis]

I think this is a cosmetic error, should not happen though. It probably indicates a leak in the accounted space for L2ARC log blocks or buffers. Since we started accounting for the size of log blocks in #9582 similar erratic (but benign) behaviour went away. Will take a look.
As a side note a cache device is never completely full because usually l2arc_evict overestimates the amount of upcoming writes.

[gamanakis]

@adamdmoss could you also post:

• zdb -l cache_device
• grep 'l2_*' /proc/spl/kstat/zfs/arcstats
• grep . /sys/module/zfs/parameters/l2arc_*

#9789 has undergone a number of revisions already. Which one are you using (which commit)?

[adamdmoss]

Ah, good point - HEAD at the time of authoring: a0cf603

[adamdmoss]

% sudo zdb -l /dev/nvme0n1p4
WARNING: ignoring tunable zfs_arc_max (using 4175925248 instead)
------------------------------------
LABEL 0
------------------------------------
    version: 5000
    state: 4
    guid: 16860830594940902945
    l2cache_persistent: true
    labels = 0 1 2 3 
------------------------------------
L2ARC device header
------------------------------------
    magic: 6504978260106102853
    version: 1
    pool_guid: 2267503110332433617
    flags: 0
    start_lbps[0]: 13454730240
    start_lbps[1]: 13437327360
    log_blk_ent: 1022
    start: 4194816
    end: 283998945280
    evict: 13555080192

------------------------------------
L2ARC device log blocks
------------------------------------
Invalid cksum
|		daddr: 12989637120
|		payload_asize: 974628352
|		payload_start: 12015008768
|		lsize: 65536
|		psize: 14848
|		compralgo: 15
|		cksumalgo: 7
|

log_blk_count:	 2 with valid cksum
		 1 with invalid cksum

[adamdmoss]

% grep 'l2_*' /proc/spl/kstat/zfs/arcstats
evict_l2_cached                 4    70138586624
evict_l2_eligible               4    2405790720
evict_l2_ineligible             4    68990976
evict_l2_skip                   4    0
l2_hits                         4    73443
l2_misses                       4    42380
l2_feeds                        4    8191
l2_rw_clash                     4    0
l2_read_bytes                   4    70505387520
l2_write_bytes                  4    5529254400
l2_writes_sent                  4    197
l2_writes_done                  4    197
l2_writes_error                 4    0
l2_writes_lock_retry            4    0
l2_evict_lock_retry             4    0
l2_evict_reading                4    0
l2_evict_l1cached               4    0
l2_free_on_write                4    67
l2_abort_lowmem                 4    0
l2_cksum_bad                    4    2622
l2_io_error                     4    0
l2_size                         4    322032336896
l2_asize                        4    288909543936
l2_hdr_size                     4    191538624
l2_log_blk_writes               4    8
l2_log_blk_avg_size             4    14635
l2_data_to_meta_ratio           4    31871
l2_rebuild_success              4    3
l2_rebuild_unsupported          4    0
l2_rebuild_io_errors            4    0
l2_rebuild_dh_errors            4    0
l2_rebuild_cksum_lb_errors      4    0
l2_rebuild_lowmem               4    0
l2_rebuild_size                 4    316499051008
l2_rebuild_bufs                 4    2008089
l2_rebuild_bufs_precached       4    562
l2_rebuild_psize                4    283800817664
l2_rebuild_log_blks             4    2400

[adamdmoss]

% grep . /sys/module/zfs/parameters/l2arc_*
/sys/module/zfs/parameters/l2arc_feed_again:1
/sys/module/zfs/parameters/l2arc_feed_min_ms:200
/sys/module/zfs/parameters/l2arc_feed_secs:1
/sys/module/zfs/parameters/l2arc_headroom:2
/sys/module/zfs/parameters/l2arc_headroom_boost:200
/sys/module/zfs/parameters/l2arc_noprefetch:0
/sys/module/zfs/parameters/l2arc_norw:0
/sys/module/zfs/parameters/l2arc_rebuild_blocks_min_l2size:1073741824
/sys/module/zfs/parameters/l2arc_rebuild_enabled:1
/sys/module/zfs/parameters/l2arc_trim_ahead:1
/sys/module/zfs/parameters/l2arc_write_boost:8388608
/sys/module/zfs/parameters/l2arc_write_max:1000000000

[adamdmoss]

Here's the precise-value version of iostat in case it yields clues:

% zpool iostat -vp
                                                    capacity                         operations                         bandwidth           
pool                                              alloc             free             read            write             read            write
--------------------------------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------
...
--------------------------------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------
zfs4-on-8tbgold                           3677631561728    4311007608832                1                0           929187           177913
  ata-WDC_WD8004FRYZ-01VAEB0_VAKDG3ML     3677631561728    4311007608832                1                0           929187           177913
cache                                                 -                -                -                -                -                -
  nvme0n1p4                                285845570560  18446744071858731520                8                1          8254318           646856
--------------------------------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------

[adamdmoss]

'Invalid cksum' makes me worry a bit; I'm inclined to remove and re-add the cache device afresh but I'll hold off in case you'd like more debug info.

[gamanakis]

I was expecting the invalid cksum, that is why I asked for these. It is benign though, your data will not be affected in any way. L2ARC will realize the buffers are invalid and read from the storage.

[gamanakis]

@adamdmoss I went through the data and this is what happened I think:
Your cache device had initially 2400 log blocks. Now it reports only 3, the first two are valid, the third one is invalid (its cksum). This means that whatever corrupted it happened recently. Some of the initial revisions of #9789 were broken in terms of trimming, ie it would trim before the writing hand, invalidating previously written buffers and log blocks.

Have you used earlier revisions of #9789?
Right now most of the persistent L2ARC is gone because of the invalid third block. If you export/import or offline/online the cache device it will restore only 2 log blocks out of the initial 2400 (before the corruption).

Now all this tells us nothing about the erroneous report of the 16EB. Looking at l2_asize = 288,909,543,936 bytes while your device has an effective size of end - start + 1 = 283,994,750,465 bytes, meaning 4,914,793,471‬ bytes leaked or in other words were not accounted for most probably by l2arc_evict(). This is causing the 16E to appear in zpool iostat. It is also highly likely that these were bytes for log blocks. From the size of the leak this must have been going on for some time, which makes me suspect #9582 instead of #9789.

I will search to see where exactly this happens.
Meanwhile feel free to re-add the cache device. I believe I got all I needed.
Thank you for helping out!

[gamanakis]

I think I found the leak and the way to mitigate it too.
@adamdmoss thank you for reporting this. Will push a patch soon!

[gamanakis]

It turns out what I thought of initially was not the case. Still investigating.