Solitary USDT probe in a tokio::select! statement seems to cause other code in one select! arm to execute unexpectedly #86
Description
Propolis recently stumbled across what seems like a code generation issue in which putting a USDT probe (and only a USDT probe) in exactly the right place caused a function to careen down an unexpected path in a tokio::select! statement. We've worked around the issue in Propolis, but we need to investigate further to root-cause it, hence this tracking issue.
(I'm not certain whether this is a problem with USDT as such or an unfortunate interaction between USDT and the Rust build tools--we might investigate and find it's the latter. But USDT probes do seem to be involved somehow so I'm filing this in this repo for now.)
Most of the context, and a link to the actual code in question, is in propolis#292. It might be faster just to read that issue. Here, however, is some long-winded background:
Propolis has a tokio task that reads/writes bytes from/to a VM's virtual COM1 and from/to serial console clients connected over a websocket. The body of the task is mostly a large select! statement that handles input/output from these various sources. In psuedocode it looks like this:
1 loop {
2 // get a future that tries to read bytes from the guest
3 let read_fut = get_read_fut_from_uart();
4
5 // get some other futures/channels ready to go
6
7 tokio::select! {
8
9 // various other cases for new connections, handling
10 // writes, etc.
11
12 nread = read_fut => {
13 match nread {
14 Some(0) | None => {
15 probes::serial_task_read!(|| { 0 });
16 // channel was closed or an error occurred,
17 // exit the task
18 break;
19 }
20 Some(n) {
21 probes::serial_task_read!(|| { n });
22 // process bytes that were read
23 }
24 }
25 }
26 }
27 }The (Propolis equivalent) of the probe on line 15 has very strange behavior. If you build this code release, and this probe (and only this probe) is present in its match arm, then the serial task breaks out of the loop unexpectedly early. Any of the following changes make the loop behave as expected:
- building the code with the
devprofile - removing the probe entirely
- adding a
slog::info!logging statement at line 16 (this need not refer to the value of nread or indeed to any other variables; it can just print a message) - hoisting the probes on lines 15 and 21 out of the match
This Propolis commit implements this last option as a workaround and shows the actual code in its full glory.
I briefly rummaged through the output of cargo-show-asm with and without the offending probe in place, but quickly decided I was in over my head, since (a) I don't (yet) understand how DTrace probes work or how USDT constructs them, and (b) the only way I could find to get all the assembly and matched line numbers I needed was to generate asm for the entire propolis-server lib, which is massive and hard to rummage through at this level of detail.
I suspect the next step here is to try to minimize this somewhat: can we reproduce this with a simplified task that fakes out the UART and builds in its own small library? If so that should make it much easier to understand what's happening.