Thoroughly confused on write performance

[danley]

Hi Everyone,

I am desperate for another set of eyes to look onto my problem.
I've been using FreeNas for a while now in a home NAS environment.
Here's my hardware which worked fine until now. I'm running on a asrock J3710-ITX with an Intel Pentium J3710 and 8GB RAM.

I've been running on a Raidz1 Pool with 3x2TB WD Red Disk until now. Those are in a pool "Old". I decided that I need more storage so I bought 2x8TB which I put into a new mirror pool named "Daten". Daten is a geli encrypted pool, Old is not encrypted.

I have zfs send | zfs recv all my date from Old to Daten, and I don't know how long that took but I feel like it was at an reasonable pace, certainly less than 12 hours.

Using the system now I get write speeds of less than 5 mb/s on Daten. Write speeds on Old are normal. Read speeds on both are normal, which makes me assume CPU is not the bottle neck due to encryption. I've been testing by writing to files in the pool as well as writing to zvols in the pool. Performance seems to be the same. I am unsure on how to diagnose this issue. CPU does not seem to be the bottleneck as far as I can tell. dd sits around 50% CPU usage.

After having resilvered the pool a couple of times I am now at 25MiB/s but still slow. I have no idea why resilvering improved the situation, though. I suspect I might have messed something up with geli the first time I tested my ability to restore the pool with geli.

root@freenas[/mnt]# dd if=/dev/da2 bs=5m | pv -s256g | dd of=/dev/zvol/Daten/testzvol 952MiB 0:00:40 [22.4MiB/s]

/dev/da2 should be capable of much higher speeds as tessted on another machine:
$ dd if=/cygdrive/e/de_windows_8_1_x64_dvd_2707227.iso bs=1M seek=7340032 of=/dev/sdc 3949217792 Bytes (3,9 GB, 3,7 GiB), 41,5303 s, 95,1 MB/s

Do you guys have any idea? How can I analyze this issue?

zpool list

Code:

NAME           SIZE  ALLOC   FREE  CKPOINT  EXPANDSZ   FRAG    CAP  DEDUP  HEALTH  ALTROOT
Daten         7.25T  1.77T  5.48T        -         -     0%    24%  1.00x  ONLINE  /mnt
Old           5.44T  2.48T  2.96T        -         -    19%    45%  1.00x  ONLINE  /mnt

zpool status

Code:

  pool: Daten
state: ONLINE
  scan: resilvered 71.6M in 0 days 00:00:02 with 0 errors on Fri Mar 29 22:03:28 2019
config:

        NAME                                                STATE     READ WRITE CKSUM
        Daten                                               ONLINE       0     0     0
          mirror-0                                          ONLINE       0     0     0
            gptid/0bd46e1a-500f-11e9-ae97-7085c22555c2.eli  ONLINE       0     0     0
            gptid/0d1c9f79-500f-11e9-ae97-7085c22555c2.eli  ONLINE       0     0     0

errors: No known data errors

  pool: Old
state: ONLINE
  scan: resilvered 4K in 0 days 00:00:01 with 0 errors on Wed Mar 27 21:03:50 2019
config:

        NAME                                            STATE     READ WRITE CKSUM
        Old                                             ONLINE       0     0     0
          raidz1-0                                      ONLINE       0     0     0
            gptid/b6053b61-422f-11e7-afe7-7085c22555c2  ONLINE       0     0     0
            gptid/b6da5f17-422f-11e7-afe7-7085c22555c2  ONLINE       0     0     0
            gptid/b7b89b77-422f-11e7-afe7-7085c22555c2  ONLINE       0     0     0

errors: No known data errors

resilver was because I was testing the disks in another machine to make sure.

Code:

oot@freenas[/mnt]# geli status
                                          Name  Status  Components
                              mirror/swap1.eli  ACTIVE  mirror/swap1
                              mirror/swap2.eli  ACTIVE  mirror/swap2
gptid/0d1c9f79-500f-11e9-ae97-7085c22555c2.eli  ACTIVE  gptid/0d1c9f79-500f-11e9-ae97-7085c22555c2
gptid/0bd46e1a-500f-11e9-ae97-7085c22555c2.eli  ACTIVE  gptid/0bd46e1a-500f-11e9-ae97-7085c22555c2

zdb with ashift seems to be fine as well. My drives have 4k sectors:

Code:

