Merge tag 'pm+acpi-3.17-rc1-2' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm

Pull more ACPI and power management updates from Rafael Wysocki:
"These are a couple of regression fixes, cpuidle menu governor
optimizations, fixes for ACPI proccessor and battery drivers,
hibernation fix to avoid problems related to the e820 memory map,
fixes for a few cpufreq drivers and a new version of the suspend
profiling tool analyze_suspend.py.

Specifics:

- Fix for an ACPI-based device hotplug regression introduced in 3.14
that causes a kernel panic to trigger when memory hot-remove is
attempted with CONFIG_ACPI_HOTPLUG_MEMORY unset from Tang Chen

- Fix for a cpufreq regression introduced in 3.16 that triggers a
"sleeping function called from invalid context" bug in
dev_pm_opp_init_cpufreq_table() from Stephen Boyd

- ACPI battery driver fix for a warning message added in 3.16 that
prints silly stuff sometimes from Mariusz Ceier

- Hibernation fix for safer handling of mismatches in the 820 memory
map between the configurations during image creation and during the
subsequent restore from Chun-Yi Lee

- ACPI processor driver fix to handle CPU hotplug notifications
correctly during system suspend/resume from Lan Tianyu

- Series of four cpuidle menu governor cleanups that also should
speed it up a bit from Mel Gorman

- Fixes for the speedstep-smi, integrator, cpu0 and arm_big_little
cpufreq drivers from Hans Wennborg, Himangi Saraogi, Markus
Pargmann and Uwe Kleine-König

- Version 3.0 of the analyze_suspend.py suspend profiling tool from
Todd E Brandt"

* tag 'pm+acpi-3.17-rc1-2' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm:
ACPI / battery: Fix warning message in acpi_battery_get_state()
PM / tools: analyze_suspend.py: update to v3.0
cpufreq: arm_big_little: fix module license spec
cpufreq: speedstep-smi: fix decimal printf specifiers
ACPI / hotplug: Check scan handlers in acpi_scan_hot_remove()
cpufreq: OPP: Avoid sleeping while atomic
cpufreq: cpu0: Do not print error message when deferring
cpufreq: integrator: Use set_cpus_allowed_ptr
PM / hibernate: avoid unsafe pages in e820 reserved regions
ACPI / processor: Make acpi_cpu_soft_notify() process CPU FROZEN events
cpuidle: menu: Lookup CPU runqueues less
cpuidle: menu: Call nr_iowait_cpu less times
cpuidle: menu: Use ktime_to_us instead of reinventing the wheel
cpuidle: menu: Use shifts when calculating averages where possible

