Strange IO Speeds

Moderators: jhartley, MSR734, nola

Strange IO Speeds

Post by shuman » Fri Sep 28, 2012 11:19 am

Currently rsync'ing all my movies to my fresh pool. Cruises along fine then nearly stops the speeds are so slow.

Mac Mini - i5 2.3 - 8GB - RSYNC over Gigabit - Mirrored 3TB Seagates

iostat Ouput - Notice disk1 and disk2:
Code: Select all
       disk0           disk1           disk2       cpu     load average
    KB/t tps  MB/s     KB/t tps  MB/s     KB/t tps  MB/s  us sy id   1m   5m   15m
    0.00   0  0.00    80.10 285 22.28    79.37 286 22.15   7 18 75  1.05 1.36 1.44
    0.00   0  0.00   103.29 230 23.18   101.09 235 23.18   4 16 80  1.05 1.36 1.44
    0.00   0  0.00    86.03 287 24.07    86.54 284 23.96   4 16 80  1.05 1.36 1.44
    8.00  47  0.37   123.81 215 25.98   122.73 218 26.11   6 17 77  1.05 1.36 1.44
    0.00   0  0.00    84.20 259 21.28    84.51 258 21.28   6 17 77  1.05 1.36 1.44
    0.00   0  0.00   103.35 233 23.50   102.14 237 23.62   5 17 78  1.05 1.35 1.44
    0.00   0  0.00    99.34 248 24.03   100.97 244 24.03   6 17 78  1.05 1.35 1.44
    0.00   0  0.00   100.09 232 22.64    99.95 240 23.39   6 16 78  1.05 1.35 1.44
    0.00   0  0.00    83.08 277 22.46    82.95 262 21.21   3 16 81  1.05 1.35 1.44
    0.00   0  0.00   108.18 245 25.85   108.51 249 26.36   5 16 78  1.05 1.35 1.44
    0.00   0  0.00   124.09 221 26.76   124.09 221 26.76   6 17 78  1.36 1.41 1.46
    0.00   0  0.00   100.45 251 24.60    99.43 251 24.35   6 17 77  1.36 1.41 1.46
    0.00   0  0.00   104.40 238 24.25   104.26 242 24.62   6 16 78  1.36 1.41 1.46
    0.00   0  0.00   100.66 250 24.55   101.36 247 24.42   6 17 77  1.36 1.41 1.46
    0.00   0  0.00   103.06 238 23.93   102.95 237 23.80   6 16 78  1.36 1.41 1.46
    0.00   0  0.00    86.84 285 24.14    87.59 284 24.27   6 17 77  1.33 1.41 1.46
   12.65  34  0.42   102.52 243 24.31   102.20 245 24.44   3 17 80  1.33 1.41 1.46
    0.00   0  0.00    93.26 299 27.21    92.95 300 27.21   5 16 79  1.33 1.41 1.46
   29.80  20  0.58   123.62 192 23.14   123.62 192 23.14   6 17 78  1.33 1.41 1.46
    0.00   0  0.00    87.50 263 22.44    87.03 263 22.32   6 17 77  1.33 1.41 1.46
          disk0           disk1           disk2       cpu     load average
    KB/t tps  MB/s     KB/t tps  MB/s     KB/t tps  MB/s  us sy id   1m   5m   15m
    0.00   0  0.00    97.88 245 23.40    97.48 246 23.40   6 17 77  1.39 1.42 1.46
    0.00   0  0.00   100.95 237 23.35   100.86 241 23.72   4 17 79  1.39 1.42 1.46
    0.00   0  0.00    90.34 284 25.04    88.95 287 24.91   3 15 82  1.39 1.42 1.46
    0.00   0  0.00   127.10 223 27.66   127.11 224 27.79   6 17 77  1.39 1.42 1.46
    0.00   0  0.00    86.11 283 23.77    86.72 281 23.77   6 17 77  1.39 1.42 1.46
    0.00   0  0.00   104.82 234 23.94   104.82 234 23.94   6 17 77  1.52 1.44 1.47
    0.00   0  0.00   101.03 244 24.04   100.62 245 24.04   6 18 76  1.52 1.44 1.47
    0.00   0  0.00   101.60 230 22.79   100.17 232 22.66   6 17 77  1.52 1.44 1.47
    0.00   0  0.00   104.00 218 22.12   104.96 216 22.12   2 15 84  1.52 1.44 1.47
    0.00   0  0.00   115.03 255 28.62   114.20 258 28.75   6 17 77  1.52 1.44 1.47
    0.00   0  0.00   115.31 216 24.31   115.85 215 24.31   6 17 77  1.56 1.45 1.47
    0.00   0  0.00    88.66 271 23.45    88.13 277 23.82   6 17 77  1.56 1.45 1.47
    0.00   0  0.00    86.57 277 23.39    86.42 276 23.27   6 17 77  1.56 1.45 1.47
    0.00   0  0.00   100.16 226 22.09    99.55 223 21.66   5 16 79  1.56 1.45 1.47
    0.00   0  0.00   106.72 232 24.13   104.70 234 23.88   2 15 83  1.56 1.45 1.47
    0.00   0  0.00   121.97 199 23.68   118.97 186 21.59   6 16 78  1.83 1.51 1.49
    0.00   0  0.00    97.09 221 20.92    99.05 236 22.79   6 16 78  1.83 1.51 1.49
    0.00   0  0.00    97.71 239 22.78    99.25 234 22.66   6 17 78  1.83 1.51 1.49
    0.00   0  0.00   103.20 229 23.06   102.98 227 22.81   2 16 82  1.83 1.51 1.49
   12.00   1  0.01   100.53 248 24.33   101.06 248 24.46   2 19 79  1.83 1.51 1.49
          disk0           disk1           disk2       cpu     load average
    KB/t tps  MB/s     KB/t tps  MB/s     KB/t tps  MB/s  us sy id   1m   5m   15m
    0.00   0  0.00   107.02 250 26.10   108.75 246 26.09   1 17 81  1.76 1.50 1.49
    0.00   0  0.00     4.00   4  0.02     4.00   4  0.02   1 15 84  1.76 1.50 1.49
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   1 13 86  1.76 1.50 1.49
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   2 11 87  1.76 1.50 1.49
    0.00   0  0.00   117.07  15  1.71   117.07  15  1.71   1 10 89  1.76 1.50 1.49
    0.00   0  0.00    75.66 106  7.82    74.95 107  7.82   1 20 79  1.78 1.51 1.49
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   1 13 86  1.78 1.51 1.49
    0.00   0  0.00    61.00   4  0.24    74.40   5  0.36   2  8 90  1.78 1.51 1.49
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   1 16 83  1.78 1.51 1.49
   13.00  18  0.23    93.45  22  2.01    93.45  22  2.01   2 14 84  1.78 1.51 1.49
    0.00   0  0.00    47.69 131  6.09    48.06 130  6.09   1 19 80  1.80 1.52 1.49
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   1 10 89  1.80 1.52 1.49
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   2 18 80  1.80 1.52 1.49
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   1  9 91  1.80 1.52 1.49
    0.00   0  0.00   116.44  18  2.05   116.44  18  2.05   1 17 81  1.80 1.52 1.49
    0.00   0  0.00    43.59 126  5.36    44.29 124  5.36   1 13 86  1.65 1.49 1.48
    6.33  24  0.15     0.00   0  0.00     0.00   0  0.00   2 16 82  1.65 1.49 1.48
    0.00   0  0.00    61.00   4  0.24    74.40   5  0.36   2 16 82  1.65 1.49 1.48
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   1 17 81  1.65 1.49 1.48
    0.00   0  0.00    83.48  23  1.87    87.20  25  2.13   1 11 88  1.65 1.49 1.48
          disk0           disk1           disk2       cpu     load average
    KB/t tps  MB/s     KB/t tps  MB/s     KB/t tps  MB/s  us sy id   1m   5m   15m
    0.00   0  0.00    76.64 107  8.00    74.91 106  7.75   1 19 79  1.60 1.48 1.48
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   1 11 88  1.60 1.48 1.48
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   1 14 85  1.60 1.48 1.48
    0.00   0  0.00     5.33   3  0.02     5.33   3  0.02   2 13 85  1.60 1.48 1.48
    0.00   0  0.00   111.62  21  2.29   113.04  23  2.54   1 17 82  1.60 1.48 1.48
    0.00   0  0.00    54.10  97  5.12    53.11  94  4.87   1 15 84  1.55 1.47 1.48
    0.00   0  0.00     0.00   0  0.00     0.00   0  0.00   1 15 84  1.55 1.47 1.48


