Project

General

Profile

Bug #1531

Maybe I'm just off base, but this seems like performance suckage.

Added by Joe Greco about 5 years ago. Updated over 3 years ago.

Status:
Cannot reproduce
Priority:
Important
Assignee:
-
Category:
-
Target version:
-
Start date:
Due date:
% Done:

0%

Seen in:
ChangeLog Entry:
Hardware Configuration:
Migration Needed:
No
Blanket Approval:
No

Description

I've been retiring some of our old storage servers, and upgrading the hardware. I had been running FreeNAS on some of these, and had always been annoyed because they would go catatonic for short periods of time during heavy write activity; I had never looked into this extensively. I knew that ZFS was a little piggy on CPU and these were old Opteron 240EE's with 8GB, so I had been writing it off as insufficient resources to make ZFS happy.

This has been problematic. NFS clients don't like their servers going catatonic. iSCSI initiators don't like their servers going catatonic. etc. But I pretty much expected that modern hardware would solve the problem.

I was horrified at the following, which represents an order-of-magnitude increase in suckageness. Comments inline.

Console setup
-------------

1) Configure Network Interfaces
2) Configure Link Aggregation
3) Create VLAN Interface
4) Configure Default Route
5) Configure Static Routes
6) Configure DNS
7) Reset WebGUI login credentials
8) Reset to factory defaults
9) Shell
10) Reboot
11) Shutdown

You may try the following URLs to access the web user interface:

http://10.255.1.233/

9
df -k
Filesystem 1024-blocks Used Avail Capacity Mounted on
/dev/ufs/FreeNASs1a 948903 387934 485057 44
/
devfs 1 1 0 100% /dev
/dev/md0 4663 1844 2446 43% /etc
/dev/md1 823 3 755 0% /mnt
/dev/md2 152791 15126 125442 11% /var
/dev/ufs/FreeNASs4 20263 350 18292 2% /data
storage0 760838283 12902098 747936184 2% /mnt/storage0
zpool list
NAME SIZE USED AVAIL CAP HEALTH ALTROOT
storage0 1.45T 24.7G 1.42T 1
ONLINE /mnt
%zpool status
pool: storage0
state: ONLINE
scrub: none requested
config:

NAME        STATE     READ WRITE CKSUM
storage0 ONLINE 0 0 0
raidz2 ONLINE 0 0 0
ada0p2 ONLINE 0 0 0
ada1p2 ONLINE 0 0 0
ada2p2 ONLINE 0 0 0
ada3p2 ONLINE 0 0 0

