Add USDT probes for Nexus background tasks (#8567)

Partially closes #8424

Author: bnaecker

Cargo.lock

@@ -110,6 +110,7 @@ tokio-postgres = { workspace = true, features = ["with-serde_json-1"] }
 tokio-util = { workspace = true, features = ["codec"] }
 tough.workspace = true
 tufaceous-artifact.workspace = true
+usdt.workspace = true
 uuid.workspace = true
 
 nexus-auth.workspace = true

nexus/Cargo.toml

@@ -7,6 +7,8 @@
 //! None of this file is specific to Nexus or any of the specific background
 //! tasks in Nexus, although the design is pretty bespoke for what Nexus needs.
 
+use crate::app::background::probes;
+
 use super::BackgroundTask;
 use super::TaskName;
 use assert_matches::assert_matches;
@@ -129,6 +131,7 @@ impl Driver {
             name.clone(),
         )]));
         let task_exec = TaskExec::new(
+            &name,
             taskdef.period,
             taskdef.task_impl,
             activator.clone(),
@@ -234,6 +237,8 @@ pub struct TaskDefinition<'a, N: ToString, D: ToString> {
 /// Encapsulates state needed by the background tokio task to manage activation
 /// of the background task
 struct TaskExec {
+    /// the name of this background task
+    name: String,
     /// how often the background task should be activated
     period: Duration,
     /// impl of the background task
@@ -251,13 +256,23 @@ struct TaskExec {
 
 impl TaskExec {
     fn new(
+        name: impl ToString,
         period: Duration,
         imp: Box<dyn BackgroundTask>,
         activation: Activator,
         opctx: OpContext,
         status_tx: watch::Sender<TaskStatus>,
     ) -> TaskExec {
-        TaskExec { period, imp, activation, opctx, status_tx, iteration: 0 }
+        let name = name.to_string();
+        TaskExec {
+            name,
+            period,
+            imp,
+            activation,
+            opctx,
+            status_tx,
+            iteration: 0,
+        }
     }
 
     /// Body of the tokio task that manages activation of this background task
@@ -318,10 +333,16 @@ impl TaskExec {
         });
 
         // Do it!
+        probes::background__task__activate__start!(|| {
+            (&self.name, self.iteration, format!("{reason:?}"))
+        });
         let details = self.imp.activate(&self.opctx).await;
         let details_str = serde_json::to_string(&details).unwrap_or_else(|e| {
             format!("<<failed to serialize task status: {}>>", e)
         });
+        probes::background__task__activate__done!(|| {
+            (&self.name, self.iteration, &details_str)
+        });
 
         let elapsed = start_instant.elapsed();
 

nexus/src/app/background/driver.rs

@@ -166,3 +166,22 @@ impl TaskName {
         &self.0
     }
 }
+
+#[usdt::provider(provider = "nexus")]
+mod probes {
+    /// Fires just before running the activate method of the named task.
+    fn background__task__activate__start(
+        task_name: &str,
+        iteration: u64,
+        reason: &str,
+    ) {
+    }
+
+    /// Fires just after completing the task, with the result as JSON.
+    fn background__task__activate__done(
+        task_name: &str,
+        iteration: u64,
+        details: &str,
+    ) {
+    }
+}

nexus/src/app/background/mod.rs

@@ -0,0 +1,43 @@
+#!/usr/sbin/dtrace -Zqs
+
+/* This script prints the result of every background task's activation.
+ * It includes the task name, its iteration, the reason the task ran,
+ * and the result and duration of the execution. Here's an example:
+ *
+ * task_name="dns_servers_internal" iteration=2 reason=Signaled details={"addresses":["[::1]:56144"]} duration=22054us
+ * task_name="dns_servers_external" iteration=2 reason=Signaled details={"addresses":["[::1]:56161"]} duration=21254us
+ * task_name="dns_propagation_internal" iteration=2 reason=Dependency details={"error":"no config"} duration=511us
+ * task_name="dns_propagation_external" iteration=2 reason=Dependency details={"error":"no config"} duration=19us
+ * task_name="v2p_manager" iteration=13 reason=Signaled details={} duration=432252us
+ * task_name="dns_servers_internal" iteration=2 reason=Signaled details={"addresses":["[::1]:36483"]} duration=21347us
+ * task_name="dns_servers_external" iteration=2 reason=Signaled details={"addresses":["[::1]:50606"]} duration=20789us
+ * task_name="dns_propagation_internal" iteration=2 reason=Dependency details={"error":"no config"} duration=38us
+ * task_name="dns_propagation_external" iteration=2 reason=Dependency details={"error":"no config"} duration=11us
+ * task_name="vpc_route_manager" iteration=10 reason=Signaled details={} duration=485381us
+ */
+
+nexus*:::background-task-activate-start
+{
+        this->task_name = copyinstr(arg0);
+        iters[this->task_name] = arg1;
+        reasons[this->task_name] = copyinstr(arg2);
+        ts[this->task_name] = timestamp;
+}
+
+nexus*:::background-task-activate-done
+/iters[copyinstr(arg0)] == arg1/
+{
+        this->task_name = copyinstr(arg0);
+        this->duration = timestamp - ts[this->task_name];
+        printf(
+            "task_name=\"%s\" iteration=%d reason=%s details=%s duration=%dus\n",
+            this->task_name,
+            iters[this->task_name],
+            reasons[this->task_name],
+            copyinstr(arg2),
+            this->duration / 1000
+        );
+        iters[this->task_name] = 0;
+        reasons[this->task_name] = 0;
+        ts[this->task_name] = 0;
+}