| Message ID | 1367360914-23389-2-git-send-email-zoran.markovic@linaro.org (mailing list archive) |
|---|---|
| State | RFC, archived |
| Headers | show |
Hi! > From: Colin Cross <ccross@android.com> > > Below is a patch from android kernel that maintains a histogram of > suspend times. Please review and provide feedback. > > Prints the time spent in suspend in the kernel log, and keeps statistics > on the time spent in suspend in /sys/kernel/debug/suspend_time > > Cc: Android Kernel Team <kernel-team@android.com> > Cc: Colin Cross <ccross@android.com> > Cc: Todd Poynor <toddpoynor@google.com> > Cc: San Mehat <san@google.com> > Cc: Benoit Goby <benoit@android.com> > Cc: John Stultz <john.stultz@linaro.org> > Cc: Pavel Machek <pavel@ucw.cz> > Cc: Rafael J. Wysocki <rjw@sisk.pl> > Cc: Len Brown <len.brown@intel.com> > Signed-off-by: Colin Cross <ccross@android.com> > Signed-off-by: Todd Poynor <toddpoynor@google.com> > [zoran.markovic@linaro.org: Re-formatted suspend time table to better fit > expected values, tweaked commit message] > Signed-off-by: Zoran Markovic <zoran.markovic@linaro.org> > +++ b/kernel/power/suspend_time.c > @@ -0,0 +1,111 @@ > +/* > + * debugfs file to track time spent in suspend > + * > + * Copyright (c) 2011, Google, Inc. > + * > + * This program is free software; you can redistribute it and/or modify > + * it under the terms of the GNU General Public License as published by > + * the Free Software Foundation; either version 2 of the License, or > + * (at your option) any later version. > + * > + * This program is distributed in the hope that it will be useful, but WITHOUT > + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or > + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for > + * more details. > + */ > + > +#include <linux/debugfs.h> > +#include <linux/err.h> > +#include <linux/init.h> > +#include <linux/kernel.h> > +#include <linux/seq_file.h> > +#include <linux/syscore_ops.h> > +#include <linux/time.h> > + > +static struct timespec suspend_time_before; > +static unsigned int time_in_suspend_bins[32]; > + > +#ifdef CONFIG_DEBUG_FS > +static int suspend_time_debug_show(struct seq_file *s, void *data) > +{ > + unsigned int bin; > + seq_printf(s, " time (secs) count\n"); > + seq_printf(s, "------------------------------\n"); > + for (bin = 0; bin < 32; bin++) { > + if (time_in_suspend_bins[bin] == 0) > + continue; > + seq_printf(s, "%10u - %-10u %4u\n", > + bin ? 1 << (bin - 1) : 0, 1 << bin, > + time_in_suspend_bins[bin]); > + } > + return 0; > +} > + > +static int suspend_time_debug_open(struct inode *inode, struct file *file) > +{ > + return single_open(file, suspend_time_debug_show, NULL); > +} Ok, whole new driver to get timing info... As we already have times in printk, can't existing printks() get the same info? Maybe Documentation/ file describing how to get that info from dmesg would be enough?
On Tue, Apr 30, 2013 at 5:29 PM, Pavel Machek <pavel@ucw.cz> wrote: > Hi! > >> From: Colin Cross <ccross@android.com> >> >> Below is a patch from android kernel that maintains a histogram of >> suspend times. Please review and provide feedback. >> >> Prints the time spent in suspend in the kernel log, and keeps statistics >> on the time spent in suspend in /sys/kernel/debug/suspend_time >> >> Cc: Android Kernel Team <kernel-team@android.com> >> Cc: Colin Cross <ccross@android.com> >> Cc: Todd Poynor <toddpoynor@google.com> >> Cc: San Mehat <san@google.com> >> Cc: Benoit Goby <benoit@android.com> >> Cc: John Stultz <john.stultz@linaro.org> >> Cc: Pavel Machek <pavel@ucw.cz> >> Cc: Rafael J. Wysocki <rjw@sisk.pl> >> Cc: Len Brown <len.brown@intel.com> >> Signed-off-by: Colin Cross <ccross@android.com> >> Signed-off-by: Todd Poynor <toddpoynor@google.com> >> [zoran.markovic@linaro.org: Re-formatted suspend time table to better fit >> expected values, tweaked commit message] >> Signed-off-by: Zoran Markovic <zoran.markovic@linaro.org> > >> +++ b/kernel/power/suspend_time.c >> @@ -0,0 +1,111 @@ >> +/* >> + * debugfs file to track time spent in suspend >> + * >> + * Copyright (c) 2011, Google, Inc. >> + * >> + * This program is free software; you can redistribute it and/or modify >> + * it under the terms of the GNU General Public License as published by >> + * the Free Software Foundation; either version 2 of the License, or >> + * (at your option) any later version. >> + * >> + * This program is distributed in the hope that it will be useful, but WITHOUT >> + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or >> + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for >> + * more details. >> + */ >> + >> +#include <linux/debugfs.h> >> +#include <linux/err.h> >> +#include <linux/init.h> >> +#include <linux/kernel.h> >> +#include <linux/seq_file.h> >> +#include <linux/syscore_ops.h> >> +#include <linux/time.h> >> + >> +static struct timespec suspend_time_before; >> +static unsigned int time_in_suspend_bins[32]; >> + >> +#ifdef CONFIG_DEBUG_FS >> +static int suspend_time_debug_show(struct seq_file *s, void *data) >> +{ >> + unsigned int bin; >> + seq_printf(s, " time (secs) count\n"); >> + seq_printf(s, "------------------------------\n"); >> + for (bin = 0; bin < 32; bin++) { >> + if (time_in_suspend_bins[bin] == 0) >> + continue; >> + seq_printf(s, "%10u - %-10u %4u\n", >> + bin ? 1 << (bin - 1) : 0, 1 << bin, >> + time_in_suspend_bins[bin]); >> + } >> + return 0; >> +} >> + >> +static int suspend_time_debug_open(struct inode *inode, struct file *file) >> +{ >> + return single_open(file, suspend_time_debug_show, NULL); >> +} > > Ok, whole new driver to get timing info... As we already have times in > printk, can't existing printks() get the same info? Maybe > Documentation/ file describing how to get that info from dmesg would > be enough? If this were to be merged I assume it would be rewritten directly into kernel/power/suspend.c instead of using syscore ops. That was just done to ease future merges while it was out of tree. dmesg is not the solution, it's not a stable api, it would require constant parsing to make sure you didn't miss data before it fell out of the ringbuffer, and sched_clock often does not (and should not) tick during suspend, so printk times don't show the time spent suspended. -- To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Hi! > >> +#include <linux/debugfs.h> > >> +#include <linux/err.h> > >> +#include <linux/init.h> > >> +#include <linux/kernel.h> > >> +#include <linux/seq_file.h> > >> +#include <linux/syscore_ops.h> > >> +#include <linux/time.h> > >> + > >> +static struct timespec suspend_time_before; > >> +static unsigned int time_in_suspend_bins[32]; > >> + > >> +#ifdef CONFIG_DEBUG_FS > >> +static int suspend_time_debug_show(struct seq_file *s, void *data) > >> +{ > >> + unsigned int bin; > >> + seq_printf(s, " time (secs) count\n"); > >> + seq_printf(s, "------------------------------\n"); > >> + for (bin = 0; bin < 32; bin++) { > >> + if (time_in_suspend_bins[bin] == 0) > >> + continue; > >> + seq_printf(s, "%10u - %-10u %4u\n", > >> + bin ? 1 << (bin - 1) : 0, 1 << bin, > >> + time_in_suspend_bins[bin]); > >> + } > >> + return 0; > >> +} > >> + > >> +static int suspend_time_debug_open(struct inode *inode, struct file *file) > >> +{ > >> + return single_open(file, suspend_time_debug_show, NULL); > >> +} > > > > Ok, whole new driver to get timing info... As we already have times in > > printk, can't existing printks() get the same info? Maybe > > Documentation/ file describing how to get that info from dmesg would > > be enough? > > If this were to be merged I assume it would be rewritten directly into > kernel/power/suspend.c instead of using syscore ops. That was just > done to ease future merges while it was out of tree. > > dmesg is not the solution, it's not a stable api, it would require > constant parsing to make sure you didn't miss data before it fell out > of the ringbuffer, and sched_clock often does not (and should not) > tick during suspend, so printk times don't show the time spent > suspended. If timing info printed is invalid, that should be fixed. Pavel
On Thu, May 2, 2013 at 5:27 AM, Pavel Machek <pavel@ucw.cz> wrote: > Hi! > >> >> +#include <linux/debugfs.h> >> >> +#include <linux/err.h> >> >> +#include <linux/init.h> >> >> +#include <linux/kernel.h> >> >> +#include <linux/seq_file.h> >> >> +#include <linux/syscore_ops.h> >> >> +#include <linux/time.h> >> >> + >> >> +static struct timespec suspend_time_before; >> >> +static unsigned int time_in_suspend_bins[32]; >> >> + >> >> +#ifdef CONFIG_DEBUG_FS >> >> +static int suspend_time_debug_show(struct seq_file *s, void *data) >> >> +{ >> >> + unsigned int bin; >> >> + seq_printf(s, " time (secs) count\n"); >> >> + seq_printf(s, "------------------------------\n"); >> >> + for (bin = 0; bin < 32; bin++) { >> >> + if (time_in_suspend_bins[bin] == 0) >> >> + continue; >> >> + seq_printf(s, "%10u - %-10u %4u\n", >> >> + bin ? 1 << (bin - 1) : 0, 1 << bin, >> >> + time_in_suspend_bins[bin]); >> >> + } >> >> + return 0; >> >> +} >> >> + >> >> +static int suspend_time_debug_open(struct inode *inode, struct file *file) >> >> +{ >> >> + return single_open(file, suspend_time_debug_show, NULL); >> >> +} >> > >> > Ok, whole new driver to get timing info... As we already have times in >> > printk, can't existing printks() get the same info? Maybe >> > Documentation/ file describing how to get that info from dmesg would >> > be enough? >> >> If this were to be merged I assume it would be rewritten directly into >> kernel/power/suspend.c instead of using syscore ops. That was just >> done to ease future merges while it was out of tree. >> >> dmesg is not the solution, it's not a stable api, it would require >> constant parsing to make sure you didn't miss data before it fell out >> of the ringbuffer, and sched_clock often does not (and should not) >> tick during suspend, so printk times don't show the time spent >> suspended. > > If timing info printed is invalid, that should be fixed. It's not invalid, its just not measuring the time that is useful here. printk is measuring something similar to (but not exactly the same as) CLOCK_MONOTONIC, but this is measuring something similar to CLOCK_BOOTTIME. -- To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On 05/02/2013 11:29 AM, Colin Cross wrote: > On Thu, May 2, 2013 at 5:27 AM, Pavel Machek <pavel@ucw.cz> wrote: >> >>> dmesg is not the solution, it's not a stable api, it would require >>> constant parsing to make sure you didn't miss data before it fell out >>> of the ringbuffer, and sched_clock often does not (and should not) >>> tick during suspend, so printk times don't show the time spent >>> suspended. >> If timing info printed is invalid, that should be fixed. > It's not invalid, its just not measuring the time that is useful here. > printk is measuring something similar to (but not exactly the same > as) CLOCK_MONOTONIC, but this is measuring something similar to > CLOCK_BOOTTIME. One thing I'm curious about with this patch, since we measure and keep track of suspend time in the timekeeping core, there may be enough justification to adding this sort of debugging info the timekeeping core itself. Although what is being tracked with this driver isn't just total time in suspend, but looks like more of a logarithmic histogram of suspend times. Is there any context you can provide as to why that particular format was chosen (which would could be added to help improve the commit message)? thanks -john -- To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, May 2, 2013 at 11:58 AM, John Stultz <john.stultz@linaro.org> wrote: > On 05/02/2013 11:29 AM, Colin Cross wrote: >> >> On Thu, May 2, 2013 at 5:27 AM, Pavel Machek <pavel@ucw.cz> wrote: >>> >>> >>>> dmesg is not the solution, it's not a stable api, it would require >>>> constant parsing to make sure you didn't miss data before it fell out >>>> of the ringbuffer, and sched_clock often does not (and should not) >>>> tick during suspend, so printk times don't show the time spent >>>> suspended. >>> >>> If timing info printed is invalid, that should be fixed. >> >> It's not invalid, its just not measuring the time that is useful here. >> printk is measuring something similar to (but not exactly the same >> as) CLOCK_MONOTONIC, but this is measuring something similar to >> CLOCK_BOOTTIME. > > > One thing I'm curious about with this patch, since we measure and keep track > of suspend time in the timekeeping core, there may be enough justification > to adding this sort of debugging info the timekeeping core itself. > > Although what is being tracked with this driver isn't just total time in > suspend, but looks like more of a logarithmic histogram of suspend times. Is > there any context you can provide as to why that particular format was > chosen (which would could be added to help improve the commit message)? The idea was to keep a minimal amount of data while still being able to see how often the device is waking up. -- To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
diff --git a/kernel/power/Kconfig b/kernel/power/Kconfig index 5dfdc9e..edc8bdd 100644 --- a/kernel/power/Kconfig +++ b/kernel/power/Kconfig @@ -274,3 +274,10 @@ config PM_GENERIC_DOMAINS_RUNTIME config CPU_PM bool depends on SUSPEND || CPU_IDLE + +config SUSPEND_TIME + bool "Log time spent in suspend" + ---help--- + Prints the time spent in suspend in the kernel log, and + keeps statistics on the time spent in suspend in + /sys/kernel/debug/suspend_time diff --git a/kernel/power/Makefile b/kernel/power/Makefile index 29472bf..578e20e 100644 --- a/kernel/power/Makefile +++ b/kernel/power/Makefile @@ -11,5 +11,6 @@ obj-$(CONFIG_HIBERNATION) += hibernate.o snapshot.o swap.o user.o \ block_io.o obj-$(CONFIG_PM_AUTOSLEEP) += autosleep.o obj-$(CONFIG_PM_WAKELOCKS) += wakelock.o +obj-$(CONFIG_SUSPEND_TIME) += suspend_time.o obj-$(CONFIG_MAGIC_SYSRQ) += poweroff.o diff --git a/kernel/power/suspend_time.c b/kernel/power/suspend_time.c new file mode 100644 index 0000000..a613ede --- /dev/null +++ b/kernel/power/suspend_time.c @@ -0,0 +1,111 @@ +/* + * debugfs file to track time spent in suspend + * + * Copyright (c) 2011, Google, Inc. + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation; either version 2 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for + * more details. + */ + +#include <linux/debugfs.h> +#include <linux/err.h> +#include <linux/init.h> +#include <linux/kernel.h> +#include <linux/seq_file.h> +#include <linux/syscore_ops.h> +#include <linux/time.h> + +static struct timespec suspend_time_before; +static unsigned int time_in_suspend_bins[32]; + +#ifdef CONFIG_DEBUG_FS +static int suspend_time_debug_show(struct seq_file *s, void *data) +{ + unsigned int bin; + seq_printf(s, " time (secs) count\n"); + seq_printf(s, "------------------------------\n"); + for (bin = 0; bin < 32; bin++) { + if (time_in_suspend_bins[bin] == 0) + continue; + seq_printf(s, "%10u - %-10u %4u\n", + bin ? 1 << (bin - 1) : 0, 1 << bin, + time_in_suspend_bins[bin]); + } + return 0; +} + +static int suspend_time_debug_open(struct inode *inode, struct file *file) +{ + return single_open(file, suspend_time_debug_show, NULL); +} + +static const struct file_operations suspend_time_debug_fops = { + .open = suspend_time_debug_open, + .read = seq_read, + .llseek = seq_lseek, + .release = single_release, +}; + +static int __init suspend_time_debug_init(void) +{ + struct dentry *d; + + d = debugfs_create_file("suspend_time", 0444, NULL, NULL, + &suspend_time_debug_fops); + if (!d) { + pr_err("Failed to create suspend_time debug file\n"); + return -ENOMEM; + } + + return 0; +} + +late_initcall(suspend_time_debug_init); +#endif + +static int suspend_time_syscore_suspend(void) +{ + read_persistent_clock(&suspend_time_before); + + return 0; +} + +static void suspend_time_syscore_resume(void) +{ + struct timespec after; + + read_persistent_clock(&after); + + after = timespec_sub(after, suspend_time_before); + + time_in_suspend_bins[fls(after.tv_sec)]++; + + pr_info("Suspended for %lu.%03lu seconds\n", after.tv_sec, + after.tv_nsec / NSEC_PER_MSEC); +} + +static struct syscore_ops suspend_time_syscore_ops = { + .suspend = suspend_time_syscore_suspend, + .resume = suspend_time_syscore_resume, +}; + +static int suspend_time_syscore_init(void) +{ + register_syscore_ops(&suspend_time_syscore_ops); + + return 0; +} + +static void suspend_time_syscore_exit(void) +{ + unregister_syscore_ops(&suspend_time_syscore_ops); +} +module_init(suspend_time_syscore_init); +module_exit(suspend_time_syscore_exit);