Sudden jump in z_rd_int CPU usage with transmission as a main workload

[nadiamoe]

Hi there,

My pool is not scrubbing.

That being said, long time ZFS on linux user here. I'm trying to troubleshoot some abnormally high CPU usage by z_rd_int kthreads and I'm running out of ideas :(

This all started when I noticed that a couple days ago my server room power usage jumped 20W above what's normal, and has been like that since:

This increase aligns with a bump in CPU usage of my storage box:

And inside it I can see that z_rd_int kthreads seem to be responsible for this usage:

perf top is not very useful either:

This pool is a raidz2 of 4 mechanical drives, with native encryption enabled for most relevant datasets:

[root@Terabox ~]# zpool status z2
  pool: z2
 state: ONLINE
status: Mismatch between pool hostid and system hostid on imported pool.
	This pool was previously imported into a system with a different hostid,
	and then was verbatim imported into this system.
action: Export this pool on all systems on which it is imported.
	Then import it to correct the mismatch.
   see: https://openzfs.github.io/openzfs-docs/msg/ZFS-8000-EY
  scan: scrub repaired 0B in 20:05:28 with 0 errors on Mon Jul  8 20:05:28 2024
config:

	NAME                                 STATE     READ WRITE CKSUM
	z2                                   ONLINE       0     0     0
	  raidz2-0                           ONLINE       0     0     0
	    ata-ST4000VN006-3CW104_ZW60GR3D  ONLINE       0     0     0
	    ata-ST4000VN008-2DR166_ZGY6V7HD  ONLINE       0     0     0
	    ata-ST4000VN006-3CW104_ZW60BXFT  ONLINE       0     0     0
	    ata-ST4000VN008-2DR166_ZGY6TK2J  ONLINE       0     0     0

errors: No known data errors

On iotop, both transmission and z_rd_int threads show as the top disk readers:

iotop is reporting each of those kthreads to be reading 20-60 M/s, which is way above what the server should be seeing. Transmission is capped (by it settings) to 4MiB/s read, and often reports less (I'd guesstimate 1-2MiB/s read sustained). I'm having a hard time trying to figure out why the numbers look so high on iotop, but I'd guess some sort of situation where transmission wants to read one piece, but reads a whole record instead, amplificating reads? I do have a 1M recordsize on this pool, but this has been like that since the beginning of times, so I wouldn't peg the noticable increase to that.

Weirdest thing is that this clearly started happening recently, but the point where it started does not correlate with anything significant. Nothing (services or servers) were restarted, upgraded, or significantly changed around the point where the cpu started to go up.

If I look at transmission io throughput over time, it doesn't seem to have increased in correlation to the cpu increase (denoted by the vertical red line here):

I'm really at my wit's end here. Any hint or random thought that can lead to reducing my electricity bill would be appreciated at this point 😁

EDIT: Added lscpu log, in case it helps. This is a relatively beefy machine with AVX and AES-NI.

---

I'm attaching my zpool/dataset config in case this rings any bell to anyone.

zfs-get-all.txt
zpool-get-all.txt
smartctl.log
lscpu.log

[rincebrain]

My guess, offhand, would be Transmission starting to seed something, and you seeing horrific amplification effects from a mismatch between how torrents work and how ZFS works.

You've got recordsize=1M. Torrents are chunked up into pieces, and even if you pick a larger piece size for it to hash over, I believe it still chops those IOs up into smaller segments to read and write, and that only controls the size that it's hashing - e.g. how many hashes it has to include in the torrent file.

And if you do a read, it has to read the entire record.

So even if transmission thinks it's only reading 4 MB/s, if it's over 1000 4k sections of the torrent, that's suddenly 4 GB/s instead. Oopsie.

[nadiamoe]

--kallsyms=/proc/kallsyms is a very useful flag, thank you!
It seems to be kfpu stuff followed by aes, so I guess it's just read overhead after all.

I'm a bit surprised to see kfpu in there though, I had expected checksums to use integer operations. Is the symbol overloaded perhaps? Or an instrumentation artifact?

10 MiB/s according to the application side or e.g. iostat?

That's container_fs_reads_bytes_total, which I would guess (haven't gone to check) that it's closer to Iostat. It's definitely not transmission's.

Thinking about it, I also have historical data from zfs metrics:

node_zfs_zpool_dataset_nread is the prometheus equivalent of kstat.zfs.misc.objset.nread.

Which again shows little change in overall usage hasn't gone up.

I would submit that it's unlikely this changed with nothing changing, and the most likely thing if you are very certain the software stack didn't change was the requests for chunks to transmission from other people.

Yeah, I think this is the only explanation available. It throws me a bit off that a change in behavior that does not seem to be visible in throughput is visible in CPU though.

[nadiamoe]

For completeness, here's a chart showing CPU usage for the node (🟢 green), IO throughput for the application as measured by the container runtime (🟡 yellow), and IO throughput for the dataset the container is accessing to as measured by zfs (node_zfs_zpool_dataset_nread + _write) (🔵 blue)

I'm pretty sure this is not a ZFS bug or problem, and that the application must be doing something to cause this increase, but for the life of me I cannot think what would cause this increase.

[rincebrain]

They are using integer operations, but the same sort of locking and save/restore is used for floating point and any kind of SIMD instructions.

[nadiamoe]

Makes sense, thanks for the insight!

I've been digging a bit more on the transmission side and identified one particular torrent with a fair amount of files that, when paused, makes CPU usage go down. I'm honestly not sure what's happening there, but if I had to guess I'd say that having so many popular but distinct files messes with caching/prefetching somehow, thus needing to go to disk more often.

It doesn't sound very convincing but it's the best I've figured.

Either way, if this CPU usage is considered normal for the workload, I guess everything is fine on the ZFS side and not much can be done about that.

Thanks again @rincebrain for your insight, I really appreciate it!

[rincebrain]

It's not even that it messes with it, but like, if you're reading 500 files, and it's having to read and keep 1M sections at a time in memory, then jumping around to ~random chunks basically never hits prefetch or your cache unless the whole thing fits in memory and is all you're doing.

Torrents treat files, AIUI, as basically if the end of one file was followed by the start of the next, for chunking purposes, like if you tarred things up, except if it's, say, Internet Archive or something that adds padding files of 0s to the end chunk of each file so that you don't have that overlap interaction in determining chunks are intact or not.