Large number of stored certificates correlated with hanging API requests

[augustuswm]

After the release of R15 onto rack 3 (colo) we noticed that external API requests would periodically hang for ~8-10s before responding. While debugging this we realized that our certificate automation (cassette) was incorrectly pilling up certificates as it was failing to identify when it had successfully installed new certificates. This lead to ~10k certificates being stored in the database.

We know that the background task that reads and parses the certificates selects all non-deleted certificates, parses them, and stores them in memory for later use when selecting which certificates to use. We also know that removing all of the extraneous certificates from the database has resulted in API requests to no longer periodically hang for 8-10s.

We do not know the casual link (assuming there is one) between these two, but we suspect based on statemaps and speculative tracing from @bcantrill that we are spending a lot of CPU time on this. It is unclear why this would block serving a request and we will need further research to determine a root cause.

We do not believe R15 had any impact on this, and it was only coincidental in timing. We should be able to debug this on dev systems now with more tooling that we have available at the moment on rack 3

[davepacheco]

Summary

This problem now appears to be well-understood. I'll post more details in subsequent comments. The summary is that chain of blocked tasks here looks like this:

• The HTTP request (or, really, any Nexus database consumer) is blocked on qorb waiting for a claim (a database connection from the pool).
• In attempting to get the claim, the qorb pool makes requests (sends message over a channel, waits for response) to the task operating the per-backend connection sets.
• The task responsible for responding to that request is sitting in a tokio worker thread's lifo slot, ready to run as soon as the current task completes, but blocked behind whatever is currently running on that worker.
• The task currently running on that worker (the ExternalEndpoints background task) runs for 10 seconds at a time (on-CPU)

This hinges on the lifo slot behavior: this is a tokio optimization where, while executing some task A, a worker thread wakes up some other task B, instead of putting B onto either a local or global queue of ready-to-run tasks, it gets put directly in a LIFO (last-in-first-out) slot tied to the current worker. After finishing running task A, if there's something in the LIFO slot, it runs that before checking other queues. This behavior is described in the documentation. Our problem here is that task A is on-CPU for a good 10 seconds after it woke up task B, and the rest of the world is waiting on task B to run. Critically, unlike tasks that are queued elsewhere, runnable tasks in the lifo slot are not stealable by other workers.

(If it sounds improbable that the task we absolutely need to run is always stuck in the lifo slot of the worker that's running some other task for ages: it's not a coincidence. The background task grabs a claim, does some database queries, then drops the claim. It's that very action that wakes up the task that processes claims being released. And waking up another task is what causes tokio to put it into the lifo slot of the current worker, in hopes that that will help it be executed sooner than it otherwise would. The connection between these two tasks is why one gets stuck behind the other, even though one does not depend on the other.)

The problem appears to affect all database consumers in Nexus, not just one or just HTTP requests. That's just about everything: authentication, authorization, saga execution, etc. all touch the database. This behavior was very evident in statemaps of both CPU states and tokio task states. While the problem was ongoing, virtually no work was being done on any CPU or any other tokio task. When we disabled lifo altogether, not only did HTTP requests complete quickly but we observed work happening on various CPUs and in various tasks even while ExternalEndpoints was on-CPU.

[davepacheco]

Quite a lot of people worked on this investigation! Please jump in where I've got anything wrong @bcantrill @hawkw @augustuswm @jgallagher @smklein @papertigers @jmpesp (and sorry for who I've forgotten)

Initial observations

After the R15 upgrade on the colo system, folks noticed:

• The web console was at times sluggish.
• After a sled was expunged, some of the Crucible replacement sagas were stuck.

The saga issues are documented elsewhere. They're likely caused in part by this issue, but they're not necessary to see this issue or understand it.

The in-browser debugging tools were able to show that while many of the console's HTTP requests were quick, some would get stuck and take upwards of 8 seconds to complete.

Background

External endpoints task

For each operator-configured silo, there is an external DNS name that serves the API for that silo. Each silo thus has its own TLS certificates. Now, all silos' DNS names resolve to the same IPs -- those of Nexus. Nexus then uses a combination of TLS SNI and HTTP information ("host" header in v1, authority in v2) to determine for an incoming request (1) which TLS certificates to serve and (2) which silo the request is aimed at. (The silo winds up being an implicit parameter for all API requests.)

To figure all this out, a Nexus background task runs periodically (every 60 seconds) and on-demand (when needed) to compile a data structure describing the set of DNS names and associated TLS certificates:

omicron/nexus/src/app/background/tasks/external_endpoints.rs

Line 45 in c7d52ab

let result = read_all_endpoints(&self.datastore, opctx).await;

It makes this structure available to the rest of Nexus via a watch channel:

omicron/nexus/src/app/background/tasks/external_endpoints.rs

Line 31 in c7d52ab

tx: watch::Sender<Option<ExternalEndpoints>>,

This channel is consumed by a NexusCertResolver:

omicron/nexus/src/app/mod.rs

Lines 620 to 623 in c7d52ab

	.with_cert_resolver(Arc::new(NexusCertResolver::new(
	self.log.new(o!("component" => "NexusCertResolver")),
	self.background_tasks_internal.external_endpoints.clone(),
	)));

That's used for all incoming TLS requests to determine which TLS certificate to use:

omicron/nexus/src/app/external_endpoints.rs

Lines 553 to 566 in c7d52ab

	/// TLS SNI certificate resolver for use with rustls/Dropshot
	///
	/// This object exists to impl `rustls::server::ResolvesServerCert`. This
	/// object looks at an incoming TLS session's SNI field, matches it against the
	/// latest `ExternalEndpoints` configuration (available via a watch channel),
	/// and then determines which certificate (if any) to provide for the new
	/// session.
	///
	/// See the module-level comment for more details.
	#[derive(Debug)]
	pub struct NexusCertResolver {
	log: slog::Logger,
	config_rx: watch::Receiver<Option<ExternalEndpoints>>,
	}

