diff --git a/drivers/devfreq/devfreq.c b/drivers/devfreq/devfreq.c index 4c49bb1330b5..141413067b5c 100644 --- a/drivers/devfreq/devfreq.c +++ b/drivers/devfreq/devfreq.c @@ -11,6 +11,7 @@ */ #include +#include #include #include #include @@ -28,9 +29,6 @@ #include #include "governor.h" -#define MAX(a,b) ((a > b) ? a : b) -#define MIN(a,b) ((a < b) ? a : b) - static struct class *devfreq_class; /* @@ -221,6 +219,49 @@ static struct devfreq_governor *find_devfreq_governor(const char *name) return ERR_PTR(-ENODEV); } +/** + * try_then_request_governor() - Try to find the governor and request the + * module if is not found. + * @name: name of the governor + * + * Search the list of devfreq governors and request the module and try again + * if is not found. This can happen when both drivers (the governor driver + * and the driver that call devfreq_add_device) are built as modules. + * devfreq_list_lock should be held by the caller. Returns the matched + * governor's pointer. + */ +static struct devfreq_governor *try_then_request_governor(const char *name) +{ + struct devfreq_governor *governor; + int err = 0; + + if (IS_ERR_OR_NULL(name)) { + pr_err("DEVFREQ: %s: Invalid parameters\n", __func__); + return ERR_PTR(-EINVAL); + } + WARN(!mutex_is_locked(&devfreq_list_lock), + "devfreq_list_lock must be locked."); + + governor = find_devfreq_governor(name); + if (IS_ERR(governor)) { + mutex_unlock(&devfreq_list_lock); + + if (!strncmp(name, DEVFREQ_GOV_SIMPLE_ONDEMAND, + DEVFREQ_NAME_LEN)) + err = request_module("governor_%s", "simpleondemand"); + else + err = request_module("governor_%s", name); + /* Restore previous state before return */ + mutex_lock(&devfreq_list_lock); + if (err) + return NULL; + + governor = find_devfreq_governor(name); + } + + return governor; +} + static int devfreq_notify_transition(struct devfreq *devfreq, struct devfreq_freqs *freqs, unsigned int state) { @@ -280,14 +321,14 @@ int update_devfreq(struct devfreq *devfreq) * max_freq * min_freq */ - max_freq = MIN(devfreq->scaling_max_freq, devfreq->max_freq); - min_freq = MAX(devfreq->scaling_min_freq, devfreq->min_freq); + max_freq = min(devfreq->scaling_max_freq, devfreq->max_freq); + min_freq = max(devfreq->scaling_min_freq, devfreq->min_freq); - if (min_freq && freq < min_freq) { + if (freq < min_freq) { freq = min_freq; flags &= ~DEVFREQ_FLAG_LEAST_UPPER_BOUND; /* Use GLB */ } - if (max_freq && freq > max_freq) { + if (freq > max_freq) { freq = max_freq; flags |= DEVFREQ_FLAG_LEAST_UPPER_BOUND; /* Use LUB */ } @@ -534,10 +575,6 @@ static void devfreq_dev_release(struct device *dev) list_del(&devfreq->node); mutex_unlock(&devfreq_list_lock); - if (devfreq->governor) - devfreq->governor->event_handler(devfreq, - DEVFREQ_GOV_STOP, NULL); - if (devfreq->profile->exit) devfreq->profile->exit(devfreq->dev.parent); @@ -646,9 +683,8 @@ struct devfreq *devfreq_add_device(struct device *dev, mutex_unlock(&devfreq->lock); mutex_lock(&devfreq_list_lock); - list_add(&devfreq->node, &devfreq_list); - governor = find_devfreq_governor(devfreq->governor_name); + governor = try_then_request_governor(devfreq->governor_name); if (IS_ERR(governor)) { dev_err(dev, "%s: Unable to find governor for the device\n", __func__); @@ -664,19 +700,20 @@ struct devfreq *devfreq_add_device(struct device *dev, __func__); goto err_init; } + + list_add(&devfreq->node, &devfreq_list); + mutex_unlock(&devfreq_list_lock); return devfreq; err_init: - list_del(&devfreq->node); mutex_unlock(&devfreq_list_lock); - device_unregister(&devfreq->dev); + devfreq_remove_device(devfreq); devfreq = NULL; err_dev: - if (devfreq) - kfree(devfreq); + kfree(devfreq); err_out: return ERR_PTR(err); } @@ -693,6 +730,9 @@ int devfreq_remove_device(struct devfreq *devfreq) if (!devfreq) return -EINVAL; + if (devfreq->governor) + devfreq->governor->event_handler(devfreq, + DEVFREQ_GOV_STOP, NULL); device_unregister(&devfreq->dev); return 0; @@ -991,7 +1031,7 @@ static ssize_t governor_store(struct device *dev, struct device_attribute *attr, return -EINVAL; mutex_lock(&devfreq_list_lock); - governor = find_devfreq_governor(str_governor); + governor = try_then_request_governor(str_governor); if (IS_ERR(governor)) { ret = PTR_ERR(governor); goto out; @@ -1126,17 +1166,26 @@ static ssize_t min_freq_store(struct device *dev, struct device_attribute *attr, struct devfreq *df = to_devfreq(dev); unsigned long value; int ret; - unsigned long max; ret = sscanf(buf, "%lu", &value); if (ret != 1) return -EINVAL; mutex_lock(&df->lock); - max = df->max_freq; - if (value && max && value > max) { - ret = -EINVAL; - goto unlock; + + if (value) { + if (value > df->max_freq) { + ret = -EINVAL; + goto unlock; + } + } else { + unsigned long *freq_table = df->profile->freq_table; + + /* Get minimum frequency according to sorting order */ + if (freq_table[0] < freq_table[df->profile->max_state - 1]) + value = freq_table[0]; + else + value = freq_table[df->profile->max_state - 1]; } df->min_freq = value; @@ -1152,7 +1201,7 @@ static ssize_t min_freq_show(struct device *dev, struct device_attribute *attr, { struct devfreq *df = to_devfreq(dev); - return sprintf(buf, "%lu\n", MAX(df->scaling_min_freq, df->min_freq)); + return sprintf(buf, "%lu\n", max(df->scaling_min_freq, df->min_freq)); } static ssize_t max_freq_store(struct device *dev, struct device_attribute *attr, @@ -1161,17 +1210,26 @@ static ssize_t max_freq_store(struct device *dev, struct device_attribute *attr, struct devfreq *df = to_devfreq(dev); unsigned long value; int ret; - unsigned long min; ret = sscanf(buf, "%lu", &value); if (ret != 1) return -EINVAL; mutex_lock(&df->lock); - min = df->min_freq; - if (value && min && value < min) { - ret = -EINVAL; - goto unlock; + + if (value) { + if (value < df->min_freq) { + ret = -EINVAL; + goto unlock; + } + } else { + unsigned long *freq_table = df->profile->freq_table; + + /* Get maximum frequency according to sorting order */ + if (freq_table[0] < freq_table[df->profile->max_state - 1]) + value = freq_table[df->profile->max_state - 1]; + else + value = freq_table[0]; } df->max_freq = value; @@ -1188,7 +1246,7 @@ static ssize_t max_freq_show(struct device *dev, struct device_attribute *attr, { struct devfreq *df = to_devfreq(dev); - return sprintf(buf, "%lu\n", MIN(df->scaling_max_freq, df->max_freq)); + return sprintf(buf, "%lu\n", min(df->scaling_max_freq, df->max_freq)); } static DEVICE_ATTR_RW(max_freq); diff --git a/drivers/devfreq/event/exynos-ppmu.c b/drivers/devfreq/event/exynos-ppmu.c index a9c64f0d3284..c61de0bdf053 100644 --- a/drivers/devfreq/event/exynos-ppmu.c +++ b/drivers/devfreq/event/exynos-ppmu.c @@ -535,8 +535,8 @@ static int of_get_devfreq_events(struct device_node *np, if (i == ARRAY_SIZE(ppmu_events)) { dev_warn(dev, - "don't know how to configure events : %s\n", - node->name); + "don't know how to configure events : %pOFn\n", + node); continue; } diff --git a/drivers/devfreq/governor.h b/drivers/devfreq/governor.h index cfc50a61a90d..f53339ca610f 100644 --- a/drivers/devfreq/governor.h +++ b/drivers/devfreq/governor.h @@ -25,6 +25,9 @@ #define DEVFREQ_GOV_SUSPEND 0x4 #define DEVFREQ_GOV_RESUME 0x5 +#define DEVFREQ_MIN_FREQ 0 +#define DEVFREQ_MAX_FREQ ULONG_MAX + /** * struct devfreq_governor - Devfreq policy governor * @node: list node - contains registered devfreq governors @@ -54,9 +57,6 @@ struct devfreq_governor { unsigned int event, void *data); }; -/* Caution: devfreq->lock must be locked before calling update_devfreq */ -extern int update_devfreq(struct devfreq *devfreq); - extern void devfreq_monitor_start(struct devfreq *devfreq); extern void devfreq_monitor_stop(struct devfreq *devfreq); extern void devfreq_monitor_suspend(struct devfreq *devfreq); diff --git a/drivers/devfreq/governor_performance.c b/drivers/devfreq/governor_performance.c index 4d23ecfbd948..ded429fd51be 100644 --- a/drivers/devfreq/governor_performance.c +++ b/drivers/devfreq/governor_performance.c @@ -20,10 +20,7 @@ static int devfreq_performance_func(struct devfreq *df, * target callback should be able to get floor value as * said in devfreq.h */ - if (!df->max_freq) - *freq = UINT_MAX; - else - *freq = df->max_freq; + *freq = DEVFREQ_MAX_FREQ; return 0; } diff --git a/drivers/devfreq/governor_powersave.c b/drivers/devfreq/governor_powersave.c index 0c42f23249ef..9e8897f5ac42 100644 --- a/drivers/devfreq/governor_powersave.c +++ b/drivers/devfreq/governor_powersave.c @@ -20,7 +20,7 @@ static int devfreq_powersave_func(struct devfreq *df, * target callback should be able to get ceiling value as * said in devfreq.h */ - *freq = df->min_freq; + *freq = DEVFREQ_MIN_FREQ; return 0; } diff --git a/drivers/devfreq/governor_simpleondemand.c b/drivers/devfreq/governor_simpleondemand.c index 28e0f2de7100..c0417f0e081e 100644 --- a/drivers/devfreq/governor_simpleondemand.c +++ b/drivers/devfreq/governor_simpleondemand.c @@ -27,7 +27,6 @@ static int devfreq_simple_ondemand_func(struct devfreq *df, unsigned int dfso_upthreshold = DFSO_UPTHRESHOLD; unsigned int dfso_downdifferential = DFSO_DOWNDIFFERENCTIAL; struct devfreq_simple_ondemand_data *data = df->data; - unsigned long max = (df->max_freq) ? df->max_freq : UINT_MAX; err = devfreq_update_stats(df); if (err) @@ -47,7 +46,7 @@ static int devfreq_simple_ondemand_func(struct devfreq *df, /* Assume MAX if it is going to be divided by zero */ if (stat->total_time == 0) { - *freq = max; + *freq = DEVFREQ_MAX_FREQ; return 0; } @@ -60,13 +59,13 @@ static int devfreq_simple_ondemand_func(struct devfreq *df, /* Set MAX if it's busy enough */ if (stat->busy_time * 100 > stat->total_time * dfso_upthreshold) { - *freq = max; + *freq = DEVFREQ_MAX_FREQ; return 0; } /* Set MAX if we do not know the initial frequency */ if (stat->current_frequency == 0) { - *freq = max; + *freq = DEVFREQ_MAX_FREQ; return 0; } @@ -85,11 +84,6 @@ static int devfreq_simple_ondemand_func(struct devfreq *df, b = div_u64(b, (dfso_upthreshold - dfso_downdifferential / 2)); *freq = (unsigned long) b; - if (df->min_freq && *freq < df->min_freq) - *freq = df->min_freq; - if (df->max_freq && *freq > df->max_freq) - *freq = df->max_freq; - return 0; } diff --git a/drivers/devfreq/governor_userspace.c b/drivers/devfreq/governor_userspace.c index 080607c3f34d..378d84c011df 100644 --- a/drivers/devfreq/governor_userspace.c +++ b/drivers/devfreq/governor_userspace.c @@ -26,19 +26,11 @@ static int devfreq_userspace_func(struct devfreq *df, unsigned long *freq) { struct userspace_data *data = df->data; - if (data->valid) { - unsigned long adjusted_freq = data->user_frequency; - - if (df->max_freq && adjusted_freq > df->max_freq) - adjusted_freq = df->max_freq; - - if (df->min_freq && adjusted_freq < df->min_freq) - adjusted_freq = df->min_freq; - - *freq = adjusted_freq; - } else { + if (data->valid) + *freq = data->user_frequency; + else *freq = df->previous_freq; /* No user freq specified yet */ - } + return 0; } diff --git a/include/linux/devfreq.h b/include/linux/devfreq.h index 3aae5b3af87c..e4963b0f45da 100644 --- a/include/linux/devfreq.h +++ b/include/linux/devfreq.h @@ -198,6 +198,14 @@ extern void devm_devfreq_remove_device(struct device *dev, extern int devfreq_suspend_device(struct devfreq *devfreq); extern int devfreq_resume_device(struct devfreq *devfreq); +/** + * update_devfreq() - Reevaluate the device and configure frequency + * @devfreq: the devfreq device + * + * Note: devfreq->lock must be held + */ +extern int update_devfreq(struct devfreq *devfreq); + /* Helper functions for devfreq user device driver with OPP. */ extern struct dev_pm_opp *devfreq_recommended_opp(struct device *dev, unsigned long *freq, u32 flags); diff --git a/tools/power/cpupower/bench/parse.c b/tools/power/cpupower/bench/parse.c index 9ba8a44ad2a7..84caee38418f 100644 --- a/tools/power/cpupower/bench/parse.c +++ b/tools/power/cpupower/bench/parse.c @@ -145,7 +145,7 @@ struct config *prepare_default_config() config->cpu = 0; config->prio = SCHED_HIGH; config->verbose = 0; - strncpy(config->governor, "ondemand", 8); + strncpy(config->governor, "ondemand", sizeof(config->governor)); config->output = stdout; diff --git a/tools/power/cpupower/utils/cpufreq-info.c b/tools/power/cpupower/utils/cpufreq-info.c index df43cd45d810..ccd08dd00996 100644 --- a/tools/power/cpupower/utils/cpufreq-info.c +++ b/tools/power/cpupower/utils/cpufreq-info.c @@ -200,6 +200,8 @@ static int get_boost_mode(unsigned int cpu) printf(_(" Boost States: %d\n"), b_states); printf(_(" Total States: %d\n"), pstate_no); for (i = 0; i < pstate_no; i++) { + if (!pstates[i]) + continue; if (i < b_states) printf(_(" Pstate-Pb%d: %luMHz (boost state)" "\n"), i, pstates[i]); diff --git a/tools/power/cpupower/utils/helpers/amd.c b/tools/power/cpupower/utils/helpers/amd.c index bb41cdd0df6b..9607ada5b29a 100644 --- a/tools/power/cpupower/utils/helpers/amd.c +++ b/tools/power/cpupower/utils/helpers/amd.c @@ -33,7 +33,7 @@ union msr_pstate { unsigned vid:8; unsigned iddval:8; unsigned idddiv:2; - unsigned res1:30; + unsigned res1:31; unsigned en:1; } fam17h_bits; unsigned long long val; @@ -119,6 +119,11 @@ int decode_pstates(unsigned int cpu, unsigned int cpu_family, } if (read_msr(cpu, MSR_AMD_PSTATE + i, &pstate.val)) return -1; + if ((cpu_family == 0x17) && (!pstate.fam17h_bits.en)) + continue; + else if (!pstate.bits.en) + continue; + pstates[i] = get_cof(cpu_family, pstate); } *no = i; diff --git a/tools/power/pm-graph/Makefile b/tools/power/pm-graph/Makefile index c1899cd72c80..845541544570 100644 --- a/tools/power/pm-graph/Makefile +++ b/tools/power/pm-graph/Makefile @@ -23,8 +23,8 @@ install : uninstall install -m 644 config/suspend-x2-proc.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config install -d $(DESTDIR)$(PREFIX)/bin - ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/bootgraph.py $(DESTDIR)$(PREFIX)/bin/bootgraph - ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/sleepgraph.py $(DESTDIR)$(PREFIX)/bin/sleepgraph + ln -s ../lib/pm-graph/bootgraph.py $(DESTDIR)$(PREFIX)/bin/bootgraph + ln -s ../lib/pm-graph/sleepgraph.py $(DESTDIR)$(PREFIX)/bin/sleepgraph install -d $(DESTDIR)$(PREFIX)/share/man/man8 install bootgraph.8 $(DESTDIR)$(PREFIX)/share/man/man8 diff --git a/tools/power/pm-graph/bootgraph.py b/tools/power/pm-graph/bootgraph.py index 8ee626c0f6a5..6dae57041537 100755 --- a/tools/power/pm-graph/bootgraph.py +++ b/tools/power/pm-graph/bootgraph.py @@ -34,6 +34,10 @@ from datetime import datetime, timedelta from subprocess import call, Popen, PIPE import sleepgraph as aslib +def pprint(msg): + print(msg) + sys.stdout.flush() + # ----------------- CLASSES -------------------- # Class: SystemValues @@ -157,11 +161,11 @@ class SystemValues(aslib.SystemValues): return cmdline def manualRebootRequired(self): cmdline = self.kernelParams() - print 'To generate a new timeline manually, follow these steps:\n' - print '1. Add the CMDLINE string to your kernel command line.' - print '2. Reboot the system.' - print '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n' - print 'CMDLINE="%s"' % cmdline + pprint('To generate a new timeline manually, follow these steps:\n\n'\ + '1. Add the CMDLINE string to your kernel command line.\n'\ + '2. Reboot the system.\n'\ + '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n\n'\ + 'CMDLINE="%s"' % cmdline) sys.exit() def blGrub(self): blcmd = '' @@ -431,7 +435,7 @@ def parseTraceLog(data): if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0): continue if(not cg.postProcess()): - print('Sanity check failed for %s-%d' % (proc, pid)) + pprint('Sanity check failed for %s-%d' % (proc, pid)) continue # match cg data to devices devname = data.deviceMatch(pid, cg) @@ -442,8 +446,8 @@ def parseTraceLog(data): sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\ (kind, cg.name, proc, pid, cg.start, cg.end)) elif len(cg.list) > 1000000: - print 'WARNING: the callgraph found for %s is massive! (%d lines)' %\ - (devname, len(cg.list)) + pprint('WARNING: the callgraph found for %s is massive! (%d lines)' %\ + (devname, len(cg.list))) # Function: retrieveLogs # Description: @@ -528,7 +532,7 @@ def createBootGraph(data): tMax = data.end tTotal = tMax - t0 if(tTotal == 0): - print('ERROR: No timeline data') + pprint('ERROR: No timeline data') return False user_mode = '%.0f'%(data.tUserMode*1000) last_init = '%.0f'%(tTotal*1000) @@ -734,7 +738,7 @@ def updateCron(restore=False): op.close() res = call([cmd, cronfile]) except Exception, e: - print 'Exception: %s' % str(e) + pprint('Exception: %s' % str(e)) shutil.move(backfile, cronfile) res = -1 if res != 0: @@ -750,7 +754,7 @@ def updateGrub(restore=False): call(sysvals.blexec, stderr=PIPE, stdout=PIPE, env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'}) except Exception, e: - print 'Exception: %s\n' % str(e) + pprint('Exception: %s\n' % str(e)) return # extract the option and create a grub config without it sysvals.rootUser(True) @@ -797,7 +801,7 @@ def updateGrub(restore=False): res = call(sysvals.blexec) os.remove(grubfile) except Exception, e: - print 'Exception: %s' % str(e) + pprint('Exception: %s' % str(e)) res = -1 # cleanup shutil.move(tempfile, grubfile) @@ -821,7 +825,7 @@ def updateKernelParams(restore=False): def doError(msg, help=False): if help == True: printHelp() - print 'ERROR: %s\n' % msg + pprint('ERROR: %s\n' % msg) sysvals.outputResult({'error':msg}) sys.exit() @@ -829,52 +833,51 @@ def doError(msg, help=False): # Description: # print out the help text def printHelp(): - print('') - print('%s v%s' % (sysvals.title, sysvals.version)) - print('Usage: bootgraph ') - print('') - print('Description:') - print(' This tool reads in a dmesg log of linux kernel boot and') - print(' creates an html representation of the boot timeline up to') - print(' the start of the init process.') - print('') - print(' If no specific command is given the tool reads the current dmesg') - print(' and/or ftrace log and creates a timeline') - print('') - print(' Generates output files in subdirectory: boot-yymmdd-HHMMSS') - print(' HTML output: _boot.html') - print(' raw dmesg output: _boot_dmesg.txt') - print(' raw ftrace output: _boot_ftrace.txt') - print('') - print('Options:') - print(' -h Print this help text') - print(' -v Print the current tool version') - print(' -verbose Print extra information during execution and analysis') - print(' -addlogs Add the dmesg log to the html output') - print(' -result fn Export a results table to a text file for parsing.') - print(' -o name Overrides the output subdirectory name when running a new test') - print(' default: boot-{date}-{time}') - print(' [advanced]') - print(' -fstat Use ftrace to add function detail and statistics (default: disabled)') - print(' -f/-callgraph Add callgraph detail, can be very large (default: disabled)') - print(' -maxdepth N limit the callgraph data to N call levels (default: 2)') - print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)') - print(' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])') - print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)') - print(' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)') - print(' -cgfilter S Filter the callgraph output in the timeline') - print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)') - print(' -bl name Use the following boot loader for kernel params (default: grub)') - print(' -reboot Reboot the machine automatically and generate a new timeline') - print(' -manual Show the steps to generate a new timeline manually (used with -reboot)') - print('') - print('Other commands:') - print(' -flistall Print all functions capable of being captured in ftrace') - print(' -sysinfo Print out system info extracted from BIOS') - print(' [redo]') - print(' -dmesg file Create HTML output using dmesg input (used with -ftrace)') - print(' -ftrace file Create HTML output using ftrace input (used with -dmesg)') - print('') + pprint('\n%s v%s\n'\ + 'Usage: bootgraph \n'\ + '\n'\ + 'Description:\n'\ + ' This tool reads in a dmesg log of linux kernel boot and\n'\ + ' creates an html representation of the boot timeline up to\n'\ + ' the start of the init process.\n'\ + '\n'\ + ' If no specific command is given the tool reads the current dmesg\n'\ + ' and/or ftrace log and creates a timeline\n'\ + '\n'\ + ' Generates output files in subdirectory: boot-yymmdd-HHMMSS\n'\ + ' HTML output: _boot.html\n'\ + ' raw dmesg output: _boot_dmesg.txt\n'\ + ' raw ftrace output: _boot_ftrace.txt\n'\ + '\n'\ + 'Options:\n'\ + ' -h Print this help text\n'\ + ' -v Print the current tool version\n'\ + ' -verbose Print extra information during execution and analysis\n'\ + ' -addlogs Add the dmesg log to the html output\n'\ + ' -result fn Export a results table to a text file for parsing.\n'\ + ' -o name Overrides the output subdirectory name when running a new test\n'\ + ' default: boot-{date}-{time}\n'\ + ' [advanced]\n'\ + ' -fstat Use ftrace to add function detail and statistics (default: disabled)\n'\ + ' -f/-callgraph Add callgraph detail, can be very large (default: disabled)\n'\ + ' -maxdepth N limit the callgraph data to N call levels (default: 2)\n'\ + ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\ + ' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])\n'\ + ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\ + ' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)\n'\ + ' -cgfilter S Filter the callgraph output in the timeline\n'\ + ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\ + ' -bl name Use the following boot loader for kernel params (default: grub)\n'\ + ' -reboot Reboot the machine automatically and generate a new timeline\n'\ + ' -manual Show the steps to generate a new timeline manually (used with -reboot)\n'\ + '\n'\ + 'Other commands:\n'\ + ' -flistall Print all functions capable of being captured in ftrace\n'\ + ' -sysinfo Print out system info extracted from BIOS\n'\ + ' [redo]\n'\ + ' -dmesg file Create HTML output using dmesg input (used with -ftrace)\n'\ + ' -ftrace file Create HTML output using ftrace input (used with -dmesg)\n'\ + '' % (sysvals.title, sysvals.version)) return True # ----------------- MAIN -------------------- @@ -895,7 +898,7 @@ if __name__ == '__main__': printHelp() sys.exit() elif(arg == '-v'): - print("Version %s" % sysvals.version) + pprint("Version %s" % sysvals.version) sys.exit() elif(arg == '-verbose'): sysvals.verbose = True @@ -1016,7 +1019,7 @@ if __name__ == '__main__': print f elif cmd == 'checkbl': sysvals.getBootLoader() - print 'Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec) + pprint('Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec)) elif(cmd == 'sysinfo'): sysvals.printSystemInfo(True) sys.exit() diff --git a/tools/power/pm-graph/config/cgskip.txt b/tools/power/pm-graph/config/cgskip.txt index e48d588fbfb4..9ff88e7e2300 100644 --- a/tools/power/pm-graph/config/cgskip.txt +++ b/tools/power/pm-graph/config/cgskip.txt @@ -27,6 +27,7 @@ ktime_get # console calls printk dev_printk +__dev_printk console_unlock # memory handling diff --git a/tools/power/pm-graph/config/custom-timeline-functions.cfg b/tools/power/pm-graph/config/custom-timeline-functions.cfg index f8fcb06fd68b..4f80ad7d7275 100644 --- a/tools/power/pm-graph/config/custom-timeline-functions.cfg +++ b/tools/power/pm-graph/config/custom-timeline-functions.cfg @@ -105,7 +105,7 @@ override-dev-timeline-functions: true # example: [color=#CC00CC] # # arglist: A list of arguments from registers/stack addresses. See URL: -# https://www.kernel.org/doc/Documentation/trace/kprobetrace.rst +# https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt # # example: cpu=%di:s32 # @@ -170,7 +170,7 @@ pm_restore_console: # example: [color=#CC00CC] # # arglist: A list of arguments from registers/stack addresses. See URL: -# https://www.kernel.org/doc/Documentation/trace/kprobetrace.rst +# https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt # # example: port=+36(%di):s32 # diff --git a/tools/power/pm-graph/sleepgraph.8 b/tools/power/pm-graph/sleepgraph.8 index 070be2cf7f74..24a2e7d0ae63 100644 --- a/tools/power/pm-graph/sleepgraph.8 +++ b/tools/power/pm-graph/sleepgraph.8 @@ -65,9 +65,9 @@ During test, enable/disable runtime suspend for all devices. The test is delayed by 5 seconds to allow runtime suspend changes to occur. The settings are restored after the test is complete. .TP -\fB-display \fIon/off\fR -Turn the display on or off for the test using the xset command. This helps -maintain the consistecy of test data for better comparison. +\fB-display \fIon/off/standby/suspend\fR +Switch the display to the requested mode for the test using the xset command. +This helps maintain the consistency of test data for better comparison. .TP \fB-skiphtml\fR Run the test and capture the trace logs, but skip the timeline generation. @@ -183,6 +183,13 @@ Print out the contents of the ACPI Firmware Performance Data Table. \fB-battery\fR Print out battery status and current charge. .TP +\fB-xon/-xoff/-xstandby/-xsuspend\fR +Test xset by attempting to switch the display to the given mode. This +is the same command which will be issued by \fB-display \fImode\fR. +.TP +\fB-xstat\fR +Get the current DPMS display mode. +.TP \fB-sysinfo\fR Print out system info extracted from BIOS. Reads /dev/mem directly instead of going through dmidecode. .TP diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py index 0c760478f7d7..52618f3444d4 100755 --- a/tools/power/pm-graph/sleepgraph.py +++ b/tools/power/pm-graph/sleepgraph.py @@ -54,6 +54,7 @@ import os import string import re import platform +import signal from datetime import datetime import struct import ConfigParser @@ -61,6 +62,10 @@ import gzip from threading import Thread from subprocess import call, Popen, PIPE +def pprint(msg): + print(msg) + sys.stdout.flush() + # ----------------- CLASSES -------------------- # Class: SystemValues @@ -69,10 +74,10 @@ from subprocess import call, Popen, PIPE # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '5.1' + version = '5.2' ansi = False rs = 0 - display = 0 + display = '' gzip = False sync = False verbose = False @@ -99,6 +104,7 @@ class SystemValues: tpath = '/sys/kernel/debug/tracing/' fpdtpath = '/sys/firmware/acpi/tables/FPDT' epath = '/sys/kernel/debug/tracing/events/power/' + pmdpath = '/sys/power/pm_debug_messages' traceevents = [ 'suspend_resume', 'device_pm_callback_end', @@ -109,8 +115,10 @@ class SystemValues: mempath = '/dev/mem' powerfile = '/sys/power/state' mempowerfile = '/sys/power/mem_sleep' + diskpowerfile = '/sys/power/disk' suspendmode = 'mem' memmode = '' + diskmode = '' hostname = 'localhost' prefix = 'test' teststamp = '' @@ -137,16 +145,15 @@ class SystemValues: useprocmon = False notestrun = False cgdump = False + devdump = False mixedphaseheight = True devprops = dict() predelay = 0 postdelay = 0 - procexecfmt = 'ps - (?P.*)$' - devpropfmt = '# Device Properties: .*' - tracertypefmt = '# tracer: (?P.*)' - firmwarefmt = '# fwsuspend (?P[0-9]*) fwresume (?P[0-9]*)$' + pmdebug = '' tracefuncs = { 'sys_sync': {}, + 'ksys_sync': {}, '__pm_notifier_call_chain': {}, 'pm_prepare_console': {}, 'pm_notifier_call_chain': {}, @@ -187,7 +194,6 @@ class SystemValues: dev_tracefuncs = { # general wait/delay/sleep 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 }, - 'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 }, 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 }, 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 }, 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 }, @@ -199,6 +205,9 @@ class SystemValues: # filesystem 'ext4_sync_fs': {}, # 80211 + 'ath10k_bmi_read_memory': { 'args_x86_64': {'length':'%cx:s32'} }, + 'ath10k_bmi_write_memory': { 'args_x86_64': {'length':'%cx:s32'} }, + 'ath10k_bmi_fast_download': { 'args_x86_64': {'length':'%cx:s32'} }, 'iwlagn_mac_start': {}, 'iwlagn_alloc_bcast_station': {}, 'iwl_trans_pcie_start_hw': {}, @@ -241,6 +250,7 @@ class SystemValues: timeformat = '%.3f' cmdline = '%s %s' % \ (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:])) + sudouser = '' def __init__(self): self.archargs = 'args_'+platform.machine() self.hostname = platform.node() @@ -256,27 +266,49 @@ class SystemValues: if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()): self.ansi = True self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S') + if os.getuid() == 0 and 'SUDO_USER' in os.environ and \ + os.environ['SUDO_USER']: + self.sudouser = os.environ['SUDO_USER'] def vprint(self, msg): self.logmsg += msg+'\n' - if(self.verbose): - print(msg) + if self.verbose or msg.startswith('WARNING:'): + pprint(msg) + def signalHandler(self, signum, frame): + if not self.result: + return + signame = self.signames[signum] if signum in self.signames else 'UNKNOWN' + msg = 'Signal %s caused a tool exit, line %d' % (signame, frame.f_lineno) + sysvals.outputResult({'error':msg}) + sys.exit(3) + def signalHandlerInit(self): + capture = ['BUS', 'SYS', 'XCPU', 'XFSZ', 'PWR', 'HUP', 'INT', 'QUIT', + 'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM', 'TSTP'] + self.signames = dict() + for i in capture: + s = 'SIG'+i + try: + signum = getattr(signal, s) + signal.signal(signum, self.signalHandler) + except: + continue + self.signames[signum] = s def rootCheck(self, fatal=True): if(os.access(self.powerfile, os.W_OK)): return True if fatal: msg = 'This command requires sysfs mount and root access' - print('ERROR: %s\n') % msg + pprint('ERROR: %s\n' % msg) self.outputResult({'error':msg}) - sys.exit() + sys.exit(1) return False def rootUser(self, fatal=False): if 'USER' in os.environ and os.environ['USER'] == 'root': return True if fatal: msg = 'This command must be run as root' - print('ERROR: %s\n') % msg + pprint('ERROR: %s\n' % msg) self.outputResult({'error':msg}) - sys.exit() + sys.exit(1) return False def getExec(self, cmd): dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin', @@ -406,8 +438,8 @@ class SystemValues: ktime = m.group('ktime') fp.close() self.dmesgstart = float(ktime) - def getdmesg(self, fwdata=[]): - op = self.writeDatafileHeader(sysvals.dmesgfile, fwdata) + def getdmesg(self, testdata): + op = self.writeDatafileHeader(sysvals.dmesgfile, testdata) # store all new dmesg lines since initdmesg was called fp = Popen('dmesg', stdout=PIPE).stdout for line in fp: @@ -535,7 +567,7 @@ class SystemValues: if len(self.kprobes) < 1: return if output: - print(' kprobe functions in this kernel:') + pprint(' kprobe functions in this kernel:') # first test each kprobe rejects = [] # sort kprobes: trace, ub-dev, custom, dev @@ -557,7 +589,7 @@ class SystemValues: else: kpl[2].append(name) if output: - print(' %s: %s' % (name, res)) + pprint(' %s: %s' % (name, res)) kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3] # remove all failed ones from the list for name in rejects: @@ -571,7 +603,7 @@ class SystemValues: if output: check = self.fgetVal('kprobe_events') linesack = (len(check.split('\n')) - 1) / 2 - print(' kprobe functions enabled: %d/%d' % (linesack, linesout)) + pprint(' kprobe functions enabled: %d/%d' % (linesack, linesout)) self.fsetVal('1', 'events/kprobes/enable') def testKprobe(self, kname, kprobe): self.fsetVal('0', 'events/kprobes/enable') @@ -619,6 +651,8 @@ class SystemValues: self.fsetVal('0', 'events/kprobes/enable') self.fsetVal('', 'kprobe_events') self.fsetVal('1024', 'buffer_size_kb') + if self.pmdebug: + self.setVal(self.pmdebug, self.pmdpath) def setupAllKprobes(self): for name in self.tracefuncs: self.defaultKprobe(name, self.tracefuncs[name]) @@ -637,10 +671,15 @@ class SystemValues: return False def initFtrace(self): self.printSystemInfo(False) - print('INITIALIZING FTRACE...') + pprint('INITIALIZING FTRACE...') # turn trace off self.fsetVal('0', 'tracing_on') self.cleanupFtrace() + # pm debug messages + pv = self.getVal(self.pmdpath) + if pv != '1': + self.setVal('1', self.pmdpath) + self.pmdebug = pv # set the trace clock to global self.fsetVal('global', 'trace_clock') self.fsetVal('nop', 'current_tracer') @@ -649,7 +688,8 @@ class SystemValues: if self.bufsize > 0: tgtsize = self.bufsize elif self.usecallgraph or self.usedevsrc: - tgtsize = min(self.memfree, 3*1024*1024) + bmax = (1*1024*1024) if self.suspendmode == 'disk' else (3*1024*1024) + tgtsize = min(self.memfree, bmax) else: tgtsize = 65536 while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'): @@ -658,7 +698,7 @@ class SystemValues: if tgtsize < 65536: tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus break - print 'Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus) + pprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus)) # initialize the callgraph trace if(self.usecallgraph): # set trace type @@ -691,7 +731,7 @@ class SystemValues: if self.usedevsrc: for name in self.dev_tracefuncs: self.defaultKprobe(name, self.dev_tracefuncs[name]) - print('INITIALIZING KPROBES...') + pprint('INITIALIZING KPROBES...') self.addKprobes(self.verbose) if(self.usetraceevents): # turn trace events on @@ -728,19 +768,24 @@ class SystemValues: if not self.ansi: return str return '\x1B[%d;40m%s\x1B[m' % (color, str) - def writeDatafileHeader(self, filename, fwdata=[]): + def writeDatafileHeader(self, filename, testdata): fp = self.openlog(filename, 'w') fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline)) - if(self.suspendmode == 'mem' or self.suspendmode == 'command'): - for fw in fwdata: + for test in testdata: + if 'fw' in test: + fw = test['fw'] if(fw): fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) + if 'bat' in test: + (a1, c1), (a2, c2) = test['bat'] + fp.write('# battery %s %d %s %d\n' % (a1, c1, a2, c2)) + if test['error'] or len(testdata) > 1: + fp.write('# enter_sleep_error %s\n' % test['error']) return fp - def sudouser(self, dir): - if os.path.exists(dir) and os.getuid() == 0 and \ - 'SUDO_USER' in os.environ: + def sudoUserchown(self, dir): + if os.path.exists(dir) and self.sudouser: cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' - call(cmd.format(os.environ['SUDO_USER'], dir), shell=True) + call(cmd.format(self.sudouser, dir), shell=True) def outputResult(self, testdata, num=0): if not self.result: return @@ -762,7 +807,7 @@ class SystemValues: if 'bugurl' in testdata: fp.write('url%s: %s\n' % (n, testdata['bugurl'])) fp.close() - self.sudouser(self.result) + self.sudoUserchown(self.result) def configFile(self, file): dir = os.path.dirname(os.path.realpath(__file__)) if os.path.exists(file): @@ -800,15 +845,16 @@ suspendmodename = { # Simple class which holds property values collected # for all the devices used in the timeline. class DevProps: - syspath = '' - altname = '' - async = True - xtraclass = '' - xtrainfo = '' + def __init__(self): + self.syspath = '' + self.altname = '' + self.async = True + self.xtraclass = '' + self.xtrainfo = '' def out(self, dev): return '%s,%s,%d;' % (dev, self.altname, self.async) def debug(self, dev): - print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async) + pprint('%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async)) def altName(self, dev): if not self.altname or self.altname == dev: return dev @@ -831,9 +877,6 @@ class DevProps: # A container used to create a device hierachy, with a single root node # and a tree of child nodes. Used by Data.deviceTopology() class DeviceNode: - name = '' - children = 0 - depth = 0 def __init__(self, nodename, nodedepth): self.name = nodename self.children = [] @@ -861,71 +904,78 @@ class DeviceNode: # } # class Data: - dmesg = {} # root data structure - phases = [] # ordered list of phases - start = 0.0 # test start - end = 0.0 # test end - tSuspended = 0.0 # low-level suspend start - tResumed = 0.0 # low-level resume start - tKernSus = 0.0 # kernel level suspend start - tKernRes = 0.0 # kernel level resume end - tLow = 0.0 # time spent in low-level suspend (standby/freeze) - fwValid = False # is firmware data available - fwSuspend = 0 # time spent in firmware suspend - fwResume = 0 # time spent in firmware resume - dmesgtext = [] # dmesg text file in memory - pstl = 0 # process timeline - testnumber = 0 - idstr = '' - html_device_id = 0 - stamp = 0 - outfile = '' - devpids = [] - kerror = False + phasedef = { + 'suspend_prepare': {'order': 0, 'color': '#CCFFCC'}, + 'suspend': {'order': 1, 'color': '#88FF88'}, + 'suspend_late': {'order': 2, 'color': '#00AA00'}, + 'suspend_noirq': {'order': 3, 'color': '#008888'}, + 'suspend_machine': {'order': 4, 'color': '#0000FF'}, + 'resume_machine': {'order': 5, 'color': '#FF0000'}, + 'resume_noirq': {'order': 6, 'color': '#FF9900'}, + 'resume_early': {'order': 7, 'color': '#FFCC00'}, + 'resume': {'order': 8, 'color': '#FFFF88'}, + 'resume_complete': {'order': 9, 'color': '#FFFFCC'}, + } + errlist = { + 'HWERROR' : '.*\[ *Hardware Error *\].*', + 'FWBUG' : '.*\[ *Firmware Bug *\].*', + 'BUG' : '.*BUG.*', + 'ERROR' : '.*ERROR.*', + 'WARNING' : '.*WARNING.*', + 'IRQ' : '.*genirq: .*', + 'TASKFAIL': '.*Freezing of tasks failed.*', + } def __init__(self, num): idchar = 'abcdefghij' - self.pstl = dict() + self.start = 0.0 # test start + self.end = 0.0 # test end + self.tSuspended = 0.0 # low-level suspend start + self.tResumed = 0.0 # low-level resume start + self.tKernSus = 0.0 # kernel level suspend start + self.tKernRes = 0.0 # kernel level resume end + self.fwValid = False # is firmware data available + self.fwSuspend = 0 # time spent in firmware suspend + self.fwResume = 0 # time spent in firmware resume + self.html_device_id = 0 + self.stamp = 0 + self.outfile = '' + self.kerror = False + self.battery = 0 + self.enterfail = '' + self.currphase = '' + self.pstl = dict() # process timeline self.testnumber = num self.idstr = idchar[num] - self.dmesgtext = [] - self.phases = [] - self.dmesg = { # fixed list of 10 phases - 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#CCFFCC', 'order': 0}, - 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#88FF88', 'order': 1}, - 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#00AA00', 'order': 2}, - 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#008888', 'order': 3}, - 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#0000FF', 'order': 4}, - 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#FF0000', 'order': 5}, - 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#FF9900', 'order': 6}, - 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#FFCC00', 'order': 7}, - 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#FFFF88', 'order': 8}, - 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': '#FFFFCC', 'order': 9} - } - self.phases = self.sortedPhases() - self.devicegroups = [] - for phase in self.phases: - self.devicegroups.append([phase]) + self.dmesgtext = [] # dmesg text file in memory + self.dmesg = dict() # root data structure self.errorinfo = {'suspend':[],'resume':[]} + self.tLow = [] # time spent in low-level suspends (standby/freeze) + self.devpids = [] + self.devicegroups = 0 + def sortedPhases(self): + return sorted(self.dmesg, key=lambda k:self.dmesg[k]['order']) + def initDevicegroups(self): + # called when phases are all finished being added + for phase in self.dmesg.keys(): + if '*' in phase: + p = phase.split('*') + pnew = '%s%d' % (p[0], len(p)) + self.dmesg[pnew] = self.dmesg.pop(phase) + self.devicegroups = [] + for phase in self.sortedPhases(): + self.devicegroups.append([phase]) + def nextPhase(self, phase, offset): + order = self.dmesg[phase]['order'] + offset + for p in self.dmesg: + if self.dmesg[p]['order'] == order: + return p + return '' + def lastPhase(self): + plist = self.sortedPhases() + if len(plist) < 1: + return '' + return plist[-1] def extractErrorInfo(self): - elist = { - 'HWERROR' : '.*\[ *Hardware Error *\].*', - 'FWBUG' : '.*\[ *Firmware Bug *\].*', - 'BUG' : '.*BUG.*', - 'ERROR' : '.*ERROR.*', - 'WARNING' : '.*WARNING.*', - 'IRQ' : '.*genirq: .*', - 'TASKFAIL': '.*Freezing of tasks failed.*', - } lf = sysvals.openlog(sysvals.dmesgfile, 'r') i = 0 list = [] @@ -939,8 +989,8 @@ class Data: continue dir = 'suspend' if t < self.tSuspended else 'resume' msg = m.group('msg') - for err in elist: - if re.match(elist[err], msg): + for err in self.errlist: + if re.match(self.errlist[err], msg): list.append((err, dir, t, i, i)) self.kerror = True break @@ -956,7 +1006,7 @@ class Data: def setEnd(self, time): self.end = time def isTraceEventOutsideDeviceCalls(self, pid, time): - for phase in self.phases: + for phase in self.sortedPhases(): list = self.dmesg[phase]['list'] for dev in list: d = list[dev] @@ -964,16 +1014,10 @@ class Data: time < d['end']): return False return True - def phaseCollision(self, phase, isbegin, line): - key = 'end' - if isbegin: - key = 'start' - if self.dmesg[phase][key] >= 0: - sysvals.vprint('IGNORE: %s' % line.strip()) - return True - return False def sourcePhase(self, start): - for phase in self.phases: + for phase in self.sortedPhases(): + if 'machine' in phase: + continue pend = self.dmesg[phase]['end'] if start <= pend: return phase @@ -1004,14 +1048,15 @@ class Data: return tgtdev def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata): # try to place the call in a device - tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device') + phases = self.sortedPhases() + tgtdev = self.sourceDevice(phases, start, end, pid, 'device') # calls with device pids that occur outside device bounds are dropped # TODO: include these somehow if not tgtdev and pid in self.devpids: return False # try to place the call in a thread if not tgtdev: - tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread') + tgtdev = self.sourceDevice(phases, start, end, pid, 'thread') # create new thread blocks, expand as new calls are found if not tgtdev: if proc == '<...>': @@ -1053,7 +1098,7 @@ class Data: def overflowDevices(self): # get a list of devices that extend beyond the end of this test run devlist = [] - for phase in self.phases: + for phase in self.sortedPhases(): list = self.dmesg[phase]['list'] for devname in list: dev = list[devname] @@ -1064,7 +1109,7 @@ class Data: # merge any devices that overlap devlist for dev in devlist: devname = dev['name'] - for phase in self.phases: + for phase in self.sortedPhases(): list = self.dmesg[phase]['list'] if devname not in list: continue @@ -1079,7 +1124,7 @@ class Data: del list[devname] def usurpTouchingThread(self, name, dev): # the caller test has priority of this thread, give it to him - for phase in self.phases: + for phase in self.sortedPhases(): list = self.dmesg[phase]['list'] if name in list: tdev = list[name] @@ -1093,7 +1138,7 @@ class Data: break def stitchTouchingThreads(self, testlist): # merge any threads between tests that touch - for phase in self.phases: + for phase in self.sortedPhases(): list = self.dmesg[phase]['list'] for devname in list: dev = list[devname] @@ -1103,7 +1148,7 @@ class Data: data.usurpTouchingThread(devname, dev) def optimizeDevSrc(self): # merge any src call loops to reduce timeline size - for phase in self.phases: + for phase in self.sortedPhases(): list = self.dmesg[phase]['list'] for dev in list: if 'src' not in list[dev]: @@ -1141,7 +1186,7 @@ class Data: self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left) self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left) self.end = self.trimTimeVal(self.end, t0, dT, left) - for phase in self.phases: + for phase in self.sortedPhases(): p = self.dmesg[phase] p['start'] = self.trimTimeVal(p['start'], t0, dT, left) p['end'] = self.trimTimeVal(p['end'], t0, dT, left) @@ -1150,6 +1195,7 @@ class Data: d = list[name] d['start'] = self.trimTimeVal(d['start'], t0, dT, left) d['end'] = self.trimTimeVal(d['end'], t0, dT, left) + d['length'] = d['end'] - d['start'] if('ftrace' in d): cg = d['ftrace'] cg.start = self.trimTimeVal(cg.start, t0, dT, left) @@ -1166,30 +1212,51 @@ class Data: tm = self.trimTimeVal(tm, t0, dT, left) list.append((type, tm, idx1, idx2)) self.errorinfo[dir] = list - def normalizeTime(self, tZero): + def trimFreezeTime(self, tZero): # trim out any standby or freeze clock time - if(self.tSuspended != self.tResumed): - if(self.tResumed > tZero): - self.trimTime(self.tSuspended, \ - self.tResumed-self.tSuspended, True) - else: - self.trimTime(self.tSuspended, \ - self.tResumed-self.tSuspended, False) + lp = '' + for phase in self.sortedPhases(): + if 'resume_machine' in phase and 'suspend_machine' in lp: + tS, tR = self.dmesg[lp]['end'], self.dmesg[phase]['start'] + tL = tR - tS + if tL > 0: + left = True if tR > tZero else False + self.trimTime(tS, tL, left) + self.tLow.append('%.0f'%(tL*1000)) + lp = phase def getTimeValues(self): - sktime = (self.dmesg['suspend_machine']['end'] - \ - self.tKernSus) * 1000 - rktime = (self.dmesg['resume_complete']['end'] - \ - self.dmesg['resume_machine']['start']) * 1000 + sktime = (self.tSuspended - self.tKernSus) * 1000 + rktime = (self.tKernRes - self.tResumed) * 1000 return (sktime, rktime) - def setPhase(self, phase, ktime, isbegin): + def setPhase(self, phase, ktime, isbegin, order=-1): if(isbegin): + # phase start over current phase + if self.currphase: + if 'resume_machine' not in self.currphase: + sysvals.vprint('WARNING: phase %s failed to end' % self.currphase) + self.dmesg[self.currphase]['end'] = ktime + phases = self.dmesg.keys() + color = self.phasedef[phase]['color'] + count = len(phases) if order < 0 else order + # create unique name for every new phase + while phase in phases: + phase += '*' + self.dmesg[phase] = {'list': dict(), 'start': -1.0, 'end': -1.0, + 'row': 0, 'color': color, 'order': count} self.dmesg[phase]['start'] = ktime + self.currphase = phase else: + # phase end without a start + if phase not in self.currphase: + if self.currphase: + sysvals.vprint('WARNING: %s ended instead of %s, ftrace corruption?' % (phase, self.currphase)) + else: + sysvals.vprint('WARNING: %s ended without a start, ftrace corruption?' % phase) + return phase + phase = self.currphase self.dmesg[phase]['end'] = ktime - def dmesgSortVal(self, phase): - return self.dmesg[phase]['order'] - def sortedPhases(self): - return sorted(self.dmesg, key=self.dmesgSortVal) + self.currphase = '' + return phase def sortedDevices(self, phase): list = self.dmesg[phase]['list'] slist = [] @@ -1208,13 +1275,13 @@ class Data: for devname in phaselist: dev = phaselist[devname] if(dev['end'] < 0): - for p in self.phases: + for p in self.sortedPhases(): if self.dmesg[p]['end'] > dev['start']: dev['end'] = self.dmesg[p]['end'] break sysvals.vprint('%s (%s): callback didnt return' % (devname, phase)) def deviceFilter(self, devicefilter): - for phase in self.phases: + for phase in self.sortedPhases(): list = self.dmesg[phase]['list'] rmlist = [] for name in list: @@ -1229,7 +1296,7 @@ class Data: del list[name] def fixupInitcallsThatDidntReturn(self): # if any calls never returned, clip them at system resume end - for phase in self.phases: + for phase in self.sortedPhases(): self.fixupInitcalls(phase) def phaseOverlap(self, phases): rmgroups = [] @@ -1248,17 +1315,18 @@ class Data: self.devicegroups.append(newgroup) def newActionGlobal(self, name, start, end, pid=-1, color=''): # which phase is this device callback or action in + phases = self.sortedPhases() targetphase = 'none' htmlclass = '' overlap = 0.0 - phases = [] - for phase in self.phases: + myphases = [] + for phase in phases: pstart = self.dmesg[phase]['start'] pend = self.dmesg[phase]['end'] # see if the action overlaps this phase o = max(0, min(end, pend) - max(start, pstart)) if o > 0: - phases.append(phase) + myphases.append(phase) # set the target phase to the one that overlaps most if o > overlap: if overlap > 0 and phase == 'post_resume': @@ -1267,19 +1335,19 @@ class Data: overlap = o # if no target phase was found, pin it to the edge if targetphase == 'none': - p0start = self.dmesg[self.phases[0]]['start'] + p0start = self.dmesg[phases[0]]['start'] if start <= p0start: - targetphase = self.phases[0] + targetphase = phases[0] else: - targetphase = self.phases[-1] + targetphase = phases[-1] if pid == -2: htmlclass = ' bg' elif pid == -3: htmlclass = ' ps' - if len(phases) > 1: + if len(myphases) > 1: htmlclass = ' bg' - self.phaseOverlap(phases) - if targetphase in self.phases: + self.phaseOverlap(myphases) + if targetphase in phases: newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color) return (targetphase, newname) return False @@ -1311,19 +1379,43 @@ class Data: if(list[child]['par'] == devname): devlist.append(child) return devlist + def maxDeviceNameSize(self, phase): + size = 0 + for name in self.dmesg[phase]['list']: + if len(name) > size: + size = len(name) + return size def printDetails(self): sysvals.vprint('Timeline Details:') sysvals.vprint(' test start: %f' % self.start) sysvals.vprint('kernel suspend start: %f' % self.tKernSus) - for phase in self.phases: - dc = len(self.dmesg[phase]['list']) - sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \ - self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) + tS = tR = False + for phase in self.sortedPhases(): + devlist = self.dmesg[phase]['list'] + dc, ps, pe = len(devlist), self.dmesg[phase]['start'], self.dmesg[phase]['end'] + if not tS and ps >= self.tSuspended: + sysvals.vprint(' machine suspended: %f' % self.tSuspended) + tS = True + if not tR and ps >= self.tResumed: + sysvals.vprint(' machine resumed: %f' % self.tResumed) + tR = True + sysvals.vprint('%20s: %f - %f (%d devices)' % (phase, ps, pe, dc)) + if sysvals.devdump: + sysvals.vprint(''.join('-' for i in range(80))) + maxname = '%d' % self.maxDeviceNameSize(phase) + fmt = '%3d) %'+maxname+'s - %f - %f' + c = 1 + for name in devlist: + s = devlist[name]['start'] + e = devlist[name]['end'] + sysvals.vprint(fmt % (c, name, s, e)) + c += 1 + sysvals.vprint(''.join('-' for i in range(80))) sysvals.vprint(' kernel resume end: %f' % self.tKernRes) sysvals.vprint(' test end: %f' % self.end) def deviceChildrenAllPhases(self, devname): devlist = [] - for phase in self.phases: + for phase in self.sortedPhases(): list = self.deviceChildren(devname, phase) for dev in list: if dev not in devlist: @@ -1344,7 +1436,7 @@ class Data: if node.name: info = '' drv = '' - for phase in self.phases: + for phase in self.sortedPhases(): list = self.dmesg[phase]['list'] if node.name in list: s = list[node.name]['start'] @@ -1478,8 +1570,29 @@ class Data: c = self.addProcessUsageEvent(ps, tres) if c > 0: sysvals.vprint('%25s (res): %d' % (ps, c)) + def handleEndMarker(self, time): + dm = self.dmesg + self.setEnd(time) + self.initDevicegroups() + # give suspend_prepare an end if needed + if 'suspend_prepare' in dm and dm['suspend_prepare']['end'] < 0: + dm['suspend_prepare']['end'] = time + # assume resume machine ends at next phase start + if 'resume_machine' in dm and dm['resume_machine']['end'] < 0: + np = self.nextPhase('resume_machine', 1) + if np: + dm['resume_machine']['end'] = dm[np]['start'] + # if kernel resume end not found, assume its the end marker + if self.tKernRes == 0.0: + self.tKernRes = time + # if kernel suspend start not found, assume its the end marker + if self.tKernSus == 0.0: + self.tKernSus = time + # set resume complete to end at end marker + if 'resume_complete' in dm: + dm['resume_complete']['end'] = time def debugPrint(self): - for p in self.phases: + for p in self.sortedPhases(): list = self.dmesg[p]['list'] for devname in list: dev = list[devname] @@ -1490,9 +1603,9 @@ class Data: # Description: # A container for kprobe function data we want in the dev timeline class DevFunction: - row = 0 - count = 1 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color): + self.row = 0 + self.count = 1 self.name = name self.args = args self.caller = caller @@ -1546,16 +1659,15 @@ class DevFunction: # suspend_resume: phase or custom exec block data # device_pm_callback: device callback info class FTraceLine: - time = 0.0 - length = 0.0 - fcall = False - freturn = False - fevent = False - fkprobe = False - depth = 0 - name = '' - type = '' def __init__(self, t, m='', d=''): + self.length = 0.0 + self.fcall = False + self.freturn = False + self.fevent = False + self.fkprobe = False + self.depth = 0 + self.name = '' + self.type = '' self.time = float(t) if not m and not d: return @@ -1633,13 +1745,13 @@ class FTraceLine: return len(str)/2 def debugPrint(self, info=''): if self.isLeaf(): - print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \ + pprint(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \ self.depth, self.name, self.length*1000000, info)) elif self.freturn: - print(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \ + pprint(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \ self.depth, self.name, self.length*1000000, info)) else: - print(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \ + pprint(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \ self.depth, self.name, self.length*1000000, info)) def startMarker(self): # Is this the starting line of a suspend? @@ -1675,19 +1787,13 @@ class FTraceLine: # Each instance is tied to a single device in a single phase, and is # comprised of an ordered list of FTraceLine objects class FTraceCallGraph: - id = '' - start = -1.0 - end = -1.0 - list = [] - invalid = False - depth = 0 - pid = 0 - name = '' - partial = False vfname = 'missing_function_name' - ignore = False - sv = 0 def __init__(self, pid, sv): + self.id = '' + self.invalid = False + self.name = '' + self.partial = False + self.ignore = False self.start = -1.0 self.end = -1.0 self.list = [] @@ -1786,7 +1892,7 @@ class FTraceCallGraph: if warning and ('[make leaf]', line) not in info: info.append(('', line)) if warning: - print 'WARNING: ftrace data missing, corrections made:' + pprint('WARNING: ftrace data missing, corrections made:') for i in info: t, obj = i if obj: @@ -1846,10 +1952,10 @@ class FTraceCallGraph: id = 'task %s' % (self.pid) window = '(%f - %f)' % (self.start, line.time) if(self.depth < 0): - print('Data misalignment for '+id+\ + pprint('Data misalignment for '+id+\ ' (buffer overflow), ignoring this callback') else: - print('Too much data for '+id+\ + pprint('Too much data for '+id+\ ' '+window+', ignoring this callback') def slice(self, dev): minicg = FTraceCallGraph(dev['pid'], self.sv) @@ -1902,7 +2008,7 @@ class FTraceCallGraph: elif l.isReturn(): if(l.depth not in stack): if self.sv.verbose: - print 'Post Process Error: Depth missing' + pprint('Post Process Error: Depth missing') l.debugPrint() return False # calculate call length from call/return lines @@ -1919,7 +2025,7 @@ class FTraceCallGraph: return True elif(cnt < 0): if self.sv.verbose: - print 'Post Process Error: Depth is less than 0' + pprint('Post Process Error: Depth is less than 0') return False # trace ended before call tree finished return self.repair(cnt) @@ -1943,7 +2049,7 @@ class FTraceCallGraph: dev['ftrace'] = cg found = devname return found - for p in data.phases: + for p in data.sortedPhases(): if(data.dmesg[p]['start'] <= self.start and self.start <= data.dmesg[p]['end']): list = data.dmesg[p]['list'] @@ -1966,7 +2072,7 @@ class FTraceCallGraph: if fs < data.start or fe > data.end: return phase = '' - for p in data.phases: + for p in data.sortedPhases(): if(data.dmesg[p]['start'] <= self.start and self.start < data.dmesg[p]['end']): phase = p @@ -1978,20 +2084,20 @@ class FTraceCallGraph: phase, myname = out data.dmesg[phase]['list'][myname]['ftrace'] = self def debugPrint(self, info=''): - print('%s pid=%d [%f - %f] %.3f us') % \ + pprint('%s pid=%d [%f - %f] %.3f us' % \ (self.name, self.pid, self.start, self.end, - (self.end - self.start)*1000000) + (self.end - self.start)*1000000)) for l in self.list: if l.isLeaf(): - print('%f (%02d): %s(); (%.3f us)%s' % (l.time, \ + pprint('%f (%02d): %s(); (%.3f us)%s' % (l.time, \ l.depth, l.name, l.length*1000000, info)) elif l.freturn: - print('%f (%02d): %s} (%.3f us)%s' % (l.time, \ + pprint('%f (%02d): %s} (%.3f us)%s' % (l.time, \ l.depth, l.name, l.length*1000000, info)) else: - print('%f (%02d): %s() { (%.3f us)%s' % (l.time, \ + pprint('%f (%02d): %s() { (%.3f us)%s' % (l.time, \ l.depth, l.name, l.length*1000000, info)) - print(' ') + pprint(' ') class DevItem: def __init__(self, test, phase, dev): @@ -2008,23 +2114,20 @@ class DevItem: # A container for a device timeline which calculates # all the html properties to display it correctly class Timeline: - html = '' - height = 0 # total timeline height - scaleH = 20 # timescale (top) row height - rowH = 30 # device row height - bodyH = 0 # body height - rows = 0 # total timeline rows - rowlines = dict() - rowheight = dict() html_tblock = '
\n' html_device = '
{6}
\n' html_phase = '
{5}
\n' html_phaselet = '
\n' html_legend = '
 {2}