errors: No known data errors
cd /mnt/storage0
%ls al
total 25804137
drwxr-xr-x 2 root wheel 3 May 19 16:23 .
drwxr-xr-x 5 root wheel 512 May 19 16:19 ..
-rw-r--r-
1 root wheel 13235126272 May 19 16:27 file
%dd if=/dev/zero of=file bs=1048576
load: 0.02 cmd: dd 3216 [running] 1.09r 0.00u 0.00s 9
964k
No response from dd to that !^T, I suspect due to it still being in the file-opening stage
load: 0.10 cmd: dd 3216 [running] 3.87r 0.00u 3.71s 32% 2020k
7552+0 records in
7551+0 records out
7917797376 bytes transferred in 2.327832 secs (3401361194 bytes/sec)
load: 0.17 cmd: dd 3216 [tx->tx_quiesce_more_cv)] 7.20r 0.01u 4.76s 28% 2068k
12036+0 records in
12035+0 records out
12619612160 bytes transferred in 5.658315 secs (2230277345 bytes/sec)
Now at this point, 2230MB/sec? Sounds great but these drives cap out at 70MB/sec each.
load: 0.17 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 10.49r 0.01u 4.87s 21% 2068k
And now the system's catatonic. Note 10.49r
load: 0.15 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 12.90r 0.01u 4.87s 16% 2068k
load: 0.15 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 14.93r 0.01u 4.87s 13% 2068k
load: 0.14 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 17.30r 0.01u 4.87s 11% 2068k
load: 0.14 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 19.91r 0.01u 4.87s 8% 2068k
load: 0.13 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 22.14r 0.01u 4.87s 7% 2068k
load: 0.13 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 26.71r 0.01u 4.87s 4% 2068k
load: 0.12 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 32.93r 0.01u 4.87s 2% 2068k
load: 0.10 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 39.79r 0.01u 4.87s 1% 2068k
load: 0.09 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 46.72r 0.01u 4.87s 0% 2068k
load: 0.08 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 52.39r 0.01u 4.87s 0% 2068k
load: 0.07 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 58.47r 0.01u 4.87s 0% 2068k
load: 0.50 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 71.57r 0.01u 4.87s 0% 2068k
load: 0.42 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 82.68r 0.01u 4.87s 0% 2068k
load: 0.33 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 96.48r 0.01u 4.87s 0% 2068k
load: 0.26 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 112.70r 0.01u 4.87s 0% 2068k
load: 0.31 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 131.05r 0.01u 4.87s 0% 2068k
load: 0.20 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 159.51r 0.01u 4.87s 0% 2068k
load: 0.19 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 179.73r 0.01u 4.87s 0% 2068k
Notice 179.73r, minus the previous 10.49r, means the system went out to lunch for 169 seconds
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898293 secs (71349309 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898349 secs (71349286 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898357 secs (71349283 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898366 secs (71349280 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898373 secs (71349277 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898380 secs (71349274 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898386 secs (71349272 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898393 secs (71349269 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898400 secs (71349266 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898407 secs (71349263 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898414 secs (71349261 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898422 secs (71349257 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898429 secs (71349255 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898437 secs (71349251 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898445 secs (71349248 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898453 secs (71349245 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898459 secs (71349243 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 179.898466 secs (71349240 bytes/sec)
12242+0 records in
12241+0 records out
12835618816 bytes transferred in 181.944199 secs (70547008 bytes/sec)
Oh and there's all the stacked responses to my !^T's
load: 0.15 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 198.68r 0.03u 7.45s 8% 2068k
load: 0.28 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 221.59r 0.03u 7.45s 0% 2068k
load: 0.20 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 241.54r 0.03u 7.45s 0% 2068k
load: 0.44 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 271.23r 0.03u 7.45s 0% 2068k
21849+0 records in
21848+0 records out
22909288448 bytes transferred in 294.758276 secs (77722291 bytes/sec)
21849+0 records in
21848+0 records out
22909288448 bytes transferred in 294.758329 secs (77722277 bytes/sec)
21849+0 records in
21848+0 records out
22909288448 bytes transferred in 294.758336 secs (77722275 bytes/sec)
21849+0 records in
21848+0 records out
22909288448 bytes transferred in 294.758342 secs (77722273 bytes/sec)
load: 0.39 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 301.10r 0.03u 8.25s 4% 2068k
load: 0.33 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 313.96r 0.03u 8.25s 0% 2068k
25932+0 records in
25931+0 records out
27190624256 bytes transferred in 324.295019 secs (83845334 bytes/sec)
25932+0 records in
25931+0 records out
27190624256 bytes transferred in 324.295065 secs (83845322 bytes/sec)
!^C Ok, enough of this, stop now
load: 0.24 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 332.80r 0.03u 9.87s 9% 2068k
Guess not
load: 0.22 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 339.76r 0.03u 9.87s 5% 2068k
load: 0.17 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 354.30r 0.03u 9.87s 0% 2068k
load: 0.13 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 366.89r 0.03u 9.87s 0% 2068k
load: 0.22 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 390.92r 0.03u 9.87s 0% 2068k
load: 0.23 cmd: dd 3216 [tx->tx_quiesce_done_cv)] 438.32r 0.03u 9.87s 0% 2068k
32334+0 records in
32333+0 records out
33903607808 bytes transferred in 478.452024 secs (70861040 bytes/sec)
32334+0 records in
32333+0 records out
33903607808 bytes transferred in 478.452074 secs (70861032 bytes/sec)
32334+0 records in
32333+0 records out
33903607808 bytes transferred in 478.452082 secs (70861031 bytes/sec)
32334+0 records in
32333+0 records out
33903607808 bytes transferred in 478.452090 secs (70861030 bytes/sec)
32334+0 records in
32333+0 records out
33903607808 bytes transferred in 478.452098 secs (70861029 bytes/sec)
32334+0 records in
32333+0 records out
33903607808 bytes transferred in 478.452105 secs (70861028 bytes/sec)
32334+0 records in
32333+0 records out
33903607808 bytes transferred in 478.452121 secs (70861025 bytes/sec)
Well, about 150 seconds after !^C, it actually stops
%

So this kind of thing was completely melting the previous platform's 2005-vintage Opteron, but the new platform is resource-rich and I'm able to look at what's going on. In particular I can log in via ssh and get an interactive shell that is responsive as long as I don't touch the ZFS filesystem...

So I look at it, and of course, all that time in tx->tx_quiesce_done_cv is time that the system is writing to the disks at about 30MB/sec each.

Ok, so vfs.zfs.txg.timeout="5" ... that helped somewhat on the Opterons. It looks like it makes it "better":

dd if=/dev/zero of=file bs=1048576
load: 0.43 cmd: dd 2718 [zio->io_cv)] 2.93r 0.00u 0.07s 0
964k
load: 0.43 cmd: dd 2718 [zio->io_cv)] 4.84r 0.00u 0.11s 0% 964k
load: 0.39 cmd: dd 2718 [zio->io_cv)] 6.81r 0.00u 0.16s 0% 964k
load: 0.39 cmd: dd 2718 [zio->io_cv)] 9.07r 0.00u 0.21s 0% 964k
load: 0.36 cmd: dd 2718 [running] 11.59r 0.00u 0.28s 1% 2020k
28+0 records in
27+0 records out
28311552 bytes transferred in 0.005912 secs (4788775086 bytes/sec)
load: 0.36 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 14.35r 0.00u 0.35s 1% 2068k
337+0 records in
336+0 records out
352321536 bytes transferred in 3.950970 secs (89173429 bytes/sec)
load: 0.28 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 27.17r 0.00u 0.75s 1% 2068k
1410+0 records in
1409+0 records out
1477443584 bytes transferred in 16.660683 secs (88678453 bytes/sec)
load: 0.28 cmd: dd 2718 [running] 28.30r 0.00u 0.75s 2% 2068k
1524+0 records in
1523+0 records out
1596981248 bytes transferred in 16.715253 secs (95540358 bytes/sec)
load: 0.26 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 29.94r 0.00u 0.86s 2% 2068k
load: 0.26 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 31.03r 0.00u 0.86s 1% 2068k
load: 0.26 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 32.50r 0.00u 0.86s 1% 2068k
load: 0.26 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 33.98r 0.00u 0.86s 1% 2068k
load: 0.24 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 35.63r 0.00u 0.86s 1% 2068k
load: 0.24 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 37.25r 0.00u 0.86s 0% 2068k
load: 0.24 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 38.81r 0.00u 0.86s 0% 2068k
load: 0.22 cmd: dd 2718 [tx->tx_quiesce_done_cv)] 40.38r 0.00u 0.86s 0% 2068k
1698+0 records in
1697+0 records out
1779433472 bytes transferred in 28.920370 secs (61528725 bytes/sec)
1698+0 records in
1697+0 records out
1779433472 bytes transferred in 28.920423 secs (61528611 bytes/sec)
1698+0 records in
1697+0 records out
1779433472 bytes transferred in 28.920431 secs (61528595 bytes/sec)
1698+0 records in
1697+0 records out
1779433472 bytes transferred in 28.920438 secs (61528580 bytes/sec)
1698+0 records in
1697+0 records out
1779433472 bytes transferred in 28.920445 secs (61528565 bytes/sec)
1698+0 records in
1697+0 records out
1779433472 bytes transferred in 28.920453 secs (61528548 bytes/sec)
1698+0 records in
1697+0 records out
1779433472 bytes transferred in 28.920460 secs (61528533 bytes/sec)
1698+0 records in
1697+0 records out
1779433472 bytes transferred in 28.920468 secs (61528516 bytes/sec)

but even there, going catatonic for 10 seconds at a time, just not cool.

A NAS product shouldn't come configured so that it goes catatonic in its default configuration, and that's my bug report, and hopefully you can see the justification.

History

#1 Updated by Joe Greco about 5 years ago

After quite a bit of playing, it's apparent that this problem can be reduced by lowering the amount of memory in the system, or setting vfs.zfs.txg.write_limit_override, or one of several other things, but none of them actually fully eliminate the problem, they just bring the amount of time it takes for the system to respond to a more reasonable number, like one second. By way of comparison, a FFS based system responds virtually instantaneously to !^T. I also noticed that the problem seems to present itself much more aggressively if your drives are somewhat slower, such as the 2005-vintage 400GB'ers I was using (write speeds ~70MB/sec) while the 2012-vintage 4TB'ers I have (write speeds ~160MB/sec) seemed to cope without write_limit_override by only going catatonic for 5-10sec at a time.

If this is just a ZFS "live with it" thing, perhaps it would make sense to default to an aggressively conservative value to ensure responsiveness of systems by default, and allow administrators to twiddle it for additional speed?

#2 Updated by Josh Paetzel about 5 years ago

  • Resolution set to invalid
  • Status changed from Unscreened to Closed

This is fallout from a ZFS pool being more than 90% full. At 90% ZFS switches from performance to space based optimization, which has massive performance implications.

UFS does this as well, but it's performance envelope is different based on a difference in underlying technology. (A Copy of Write filesystem such as ZFS takes an incredible hit)

As you've found you can mitigate the symptoms a bit with tuning but the fix is to expand the pool or delete some data.

#3 Updated by Joe Greco about 5 years ago

  • Status changed from Closed to Investigation
  • Resolution deleted (invalid)

No, it ISN'T "fallout from a ZFS pool being more than 90% full." Did you look at the transcript? This happens instantly upon creation. I was getting it with ZERO PERCENT FULL. NEW FILESYSTEM.

I stopped after 2%, turned on serial console to capture the output, and then rebooted, which is why my transcript starts at 2% ... but I am rewriting the file, so it goes back to zero percent as part of the listed test. You can see that from the transcript too.

#4 Updated by Josh Paetzel about 5 years ago

Easy there tiger.

I'm sure everything you are doing is very obvious to you, but from the outside looking in it's not apparent that you are starting with an empty filesystem.

Your "transcript" (I didn't realize it was that) shows a full pool first, then a bunch of dd operations. You can hopefully see where one would get the impression you has a full pool and were trying to track down performance issues?

Can you run gstat while doing these operations? RAIDZ2 takes a big performance hit over RAIDZ or RAID10 and if one drive is acting up it will drag performance of the entire array down (which is already lower than a RAIDZ by 40% or so). While running gstat you're looking for one drive that has significantly higher latency than the others, or an inordinate amount of i/o's queued up compared to the others. (These both point to i/o retries)

What does smart say about the health of the drives? Are there any timeout errors being reported in /var/log/messages?

#5 Updated by Joe Greco about 5 years ago

While I'm happy to try that next time the system's together enough for me to do so, I have the following comments:

1) My transcript shows a full pool first? Could you please validate that claim? I am apparently extra dense this morning. I can't figure out what would lead you to make such an unusual statement.

2) As for your not realizing that I was showing a transcript, perhaps things have changed in recent years, but it used to be extremely common to show the output of script(1) or console output where doing so would provide relevant details. I'm kind of curious what you thought all the detail was, or what the new standard for transmission of detail is. I don't mean to be inconvenient, and typically I try to keep up with community norms, but I do sometimes lag a bit.

3) I'm an old-timer and so I was using iostat; running "iostat ada0 ada1 ada2 ada3 1" showed each member drive writing at a very consistent 30-32MB/sec except when the dd would become responsive. At that point, the drives would drop down to 0MB/sec for a second or two, a bunch of dd status responses would appear in the other window, and then dd would go unresponsive again and the drives were again writing out at a very consistent 30-32MB/sec.

This appears to be a case of an incredibly unreasonably large write buffer being maintained by ZFS. dd blasts an incredible amount of data into the write buffer, then ZFS hoses all further I/O requests until that's flushed out to disk, at which point the process repeats.

So, again, the point is, there almost certainly needs to be some cap on the write buffer size. There are good reasons to allow this to be a tunable, since it is probably trivial to come up with configurations where large numbers make sense, but a NAS that goes catatonic for minutes at a time in a default configuration ... well, at best that will leave users with a poor impression.

#6 Updated by Josh Paetzel about 5 years ago

df -k
Filesystem 1024-blocks Used Avail Capacity Mounted on
/dev/ufs/FreeNASs1a 948903 387934 485057 44
/
devfs 1 1 0 100% /dev
/dev/md0 4663 1844 2446 43% /etc
/dev/md1 823 3 755 0% /mnt
/dev/md2 152791 15126 125442 11% /var
/dev/ufs/FreeNASs4 20263 350 18292 2% /data
storage0 760838283 12902098 747936184 2% /mnt/storage0
zpool list
NAME SIZE USED AVAIL CAP HEALTH ALTROOT
storage0 1.45T 24.7G 1.42T 1
ONLINE /mnt
%zpool status

pool: storage0
state: ONLINE
scrub: none requested

config:

NAME STATE READ WRITE CKSUM
storage0 ONLINE 0 0 0
raidz2 ONLINE 0 0 0
ada0p2 ONLINE 0 0 0
ada1p2 ONLINE 0 0 0
ada2p2 ONLINE 0 0 0
ada3p2 ONLINE 0 0 0

errors: No known data errors
%cd /mnt/storage0
%ls al
total 25804137
drwxr-xr-x 2 root wheel 3 May 19 16:23 .
drwxr-xr-x 5 root wheel 512 May 19 16:19 ..
-rw-r--r-
1 root wheel 13235126272 May 19 16:27 file

1)

I'll just paste right from the beginning.....

This shows a ~ 1.4 TB pool with a few GB free. It shows a single file using all the space. That's where I got the impression you were using a full pool.

ZFS is a COW filesystem, rewriting in place doesn't occur, so your dd commands don't necessarily do what you think they might as compared to a journaling filesystem or something like UFS2.

2)

I've no idea what the "standards" are anymore. What is obvious to you isn't obvious to someone who deals with people of differing experience and skillsets on a daily basis. I get people who have no idea what UNIX is all the way to people who dwarf my two decades of experience and knowledge, and everything in between. The FreeNAS community is huge and varies widely.

"Here's the script output of a session showing my experiences"

"Here's a random sampling of commands I'm using to show the issue"

etc etc etc, can help someone who is trying to help sort out what is going on get caught up.

Remember, I was just dealing with why a cvsup mirror got cranky after an OS upgrade, then was collecting telemetry for a meeting with intel, then looked at your ticket. You're far more familiar with your situation than I am. What's obvious and clear to you doesn't always come across.

3) gstat will show you I/O latency whereas iostat will not.

It's still possible that hardware issues are causing the performance issues you are seeing. As a general rule, FreeNAS doesn't go out to lunch the way you are seeing in the default case. (whatever the default case is these days, which is somewhere along the lines of taking a 2011 Honda to an auto mechanic and asking for a tune-up)

vfs.zfs.txg.write_limit_override

This will limit how much data ZFS will cache before writing to disk.

Create a loader with this variable, try setting it to 1GB and see where that gets things. You'll have to reboot the system for it to take affect. By default this is disabled, which causes ZFS to pick a (very high)magic value. The "best" default value for it is so widely variable across hardware and workloads that it's not possible to pick a default that works across all hardware specs and workloads.

#7 Updated by Joe Greco about 5 years ago

1)

zpool list
NAME SIZE USED AVAIL CAP HEALTH ALTROOT
storage0 1.45T 24.7G 1.42T 1
ONLINE /mnt

Still not seeing it. To me this looks like a 1.45TB pool with 24.7GB used, 1.42TB available, which the system says is 1% of capacity.

Now the "df" command upstairs disagrees with that; it says

storage0 760838283 12902098 747936184 2% /mnt/storage0

that there's 2% used. Of course, that's a trivial difference. I think you are just in need of more coffee. ;-)

Either way, the behaviour exists on a blank zero percent empty filesystem - instantly.

2)

I would have expected either of your two suggested comments would have been implicit by showing a command prompt, a command, and the output, especially when prefaced by the console menu, showing 9 selected, etc. Sorry for not being sufficiently verbose. You can't win; others complain of TL;DR.

3)

I already discussed write_limit_override in comment:1, it is not really a fix and more of a band-aid. There is still some lagginess, though it can be tuned down to around a second without killing performance completely. By the way, it can be tuned on the fly, at least in 7.2, but I think in 7.3 it goes read-only.

But here's where I ultimately have to disagree with you; the purpose of this bug report was to indicate that the default breaks systems in horrible ways. You're saying that it's not possible to pick a default that works across all hardware specs and workloads. I find that hard to swallow.

My research suggests that Sun's attitude towards this issue is basically a variation on "it's supposed to be like that", which is typical Sun, but I've been re-engineering Sun stuff for decades now, and that doesn't faze me.

I've already suggested using a conservatively small value, partly because I've seen no failure cases for small values like 64M, but on the other hand, it impacts performance. I understand the desire for FreeNAS to perform as fast as possible, but on the flip side, a NAS that goes catatonic for minutes at a time is retarded in the usability dep't, and won't necessarily be a feature that is convincing new users to use it.

So perhaps I should observe that FreeNAS is in the enviable position of sitting between the user and his hardware/config/etc., and FreeNAS can quite possibly be made to test the system's I/O speed at the time a pool is created or imported. Combined with its existing knowledge of the disk layout, it would seem that an intelligent extrapolation could be made as to the maximum amount of I/O a user's setup could possibly sustain.

For example, a read test of my 400GB disks would show them capable of a maximum of 70MB/sec. In a RAIDZ2 configuration, four disks could only possibly write 140MB/sec of actual data (and in practice only write 70MB/sec). That's sequential so it is maximal possible best case - there is no way in heck that the hardware can ever possibly do much better than that, right? And if I'm doing random I/O, it'll be ... worse.

So what business does ZFS have caching two GIGABYTES of data to write out, and then hanging all further I/O until it is flushed?

You don't feel that a single default is possible? Well okay, then this is a feature request to at least provide an intelligent cap based on an educated guess.

I am willing to discuss this further, and I'm happy to help out if I can. I've /extensive/ experience with I/O subsystems, plus access to plenty of resources for experimentation and testing.

#8 Updated by Josh Paetzel about 5 years ago

Ok, formatting got me on the zpool status, df stuff, long weekend, Monday morning, the columns were shifted over in my browser, I didn't catch that.

You seem to be not responding to any suggestions that hardware could be an issue here.

The defaults do not, as a general rule, hang I/O for minutes at a time.

I think reasonable situational defaults also need to take network bandwidth into account as well.

#9 Updated by Joe Greco about 5 years ago

That's fine, as I said, not enough coffee. ;-)

I'm not responding to any suggestions about hardware being an issue because the hardware's not immediately available. This is a system that is undergoing a complete strip-down and refit, so as I said previously, I'll be happy to provide the gstat stats and anything else you'd like once it's operable again. Right now its fans are being migrated from 3 pin to 4 pin, and we're needing a special harness to be built by shop for the extras that the system board isn't capable of handling directly. ETA later this week, I think. Once that's done, I could even set you up with access to it over the Internet if you would like. Until then, running it is kind of a fun exercise in duct tape and baling wire.

I was kind of shocked at a minutes-long I/O hang as well, but I'll point out that even seconds can be too long for many applications, as many clients will give up when a fileserver serving whatever protocol you like just seems to "go out to lunch." That's why this needs some further investigation.

Network bandwidth may actually be the thing that saves the average FreeNAS box; it is pretty clear that what's problematic in my 400GB setup is that the dd process write speed is pretty much infinitely fast while the disks are relatively slow by today's standards. The problem was significantly reduced on modern 4TB drives, though it still stalled. The average user who is accessing FreeNAS via network with modern disks probably comes much closer to a happy place performance-wise.

However, I will note that the forums are littered with:

1) People who notice hiccups in their data transfer,

2) People who've suffered "random disconnects" during long transfers,

