mksnap_ffs, snapshot issues, again

From: Kirk McKusick <mckusick_at_beastie.mckusick.com>
Date: Sat, 23 Aug 2003 01:32:38 -0700
Robert Watson forwarded your posting to me as I am not as current
on current as I should be.

---------- Forwarded message ----------
> Date: Mon, 18 Aug 2003 22:38:47 +0200
> From: "[iso-8859-2] Branko F. Gračnar" <bfg_at_noviforum.si>
> To: freebsd-current_at_freebsd.org
> Subject: mksnap_ffs, snapshot issues, again
> 
> I have 900G array on a promise sx6000 controller
> 
> This is freshly formatted filesystem (newfs -L export -O 2 -U -g 48000 -i 2048 -m 0 -o space /dev/pst0s2d)
> 
> # df -i /export
> /dev/pst0s2d 778742004 216194 778525810   0%       2 445159292    0%   /export
> 
> # mount | grep export
> /dev/pst0s2d on /export (ufs, local, soft-updates)
> 
> let's try to create a snapshot of empty filesystem
> 
> # cd /export
> # mksnap_ffs /export aaa.snap
> 
> ... after 30 minutes ... snapshot was not created (!!! On a empty
> filesystem !!!)... Ok, long snapshot creation would be fine if it
> would not hang all processes, which would like to do something on
> /export (ls /export for example.). Filesystem cannot be unmounted.
> mksnap_ffs process cannot be killed. Reboot and foreground fsck
> helps.
>
> This is 5.1-RELEASE (without patches, with custom kernel -> just picked up generic kernel and removed uneeded stuff.)....
> 
> Any ideas, why is this happening? As i mentioned before, this prevents background fsck to make his job done (machine hangs.)
> 
> 
> I would really like to solve this issue....
> 
> Brane

------------ Discussion -----------------

