Skip to content

Commit 628530c

Browse files
committed
refactor(tests): update boot time device metrics
Emit both boot time metrics for boot device: clock time and cpu time. Additionally, stop subtracting VM build time from a guest boot time at the metric emit time. This can be done later at the visualization stage. Signed-off-by: Egor Lazarchuk <yegorlz@amazon.co.uk>
1 parent 19e012a commit 628530c

File tree

1 file changed

+22
-12
lines changed

1 file changed

+22
-12
lines changed

tests/integration_tests/performance/test_boottime.py

Lines changed: 22 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,6 @@
1111
from framework.properties import global_props
1212

1313
# Regex for obtaining boot time from some string.
14-
TIMESTAMP_LOG_REGEX = r"Guest-boot-time\s+\=\s+(\d+)\s+us"
1514

1615
DEFAULT_BOOT_ARGS = (
1716
"reboot=k panic=1 pci=off nomodule 8250.nr_uarts=0"
@@ -27,27 +26,32 @@
2726
}
2827

2928

30-
def _get_microvm_boottime(vm):
29+
def get_boottime_device_info(vm):
3130
"""Auxiliary function for asserting the expected boot time."""
3231
boot_time_us = None
32+
boot_time_cpu_us = None
3333
timestamps = []
3434

35+
timestamp_log_regex = (
36+
r"Guest-boot-time =\s+(\d+) us\s+(\d+) ms,\s+(\d+) CPU us\s+(\d+) CPU ms"
37+
)
38+
3539
iterations = 50
3640
sleep_time_s = 0.1
3741
for _ in range(iterations):
38-
timestamps = re.findall(TIMESTAMP_LOG_REGEX, vm.log_data)
42+
timestamps = re.findall(timestamp_log_regex, vm.log_data)
3943
if timestamps:
4044
break
4145
time.sleep(sleep_time_s)
4246
if timestamps:
43-
boot_time_us = int(timestamps[0])
47+
boot_time_us, _, boot_time_cpu_us, _ = timestamps[0]
4448

45-
assert boot_time_us, (
49+
assert boot_time_us and boot_time_cpu_us, (
4650
f"MicroVM did not boot within {sleep_time_s * iterations}s\n"
4751
f"Firecracker logs:\n{vm.log_data}\n"
4852
f"Thread backtraces:\n{vm.thread_backtraces}"
4953
)
50-
return boot_time_us
54+
return int(boot_time_us), int(boot_time_cpu_us)
5155

5256

5357
def find_events(log_data):
@@ -133,16 +137,22 @@ def test_boottime(
133137
vm.add_net_iface()
134138
vm.start()
135139
vm.pin_threads(0)
136-
boottime_us = _get_microvm_boottime(vm)
137-
metrics.put_metric("boot_time", boottime_us, unit="Microseconds")
138-
timestamps = find_events(vm.log_data)
139-
build_time = timestamps["build microvm for boot"]["duration"]
140-
metrics.put_metric("build_time", build_time.microseconds, unit="Microseconds")
140+
141+
boot_time_us, cpu_boot_time_us = get_boottime_device_info(vm)
141142
metrics.put_metric(
142143
"guest_boot_time",
143-
boottime_us - build_time.microseconds,
144+
boot_time_us,
144145
unit="Microseconds",
145146
)
147+
metrics.put_metric(
148+
"guest_cpu_boot_time",
149+
cpu_boot_time_us,
150+
unit="Microseconds",
151+
)
152+
153+
timestamps = find_events(vm.log_data)
154+
build_time = timestamps["build microvm for boot"]["duration"]
155+
metrics.put_metric("build_time", build_time.microseconds, unit="Microseconds")
146156

147157
kernel, userspace, total = get_systemd_analyze_times(vm)
148158
metrics.put_metric("systemd_kernel", kernel, unit="Milliseconds")

0 commit comments

Comments
 (0)