3) People who've suffered "disappearing iSCSI disks" (often coupled with "during heavy access")

4) People who are normally OK but are noticing these problems during ZFS scrubs, which of course change the write characteristics of their pool

etc. which all could easily be related to this, as I hope you can see.

#10 Updated by Josh Paetzel about 5 years ago

Agreed.

Let me know when you have the system put back together and we'll see if we can't chase down a root cause analysis as well as sane(r) defaults. (Perhaps they'll need to be hidden away in the autotuner)

#11 Updated by Joe Greco about 5 years ago

The system's back together.

To address your concerns:

1) I had dd simultaneously read all four disks, and confirmed for the first minute or two that the read rates were as expected. You can also examine the dd stats upon completion. The disks perform very similarly.

2) I had dd simultaneously write all four disks, ditto monitored, ditto dd stats, ditto conclusion.

If you have any other hardware concerns you would like tested, please advise. Given that the usage case I'm testing is sequential write to the filesystem, I would expect that ZFS is not doing anything that is substantially randomizing access to the disks.

So after those two tests, I essentially repeated the scenario I listed above. "gstat" is next to useless for serious use, as it does not seem to have a noninteractive mode suitable for long-term monitoring. Nice for instantaneous glimpses of the system, I guess. It reports the disks as 99-100% busy during periods of nonresponsiveness, though it also only reports about 35MB/sec write per disk (and 15-35ms/w), which is below my observed speeds via dd.

All of this is done as a single shot and documented in a script session via serial console.

http://www.sol.net/tmp/freenas/freenasslow.txt

Except the creation of filesystem, which is noted inline.

This system is temporarily available for play, and I can either do testing via proxy, or you're welcome to log in and try it yourself.

#12 Updated by Joe Greco over 4 years ago

After some extensive experimentation with this, and now with 8.3.0, I'm going to add some further notes to help people doing battle with this problem. There are also some useful comments in the forums.

ZFS is really lacking in its ability to adapt to a (small?) pool's maximum IOPS capacity. Some configurations bring out serious performance issues, sometimes more than would be expected. One of these seems to be 4-disk RAIDZ2. However, the comments herein seem to apply in some form to any ZFS pool that I've experimented with.

It's extremely important to understand the capabilities of your ZFS pool. This will be affected by things such as whether or not you are suffering a scrub, the availability of ARC/L2ARC, your mix of reads vs writes, your pool percentage full, and whether you are doing linear or random reads from the pool.

For maximum write performance, ZFS guides generally advise filling a pool no more than 80%, but I'd say 60% is more realistic. The advice here seems to fall apart on pools even at just 80% capacity.

Scrubs kill performance. For purposes of determining the capabilities of a pool, it is suggested that you RUN A SCRUB while establishing pool capabilities.

ARC/L2ARC greatly increases read performance, obviously, especially if your L2ARC is capable of storing the pool's entire "working set" (to borrow a term). Having a sufficiently large ARC/L2ARC all but eliminates the need to worry about read performance from the pool.

I've been using an exceedingly simple way to establish the minimum performance of a pool. I've been filling it approximately 50% full with a plain file. I then start a scrub. If I don't have a large ARC/L2ARC, I simultaneously start a read of the plain file. While that's going on, I start a write of a file 10% of the capacity of the pool. The number reported by dd at the end of that write is the approximate speed the pool is capable of sustaining "under rather heavy duress". While one can slew this number in either direction by altering the workload, this seems to be a workable estimate of the minimum a pool can support. A heavily seek-oriented read workload could severely impact that, but if you can keep the working set in L2ARC, that goes away as an issue.

I've then been modifying write_limit_override to 5x the number established. I originally expected that since the txg buffer was being flushed every 5 seconds, this would result in something close to the dd number above, but that seems to be optimistic, so w_l_o can be tweaked upwards. The side effect of this, of course, is that all writes are limited to this speed. Since I'm finding that this speed is typically only 5-10% of what a pool can sustain when it is otherwise idle, that kind of sucks. On the other hand, it really sucks to have your iSCSI going wonky during scrubs or heavy write activity.

I have not been able to "lose" an iSCSI connection with a 60% full pool, a 10%-write_limit_override, a scrub going on, an SSD L2ARC, and maximal read/write activity going on with a 4-disk RAIDZ2. The downside to this? On a pool that's nominally capable of 80MB/sec writes, that works out to 8MB/sec writes.

#13 Updated by Joe Greco over 4 years ago

A summary of some of the underlying issues:

http://forums.freenas.org/showthread.php?7731-Slow-write-speeds-on-a-ZFS-setup-and-a-gigabit-network&p=31049&viewfull=1#post31049

Posted here in order to help anyone struggling to implement a busy storage pool that requires a high level of responsiveness (sadly, still not bounded/guaranteed responsiveness).

#14 Updated by Joe Greco over 4 years ago

And another update. I've got a pretty good handle on this. I spent some time looking at the ZFS code involved and I think I see why it is implemented the way it is, and why it breaks for smaller, slower pools.

Fundamentally, a significant issue is that the txg buffer size can be just WAY TOO BIG for a system that has lots of RAM (8GB or more). The common advice for twiddling with that is to use write_limit_override, but that seems to introduce new brokenness elsewhere, including extremely degraded write performance under non-stressy conditions, and crippling ZFS's ability to self-manage what it thinks is an appropriate write limit (it isn't always wrong, it just starts out too aggressively, I think). So I took an entirely different approach. I've attacked the maximum sizing of the buffer. I ran into some odd issues trying to twiddle vfs.zfs.write_limit_max directly, but vfs.zfs.write_limit_shift is used internally to derive the size of vfs.zfs.write_limit_max based on the system memory size. The default value of 3 causes w_l_m to be 4GB on a 32GB system; this is excessive for a zpool only capable of maybe 100MB/sec. SO! I bumped it up to 8, which causes w_l_m to be 128MB. The magic isn't the 8, it's the sizing of 128 being similar to the pool's actual capabilities, so my suggestion is to determine the speed your pool can handle, probably with a simple "dd if=/dev/zero of=foo bs=1048576" and let it fill your pool, take that speed as "max the pool is capable of." Then tune write_limit_shift so that your txg limit is close to that. Each increment of w_l_s cuts the w_l_m in two.

Also, noticing that the v28 drop of vfs.zfs.txg.timeout from 30 to 5 was a little helpful, I dropped it further, to 1. Also dropping vfs.zfs.txg.synctime_ms to 200. All this taken together? Magic happens!

On a 50% full pool, without tweaks and system quiescent, the write speeds were 100-110MB/sec for a dd, with frequent catatonics of 120 or more seconds.

On the same 50% full pool, with w_l_s=8/timeout=1/synctime=200, dd write was 70-75MB/sec, couldn't see a pause of more than a second when doing many control-T's.

With those same settings while reading from the pool at full speed, read speeds were ~130MB/sec and write speeds were ~2-10MB/sec. I was able to catch some brief 1-2 second catatonics.

With those same settings while scrubbing and just writing, write speeds were ~40MB/sec. It felt laggy but not quite to the level of catatonic. It did not seem unreasonable.

So here's the short form. If you have a heavy read load, get a big SSD for L2ARC to offload frequently read stuff. Apply the method above to tune your pool. You'll lose some write speed, yes, but it seems quite possible to get good interactive response.

I would suggest to the FreeNAS maintainers that there may be some good reason to reflect on the sizing of the txg buffer. While some people will want maximum throughput at any cost, it seems like it'd be cool to have autotune maybe do some tests to estimate pool write speed and then maybe fix the sizing accordingly, and also a tickbox for "better interactive response" to reduce the time values as suggested.

Either way, I'm not convinced that this can be fixed any further than this with the design that exists, so I'll leave it to the FreeNAS maintainers as to what the disposition of this bug report should be.

#15 Updated by Rick Bollar over 4 years ago

This is helpful!

I would like to see autotune make an attempt at tweaking these settings. Seems like the perfect application!

#16 Updated by Joe Greco over 4 years ago

We've moved one of our old, problematic, laggy 1st generation servers onto a new E3-1230 virtual machine with 8GB of RAM, 4 ST3000DM001's in RAIDZ2/4K and 8.3.0-RELEASE. Saw the more-or-less expected txg flushing problem under heavy dd write to pool. Applied w_l_s=5 (256M w_l_m) with timeout=1/synctime=200. Suddenly the system is able to write to the pool at 90+MB/sec. It is able to simultaneously read at about 20MB/sec (worst case, up to 65MB/sec at times). Both reads and writes feel fluid and very responsive. The write is a single large file and the read are large ISO files being read sequentially, so of course performance would be substantially lower on small files, but that's to be expected.

My test for responsiveness remains a relatively unscientific "hit control-T and see how long it takes 'dd bs=1048576' to respond". If you're reading or writing 1MB blocks of data and the thing is able to respond in small fractions of a second consistently, that's about as good as any other test I've seen.

It is interesting to watch the system sacrifice read speeds to support the write operations; the system is capable of ~270MB/sec off the pool doing just reads, but that drops to within the 20-65MB/sec range under pressure from a write stream.

An only vaguely-related discussion of other problems resulting from ZFS having basically "too much" memory:

http://www.zfsbuild.com/2012/03/05/when-is-enough-memory-too-much-part-2/

#17 Updated by Joe Greco over 4 years ago

Another interesting data point is that, having put a moderately fast pool on a poor little HP MicroServer N36L (4xWD20EARS, 16GB RAM, no autotune or tweaks), I'm not seeing any noticeable catatonic states doing just a dd write, and even with a scrub going on with a RAIDZ2 pool, it's very responsive. I think this is just a sign that the faster system outlined above was completely saturating the I/O subsystem with too much traffic.

Oh, that did it. I went and said it and now I'm catching occasional 5 second catatonics. Loading it down with a read, write, and scrub gives ~10 second catatonics. But, point being, test under load.

#18 Updated by Joe Greco almost 4 years ago

Updated for FreeNAS 9.

Problem still exists. E5-2609 based system with 128GB RAM, 11 x 4TB Seagate HDD.15's in a RAIDZ3 vdev. Using a little shell magic to get consistent control-T's

#! /bin/sh -

(
while true; do
        printf \\024
        sleep 1
done
) | watch -W pts/0

and a dd session on ssh pts/0