zdb -U /data/zfs/zpool.cache
Daten:
    version: 5000
    name: 'Daten'
    state: 0
    txg: 50424
    pool_guid: 15516724398489669549
    hostid: 3116882024
    hostname: 'freenas.local'
    com.delphix:has_per_vdev_zaps
    vdev_children: 1
    vdev_tree:
        type: 'root'
        id: 0
        guid: 15516724398489669549
        create_txg: 4
        children[0]:
            type: 'mirror'
            id: 0
            guid: 16389544199983235145
            metaslab_array: 39
            metaslab_shift: 36
            ashift: 12
            asize: 7984378019840
            is_log: 0
            create_txg: 4
            com.delphix:vdev_zap_top: 36
            children[0]:
                type: 'disk'
                id: 0
                guid: 10871911267321680461
                path: '/dev/gptid/0bd46e1a-500f-11e9-ae97-7085c22555c2.eli'
                whole_disk: 1
                DTL: 80
                create_txg: 4
                com.delphix:vdev_zap_leaf: 37
            children[1]:
                type: 'disk'
                id: 1
                guid: 17126202940566585759
                path: '/dev/gptid/0d1c9f79-500f-11e9-ae97-7085c22555c2.eli'
                whole_disk: 1
                DTL: 84
                create_txg: 4
                com.delphix:vdev_zap_leaf: 38
    features_for_read:
        com.delphix:hole_birth
        com.delphix:embedded_data
Old:
    version: 5000
    name: 'Old'
    state: 0
    txg: 7368637
    pool_guid: 420297742057380397
    hostid: 3116882024
    hostname: 'freenas.local'
    com.delphix:has_per_vdev_zaps
    vdev_children: 1
    vdev_tree:
        type: 'root'
        id: 0
        guid: 420297742057380397
        create_txg: 4
        children[0]:
            type: 'raidz'
            id: 0
            guid: 4413359244737712072
            nparity: 1
            metaslab_array: 40
            metaslab_shift: 35
            ashift: 12
            asize: 5994739924992
            is_log: 0
            create_txg: 4
            com.delphix:vdev_zap_top: 36
            children[0]:
                type: 'disk'
                id: 0
                guid: 7363565121042714212
                path: '/dev/gptid/b6053b61-422f-11e7-afe7-7085c22555c2'
                whole_disk: 1
                DTL: 453
                create_txg: 4
                com.delphix:vdev_zap_leaf: 37
            children[1]:
                type: 'disk'
                id: 1
                guid: 16961918986075126235
                path: '/dev/gptid/b6da5f17-422f-11e7-afe7-7085c22555c2'
                whole_disk: 1
                DTL: 452
                create_txg: 4
                com.delphix:vdev_zap_leaf: 38
            children[2]:
                type: 'disk'
                id: 2
                guid: 12975178285482062768
                path: '/dev/gptid/b7b89b77-422f-11e7-afe7-7085c22555c2'
                whole_disk: 1
                DTL: 450
                create_txg: 4
                com.delphix:vdev_zap_leaf: 39
    features_for_read:
        com.delphix:hole_birth
        com.delphix:embedded_data

 

[Chris Moore]

What kind of drive is the new 8TB?

 

[jgreco]

What kind of drives did you get for the 8TB drives? Are they possibly SMR drives?

 

[danley]

Code:

root@freenas[/mnt]# smartctl -a /dev/ada1
smartctl 6.6 2017-11-05 r4594 [FreeBSD 11.2-STABLE amd64] (local build)
Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Family:     Seagate Enterprise Capacity 3.5 HDD
Device Model:     ST8000NM0045-1RL112
Serial Number:    ZA1EB47E
LU WWN Device Id: 5 000c50 0b4424266
Firmware Version: UG07
User Capacity:    8,001,563,222,016 bytes [8.00 TB]
Sector Size:      4096 bytes logical/physical
Rotation Rate:    7200 rpm
Form Factor:      3.5 inches
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ACS-3 T13/2161-D revision 5
SATA Version is:  SATA 3.1, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Fri Mar 29 22:53:46 2019 CET
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

Code:

root@freenas[/mnt]# smartctl -a /dev/ada5
smartctl 6.6 2017-11-05 r4594 [FreeBSD 11.2-STABLE amd64] (local build)
Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Device Model:     HUH721008ALN600
Serial Number:    7SKAP82U
Firmware Version: LHGNT290
User Capacity:    8,001,563,222,016 bytes [8.00 TB]
Sector Size:      4096 bytes logical/physical
Rotation Rate:    7200 rpm
Form Factor:      3.5 inches
Device is:        Not in smartctl database [for details use: -P showall]
ATA Version is:   ACS-2, ATA8-ACS T13/1699-D revision 4
SATA Version is:  SATA 3.2, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Fri Mar 29 22:54:38 2019 CET
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

Smart Tests are completed without error.

 

[danley]

What kind of drives did you get for the 8TB drives? Are they possibly SMR drives?

ada5 is not an SMR drive. Pretty sure ada1 isn't either, at least it's not saying it in the datasheet.

 

[mjt5282]

Are the new 8TB disks SMR drives (shingled)? Perhaps constant writes are overflowing the fast buffers and writing is delayed. What is the brand/model number of the 8TB disks?

 

[HoneyBadger]

With neither drive being SMR and your ashift being correct, I would have to assume it's the encryption. The J3710 isn't a particularly powerful chip at all and if the write speeds are choking only on the encrypted pool it kind of points there.

