xref: /cloud-hypervisor/performance-metrics/src/performance_tests.rs (revision 5641e3a283db4149052b1e9278c640bcef8a000e)
1 // Copyright © 2022 Intel Corporation
2 //
3 // SPDX-License-Identifier: Apache-2.0
4 //
5 
6 // Performance tests
7 
8 use crate::{mean, PerformanceTestControl};
9 use std::fs;
10 use std::path::PathBuf;
11 use std::string::String;
12 use std::thread;
13 use std::time::Duration;
14 use test_infra::Error as InfraError;
15 use test_infra::*;
16 
17 #[cfg(target_arch = "x86_64")]
18 pub const FOCAL_IMAGE_NAME: &str = "focal-server-cloudimg-amd64-custom-20210609-0.raw";
19 #[cfg(target_arch = "aarch64")]
20 pub const FOCAL_IMAGE_NAME: &str = "focal-server-cloudimg-arm64-custom-20210929-0-update-tool.raw";
21 
22 #[allow(dead_code)]
23 #[derive(Debug)]
24 enum Error {
25     BootTimeParse,
26     Infra(InfraError),
27 }
28 
29 impl From<InfraError> for Error {
30     fn from(e: InfraError) -> Self {
31         Self::Infra(e)
32     }
33 }
34 
35 const BLK_IO_TEST_IMG: &str = "/var/tmp/ch-blk-io-test.img";
36 
37 pub fn init_tests() {
38     // The test image can not be created on tmpfs (e.g. /tmp) filesystem,
39     // as tmpfs does not support O_DIRECT
40     assert!(exec_host_command_output(&format!(
41         "dd if=/dev/zero of={BLK_IO_TEST_IMG} bs=1M count=4096"
42     ))
43     .status
44     .success());
45 }
46 
47 pub fn cleanup_tests() {
48     fs::remove_file(BLK_IO_TEST_IMG)
49         .unwrap_or_else(|_| panic!("Failed to remove file '{BLK_IO_TEST_IMG}'."));
50 }
51 
52 // Performance tests are expected to be executed sequentially, so we can
53 // start VM guests with the same IP while putting them on a different
54 // private network. The default constructor "Guest::new()" does not work
55 // well, as we can easily create more than 256 VMs from repeating various
56 // performance tests dozens times in a single run.
57 fn performance_test_new_guest(disk_config: Box<dyn DiskConfig>) -> Guest {
58     Guest::new_from_ip_range(disk_config, "172.19", 0)
59 }
60 
61 const DIRECT_KERNEL_BOOT_CMDLINE: &str =
62     "root=/dev/vda1 console=hvc0 rw systemd.journald.forward_to_console=1";
63 
64 // Creates the path for direct kernel boot and return the path.
65 // For x86_64, this function returns the vmlinux kernel path.
66 // For AArch64, this function returns the PE kernel path.
67 fn direct_kernel_boot_path() -> PathBuf {
68     let mut workload_path = dirs::home_dir().unwrap();
69     workload_path.push("workloads");
70 
71     let mut kernel_path = workload_path;
72     #[cfg(target_arch = "x86_64")]
73     kernel_path.push("vmlinux");
74     #[cfg(target_arch = "aarch64")]
75     kernel_path.push("Image");
76 
77     kernel_path
78 }
79 
80 pub fn performance_net_throughput(control: &PerformanceTestControl) -> f64 {
81     let test_timeout = control.test_timeout;
82     let (rx, bandwidth) = control.net_control.unwrap();
83 
84     let focal = UbuntuDiskConfig::new(FOCAL_IMAGE_NAME.to_string());
85     let guest = performance_test_new_guest(Box::new(focal));
86 
87     let num_queues = control.num_queues.unwrap();
88     let queue_size = control.queue_size.unwrap();
89     let net_params = format!(
90         "tap=,mac={},ip={},mask=255.255.255.0,num_queues={},queue_size={}",
91         guest.network.guest_mac, guest.network.host_ip, num_queues, queue_size,
92     );
93 
94     let mut child = GuestCommand::new(&guest)
95         .args(["--cpus", &format!("boot={num_queues}")])
96         .args(["--memory", "size=4G"])
97         .args(["--kernel", direct_kernel_boot_path().to_str().unwrap()])
98         .args(["--cmdline", DIRECT_KERNEL_BOOT_CMDLINE])
99         .default_disks()
100         .args(["--net", net_params.as_str()])
101         .capture_output()
102         .verbosity(VerbosityLevel::Warn)
103         .set_print_cmd(false)
104         .spawn()
105         .unwrap();
106 
107     let r = std::panic::catch_unwind(|| {
108         guest.wait_vm_boot(None).unwrap();
109         measure_virtio_net_throughput(test_timeout, num_queues / 2, &guest, rx, bandwidth).unwrap()
110     });
111 
112     let _ = child.kill();
113     let output = child.wait_with_output().unwrap();
114 
115     match r {
116         Ok(r) => r,
117         Err(e) => {
118             handle_child_output(Err(e), &output);
119             panic!("test failed!");
120         }
121     }
122 }
123 
124 pub fn performance_net_latency(control: &PerformanceTestControl) -> f64 {
125     let focal = UbuntuDiskConfig::new(FOCAL_IMAGE_NAME.to_string());
126     let guest = performance_test_new_guest(Box::new(focal));
127 
128     let num_queues = control.num_queues.unwrap();
129     let queue_size = control.queue_size.unwrap();
130     let net_params = format!(
131         "tap=,mac={},ip={},mask=255.255.255.0,num_queues={},queue_size={}",
132         guest.network.guest_mac, guest.network.host_ip, num_queues, queue_size,
133     );
134 
135     let mut child = GuestCommand::new(&guest)
136         .args(["--cpus", &format!("boot={num_queues}")])
137         .args(["--memory", "size=4G"])
138         .args(["--kernel", direct_kernel_boot_path().to_str().unwrap()])
139         .args(["--cmdline", DIRECT_KERNEL_BOOT_CMDLINE])
140         .default_disks()
141         .args(["--net", net_params.as_str()])
142         .capture_output()
143         .verbosity(VerbosityLevel::Warn)
144         .set_print_cmd(false)
145         .spawn()
146         .unwrap();
147 
148     let r = std::panic::catch_unwind(|| {
149         guest.wait_vm_boot(None).unwrap();
150 
151         // 'ethr' tool will measure the latency multiple times with provided test time
152         let latency = measure_virtio_net_latency(&guest, control.test_timeout).unwrap();
153         mean(&latency).unwrap()
154     });
155 
156     let _ = child.kill();
157     let output = child.wait_with_output().unwrap();
158 
159     match r {
160         Ok(r) => r,
161         Err(e) => {
162             handle_child_output(Err(e), &output);
163             panic!("test failed!");
164         }
165     }
166 }
167 
168 fn parse_boot_time_output(output: &[u8]) -> Result<f64, Error> {
169     std::panic::catch_unwind(|| {
170         let l: Vec<String> = String::from_utf8_lossy(output)
171             .lines()
172             .filter(|l| l.contains("Debug I/O port: Kernel code"))
173             .map(|l| l.to_string())
174             .collect();
175 
176         assert_eq!(
177             l.len(),
178             2,
179             "Expecting two matching lines for 'Debug I/O port: Kernel code'"
180         );
181 
182         let time_stamp_kernel_start = {
183             let s = l[0].split("--").collect::<Vec<&str>>();
184             assert_eq!(
185                 s.len(),
186                 2,
187                 "Expecting '--' for the matching line of 'Debug I/O port' output"
188             );
189 
190             // Sample output: "[Debug I/O port: Kernel code 0x40] 0.096537 seconds"
191             assert!(
192                 s[1].contains("0x40"),
193                 "Expecting kernel code '0x40' for 'linux_kernel_start' time stamp output"
194             );
195             let t = s[1].split_whitespace().collect::<Vec<&str>>();
196             assert_eq!(
197                 t.len(),
198                 8,
199                 "Expecting exact '8' words from the 'Debug I/O port' output"
200             );
201             assert!(
202                 t[7].eq("seconds"),
203                 "Expecting 'seconds' as the the last word of the 'Debug I/O port' output"
204             );
205 
206             t[6].parse::<f64>().unwrap()
207         };
208 
209         let time_stamp_user_start = {
210             let s = l[1].split("--").collect::<Vec<&str>>();
211             assert_eq!(
212                 s.len(),
213                 2,
214                 "Expecting '--' for the matching line of 'Debug I/O port' output"
215             );
216 
217             // Sample output: "Debug I/O port: Kernel code 0x41] 0.198980 seconds"
218             assert!(
219                 s[1].contains("0x41"),
220                 "Expecting kernel code '0x41' for 'linux_kernel_start' time stamp output"
221             );
222             let t = s[1].split_whitespace().collect::<Vec<&str>>();
223             assert_eq!(
224                 t.len(),
225                 8,
226                 "Expecting exact '8' words from the 'Debug I/O port' output"
227             );
228             assert!(
229                 t[7].eq("seconds"),
230                 "Expecting 'seconds' as the the last word of the 'Debug I/O port' output"
231             );
232 
233             t[6].parse::<f64>().unwrap()
234         };
235 
236         time_stamp_user_start - time_stamp_kernel_start
237     })
238     .map_err(|_| {
239         eprintln!(
240             "=============== boot-time output ===============\n\n{}\n\n===========end============\n\n",
241             String::from_utf8_lossy(output)
242         );
243         Error::BootTimeParse
244     })
245 }
246 
247 fn measure_boot_time(cmd: &mut GuestCommand, test_timeout: u32) -> Result<f64, Error> {
248     let mut child = cmd
249         .capture_output()
250         .verbosity(VerbosityLevel::Warn)
251         .set_print_cmd(false)
252         .spawn()
253         .unwrap();
254 
255     thread::sleep(Duration::new(test_timeout as u64, 0));
256     let _ = child.kill();
257     let output = child.wait_with_output().unwrap();
258 
259     parse_boot_time_output(&output.stderr).map_err(|e| {
260         eprintln!(
261             "\n\n==== Start child stdout ====\n\n{}\n\n==== End child stdout ====",
262             String::from_utf8_lossy(&output.stdout)
263         );
264         eprintln!(
265             "\n\n==== Start child stderr ====\n\n{}\n\n==== End child stderr ====",
266             String::from_utf8_lossy(&output.stderr)
267         );
268 
269         e
270     })
271 }
272 
273 pub fn performance_boot_time(control: &PerformanceTestControl) -> f64 {
274     let r = std::panic::catch_unwind(|| {
275         let focal = UbuntuDiskConfig::new(FOCAL_IMAGE_NAME.to_string());
276         let guest = performance_test_new_guest(Box::new(focal));
277         let mut cmd = GuestCommand::new(&guest);
278 
279         let c = cmd
280             .args([
281                 "--cpus",
282                 &format!("boot={}", control.num_boot_vcpus.unwrap_or(1)),
283             ])
284             .args(["--memory", "size=1G"])
285             .args(["--kernel", direct_kernel_boot_path().to_str().unwrap()])
286             .args(["--cmdline", DIRECT_KERNEL_BOOT_CMDLINE])
287             .args(["--console", "off"])
288             .default_disks();
289 
290         measure_boot_time(c, control.test_timeout).unwrap()
291     });
292 
293     match r {
294         Ok(r) => r,
295         Err(_) => {
296             panic!("test failed!");
297         }
298     }
299 }
300 
301 pub fn performance_boot_time_pmem(control: &PerformanceTestControl) -> f64 {
302     let r = std::panic::catch_unwind(|| {
303         let focal = UbuntuDiskConfig::new(FOCAL_IMAGE_NAME.to_string());
304         let guest = performance_test_new_guest(Box::new(focal));
305         let mut cmd = GuestCommand::new(&guest);
306         let c = cmd
307             .args([
308                 "--cpus",
309                 &format!("boot={}", control.num_boot_vcpus.unwrap_or(1)),
310             ])
311             .args(["--memory", "size=1G,hugepages=on"])
312             .args(["--kernel", direct_kernel_boot_path().to_str().unwrap()])
313             .args(["--cmdline", "root=/dev/pmem0p1 console=ttyS0 quiet rw"])
314             .args(["--console", "off"])
315             .args([
316                 "--pmem",
317                 format!(
318                     "file={}",
319                     guest.disk_config.disk(DiskType::OperatingSystem).unwrap()
320                 )
321                 .as_str(),
322             ]);
323 
324         measure_boot_time(c, control.test_timeout).unwrap()
325     });
326 
327     match r {
328         Ok(r) => r,
329         Err(_) => {
330             panic!("test failed!");
331         }
332     }
333 }
334 
335 pub fn performance_block_io(control: &PerformanceTestControl) -> f64 {
336     let test_timeout = control.test_timeout;
337     let num_queues = control.num_queues.unwrap();
338     let (fio_ops, bandwidth) = control.fio_control.as_ref().unwrap();
339 
340     let focal = UbuntuDiskConfig::new(FOCAL_IMAGE_NAME.to_string());
341     let guest = performance_test_new_guest(Box::new(focal));
342     let api_socket = guest
343         .tmp_dir
344         .as_path()
345         .join("cloud-hypervisor.sock")
346         .to_str()
347         .unwrap()
348         .to_string();
349 
350     let mut child = GuestCommand::new(&guest)
351         .args(["--cpus", &format!("boot={num_queues}")])
352         .args(["--memory", "size=4G"])
353         .args(["--kernel", direct_kernel_boot_path().to_str().unwrap()])
354         .args(["--cmdline", DIRECT_KERNEL_BOOT_CMDLINE])
355         .args([
356             "--disk",
357             format!(
358                 "path={}",
359                 guest.disk_config.disk(DiskType::OperatingSystem).unwrap()
360             )
361             .as_str(),
362             format!(
363                 "path={}",
364                 guest.disk_config.disk(DiskType::CloudInit).unwrap()
365             )
366             .as_str(),
367             format!("path={BLK_IO_TEST_IMG}").as_str(),
368         ])
369         .default_net()
370         .args(["--api-socket", &api_socket])
371         .capture_output()
372         .verbosity(VerbosityLevel::Warn)
373         .set_print_cmd(false)
374         .spawn()
375         .unwrap();
376 
377     let r = std::panic::catch_unwind(|| {
378         guest.wait_vm_boot(None).unwrap();
379 
380         let fio_command = format!(
381             "sudo fio --filename=/dev/vdc --name=test --output-format=json \
382             --direct=1 --bs=4k --ioengine=io_uring --iodepth=64 \
383             --rw={fio_ops} --runtime={test_timeout} --numjobs={num_queues}"
384         );
385         let output = guest
386             .ssh_command(&fio_command)
387             .map_err(InfraError::SshCommand)
388             .unwrap();
389 
390         // Parse fio output
391         if *bandwidth {
392             parse_fio_output(&output, fio_ops, num_queues).unwrap()
393         } else {
394             parse_fio_output_iops(&output, fio_ops, num_queues).unwrap()
395         }
396     });
397 
398     let _ = child.kill();
399     let output = child.wait_with_output().unwrap();
400 
401     match r {
402         Ok(r) => r,
403         Err(e) => {
404             handle_child_output(Err(e), &output);
405             panic!("test failed!");
406         }
407     }
408 }
409 
410 #[cfg(test)]
411 mod tests {
412     use super::*;
413 
414     #[test]
415     fn test_parse_iperf3_output() {
416         let output = r#"
417 {
418 	"end":	{
419 		"sum_sent":	{
420 			"start":	0,
421 			"end":	5.000196,
422 			"seconds":	5.000196,
423 			"bytes":	14973836248,
424 			"bits_per_second":	23957198874.604115,
425 			"retransmits":	0,
426 			"sender":	false
427 		}
428 	}
429 }
430        "#;
431         assert_eq!(
432             parse_iperf3_output(output.as_bytes(), true, true).unwrap(),
433             23957198874.604115
434         );
435 
436         let output = r#"
437 {
438 	"end":	{
439 		"sum_received":	{
440 			"start":	0,
441 			"end":	5.000626,
442 			"seconds":	5.000626,
443 			"bytes":	24703557800,
444 			"bits_per_second":	39520744482.79,
445 			"sender":	true
446 		}
447 	}
448 }
449               "#;
450         assert_eq!(
451             parse_iperf3_output(output.as_bytes(), false, true).unwrap(),
452             39520744482.79
453         );
454         let output = r#"
455 {
456     "end":	{
457         "sum":  {
458             "start":        0,
459             "end":  5.000036,
460             "seconds":      5.000036,
461             "bytes":        29944971264,
462             "bits_per_second":      47911877363.396217,
463             "jitter_ms":    0.0038609822983198556,
464             "lost_packets": 16,
465             "packets":      913848,
466             "lost_percent": 0.0017508382137948542,
467             "sender":       true
468         }
469     }
470 }
471               "#;
472         assert_eq!(
473             parse_iperf3_output(output.as_bytes(), true, false).unwrap(),
474             182765.08409139456
475         );
476     }
477 
478     #[test]
479     fn test_parse_ethr_latency_output() {
480         let output = r#"{"Time":"2022-02-08T03:52:50Z","Title":"","Type":"INFO","Message":"Using destination: 192.168.249.2, ip: 192.168.249.2, port: 8888"}
481 {"Time":"2022-02-08T03:52:51Z","Title":"","Type":"INFO","Message":"Running latency test: 1000, 1"}
482 {"Time":"2022-02-08T03:52:51Z","Title":"","Type":"LatencyResult","RemoteAddr":"192.168.249.2","Protocol":"TCP","Avg":"80.712us","Min":"61.677us","P50":"257.014us","P90":"74.418us","P95":"107.283us","P99":"119.309us","P999":"142.100us","P9999":"216.341us","Max":"216.341us"}
483 {"Time":"2022-02-08T03:52:52Z","Title":"","Type":"LatencyResult","RemoteAddr":"192.168.249.2","Protocol":"TCP","Avg":"79.826us","Min":"55.129us","P50":"598.996us","P90":"73.849us","P95":"106.552us","P99":"122.152us","P999":"142.459us","P9999":"474.280us","Max":"474.280us"}
484 {"Time":"2022-02-08T03:52:53Z","Title":"","Type":"LatencyResult","RemoteAddr":"192.168.249.2","Protocol":"TCP","Avg":"78.239us","Min":"56.999us","P50":"396.820us","P90":"69.469us","P95":"115.421us","P99":"119.404us","P999":"130.158us","P9999":"258.686us","Max":"258.686us"}"#;
485 
486         let ret = parse_ethr_latency_output(output.as_bytes()).unwrap();
487         let reference = vec![80.712_f64, 79.826_f64, 78.239_f64];
488         assert_eq!(ret, reference);
489     }
490 
491     #[test]
492     fn test_parse_boot_time_output() {
493         let output = r#"
494 cloud-hypervisor: 161.167103ms: <vcpu0> INFO:vmm/src/vm.rs:392 -- [Debug I/O port: Kernel code 0x40] 0.132 seconds
495 cloud-hypervisor: 613.57361ms: <vcpu0> INFO:vmm/src/vm.rs:392 -- [Debug I/O port: Kernel code 0x41] 0.5845 seconds
496         "#;
497 
498         assert_eq!(parse_boot_time_output(output.as_bytes()).unwrap(), 0.4525);
499     }
500 
501     #[test]
502     fn test_parse_fio_output() {
503         let output = r#"
504 {
505   "jobs" : [
506     {
507       "read" : {
508         "io_bytes" : 1965273088,
509         "io_kbytes" : 1919212,
510         "bw_bytes" : 392976022,
511         "bw" : 383765,
512         "iops" : 95941.411718,
513         "runtime" : 5001,
514         "total_ios" : 479803,
515         "short_ios" : 0,
516         "drop_ios" : 0
517       }
518     }
519   ]
520 }
521 "#;
522 
523         let bps = 1965273088_f64 / (5001_f64 / 1000_f64);
524         assert_eq!(
525             parse_fio_output(output, &FioOps::RandomRead, 1).unwrap(),
526             bps
527         );
528         assert_eq!(parse_fio_output(output, &FioOps::Read, 1).unwrap(), bps);
529 
530         let output = r#"
531 {
532   "jobs" : [
533     {
534       "write" : {
535         "io_bytes" : 1172783104,
536         "io_kbytes" : 1145296,
537         "bw_bytes" : 234462835,
538         "bw" : 228967,
539         "iops" : 57241.903239,
540         "runtime" : 5002,
541         "total_ios" : 286324,
542         "short_ios" : 0,
543         "drop_ios" : 0
544       }
545     },
546     {
547       "write" : {
548         "io_bytes" : 1172234240,
549         "io_kbytes" : 1144760,
550         "bw_bytes" : 234353106,
551         "bw" : 228860,
552         "iops" : 57215.113954,
553         "runtime" : 5002,
554         "total_ios" : 286190,
555         "short_ios" : 0,
556         "drop_ios" : 0
557       }
558     }
559   ]
560 }
561 "#;
562 
563         let bps = 1172783104_f64 / (5002_f64 / 1000_f64) + 1172234240_f64 / (5002_f64 / 1000_f64);
564         assert_eq!(
565             parse_fio_output(output, &FioOps::RandomWrite, 2).unwrap(),
566             bps
567         );
568         assert_eq!(parse_fio_output(output, &FioOps::Write, 2).unwrap(), bps);
569     }
570 }
571