ufs snapshot is sometimes corrupt on gjourneled partition

Andreas Longwitz longwitz at incore.de
Sun Jul 16 16:00:04 UTC 2017


Hello,

I like to discuss the following code snippet from function
indiracct_ufs2() in source file ffs_snapshot.c:

    /*
     * We have to expand bread here since it will deadlock looking
     * up the block number for any blocks that are not in the cache.
     */
    bp = getblk(cancelvp, lbn, fs->fs_bsize, 0, 0, 0);
    bp->b_blkno = fsbtodb(fs, blkno);
    if ((bp->b_flags & (B_DONE | B_DELWRI)) == 0 &&
        (error = readblock(cancelvp, bp, fragstoblks(fs, blkno)))) {
            brelse(bp);
            return (error);
    }

In all my tests (all mount types, good or bad result) the flags B_DONE
and B_DELWRI in bp->b_flags were alway zero, so the data buffer given by
getblk() at bp->b_data is always overwritten with the data from the
explicit I/O performed by readblock(). By the way the flag B_CACHE was
always set. I have saved the buffer given by getblk() and compared this
buffer with the data read by readblock(). Without gjournal there is
never a difference. Using a gjournaled partition  things are more
sophisticated. Taking a snapshot in my example environment needs 678
calls of getblk(). In the "good case" all I/O's performed by readblock()
gave the same data as getblk(), in the "bad case" there are some
differences between the data in buffer cache seen by getblk() and the
data on disk seen by readblock(). Mostly two or three of the 678 blocks
are different. In this case the block read by readblock() is always
zero, the block read by getblk() has a lot of BLK_NOCOPY values,
sometimes 4096 (a full block).

There is one other flag in bp->b_flags given by getblk that is of
interest: B_CLUSTEROK. This flag is always in sync with the flag
BV_SCANNED in bp->b_vflags. In the above code snippet I can check this
flag too before going to disk:

   if (bp->b_flags & (B_DONE | B_DELWRI | B_CLUSTEROK)) == 0 && ...

With this patch the problem has gone in all my tests. The resulting
snapblklist written to the end of the snapfile is always the same.

I am not familiar with buffer and memory management of FreeBSD, so I can
not explain what is going on. But I see in cgaccount() a lot of
BLK_NOCOPY values are set and in expunge_ufs2() these values should be
seen again. It seems they are in the buffer cache but sometimes not on
disk. The patch given above in my test example reads data from buffer
cache instead of from disk 141 times.

All sync operations in ffs_snapshot() use the parameter MNT_WAIT, the
gjournal switcher runs all the time but syncs the same partition with
MNT_NOWAIT (g_journal.c: vfs_msync followed by VFS_SYNC). I do not know
if this can lead to a race condition between gjournal and snapshot.