Paul Saab kindly arranged a machine (tank.freebsd.org) with a 2Tb
disk array on it for me to test. I enclose a copy of the `sysctl kern'
output at the end of this message. I first ran my own test which
involved creating a default configuration filesystem, taking a
snapshot, and removing the snapshot. The scripted result is below.
It shows that it takes 48 minutes to create the snapshot and 15
minutes to remove it. But importantly, it shows that the filesystem
is only locked down and inaccessible for 0.042 seconds of that 48
minutes. The problem is that the 77,000 indirect blocks needed by
the snapshot do not fit in the 300 kernel buffers allotted to it.
So, every indirect block needs to be read and written approximately
three times. Just to be sure that there was not something weird about
your configuration, I also ran the same set of tests using your
newfs parameters. Other than creating more cylinder groups the
result (e.g., running time) was about the same.

But, to get to the problem that you are having with accessing your
filesystem. The problem is that although the filesystem is only
locked briefly, the snapshot file is locked for the entire 48 minutes.
Thus, if you touch the snapshot file (by for example doing a "stat"
on it), then the process doing the stat will hang for 48 minutes.
The next process to try and touch the snapshot will lock /export
while it waits for the lock on the snapshot to clear. And at that
point you are hosed for 48 minutes on all access to /export :-(
So, I think that the best solution for you would be to try creating
a hidden directory for the snapshot file, e.g., create a /export/.snap
directory mode 700 owned by root, then create the snapshot as say
/export/.snap/snap1. This way, it will be out of the way of all
snoopy programs except those walking the filetree as root.

	Kirk McKusick

------------ Results of my test -----------------

Script started on Fri Aug 22 17:18:34 2003

tank# newfs /dev/twed0
/dev/twed0: 2097152.0MB (4294967292 sectors) block size 16384, fragment size 2048
        using 11413 cylinder groups of 183.77MB, 11761 blks, 23552 inodes.
super-block backups (for fsck -b #) at:
 160, 376512, 752864, 1129216, 1505568, 1881920, 2258272, 2634624, 3010976,
 3387328, 3763680, 4140032, 4516384, 4892736, 5269088, 5645440, 6021792,
 6398144, 6774496, 7150848, 7527200, 7903552, 8279904, 8656256, 9032608,
 9408960, 9785312, 10161664, 10538016, 10914368, 11290720, 11667072, 12043424,
 12419776, 12796128, 13172480, 13548832, 13925184, 14301536, 14677888,
 15054240, 15430592, 15806944, 16183296, 16559648, 16936000, 17312352,
 17688704, 18065056, 18441408, 18817760, 19194112, 19570464, 19946816,
 20323168, 20699520, 21075872, 21452224, 21828576, 22204928, 22581280,

 < etc, etc, etc >

 4283638624, 4284014976, 4284391328, 4284767680, 4285144032, 4285520384,
 4285896736, 4286273088, 4286649440, 4287025792, 4287402144, 4287778496,
 4288154848, 4288531200, 4288907552, 4289283904, 4289660256, 4290036608,
 4290412960, 4290789312, 4291165664, 4291542016, 4291918368, 4292294720,
 4292671072, 4293047424, 4293423776, 4293800128, 4294176480, 4294552832,
 4294929184

tank# dumpfs /dev/twed0 | head -22
magic   19540119 (UFS2) time    Sat Aug 23 01:18:55 2003
superblock location     65536   id      [ 3f47236f d612c37d ]
ncg     11413   size    1073741823      blocks  1039959213
bsize   16384   shift   14      mask    0xffffc000
fsize   2048    shift   11      mask    0xfffff800
frag    8       shift   3       fsbtodb 2
minfree 8%      optim   time    symlinklen 120
maxbsize 16384  maxbpg  2048    maxcontig 8     contigsumsize 8
nbfree  129994899       ndir    1       nifree  268798973       nffree  20
bpg     11761   fpg     94088   ipg     23552
nindir  2048    inopb   64      maxfilesize     140806241583103
sbsize  2048    cgsize  16384   csaddr  3000    cssize  184320
sblkno  40      cblkno  48      iblkno  56      dblkno  3000
cgrotor 0       fmod    0       ronly   0       clean   1
flags   none
fsmnt   
volname         swuid   0

cs[].cs_(nbfree,ndir,nifree,nffree):
        (11373,1,23549,13) (11391,0,23552,0) (11391,0,23552,0) (11391,0,23552,0) 
        (11391,0,23552,0) (11391,0,23552,0) (11391,0,23552,0) (11391,0,23552,0) 
        (11391,0,23552,0) (11391,0,23552,0) (11391,0,23552,0) (11391,0,23552,0) 

tank# ^ew^we
tunefs -n enable /dev/twed0
tunefs: soft updates set

tank# mount /dev/twed0 /mnt

tank# cd /mnt

tank# df -i /mnt
Filesystem 1K-blocks  Used      Avail Capacity iused     ifree %iused  Mounted on
/dev/twed0 2079918426    2 1913524950     0%       1 268798973    0%   /mnt

tank# df -i -g /mnt
Filesystem 1G-blocks Used Avail Capacity iused     ifree %iused  Mounted on
/dev/twed0      1983    0  1824     0%       1 268798973    0%   /mnt

tank# sysctl -w debug.collectsnapstats=1
debug.collectsnapstats: 0 -> 1

tank# mount -u -o snapshot snap1 /mnt
0.000u 51.055s 47:57.80 1.7%    522+253k 191899+286461io 0pf+0w

tank# ls -lis /mnt/snap1
3 1232048 -r--------  1 root  wheel  2199023346984 Aug 22 17:06 snap1

tank % df /mnt
Filesystem 1K-blocks     Used      Avail Capacity  Mounted on
/dev/twed0 2079918426 1232050 1912292902     0%    /mnt

tank# rm -f snap1
0.000u 8.084s 14:39.67 0.9%     506+275k 65567+65536io 0pf+0w

tank# egrep suspended /var/log/messages | tail -1
Aug 22 18:04:02 tank kernel: /mnt: suspended 0.042 sec, redo 0 of 11413

tank# exit

Script done on Fri Aug 22 19:21:00 2003

------------ Results of your test -----------------

Script started on Fri Aug 22 23:52:19 2003

tank# newfs -L export -O 2 -U -g 48000 -i 2048 -m 0 -o space /dev/twed0
/dev/twed0: 2097152.0MB (4294967292 sectors) block size 16384, fragment size 2048
        using 17642 cylinder groups of 118.88MB, 7608 blks, 60864 inodes.
        with soft updates
super-block backups (for fsck -b #) at:
 160, 243616, 487072, 730528, 973984, 1217440, 1460896, 1704352, 1947808,
 2191264, 2434720, 2678176, 2921632, 3165088, 3408544, 3652000, 3895456,
 4138912, 4382368, 4625824, 4869280, 5112736, 5356192, 5599648, 5843104,
 6086560, 6330016, 6573472, 6816928, 7060384, 7303840, 7547296, 7790752,
 8034208, 8277664, 8521120, 8764576, 9008032, 9251488, 9494944, 9738400,
 9981856, 10225312, 10468768, 10712224, 10955680, 11199136, 11442592, 11686048,
 11929504, 12172960, 12416416, 12659872, 12903328, 13146784, 13390240,
 13633696, 13877152, 14120608, 14364064, 14607520, 14850976, 15094432,

 < etc, etc, etc >

 4287016864, 4287260320, 4287503776, 4287747232, 4287990688, 4288234144,
 4288477600, 4288721056, 4288964512, 4289207968, 4289451424, 4289694880,
 4289938336, 4290181792, 4290425248, 4290668704, 4290912160, 4291155616,
 4291399072, 4291642528, 4291885984, 4292129440, 4292372896, 4292616352,
 4292859808, 4293103264, 4293346720, 4293590176, 4293833632, 4294077088,
 4294320544, 4294564000, 4294807456

tank# dumpfs /dev/twed0 | head -22
magic   19540119 (UFS2) time    Fri Aug 22 23:52:39 2003
superblock location     65536   id      [ 3f470f37 1d9cb87a ]
ncg     17642   size    1073741823      blocks  939239037
bsize   16384   shift   14      mask    0xffffc000
fsize   2048    shift   11      mask    0xfffff800
frag    8       shift   3       fsbtodb 2
minfree 0%      optim   space   symlinklen 120
maxbsize 16384  maxbpg  2048    maxcontig 8     contigsumsize 8
nbfree  117404877       ndir    1       nifree  1073762685      nffree  20
bpg     7608    fpg     60864   ipg     60864
nindir  2048    inopb   64      maxfilesize     140806241583103
sbsize  2048    cgsize  16384   csaddr  7664    cssize  282624
sblkno  40      cblkno  48      iblkno  56      dblkno  7664
cgrotor 0       fmod    0       ronly   0       clean   1
flags   soft-updates 
fsmnt   
volname export  swuid   0

cs[].cs_(nbfree,ndir,nifree,nffree):
        (6631,1,60861,13) (6655,0,60864,0) (6655,0,60864,0) (6655,0,60864,0) 
        (6655,0,60864,0) (6655,0,60864,0) (6655,0,60864,0) (6655,0,60864,0) 
        (6655,0,60864,0) (6655,0,60864,0) (6655,0,60864,0) (6655,0,60864,0) 

tank# mount /dev/twed0 /mnt

tank# cd /mnt

tank# df -i /mnt
Filesystem 1K-blocks  Used      Avail Capacity iused      ifree %iused  Mounted on
/dev/twed0 1878478074    2 1878478072     0%       1 1073762685    0%   /mnt

tank# df -i -g /mnt
Filesystem 1G-blocks Used Avail Capacity iused      ifree %iused  Mounted on
/dev/twed0      1791    0  1791     0%       1 1073762685    0%   /mnt

tank# sysctl debug.collectsnapstats
debug.collectsnapstats: 1

tank# set time

tank# mount -u -o snapshot /mnt/snap1 /mnt
load: 0.00  cmd: mount 3908 [biord] 0.00u 49.03s 0% 360k
load: 0.07  cmd: mount 3908 [physrd] 0.00u 49.30s 0% 360k
0.000u 57.064s 47:55.13 1.9%    526+255k 222815+300336io 0pf+0w

tank# ls -lis /mnt/snap1
3 1331856 -r--------  1 root  wheel  2199023396864 Aug 23 00:43 /mnt/snap1

tank# df /mnt
Filesystem 1K-blocks     Used      Avail Capacity  Mounted on
/dev/twed0 1878478074 1331858 1877146216     0%    /mnt

tank# rm -f snap1
0.000u 8.180s 10:25.82 1.3%     505+240k 65567+65536io 0pf+0w

tank# egrep suspended /var/log/messages | tail -1
Aug 23 00:15:30 tank kernel: /mnt: suspended 0.027 sec, redo 0 of 17642

tank# exit

Script done on Sat Aug 23 00:54:41 2003

------------ sysctl kern output -----------------

kern.ostype: FreeBSD
kern.osrelease: 5.1-CURRENT
kern.osrevision: 199506
kern.version: FreeBSD 5.1-CURRENT #0: Thu Aug 21 02:11:29 PDT 2003
    ps_at_tank.freebsd.org:/usr/src/sys/i386/compile/TANK
kern.maxvnodes: 70264
kern.maxproc: 6164
kern.maxfiles: 12328
kern.argmax: 65536
kern.securelevel: -1
kern.hostname: tank.freebsd.org
kern.hostid: 0
kern.clockrate: { hz = 100, tick = 10000, profhz = 1024, stathz = 128 }
kern.posix1version: 200112
kern.ngroups: 16
kern.job_control: 1
kern.saved_ids: 0
kern.boottime: { sec = 1061550694, usec = 491116 } Fri Aug 22 04:11:34 2003
kern.domainname: freebsd
kern.osreldate: 501105
kern.bootfile: /boot/kernel/kernel
kern.maxfilesperproc: 11095
kern.maxprocperuid: 5547
kern.ipc.maxsockbuf: 262144
kern.ipc.sockbuf_waste_factor: 8
kern.ipc.somaxconn: 128
kern.ipc.max_linkhdr: 16
kern.ipc.max_protohdr: 40
kern.ipc.max_hdr: 56
kern.ipc.max_datalen: 152
kern.ipc.nmbclusters: 25600
kern.ipc.nmbufs: 51200
kern.ipc.nmbcnt: 32256
kern.ipc.nsfbufs: 6656
kern.ipc.mbuf_wait: 64
kern.ipc.mbuf_hiwm: 512
kern.ipc.mbuf_lowm: 128
kern.ipc.clust_hiwm: 128
kern.ipc.clust_lowm: 16
kern.ipc.maxpipekva: 10485760
kern.ipc.maxpipekvawired: 5242880
kern.ipc.pipes: 2
kern.ipc.bigpipes: 0
kern.ipc.pipekva: 32768
kern.ipc.pipekvawired: 0
kern.ipc.msgmax: 16384
kern.ipc.msgmni: 40
kern.ipc.msgmnb: 2048
kern.ipc.msgtql: 40
kern.ipc.msgssz: 8
kern.ipc.msgseg: 2048
kern.ipc.semmap: 30
kern.ipc.semmni: 10
kern.ipc.semmns: 60
kern.ipc.semmnu: 30
kern.ipc.semmsl: 60
kern.ipc.semopm: 100
kern.ipc.semume: 10
kern.ipc.semusz: 92
kern.ipc.semvmx: 32767
kern.ipc.semaem: 16384
kern.ipc.shmmax: 33554432
kern.ipc.shmmin: 1
kern.ipc.shmmni: 192
kern.ipc.shmseg: 128
kern.ipc.shmall: 8192
kern.ipc.shm_use_phys: 0
kern.ipc.numopensockets: 23
kern.ipc.maxsockets: 25600
kern.dummy: 0
kern.ps_strings: 3217031152
kern.usrstack: 3217031168
kern.logsigexit: 1
kern.iov_max: 1024
kern.cam.scsi_delay: 15000
kern.cam.cd.changer.min_busy_seconds: 5
kern.cam.cd.changer.max_busy_seconds: 15
kern.cam.da.retry_count: 4
kern.cam.da.default_timeout: 60
kern.random.sys.seeded: 1
kern.random.sys.burst: 20
kern.random.sys.harvest.ethernet: 1
kern.random.sys.harvest.point_to_point: 1
kern.random.sys.harvest.interrupt: 1
kern.random.sys.harvest.swi: 0
kern.random.yarrow.gengateinterval: 10
kern.random.yarrow.bins: 10
kern.random.yarrow.fastthresh: 192
kern.random.yarrow.slowthresh: 256
kern.random.yarrow.slowoverthresh: 2
kern.disks: twed0 ad2 ad0
kern.geom.debugflags: 0
kern.geom.collectstats: 1
kern.elf32.fallback_brand: -1
kern.init_path: /sbin/init:/sbin/oinit:/sbin/init.bak:/stand/sysinstall
kern.acct_suspend: 2
kern.acct_resume: 4
kern.acct_chkfreq: 15
kern.cp_time: 6158 0 148996 17012 17783789
kern.openfiles: 69
kern.kq_calloutmax: 4096
kern.stackprot: 7
kern.ps_arg_cache_limit: 256
kern.ps_argsopen: 1
kern.lastpid: 3850
kern.randompid: 0
kern.ktrace.genio_size: 4096
kern.ktrace.request_pool: 100
kern.module_path: /boot/kernel;/boot/modules
kern.malloc: 
        Type  InUse MemUse HighUse Requests  Size(s)
 twe commands   255    16K     32K      266  64,512,8192,16384
  ISOFS mount     1   256K    256K        1
     atkbddev     2     1K      1K        2  32
       isadev    21     2K      2K       21  64
         GEOM   116    12K     83K     6174  16,32,64,128,256,512,1024,65536
     nexusdev     3     1K      1K        3  16
      memdesc     1     4K      4K        1  4096
    VM pgdata     2    65K     65K        2  64,65536
   pfs_fileno     1    32K     32K        1  32768
    pfs_nodes    20     3K      3K       20  128
    UFS mount    26   379K    711K       41  64,256,2048,4096,8192
    UFS ihash     1   256K    256K        1
  UFS dirhash    69    13K     13K       69  16,32,64,128,256,512
       dirrem     0     0K      1K     1011  32
        mkdir     0     0K      1K        2  32
       diradd     0     0K      1K     1045  32
     freefile     0     0K      1K      175  32
     freeblks     0     0K      5K      161  256
     freefrag     0     0K      1K       40  32
   allocindir     0     0K    329K   154001  64
     indirdep     0     0K     52K    22901  32,16384
  allocdirect     0     0K      3K      313  128
    bmsafemap     0     0K     53K   149301  32
       newblk     1     1K      1K   154315  64,256
     inodedep     1   256K    265K     1369  128,256
      pagedep     1    32K     33K      227  64,32768
     p1003.1b     1     1K      1K        1  16
   NFS daemon     1     1K      1K        1  256
     NFS hash     1   256K    256K        1
      NFS req     0     0K      1K     2240  64
     syncache     1     8K      8K        1  8192
    tseg_qent     0     0K      1K        2  32
     in_multi     2     1K      1K        2  32
     routetbl    38     6K      6K       96  16,32,64,128,256
           lo     1     1K      1K        1  512
        clone     1     4K      4K        1  4096
  ether_multi     7     1K      1K        7  16,32,64
       ifaddr    21     6K      6K       21  32,256,512,2048
          BPF     3     1K      1K        3  128
        mount    19     7K      7K       26  16,32,128,512
MSDOSFS mount     1   128K    128K        1
       vnodes    25     6K      6K      153  16,32,64,128,256
cluster_save buffer     0     0K      1K        1  64
     vfscache     1   512K    512K        1
   BIO buffer     2     4K    185K      100  1024,2048
          pcb    21     5K      5K     1730  16,32,64,2048
       soname     5     1K      1K   594269  16,32,128
         ptys     2     1K      1K        2  512
         ttys  1110   143K    156K     2790  128,512
          shm     1    16K     16K        1  16384
          sem     4     7K      7K        4  1024,4096
          msg     4    25K     25K        4  512,4096,16384
     ioctlops     0     0K      1K      331  512,1024
        DEVFS   107    17K     18K      217  16,32,128,4096
  ATA generic     4     2K      2K        4  16,512
   MD sectors     4    16K     16K       80  4096
    taskqueue     3     1K      1K        3  128
      MD disk     8     2K      2K      160  16,256
      acpidev    55     1K      1K       55  16
         sbuf     0     0K     33K     2205  16,32,64,128,256,512,1024,2048,4096,8192,16384
         rman   115     8K      8K      481  64
      acpisem    17     3K      3K       17  64,128
     acpitask     0     0K      1K        2  16,32
      mbufmgr   102   135K    135K      102  32,64,256,8192,16384
       acpica   965    53K     54K    10560  16,32,64,128,256,512,1024,2048
         kobj    97   388K    388K       97  4096
 eventhandler    31     2K      2K       31  32,128
      devstat    12    25K     25K       12  16,4096
          bus   609    42K    133K     4434  16,32,64,128,256,512,1024,2048,4096,16384,32768
         SWAP     2   549K    549K        2  64
    sysctltmp     0     0K      2K    21688  16,32,64,128,256,512,2048
    sysctloid   125     4K      4K      125  16,32,64
       sysctl     0     0K      1K      973  16,32,64
      uidinfo     6     2K      2K      143  32,1024
         cred    26     4K      5K     9207  128
      subproc    85   292K    328K     4251  256,4096
         proc     2     8K      8K        2  4096
      session    20     3K      3K      409  128
         pgrp    24     3K      4K      698  128
     mtx_pool     1     8K      8K        1  8192
       module   147    10K     10K      149  64,128
         temp     7   117K    117K     7384  16,32,64,128,256,512,1024,2048,4096,8192,32768
       devbuf   142   855K    905K   131522  16,32,64,128,256,512,1024,2048,4096,16384
        lockf     9     1K      1K      877  32,64
       linker    33    93K     98K      103  16,32,256,1024,2048,4096,16384,65536
    AR driver     1     1K      3K        5  64,256,2048
       KTRACE   100    13K     13K      100  128
      ithread    41     4K      4K       41  64,128
       zombie     0     0K      1K     3779  128
    proc-args    25     2K      2K    17589  16,32,64,128,256
       kqueue     6     6K     10K   193053  256,1024
         kenv   109     6K      6K      110  16,32,64,2048
        sigio     1     1K      1K        1  32
    file desc    71    18K     26K     3960  256,2048
        dev_t   147    37K     37K      147  256
    AD driver     2     1K      2K    21823  64,512
      ATA DMA     2     1K      1K        2  64

kern.ident: TANK
kern.maxusers: 384
kern.fallback_elf_brand: -1
kern.kstack_pages: 2
kern.uarea_pages: 1
kern.sync_on_panic: 1
kern.shutdown.poweroff_delay: 5000
kern.shutdown.kproc_shutdown_wait: 60
kern.sugid_coredump: 0
kern.coredump: 1
kern.corefile: %N.core
kern.fscale: 2048
kern.timecounter.nbinuptime: 35881781
kern.timecounter.nnanouptime: 3
kern.timecounter.nmicrouptime: 3883
kern.timecounter.nbintime: 245389
kern.timecounter.nnanotime: 34
kern.timecounter.nmicrotime: 245355
kern.timecounter.ngetbinuptime: 0
kern.timecounter.ngetnanouptime: 3087
kern.timecounter.ngetmicrouptime: 2181958
kern.timecounter.ngetbintime: 0
kern.timecounter.ngetnanotime: 0
kern.timecounter.ngetmicrotime: 7012364
kern.timecounter.nsetclock: 3
kern.timecounter.hardware: ACPI-fast
kern.timecounter.choice: TSC(-100) ACPI-fast(1000) i8254(0) dummy(-1000000)
kern.timecounter.tick: 1
kern.timecounter.smp_tsc: 0
kern.threads.debug: 0
kern.threads.max_threads_per_proc: 150
kern.threads.max_groups_per_proc: 50
kern.threads.max_threads_hits: 0
kern.threads.virtual_cpu: 4
kern.quantum: 100000
kern.ccpu: 1948
kern.devstat.numdevs: 3
kern.devstat.generation: 1738
kern.devstat.version: 6
kern.kobj_methodcount: 58
kern.log_wakeups_per_second: 5
kern.log_console_output: 1
kern.msgbuf: 
kern.msgbuf_clear: 0
kern.smp.active: 1
kern.smp.disabled: 0
kern.smp.cpus: 4
kern.smp.forward_signal_enabled: 1
kern.smp.forward_roundrobin_enabled: 1
kern.nselcoll: 0
kern.drainwait: 300
kern.tty_nin: 3131
kern.tty_nout: 368061
kern.console: ttyd0,/ttyd0,consolectl,
kern.consmute: 0
kern.consmsgbuf_size: 8192
kern.constty_wakeups_per_second: 5
kern.rootdev: ad0s1a
kern.filedelay: 30
kern.dirdelay: 29
kern.metadelay: 28
kern.minvnodes: 17566
kern.chroot_allow_open_directories: 1
Received on Fri Aug 22 2003 - 23:52:40 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:37:19 UTC