power_Resume: report time to bring all cpus online
look for the last instance of "CPUn is up" and subtract the resume begin from there
BUG=13649
TEST=run power_Resume and check for the presense of the resume_kernel_cpu metric
Change-Id: I3e03e4a3faea7772f5557dcbe21a5d9d0ca836f6
R=bleung@chromium.org,snanda@chromium.org
Review URL: http://codereview.chromium.org/6756015
diff --git a/client/site_tests/power_Resume/power_Resume.py b/client/site_tests/power_Resume/power_Resume.py
index 48d06a3..b0d0721 100644
--- a/client/site_tests/power_Resume/power_Resume.py
+++ b/client/site_tests/power_Resume/power_Resume.py
@@ -16,7 +16,7 @@
preserve_srcdir = True
- def _get_last_msg_time(self, msg):
+ def _get_last_msg(self, msg):
cmd = "grep -a '%s' /var/log/messages | tail -n 1" % msg
# The order in which processes are un-frozen is indeterminate
# and therfore this test may get resumed before the system has gotten
@@ -32,6 +32,10 @@
if count == 5:
raise error.TestError("Failed to find log message: " + msg)
+ return data
+
+ def _get_last_msg_time(self, msg):
+ data = self._get_last_msg(msg)
match = re.search(r' \[\s*([0-9.]+)\] ', data)
if match is None:
raise error.TestError('Failed to find timestamp for log message: '
@@ -59,6 +63,8 @@
return time
+ def _get_end_cpu_resume_time(self):
+ return self._get_last_msg_time('CPU[0-9]\+ is up')
def _get_end_suspend_time(self):
time = self._get_last_msg_time_multiple(END_SUSPEND_MESSAGES)
@@ -74,6 +80,15 @@
return time
+ def _get_device_resume_time(self):
+ data = self._get_last_msg("PM: resume of devices complete after")
+ match = re.search(r'PM: resume of devices complete after ([0-9.]+)',
+ data)
+ if match is None:
+ raise error.TestError('Failed to find device resume time on line: '
+ + data)
+ # convert from msec to sec
+ return float(match.group(1)) / 1000
def _get_hwclock_seconds(self):
"""
@@ -119,11 +134,14 @@
start_suspend_time = self._get_start_suspend_time()
end_suspend_time = self._get_end_suspend_time()
end_resume_time = self._get_end_resume_time()
+ end_cpu_resume_time = self._get_end_cpu_resume_time()
+ kernel_device_resume_time = self._get_device_resume_time()
# Calculate the suspend/resume times
total_resume_time = self._get_hwclock_seconds() - alarm_time
suspend_time = end_suspend_time - start_suspend_time
kernel_resume_time = end_resume_time - end_suspend_time
+ kernel_cpu_resume_time = end_cpu_resume_time - end_suspend_time
firmware_resume_time = total_resume_time - kernel_resume_time
# Prepare the results
@@ -132,4 +150,6 @@
results['seconds_system_resume'] = total_resume_time
results['seconds_system_resume_firmware'] = firmware_resume_time
results['seconds_system_resume_kernel'] = kernel_resume_time
+ results['seconds_system_resume_kernel_cpu'] = kernel_cpu_resume_time
+ results['seconds_system_resume_kernel_dev'] = kernel_device_resume_time
self.write_perf_keyval(results)