DTrace probes for IO on/off the network (#1284)

Put in DTrace probes for when a message is put on the wire to a
downstairs, and a corresponding probe when a message is pulled
off the wire from a downstairs.

Updated the README, and moved a few D scripts around.

Left the existing probes that were previously marking networking but had
drifted off to measuring something else where they were, but updated the
comments to reflect their new role.

Added a new D script, `perf-ds-net.d`, for the new probes. Moved the old
`perfdw.d` to be `perf-ds-client.d`.

---------

Co-authored-by: Alan Hanson <[email protected]>

tools/dtrace/README.md

@@ -82,18 +82,22 @@ queue of work for the three downstairs.
 IO that it is ready to ack.
 3: From the IO being ready to ack, to that ack being sent.
 
-## perfdw.d
-This is a simple dtrace script that measures latency times for when a r/w/f
+## perf-ds-client.d
+A DTrace script that records the time in the Upstairs from when a Message
+is sent to a client task to when that client task returns the response.
+
+## perf-ds-net.d
+This is a simple DTrace script that measures latency times for when a r/w/f
 job is sent over the network to each downstairs to when the ACK for that job
 is returned to the upstairs. Jobs are sorted by type (r/w/f) and by each
 downstairs client ID.
 ```
-sudo dtrace -s perfdw.d
+sudo dtrace -s perf-net-ds.d
 ```
 
 Here is an example of how it might look:
 ```
-final:crucible alan$ sudo sudo dtrace -Z -s perfdw.d
+final:crucible alan$ sudo sudo dtrace -Z -s perf-net-ds.d
 Password:
 dtrace: system integrity protection is on, some features will not be available
 
@@ -220,7 +224,7 @@ dtrace: script 'perfdw.d' matched 0 probes
 ```
 
 ## perfgw.d
-This is a simple dtrace script that measures latency times for when a r/w/f
+This is a simple DTrace script that measures latency times for when a r/w/f
 job is submitted to the internal upstairs work queue, to when that job has
 completed and the notification was sent back to the guest.
 If the upstairs is not yet running, add the -Z flag to dtrace so it will

tools/dtrace/perf-ds-client.d

@@ -0,0 +1,25 @@
+/*
+ * Trace all IOs from the Upstairs for each Downstairs from the time they
+ * are sent to the client task who handles the network tranmission to the
+ * time the result message is returned to the main task and processing
+ * is about to begin.
+ * Group by IO type (R/W/F) and client ID (Which downstairs).
+ *
+ * arg0 is the job ID number.
+ * arg1 is the client ID
+ */
+crucible_upstairs*:::ds-*-client-start
+{
+    start[arg0, arg1] = timestamp;
+}
+
+crucible_upstairs*:::ds-*-client-done
+/start[arg0, arg1]/
+{
+    strtok(probename, "-");
+    this->cmd = strtok(NULL, "-");
+
+    @time[strjoin(this->cmd, " for downstairs client"), arg1] =
+            quantize(timestamp - start[arg0, arg1]);
+    start[arg0, arg1] = 0;
+}

tools/dtrace/perfdw.d → tools/dtrace/perf-ds-net.d

@@ -7,12 +7,12 @@
  * arg0 is the job ID number.
  * arg1 is the client ID
  */
-crucible_upstairs*:::ds-*-io-start
+crucible_upstairs*:::ds-*-net-start
 {
     start[arg0, arg1] = timestamp;
 }
 
-crucible_upstairs*:::ds-*-io-done
+crucible_upstairs*:::ds-*-net-done
 /start[arg0, arg1]/
 {
     strtok(probename, "-");
@@ -22,4 +22,3 @@ crucible_upstairs*:::ds-*-io-done
             quantize(timestamp - start[arg0, arg1]);
     start[arg0, arg1] = 0;
 }
-

upstairs/src/client.rs

@@ -2665,6 +2665,7 @@ impl ClientIoTask {
             self.response_tx.clone(),
             fr,
             self.log.clone(),
+            self.client_id,
         )));
 
         let mut ping_interval = deadline_secs(PING_INTERVAL_SECS);
@@ -2759,6 +2760,7 @@ impl ClientIoTask {
             }
         }
 