[root@freenas] /mnt/test# dd if=/dev/zero of=file5 bs=1048576
load: 0.74  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 1.44r 0.00u 0.64s 5% 2508k
1588+0 records in
1587+0 records out
1664090112 bytes transferred in 1.507208 secs (1104087818 bytes/sec)
load: 0.74  cmd: dd 3923 [running] 2.45r 0.00u 0.79s 6% 2508k
1762+0 records in
1761+0 records out
1846542336 bytes transferred in 2.450955 secs (753397031 bytes/sec)
load: 0.74  cmd: dd 3923 [runnable] 3.48r 0.00u 0.99s 7% 2508k
2171+0 records in
2170+0 records out
2275409920 bytes transferred in 3.480266 secs (653803433 bytes/sec)
load: 0.74  cmd: dd 3923 [runnable] 4.48r 0.00u 1.17s 8% 2508k
2528+0 records in
2527+0 records out
2649751552 bytes transferred in 4.556460 secs (581537305 bytes/sec)
load: 0.74  cmd: dd 3923 [running] 5.52r 0.00u 1.33s 8% 2508k
2749+0 records in
2748+0 records out
2881486848 bytes transferred in 5.528915 secs (521166790 bytes/sec)
load: 0.74  cmd: dd 3923 [running] 6.66r 0.01u 1.56s 10% 2508k
3222+0 records in
3222+0 records out
3378511872 bytes transferred in 6.665127 secs (506893845 bytes/sec)
load: 1.48  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 7.76r 0.02u 2.02s 13% 2508k
4811+0 records in
4810+0 records out
5043650560 bytes transferred in 7.818231 secs (645114028 bytes/sec)
load: 1.48  cmd: dd 3923 [runnable] 8.85r 0.02u 2.03s 12% 2508k
4820+0 records in
4819+0 records out
5053087744 bytes transferred in 8.856160 secs (570573211 bytes/sec)
load: 1.48  cmd: dd 3923 [runnable] 9.95r 0.02u 2.22s 13% 2508k
5380+0 records in
5379+0 records out
5640290304 bytes transferred in 9.954371 secs (566614437 bytes/sec)
load: 1.48  cmd: dd 3923 [running] 11.05r 0.02u 2.41s 14% 2508k
5961+0 records in
5960+0 records out
6249512960 bytes transferred in 11.052460 secs (565440905 bytes/sec)
load: 1.44  cmd: dd 3923 [runnable] 12.27r 0.02u 2.61s 13% 2508k
6520+0 records in
6519+0 records out
6835666944 bytes transferred in 12.273474 secs (556946383 bytes/sec)
load: 1.44  cmd: dd 3923 [running] 13.39r 0.02u 2.80s 13% 2508k
7091+0 records in
7090+0 records out
7434403840 bytes transferred in 13.401658 secs (554737616 bytes/sec)
load: 1.44  cmd: dd 3923 [runnable] 14.53r 0.02u 2.99s 14% 2508k
7662+0 records in
7662+0 records out
8034189312 bytes transferred in 14.540684 secs (552531732 bytes/sec)
load: 1.44  cmd: dd 3923 [running] 15.67r 0.02u 3.19s 14% 2508k
8237+0 records in
8236+0 records out
8636071936 bytes transferred in 15.673138 secs (551011027 bytes/sec)
load: 1.44  cmd: dd 3923 [runnable] 16.74r 0.02u 3.39s 14% 2508k
8815+0 records in
8815+0 records out
9243197440 bytes transferred in 16.750077 secs (551830146 bytes/sec)
load: 2.12  cmd: dd 3923 [arc_eviction_mtx] 17.95r 0.02u 3.58s 14% 2508k
9395+0 records in
9394+0 records out
9850322944 bytes transferred in 17.965299 secs (548297185 bytes/sec)
load: 2.12  cmd: dd 3923 [runnable] 19.12r 0.02u 3.78s 14% 2508k
9975+0 records in
9974+0 records out
10458497024 bytes transferred in 19.124169 secs (546873277 bytes/sec)
load: 2.12  cmd: dd 3923 [running] 20.39r 0.02u 3.91s 13% 2508k
10318+0 records in
10317+0 records out
10818158592 bytes transferred in 20.393277 secs (530476717 bytes/sec)
load: 2.12  cmd: dd 3923 [runnable] 21.39r 0.02u 4.03s 13% 2508k
10524+0 records in
10523+0 records out
11034165248 bytes transferred in 21.398081 secs (515661438 bytes/sec)
load: 2.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 22.40r 0.02u 4.06s 12% 2508k
load: 1.95  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 23.41r 0.02u 4.06s 11% 2508k
load: 1.95  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 24.42r 0.02u 4.06s 9% 2508k
load: 1.95  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 25.43r 0.02u 4.06s 8% 2508k
load: 1.95  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 26.44r 0.02u 4.06s 7% 2508k
load: 1.80  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 27.45r 0.02u 4.06s 6% 2508k
load: 1.80  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 28.46r 0.02u 4.06s 5% 2508k
load: 1.80  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 29.47r 0.02u 4.06s 5% 2508k
load: 1.80  cmd: dd 3923 [runnable] 30.65r 0.02u 4.06s 4% 2508k
10594+0 records in
10593+0 records out
11107565568 bytes transferred in 30.655486 secs (362335327 bytes/sec)
10594+0 records in
10593+0 records out
11107565568 bytes transferred in 30.655512 secs (362335019 bytes/sec)
10594+0 records in
10593+0 records out
11107565568 bytes transferred in 30.655520 secs (362334926 bytes/sec)
10594+0 records in
10593+0 records out
11107565568 bytes transferred in 30.655528 secs (362334831 bytes/sec)
10594+0 records in
10593+0 records out
11107565568 bytes transferred in 30.655535 secs (362334749 bytes/sec)
10594+0 records in
10593+0 records out
11107565568 bytes transferred in 30.655542 secs (362334664 bytes/sec)
10594+0 records in
10593+0 records out
11107565568 bytes transferred in 30.655549 secs (362334583 bytes/sec)
10594+0 records in
10593+0 records out
11107565568 bytes transferred in 30.655556 secs (362334501 bytes/sec)
10594+0 records in
10593+0 records out
11107565568 bytes transferred in 30.655564 secs (362334405 bytes/sec)
load: 2.45  cmd: dd 3923 [running] 31.76r 0.02u 4.34s 6% 2508k
11427+0 records in
11426+0 records out
11981029376 bytes transferred in 31.764633 secs (377181421 bytes/sec)
load: 2.45  cmd: dd 3923 [running] 32.81r 0.02u 4.65s 8% 2508k
12224+0 records in
12223+0 records out
12816744448 bytes transferred in 32.819261 secs (390525077 bytes/sec)
load: 2.45  cmd: dd 3923 [runnable] 34.04r 0.02u 4.96s 10% 2508k
13105+0 records in
13105+0 records out
13741588480 bytes transferred in 34.049354 secs (403578536 bytes/sec)
load: 2.45  cmd: dd 3923 [runnable] 35.22r 0.02u 5.24s 12% 2508k
13928+0 records in
13927+0 records out
14603517952 bytes transferred in 35.285988 secs (413861670 bytes/sec)
load: 2.45  cmd: dd 3923 [runnable] 36.46r 0.02u 5.28s 11% 2508k
14049+0 records in
14048+0 records out
14730395648 bytes transferred in 36.466981 secs (403937899 bytes/sec)
load: 3.30  cmd: dd 3923 [arc_mfu->arcs_locks[i].arcs_lock] 37.60r 0.02u 5.46s 11% 2508k
14542+0 records in
14541+0 records out
15247343616 bytes transferred in 37.605756 secs (405452389 bytes/sec)
load: 3.30  cmd: dd 3923 [runnable] 38.74r 0.02u 5.66s 12% 2508k
15048+0 records in
15047+0 records out
15777923072 bytes transferred in 38.742825 secs (407247614 bytes/sec)
load: 3.30  cmd: dd 3923 [*vm map (system)] 39.88r 0.02u 5.89s 11% 2508k
15659+0 records in
15658+0 records out
16418603008 bytes transferred in 39.890078 secs (411596161 bytes/sec)
load: 3.30  cmd: dd 3923 [runnable] 41.02r 0.02u 6.24s 13% 2508k
16716+0 records in
16715+0 records out
17526947840 bytes transferred in 41.049400 secs (426972082 bytes/sec)
load: 3.92  cmd: dd 3923 [running] 42.15r 0.02u 6.27s 12% 2508k
16816+0 records in
16815+0 records out
17631805440 bytes transferred in 42.151046 secs (418300543 bytes/sec)
load: 3.92  cmd: dd 3923 [running] 43.29r 0.02u 6.48s 12% 2508k
17352+0 records in
17351+0 records out
18193842176 bytes transferred in 43.297944 secs (420201064 bytes/sec)
load: 3.92  cmd: dd 3923 [runnable] 44.43r 0.02u 6.84s 14% 2508k
18425+0 records in
18424+0 records out
19318964224 bytes transferred in 44.482215 secs (434307605 bytes/sec)
load: 3.92  cmd: dd 3923 [running] 45.53r 0.02u 6.86s 12% 2508k
18484+0 records in
18483+0 records out
19380830208 bytes transferred in 45.534568 secs (425628946 bytes/sec)
load: 3.92  cmd: dd 3923 [running] 46.69r 0.02u 7.10s 13% 2508k
19103+0 records in
19102+0 records out
20029898752 bytes transferred in 46.689796 secs (428999492 bytes/sec)
load: 3.92  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 47.88r 0.02u 7.46s 15% 2508k
20150+0 records in
20149+0 records out
21127757824 bytes transferred in 47.915871 secs (440934440 bytes/sec)
load: 3.92  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 48.99r 0.02u 7.48s 14% 2508k
20219+0 records in
20218+0 records out
21200109568 bytes transferred in 48.991343 secs (432731749 bytes/sec)
load: 3.92  cmd: dd 3923 [runnable] 50.13r 0.02u 7.74s 14% 2508k
20964+0 records in
20963+0 records out
21981298688 bytes transferred in 50.140507 secs (438394025 bytes/sec)
load: 4.49  cmd: dd 3923 [running] 51.25r 0.02u 7.89s 14% 2508k
21332+0 records in
21332+0 records out
22368223232 bytes transferred in 51.259099 secs (436375661 bytes/sec)
load: 4.49  cmd: dd 3923 [running] 52.36r 0.03u 8.13s 15% 2508k
21954+0 records in
21953+0 records out
23019388928 bytes transferred in 52.363907 secs (439604113 bytes/sec)
load: 4.49  cmd: dd 3923 [running] 53.48r 0.03u 8.33s 16% 2508k
22474+0 records in
22474+0 records out
23565697024 bytes transferred in 53.481225 secs (440634952 bytes/sec)
load: 4.49  cmd: dd 3923 [runnable] 54.65r 0.03u 8.58s 16% 2508k
23121+0 records in
23120+0 records out
24243077120 bytes transferred in 54.653738 secs (443575828 bytes/sec)
load: 5.09  cmd: dd 3923 [runnable] 55.80r 0.04u 8.95s 16% 2508k
24226+0 records in
24225+0 records out
25401753600 bytes transferred in 55.856920 secs (454764667 bytes/sec)
load: 5.09  cmd: dd 3923 [running] 56.95r 0.04u 8.98s 15% 2508k
24335+0 records in
24334+0 records out
25516048384 bytes transferred in 56.955226 secs (448001881 bytes/sec)
load: 5.09  cmd: dd 3923 [runnable] 58.07r 0.04u 9.19s 15% 2508k
24876+0 records in
24875+0 records out
26083328000 bytes transferred in 58.078071 secs (449108028 bytes/sec)
load: 5.09  cmd: dd 3923 [runnable] 59.11r 0.04u 9.52s 17% 2508k
25787+0 records in
25786+0 records out
27038580736 bytes transferred in 59.266566 secs (456219797 bytes/sec)
load: 5.56  cmd: dd 3923 [running] 60.40r 0.05u 9.63s 16% 2508k
26103+0 records in
26102+0 records out
27369930752 bytes transferred in 60.407855 secs (453085625 bytes/sec)
load: 5.56  cmd: dd 3923 [*vm map (system)] 61.54r 0.05u 9.84s 18% 2508k
26644+0 records in
26643+0 records out
27937210368 bytes transferred in 61.549235 secs (453900204 bytes/sec)
load: 5.56  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 62.55r 0.06u 10.04s 19% 2508k
27151+0 records in
27150+0 records out
28468838400 bytes transferred in 62.590110 secs (454845636 bytes/sec)
load: 5.56  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 63.57r 0.06u 10.08s 17% 2508k
load: 5.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 64.57r 0.06u 10.08s 15% 2508k
load: 5.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 65.58r 0.06u 10.08s 13% 2508k
load: 5.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 66.59r 0.06u 10.08s 11% 2508k
load: 5.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 67.60r 0.06u 10.08s 10% 2508k
load: 5.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 68.61r 0.06u 10.08s 9% 2508k
load: 5.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 69.62r 0.06u 10.08s 8% 2508k
load: 4.79  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 70.63r 0.06u 10.08s 7% 2508k
load: 4.79  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 71.64r 0.06u 10.08s 6% 2508k
load: 4.79  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 72.65r 0.06u 10.08s 5% 2508k
load: 4.79  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 73.66r 0.06u 10.08s 4% 2508k
load: 4.79  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 74.67r 0.06u 10.08s 4% 2508k
load: 4.40  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 75.68r 0.06u 10.08s 3% 2508k
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171112 secs (374712118 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171230 secs (374711537 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171238 secs (374711499 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171246 secs (374711459 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171257 secs (374711405 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171264 secs (374711371 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171271 secs (374711336 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171278 secs (374711302 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171285 secs (374711266 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171292 secs (374711232 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171299 secs (374711198 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171306 secs (374711163 bytes/sec)
27221+0 records in
27220+0 records out
28542238720 bytes transferred in 76.171313 secs (374711129 bytes/sec)
load: 4.40  cmd: dd 3923 [running] 76.70r 0.06u 10.18s 4% 2508k
27359+0 records in
27358+0 records out
28686942208 bytes transferred in 76.701615 secs (374007016 bytes/sec)
load: 4.40  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 77.72r 0.06u 10.43s 5% 2508k
27717+0 records in
27716+0 records out
29062332416 bytes transferred in 77.776752 secs (373663488 bytes/sec)
load: 4.40  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 78.73r 0.06u 10.44s 5% 2508k
27730+0 records in
27729+0 records out
29075963904 bytes transferred in 78.816784 secs (368905738 bytes/sec)
load: 4.40  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 79.74r 0.06u 10.45s 4% 2508k
27742+0 records in
27741+0 records out
29088546816 bytes transferred in 79.776757 secs (364624333 bytes/sec)
load: 4.40  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 80.75r 0.06u 10.46s 3% 2508k
27755+0 records in
27754+0 records out
29102178304 bytes transferred in 80.816754 secs (360100806 bytes/sec)
load: 4.05  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 81.76r 0.06u 10.47s 3% 2508k
load: 4.05  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 82.77r 0.06u 10.47s 2% 2508k
load: 4.05  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 83.78r 0.06u 10.47s 2% 2508k
load: 4.05  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 84.79r 0.06u 10.47s 2% 2508k
load: 4.05  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 85.80r 0.06u 10.47s 1% 2508k
load: 3.73  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 86.81r 0.06u 10.47s 1% 2508k
load: 3.73  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 87.82r 0.06u 10.47s 1% 2508k
load: 3.73  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 88.83r 0.06u 10.47s 0% 2508k
load: 3.73  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 89.84r 0.06u 10.47s 0% 2508k
load: 3.73  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 90.85r 0.06u 10.47s 0% 2508k
load: 3.59  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 91.86r 0.06u 10.47s 0% 2508k
load: 3.59  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 92.87r 0.06u 10.47s 0% 2508k
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087202 secs (312926381 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087220 secs (312926321 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087228 secs (312926294 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087236 secs (312926267 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087243 secs (312926243 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087250 secs (312926220 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087257 secs (312926196 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087264 secs (312926173 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087271 secs (312926150 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087279 secs (312926122 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087286 secs (312926099 bytes/sec)
27781+0 records in
27780+0 records out
29129441280 bytes transferred in 93.087293 secs (312926075 bytes/sec)
load: 3.59  cmd: dd 3923 [runnable] 93.88r 0.06u 10.81s 3% 2508k
28493+0 records in
28492+0 records out
29876027392 bytes transferred in 93.889725 secs (318203375 bytes/sec)
load: 3.59  cmd: dd 3923 [runnable] 94.90r 0.06u 11.05s 4% 2508k
28919+0 records in
28918+0 records out
30322720768 bytes transferred in 94.904599 secs (319507391 bytes/sec)
load: 3.59  cmd: dd 3923 [runnable] 95.90r 0.06u 11.36s 6% 2508k
29432+0 records in
29431+0 records out
30860640256 bytes transferred in 95.909717 secs (321767608 bytes/sec)
load: 3.54  cmd: dd 3923 [runnable] 96.97r 0.07u 11.67s 9% 2508k
29876+0 records in
29875+0 records out
31326208000 bytes transferred in 96.973590 secs (323038551 bytes/sec)
load: 3.54  cmd: dd 3923 [dn->dn_struct_rwlock] 98.14r 0.07u 11.93s 10% 2508k
30027+0 records in
30026+0 records out
31484542976 bytes transferred in 98.421242 secs (319895810 bytes/sec)
load: 3.54  cmd: dd 3923 [running] 99.15r 0.07u 12.07s 10% 2508k
30420+0 records in
30419+0 records out
31896633344 bytes transferred in 99.157217 secs (321677376 bytes/sec)
load: 3.54  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 100.16r 0.07u 12.53s 14% 2508k
31588+0 records in
31587+0 records out
33121370112 bytes transferred in 100.208805 secs (330523551 bytes/sec)
load: 3.98  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 101.17r 0.07u 12.70s 14% 2508k
32152+0 records in
32151+0 records out
33712766976 bytes transferred in 101.194959 secs (333146703 bytes/sec)
load: 3.98  cmd: dd 3923 [runnable] 102.19r 0.07u 12.86s 14% 2508k
32696+0 records in
32695+0 records out
34283192320 bytes transferred in 102.230019 secs (335353477 bytes/sec)
load: 3.98  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 103.20r 0.07u 13.03s 14% 2508k
33247+0 records in
33246+0 records out
34860957696 bytes transferred in 103.217574 secs (337742463 bytes/sec)
load: 3.98  cmd: dd 3923 [runnable] 104.22r 0.07u 13.13s 13% 2508k
33500+0 records in
33499+0 records out
35126247424 bytes transferred in 104.230112 secs (337006713 bytes/sec)
load: 3.66  cmd: dd 3923 [runnable] 105.23r 0.07u 13.29s 13% 2508k
33903+0 records in
33902+0 records out
35548823552 bytes transferred in 105.243556 secs (337776724 bytes/sec)
load: 3.66  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 106.37r 0.07u 13.64s 15% 2508k
34949+0 records in
34948+0 records out
36645634048 bytes transferred in 106.448324 secs (344257502 bytes/sec)
load: 3.66  cmd: dd 3923 [runnable] 107.40r 0.07u 13.71s 14% 2508k
35149+0 records in
35148+0 records out
36855349248 bytes transferred in 107.407532 secs (343135612 bytes/sec)
load: 3.66  cmd: dd 3923 [running] 108.61r 0.07u 13.83s 14% 2508k
35538+0 records in
35537+0 records out
37263245312 bytes transferred in 108.615913 secs (343073535 bytes/sec)
load: 3.66  cmd: dd 3923 [runnable] 109.62r 0.08u 14.12s 15% 2508k
36378+0 records in
36377+0 records out
38144049152 bytes transferred in 109.627599 secs (347942028 bytes/sec)
load: 3.66  cmd: dd 3923 [dn->dn_struct_rwlock] 110.63r 0.08u 14.24s 15% 2508k
36691+0 records in
36690+0 records out
38472253440 bytes transferred in 110.690168 secs (347567034 bytes/sec)
load: 4.49  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 111.64r 0.08u 14.46s 15% 2508k
37260+0 records in
37259+0 records out
39068893184 bytes transferred in 111.656770 secs (349901696 bytes/sec)
load: 4.49  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 112.66r 0.08u 14.68s 15% 2508k
37840+0 records in
37839+0 records out
39677067264 bytes transferred in 112.671637 secs (352147784 bytes/sec)
load: 4.49  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 113.67r 0.08u 14.89s 16% 2508k
38428+0 records in
38427+0 records out
40293629952 bytes transferred in 113.709175 secs (354356893 bytes/sec)
load: 4.49  cmd: dd 3923 [runnable] 114.68r 0.08u 15.08s 16% 2508k
38921+0 records in
38920+0 records out
40810577920 bytes transferred in 114.689189 secs (355836311 bytes/sec)
load: 4.49  cmd: dd 3923 [running] 115.70r 0.08u 15.20s 15% 2508k
39255+0 records in
39254+0 records out
41160802304 bytes transferred in 115.702356 secs (355747313 bytes/sec)
load: 4.93  cmd: dd 3923 [arc_eviction_mtx] 116.74r 0.08u 15.36s 15% 2508k
39665+0 records in
39664+0 records out
41590718464 bytes transferred in 116.744311 secs (356254777 bytes/sec)
load: 4.93  cmd: dd 3923 [running] 117.91r 0.08u 15.59s 15% 2508k
40261+0 records in
40260+0 records out
42215669760 bytes transferred in 117.914540 secs (358019204 bytes/sec)
load: 4.93  cmd: dd 3923 [runnable] 119.06r 0.08u 15.81s 15% 2508k
40839+0 records in
40838+0 records out
42821746688 bytes transferred in 119.064784 secs (359650816 bytes/sec)
load: 4.93  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 120.25r 0.08u 16.18s 17% 2508k
41951+0 records in
41950+0 records out
43987763200 bytes transferred in 120.317605 secs (365597064 bytes/sec)
load: 4.93  cmd: dd 3923 [running] 121.42r 0.08u 16.20s 16% 2508k
41986+0 records in
41986+0 records out
44025511936 bytes transferred in 121.429057 secs (362561589 bytes/sec)
load: 5.17  cmd: dd 3923 [running] 122.63r 0.08u 16.44s 16% 2508k
42607+0 records in
42606+0 records out
44675629056 bytes transferred in 122.633643 secs (364301573 bytes/sec)
load: 5.17  cmd: dd 3923 [runnable] 123.86r 0.08u 16.82s 18% 2508k
43713+0 records in
43712+0 records out
45835354112 bytes transferred in 123.870213 secs (370027249 bytes/sec)
load: 5.17  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 124.97r 0.08u 16.84s 16% 2508k
43770+0 records in
43769+0 records out
45895122944 bytes transferred in 125.486973 secs (365736154 bytes/sec)
load: 5.17  cmd: dd 3923 [runnable] 125.97r 0.08u 16.93s 15% 2508k
43855+0 records in
43854+0 records out
45984251904 bytes transferred in 125.984079 secs (365000500 bytes/sec)
load: 5.17  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 126.98r 0.08u 17.09s 14% 2508k
load: 6.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 128.00r 0.08u 17.09s 12% 2508k
load: 6.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 129.01r 0.08u 17.09s 11% 2508k
load: 6.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 130.02r 0.08u 17.09s 9% 2508k
load: 6.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 131.03r 0.08u 17.09s 8% 2508k
load: 6.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 132.04r 0.08u 17.09s 7% 2508k
load: 6.12  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 133.05r 0.08u 17.09s 6% 2508k
load: 5.63  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 134.06r 0.08u 17.09s 6% 2508k
load: 5.63  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 135.07r 0.08u 17.09s 5% 2508k
load: 5.63  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 136.08r 0.08u 17.09s 4% 2508k
load: 5.63  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 137.09r 0.08u 17.09s 3% 2508k
load: 5.18  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 138.10r 0.08u 17.09s 3% 2508k
load: 5.18  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 139.11r 0.08u 17.09s 2% 2508k
load: 5.18  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 140.12r 0.08u 17.09s 2% 2508k
load: 5.18  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 141.13r 0.08u 17.09s 2% 2508k
load: 5.18  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 142.14r 0.08u 17.09s 1% 2508k
load: 5.18  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 143.15r 0.08u 17.09s 1% 2508k
load: 4.92  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 144.16r 0.08u 17.09s 1% 2508k
load: 4.92  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 145.17r 0.08u 17.09s 0% 2508k
load: 4.92  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 146.18r 0.08u 17.09s 0% 2508k
load: 4.92  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 147.19r 0.08u 17.09s 0% 2508k
load: 4.53  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 148.20r 0.08u 17.09s 0% 2508k
load: 4.53  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 149.21r 0.08u 17.09s 0% 2508k
load: 4.53  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 150.22r 0.08u 17.09s 0% 2508k
load: 4.53  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 151.23r 0.08u 17.09s 0% 2508k
load: 4.25  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 152.24r 0.08u 17.09s 0% 2508k
load: 4.25  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 153.25r 0.08u 17.09s 0% 2508k
load: 4.25  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 154.26r 0.08u 17.09s 0% 2508k
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.073503 secs (299716781 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343919 secs (299195047 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343928 secs (299195030 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343936 secs (299195015 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343943 secs (299195001 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343950 secs (299194988 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343957 secs (299194974 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343965 secs (299194959 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343972 secs (299194945 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343979 secs (299194932 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343986 secs (299194918 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.343993 secs (299194905 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344000 secs (299194891 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344007 secs (299194878 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344014 secs (299194865 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344021 secs (299194851 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344028 secs (299194837 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344035 secs (299194824 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344042 secs (299194810 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344049 secs (299194797 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344056 secs (299194783 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344063 secs (299194770 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344070 secs (299194757 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344077 secs (299194743 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344084 secs (299194730 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344091 secs (299194716 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344098 secs (299194702 bytes/sec)
44326+0 records in
44325+0 records out
46478131200 bytes transferred in 155.344105 secs (299194689 bytes/sec)
load: 4.25  cmd: dd 3923 [running] 155.34r 0.08u 17.09s 0% 2508k
44327+0 records in
44326+0 records out
46479179776 bytes transferred in 155.366004 secs (299159266 bytes/sec)
load: 4.25  cmd: dd 3923 [running] 156.35r 0.08u 17.35s 1% 2508k
44806+0 records in
44805+0 records out
46981447680 bytes transferred in 156.436718 secs (300322381 bytes/sec)
load: 3.99  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 157.36r 0.08u 17.36s 1% 2508k
44818+0 records in
44817+0 records out
46994030592 bytes transferred in 157.396759 secs (298570510 bytes/sec)
load: 3.99  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 158.37r 0.08u 17.37s 1% 2508k
44831+0 records in
44830+0 records out
47007662080 bytes transferred in 158.436835 secs (296696548 bytes/sec)
load: 3.99  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 159.38r 0.08u 17.38s 1% 2508k
44843+0 records in
44842+0 records out
47020244992 bytes transferred in 159.396776 secs (294988683 bytes/sec)
load: 3.99  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 160.39r 0.08u 17.39s 0% 2508k
load: 3.99  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 161.40r 0.08u 17.39s 0% 2508k
load: 3.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 162.41r 0.08u 17.39s 0% 2508k
load: 3.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 163.42r 0.08u 17.39s 0% 2508k
load: 3.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 164.43r 0.08u 17.39s 0% 2508k
load: 3.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 165.44r 0.08u 17.39s 0% 2508k
load: 3.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 166.45r 0.08u 17.39s 0% 2508k
load: 3.37  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 167.46r 0.08u 17.39s 0% 2508k
load: 3.37  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 168.47r 0.08u 17.39s 0% 2508k
44871+0 records in
44870+0 records out
47049605120 bytes transferred in 168.496961 secs (279231179 bytes/sec)
44871+0 records in
44870+0 records out
47049605120 bytes transferred in 168.496987 secs (279231136 bytes/sec)
44871+0 records in
44870+0 records out
47049605120 bytes transferred in 168.496995 secs (279231123 bytes/sec)
44871+0 records in
44870+0 records out
47049605120 bytes transferred in 168.497004 secs (279231108 bytes/sec)
44871+0 records in
44870+0 records out
47049605120 bytes transferred in 168.497011 secs (279231096 bytes/sec)
44871+0 records in
44870+0 records out
47049605120 bytes transferred in 168.497018 secs (279231085 bytes/sec)
44871+0 records in
44870+0 records out
47049605120 bytes transferred in 168.497025 secs (279231073 bytes/sec)
44871+0 records in
44870+0 records out
47049605120 bytes transferred in 168.497032 secs (279231062 bytes/sec)
44871+0 records in
44870+0 records out
47049605120 bytes transferred in 168.497039 secs (279231050 bytes/sec)
load: 3.37  cmd: dd 3923 [runnable] 169.48r 0.09u 17.72s 2% 2508k
45493+0 records in
45492+0 records out
47701819392 bytes transferred in 169.500785 secs (281425360 bytes/sec)
load: 3.37  cmd: dd 3923 [running] 170.50r 0.10u 18.05s 5% 2508k
46137+0 records in
46137+0 records out
48378150912 bytes transferred in 170.507795 secs (283729849 bytes/sec)
load: 3.37  cmd: dd 3923 [running] 171.52r 0.10u 18.32s 6% 2508k
46596+0 records in
46595+0 records out
48858398720 bytes transferred in 171.521533 secs (284852857 bytes/sec)
load: 3.98  cmd: dd 3923 [runnable] 172.53r 0.10u 18.62s 8% 2508k
47115+0 records in
47114+0 records out
49402609664 bytes transferred in 172.540606 secs (286324540 bytes/sec)
load: 3.98  cmd: dd 3923 [runnable] 173.60r 0.10u 18.99s 11% 2508k
47599+0 records in
47598+0 records out
49910120448 bytes transferred in 173.607282 secs (287488634 bytes/sec)
load: 3.98  cmd: dd 3923 [running] 174.61r 0.10u 19.31s 12% 2508k
48037+0 records in
48036+0 records out
50369396736 bytes transferred in 174.617238 secs (288456038 bytes/sec)
load: 3.98  cmd: dd 3923 [runnable] 175.64r 0.10u 19.62s 14% 2508k
48765+0 records in
48764+0 records out
51132760064 bytes transferred in 175.639943 secs (291122618 bytes/sec)
load: 4.30  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 176.64r 0.10u 19.84s 14% 2508k
49315+0 records in
49314+0 records out
51709476864 bytes transferred in 176.700500 secs (292639109 bytes/sec)
load: 4.30  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 177.65r 0.11u 20.06s 15% 2508k
49897+0 records in
49896+0 records out
52319748096 bytes transferred in 177.699177 secs (294428759 bytes/sec)
load: 4.30  cmd: dd 3923 [running] 178.66r 0.11u 20.26s 16% 2508k
50424+0 records in
50423+0 records out
52872347648 bytes transferred in 178.668915 secs (295923595 bytes/sec)
load: 4.30  cmd: dd 3923 [running] 179.68r 0.11u 20.46s 16% 2508k
51012+0 records in
51011+0 records out
53488910336 bytes transferred in 179.682802 secs (297685197 bytes/sec)
load: 4.30  cmd: dd 3923 [runnable] 180.75r 0.11u 20.60s 15% 2508k
51446+0 records in
51445+0 records out
53943992320 bytes transferred in 180.752949 secs (298440455 bytes/sec)
load: 4.76  cmd: dd 3923 [runnable] 181.90r 0.12u 20.70s 14% 2508k
51721+0 records in
51720+0 records out
54232350720 bytes transferred in 181.912358 secs (298123510 bytes/sec)
load: 4.76  cmd: dd 3923 [running] 183.11r 0.12u 20.96s 15% 2508k
52440+0 records in
52439+0 records out
54986276864 bytes transferred in 183.116260 secs (300280690 bytes/sec)
load: 4.76  cmd: dd 3923 [runnable] 184.23r 0.12u 21.13s 15% 2508k
52890+0 records in
52889+0 records out
55458136064 bytes transferred in 184.234419 secs (301019410 bytes/sec)
load: 4.76  cmd: dd 3923 [running] 185.50r 0.12u 21.47s 17% 2508k
53984+0 records in
53983+0 records out
56605278208 bytes transferred in 185.578145 secs (305021252 bytes/sec)
load: 4.76  cmd: dd 3923 [runnable] 186.66r 0.12u 21.64s 17% 2508k
54562+0 records in
54561+0 records out
57211355136 bytes transferred in 186.728797 secs (306387424 bytes/sec)
load: 5.26  cmd: dd 3923 [running] 187.83r 0.12u 21.66s 15% 2508k
54632+0 records in
54631+0 records out
57284755456 bytes transferred in 187.837536 secs (304969692 bytes/sec)
load: 5.26  cmd: dd 3923 [running] 189.02r 0.12u 21.87s 15% 2508k
55207+0 records in
55206+0 records out
57887686656 bytes transferred in 189.019404 secs (306252615 bytes/sec)
load: 5.26  cmd: dd 3923 [running] 190.16r 0.12u 22.10s 16% 2508k
55841+0 records in
55840+0 records out
58552483840 bytes transferred in 190.163396 secs (307906175 bytes/sec)
load: 5.26  cmd: dd 3923 [runnable] 191.43r 0.12u 22.46s 16% 2508k
56871+0 records in
56870+0 records out
59632517120 bytes transferred in 191.458980 secs (311463673 bytes/sec)
load: 5.26  cmd: dd 3923 [runnable] 192.70r 0.12u 22.48s 14% 2508k
56926+0 records in
56925+0 records out
59690188800 bytes transferred in 192.708985 secs (309742635 bytes/sec)
load: 5.72  cmd: dd 3923 [running] 194.00r 0.12u 22.74s 15% 2508k
57577+0 records in
57576+0 records out
60372811776 bytes transferred in 194.023689 secs (311162065 bytes/sec)
load: 5.72  cmd: dd 3923 [runnable] 195.25r 0.12u 22.93s 14% 2508k
58047+0 records in
58047+0 records out
60866691072 bytes transferred in 195.254840 secs (311729487 bytes/sec)
load: 5.72  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 196.26r 0.12u 23.13s 14% 2508k
58541+0 records in
58540+0 records out
61383639040 bytes transferred in 196.276756 secs (312740236 bytes/sec)
load: 6.06  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 197.28r 0.12u 23.27s 14% 2508k
59052+0 records in
59051+0 records out
61919461376 bytes transferred in 197.311468 secs (313815826 bytes/sec)
load: 6.06  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 198.28r 0.12u 23.28s 13% 2508k
59065+0 records in
59064+0 records out
61933092864 bytes transferred in 198.346747 secs (312246577 bytes/sec)
load: 6.06  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 199.30r 0.12u 23.47s 13% 2508k
59575+0 records in
59574+0 records out
62467866624 bytes transferred in 199.311386 secs (313418455 bytes/sec)
load: 6.06  cmd: dd 3923 [runnable] 200.31r 0.12u 23.51s 12% 2508k
59659+0 records in
59658+0 records out
62555947008 bytes transferred in 200.318102 secs (312283046 bytes/sec)
load: 6.06  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 201.33r 0.12u 23.73s 13% 2508k
load: 6.46  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 202.33r 0.12u 23.73s 11% 2508k
load: 6.46  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 203.34r 0.12u 23.73s 10% 2508k
load: 6.46  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 204.35r 0.12u 23.73s 9% 2508k
load: 6.46  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 205.36r 0.12u 23.73s 8% 2508k
load: 6.46  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 206.37r 0.12u 23.73s 7% 2508k
load: 5.94  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 207.38r 0.12u 23.73s 6% 2508k
load: 5.94  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 208.39r 0.12u 23.73s 5% 2508k
load: 5.94  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 209.40r 0.12u 23.73s 4% 2508k
load: 5.94  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 210.41r 0.12u 23.73s 4% 2508k
load: 5.94  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 211.42r 0.12u 23.73s 3% 2508k
load: 5.46  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 212.43r 0.12u 23.73s 3% 2508k
load: 5.46  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 213.44r 0.12u 23.73s 2% 2508k
load: 5.46  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 214.45r 0.12u 23.73s 2% 2508k
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929748 secs (293604551 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929780 secs (293604508 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929792 secs (293604491 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929799 secs (293604482 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929806 secs (293604472 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929813 secs (293604462 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929820 secs (293604453 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929828 secs (293604442 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929835 secs (293604432 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929842 secs (293604423 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929849 secs (293604413 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929856 secs (293604404 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929863 secs (293604394 bytes/sec)
60182+0 records in
60181+0 records out
63104352256 bytes transferred in 214.929870 secs (293604385 bytes/sec)
load: 5.46  cmd: dd 3923 [runnable] 215.46r 0.12u 23.81s 2% 2508k
60276+0 records in
60275+0 records out
63202918400 bytes transferred in 215.470401 secs (293325292 bytes/sec)
load: 5.46  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 216.47r 0.12u 24.00s 4% 2508k
60657+0 records in
60656+0 records out
63602425856 bytes transferred in 216.536753 secs (293725776 bytes/sec)
load: 5.46  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 217.48r 0.12u 24.01s 3% 2508k
60669+0 records in
60668+0 records out
63615008768 bytes transferred in 217.496729 secs (292487197 bytes/sec)
load: 5.03  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 218.49r 0.12u 24.01s 3% 2508k
60682+0 records in
60681+0 records out
63628640256 bytes transferred in 218.536757 secs (291157612 bytes/sec)
load: 5.03  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 219.50r 0.12u 24.02s 2% 2508k
60695+0 records in
60694+0 records out
63642271744 bytes transferred in 219.576763 secs (289840650 bytes/sec)
load: 5.03  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 220.51r 0.12u 24.02s 2% 2508k
load: 5.03  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 221.52r 0.12u 24.02s 1% 2508k
load: 5.03  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 222.53r 0.12u 24.02s 1% 2508k
load: 4.62  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 223.54r 0.12u 24.02s 1% 2508k
load: 4.62  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 224.55r 0.12u 24.02s 1% 2508k
load: 4.62  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 225.56r 0.12u 24.02s 0% 2508k
60716+0 records in
60715+0 records out
63664291840 bytes transferred in 226.464323 secs (281122832 bytes/sec)
60716+0 records in
60715+0 records out
63664291840 bytes transferred in 226.464346 secs (281122804 bytes/sec)
60716+0 records in
60715+0 records out
63664291840 bytes transferred in 226.464354 secs (281122794 bytes/sec)
60716+0 records in
60715+0 records out
63664291840 bytes transferred in 226.464362 secs (281122783 bytes/sec)
60716+0 records in
60715+0 records out
63664291840 bytes transferred in 226.464369 secs (281122775 bytes/sec)
60716+0 records in
60715+0 records out
63664291840 bytes transferred in 226.464376 secs (281122766 bytes/sec)
load: 4.62  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 226.57r 0.12u 24.13s 1% 2508k
61074+0 records in
61073+0 records out
64039682048 bytes transferred in 226.646723 secs (282552870 bytes/sec)
load: 4.62  cmd: dd 3923 [runnable] 227.58r 0.12u 24.29s 2% 2508k
61487+0 records in
61486+0 records out
64472743936 bytes transferred in 227.616886 secs (283251146 bytes/sec)
load: 4.62  cmd: dd 3923 [running] 228.71r 0.12u 24.56s 5% 2508k
62425+0 records in
62424+0 records out
65456308224 bytes transferred in 228.718233 secs (286187539 bytes/sec)
load: 5.13  cmd: dd 3923 [running] 229.87r 0.12u 24.73s 5% 2508k
62895+0 records in
62894+0 records out
65949138944 bytes transferred in 229.872104 secs (286894920 bytes/sec)
load: 5.13  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 230.89r 0.12u 24.93s 7% 2508k
63558+0 records in
63557+0 records out
66644344832 bytes transferred in 230.967008 secs (288544868 bytes/sec)
load: 5.13  cmd: dd 3923 [running] 231.90r 0.12u 24.97s 6% 2508k
63663+0 records in
63662+0 records out
66754445312 bytes transferred in 231.907743 secs (287849144 bytes/sec)
load: 5.13  cmd: dd 3923 [running] 232.98r 0.12u 25.17s 7% 2508k
64189+0 records in
64189+0 records out
67307044864 bytes transferred in 232.985239 secs (288889739 bytes/sec)
load: 5.13  cmd: dd 3923 [runnable] 234.07r 0.12u 25.39s 9% 2508k
64737+0 records in
64736+0 records out
67880615936 bytes transferred in 234.073475 secs (289997044 bytes/sec)
load: 5.60  cmd: dd 3923 [running] 235.21r 0.12u 25.69s 10% 2508k
65235+0 records in
65234+0 records out
68402806784 bytes transferred in 235.214454 secs (290810389 bytes/sec)
load: 5.60  cmd: dd 3923 [running] 236.39r 0.12u 26.08s 13% 2508k
65816+0 records in
65815+0 records out
69012029440 bytes transferred in 236.395605 secs (291934486 bytes/sec)
load: 5.60  cmd: dd 3923 [*vm map (system)] 237.55r 0.12u 26.49s 16% 2508k
66439+0 records in
66438+0 records out
69665292288 bytes transferred in 237.560913 secs (293252334 bytes/sec)
load: 5.60  cmd: dd 3923 [running] 238.71r 0.13u 26.83s 19% 2508k
66940+0 records in
66939+0 records out
70190628864 bytes transferred in 238.718251 secs (294031263 bytes/sec)
load: 5.60  cmd: dd 3923 [runnable] 239.73r 0.13u 27.14s 21% 2508k
67316+0 records in
67315+0 records out
70584893440 bytes transferred in 239.928703 secs (294191118 bytes/sec)
load: 5.79  cmd: dd 3923 [runnable] 240.73r 0.13u 27.21s 19% 2508k
67400+0 records in
67399+0 records out
70672973824 bytes transferred in 240.737307 secs (293568848 bytes/sec)
load: 5.79  cmd: dd 3923 [arc_eviction_mtx] 241.74r 0.13u 27.38s 18% 2508k
67610+0 records in
67609+0 records out
70893174784 bytes transferred in 241.756401 secs (293242183 bytes/sec)
load: 5.79  cmd: dd 3923 [runnable] 242.76r 0.13u 27.59s 19% 2508k
68193+0 records in
68192+0 records out
71504494592 bytes transferred in 242.774500 secs (294530499 bytes/sec)
load: 5.79  cmd: dd 3923 [running] 243.78r 0.13u 27.84s 19% 2508k
68973+0 records in
68972+0 records out
72322383872 bytes transferred in 243.786713 secs (296662533 bytes/sec)
load: 6.45  cmd: dd 3923 [runnable] 244.80r 0.13u 28.05s 19% 2508k
69617+0 records in
69617+0 records out
72998715392 bytes transferred in 244.805239 secs (298190985 bytes/sec)
load: 6.45  cmd: dd 3923 [runnable] 245.80r 0.13u 28.25s 18% 2508k
70245+0 records in
70244+0 records out
73656172544 bytes transferred in 245.830233 secs (299622108 bytes/sec)
load: 6.45  cmd: dd 3923 [runnable] 246.93r 0.13u 28.57s 19% 2508k
71206+0 records in
71205+0 records out
74663854080 bytes transferred in 246.946665 secs (302348096 bytes/sec)
load: 6.45  cmd: dd 3923 [runnable] 248.12r 0.13u 28.64s 18% 2508k
71368+0 records in
71367+0 records out
74833723392 bytes transferred in 248.128059 secs (301593152 bytes/sec)
load: 6.58  cmd: dd 3923 [runnable] 249.26r 0.14u 28.83s 18% 2508k
71930+0 records in
71929+0 records out
75423023104 bytes transferred in 249.289718 secs (302551680 bytes/sec)
load: 6.58  cmd: dd 3923 [running] 250.44r 0.14u 29.02s 18% 2508k
72501+0 records in
72500+0 records out
76021760000 bytes transferred in 250.441639 secs (303550801 bytes/sec)
load: 6.58  cmd: dd 3923 [runnable] 251.62r 0.14u 29.21s 18% 2508k
73077+0 records in
73076+0 records out
76625739776 bytes transferred in 251.631947 secs (304515149 bytes/sec)
load: 6.58  cmd: dd 3923 [runnable] 252.84r 0.14u 29.41s 16% 2508k
73653+0 records in
73653+0 records out
77230768128 bytes transferred in 252.846436 secs (305445350 bytes/sec)
load: 6.58  cmd: dd 3923 [runnable] 254.08r 0.14u 29.61s 16% 2508k
74227+0 records in
74226+0 records out
77831602176 bytes transferred in 254.087179 secs (306318495 bytes/sec)
load: 6.53  cmd: dd 3923 [arc_eviction_mtx] 255.30r 0.15u 29.80s 19% 2508k
74800+0 records in
74799+0 records out
78432436224 bytes transferred in 255.306722 secs (307208661 bytes/sec)
load: 6.53  cmd: dd 3923 [arc_eviction_mtx] 256.53r 0.15u 30.00s 18% 2508k
75377+0 records in
75376+0 records out
79037464576 bytes transferred in 256.538577 secs (308091927 bytes/sec)
load: 6.53  cmd: dd 3923 [running] 257.86r 0.15u 30.19s 17% 2508k
75956+0 records in
75956+0 records out
79645638656 bytes transferred in 257.864988 secs (308865656 bytes/sec)
load: 6.53  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 258.87r 0.15u 30.26s 16% 2508k
load: 6.17  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 259.88r 0.15u 30.26s 14% 2508k
load: 6.17  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 260.89r 0.15u 30.26s 13% 2508k
load: 6.17  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 261.90r 0.15u 30.26s 11% 2508k
load: 6.17  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 262.91r 0.15u 30.26s 10% 2508k
load: 6.17  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 263.92r 0.15u 30.26s 9% 2508k
load: 5.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 264.93r 0.15u 30.26s 8% 2508k
load: 5.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 265.94r 0.15u 30.26s 7% 2508k
load: 5.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 266.95r 0.15u 30.26s 6% 2508k
load: 5.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 267.96r 0.15u 30.26s 5% 2508k
load: 5.67  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 268.97r 0.15u 30.26s 4% 2508k
load: 5.22  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 269.98r 0.15u 30.26s 4% 2508k
load: 5.22  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 270.99r 0.15u 30.26s 3% 2508k
load: 5.22  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 272.00r 0.15u 30.26s 3% 2508k
load: 5.22  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 273.01r 0.15u 30.26s 2% 2508k
load: 5.22  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 274.02r 0.15u 30.26s 2% 2508k
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.592295 secs (290317829 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876901 secs (290017236 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876910 secs (290017226 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876918 secs (290017218 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876925 secs (290017210 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876941 secs (290017193 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876949 secs (290017185 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876956 secs (290017178 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876963 secs (290017170 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876978 secs (290017154 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876985 secs (290017147 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.876992 secs (290017140 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.877007 secs (290017124 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.877014 secs (290017116 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.877021 secs (290017109 bytes/sec)
76027+0 records in
76026+0 records out
79719038976 bytes transferred in 274.877036 secs (290017093 bytes/sec)
load: 4.96  cmd: dd 3923 [runnable] 275.03r 0.15u 30.33s 2% 2508k
76124+0 records in
76123+0 records out
79820750848 bytes transferred in 275.041788 secs (290213176 bytes/sec)
load: 4.96  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 276.04r 0.16u 30.57s 3% 2508k
76509+0 records in
76508+0 records out
80224452608 bytes transferred in 276.106752 secs (290555924 bytes/sec)
load: 4.96  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 277.05r 0.16u 30.57s 3% 2508k
76521+0 records in
76520+0 records out
80237035520 bytes transferred in 277.068281 secs (289593003 bytes/sec)
load: 4.96  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 278.06r 0.16u 30.58s 2% 2508k
76534+0 records in
76533+0 records out
80250667008 bytes transferred in 278.106768 secs (288560640 bytes/sec)
load: 4.96  cmd: dd 3923 [tx->tx_quiesce_more_cv)] 279.07r 0.16u 30.59s 2% 2508k
76547+0 records in
76546+0 records out
80264298496 bytes transferred in 279.146748 secs (287534421 bytes/sec)
load: 4.56  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 280.08r 0.16u 30.60s 2% 2508k
load: 4.56  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 281.09r 0.16u 30.60s 1% 2508k
load: 4.56  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 282.10r 0.16u 30.60s 1% 2508k
load: 4.56  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 283.11r 0.16u 30.60s 1% 2508k
load: 4.56  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 284.12r 0.16u 30.60s 0% 2508k
load: 4.20  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 285.13r 0.16u 30.60s 0% 2508k
load: 4.20  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 286.14r 0.16u 30.60s 0% 2508k
load: 4.20  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 287.15r 0.16u 30.60s 0% 2508k
load: 4.20  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 288.16r 0.16u 30.60s 0% 2508k
load: 4.20  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 289.17r 0.16u 30.60s 0% 2508k
load: 4.20  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 290.18r 0.16u 30.60s 0% 2508k
load: 3.86  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 291.19r 0.16u 30.60s 0% 2508k
load: 3.86  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 292.20r 0.16u 30.60s 0% 2508k
load: 3.86  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 293.21r 0.16u 30.60s 0% 2508k
load: 3.86  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 294.22r 0.16u 30.60s 0% 2508k
load: 3.86  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 295.23r 0.16u 30.60s 0% 2508k
load: 3.55  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 296.24r 0.16u 30.60s 0% 2508k
load: 3.55  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 297.25r 0.16u 30.60s 0% 2508k
load: 3.55  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 298.26r 0.16u 30.60s 0% 2508k
load: 3.55  cmd: dd 3923 [tx->tx_quiesce_done_cv)] 299.27r 0.16u 30.60s 0% 2508k
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786634 secs (267829024 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786677 secs (267828985 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786687 secs (267828976 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786694 secs (267828970 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786702 secs (267828963 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786709 secs (267828957 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786716 secs (267828950 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786723 secs (267828944 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786731 secs (267828937 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786741 secs (267828928 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786748 secs (267828922 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786755 secs (267828915 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786763 secs (267828908 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786770 secs (267828902 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786777 secs (267828896 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786784 secs (267828890 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786791 secs (267828883 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786802 secs (267828873 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786809 secs (267828867 bytes/sec)
76573+0 records in
76572+0 records out
80291561472 bytes transferred in 299.786816 secs (267828861 bytes/sec)
load: 3.55  cmd: dd 3923 [running] 300.28r 0.16u 30.79s 0% 2508k
77124+0 records in
77123+0 records out
80869326848 bytes transferred in 300.287843 secs (269306030 bytes/sec)
load: 3.51  cmd: dd 3923 [running] 301.37r 0.16u 31.15s 4% 2508k
77728+0 records in
77727+0 records out
81502666752 bytes transferred in 301.373874 secs (270437068 bytes/sec)
load: 3.51  cmd: dd 3923 [running] 302.50r 0.16u 31.49s 6% 2508k
78232+0 records in
78232+0 records out
82032197632 bytes transferred in 302.502533 secs (271178548 bytes/sec)
^C78369+0 records in
78368+0 records out
82174803968 bytes transferred in 302.973036 secs (271228110 bytes/sec)
[root@freenas] /mnt/test#
[root@freenas] /mnt/test# sysctl -a|grep write_l
vfs.zfs.write_limit_override: 0
vfs.zfs.write_limit_inflated: 352259665920
vfs.zfs.write_limit_max: 14677486080
vfs.zfs.write_limit_min: 33554432
vfs.zfs.write_limit_shift: 3
[root@freenas] /mnt/test#

I had originally noticed that the reduction of vfs.zfs.txg.timeout to 5 had reduced the impact of this issue on FreeBSD 8, but raising the limit back to 30 does not seem to cause quite as much additional havoc on 9. It still boosts average write speeds, from the ~290MB/sec below to about ~320MB/sec, but with a big 30sec-50sec burp now and then.

The big problem is that an almost 14GB txg buffer is still just way too large if the system can only write out 300MB/sec. At five seconds, that's 1500MB. For this system, setting write_limit_shift to 6 causes write_limit_max to come out to 1.8GB. But doing just that setting, I still saw 30 second stalls, which is confusing, since I'm not clear on what it would be doing. Pool write speeds measured with "zpool iostat 1" drop to a tenth of normal during these periods too.

Sadly, the tuning that worked under FreeNAS 8 only mostly-works under FreeNAS 9; I am seeing ~5 second bursts of catatonic state and I don't really know what exactly to attribute it to. One other interesting observation is that system percentage, which is generally fairly high on this slow CPU, drops to almost 0% during the catatonic state. In combination with the reduced pool I/O, it almost looks like seek latency or something like that.

#19 Updated by Anonymous almost 4 years ago

Reading the code from FreeBSD 9, it appears that vfs.zfs.write_limit_shift must be set by tunable to have any effect on FreeBSD since the code that recomputes the values set by zfs_write_limit_shift is predicated on the physical memory size changing which it does not on FreeBSD, ever. This could be fixed by converting the sysctl into a SYSCTL_PROC and zeroing old_physmem after setting zfs_write_limit_shift.

From database tuning, the standard approach is to reduce the per-sync size and increase the sync frequency to smooth out the hit, though it seems we haven't hit on the precise incantation to do that in this thread. ZFS's perchance for dynamically recalculating that value doesn't help us here, either.

There is always the possibility that you simply don't have enough capacity in your disk subsystem to handle the workload. RAID-Z3 is not helping your case, either; you are explicitly trading performance for an unusual amount of redundancy. RAID-Z2 is already a 30% performance reduction over RAID-Z and I would not be surprised if the 3rd layer of parity takes off another 30%.

Perhaps you should be exploring performance on RAID-Z or some other scheme that does not have such a high inherent performance penalty?

#20 Updated by Joe Greco almost 4 years ago

Just for clarity, I'm not seeking to solve this for myself at this point... and I've only very vaguely glanced at FreeBSD 9's ZFS code. My understanding is still mostly based on the digging into the 8.3 v28 code. Still, I understand the dynamics sufficiently that I can address any issues I run across, or I can probably figure it out myself. However, this continues to catch users in the forums unaware.

We advise people that larger ARC is good and that stuffing their systems with memory is generally desirable for the increased ARC size, but this has the undesirable side effect of also bumping up the default txg size. Since you might reasonably be increasing ARC size to compensate for a slowish pool, that can be bad.

The argument that there isn't enough disk capacity to handle the workload is a specious one; a single dd task will go as fast as the system allows, and if that is all that is required to cause other I/O requests to block, then that's crap. That's what I've outlined above. I'm not talking a system with a heavy multitask workload above. I'm talking the system going catatonic during a singlethreaded output event. A UNIX system should expect to be able to handle two tasks at the same time.

This general problem has been noted hundreds of times in the forums. It has very little to do with RAIDZ vs RAIDZ3; it has almost entirely to do with the system allowing far more (10x+) data than is reasonable to be cached up in a transaction group. To be sure, the problem is exacerbated by a larger amount of RAM and a pool that is slowish, but it exists in more "reasonable" configs as well.

We've also stopped advising users to use RAIDZ in the forums. There is sufficient anecdotal evidence to suggest that resilvering a failed RAIDZ has a nontrivial chance of failing that RAIDZ2 or greater is what we've been advising users to embrace. As we know from analysis,

http://www.cs.cmu.edu/~bianca/fast07.pdf

and some possibly faulty analysis, "RAID5 dies in 2009". So we should probably assume that RAIDZ users will be using RAIDZ2 or RAIDZ3 if we want to have a discussion of performance on actual FreeNAS systems designed to store and protect valuable data.

#21 Updated by HarmsCon - almost 4 years ago

How can we systematically determine the cause of this problem? It is easy enough to observe the issue using the dd test above (I first observed the problem using "md5sum /mnt/zpool1/foo-50GBfile".

This is a particularly bad bug for me as our zpools are exclusively used by the iscsi service, and istgt crashes the system when these stalls are prolonged. Only a power-cycle can recover the system once istgt crashes.

My best assessment is that this a ZFS memory tuning issue. I have 16GB RAM and 11GB of raw disk space, comprising:
2*(2*480GB SS) RAIDZ
4*2TB HDD RAIDZ + 4GB SSD ZIL + 96GB SSD L2ARC
So on the 1GB per TB guideline, I'm pretty close and certainly not absurdly under-provisioned. I have enabled FreeNAS autotune in the settings menu and that set values:
vm.kmem_size: 11796686540
vm.kmem_size_max: 14745858176
vfs.zfs.arc_max: 10617017886

What are the metrics to predict and prevent this issue, eg are there values in arc_summary.py or arcstat.py that indicate lack of resources? Is there anything I can monitor to determine the fault is my config?

#22 Updated by Joe Greco almost 4 years ago

You obviously didn't read the extensive discussion of the cause of the problem contained in the comments above, plus the steps that could be taken to mitigate. If you have technical analysis and suggestions that go beyond what I came up with, feel free to add them. Otherwise, if you just have further questions, the forum is -->> thataway.

#23 Updated by Jordan Hubbard over 3 years ago

  • Status changed from Investigation to Cannot reproduce
  • Seen in set to

Current performance data does not reflect the results above. Must be fixed?

#24 Updated by Joe Greco over 3 years ago

No, not quite. I specifically asked you awhile back if you had a pointer to what exactly had changed, and you most helpfully referred me to the source code. I know stuff's changed in the transaction group code but I simply do not have time to independently re-research this issue from the ground on up again. I am not going to go line by line trying to infer the reasoning changes were made.

It appears to me, based on experimental results, that the default transaction group sizing is still way off for systems with large memory and small IOPS capacity, but that - and this is the important bit - that the system adapts much more quickly when it makes a mistake in this regard. I can get it to go catatonic for at least a little while after a cold boot, but then it doesn't happen again for a very long time, usually until the pool gets much fuller, and I think it ends up needing to seek around, at which point the IOPS that can be done per txg drops again, and it'll kind of stutter around for awhile before reaching some sort of equilibrium. It will do that several more times until it gets up past 80% full, at which point I no longer care.

I have interpreted my results to mean that someone put in some logic to try to judge transaction group sizing more reasonably.

I would prefer to be able to avoid the first hit, but I have also noticed that if I do not immediately slam the pool after a cold boot, and allow some other work to occur first, some "adjustment" seems to take place very rapidly, and I cannot get the massive catatonic. I also note that the overall ZFS performance is improved, and that the problems I'm noticing would require greater-than-gigE to exploit in many cases.

I haven't yet tried the current code on a wide variety of platforms, so this is in some ways an optimistic status update.

#27 Updated by Joe Greco over 3 years ago

Also:

http://open-zfs.org/wiki/Features#Smoother_Write_Throttle

_The write throttle (dsl_pool_tempreserve_space() and txg_constrain_throughput()) is rewritten to produce much more consistent delays when under constant load. The new write throttle is based on the amount of dirty data, rather than guesses about future performance of the system. When there is a lot of dirty data, each transaction (e.g. write() syscall) will be delayed by the same small amount. This eliminates the "brick wall of wait" that the old write throttle could hit, causing all transactions to wait several seconds until the next txg opens. One of the keys to the new write throttle is decrementing the amount of dirty data as i/o completes, rather than at the end of spa_sync(). Note that the write throttle is only applied once the i/o scheduler is issuing the maximum number of outstanding async writes. See the block comments in dsl_pool.c and above dmu_tx_delay() for more details.

The ZFS i/o scheduler (vdev_queue.c) now divides i/os into 5 classes: sync read, sync write, async read, async write, and scrub/resilver. The scheduler issues a number of concurrent i/os from each class to the device. Once a class has been selected, an i/o is selected from this class using either an elevator algorithem (async, scrub classes) or FIFO (sync classes). The number of concurrent async write i/os is tuned dynamically based on i/o load, to achieve good sync i/o latency when there is not a high load of writes, and good write throughput when there is. See the block comment in vdev_queue.c for more details_.

Also available in: Atom PDF