Stopping the RSYNC and restarting immediately causes the data rate to jump back up in the 20's (MB). After about 30 seconds drops back off to basically nothing.

zstat Output if it helps:
Code: Select all
 v2012.09.23    155 threads        7 mounts        3233 vnodes     11:15:01
____________________________________________________________________________
             KALLOC      KERNEL/MAPS        TOTAL         EQUITY
  WIRED      46 MiB    1778 MiB/1783         1825 MiB      22.29%
  PEAK       86 MiB    3028 MiB              3115 MiB
  VMPAGE      16459 (IN)       6617 (OUT)       6617 (SYNC)         25 (MDS)
____________________________________________________________________________
                     HITS                  MISSES
  ARC overall:        96% (43601732)           4% (1668746)
  ARC demand data:    94% (5507868)            6% (331664)
  ARC demand meta:    97% (35365665)           3% (769807)
  ARC prefetch data:   5% (24302)             95% (452278)
  ARC prefetch meta:  95% (2703897)            5% (114997)
  DMU zfetch:         87% (65224160)          13% (8919061)
____________________________________________________________________________
     SIZE     SLAB    AVAIL    INUSE    TOTAL     PEAK  KMEM CACHE NAME
       72     4096    31813    31712    63525    77495  kmem_slab_cache
       24     4096   267522   360565   628087   959248  kmem_bufctl_cache
       88     4096      151     1019     1170     2070  taskq_ent_cache
      360     4096        9       24       33       33  taskq_cache
      824     8192        8        1        9    11574  zio_cache
       80     4096    33267     3233    36500    99600  sa_cache
      840     8192     2510   110143   112653   357732  dnode_t
      216     4096    58981   121487   180468   476766  dmu_buf_impl_t
      200     4096    56058   203222   259280   309160  arc_buf_hdr_t
      104     4096    22622    22104    44726   135166  arc_buf_t
      192     4096       38        2       40      400  zil_lwb_cache
      400     4096     8477     3233    11710    99570  znode_t
      512     8192    21077   105899   126976   441504  zio_buf_512
     1024     8192       45      427      472    13520  zio_buf_1024
     1536    12288      162      174      336     2512  zio_buf_1536
     2048     8192       15       89      104     3732  zio_buf_2048
     2560    20480       19       45       64    23872  zio_buf_2560
     3072    12288        8       36       44    37968  zio_buf_3072
     3584   114688       32       32       64      832  zio_buf_3584
     4096     8192        1      341      342    11710  zio_buf_4096
     5120    20480        7       21       28      968  zio_buf_5120
     6144    12288        3       15       18      910  zio_buf_6144
     7168   114688       67       13       80     1152  zio_buf_7168
     8192     8192        0        6        6     1110  zio_buf_8192
    10240    20480        4       16       20     1092  zio_buf_10240
    12288    12288        0        8        8      805  zio_buf_12288
    14336   114688        3        5        8      672  zio_buf_14336
    16384    65536        3    11761    11764    33300  zio_buf_16384
    20480    20480        0        6        6    10152  zio_buf_20480
    24576    98304        8        4       12     3596  zio_buf_24576
    28672   114688        3        1        4     5784  zio_buf_28672
    32768    65536        1        1        2     5800  zio_buf_32768
    36864   262144       12        2       14     3787  zio_buf_36864
    53248    65536        0        1        1     1150  zio_buf_53248
    61440   131072        0        2        2      840  zio_buf_61440
   118784   131072        0       33       33       90  zio_buf_118784
   122880   131072        0        2        2       78  zio_buf_122880
   131072   131072        0     6132     6132    15963  zio_buf_131072
