From 9de65a219e48fd664f242ba18343f6bf50caa16a Mon Sep 17 00:00:00 2001 From: iximeow Date: Tue, 11 Feb 2025 01:56:41 +0000 Subject: [PATCH 01/14] Test oximeter metrics end to end Other tests in Propolis validate that the Oximeter translation of kstats for a VM are coherent but do so from stubbed kstat readings. Those tests are fine (and quick!), but don't cover the risk of a translation error in Propolis reading from a real system, nor the possibility of reading kstats incorrectly in the first place. ... good news: test doesn't catch anything interesting! The bug I was looking at is somewhere else. --- Cargo.lock | 8 + .../framework/src/test_vm/environment.rs | 19 +- phd-tests/framework/src/test_vm/mod.rs | 22 +- phd-tests/framework/src/test_vm/server.rs | 37 +- phd-tests/tests/Cargo.toml | 12 +- phd-tests/tests/src/lib.rs | 1 + phd-tests/tests/src/stats.rs | 488 ++++++++++++++++++ 7 files changed, 563 insertions(+), 24 deletions(-) create mode 100644 phd-tests/tests/src/stats.rs diff --git a/Cargo.lock b/Cargo.lock index c9b0552b2..51269f850 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3903,13 +3903,21 @@ version = "0.1.0" dependencies = [ "anyhow", "byteorder", + "chrono", "cpuid_utils", + "dropshot", "futures", "http 1.2.0", "itertools 0.13.0", + "omicron-common", + "oximeter", + "oximeter-producer", "phd-testcase", "propolis-client", "reqwest 0.12.7", + "slog", + "slog-term", + "tokio", "tracing", "uuid", ] diff --git a/phd-tests/framework/src/test_vm/environment.rs b/phd-tests/framework/src/test_vm/environment.rs index aa4f8bf7e..79a8b9529 100644 --- a/phd-tests/framework/src/test_vm/environment.rs +++ b/phd-tests/framework/src/test_vm/environment.rs @@ -2,7 +2,7 @@ // License, v. 2.0. If a copy of the MPL was not distributed with this // file, You can obtain one at https://mozilla.org/MPL/2.0/. -use std::net::{Ipv4Addr, SocketAddrV4}; +use std::net::{Ipv4Addr, SocketAddr, SocketAddrV4}; use anyhow::Context; @@ -20,11 +20,16 @@ pub enum VmLocation { pub struct EnvironmentSpec { pub(crate) location: VmLocation, pub(crate) propolis_artifact: String, + pub(crate) metrics_addr: Option, } impl EnvironmentSpec { pub(crate) fn new(location: VmLocation, propolis_artifact: &str) -> Self { - Self { location, propolis_artifact: propolis_artifact.to_owned() } + Self { + location, + propolis_artifact: propolis_artifact.to_owned(), + metrics_addr: None, + } } pub fn location(&mut self, location: VmLocation) -> &mut Self { @@ -37,6 +42,14 @@ impl EnvironmentSpec { self } + pub fn metrics_addr( + &mut self, + metrics_addr: Option, + ) -> &mut Self { + self.metrics_addr = metrics_addr; + self + } + pub(crate) async fn build<'a>( &self, framework: &'a Framework, @@ -71,6 +84,7 @@ impl<'a> Environment<'a> { .port_allocator .next() .context("getting Propolis server port")?; + let metrics_addr = builder.metrics_addr.clone(); let vnc_port = framework .port_allocator .next() @@ -82,6 +96,7 @@ impl<'a> Environment<'a> { Ipv4Addr::new(127, 0, 0, 1), server_port, ), + metrics_addr, vnc_addr: SocketAddrV4::new( Ipv4Addr::new(127, 0, 0, 1), vnc_port, diff --git a/phd-tests/framework/src/test_vm/mod.rs b/phd-tests/framework/src/test_vm/mod.rs index caa17360e..077dabe74 100644 --- a/phd-tests/framework/src/test_vm/mod.rs +++ b/phd-tests/framework/src/test_vm/mod.rs @@ -270,6 +270,15 @@ impl TestVm { self.environment_spec.clone() } + pub fn instance_properties(&self) -> InstanceProperties { + InstanceProperties { + id: self.id, + name: format!("phd-vm-{}", self.id), + metadata: self.spec.metadata.clone(), + description: "Pheidippides-managed VM".to_string(), + } + } + /// Sends an instance ensure request to this VM's server, allowing it to /// transition into the running state. #[instrument(skip_all, fields(vm = self.spec.vm_name, vm_id = %self.id))] @@ -282,13 +291,6 @@ impl TestVm { return Err(VmStateError::InstanceAlreadyEnsured.into()); } - let properties = InstanceProperties { - id: self.id, - name: format!("phd-vm-{}", self.id), - metadata: self.spec.metadata.clone(), - description: "Pheidippides-managed VM".to_string(), - }; - let init = match migrate { None => InstanceInitializationMethod::Spec { spec: self.spec.instance_spec.clone(), @@ -299,8 +301,10 @@ impl TestVm { src_addr: info.src_addr.to_string(), }, }; - let ensure_req = - InstanceEnsureRequest { properties: properties.clone(), init }; + let ensure_req = InstanceEnsureRequest { + properties: self.instance_properties(), + init, + }; // There is a brief period where the Propolis server process has begun // to run but hasn't started its Dropshot server yet. Ensure requests diff --git a/phd-tests/framework/src/test_vm/server.rs b/phd-tests/framework/src/test_vm/server.rs index 01da19d37..0744f3d66 100644 --- a/phd-tests/framework/src/test_vm/server.rs +++ b/phd-tests/framework/src/test_vm/server.rs @@ -4,7 +4,11 @@ //! Routines and data structures for working with Propolis server processes. -use std::{fmt::Debug, net::SocketAddrV4, os::unix::process::CommandExt}; +use std::{ + fmt::Debug, + net::{SocketAddr, SocketAddrV4}, + os::unix::process::CommandExt, +}; use anyhow::Result; use camino::{Utf8Path, Utf8PathBuf}; @@ -27,6 +31,10 @@ pub struct ServerProcessParameters<'a> { /// The address at which the server should serve. pub server_addr: SocketAddrV4, + /// The address of HTTP server with which the spawned server should register + /// as an Oximeter producer. + pub metrics_addr: Option, + /// The address at which the server should offer its VNC server. pub vnc_addr: SocketAddrV4, @@ -48,6 +56,7 @@ impl PropolisServer { server_path, data_dir, server_addr, + metrics_addr, vnc_addr, log_mode, } = process_params; @@ -62,17 +71,23 @@ impl PropolisServer { let (server_stdout, server_stderr) = log_mode.get_handles(&data_dir, vm_name)?; + let mut args = vec![server_path.into_string(), "run".to_string()]; + + if let Some(metrics_addr) = metrics_addr { + args.extend_from_slice(&[ + "--metric-addr".to_string(), + metrics_addr.to_string(), + ]); + } + + args.extend_from_slice(&[ + bootrom_path.as_str().to_string(), + server_addr.to_string(), + vnc_addr.to_string(), + ]); + let mut server_cmd = std::process::Command::new("pfexec"); - server_cmd - .args([ - server_path.as_str(), - "run", - bootrom_path.as_str(), - server_addr.to_string().as_str(), - vnc_addr.to_string().as_str(), - ]) - .stdout(server_stdout) - .stderr(server_stderr); + server_cmd.args(args).stdout(server_stdout).stderr(server_stderr); // Gracefully shutting down a Propolis server requires PHD to send an // instance stop request to the server before it is actually terminated. diff --git a/phd-tests/tests/Cargo.toml b/phd-tests/tests/Cargo.toml index e220e0f08..8892edcf8 100644 --- a/phd-tests/tests/Cargo.toml +++ b/phd-tests/tests/Cargo.toml @@ -10,12 +10,20 @@ doctest = false [dependencies] anyhow.workspace = true byteorder.workspace = true +chrono.workspace = true cpuid_utils.workspace = true +dropshot.workspace = true futures.workspace = true -itertools.workspace = true http.workspace = true -propolis-client.workspace = true +itertools.workspace = true +omicron-common.workspace = true +oximeter-producer.workspace = true +oximeter.workspace = true phd-testcase.workspace = true +propolis-client.workspace = true reqwest.workspace = true +slog-term.workspace = true +slog.workspace = true +tokio.workspace = true tracing.workspace = true uuid.workspace = true diff --git a/phd-tests/tests/src/lib.rs b/phd-tests/tests/src/lib.rs index b76f0bec1..c2265ff24 100644 --- a/phd-tests/tests/src/lib.rs +++ b/phd-tests/tests/src/lib.rs @@ -13,3 +13,4 @@ mod hw; mod migrate; mod server_state_machine; mod smoke; +mod stats; diff --git a/phd-tests/tests/src/stats.rs b/phd-tests/tests/src/stats.rs new file mode 100644 index 000000000..86429b5f7 --- /dev/null +++ b/phd-tests/tests/src/stats.rs @@ -0,0 +1,488 @@ +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + +use std::collections::HashMap; +use std::sync::Arc; +use std::sync::Mutex; +use std::time::Duration; + +use phd_testcase::*; +use tracing::trace; +use uuid::Uuid; + +use chrono::{DateTime, Utc}; +use dropshot::endpoint; +use dropshot::ApiDescription; +use dropshot::ConfigDropshot; +use dropshot::HttpError; +use dropshot::HttpResponseCreated; +use dropshot::HttpServer; +use dropshot::HttpServerStarter; +use dropshot::RequestContext; +use dropshot::TypedBody; +use omicron_common::api::internal::nexus::ProducerEndpoint; +use omicron_common::api::internal::nexus::ProducerKind; +use omicron_common::api::internal::nexus::ProducerRegistrationResponse; +use oximeter::types::{ProducerResults, ProducerResultsItem, Sample}; +use oximeter::{Datum, FieldValue}; +use slog::Drain; +use slog::Logger; + +fn test_logger() -> Logger { + let dec = slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter); + let drain = slog_term::FullFormat::new(dec).build().fuse(); + let log = Logger::root(drain, slog::o!("component" => "fake-cleanup-task")); + log +} + +// Re-registration interval for tests. A long value here helps avoid log spew +// from Oximeter, which will re-register after about 1/6th of this interval +// elapses. +const INTERVAL: Duration = Duration::from_secs(300); + +// For convenience when comparing times below. +const NANOS_PER_SEC: f64 = 1_000_000_000.0; + +struct PropolisOximeterSampler { + addr: std::net::SocketAddr, + uuid: Uuid, +} + +struct FakeNexusContext { + sampler: Arc>>, +} + +#[derive(Copy, Clone, Debug, Eq, Hash, PartialEq)] +enum VcpuState { + Emulation, + Run, + Idle, + Waiting, +} + +impl VcpuState { + fn from_oximeter_state_name(name: &str) -> Self { + match name { + "emulation" => VcpuState::Emulation, + "run" => VcpuState::Run, + "idle" => VcpuState::Idle, + "waiting" => VcpuState::Waiting, + other => { + panic!("unknown Oximeter vpcu state name: {}", other); + } + } + } +} + +#[derive(Default)] +struct VcpuUsageMetric { + metrics: HashMap, +} + +/// A collection of the stats produced by `propolis-server`'s Oximeter producer. +/// +/// Oximeter producers produce a series of lists of samples, where each list +/// of samples is conceptually distinct but may still be interesting to +/// tset. In `propolis-server`, the first list of samples will be +/// `virtual_machine:vcpu_usage`, which may be blank of kstats have not been +/// sampled since the last producer poll. The second list of samples +/// will be `virtual_machine:reset`. +/// +/// `VirtualMachineMetrics` collects these all back together into a single view +/// to test against. See [`VirtualMachineMetrics::add_producer_result`] as the +/// means to accumulate samples into this struct. +struct VirtualMachineMetrics { + oldest_time: DateTime, + reset: Option, + vcpus: HashMap, +} + +impl VirtualMachineMetrics { + fn vcpu_state_total(&self, state: &VcpuState) -> u64 { + self.vcpus + .values() + .fold(0, |total, vcpu_usage| total + vcpu_usage.metrics[state]) + } + + fn update_metric_times(&mut self, metric_time: DateTime) { + self.oldest_time = std::cmp::min(self.oldest_time, metric_time); + } + + /// Integrate a list of samples into this collection of virtual machine + /// metrics. + fn add_producer_result(&mut self, samples: &[Sample]) { + let mut samples_by_metric = HashMap::new(); + + for sample in samples { + let name = sample.timeseries_name.to_owned(); + let fields = sample.sorted_metric_fields().to_owned(); + let collection: &mut Vec = + samples_by_metric.entry((name, fields)).or_default(); + + collection.push(sample.clone()); + } + + for v in samples_by_metric.values_mut() { + v.sort_by_key(|s| s.measurement.timestamp()); + } + + for ((name, fields), samples) in samples_by_metric { + let last_sample = samples.last().expect("at least one sample"); + if name == "virtual_machine:reset" { + assert!( + self.reset.is_none(), + "multiple virtual_machine:reset measurements for a \ + single Propolis?" + ); + + let datum = last_sample.measurement.datum(); + let amount = if let Datum::CumulativeU64(amount) = datum { + amount.value() + } else { + panic!("unexpected reset value type"); + }; + self.reset = Some(amount); + self.update_metric_times(last_sample.measurement.timestamp()); + } else if name == "virtual_machine:vcpu_usage" { + let datum = last_sample.measurement.datum(); + let amount = if let Datum::CumulativeU64(amount) = datum { + amount.value() + } else { + panic!("unexpected vcpu_usage datum type: {:?}", datum); + }; + let field = &fields["state"]; + let state: VcpuState = + if let FieldValue::String(state) = &field.value { + VcpuState::from_oximeter_state_name(state.as_ref()) + } else { + panic!("unknown vcpu state datum type: {:?}", field); + }; + let field = &fields["vcpu_id"]; + let vcpu_id = if let FieldValue::U32(vcpu_id) = field.value { + vcpu_id + } else { + panic!("unknown vcpu id datum type: {:?}", field); + }; + let vcpu_metrics = self.vcpus.entry(vcpu_id).or_default(); + if vcpu_metrics.metrics.contains_key(&state) { + panic!( + "vcpu {} state {:?} has duplicate metric {:?}", + vcpu_id, state, last_sample + ); + } + trace!( + "recorded cpu {} state {:?} = {} at {}", + vcpu_id, + state, + amount, + last_sample.measurement.timestamp() + ); + vcpu_metrics.metrics.insert(state, amount); + self.update_metric_times(last_sample.measurement.timestamp()); + } + } + } +} + +impl FakeNexusContext { + fn new() -> Self { + Self { sampler: Arc::new(Mutex::new(None)) } + } + + fn set_producer_info(&self, info: ProducerEndpoint) { + assert_eq!(info.kind, ProducerKind::Instance); + *self.sampler.lock().unwrap() = + Some(PropolisOximeterSampler { addr: info.address, uuid: info.id }); + } + + async fn wait_for_producer(&self) { + loop { + { + let sampler = self.sampler.lock().unwrap(); + if sampler.is_some() { + return; + } + } + tokio::time::sleep(std::time::Duration::from_millis(100)).await; + } + } + + /// Sample Propolis' Oximeter metrics, waiting up to a few seconds so that + /// all measurements are from the time this function was called or later. + async fn wait_for_propolis_stats(&self) -> VirtualMachineMetrics { + let retry_delay = Duration::from_millis(1000); + let max_wait = Duration::from_millis(10000); + let wait_start = std::time::SystemTime::now(); + + let min_metric_time = Utc::now(); + + while wait_start.elapsed().expect("time goes forward") < max_wait { + if let Some(metrics) = self.sample_propolis_stats().await { + if metrics.oldest_time >= min_metric_time { + return metrics; + } + } + + tokio::time::sleep(retry_delay).await; + } + + panic!( + "propolis-server Oximeter stats unavailable? waited {:?}", + max_wait + ); + } + + /// Sample Propolis' Oximeter metrics, including the timestamp of the oldest + /// metric reflected in the sample. + /// + /// Returns `None` for some kinds of incomplete stats or when no stats are + /// available at all. + async fn sample_propolis_stats(&self) -> Option { + let metrics_url = { + let sampler = self.sampler.lock().unwrap(); + let stats = sampler.as_ref().expect("stats url info exists"); + format!("http://{}/{}", stats.addr, stats.uuid) + }; + let res = reqwest::Client::new() + .get(metrics_url) + .send() + .await + .expect("can send oximeter stats request"); + assert!( + res.status().is_success(), + "failed to fetch stats from propolis-server" + ); + trace!(?res, "got stats response"); + let results = + res.json::().await.expect("can deserialize"); + + let mut metrics = VirtualMachineMetrics { + oldest_time: Utc::now(), + reset: None, + vcpus: HashMap::new(), + }; + + for result in results { + match result { + ProducerResultsItem::Ok(samples) => { + metrics.add_producer_result(&samples); + } + ProducerResultsItem::Err(e) => { + panic!("ProducerResultsItem error: {}", e); + } + } + } + + if metrics.vcpus.len() == 0 { + trace!("no vcpu metrics yet?"); + return None; + } + + Some(metrics) + } +} + +// Stub functionality for our fake Nexus that test Oximeter produces +// (`propolis-server`) will register with. +#[endpoint { + method = POST, + path = "/metrics/producers", +}] +async fn register_producer( + rqctx: RequestContext, + producer_info: TypedBody, +) -> Result, HttpError> { + let info = producer_info.into_inner(); + trace!(?info, "producer registration"); + rqctx.context().set_producer_info(info); + + Ok(HttpResponseCreated(ProducerRegistrationResponse { + lease_duration: INTERVAL, + })) +} + +// Start a Dropshot server mocking the Nexus registration endpoint. +fn spawn_fake_nexus_server() -> HttpServer { + let log = test_logger(); + + let mut api = ApiDescription::new(); + api.register(register_producer).expect("Expected to register endpoint"); + let server = HttpServerStarter::new( + &ConfigDropshot { + bind_address: "[::1]:0".parse().unwrap(), + request_body_max_bytes: 2048, + ..Default::default() + }, + api, + FakeNexusContext::new(), + &log, + ) + .expect("Expected to start Dropshot server") + .start(); + + slog::info!( + log, + "fake nexus test server listening"; + "address" => ?server.local_addr(), + ); + + server +} + +#[phd_testcase] +async fn instance_vcpu_stats(ctx: &Framework) { + let fake_nexus = spawn_fake_nexus_server(); + + let mut env = ctx.environment_builder(); + env.metrics_addr(Some(fake_nexus.local_addr())); + + let mut vm_config = ctx.vm_config_builder("instance_vcpu_stats"); + vm_config.cpus(1); + + let mut source = ctx.spawn_vm(&vm_config, Some(&env)).await?; + + source.launch().await?; + + fake_nexus.app_private().wait_for_producer().await; + source.wait_to_boot().await?; + + // From watching Linux guests, some services may be relatively active right + // at and immediately after login. Wait a few seconds to try counting any + // post-boot festivities as part of "baseline". + source.run_shell_command("sleep 10").await?; + + let start_metrics = + fake_nexus.app_private().wait_for_propolis_stats().await; + + // Measure a specific amount of time with guest vCPUs in the "run" state. + // + // We measure the "run" state using some fixed-size busywork because we + // can't simply say "run for 5 seconds please" - if we did, a combination of + // host OS or guest OS may leave the process timing itself descheduled for + // some or all of that time, so we could end up with substantially less than + // 5 seconds of execution and a flaky test as a result. + // + // Instead, run some busywork, time how long that took on the host OS, then + // know the guest OS should have spent around that long running. This still + // relies us measuring the completion time relatively quickly after the + // busywork completes, but it's one fewer sources of nondeterminism. + + let run_start = std::time::SystemTime::now(); + source.run_shell_command("i=0").await?; + source.run_shell_command("lim=2000000").await?; + source + .run_shell_command("while [ $i -lt $lim ]; do i=$((i+1)); done") + .await?; + let run_time = run_start.elapsed().expect("time goes forwards"); + trace!("measured run time {:?}", run_time); + + let now_metrics = fake_nexus.app_private().wait_for_propolis_stats().await; + + let run_delta = (now_metrics.vcpu_state_total(&VcpuState::Run) + - start_metrics.vcpu_state_total(&VcpuState::Run)) + as u128; + + // The guest should not have run longer than we were running a shell command + // in the guest.. + assert!(run_delta < run_time.as_nanos()); + + // Our measurement of how long the guest took should be pretty close to the + // guest's measured running time. Check only that the guest ran for at least + // 90% of the time we measured it running because we're woken strictly after + // the guest completed its work - we know we've overcounted some. + // + // (Anecdotally the actual difference here on a responsive test system is + // closer to 10ms, or <1% of expected runtime. Lots of margin for error on a + // very busy CI system.) + let min_guest_run_delta = (run_time.as_nanos() as f64 * 0.9) as u128; + assert!( + run_delta > min_guest_run_delta, + "{} > {}", + run_delta as f64 / NANOS_PER_SEC, + min_guest_run_delta as f64 / NANOS_PER_SEC + ); + + // VM vCPU stats are sampled roughly every five seconds, which means the + // minimum granularity of `run + idle + waiting + emul` is also roughly + // units of 5 seconds. There could be one or two sample intervals between + // `start_metrics` and `now_metrics` depending on how long it took to get + // from starting the Oximeter producer to actually sampling. + // + // This is to say: there isn't a strong statement that we can make about + // idle time at this point other than that it is probably around a large + // enough value to fill the total time out to a mutiple of 5 seconds. + // + // The guesswork to validate that doesn't seem great in the face of + // variable-time CI. We'll validate idle time measurements separately, + // below. + let idle_start_metrics = + fake_nexus.app_private().wait_for_propolis_stats().await; + let idle_start = std::time::SystemTime::now(); + source.run_shell_command("sleep 20").await?; + + let now_metrics = fake_nexus.app_private().wait_for_propolis_stats().await; + + // The guest VM would continues to exist with its idle vCPU being accounted + // by the kstats Oximeter samples. This means `wait_for_propolis_stats` + // could introduce as much as a full Oximeter sample interval of additional + // idle vCPU, and is we why wait to measure idle time until *after* getting + // new Oximeter metrics. + let idle_time = idle_start.elapsed().expect("time goes forwards"); + trace!("measured idle time {:?}", idle_time); + + let idle_delta = (now_metrics.vcpu_state_total(&VcpuState::Idle) + - idle_start_metrics.vcpu_state_total(&VcpuState::Idle)) + as u128; + + // We've idled for at least 20 seconds. The guest may not be fully idle (its + // OS is still running on its sole CPU, for example), so we test that the + // guest was just mostly idle for the time period. + let min_guest_idle_delta = (idle_time.as_nanos() as f64 * 0.9) as u128; + assert!( + idle_delta < idle_time.as_nanos(), + "{} < {}", + idle_delta as f64 / NANOS_PER_SEC, + idle_time.as_nanos() as f64 / NANOS_PER_SEC + ); + assert!( + idle_delta > min_guest_idle_delta, + "{} > {}", + idle_delta as f64 / NANOS_PER_SEC, + min_guest_idle_delta as f64 / NANOS_PER_SEC + ); + + let run_delta = (now_metrics.vcpu_state_total(&VcpuState::Run) + - start_metrics.vcpu_state_total(&VcpuState::Run)) + as u128; + + let idle_delta = (now_metrics.vcpu_state_total(&VcpuState::Idle) + - start_metrics.vcpu_state_total(&VcpuState::Idle)) + as u128; + + let waiting_delta = (now_metrics.vcpu_state_total(&VcpuState::Waiting) + - start_metrics.vcpu_state_total(&VcpuState::Waiting)) + as u128; + + let emul_delta = (now_metrics.vcpu_state_total(&VcpuState::Emulation) + - start_metrics.vcpu_state_total(&VcpuState::Emulation)) + as u128; + + // Pick 100ms as a comically high upper bound for how much time might have + // been spent emulating instructions on the guest's behalf. Anecdotally the + // this is on the order of 8ms between the two samples. This should be very + // low; the workload is almost entirely guest user mode execution. + assert!(emul_delta < Duration::from_millis(100).as_nanos()); + + // Waiting is a similar but more constrained situation as `emul`: time when + // the vCPU was runnable but not *actually* running. This should be a very + // short duration, and on my workstation this is around 400 microseconds. + // Again, test against a significantly larger threshold in case CI is + // extremely slow. + assert!(waiting_delta < Duration::from_millis(20).as_nanos()); + + trace!("run: {}", run_delta); + trace!("idle: {}", idle_delta); + trace!("waiting: {}", waiting_delta); + trace!("emul: {}", emul_delta); +} From 2c50316fa3122586350f6861e83c1bc8d025e4de Mon Sep 17 00:00:00 2001 From: iximeow Date: Tue, 11 Feb 2025 20:51:15 +0000 Subject: [PATCH 02/14] assert that running time doesn't meaningfully change while idle just since we're here looking at times. didn't expect this to be interesting, and it wasn't. --- phd-tests/tests/src/stats.rs | 25 ++++++++++++++++--------- 1 file changed, 16 insertions(+), 9 deletions(-) diff --git a/phd-tests/tests/src/stats.rs b/phd-tests/tests/src/stats.rs index 86429b5f7..aacac5073 100644 --- a/phd-tests/tests/src/stats.rs +++ b/phd-tests/tests/src/stats.rs @@ -452,19 +452,26 @@ async fn instance_vcpu_stats(ctx: &Framework) { min_guest_idle_delta as f64 / NANOS_PER_SEC ); + // The delta in vCPU `run` time should be negligible. We've run one shell + // command which in turn just idled. let run_delta = (now_metrics.vcpu_state_total(&VcpuState::Run) + - idle_start_metrics.vcpu_state_total(&VcpuState::Run)) + as u128; + assert!(run_delta < Duration::from_millis(100).as_nanos()); + + let full_run_delta = (now_metrics.vcpu_state_total(&VcpuState::Run) - start_metrics.vcpu_state_total(&VcpuState::Run)) as u128; - let idle_delta = (now_metrics.vcpu_state_total(&VcpuState::Idle) + let full_idle_delta = (now_metrics.vcpu_state_total(&VcpuState::Idle) - start_metrics.vcpu_state_total(&VcpuState::Idle)) as u128; - let waiting_delta = (now_metrics.vcpu_state_total(&VcpuState::Waiting) + let full_waiting_delta = (now_metrics.vcpu_state_total(&VcpuState::Waiting) - start_metrics.vcpu_state_total(&VcpuState::Waiting)) as u128; - let emul_delta = (now_metrics.vcpu_state_total(&VcpuState::Emulation) + let full_emul_delta = (now_metrics.vcpu_state_total(&VcpuState::Emulation) - start_metrics.vcpu_state_total(&VcpuState::Emulation)) as u128; @@ -472,17 +479,17 @@ async fn instance_vcpu_stats(ctx: &Framework) { // been spent emulating instructions on the guest's behalf. Anecdotally the // this is on the order of 8ms between the two samples. This should be very // low; the workload is almost entirely guest user mode execution. - assert!(emul_delta < Duration::from_millis(100).as_nanos()); + assert!(full_emul_delta < Duration::from_millis(100).as_nanos()); // Waiting is a similar but more constrained situation as `emul`: time when // the vCPU was runnable but not *actually* running. This should be a very // short duration, and on my workstation this is around 400 microseconds. // Again, test against a significantly larger threshold in case CI is // extremely slow. - assert!(waiting_delta < Duration::from_millis(20).as_nanos()); + assert!(full_waiting_delta < Duration::from_millis(20).as_nanos()); - trace!("run: {}", run_delta); - trace!("idle: {}", idle_delta); - trace!("waiting: {}", waiting_delta); - trace!("emul: {}", emul_delta); + trace!("run: {}", full_run_delta); + trace!("idle: {}", full_idle_delta); + trace!("waiting: {}", full_waiting_delta); + trace!("emul: {}", full_emul_delta); } From 998f5a36612e6ce04ac5da289ddab6bfe20c8648 Mon Sep 17 00:00:00 2001 From: iximeow Date: Tue, 11 Feb 2025 21:06:06 +0000 Subject: [PATCH 03/14] forgot to ask clippy --- phd-tests/framework/src/test_vm/environment.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/phd-tests/framework/src/test_vm/environment.rs b/phd-tests/framework/src/test_vm/environment.rs index 79a8b9529..b45feb92d 100644 --- a/phd-tests/framework/src/test_vm/environment.rs +++ b/phd-tests/framework/src/test_vm/environment.rs @@ -84,7 +84,6 @@ impl<'a> Environment<'a> { .port_allocator .next() .context("getting Propolis server port")?; - let metrics_addr = builder.metrics_addr.clone(); let vnc_port = framework .port_allocator .next() @@ -96,7 +95,7 @@ impl<'a> Environment<'a> { Ipv4Addr::new(127, 0, 0, 1), server_port, ), - metrics_addr, + metrics_addr: builder.metrics_addr, vnc_addr: SocketAddrV4::new( Ipv4Addr::new(127, 0, 0, 1), vnc_port, From cea54ecc61f61787b2afdfaf62bd091889b135cb Mon Sep 17 00:00:00 2001 From: iximeow Date: Tue, 11 Feb 2025 21:22:24 +0000 Subject: [PATCH 04/14] didn't ask clippy the right way the first time --- phd-tests/tests/src/stats.rs | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/phd-tests/tests/src/stats.rs b/phd-tests/tests/src/stats.rs index aacac5073..3e0f6734b 100644 --- a/phd-tests/tests/src/stats.rs +++ b/phd-tests/tests/src/stats.rs @@ -32,8 +32,7 @@ use slog::Logger; fn test_logger() -> Logger { let dec = slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter); let drain = slog_term::FullFormat::new(dec).build().fuse(); - let log = Logger::root(drain, slog::o!("component" => "fake-cleanup-task")); - log + Logger::root(drain, slog::o!("component" => "fake-cleanup-task")) } // Re-registration interval for tests. A long value here helps avoid log spew @@ -274,7 +273,7 @@ impl FakeNexusContext { } } - if metrics.vcpus.len() == 0 { + if metrics.vcpus.is_empty() { trace!("no vcpu metrics yet?"); return None; } From 53196223f371697652b9c2c2f1d83dbc223149b9 Mon Sep 17 00:00:00 2001 From: iximeow Date: Tue, 11 Feb 2025 23:07:01 +0000 Subject: [PATCH 05/14] review feedback, fix one more "idle" accounting test race if there's a significant delay between the initial idle kstats observation becoming available and idle_start being measured, it's possible that the guest's actual idle vCPU time is greater than the "measured" idle time from PHD's view. instead, measure max idle time as "the time from before initial measurement to after last measurement", and min idle time as "the time just after initial measurement to after last measurement". still bias min idle time down a bit since the guest may have some active CPU time. --- Cargo.lock | 2 + phd-tests/tests/Cargo.toml | 2 + phd-tests/tests/src/stats.rs | 97 +++++++++++++++++++----------------- 3 files changed, 56 insertions(+), 45 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 51269f850..b7b1ff51a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3902,6 +3902,7 @@ name = "phd-tests" version = "0.1.0" dependencies = [ "anyhow", + "backoff", "byteorder", "chrono", "cpuid_utils", @@ -3917,6 +3918,7 @@ dependencies = [ "reqwest 0.12.7", "slog", "slog-term", + "strum", "tokio", "tracing", "uuid", diff --git a/phd-tests/tests/Cargo.toml b/phd-tests/tests/Cargo.toml index 8892edcf8..9e09342e8 100644 --- a/phd-tests/tests/Cargo.toml +++ b/phd-tests/tests/Cargo.toml @@ -9,6 +9,7 @@ doctest = false [dependencies] anyhow.workspace = true +backoff.workspace = true byteorder.workspace = true chrono.workspace = true cpuid_utils.workspace = true @@ -24,6 +25,7 @@ propolis-client.workspace = true reqwest.workspace = true slog-term.workspace = true slog.workspace = true +strum.workspace = true tokio.workspace = true tracing.workspace = true uuid.workspace = true diff --git a/phd-tests/tests/src/stats.rs b/phd-tests/tests/src/stats.rs index 3e0f6734b..a6030930b 100644 --- a/phd-tests/tests/src/stats.rs +++ b/phd-tests/tests/src/stats.rs @@ -3,14 +3,11 @@ // file, You can obtain one at https://mozilla.org/MPL/2.0/. use std::collections::HashMap; +use std::str::FromStr; use std::sync::Arc; use std::sync::Mutex; use std::time::Duration; -use phd_testcase::*; -use tracing::trace; -use uuid::Uuid; - use chrono::{DateTime, Utc}; use dropshot::endpoint; use dropshot::ApiDescription; @@ -26,8 +23,11 @@ use omicron_common::api::internal::nexus::ProducerKind; use omicron_common::api::internal::nexus::ProducerRegistrationResponse; use oximeter::types::{ProducerResults, ProducerResultsItem, Sample}; use oximeter::{Datum, FieldValue}; +use phd_testcase::*; use slog::Drain; use slog::Logger; +use tracing::trace; +use uuid::Uuid; fn test_logger() -> Logger { let dec = slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter); @@ -52,7 +52,8 @@ struct FakeNexusContext { sampler: Arc>>, } -#[derive(Copy, Clone, Debug, Eq, Hash, PartialEq)] +#[derive(Copy, Clone, Debug, Eq, Hash, PartialEq, strum::EnumString)] +#[strum(serialize_all = "snake_case")] enum VcpuState { Emulation, Run, @@ -60,20 +61,6 @@ enum VcpuState { Waiting, } -impl VcpuState { - fn from_oximeter_state_name(name: &str) -> Self { - match name { - "emulation" => VcpuState::Emulation, - "run" => VcpuState::Run, - "idle" => VcpuState::Idle, - "waiting" => VcpuState::Waiting, - other => { - panic!("unknown Oximeter vpcu state name: {}", other); - } - } - } -} - #[derive(Default)] struct VcpuUsageMetric { metrics: HashMap, @@ -139,7 +126,7 @@ impl VirtualMachineMetrics { let amount = if let Datum::CumulativeU64(amount) = datum { amount.value() } else { - panic!("unexpected reset value type"); + panic!("unexpected reset datum type: {:?}", datum); }; self.reset = Some(amount); self.update_metric_times(last_sample.measurement.timestamp()); @@ -151,12 +138,15 @@ impl VirtualMachineMetrics { panic!("unexpected vcpu_usage datum type: {:?}", datum); }; let field = &fields["state"]; - let state: VcpuState = - if let FieldValue::String(state) = &field.value { - VcpuState::from_oximeter_state_name(state.as_ref()) - } else { - panic!("unknown vcpu state datum type: {:?}", field); - }; + let state: VcpuState = if let FieldValue::String(state) = + &field.value + { + VcpuState::from_str(state.as_ref()).unwrap_or_else(|_| { + panic!("unknown Oximeter vpcu state name: {}", state); + }) + } else { + panic!("unknown vcpu state datum type: {:?}", field); + }; let field = &fields["vcpu_id"]; let vcpu_id = if let FieldValue::U32(vcpu_id) = field.value { vcpu_id @@ -203,33 +193,40 @@ impl FakeNexusContext { return; } } - tokio::time::sleep(std::time::Duration::from_millis(100)).await; + tokio::time::sleep(Duration::from_millis(100)).await; } } /// Sample Propolis' Oximeter metrics, waiting up to a few seconds so that /// all measurements are from the time this function was called or later. async fn wait_for_propolis_stats(&self) -> VirtualMachineMetrics { - let retry_delay = Duration::from_millis(1000); - let max_wait = Duration::from_millis(10000); - let wait_start = std::time::SystemTime::now(); - let min_metric_time = Utc::now(); - while wait_start.elapsed().expect("time goes forward") < max_wait { - if let Some(metrics) = self.sample_propolis_stats().await { - if metrics.oldest_time >= min_metric_time { - return metrics; + let result = backoff::future::retry( + backoff::ExponentialBackoff { + max_interval: Duration::from_secs(1), + max_elapsed_time: Some(Duration::from_secs(10)), + ..Default::default() + }, + || async { + if let Some(metrics) = self.sample_propolis_stats().await { + if metrics.oldest_time >= min_metric_time { + Ok(metrics) + } else { + Err(backoff::Error::transient(anyhow::anyhow!( + "sampled metrics are not recent enough" + ))) + } + } else { + Err(backoff::Error::transient(anyhow::anyhow!( + "full metrics sample not available (yet?)" + ))) } - } + }, + ) + .await; - tokio::time::sleep(retry_delay).await; - } - - panic!( - "propolis-server Oximeter stats unavailable? waited {:?}", - max_wait - ); + result.expect("propolis-server Oximeter stats should become available") } /// Sample Propolis' Oximeter metrics, including the timestamp of the oldest @@ -415,6 +412,15 @@ async fn instance_vcpu_stats(ctx: &Framework) { // The guesswork to validate that doesn't seem great in the face of // variable-time CI. We'll validate idle time measurements separately, // below. + + // Idle time boundaries are a little differnt than running time boundaries + // because it's more difficult to stop counting to idle vCPU time than it is + // to stop counting running vCPU time. Instead, the maximum amount of idling + // time we might measure is however long it takes to get the initial kstat + // readings, plus how long the idle time takes, plus however long it takes + // to get final kstat readings. The miminum amount of idling time is + // the time elapsed since just after the initial kstat readings. + let max_idle_start = std::time::SystemTime::now(); let idle_start_metrics = fake_nexus.app_private().wait_for_propolis_stats().await; let idle_start = std::time::SystemTime::now(); @@ -427,6 +433,7 @@ async fn instance_vcpu_stats(ctx: &Framework) { // could introduce as much as a full Oximeter sample interval of additional // idle vCPU, and is we why wait to measure idle time until *after* getting // new Oximeter metrics. + let max_idle_time = max_idle_start.elapsed().expect("time goes forwards"); let idle_time = idle_start.elapsed().expect("time goes forwards"); trace!("measured idle time {:?}", idle_time); @@ -437,13 +444,13 @@ async fn instance_vcpu_stats(ctx: &Framework) { // We've idled for at least 20 seconds. The guest may not be fully idle (its // OS is still running on its sole CPU, for example), so we test that the // guest was just mostly idle for the time period. - let min_guest_idle_delta = (idle_time.as_nanos() as f64 * 0.9) as u128; assert!( - idle_delta < idle_time.as_nanos(), + idle_delta < max_idle_time.as_nanos(), "{} < {}", idle_delta as f64 / NANOS_PER_SEC, idle_time.as_nanos() as f64 / NANOS_PER_SEC ); + let min_guest_idle_delta = (idle_time.as_nanos() as f64 * 0.9) as u128; assert!( idle_delta > min_guest_idle_delta, "{} > {}", From fe6ab8870c4c6d32af0cfa180efc8fd190d3ed0f Mon Sep 17 00:00:00 2001 From: iximeow Date: Wed, 19 Feb 2025 23:25:29 +0000 Subject: [PATCH 06/14] separate out some more easily resued bits into PHD framework --- Cargo.lock | 3 + phd-tests/framework/Cargo.toml | 3 + phd-tests/framework/src/lib.rs | 3 + .../framework/src/test_vm/environment.rs | 38 +- phd-tests/framework/src/test_vm/metrics.rs | 188 +++++++++ phd-tests/framework/src/test_vm/mod.rs | 21 +- phd-tests/tests/src/stats.rs | 363 +++++++----------- 7 files changed, 377 insertions(+), 242 deletions(-) create mode 100644 phd-tests/framework/src/test_vm/metrics.rs diff --git a/Cargo.lock b/Cargo.lock index b7b1ff51a..18f94cbb3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3829,6 +3829,7 @@ dependencies = [ "camino", "cfg-if", "cpuid_utils", + "dropshot", "errno 0.2.8", "fatfs", "flate2", @@ -3836,6 +3837,8 @@ dependencies = [ "hex", "libc", "newtype_derive", + "omicron-common", + "oximeter", "propolis-client", "rand", "reqwest 0.12.7", diff --git a/phd-tests/framework/Cargo.toml b/phd-tests/framework/Cargo.toml index ee666d722..b2be8ecb8 100644 --- a/phd-tests/framework/Cargo.toml +++ b/phd-tests/framework/Cargo.toml @@ -16,6 +16,7 @@ bhyve_api.workspace = true camino = { workspace = true, features = ["serde1"] } cfg-if.workspace = true cpuid_utils.workspace = true +dropshot.workspace = true errno.workspace = true fatfs.workspace = true futures.workspace = true @@ -23,6 +24,8 @@ flate2.workspace = true hex.workspace = true libc.workspace = true newtype_derive.workspace = true +omicron-common.workspace = true +oximeter.workspace = true propolis-client.workspace = true reqwest = { workspace = true, features = ["blocking"] } ring.workspace = true diff --git a/phd-tests/framework/src/lib.rs b/phd-tests/framework/src/lib.rs index 912ff397c..c9cf6ccc1 100644 --- a/phd-tests/framework/src/lib.rs +++ b/phd-tests/framework/src/lib.rs @@ -58,6 +58,9 @@ pub mod server_log_mode; pub mod test_vm; pub(crate) mod zfs; +pub use test_vm::environment::MetricsLocation; +pub use test_vm::metrics::FakeOximeterContext; + /// An instance of the PHD test framework. pub struct Framework { pub(crate) tmp_directory: Utf8PathBuf, diff --git a/phd-tests/framework/src/test_vm/environment.rs b/phd-tests/framework/src/test_vm/environment.rs index b45feb92d..58764cc54 100644 --- a/phd-tests/framework/src/test_vm/environment.rs +++ b/phd-tests/framework/src/test_vm/environment.rs @@ -2,7 +2,7 @@ // License, v. 2.0. If a copy of the MPL was not distributed with this // file, You can obtain one at https://mozilla.org/MPL/2.0/. -use std::net::{Ipv4Addr, SocketAddr, SocketAddrV4}; +use std::net::{Ipv4Addr, SocketAddrV4}; use anyhow::Context; @@ -16,11 +16,22 @@ pub enum VmLocation { // TODO: Support remote VMs. } +/// Specifies where test VMs should report metrics to, if anywhere. +#[derive(Clone, Copy, Debug)] +pub enum MetricsLocation { + /// Oximeter metrics should be reported to a server colocated with the test + /// VM to be started. + Local, + // When the time comes to support remote VMs, it will presumably be useful + // to have local and (perhaps multiple) remote VMs report metrics to the + // same server. But we don't support remote VMs yet. +} + #[derive(Clone, Debug)] pub struct EnvironmentSpec { pub(crate) location: VmLocation, pub(crate) propolis_artifact: String, - pub(crate) metrics_addr: Option, + pub(crate) metrics: Option, } impl EnvironmentSpec { @@ -28,7 +39,7 @@ impl EnvironmentSpec { Self { location, propolis_artifact: propolis_artifact.to_owned(), - metrics_addr: None, + metrics: None, } } @@ -42,11 +53,8 @@ impl EnvironmentSpec { self } - pub fn metrics_addr( - &mut self, - metrics_addr: Option, - ) -> &mut Self { - self.metrics_addr = metrics_addr; + pub fn metrics(&mut self, metrics: Option) -> &mut Self { + self.metrics = metrics; self } @@ -88,6 +96,18 @@ impl<'a> Environment<'a> { .port_allocator .next() .context("getting VNC server port")?; + let metrics_addr = builder.metrics.and_then(|m| match m { + MetricsLocation::Local => { + // If the test requests metrics are local, we'll start + // an Oximeter stand-in for this VM when setting up this + // environment later. `start_local_vm` will patch in the + // actual server address when it has created one. + // + // If the VM is to be started remotely but requests + // "Local" metrics, that's probably an error. + None + } + }); let params = ServerProcessParameters { server_path: propolis_server, data_dir: framework.tmp_directory.as_path(), @@ -95,7 +115,7 @@ impl<'a> Environment<'a> { Ipv4Addr::new(127, 0, 0, 1), server_port, ), - metrics_addr: builder.metrics_addr, + metrics_addr, vnc_addr: SocketAddrV4::new( Ipv4Addr::new(127, 0, 0, 1), vnc_port, diff --git a/phd-tests/framework/src/test_vm/metrics.rs b/phd-tests/framework/src/test_vm/metrics.rs new file mode 100644 index 000000000..9578eb383 --- /dev/null +++ b/phd-tests/framework/src/test_vm/metrics.rs @@ -0,0 +1,188 @@ +use std::net::SocketAddr; +use std::time::Duration; + +use dropshot::{ + endpoint, ApiDescription, ConfigDropshot, HttpError, HttpResponseCreated, + HttpServer, HttpServerStarter, RequestContext, TypedBody, +}; +use omicron_common::api::internal::nexus::{ + ProducerEndpoint, ProducerKind, ProducerRegistrationResponse, +}; +use oximeter::types::ProducerResults; +use slog::{Drain, Logger}; +use tokio::sync::watch; +use tracing::trace; +use uuid::Uuid; + +// Re-registration interval for tests. A long value here helps avoid log spew +// from Oximeter, which will re-register after about 1/6th of this interval +// elapses. +const INTERVAL: Duration = Duration::from_secs(300); + +fn test_logger() -> Logger { + let dec = slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter); + let drain = slog_term::FullFormat::new(dec).build().fuse(); + Logger::root(drain, slog::o!("component" => "fake-cleanup-task")) +} + +struct PropolisOximeterSampler { + addr: std::net::SocketAddr, + uuid: Uuid, +} + +pub(crate) struct FakeOximeterServer { + server: HttpServer, +} + +pub(crate) struct FakeOximeterServerState { + sampler_sender: watch::Sender>, + sampler: watch::Receiver>, +} + +impl FakeOximeterServer { + pub fn local_addr(&self) -> SocketAddr { + self.server.local_addr() + } + + pub fn sampler(&self) -> FakeOximeterContext { + FakeOximeterContext { + sampler: self.server.app_private().sampler.clone(), + } + } +} + +pub struct FakeOximeterContext { + sampler: watch::Receiver>, +} + +impl FakeOximeterServerState { + fn new() -> Self { + let (tx, rx) = watch::channel(None); + + Self { sampler_sender: tx, sampler: rx } + } + + async fn set_producer_info(&self, info: ProducerEndpoint) { + assert_eq!(info.kind, ProducerKind::Instance); + let new_sampler = + PropolisOximeterSampler { addr: info.address, uuid: info.id }; + self.sampler_sender + .send(Some(new_sampler)) + .expect("channel is subscribed"); + } +} + +impl FakeOximeterContext { + /// Sample Propolis' Oximeter metrics, waiting up to a few seconds so that + /// all measurements are from the time this function was called or later. + pub async fn wait_for_propolis_stats( + &self, + f: impl Fn(ProducerResults) -> Option, + ) -> U { + let result = backoff::future::retry( + backoff::ExponentialBackoff { + max_interval: Duration::from_secs(1), + max_elapsed_time: Some(Duration::from_secs(10)), + ..Default::default() + }, + || async { + let producer_results = self.sample_propolis_stats().await + .map_err(|e| backoff::Error::transient(e))?; + + if let Some(metrics) = f(producer_results) { + Ok(metrics) + } else { + Err(backoff::Error::transient(anyhow::anyhow!( + "full metrics sample not available or fresh enough (yet?)" + ))) + } + }, + ) + .await; + + result.expect("propolis-server Oximeter stats should become available") + } + + /// Sample Propolis' Oximeter metrics, including the timestamp of the oldest + /// metric reflected in the sample. + /// + /// Returns `None` for some kinds of incomplete stats or when no stats are + /// available at all. + async fn sample_propolis_stats( + &self, + ) -> Result { + let metrics_url = { + self.sampler + .clone() + .wait_for(Option::is_some) + .await + .expect("can recv"); + let sampler = self.sampler.borrow(); + let stats = sampler.as_ref().expect("sampler does not become None"); + format!("http://{}/{}", stats.addr, stats.uuid) + }; + let res = reqwest::Client::new() + .get(metrics_url) + .send() + .await + .expect("can send oximeter stats request"); + assert!( + res.status().is_success(), + "failed to fetch stats from propolis-server" + ); + trace!(?res, "got stats response"); + Ok(res.json::().await?) + /* + let results = + res.json::().await.expect("can deserialize"); + */ + } +} + +// Stub functionality for our fake Nexus that test Oximeter produces +// (`propolis-server`) will register with. +#[endpoint { + method = POST, + path = "/metrics/producers", +}] +async fn register_producer( + rqctx: RequestContext, + producer_info: TypedBody, +) -> Result, HttpError> { + let info = producer_info.into_inner(); + trace!(?info, "producer registration"); + rqctx.context().set_producer_info(info).await; + + Ok(HttpResponseCreated(ProducerRegistrationResponse { + lease_duration: INTERVAL, + })) +} + +// Start a Dropshot server mocking the Oximeter registration endpoint we would +// expect from Nexus. +pub fn spawn_fake_oximeter_server() -> FakeOximeterServer { + let log = test_logger(); + + let mut api = ApiDescription::new(); + api.register(register_producer).expect("Expected to register endpoint"); + let server = HttpServerStarter::new( + &ConfigDropshot { + bind_address: "[::1]:0".parse().unwrap(), + request_body_max_bytes: 2048, + ..Default::default() + }, + api, + FakeOximeterServerState::new(), + &log, + ) + .expect("Expected to start Dropshot server") + .start(); + + slog::info!( + log, + "fake nexus test server listening"; + "address" => ?server.local_addr(), + ); + + FakeOximeterServer { server } +} diff --git a/phd-tests/framework/src/test_vm/mod.rs b/phd-tests/framework/src/test_vm/mod.rs index 077dabe74..f5bd53b20 100644 --- a/phd-tests/framework/src/test_vm/mod.rs +++ b/phd-tests/framework/src/test_vm/mod.rs @@ -17,7 +17,9 @@ use crate::{ }, serial::{BufferKind, SerialConsole}, test_vm::{ - environment::Environment, server::ServerProcessParameters, spec::VmSpec, + environment::Environment, environment::MetricsLocation, + metrics::FakeOximeterContext, server::ServerProcessParameters, + spec::VmSpec, }, Framework, }; @@ -51,6 +53,7 @@ type PropolisClientResult = StdResult, PropolisClientError>; pub(crate) mod config; pub(crate) mod environment; +pub(crate) mod metrics; mod server; pub(crate) mod spec; @@ -156,6 +159,7 @@ pub struct TestVm { id: Uuid, client: Client, server: Option, + metrics: Option, spec: VmSpec, environment_spec: EnvironmentSpec, data_dir: Utf8PathBuf, @@ -228,9 +232,17 @@ impl TestVm { vm_id: Uuid, vm_spec: VmSpec, environment_spec: EnvironmentSpec, - params: ServerProcessParameters, + mut params: ServerProcessParameters, cleanup_task_tx: UnboundedSender>, ) -> Result { + let metrics = environment_spec.metrics.as_ref().map(|m| match m { + MetricsLocation::Local => { + let metrics_server = metrics::spawn_fake_oximeter_server(); + params.metrics_addr = Some(metrics_server.local_addr()); + metrics_server + } + }); + let data_dir = params.data_dir.to_path_buf(); let server_addr = params.server_addr; let server = server::PropolisServer::new( @@ -245,6 +257,7 @@ impl TestVm { id: vm_id, client, server: Some(server), + metrics, spec: vm_spec, environment_spec, data_dir, @@ -279,6 +292,10 @@ impl TestVm { } } + pub fn metrics_sampler(&self) -> Option { + self.metrics.as_ref().map(|m| m.sampler()) + } + /// Sends an instance ensure request to this VM's server, allowing it to /// transition into the running state. #[instrument(skip_all, fields(vm = self.spec.vm_name, vm_id = %self.id))] diff --git a/phd-tests/tests/src/stats.rs b/phd-tests/tests/src/stats.rs index a6030930b..8edeaf9c9 100644 --- a/phd-tests/tests/src/stats.rs +++ b/phd-tests/tests/src/stats.rs @@ -4,54 +4,17 @@ use std::collections::HashMap; use std::str::FromStr; -use std::sync::Arc; -use std::sync::Mutex; use std::time::Duration; use chrono::{DateTime, Utc}; -use dropshot::endpoint; -use dropshot::ApiDescription; -use dropshot::ConfigDropshot; -use dropshot::HttpError; -use dropshot::HttpResponseCreated; -use dropshot::HttpServer; -use dropshot::HttpServerStarter; -use dropshot::RequestContext; -use dropshot::TypedBody; -use omicron_common::api::internal::nexus::ProducerEndpoint; -use omicron_common::api::internal::nexus::ProducerKind; -use omicron_common::api::internal::nexus::ProducerRegistrationResponse; use oximeter::types::{ProducerResults, ProducerResultsItem, Sample}; use oximeter::{Datum, FieldValue}; use phd_testcase::*; -use slog::Drain; -use slog::Logger; -use tracing::trace; -use uuid::Uuid; - -fn test_logger() -> Logger { - let dec = slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter); - let drain = slog_term::FullFormat::new(dec).build().fuse(); - Logger::root(drain, slog::o!("component" => "fake-cleanup-task")) -} - -// Re-registration interval for tests. A long value here helps avoid log spew -// from Oximeter, which will re-register after about 1/6th of this interval -// elapses. -const INTERVAL: Duration = Duration::from_secs(300); +use tracing::{trace, warn}; // For convenience when comparing times below. const NANOS_PER_SEC: f64 = 1_000_000_000.0; -struct PropolisOximeterSampler { - addr: std::net::SocketAddr, - uuid: Uuid, -} - -struct FakeNexusContext { - sampler: Arc>>, -} - #[derive(Copy, Clone, Debug, Eq, Hash, PartialEq, strum::EnumString)] #[strum(serialize_all = "snake_case")] enum VcpuState { @@ -61,7 +24,7 @@ enum VcpuState { Waiting, } -#[derive(Default)] +#[derive(Default, Debug)] struct VcpuUsageMetric { metrics: HashMap, } @@ -78,12 +41,56 @@ struct VcpuUsageMetric { /// `VirtualMachineMetrics` collects these all back together into a single view /// to test against. See [`VirtualMachineMetrics::add_producer_result`] as the /// means to accumulate samples into this struct. +#[derive(Debug)] struct VirtualMachineMetrics { oldest_time: DateTime, reset: Option, vcpus: HashMap, } +/// Collect a record of all metrics for a VM as of the time this function is called. +async fn vm_metrics_snapshot( + sampler: &crate::stats::phd_framework::FakeOximeterContext, +) -> VirtualMachineMetrics { + let min_metric_time = Utc::now(); + + let metrics_check = move |producer_items| { + producer_results_as_vm_metrics(producer_items) + .filter(|metrics| metrics.oldest_time >= min_metric_time) + }; + + sampler.wait_for_propolis_stats(metrics_check).await +} + +fn producer_results_as_vm_metrics( + s: ProducerResults, +) -> Option { + let results = s; + let mut metrics = VirtualMachineMetrics { + oldest_time: Utc::now(), + reset: None, + vcpus: HashMap::new(), + }; + + for result in results { + match result { + ProducerResultsItem::Ok(samples) => { + metrics.add_producer_result(&samples); + } + ProducerResultsItem::Err(e) => { + panic!("ProducerResultsItem error: {}", e); + } + } + } + + if metrics.vcpus.is_empty() { + trace!("no vcpu metrics yet?"); + return None; + } + + Some(metrics) +} + impl VirtualMachineMetrics { fn vcpu_state_total(&self, state: &VcpuState) -> u64 { self.vcpus @@ -174,182 +181,42 @@ impl VirtualMachineMetrics { } } -impl FakeNexusContext { - fn new() -> Self { - Self { sampler: Arc::new(Mutex::new(None)) } - } - - fn set_producer_info(&self, info: ProducerEndpoint) { - assert_eq!(info.kind, ProducerKind::Instance); - *self.sampler.lock().unwrap() = - Some(PropolisOximeterSampler { addr: info.address, uuid: info.id }); - } - - async fn wait_for_producer(&self) { - loop { - { - let sampler = self.sampler.lock().unwrap(); - if sampler.is_some() { - return; - } - } - tokio::time::sleep(Duration::from_millis(100)).await; - } - } - - /// Sample Propolis' Oximeter metrics, waiting up to a few seconds so that - /// all measurements are from the time this function was called or later. - async fn wait_for_propolis_stats(&self) -> VirtualMachineMetrics { - let min_metric_time = Utc::now(); - - let result = backoff::future::retry( - backoff::ExponentialBackoff { - max_interval: Duration::from_secs(1), - max_elapsed_time: Some(Duration::from_secs(10)), - ..Default::default() - }, - || async { - if let Some(metrics) = self.sample_propolis_stats().await { - if metrics.oldest_time >= min_metric_time { - Ok(metrics) - } else { - Err(backoff::Error::transient(anyhow::anyhow!( - "sampled metrics are not recent enough" - ))) - } - } else { - Err(backoff::Error::transient(anyhow::anyhow!( - "full metrics sample not available (yet?)" - ))) - } - }, - ) - .await; - - result.expect("propolis-server Oximeter stats should become available") - } - - /// Sample Propolis' Oximeter metrics, including the timestamp of the oldest - /// metric reflected in the sample. - /// - /// Returns `None` for some kinds of incomplete stats or when no stats are - /// available at all. - async fn sample_propolis_stats(&self) -> Option { - let metrics_url = { - let sampler = self.sampler.lock().unwrap(); - let stats = sampler.as_ref().expect("stats url info exists"); - format!("http://{}/{}", stats.addr, stats.uuid) - }; - let res = reqwest::Client::new() - .get(metrics_url) - .send() - .await - .expect("can send oximeter stats request"); - assert!( - res.status().is_success(), - "failed to fetch stats from propolis-server" - ); - trace!(?res, "got stats response"); - let results = - res.json::().await.expect("can deserialize"); - - let mut metrics = VirtualMachineMetrics { - oldest_time: Utc::now(), - reset: None, - vcpus: HashMap::new(), - }; - - for result in results { - match result { - ProducerResultsItem::Ok(samples) => { - metrics.add_producer_result(&samples); - } - ProducerResultsItem::Err(e) => { - panic!("ProducerResultsItem error: {}", e); - } - } - } - - if metrics.vcpus.is_empty() { - trace!("no vcpu metrics yet?"); - return None; - } - - Some(metrics) - } -} - -// Stub functionality for our fake Nexus that test Oximeter produces -// (`propolis-server`) will register with. -#[endpoint { - method = POST, - path = "/metrics/producers", -}] -async fn register_producer( - rqctx: RequestContext, - producer_info: TypedBody, -) -> Result, HttpError> { - let info = producer_info.into_inner(); - trace!(?info, "producer registration"); - rqctx.context().set_producer_info(info); - - Ok(HttpResponseCreated(ProducerRegistrationResponse { - lease_duration: INTERVAL, - })) -} - -// Start a Dropshot server mocking the Nexus registration endpoint. -fn spawn_fake_nexus_server() -> HttpServer { - let log = test_logger(); - - let mut api = ApiDescription::new(); - api.register(register_producer).expect("Expected to register endpoint"); - let server = HttpServerStarter::new( - &ConfigDropshot { - bind_address: "[::1]:0".parse().unwrap(), - request_body_max_bytes: 2048, - ..Default::default() - }, - api, - FakeNexusContext::new(), - &log, - ) - .expect("Expected to start Dropshot server") - .start(); - - slog::info!( - log, - "fake nexus test server listening"; - "address" => ?server.local_addr(), - ); - - server -} - #[phd_testcase] async fn instance_vcpu_stats(ctx: &Framework) { - let fake_nexus = spawn_fake_nexus_server(); + /// Allow as much as 20% measurement error for time comparisons in this + /// test. When measuring active guest time, some guests (looking at you + /// Windows) may have services that continue running in the time period + /// where our test workload completes but we're still waiting for metrics; + /// this means Oximeter can see more running time than we know we caused. + /// When measuring guest idle time, these same idle services can result in + /// the VM being less idle than our intended idling. + /// + /// "0.XX" here reflects an expectation that a system with no user-directed + /// activity will actually be idle for XX% of a given time period. In + /// practice this may be as low as 5% or less (many Linux guests), and as + /// high as 12% in practice for Windows guests. Round up to 20% for some + /// buffer. + const TOLERANCE: f64 = 0.8; let mut env = ctx.environment_builder(); - env.metrics_addr(Some(fake_nexus.local_addr())); + env.metrics(Some(crate::stats::phd_framework::MetricsLocation::Local)); let mut vm_config = ctx.vm_config_builder("instance_vcpu_stats"); vm_config.cpus(1); - let mut source = ctx.spawn_vm(&vm_config, Some(&env)).await?; + let mut vm = ctx.spawn_vm(&vm_config, Some(&env)).await?; - source.launch().await?; + let sampler = vm.metrics_sampler().expect("metrics are enabled"); + vm.launch().await?; - fake_nexus.app_private().wait_for_producer().await; - source.wait_to_boot().await?; + vm.wait_to_boot().await?; // From watching Linux guests, some services may be relatively active right // at and immediately after login. Wait a few seconds to try counting any // post-boot festivities as part of "baseline". - source.run_shell_command("sleep 10").await?; + vm.run_shell_command("sleep 20").await?; - let start_metrics = - fake_nexus.app_private().wait_for_propolis_stats().await; + let start_metrics = vm_metrics_snapshot(&sampler).await; // Measure a specific amount of time with guest vCPUs in the "run" state. // @@ -362,36 +229,38 @@ async fn instance_vcpu_stats(ctx: &Framework) { // Instead, run some busywork, time how long that took on the host OS, then // know the guest OS should have spent around that long running. This still // relies us measuring the completion time relatively quickly after the - // busywork completes, but it's one fewer sources of nondeterminism. + // busywork completes, but it's one fewer vms of nondeterminism. let run_start = std::time::SystemTime::now(); - source.run_shell_command("i=0").await?; - source.run_shell_command("lim=2000000").await?; - source - .run_shell_command("while [ $i -lt $lim ]; do i=$((i+1)); done") - .await?; + vm.run_shell_command("i=0").await?; + vm.run_shell_command("lim=2000000").await?; + vm.run_shell_command("while [ $i -lt $lim ]; do i=$((i+1)); done").await?; let run_time = run_start.elapsed().expect("time goes forwards"); - trace!("measured run time {:?}", run_time); + tracing::warn!("measured run time {:?}", run_time); - let now_metrics = fake_nexus.app_private().wait_for_propolis_stats().await; + let now_metrics = vm_metrics_snapshot(&sampler).await; + let total_run_window = run_start.elapsed().expect("time goes forwards"); + tracing::warn!("start_metrics: {:?}", start_metrics); + tracing::warn!("now_metrics: {:?}", now_metrics); let run_delta = (now_metrics.vcpu_state_total(&VcpuState::Run) - start_metrics.vcpu_state_total(&VcpuState::Run)) as u128; - // The guest should not have run longer than we were running a shell command - // in the guest.. - assert!(run_delta < run_time.as_nanos()); + // The guest should not have run longer than the total time we were + // measuring it.. + assert!(run_delta < total_run_window.as_nanos()); // Our measurement of how long the guest took should be pretty close to the - // guest's measured running time. Check only that the guest ran for at least - // 90% of the time we measured it running because we're woken strictly after - // the guest completed its work - we know we've overcounted some. + // guest's measured running time. It won't be exact: the guest may have + // services that continue in the period between the shell command completing + // and a final metrics collection - it may be running for more time than we + // intended. // - // (Anecdotally the actual difference here on a responsive test system is - // closer to 10ms, or <1% of expected runtime. Lots of margin for error on a - // very busy CI system.) - let min_guest_run_delta = (run_time.as_nanos() as f64 * 0.9) as u128; + // (Anecdotally the actual difference here depends on the guest, with + // minimal Linux guests like Alpine being quite close with <1% differences + // here.) + let min_guest_run_delta = (run_time.as_nanos() as f64 * TOLERANCE) as u128; assert!( run_delta > min_guest_run_delta, "{} > {}", @@ -421,18 +290,17 @@ async fn instance_vcpu_stats(ctx: &Framework) { // to get final kstat readings. The miminum amount of idling time is // the time elapsed since just after the initial kstat readings. let max_idle_start = std::time::SystemTime::now(); - let idle_start_metrics = - fake_nexus.app_private().wait_for_propolis_stats().await; + let idle_start_metrics = vm_metrics_snapshot(&sampler).await; let idle_start = std::time::SystemTime::now(); - source.run_shell_command("sleep 20").await?; + vm.run_shell_command("sleep 10").await?; - let now_metrics = fake_nexus.app_private().wait_for_propolis_stats().await; + let now_metrics = vm_metrics_snapshot(&sampler).await; // The guest VM would continues to exist with its idle vCPU being accounted - // by the kstats Oximeter samples. This means `wait_for_propolis_stats` - // could introduce as much as a full Oximeter sample interval of additional - // idle vCPU, and is we why wait to measure idle time until *after* getting - // new Oximeter metrics. + // by the kstats Oximeter samples. This means `vm_metrics_snapshot` could + // introduce as much as a full Oximeter sample interval of additional idle + // vCPU, and is we why wait to measure idle time until *after* getting new + // Oximeter metrics. let max_idle_time = max_idle_start.elapsed().expect("time goes forwards"); let idle_time = idle_start.elapsed().expect("time goes forwards"); trace!("measured idle time {:?}", idle_time); @@ -450,7 +318,8 @@ async fn instance_vcpu_stats(ctx: &Framework) { idle_delta as f64 / NANOS_PER_SEC, idle_time.as_nanos() as f64 / NANOS_PER_SEC ); - let min_guest_idle_delta = (idle_time.as_nanos() as f64 * 0.9) as u128; + let min_guest_idle_delta = + (idle_time.as_nanos() as f64 * TOLERANCE) as u128; assert!( idle_delta > min_guest_idle_delta, "{} > {}", @@ -459,11 +328,17 @@ async fn instance_vcpu_stats(ctx: &Framework) { ); // The delta in vCPU `run` time should be negligible. We've run one shell - // command which in turn just idled. + // command which in turn just idled. In reality, if the guest has idle + // processes running even sitting at an empty prompt, assume there is up to + // THRESHOLD activity happening anyway. This is another threshold that + // varies based on guest OS type. let run_delta = (now_metrics.vcpu_state_total(&VcpuState::Run) - idle_start_metrics.vcpu_state_total(&VcpuState::Run)) as u128; - assert!(run_delta < Duration::from_millis(100).as_nanos()); + let idle_delta = (now_metrics.vcpu_state_total(&VcpuState::Idle) + - idle_start_metrics.vcpu_state_total(&VcpuState::Idle)) + as u128; + assert!(run_delta < (idle_delta as f64 * (1.0 - TOLERANCE)) as u128); let full_run_delta = (now_metrics.vcpu_state_total(&VcpuState::Run) - start_metrics.vcpu_state_total(&VcpuState::Run)) @@ -485,14 +360,40 @@ async fn instance_vcpu_stats(ctx: &Framework) { // been spent emulating instructions on the guest's behalf. Anecdotally the // this is on the order of 8ms between the two samples. This should be very // low; the workload is almost entirely guest user mode execution. - assert!(full_emul_delta < Duration::from_millis(100).as_nanos()); + if vm.guest_os_kind().is_linux() { + // Unfortunately, the above is currently too optimistic in the general + // case of arbitrary guest OSes - if a guest OS has idle services, and + // those idle services involve checking the current time, and the guest + // has determined the TSC is unreliable, we may count substantial + // emulation time due to emulating guest accesses to the ACPI PM timer. + // + // Linux guests are known to not (currently?) consult the current time + // if fully idle, so we can be more precise about emulation time + // assertions. + assert!( + full_emul_delta < Duration::from_millis(100).as_nanos(), + "full emul delta was above threshold: {} > {}", + full_emul_delta, + Duration::from_millis(100).as_nanos() + ); + } else { + warn!( + "guest OS may cause substantial emulation time due to benign \ + factors outside our control; skipping emulation stat check" + ); + } // Waiting is a similar but more constrained situation as `emul`: time when // the vCPU was runnable but not *actually* running. This should be a very // short duration, and on my workstation this is around 400 microseconds. // Again, test against a significantly larger threshold in case CI is // extremely slow. - assert!(full_waiting_delta < Duration::from_millis(20).as_nanos()); + assert!( + full_waiting_delta < Duration::from_millis(20).as_nanos(), + "full waiting delta was above threshold: {} > {}", + full_waiting_delta, + Duration::from_millis(20).as_nanos() + ); trace!("run: {}", full_run_delta); trace!("idle: {}", full_idle_delta); From f8e5901e874c2063ac4f29503cbae353ce01d8c1 Mon Sep 17 00:00:00 2001 From: iximeow Date: Thu, 20 Feb 2025 00:52:44 +0000 Subject: [PATCH 07/14] a bit more post-rework cleanup --- phd-tests/framework/src/lib.rs | 3 -- phd-tests/framework/src/test_vm/metrics.rs | 16 ++++++++-- phd-tests/framework/src/test_vm/mod.rs | 7 ++-- phd-tests/tests/src/stats.rs | 37 +++++++++++++++------- 4 files changed, 42 insertions(+), 21 deletions(-) diff --git a/phd-tests/framework/src/lib.rs b/phd-tests/framework/src/lib.rs index c9cf6ccc1..912ff397c 100644 --- a/phd-tests/framework/src/lib.rs +++ b/phd-tests/framework/src/lib.rs @@ -58,9 +58,6 @@ pub mod server_log_mode; pub mod test_vm; pub(crate) mod zfs; -pub use test_vm::environment::MetricsLocation; -pub use test_vm::metrics::FakeOximeterContext; - /// An instance of the PHD test framework. pub struct Framework { pub(crate) tmp_directory: Utf8PathBuf, diff --git a/phd-tests/framework/src/test_vm/metrics.rs b/phd-tests/framework/src/test_vm/metrics.rs index 9578eb383..df8c180bb 100644 --- a/phd-tests/framework/src/test_vm/metrics.rs +++ b/phd-tests/framework/src/test_vm/metrics.rs @@ -63,9 +63,15 @@ impl FakeOximeterServerState { } async fn set_producer_info(&self, info: ProducerEndpoint) { + // Just don't know what to do with other ProducerKinds, if or when we'll + // see them here.. assert_eq!(info.kind, ProducerKind::Instance); + let new_sampler = PropolisOximeterSampler { addr: info.address, uuid: info.id }; + + // There should always be at least one Receiver on the channel since we + // hold one in `self`. self.sampler_sender .send(Some(new_sampler)) .expect("channel is subscribed"); @@ -73,8 +79,14 @@ impl FakeOximeterServerState { } impl FakeOximeterContext { - /// Sample Propolis' Oximeter metrics, waiting up to a few seconds so that - /// all measurements are from the time this function was called or later. + /// Sample Propolis' Oximeter metrics, taking some function that determines + /// if a sample is satisfactory for the caller to proceed with. + /// + /// `wait_for_propolis_stats` will poll the corresponding Oximeter producer + /// and call `f` with each returned set of results. + /// + /// Panics if `f` does not return `Some` after some number of retries and + /// `ProducerResults` updates. pub async fn wait_for_propolis_stats( &self, f: impl Fn(ProducerResults) -> Option, diff --git a/phd-tests/framework/src/test_vm/mod.rs b/phd-tests/framework/src/test_vm/mod.rs index f5bd53b20..8ab99ef1b 100644 --- a/phd-tests/framework/src/test_vm/mod.rs +++ b/phd-tests/framework/src/test_vm/mod.rs @@ -17,9 +17,7 @@ use crate::{ }, serial::{BufferKind, SerialConsole}, test_vm::{ - environment::Environment, environment::MetricsLocation, - metrics::FakeOximeterContext, server::ServerProcessParameters, - spec::VmSpec, + environment::Environment, server::ServerProcessParameters, spec::VmSpec, }, Framework, }; @@ -58,7 +56,8 @@ mod server; pub(crate) mod spec; pub use config::*; -pub use environment::VmLocation; +pub use environment::{MetricsLocation, VmLocation}; +pub use metrics::FakeOximeterContext; use self::environment::EnvironmentSpec; diff --git a/phd-tests/tests/src/stats.rs b/phd-tests/tests/src/stats.rs index 8edeaf9c9..c90444a97 100644 --- a/phd-tests/tests/src/stats.rs +++ b/phd-tests/tests/src/stats.rs @@ -6,6 +6,8 @@ use std::collections::HashMap; use std::str::FromStr; use std::time::Duration; +use phd_framework::test_vm::{FakeOximeterContext, MetricsLocation}; + use chrono::{DateTime, Utc}; use oximeter::types::{ProducerResults, ProducerResultsItem, Sample}; use oximeter::{Datum, FieldValue}; @@ -34,13 +36,25 @@ struct VcpuUsageMetric { /// Oximeter producers produce a series of lists of samples, where each list /// of samples is conceptually distinct but may still be interesting to /// tset. In `propolis-server`, the first list of samples will be -/// `virtual_machine:vcpu_usage`, which may be blank of kstats have not been +/// `virtual_machine:vcpu_usage`, which may be blank if kstats have not been /// sampled since the last producer poll. The second list of samples /// will be `virtual_machine:reset`. /// /// `VirtualMachineMetrics` collects these all back together into a single view /// to test against. See [`VirtualMachineMetrics::add_producer_result`] as the /// means to accumulate samples into this struct. +/// +/// ### Should this be in `framework`? +/// +/// Arguably! It happens to encompass all `propolis-server` metrics today after +/// all. I expect we'll have many more Oximeter-produced stats from +/// `propolis-server` in the future, though, and only a few of them might be +/// relevant to these specific tests. Other tests may not want to wait for fresh +/// vCPU data that they don't care about, as well. +/// +/// As-is, this is trying to be a relatively-standalone halfway point before the +/// most comprehensive approach: running Clickhouse alongside PHD and storing +/// Oximeter data there, maybe even querying samples with OxQL. #[derive(Debug)] struct VirtualMachineMetrics { oldest_time: DateTime, @@ -50,7 +64,7 @@ struct VirtualMachineMetrics { /// Collect a record of all metrics for a VM as of the time this function is called. async fn vm_metrics_snapshot( - sampler: &crate::stats::phd_framework::FakeOximeterContext, + sampler: &FakeOximeterContext, ) -> VirtualMachineMetrics { let min_metric_time = Utc::now(); @@ -63,9 +77,8 @@ async fn vm_metrics_snapshot( } fn producer_results_as_vm_metrics( - s: ProducerResults, + results: ProducerResults, ) -> Option { - let results = s; let mut metrics = VirtualMachineMetrics { oldest_time: Utc::now(), reset: None, @@ -199,7 +212,7 @@ async fn instance_vcpu_stats(ctx: &Framework) { const TOLERANCE: f64 = 0.8; let mut env = ctx.environment_builder(); - env.metrics(Some(crate::stats::phd_framework::MetricsLocation::Local)); + env.metrics(Some(MetricsLocation::Local)); let mut vm_config = ctx.vm_config_builder("instance_vcpu_stats"); vm_config.cpus(1); @@ -236,12 +249,10 @@ async fn instance_vcpu_stats(ctx: &Framework) { vm.run_shell_command("lim=2000000").await?; vm.run_shell_command("while [ $i -lt $lim ]; do i=$((i+1)); done").await?; let run_time = run_start.elapsed().expect("time goes forwards"); - tracing::warn!("measured run time {:?}", run_time); + trace!("measured run time {:?}", run_time); let now_metrics = vm_metrics_snapshot(&sampler).await; let total_run_window = run_start.elapsed().expect("time goes forwards"); - tracing::warn!("start_metrics: {:?}", start_metrics); - tracing::warn!("now_metrics: {:?}", now_metrics); let run_delta = (now_metrics.vcpu_state_total(&VcpuState::Run) - start_metrics.vcpu_state_total(&VcpuState::Run)) @@ -370,11 +381,12 @@ async fn instance_vcpu_stats(ctx: &Framework) { // Linux guests are known to not (currently?) consult the current time // if fully idle, so we can be more precise about emulation time // assertions. + const LIMIT: u128 = Duration::from_millis(100).as_nanos(); assert!( - full_emul_delta < Duration::from_millis(100).as_nanos(), + full_emul_delta < LIMIT, "full emul delta was above threshold: {} > {}", full_emul_delta, - Duration::from_millis(100).as_nanos() + LIMIT ); } else { warn!( @@ -388,11 +400,12 @@ async fn instance_vcpu_stats(ctx: &Framework) { // short duration, and on my workstation this is around 400 microseconds. // Again, test against a significantly larger threshold in case CI is // extremely slow. + const LIMIT: u128 = Duration::from_millis(20).as_nanos(); assert!( - full_waiting_delta < Duration::from_millis(20).as_nanos(), + full_waiting_delta < LIMIT, "full waiting delta was above threshold: {} > {}", full_waiting_delta, - Duration::from_millis(20).as_nanos() + LIMIT ); trace!("run: {}", full_run_delta); From 20e0d3f73321d73f07aa8e3ef41fc68c20bb6429 Mon Sep 17 00:00:00 2001 From: iximeow Date: Thu, 20 Feb 2025 01:11:29 +0000 Subject: [PATCH 08/14] YAY happy with it --- phd-tests/framework/src/test_vm/metrics.rs | 18 +++++++++--------- phd-tests/framework/src/test_vm/mod.rs | 4 ++-- phd-tests/tests/src/stats.rs | 4 ++-- 3 files changed, 13 insertions(+), 13 deletions(-) diff --git a/phd-tests/framework/src/test_vm/metrics.rs b/phd-tests/framework/src/test_vm/metrics.rs index df8c180bb..d10742f4a 100644 --- a/phd-tests/framework/src/test_vm/metrics.rs +++ b/phd-tests/framework/src/test_vm/metrics.rs @@ -25,7 +25,7 @@ fn test_logger() -> Logger { Logger::root(drain, slog::o!("component" => "fake-cleanup-task")) } -struct PropolisOximeterSampler { +struct OximeterProducerInfo { addr: std::net::SocketAddr, uuid: Uuid, } @@ -35,8 +35,8 @@ pub(crate) struct FakeOximeterServer { } pub(crate) struct FakeOximeterServerState { - sampler_sender: watch::Sender>, - sampler: watch::Receiver>, + sampler_sender: watch::Sender>, + sampler: watch::Receiver>, } impl FakeOximeterServer { @@ -44,15 +44,15 @@ impl FakeOximeterServer { self.server.local_addr() } - pub fn sampler(&self) -> FakeOximeterContext { - FakeOximeterContext { + pub fn sampler(&self) -> FakeOximeterSampler { + FakeOximeterSampler { sampler: self.server.app_private().sampler.clone(), } } } -pub struct FakeOximeterContext { - sampler: watch::Receiver>, +pub struct FakeOximeterSampler { + sampler: watch::Receiver>, } impl FakeOximeterServerState { @@ -68,7 +68,7 @@ impl FakeOximeterServerState { assert_eq!(info.kind, ProducerKind::Instance); let new_sampler = - PropolisOximeterSampler { addr: info.address, uuid: info.id }; + OximeterProducerInfo { addr: info.address, uuid: info.id }; // There should always be at least one Receiver on the channel since we // hold one in `self`. @@ -78,7 +78,7 @@ impl FakeOximeterServerState { } } -impl FakeOximeterContext { +impl FakeOximeterSampler { /// Sample Propolis' Oximeter metrics, taking some function that determines /// if a sample is satisfactory for the caller to proceed with. /// diff --git a/phd-tests/framework/src/test_vm/mod.rs b/phd-tests/framework/src/test_vm/mod.rs index 8ab99ef1b..87acb61e6 100644 --- a/phd-tests/framework/src/test_vm/mod.rs +++ b/phd-tests/framework/src/test_vm/mod.rs @@ -57,7 +57,7 @@ pub(crate) mod spec; pub use config::*; pub use environment::{MetricsLocation, VmLocation}; -pub use metrics::FakeOximeterContext; +pub use metrics::FakeOximeterSampler; use self::environment::EnvironmentSpec; @@ -291,7 +291,7 @@ impl TestVm { } } - pub fn metrics_sampler(&self) -> Option { + pub fn metrics_sampler(&self) -> Option { self.metrics.as_ref().map(|m| m.sampler()) } diff --git a/phd-tests/tests/src/stats.rs b/phd-tests/tests/src/stats.rs index c90444a97..dc3b012f9 100644 --- a/phd-tests/tests/src/stats.rs +++ b/phd-tests/tests/src/stats.rs @@ -6,7 +6,7 @@ use std::collections::HashMap; use std::str::FromStr; use std::time::Duration; -use phd_framework::test_vm::{FakeOximeterContext, MetricsLocation}; +use phd_framework::test_vm::{FakeOximeterSampler, MetricsLocation}; use chrono::{DateTime, Utc}; use oximeter::types::{ProducerResults, ProducerResultsItem, Sample}; @@ -64,7 +64,7 @@ struct VirtualMachineMetrics { /// Collect a record of all metrics for a VM as of the time this function is called. async fn vm_metrics_snapshot( - sampler: &FakeOximeterContext, + sampler: &FakeOximeterSampler, ) -> VirtualMachineMetrics { let min_metric_time = Utc::now(); From c9c348a9fe6e459425931305d6fbe3b7affa6d1b Mon Sep 17 00:00:00 2001 From: iximeow Date: Thu, 20 Feb 2025 01:16:15 +0000 Subject: [PATCH 09/14] clippy is right --- phd-tests/framework/src/test_vm/metrics.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/phd-tests/framework/src/test_vm/metrics.rs b/phd-tests/framework/src/test_vm/metrics.rs index d10742f4a..8d88e40c7 100644 --- a/phd-tests/framework/src/test_vm/metrics.rs +++ b/phd-tests/framework/src/test_vm/metrics.rs @@ -99,7 +99,7 @@ impl FakeOximeterSampler { }, || async { let producer_results = self.sample_propolis_stats().await - .map_err(|e| backoff::Error::transient(e))?; + .map_err(backoff::Error::transient)?; if let Some(metrics) = f(producer_results) { Ok(metrics) From be7f609de209badaddca5805a3b4ee5a7e7f530f Mon Sep 17 00:00:00 2001 From: iximeow Date: Thu, 20 Feb 2025 01:17:59 +0000 Subject: [PATCH 10/14] absolutely forgot the license header --- phd-tests/framework/src/test_vm/metrics.rs | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/phd-tests/framework/src/test_vm/metrics.rs b/phd-tests/framework/src/test_vm/metrics.rs index 8d88e40c7..1e24e288b 100644 --- a/phd-tests/framework/src/test_vm/metrics.rs +++ b/phd-tests/framework/src/test_vm/metrics.rs @@ -1,3 +1,7 @@ +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + use std::net::SocketAddr; use std::time::Duration; From 61734a12a9a18906635e4cc4ecdba3160cbac776 Mon Sep 17 00:00:00 2001 From: iximeow Date: Thu, 20 Feb 2025 17:49:01 +0000 Subject: [PATCH 11/14] urgh stray comment --- phd-tests/framework/src/test_vm/metrics.rs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/phd-tests/framework/src/test_vm/metrics.rs b/phd-tests/framework/src/test_vm/metrics.rs index 1e24e288b..4e0be28fc 100644 --- a/phd-tests/framework/src/test_vm/metrics.rs +++ b/phd-tests/framework/src/test_vm/metrics.rs @@ -148,10 +148,6 @@ impl FakeOximeterSampler { ); trace!(?res, "got stats response"); Ok(res.json::().await?) - /* - let results = - res.json::().await.expect("can deserialize"); - */ } } From e88d07c638c9ef3c103ba9f34f41b44c1c458807 Mon Sep 17 00:00:00 2001 From: iximeow Date: Wed, 5 Mar 2025 22:42:02 +0000 Subject: [PATCH 12/14] plumb Bunyan formatting through to spawned fake Oximeter this comes with a wider replumbing of log configuration, since it seems prudent to use the same log configuration for any supporting tasks (be they propolis-server itself, Crucible downstairs we spawn, or a fake Oximeter that happens to be in-process). one upside here is that conceivably an in-process task like fake Oximeter servers could be configured to write to a separate stdout/stderr file pair, if we could come up with useful unique filenames for them.. --- Cargo.lock | 1 + phd-tests/framework/Cargo.toml | 1 + phd-tests/framework/src/disk/crucible.rs | 17 ++++---- phd-tests/framework/src/disk/mod.rs | 10 ++--- phd-tests/framework/src/lib.rs | 12 +++--- .../src/{server_log_mode.rs => log_config.rs} | 42 +++++++++++++------ .../framework/src/test_vm/environment.rs | 2 +- phd-tests/framework/src/test_vm/metrics.rs | 31 ++++++++++---- phd-tests/framework/src/test_vm/mod.rs | 6 ++- phd-tests/framework/src/test_vm/server.rs | 8 ++-- phd-tests/runner/src/config.rs | 8 ++-- phd-tests/runner/src/main.rs | 18 ++++++-- 12 files changed, 105 insertions(+), 51 deletions(-) rename phd-tests/framework/src/{server_log_mode.rs => log_config.rs} (64%) diff --git a/Cargo.lock b/Cargo.lock index 9a9a2c8a6..c6cf0260d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3984,6 +3984,7 @@ dependencies = [ "serde_json", "slog", "slog-async", + "slog-bunyan", "slog-term", "tar", "termwiz", diff --git a/phd-tests/framework/Cargo.toml b/phd-tests/framework/Cargo.toml index b2be8ecb8..bb4bf0698 100644 --- a/phd-tests/framework/Cargo.toml +++ b/phd-tests/framework/Cargo.toml @@ -34,6 +34,7 @@ serde_derive.workspace = true serde_json.workspace = true slog.workspace = true slog-async.workspace = true +slog-bunyan.workspace = true slog-term.workspace = true tar.workspace = true termwiz.workspace = true diff --git a/phd-tests/framework/src/disk/crucible.rs b/phd-tests/framework/src/disk/crucible.rs index 5ac2f2747..3cc12adb7 100644 --- a/phd-tests/framework/src/disk/crucible.rs +++ b/phd-tests/framework/src/disk/crucible.rs @@ -21,9 +21,7 @@ use tracing::{error, info}; use uuid::Uuid; use super::BlockSize; -use crate::{ - disk::DeviceName, guest_os::GuestOsKind, server_log_mode::ServerLogMode, -}; +use crate::{disk::DeviceName, guest_os::GuestOsKind, log_config::LogConfig}; /// An RAII wrapper around a directory containing Crucible data files. Deletes /// the directory and its contents when dropped. @@ -79,7 +77,7 @@ impl CrucibleDisk { data_dir_root: &impl AsRef, read_only_parent: Option<&impl AsRef>, guest_os: Option, - log_mode: ServerLogMode, + log_config: LogConfig, ) -> anyhow::Result { Ok(Self { device_name, @@ -92,7 +90,7 @@ impl CrucibleDisk { downstairs_ports, data_dir_root, read_only_parent, - log_mode, + log_config, )?), }) } @@ -163,7 +161,7 @@ impl Inner { downstairs_ports: &[u16], data_dir_root: &impl AsRef, read_only_parent: Option<&impl AsRef>, - log_mode: ServerLogMode, + log_config: LogConfig, ) -> anyhow::Result { // To create a region, Crucible requires a block size, an extent size // given as a number of blocks, and an extent count. Compute the latter @@ -288,7 +286,12 @@ impl Inner { dir_arg.as_ref(), ]; - let (stdout, stderr) = log_mode.get_handles( + // NOTE: `log_format` is ignored here because Crucible determines + // Bunyan or plain formatting based on `atty::is()`. In practice + // this is fine, and matches what we want right now, but it might be + // nice to connect this more directly to the output desire expressed + // by the test runner. + let (stdout, stderr) = log_config.output_mode.get_handles( data_dir_root, &format!("crucible_{}_{}", disk_uuid, port), )?; diff --git a/phd-tests/framework/src/disk/mod.rs b/phd-tests/framework/src/disk/mod.rs index 0fbb542c4..21ff8b339 100644 --- a/phd-tests/framework/src/disk/mod.rs +++ b/phd-tests/framework/src/disk/mod.rs @@ -19,8 +19,8 @@ use thiserror::Error; use crate::{ artifacts::ArtifactStore, guest_os::GuestOsKind, + log_config::LogConfig, port_allocator::{PortAllocator, PortAllocatorError}, - server_log_mode::ServerLogMode, }; use self::{crucible::CrucibleDisk, file::FileBackedDisk}; @@ -190,7 +190,7 @@ pub(crate) struct DiskFactory { port_allocator: Arc, /// The logging discipline to use for Crucible server processes. - log_mode: ServerLogMode, + log_config: LogConfig, } impl DiskFactory { @@ -201,13 +201,13 @@ impl DiskFactory { storage_dir: &impl AsRef, artifact_store: Arc, port_allocator: Arc, - log_mode: ServerLogMode, + log_config: LogConfig, ) -> Self { Self { storage_dir: storage_dir.as_ref().to_path_buf(), artifact_store, port_allocator, - log_mode, + log_config, } } } @@ -325,7 +325,7 @@ impl DiskFactory { &self.storage_dir, artifact_path.as_ref(), guest_os, - self.log_mode, + self.log_config, ) .map(Arc::new) .map_err(Into::into) diff --git a/phd-tests/framework/src/lib.rs b/phd-tests/framework/src/lib.rs index 327b1804b..b9880982c 100644 --- a/phd-tests/framework/src/lib.rs +++ b/phd-tests/framework/src/lib.rs @@ -36,8 +36,8 @@ use camino::Utf8PathBuf; use disk::DiskFactory; use futures::{stream::FuturesUnordered, StreamExt}; use guest_os::GuestOsKind; +use log_config::LogConfig; use port_allocator::PortAllocator; -use server_log_mode::ServerLogMode; pub use test_vm::TestVm; use test_vm::{ environment::EnvironmentSpec, spec::VmSpec, VmConfig, VmLocation, @@ -52,16 +52,16 @@ pub mod disk; pub mod guest_os; pub mod host_api; pub mod lifecycle; +pub mod log_config; mod port_allocator; mod serial; -pub mod server_log_mode; pub mod test_vm; pub(crate) mod zfs; /// An instance of the PHD test framework. pub struct Framework { pub(crate) tmp_directory: Utf8PathBuf, - pub(crate) server_log_mode: ServerLogMode, + pub(crate) log_config: LogConfig, pub(crate) default_guest_cpus: u8, pub(crate) default_guest_memory_mib: u64, @@ -99,7 +99,7 @@ pub struct FrameworkParameters<'a> { pub tmp_directory: Utf8PathBuf, pub artifact_directory: Utf8PathBuf, pub artifact_toml: Utf8PathBuf, - pub server_log_mode: ServerLogMode, + pub log_config: LogConfig, pub default_guest_cpus: u8, pub default_guest_memory_mib: u64, @@ -187,14 +187,14 @@ impl Framework { ¶ms.tmp_directory, artifact_store.clone(), port_allocator.clone(), - params.server_log_mode, + params.log_config, ); let (cleanup_task_tx, cleanup_task_rx) = tokio::sync::mpsc::unbounded_channel(); Ok(Self { tmp_directory: params.tmp_directory, - server_log_mode: params.server_log_mode, + log_config: params.log_config, default_guest_cpus: params.default_guest_cpus, default_guest_memory_mib: params.default_guest_memory_mib, default_guest_os_artifact: params.default_guest_os_artifact, diff --git a/phd-tests/framework/src/server_log_mode.rs b/phd-tests/framework/src/log_config.rs similarity index 64% rename from phd-tests/framework/src/server_log_mode.rs rename to phd-tests/framework/src/log_config.rs index 536672970..f7efd8b02 100644 --- a/phd-tests/framework/src/server_log_mode.rs +++ b/phd-tests/framework/src/log_config.rs @@ -2,16 +2,23 @@ // License, v. 2.0. If a copy of the MPL was not distributed with this // file, You can obtain one at https://mozilla.org/MPL/2.0/. -//! Types and helpers specifying where a server process's stdout/stderr should -//! be recorded. +//! Types and helpers specifying how logs should be formatted and where they +//! should be directed. use std::{path::Path, process::Stdio, str::FromStr}; use tracing::info; -/// Specifies where a process's output should be written. +/// Specifies how a test's logging should be managed. #[derive(Debug, Clone, Copy)] -pub enum ServerLogMode { +pub struct LogConfig { + pub output_mode: OutputMode, + pub log_format: LogFormat, +} + +/// Specifies where a output for a test's processes should be written. +#[derive(Debug, Clone, Copy)] +pub enum OutputMode { /// Write to files in the server's factory's temporary directory. TmpFile, @@ -22,14 +29,14 @@ pub enum ServerLogMode { Null, } -impl FromStr for ServerLogMode { +impl FromStr for OutputMode { type Err = std::io::Error; fn from_str(s: &str) -> Result { match s.to_lowercase().as_str() { - "file" | "tmpfile" => Ok(ServerLogMode::TmpFile), - "stdio" => Ok(ServerLogMode::Stdio), - "null" => Ok(ServerLogMode::Null), + "file" | "tmpfile" => Ok(OutputMode::TmpFile), + "stdio" => Ok(OutputMode::Stdio), + "null" => Ok(OutputMode::Null), _ => Err(std::io::Error::new( std::io::ErrorKind::InvalidData, s.to_string(), @@ -38,7 +45,7 @@ impl FromStr for ServerLogMode { } } -impl ServerLogMode { +impl OutputMode { /// Returns the stdout/stderr handles to pass to processes using the /// specified logging mode. /// @@ -54,7 +61,7 @@ impl ServerLogMode { file_prefix: &str, ) -> anyhow::Result<(Stdio, Stdio)> { match self { - ServerLogMode::TmpFile => { + OutputMode::TmpFile => { let mut stdout_path = directory.as_ref().to_path_buf(); stdout_path.push(format!("{}.stdout.log", file_prefix)); @@ -67,8 +74,19 @@ impl ServerLogMode { std::fs::File::create(stderr_path)?.into(), )) } - ServerLogMode::Stdio => Ok((Stdio::inherit(), Stdio::inherit())), - ServerLogMode::Null => Ok((Stdio::null(), Stdio::null())), + OutputMode::Stdio => Ok((Stdio::inherit(), Stdio::inherit())), + OutputMode::Null => Ok((Stdio::null(), Stdio::null())), } } } + +/// Specifies how output for a test's processes should be structured. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum LogFormat { + /// Format logs as plain hopefully human-readable output. + Plain, + + /// Format logs as Bunyan output, more suitable for machine processing (such + /// as in CI). + Bunyan, +} diff --git a/phd-tests/framework/src/test_vm/environment.rs b/phd-tests/framework/src/test_vm/environment.rs index 58764cc54..a5375aebe 100644 --- a/phd-tests/framework/src/test_vm/environment.rs +++ b/phd-tests/framework/src/test_vm/environment.rs @@ -120,7 +120,7 @@ impl<'a> Environment<'a> { Ipv4Addr::new(127, 0, 0, 1), vnc_port, ), - log_mode: framework.server_log_mode, + log_config: framework.log_config, }; Ok(Self::Local(params)) } diff --git a/phd-tests/framework/src/test_vm/metrics.rs b/phd-tests/framework/src/test_vm/metrics.rs index 4e0be28fc..60570a593 100644 --- a/phd-tests/framework/src/test_vm/metrics.rs +++ b/phd-tests/framework/src/test_vm/metrics.rs @@ -4,7 +4,9 @@ use std::net::SocketAddr; use std::time::Duration; +use std::sync::{Arc, Mutex}; +use crate::log_config::{LogConfig, LogFormat}; use dropshot::{ endpoint, ApiDescription, ConfigDropshot, HttpError, HttpResponseCreated, HttpServer, HttpServerStarter, RequestContext, TypedBody, @@ -23,10 +25,23 @@ use uuid::Uuid; // elapses. const INTERVAL: Duration = Duration::from_secs(300); -fn test_logger() -> Logger { - let dec = slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter); - let drain = slog_term::FullFormat::new(dec).build().fuse(); - Logger::root(drain, slog::o!("component" => "fake-cleanup-task")) +fn oximeter_logger(log_config: LogConfig) -> Logger { + // Morally the fake Oximeter server is a distinct process that happens to + // cohabitate with the test process. If the log config is such that we want + // to log supporting processes to their own files, the Oximeter server's + // logs probably should be in distinct files too. + if log_config.log_format == LogFormat::Bunyan { + let drain = Arc::new(Mutex::new(slog_bunyan::default( + slog_term::TestStdoutWriter, + ))) + .fuse(); + Logger::root(drain, slog::o!("component" => "phd-oximeter-consumer")) + } else { + let dec = + slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter); + let drain = slog_term::FullFormat::new(dec).build().fuse(); + Logger::root(drain, slog::o!("component" => "phd-oximeter-consumer")) + } } struct OximeterProducerInfo { @@ -151,7 +166,7 @@ impl FakeOximeterSampler { } } -// Stub functionality for our fake Nexus that test Oximeter produces +// Stub functionality for our fake Nexus that test Oximeter producers // (`propolis-server`) will register with. #[endpoint { method = POST, @@ -172,8 +187,8 @@ async fn register_producer( // Start a Dropshot server mocking the Oximeter registration endpoint we would // expect from Nexus. -pub fn spawn_fake_oximeter_server() -> FakeOximeterServer { - let log = test_logger(); +pub fn spawn_fake_oximeter_server(log_config: LogConfig) -> FakeOximeterServer { + let log = oximeter_logger(log_config); let mut api = ApiDescription::new(); api.register(register_producer).expect("Expected to register endpoint"); @@ -192,7 +207,7 @@ pub fn spawn_fake_oximeter_server() -> FakeOximeterServer { slog::info!( log, - "fake nexus test server listening"; + "fake oximeter test server listening"; "address" => ?server.local_addr(), ); diff --git a/phd-tests/framework/src/test_vm/mod.rs b/phd-tests/framework/src/test_vm/mod.rs index bcfbf47a3..19ab5c8d8 100644 --- a/phd-tests/framework/src/test_vm/mod.rs +++ b/phd-tests/framework/src/test_vm/mod.rs @@ -237,7 +237,11 @@ impl TestVm { ) -> Result { let metrics = environment_spec.metrics.as_ref().map(|m| match m { MetricsLocation::Local => { - let metrics_server = metrics::spawn_fake_oximeter_server(); + // Our fake oximeter server should have the same logging + // discipline as any other subprocess we'd start in support of + // the test, so copy the config from `ServerProcessParameters`. + let metrics_server = + metrics::spawn_fake_oximeter_server(params.log_config); params.metrics_addr = Some(metrics_server.local_addr()); metrics_server } diff --git a/phd-tests/framework/src/test_vm/server.rs b/phd-tests/framework/src/test_vm/server.rs index 0744f3d66..5b2006592 100644 --- a/phd-tests/framework/src/test_vm/server.rs +++ b/phd-tests/framework/src/test_vm/server.rs @@ -14,7 +14,7 @@ use anyhow::Result; use camino::{Utf8Path, Utf8PathBuf}; use tracing::{debug, info}; -use crate::server_log_mode::ServerLogMode; +use crate::log_config::LogConfig; /// Parameters used to launch and configure the Propolis server process. These /// are distinct from the parameters used to configure the VM that that process @@ -38,7 +38,7 @@ pub struct ServerProcessParameters<'a> { /// The address at which the server should offer its VNC server. pub vnc_addr: SocketAddrV4, - pub log_mode: ServerLogMode, + pub log_config: LogConfig, } pub struct PropolisServer { @@ -58,7 +58,7 @@ impl PropolisServer { server_addr, metrics_addr, vnc_addr, - log_mode, + log_config, } = process_params; info!( @@ -69,7 +69,7 @@ impl PropolisServer { ); let (server_stdout, server_stderr) = - log_mode.get_handles(&data_dir, vm_name)?; + log_config.output_mode.get_handles(&data_dir, vm_name)?; let mut args = vec![server_path.into_string(), "run".to_string()]; diff --git a/phd-tests/runner/src/config.rs b/phd-tests/runner/src/config.rs index 1e152d08f..313d389d3 100644 --- a/phd-tests/runner/src/config.rs +++ b/phd-tests/runner/src/config.rs @@ -6,7 +6,7 @@ use anyhow::Context; use camino::Utf8PathBuf; use clap::{Args, Parser, Subcommand}; use phd_framework::{ - artifacts, server_log_mode::ServerLogMode, BasePropolisSource, + artifacts, log_config::OutputMode, BasePropolisSource, CrucibleDownstairsSource, }; use std::str::FromStr; @@ -143,8 +143,8 @@ pub struct RunOptions { #[clap(long, value_parser)] artifact_directory: Option, - /// If true, direct Propolis servers created by the runner to log to - /// stdout/stderr handles inherited from the runner. + /// Configure where Propolis servers and other processes created by the + /// runner to log to. /// /// Valid options are: /// @@ -154,7 +154,7 @@ pub struct RunOptions { /// /// - null: Don't log anywhere. #[clap(long, default_value = "file")] - pub server_logging_mode: ServerLogMode, + pub output_mode: OutputMode, /// The number of CPUs to assign to the guest in tests where the test is /// using the default machine configuration. diff --git a/phd-tests/runner/src/main.rs b/phd-tests/runner/src/main.rs index 225f5a45b..1a0ec0284 100644 --- a/phd-tests/runner/src/main.rs +++ b/phd-tests/runner/src/main.rs @@ -9,6 +9,7 @@ mod fixtures; use clap::Parser; use config::{ListOptions, ProcessArgs, RunOptions}; use phd_tests::phd_testcase::{Framework, FrameworkParameters}; +use phd_framework::log_config::{LogConfig, LogFormat}; use std::sync::Arc; use std::time::Duration; use tracing::{debug, info, warn}; @@ -36,7 +37,7 @@ async fn main() -> anyhow::Result<()> { match &runner_args.command { config::Command::Run(opts) => { - let exit_code = run_tests(opts).await?.tests_failed; + let exit_code = run_tests(opts, &runner_args).await?.tests_failed; debug!(exit_code); std::process::exit(exit_code.try_into().unwrap()); } @@ -46,7 +47,7 @@ async fn main() -> anyhow::Result<()> { Ok(()) } -async fn run_tests(run_opts: &RunOptions) -> anyhow::Result { +async fn run_tests(run_opts: &RunOptions, runner_args: &ProcessArgs) -> anyhow::Result { let ctx_params = FrameworkParameters { propolis_server_path: run_opts.propolis_server_cmd.clone(), crucible_downstairs: run_opts.crucible_downstairs()?, @@ -54,7 +55,18 @@ async fn run_tests(run_opts: &RunOptions) -> anyhow::Result { tmp_directory: run_opts.tmp_directory.clone(), artifact_directory: run_opts.artifact_directory(), artifact_toml: run_opts.artifact_toml_path.clone(), - server_log_mode: run_opts.server_logging_mode, + // We have to synthesize an actual LogConfig for the test because the + // log format - half of the config - is specified earlier to indicate + // log formatting for the runner itself. Reuse that setting to influence + // the formatting for tasks started by the runner during tests. + log_config: LogConfig { + output_mode: run_opts.output_mode, + log_format: if runner_args.emit_bunyan { + LogFormat::Bunyan + } else { + LogFormat::Plain + } + }, default_guest_cpus: run_opts.default_guest_cpus, default_guest_memory_mib: run_opts.default_guest_memory_mib, default_guest_os_artifact: run_opts.default_guest_artifact.clone(), From e42be6010125c87d4443f1d9918ff233e3e40674 Mon Sep 17 00:00:00 2001 From: iximeow Date: Wed, 5 Mar 2025 22:44:11 +0000 Subject: [PATCH 13/14] enable TSC enlightenment for the vCPU metrics test, refine comments unfortunately even with the TSC enlightenment passed along, guests can still cause nontrivial instruction emulation time even while "idle" by relying on the APIC for tasks of some sort or another. I don't really know *what* Windows does here, but on Linux guests we can still make strong assertions about expected emulation time. --- phd-tests/tests/src/stats.rs | 59 ++++++++++++++++++++++++------------ 1 file changed, 39 insertions(+), 20 deletions(-) diff --git a/phd-tests/tests/src/stats.rs b/phd-tests/tests/src/stats.rs index dc3b012f9..63c61d488 100644 --- a/phd-tests/tests/src/stats.rs +++ b/phd-tests/tests/src/stats.rs @@ -6,6 +6,8 @@ use std::collections::HashMap; use std::str::FromStr; use std::time::Duration; +use propolis_client::types::HyperVFeatureFlag; + use phd_framework::test_vm::{FakeOximeterSampler, MetricsLocation}; use chrono::{DateTime, Utc}; @@ -35,7 +37,7 @@ struct VcpuUsageMetric { /// /// Oximeter producers produce a series of lists of samples, where each list /// of samples is conceptually distinct but may still be interesting to -/// tset. In `propolis-server`, the first list of samples will be +/// test. In `propolis-server`, the first list of samples will be /// `virtual_machine:vcpu_usage`, which may be blank if kstats have not been /// sampled since the last producer poll. The second list of samples /// will be `virtual_machine:reset`. @@ -215,6 +217,18 @@ async fn instance_vcpu_stats(ctx: &Framework) { env.metrics(Some(MetricsLocation::Local)); let mut vm_config = ctx.vm_config_builder("instance_vcpu_stats"); + vm_config.guest_hv_interface( + propolis_client::types::GuestHypervisorInterface::HyperV { + features: vec![HyperVFeatureFlag::ReferenceTsc], + }, + ); + // Having one CPU simplifies the math for time expectations later in the + // test. One CPU means one second per second of time across all one vCPU's + // microstates, and if we have caused guest load the guest vCPU should + // be in "run" basically entirely until the load completes. + // + // Using the (configurable!) default "could" work, but this lets us avoid + // having to for additional probably-idle CPUs. vm_config.cpus(1); let mut vm = ctx.spawn_vm(&vm_config, Some(&env)).await?; @@ -367,26 +381,31 @@ async fn instance_vcpu_stats(ctx: &Framework) { - start_metrics.vcpu_state_total(&VcpuState::Emulation)) as u128; - // Pick 100ms as a comically high upper bound for how much time might have - // been spent emulating instructions on the guest's behalf. Anecdotally the - // this is on the order of 8ms between the two samples. This should be very - // low; the workload is almost entirely guest user mode execution. + // Theoretically 100ms would be a comically high upper bound for how much + // time we've spent emulating instructions on the guest's behalf during this + // test. In reality, the situation is more subtle. Guest OSes can be + // surprisingly heavy on the APIC, and if they believe the TSC is + // unreliable, heavy on the ACPI PM timer too. We've at least set up guest + // enlightments to present a reliable TSC, so as long as the guest picks up + // that enlightenment and does not fall back to the ACPI PM timer, that + // source of instruction emulation activity is quashed. + // + // So, it's hard to make a universal statement about how much time should be + // spent emulating instructions here. Instead, only check this if we know + // the guest is going to result in predictable times. Specifically: expect + // that Linux doesn't use the APIC much while idle and trusts the HyperV TSC + // enlightenment, and so is a candidate for reliable assertions on + // instruction emulation time. if vm.guest_os_kind().is_linux() { - // Unfortunately, the above is currently too optimistic in the general - // case of arbitrary guest OSes - if a guest OS has idle services, and - // those idle services involve checking the current time, and the guest - // has determined the TSC is unreliable, we may count substantial - // emulation time due to emulating guest accesses to the ACPI PM timer. - // - // Linux guests are known to not (currently?) consult the current time - // if fully idle, so we can be more precise about emulation time - // assertions. - const LIMIT: u128 = Duration::from_millis(100).as_nanos(); + const EMUL_LIMIT: u128 = Duration::from_millis(100).as_nanos(); + // As of writing this test, `full_emul_delta` is around 12-13ms with an + // Alpine guest. 100ms is hopefully plenty of margin for slower or + // busier test systems, or reasonable implementation changes. assert!( - full_emul_delta < LIMIT, + full_emul_delta < EMUL_LIMIT, "full emul delta was above threshold: {} > {}", full_emul_delta, - LIMIT + EMUL_LIMIT ); } else { warn!( @@ -400,12 +419,12 @@ async fn instance_vcpu_stats(ctx: &Framework) { // short duration, and on my workstation this is around 400 microseconds. // Again, test against a significantly larger threshold in case CI is // extremely slow. - const LIMIT: u128 = Duration::from_millis(20).as_nanos(); + const WAIT_LIMIT: u128 = Duration::from_millis(20).as_nanos(); assert!( - full_waiting_delta < LIMIT, + full_waiting_delta < WAIT_LIMIT, "full waiting delta was above threshold: {} > {}", full_waiting_delta, - LIMIT + WAIT_LIMIT ); trace!("run: {}", full_run_delta); From 7bbbee3d701e90383a5acd3f6d00ac1f989847ac Mon Sep 17 00:00:00 2001 From: iximeow Date: Wed, 5 Mar 2025 22:46:32 +0000 Subject: [PATCH 14/14] rustfmt --- phd-tests/framework/src/test_vm/metrics.rs | 2 +- phd-tests/runner/src/main.rs | 9 ++++++--- phd-tests/tests/src/stats.rs | 3 +-- 3 files changed, 8 insertions(+), 6 deletions(-) diff --git a/phd-tests/framework/src/test_vm/metrics.rs b/phd-tests/framework/src/test_vm/metrics.rs index 60570a593..4d65292ea 100644 --- a/phd-tests/framework/src/test_vm/metrics.rs +++ b/phd-tests/framework/src/test_vm/metrics.rs @@ -3,8 +3,8 @@ // file, You can obtain one at https://mozilla.org/MPL/2.0/. use std::net::SocketAddr; -use std::time::Duration; use std::sync::{Arc, Mutex}; +use std::time::Duration; use crate::log_config::{LogConfig, LogFormat}; use dropshot::{ diff --git a/phd-tests/runner/src/main.rs b/phd-tests/runner/src/main.rs index 1a0ec0284..087d8d479 100644 --- a/phd-tests/runner/src/main.rs +++ b/phd-tests/runner/src/main.rs @@ -8,8 +8,8 @@ mod fixtures; use clap::Parser; use config::{ListOptions, ProcessArgs, RunOptions}; -use phd_tests::phd_testcase::{Framework, FrameworkParameters}; use phd_framework::log_config::{LogConfig, LogFormat}; +use phd_tests::phd_testcase::{Framework, FrameworkParameters}; use std::sync::Arc; use std::time::Duration; use tracing::{debug, info, warn}; @@ -47,7 +47,10 @@ async fn main() -> anyhow::Result<()> { Ok(()) } -async fn run_tests(run_opts: &RunOptions, runner_args: &ProcessArgs) -> anyhow::Result { +async fn run_tests( + run_opts: &RunOptions, + runner_args: &ProcessArgs, +) -> anyhow::Result { let ctx_params = FrameworkParameters { propolis_server_path: run_opts.propolis_server_cmd.clone(), crucible_downstairs: run_opts.crucible_downstairs()?, @@ -65,7 +68,7 @@ async fn run_tests(run_opts: &RunOptions, runner_args: &ProcessArgs) -> anyhow:: LogFormat::Bunyan } else { LogFormat::Plain - } + }, }, default_guest_cpus: run_opts.default_guest_cpus, default_guest_memory_mib: run_opts.default_guest_memory_mib, diff --git a/phd-tests/tests/src/stats.rs b/phd-tests/tests/src/stats.rs index 63c61d488..f7a962e4b 100644 --- a/phd-tests/tests/src/stats.rs +++ b/phd-tests/tests/src/stats.rs @@ -6,9 +6,8 @@ use std::collections::HashMap; use std::str::FromStr; use std::time::Duration; -use propolis_client::types::HyperVFeatureFlag; - use phd_framework::test_vm::{FakeOximeterSampler, MetricsLocation}; +use propolis_client::types::HyperVFeatureFlag; use chrono::{DateTime, Utc}; use oximeter::types::{ProducerResults, ProducerResultsItem, Sample};