\n' def __init__(self, rowheight, scaleheight): - self.rowH = rowheight - self.scaleH = scaleheight self.html = '' + self.height = 0 # total timeline height + self.scaleH = scaleheight # timescale (top) row height + self.rowH = rowheight # device row height + self.bodyH = 0 # body height + self.rows = 0 # total timeline rows + self.rowlines = dict() + self.rowheight = dict() def createHeader(self, sv, stamp): if(not stamp['time']): return @@ -2251,18 +2354,18 @@ class Timeline: # Description: # A list of values describing the properties of these test runs class TestProps: - stamp = '' - sysinfo = '' - cmdline = '' - kparams = '' - S0i3 = False - fwdata = [] stampfmt = '# [a-z]*-(?P[0-9]{2})(?P[0-9]{2})(?P[0-9]{2})-'+\ '(?P[0-9]{2})(?P[0-9]{2})(?P[0-9]{2})'+\ ' (?P.*) (?P.*) (?P.*)$' + batteryfmt = '^# battery (?P\w*) (?P\d*) (?P\w*) (?P\d*)' + testerrfmt = '^# enter_sleep_error (?P.*)' sysinfofmt = '^# sysinfo .*' cmdlinefmt = '^# command \| (?P.*)' kparamsfmt = '^# kparams \| (?P.*)' + devpropfmt = '# Device Properties: .*' + tracertypefmt = '# tracer: (?P.*)' + firmwarefmt = '# fwsuspend (?P[0-9]*) fwresume (?P[0-9]*)$' + procexecfmt = 'ps - (?P.*)$' ftrace_line_fmt_fg = \ '^ *(?P