+1 -1
drivers/acpi/battery.c
··· 540 540 */ 541 541 if (battery->capacity_now > battery->full_charge_capacity 542 542 && battery->full_charge_capacity != ACPI_BATTERY_VALUE_UNKNOWN) { 543 - battery->capacity_now = battery->full_charge_capacity; 544 543 if (battery->capacity_now != battery->design_capacity) 545 544 printk_once(KERN_WARNING FW_BUG 546 545 "battery: reported current charge level (%d) " 547 546 "is higher than reported maximum charge level (%d).\n", 548 547 battery->capacity_now, battery->full_charge_capacity); 548 + battery->capacity_now = battery->full_charge_capacity; 549 549 } 550 550 551 551 if (test_bit(ACPI_BATTERY_QUIRK_PERCENTAGE_CAPACITY, &battery->flags)
+1
drivers/acpi/processor_driver.c
··· 120 120 unsigned int cpu = (unsigned long)hcpu; 121 121 struct acpi_processor *pr = per_cpu(processors, cpu); 122 122 struct acpi_device *device; 123 + action &= ~CPU_TASKS_FROZEN; 123 124 124 125 /* 125 126 * CPU_STARTING and CPU_DYING must not sleep. Return here since
+2 -1
drivers/acpi/scan.c
··· 353 353 unsigned long long sta; 354 354 acpi_status status; 355 355 356 - if (device->handler->hotplug.demand_offline && !acpi_force_hot_remove) { 356 + if (device->handler && device->handler->hotplug.demand_offline 357 + && !acpi_force_hot_remove) { 357 358 if (!acpi_scan_is_offline(device, true)) 358 359 return -EBUSY; 359 360 } else {
+5
drivers/cpufreq/arm_big_little.c
··· 24 24 #include <linux/cpufreq.h> 25 25 #include <linux/cpumask.h> 26 26 #include <linux/export.h> 27 + #include <linux/module.h> 27 28 #include <linux/mutex.h> 28 29 #include <linux/of_platform.h> 29 30 #include <linux/pm_opp.h> ··· 594 593 arm_bL_ops = NULL; 595 594 } 596 595 EXPORT_SYMBOL_GPL(bL_cpufreq_unregister); 596 + 597 + MODULE_AUTHOR("Viresh Kumar <viresh.kumar@linaro.org>"); 598 + MODULE_DESCRIPTION("Generic ARM big LITTLE cpufreq driver"); 599 + MODULE_LICENSE("GPL v2");
+1 -1
drivers/cpufreq/arm_big_little_dt.c
··· 114 114 115 115 MODULE_AUTHOR("Viresh Kumar <viresh.kumar@linaro.org>"); 116 116 MODULE_DESCRIPTION("Generic ARM big LITTLE cpufreq driver via DT"); 117 - MODULE_LICENSE("GPL"); 117 + MODULE_LICENSE("GPL v2");
+1 -1
drivers/cpufreq/cpufreq-cpu0.c
··· 137 137 * not yet registered, we should try defering probe. 138 138 */ 139 139 if (PTR_ERR(cpu_reg) == -EPROBE_DEFER) { 140 - dev_err(cpu_dev, "cpu0 regulator not ready, retry\n"); 140 + dev_dbg(cpu_dev, "cpu0 regulator not ready, retry\n"); 141 141 ret = -EPROBE_DEFER; 142 142 goto out_put_node; 143 143 }
+1 -1
drivers/cpufreq/cpufreq_opp.c
··· 60 60 goto out; 61 61 } 62 62 63 - freq_table = kzalloc(sizeof(*freq_table) * (max_opps + 1), GFP_KERNEL); 63 + freq_table = kcalloc(sizeof(*freq_table), (max_opps + 1), GFP_ATOMIC); 64 64 if (!freq_table) { 65 65 ret = -ENOMEM; 66 66 goto out;
+5 -5
drivers/cpufreq/integrator-cpufreq.c
··· 92 92 * Bind to the specified CPU. When this call returns, 93 93 * we should be running on the right CPU. 94 94 */ 95 - set_cpus_allowed(current, cpumask_of_cpu(cpu)); 95 + set_cpus_allowed_ptr(current, cpumask_of(cpu)); 96 96 BUG_ON(cpu != smp_processor_id()); 97 97 98 98 /* get current setting */ ··· 118 118 freqs.new = icst_hz(&cclk_params, vco) / 1000; 119 119 120 120 if (freqs.old == freqs.new) { 121 - set_cpus_allowed(current, cpus_allowed); 121 + set_cpus_allowed_ptr(current, &cpus_allowed); 122 122 return 0; 123 123 } 124 124 ··· 141 141 /* 142 142 * Restore the CPUs allowed mask. 143 143 */ 144 - set_cpus_allowed(current, cpus_allowed); 144 + set_cpus_allowed_ptr(current, &cpus_allowed); 145 145 146 146 cpufreq_freq_transition_end(policy, &freqs, 0); 147 147 ··· 157 157 158 158 cpus_allowed = current->cpus_allowed; 159 159 160 - set_cpus_allowed(current, cpumask_of_cpu(cpu)); 160 + set_cpus_allowed_ptr(current, cpumask_of(cpu)); 161 161 BUG_ON(cpu != smp_processor_id()); 162 162 163 163 /* detect memory etc. */ ··· 173 173 174 174 current_freq = icst_hz(&cclk_params, vco) / 1000; /* current freq */ 175 175 176 - set_cpus_allowed(current, cpus_allowed); 176 + set_cpus_allowed_ptr(current, &cpus_allowed); 177 177 178 178 return current_freq; 179 179 }
+2 -2
drivers/cpufreq/speedstep-smi.c
··· 324 324 return -ENODEV; 325 325 } 326 326 327 - pr_debug("signature:0x%.8ulx, command:0x%.8ulx, " 328 - "event:0x%.8ulx, perf_level:0x%.8ulx.\n", 327 + pr_debug("signature:0x%.8x, command:0x%.8x, " 328 + "event:0x%.8x, perf_level:0x%.8x.\n", 329 329 ist_info.signature, ist_info.command, 330 330 ist_info.event, ist_info.perf_level); 331 331
+23 -20
drivers/cpuidle/governors/menu.c
··· 31 31 * The default values do not overflow. 32 32 */ 33 33 #define BUCKETS 12 34 - #define INTERVALS 8 34 + #define INTERVAL_SHIFT 3 35 + #define INTERVALS (1UL << INTERVAL_SHIFT) 35 36 #define RESOLUTION 1024 36 37 #define DECAY 8 37 38 #define MAX_INTERESTING 50000 ··· 134 133 #define LOAD_INT(x) ((x) >> FSHIFT) 135 134 #define LOAD_FRAC(x) LOAD_INT(((x) & (FIXED_1-1)) * 100) 136 135 137 - static int get_loadavg(void) 136 + static inline int get_loadavg(unsigned long load) 138 137 { 139 - unsigned long this = this_cpu_load(); 140 - 141 - 142 - return LOAD_INT(this) * 10 + LOAD_FRAC(this) / 10; 138 + return LOAD_INT(load) * 10 + LOAD_FRAC(load) / 10; 143 139 } 144 140 145 - static inline int which_bucket(unsigned int duration) 141 + static inline int which_bucket(unsigned int duration, unsigned long nr_iowaiters) 146 142 { 147 143 int bucket = 0; 148 144 ··· 149 151 * This allows us to calculate 150 152 * E(duration)|iowait 151 153 */ 152 - if (nr_iowait_cpu(smp_processor_id())) 154 + if (nr_iowaiters) 153 155 bucket = BUCKETS/2; 154 156 155 157 if (duration < 10) ··· 172 174 * to be, the higher this multiplier, and thus the higher 173 175 * the barrier to go to an expensive C state. 174 176 */ 175 - static inline int performance_multiplier(void) 177 + static inline int performance_multiplier(unsigned long nr_iowaiters, unsigned long load) 176 178 { 177 179 int mult = 1; 178 180 179 181 /* for higher loadavg, we are more reluctant */ 180 182 181 - mult += 2 * get_loadavg(); 183 + mult += 2 * get_loadavg(load); 182 184 183 185 /* for IO wait tasks (per cpu!) we add 5x each */ 184 - mult += 10 * nr_iowait_cpu(smp_processor_id()); 186 + mult += 10 * nr_iowaiters; 185 187 186 188 return mult; 187 189 } ··· 225 227 max = value; 226 228 } 227 229 } 228 - do_div(avg, divisor); 230 + if (divisor == INTERVALS) 231 + avg >>= INTERVAL_SHIFT; 232 + else 233 + do_div(avg, divisor); 229 234 230 235 /* Then try to determine standard deviation */ 231 236 stddev = 0; ··· 239 238 stddev += diff * diff; 240 239 } 241 240 } 242 - do_div(stddev, divisor); 241 + if (divisor == INTERVALS) 242 + stddev >>= INTERVAL_SHIFT; 243 + else 244 + do_div(stddev, divisor); 245 + 243 246 /* 244 247 * The typical interval is obtained when standard deviation is small 245 248 * or standard deviation is small compared to the average interval. ··· 293 288 int latency_req = pm_qos_request(PM_QOS_CPU_DMA_LATENCY); 294 289 int i; 295 290 unsigned int interactivity_req; 296 - struct timespec t; 291 + unsigned long nr_iowaiters, cpu_load; 297 292 298 293 if (data->needs_update) { 299 294 menu_update(drv, dev); ··· 307 302 return 0; 308 303 309 304 /* determine the expected residency time, round up */ 310 - t = ktime_to_timespec(tick_nohz_get_sleep_length()); 311 - data->next_timer_us = 312 - t.tv_sec * USEC_PER_SEC + t.tv_nsec / NSEC_PER_USEC; 305 + data->next_timer_us = ktime_to_us(tick_nohz_get_sleep_length()); 313 306 314 - 315 - data->bucket = which_bucket(data->next_timer_us); 307 + get_iowait_load(&nr_iowaiters, &cpu_load); 308 + data->bucket = which_bucket(data->next_timer_us, nr_iowaiters); 316 309 317 310 /* 318 311 * Force the result of multiplication to be 64 bits even if both ··· 328 325 * duration / latency ratio. Adjust the latency limit if 329 326 * necessary. 330 327 */ 331 - interactivity_req = data->predicted_us / performance_multiplier(); 328 + interactivity_req = data->predicted_us / performance_multiplier(nr_iowaiters, cpu_load); 332 329 if (latency_req > interactivity_req) 333 330 latency_req = interactivity_req; 334 331
+1 -2
include/linux/sched.h
··· 169 169 extern unsigned long nr_running(void); 170 170 extern unsigned long nr_iowait(void); 171 171 extern unsigned long nr_iowait_cpu(int cpu); 172 - extern unsigned long this_cpu_load(void); 173 - 172 + extern void get_iowait_load(unsigned long *nr_waiters, unsigned long *load); 174 173 175 174 extern void calc_global_load(unsigned long ticks); 176 175 extern void update_cpu_load_nohz(void);
+20 -1
kernel/power/snapshot.c
··· 954 954 } 955 955 } 956 956 957 + static bool is_nosave_page(unsigned long pfn) 958 + { 959 + struct nosave_region *region; 960 + 961 + list_for_each_entry(region, &nosave_regions, list) { 962 + if (pfn >= region->start_pfn && pfn < region->end_pfn) { 963 + pr_err("PM: %#010llx in e820 nosave region: " 964 + "[mem %#010llx-%#010llx]\n", 965 + (unsigned long long) pfn << PAGE_SHIFT, 966 + (unsigned long long) region->start_pfn << PAGE_SHIFT, 967 + ((unsigned long long) region->end_pfn << PAGE_SHIFT) 968 + - 1); 969 + return true; 970 + } 971 + } 972 + 973 + return false; 974 + } 975 + 957 976 /** 958 977 * create_basic_memory_bitmaps - create bitmaps needed for marking page 959 978 * frames that should not be saved and free page frames. The pointers ··· 2034 2015 do { 2035 2016 pfn = memory_bm_next_pfn(bm); 2036 2017 if (likely(pfn != BM_END_OF_MAP)) { 2037 - if (likely(pfn_valid(pfn))) 2018 + if (likely(pfn_valid(pfn)) && !is_nosave_page(pfn)) 2038 2019 swsusp_set_page_free(pfn_to_page(pfn)); 2039 2020 else 2040 2021 return -EFAULT;
+7
kernel/sched/core.c
··· 2393 2393 return atomic_read(&this->nr_iowait); 2394 2394 } 2395 2395 2396 + void get_iowait_load(unsigned long *nr_waiters, unsigned long *load) 2397 + { 2398 + struct rq *this = this_rq(); 2399 + *nr_waiters = atomic_read(&this->nr_iowait); 2400 + *load = this->cpu_load[0]; 2401 + } 2402 + 2396 2403 #ifdef CONFIG_SMP 2397 2404 2398 2405 /*
-7
kernel/sched/proc.c
··· 8 8 9 9 #include "sched.h" 10 10 11 - unsigned long this_cpu_load(void) 12 - { 13 - struct rq *this = this_rq(); 14 - return this->cpu_load[0]; 15 - } 16 - 17 - 18 11 /* 19 12 * Global load-average calculations 20 13 *
+2978 -833
scripts/analyze_suspend.py
··· 36 36 # CONFIG_FUNCTION_TRACER=y 37 37 # CONFIG_FUNCTION_GRAPH_TRACER=y 38 38 # 39 + # For kernel versions older than 3.15: 39 40 # The following additional kernel parameters are required: 40 41 # (e.g. in file /etc/default/grub) 41 42 # GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..." 42 43 # 44 + 45 + # ----------------- LIBRARIES -------------------- 43 46 44 47 import sys 45 48 import time 46 49 import os 47 50 import string 48 51 import re 49 - import array 50 52 import platform 51 - import datetime 53 + from datetime import datetime 52 54 import struct 53 55 54 - # -- classes -- 56 + # ----------------- CLASSES -------------------- 55 57 58 + # Class: SystemValues 59 + # Description: 60 + # A global, single-instance container used to 61 + # store system values and test parameters 56 62 class SystemValues: 57 - testdir = "." 58 - tpath = "/sys/kernel/debug/tracing/" 59 - mempath = "/dev/mem" 60 - powerfile = "/sys/power/state" 61 - suspendmode = "mem" 62 - prefix = "test" 63 - teststamp = "" 64 - dmesgfile = "" 65 - ftracefile = "" 66 - htmlfile = "" 67 - rtcwake = False 68 - def setOutputFile(self): 69 - if((self.htmlfile == "") and (self.dmesgfile != "")): 70 - m = re.match(r"(?P<name>.*)_dmesg\.txt$", self.dmesgfile) 71 - if(m): 72 - self.htmlfile = m.group("name")+".html" 73 - if((self.htmlfile == "") and (self.ftracefile != "")): 74 - m = re.match(r"(?P<name>.*)_ftrace\.txt$", self.ftracefile) 75 - if(m): 76 - self.htmlfile = m.group("name")+".html" 77 - if(self.htmlfile == ""): 78 - self.htmlfile = "output.html" 79 - def initTestOutput(self): 80 - hostname = platform.node() 81 - if(hostname != ""): 82 - self.prefix = hostname 83 - v = os.popen("cat /proc/version").read().strip() 84 - kver = string.split(v)[2] 85 - self.testdir = os.popen("date \"+suspend-%m%d%y-%H%M%S\"").read().strip() 86 - self.teststamp = "# "+self.testdir+" "+self.prefix+" "+self.suspendmode+" "+kver 87 - self.dmesgfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_dmesg.txt" 88 - self.ftracefile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_ftrace.txt" 89 - self.htmlfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+".html" 90 - os.mkdir(self.testdir) 91 - 92 - class Data: 93 - altdevname = dict() 94 - usedmesg = False 95 - useftrace = False 96 - notestrun = False 63 + version = 3.0 97 64 verbose = False 98 - phases = [] 99 - dmesg = {} # root data structure 100 - start = 0.0 101 - end = 0.0 102 - stamp = {'time': "", 'host': "", 'mode': ""} 103 - id = 0 104 - tSuspended = 0.0 105 - fwValid = False 106 - fwSuspend = 0 107 - fwResume = 0 108 - def initialize(self): 109 - self.dmesg = { # dmesg log data 110 - 'suspend_general': {'list': dict(), 'start': -1.0, 'end': -1.0, 111 - 'row': 0, 'color': "#CCFFCC", 'order': 0}, 112 - 'suspend_early': {'list': dict(), 'start': -1.0, 'end': -1.0, 113 - 'row': 0, 'color': "green", 'order': 1}, 65 + testdir = '.' 66 + tpath = '/sys/kernel/debug/tracing/' 67 + fpdtpath = '/sys/firmware/acpi/tables/FPDT' 68 + epath = '/sys/kernel/debug/tracing/events/power/' 69 + traceevents = [ 70 + 'suspend_resume', 71 + 'device_pm_callback_end', 72 + 'device_pm_callback_start' 73 + ] 74 + modename = { 75 + 'freeze': 'Suspend-To-Idle (S0)', 76 + 'standby': 'Power-On Suspend (S1)', 77 + 'mem': 'Suspend-to-RAM (S3)', 78 + 'disk': 'Suspend-to-disk (S4)' 79 + } 80 + mempath = '/dev/mem' 81 + powerfile = '/sys/power/state' 82 + suspendmode = 'mem' 83 + hostname = 'localhost' 84 + prefix = 'test' 85 + teststamp = '' 86 + dmesgfile = '' 87 + ftracefile = '' 88 + htmlfile = '' 89 + rtcwake = False 90 + rtcwaketime = 10 91 + rtcpath = '' 92 + android = False 93 + adb = 'adb' 94 + devicefilter = [] 95 + stamp = 0 96 + execcount = 1 97 + x2delay = 0 98 + usecallgraph = False 99 + usetraceevents = False 100 + usetraceeventsonly = False 101 + notestrun = False 102 + altdevname = dict() 103 + postresumetime = 0 104 + tracertypefmt = '# tracer: (?P<t>.*)' 105 + firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' 106 + postresumefmt = '# post resume time (?P<t>[0-9]*)$' 107 + stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\ 108 + '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\ 109 + ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' 110 + def __init__(self): 111 + self.hostname = platform.node() 112 + if(self.hostname == ''): 113 + self.hostname = 'localhost' 114 + rtc = "rtc0" 115 + if os.path.exists('/dev/rtc'): 116 + rtc = os.readlink('/dev/rtc') 117 + rtc = '/sys/class/rtc/'+rtc 118 + if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \ 119 + os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'): 120 + self.rtcpath = rtc 121 + def setOutputFile(self): 122 + if((self.htmlfile == '') and (self.dmesgfile != '')): 123 + m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile) 124 + if(m): 125 + self.htmlfile = m.group('name')+'.html' 126 + if((self.htmlfile == '') and (self.ftracefile != '')): 127 + m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile) 128 + if(m): 129 + self.htmlfile = m.group('name')+'.html' 130 + if(self.htmlfile == ''): 131 + self.htmlfile = 'output.html' 132 + def initTestOutput(self, subdir): 133 + if(not self.android): 134 + self.prefix = self.hostname 135 + v = open('/proc/version', 'r').read().strip() 136 + kver = string.split(v)[2] 137 + else: 138 + self.prefix = 'android' 139 + v = os.popen(self.adb+' shell cat /proc/version').read().strip() 140 + kver = string.split(v)[2] 141 + testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S') 142 + if(subdir != "."): 143 + self.testdir = subdir+"/"+testtime 144 + else: 145 + self.testdir = testtime 146 + self.teststamp = \ 147 + '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver 148 + self.dmesgfile = \ 149 + self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt' 150 + self.ftracefile = \ 151 + self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt' 152 + self.htmlfile = \ 153 + self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html' 154 + os.mkdir(self.testdir) 155 + def setDeviceFilter(self, devnames): 156 + self.devicefilter = string.split(devnames) 157 + def rtcWakeAlarm(self): 158 + os.system('echo 0 > '+self.rtcpath+'/wakealarm') 159 + outD = open(self.rtcpath+'/date', 'r').read().strip() 160 + outT = open(self.rtcpath+'/time', 'r').read().strip() 161 + mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD) 162 + mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT) 163 + if(mD and mT): 164 + # get the current time from hardware 165 + utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds()) 166 + dt = datetime(\ 167 + int(mD.group('y')), int(mD.group('m')), int(mD.group('d')), 168 + int(mT.group('h')), int(mT.group('m')), int(mT.group('s'))) 169 + nowtime = int(dt.strftime('%s')) + utcoffset 170 + else: 171 + # if hardware time fails, use the software time 172 + nowtime = int(datetime.now().strftime('%s')) 173 + alarm = nowtime + self.rtcwaketime 174 + os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath)) 175 + 176 + sysvals = SystemValues() 177 + 178 + # Class: DeviceNode 179 + # Description: 180 + # A container used to create a device hierachy, with a single root node 181 + # and a tree of child nodes. Used by Data.deviceTopology() 182 + class DeviceNode: 183 + name = '' 184 + children = 0 185 + depth = 0 186 + def __init__(self, nodename, nodedepth): 187 + self.name = nodename 188 + self.children = [] 189 + self.depth = nodedepth 190 + 191 + # Class: Data 192 + # Description: 193 + # The primary container for suspend/resume test data. There is one for 194 + # each test run. The data is organized into a cronological hierarchy: 195 + # Data.dmesg { 196 + # root structure, started as dmesg & ftrace, but now only ftrace 197 + # contents: times for suspend start/end, resume start/end, fwdata 198 + # phases { 199 + # 10 sequential, non-overlapping phases of S/R 200 + # contents: times for phase start/end, order/color data for html 201 + # devlist { 202 + # device callback or action list for this phase 203 + # device { 204 + # a single device callback or generic action 205 + # contents: start/stop times, pid/cpu/driver info 206 + # parents/children, html id for timeline/callgraph 207 + # optionally includes an ftrace callgraph 208 + # optionally includes intradev trace events 209 + # } 210 + # } 211 + # } 212 + # } 213 + # 214 + class Data: 215 + dmesg = {} # root data structure 216 + phases = [] # ordered list of phases 217 + start = 0.0 # test start 218 + end = 0.0 # test end 219 + tSuspended = 0.0 # low-level suspend start 220 + tResumed = 0.0 # low-level resume start 221 + tLow = 0.0 # time spent in low-level suspend (standby/freeze) 222 + fwValid = False # is firmware data available 223 + fwSuspend = 0 # time spent in firmware suspend 224 + fwResume = 0 # time spent in firmware resume 225 + dmesgtext = [] # dmesg text file in memory 226 + testnumber = 0 227 + idstr = '' 228 + html_device_id = 0 229 + stamp = 0 230 + outfile = '' 231 + def __init__(self, num): 232 + idchar = 'abcdefghijklmnopqrstuvwxyz' 233 + self.testnumber = num 234 + self.idstr = idchar[num] 235 + self.dmesgtext = [] 236 + self.phases = [] 237 + self.dmesg = { # fixed list of 10 phases 238 + 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0, 239 + 'row': 0, 'color': '#CCFFCC', 'order': 0}, 240 + 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0, 241 + 'row': 0, 'color': '#88FF88', 'order': 1}, 242 + 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0, 243 + 'row': 0, 'color': '#00AA00', 'order': 2}, 114 244 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, 115 - 'row': 0, 'color': "#00FFFF", 'order': 2}, 116 - 'suspend_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0, 117 - 'row': 0, 'color': "blue", 'order': 3}, 118 - 'resume_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0, 119 - 'row': 0, 'color': "red", 'order': 4}, 245 + 'row': 0, 'color': '#008888', 'order': 3}, 246 + 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, 247 + 'row': 0, 'color': '#0000FF', 'order': 4}, 248 + 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, 249 + 'row': 0, 'color': '#FF0000', 'order': 5}, 120 250 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, 121 - 'row': 0, 'color': "orange", 'order': 5}, 251 + 'row': 0, 'color': '#FF9900', 'order': 6}, 122 252 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0, 123 - 'row': 0, 'color': "yellow", 'order': 6}, 124 - 'resume_general': {'list': dict(), 'start': -1.0, 'end': -1.0, 125 - 'row': 0, 'color': "#FFFFCC", 'order': 7} 253 + 'row': 0, 'color': '#FFCC00', 'order': 7}, 254 + 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0, 255 + 'row': 0, 'color': '#FFFF88', 'order': 8}, 256 + 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0, 257 + 'row': 0, 'color': '#FFFFCC', 'order': 9} 126 258 } 127 259 self.phases = self.sortedPhases() 128 - def normalizeTime(self): 129 - tSus = tRes = self.tSuspended 130 - if self.fwValid: 131 - tSus -= -self.fwSuspend / 1000000000.0 132 - tRes -= self.fwResume / 1000000000.0 133 - self.tSuspended = 0.0 134 - self.start -= tSus 135 - self.end -= tRes 260 + def getStart(self): 261 + return self.dmesg[self.phases[0]]['start'] 262 + def setStart(self, time): 263 + self.start = time 264 + self.dmesg[self.phases[0]]['start'] = time 265 + def getEnd(self): 266 + return self.dmesg[self.phases[-1]]['end'] 267 + def setEnd(self, time): 268 + self.end = time 269 + self.dmesg[self.phases[-1]]['end'] = time 270 + def isTraceEventOutsideDeviceCalls(self, pid, time): 136 271 for phase in self.phases: 137 - zero = tRes 138 - if "suspend" in phase: 139 - zero = tSus 272 + list = self.dmesg[phase]['list'] 273 + for dev in list: 274 + d = list[dev] 275 + if(d['pid'] == pid and time >= d['start'] and 276 + time <= d['end']): 277 + return False 278 + return True 279 + def addIntraDevTraceEvent(self, action, name, pid, time): 280 + if(action == 'mutex_lock_try'): 281 + color = 'red' 282 + elif(action == 'mutex_lock_pass'): 283 + color = 'green' 284 + elif(action == 'mutex_unlock'): 285 + color = 'blue' 286 + else: 287 + # create separate colors based on the name 288 + v1 = len(name)*10 % 256 289 + v2 = string.count(name, 'e')*100 % 256 290 + v3 = ord(name[0])*20 % 256 291 + color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3) 292 + for phase in self.phases: 293 + list = self.dmesg[phase]['list'] 294 + for dev in list: 295 + d = list[dev] 296 + if(d['pid'] == pid and time >= d['start'] and 297 + time <= d['end']): 298 + e = TraceEvent(action, name, color, time) 299 + if('traceevents' not in d): 300 + d['traceevents'] = [] 301 + d['traceevents'].append(e) 302 + return d 303 + break 304 + return 0 305 + def capIntraDevTraceEvent(self, action, name, pid, time): 306 + for phase in self.phases: 307 + list = self.dmesg[phase]['list'] 308 + for dev in list: 309 + d = list[dev] 310 + if(d['pid'] == pid and time >= d['start'] and 311 + time <= d['end']): 312 + if('traceevents' not in d): 313 + return 314 + for e in d['traceevents']: 315 + if(e.action == action and 316 + e.name == name and not e.ready): 317 + e.length = time - e.time 318 + e.ready = True 319 + break 320 + return 321 + def trimTimeVal(self, t, t0, dT, left): 322 + if left: 323 + if(t > t0): 324 + if(t - dT < t0): 325 + return t0 326 + return t - dT 327 + else: 328 + return t 329 + else: 330 + if(t < t0 + dT): 331 + if(t > t0): 332 + return t0 + dT 333 + return t + dT 334 + else: 335 + return t 336 + def trimTime(self, t0, dT, left): 337 + self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left) 338 + self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left) 339 + self.start = self.trimTimeVal(self.start, t0, dT, left) 340 + self.end = self.trimTimeVal(self.end, t0, dT, left) 341 + for phase in self.phases: 140 342 p = self.dmesg[phase] 141 - p['start'] -= zero 142 - p['end'] -= zero 343 + p['start'] = self.trimTimeVal(p['start'], t0, dT, left) 344 + p['end'] = self.trimTimeVal(p['end'], t0, dT, left) 143 345 list = p['list'] 144 346 for name in list: 145 347 d = list[name] 146 - d['start'] -= zero 147 - d['end'] -= zero 348 + d['start'] = self.trimTimeVal(d['start'], t0, dT, left) 349 + d['end'] = self.trimTimeVal(d['end'], t0, dT, left) 148 350 if('ftrace' in d): 149 351 cg = d['ftrace'] 150 - cg.start -= zero 151 - cg.end -= zero 352 + cg.start = self.trimTimeVal(cg.start, t0, dT, left) 353 + cg.end = self.trimTimeVal(cg.end, t0, dT, left) 152 354 for line in cg.list: 153 - line.time -= zero 154 - if self.fwValid: 155 - fws = -self.fwSuspend / 1000000000.0 156 - fwr = self.fwResume / 1000000000.0 157 - list = dict() 158 - self.id += 1 159 - devid = "dc%d" % self.id 160 - list["firmware-suspend"] = \ 161 - {'start': fws, 'end': 0, 'pid': 0, 'par': "", 162 - 'length': -fws, 'row': 0, 'id': devid }; 163 - self.id += 1 164 - devid = "dc%d" % self.id 165 - list["firmware-resume"] = \ 166 - {'start': 0, 'end': fwr, 'pid': 0, 'par': "", 167 - 'length': fwr, 'row': 0, 'id': devid }; 168 - self.dmesg['BIOS'] = \ 169 - {'list': list, 'start': fws, 'end': fwr, 170 - 'row': 0, 'color': "purple", 'order': 4} 171 - self.dmesg['resume_cpu']['order'] += 1 172 - self.dmesg['resume_noirq']['order'] += 1 173 - self.dmesg['resume_early']['order'] += 1 174 - self.dmesg['resume_general']['order'] += 1 175 - self.phases = self.sortedPhases() 176 - def vprint(self, msg): 177 - if(self.verbose): 178 - print(msg) 355 + line.time = self.trimTimeVal(line.time, t0, dT, left) 356 + if('traceevents' in d): 357 + for e in d['traceevents']: 358 + e.time = self.trimTimeVal(e.time, t0, dT, left) 359 + def normalizeTime(self, tZero): 360 + # first trim out any standby or freeze clock time 361 + if(self.tSuspended != self.tResumed): 362 + if(self.tResumed > tZero): 363 + self.trimTime(self.tSuspended, \ 364 + self.tResumed-self.tSuspended, True) 365 + else: 366 + self.trimTime(self.tSuspended, \ 367 + self.tResumed-self.tSuspended, False) 368 + # shift the timeline so that tZero is the new 0 369 + self.tSuspended -= tZero 370 + self.tResumed -= tZero 371 + self.start -= tZero 372 + self.end -= tZero 373 + for phase in self.phases: 374 + p = self.dmesg[phase] 375 + p['start'] -= tZero 376 + p['end'] -= tZero 377 + list = p['list'] 378 + for name in list: 379 + d = list[name] 380 + d['start'] -= tZero 381 + d['end'] -= tZero 382 + if('ftrace' in d): 383 + cg = d['ftrace'] 384 + cg.start -= tZero 385 + cg.end -= tZero 386 + for line in cg.list: 387 + line.time -= tZero 388 + if('traceevents' in d): 389 + for e in d['traceevents']: 390 + e.time -= tZero 391 + def newPhaseWithSingleAction(self, phasename, devname, start, end, color): 392 + for phase in self.phases: 393 + self.dmesg[phase]['order'] += 1 394 + self.html_device_id += 1 395 + devid = '%s%d' % (self.idstr, self.html_device_id) 396 + list = dict() 397 + list[devname] = \ 398 + {'start': start, 'end': end, 'pid': 0, 'par': '', 399 + 'length': (end-start), 'row': 0, 'id': devid, 'drv': '' }; 400 + self.dmesg[phasename] = \ 401 + {'list': list, 'start': start, 'end': end, 402 + 'row': 0, 'color': color, 'order': 0} 403 + self.phases = self.sortedPhases() 404 + def newPhase(self, phasename, start, end, color, order): 405 + if(order < 0): 406 + order = len(self.phases) 407 + for phase in self.phases[order:]: 408 + self.dmesg[phase]['order'] += 1 409 + if(order > 0): 410 + p = self.phases[order-1] 411 + self.dmesg[p]['end'] = start 412 + if(order < len(self.phases)): 413 + p = self.phases[order] 414 + self.dmesg[p]['start'] = end 415 + list = dict() 416 + self.dmesg[phasename] = \ 417 + {'list': list, 'start': start, 'end': end, 418 + 'row': 0, 'color': color, 'order': order} 419 + self.phases = self.sortedPhases() 420 + def setPhase(self, phase, ktime, isbegin): 421 + if(isbegin): 422 + self.dmesg[phase]['start'] = ktime 423 + else: 424 + self.dmesg[phase]['end'] = ktime 179 425 def dmesgSortVal(self, phase): 180 426 return self.dmesg[phase]['order'] 181 427 def sortedPhases(self): ··· 443 197 dev = phaselist[devname] 444 198 if(dev['end'] < 0): 445 199 dev['end'] = end 446 - self.vprint("%s (%s): callback didn't return" % (devname, phase)) 200 + vprint('%s (%s): callback didnt return' % (devname, phase)) 201 + def deviceFilter(self, devicefilter): 202 + # remove all by the relatives of the filter devnames 203 + filter = [] 204 + for phase in self.phases: 205 + list = self.dmesg[phase]['list'] 206 + for name in devicefilter: 207 + dev = name 208 + while(dev in list): 209 + if(dev not in filter): 210 + filter.append(dev) 211 + dev = list[dev]['par'] 212 + children = self.deviceDescendants(name, phase) 213 + for dev in children: 214 + if(dev not in filter): 215 + filter.append(dev) 216 + for phase in self.phases: 217 + list = self.dmesg[phase]['list'] 218 + rmlist = [] 219 + for name in list: 220 + pid = list[name]['pid'] 221 + if(name not in filter and pid >= 0): 222 + rmlist.append(name) 223 + for name in rmlist: 224 + del list[name] 447 225 def fixupInitcallsThatDidntReturn(self): 448 226 # if any calls never returned, clip them at system resume end 449 227 for phase in self.phases: 450 - self.fixupInitcalls(phase, self.dmesg['resume_general']['end']) 451 - if(phase == "resume_general"): 452 - break 453 - def newAction(self, phase, name, pid, parent, start, end): 454 - self.id += 1 455 - devid = "dc%d" % self.id 228 + self.fixupInitcalls(phase, self.getEnd()) 229 + def newActionGlobal(self, name, start, end): 230 + # which phase is this device callback or action "in" 231 + targetphase = "none" 232 + overlap = 0.0 233 + for phase in self.phases: 234 + pstart = self.dmesg[phase]['start'] 235 + pend = self.dmesg[phase]['end'] 236 + o = max(0, min(end, pend) - max(start, pstart)) 237 + if(o > overlap): 238 + targetphase = phase 239 + overlap = o 240 + if targetphase in self.phases: 241 + self.newAction(targetphase, name, -1, '', start, end, '') 242 + return True 243 + return False 244 + def newAction(self, phase, name, pid, parent, start, end, drv): 245 + # new device callback for a specific phase 246 + self.html_device_id += 1 247 + devid = '%s%d' % (self.idstr, self.html_device_id) 456 248 list = self.dmesg[phase]['list'] 457 249 length = -1.0 458 250 if(start >= 0 and end >= 0): 459 251 length = end - start 460 252 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent, 461 - 'length': length, 'row': 0, 'id': devid } 253 + 'length': length, 'row': 0, 'id': devid, 'drv': drv } 462 254 def deviceIDs(self, devlist, phase): 463 255 idlist = [] 464 - for p in self.phases: 465 - if(p[0] != phase[0]): 466 - continue 467 - list = data.dmesg[p]['list'] 468 - for devname in list: 469 - if devname in devlist: 470 - idlist.append(list[devname]['id']) 256 + list = self.dmesg[phase]['list'] 257 + for devname in list: 258 + if devname in devlist: 259 + idlist.append(list[devname]['id']) 471 260 return idlist 472 261 def deviceParentID(self, devname, phase): 473 - pdev = "" 474 - pdevid = "" 475 - for p in self.phases: 476 - if(p[0] != phase[0]): 477 - continue 478 - list = data.dmesg[p]['list'] 479 - if devname in list: 480 - pdev = list[devname]['par'] 481 - for p in self.phases: 482 - if(p[0] != phase[0]): 483 - continue 484 - list = data.dmesg[p]['list'] 485 - if pdev in list: 486 - return list[pdev]['id'] 262 + pdev = '' 263 + pdevid = '' 264 + list = self.dmesg[phase]['list'] 265 + if devname in list: 266 + pdev = list[devname]['par'] 267 + if pdev in list: 268 + return list[pdev]['id'] 487 269 return pdev 488 - def deviceChildrenIDs(self, devname, phase): 270 + def deviceChildren(self, devname, phase): 489 271 devlist = [] 490 - for p in self.phases: 491 - if(p[0] != phase[0]): 492 - continue 493 - list = data.dmesg[p]['list'] 494 - for child in list: 495 - if(list[child]['par'] == devname): 496 - devlist.append(child) 272 + list = self.dmesg[phase]['list'] 273 + for child in list: 274 + if(list[child]['par'] == devname): 275 + devlist.append(child) 276 + return devlist 277 + def deviceDescendants(self, devname, phase): 278 + children = self.deviceChildren(devname, phase) 279 + family = children 280 + for child in children: 281 + family += self.deviceDescendants(child, phase) 282 + return family 283 + def deviceChildrenIDs(self, devname, phase): 284 + devlist = self.deviceChildren(devname, phase) 497 285 return self.deviceIDs(devlist, phase) 286 + def printDetails(self): 287 + vprint(' test start: %f' % self.start) 288 + for phase in self.phases: 289 + dc = len(self.dmesg[phase]['list']) 290 + vprint(' %16s: %f - %f (%d devices)' % (phase, \ 291 + self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) 292 + vprint(' test end: %f' % self.end) 293 + def masterTopology(self, name, list, depth): 294 + node = DeviceNode(name, depth) 295 + for cname in list: 296 + clist = self.deviceChildren(cname, 'resume') 297 + cnode = self.masterTopology(cname, clist, depth+1) 298 + node.children.append(cnode) 299 + return node 300 + def printTopology(self, node): 301 + html = '' 302 + if node.name: 303 + info = '' 304 + drv = '' 305 + for phase in self.phases: 306 + list = self.dmesg[phase]['list'] 307 + if node.name in list: 308 + s = list[node.name]['start'] 309 + e = list[node.name]['end'] 310 + if list[node.name]['drv']: 311 + drv = ' {'+list[node.name]['drv']+'}' 312 + info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000)) 313 + html += '<li><b>'+node.name+drv+'</b>' 314 + if info: 315 + html += '<ul>'+info+'</ul>' 316 + html += '</li>' 317 + if len(node.children) > 0: 318 + html += '<ul>' 319 + for cnode in node.children: 320 + html += self.printTopology(cnode) 321 + html += '</ul>' 322 + return html 323 + def rootDeviceList(self): 324 + # list of devices graphed 325 + real = [] 326 + for phase in self.dmesg: 327 + list = self.dmesg[phase]['list'] 328 + for dev in list: 329 + if list[dev]['pid'] >= 0 and dev not in real: 330 + real.append(dev) 331 + # list of top-most root devices 332 + rootlist = [] 333 + for phase in self.dmesg: 334 + list = self.dmesg[phase]['list'] 335 + for dev in list: 336 + pdev = list[dev]['par'] 337 + if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)): 338 + continue 339 + if pdev and pdev not in real and pdev not in rootlist: 340 + rootlist.append(pdev) 341 + return rootlist 342 + def deviceTopology(self): 343 + rootlist = self.rootDeviceList() 344 + master = self.masterTopology('', rootlist, 0) 345 + return self.printTopology(master) 498 346 347 + # Class: TraceEvent 348 + # Description: 349 + # A container for trace event data found in the ftrace file 350 + class TraceEvent: 351 + ready = False 352 + name = '' 353 + time = 0.0 354 + color = '#FFFFFF' 355 + length = 0.0 356 + action = '' 357 + def __init__(self, a, n, c, t): 358 + self.action = a 359 + self.name = n 360 + self.color = c 361 + self.time = t 362 + 363 + # Class: FTraceLine 364 + # Description: 365 + # A container for a single line of ftrace data. There are six basic types: 366 + # callgraph line: 367 + # call: " dpm_run_callback() {" 368 + # return: " }" 369 + # leaf: " dpm_run_callback();" 370 + # trace event: 371 + # tracing_mark_write: SUSPEND START or RESUME COMPLETE 372 + # suspend_resume: phase or custom exec block data 373 + # device_pm_callback: device callback info 499 374 class FTraceLine: 500 375 time = 0.0 501 376 length = 0.0 ··· 624 257 freturn = False 625 258 fevent = False 626 259 depth = 0 627 - name = "" 260 + name = '' 261 + type = '' 628 262 def __init__(self, t, m, d): 629 263 self.time = float(t) 630 - # check to see if this is a trace event 631 - em = re.match(r"^ *\/\* *(?P<msg>.*) \*\/ *$", m) 632 - if(em): 633 - self.name = em.group("msg") 264 + # is this a trace event 265 + if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)): 266 + if(d == 'traceevent'): 267 + # nop format trace event 268 + msg = m 269 + else: 270 + # function_graph format trace event 271 + em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m) 272 + msg = em.group('msg') 273 + 274 + emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg) 275 + if(emm): 276 + self.name = emm.group('msg') 277 + self.type = emm.group('call') 278 + else: 279 + self.name = msg 634 280 self.fevent = True 635 281 return 636 282 # convert the duration to seconds 637 283 if(d): 638 284 self.length = float(d)/1000000 639 285 # the indentation determines the depth 640 - match = re.match(r"^(?P<d> *)(?P<o>.*)$", m) 286 + match = re.match('^(?P<d> *)(?P<o>.*)$', m) 641 287 if(not match): 642 288 return 643 289 self.depth = self.getDepth(match.group('d')) ··· 660 280 self.freturn = True 661 281 if(len(m) > 1): 662 282 # includes comment with function name 663 - match = re.match(r"^} *\/\* *(?P<n>.*) *\*\/$", m) 283 + match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m) 664 284 if(match): 665 285 self.name = match.group('n') 666 286 # function call ··· 668 288 self.fcall = True 669 289 # function call with children 670 290 if(m[-1] == '{'): 671 - match = re.match(r"^(?P<n>.*) *\(.*", m) 291 + match = re.match('^(?P<n>.*) *\(.*', m) 672 292 if(match): 673 293 self.name = match.group('n') 674 294 # function call with no children (leaf) 675 295 elif(m[-1] == ';'): 676 296 self.freturn = True 677 - match = re.match(r"^(?P<n>.*) *\(.*", m) 297 + match = re.match('^(?P<n>.*) *\(.*', m) 678 298 if(match): 679 299 self.name = match.group('n') 680 300 # something else (possibly a trace marker) ··· 682 302 self.name = m 683 303 def getDepth(self, str): 684 304 return len(str)/2 305 + def debugPrint(self, dev): 306 + if(self.freturn and self.fcall): 307 + print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \ 308 + self.depth, self.name, self.length*1000000)) 309 + elif(self.freturn): 310 + print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \ 311 + self.depth, self.name, self.length*1000000)) 312 + else: 313 + print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \ 314 + self.depth, self.name, self.length*1000000)) 685 315 316 + # Class: FTraceCallGraph 317 + # Description: 318 + # A container for the ftrace callgraph of a single recursive function. 319 + # This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph 320 + # Each instance is tied to a single device in a single phase, and is 321 + # comprised of an ordered list of FTraceLine objects 686 322 class FTraceCallGraph: 687 323 start = -1.0 688 324 end = -1.0 ··· 723 327 if(not self.invalid): 724 328 self.setDepth(line) 725 329 if(line.depth == 0 and line.freturn): 330 + if(self.start < 0): 331 + self.start = line.time 726 332 self.end = line.time 727 333 self.list.append(line) 728 334 return True 729 335 if(self.invalid): 730 336 return False 731 337 if(len(self.list) >= 1000000 or self.depth < 0): 732 - first = self.list[0] 733 - self.list = [] 734 - self.list.append(first) 735 - self.invalid = True 736 - id = "task %s cpu %s" % (match.group("pid"), match.group("cpu")) 737 - window = "(%f - %f)" % (self.start, line.time) 738 - data.vprint("Too much data for "+id+" "+window+", ignoring this callback") 739 - return False 338 + if(len(self.list) > 0): 339 + first = self.list[0] 340 + self.list = [] 341 + self.list.append(first) 342 + self.invalid = True 343 + if(not match): 344 + return False 345 + id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu')) 346 + window = '(%f - %f)' % (self.start, line.time) 347 + if(self.depth < 0): 348 + print('Too much data for '+id+\ 349 + ' (buffer overflow), ignoring this callback') 350 + else: 351 + print('Too much data for '+id+\ 352 + ' '+window+', ignoring this callback') 353 + return False 740 354 self.list.append(line) 741 355 if(self.start < 0): 742 356 self.start = line.time 743 357 return False 358 + def slice(self, t0, tN): 359 + minicg = FTraceCallGraph() 360 + count = -1 361 + firstdepth = 0 362 + for l in self.list: 363 + if(l.time < t0 or l.time > tN): 364 + continue 365 + if(count < 0): 366 + if(not l.fcall or l.name == 'dev_driver_string'): 367 + continue 368 + firstdepth = l.depth 369 + count = 0 370 + l.depth -= firstdepth 371 + minicg.addLine(l, 0) 372 + if((count == 0 and l.freturn and l.fcall) or 373 + (count > 0 and l.depth <= 0)): 374 + break 375 + count += 1 376 + return minicg 744 377 def sanityCheck(self): 745 378 stack = dict() 746 379 cnt = 0 ··· 778 353 stack[l.depth] = l 779 354 cnt += 1 780 355 elif(l.freturn and not l.fcall): 781 - if(not stack[l.depth]): 356 + if(l.depth not in stack): 782 357 return False 783 358 stack[l.depth].length = l.length 784 359 stack[l.depth] = 0 ··· 788 363 return True 789 364 return False 790 365 def debugPrint(self, filename): 791 - if(filename == "stdout"): 792 - print("[%f - %f]") % (self.start, self.end) 366 + if(filename == 'stdout'): 367 + print('[%f - %f]') % (self.start, self.end) 793 368 for l in self.list: 794 369 if(l.freturn and l.fcall): 795 - print("%f (%02d): %s(); (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000)) 370 + print('%f (%02d): %s(); (%.3f us)' % (l.time, \ 371 + l.depth, l.name, l.length*1000000)) 796 372 elif(l.freturn): 797 - print("%f (%02d): %s} (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000)) 373 + print('%f (%02d): %s} (%.3f us)' % (l.time, \ 374 + l.depth, l.name, l.length*1000000)) 798 375 else: 799 - print("%f (%02d): %s() { (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000)) 800 - print(" ") 376 + print('%f (%02d): %s() { (%.3f us)' % (l.time, \ 377 + l.depth, l.name, l.length*1000000)) 378 + print(' ') 801 379 else: 802 380 fp = open(filename, 'w') 803 381 print(filename) 804 382 for l in self.list: 805 383 if(l.freturn and l.fcall): 806 - fp.write("%f (%02d): %s(); (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000)) 384 + fp.write('%f (%02d): %s(); (%.3f us)\n' % (l.time, \ 385 + l.depth, l.name, l.length*1000000)) 807 386 elif(l.freturn): 808 - fp.write("%f (%02d): %s} (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000)) 387 + fp.write('%f (%02d): %s} (%.3f us)\n' % (l.time, \ 388 + l.depth, l.name, l.length*1000000)) 809 389 else: 810 - fp.write("%f (%02d): %s() { (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000)) 390 + fp.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \ 391 + l.depth, l.name, l.length*1000000)) 811 392 fp.close() 812 393 394 + # Class: Timeline 395 + # Description: 396 + # A container for a suspend/resume html timeline. In older versions 397 + # of the script there were multiple timelines, but in the latest 398 + # there is only one. 813 399 class Timeline: 814 400 html = {} 815 - scaleH = 0.0 # height of the timescale row as a percent of the timeline height 401 + scaleH = 0.0 # height of the row as a percent of the timeline height 816 402 rowH = 0.0 # height of each row in percent of the timeline height 817 403 row_height_pixels = 30 818 404 maxrows = 0 819 405 height = 0 820 406 def __init__(self): 821 407 self.html = { 822 - 'timeline': "", 823 - 'legend': "", 824 - 'scale': "" 408 + 'timeline': '', 409 + 'legend': '', 410 + 'scale': '' 825 411 } 826 412 def setRows(self, rows): 827 413 self.maxrows = int(rows) ··· 843 407 r = 1.0 844 408 self.rowH = (100.0 - self.scaleH)/r 845 409 846 - # -- global objects -- 410 + # Class: TestRun 411 + # Description: 412 + # A container for a suspend/resume test run. This is necessary as 413 + # there could be more than one, and they need to be separate. 414 + class TestRun: 415 + ftrace_line_fmt_fg = \ 416 + '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ 417 + ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ 418 + '[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)' 419 + ftrace_line_fmt_nop = \ 420 + ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ 421 + '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\ 422 + '(?P<msg>.*)' 423 + ftrace_line_fmt = ftrace_line_fmt_nop 424 + cgformat = False 425 + ftemp = dict() 426 + ttemp = dict() 427 + inthepipe = False 428 + tracertype = '' 429 + data = 0 430 + def __init__(self, dataobj): 431 + self.data = dataobj 432 + self.ftemp = dict() 433 + self.ttemp = dict() 434 + def isReady(self): 435 + if(tracertype == '' or not data): 436 + return False 437 + return True 438 + def setTracerType(self, tracer): 439 + self.tracertype = tracer 440 + if(tracer == 'function_graph'): 441 + self.cgformat = True 442 + self.ftrace_line_fmt = self.ftrace_line_fmt_fg 443 + elif(tracer == 'nop'): 444 + self.ftrace_line_fmt = self.ftrace_line_fmt_nop 445 + else: 446 + doError('Invalid tracer format: [%s]' % tracer, False) 847 447 848 - sysvals = SystemValues() 849 - data = Data() 448 + # ----------------- FUNCTIONS -------------------- 850 449 851 - # -- functions -- 450 + # Function: vprint 451 + # Description: 452 + # verbose print (prints only with -verbose option) 453 + # Arguments: 454 + # msg: the debug/log message to print 455 + def vprint(msg): 456 + global sysvals 457 + if(sysvals.verbose): 458 + print(msg) 852 459 853 460 # Function: initFtrace 854 461 # Description: 855 - # Configure ftrace to capture a function trace during suspend/resume 462 + # Configure ftrace to use trace events and/or a callgraph 856 463 def initFtrace(): 857 464 global sysvals 858 465 859 - print("INITIALIZING FTRACE...") 860 - # turn trace off 861 - os.system("echo 0 > "+sysvals.tpath+"tracing_on") 862 - # set the trace clock to global 863 - os.system("echo global > "+sysvals.tpath+"trace_clock") 864 - # set trace buffer to a huge value 865 - os.system("echo nop > "+sysvals.tpath+"current_tracer") 866 - os.system("echo 100000 > "+sysvals.tpath+"buffer_size_kb") 867 - # clear the trace buffer 868 - os.system("echo \"\" > "+sysvals.tpath+"trace") 869 - # set trace type 870 - os.system("echo function_graph > "+sysvals.tpath+"current_tracer") 871 - os.system("echo \"\" > "+sysvals.tpath+"set_ftrace_filter") 872 - # set trace format options 873 - os.system("echo funcgraph-abstime > "+sysvals.tpath+"trace_options") 874 - os.system("echo funcgraph-proc > "+sysvals.tpath+"trace_options") 875 - # focus only on device suspend and resume 876 - os.system("cat "+sysvals.tpath+"available_filter_functions | grep dpm_run_callback > "+sysvals.tpath+"set_graph_function") 466 + tp = sysvals.tpath 467 + cf = 'dpm_run_callback' 468 + if(sysvals.usetraceeventsonly): 469 + cf = '-e dpm_prepare -e dpm_complete -e dpm_run_callback' 470 + if(sysvals.usecallgraph or sysvals.usetraceevents): 471 + print('INITIALIZING FTRACE...') 472 + # turn trace off 473 + os.system('echo 0 > '+tp+'tracing_on') 474 + # set the trace clock to global 475 + os.system('echo global > '+tp+'trace_clock') 476 + # set trace buffer to a huge value 477 + os.system('echo nop > '+tp+'current_tracer') 478 + os.system('echo 100000 > '+tp+'buffer_size_kb') 479 + # initialize the callgraph trace, unless this is an x2 run 480 + if(sysvals.usecallgraph and sysvals.execcount == 1): 481 + # set trace type 482 + os.system('echo function_graph > '+tp+'current_tracer') 483 + os.system('echo "" > '+tp+'set_ftrace_filter') 484 + # set trace format options 485 + os.system('echo funcgraph-abstime > '+tp+'trace_options') 486 + os.system('echo funcgraph-proc > '+tp+'trace_options') 487 + # focus only on device suspend and resume 488 + os.system('cat '+tp+'available_filter_functions | grep '+\ 489 + cf+' > '+tp+'set_graph_function') 490 + if(sysvals.usetraceevents): 491 + # turn trace events on 492 + events = iter(sysvals.traceevents) 493 + for e in events: 494 + os.system('echo 1 > '+sysvals.epath+e+'/enable') 495 + # clear the trace buffer 496 + os.system('echo "" > '+tp+'trace') 497 + 498 + # Function: initFtraceAndroid 499 + # Description: 500 + # Configure ftrace to capture trace events 501 + def initFtraceAndroid(): 502 + global sysvals 503 + 504 + tp = sysvals.tpath 505 + if(sysvals.usetraceevents): 506 + print('INITIALIZING FTRACE...') 507 + # turn trace off 508 + os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'") 509 + # set the trace clock to global 510 + os.system(sysvals.adb+" shell 'echo global > "+tp+"trace_clock'") 511 + # set trace buffer to a huge value 512 + os.system(sysvals.adb+" shell 'echo nop > "+tp+"current_tracer'") 513 + os.system(sysvals.adb+" shell 'echo 10000 > "+tp+"buffer_size_kb'") 514 + # turn trace events on 515 + events = iter(sysvals.traceevents) 516 + for e in events: 517 + os.system(sysvals.adb+" shell 'echo 1 > "+\ 518 + sysvals.epath+e+"/enable'") 519 + # clear the trace buffer 520 + os.system(sysvals.adb+" shell 'echo \"\" > "+tp+"trace'") 877 521 878 522 # Function: verifyFtrace 879 523 # Description: 880 524 # Check that ftrace is working on the system 525 + # Output: 526 + # True or False 881 527 def verifyFtrace(): 882 528 global sysvals 883 - files = ["available_filter_functions", "buffer_size_kb", 884 - "current_tracer", "set_ftrace_filter", 885 - "trace", "trace_marker"] 529 + # files needed for any trace data 530 + files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock', 531 + 'trace_marker', 'trace_options', 'tracing_on'] 532 + # files needed for callgraph trace data 533 + tp = sysvals.tpath 534 + if(sysvals.usecallgraph): 535 + files += [ 536 + 'available_filter_functions', 537 + 'set_ftrace_filter', 538 + 'set_graph_function' 539 + ] 886 540 for f in files: 887 - if(os.path.exists(sysvals.tpath+f) == False): 888 - return False 541 + if(sysvals.android): 542 + out = os.popen(sysvals.adb+' shell ls '+tp+f).read().strip() 543 + if(out != tp+f): 544 + return False 545 + else: 546 + if(os.path.exists(tp+f) == False): 547 + return False 889 548 return True 890 549 891 - def parseStamp(line): 892 - global data, sysvals 893 - stampfmt = r"# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-"+\ 894 - "(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})"+\ 895 - " (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$" 896 - m = re.match(stampfmt, line) 897 - if(m): 898 - dt = datetime.datetime(int(m.group("y"))+2000, int(m.group("m")), 899 - int(m.group("d")), int(m.group("H")), int(m.group("M")), 900 - int(m.group("S"))) 901 - data.stamp['time'] = dt.strftime("%B %d %Y, %I:%M:%S %p") 902 - data.stamp['host'] = m.group("host") 903 - data.stamp['mode'] = m.group("mode") 904 - data.stamp['kernel'] = m.group("kernel") 905 - sysvals.suspendmode = data.stamp['mode'] 906 - 907 - # Function: analyzeTraceLog 550 + # Function: parseStamp 908 551 # Description: 909 - # Analyse an ftrace log output file generated from this app during 910 - # the execution phase. Create an "ftrace" structure in memory for 911 - # subsequent formatting in the html output file 912 - def analyzeTraceLog(): 913 - global sysvals, data 552 + # Pull in the stamp comment line from the data file(s), 553 + # create the stamp, and add it to the global sysvals object 554 + # Arguments: 555 + # m: the valid re.match output for the stamp line 556 + def parseStamp(m, data): 557 + global sysvals 558 + data.stamp = {'time': '', 'host': '', 'mode': ''} 559 + dt = datetime(int(m.group('y'))+2000, int(m.group('m')), 560 + int(m.group('d')), int(m.group('H')), int(m.group('M')), 561 + int(m.group('S'))) 562 + data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p') 563 + data.stamp['host'] = m.group('host') 564 + data.stamp['mode'] = m.group('mode') 565 + data.stamp['kernel'] = m.group('kernel') 566 + sysvals.suspendmode = data.stamp['mode'] 567 + if not sysvals.stamp: 568 + sysvals.stamp = data.stamp 914 569 915 - # the ftrace data is tied to the dmesg data 916 - if(not data.usedmesg): 917 - return 570 + # Function: diffStamp 571 + # Description: 572 + # compare the host, kernel, and mode fields in 3 stamps 573 + # Arguments: 574 + # stamp1: string array with mode, kernel, and host 575 + # stamp2: string array with mode, kernel, and host 576 + # Return: 577 + # True if stamps differ, False if they're the same 578 + def diffStamp(stamp1, stamp2): 579 + if 'host' in stamp1 and 'host' in stamp2: 580 + if stamp1['host'] != stamp2['host']: 581 + return True 582 + if 'kernel' in stamp1 and 'kernel' in stamp2: 583 + if stamp1['kernel'] != stamp2['kernel']: 584 + return True 585 + if 'mode' in stamp1 and 'mode' in stamp2: 586 + if stamp1['mode'] != stamp2['mode']: 587 + return True 588 + return False 918 589 919 - # read through the ftrace and parse the data 920 - data.vprint("Analyzing the ftrace data...") 921 - ftrace_line_fmt = r"^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)"+\ 922 - " *(?P<proc>.*)-(?P<pid>[0-9]*) *\|"+\ 923 - "[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)" 924 - ftemp = dict() 925 - inthepipe = False 590 + # Function: doesTraceLogHaveTraceEvents 591 + # Description: 592 + # Quickly determine if the ftrace log has some or all of the trace events 593 + # required for primary parsing. Set the usetraceevents and/or 594 + # usetraceeventsonly flags in the global sysvals object 595 + def doesTraceLogHaveTraceEvents(): 596 + global sysvals 597 + 598 + sysvals.usetraceeventsonly = True 599 + sysvals.usetraceevents = False 600 + for e in sysvals.traceevents: 601 + out = os.popen('cat '+sysvals.ftracefile+' | grep "'+e+': "').read() 602 + if(not out): 603 + sysvals.usetraceeventsonly = False 604 + if(e == 'suspend_resume' and out): 605 + sysvals.usetraceevents = True 606 + 607 + # Function: appendIncompleteTraceLog 608 + # Description: 609 + # [deprecated for kernel 3.15 or newer] 610 + # Legacy support of ftrace outputs that lack the device_pm_callback 611 + # and/or suspend_resume trace events. The primary data should be 612 + # taken from dmesg, and this ftrace is used only for callgraph data 613 + # or custom actions in the timeline. The data is appended to the Data 614 + # objects provided. 615 + # Arguments: 616 + # testruns: the array of Data objects obtained from parseKernelLog 617 + def appendIncompleteTraceLog(testruns): 618 + global sysvals 619 + 620 + # create TestRun vessels for ftrace parsing 621 + testcnt = len(testruns) 622 + testidx = -1 623 + testrun = [] 624 + for data in testruns: 625 + testrun.append(TestRun(data)) 626 + 627 + # extract the callgraph and traceevent data 628 + vprint('Analyzing the ftrace data...') 926 629 tf = open(sysvals.ftracefile, 'r') 927 - count = 0 928 630 for line in tf: 929 - count = count + 1 930 - # grab the time stamp if it's valid 931 - if(count == 1): 932 - parseStamp(line) 631 + # remove any latent carriage returns 632 + line = line.replace('\r\n', '') 633 + # grab the time stamp first (signifies the start of the test run) 634 + m = re.match(sysvals.stampfmt, line) 635 + if(m): 636 + testidx += 1 637 + parseStamp(m, testrun[testidx].data) 933 638 continue 934 - # parse only valid lines 935 - m = re.match(ftrace_line_fmt, line) 639 + # pull out any firmware data 640 + if(re.match(sysvals.firmwarefmt, line)): 641 + continue 642 + # if we havent found a test time stamp yet keep spinning til we do 643 + if(testidx < 0): 644 + continue 645 + # determine the trace data type (required for further parsing) 646 + m = re.match(sysvals.tracertypefmt, line) 647 + if(m): 648 + tracer = m.group('t') 649 + testrun[testidx].setTracerType(tracer) 650 + continue 651 + # parse only valid lines, if this isnt one move on 652 + m = re.match(testrun[testidx].ftrace_line_fmt, line) 936 653 if(not m): 937 654 continue 938 - m_time = m.group("time") 939 - m_pid = m.group("pid") 940 - m_msg = m.group("msg") 941 - m_dur = m.group("dur") 655 + # gather the basic message data from the line 656 + m_time = m.group('time') 657 + m_pid = m.group('pid') 658 + m_msg = m.group('msg') 659 + if(testrun[testidx].cgformat): 660 + m_param3 = m.group('dur') 661 + else: 662 + m_param3 = 'traceevent' 942 663 if(m_time and m_pid and m_msg): 943 - t = FTraceLine(m_time, m_msg, m_dur) 664 + t = FTraceLine(m_time, m_msg, m_param3) 944 665 pid = int(m_pid) 945 666 else: 946 667 continue ··· 1105 512 if(not t.fcall and not t.freturn and not t.fevent): 1106 513 continue 1107 514 # only parse the ftrace data during suspend/resume 1108 - if(not inthepipe): 515 + data = testrun[testidx].data 516 + if(not testrun[testidx].inthepipe): 1109 517 # look for the suspend start marker 1110 518 if(t.fevent): 1111 - if(t.name == "SUSPEND START"): 1112 - data.vprint("SUSPEND START %f %s:%d" % (t.time, sysvals.ftracefile, count)) 1113 - inthepipe = True 519 + if(t.name == 'SUSPEND START'): 520 + testrun[testidx].inthepipe = True 521 + data.setStart(t.time) 1114 522 continue 1115 523 else: 1116 - # look for the resume end marker 524 + # trace event processing 1117 525 if(t.fevent): 1118 - if(t.name == "RESUME COMPLETE"): 1119 - data.vprint("RESUME COMPLETE %f %s:%d" % (t.time, sysvals.ftracefile, count)) 1120 - inthepipe = False 1121 - break 1122 - continue 1123 - # create a callgraph object for the data 1124 - if(pid not in ftemp): 1125 - ftemp[pid] = FTraceCallGraph() 1126 - # when the call is finished, see which device matches it 1127 - if(ftemp[pid].addLine(t, m)): 1128 - if(not ftemp[pid].sanityCheck()): 1129 - id = "task %s cpu %s" % (pid, m.group("cpu")) 1130 - data.vprint("Sanity check failed for "+id+", ignoring this callback") 1131 - continue 1132 - callstart = ftemp[pid].start 1133 - callend = ftemp[pid].end 1134 - for p in data.phases: 1135 - if(data.dmesg[p]['start'] <= callstart and callstart <= data.dmesg[p]['end']): 1136 - list = data.dmesg[p]['list'] 1137 - for devname in list: 1138 - dev = list[devname] 1139 - if(pid == dev['pid'] and callstart <= dev['start'] and callend >= dev['end']): 1140 - data.vprint("%15s [%f - %f] %s(%d)" % (p, callstart, callend, devname, pid)) 1141 - dev['ftrace'] = ftemp[pid] 526 + if(t.name == 'RESUME COMPLETE'): 527 + testrun[testidx].inthepipe = False 528 + data.setEnd(t.time) 529 + if(testidx == testcnt - 1): 1142 530 break 1143 - ftemp[pid] = FTraceCallGraph() 531 + continue 532 + # general trace events have two types, begin and end 533 + if(re.match('(?P<name>.*) begin$', t.name)): 534 + isbegin = True 535 + elif(re.match('(?P<name>.*) end$', t.name)): 536 + isbegin = False 537 + else: 538 + continue 539 + m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name) 540 + if(m): 541 + val = m.group('val') 542 + if val == '0': 543 + name = m.group('name') 544 + else: 545 + name = m.group('name')+'['+val+']' 546 + else: 547 + m = re.match('(?P<name>.*) .*', t.name) 548 + name = m.group('name') 549 + # special processing for trace events 550 + if re.match('dpm_prepare\[.*', name): 551 + continue 552 + elif re.match('machine_suspend.*', name): 553 + continue 554 + elif re.match('suspend_enter\[.*', name): 555 + if(not isbegin): 556 + data.dmesg['suspend_prepare']['end'] = t.time 557 + continue 558 + elif re.match('dpm_suspend\[.*', name): 559 + if(not isbegin): 560 + data.dmesg['suspend']['end'] = t.time 561 + continue 562 + elif re.match('dpm_suspend_late\[.*', name): 563 + if(isbegin): 564 + data.dmesg['suspend_late']['start'] = t.time 565 + else: 566 + data.dmesg['suspend_late']['end'] = t.time 567 + continue 568 + elif re.match('dpm_suspend_noirq\[.*', name): 569 + if(isbegin): 570 + data.dmesg['suspend_noirq']['start'] = t.time 571 + else: 572 + data.dmesg['suspend_noirq']['end'] = t.time 573 + continue 574 + elif re.match('dpm_resume_noirq\[.*', name): 575 + if(isbegin): 576 + data.dmesg['resume_machine']['end'] = t.time 577 + data.dmesg['resume_noirq']['start'] = t.time 578 + else: 579 + data.dmesg['resume_noirq']['end'] = t.time 580 + continue 581 + elif re.match('dpm_resume_early\[.*', name): 582 + if(isbegin): 583 + data.dmesg['resume_early']['start'] = t.time 584 + else: 585 + data.dmesg['resume_early']['end'] = t.time 586 + continue 587 + elif re.match('dpm_resume\[.*', name): 588 + if(isbegin): 589 + data.dmesg['resume']['start'] = t.time 590 + else: 591 + data.dmesg['resume']['end'] = t.time 592 + continue 593 + elif re.match('dpm_complete\[.*', name): 594 + if(isbegin): 595 + data.dmesg['resume_complete']['start'] = t.time 596 + else: 597 + data.dmesg['resume_complete']['end'] = t.time 598 + continue 599 + # is this trace event outside of the devices calls 600 + if(data.isTraceEventOutsideDeviceCalls(pid, t.time)): 601 + # global events (outside device calls) are simply graphed 602 + if(isbegin): 603 + # store each trace event in ttemp 604 + if(name not in testrun[testidx].ttemp): 605 + testrun[testidx].ttemp[name] = [] 606 + testrun[testidx].ttemp[name].append(\ 607 + {'begin': t.time, 'end': t.time}) 608 + else: 609 + # finish off matching trace event in ttemp 610 + if(name in testrun[testidx].ttemp): 611 + testrun[testidx].ttemp[name][-1]['end'] = t.time 612 + else: 613 + if(isbegin): 614 + data.addIntraDevTraceEvent('', name, pid, t.time) 615 + else: 616 + data.capIntraDevTraceEvent('', name, pid, t.time) 617 + # call/return processing 618 + elif sysvals.usecallgraph: 619 + # create a callgraph object for the data 620 + if(pid not in testrun[testidx].ftemp): 621 + testrun[testidx].ftemp[pid] = [] 622 + testrun[testidx].ftemp[pid].append(FTraceCallGraph()) 623 + # when the call is finished, see which device matches it 624 + cg = testrun[testidx].ftemp[pid][-1] 625 + if(cg.addLine(t, m)): 626 + testrun[testidx].ftemp[pid].append(FTraceCallGraph()) 1144 627 tf.close() 1145 628 1146 - # Function: sortKernelLog 629 + for test in testrun: 630 + # add the traceevent data to the device hierarchy 631 + if(sysvals.usetraceevents): 632 + for name in test.ttemp: 633 + for event in test.ttemp[name]: 634 + begin = event['begin'] 635 + end = event['end'] 636 + # if event starts before timeline start, expand timeline 637 + if(begin < test.data.start): 638 + test.data.setStart(begin) 639 + # if event ends after timeline end, expand the timeline 640 + if(end > test.data.end): 641 + test.data.setEnd(end) 642 + test.data.newActionGlobal(name, begin, end) 643 + 644 + # add the callgraph data to the device hierarchy 645 + for pid in test.ftemp: 646 + for cg in test.ftemp[pid]: 647 + if(not cg.sanityCheck()): 648 + id = 'task %s cpu %s' % (pid, m.group('cpu')) 649 + vprint('Sanity check failed for '+\ 650 + id+', ignoring this callback') 651 + continue 652 + callstart = cg.start 653 + callend = cg.end 654 + for p in test.data.phases: 655 + if(test.data.dmesg[p]['start'] <= callstart and 656 + callstart <= test.data.dmesg[p]['end']): 657 + list = test.data.dmesg[p]['list'] 658 + for devname in list: 659 + dev = list[devname] 660 + if(pid == dev['pid'] and 661 + callstart <= dev['start'] and 662 + callend >= dev['end']): 663 + dev['ftrace'] = cg 664 + break 665 + 666 + if(sysvals.verbose): 667 + test.data.printDetails() 668 + 669 + 670 + # add the time in between the tests as a new phase so we can see it 671 + if(len(testruns) > 1): 672 + t1e = testruns[0].getEnd() 673 + t2s = testruns[-1].getStart() 674 + testruns[-1].newPhaseWithSingleAction('user mode', \ 675 + 'user mode', t1e, t2s, '#FF9966') 676 + 677 + # Function: parseTraceLog 1147 678 # Description: 1148 - # The dmesg output log sometimes comes with with lines that have 1149 - # timestamps out of order. This could cause issues since a call 1150 - # could accidentally end up in the wrong phase 1151 - def sortKernelLog(): 1152 - global sysvals, data 679 + # Analyze an ftrace log output file generated from this app during 680 + # the execution phase. Used when the ftrace log is the primary data source 681 + # and includes the suspend_resume and device_pm_callback trace events 682 + # The ftrace filename is taken from sysvals 683 + # Output: 684 + # An array of Data objects 685 + def parseTraceLog(): 686 + global sysvals 687 + 688 + vprint('Analyzing the ftrace data...') 689 + if(os.path.exists(sysvals.ftracefile) == False): 690 + doError('%s doesnt exist' % sysvals.ftracefile, False) 691 + 692 + # extract the callgraph and traceevent data 693 + testruns = [] 694 + testdata = [] 695 + testrun = 0 696 + data = 0 697 + tf = open(sysvals.ftracefile, 'r') 698 + phase = 'suspend_prepare' 699 + for line in tf: 700 + # remove any latent carriage returns 701 + line = line.replace('\r\n', '') 702 + # stamp line: each stamp means a new test run 703 + m = re.match(sysvals.stampfmt, line) 704 + if(m): 705 + data = Data(len(testdata)) 706 + testdata.append(data) 707 + testrun = TestRun(data) 708 + testruns.append(testrun) 709 + parseStamp(m, data) 710 + continue 711 + if(not data): 712 + continue 713 + # firmware line: pull out any firmware data 714 + m = re.match(sysvals.firmwarefmt, line) 715 + if(m): 716 + data.fwSuspend = int(m.group('s')) 717 + data.fwResume = int(m.group('r')) 718 + if(data.fwSuspend > 0 or data.fwResume > 0): 719 + data.fwValid = True 720 + continue 721 + # tracer type line: determine the trace data type 722 + m = re.match(sysvals.tracertypefmt, line) 723 + if(m): 724 + tracer = m.group('t') 725 + testrun.setTracerType(tracer) 726 + continue 727 + # post resume time line: did this test run include post-resume data 728 + m = re.match(sysvals.postresumefmt, line) 729 + if(m): 730 + t = int(m.group('t')) 731 + if(t > 0): 732 + sysvals.postresumetime = t 733 + continue 734 + # ftrace line: parse only valid lines 735 + m = re.match(testrun.ftrace_line_fmt, line) 736 + if(not m): 737 + continue 738 + # gather the basic message data from the line 739 + m_time = m.group('time') 740 + m_pid = m.group('pid') 741 + m_msg = m.group('msg') 742 + if(testrun.cgformat): 743 + m_param3 = m.group('dur') 744 + else: 745 + m_param3 = 'traceevent' 746 + if(m_time and m_pid and m_msg): 747 + t = FTraceLine(m_time, m_msg, m_param3) 748 + pid = int(m_pid) 749 + else: 750 + continue 751 + # the line should be a call, return, or event 752 + if(not t.fcall and not t.freturn and not t.fevent): 753 + continue 754 + # only parse the ftrace data during suspend/resume 755 + if(not testrun.inthepipe): 756 + # look for the suspend start marker 757 + if(t.fevent): 758 + if(t.name == 'SUSPEND START'): 759 + testrun.inthepipe = True 760 + data.setStart(t.time) 761 + continue 762 + # trace event processing 763 + if(t.fevent): 764 + if(t.name == 'RESUME COMPLETE'): 765 + if(sysvals.postresumetime > 0): 766 + phase = 'post_resume' 767 + data.newPhase(phase, t.time, t.time, '#FF9966', -1) 768 + else: 769 + testrun.inthepipe = False 770 + data.setEnd(t.time) 771 + continue 772 + if(phase == 'post_resume'): 773 + data.setEnd(t.time) 774 + if(t.type == 'suspend_resume'): 775 + # suspend_resume trace events have two types, begin and end 776 + if(re.match('(?P<name>.*) begin$', t.name)): 777 + isbegin = True 778 + elif(re.match('(?P<name>.*) end$', t.name)): 779 + isbegin = False 780 + else: 781 + continue 782 + m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name) 783 + if(m): 784 + val = m.group('val') 785 + if val == '0': 786 + name = m.group('name') 787 + else: 788 + name = m.group('name')+'['+val+']' 789 + else: 790 + m = re.match('(?P<name>.*) .*', t.name) 791 + name = m.group('name') 792 + # ignore these events 793 + if(re.match('acpi_suspend\[.*', t.name) or 794 + re.match('suspend_enter\[.*', name)): 795 + continue 796 + # -- phase changes -- 797 + # suspend_prepare start 798 + if(re.match('dpm_prepare\[.*', t.name)): 799 + phase = 'suspend_prepare' 800 + if(not isbegin): 801 + data.dmesg[phase]['end'] = t.time 802 + continue 803 + # suspend start 804 + elif(re.match('dpm_suspend\[.*', t.name)): 805 + phase = 'suspend' 806 + data.setPhase(phase, t.time, isbegin) 807 + continue 808 + # suspend_late start 809 + elif(re.match('dpm_suspend_late\[.*', t.name)): 810 + phase = 'suspend_late' 811 + data.setPhase(phase, t.time, isbegin) 812 + continue 813 + # suspend_noirq start 814 + elif(re.match('dpm_suspend_noirq\[.*', t.name)): 815 + phase = 'suspend_noirq' 816 + data.setPhase(phase, t.time, isbegin) 817 + if(not isbegin): 818 + phase = 'suspend_machine' 819 + data.dmesg[phase]['start'] = t.time 820 + continue 821 + # suspend_machine/resume_machine 822 + elif(re.match('machine_suspend\[.*', t.name)): 823 + if(isbegin): 824 + phase = 'suspend_machine' 825 + data.dmesg[phase]['end'] = t.time 826 + data.tSuspended = t.time 827 + else: 828 + if(sysvals.suspendmode in ['mem', 'disk']): 829 + data.dmesg['suspend_machine']['end'] = t.time 830 + data.tSuspended = t.time 831 + phase = 'resume_machine' 832 + data.dmesg[phase]['start'] = t.time 833 + data.tResumed = t.time 834 + data.tLow = data.tResumed - data.tSuspended 835 + continue 836 + # resume_noirq start 837 + elif(re.match('dpm_resume_noirq\[.*', t.name)): 838 + phase = 'resume_noirq' 839 + data.setPhase(phase, t.time, isbegin) 840 + if(isbegin): 841 + data.dmesg['resume_machine']['end'] = t.time 842 + continue 843 + # resume_early start 844 + elif(re.match('dpm_resume_early\[.*', t.name)): 845 + phase = 'resume_early' 846 + data.setPhase(phase, t.time, isbegin) 847 + continue 848 + # resume start 849 + elif(re.match('dpm_resume\[.*', t.name)): 850 + phase = 'resume' 851 + data.setPhase(phase, t.time, isbegin) 852 + continue 853 + # resume complete start 854 + elif(re.match('dpm_complete\[.*', t.name)): 855 + phase = 'resume_complete' 856 + if(isbegin): 857 + data.dmesg[phase]['start'] = t.time 858 + continue 859 + 860 + # is this trace event outside of the devices calls 861 + if(data.isTraceEventOutsideDeviceCalls(pid, t.time)): 862 + # global events (outside device calls) are simply graphed 863 + if(name not in testrun.ttemp): 864 + testrun.ttemp[name] = [] 865 + if(isbegin): 866 + # create a new list entry 867 + testrun.ttemp[name].append(\ 868 + {'begin': t.time, 'end': t.time}) 869 + else: 870 + if(len(testrun.ttemp[name]) > 0): 871 + # if an antry exists, assume this is its end 872 + testrun.ttemp[name][-1]['end'] = t.time 873 + elif(phase == 'post_resume'): 874 + # post resume events can just have ends 875 + testrun.ttemp[name].append({ 876 + 'begin': data.dmesg[phase]['start'], 877 + 'end': t.time}) 878 + else: 879 + if(isbegin): 880 + data.addIntraDevTraceEvent('', name, pid, t.time) 881 + else: 882 + data.capIntraDevTraceEvent('', name, pid, t.time) 883 + # device callback start 884 + elif(t.type == 'device_pm_callback_start'): 885 + m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\ 886 + t.name); 887 + if(not m): 888 + continue 889 + drv = m.group('drv') 890 + n = m.group('d') 891 + p = m.group('p') 892 + if(n and p): 893 + data.newAction(phase, n, pid, p, t.time, -1, drv) 894 + # device callback finish 895 + elif(t.type == 'device_pm_callback_end'): 896 + m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name); 897 + if(not m): 898 + continue 899 + n = m.group('d') 900 + list = data.dmesg[phase]['list'] 901 + if(n in list): 902 + dev = list[n] 903 + dev['length'] = t.time - dev['start'] 904 + dev['end'] = t.time 905 + # callgraph processing 906 + elif sysvals.usecallgraph: 907 + # this shouldn't happen, but JIC, ignore callgraph data post-res 908 + if(phase == 'post_resume'): 909 + continue 910 + # create a callgraph object for the data 911 + if(pid not in testrun.ftemp): 912 + testrun.ftemp[pid] = [] 913 + testrun.ftemp[pid].append(FTraceCallGraph()) 914 + # when the call is finished, see which device matches it 915 + cg = testrun.ftemp[pid][-1] 916 + if(cg.addLine(t, m)): 917 + testrun.ftemp[pid].append(FTraceCallGraph()) 918 + tf.close() 919 + 920 + for test in testruns: 921 + # add the traceevent data to the device hierarchy 922 + if(sysvals.usetraceevents): 923 + for name in test.ttemp: 924 + for event in test.ttemp[name]: 925 + begin = event['begin'] 926 + end = event['end'] 927 + # if event starts before timeline start, expand timeline 928 + if(begin < test.data.start): 929 + test.data.setStart(begin) 930 + # if event ends after timeline end, expand the timeline 931 + if(end > test.data.end): 932 + test.data.setEnd(end) 933 + test.data.newActionGlobal(name, begin, end) 934 + 935 + # add the callgraph data to the device hierarchy 936 + borderphase = { 937 + 'dpm_prepare': 'suspend_prepare', 938 + 'dpm_complete': 'resume_complete' 939 + } 940 + for pid in test.ftemp: 941 + for cg in test.ftemp[pid]: 942 + if len(cg.list) < 2: 943 + continue 944 + if(not cg.sanityCheck()): 945 + id = 'task %s cpu %s' % (pid, m.group('cpu')) 946 + vprint('Sanity check failed for '+\ 947 + id+', ignoring this callback') 948 + continue 949 + callstart = cg.start 950 + callend = cg.end 951 + if(cg.list[0].name in borderphase): 952 + p = borderphase[cg.list[0].name] 953 + list = test.data.dmesg[p]['list'] 954 + for devname in list: 955 + dev = list[devname] 956 + if(pid == dev['pid'] and 957 + callstart <= dev['start'] and 958 + callend >= dev['end']): 959 + dev['ftrace'] = cg.slice(dev['start'], dev['end']) 960 + continue 961 + if(cg.list[0].name != 'dpm_run_callback'): 962 + continue 963 + for p in test.data.phases: 964 + if(test.data.dmesg[p]['start'] <= callstart and 965 + callstart <= test.data.dmesg[p]['end']): 966 + list = test.data.dmesg[p]['list'] 967 + for devname in list: 968 + dev = list[devname] 969 + if(pid == dev['pid'] and 970 + callstart <= dev['start'] and 971 + callend >= dev['end']): 972 + dev['ftrace'] = cg 973 + break 974 + 975 + # fill in any missing phases 976 + for data in testdata: 977 + lp = data.phases[0] 978 + for p in data.phases: 979 + if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): 980 + print('WARNING: phase "%s" is missing!' % p) 981 + if(data.dmesg[p]['start'] < 0): 982 + data.dmesg[p]['start'] = data.dmesg[lp]['end'] 983 + if(p == 'resume_machine'): 984 + data.tSuspended = data.dmesg[lp]['end'] 985 + data.tResumed = data.dmesg[lp]['end'] 986 + data.tLow = 0 987 + if(data.dmesg[p]['end'] < 0): 988 + data.dmesg[p]['end'] = data.dmesg[p]['start'] 989 + lp = p 990 + 991 + if(len(sysvals.devicefilter) > 0): 992 + data.deviceFilter(sysvals.devicefilter) 993 + data.fixupInitcallsThatDidntReturn() 994 + if(sysvals.verbose): 995 + data.printDetails() 996 + 997 + # add the time in between the tests as a new phase so we can see it 998 + if(len(testdata) > 1): 999 + t1e = testdata[0].getEnd() 1000 + t2s = testdata[-1].getStart() 1001 + testdata[-1].newPhaseWithSingleAction('user mode', \ 1002 + 'user mode', t1e, t2s, '#FF9966') 1003 + return testdata 1004 + 1005 + # Function: loadKernelLog 1006 + # Description: 1007 + # [deprecated for kernel 3.15.0 or newer] 1008 + # load the dmesg file into memory and fix up any ordering issues 1009 + # The dmesg filename is taken from sysvals 1010 + # Output: 1011 + # An array of empty Data objects with only their dmesgtext attributes set 1012 + def loadKernelLog(): 1013 + global sysvals 1014 + 1015 + vprint('Analyzing the dmesg data...') 1016 + if(os.path.exists(sysvals.dmesgfile) == False): 1017 + doError('%s doesnt exist' % sysvals.dmesgfile, False) 1018 + 1019 + # there can be multiple test runs in a single file delineated by stamps 1020 + testruns = [] 1021 + data = 0 1153 1022 lf = open(sysvals.dmesgfile, 'r') 1154 - dmesglist = [] 1155 - count = 0 1156 1023 for line in lf: 1157 - line = line.replace("\r\n", "") 1158 - if(count == 0): 1159 - parseStamp(line) 1160 - elif(count == 1): 1161 - m = re.match(r"# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$", line) 1162 - if(m): 1163 - data.fwSuspend = int(m.group("s")) 1164 - data.fwResume = int(m.group("r")) 1165 - if(data.fwSuspend > 0 or data.fwResume > 0): 1166 - data.fwValid = True 1167 - if(re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)): 1168 - dmesglist.append(line) 1169 - count += 1 1024 + line = line.replace('\r\n', '') 1025 + idx = line.find('[') 1026 + if idx > 1: 1027 + line = line[idx:] 1028 + m = re.match(sysvals.stampfmt, line) 1029 + if(m): 1030 + if(data): 1031 + testruns.append(data) 1032 + data = Data(len(testruns)) 1033 + parseStamp(m, data) 1034 + continue 1035 + if(not data): 1036 + continue 1037 + m = re.match(sysvals.firmwarefmt, line) 1038 + if(m): 1039 + data.fwSuspend = int(m.group('s')) 1040 + data.fwResume = int(m.group('r')) 1041 + if(data.fwSuspend > 0 or data.fwResume > 0): 1042 + data.fwValid = True 1043 + continue 1044 + m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) 1045 + if(m): 1046 + data.dmesgtext.append(line) 1047 + if(re.match('ACPI: resume from mwait', m.group('msg'))): 1048 + print('NOTE: This suspend appears to be freeze rather than'+\ 1049 + ' %s, it will be treated as such' % sysvals.suspendmode) 1050 + sysvals.suspendmode = 'freeze' 1051 + else: 1052 + vprint('ignoring dmesg line: %s' % line.replace('\n', '')) 1053 + testruns.append(data) 1170 1054 lf.close() 1171 - last = "" 1172 1055 1173 - # fix lines with the same time stamp and function with the call and return swapped 1174 - for line in dmesglist: 1175 - mc = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) calling (?P<f>.*)\+ @ .*, parent: .*", line) 1176 - mr = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) call (?P<f>.*)\+ returned .* after (?P<dt>.*) usecs", last) 1177 - if(mc and mr and (mc.group("t") == mr.group("t")) and (mc.group("f") == mr.group("f"))): 1178 - i = dmesglist.index(last) 1179 - j = dmesglist.index(line) 1180 - dmesglist[i] = line 1181 - dmesglist[j] = last 1182 - last = line 1183 - return dmesglist 1056 + if(not data): 1057 + print('ERROR: analyze_suspend header missing from dmesg log') 1058 + sys.exit() 1184 1059 1185 - # Function: analyzeKernelLog 1060 + # fix lines with same timestamp/function with the call and return swapped 1061 + for data in testruns: 1062 + last = '' 1063 + for line in data.dmesgtext: 1064 + mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ 1065 + '(?P<f>.*)\+ @ .*, parent: .*', line) 1066 + mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ 1067 + '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last) 1068 + if(mc and mr and (mc.group('t') == mr.group('t')) and 1069 + (mc.group('f') == mr.group('f'))): 1070 + i = data.dmesgtext.index(last) 1071 + j = data.dmesgtext.index(line) 1072 + data.dmesgtext[i] = line 1073 + data.dmesgtext[j] = last 1074 + last = line 1075 + return testruns 1076 + 1077 + # Function: parseKernelLog 1186 1078 # Description: 1079 + # [deprecated for kernel 3.15.0 or newer] 1187 1080 # Analyse a dmesg log output file generated from this app during 1188 1081 # the execution phase. Create a set of device structures in memory 1189 1082 # for subsequent formatting in the html output file 1190 - def analyzeKernelLog(): 1191 - global sysvals, data 1083 + # This call is only for legacy support on kernels where the ftrace 1084 + # data lacks the suspend_resume or device_pm_callbacks trace events. 1085 + # Arguments: 1086 + # data: an empty Data object (with dmesgtext) obtained from loadKernelLog 1087 + # Output: 1088 + # The filled Data object 1089 + def parseKernelLog(data): 1090 + global sysvals 1192 1091 1193 - print("PROCESSING DATA") 1194 - data.vprint("Analyzing the dmesg data...") 1195 - if(os.path.exists(sysvals.dmesgfile) == False): 1196 - print("ERROR: %s doesn't exist") % sysvals.dmesgfile 1197 - return False 1092 + phase = 'suspend_runtime' 1198 1093 1199 - lf = sortKernelLog() 1200 - phase = "suspend_runtime" 1094 + if(data.fwValid): 1095 + vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \ 1096 + (data.fwSuspend, data.fwResume)) 1201 1097 1098 + # dmesg phase match table 1202 1099 dm = { 1203 - 'suspend_general': r"PM: Syncing filesystems.*", 1204 - 'suspend_early': r"PM: suspend of devices complete after.*", 1205 - 'suspend_noirq': r"PM: late suspend of devices complete after.*", 1206 - 'suspend_cpu': r"PM: noirq suspend of devices complete after.*", 1207 - 'resume_cpu': r"ACPI: Low-level resume complete.*", 1208 - 'resume_noirq': r"ACPI: Waking up from system sleep state.*", 1209 - 'resume_early': r"PM: noirq resume of devices complete after.*", 1210 - 'resume_general': r"PM: early resume of devices complete after.*", 1211 - 'resume_complete': r".*Restarting tasks \.\.\..*", 1100 + 'suspend_prepare': 'PM: Syncing filesystems.*', 1101 + 'suspend': 'PM: Entering [a-z]* sleep.*', 1102 + 'suspend_late': 'PM: suspend of devices complete after.*', 1103 + 'suspend_noirq': 'PM: late suspend of devices complete after.*', 1104 + 'suspend_machine': 'PM: noirq suspend of devices complete after.*', 1105 + 'resume_machine': 'ACPI: Low-level resume complete.*', 1106 + 'resume_noirq': 'ACPI: Waking up from system sleep state.*', 1107 + 'resume_early': 'PM: noirq resume of devices complete after.*', 1108 + 'resume': 'PM: early resume of devices complete after.*', 1109 + 'resume_complete': 'PM: resume of devices complete after.*', 1110 + 'post_resume': '.*Restarting tasks \.\.\..*', 1212 1111 } 1213 - if(sysvals.suspendmode == "standby"): 1214 - dm['resume_cpu'] = r"PM: Restoring platform NVS memory" 1215 - elif(sysvals.suspendmode == "disk"): 1216 - dm['suspend_early'] = r"PM: freeze of devices complete after.*" 1217 - dm['suspend_noirq'] = r"PM: late freeze of devices complete after.*" 1218 - dm['suspend_cpu'] = r"PM: noirq freeze of devices complete after.*" 1219 - dm['resume_cpu'] = r"PM: Restoring platform NVS memory" 1220 - dm['resume_early'] = r"PM: noirq restore of devices complete after.*" 1221 - dm['resume_general'] = r"PM: early restore of devices complete after.*" 1112 + if(sysvals.suspendmode == 'standby'): 1113 + dm['resume_machine'] = 'PM: Restoring platform NVS memory' 1114 + elif(sysvals.suspendmode == 'disk'): 1115 + dm['suspend_late'] = 'PM: freeze of devices complete after.*' 1116 + dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*' 1117 + dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*' 1118 + dm['resume_machine'] = 'PM: Restoring platform NVS memory' 1119 + dm['resume_early'] = 'PM: noirq restore of devices complete after.*' 1120 + dm['resume'] = 'PM: early restore of devices complete after.*' 1121 + dm['resume_complete'] = 'PM: restore of devices complete after.*' 1122 + elif(sysvals.suspendmode == 'freeze'): 1123 + dm['resume_machine'] = 'ACPI: resume from mwait' 1222 1124 1223 - action_start = 0.0 1224 - for line in lf: 1125 + # action table (expected events that occur and show up in dmesg) 1126 + at = { 1127 + 'sync_filesystems': { 1128 + 'smsg': 'PM: Syncing filesystems.*', 1129 + 'emsg': 'PM: Preparing system for mem sleep.*' }, 1130 + 'freeze_user_processes': { 1131 + 'smsg': 'Freezing user space processes .*', 1132 + 'emsg': 'Freezing remaining freezable tasks.*' }, 1133 + 'freeze_tasks': { 1134 + 'smsg': 'Freezing remaining freezable tasks.*', 1135 + 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' }, 1136 + 'ACPI prepare': { 1137 + 'smsg': 'ACPI: Preparing to enter system sleep state.*', 1138 + 'emsg': 'PM: Saving platform NVS memory.*' }, 1139 + 'PM vns': { 1140 + 'smsg': 'PM: Saving platform NVS memory.*', 1141 + 'emsg': 'Disabling non-boot CPUs .*' }, 1142 + } 1143 + 1144 + t0 = -1.0 1145 + cpu_start = -1.0 1146 + prevktime = -1.0 1147 + actions = dict() 1148 + for line in data.dmesgtext: 1225 1149 # -- preprocessing -- 1226 1150 # parse each dmesg line into the time and message 1227 - m = re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line) 1151 + m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) 1228 1152 if(m): 1229 - ktime = float(m.group("ktime")) 1230 - msg = m.group("msg") 1153 + val = m.group('ktime') 1154 + try: 1155 + ktime = float(val) 1156 + except: 1157 + doWarning('INVALID DMESG LINE: '+\ 1158 + line.replace('\n', ''), 'dmesg') 1159 + continue 1160 + msg = m.group('msg') 1161 + # initialize data start to first line time 1162 + if t0 < 0: 1163 + data.setStart(ktime) 1164 + t0 = ktime 1231 1165 else: 1232 - print line 1233 1166 continue 1234 1167 1235 - # -- phase changes -- 1236 - # suspend_general start 1237 - if(re.match(dm['suspend_general'], msg)): 1238 - phase = "suspend_general" 1168 + # hack for determining resume_machine end for freeze 1169 + if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \ 1170 + and phase == 'resume_machine' and \ 1171 + re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): 1172 + data.dmesg['resume_machine']['end'] = ktime 1173 + phase = 'resume_noirq' 1239 1174 data.dmesg[phase]['start'] = ktime 1240 - data.start = ktime 1241 - # action start: syncing filesystems 1242 - action_start = ktime 1243 - # suspend_early start 1244 - elif(re.match(dm['suspend_early'], msg)): 1245 - data.dmesg["suspend_general"]['end'] = ktime 1246 - phase = "suspend_early" 1175 + 1176 + # -- phase changes -- 1177 + # suspend start 1178 + if(re.match(dm['suspend_prepare'], msg)): 1179 + phase = 'suspend_prepare' 1180 + data.dmesg[phase]['start'] = ktime 1181 + data.setStart(ktime) 1182 + # suspend start 1183 + elif(re.match(dm['suspend'], msg)): 1184 + data.dmesg['suspend_prepare']['end'] = ktime 1185 + phase = 'suspend' 1186 + data.dmesg[phase]['start'] = ktime 1187 + # suspend_late start 1188 + elif(re.match(dm['suspend_late'], msg)): 1189 + data.dmesg['suspend']['end'] = ktime 1190 + phase = 'suspend_late' 1247 1191 data.dmesg[phase]['start'] = ktime 1248 1192 # suspend_noirq start 1249 1193 elif(re.match(dm['suspend_noirq'], msg)): 1250 - data.dmesg["suspend_early"]['end'] = ktime 1251 - phase = "suspend_noirq" 1194 + data.dmesg['suspend_late']['end'] = ktime 1195 + phase = 'suspend_noirq' 1252 1196 data.dmesg[phase]['start'] = ktime 1253 - # suspend_cpu start 1254 - elif(re.match(dm['suspend_cpu'], msg)): 1255 - data.dmesg["suspend_noirq"]['end'] = ktime 1256 - phase = "suspend_cpu" 1197 + # suspend_machine start 1198 + elif(re.match(dm['suspend_machine'], msg)): 1199 + data.dmesg['suspend_noirq']['end'] = ktime 1200 + phase = 'suspend_machine' 1257 1201 data.dmesg[phase]['start'] = ktime 1258 - # resume_cpu start 1259 - elif(re.match(dm['resume_cpu'], msg)): 1260 - data.tSuspended = ktime 1261 - data.dmesg["suspend_cpu"]['end'] = ktime 1262 - phase = "resume_cpu" 1202 + # resume_machine start 1203 + elif(re.match(dm['resume_machine'], msg)): 1204 + if(sysvals.suspendmode in ['freeze', 'standby']): 1205 + data.tSuspended = prevktime 1206 + data.dmesg['suspend_machine']['end'] = prevktime 1207 + else: 1208 + data.tSuspended = ktime 1209 + data.dmesg['suspend_machine']['end'] = ktime 1210 + phase = 'resume_machine' 1211 + data.tResumed = ktime 1212 + data.tLow = data.tResumed - data.tSuspended 1263 1213 data.dmesg[phase]['start'] = ktime 1264 1214 # resume_noirq start 1265 1215 elif(re.match(dm['resume_noirq'], msg)): 1266 - data.dmesg["resume_cpu"]['end'] = ktime 1267 - phase = "resume_noirq" 1216 + data.dmesg['resume_machine']['end'] = ktime 1217 + phase = 'resume_noirq' 1268 1218 data.dmesg[phase]['start'] = ktime 1269 - # action end: ACPI resume 1270 - data.newAction("resume_cpu", "ACPI", -1, "", action_start, ktime) 1271 1219 # resume_early start 1272 1220 elif(re.match(dm['resume_early'], msg)): 1273 - data.dmesg["resume_noirq"]['end'] = ktime 1274 - phase = "resume_early" 1221 + data.dmesg['resume_noirq']['end'] = ktime 1222 + phase = 'resume_early' 1275 1223 data.dmesg[phase]['start'] = ktime 1276 - # resume_general start 1277 - elif(re.match(dm['resume_general'], msg)): 1278 - data.dmesg["resume_early"]['end'] = ktime 1279 - phase = "resume_general" 1224 + # resume start 1225 + elif(re.match(dm['resume'], msg)): 1226 + data.dmesg['resume_early']['end'] = ktime 1227 + phase = 'resume' 1280 1228 data.dmesg[phase]['start'] = ktime 1281 1229 # resume complete start 1282 1230 elif(re.match(dm['resume_complete'], msg)): 1283 - data.dmesg["resume_general"]['end'] = ktime 1284 - data.end = ktime 1285 - phase = "resume_runtime" 1231 + data.dmesg['resume']['end'] = ktime 1232 + phase = 'resume_complete' 1233 + data.dmesg[phase]['start'] = ktime 1234 + # post resume start 1235 + elif(re.match(dm['post_resume'], msg)): 1236 + data.dmesg['resume_complete']['end'] = ktime 1237 + data.setEnd(ktime) 1238 + phase = 'post_resume' 1286 1239 break 1287 1240 1288 1241 # -- device callbacks -- 1289 1242 if(phase in data.phases): 1290 1243 # device init call 1291 - if(re.match(r"calling (?P<f>.*)\+ @ .*, parent: .*", msg)): 1292 - sm = re.match(r"calling (?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)", msg); 1293 - f = sm.group("f") 1294 - n = sm.group("n") 1295 - p = sm.group("p") 1244 + if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): 1245 + sm = re.match('calling (?P<f>.*)\+ @ '+\ 1246 + '(?P<n>.*), parent: (?P<p>.*)', msg); 1247 + f = sm.group('f') 1248 + n = sm.group('n') 1249 + p = sm.group('p') 1296 1250 if(f and n and p): 1297 - data.newAction(phase, f, int(n), p, ktime, -1) 1251 + data.newAction(phase, f, int(n), p, ktime, -1, '') 1298 1252 # device init return 1299 - elif(re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs", msg)): 1300 - sm = re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs(?P<a>.*)", msg); 1301 - f = sm.group("f") 1302 - t = sm.group("t") 1253 + elif(re.match('call (?P<f>.*)\+ returned .* after '+\ 1254 + '(?P<t>.*) usecs', msg)): 1255 + sm = re.match('call (?P<f>.*)\+ returned .* after '+\ 1256 + '(?P<t>.*) usecs(?P<a>.*)', msg); 1257 + f = sm.group('f') 1258 + t = sm.group('t') 1303 1259 list = data.dmesg[phase]['list'] 1304 1260 if(f in list): 1305 1261 dev = list[f] 1306 1262 dev['length'] = int(t) 1307 1263 dev['end'] = ktime 1308 - data.vprint("%15s [%f - %f] %s(%d) %s" % 1309 - (phase, dev['start'], dev['end'], f, dev['pid'], dev['par'])) 1310 1264 1311 - # -- phase specific actions -- 1312 - if(phase == "suspend_general"): 1313 - if(re.match(r"PM: Preparing system for mem sleep.*", msg)): 1314 - data.newAction(phase, "filesystem-sync", -1, "", action_start, ktime) 1315 - elif(re.match(r"Freezing user space processes .*", msg)): 1316 - action_start = ktime 1317 - elif(re.match(r"Freezing remaining freezable tasks.*", msg)): 1318 - data.newAction(phase, "freeze-user-processes", -1, "", action_start, ktime) 1319 - action_start = ktime 1320 - elif(re.match(r"PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*", msg)): 1321 - data.newAction(phase, "freeze-tasks", -1, "", action_start, ktime) 1322 - elif(phase == "suspend_cpu"): 1323 - m = re.match(r"smpboot: CPU (?P<cpu>[0-9]*) is now offline", msg) 1324 - if(m): 1325 - cpu = "CPU"+m.group("cpu") 1326 - data.newAction(phase, cpu, -1, "", action_start, ktime) 1327 - action_start = ktime 1328 - elif(re.match(r"ACPI: Preparing to enter system sleep state.*", msg)): 1329 - action_start = ktime 1330 - elif(re.match(r"Disabling non-boot CPUs .*", msg)): 1331 - data.newAction(phase, "ACPI", -1, "", action_start, ktime) 1332 - action_start = ktime 1333 - elif(phase == "resume_cpu"): 1334 - m = re.match(r"CPU(?P<cpu>[0-9]*) is up", msg) 1335 - if(m): 1336 - cpu = "CPU"+m.group("cpu") 1337 - data.newAction(phase, cpu, -1, "", action_start, ktime) 1338 - action_start = ktime 1339 - elif(re.match(r"Enabling non-boot CPUs .*", msg)): 1340 - action_start = ktime 1265 + # -- non-devicecallback actions -- 1266 + # if trace events are not available, these are better than nothing 1267 + if(not sysvals.usetraceevents): 1268 + # look for known actions 1269 + for a in at: 1270 + if(re.match(at[a]['smsg'], msg)): 1271 + if(a not in actions): 1272 + actions[a] = [] 1273 + actions[a].append({'begin': ktime, 'end': ktime}) 1274 + if(re.match(at[a]['emsg'], msg)): 1275 + actions[a][-1]['end'] = ktime 1276 + # now look for CPU on/off events 1277 + if(re.match('Disabling non-boot CPUs .*', msg)): 1278 + # start of first cpu suspend 1279 + cpu_start = ktime 1280 + elif(re.match('Enabling non-boot CPUs .*', msg)): 1281 + # start of first cpu resume 1282 + cpu_start = ktime 1283 + elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)): 1284 + # end of a cpu suspend, start of the next 1285 + m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg) 1286 + cpu = 'CPU'+m.group('cpu') 1287 + if(cpu not in actions): 1288 + actions[cpu] = [] 1289 + actions[cpu].append({'begin': cpu_start, 'end': ktime}) 1290 + cpu_start = ktime 1291 + elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)): 1292 + # end of a cpu resume, start of the next 1293 + m = re.match('CPU(?P<cpu>[0-9]*) is up', msg) 1294 + cpu = 'CPU'+m.group('cpu') 1295 + if(cpu not in actions): 1296 + actions[cpu] = [] 1297 + actions[cpu].append({'begin': cpu_start, 'end': ktime}) 1298 + cpu_start = ktime 1299 + prevktime = ktime 1341 1300 1342 1301 # fill in any missing phases 1343 - lp = "suspend_general" 1302 + lp = data.phases[0] 1344 1303 for p in data.phases: 1345 - if(p == "suspend_general"): 1346 - continue 1304 + if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): 1305 + print('WARNING: phase "%s" is missing, something went wrong!' % p) 1306 + print(' In %s, this dmesg line denotes the start of %s:' % \ 1307 + (sysvals.suspendmode, p)) 1308 + print(' "%s"' % dm[p]) 1347 1309 if(data.dmesg[p]['start'] < 0): 1348 1310 data.dmesg[p]['start'] = data.dmesg[lp]['end'] 1349 - if(p == "resume_cpu"): 1311 + if(p == 'resume_machine'): 1350 1312 data.tSuspended = data.dmesg[lp]['end'] 1313 + data.tResumed = data.dmesg[lp]['end'] 1314 + data.tLow = 0 1351 1315 if(data.dmesg[p]['end'] < 0): 1352 1316 data.dmesg[p]['end'] = data.dmesg[p]['start'] 1353 1317 lp = p 1354 1318 1319 + # fill in any actions we've found 1320 + for name in actions: 1321 + for event in actions[name]: 1322 + begin = event['begin'] 1323 + end = event['end'] 1324 + # if event starts before timeline start, expand timeline 1325 + if(begin < data.start): 1326 + data.setStart(begin) 1327 + # if event ends after timeline end, expand the timeline 1328 + if(end > data.end): 1329 + data.setEnd(end) 1330 + data.newActionGlobal(name, begin, end) 1331 + 1332 + if(sysvals.verbose): 1333 + data.printDetails() 1334 + if(len(sysvals.devicefilter) > 0): 1335 + data.deviceFilter(sysvals.devicefilter) 1355 1336 data.fixupInitcallsThatDidntReturn() 1356 1337 return True 1357 1338 1358 1339 # Function: setTimelineRows 1359 1340 # Description: 1360 - # Organize the device or thread lists into the smallest 1341 + # Organize the timeline entries into the smallest 1361 1342 # number of rows possible, with no entry overlapping 1362 1343 # Arguments: 1363 - # list: the list to sort (dmesg or ftrace) 1364 - # sortedkeys: sorted key list to use 1344 + # list: the list of devices/actions for a single phase 1345 + # sortedkeys: cronologically sorted key list to use 1346 + # Output: 1347 + # The total number of rows needed to display this phase of the timeline 1365 1348 def setTimelineRows(list, sortedkeys): 1366 - global data 1367 1349 1368 1350 # clear all rows and set them to undefined 1369 1351 remaining = len(list) ··· 1959 791 for ritem in rowdata[row]: 1960 792 rs = ritem['start'] 1961 793 re = ritem['end'] 1962 - if(not (((s <= rs) and (e <= rs)) or ((s >= re) and (e >= re)))): 794 + if(not (((s <= rs) and (e <= rs)) or 795 + ((s >= re) and (e >= re)))): 1963 796 valid = False 1964 797 break 1965 798 if(valid): ··· 1972 803 1973 804 # Function: createTimeScale 1974 805 # Description: 1975 - # Create timescale lines for the dmesg and ftrace timelines 806 + # Create the timescale header for the html timeline 1976 807 # Arguments: 1977 808 # t0: start time (suspend begin) 1978 809 # tMax: end time (resume end) 1979 - # tSuspend: time when suspend occurs 810 + # tSuspend: time when suspend occurs, i.e. the zero time 811 + # Output: 812 + # The html code needed to display the time scale 1980 813 def createTimeScale(t0, tMax, tSuspended): 1981 - global data 1982 - timescale = "<div class=\"t\" style=\"right:{0}%\">{1}</div>\n" 814 + timescale = '<div class="t" style="right:{0}%">{1}</div>\n' 1983 815 output = '<div id="timescale">\n' 1984 816 1985 817 # set scale for timeline ··· 1992 822 tS = 1 1993 823 if(tSuspended < 0): 1994 824 for i in range(int(tTotal/tS)+1): 1995 - pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal)) 825 + pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal)) 1996 826 if(i > 0): 1997 - val = "%0.f" % (float(i)*tS*1000) 827 + val = '%0.fms' % (float(i)*tS*1000) 1998 828 else: 1999 - val = "" 829 + val = '' 2000 830 output += timescale.format(pos, val) 2001 831 else: 2002 832 tSuspend = tSuspended - t0 ··· 2004 834 divSuspend = int(tSuspend/tS) 2005 835 s0 = (tSuspend - tS*divSuspend)*100/tTotal 2006 836 for i in range(divTotal): 2007 - pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal) - s0) 837 + pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal) - s0) 2008 838 if((i == 0) and (s0 < 3)): 2009 - val = "" 839 + val = '' 2010 840 elif(i == divSuspend): 2011 - val = "S/R" 841 + val = 'S/R' 2012 842 else: 2013 - val = "%0.f" % (float(i-divSuspend)*tS*1000) 843 + val = '%0.fms' % (float(i-divSuspend)*tS*1000) 2014 844 output += timescale.format(pos, val) 2015 845 output += '</div>\n' 2016 846 return output 2017 847 848 + # Function: createHTMLSummarySimple 849 + # Description: 850 + # Create summary html file for a series of tests 851 + # Arguments: 852 + # testruns: array of Data objects from parseTraceLog 853 + def createHTMLSummarySimple(testruns, htmlfile): 854 + global sysvals 855 + 856 + # print out the basic summary of all the tests 857 + hf = open(htmlfile, 'w') 858 + 859 + # write the html header first (html head, css code, up to body start) 860 + html = '<!DOCTYPE html>\n<html>\n<head>\n\ 861 + <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ 862 + <title>AnalyzeSuspend Summary</title>\n\ 863 + <style type=\'text/css\'>\n\ 864 + body {overflow-y: scroll;}\n\ 865 + .stamp {width: 100%;text-align:center;background-color:#495E09;line-height:30px;color:white;font: 25px Arial;}\n\ 866 + table {width:100%;border-collapse: collapse;}\n\ 867 + .summary {font: 22px Arial;border:1px solid;}\n\ 868 + th {border: 1px solid black;background-color:#A7C942;color:white;}\n\ 869 + td {text-align: center;}\n\ 870 + tr.alt td {background-color:#EAF2D3;}\n\ 871 + tr.avg td {background-color:#BDE34C;}\n\ 872 + a:link {color: #90B521;}\n\ 873 + a:visited {color: #495E09;}\n\ 874 + a:hover {color: #B1DF28;}\n\ 875 + a:active {color: #FFFFFF;}\n\ 876 + </style>\n</head>\n<body>\n' 877 + 878 + # group test header 879 + count = len(testruns) 880 + headline_stamp = '<div class="stamp">{0} {1} {2} {3} ({4} tests)</div>\n' 881 + html += headline_stamp.format(sysvals.stamp['host'], 882 + sysvals.stamp['kernel'], sysvals.stamp['mode'], 883 + sysvals.stamp['time'], count) 884 + 885 + # check to see if all the tests have the same value 886 + stampcolumns = False 887 + for data in testruns: 888 + if diffStamp(sysvals.stamp, data.stamp): 889 + stampcolumns = True 890 + break 891 + 892 + th = '\t<th>{0}</th>\n' 893 + td = '\t<td>{0}</td>\n' 894 + tdlink = '\t<td><a href="{0}">Click Here</a></td>\n' 895 + 896 + # table header 897 + html += '<table class="summary">\n<tr>\n' 898 + html += th.format("Test #") 899 + if stampcolumns: 900 + html += th.format("Hostname") 901 + html += th.format("Kernel Version") 902 + html += th.format("Suspend Mode") 903 + html += th.format("Test Time") 904 + html += th.format("Suspend Time") 905 + html += th.format("Resume Time") 906 + html += th.format("Detail") 907 + html += '</tr>\n' 908 + 909 + # test data, 1 row per test 910 + sTimeAvg = 0.0 911 + rTimeAvg = 0.0 912 + num = 1 913 + for data in testruns: 914 + # data.end is the end of post_resume 915 + resumeEnd = data.dmesg['resume_complete']['end'] 916 + if num % 2 == 1: 917 + html += '<tr class="alt">\n' 918 + else: 919 + html += '<tr>\n' 920 + 921 + # test num 922 + html += td.format("test %d" % num) 923 + num += 1 924 + if stampcolumns: 925 + # host name 926 + val = "unknown" 927 + if('host' in data.stamp): 928 + val = data.stamp['host'] 929 + html += td.format(val) 930 + # host kernel 931 + val = "unknown" 932 + if('kernel' in data.stamp): 933 + val = data.stamp['kernel'] 934 + html += td.format(val) 935 + # suspend mode 936 + val = "unknown" 937 + if('mode' in data.stamp): 938 + val = data.stamp['mode'] 939 + html += td.format(val) 940 + # test time 941 + val = "unknown" 942 + if('time' in data.stamp): 943 + val = data.stamp['time'] 944 + html += td.format(val) 945 + # suspend time 946 + sTime = (data.tSuspended - data.start)*1000 947 + sTimeAvg += sTime 948 + html += td.format("%3.3f ms" % sTime) 949 + # resume time 950 + rTime = (resumeEnd - data.tResumed)*1000 951 + rTimeAvg += rTime 952 + html += td.format("%3.3f ms" % rTime) 953 + # link to the output html 954 + html += tdlink.format(data.outfile) 955 + 956 + html += '</tr>\n' 957 + 958 + # last line: test average 959 + if(count > 0): 960 + sTimeAvg /= count 961 + rTimeAvg /= count 962 + html += '<tr class="avg">\n' 963 + html += td.format('Average') # name 964 + if stampcolumns: 965 + html += td.format('') # host 966 + html += td.format('') # kernel 967 + html += td.format('') # mode 968 + html += td.format('') # time 969 + html += td.format("%3.3f ms" % sTimeAvg) # suspend time 970 + html += td.format("%3.3f ms" % rTimeAvg) # resume time 971 + html += td.format('') # output link 972 + html += '</tr>\n' 973 + 974 + # flush the data to file 975 + hf.write(html+'</table>\n') 976 + hf.write('</body>\n</html>\n') 977 + hf.close() 978 + 2018 979 # Function: createHTML 2019 980 # Description: 2020 - # Create the output html file. 2021 - def createHTML(): 2022 - global sysvals, data 981 + # Create the output html file from the resident test data 982 + # Arguments: 983 + # testruns: array of Data objects from parseKernelLog or parseTraceLog 984 + # Output: 985 + # True if the html file was created, false if it failed 986 + def createHTML(testruns): 987 + global sysvals 2023 988 2024 - data.normalizeTime() 989 + for data in testruns: 990 + data.normalizeTime(testruns[-1].tSuspended) 2025 991 992 + x2changes = ['', 'absolute'] 993 + if len(testruns) > 1: 994 + x2changes = ['1', 'relative'] 2026 995 # html function templates 2027 996 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n' 2028 - html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n<div id="dmesgzoombox" class="zoombox">\n' 2029 - html_timeline = '<div id="{0}" class="timeline" style="height:{1}px">\n' 997 + html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0] 998 + html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n' 999 + html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n' 1000 + html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n' 2030 1001 html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n' 1002 + html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}%;height:{3}%;width:{4}%;border:1px solid {5};background-color:{5}">{6}</div>\n' 2031 1003 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n' 1004 + html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n' 2032 1005 html_legend = '<div class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n' 2033 1006 html_timetotal = '<table class="time1">\n<tr>'\ 2034 - '<td class="gray">{2} Suspend Time: <b>{0} ms</b></td>'\ 2035 - '<td class="gray">{2} Resume Time: <b>{1} ms</b></td>'\ 1007 + '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\ 1008 + '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\ 1009 + '</tr>\n</table>\n' 1010 + html_timetotal2 = '<table class="time1">\n<tr>'\ 1011 + '<td class="green">{3} Suspend Time: <b>{0} ms</b></td>'\ 1012 + '<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\ 1013 + '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\ 2036 1014 '</tr>\n</table>\n' 2037 1015 html_timegroups = '<table class="time2">\n<tr>'\ 2038 - '<td class="green">Kernel Suspend: {0} ms</td>'\ 2039 - '<td class="purple">Firmware Suspend: {1} ms</td>'\ 2040 - '<td class="purple">Firmware Resume: {2} ms</td>'\ 2041 - '<td class="yellow">Kernel Resume: {3} ms</td>'\ 1016 + '<td class="green">{4}Kernel Suspend: {0} ms</td>'\ 1017 + '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\ 1018 + '<td class="purple">{4}Firmware Resume: {2} ms</td>'\ 1019 + '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\ 2042 1020 '</tr>\n</table>\n' 2043 1021 2044 - # device timeline (dmesg) 2045 - if(data.usedmesg): 2046 - data.vprint("Creating Device Timeline...") 2047 - devtl = Timeline() 1022 + # device timeline 1023 + vprint('Creating Device Timeline...') 1024 + devtl = Timeline() 2048 1025 2049 - # Generate the header for this timeline 2050 - t0 = data.start 2051 - tMax = data.end 2052 - tTotal = tMax - t0 1026 + # Generate the header for this timeline 1027 + textnum = ['First', 'Second'] 1028 + for data in testruns: 1029 + tTotal = data.end - data.start 1030 + tEnd = data.dmesg['resume_complete']['end'] 2053 1031 if(tTotal == 0): 2054 - print("ERROR: No timeline data") 1032 + print('ERROR: No timeline data') 2055 1033 sys.exit() 2056 - suspend_time = "%.0f"%(-data.start*1000) 2057 - resume_time = "%.0f"%(data.end*1000) 1034 + if(data.tLow > 0): 1035 + low_time = '%.0f'%(data.tLow*1000) 2058 1036 if data.fwValid: 2059 - devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Total") 2060 - sktime = "%.3f"%((data.dmesg['suspend_cpu']['end'] - data.dmesg['suspend_general']['start'])*1000) 2061 - sftime = "%.3f"%(data.fwSuspend / 1000000.0) 2062 - rftime = "%.3f"%(data.fwResume / 1000000.0) 2063 - rktime = "%.3f"%((data.dmesg['resume_general']['end'] - data.dmesg['resume_cpu']['start'])*1000) 2064 - devtl.html['timeline'] += html_timegroups.format(sktime, sftime, rftime, rktime) 1037 + suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \ 1038 + (data.fwSuspend/1000000.0)) 1039 + resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \ 1040 + (data.fwResume/1000000.0)) 1041 + testdesc1 = 'Total' 1042 + testdesc2 = '' 1043 + if(len(testruns) > 1): 1044 + testdesc1 = testdesc2 = textnum[data.testnumber] 1045 + testdesc2 += ' ' 1046 + if(data.tLow == 0): 1047 + thtml = html_timetotal.format(suspend_time, \ 1048 + resume_time, testdesc1) 1049 + else: 1050 + thtml = html_timetotal2.format(suspend_time, low_time, \ 1051 + resume_time, testdesc1) 1052 + devtl.html['timeline'] += thtml 1053 + sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \ 1054 + data.getStart())*1000) 1055 + sftime = '%.3f'%(data.fwSuspend / 1000000.0) 1056 + rftime = '%.3f'%(data.fwResume / 1000000.0) 1057 + rktime = '%.3f'%((data.getEnd() - \ 1058 + data.dmesg['resume_machine']['start'])*1000) 1059 + devtl.html['timeline'] += html_timegroups.format(sktime, \ 1060 + sftime, rftime, rktime, testdesc2) 2065 1061 else: 2066 - devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Kernel") 1062 + suspend_time = '%.0f'%((data.tSuspended-data.start)*1000) 1063 + resume_time = '%.0f'%((tEnd-data.tSuspended)*1000) 1064 + testdesc = 'Kernel' 1065 + if(len(testruns) > 1): 1066 + testdesc = textnum[data.testnumber]+' '+testdesc 1067 + if(data.tLow == 0): 1068 + thtml = html_timetotal.format(suspend_time, \ 1069 + resume_time, testdesc) 1070 + else: 1071 + thtml = html_timetotal2.format(suspend_time, low_time, \ 1072 + resume_time, testdesc) 1073 + devtl.html['timeline'] += thtml 2067 1074 2068 - # determine the maximum number of rows we need to draw 2069 - timelinerows = 0 1075 + # time scale for potentially multiple datasets 1076 + t0 = testruns[0].start 1077 + tMax = testruns[-1].end 1078 + tSuspended = testruns[-1].tSuspended 1079 + tTotal = tMax - t0 1080 + 1081 + # determine the maximum number of rows we need to draw 1082 + timelinerows = 0 1083 + for data in testruns: 2070 1084 for phase in data.dmesg: 2071 1085 list = data.dmesg[phase]['list'] 2072 1086 rows = setTimelineRows(list, list) ··· 2258 904 if(rows > timelinerows): 2259 905 timelinerows = rows 2260 906 2261 - # calculate the timeline height and create its bounding box 2262 - devtl.setRows(timelinerows + 1) 2263 - devtl.html['timeline'] += html_zoombox; 2264 - devtl.html['timeline'] += html_timeline.format("dmesg", devtl.height); 907 + # calculate the timeline height and create bounding box, add buttons 908 + devtl.setRows(timelinerows + 1) 909 + devtl.html['timeline'] += html_devlist1 910 + if len(testruns) > 1: 911 + devtl.html['timeline'] += html_devlist2 912 + devtl.html['timeline'] += html_zoombox 913 + devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height) 2265 914 2266 - # draw the colored boxes for each of the phases 915 + # draw the colored boxes for each of the phases 916 + for data in testruns: 2267 917 for b in data.dmesg: 2268 918 phase = data.dmesg[b] 2269 - left = "%.3f" % (((phase['start']-data.start)*100)/tTotal) 2270 - width = "%.3f" % (((phase['end']-phase['start'])*100)/tTotal) 2271 - devtl.html['timeline'] += html_phase.format(left, width, "%.3f"%devtl.scaleH, "%.3f"%(100-devtl.scaleH), data.dmesg[b]['color'], "") 919 + length = phase['end']-phase['start'] 920 + left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) 921 + width = '%.3f' % ((length*100.0)/tTotal) 922 + devtl.html['timeline'] += html_phase.format(left, width, \ 923 + '%.3f'%devtl.scaleH, '%.3f'%(100-devtl.scaleH), \ 924 + data.dmesg[b]['color'], '') 2272 925 2273 - # draw the time scale, try to make the number of labels readable 2274 - devtl.html['scale'] = createTimeScale(t0, tMax, data.tSuspended) 2275 - devtl.html['timeline'] += devtl.html['scale'] 926 + # draw the time scale, try to make the number of labels readable 927 + devtl.html['scale'] = createTimeScale(t0, tMax, tSuspended) 928 + devtl.html['timeline'] += devtl.html['scale'] 929 + for data in testruns: 2276 930 for b in data.dmesg: 2277 931 phaselist = data.dmesg[b]['list'] 2278 932 for d in phaselist: 2279 933 name = d 2280 - if(d in data.altdevname): 2281 - name = data.altdevname[d] 934 + drv = '' 2282 935 dev = phaselist[d] 936 + if(d in sysvals.altdevname): 937 + name = sysvals.altdevname[d] 938 + if('drv' in dev and dev['drv']): 939 + drv = ' {%s}' % dev['drv'] 2283 940 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] 2284 - top = "%.3f" % ((dev['row']*height) + devtl.scaleH) 2285 - left = "%.3f" % (((dev['start']-data.start)*100)/tTotal) 2286 - width = "%.3f" % (((dev['end']-dev['start'])*100)/tTotal) 2287 - len = " (%0.3f ms) " % ((dev['end']-dev['start'])*1000) 2288 - color = "rgba(204,204,204,0.5)" 2289 - devtl.html['timeline'] += html_device.format(dev['id'], name+len+b, left, top, "%.3f"%height, width, name) 941 + top = '%.3f' % ((dev['row']*height) + devtl.scaleH) 942 + left = '%.3f' % (((dev['start']-t0)*100)/tTotal) 943 + width = '%.3f' % (((dev['end']-dev['start'])*100)/tTotal) 944 + length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000) 945 + color = 'rgba(204,204,204,0.5)' 946 + devtl.html['timeline'] += html_device.format(dev['id'], \ 947 + d+drv+length+b, left, top, '%.3f'%height, width, name+drv) 2290 948 2291 - # timeline is finished 2292 - devtl.html['timeline'] += "</div>\n</div>\n" 949 + # draw any trace events found 950 + for data in testruns: 951 + for b in data.dmesg: 952 + phaselist = data.dmesg[b]['list'] 953 + for name in phaselist: 954 + dev = phaselist[name] 955 + if('traceevents' in dev): 956 + vprint('Debug trace events found for device %s' % name) 957 + vprint('%20s %20s %10s %8s' % ('action', \ 958 + 'name', 'time(ms)', 'length(ms)')) 959 + for e in dev['traceevents']: 960 + vprint('%20s %20s %10.3f %8.3f' % (e.action, \ 961 + e.name, e.time*1000, e.length*1000)) 962 + height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] 963 + top = '%.3f' % ((dev['row']*height) + devtl.scaleH) 964 + left = '%.3f' % (((e.time-t0)*100)/tTotal) 965 + width = '%.3f' % (e.length*100/tTotal) 966 + color = 'rgba(204,204,204,0.5)' 967 + devtl.html['timeline'] += \ 968 + html_traceevent.format(e.action+' '+e.name, \ 969 + left, top, '%.3f'%height, \ 970 + width, e.color, '') 2293 971 2294 - # draw a legend which describes the phases by color 2295 - devtl.html['legend'] = "<div class=\"legend\">\n" 2296 - pdelta = 100.0/data.phases.__len__() 2297 - pmargin = pdelta / 4.0 2298 - for phase in data.phases: 2299 - order = "%.2f" % ((data.dmesg[phase]['order'] * pdelta) + pmargin) 2300 - name = string.replace(phase, "_", " &nbsp;") 2301 - devtl.html['legend'] += html_legend.format(order, data.dmesg[phase]['color'], name) 2302 - devtl.html['legend'] += "</div>\n" 972 + # timeline is finished 973 + devtl.html['timeline'] += '</div>\n</div>\n' 974 + 975 + # draw a legend which describes the phases by color 976 + data = testruns[-1] 977 + devtl.html['legend'] = '<div class="legend">\n' 978 + pdelta = 100.0/len(data.phases) 979 + pmargin = pdelta / 4.0 980 + for phase in data.phases: 981 + order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin) 982 + name = string.replace(phase, '_', ' &nbsp;') 983 + devtl.html['legend'] += html_legend.format(order, \ 984 + data.dmesg[phase]['color'], name) 985 + devtl.html['legend'] += '</div>\n' 2303 986 2304 987 hf = open(sysvals.htmlfile, 'w') 2305 988 thread_height = 0 2306 989 2307 - # write the html header first (html head, css code, everything up to the start of body) 2308 - html_header = "<!DOCTYPE html>\n<html>\n<head>\n\ 2309 - <meta http-equiv=\"content-type\" content=\"text/html; charset=UTF-8\">\n\ 990 + # write the html header first (html head, css code, up to body start) 991 + html_header = '<!DOCTYPE html>\n<html>\n<head>\n\ 992 + <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ 2310 993 <title>AnalyzeSuspend</title>\n\ 2311 - <style type='text/css'>\n\ 994 + <style type=\'text/css\'>\n\ 2312 995 body {overflow-y: scroll;}\n\ 2313 996 .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\ 2314 997 .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\ 2315 998 .callgraph article * {padding-left: 28px;}\n\ 2316 999 h1 {color:black;font: bold 30px Times;}\n\ 1000 + t0 {color:black;font: bold 30px Times;}\n\ 1001 + t1 {color:black;font: 30px Times;}\n\ 1002 + t2 {color:black;font: 25px Times;}\n\ 1003 + t3 {color:black;font: 20px Times;white-space:nowrap;}\n\ 1004 + t4 {color:black;font: bold 30px Times;line-height:60px;white-space:nowrap;}\n\ 2317 1005 table {width:100%;}\n\ 2318 1006 .gray {background-color:rgba(80,80,80,0.1);}\n\ 2319 1007 .green {background-color:rgba(204,255,204,0.4);}\n\ ··· 2364 968 .time1 {font: 22px Arial;border:1px solid;}\n\ 2365 969 .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\ 2366 970 td {text-align: center;}\n\ 971 + r {color:#500000;font:15px Tahoma;}\n\ 972 + n {color:#505050;font:15px Tahoma;}\n\ 2367 973 .tdhl {color: red;}\n\ 2368 974 .hide {display: none;}\n\ 2369 975 .pf {display: none;}\n\ 2370 - .pf:checked + label {background: url(\'data:image/svg+xml;utf,<?xml version=\"1.0\" standalone=\"no\"?><svg xmlns=\"http://www.w3.org/2000/svg\" height=\"18\" width=\"18\" version=\"1.1\"><circle cx=\"9\" cy=\"9\" r=\"8\" stroke=\"black\" stroke-width=\"1\" fill=\"white\"/><rect x=\"4\" y=\"8\" width=\"10\" height=\"2\" style=\"fill:black;stroke-width:0\"/><rect x=\"8\" y=\"4\" width=\"2\" height=\"10\" style=\"fill:black;stroke-width:0\"/></svg>\') no-repeat left center;}\n\ 2371 - .pf:not(:checked) ~ label {background: url(\'data:image/svg+xml;utf,<?xml version=\"1.0\" standalone=\"no\"?><svg xmlns=\"http://www.w3.org/2000/svg\" height=\"18\" width=\"18\" version=\"1.1\"><circle cx=\"9\" cy=\"9\" r=\"8\" stroke=\"black\" stroke-width=\"1\" fill=\"white\"/><rect x=\"4\" y=\"8\" width=\"10\" height=\"2\" style=\"fill:black;stroke-width:0\"/></svg>\') no-repeat left center;}\n\ 976 + .pf:checked + label {background: url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/><rect x="8" y="4" width="2" height="10" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\ 977 + .pf:not(:checked) ~ label {background: url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\ 2372 978 .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\ 2373 979 .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\ 2374 980 .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\ 2375 - .thread {position: absolute; height: "+"%.3f"%thread_height+"%; overflow: hidden; line-height: 30px; border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\ 981 + .thread {position: absolute; height: '+'%.3f'%thread_height+'%; overflow: hidden; line-height: 30px; border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\ 2376 982 .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\ 983 + .hover {background-color:white;border:1px solid red;z-index:10;}\n\ 984 + .traceevent {position: absolute;opacity: 0.3;height: '+'%.3f'%thread_height+'%;width:0;overflow:hidden;line-height:30px;text-align:center;white-space:nowrap;}\n\ 2377 985 .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\ 2378 - .t {position: absolute; top: 0%; height: 100%; border-right:1px solid black;}\n\ 986 + .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\ 987 + .t {position:absolute;top:0%;height:100%;border-right:1px solid black;}\n\ 2379 988 .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\ 2380 989 .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\ 2381 990 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\ 2382 - </style>\n</head>\n<body>\n" 991 + .devlist {position:'+x2changes[1]+';width:190px;}\n\ 992 + #devicedetail {height:100px;box-shadow: 5px 5px 20px black;}\n\ 993 + </style>\n</head>\n<body>\n' 2383 994 hf.write(html_header) 2384 995 2385 996 # write the test title and general info header 2386 - if(data.stamp['time'] != ""): 2387 - hf.write(headline_stamp.format(data.stamp['host'], 2388 - data.stamp['kernel'], data.stamp['mode'], data.stamp['time'])) 997 + if(sysvals.stamp['time'] != ""): 998 + hf.write(headline_stamp.format(sysvals.stamp['host'], 999 + sysvals.stamp['kernel'], sysvals.stamp['mode'], \ 1000 + sysvals.stamp['time'])) 2389 1001 2390 - # write the dmesg data (device timeline) 2391 - if(data.usedmesg): 2392 - hf.write(devtl.html['timeline']) 2393 - hf.write(devtl.html['legend']) 2394 - hf.write('<div id="devicedetail"></div>\n') 2395 - hf.write('<div id="devicetree"></div>\n') 1002 + # write the device timeline 1003 + hf.write(devtl.html['timeline']) 1004 + hf.write(devtl.html['legend']) 1005 + hf.write('<div id="devicedetailtitle"></div>\n') 1006 + hf.write('<div id="devicedetail" style="display:none;">\n') 1007 + # draw the colored boxes for the device detail section 1008 + for data in testruns: 1009 + hf.write('<div id="devicedetail%d">\n' % data.testnumber) 1010 + for b in data.phases: 1011 + phase = data.dmesg[b] 1012 + length = phase['end']-phase['start'] 1013 + left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) 1014 + width = '%.3f' % ((length*100.0)/tTotal) 1015 + hf.write(html_phaselet.format(b, left, width, \ 1016 + data.dmesg[b]['color'])) 1017 + hf.write('</div>\n') 1018 + hf.write('</div>\n') 2396 1019 2397 1020 # write the ftrace data (callgraph) 2398 - if(data.useftrace): 1021 + data = testruns[-1] 1022 + if(sysvals.usecallgraph): 2399 1023 hf.write('<section id="callgraphs" class="callgraph">\n') 2400 1024 # write out the ftrace data converted to html 2401 1025 html_func_top = '<article id="{0}" class="atop" style="background-color:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n' ··· 2429 1013 if('ftrace' not in list[devname]): 2430 1014 continue 2431 1015 name = devname 2432 - if(devname in data.altdevname): 2433 - name = data.altdevname[devname] 1016 + if(devname in sysvals.altdevname): 1017 + name = sysvals.altdevname[devname] 2434 1018 devid = list[devname]['id'] 2435 1019 cg = list[devname]['ftrace'] 2436 - flen = "(%.3f ms)" % ((cg.end - cg.start)*1000) 2437 - hf.write(html_func_top.format(devid, data.dmesg[p]['color'], num, name+" "+p, flen)) 1020 + flen = '<r>(%.3f ms @ %.3f to %.3f)</r>' % \ 1021 + ((cg.end - cg.start)*1000, cg.start*1000, cg.end*1000) 1022 + hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \ 1023 + num, name+' '+p, flen)) 2438 1024 num += 1 2439 1025 for line in cg.list: 2440 1026 if(line.length < 0.000000001): 2441 - flen = "" 1027 + flen = '' 2442 1028 else: 2443 - flen = "(%.3f ms)" % (line.length*1000) 1029 + flen = '<n>(%.3f ms @ %.3f)</n>' % (line.length*1000, \ 1030 + line.time*1000) 2444 1031 if(line.freturn and line.fcall): 2445 1032 hf.write(html_func_leaf.format(line.name, flen)) 2446 1033 elif(line.freturn): ··· 2452 1033 hf.write(html_func_start.format(num, line.name, flen)) 2453 1034 num += 1 2454 1035 hf.write(html_func_end) 2455 - hf.write("\n\n </section>\n") 1036 + hf.write('\n\n </section>\n') 2456 1037 # write the footer and close 2457 - addScriptCode(hf) 2458 - hf.write("</body>\n</html>\n") 1038 + addScriptCode(hf, testruns) 1039 + hf.write('</body>\n</html>\n') 2459 1040 hf.close() 2460 1041 return True 2461 1042 2462 - def addScriptCode(hf): 2463 - global data 2464 - 2465 - t0 = (data.start - data.tSuspended) * 1000 2466 - tMax = (data.end - data.tSuspended) * 1000 1043 + # Function: addScriptCode 1044 + # Description: 1045 + # Adds the javascript code to the output html 1046 + # Arguments: 1047 + # hf: the open html file pointer 1048 + # testruns: array of Data objects from parseKernelLog or parseTraceLog 1049 + def addScriptCode(hf, testruns): 1050 + t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000 1051 + tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000 2467 1052 # create an array in javascript memory with the device details 2468 - detail = ' var bounds = [%f,%f];\n' % (t0, tMax) 2469 - detail += ' var d = [];\n' 2470 - dfmt = ' d["%s"] = { n:"%s", p:"%s", c:[%s] };\n'; 2471 - for p in data.dmesg: 2472 - list = data.dmesg[p]['list'] 2473 - for d in list: 2474 - parent = data.deviceParentID(d, p) 2475 - idlist = data.deviceChildrenIDs(d, p) 2476 - idstr = "" 2477 - for i in idlist: 2478 - if(idstr == ""): 2479 - idstr += '"'+i+'"' 2480 - else: 2481 - idstr += ', '+'"'+i+'"' 2482 - detail += dfmt % (list[d]['id'], d, parent, idstr) 2483 - 1053 + detail = ' var devtable = [];\n' 1054 + for data in testruns: 1055 + topo = data.deviceTopology() 1056 + detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo) 1057 + detail += ' var bounds = [%f,%f];\n' % (t0, tMax) 2484 1058 # add the code which will manipulate the data in the browser 2485 1059 script_code = \ 2486 1060 '<script type="text/javascript">\n'+detail+\ 2487 - ' var filter = [];\n'\ 2488 - ' var table = [];\n'\ 2489 - ' function deviceParent(devid) {\n'\ 2490 - ' var devlist = [];\n'\ 2491 - ' if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\ 2492 - ' if(d[devid].p in d)\n'\ 2493 - ' devlist = deviceParent(d[devid].p);\n'\ 2494 - ' else if(d[devid].p != "")\n'\ 2495 - ' devlist = [d[devid].p];\n'\ 2496 - ' devlist[devlist.length] = d[devid].n;\n'\ 2497 - ' return devlist;\n'\ 2498 - ' }\n'\ 2499 - ' function deviceChildren(devid, column, row) {\n'\ 2500 - ' if(!(devid in d)) return;\n'\ 2501 - ' if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\ 2502 - ' var cell = {name: d[devid].n, span: 1};\n'\ 2503 - ' var span = 0;\n'\ 2504 - ' if(column >= table.length) table[column] = [];\n'\ 2505 - ' table[column][row] = cell;\n'\ 2506 - ' for(var i = 0; i < d[devid].c.length; i++) {\n'\ 2507 - ' var cid = d[devid].c[i];\n'\ 2508 - ' span += deviceChildren(cid, column+1, row+span);\n'\ 2509 - ' }\n'\ 2510 - ' if(span == 0) span = 1;\n'\ 2511 - ' table[column][row].span = span;\n'\ 2512 - ' return span;\n'\ 2513 - ' }\n'\ 2514 - ' function deviceTree(devid, resume) {\n'\ 2515 - ' var html = "<table border=1>";\n'\ 2516 - ' filter = [];\n'\ 2517 - ' table = [];\n'\ 2518 - ' plist = deviceParent(devid);\n'\ 2519 - ' var devidx = plist.length - 1;\n'\ 2520 - ' for(var i = 0; i < devidx; i++)\n'\ 2521 - ' table[i] = [{name: plist[i], span: 1}];\n'\ 2522 - ' deviceChildren(devid, devidx, 0);\n'\ 2523 - ' for(var i = 0; i < devidx; i++)\n'\ 2524 - ' table[i][0].span = table[devidx][0].span;\n'\ 2525 - ' for(var row = 0; row < table[0][0].span; row++) {\n'\ 2526 - ' html += "<tr>";\n'\ 2527 - ' for(var col = 0; col < table.length; col++)\n'\ 2528 - ' if(row in table[col]) {\n'\ 2529 - ' var cell = table[col][row];\n'\ 2530 - ' var args = "";\n'\ 2531 - ' if(cell.span > 1)\n'\ 2532 - ' args += " rowspan="+cell.span;\n'\ 2533 - ' if((col == devidx) && (row == 0))\n'\ 2534 - ' args += " class=tdhl";\n'\ 2535 - ' if(resume)\n'\ 2536 - ' html += "<td"+args+">"+cell.name+" &rarr;</td>";\n'\ 2537 - ' else\n'\ 2538 - ' html += "<td"+args+">&larr; "+cell.name+"</td>";\n'\ 2539 - ' }\n'\ 2540 - ' html += "</tr>";\n'\ 2541 - ' }\n'\ 2542 - ' html += "</table>";\n'\ 2543 - ' return html;\n'\ 2544 - ' }\n'\ 2545 1061 ' function zoomTimeline() {\n'\ 2546 1062 ' var timescale = document.getElementById("timescale");\n'\ 2547 1063 ' var dmesg = document.getElementById("dmesg");\n'\ ··· 2508 1154 ' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\ 2509 1155 ' var pos = (tMax - s) * 100.0 / tTotal;\n'\ 2510 1156 ' var name = (s == 0)?"S/R":(s+"ms");\n'\ 2511 - ' html += \"<div class=\\\"t\\\" style=\\\"right:\"+pos+\"%\\\">\"+name+\"</div>\";\n'\ 1157 + ' html += "<div class=\\"t\\" style=\\"right:"+pos+"%\\">"+name+"</div>";\n'\ 2512 1158 ' }\n'\ 2513 1159 ' timescale.innerHTML = html;\n'\ 2514 1160 ' }\n'\ 1161 + ' function deviceHover() {\n'\ 1162 + ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\ 1163 + ' var dmesg = document.getElementById("dmesg");\n'\ 1164 + ' var dev = dmesg.getElementsByClassName("thread");\n'\ 1165 + ' var cpu = -1;\n'\ 1166 + ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\ 1167 + ' cpu = parseInt(name.slice(7));\n'\ 1168 + ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\ 1169 + ' cpu = parseInt(name.slice(8));\n'\ 1170 + ' for (var i = 0; i < dev.length; i++) {\n'\ 1171 + ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\ 1172 + ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ 1173 + ' (name == dname))\n'\ 1174 + ' {\n'\ 1175 + ' dev[i].className = "thread hover";\n'\ 1176 + ' } else {\n'\ 1177 + ' dev[i].className = "thread";\n'\ 1178 + ' }\n'\ 1179 + ' }\n'\ 1180 + ' }\n'\ 1181 + ' function deviceUnhover() {\n'\ 1182 + ' var dmesg = document.getElementById("dmesg");\n'\ 1183 + ' var dev = dmesg.getElementsByClassName("thread");\n'\ 1184 + ' for (var i = 0; i < dev.length; i++) {\n'\ 1185 + ' dev[i].className = "thread";\n'\ 1186 + ' }\n'\ 1187 + ' }\n'\ 1188 + ' function deviceTitle(title, total, cpu) {\n'\ 1189 + ' var prefix = "Total";\n'\ 1190 + ' if(total.length > 3) {\n'\ 1191 + ' prefix = "Average";\n'\ 1192 + ' total[1] = (total[1]+total[3])/2;\n'\ 1193 + ' total[2] = (total[2]+total[4])/2;\n'\ 1194 + ' }\n'\ 1195 + ' var devtitle = document.getElementById("devicedetailtitle");\n'\ 1196 + ' var name = title.slice(0, title.indexOf(" "));\n'\ 1197 + ' if(cpu >= 0) name = "CPU"+cpu;\n'\ 1198 + ' var driver = "";\n'\ 1199 + ' var tS = "<t2>(</t2>";\n'\ 1200 + ' var tR = "<t2>)</t2>";\n'\ 1201 + ' if(total[1] > 0)\n'\ 1202 + ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\ 1203 + ' if(total[2] > 0)\n'\ 1204 + ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\ 1205 + ' var s = title.indexOf("{");\n'\ 1206 + ' var e = title.indexOf("}");\n'\ 1207 + ' if((s >= 0) && (e >= 0))\n'\ 1208 + ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\ 1209 + ' if(total[1] > 0 && total[2] > 0)\n'\ 1210 + ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\ 1211 + ' else\n'\ 1212 + ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\ 1213 + ' return name;\n'\ 1214 + ' }\n'\ 2515 1215 ' function deviceDetail() {\n'\ 2516 - ' var devtitle = document.getElementById("devicedetail");\n'\ 2517 - ' devtitle.innerHTML = "<h1>"+this.title+"</h1>";\n'\ 2518 - ' var devtree = document.getElementById("devicetree");\n'\ 2519 - ' devtree.innerHTML = deviceTree(this.id, (this.title.indexOf("resume") >= 0));\n'\ 1216 + ' var devinfo = document.getElementById("devicedetail");\n'\ 1217 + ' devinfo.style.display = "block";\n'\ 1218 + ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\ 1219 + ' var cpu = -1;\n'\ 1220 + ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\ 1221 + ' cpu = parseInt(name.slice(7));\n'\ 1222 + ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\ 1223 + ' cpu = parseInt(name.slice(8));\n'\ 1224 + ' var dmesg = document.getElementById("dmesg");\n'\ 1225 + ' var dev = dmesg.getElementsByClassName("thread");\n'\ 1226 + ' var idlist = [];\n'\ 1227 + ' var pdata = [[]];\n'\ 1228 + ' var pd = pdata[0];\n'\ 1229 + ' var total = [0.0, 0.0, 0.0];\n'\ 1230 + ' for (var i = 0; i < dev.length; i++) {\n'\ 1231 + ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\ 1232 + ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ 1233 + ' (name == dname))\n'\ 1234 + ' {\n'\ 1235 + ' idlist[idlist.length] = dev[i].id;\n'\ 1236 + ' var tidx = 1;\n'\ 1237 + ' if(dev[i].id[0] == "a") {\n'\ 1238 + ' pd = pdata[0];\n'\ 1239 + ' } else {\n'\ 1240 + ' if(pdata.length == 1) pdata[1] = [];\n'\ 1241 + ' if(total.length == 3) total[3]=total[4]=0.0;\n'\ 1242 + ' pd = pdata[1];\n'\ 1243 + ' tidx = 3;\n'\ 1244 + ' }\n'\ 1245 + ' var info = dev[i].title.split(" ");\n'\ 1246 + ' var pname = info[info.length-1];\n'\ 1247 + ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\ 1248 + ' total[0] += pd[pname];\n'\ 1249 + ' if(pname.indexOf("suspend") >= 0)\n'\ 1250 + ' total[tidx] += pd[pname];\n'\ 1251 + ' else\n'\ 1252 + ' total[tidx+1] += pd[pname];\n'\ 1253 + ' }\n'\ 1254 + ' }\n'\ 1255 + ' var devname = deviceTitle(this.title, total, cpu);\n'\ 1256 + ' var left = 0.0;\n'\ 1257 + ' for (var t = 0; t < pdata.length; t++) {\n'\ 1258 + ' pd = pdata[t];\n'\ 1259 + ' devinfo = document.getElementById("devicedetail"+t);\n'\ 1260 + ' var phases = devinfo.getElementsByClassName("phaselet");\n'\ 1261 + ' for (var i = 0; i < phases.length; i++) {\n'\ 1262 + ' if(phases[i].id in pd) {\n'\ 1263 + ' var w = 100.0*pd[phases[i].id]/total[0];\n'\ 1264 + ' var fs = 32;\n'\ 1265 + ' if(w < 8) fs = 4*w | 0;\n'\ 1266 + ' var fs2 = fs*3/4;\n'\ 1267 + ' phases[i].style.width = w+"%";\n'\ 1268 + ' phases[i].style.left = left+"%";\n'\ 1269 + ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\ 1270 + ' left += w;\n'\ 1271 + ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\ 1272 + ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace("_", " ")+"</t3>";\n'\ 1273 + ' phases[i].innerHTML = time+pname;\n'\ 1274 + ' } else {\n'\ 1275 + ' phases[i].style.width = "0%";\n'\ 1276 + ' phases[i].style.left = left+"%";\n'\ 1277 + ' }\n'\ 1278 + ' }\n'\ 1279 + ' }\n'\ 2520 1280 ' var cglist = document.getElementById("callgraphs");\n'\ 2521 1281 ' if(!cglist) return;\n'\ 2522 1282 ' var cg = cglist.getElementsByClassName("atop");\n'\ 2523 1283 ' for (var i = 0; i < cg.length; i++) {\n'\ 2524 - ' if(filter.indexOf(cg[i].id) >= 0) {\n'\ 1284 + ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\ 2525 1285 ' cg[i].style.display = "block";\n'\ 2526 1286 ' } else {\n'\ 2527 1287 ' cg[i].style.display = "none";\n'\ 2528 1288 ' }\n'\ 2529 1289 ' }\n'\ 1290 + ' }\n'\ 1291 + ' function devListWindow(e) {\n'\ 1292 + ' var sx = e.clientX;\n'\ 1293 + ' if(sx > window.innerWidth - 440)\n'\ 1294 + ' sx = window.innerWidth - 440;\n'\ 1295 + ' var cfg="top="+e.screenY+", left="+sx+", width=440, height=720, scrollbars=yes";\n'\ 1296 + ' var win = window.open("", "_blank", cfg);\n'\ 1297 + ' if(window.chrome) win.moveBy(sx, 0);\n'\ 1298 + ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\ 1299 + ' "<style type=\\"text/css\\">"+\n'\ 1300 + ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\ 1301 + ' "</style>"\n'\ 1302 + ' var dt = devtable[0];\n'\ 1303 + ' if(e.target.id != "devlist1")\n'\ 1304 + ' dt = devtable[1];\n'\ 1305 + ' win.document.write(html+dt);\n'\ 2530 1306 ' }\n'\ 2531 1307 ' window.addEventListener("load", function () {\n'\ 2532 1308 ' var dmesg = document.getElementById("dmesg");\n'\ ··· 2664 1180 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\ 2665 1181 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\ 2666 1182 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\ 1183 + ' var devlist = document.getElementsByClassName("devlist");\n'\ 1184 + ' for (var i = 0; i < devlist.length; i++)\n'\ 1185 + ' devlist[i].onclick = devListWindow;\n'\ 2667 1186 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 2668 1187 ' for (var i = 0; i < dev.length; i++) {\n'\ 2669 1188 ' dev[i].onclick = deviceDetail;\n'\ 1189 + ' dev[i].onmouseover = deviceHover;\n'\ 1190 + ' dev[i].onmouseout = deviceUnhover;\n'\ 2670 1191 ' }\n'\ 2671 1192 ' zoomTimeline();\n'\ 2672 1193 ' });\n'\ ··· 2680 1191 2681 1192 # Function: executeSuspend 2682 1193 # Description: 2683 - # Execute system suspend through the sysfs interface 1194 + # Execute system suspend through the sysfs interface, then copy the output 1195 + # dmesg and ftrace files to the test output directory. 2684 1196 def executeSuspend(): 2685 - global sysvals, data 1197 + global sysvals 2686 1198 2687 - detectUSB() 2688 - pf = open(sysvals.powerfile, 'w') 2689 - # clear the kernel ring buffer just as we start 2690 - os.system("dmesg -C") 2691 - # start ftrace 2692 - if(data.useftrace): 2693 - print("START TRACING") 2694 - os.system("echo 1 > "+sysvals.tpath+"tracing_on") 2695 - os.system("echo SUSPEND START > "+sysvals.tpath+"trace_marker") 2696 - # initiate suspend 2697 - if(sysvals.rtcwake): 2698 - print("SUSPEND START") 2699 - os.system("rtcwake -s 10 -m "+sysvals.suspendmode) 2700 - else: 2701 - print("SUSPEND START (press a key to resume)") 1199 + detectUSB(False) 1200 + t0 = time.time()*1000 1201 + tp = sysvals.tpath 1202 + # execute however many s/r runs requested 1203 + for count in range(1,sysvals.execcount+1): 1204 + # clear the kernel ring buffer just as we start 1205 + os.system('dmesg -C') 1206 + # enable callgraph ftrace only for the second run 1207 + if(sysvals.usecallgraph and count == 2): 1208 + # set trace type 1209 + os.system('echo function_graph > '+tp+'current_tracer') 1210 + os.system('echo "" > '+tp+'set_ftrace_filter') 1211 + # set trace format options 1212 + os.system('echo funcgraph-abstime > '+tp+'trace_options') 1213 + os.system('echo funcgraph-proc > '+tp+'trace_options') 1214 + # focus only on device suspend and resume 1215 + os.system('cat '+tp+'available_filter_functions | '+\ 1216 + 'grep dpm_run_callback > '+tp+'set_graph_function') 1217 + # if this is test2 and there's a delay, start here 1218 + if(count > 1 and sysvals.x2delay > 0): 1219 + tN = time.time()*1000 1220 + while (tN - t0) < sysvals.x2delay: 1221 + tN = time.time()*1000 1222 + time.sleep(0.001) 1223 + # start ftrace 1224 + if(sysvals.usecallgraph or sysvals.usetraceevents): 1225 + print('START TRACING') 1226 + os.system('echo 1 > '+tp+'tracing_on') 1227 + # initiate suspend 1228 + if(sysvals.usecallgraph or sysvals.usetraceevents): 1229 + os.system('echo SUSPEND START > '+tp+'trace_marker') 1230 + if(sysvals.rtcwake): 1231 + print('SUSPEND START') 1232 + print('will autoresume in %d seconds' % sysvals.rtcwaketime) 1233 + sysvals.rtcWakeAlarm() 1234 + else: 1235 + print('SUSPEND START (press a key to resume)') 1236 + pf = open(sysvals.powerfile, 'w') 2702 1237 pf.write(sysvals.suspendmode) 2703 - # execution will pause here 2704 - pf.close() 2705 - # return from suspend 2706 - print("RESUME COMPLETE") 2707 - # stop ftrace 2708 - if(data.useftrace): 2709 - os.system("echo RESUME COMPLETE > "+sysvals.tpath+"trace_marker") 2710 - os.system("echo 0 > "+sysvals.tpath+"tracing_on") 2711 - print("CAPTURING FTRACE") 2712 - os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.ftracefile) 2713 - os.system("cat "+sysvals.tpath+"trace >> "+sysvals.ftracefile) 2714 - # grab a copy of the dmesg output 2715 - print("CAPTURING DMESG") 2716 - os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.dmesgfile) 2717 - os.system("dmesg -c >> "+sysvals.dmesgfile) 1238 + # execution will pause here 1239 + pf.close() 1240 + t0 = time.time()*1000 1241 + # return from suspend 1242 + print('RESUME COMPLETE') 1243 + if(sysvals.usecallgraph or sysvals.usetraceevents): 1244 + os.system('echo RESUME COMPLETE > '+tp+'trace_marker') 1245 + # see if there's firmware timing data to be had 1246 + t = sysvals.postresumetime 1247 + if(t > 0): 1248 + print('Waiting %d seconds for POST-RESUME trace events...' % t) 1249 + time.sleep(t) 1250 + # stop ftrace 1251 + if(sysvals.usecallgraph or sysvals.usetraceevents): 1252 + os.system('echo 0 > '+tp+'tracing_on') 1253 + print('CAPTURING TRACE') 1254 + writeDatafileHeader(sysvals.ftracefile) 1255 + os.system('cat '+tp+'trace >> '+sysvals.ftracefile) 1256 + os.system('echo "" > '+tp+'trace') 1257 + # grab a copy of the dmesg output 1258 + print('CAPTURING DMESG') 1259 + writeDatafileHeader(sysvals.dmesgfile) 1260 + os.system('dmesg -c >> '+sysvals.dmesgfile) 1261 + 1262 + def writeDatafileHeader(filename): 1263 + global sysvals 1264 + 1265 + fw = getFPDT(False) 1266 + prt = sysvals.postresumetime 1267 + fp = open(filename, 'a') 1268 + fp.write(sysvals.teststamp+'\n') 1269 + if(fw): 1270 + fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) 1271 + if(prt > 0): 1272 + fp.write('# post resume time %u\n' % prt) 1273 + fp.close() 1274 + 1275 + # Function: executeAndroidSuspend 1276 + # Description: 1277 + # Execute system suspend through the sysfs interface 1278 + # on a remote android device, then transfer the output 1279 + # dmesg and ftrace files to the local output directory. 1280 + def executeAndroidSuspend(): 1281 + global sysvals 1282 + 1283 + # check to see if the display is currently off 1284 + tp = sysvals.tpath 1285 + out = os.popen(sysvals.adb+\ 1286 + ' shell dumpsys power | grep mScreenOn').read().strip() 1287 + # if so we need to turn it on so we can issue a new suspend 1288 + if(out.endswith('false')): 1289 + print('Waking the device up for the test...') 1290 + # send the KEYPAD_POWER keyevent to wake it up 1291 + os.system(sysvals.adb+' shell input keyevent 26') 1292 + # wait a few seconds so the user can see the device wake up 1293 + time.sleep(3) 1294 + # execute however many s/r runs requested 1295 + for count in range(1,sysvals.execcount+1): 1296 + # clear the kernel ring buffer just as we start 1297 + os.system(sysvals.adb+' shell dmesg -c > /dev/null 2>&1') 1298 + # start ftrace 1299 + if(sysvals.usetraceevents): 1300 + print('START TRACING') 1301 + os.system(sysvals.adb+" shell 'echo 1 > "+tp+"tracing_on'") 1302 + # initiate suspend 1303 + for count in range(1,sysvals.execcount+1): 1304 + if(sysvals.usetraceevents): 1305 + os.system(sysvals.adb+\ 1306 + " shell 'echo SUSPEND START > "+tp+"trace_marker'") 1307 + print('SUSPEND START (press a key on the device to resume)') 1308 + os.system(sysvals.adb+" shell 'echo "+sysvals.suspendmode+\ 1309 + " > "+sysvals.powerfile+"'") 1310 + # execution will pause here, then adb will exit 1311 + while(True): 1312 + check = os.popen(sysvals.adb+\ 1313 + ' shell pwd 2>/dev/null').read().strip() 1314 + if(len(check) > 0): 1315 + break 1316 + time.sleep(1) 1317 + if(sysvals.usetraceevents): 1318 + os.system(sysvals.adb+" shell 'echo RESUME COMPLETE > "+tp+\ 1319 + "trace_marker'") 1320 + # return from suspend 1321 + print('RESUME COMPLETE') 1322 + # stop ftrace 1323 + if(sysvals.usetraceevents): 1324 + os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'") 1325 + print('CAPTURING TRACE') 1326 + os.system('echo "'+sysvals.teststamp+'" > '+sysvals.ftracefile) 1327 + os.system(sysvals.adb+' shell cat '+tp+\ 1328 + 'trace >> '+sysvals.ftracefile) 1329 + # grab a copy of the dmesg output 1330 + print('CAPTURING DMESG') 1331 + os.system('echo "'+sysvals.teststamp+'" > '+sysvals.dmesgfile) 1332 + os.system(sysvals.adb+' shell dmesg >> '+sysvals.dmesgfile) 1333 + 1334 + # Function: setUSBDevicesAuto 1335 + # Description: 1336 + # Set the autosuspend control parameter of all USB devices to auto 1337 + # This can be dangerous, so use at your own risk, most devices are set 1338 + # to always-on since the kernel cant determine if the device can 1339 + # properly autosuspend 1340 + def setUSBDevicesAuto(): 1341 + global sysvals 1342 + 1343 + rootCheck() 1344 + for dirname, dirnames, filenames in os.walk('/sys/devices'): 1345 + if(re.match('.*/usb[0-9]*.*', dirname) and 1346 + 'idVendor' in filenames and 'idProduct' in filenames): 1347 + os.system('echo auto > %s/power/control' % dirname) 1348 + name = dirname.split('/')[-1] 1349 + desc = os.popen('cat %s/product 2>/dev/null' % \ 1350 + dirname).read().replace('\n', '') 1351 + ctrl = os.popen('cat %s/power/control 2>/dev/null' % \ 1352 + dirname).read().replace('\n', '') 1353 + print('control is %s for %6s: %s' % (ctrl, name, desc)) 1354 + 1355 + # Function: yesno 1356 + # Description: 1357 + # Print out an equivalent Y or N for a set of known parameter values 1358 + # Output: 1359 + # 'Y', 'N', or ' ' if the value is unknown 1360 + def yesno(val): 1361 + yesvals = ['auto', 'enabled', 'active', '1'] 1362 + novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported'] 1363 + if val in yesvals: 1364 + return 'Y' 1365 + elif val in novals: 1366 + return 'N' 1367 + return ' ' 1368 + 1369 + # Function: ms2nice 1370 + # Description: 1371 + # Print out a very concise time string in minutes and seconds 1372 + # Output: 1373 + # The time string, e.g. "1901m16s" 1374 + def ms2nice(val): 1375 + ms = 0 1376 + try: 1377 + ms = int(val) 1378 + except: 1379 + return 0.0 1380 + m = ms / 60000 1381 + s = (ms / 1000) - (m * 60) 1382 + return '%3dm%2ds' % (m, s) 2718 1383 2719 1384 # Function: detectUSB 2720 1385 # Description: 2721 - # Detect all the USB hosts and devices currently connected 2722 - def detectUSB(): 2723 - global sysvals, data 1386 + # Detect all the USB hosts and devices currently connected and add 1387 + # a list of USB device names to sysvals for better timeline readability 1388 + # Arguments: 1389 + # output: True to output the info to stdout, False otherwise 1390 + def detectUSB(output): 1391 + global sysvals 2724 1392 2725 - for dirname, dirnames, filenames in os.walk("/sys/devices"): 2726 - if(re.match(r".*/usb[0-9]*.*", dirname) and 2727 - "idVendor" in filenames and "idProduct" in filenames): 2728 - vid = os.popen("cat %s/idVendor 2>/dev/null" % dirname).read().replace('\n', '') 2729 - pid = os.popen("cat %s/idProduct 2>/dev/null" % dirname).read().replace('\n', '') 2730 - product = os.popen("cat %s/product 2>/dev/null" % dirname).read().replace('\n', '') 1393 + field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''} 1394 + power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'', 1395 + 'control':'', 'persist':'', 'runtime_enabled':'', 1396 + 'runtime_status':'', 'runtime_usage':'', 1397 + 'runtime_active_time':'', 1398 + 'runtime_suspended_time':'', 1399 + 'active_duration':'', 1400 + 'connected_duration':''} 1401 + if(output): 1402 + print('LEGEND') 1403 + print('---------------------------------------------------------------------------------------------') 1404 + print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)') 1405 + print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)') 1406 + print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)') 1407 + print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)') 1408 + print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)') 1409 + print(' U = runtime usage count') 1410 + print('---------------------------------------------------------------------------------------------') 1411 + print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT') 1412 + print('---------------------------------------------------------------------------------------------') 1413 + 1414 + for dirname, dirnames, filenames in os.walk('/sys/devices'): 1415 + if(re.match('.*/usb[0-9]*.*', dirname) and 1416 + 'idVendor' in filenames and 'idProduct' in filenames): 1417 + for i in field: 1418 + field[i] = os.popen('cat %s/%s 2>/dev/null' % \ 1419 + (dirname, i)).read().replace('\n', '') 2731 1420 name = dirname.split('/')[-1] 2732 - if(len(product) > 0): 2733 - data.altdevname[name] = "%s [%s]" % (product, name) 1421 + if(len(field['product']) > 0): 1422 + sysvals.altdevname[name] = \ 1423 + '%s [%s]' % (field['product'], name) 2734 1424 else: 2735 - data.altdevname[name] = "%s:%s [%s]" % (vid, pid, name) 1425 + sysvals.altdevname[name] = \ 1426 + '%s:%s [%s]' % (field['idVendor'], \ 1427 + field['idProduct'], name) 1428 + if(output): 1429 + for i in power: 1430 + power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \ 1431 + (dirname, i)).read().replace('\n', '') 1432 + if(re.match('usb[0-9]*', name)): 1433 + first = '%-8s' % name 1434 + else: 1435 + first = '%8s' % name 1436 + print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \ 1437 + (first, field['idVendor'], field['idProduct'], \ 1438 + field['product'][0:20], field['speed'], \ 1439 + yesno(power['async']), \ 1440 + yesno(power['control']), \ 1441 + yesno(power['persist']), \ 1442 + yesno(power['runtime_enabled']), \ 1443 + yesno(power['runtime_status']), \ 1444 + power['runtime_usage'], \ 1445 + power['autosuspend'], \ 1446 + ms2nice(power['runtime_active_time']), \ 1447 + ms2nice(power['runtime_suspended_time']), \ 1448 + ms2nice(power['active_duration']), \ 1449 + ms2nice(power['connected_duration']))) 2736 1450 1451 + # Function: getModes 1452 + # Description: 1453 + # Determine the supported power modes on this system 1454 + # Output: 1455 + # A string list of the available modes 2737 1456 def getModes(): 2738 1457 global sysvals 2739 - modes = "" 2740 - if(os.path.exists(sysvals.powerfile)): 2741 - fp = open(sysvals.powerfile, 'r') 2742 - modes = string.split(fp.read()) 2743 - fp.close() 1458 + modes = '' 1459 + if(not sysvals.android): 1460 + if(os.path.exists(sysvals.powerfile)): 1461 + fp = open(sysvals.powerfile, 'r') 1462 + modes = string.split(fp.read()) 1463 + fp.close() 1464 + else: 1465 + line = os.popen(sysvals.adb+' shell cat '+\ 1466 + sysvals.powerfile).read().strip() 1467 + modes = string.split(line) 2744 1468 return modes 1469 + 1470 + # Function: getFPDT 1471 + # Description: 1472 + # Read the acpi bios tables and pull out FPDT, the firmware data 1473 + # Arguments: 1474 + # output: True to output the info to stdout, False otherwise 1475 + def getFPDT(output): 1476 + global sysvals 1477 + 1478 + rectype = {} 1479 + rectype[0] = 'Firmware Basic Boot Performance Record' 1480 + rectype[1] = 'S3 Performance Table Record' 1481 + prectype = {} 1482 + prectype[0] = 'Basic S3 Resume Performance Record' 1483 + prectype[1] = 'Basic S3 Suspend Performance Record' 1484 + 1485 + rootCheck() 1486 + if(not os.path.exists(sysvals.fpdtpath)): 1487 + if(output): 1488 + doError('file doesnt exist: %s' % sysvals.fpdtpath, False) 1489 + return False 1490 + if(not os.access(sysvals.fpdtpath, os.R_OK)): 1491 + if(output): 1492 + doError('file isnt readable: %s' % sysvals.fpdtpath, False) 1493 + return False 1494 + if(not os.path.exists(sysvals.mempath)): 1495 + if(output): 1496 + doError('file doesnt exist: %s' % sysvals.mempath, False) 1497 + return False 1498 + if(not os.access(sysvals.mempath, os.R_OK)): 1499 + if(output): 1500 + doError('file isnt readable: %s' % sysvals.mempath, False) 1501 + return False 1502 + 1503 + fp = open(sysvals.fpdtpath, 'rb') 1504 + buf = fp.read() 1505 + fp.close() 1506 + 1507 + if(len(buf) < 36): 1508 + if(output): 1509 + doError('Invalid FPDT table data, should '+\ 1510 + 'be at least 36 bytes', False) 1511 + return False 1512 + 1513 + table = struct.unpack('4sIBB6s8sI4sI', buf[0:36]) 1514 + if(output): 1515 + print('') 1516 + print('Firmware Performance Data Table (%s)' % table[0]) 1517 + print(' Signature : %s' % table[0]) 1518 + print(' Table Length : %u' % table[1]) 1519 + print(' Revision : %u' % table[2]) 1520 + print(' Checksum : 0x%x' % table[3]) 1521 + print(' OEM ID : %s' % table[4]) 1522 + print(' OEM Table ID : %s' % table[5]) 1523 + print(' OEM Revision : %u' % table[6]) 1524 + print(' Creator ID : %s' % table[7]) 1525 + print(' Creator Revision : 0x%x' % table[8]) 1526 + print('') 1527 + 1528 + if(table[0] != 'FPDT'): 1529 + if(output): 1530 + doError('Invalid FPDT table') 1531 + return False 1532 + if(len(buf) <= 36): 1533 + return False 1534 + i = 0 1535 + fwData = [0, 0] 1536 + records = buf[36:] 1537 + fp = open(sysvals.mempath, 'rb') 1538 + while(i < len(records)): 1539 + header = struct.unpack('HBB', records[i:i+4]) 1540 + if(header[0] not in rectype): 1541 + continue 1542 + if(header[1] != 16): 1543 + continue 1544 + addr = struct.unpack('Q', records[i+8:i+16])[0] 1545 + try: 1546 + fp.seek(addr) 1547 + first = fp.read(8) 1548 + except: 1549 + doError('Bad address 0x%x in %s' % (addr, sysvals.mempath), False) 1550 + rechead = struct.unpack('4sI', first) 1551 + recdata = fp.read(rechead[1]-8) 1552 + if(rechead[0] == 'FBPT'): 1553 + record = struct.unpack('HBBIQQQQQ', recdata) 1554 + if(output): 1555 + print('%s (%s)' % (rectype[header[0]], rechead[0])) 1556 + print(' Reset END : %u ns' % record[4]) 1557 + print(' OS Loader LoadImage Start : %u ns' % record[5]) 1558 + print(' OS Loader StartImage Start : %u ns' % record[6]) 1559 + print(' ExitBootServices Entry : %u ns' % record[7]) 1560 + print(' ExitBootServices Exit : %u ns' % record[8]) 1561 + elif(rechead[0] == 'S3PT'): 1562 + if(output): 1563 + print('%s (%s)' % (rectype[header[0]], rechead[0])) 1564 + j = 0 1565 + while(j < len(recdata)): 1566 + prechead = struct.unpack('HBB', recdata[j:j+4]) 1567 + if(prechead[0] not in prectype): 1568 + continue 1569 + if(prechead[0] == 0): 1570 + record = struct.unpack('IIQQ', recdata[j:j+prechead[1]]) 1571 + fwData[1] = record[2] 1572 + if(output): 1573 + print(' %s' % prectype[prechead[0]]) 1574 + print(' Resume Count : %u' % \ 1575 + record[1]) 1576 + print(' FullResume : %u ns' % \ 1577 + record[2]) 1578 + print(' AverageResume : %u ns' % \ 1579 + record[3]) 1580 + elif(prechead[0] == 1): 1581 + record = struct.unpack('QQ', recdata[j+4:j+prechead[1]]) 1582 + fwData[0] = record[1] - record[0] 1583 + if(output): 1584 + print(' %s' % prectype[prechead[0]]) 1585 + print(' SuspendStart : %u ns' % \ 1586 + record[0]) 1587 + print(' SuspendEnd : %u ns' % \ 1588 + record[1]) 1589 + print(' SuspendTime : %u ns' % \ 1590 + fwData[0]) 1591 + j += prechead[1] 1592 + if(output): 1593 + print('') 1594 + i += header[1] 1595 + fp.close() 1596 + return fwData 2745 1597 2746 1598 # Function: statusCheck 2747 1599 # Description: 2748 - # Verify that the requested command and options will work 2749 - def statusCheck(dryrun): 2750 - global sysvals, data 2751 - res = dict() 1600 + # Verify that the requested command and options will work, and 1601 + # print the results to the terminal 1602 + # Output: 1603 + # True if the test will work, False if not 1604 + def statusCheck(): 1605 + global sysvals 1606 + status = True 2752 1607 2753 - if(data.notestrun): 2754 - print("SUCCESS: The command should run!") 2755 - return 1608 + if(sysvals.android): 1609 + print('Checking the android system ...') 1610 + else: 1611 + print('Checking this system (%s)...' % platform.node()) 1612 + 1613 + # check if adb is connected to a device 1614 + if(sysvals.android): 1615 + res = 'NO' 1616 + out = os.popen(sysvals.adb+' get-state').read().strip() 1617 + if(out == 'device'): 1618 + res = 'YES' 1619 + print(' is android device connected: %s' % res) 1620 + if(res != 'YES'): 1621 + print(' Please connect the device before using this tool') 1622 + return False 2756 1623 2757 1624 # check we have root access 2758 - check = "YES" 2759 - if(os.environ['USER'] != "root"): 2760 - if(not dryrun): 2761 - doError("root access is required", False) 2762 - check = "NO" 2763 - res[" have root access: "] = check 1625 + res = 'NO (No features of this tool will work!)' 1626 + if(sysvals.android): 1627 + out = os.popen(sysvals.adb+' shell id').read().strip() 1628 + if('root' in out): 1629 + res = 'YES' 1630 + else: 1631 + if(os.environ['USER'] == 'root'): 1632 + res = 'YES' 1633 + print(' have root access: %s' % res) 1634 + if(res != 'YES'): 1635 + if(sysvals.android): 1636 + print(' Try running "adb root" to restart the daemon as root') 1637 + else: 1638 + print(' Try running this script with sudo') 1639 + return False 2764 1640 2765 1641 # check sysfs is mounted 2766 - check = "YES" 2767 - if(not os.path.exists(sysvals.powerfile)): 2768 - if(not dryrun): 2769 - doError("sysfs must be mounted", False) 2770 - check = "NO" 2771 - res[" is sysfs mounted: "] = check 1642 + res = 'NO (No features of this tool will work!)' 1643 + if(sysvals.android): 1644 + out = os.popen(sysvals.adb+' shell ls '+\ 1645 + sysvals.powerfile).read().strip() 1646 + if(out == sysvals.powerfile): 1647 + res = 'YES' 1648 + else: 1649 + if(os.path.exists(sysvals.powerfile)): 1650 + res = 'YES' 1651 + print(' is sysfs mounted: %s' % res) 1652 + if(res != 'YES'): 1653 + return False 2772 1654 2773 1655 # check target mode is a valid mode 2774 - check = "YES" 1656 + res = 'NO' 2775 1657 modes = getModes() 2776 - if(sysvals.suspendmode not in modes): 2777 - if(not dryrun): 2778 - doError("%s is not a value power mode" % sysvals.suspendmode, False) 2779 - check = "NO" 2780 - res[" is "+sysvals.suspendmode+" a power mode: "] = check 1658 + if(sysvals.suspendmode in modes): 1659 + res = 'YES' 1660 + else: 1661 + status = False 1662 + print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) 1663 + if(res == 'NO'): 1664 + print(' valid power modes are: %s' % modes) 1665 + print(' please choose one with -m') 1666 + 1667 + # check if the tool can unlock the device 1668 + if(sysvals.android): 1669 + res = 'YES' 1670 + out1 = os.popen(sysvals.adb+\ 1671 + ' shell dumpsys power | grep mScreenOn').read().strip() 1672 + out2 = os.popen(sysvals.adb+\ 1673 + ' shell input').read().strip() 1674 + if(not out1.startswith('mScreenOn') or not out2.startswith('usage')): 1675 + res = 'NO (wake the android device up before running the test)' 1676 + print(' can I unlock the screen: %s' % res) 2781 1677 2782 1678 # check if ftrace is available 2783 - if(data.useftrace): 2784 - check = "YES" 2785 - if(not verifyFtrace()): 2786 - if(not dryrun): 2787 - doError("ftrace is not configured", False) 2788 - check = "NO" 2789 - res[" is ftrace usable: "] = check 1679 + res = 'NO' 1680 + ftgood = verifyFtrace() 1681 + if(ftgood): 1682 + res = 'YES' 1683 + elif(sysvals.usecallgraph): 1684 + status = False 1685 + print(' is ftrace supported: %s' % res) 1686 + 1687 + # what data source are we using 1688 + res = 'DMESG' 1689 + if(ftgood): 1690 + sysvals.usetraceeventsonly = True 1691 + sysvals.usetraceevents = False 1692 + for e in sysvals.traceevents: 1693 + check = False 1694 + if(sysvals.android): 1695 + out = os.popen(sysvals.adb+' shell ls -d '+\ 1696 + sysvals.epath+e).read().strip() 1697 + if(out == sysvals.epath+e): 1698 + check = True 1699 + else: 1700 + if(os.path.exists(sysvals.epath+e)): 1701 + check = True 1702 + if(not check): 1703 + sysvals.usetraceeventsonly = False 1704 + if(e == 'suspend_resume' and check): 1705 + sysvals.usetraceevents = True 1706 + if(sysvals.usetraceevents and sysvals.usetraceeventsonly): 1707 + res = 'FTRACE (all trace events found)' 1708 + elif(sysvals.usetraceevents): 1709 + res = 'DMESG and FTRACE (suspend_resume trace event found)' 1710 + print(' timeline data source: %s' % res) 2790 1711 2791 1712 # check if rtcwake 2792 - if(sysvals.rtcwake): 2793 - check = "YES" 2794 - version = os.popen("rtcwake -V 2>/dev/null").read() 2795 - if(not version.startswith("rtcwake")): 2796 - if(not dryrun): 2797 - doError("rtcwake is not installed", False) 2798 - check = "NO" 2799 - res[" is rtcwake usable: "] = check 1713 + res = 'NO' 1714 + if(sysvals.rtcpath != ''): 1715 + res = 'YES' 1716 + elif(sysvals.rtcwake): 1717 + status = False 1718 + print(' is rtcwake supported: %s' % res) 2800 1719 2801 - if(dryrun): 2802 - status = True 2803 - print("Checking if system can run the current command:") 2804 - for r in res: 2805 - print("%s\t%s" % (r, res[r])) 2806 - if(res[r] != "YES"): 2807 - status = False 2808 - if(status): 2809 - print("SUCCESS: The command should run!") 1720 + return status 1721 + 1722 + # Function: doError 1723 + # Description: 1724 + # generic error function for catastrphic failures 1725 + # Arguments: 1726 + # msg: the error message to print 1727 + # help: True if printHelp should be called after, False otherwise 1728 + def doError(msg, help): 1729 + if(help == True): 1730 + printHelp() 1731 + print('ERROR: %s\n') % msg 1732 + sys.exit() 1733 + 1734 + # Function: doWarning 1735 + # Description: 1736 + # generic warning function for non-catastrophic anomalies 1737 + # Arguments: 1738 + # msg: the warning message to print 1739 + # file: If not empty, a filename to request be sent to the owner for debug 1740 + def doWarning(msg, file): 1741 + print('/* %s */') % msg 1742 + if(file): 1743 + print('/* For a fix, please send this'+\ 1744 + ' %s file to <todd.e.brandt@intel.com> */' % file) 1745 + 1746 + # Function: rootCheck 1747 + # Description: 1748 + # quick check to see if we have root access 1749 + def rootCheck(): 1750 + if(os.environ['USER'] != 'root'): 1751 + doError('This script must be run as root', False) 1752 + 1753 + # Function: getArgInt 1754 + # Description: 1755 + # pull out an integer argument from the command line with checks 1756 + def getArgInt(name, args, min, max): 1757 + try: 1758 + arg = args.next() 1759 + except: 1760 + doError(name+': no argument supplied', True) 1761 + try: 1762 + val = int(arg) 1763 + except: 1764 + doError(name+': non-integer value given', True) 1765 + if(val < min or val > max): 1766 + doError(name+': value should be between %d and %d' % (min, max), True) 1767 + return val 1768 + 1769 + # Function: rerunTest 1770 + # Description: 1771 + # generate an output from an existing set of ftrace/dmesg logs 1772 + def rerunTest(): 1773 + global sysvals 1774 + 1775 + if(sysvals.ftracefile != ''): 1776 + doesTraceLogHaveTraceEvents() 1777 + if(sysvals.dmesgfile == '' and not sysvals.usetraceeventsonly): 1778 + doError('recreating this html output '+\ 1779 + 'requires a dmesg file', False) 1780 + sysvals.setOutputFile() 1781 + vprint('Output file: %s' % sysvals.htmlfile) 1782 + print('PROCESSING DATA') 1783 + if(sysvals.usetraceeventsonly): 1784 + testruns = parseTraceLog() 1785 + else: 1786 + testruns = loadKernelLog() 1787 + for data in testruns: 1788 + parseKernelLog(data) 1789 + if(sysvals.ftracefile != ''): 1790 + appendIncompleteTraceLog(testruns) 1791 + createHTML(testruns) 1792 + 1793 + # Function: runTest 1794 + # Description: 1795 + # execute a suspend/resume, gather the logs, and generate the output 1796 + def runTest(subdir): 1797 + global sysvals 1798 + 1799 + # prepare for the test 1800 + if(not sysvals.android): 1801 + initFtrace() 1802 + else: 1803 + initFtraceAndroid() 1804 + sysvals.initTestOutput(subdir) 1805 + 1806 + vprint('Output files:\n %s' % sysvals.dmesgfile) 1807 + if(sysvals.usecallgraph or 1808 + sysvals.usetraceevents or 1809 + sysvals.usetraceeventsonly): 1810 + vprint(' %s' % sysvals.ftracefile) 1811 + vprint(' %s' % sysvals.htmlfile) 1812 + 1813 + # execute the test 1814 + if(not sysvals.android): 1815 + executeSuspend() 1816 + else: 1817 + executeAndroidSuspend() 1818 + 1819 + # analyze the data and create the html output 1820 + print('PROCESSING DATA') 1821 + if(sysvals.usetraceeventsonly): 1822 + # data for kernels 3.15 or newer is entirely in ftrace 1823 + testruns = parseTraceLog() 1824 + else: 1825 + # data for kernels older than 3.15 is primarily in dmesg 1826 + testruns = loadKernelLog() 1827 + for data in testruns: 1828 + parseKernelLog(data) 1829 + if(sysvals.usecallgraph or sysvals.usetraceevents): 1830 + appendIncompleteTraceLog(testruns) 1831 + createHTML(testruns) 1832 + 1833 + # Function: runSummary 1834 + # Description: 1835 + # create a summary of tests in a sub-directory 1836 + def runSummary(subdir, output): 1837 + global sysvals 1838 + 1839 + # get a list of ftrace output files 1840 + files = [] 1841 + for dirname, dirnames, filenames in os.walk(subdir): 1842 + for filename in filenames: 1843 + if(re.match('.*_ftrace.txt', filename)): 1844 + files.append("%s/%s" % (dirname, filename)) 1845 + 1846 + # process the files in order and get an array of data objects 1847 + testruns = [] 1848 + for file in sorted(files): 1849 + if output: 1850 + print("Test found in %s" % os.path.dirname(file)) 1851 + sysvals.ftracefile = file 1852 + sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt') 1853 + doesTraceLogHaveTraceEvents() 1854 + sysvals.usecallgraph = False 1855 + if not sysvals.usetraceeventsonly: 1856 + if(not os.path.exists(sysvals.dmesgfile)): 1857 + print("Skipping %s: not a valid test input" % file) 1858 + continue 1859 + else: 1860 + if output: 1861 + f = os.path.basename(sysvals.ftracefile) 1862 + d = os.path.basename(sysvals.dmesgfile) 1863 + print("\tInput files: %s and %s" % (f, d)) 1864 + testdata = loadKernelLog() 1865 + data = testdata[0] 1866 + parseKernelLog(data) 1867 + testdata = [data] 1868 + appendIncompleteTraceLog(testdata) 2810 1869 else: 2811 - print("FAILURE: The command won't run!") 1870 + if output: 1871 + print("\tInput file: %s" % os.path.basename(sysvals.ftracefile)) 1872 + testdata = parseTraceLog() 1873 + data = testdata[0] 1874 + data.normalizeTime(data.tSuspended) 1875 + link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html') 1876 + data.outfile = link 1877 + testruns.append(data) 2812 1878 1879 + createHTMLSummarySimple(testruns, subdir+'/summary.html') 1880 + 1881 + # Function: printHelp 1882 + # Description: 1883 + # print out the help text 2813 1884 def printHelp(): 2814 1885 global sysvals 2815 1886 modes = getModes() 2816 1887 2817 - print("") 2818 - print("AnalyzeSuspend") 2819 - print("Usage: sudo analyze_suspend.py <options>") 2820 - print("") 2821 - print("Description:") 2822 - print(" Initiates a system suspend/resume while capturing dmesg") 2823 - print(" and (optionally) ftrace data to analyze device timing") 2824 - print("") 2825 - print(" Generates output files in subdirectory: suspend-mmddyy-HHMMSS") 2826 - print(" HTML output: <hostname>_<mode>.html") 2827 - print(" raw dmesg output: <hostname>_<mode>_dmesg.txt") 2828 - print(" raw ftrace output (with -f): <hostname>_<mode>_ftrace.txt") 2829 - print("") 2830 - print("Options:") 2831 - print(" [general]") 2832 - print(" -h Print this help text") 2833 - print(" -verbose Print extra information during execution and analysis") 2834 - print(" -status Test to see if the system is enabled to run this tool") 2835 - print(" -modes List available suspend modes") 2836 - print(" -m mode Mode to initiate for suspend %s (default: %s)") % (modes, sysvals.suspendmode) 2837 - print(" -rtcwake Use rtcwake to autoresume after 10 seconds (default: disabled)") 2838 - print(" -f Use ftrace to create device callgraphs (default: disabled)") 2839 - print(" [re-analyze data from previous runs]") 2840 - print(" -dmesg dmesgfile Create HTML timeline from dmesg file") 2841 - print(" -ftrace ftracefile Create HTML callgraph from ftrace file") 2842 - print("") 1888 + print('') 1889 + print('AnalyzeSuspend v%.1f' % sysvals.version) 1890 + print('Usage: sudo analyze_suspend.py <options>') 1891 + print('') 1892 + print('Description:') 1893 + print(' This tool is designed to assist kernel and OS developers in optimizing') 1894 + print(' their linux stack\'s suspend/resume time. Using a kernel image built') 1895 + print(' with a few extra options enabled, the tool will execute a suspend and') 1896 + print(' capture dmesg and ftrace data until resume is complete. This data is') 1897 + print(' transformed into a device timeline and an optional callgraph to give') 1898 + print(' a detailed view of which devices/subsystems are taking the most') 1899 + print(' time in suspend/resume.') 1900 + print('') 1901 + print(' Generates output files in subdirectory: suspend-mmddyy-HHMMSS') 1902 + print(' HTML output: <hostname>_<mode>.html') 1903 + print(' raw dmesg output: <hostname>_<mode>_dmesg.txt') 1904 + print(' raw ftrace output: <hostname>_<mode>_ftrace.txt') 1905 + print('') 1906 + print('Options:') 1907 + print(' [general]') 1908 + print(' -h Print this help text') 1909 + print(' -v Print the current tool version') 1910 + print(' -verbose Print extra information during execution and analysis') 1911 + print(' -status Test to see if the system is enabled to run this tool') 1912 + print(' -modes List available suspend modes') 1913 + print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode) 1914 + print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)') 1915 + print(' [advanced]') 1916 + print(' -f Use ftrace to create device callgraphs (default: disabled)') 1917 + print(' -filter "d1 d2 ..." Filter out all but this list of dev names') 1918 + print(' -x2 Run two suspend/resumes back to back (default: disabled)') 1919 + print(' -x2delay t Minimum millisecond delay <t> between the two test runs (default: 0 ms)') 1920 + print(' -postres t Time after resume completion to wait for post-resume events (default: 0 S)') 1921 + print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will') 1922 + print(' be created in a new subdirectory with a summary page.') 1923 + print(' [utilities]') 1924 + print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') 1925 + print(' -usbtopo Print out the current USB topology with power info') 1926 + print(' -usbauto Enable autosuspend for all connected USB devices') 1927 + print(' [android testing]') 1928 + print(' -adb binary Use the given adb binary to run the test on an android device.') 1929 + print(' The device should already be connected and with root access.') 1930 + print(' Commands will be executed on the device using "adb shell"') 1931 + print(' [re-analyze data from previous runs]') 1932 + print(' -ftrace ftracefile Create HTML output using ftrace input') 1933 + print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)') 1934 + print(' -summary directory Create a summary of all test in this dir') 1935 + print('') 2843 1936 return True 2844 1937 2845 - def doError(msg, help): 2846 - print("ERROR: %s") % msg 2847 - if(help == True): 2848 - printHelp() 2849 - sys.exit() 1938 + # ----------------- MAIN -------------------- 1939 + # exec start (skipped if script is loaded as library) 1940 + if __name__ == '__main__': 1941 + cmd = '' 1942 + cmdarg = '' 1943 + multitest = {'run': False, 'count': 0, 'delay': 0} 1944 + # loop through the command line arguments 1945 + args = iter(sys.argv[1:]) 1946 + for arg in args: 1947 + if(arg == '-m'): 1948 + try: 1949 + val = args.next() 1950 + except: 1951 + doError('No mode supplied', True) 1952 + sysvals.suspendmode = val 1953 + elif(arg == '-adb'): 1954 + try: 1955 + val = args.next() 1956 + except: 1957 + doError('No adb binary supplied', True) 1958 + if(not os.path.exists(val)): 1959 + doError('file doesnt exist: %s' % val, False) 1960 + if(not os.access(val, os.X_OK)): 1961 + doError('file isnt executable: %s' % val, False) 1962 + try: 1963 + check = os.popen(val+' version').read().strip() 1964 + except: 1965 + doError('adb version failed to execute', False) 1966 + if(not re.match('Android Debug Bridge .*', check)): 1967 + doError('adb version failed to execute', False) 1968 + sysvals.adb = val 1969 + sysvals.android = True 1970 + elif(arg == '-x2'): 1971 + if(sysvals.postresumetime > 0): 1972 + doError('-x2 is not compatible with -postres', False) 1973 + sysvals.execcount = 2 1974 + elif(arg == '-x2delay'): 1975 + sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000) 1976 + elif(arg == '-postres'): 1977 + if(sysvals.execcount != 1): 1978 + doError('-x2 is not compatible with -postres', False) 1979 + sysvals.postresumetime = getArgInt('-postres', args, 0, 3600) 1980 + elif(arg == '-f'): 1981 + sysvals.usecallgraph = True 1982 + elif(arg == '-modes'): 1983 + cmd = 'modes' 1984 + elif(arg == '-fpdt'): 1985 + cmd = 'fpdt' 1986 + elif(arg == '-usbtopo'): 1987 + cmd = 'usbtopo' 1988 + elif(arg == '-usbauto'): 1989 + cmd = 'usbauto' 1990 + elif(arg == '-status'): 1991 + cmd = 'status' 1992 + elif(arg == '-verbose'): 1993 + sysvals.verbose = True 1994 + elif(arg == '-v'): 1995 + print("Version %.1f" % sysvals.version) 1996 + sys.exit() 1997 + elif(arg == '-rtcwake'): 1998 + sysvals.rtcwake = True 1999 + sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600) 2000 + elif(arg == '-multi'): 2001 + multitest['run'] = True 2002 + multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000) 2003 + multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600) 2004 + elif(arg == '-dmesg'): 2005 + try: 2006 + val = args.next() 2007 + except: 2008 + doError('No dmesg file supplied', True) 2009 + sysvals.notestrun = True 2010 + sysvals.dmesgfile = val 2011 + if(os.path.exists(sysvals.dmesgfile) == False): 2012 + doError('%s doesnt exist' % sysvals.dmesgfile, False) 2013 + elif(arg == '-ftrace'): 2014 + try: 2015 + val = args.next() 2016 + except: 2017 + doError('No ftrace file supplied', True) 2018 + sysvals.notestrun = True 2019 + sysvals.usecallgraph = True 2020 + sysvals.ftracefile = val 2021 + if(os.path.exists(sysvals.ftracefile) == False): 2022 + doError('%s doesnt exist' % sysvals.ftracefile, False) 2023 + elif(arg == '-summary'): 2024 + try: 2025 + val = args.next() 2026 + except: 2027 + doError('No directory supplied', True) 2028 + cmd = 'summary' 2029 + cmdarg = val 2030 + sysvals.notestrun = True 2031 + if(os.path.isdir(val) == False): 2032 + doError('%s isnt accesible' % val, False) 2033 + elif(arg == '-filter'): 2034 + try: 2035 + val = args.next() 2036 + except: 2037 + doError('No devnames supplied', True) 2038 + sysvals.setDeviceFilter(val) 2039 + elif(arg == '-h'): 2040 + printHelp() 2041 + sys.exit() 2042 + else: 2043 + doError('Invalid argument: '+arg, True) 2850 2044 2851 - # -- script main -- 2852 - # loop through the command line arguments 2853 - cmd = "" 2854 - args = iter(sys.argv[1:]) 2855 - for arg in args: 2856 - if(arg == "-m"): 2857 - try: 2858 - val = args.next() 2859 - except: 2860 - doError("No mode supplied", True) 2861 - sysvals.suspendmode = val 2862 - elif(arg == "-f"): 2863 - data.useftrace = True 2864 - elif(arg == "-modes"): 2865 - cmd = "modes" 2866 - elif(arg == "-status"): 2867 - cmd = "status" 2868 - elif(arg == "-verbose"): 2869 - data.verbose = True 2870 - elif(arg == "-rtcwake"): 2871 - sysvals.rtcwake = True 2872 - elif(arg == "-dmesg"): 2873 - try: 2874 - val = args.next() 2875 - except: 2876 - doError("No dmesg file supplied", True) 2877 - data.notestrun = True 2878 - data.usedmesg = True 2879 - sysvals.dmesgfile = val 2880 - elif(arg == "-ftrace"): 2881 - try: 2882 - val = args.next() 2883 - except: 2884 - doError("No ftrace file supplied", True) 2885 - data.notestrun = True 2886 - data.useftrace = True 2887 - sysvals.ftracefile = val 2888 - elif(arg == "-h"): 2889 - printHelp() 2045 + # just run a utility command and exit 2046 + if(cmd != ''): 2047 + if(cmd == 'status'): 2048 + statusCheck() 2049 + elif(cmd == 'fpdt'): 2050 + if(sysvals.android): 2051 + doError('cannot read FPDT on android device', False) 2052 + getFPDT(True) 2053 + elif(cmd == 'usbtopo'): 2054 + if(sysvals.android): 2055 + doError('cannot read USB topology '+\ 2056 + 'on an android device', False) 2057 + detectUSB(True) 2058 + elif(cmd == 'modes'): 2059 + modes = getModes() 2060 + print modes 2061 + elif(cmd == 'usbauto'): 2062 + setUSBDevicesAuto() 2063 + elif(cmd == 'summary'): 2064 + print("Generating a summary of folder \"%s\"" % cmdarg) 2065 + runSummary(cmdarg, True) 2890 2066 sys.exit() 2067 + 2068 + # run test on android device 2069 + if(sysvals.android): 2070 + if(sysvals.usecallgraph): 2071 + doError('ftrace (-f) is not yet supported '+\ 2072 + 'in the android kernel', False) 2073 + if(sysvals.notestrun): 2074 + doError('cannot analyze test files on the '+\ 2075 + 'android device', False) 2076 + 2077 + # if instructed, re-analyze existing data files 2078 + if(sysvals.notestrun): 2079 + rerunTest() 2080 + sys.exit() 2081 + 2082 + # verify that we can run a test 2083 + if(not statusCheck()): 2084 + print('Check FAILED, aborting the test run!') 2085 + sys.exit() 2086 + 2087 + if multitest['run']: 2088 + # run multiple tests in a separte subdirectory 2089 + s = 'x%d' % multitest['count'] 2090 + subdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S') 2091 + os.mkdir(subdir) 2092 + for i in range(multitest['count']): 2093 + if(i != 0): 2094 + print('Waiting %d seconds...' % (multitest['delay'])) 2095 + time.sleep(multitest['delay']) 2096 + print('TEST (%d/%d) START' % (i+1, multitest['count'])) 2097 + runTest(subdir) 2098 + print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count'])) 2099 + runSummary(subdir, False) 2891 2100 else: 2892 - doError("Invalid argument: "+arg, True) 2893 - 2894 - # just run a utility command and exit 2895 - if(cmd != ""): 2896 - if(cmd == "status"): 2897 - statusCheck(True) 2898 - elif(cmd == "modes"): 2899 - modes = getModes() 2900 - print modes 2901 - sys.exit() 2902 - 2903 - data.initialize() 2904 - 2905 - # if instructed, re-analyze existing data files 2906 - if(data.notestrun): 2907 - sysvals.setOutputFile() 2908 - data.vprint("Output file: %s" % sysvals.htmlfile) 2909 - if(sysvals.dmesgfile != ""): 2910 - analyzeKernelLog() 2911 - if(sysvals.ftracefile != ""): 2912 - analyzeTraceLog() 2913 - createHTML() 2914 - sys.exit() 2915 - 2916 - # verify that we can run a test 2917 - data.usedmesg = True 2918 - statusCheck(False) 2919 - 2920 - # prepare for the test 2921 - if(data.useftrace): 2922 - initFtrace() 2923 - sysvals.initTestOutput() 2924 - 2925 - data.vprint("Output files:\n %s" % sysvals.dmesgfile) 2926 - if(data.useftrace): 2927 - data.vprint(" %s" % sysvals.ftracefile) 2928 - data.vprint(" %s" % sysvals.htmlfile) 2929 - 2930 - # execute the test 2931 - executeSuspend() 2932 - analyzeKernelLog() 2933 - if(data.useftrace): 2934 - analyzeTraceLog() 2935 - createHTML() 2101 + # run the test in the current directory 2102 + runTest(".")