I don't think that AES-NI is being used on 2.1.6 rc4

[Sharko]

I created an encrypted dataset in a pool created under 2.1.6 rc 4. I'm trying to copy data to it, but it is waaaaaay slow at 11 MB/sec, and the CPU percentage is up around 500%. That suggests to me that encryption is being done completely in software under this build. This machine has an Intel X5670, which is Westmere, so it should be able to use the hardware encryption. But I don't think it is. I looked through that thread we had last January/February on encryption speed; I think you had prepared a special build back then, but perhaps the changes since then have invalidated the support for hardware AES-NI encryption?

Kurt

Edit: I have a spindump of kernel_task, but it is too large to post, even after trimming it down to just the zfs-related threads.

[lundman]

If you have a spindump, you can check if:

aes_encrypt_intel) or aes_decrypt_intel()

those are the functions in: module/icp/asm-x86_64/os/macos/aes/aes_aesni.S

One second

I get:

Code: Select all

# log show --source --predicate 'sender == "zfs"' --style compact --last 5m


<zfs`spl_start (spl-osx.c:438)> SPL: loading
<zfs`spl_cpuid_features (spl-processor.c:107)> SPL: CPUID 0x1f8bfbfffffa320b and leaf7 0xbc000400009c27ab
<zfs`spl_cpuid_features (spl-processor.c:113)> which includes: AES PCLMULQDQ
<zfs`zfs_init (zfs_vfsops.c:2798)> ZFS filesystem version: 5
<zfs`aes_aesni_will_work (aes_impl_aesni.c:120)> Indicating AESNI will work

# zpool import -l BOOM

Enter passphrase for 'BOOM/ccm':
<zfs`aes_aesni_encrypt (aes_impl_aesni.c:84)> ACTUALLY CALLING AESNI



[lundman]

OK, looking into AESNI made me realise we were missing the tunables for it, so
try this build here, in addition to the comments in my previous post, you can
also check:

Code: Select all


kstat.zfs.darwin.tunable.zfs_vdev_raidz_impl: cycle fastest original scalar sse2 [ssse3]
kstat.zfs.darwin.tunable.icp_gcm_impl: cycle [fastest] generic pclmulqdq
kstat.zfs.darwin.tunable.icp_aes_impl: cycle [fastest] generic x86_64 aesni
kstat.zfs.darwin.tunable.zfs.fletcher_4_impl: [fastest] scalar superscalar superscalar4 sse2 ssse3
kstat.zfs.darwin.tunable.zfs.blake3_impl: cycle [fastest] generic sse2 sse41

ie,
sysctl kstat.zfs.darwin.tunable.icp_aes_impl



OpenZFSonOsX-2.1.6rc4-Catalina-10.15.pkg

(16.24 MiB) Downloaded 482 times

[Sharko]

If you have a spindump, you can check if:

aes_encrypt_intel) or aes_decrypt_intel()

those are the functions in: module/icp/asm-x86_64/os/macos/aes/aes_aesni.S

Neither of those functions show up in my spin dump.

Running the sysctl tunables I get:

Code: Select all

Admins-cMP-DP1:~ adminkurt$ sysctl kstat.zfs.darwin.tunable.zfs_vdev_raidz_impl
sysctl: unknown oid 'kstat.zfs.darwin.tunable.zfs_vdev_raidz_impl'
Admins-cMP-DP1:~ adminkurt$ sysctl kstat.zfs.darwin.tunable.icp_gcm_impl
sysctl: unknown oid 'kstat.zfs.darwin.tunable.icp_gcm_impl'
Admins-cMP-DP1:~ adminkurt$ sysctl kstat.zfs.darwin.tunable.icp_aes_impl
sysctl: unknown oid 'kstat.zfs.darwin.tunable.icp_aes_impl'
Admins-cMP-DP1:~ adminkurt$ sysctl kstat.zfs.darwin.tunable.zfs.fletcher_4_impl
kstat.zfs.darwin.tunable.zfs.fletcher_4_impl: [fastest] scalar superscalar superscalar4
Admins-cMP-DP1:~ adminkurt$ sysctl kstat.zfs.darwin.tunable.zfs.blake3_impl
kstat.zfs.darwin.tunable.zfs.blake3_impl: cycle [fastest] generic sse41
Admins-cMP-DP1:~ adminkurt$


