Skip site navigation (1)Skip section navigation (2)
Date:      Sat, 26 Jan 2013 03:10:01 GMT
From:      Harry Coin <hgcoin@gmail.com>
To:        freebsd-fs@FreeBSD.org
Subject:   Re: kern/169480: [zfs] ZFS stalls on heavy I/O
Message-ID:  <201301260310.r0Q3A1fe051107@freefall.freebsd.org>

next in thread | raw e-mail | index | archive | help
The following reply was made to PR kern/169480; it has been noted by GNATS.

From: Harry Coin <hgcoin@gmail.com>
To: bug-followup@FreeBSD.org, levent.serinol@mynet.com, 
 Jeremy Chadwick <jdc@koitsu.org>
Cc:  
Subject: Re: kern/169480: [zfs] ZFS stalls on heavy I/O
Date: Fri, 25 Jan 2013 21:04:05 -0600

 Jeremy, Thanks.
 
 re: 1.  Not only have I removed the zil but I removed the cache before 
 running this test as well, thinking as you did the whole l2arc thing was 
 adding too much complexity.   The pool was nothing more than the single 
 raidz when doing the test to cause the failure noted.
 
 re 2.  The raw benchmarks you saw for ada2 were identically duplicated 
 for 3, 4 and 5.  They are all exactly the same drive make and model 
 purchased at the same time.
 
 re 3.  These are 512 byte/sector drives.  v6.0 smartctl -a reports 512 
 bytes/sector logical / physical.
 
 re 4.  The drives are partitioned so that each of them can hold boot 
 information should I decide someday to boot off the array, to make sure 
 sector 0 of the partition starts on the afore-noticed 4K boundary,  and 
 there is a couple of gig at the end for swap if I decide I want that.  
 Partition 1 is just big enough for the boot code, 2 is the bulk of the 
 storage, and 3 is the last 2 gig.
 
 So, no zil or cache used in the test, all formatted zfs v28, scrub 
 reported zero errors on the array two days ago (though the scrub speed 
 was 14M/s or so).
 
 It's something about max speed writes that get interrupted by another 
 read that kills zfs/nas4free somehow.
 
 re 5:  The ata drives indeed are on the ICH7, as the 300gb isn't an 
 issue.  The ssd's are on the higher speed controller, and are unused as 
 noted before.
 
 re 6:  You'll note that 'ls -l' didn't return, only the 'top' program 
 run before the dd was started was launched.  Here are the procstat -kk's 
 for the dd and ls during their run (the ls not returning)
 nas4free:~# ps axu | grep dd
 root  4006  47.1  0.1  9916 1752 v0  R+    2:56AM   0:07.92 dd 
 if=/dev/urandom of=foo bs=512 count=20000000
 root  4009   0.0  0.1 16280 2092  0  S+    2:56AM   0:00.00 grep dd
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_timedwait+0x42 _cv_timedwait+0x13c txg_delay+0x137 
 dsl_pool_tempreserve_space+0xd5 dsl_dir_tempreserve_space+0x154 
 dmu_tx_assign+0x370 zfs_freebsd_write+0x45b VOP_WRITE_APV+0xb2 
 vn_write+0x38c dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_timedwait+0x42 _cv_timedwait+0x13c txg_delay+0x137 
 dsl_pool_tempreserve_space+0xd5 dsl_dir_tempreserve_space+0x154 
 dmu_tx_assign+0x370 zfs_freebsd_write+0x45b VOP_WRITE_APV+0xb2 
 vn_write+0x38c dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_timedwait+0x42 _cv_timedwait+0x13c txg_delay+0x137 
 dsl_pool_tempreserve_space+0xd5 dsl_dir_tempreserve_space+0x154 
 dmu_tx_assign+0x370 zfs_freebsd_write+0x45b VOP_WRITE_APV+0xb2 
 vn_write+0x38c dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_timedwait+0x42 _cv_timedwait+0x13c txg_delay+0x137 
 dsl_pool_tempreserve_space+0xd5 dsl_dir_tempreserve_space+0x154 
 dmu_tx_assign+0x370 zfs_freebsd_write+0x45b VOP_WRITE_APV+0xb2 
 vn_write+0x38c dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# ps axu | grep ls
 root  4016   0.0  0.1 14420 2196 v2  D+    2:57AM   0:00.00 ls -l
 root  4018   0.0  0.1 16280 2084  0  RL+   2:57AM   0:00.00 grep ls
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_wait+0x42 _cv_wait+0x121 txg_wait_open+0x85 
 zfs_freebsd_write+0x47b VOP_WRITE_APV+0xb2 vn_write+0x38c 
 dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 amd64_syscall+0x546 
 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_wait+0x42 _cv_wait+0x121 txg_wait_open+0x85 
 zfs_freebsd_write+0x47b VOP_WRITE_APV+0xb2 vn_write+0x38c 
 dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 amd64_syscall+0x546 
 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_wait+0x42 _cv_wait+0x121 txg_wait_open+0x85 
 zfs_freebsd_write+0x47b VOP_WRITE_APV+0xb2 vn_write+0x38c 
 dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 amd64_syscall+0x546 
 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_wait+0x42 _cv_wait+0x121 txg_wait_open+0x85 
 zfs_freebsd_write+0x47b VOP_WRITE_APV+0xb2 vn_write+0x38c 
 dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 amd64_syscall+0x546 
 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_wait+0x42 _cv_wait+0x121 txg_wait_open+0x85 
 zfs_freebsd_write+0x47b VOP_WRITE_APV+0xb2 vn_write+0x38c 
 dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 amd64_syscall+0x546 
 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_wait+0x42 _cv_wait+0x121 txg_wait_open+0x85 
 zfs_freebsd_write+0x47b VOP_WRITE_APV+0xb2 vn_write+0x38c 
 dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 amd64_syscall+0x546 
 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4006
    PID    TID COMM             TDNAME           KSTACK
   4006 100114 dd               -                mi_switch+0x186 
 sleepq_wait+0x42 _cv_wait+0x121 txg_wait_open+0x85 
 zfs_freebsd_write+0x47b VOP_WRITE_APV+0xb2 vn_write+0x38c 
 dofilewrite+0x8b kern_writev+0x6c sys_write+0x64 amd64_syscall+0x546 
 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~# procstat -kk 4016
    PID    TID COMM             TDNAME           KSTACK
   4016 100085 ls               -                mi_switch+0x186 
 sleepq_wait+0x42 __lockmgr_args+0xe40 vop_stdlock+0x39 
 VOP_LOCK1_APV+0x46 _vn_lock+0x47 vget+0x70 cache_lookup_times+0x55a 
 vfs_cache_lookup+0xc8 VOP_LOOKUP_APV+0x40 lookup+0x464 namei+0x4e9 
 kern_statat_vnhook+0xb3 kern_statat+0x15 sys_lstat+0x2a 
 amd64_syscall+0x546 Xfast_syscall+0xf7
 nas4free:~#
 
 
 re 7:  The 'submit a problem' form doesn't list 'fs' as an option, just 
 kern.  If there's another place for fs bugs I trust the freebsd folks 
 will know what to do with it.  Anyhow I do think it's about write 
 completions getting lost.   And, 'nas4free' is a pretty popular project 
 having the major virtue that anyone, anywhere looking to solve this 
 problem can download a livecd iso and reproduce it.  This is not my 
 first rodeo, there are several bug reports with various black magic 
 tunable tweaks that generally I think accomplish avoiding the bug only 
 by their usage patterns and the tweaks not hitting it.
 
 This particular iso freebsd download has the virtue of being completely 
 reproducible.
 
 Does any of the above help?   Also here's an update zpool :
 
 nas4free:~# zpool status pool1
    pool: pool1
   state: ONLINE
    scan: scrub canceled on Fri Jan 25 22:07:51 2013
 config:
 
      NAME        STATE     READ WRITE CKSUM
      pool1       ONLINE       0     0     0
        raidz1-0  ONLINE       0     0     0
          ada2p2  ONLINE       0     0     0
          ada3p2  ONLINE       0     0     0
          ada4p2  ONLINE       0     0     0
          ada5p2  ONLINE       0     0     0
 
 errors: No known data errors
 nas4free:~#
 
 as4free:~# zpool iostat -v pool1
                 capacity     operations    bandwidth
 pool        alloc   free   read  write   read  write
 ----------  -----  -----  -----  -----  -----  -----
 pool1       3.01T  2.43T    168      0   360K  3.42K
    raidz1    3.01T  2.43T    168      0   360K  3.42K
      ada2p2      -      -    124      0   104K  2.34K
      ada3p2      -      -    123      0   104K  2.28K
      ada4p2      -      -    124      0   103K  2.34K
      ada5p2      -      -    126      0  98.1K  2.29K
 ----------  -----  -----  -----  -----  -----  -----
 
 nas4free:~#
 
 nas4free:~# zpool get all pool1
 NAME   PROPERTY       VALUE       SOURCE
 pool1  size           5.44T       -
 pool1  capacity       55%         -
 pool1  altroot        -           default
 pool1  health         ONLINE      -
 pool1  guid           1701438519865110975  default
 pool1  version        28          default
 pool1  bootfs         -           default
 pool1  delegation     on          default
 pool1  autoreplace    off         default
 pool1  cachefile      -           default
 pool1  failmode       wait        default
 pool1  listsnapshots  off         default
 pool1  autoexpand     off         default
 pool1  dedupditto     0           default
 pool1  dedupratio     1.46x       -
 pool1  free           2.43T       -
 pool1  allocated      3.01T       -
 pool1  readonly       off         -
 pool1  comment        -           default
 pool1  expandsize     0           -
 nas4free:~#
 nas4free:~# zfs get all pool1/videos
 NAME          PROPERTY              VALUE                  SOURCE
 pool1/videos  type                  filesystem             -
 pool1/videos  creation              Sat Jan 19  5:12 2013  -
 pool1/videos  used                  526G                   -
 pool1/videos  available             1.74T                  -
 pool1/videos  referenced            526G                   -
 pool1/videos  compressratio         1.00x                  -
 pool1/videos  mounted               yes                    -
 pool1/videos  quota                 none                   local
 pool1/videos  reservation           none                   local
 pool1/videos  recordsize            128K                   default
 pool1/videos  mountpoint            /mnt/pool1/videos      inherited 
 from pool1
 pool1/videos  sharenfs              off                    default
 pool1/videos  checksum              on                     default
 pool1/videos  compression           off                    local
 pool1/videos  atime                 off                    local
 pool1/videos  devices               on                     default
 pool1/videos  exec                  on                     default
 pool1/videos  setuid                on                     default
 pool1/videos  readonly              off                    local
 pool1/videos  jailed                off                    default
 pool1/videos  snapdir               hidden                 local
 pool1/videos  aclmode               discard                default
 pool1/videos  aclinherit            restricted             default
 pool1/videos  canmount              on                     local
 pool1/videos  xattr                 off                    temporary
 pool1/videos  copies                1                      default
 pool1/videos  version               5                      -
 pool1/videos  utf8only              off                    -
 pool1/videos  normalization         none                   -
 pool1/videos  casesensitivity       sensitive              -
 pool1/videos  vscan                 off                    default
 pool1/videos  nbmand                off                    default
 pool1/videos  sharesmb              off                    default
 pool1/videos  refquota              none                   default
 pool1/videos  refreservation        none                   default
 pool1/videos  primarycache          all                    default
 pool1/videos  secondarycache        all                    default
 pool1/videos  usedbysnapshots       0                      -
 pool1/videos  usedbydataset         526G                   -
 pool1/videos  usedbychildren        0                      -
 pool1/videos  usedbyrefreservation  0                      -
 pool1/videos  logbias               latency                default
 pool1/videos  dedup                 off                    local
 pool1/videos  mlslabel                                     -
 pool1/videos  sync                  standard               local
 pool1/videos  refcompressratio      1.00x                  -
 pool1/videos  written               526G                   -
 nas4free:~#
 
 
 
 
 
 
 
 
 
 
 
 



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201301260310.r0Q3A1fe051107>