The whole idea here is to minimize request path latency (and contention) by computing this structure in the background. When a request arrives, it's very quick to look up the information we need in this structure.

Qorb pools and sets

Qorb is our connection pooling library. Among other things, it's used to manage Nexus's connections to the database. All one really needs to know here is:

• Virtually everything Nexus does involves the database (including authentication, authorization, saga execution, etc.)
• All uses of the database require acquiring a claim, a connection to the database, from the qorb pool.
• For our database, the pool knows about five distinct backends (five distinct CockroachDB nodes).
• For each of the five backends, Qorb maintains a separate slot set that tracks all connections to the backend.

What's going on

A critical factor identified early is that this system was configured with 10,000 TLS certificates, which is far more than we normally expect to see. This was a mistake in automation, but obviously shouldn't have caused this problem.

When the background task is not running, everything appears to be working fine.

When the background task is activated:

• The task takes over 10s to complete, nearly all on-CPU time, nearly all of it parsing these TLS certificates. There are no database connections held nor locks held during the parsing.
• During this time, there's virtually no activity in any other threads or tokio tasks.
• Any attempt to access the database while this is happening gets stuck until the task completes. This includes most incoming HTTP requests. (We found that some requests that do not attempt to authenticate do complete during this window. That makes sense, since they don't touch the database.)

And here's what's going on:

1. Initially, all is fine.
2. The background task is activated and starts running on tokio worker thread T. The task runs a bunch of datastore operations that individually claim a database connection, make one or more queries, and then release the claim (the database connection) when the connection gets dropped. For reasons I'll explain below, we can assume this happens once, even though it might happen a bunch of times.
3. When the claim is released, the qorb task responsible for processing released claims becomes runnable. tokio puts it into worker thread T's LIFO slot, in hopes that can be executed sooner than it would be if it went into some other run queue.
4. The background task continues to execute, starting to parse its 10,000 TLS certificates.
5. Meanwhile, an HTTP request arrives and starts being processed normally: TLS session establishment, dropshot routing, etc. When it comes time to authenticate the request, it tries to acquire a claim from the database qorb pool.
6. Inside qorb, acquiring a claim from the pool makes requests to separate tokio tasks for each backend to see if any one has a claim available. If we get lucky and hit a backend other than the one whose task is sitting in T's LIFO slot, then this could return early with a claim. Eventually, a consumer will arrive that won't get lucky. It will block waiting for the released claim to be processed.
7. This is where we get stuck for a prolonged period. In this state: the HTTP request is blocked on getting a claim, getting a claim is blocked on hearing from one of the sets, hearing from one of the sets is blocked on processing the released claim, processing the released claim is blocked on worker thread T getting to its LIFO slot, and that's blocked on the task that's currentely running on T.
8. Eventually, though, the background task completes. T then runs what's in its LIFO slot, the claim is released, the HTTP request's claim is satisfied, and then the request completes normally.
9. All of this repeats about every 60 seconds.

Above, I glossed over the fact that we actually acquire and release claims several times in the background task. Why doesn't this deadlock? I suspect that for all but the last one of these, the background task does run into the same trouble acquiring a claim, so then blocks, allowing the LIFO slot to be run to process the claim release. (That may well put the background task back into the LIFO slot, causing it to be run next. This is the very ping-ponging between tasks that the LIFO slot is intended to optimize.) Anyway, these cases don't matter. You can consider that all of the above happens only with the very last claim released.

Also, there are many little variations on this (e.g., maybe it wasn't authn where the HTTP request hit this problem, or maybe it wasn't an HTTP request at all), but they're all pretty similar.

FAQs

We had noticed early on that the slow requests correlated with heavy on-CPU activity in one tokio task. We were left with two main questions that we're now able to answer:

What was the HTTP request stuck on? The HTTP request was blocked on acquiring a database claim.

How did the on-CPU background task block claim acquisition? Why did it affect all backends? (Shouldn't we have just handed out a connection to a different backend than the task was using?) Because the problem here was never that qorb didn't have a claim; rather, qorb assumes (reasonably) that it can make requests to each of its slot sets and get an answer promptly. It's that the task for one of those slot sets was not being run, in turn because of the LIFO slot problem.

10 seconds on-CPU?! Why are we doing so much work in an async task instead of the blocking pool or something? The short version is: we didn't expect this to be taking so long in practice, and if it did, well: we have 128 cores on this system and only one can be doing this work. It didn't seem like it should be a problem to have one of them busy doing this.

Why doesn't tokio run this task somewhere else? It should. This is a known issue.

Severity

This problem was deemed low severity (and not a blocker for R15) once it was determined to be related to having 10,000 TLS certificates.

• We're not aware of deployments intending to have nearly that many (including this deployment).
• It's not a regression.
• This behavior won't break an existing workload -- it can only be seen by adding a bunch of TLS certificates. It could be a blocker for a certain kind of new deployment (e.g., a customer newly wanting to deploy lots of silos).

Fixes / workarounds

The primary fix for now is to disable the LIFO optimization in tokio. That's sufficient to resolve this issue for us and may well resolve many other latency bubbles that we haven't noticed. We expect the downside to be negligible for our workload. Our workload is not sensitive to increased latency on the order of a scheduler operation.

Lots of other suggestions have been made to improve this situation. These aren't bad ideas but aren't necessarily worth prioritizing either:

• External endpoints could cache parsed certificates instead of re-parsing them each time. With this issue fixed by other means, the main problem this solves is reduced ambient control plane CPU utilization.
• Move the TLS certificate parsing to a blocking task. Starvation from tasks that hog the CPU is a well-known problem with cooperative multi-tasking. It's generally recommended to put CPU-heavy work into a separate thread pool of some kind. This could make sense when heavy CPU consumers are unusual and readily identifiable. We could certainly do that here. However, this is an extreme case of a pretty common pattern, which is processing a variable-length amount of input, when processing each item is itself fairly quick. This pattern appears all over our code: reading and parsing HTTP, reading and parsing JSON, processing data sent to the database or returned from the database, etc. It's not that obvious where this line should be drawn. And if we punt more than a few things out, then we have to manage the size and scheduling issues (including starvation!) of the pool we're punting this work out, too. Which brings one back to: if this is going to be running in some thread, and we have as many worker threads as CPUs, what's better about running it in a thread outside of the worker thread pool?

In terms of observability:

• instrumentation for tokio task execution, integration into Nexus (instrumental in root-causing this problem)
• on top of that, it would be incredibly useful to have a probe for task-wakeup that tells you when a tokio task wakes up another task
• qorb instrumentation improvements
• qorb uses tracing for logging but we have no way to get this information out of deployed systems
• nexus could use more DTrace probes #8424
• need better facilities for post hoc debugging of slow API requests in production
• it sure would have been helpful if we could look at tokio tasks and their states from core files
• it'd be really useful to have microstates for:
  • tokio tasks (runnable/running/blocked or something?)
  • qorb connections (dead/connecting/claimed/recycling/ready/etc)
  • Nexus HTTP requests

Investigation details coming

I hope to post more here with details about the investigation itself and the data we collected.

[hawkw]

For more details on the LIFO slot optimization and the problems it has caused for others, see also:

• Tokio's documentation for the feature and how to disable it
• rt: Tolerate slow task polls tokio-rs/tokio#6315 (comment)
• rt: make the LIFO slot in the multi-threaded scheduler stealable tokio-rs/tokio#4941

[davepacheco]

Investigation

I wanted to share the chain of questions and answers that led to the diagnosis here, along with the D scripts we used and their output. This is mainly for people that are curious about the debugging process or the tools and also for our future selves if we wind up facing a similar issue. Unfortunately, this information is somewhat scattered across chat, transcripts, and whatever I remembered to save along the way so this summary is a bit rambling and incomplete. I've included some timing notes just in case anybody winds up digging into recordings. For folks at Oxide, also see @augustuswm's notes in oxidecomputer/colo#120. What follows is not all chronological. I will attach all the D scripts and data I have as a ZIP file.

First steps

This all started on 2025-06-11. By 11:47am PT, the R15 update was complete (having run into a small hiccup where schema migration timed out due to an unexpectedly huge table). Console sluggishness was first reported around 1:26pm, then we kicked off the sled expungement, and quickly (by 1:33pm) started seeing an internal API request timeout and saga errors due to failure to acquire database claims. We spent some time digging into the saga stuff but I'm going to ignore that here.

The sluggishness was soon better characterized in the way described above: many requests were quick, but sometimes they would take upwards of 8 seconds. When reloading the page (which makes many requests over a few seconds) and looking at the dev tools, it was common to see a lot of requests complete successfully, then they'd get stuck.

We looked at one of these slow requests from the Nexus log and observed:

• the reported request latency was over 9s (this rules out many client-side issues or queueing outside of Nexus, either before the request started or after the request completed)
• all of the log entries for the request took place in the last 120ms before the request was marked completed (this rules out most of the operations that most requests do)

Having seen the claim acquisition errors, we wondered if it was taking a long time getting a database connection from the qorb pool. We verified that Nexus had about the same number of connections as we see on dogfood, which was slightly more than we expected from code inspection (20 per Nexus instead of 16), but not obviously a problem. We did this with SQL like this one, but this output is from dogfood, not colo:

root@[fd00:1122:3344:105::3]:32221/omicron> with x as (show sessions), y as (select left(client_address, length(client_address) - position(':' in reverse(client_address))) as ip from x) select ip,count(*) from y group by ip;
            ip            | count
--------------------------+--------
  [fd00:1122:3344:104::3] |    20
  [fd00:1122:3344:102::3] |    20
  [fd00:1122:3344:103::3] |    20
  [fd00:1122:3344:105::3] |     2
(4 rows)

I wondered whether a change in the release altered the indexes in a way that was causing the authn queries to behave terribly. We checked with EXPLAIN ANALYZE, but the query was very quick.

We did look at database query times and found that these latencies couldn't obviously explain this. This was confirmed later via queries-during-slow-window.d and queries-during-slow-window.out. The longest ones here are between 500ms to 1s, and there were only two of these out of thousands of queries.

Focusing on qorb

Sean suggested using the qorb probes to see how long it's taking to get claims. We iterated on some one-liners, but I don't have real scripts and data until later in the evening. We did try tracing the stack traces that were releasing long-held claims, but they weren't useful because these probes fire in the qorb task, not the code that released the claim.

We iterated a bit on tracing qorb. That's claims*.d and claims*.out. John noticed from code inspection that we hold an extra claim when reading the latest inventory collection, but we couldn't understand why that would cause much of a problem since we have way more than two connections.

Around 5:20pm PT, I summarized these questions:

• "Are the long database claim times we're looking at responsible for the long console HTTP requests? I don't know how clear this is, especially since we saw some 8+s claim times when we weren't making HTTP requests."
• "How long are claims being held? Is that very different from how long it takes to acquire one (i.e., shorter)? How often are things queueing up for the claims? How long are they waiting for one?"
• "How can we get a stack trace for the code path that's actually acquiring/dropping the claims? the probes for claim-start/claim-done is asynchronous with respect to the thing that is actually trying to acquire the claim."
• "What else does this task that's handling the claim recycling do? Is it taking a while to handle the claim releases because it's busy doing something else?" [In retrospect, this was important: that task was taking a while to finish, but that was not its own fault. It was not being scheduled.]
• "Are the long claim times database claims or other qorb pools?"

and wrote: "if the request latency is tied to latency acquiring a claim, that would imply:

• all 16 claims are held for 8s (not necessarily individually; it could just be that there are a large number queued up ahead of this request, but there would have to be a solid 8s in which all claims were held essentially that whole time)
• the time spent by any claim that's held has to be split among:
  • time spent by the claimer making database queries
  • time spent by the claimer doing other random stuff
  • time spent in qorb from when the claim is released to when it's taken out again

Individual queries didn't seem to be taking that long. so either it's: things doing a lot of queries that add up, things doing other random stuff, or qorb taking a while to recycle it."

But mechanically, it wasn't clear:

• how to tie request activity to qorb claim activity
• how to tie qorb claim activity to which pool it's for
• how to tie query activity to qorb claim activity

Later, we put together qorb.d / qorb.out, which traces:

• the distribution of claim acquisition times (claim-start to claim-done)
• the distribution of claim hold times (handle-claimed to handle-returned)

At some point, we observed that it's pretty surprising that only one qorb claim was held for 8+ seconds, but 32 were blocked for 8+s. Besides that one long-held claim, other claim hold times were pretty short. It's conceivable that a large number of short holds added up but it seemed fishy. We tried to trace the number of in-use claims over time, but this proved a little tricky since we only had probes for claims acquired/released, so we only had relative counts. And it was also changing frequently.

Based on what we did manage to trace about connections in use, we never saw more than 9 connections in use. Between these two observations (that many more tasks were blocked for 8+s than held claims for 8s, and we only ever had 9 claims held at a time when there could be as many as 16), it seemed like Nexus shouldn't have been out of qorb connections during the period where it couldn't acquire a claim. "In tracing claim acquisitions that take over 6s, we see a whole pile of them complete at almost the same time, all having taken many seconds to acquire. Tracing all qorb DTrace probes: we see these multi-second blips during which basically nothing happens, then a whole pile of stuff happens (more than steady-state before)."

We wrote: "All of this sounds like qorb is maybe off doing something else in the actor that normally handles release/recycle/claims."

"If there's no activity then it's got to be one of:

• there's no load
• there's load but connections are all legitimately busy
• there is load and there are connections but we're not matching them up

We continued: "[We] should be able to distinguish (no load) from the other two. I think my next step will be to write a D script that traces a bunch of these events in a ringbuffer and then dumps them out when we see a pile of stuff finish that was waiting for a long time. What I hope to see is:

• enough "releases" not followed by acquires to convince us that there are connections available
• then a big gap
• then we satisfy the pile of claims"

I believe this is what led to qorb3.d / qorb3.out, qorb4.d / qorb4.out, and qorb5.d / qorb5.out, where we tried using the DTrace ringbuffer policy to record more detailed information in-memory and only dump it out when we hit the slow query.

I was postprocessing these with:

awk 'BEGIN { prev_time = $2 } { printf("%10d %s\n", $2 - prev_time, $0); prev_time = $2; }' < qorb4_data.txt > qorb4_post.txt

to add a time-since-previous-event column at the front of each line.

Finally, qorb6.d/qorb6.out contained a very strong data point:

17682    1399789 43889803395673 46548030664 handle-returned    id 10386 (believed in use: 5, waiting: -1, total seen: 16)
17683      10110 43889803405783 46548040774 recycle-start      id 472446408643 [fd00:1122:3344:109::3]:32221
17684     382830 43889803788613 46548423604 recycle-done       id 472446408643
17685   49758803 43889853547416 46598182407 claim-start        id 154618831716 (believed in use: 5, waiting: 0, total seen: 16)
17686    8487517 43889862034933 46606669924 claim-start        id 154618831717 (believed in use: 5, waiting: 1, total seen: 16)
17687     852766 43889862887699 46607522690 claim-start        id 154618831718 (believed in use: 5, waiting: 2, total seen: 16)
17688   94527680 43889957415379 46702050370 claim-start        id 154618831719 (believed in use: 5, waiting: 3, total seen: 16)
17689   46112110 43890003527489 46748162480 claim-start        id 154618831720 (believed in use: 5, waiting: 4, total seen: 16)
17690   40605637 43890044133126 46788768117 claim-start        id 154618831721 (believed in use: 5, waiting: 5, total seen: 16)
17691    1861741 43890045994867 46790629858 claim-start        id 154618831722 (believed in use: 5, waiting: 6, total seen: 16)
17692    6424191 43890052419058 46797054049 claim-start        id 154618831723 (believed in use: 5, waiting: 7, total seen: 16)
17693    5219685 43890057638743 46802273734 claim-start        id 154618831724 (believed in use: 5, waiting: 8, total seen: 16)
17694     850001 43890058488744 46803123735 claim-start        id 154618831725 (believed in use: 5, waiting: 9, total seen: 16)
17695   27284924 43890085773668 46830408659 claim-start        id 154618831726 (believed in use: 5, waiting: 10, total seen: 16)
17696   16079655 43890101853323 46846488314 claim-start        id 154618831727 (believed in use: 5, waiting: 11, total seen: 16)
17697   18199358 43890120052681 46864687672 claim-start        id 154618831728 (believed in use: 5, waiting: 12, total seen: 16)
17698   57637528 43890177690209 46922325200 claim-start        id 154618831729 (believed in use: 5, waiting: 13, total seen: 16)
17699    1864216 43890179554425 46924189416 claim-start        id 154618831730 (believed in use: 5, waiting: 14, total seen: 16)
17700   41025639 43890220580064 46965215055 claim-start        id 154618831731 (believed in use: 5, waiting: 15, total seen: 16)
17701    7203026 43890227783090 46972418081 claim-start        id 154618831732 (believed in use: 5, waiting: 16, total seen: 16)
17702   43279978 43890271063068 47015698059 claim-start        id 154618831733 (believed in use: 5, waiting: 17, total seen: 16)
17703  176738664 43890447801732 47192436723 claim-start        id 154618831734 (believed in use: 5, waiting: 18, total seen: 16)
17704   13694165 43890461495897 47206130888 claim-start        id 154618831735 (believed in use: 5, waiting: 19, total seen: 16)
17705   40496390 43890501992287 47246627278 claim-start        id 154618831736 (believed in use: 5, waiting: 20, total seen: 16)
17706   76562290 43890578554577 47323189568 claim-start        id 154618831737 (believed in use: 5, waiting: 21, total seen: 16)
17707   23924686 43890602479263 47347114254 claim-start        id 154618831738 (believed in use: 5, waiting: 22, total seen: 16)
17708  115539161 43890718018424 47462653415 claim-start        id 154618831739 (believed in use: 5, waiting: 23, total seen: 16)
17709   66498217 43890784516641 47529151632 claim-start        id 154618831740 (believed in use: 5, waiting: 24, total seen: 16)
17710    5054520 43890789571161 47534206152 claim-start        id 154618831741 (believed in use: 5, waiting: 25, total seen: 16)
17711   29772147 43890819343308 47563978299 claim-start        id 154618831742 (believed in use: 5, waiting: 26, total seen: 16)
17712  180533520 43890999876828 47744511819 claim-start        id 154618831743 (believed in use: 5, waiting: 27, total seen: 16)
17713   19564852 43891019441680 47764076671 claim-start        id 154618831744 (believed in use: 5, waiting: 28, total seen: 16)
17714  466232479 43891485674159 48230309150 claim-start        id 154618831745 (believed in use: 5, waiting: 29, total seen: 16)
17715  205982604 43891691656763 48436291754 claim-start        id 154618831746 (believed in use: 5, waiting: 30, total seen: 16)
17716 1348443759 43893040100522 49784735513 claim-start        id 154618831747 (believed in use: 5, waiting: 31, total seen: 16)
17717  865249213 43893905349735 50649984726 claim-start        id 154618831748 (believed in use: 5, waiting: 32, total seen: 16)
17718 1354548381 43895259898116 52004533107 claim-start        id 154618831749 (believed in use: 5, waiting: 33, total seen: 16)
17719    1035494 43895260933610 52005568601 claim-start        id 154618831750 (believed in use: 5, waiting: 34, total seen: 16)
17720  185403208 43895446336818 52190971809 claim-start        id 154618831751 (believed in use: 5, waiting: 35, total seen: 16)
17721  327253185 43895773590003 52518224994 health-check-start id 154618831752 [fd00:1122:3344:10f::3]:17000
17722    3249678 43895776839681 52521474672 connect-start      id 154618831753 [fd00:1122:3344:10f::3]:17000
17723      21931 43895776861612 52521496603 health-check-start id 472446408644 [fd00:1122:3344:10f::3]:17000
17724     725504 43895777587116 52522222107 health-check-done  id 472446408644
17725   76069600 43895853656716 52598291707 connect-done       id 154618831753
17726  504504496 43896358161212 53102796203 health-check-start id 472446408645 [fd00:1122:3344:10f::3]:17000
17727     607228 43896358768440 53103403431 health-check-done  id 472446408645
17728 1490900184 43897849668624 54594303615 claim-start        id 472446408646 (believed in use: 5, waiting: 36, total seen: 16)
17729      63270 43897849731894 54594366885 claim-start        id 94489281667 (believed in use: 5, waiting: 37, total seen: 16)
17730   45593260 43897895325154 54639960145 claim-start        id 154618831754 (believed in use: 5, waiting: 38, total seen: 16)
17731  187891913 43898083217067 54827852058 claim-start        id 472446408647 (believed in use: 5, waiting: 39, total seen: 16)
17732     101434 43898083318501 54827953492 claim-start        id 154618831755 (believed in use: 5, waiting: 40, total seen: 16)
17733 1298205221 43899381523722 56126158713 health-check-start id 94489281668 [fd00:1122:3344:119::3]:17000
17734     692751 43899382216473 56126851464 health-check-done  id 94489281668
17735   40090977 43899422307450 56166942441 claim-start        id 94489281669 (believed in use: 5, waiting: 41, total seen: 16)
17736  409676883 43899831984333 56576619324 claim-start        id 94489281670 (believed in use: 5, waiting: 42, total seen: 16)
17737   47278704 43899879263037 56623898028 claim-start        id 94489281671 (believed in use: 5, waiting: 43, total seen: 16)
17738  102612168 43899981875205 56726510196 claim-start        id 94489281672 (believed in use: 5, waiting: 44, total seen: 16)
17739  449530658 43900431405863 57176040854 handle-returned    id 10396 (believed in use: 4, waiting: 44, total seen: 16)
17740      26390 43900431432253 57176067244 handle-claimed     id 10397 ([fd00:1122:3344:11f::3]:32221) (believed in use: 5, waiting: 44, total seen: 16)
17741      63010 43900431495263 57176130254 recycle-start      id 489626280206 [fd00:1122:3344:11f::3]:32221
17742     899686 43900432394949 57177029940 recycle-done       id 489626280206
17743      21481 43900432416430 57177051421 handle-claimed     id 10409 ([fd00:1122:3344:105::3]:32221) (believed in use: 6, waiting: 44, total seen: 16)
17744       6553 43900432422983 57177057974 claim-done         id 154618831716 (believed in use: 6, waiting: 43, total seen: 16)
17745       6552 43900432429535 57177064526 claim-done         154618831716 long claim: 10578ms
17746     771401 43900433200936 57177835927 handle-claimed     id 10410 ([fd00:1122:3344:102::3]:32221) (believed in use: 7, waiting: 43, total seen: 16)
17747      44124 43900433245060 57177880051 claim-done         id 154618831717 (believed in use: 7, waiting: 42, total seen: 16)
17748       6853 43900433251913 57177886904 claim-done         154618831717 long claim: 10571ms
17749     774257 43900434026170 57178661161 handle-claimed     id 10379 ([fd00:1122:3344:116::3]:32221) (believed in use: 8, waiting: 42, total seen: 16)
17750      28454 43900434054624 57178689615 claim-done         id 154618831718 (believed in use: 8, waiting: 41, total seen: 16)
17751       1794 43900434056418 57178691409 claim-done         154618831718 long claim: 10571ms
17752      95842 43900434152260 57178787251 handle-returned    id 10397 (believed in use: 7, waiting: 41, total seen: 16)
17753      18616 43900434170876 57178805867 recycle-start      id 472446408648 [fd00:1122:3344:11f::3]:32221

The columns there are: line number in the output file, delta in ns from the previous line (added by my postprocessing step), timestamp (gethrtime), timestamp delta from the beginning of the file, probe name, "id", and then an id. The ids for the start/done pairs are generally unique to the pair. The ids for handle-returned/handle-claimed identify the connection.

There are two big limitations with this data: first, we didn't have a way to match up these two kinds of ids. For claim-start/claim-done, we can't match that up with handle-claimed/handle-returned, or recycle-start/recycle-done. We do have the addresses of the backends involved, but there can be many connections for each backend, so that's not specific enough. Second, we could even be looking at data from multiple qorb pools (including some unrelated to the database). (Sean later confirmed that indeed that was happening here.)

Limitations aside, here's the smoke, if not the fire:

• At L17682, we have basically a steady state: we've returned a handle to the pool, we believe that 5 are still in use, and there are zero things trying to acquire a claim. (It says -1, but we convinced ourselves this resulted from a dropped increment because x++ in D is not atomic. We saw this convincingly earlier in the file where we had a pair of claim-start events a few nanoseconds apart where waiting did not increment.)
• We recycle that connection promptly, but there's nothing else waiting for it, so there's nothing to do.
• 49.7ms later, at L17685 something tries to make a claim. Then another 34 claims come in. There's good reason to believe we have connections available to give these, but we don't. More later.
• At L17721 we start doing some health checking, one of which establishes a connection, but this doesn't seem relevant. Then we get a few more claims, a few more health checks, etc.
• At this point, from about L17685 to L17739 (which is about 10s), we seem to have a lot of things trying to make claims and some connections, but we're not doing anything.
• At L17739, which is 10.6 seconds after L17682 (the start of my summary), things get uncorked. A connection gets returned. It appears to get recycled, then claimed, and that wakes up our claim that's been waiting for 10.8s.
• Immediately, a bunch more claims become satisfied -- we quickly see "believed in use" rise up to 8 (and further). There's been at most one connection created this whole time, yet we've satisfied 3 claims.

The reason it seems like we had connections but weren't giving them out is that we did give out a bunch after L17739, even though no new ones appear to have been created. The other reason is that we think qorb should be maintaining more than 5 connections to CockroachDB.

Even if we're looking at data from multiple pools, it remains true that starting at L17745, qorb satisfied 3 claims in a row that had been waiting for over 10s with only one recent handle-returned and no new claim-starts, so it sure looks like it satisfied them with connections that had already been present for a while.

This seems to clearly show that qorb had connections available for several seconds while claims were not being acquired.

We picked this up again on Thursday morning 6/12, writing:

"Assuming to start with that it's only one problem, it could be:

• Nexus is legitimately out of connections because consumers are holding them for long periods (this seems to conflict with the DTrace data we collected in qorb6.d, but of course it's possible that's wrong or we interpreted it wrong).
  • They're holding them for long periods because their database queries are slow (I think we ruled this out but if we can trace this again we can be sure)
  • They're holding them for long periods because they're doing a large number of queries, even though they're fast queries.
  • They're holding them for long periods because they're doing a bunch of Rust stuff.
• We're out of connections because qorb isn't making/keeping enough (or isn't able to) (again, it seems to conflict with the DTrace data).
• We have connections but aren't handing them out (seems to be what the data is showing)
  • They're not ready to be handed out
  • Missed wakeup?
  • ???"

[This decomposition was right, but the answer was in the "???" bucket: qorb isn't getting on-CPU to handle these releases.]

We double-checked the actual query times (this is when we collected queries-during-slow-window.out). This ruled out slow queries during claim establishment. qorb6.out ruled out slowness during healthcheck / recycle.

Around this time I was really wishing we had tokio task information in these other probes to better correlate claim activity with request activity and database activity. I started looking at how to identify which thread is running which tasks. I didn't get very far doing this on uninstrumented systems. @hawkw later picked this up in https://github.com/oxidecomputer/tokio-dtrace/. This wound up being huge later, but wasn't usable at this point since it required a code change.

@bcantrill started looking at statemaps, first in dogfood and then in colo. This yielded some important results in spec.d / spec.out. This showed the ExternalEndpoints background task on-CPU for 10+ seconds at a time. @augustuswm quickly identified that we had an enormous number of TLS certificates in this system. That explains that task taking a while, but it wasn't clear how this would affect HTTP requests.

@hawkw noticed the use of watch::Sender::send_replace and wondered if that was holding onto the lock while memcpy`'ing a ton of data, but we didn't see that in any of the stacks.

@augustuswm removed all the extra certificates and the problem went away. It seemed pretty clear that the problem was related to having lots of TLS certificates, though the full mechanism was not understood. We declared this not an R15 regression and planned to reproduce the problem on a dev system for further debugging.

Aside on dogfood

It wasn't until Wednesday 6/18 that I picked this up again. I looked in dogfood first because @bcantrill had observed a similar problem there (tasks being on-CPU for hundreds of milliseconds). However, I found that this seemed to be a different problem (if maybe related). I did not see ExternalEndpoints show up in tasks running on-CPU for a while. I saw a bunch of different background tasks calling sled_client_for_address(), which called X509_STORE_set_default_paths_ex(), which was parsing the system certificate chain. A lot of time was spent acquiring/releasing some locks in OpenSSL. There's probably something to look into here, and several suggestions were made, but it's not obviously the same thing.

Reproducing on dublin

I was able to reproduce this on dublin pretty easily.

First, I used rkadm to set up dublin with commit b49d105 (from #8364) so that I would have the new tokio probes.

I created a TLS certificate using:

$ ./target/debug/cert-dev create dublin-test- '*.sys.dublin.eng.oxide.computer'
wrote certificate to dublin-test-cert.pem
wrote private key to dublin-test-key.pem

I created a new silo using the console, using this TLS certificate.

I created a silo admin user in that silo:

$ cat user.json 
{
  "external_id": "dap",
  "password": {
    "mode": "password",
    "value": "oxide"
  }
}

$ cat policy.json 
{
  "role_assignments": [{
    "identity_id": "29159f66-0bc1-42cd-a48d-eb68d84f3bea",
    "identity_type": "silo_user",
    "role_name": "admin"
  }]
}


$ oxide --profile recovery5 silo idp local user create --silo lotsa-certs --json-body user.json
{
  "display_name": "dap",
  "id": "29159f66-0bc1-42cd-a48d-eb68d84f3bea",
  "silo_id": "7e5b2c6c-1fc9-4fbe-8317-668625f15ef7"
}

$ oxide --profile recovery5 silo policy update --silo lotsa-certs --json-body policy.json
{
  "role_assignments": [
    {
      "identity_id": "29159f66-0bc1-42cd-a48d-eb68d84f3bea",
      "identity_type": "silo_user",
      "role_name": "admin"
    }
  ]
}

I authenticated to the new silo with the CLI using:

$ oxide --insecure --resolve lotsa-certs.sys.dublin.eng.oxide.computer:443:172.20.29.3 auth login --host https://lotsa-certs.sys.dublin.eng.oxide.computer

I found some old instructions for adding TLS certificates using the CLI. First, I processed them like this:

$ jq -Rs . < dublin-test-cert.pem > cert.txt
$ jq -Rs . < dublin-test-key.pem > key.txt

Then I uploaded them in a loop like this:

$ for i in $(seq 2 1000); do oxide --profile lotsa-certs --insecure --resolve lotsa-certs.sys.dublin.eng.oxide.computer:443:172.20.29.3 api /v1/certificates -X POST --input - <<EOF
{
    "description": "dummy",
    "name": "dummy$i",
    "service": "external_api",
    "cert": $(cat cert.txt),
  "key": $(cat key.txt)
}
EOF
 echo $i; done

It got through 800 in about 8 minutes, but slowed down. It took a few hours to get to 10,000. But once it did, I had the same behavior that we saw in colo.

Analyzing behavior on dublin

I wondered whether somehow the problem was happening during TLS negotiation, for two reasons:

1. ExternalEndpoints computes that data structure and was also obviously doing a bunch of stuff in OpenSSL. So if there were locks held or something, maybe that could cause this?
2. That would explain why all the time was spent at the end of the 9s request latency.

An easy experiment ruled this out: requests made with curl with no authentication credentials (i.e., no authorization header) were always fast, even during the 9+s when requests with authentication credentials would get stuck. Further, providing bogus authn credentials didn't affect whether the request took a long time. This makes sense if the problem is getting a database claim because the database is used for authentication.

The root problem at this point was that we knew tasks handling these HTTP requests were going off-CPU for a long time but we couldn't figure out why. All the tools we had for this for threaded systems -- e.g., sched:::wakeup/sched:::on-cpu/sched:::off-cpu probes, saving a core file and looking with mdb, etc. -- are useless on async programs. Their new tokio analogs -- task-poll-start/task-poll-done -- were also not helpful for providing context because the nature of async Rust is that when a worker thread picks up a task (or puts one down), the stack is already unwound. The analog to grabbing a stack trace at sched:::off-cpu would be grabbing a stack trace from all Futures' poll() methods returning Poll::Pending. There's no common code involved, so no single place to trace. (It's interesting to think about having rustc insert probes for this, but far outside the scope of this problem.)

In a somewhat desperate attempt to figure out what these tasks were doing when they went off-CPU, I used the pid provider to trace all userland function entry/returns for functions with nexus in the name. I iterated on this a bunch -- these are the tasks*.d/tasks*.out scripts and outputs. I eventually landed on this sequence from tasks4.out:

34899708826 tid 100 taskid 717 <- pid21477:nexus: nexus_types::internal_api::views::CurrentStatus::unwrap_running::hc4e83bf8dd8ff9f8 :return
34901142615 tid 100 taskid 717 <- pid21477:nexus: omicron_nexus::app::background::driver::TaskExec::activate::{{closure}}::h6e38f20e4c2fd51b :return
        (that was a long time on-CPU)
34901160118 tid 100 taskid 717 stopped running after 10977 ms
        (that was a long time off-CPU)
34901176218 tid 100 taskid 137 now running after blocking for 10980 ms
34901196637 tid 100 taskid 137 -> pid21477:nexus: _ZN101_$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connector$GT$10on_acquire17h5740b3nexus :entry
34901201536 tid 100 taskid 137 <- pid21477:nexus: _ZN101_$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connector$GT$10on_acquire17h5740b3nexus :return
34901206676 tid 100 taskid 137 -> pid21477:nexus: _ZN101_$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connector$GT$10on_acquire28_$u7b$$nexus :entry
34901220482 tid 100 taskid 137 <- pid21477:nexus: _ZN101_$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connector$GT$10on_acquire28_$u7b$$nexus :return
34901237875 tid 100 taskid 137 stopped running after 0 ms
        (that was a long time off-CPU)
34901241181 tid 100 taskid 3819985 now running after blocking for 7161 ms
34901246752 tid 100 taskid 3819985 -> pid21477:nexus: _ZN101_$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connector$GT$8is_valid28_$u7b$$u7bnexus :entry
34901264966 tid 100 taskid 3819985 stopped running after 0 ms
34901839882 tid 100 taskid 3819985 now running after blocking for 0 ms
34901841816 tid 100 taskid 3819985 -> pid21477:nexus: _ZN101_$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connector$GT$8is_valid28_$u7b$$u7bnexus :entry
34901850963 tid 100 taskid 3819985 -> pid21477:nexus: _ZN4core3ptr1408drop_in_place$LT$$LT$async_bb8_diesel..connection..Connection$LT$diesel_dtrace..DTraceConnection$LT$diesel..pg..nexus :entry
34901855341 tid 100 taskid 3819985 <- pid21477:nexus: _ZN4core3ptr1408drop_in_place$LT$$LT$async_bb8_diesel..connection..Connection$LT$diesel_dtrace..DTraceConnection$LT$diesel..pg..nexus :return
34901866823 tid 100 taskid 3819985 stopped running after 0 ms
34902577666 tid 100 taskid 3819985 now running after blocking for 0 ms
34902579309 tid 100 taskid 3819985 -> pid21477:nexus: _ZN101_$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connector$GT$8is_valid28_$u7b$$u7bnexus :entry
34902583658 tid 100 taskid 3819985 -> pid21477:nexus: _ZN4core3ptr1408drop_in_place$LT$$LT$async_bb8_diesel..connection..Connection$LT$diesel_dtrace..DTraceConnection$LT$diesel..pg..nexus :entry
34902585751 tid 100 taskid 3819985 <- pid21477:nexus: _ZN4core3ptr1408drop_in_place$LT$$LT$async_bb8_diesel..connection..Connection$LT$diesel_dtrace..DTraceConnection$LT$diesel..pg..nexus :return
34902590781 tid 100 taskid 3819985 -> pid21477:nexus: _ZN4core3ptr160drop_in_place$LT$$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connectornexus :entry
34902594799 tid 100 taskid 3819985 <- pid21477:nexus: _ZN4core3ptr160drop_in_place$LT$$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connectornexus :return
34902599718 tid 100 taskid 3819985 stopped running after 0 ms
34902777935 tid 100 taskid 137 now running after blocking for 1 ms
34902779508 tid 100 taskid 137 -> pid21477:nexus: _ZN101_$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connector$GT$10on_acquire28_$u7b$$nexus :entry
34902786942 tid 100 taskid 137 -> pid21477:nexus: _ZN4core3ptr159drop_in_place$LT$$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connectornexus :entry
34902790098 tid 100 taskid 137 <- pid21477:nexus: _ZN4core3ptr159drop_in_place$LT$$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connectornexus :return
34902792472 tid 100 taskid 137 <- pid21477:nexus: _ZN101_$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connector$GT$10on_acquire28_$u7b$$nexus :return
34902795798 tid 100 taskid 137 -> pid21477:nexus: _ZN4core3ptr162drop_in_place$LT$$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connectornexus :entry
34902799185 tid 100 taskid 137 <- pid21477:nexus: _ZN4core3ptr162drop_in_place$LT$$LT$nexus_db_queries..db..pool_connection..DieselPgConnector$u20$as$u20$qorb..backend..Connectornexus :return

That sequence seems to show:

• task 717 (our high-CPU consumer) just finished running ExternalEndpoints for 10.9s
• the same thread picks up task 137, which seems to be a qorb task that seems to just run on_acquire and then hand the connection over to task 3819985, still on the same thread
• task 3819985 runs is-valid, fires a DTrace probe, then maybe drops the claim?
• taskid 137 runs again, runs drop_in_place on some qorb thing

I had noticed a similar pattern while we were debugging colo (namely: an on-CPU task runs for a while, then we pick up a task that had been off-CPU that whole time and run it). I thought it was noteworthy, but couldn't see how it related to this because it didn't seem like the task that got woken up did a whole lot of work. @smklein had observed earlier in the week that if qorb got stuck in on_acquire, that could cork up the pool. @jgallagher now noticed that the on_acquire call we see there might be quite critical -- that's the very thing we're waiting on to unblock the pool. @bcantrill suggested this looked like a work-stealing issue in way tasks were being scheduled. Several people looked at the work-stealing implementation in tokio. We went down a (potentially?) blind alley around the fact that work-stealing seems like it won't steal the sole task on a worker thread's queue. But we converged on the fact that there is no work stealing for tasks that are using the LIFO slot optimization. It was easy to try disabling this, confirming that that resolved the issue, and we landed at the complete explanation in the comment above.

[davepacheco]

The full set of data is 120 MiB zipped up and much too large for a GitHub attachment. For folks at Oxide, it's available at /staff/core/omicron-8334.

I have attached a smaller zip file called issue-8334-data-github.zip that contains almost all of the same stuff. It just leaves out the output files from tasks{2,3}.d. These were much more verbose and not especially critical.

[sambacha]

//! Pingora tokio runtime.
//!
//! Tokio runtime comes in two flavors: a single-threaded runtime
//! and a multi-threaded one which provides work stealing.
//! Benchmark shows that, compared to the single-threaded runtime, the multi-threaded one
//! has some overhead due to its more sophisticated work steal scheduling.
//!
//! This crate provides a third flavor: a multi-threaded runtime without work stealing.
//! This flavor is as efficient as the single-threaded runtime while allows the async
//! program to use multiple cores.

https://github.com/cloudflare/pingora/blob/main/pingora-runtime/src/lib.rs