____________________________________________________________________________



Pool created with the following:
Code: Select all
zpool create -O casesensitivity=insensitive -O normalization=formD zdata mirror /dev/disk1 /dev/disk2


I'm not new to ZFS, but I am new to performance monitoring so I would appreciate it if you would dumb down your responses a bit. :D
- Mac Mini (Late 2012), 10.8.5, 16GB memory, pool - 2 Mirrored 3TB USB 3.0 External Drives
shuman Offline

User avatar
 
Posts: 96
Joined: Mon Sep 17, 2012 8:15 am

Re: Strange IO Speeds

Post by shuman » Fri Sep 28, 2012 1:10 pm

It does appear to be a ZFS issue. rsync from internal drive to the same internal drive yields high IO. rsync from zdata/Videos to the same FS yields extremely low IO.

Internal to Internal = ~30MBs
zfs to zfs = ~1MBs

FYI, rsync version 3.0.9

Thoughts?
- Mac Mini (Late 2012), 10.8.5, 16GB memory, pool - 2 Mirrored 3TB USB 3.0 External Drives
shuman Offline

User avatar
 
Posts: 96
Joined: Mon Sep 17, 2012 8:15 am

Re: Strange IO Speeds

Post by dbrady » Fri Sep 28, 2012 2:46 pm

Perhaps a spindump(8) capture might shed some light on where the ZFS I/O is stalled. Spindump will sample the user process stacks (rsync in this case) as well as all the kernel process thread stacks.

Code: Select all
$ sudo spindump <pid-for-rsync>
dbrady Offline


 
Posts: 67
Joined: Wed Sep 12, 2012 12:43 am


Return to General Discussion

Who is online

Users browsing this forum: ilovezfs and 1 guest

cron