oxidecomputer / oxidecomputer/crucible

Lock contention during `iodriver` runs

Open
#1,337 6 comments 0 reactions 1 assignee View on GitHub

@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.

flamegraph-4krandw-londonBRM42220030-500ms-stack-ustack_16KiB
(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

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.