diff --git a/tools/dtrace/README.md b/tools/dtrace/README.md index 6b5913e2c..11ddb02d2 100644 --- 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 new file mode 100755 index 000000000..64c2a891a --- /dev/null +++ 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 index d023c4da2..370453560 100755 --- 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 index a335b7497..470f25132 100644 --- 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 index cca97f767..0cb3e946c 100644 --- 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, @@ -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,