oxidecomputer / oxidecomputer/crucible
Lock contention during `iodriver` runs
@faithanalog is already working on this.
Since Jun 5, 2024.
- Dominant language
- Rust
- Stars
- 260
- Forks
- 34
- Avg merge
- 2d 1h
- Merged PRs (30d)
- 8
Description
Flamegraphs from iodriver 4K random writes show significant amounts of time being spent in kernel mutex spinlocks, e.g.
(interactive, originally from this run)
Lockstat shows two stacks (on the same lock) being responsible for 63% of total lock time:
Count indv cuml rcnt nsec Hottest Lock Caller
902020 35% 35% 0.00 191379 0xfffffcfa2064cca0 taskq_thread+0x2cd
-------------------------------------------------------------------------------
Count indv cuml rcnt nsec Hottest Lock Caller
789689 30% 65% 0.00 197303 0xfffffcfa2064cca0 cv_wait+0x78
(histograms elided)
We can use mdb to find which taskq is at fault here. (The system has been rebooted since the above capture, so I ran lockstat -W -Ch sleep 5 to get the current address)
BRM42220030 # head -n10 lockstat.txt
Adaptive mutex spin: 21566 events in 5.019 seconds (4297 events/sec)
-------------------------------------------------------------------------------
Count indv cuml rcnt nsec Hottest Lock Caller
6838 32% 32% 0.00 197362 0xfffffd02ce540be0 cv_wait+0x78
nsec ------ Time Distribution ------ count Stack
256 | 9 taskq_thread_wait+0xbe
512 | 112 taskq_thread+0x334
BRM42220030 # mdb -k
Loading modules: [ unix genunix specfs dtrace mac cpu.generic apix cpc crypto mm random smbios zfs sata ip hook neti sockfs lofs vmm scsi_vhci arp ufs ipcc logindmux nsmb ptm ]
> 0xfffffd02ce540be0::whatis
fffffd02ce540be0 is fffffd02ce540bc0+20, allocated from taskq_cache
> fffffd02ce540bc0::print taskq_t tq_name
tq_name = [ "dp_sync_taskq" ]
This taskq was created with
/*
* This determines the number of threads used by the dp_sync_taskq.
*/
int zfs_sync_taskq_batch_pct = 75;
// ...
dp->dp_sync_taskq = taskq_create("dp_sync_taskq",
zfs_sync_taskq_batch_pct, minclsyspri, 1, INT_MAX,
TASKQ_THREADS_CPU_PCT);
i.e. creating 0.75 * NUM_CPUS threads. We can confirm in mdb:
> fffffd02ce540bc0::print taskq_t tq_nthreads
tq_nthreads = 0x60
This is probably Too Many Threads, falling into the same category illumos#16202 (i.e. defaults that seem reasonable for normal computers, but not for a Big Computer).
OpenZFS has changed this behavior: https://github.com/openzfs/zfs/commit/3bd4df3841529316e5145590cc67076467b6abb7
We can locally tweak this behavior using the SP to hold a kernel configuration fragment, i.e.
sed -i '/^\*/d; /^$/d' /etc/system
echo set zfs:zfs_sync_taskq_batch_pct = 50 >> /etc/system
/usr/platform/oxide/bin/ipcc keyset -c system /etc/system
(then rebooting the Gimlet)
We can change it persistently by editing gimlet-system-zfs:dbuf
@faithanalog I think it would be interesting to do an iodriver run with a reduced zfs_sync_taskq_batch_pct and see what happens!
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Assessment
This issue has not been assessed yet.