diff --git a/docs/performance_metrics.md b/docs/performance_metrics.md index 33097653b..623ea86c0 100644 --- a/docs/performance_metrics.md +++ b/docs/performance_metrics.md @@ -31,6 +31,7 @@ $ ./scripts/dev_cli.sh tests --metrics -- -- --report-file /tmp/metrics.json --t ``` To set custom timeout or test iterations for all performance tests: + ``` $ ./scripts/dev_cli.sh tests --metrics -- -- --timeout 5 --iterations 10 ``` @@ -70,6 +71,7 @@ data. | | block_multi_queue_write_IOPS | 10 | 5 | | | block_multi_queue_random_read_IOPS | 10 | 5 | | | block_multi_queue_random_write_IOPS | 10 | 5 | +| Other | restore_latency_time_ms | 2 | 10 | ## Output Format @@ -84,7 +86,6 @@ param is set. The fields included in JSON include: | date | Date for executing the program | | results | A list of metrics | - ## Example Here is an example of generating metrics data for the boot time using diff --git a/performance-metrics/src/main.rs b/performance-metrics/src/main.rs index 843066cab..89c3f18c1 100644 --- a/performance-metrics/src/main.rs +++ b/performance-metrics/src/main.rs @@ -274,7 +274,7 @@ mod adjuster { } } -const TEST_LIST: [PerformanceTest; 29] = [ +const TEST_LIST: [PerformanceTest; 30] = [ PerformanceTest { name: "boot_time_ms", func_ptr: performance_boot_time, @@ -306,6 +306,16 @@ const TEST_LIST: [PerformanceTest; 29] = [ }, unit_adjuster: adjuster::s_to_ms, }, + PerformanceTest { + name: "restore_latency_time_ms", + func_ptr: performance_restore_latency, + control: PerformanceTestControl { + test_timeout: 2, + test_iterations: 10, + ..PerformanceTestControl::default() + }, + unit_adjuster: adjuster::identity, + }, PerformanceTest { name: "boot_time_16_vcpus_pmem_ms", func_ptr: performance_boot_time_pmem, diff --git a/performance-metrics/src/performance_tests.rs b/performance-metrics/src/performance_tests.rs index 95e679c7f..8d8c34256 100644 --- a/performance-metrics/src/performance_tests.rs +++ b/performance-metrics/src/performance_tests.rs @@ -23,6 +23,7 @@ pub const FOCAL_IMAGE_NAME: &str = "focal-server-cloudimg-arm64-custom-20210929- enum Error { BootTimeParse, Infra(InfraError), + RestoreTimeParse, } impl From for Error { @@ -76,6 +77,26 @@ fn direct_kernel_boot_path() -> PathBuf { kernel_path } +fn remote_command(api_socket: &str, command: &str, arg: Option<&str>) -> bool { + let mut cmd = std::process::Command::new(clh_command("ch-remote")); + cmd.args([&format!("--api-socket={}", api_socket), command]); + + if let Some(arg) = arg { + cmd.arg(arg); + } + let output = cmd.output().unwrap(); + if output.status.success() { + true + } else { + eprintln!( + "Error running ch-remote command: {:?}\nstderr: {}", + &cmd, + String::from_utf8_lossy(&output.stderr) + ); + false + } +} + pub fn performance_net_throughput(control: &PerformanceTestControl) -> f64 { let test_timeout = control.test_timeout; let (rx, bandwidth) = control.net_control.unwrap(); @@ -404,6 +425,120 @@ pub fn performance_block_io(control: &PerformanceTestControl) -> f64 { } } +// Parse the event_monitor file based on the format that each event +// is followed by a double newline +fn parse_event_file(event_file: &str) -> Vec { + let content = fs::read(event_file).unwrap(); + let mut ret = Vec::new(); + for entry in String::from_utf8_lossy(&content) + .trim() + .split("\n\n") + .collect::>() + { + ret.push(serde_json::from_str(entry).unwrap()); + } + ret +} + +fn parse_restore_time_output(events: &[serde_json::Value]) -> Result { + for entry in events.iter() { + if entry["event"].as_str().unwrap() == "restored" { + let duration = entry["timestamp"]["secs"].as_u64().unwrap() as f64 * 1_000f64 + + entry["timestamp"]["nanos"].as_u64().unwrap() as f64 / 1_000_000f64; + return Ok(duration); + } + } + Err(Error::RestoreTimeParse) +} + +fn measure_restore_time( + cmd: &mut GuestCommand, + event_file: &str, + test_timeout: u32, +) -> Result { + let mut child = cmd + .capture_output() + .verbosity(VerbosityLevel::Warn) + .set_print_cmd(false) + .spawn() + .unwrap(); + + thread::sleep(Duration::new((test_timeout / 2) as u64, 0)); + let _ = child.kill(); + let output = child.wait_with_output().unwrap(); + + let json_events = parse_event_file(event_file); + + parse_restore_time_output(&json_events).inspect_err(|_| { + eprintln!( + "\n\n==== Start child stdout ====\n\n{}\n\n==== End child stdout ====\ + \n\n==== Start child stderr ====\n\n{}\n\n==== End child stderr ====", + String::from_utf8_lossy(&output.stdout), + String::from_utf8_lossy(&output.stderr) + ) + }) +} + +pub fn performance_restore_latency(control: &PerformanceTestControl) -> f64 { + let r = std::panic::catch_unwind(|| { + let focal = UbuntuDiskConfig::new(FOCAL_IMAGE_NAME.to_string()); + let guest = performance_test_new_guest(Box::new(focal)); + let api_socket_source = String::from( + guest + .tmp_dir + .as_path() + .join("cloud-hypervisor.sock") + .to_str() + .unwrap(), + ); + + let mut child = GuestCommand::new(&guest) + .args(["--api-socket", &api_socket_source]) + .args([ + "--cpus", + &format!("boot={}", control.num_boot_vcpus.unwrap_or(1)), + ]) + .args(["--memory", "size=256M"]) + .args(["--kernel", direct_kernel_boot_path().to_str().unwrap()]) + .args(["--cmdline", DIRECT_KERNEL_BOOT_CMDLINE]) + .args(["--console", "off"]) + .default_disks() + .set_print_cmd(false) + .spawn() + .unwrap(); + + thread::sleep(Duration::new((control.test_timeout / 2) as u64, 0)); + let snapshot_dir = String::from(guest.tmp_dir.as_path().join("snapshot").to_str().unwrap()); + std::fs::create_dir(&snapshot_dir).unwrap(); + assert!(remote_command(&api_socket_source, "pause", None)); + assert!(remote_command( + &api_socket_source, + "snapshot", + Some(format!("file://{}", snapshot_dir).as_str()), + )); + + let _ = child.kill(); + + let event_path = String::from(guest.tmp_dir.as_path().join("event.json").to_str().unwrap()); + let mut cmd = GuestCommand::new(&guest); + let c = cmd + .args([ + "--restore", + format!("source_url=file://{}", snapshot_dir).as_str(), + ]) + .args(["--event-monitor", format!("path={}", event_path).as_str()]); + + measure_restore_time(c, event_path.as_str(), control.test_timeout).unwrap() + }); + + match r { + Ok(r) => r, + Err(_) => { + panic!("test failed!"); + } + } +} + #[cfg(test)] mod tests { use super::*; @@ -494,7 +629,42 @@ cloud-hypervisor: 613.57361ms: INFO:vmm/src/vm.rs:392 -- [Debug I/O port assert_eq!(parse_boot_time_output(output.as_bytes()).unwrap(), 0.4525); } + #[test] + fn test_parse_restore_time_output() { + let output = r#" +{ + "timestamp": { + "secs": 0, + "nanos": 4664404 + }, + "source": "virtio-device", + "event": "activated", + "properties": { + "id": "__rng" + } +} +{ + "timestamp": { + "secs": 0, + "nanos": 5505133 + }, + "source": "vm", + "event": "restored", + "properties": null +} +"#; + let mut ret = Vec::new(); + for entry in String::from(output) + .trim() + .split("\n\n") + .collect::>() + { + ret.push(serde_json::from_str(entry).unwrap()); + } + + assert_eq!(parse_restore_time_output(&ret).unwrap(), 5.505133_f64); + } #[test] fn test_parse_fio_output() { let output = r#"