New dtrace probes and a counter struct in the Upstairs. (#1104)

* New dtrace probes and a counter struct in the Upstairs. This enables watching what path the Upstairs Apply takes and how frequently it takes each one. Added a new dtrace script to show the new counters. --------- Co-authored-by: Alan Hanson <[email protected]>
oxidecomputer · Jan 24, 2024 · 9525b3e · 9525b3e
1 parent df343e7
commit 9525b3e
Show file tree

Hide file tree

Showing 5 changed files with 178 additions and 1 deletion.
diff --git a/tools/dtrace/README.md b/tools/dtrace/README.md
@@ -300,6 +300,38 @@ Trace a downstairs IO and measure time for in in the following three parts:
 * 2nd report is OS time (for flush, to flush all extents)
 * 3rd report is OS done to downstairs sending the ACK back to upstairs
 
+## upstairs_action.d
+This is a dtrace script for printing the counts of the upstairs main action
+loop.
+```
+pfexec dtrace -s upstairs_action.d
+```
+
+You start crucible, then run the above script.  Output should start appearing
+within a few seconds.
+
+The output has several columns.  The first column is the total count of time
+the upstairs apply() was called in the main run loop.
+The other columns indicate counters for each UpstairsAction the apply loop
+has received.
+
+Here is how some sample output might look:
+```
+    APPLY    DOWN_S     GUEST   DFR_BLK   DFR_MSG  LEAK_CHK FLUSH_CHK  STAT_CHK  REPR_CHK  CTRL_CHK      NOOP
+    19533      8829      2945      1417      3792         0         1         1         0         0      2548
+    39372     17769      5924      2791      7752         2         3         2         0         0      5129
+    59638     26823      8941      4214     11870         3         5         3         0         0      7779
+    78887     35580     11859      5545     15599         4         7         4         0         1     10288
+    98570     44556     14849      6918     19395         5         9         5         0         2     12831
+   117642     53205     17731      8259     23104         6        11         6         0         3     15317
+   137393     62142     20709      9660     26965         6        13         7         0         4     17887
+   157578     71220     23734     11043     31032         8        15         8         0         5     20513
+   176640     79788     26590     12371     34814         9        17         9         0         6     23036
+   195661     88512     29496     13719     38399        10        19        10         0         6     25490
+   215616     97539     32503     15120     42307        11        21        11         0         6     28098
+   234292    106008     35324     16515     45826        12        23        12         0         6     30566
+```
+
 ## upstairs_info.d
 This is a dtrace script for printing upstairs state and work queue info.
 If the upstairs is not yet running, add the -Z flag to dtrace so it will

diff --git a/tools/dtrace/upstairs_action.d b/tools/dtrace/upstairs_action.d
@@ -0,0 +1,44 @@
+/*
+ * Display internal Upstairs status.
+ */
+#pragma D option quiet
+#pragma D option strsize=1k
+/*
+ * Print the header right away
+ */
+dtrace:::BEGIN
+{
+    show = 21;
+}
+
+/*
+ * Every second, check and see if we have printed enough that it is
+ * time to print the header again
+ */
+tick-1s
+/show > 20/
+{
+    printf("%9s %9s %9s", "APPLY", "DOWN_S", "GUEST");
+    printf(" %9s %9s %9s", "DFR_BLK", "DFR_MSG", "LEAK_CHK");
+    printf(" %9s %9s %9s", "FLUSH_CHK", "STAT_CHK", "REPR_CHK");
+    printf(" %9s %9s", "CTRL_CHK", "NOOP");
+    printf("\n");
+    show = 0;
+}
+
+crucible_upstairs*:::up-status
+{
+    show = show + 1;
+    printf("%9s", json(copyinstr(arg1), "ok.up_counters.apply"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_downstairs"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_guest"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_deferred_block"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_deferred_message"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_leak_check"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_flush_check"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_stat_check"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_repair_check"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_control_check"));
+    printf(" %9s", json(copyinstr(arg1), "ok.up_counters.action_noop"));
+    printf("\n");
+}
diff --git a/tools/dtrace/upstairs_info.d b/tools/dtrace/upstairs_info.d
@@ -2,6 +2,7 @@
  * Display internal Upstairs status.
  */
 #pragma D option quiet
+#pragma D option strsize=1k
 /*
  * Print the header right away
  */

diff --git a/upstairs/src/lib.rs b/upstairs/src/lib.rs
@@ -73,6 +73,7 @@ use async_trait::async_trait;
 mod client;
 mod downstairs;
 mod upstairs;
+use crate::upstairs::UpCounters;
 
 // Max number of outstanding IOs between the upstairs and the downstairs
 // before we give up and mark that downstairs faulted.
@@ -254,6 +255,11 @@ impl Debug for ReplaceResult {
 /// as well as the work queue counts for the upstairs work queue and the
 /// downstairs work queue.
 ///
+/// up__apply: A count of times the upstairs main loop applies an action.
+///
+/// up_action_*: These probes record which path is taken when the
+/// upstairs apply select is triggered.
+///
 /// For each read/write/flush, we have a DTrace probe at specific
 /// points throughout its path through the upstairs.  Below is the basic
 /// order of probes an IO will hit as it works its way through the
@@ -304,6 +310,17 @@ mod cdt {
     use crate::Arg;
     fn up__status(_: String, arg: Arg) {}
     fn ds__ping__sent(_: u64, _: u8) {}
+    fn up__apply(_: u64) {}
+    fn up__action_downstairs(_: u64) {}
+    fn up__action_guest(_: u64) {}
+    fn up__action_deferred_block(_: u64) {}
+    fn up__action_deferred_message(_: u64) {}
+    fn up__action_leak_check(_: u64) {}
+    fn up__action_flush_check(_: u64) {}
+    fn up__action_stat_check(_: u64) {}
+    fn up__action_repair_check(_: u64) {}
+    fn up__action_control_check(_: u64) {}
+    fn up__action_noop(_: u64) {}
     fn volume__read__start(_: u32, _: Uuid) {}
     fn volume__write__start(_: u32, _: Uuid) {}
     fn volume__writeunwritten__start(_: u32, _: Uuid) {}
@@ -2711,6 +2728,8 @@ pub struct WQCounts {
 pub struct Arg {
     /// Jobs on the upstairs guest work queue.
     pub up_count: u32,
+    /// Apply loop counter
+    pub up_counters: UpCounters,
     /// Backpressure value
     pub up_backpressure: u64,
     /// Jobs on the downstairs work queue.

diff --git a/upstairs/src/upstairs.rs b/upstairs/src/upstairs.rs
@@ -17,6 +17,7 @@ use crate::{
     RegionDefinition, RegionDefinitionStatus, SnapshotDetails, WQCounts,
 };
 use crucible_common::CrucibleError;
+use serde::{Deserialize, Serialize};
 
 use std::{
     ops::DerefMut,
@@ -64,6 +65,41 @@ pub(crate) enum UpstairsState {
     Deactivating(BlockRes),
 }
 
+/// Crucible upstairs counters
+///
+/// Counters indicating the upstairs selects path.
+#[derive(Clone, Copy, Debug, Serialize, Deserialize)]
+pub struct UpCounters {
+    apply: u64,
+    action_downstairs: u64,
+    action_guest: u64,
+    action_deferred_block: u64,
+    action_deferred_message: u64,
+    action_leak_check: u64,
+    action_flush_check: u64,
+    action_stat_check: u64,
+    action_repair_check: u64,
+    action_control_check: u64,
+    action_noop: u64,
+}
+
+impl UpCounters {
+    fn new() -> UpCounters {
+        UpCounters {
+            apply: 0,
+            action_downstairs: 0,
+            action_guest: 0,
+            action_deferred_block: 0,
+            action_deferred_message: 0,
+            action_leak_check: 0,
+            action_flush_check: 0,
+            action_stat_check: 0,
+            action_repair_check: 0,
+            action_control_check: 0,
+            action_noop: 0,
+        }
+    }
+}
 /// Crucible upstairs state
 ///
 /// This `struct` has exclusive ownership over (almost) everything that's needed
@@ -165,6 +201,8 @@ pub(crate) struct Upstairs {
     /// Shared with the metrics producer, so this `struct` wraps a
     /// `std::sync::Mutex`
     pub(crate) stats: UpStatOuter,
+    /// Some internal counters
+    pub(crate) counters: UpCounters,
 
     /// Fixed configuration
     pub(crate) cfg: Arc<UpstairsConfig>,
@@ -300,6 +338,7 @@ impl Upstairs {
 
         let uuid = opt.id;
         let stats = UpStatOuter::new(uuid);
+        let counters = UpCounters::new();
 
         let rd_status = match expected_region_def {
             None => RegionDefinitionStatus::WaitingForDownstairs,
@@ -342,6 +381,7 @@ impl Upstairs {
             ddef: rd_status,
             need_flush: false,
             stats,
+            counters,
             log,
             downstairs,
             control_rx,
@@ -382,6 +422,8 @@ impl Upstairs {
     pub(crate) async fn run(&mut self) {
         loop {
             let action = self.select().await;
+            self.counters.apply += 1;
+            cdt::up__apply!(|| (self.counters.apply));
             self.apply(action).await
         }
     }
@@ -455,18 +497,36 @@ impl Upstairs {
     pub(crate) async fn apply(&mut self, action: UpstairsAction) {
         match action {
             UpstairsAction::Downstairs(d) => {
+                self.counters.action_downstairs += 1;
+                cdt::up__action_downstairs!(|| (self
+                    .counters
+                    .action_downstairs));
                 self.apply_downstairs_action(d).await
             }
             UpstairsAction::Guest(b) => {
+                self.counters.action_guest += 1;
+                cdt::up__action_guest!(|| (self.counters.action_guest));
                 self.defer_guest_request(b).await;
             }
             UpstairsAction::DeferredBlockReq(req) => {
+                self.counters.action_deferred_block += 1;
+                cdt::up__action_deferred_block!(|| (self
+                    .counters
+                    .action_deferred_block));
                 self.apply_guest_request(req).await;
             }
             UpstairsAction::DeferredMessage(m) => {
+                self.counters.action_deferred_message += 1;
+                cdt::up__action_deferred_message!(|| (self
+                    .counters
+                    .action_deferred_message));
                 self.on_client_message(m).await;
             }
             UpstairsAction::LeakCheck => {
+                self.counters.action_leak_check += 1;
+                cdt::up__action_leak_check!(|| (self
+                    .counters
+                    .action_leak_check));
                 const LEAK_MS: usize = 1000;
                 let leak_tick =
                     tokio::time::Duration::from_millis(LEAK_MS as u64);
@@ -484,22 +544,41 @@ impl Upstairs {
                     Instant::now().checked_add(leak_tick).unwrap();
             }
             UpstairsAction::FlushCheck => {
+                self.counters.action_flush_check += 1;
+                cdt::up__action_flush_check!(|| (self
+                    .counters
+                    .action_flush_check));
                 if self.need_flush {
                     self.submit_flush(None, None).await;
                 }
                 self.flush_deadline = deadline_secs(self.flush_timeout_secs);
             }
             UpstairsAction::StatUpdate => {
+                self.counters.action_stat_check += 1;
+                cdt::up__action_stat_check!(|| (self
+                    .counters
+                    .action_stat_check));
                 self.on_stat_update().await;
                 self.stat_deadline = deadline_secs(STAT_INTERVAL_SECS);
             }
             UpstairsAction::RepairCheck => {
+                self.counters.action_repair_check += 1;
+                cdt::up__action_repair_check!(|| (self
+                    .counters
+                    .action_repair_check));
                 self.on_repair_check().await;
             }
             UpstairsAction::Control(c) => {
+                self.counters.action_control_check += 1;
+                cdt::up__action_control_check!(|| (self
+                    .counters
+                    .action_control_check));
                 self.on_control_req(c).await;
             }
-            UpstairsAction::NoOp => (),
+            UpstairsAction::NoOp => {
+                self.counters.action_noop += 1;
+                cdt::up__action_noop!(|| (self.counters.action_noop));
+            }
         }
 
         // Check whether we need to mark a Downstairs as faulted because too
@@ -627,6 +706,7 @@ impl Upstairs {
     /// Fires the `up-status` DTrace probe
     async fn on_stat_update(&self) {
         let up_count = self.guest.guest_work.lock().await.active.len() as u32;
+        let up_counters = self.counters;
         let ds_count = self.downstairs.active_count() as u32;
         let ds_state = self.downstairs.collect_stats(|c| c.state());
 
@@ -659,6 +739,7 @@ impl Upstairs {
         cdt::up__status!(|| {
             let arg = Arg {
                 up_count,
+                up_counters,
                 up_backpressure,
                 write_bytes_out,
                 ds_count,