Increment zil_itx_needcopy_bytes properly

[chrisrd]

Description

Increment zil_itx_needcopy_bytes properly

Motivation and Context

See #6988

In zil_lwb_commit() with TX_WRITE, we copy the log write record (lrw) into the log write block (lwb) and send it off using zil_lwb_add_txg(). If we also have WR_NEED_COPY, we additionally copy the lwr's data into the lwb to be sent off. If the lwr + data doesn't fit into the lwb, we send the lrw and as much data as will fit (dnow bytes), then go back and do the same with the remaining data.

Each time through this loop we're sending dnow data bytes. I.e. zil_itx_needcopy_bytes should be incremented by dnow.

How Has This Been Tested?

Minimally: compile, install, run.

But I can't test further (other than wait for something to not happen!) as I don't know how to trigger the problem at will.

Types of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Performance enhancement (non-breaking change which improves efficiency)
• Code cleanup (non-breaking change which makes code smaller or more readable)
• Breaking change (fix or feature that would cause existing functionality to change)
• Documentation (a change to man pages or other documentation)

Checklist:

• My code follows the ZFS on Linux code style requirements.
• I have updated the documentation accordingly.
• I have read the CONTRIBUTING document.
• I have added tests to cover my changes.
• All new and existing tests passed.
• All commit messages are properly formatted and contain Signed-off-by.
• Change has been approved by a ZFS on Linux member.

[codecov]

Codecov Report

Merging #7176 into master will decrease coverage by 0.18%.
The diff coverage is 100%.

@@            Coverage Diff             @@
##           master    #7176      +/-   ##
==========================================
- Coverage   76.57%   76.39%   -0.19%     
==========================================
  Files         327      327              
  Lines      103866   103866              
==========================================
- Hits        79537    79350     -187     
- Misses      24329    24516     +187

Flag	Coverage Δ
#kernel	76.01% <100%> (-0.37%)	⬇️
#user	65.67% <100%> (-0.26%)	⬇️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update e086e71...f82fd01. Read the comment docs.

[richardelling]

I'm not convinced dnow is correct, either. My reasoning is that it shouldn't cause the negative.
For now, I'm ok with adding a few debug counters to verify my suspicion, but I'm not sure if we have a good test case.

[chrisrd]

The reason lrw->lr_length goes negative is because dlen, from which dnow is derived, is the rounded up lrw->lr_length. Each time we go through the loop, we send out dnow bytes of lrw->lr_length, and decrement lrw->lr_length accordingly. The last time through the loop, lrw->lr_length goes negative by the amount dlen was rounded up. That's ugly, but it's not a error because by the time that happens we're not going to use lrw->lr_length again (it's used on the next loop iteration and we're not going through again) ...EXCEPT for (prior to the patch) incrementing zil_itx_needcopy_bytes, i.e. the source of the problem!

[chrisrd]

Hmm, maybe the way to trigger the problem is, on an otherwise quiet pool, issue very small (1 byte?) writes such that each write is the only one in the txg (i.e. txg sync secs apart), which would then force the round up and over-decrement lrw->lr_length?

[behlendorf]

This same change should be made when incrementing the zil_itx_copied_bytes above and zil_itx_indirect_bytes below. They can't underflow in the same way but dnow is the accurate length to use.

[chrisrd]

dnow will always be zero in those cases because itx_wr_state != WR_NEED_COPY:

        if (lrc->lrc_txtype == TX_WRITE && itx->itx_wr_state == WR_NEED_COPY) {
                dlen = P2ROUNDUP_TYPED(
                    lrw->lr_length, sizeof (uint64_t), uint64_t);
        } else {
                dlen = 0;
        }
        ...
        dnow = MIN(dlen, lwb_sp - reclen);
        ...
               if (itx->itx_wr_state == WR_COPIED) {
                        ZIL_STAT_BUMP(zil_itx_copied_count);
>>>                     ZIL_STAT_INCR(zil_itx_copied_bytes, lrw->lr_length);
                } else {
                ...
                       if (itx->itx_wr_state == WR_NEED_COPY) {
                                ...
                        } else {
                                ASSERT3S(itx->itx_wr_state, ==, WR_INDIRECT);
                                dbuf = NULL;
                                ZIL_STAT_BUMP(zil_itx_indirect_count);
>>>                             ZIL_STAT_INCR(zil_itx_indirect_bytes,
>>>                                lrw->lr_length);
                        }

[richardelling]

I think the simple change is better than where we are now (dnow? :-)

I'd like to consider recording both dnow and lr_length, but that should be a separate PR, if and when it proves useful. And I'd like to move any test case to the separate PR.

[behlendorf]

@chrisrd good point! OK, then this LGTM and nice job reproducing the issue to veirfy the fix.

[chrisrd]

I have a reproducer!

zpool export testpool
rmmod zfs zcommon znvpair zavl zunicode icp spl
modprobe zfs
echo 1 > /sys/module/zfs/parameters/zfs_txg_timeout
zpool import testpool
sleep 2
dd if=/dev/urandom of=/testpool/1/$i conv=fdatasync bs=1 count=1 2> /dev/null
grep zil_itx_needcopy_bytes /proc/spl/kstat/zfs/zil

Actually wasn't that difficult once you follow the logic in zfs_log_write().

current master, unpatched:

zil_itx_needcopy_bytes          4    18446744073709551609

current master, patched:

zil_itx_needcopy_bytes          4    8

Note the patched zil_itx_needcopy_bytes is the size of the data write rounded up to 8 bytes, per zil_lwb_commit():

                dlen = P2ROUNDUP_TYPED(
                    lrw->lr_length, sizeof (uint64_t), uint64_t);

[chrisrd]

Push: rebased on current master.

[chrisrd]

buildbot Ubuntu 17.10 x86_64 (Test) failures...

mv_files_001_pos looks like a spurious failure:

/usr/share/zfs/zfs-tests/tests/functional/mv_files/mv_files_001_pos (run as root) [00:55] [FAIL]
09:37:33.29 ASSERTION: Doing a 'mv' of a large amount of files within a zfs filesystem works without errors.
09:38:28.90 The file number of target directory 3000 is not equal to that of the source  directory /mnt/testdir/newdir

See #7258

zfs_promote_008_pos also looks like a spurious failure:

Test: /usr/share/zfs/zfs-tests/tests/functional/cli_root/zfs_promote/zfs_promote_008_pos (run as root) [00:00] [FAIL]
08:34:58.51 ASSERTION: 'zfs promote' can promote a volume clone.
...
08:34:58.63 cannot destroy 'testpool/volclone': dataset is busy

Haven't dug into it but I suspect testing somehow to see if the dataset is still busy - or a simple sleep - is needed before trying to clean up.

[behlendorf]

@chrisrd good point! OK, then this LGTM and nice job reproducing the issue to veirfy the fix.

[behlendorf]

Also looks like a spurious failure:

@chrisrd @richardelling as an aside, both mv_files_001_pos and zfs_promote_008_pos are definitely spurious failures.

In fact, I wanted to get a better handle on this so recenty I threw together a known issues page page whch gets automatically refreshed. It still needs some polish but the page shows a summary of the incidence rate of every ZTS failure observed in the master branch. Once an issue gets fixed it'll drop off the list when we haven't seen it in 30 days. The data used comes from the buildbot since it re-tests every commit after it's merged.

My expectation is this should help us resolve the most common spurious failures and provide an easy way for developers to check if something is a known issue. My hope is that now that we have a convenient list we can resolve most of these fairly quickly.

[richardelling]

@behlendorf brilliant!