It appears that I'll need to reboot to get that log file data after startup, so I'll do that in a minute, after I kill off this zfs send that appears on track to complete next week

Kurt

[Sharko]

I don't find aesni in the log file output:

Code: Select all

Admins-cMP-DP1:~ adminkurt$ log show --source --predicate 'sender == "zfs"' --style compact --last 5m
Filtering the log data using "sender == "zfs""
Skipping info and debug messages, pass --info and/or --debug to include.
Timestamp               Ty Process[PID:TID]
2022-11-08 20:50:00.494 Df kernel[0:765] (zfs) <zfs`org_openzfsonosx_zfs_zvol::start(IOService*)> ZFS: Loading module ...
2022-11-08 20:50:00.494 Df kernel[0:765] (zfs) <zfs`spl_start> SPL: loading
2022-11-08 20:50:00.584 Df kernel[0:765] (zfs) <zfs`org_openzfsonosx_zfs_zvol::start(IOService*)> ZFS: hostid set to e3455a94 from UUID 'D4B303FB-71BB-5D7C-8BE4-AE1277BD3269'
2022-11-08 20:50:01.633 Df kernel[0:765] (zfs) <zfs`zfs_init> ZFS filesystem version: 5
2022-11-08 20:50:01.642 Df kernel[0:765] (zfs) <zfs`org_openzfsonosx_zfs_zvol::start(IOService*)> ZFS: Loaded module v2.1.6-9_g516e3c7a5, ZFS pool version 5000, ZFS filesystem version 5
2022-11-08 20:50:19.076 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa.c:6310:spa_tryimport(): spa_tryimport: importing EXO
2022-11-08 20:50:19.076 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa_misc.c:417:spa_load_note(): spa_load($import, config trusted): LOADING
2022-11-08 20:50:19.096 Df kernel[0:d0b] (zfs) <zfs`__dprintf> vdev.c:162:vdev_dbgmsg(): disk vdev '/private/var/run/disk/by-id/media-82B79FF3-D2A1-6247-B12F-27616DEFDDC4': best uberblock found for spa $import. txg 50393
2022-11-08 20:50:19.099 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa_misc.c:417:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=50393
2022-11-08 20:50:19.340 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa.c:8426:spa_async_request(): spa=$import async request task=2048
2022-11-08 20:50:19.340 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa_misc.c:417:spa_load_note(): spa_load($import, config trusted): LOADED
2022-11-08 20:50:19.340 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa_misc.c:417:spa_load_note(): spa_load($import, config trusted): UNLOADING
2022-11-08 20:50:19.348 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa.c:6162:spa_import(): spa_import: importing EXO
2022-11-08 20:50:19.348 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa_misc.c:417:spa_load_note(): spa_load(EXO, config trusted): LOADING
2022-11-08 20:50:19.360 Df kernel[0:d0b] (zfs) <zfs`__dprintf> vdev.c:162:vdev_dbgmsg(): disk vdev '/private/var/run/disk/by-id/media-82B79FF3-D2A1-6247-B12F-27616DEFDDC4': best uberblock found for spa EXO. txg 50393
2022-11-08 20:50:19.364 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa_misc.c:417:spa_load_note(): spa_load(EXO, config untrusted): using uberblock with txg=50393
2022-11-08 20:50:21.873 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa_misc.c:417:spa_load_note(): spa_load(EXO, config trusted): read 43 log space maps (43 total blocks - blksz = 131072 bytes) in 163 ms
2022-11-08 20:50:22.128 Df kernel[0:d0b] (zfs) <zfs`__dprintf> mmp.c:240:mmp_thread_start(): MMP thread started pool 'EXO' gethrtime 21633395242
2022-11-08 20:50:22.132 Df kernel[0:e37] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50394, spa EXO, vdev_id 0, ms_id 4, smp_length 62256, unflushed_allocs 20480, unflushed_frees 24576, freed 0, defer 0 + 0, unloaded time 21633 ms, loading_time 4 ms, ms_max_size 16781287424, max size error 16781283328, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.136 Df kernel[0:e37] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50394, spa EXO, vdev_id 0, ms_id 6, smp_length 71728, unflushed_allocs 499712, unflushed_frees 688128, freed 0, defer 0 + 0, unloaded time 21637 ms, loading_time 4 ms, ms_max_size 17012498432, max size error 17012412416, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.157 Df kernel[0:e47] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50394, spa EXO, vdev_id 0, ms_id 36, smp_length 67088, unflushed_allocs 204800, unflushed_frees 4235264, freed 0, defer 0 + 0, unloaded time 21643 ms, loading_time 19 ms, ms_max_size 16386379776, max size error 16386117632, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.162 Df kernel[0:e47] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50394, spa EXO, vdev_id 0, ms_id 74, smp_length 15928, unflushed_allocs 258048, unflushed_frees 495616, freed 0, defer 0 + 0, unloaded time 21662 ms, loading_time 4 ms, ms_max_size 12880089088, max size error 12879953920, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.163 Df kernel[0:e47] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50394, spa EXO, vdev_id 0, ms_id 78, smp_length 13424, unflushed_allocs 442368, unflushed_frees 1912832, freed 0, defer 0 + 0, unloaded time 21667 ms, loading_time 1 ms, ms_max_size 15068651520, max size error 15068561408, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.164 Df kernel[0:e47] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50394, spa EXO, vdev_id 0, ms_id 82, smp_length 1144, unflushed_allocs 393216, unflushed_frees 2949120, freed 0, defer 0 + 0, unloaded time 21668 ms, loading_time 0 ms, ms_max_size 17172971520, max size error 17172746240, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.165 Df kernel[0:e47] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50394, spa EXO, vdev_id 0, ms_id 84, smp_length 5264, unflushed_allocs 196608, unflushed_frees 344064, freed 0, defer 0 + 0, unloaded time 21669 ms, loading_time 1 ms, ms_max_size 17167028224, max size error 17166954496, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.199 Df kernel[0:e5e] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50394, spa EXO, vdev_id 0, ms_id 86, smp_length 6184, unflushed_allocs 49152, unflushed_frees 49152, freed 0, defer 0 + 0, unloaded time 21691 ms, loading_time 13 ms, ms_max_size 17173721088, max size error 17173684224, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.201 Df kernel[0:e5e] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50394, spa EXO, vdev_id 0, ms_id 92, smp_length 2712, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 21704 ms, loading_time 1 ms, ms_max_size 17176891392, max size error 17176891392, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.325 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa.c:8426:spa_async_request(): spa=EXO async request task=1
2022-11-08 20:50:22.329 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa.c:8426:spa_async_request(): spa=EXO async request task=2048
2022-11-08 20:50:22.329 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa_misc.c:417:spa_load_note(): spa_load(EXO, config trusted): LOADED
2022-11-08 20:50:22.333 Df kernel[0:f34] (zfs) <zfs`__dprintf> spa_history.c:310:spa_history_log_sync(): txg 50395 open pool version 5000; software version zfs-macOS-2.1.6rc4-0-g516e3c7a5; uts noname 21.6.0 Darwin Kernel Version 21.6.0: Thu Sep 29 20:12:57 PDT 2022; root:xnu-8020.240.7~1/RELEASE_X86_64
2022-11-08 20:50:22.559 Df kernel[0:f4f] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50395, spa EXO, vdev_id 0, ms_id 93, smp_length 13936, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 18 ms, ms_max_size 17162895360, max size error 17162895360, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.565 Df kernel[0:f4e] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50395, spa EXO, vdev_id 0, ms_id 106, smp_length 4552, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 24 ms, ms_max_size 11345047552, max size error 11345047552, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.574 Df kernel[0:f55] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50395, spa EXO, vdev_id 0, ms_id 108, smp_length 10112, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 33 ms, ms_max_size 11378655232, max size error 11378655232, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.575 Df kernel[0:f53] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50395, spa EXO, vdev_id 0, ms_id 107, smp_length 53864, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 34 ms, ms_max_size 14265151488, max size error 14265151488, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.583 Df kernel[0:f50] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50395, spa EXO, vdev_id 0, ms_id 95, smp_length 3560, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 42 ms, ms_max_size 17178542080, max size error 17178542080, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.591 Df kernel[0:f54] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50395, spa EXO, vdev_id 0, ms_id 109, smp_length 8320, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 50 ms, ms_max_size 17169481728, max size error 17169481728, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.599 Df kernel[0:f51] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50395, spa EXO, vdev_id 0, ms_id 103, smp_length 632, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 58 ms, ms_max_size 17179631616, max size error 17179631616, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.608 Df kernel[0:f56] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50395, spa EXO, vdev_id 0, ms_id 110, smp_length 1904, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 67 ms, ms_max_size 17177088000, max size error 17177088000, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.618 Df kernel[0:f52] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50395, spa EXO, vdev_id 0, ms_id 104, smp_length 5240, unflushed_allocs 0, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 77 ms, ms_max_size 8617566208, max size error 8617566208, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.634 Df kernel[0:f58] (zfs) <zfs`__dprintf> metaslab.c:2459:metaslab_load_impl(): metaslab_load: txg 50396, spa EXO, vdev_id 0, ms_id 452, smp_length 136, unflushed_allocs 12288, unflushed_frees 0, freed 0, defer 0 + 0, unloaded time 22046 ms, loading_time 93 ms, ms_max_size 17179856896, max size error 17179856896, old_weight 840000000000001, new_weight 840000000000001
2022-11-08 20:50:22.636 Df kernel[0:d0b] (zfs) <zfs`__dprintf> spa.c:8426:spa_async_request(): spa=EXO async request task=32
2022-11-08 20:50:22.639 Df kernel[0:f34] (zfs) <zfs`__dprintf> spa_history.c:310:spa_history_log_sync(): txg 50397 import pool version 5000; software version zfs-macOS-2.1.6rc4-0-g516e3c7a5; uts noname 21.6.0 Darwin Kernel Version 21.6.0: Thu Sep 29 20:12:57 PDT 2022; root:xnu-8020.240.7~1/RELEASE_X86_64
2022-11-08 20:50:22.916 Df kernel[0:fee] (zfs) <zfs`zfs_ioc_osx_proxy_dataset> zfs_ioc_osx_proxy_dataset: Created virtual disk 'disk6s1' for 'EXO'
2022-11-08 20:50:27.857 Df kernel[0:f34] (zfs) <zfs`__dprintf> spa_history.c:294:spa_history_log_sync(): command: zpool import -a -d /var/run/disk/by-id
Admins-cMP-DP1:~ adminkurt$