>> Kirk McKusick wrote:
>>> Date: Sat, 24 Jun 2017 18:30:17 +0300
>>> From: Konstantin Belousov <kostikbel at gmail.com>
>>> To: Andreas Longwitz <longwitz at incore.de>
>>> Subject: Re: ufs snapshot is sometimes corrupt on gjourneled partition
>>>
>>> On Fri, Jun 23, 2017 at 11:14:43AM +0200, Andreas Longwitz wrote:
>>>> I try to understand the cause for the "free inode" problem described in
>>>>   https://lists.freebsd.org/pipermail/freebsd-fs/2013-November/018610.html
>>>>
>>>> I have setup a test server (FreeBSD 10.3-STABLE #4 r317936) with a
>>>> gjournaled partition for /home:
>>>> mount -t ufs | grep /home -->
>>>> /dev/mirror/gmsvt7p10.journal on /home (ufs, asynchronous, local,
>>>> noatime, gjournal)
>>> As the first thing to try, if you perform your tests on the raw
>>> partition without gjournal, does the problem stay around ?
>> I concur that running your test without gjournal is the next test to try.
>> I think that your suspicion that there is a race condition with gjournal
>> is likely correct. And if that is true, then the problem will go away
>> when gjournal is taken out of the stack.
> 
> The problem only accurs when gjournal is active (tunefs -J) independent
> of the three possible mount options I have tested: async, noasync, sync.
> For my test I prefer async mount option as stated in gjournal(8). Using
> soft updates instead of gjournal is ok in all cases.
> 
>>>> My test creates one snapshot of /home (gets alway inode 4) and removes
>>>> this snapshot:
>>>>
>>>>   for i in 1 2 3 4 5 6 7 8; do
>>>>      echo "starting snaptest $i" >/dev/console
>>>>      mount -u -o snapshot -o noatime -o async /home/.snap/fscktest /home
>>>>      echo $(ls -ils /home/.snap/fscktest) >/dev/console
>>>>      rm -f /home/.snap/fscktest
>>>>   done
>>>>
>>>> I never have more than this one snapshot at work and during the test I
>>>> never have any other
>>>> user processes working on /home. A typical output looks like this:
>>>>
>>>> Jun 21 15:59:52 root: starting snaptest 1
>>>> Jun 21 15:59:52 root: 4 26592 -r--------  1 root  operator  90762970240
>>>> 21 Jun 15:59 /home/.snap/fscktest
>>>> Jun 21 15:59:53 root: starting snaptest 2
>>>> Jun 21 15:59:53 root: 4 26592 -r--------  1 root  operator  90762970152
>>>> 21 Jun 15:59 /home/.snap/fscktest
>>>> Jun 21 15:59:54 kernel: freeing inode /home/4 with 704 blocks
>>>> Jun 21 15:59:54 root: starting snaptest 3
>>>> Jun 21 15:59:54 kernel: free inode /home/4 had 704 blocks
>>>> Jun 21 15:59:54 root: 4 26592 -r--------  1 root  operator  90762969976
>>>> 21 Jun 15:59 /home/.snap/fscktest
>>>> Jun 21 15:59:56 kernel: freeing inode /home/4 with 2112 blocks
>>>> Jun 21 15:59:56 root: starting snaptest 4
>>>> Jun 21 15:59:56 kernel: free inode /home/4 had 2112 blocks
>>>> Jun 21 15:59:56 root: 4 26592 -r--------  1 root  operator  90762970240
>>>> 21 Jun 15:59 /home/.snap/fscktest
>>>> Jun 21 15:59:57 root: starting snaptest 5
>>>> Jun 21 15:59:57 root: 4 26592 -r--------  1 root  operator  90762970240
>>>> 21 Jun 15:59 /home/.snap/fscktest
>>>> Jun 21 15:59:58 root: starting snaptest 6
>>>> Jun 21 15:59:58 root: 4 26592 -r--------  1 root  operator  90762970216
>>>> 21 Jun 15:59 /home/.snap/fscktest
>>>> Jun 21 15:59:59 kernel: freeing inode /home/4 with 192 blocks
>>>> Jun 21 15:59:59 root: starting snaptest 7
>>>> Jun 21 15:59:59 kernel: free inode /home/4 had 192 blocks
>>>> Jun 21 15:59:59 root: 4 26592 -r--------  1 root  operator  90762970240
>>>> 21 Jun 16:00 /home/.snap/fscktest
>>>> Jun 21 16:00:00 root: starting snaptest 8
>>>> Jun 21 16:00:00 root: 4 26592 -r--------  1 root  operator  90762970240
>>>> 21 Jun 16:00 /home/.snap/fscktest
>>>>
>>>> The "free inode /home/4 had NNN blocks" message during run of the mount
>>>> command is output of ffs_valloc(), because ffs_load_inode() has load the
>>>> disk inode 4 with a non zero i_blocks field. The corresponding "freeing
>>>> inode /home/4 with NNN blocks" message during the previous rm command
>>>> is output of my following diagnostic patch in function ffs_truncate():
>>>>
>>>> --- ffs_inode.c.1st     2016-06-08 17:25:21.000000000 +0200
>>>> +++ ffs_inode.c 2017-06-19 10:02:07.145360000 +0200
>>>> @@ -551,6 +551,9 @@
>>>>                 DIP_SET(ip, i_blocks, DIP(ip, i_blocks) - blocksreleased);
>>>>         else    /* sanity */
>>>>                 DIP_SET(ip, i_blocks, 0);
>>>> +       if (bootverbose == 2 && DIP(ip, i_blocks) > 0)
>>>> +               printf("freeing inode %s/%lu with %ld blocks\n",
>>>> +                       fs->fs_fsmnt, (u_long)ip->i_number,
>>>> (long)DIP(ip, i_blocks));
>>>>         ip->i_flag |= IN_CHANGE;
>>>>  #ifdef QUOTA
>>>>         (void) chkdq(ip, -blocksreleased, NOCRED, 0);
>>>>
>>>> The rm command can only free all the blocks of the snapshotfile (means
>>>> i_blocks for inode 4 ends with zero) , if this file has the "correct" size:
>>>>
>>>> ls -ils /home/.snap/fscktest -->
>>>> 4 53184 -r--------  1 root  operator  90762970240 Jun 17 06:15
>>>> /home/.snap/fscktest
>>>>
>>>> The size of the /home partition is given by
>>>> diskinfo /dev/mirror/gmsvt7p10.journal -->
>>>> /dev/mirror/gmsvt7p10.journal   512     90762954240     177271395
>>>>
>>>> So we have 2769865 full 32kB blocks with size 90631864320. During
>>>> creating a snapshot a "last block" (32kB) is written at this offset
>>>> ending at 90762969088. Finally the snapblklist is written with
>>>> VOP_WRITE: "Write out the list of allocated blocks to the end of the
>>>> snapshot". In all my correct tests the table snapblklist is 1152 bytes
>>>> in size giving the correct size of the snapshot file : 90762970240. In
>>>> this case the table snapblklist has 144 entries of length 8: one lenght
>>>> entry and 143 logical block numbers recorded in mapacct_ufs2():
>>>>
>>>>           if (acctit && expungetype == BLK_SNAP && blkno != BLK_SNAP)
>>>>                    *ip->i_snapblklist++ = lblkno;
>>>>
>>>> The console output above shows three error situations with block
>>>> counters 704, 2112 and 192. Dividing these values by 8 gives exactly the
>>>> reduced size of the snapblocklist at the end of the snapshotfile, so in
>>>> these cases the snapshotfile is corrupt.
>>> I am not sure what do you mean by 'match' there.  Could you explicitely
>>> mention what relations between snapshot size and leaked blocks of the
>>> free snapshot inode did you noted ?
>> I too am confused here. Are you saying for example that 192 / 8 == 24
>> and that the snapblocklist is short by 24 blocks? Because from the table
>> below, it appears to be short by only 3 blocks.
> 
> In this example the snapblocklist is short by 24 bytes (= 3 table
> entries) and 24/8 = 3 calls to ffs_blkfree are missing.
> 
> Ok, I give one more table to explain a little better:
> 
> The meaning of the columns:
>   #1 number of "free inode blocks" in kernel message
>   #2 blocks from #1 divides by 8 (= fs_frag)
>   #3 size of snapblklist write at the end of snapshotfile
>   #4 ls -s of snapshotfile: 907629...
>   #5 enties in table snapblklist, we have #5 = #3 / 8, because each
>      entry in the table is of type ufs2_daddr_t
>   #6 counter ct_blkfree, thats the number of calls to ffs_blkfree().
>   #7 missing table entries in snapblklist and calls of ffs_blkfree().
> 
> test     #1   #2    #3        #4    #5   #6  #7
> -----------------------------------------------
> 1 ok      0    0  1152   ..70240   144  821   0
> 2 bad   704   88  1064   ..70152   133  810  11
> 3 bad  2112  264   888   ..69976   111  788  33
> 6 bad   192   24  1128   ..70216   141  818   3
> 
> The difference of #5 and #6 is the variable acctit which is set only for
> blkno != -1. In all my test (ok and bad) the function mapacct_ufs2() is
> called 680 times, the first calls look like this (diffblk = lastblk -
> oldblk):
> 
>  mapacct_ufs2:entry   /home, inum=4, diffblkp=0xc, lblkno=0
>  mapacct_ufs2:entry   /home, inum=4, diffblkp=0x3, lblkno=-1
>  mapacct_ufs2:entry   /home, inum=4, diffblkp=0x1000, lblkno=12
>  mapacct_ufs2:entry   /home, inum=4, diffblkp=0x2a4, lblkno=-1
>  mapacct_ufs2:entry   /home, inum=4, diffblkp=0x1000, lblkno=4108
>  mapacct_ufs2:entry   /home, inum=4, diffblkp=0x1000, lblkno=8204
>  mapacct_ufs2:entry   /home, inum=4, diffblkp=0x1000, lblkno=12300
>  ....
> 
> There are exact two calls with lblkno=-1 with together 0x2a7 -2 = 677
> runs of the for loop where #5 is skipped.
> 
>>>> I use a test kernel with some extra counters ct_* in mapacct_ufs2():
>>>>
>>>>            ++ct_blkno_all;
>>>>            if (blkno == 0)
>>>>                    ++ct_blkno_0;
>>>>            if (blkno == BLK_NOCOPY)
>>>>                    ++ct_blkno_nocopy;
>>>>            if (blkno == BLK_SNAP)
>>>>                    ++ct_blkno_snap;
>>>>            if (blkno == 0 || blkno == BLK_NOCOPY)
>>>>                    continue;
>>>>            if (acctit && expungetype == BLK_SNAP && blkno != BLK_SNAP) {
>>>>                    *ip->i_snapblklist++ = lblkno;
>>>>                    ++ct_snapblklist;
>>>>            }
>>>>            if (blkno == BLK_SNAP)
>>>>                    blkno = blkstofrags(fs, lblkno);
>>>>            ++ct_blkfree;
>>>>            ffs_blkfree(ip->i_ump, fs, vp, blkno, fs->fs_bsize, inum,
>>>>                vp->v_type, NULL);
>>>>
>>>> and for the 8 test runs shown above I can see these results using DTrace
>>>> at probe expunge_ufs2:return (blkno_snap is always 0):
>>>>
>>>>  test   blkno_all blkno_0 blkno_nocopy snapblklist blkfree cg_nocopy
>>>>  -------------------------------------------------------------------
>>>>  1 ok   2770545   353320  2416404      143         821     2416404
>>>>  2 bad  2770545   587860  2181875      132         810     2416404
>>>>  3 bad  2770545   956582  1813175      110         788     2416393
>>>>  4 ok   2770545   353364  2416360      143         821     2416360
>>>>  5 ok   2770545   353364  2416360      143         821     2416360
>>>>  6 bad  2770545   418376  2351351      140         818     2416360
>>>>  7 ok   2770545   353367  2416357      143         821     2416357
>>>>  8 ok   2770545   353367  2416357      143         821     2416357
>>>>
>>>> For correct tests the sum of blkno_0 and blkno_nocopy is always the same
>>>> (2769724), for bad tests especially the counter for blkno_nocopy is
>>>> significant lower. In the test table I give one more column cg_nocopy
>>>> for a counter I have added in cgaccount() to see how many entries are
>>>> set to BLK_NOCOPY during copy of cylinder group maps:
>>>>
>>>>                 if (ffs_isblock(fs, cg_blksfree(cgp), loc)) {
>>>>                         ++ct_cg_nocopy;
>>>>                         DIP_SET(ip, i_db[loc], BLK_NOCOPY);
>>>>                 }
>>>>                 ...
>>>>                 if (ffs_isblock(fs, cg_blksfree(cgp), loc)) {
>>>>                         ++ct_cg_nocopy;
>>>>                         ((ufs2_daddr_t *)(ibp->b_data))[indiroff] =
>>>> BLK_NOCOPY;
>>>>                 }
>>>>
>>>> For correct tests all the BLK_NOCOPY's which are set in cgaccount() can
>>>> later be seen in mapacct_ufs2(), for bad tests many of the BLK_NOCOPY's
>>>> have changed to 0.
>>>>
>>>> I looks like the rm command removing the previous snapshot in some way
>>>> runs "in the background" simultan to expunge_ufs2() and changes some of
>>>> the BLK_NOCOPY's to zero. So this may be a buffer management problem
>>>> which only exists on gjourneled partitions, maybe getblk/readblock used
>>>> in indiracct_ufs2() is not compatibel with gjournel in the special case
>>>> of creating or removing a spapshot. A hint in this direction is the
>>>> fact, that the first test after cleaning the partition with
>>>>         umount /home; fsck -y /home; mount /home
>>>> always succeeds. The following modified test procedure never fails:
>>>>
>>>>   for i in 1 2 3 4 5 6 7 8; do
>>>>      echo "starting snaptest $i" >/dev/console
>>>>      mount -u -o snapshot -o noatime -o async /home/.snap/fscktest /home
>>>>      echo $(ls -ils /home/.snap/fscktest) >/dev/console
>>>>      rm -f /home/.snap/fscktest /home
>>>>      umount /home
>>>>      mount /home
>>>>   done
>>> After the allocations of required blocks for the snapshot inode
>>> are finished, the filesystem is suspended. You can see the
>>> call to vfs_write_suspend() in the ffs_snapshot() where the
>>> suspension is enforced. As part of the suspension, all soft-update
>>> workitems are flushed, this is done by vfs_write_suspend() calling
>>> VFS_SYNC(MNT_SUSPEND).
>>>
>>> UFS classifies writers into primary and secondary. Primary are mostly
>>> the writes initiated by the top-level syscall entries, like direct
>>> calls to write(2) or metadata-changing ops mkdir(), create() and so on.
>>> Secondary are writes performed when system initiates metadata updates
>>> during inactivation, quota updates, softdep background processing and
>>> similar. Primary modifications are blocked outright on suspension, while
>>> secondary are waited to finish in the mentioned VFS_SYNC(MNT_SUSPEND)
>>> call.
>>>
>>> If you can provide a proof that some SU-related activity happens after the
>>> suspension is established, this would be interesting to see.
>>> Might be it is something different and much simpler, but I do not see
>>> an obvious mistake in the code, after reading your observations.
>> The mount information at the top shows:
>>
>> /dev/mirror/gmsvt7p10.journal on /home (ufs, asynchronous, local, noatime, gjournal)
>>
>> Thus no soft updates are being used. We are running on just a basic UFS
>> filesystem. So, soft update processing has no relevance here.
>>
>>>> Another proof that the snapshot file is corrupt when the snapblklist is
>>>> shortend is the fact that the rm command sporadically panics in a kernel
>>>> routine that is known to be correct:
>>>>
>>>> nread portion of the kernel message buffer:
>>>> dev = mirror/gmsvt7p10.journal, block = 19727560, fs = /home
>>>> panic: ffs_blkfree_cg: freeing free block
>>>> cpuid = 1
>>>> KDB: stack backtrace:
>>>> db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame
>>>> 0xfffffe0857e3b1c0
>>>> kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe0857e3b270
>>>> vpanic() at vpanic+0x126/frame 0xfffffe0857e3b2b0
>>>> panic() at panic+0x43/frame 0xfffffe0857e3b310
>>>> ffs_blkfree_cg() at ffs_blkfree_cg+0x5c6/frame 0xfffffe0857e3b3d0
>>>> ffs_blkfree() at ffs_blkfree+0x99/frame 0xfffffe0857e3b430
>>>> ffs_indirtrunc() at ffs_indirtrunc+0x474/frame 0xfffffe0857e3b510
>>>> ffs_indirtrunc() at ffs_indirtrunc+0x423/frame 0xfffffe0857e3b5f0
>>>> ffs_truncate() at ffs_truncate+0x10b4/frame 0xfffffe0857e3b7d0
>>>> ufs_inactive() at ufs_inactive+0x16b/frame 0xfffffe0857e3b810
>>>> VOP_INACTIVE_APV() at VOP_INACTIVE_APV+0xf7/frame 0xfffffe0857e3b840
>>>> vinactive() at vinactive+0xc6/frame 0xfffffe0857e3b890
>>>> vputx() at vputx+0x27a/frame 0xfffffe0857e3b8f0
>>>> kern_unlinkat() at kern_unlinkat+0x243/frame 0xfffffe0857e3bae0
>>>> amd64_syscall() at amd64_syscall+0x2c6/frame 0xfffffe0857e3bbf0
>>>> Xfast_syscall() at Xfast_syscall+0xfb/frame 0xfffffe0857e3bbf0
>>>> --- syscall (10, FreeBSD ELF64, sys_unlink), rip = 0x80095425a, rsp =
>>>> 0x7fffffffe988, rbp = 0x7fffffffea20 ---
>>>>
>>>> Any hints solving this problem are welcome.
>> Per the suggestion at the top, I recommend trying your test without
>> gjournal present to see if the bug goes away. If that is true, then
>> we can focus our attention on a possible race during rm in the gjournal
>> code.
>>
>> 	Kirk McKusick
> I have done as explained above. Some more hints may help for debugging
> this.
> 
> 1. Output of dumpfs of the partition is
> 
> magic   19540119 (UFS2) time    Sun Jun 25 03:46:09 2017
> superblock location     65536   id      [ 561bcaa3 624b156b ]
> ncg     139     size    22158924        blocks  21459451
> bsize   32768   shift   15      mask    0xffff8000
> fsize   4096    shift   12      mask    0xfffff000
> frag    8       shift   3       fsbtodb 3
> minfree 8%      optim   time    symlinklen 120
> maxbsize 32768  maxbpg  4096    maxcontig 4     contigsumsize 4
> nbfree  2413023 ndir    229     nifree  11153267        nffree  274
> bpg     20035   fpg     160280  ipg     80256   unrefs  0
> nindir  4096    inopb   128     maxfilesize     2252349704110079
> sbsize  4096    cgsize  32768   csaddr  5056    cssize  4096
> sblkno  24      cblkno  32      iblkno  40      dblkno  5056
> cgrotor 123     fmod    0       ronly   0       clean   0
> metaspace 6408  avgfpdir 64     avgfilesize 16384
> flags   gjournal
> fsmnt   /home
> volname         swuid   0       providersize    22158924
> 
> 2. I am quite sure that the process g_journal_switcher does not break
> things during run of "mount -o snapshot". I have severel DTrace output
> of the problem, where g_journal_switcher sleeps all the time.
> 
> 3. The probe expunge_ufs2:return is the first probe from several DTrace
> probing that shows a difference between good and bad.
> 
> 4. The problem occurs for many years on several production server and
> partitions where only one snapshot is taken every day, but not all and
> not very often. On newer server the "free inode" messages increases. On
> my test server I have a "freezed" partition /home that shows the problem
> with less than ten runs all the time. If I run DTrace with a lot of
> probes then the problem sometimes becomes a "Heisenbug".
> 

Dr. Andreas Longwitz



More information about the freebsd-fs mailing list