Since you still have the source data is it possible to destroy the pool and recreate with encryption disabled to see if that resolves it?

 

[danley]

With neither drive being SMR and your ashift being correct, I would have to assume it's the encryption. The J3710 isn't a particularly powerful chip at all and if the write speeds are choking only on the encrypted pool it kind of points there.

Wouldn't that also affect read speeds? I'm reading the data at almost 200mb/s even after a reboot. At least I think I'm testing this with files that can't possibly be in the ARC:
root@freenas[/mnt]# pv /mnt/Daten/Downloads/ubuntu-18.04.2-live-server-amd64.iso > /dev/null 834MiB 0:00:05 [ 163MiB/s] [===============================================================================================================================================================================================================================>] 100% root@freenas[/mnt]# pv /mnt/Daten/Downloads/ubuntu-18.10-desktop-amd64.iso > /dev/null 1.86GiB 0:00:09 [ 191MiB/s] [===============================================================================================================================================================================================================================>] 100%

Since you still have the source data is it possible to destroy the pool and recreate with encryption disabled to see if that resolves it?

yes, that would be an option. I deliberately set out to test everything first. But I'd like to keep encryption because I like the idea of not having to care about zeroing a failing drive once its time has come.

I'd first like to see if it really is the encryption that slows things down. Get to the root cause.

 

[Yorick]

https://www.ixsystems.com/community/threads/encryption-performance-benchmarks.12157/

Your CPU does support the AES-NI instruction set. If it’s not keeping up with encryption, that’d be unexpected, from reading that link. Maybe the steps suggested in there can help you narrow it down.

 

[danley]

https://www.ixsystems.com/community/threads/encryption-performance-benchmarks.12157/

Your CPU does support the AES-NI instruction set. If it’s not keeping up with encryption, that’d be unexpected, from reading that link. Maybe the steps suggested in there can help you narrow it down.

Thank you for that link. And I think you're right, it doesn't seem to be the encryption, at least not entirely.

Following the instructions in the link I get

Code:

root@freenas[~]# dmesg | grep aes
aesni0: <AES-CBC,AES-XTS,AES-GCM,AES-ICM> on motherboard
aesni0: <AES-CBC,AES-XTS,AES-GCM,AES-ICM> on motherboard
aesni0: <AES-CBC,AES-XTS,AES-GCM,AES-ICM> on motherboard
root@freenas[~]# kldload aesni
kldload: can't load aesni: module already loaded or in kernel
root@freenas[~]# kldload geom_zero
root@freenas[~]# sysctl kern.geom.zero.clear=0
kern.geom.zero.clear: 1 -> 0
root@freenas[~]# geli onetime -s 4096 -l 256 -e aes-xts gzero
root@freenas[~]# dd if=/dev/gzero.eli of=/dev/null bs=1m count=4096
4096+0 records in
4096+0 records out
4294967296 bytes transferred in 21.172827 secs (202852799 bytes/sec)
root@freenas[~]# geli kill gzero

which is about the 200MB/s I see as read performance.

 

[Chris Moore]

Do you have sync enabled on the dataset?

 

[danley]

No, the dataset is at default settings.

 

[danley]

I think I fixed it. When replying to you I noticed that atime was on on all of my datasets. I disabled atime on Daten and now I'm getting expected write speeds.

So it's working now. I don't understand why, though. It was my understanding that atime would impact read performance due to having to deal with additional writes when accessing files. Is my understanding wrong in this case?

Edit: This would also explain why zfs recv worked with normal speeds. But then again it has me confused because I also tested writing to zvols which should not be affected by atime?

 

[Yorick]

That is odd. Maybe whatever you are using to write also does a read of the metadata, thus slowing everything down when atime is enabled?

 

[danley]

Oh well, update. I think whatever fixed it yesteday was only coincidental with me changing atime. Now with atime still off I'm back to write speeds of about 3MiB/s.

 

[danley]

I guess last update for now. I think the fault lies with the seagate drive. During testing today I noticed it's more than 10° hotter than the other 4 drives in the same space and then today for the first time SMART Errors started to pop up. Even though the drive has less than 100 hours on time it seems to have some electrical problem. I'm contacting Seagate support to see if I can get a replacement. I degraded the pool for now and write speed is in the expected range again aith atime=on.

 

[jgreco]

If the drive has less than 100 hours on time, that implies you did no burn-in testing on it.

https://www.ixsystems.com/community/threads/building-burn-in-and-testing-your-freenas-system.17750/

 

[danley]

If the drive has less than 100 hours on time, that implies you did no burn-in testing on it.

https://www.ixsystems.com/community/threads/building-burn-in-and-testing-your-freenas-system.17750/

Still in the middle of doing it. The fault popped up after I've done the SMART long tests, moved my data overand started testing with dd.

I'm glad the new pool is not really used so far. The old pool still works flawlessly. I guess this situation, especially since SMART took its time to report errors, is a prime example why testing as you described it is important.