I'll try that latest Catalina build you supplied, and report back.

[Sharko]

Well, uninstalled and reinstalled with the latest pkg supplied in this thread, and it looks promising:

Code: Select all

sh-3.2# log show --source --predicate 'sender == "zfs"' --style compact --last 3m | grep aesni
2022-11-08 21:06:43.449 Df kernel[0:767] (zfs) <zfs`aes_aesni_will_work> Indicating AESNI will work
2022-11-08 21:06:43.449 Df kernel[0:767] (zfs) <zfs`aes_aesni_will_work> Indicating AESNI will work
sh-3.2# sysctl kstat.zfs.darwin.tunable.icp_gcm_impl
kstat.zfs.darwin.tunable.icp_gcm_impl: cycle [fastest] generic pclmulqdq
sh-3.2# sysctl kstat.zfs.darwin.tunable.icp_aes_impl
kstat.zfs.darwin.tunable.icp_aes_impl: cycle [fastest] generic x86_64 aesni
sh-3.2#


I'll see what happens with a zfs send/receive to an encrypted dataset now...

[Sharko]

... and YAY, the data is transferring at the usual 125 MB/sec with cpu utilization at around 175%! That CPU utilization is higher than I'm used to seeing under 1.9.4, but at least the speed seems comparable. Thank you, Mr. Lundman!

Kurt

[lundman]

Ace, I wish I knew what I fixed