+        update_net_start_probes(&m, self.client_id);
         // There's some duplication between this function and `cmd_loop` above,
         // but it's not obvious whether there's a cleaner way to organize stuff.
         tokio::select! {
@@ -2795,6 +2797,7 @@ async fn rx_loop<R>(
     response_tx: mpsc::UnboundedSender<ClientResponse>,
     mut fr: FramedRead<R, crucible_protocol::CrucibleDecoder>,
     log: Logger,
+    cid: ClientId,
 ) -> ClientRunResult
 where
     R: tokio::io::AsyncRead + std::marker::Unpin + std::marker::Send + 'static,
@@ -2804,6 +2807,7 @@ where
             f = fr.next() => {
                 match f {
                     Some(Ok(m)) => {
+                        update_net_done_probes(&m, cid);
                         if let Err(e) =
                             response_tx.send(ClientResponse::Message(m))
                         {
@@ -2833,6 +2837,44 @@ where
     }
 }
 
+fn update_net_start_probes(m: &Message, cid: ClientId) {
+    match m {
+        Message::ReadRequest { job_id, .. } => {
+            cdt::ds__read__net__start!(|| (job_id.0, cid.get()));
+        }
+        Message::Write { ref header, .. } => {
+            cdt::ds__write__net__start!(|| (header.job_id.0, cid.get()));
+        }
+        Message::WriteUnwritten { ref header, .. } => {
+            cdt::ds__write__unwritten__net__start!(|| (
+                header.job_id.0,
+                cid.get()
+            ));
+        }
+        Message::Flush { job_id, .. } => {
+            cdt::ds__flush__net__start!(|| (job_id.0, cid.get()));
+        }
+        _ => {}
+    }
+}
+fn update_net_done_probes(m: &Message, cid: ClientId) {
+    match m {
+        Message::ReadResponse { ref header, .. } => {
+            cdt::ds__read__net__done!(|| (header.job_id.0, cid.get()));
+        }
+        Message::WriteAck { job_id, .. } => {
+            cdt::ds__write__net__done!(|| (job_id.0, cid.get()));
+        }
+        Message::WriteUnwrittenAck { job_id, .. } => {
+            cdt::ds__write__unwritten__net__done!(|| (job_id.0, cid.get()));
+        }
+        Message::FlushAck { job_id, .. } => {
+            cdt::ds__flush__net__done!(|| (job_id.0, cid.get()));
+        }
+        _ => {}
+    }
+}
+
 /// Returns:
 /// - Ok(Some(valid_hash)) for successfully decrypted data
 /// - Ok(None) if there were no block contexts and block was all 0

upstairs/src/downstairs.rs

@@ -529,7 +529,10 @@ impl Downstairs {
                     blocks,
                     data,
                 } => {
-                    cdt::ds__write__io__start!(|| (new_id.0, client_id.get()));
+                    cdt::ds__write__client__start!(|| (
+                        new_id.0,
+                        client_id.get()
+                    ));
                     Message::Write {
                         header: WriteHeader {
                             upstairs_id: self.cfg.upstairs_id,
@@ -546,7 +549,7 @@ impl Downstairs {
                     dependencies,
                     data,
                 } => {
-                    cdt::ds__write__unwritten__io__start!(|| (
+                    cdt::ds__write__unwritten__client__start!(|| (
                         new_id.0,
                         client_id.get()
                     ));
@@ -568,7 +571,10 @@ impl Downstairs {
                     snapshot_details,
                     extent_limit,
                 } => {
-                    cdt::ds__flush__io__start!(|| (new_id.0, client_id.get()));
+                    cdt::ds__flush__client__start!(|| (
+                        new_id.0,
+                        client_id.get()
+                    ));
                     Message::Flush {
                         upstairs_id: self.cfg.upstairs_id,
                         session_id: self.cfg.session_id,
@@ -584,7 +590,10 @@ impl Downstairs {
                     dependencies,
                     requests,
                 } => {
-                    cdt::ds__read__io__start!(|| (new_id.0, client_id.get()));
+                    cdt::ds__read__client__start!(|| (
+                        new_id.0,
+                        client_id.get()
+                    ));
                     Message::ReadRequest {
                         upstairs_id: self.cfg.upstairs_id,
                         session_id: self.cfg.session_id,
@@ -3090,7 +3099,7 @@ impl Downstairs {
                 job_id,
                 result,
             } => {
-                cdt::ds__write__io__done!(|| (job_id.0, client_id.get()));
+                cdt::ds__write__client__done!(|| (job_id.0, client_id.get()));
                 (
                     upstairs_id,
                     session_id,
@@ -3105,7 +3114,7 @@ impl Downstairs {
                 job_id,
                 result,
             } => {
-                cdt::ds__write__unwritten__io__done!(|| (
+                cdt::ds__write__unwritten__client__done!(|| (
                     job_id.0,
                     client_id.get()
                 ));
@@ -3123,7 +3132,7 @@ impl Downstairs {
                 job_id,
                 result,
             } => {
-                cdt::ds__flush__io__done!(|| (job_id.0, client_id.get()));
+                cdt::ds__flush__client__done!(|| (job_id.0, client_id.get()));
                 (
                     upstairs_id,
                     session_id,
@@ -3133,7 +3142,10 @@ impl Downstairs {
                 )
             }
             Message::ReadResponse { header, data } => {
-                cdt::ds__read__io__done!(|| (header.job_id.0, client_id.get()));
+                cdt::ds__read__client__done!(|| (
+                    header.job_id.0,
+                    client_id.get()
+                ));
                 let upstairs_id = header.upstairs_id;
                 let session_id = header.session_id;
                 let job_id = header.job_id;

upstairs/src/lib.rs

@@ -270,15 +270,22 @@ pub type CrucibleBlockIOFuture<'a> = Pin<
 /// has received or is acting on the IO yet, it just means the notification
 /// has been sent.
 ///
-/// ds__*__io__start: This is when a downstairs task puts an IO on the
-/// wire to the actual downstairs that will do the work. This probe has
+/// ds__*__client__start: This is when a job is sent to the client task
+/// who will handle the network transfer
+///
+/// ds__*__net__start: This is when a downstairs client task puts an IO on
+/// the wire to the actual downstairs that will do the work. This probe has
 /// both the job ID and the client ID so we can tell the individual
 /// downstairs apart.
 ///
-/// ds__*__io_done: An ACK has been received from a downstairs for an IO
+/// ds__*__net__done: An ACK has been received from a downstairs for an IO
 /// sent to it. At the point of this probe the IO has just come off the
 /// wire and we have not processed it yet.
 ///
+/// ds__*__client__done: This probe indicates a message off the wire has
+/// been sent back from the client rx task to the main task and is now being
+/// processed.
+///
 /// up__to__ds__*__done: (Upstairs__to__Downstairs) This is the point where
 /// the upstairs has decided that it has enough data to complete an IO
 /// and send an ACK back to the guest.  For a read, this could be the the
@@ -328,18 +335,31 @@ mod cdt {
     fn up__to__ds__write__unwritten__start(_: u64) {}
     fn up__to__ds__flush__start(_: u64) {}
     fn up__block__req__dropped() {}
-    fn ds__read__io__start(_: u64, _: u8) {}
-    fn ds__write__io__start(_: u64, _: u8) {}
-    fn ds__write__unwritten__io__start(_: u64, _: u8) {}
-    fn ds__flush__io__start(_: u64, _: u8) {}
+    fn ds__read__client__start(_: u64, _: u8) {}
+    fn ds__write__client__start(_: u64, _: u8) {}
+    fn ds__write__unwritten__client__start(_: u64, _: u8) {}
+    fn ds__flush__client__start(_: u64, _: u8) {}
     fn ds__close__start(_: u64, _: u8, _: usize) {}
     fn ds__repair__start(_: u64, _: u8, _: usize) {}
     fn ds__noop__start(_: u64, _: u8) {}
     fn ds__reopen__start(_: u64, _: u8, _: usize) {}
-    fn ds__read__io__done(_: u64, _: u8) {}
-    fn ds__write__io__done(_: u64, _: u8) {}
-    fn ds__write__unwritten__io__done(_: u64, _: u8) {}
-    fn ds__flush__io__done(_: u64, _: u8) {}
+    fn ds__read__net__start(_: u64, _: u8) {}
+    fn ds__write__net__start(_: u64, _: u8) {}
+    fn ds__write__unwritten__net__start(_: u64, _: u8) {}
+    fn ds__flush__net__start(_: u64, _: u8) {}
+    fn ds__close__net__start(_: u64, _: u8, _: usize) {}
+    fn ds__repair__net__start(_: u64, _: u8, _: usize) {}
+    fn ds__noop__net__start(_: u64, _: u8) {}
+    fn ds__reopen__net__start(_: u64, _: u8, _: usize) {}
+    fn ds__read__net__done(_: u64, _: u8) {}
+    fn ds__write__net__done(_: u64, _: u8) {}
+    fn ds__write__unwritten__net__done(_: u64, _: u8) {}
+    fn ds__flush__net__done(_: u64, _: u8) {}
+    fn ds__close__net__done(_: u64, _: u8) {}
+    fn ds__read__client__done(_: u64, _: u8) {}
+    fn ds__write__client__done(_: u64, _: u8) {}
+    fn ds__write__unwritten__client__done(_: u64, _: u8) {}
+    fn ds__flush__client__done(_: u64, _: u8) {}
     fn ds__close__done(_: u64, _: u8) {}
     fn ds__repair__done(_: u64, _: u8) {}
     fn ds__noop__done(_: u64, _: u8) {}