* [GIT PULL][PATCH 0/7] Timekeeping changes for 4.10 (take 2) @ 2016-11-28 22:35 John Stultz 2016-11-28 22:35 ` [PATCH 1/7] selftests/timers: Fix spelling mistake "Asyncrhonous" -> "Asynchronous" John Stultz ` (6 more replies) 0 siblings, 7 replies; 29+ messages in thread From: John Stultz @ 2016-11-28 22:35 UTC (permalink / raw) To: lkml Cc: John Stultz, Richard Cochran, Ingo Molnar, Prarit Bhargava, Thomas Gleixner Hey Thomas, Ingo, Just wanted to resend my patch queue for 4.10, including changes from the last submission suggested by Ingo and some additional changes from Joel to add extra a boot trace clock. Let me know if you have any comments or objections. thanks -john Cc: Richard Cochran <richardcochran@gmail.com> Cc: Ingo Molnar <mingo@kernel.org> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Thomas Gleixner <tglx@linutronix.de> The following changes since commit a909d3e636995ba7c349e2ca5dbb528154d4ac30: Linux 4.9-rc3 (2016-10-29 13:52:02 -0700) are available in the git repository at: https://git.linaro.org/people/john.stultz/linux.git fortglx/4.10/time for you to fetch changes up to 6ade3fa56aa5a0a3339caa8c1c268d19982101e3: trace: Update documentation for mono, mono_raw and boot clock (2016-11-28 14:28:39 -0800) ---------------------------------------------------------------- Baolin Wang (1): time: alarmtimer: Add the tracepoints for alarmtimer Chen Yu (1): timekeeping: Ignore the bogus sleep time if pm_trace is enabled Chris Metcalf (1): timekeeping: clocksource_cyc2ns: Document intended range limitation Colin Ian King (1): selftests/timers: Fix spelling mistake "Asyncrhonous" -> "Asynchronous" Joel Fernandes (3): timekeeping: Add a fast and NMI safe boot clock trace: Add an option for boot clock as trace clock trace: Update documentation for mono, mono_raw and boot clock Documentation/trace/ftrace.txt | 20 +++++ arch/x86/kernel/rtc.c | 9 +++ drivers/base/power/trace.c | 26 +++++++ drivers/rtc/rtc-cmos.c | 7 ++ include/linux/clocksource.h | 5 +- include/linux/mc146818rtc.h | 1 + include/linux/pm-trace.h | 9 ++- include/linux/timekeeping.h | 1 + include/trace/events/alarmtimer.h | 92 +++++++++++++++++++++++ kernel/time/alarmtimer.c | 16 +++- kernel/time/timekeeping.c | 29 +++++++ kernel/trace/trace.c | 1 + tools/testing/selftests/timers/skew_consistency.c | 2 +- 13 files changed, 213 insertions(+), 5 deletions(-) create mode 100644 include/trace/events/alarmtimer.h -- 2.7.4 ^ permalink raw reply [flat|nested] 29+ messages in thread
* [PATCH 1/7] selftests/timers: Fix spelling mistake "Asyncrhonous" -> "Asynchronous" 2016-11-28 22:35 [GIT PULL][PATCH 0/7] Timekeeping changes for 4.10 (take 2) John Stultz @ 2016-11-28 22:35 ` John Stultz 2016-11-29 17:10 ` [tip:timers/core] " tip-bot for Colin Ian King 2016-11-28 22:35 ` [PATCH 2/7] timekeeping: Ignore the bogus sleep time if pm_trace is enabled John Stultz ` (5 subsequent siblings) 6 siblings, 1 reply; 29+ messages in thread From: John Stultz @ 2016-11-28 22:35 UTC (permalink / raw) To: lkml Cc: Colin Ian King, Thomas Gleixner, Richard Cochran, Ingo Molnar, Shuah Khan, Prarit Bhargava, John Stultz From: Colin Ian King <colin.king@canonical.com> Trivial fix to spelling mistake Cc: Thomas Gleixner <tglx@linutronix.de> Cc: Richard Cochran <richardcochran@gmail.com> Cc: Ingo Molnar <mingo@kernel.org> Cc: Shuah Khan <shuah@kernel.org> Cc: Prarit Bhargava <prarit@redhat.com> Signed-off-by: Colin Ian King <colin.king@canonical.com> Signed-off-by: John Stultz <john.stultz@linaro.org> --- tools/testing/selftests/timers/skew_consistency.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/testing/selftests/timers/skew_consistency.c b/tools/testing/selftests/timers/skew_consistency.c index 5562f84..2a996e0 100644 --- a/tools/testing/selftests/timers/skew_consistency.c +++ b/tools/testing/selftests/timers/skew_consistency.c @@ -57,7 +57,7 @@ int main(int argv, char **argc) pid_t pid; - printf("Running Asyncrhonous Frequency Changing Tests...\n"); + printf("Running Asynchronous Frequency Changing Tests...\n"); pid = fork(); if (!pid) -- 2.7.4 ^ permalink raw reply related [flat|nested] 29+ messages in thread
* [tip:timers/core] selftests/timers: Fix spelling mistake "Asyncrhonous" -> "Asynchronous" 2016-11-28 22:35 ` [PATCH 1/7] selftests/timers: Fix spelling mistake "Asyncrhonous" -> "Asynchronous" John Stultz @ 2016-11-29 17:10 ` tip-bot for Colin Ian King 0 siblings, 0 replies; 29+ messages in thread From: tip-bot for Colin Ian King @ 2016-11-29 17:10 UTC (permalink / raw) To: linux-tip-commits Cc: linux-kernel, richardcochran, hpa, john.stultz, shuah, prarit, tglx, mingo, colin.king Commit-ID: a109ded26c8c85c17872c8f61e8979c5d650004d Gitweb: http://git.kernel.org/tip/a109ded26c8c85c17872c8f61e8979c5d650004d Author: Colin Ian King <colin.king@canonical.com> AuthorDate: Mon, 28 Nov 2016 14:35:18 -0800 Committer: Thomas Gleixner <tglx@linutronix.de> CommitDate: Tue, 29 Nov 2016 18:02:57 +0100 selftests/timers: Fix spelling mistake "Asyncrhonous" -> "Asynchronous" Trivial fix to spelling mistake Signed-off-by: Colin Ian King <colin.king@canonical.com> Signed-off-by: John Stultz <john.stultz@linaro.org> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Cc: Shuah Khan <shuah@kernel.org> Link: http://lkml.kernel.org/r/1480372524-15181-2-git-send-email-john.stultz@linaro.org Signed-off-by: Thomas Gleixner <tglx@linutronix.de> --- tools/testing/selftests/timers/skew_consistency.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/testing/selftests/timers/skew_consistency.c b/tools/testing/selftests/timers/skew_consistency.c index 5562f84..2a996e0 100644 --- a/tools/testing/selftests/timers/skew_consistency.c +++ b/tools/testing/selftests/timers/skew_consistency.c @@ -57,7 +57,7 @@ int main(int argv, char **argc) pid_t pid; - printf("Running Asyncrhonous Frequency Changing Tests...\n"); + printf("Running Asynchronous Frequency Changing Tests...\n"); pid = fork(); if (!pid) ^ permalink raw reply related [flat|nested] 29+ messages in thread
* [PATCH 2/7] timekeeping: Ignore the bogus sleep time if pm_trace is enabled 2016-11-28 22:35 [GIT PULL][PATCH 0/7] Timekeeping changes for 4.10 (take 2) John Stultz 2016-11-28 22:35 ` [PATCH 1/7] selftests/timers: Fix spelling mistake "Asyncrhonous" -> "Asynchronous" John Stultz @ 2016-11-28 22:35 ` John Stultz 2016-11-29 7:19 ` Ingo Molnar 2016-11-29 17:10 ` [tip:timers/core] " tip-bot for Chen Yu 2016-11-28 22:35 ` [PATCH 3/7] timekeeping: clocksource_cyc2ns: Document intended range limitation John Stultz ` (4 subsequent siblings) 6 siblings, 2 replies; 29+ messages in thread From: John Stultz @ 2016-11-28 22:35 UTC (permalink / raw) To: lkml Cc: Chen Yu, Rafael J. Wysocki, John Stultz, Xunlei Pang, Ingo Molnar, Len Brown, H. Peter Anvin, Pavel Machek, Thomas Gleixner, Prarit Bhargava, Richard Cochran From: Chen Yu <yu.c.chen@intel.com> Previously we encountered some memory overflow issues due to the bogus sleep time brought by inconsistent rtc, which is triggered when pm_trace is enabled, and we have fixed it in recent kernel. However it's improper in the first place to call __timekeeping_inject_sleeptime() in case that pm_trace is enabled simply because that "hash" time value will wreckage the timekeeping subsystem. This patch is originally written by Thomas, which would bypass the bogus rtc interval when pm_trace is enabled. Meanwhile, if system succeed to resume back with pm_trace set, the users are warned to adjust the bogus rtc either by 'ntpdate' or 'rdate', by resetting pm_trace_rtc_abused to false, otherwise above tools might not work as expected. Originally-from: Thomas Gleixner <tglx@linutronix.de> Cc: "Rafael J. Wysocki" <rjw@rjwysocki.net> Cc: John Stultz <john.stultz@linaro.org> Cc: Xunlei Pang <xlpang@redhat.com> Cc: Ingo Molnar <mingo@redhat.com> Cc: Len Brown <lenb@kernel.org> Cc: "H. Peter Anvin" <hpa@zytor.com> Cc: Pavel Machek <pavel@ucw.cz> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Acked-by: Pavel Machek <pavel@ucw.cz> Acked-by: Thomas Gleixner <tglx@linutronix.de> Signed-off-by: Chen Yu <yu.c.chen@intel.com> [jstultz: Fixed up pr_warn formating, and implemented suggestions from Ingo] Signed-off-by: John Stultz <john.stultz@linaro.org> --- v2: Added suggestions from Ingo --- arch/x86/kernel/rtc.c | 9 +++++++++ drivers/base/power/trace.c | 26 ++++++++++++++++++++++++++ drivers/rtc/rtc-cmos.c | 7 +++++++ include/linux/mc146818rtc.h | 1 + include/linux/pm-trace.h | 9 ++++++++- 5 files changed, 51 insertions(+), 1 deletion(-) diff --git a/arch/x86/kernel/rtc.c b/arch/x86/kernel/rtc.c index 79c6311c..3282a88 100644 --- a/arch/x86/kernel/rtc.c +++ b/arch/x86/kernel/rtc.c @@ -64,6 +64,15 @@ void mach_get_cmos_time(struct timespec *now) unsigned int status, year, mon, day, hour, min, sec, century = 0; unsigned long flags; + /* + * If pm_trace abused the RTC as storage set the timespec to 0 + * which tells the caller that this RTC value is bogus. + */ + if (!pm_trace_rtc_valid()) { + now->tv_sec = now->tv_nsec = 0; + return; + } + spin_lock_irqsave(&rtc_lock, flags); /* diff --git a/drivers/base/power/trace.c b/drivers/base/power/trace.c index efec10b..15563c4 100644 --- a/drivers/base/power/trace.c +++ b/drivers/base/power/trace.c @@ -10,6 +10,7 @@ #include <linux/pm-trace.h> #include <linux/export.h> #include <linux/rtc.h> +#include <linux/suspend.h> #include <linux/mc146818rtc.h> @@ -74,6 +75,9 @@ #define DEVSEED (7919) +bool pm_trace_rtc_abused __read_mostly; +EXPORT_SYMBOL(pm_trace_rtc_abused); + static unsigned int dev_hash_value; static int set_magic_time(unsigned int user, unsigned int file, unsigned int device) @@ -104,6 +108,7 @@ static int set_magic_time(unsigned int user, unsigned int file, unsigned int dev time.tm_min = (n % 20) * 3; n /= 20; mc146818_set_time(&time); + pm_trace_rtc_abused = true; return n ? -1 : 0; } @@ -238,10 +243,31 @@ int show_trace_dev_match(char *buf, size_t size) device_pm_unlock(); return ret; } +static int pm_trace_notify(struct notifier_block *nb, + unsigned long mode, void *_unused) +{ + switch (mode) { + case PM_POST_HIBERNATION: + case PM_POST_SUSPEND: + if (pm_trace_rtc_abused) { + pm_trace_rtc_abused = false; + pr_warn("Possible incorrect RTC due to pm_trace, please use 'ntpdate' or 'rdate' to reset.\n"); + } + break; + default: + break; + } + return 0; +} + +static struct notifier_block pm_trace_nb = { + .notifier_call = pm_trace_notify, +}; static int early_resume_init(void) { hash_value_early_read = read_magic_time(); + register_pm_notifier(&pm_trace_nb); return 0; } diff --git a/drivers/rtc/rtc-cmos.c b/drivers/rtc/rtc-cmos.c index dd3d598..9cf06b7 100644 --- a/drivers/rtc/rtc-cmos.c +++ b/drivers/rtc/rtc-cmos.c @@ -191,6 +191,13 @@ static inline void cmos_write_bank2(unsigned char val, unsigned char addr) static int cmos_read_time(struct device *dev, struct rtc_time *t) { + /* + * If pm_trace abused the RTC for storage tell the caller that it is + * unusable. + */ + if (!pm_trace_rtc_valid()) + return -EIO; + /* REVISIT: if the clock has a "century" register, use * that instead of the heuristic in mc146818_get_time(). * That'll make Y3K compatility (year > 2070) easy! diff --git a/include/linux/mc146818rtc.h b/include/linux/mc146818rtc.h index a585b4b..0661af1 100644 --- a/include/linux/mc146818rtc.h +++ b/include/linux/mc146818rtc.h @@ -16,6 +16,7 @@ #include <asm/mc146818rtc.h> /* register access macros */ #include <linux/bcd.h> #include <linux/delay.h> +#include <linux/pm-trace.h> #ifdef __KERNEL__ #include <linux/spinlock.h> /* spinlock_t */ diff --git a/include/linux/pm-trace.h b/include/linux/pm-trace.h index ecbde7a..7b78793 100644 --- a/include/linux/pm-trace.h +++ b/include/linux/pm-trace.h @@ -1,11 +1,17 @@ #ifndef PM_TRACE_H #define PM_TRACE_H +#include <linux/types.h> #ifdef CONFIG_PM_TRACE #include <asm/pm-trace.h> -#include <linux/types.h> extern int pm_trace_enabled; +extern bool pm_trace_rtc_abused; + +static inline bool pm_trace_rtc_valid(void) +{ + return !pm_trace_rtc_abused; +} static inline int pm_trace_is_enabled(void) { @@ -24,6 +30,7 @@ extern int show_trace_dev_match(char *buf, size_t size); #else +static inline bool pm_trace_rtc_valid(void) { return true; } static inline int pm_trace_is_enabled(void) { return 0; } #define TRACE_DEVICE(dev) do { } while (0) -- 2.7.4 ^ permalink raw reply related [flat|nested] 29+ messages in thread
* Re: [PATCH 2/7] timekeeping: Ignore the bogus sleep time if pm_trace is enabled 2016-11-28 22:35 ` [PATCH 2/7] timekeeping: Ignore the bogus sleep time if pm_trace is enabled John Stultz @ 2016-11-29 7:19 ` Ingo Molnar 2016-11-29 9:38 ` Chen Yu 2016-11-29 17:10 ` [tip:timers/core] " tip-bot for Chen Yu 1 sibling, 1 reply; 29+ messages in thread From: Ingo Molnar @ 2016-11-29 7:19 UTC (permalink / raw) To: John Stultz Cc: lkml, Chen Yu, Rafael J. Wysocki, Xunlei Pang, Ingo Molnar, Len Brown, H. Peter Anvin, Pavel Machek, Thomas Gleixner, Prarit Bhargava, Richard Cochran * John Stultz <john.stultz@linaro.org> wrote: > From: Chen Yu <yu.c.chen@intel.com> > > Previously we encountered some memory overflow issues due to > the bogus sleep time brought by inconsistent rtc, which is > triggered when pm_trace is enabled, and we have fixed it > in recent kernel. However it's improper in the first place > to call __timekeeping_inject_sleeptime() in case that pm_trace > is enabled simply because that "hash" time value will wreckage > the timekeeping subsystem. s/ Previously we encountered memory overflow issues due to bogus sleep time brought by an inconsistent RTC, which is triggered when pm_trace is enabled, and we have fixed it in recent kernels. However it's improper in the first place to call __timekeeping_inject_sleeptime() in case pm_trace is enabled simply because the "hash" time value will wreckage the timekeeping subsystem. Half a dozen typos ... > This patch is originally written by Thomas, which would bypass > the bogus rtc interval when pm_trace is enabled. > Meanwhile, if system succeed to resume back with pm_trace set, the > users are warned to adjust the bogus rtc either by 'ntpdate' or > 'rdate', by resetting pm_trace_rtc_abused to false, otherwise above > tools might not work as expected. s/ This patch was originally written by Thomas, which would bypass the bogus RTC interval when pm_trace is enabled. Meanwhile, if the system succeeds to resume back with pm_trace set, users are warned to adjust the bogus RTC either by 'ntpdate' or 'rdate', by resetting pm_trace_rtc_abused to false, otherwise above tools might not work as expected. > + /* > + * If pm_trace abused the RTC as storage set the timespec to 0 > + * which tells the caller that this RTC value is bogus. > + */ s/ /* * If pm_trace abused the RTC as storage, set the timespec to 0, * which tells the caller that this RTC value is bogus. */ > @@ -74,6 +75,9 @@ > > #define DEVSEED (7919) > > +bool pm_trace_rtc_abused __read_mostly; > +EXPORT_SYMBOL(pm_trace_rtc_abused); EXPORT_SYMBOL_GPL() > +static int pm_trace_notify(struct notifier_block *nb, > + unsigned long mode, void *_unused) Please no nonsensical linebreaks in the middle of an argument list. > +{ > + switch (mode) { > + case PM_POST_HIBERNATION: > + case PM_POST_SUSPEND: > + if (pm_trace_rtc_abused) { > + pm_trace_rtc_abused = false; > + pr_warn("Possible incorrect RTC due to pm_trace, please use 'ntpdate' or 'rdate' to reset.\n"); s/to reset./to reset it. Thanks, Ingo ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 2/7] timekeeping: Ignore the bogus sleep time if pm_trace is enabled 2016-11-29 7:19 ` Ingo Molnar @ 2016-11-29 9:38 ` Chen Yu 0 siblings, 0 replies; 29+ messages in thread From: Chen Yu @ 2016-11-29 9:38 UTC (permalink / raw) To: Ingo Molnar Cc: John Stultz, lkml, Rafael J. Wysocki, Xunlei Pang, Ingo Molnar, Len Brown, H. Peter Anvin, Pavel Machek, Thomas Gleixner, Prarit Bhargava, Richard Cochran On Tue, Nov 29, 2016 at 08:19:55AM +0100, Ingo Molnar wrote: > > * John Stultz <john.stultz@linaro.org> wrote: > > > From: Chen Yu <yu.c.chen@intel.com> > > > > Previously we encountered some memory overflow issues due to > > the bogus sleep time brought by inconsistent rtc, which is > > triggered when pm_trace is enabled, and we have fixed it > > in recent kernel. However it's improper in the first place > > to call __timekeeping_inject_sleeptime() in case that pm_trace > > is enabled simply because that "hash" time value will wreckage > > the timekeeping subsystem. > > s/ > > Previously we encountered memory overflow issues due to > bogus sleep time brought by an inconsistent RTC, which is > triggered when pm_trace is enabled, and we have fixed it > in recent kernels. However it's improper in the first place > to call __timekeeping_inject_sleeptime() in case pm_trace > is enabled simply because the "hash" time value will wreckage > the timekeeping subsystem. > > Half a dozen typos ... > > > This patch is originally written by Thomas, which would bypass > > the bogus rtc interval when pm_trace is enabled. > > Meanwhile, if system succeed to resume back with pm_trace set, the > > users are warned to adjust the bogus rtc either by 'ntpdate' or > > 'rdate', by resetting pm_trace_rtc_abused to false, otherwise above > > tools might not work as expected. > > s/ > > This patch was originally written by Thomas, which would bypass > the bogus RTC interval when pm_trace is enabled. > Meanwhile, if the system succeeds to resume back with pm_trace set, > users are warned to adjust the bogus RTC either by 'ntpdate' or > 'rdate', by resetting pm_trace_rtc_abused to false, otherwise above > tools might not work as expected. > > > + /* > > + * If pm_trace abused the RTC as storage set the timespec to 0 > > + * which tells the caller that this RTC value is bogus. > > + */ > > s/ > /* > * If pm_trace abused the RTC as storage, set the timespec to 0, > * which tells the caller that this RTC value is bogus. > */ > > > @@ -74,6 +75,9 @@ > > > > #define DEVSEED (7919) > > > > +bool pm_trace_rtc_abused __read_mostly; > > +EXPORT_SYMBOL(pm_trace_rtc_abused); > > EXPORT_SYMBOL_GPL() > > > +static int pm_trace_notify(struct notifier_block *nb, > > + unsigned long mode, void *_unused) > > Please no nonsensical linebreaks in the middle of an argument list. > > > +{ > > + switch (mode) { > > + case PM_POST_HIBERNATION: > > + case PM_POST_SUSPEND: > > + if (pm_trace_rtc_abused) { > > + pm_trace_rtc_abused = false; > > + pr_warn("Possible incorrect RTC due to pm_trace, please use 'ntpdate' or 'rdate' to reset.\n"); > > > s/to reset./to reset it. > > Thanks, > > Ingo Thanks Ingo, I've sent out a new versin based on your comments. Yu ^ permalink raw reply [flat|nested] 29+ messages in thread
* [tip:timers/core] timekeeping: Ignore the bogus sleep time if pm_trace is enabled 2016-11-28 22:35 ` [PATCH 2/7] timekeeping: Ignore the bogus sleep time if pm_trace is enabled John Stultz 2016-11-29 7:19 ` Ingo Molnar @ 2016-11-29 17:10 ` tip-bot for Chen Yu 1 sibling, 0 replies; 29+ messages in thread From: tip-bot for Chen Yu @ 2016-11-29 17:10 UTC (permalink / raw) To: linux-tip-commits Cc: linux-kernel, lenb, richardcochran, mingo, xlpang, pavel, yu.c.chen, rjw, hpa, tglx, john.stultz, prarit Commit-ID: ba58d1020a54933c6b087a3107661c8513556cb8 Gitweb: http://git.kernel.org/tip/ba58d1020a54933c6b087a3107661c8513556cb8 Author: Chen Yu <yu.c.chen@intel.com> AuthorDate: Mon, 28 Nov 2016 14:35:19 -0800 Committer: Thomas Gleixner <tglx@linutronix.de> CommitDate: Tue, 29 Nov 2016 18:02:58 +0100 timekeeping: Ignore the bogus sleep time if pm_trace is enabled Power management suspend/resume tracing (ab)uses the RTC to store suspend/resume information persistently. As a consequence the RTC value is clobbered when timekeeping is resumed and tries to inject the sleep time. Commit a4f8f6667f09 ("timekeeping: Cap array access in timekeeping_debug") plugged a out of bounds array access in the timekeeping debug code which was caused by the clobbered RTC value, but we still use the clobbered RTC value for sleep time injection into kernel timekeeping, which will result in random adjustments depending on the stored "hash" value. To prevent this keep track of the RTC clobbering and ignore the invalid RTC timestamp at resume. If the system resumed successfully clear the flag, which marks the RTC as unusable, warn the user about the RTC clobber and recommend to adjust the RTC with 'ntpdate' or 'rdate'. [jstultz: Fixed up pr_warn formating, and implemented suggestions from Ingo] [ tglx: Rewrote changelog ] Originally-from: Thomas Gleixner <tglx@linutronix.de> Signed-off-by: Chen Yu <yu.c.chen@intel.com> Signed-off-by: John Stultz <john.stultz@linaro.org> Acked-by: Pavel Machek <pavel@ucw.cz> Acked-by: Thomas Gleixner <tglx@linutronix.de> Cc: Prarit Bhargava <prarit@redhat.com> Cc: "Rafael J. Wysocki" <rjw@rjwysocki.net> Cc: Richard Cochran <richardcochran@gmail.com> Cc: Xunlei Pang <xlpang@redhat.com> Cc: Len Brown <lenb@kernel.org> Link: http://lkml.kernel.org/r/1480372524-15181-3-git-send-email-john.stultz@linaro.org Signed-off-by: Thomas Gleixner <tglx@linutronix.de> --- arch/x86/kernel/rtc.c | 9 +++++++++ drivers/base/power/trace.c | 27 +++++++++++++++++++++++++++ drivers/rtc/rtc-cmos.c | 7 +++++++ include/linux/mc146818rtc.h | 1 + include/linux/pm-trace.h | 9 ++++++++- 5 files changed, 52 insertions(+), 1 deletion(-) diff --git a/arch/x86/kernel/rtc.c b/arch/x86/kernel/rtc.c index 79c6311c..5b21cb7 100644 --- a/arch/x86/kernel/rtc.c +++ b/arch/x86/kernel/rtc.c @@ -64,6 +64,15 @@ void mach_get_cmos_time(struct timespec *now) unsigned int status, year, mon, day, hour, min, sec, century = 0; unsigned long flags; + /* + * If pm_trace abused the RTC as storage, set the timespec to 0, + * which tells the caller that this RTC value is unusable. + */ + if (!pm_trace_rtc_valid()) { + now->tv_sec = now->tv_nsec = 0; + return; + } + spin_lock_irqsave(&rtc_lock, flags); /* diff --git a/drivers/base/power/trace.c b/drivers/base/power/trace.c index efec10b..1cda505 100644 --- a/drivers/base/power/trace.c +++ b/drivers/base/power/trace.c @@ -10,6 +10,7 @@ #include <linux/pm-trace.h> #include <linux/export.h> #include <linux/rtc.h> +#include <linux/suspend.h> #include <linux/mc146818rtc.h> @@ -74,6 +75,9 @@ #define DEVSEED (7919) +bool pm_trace_rtc_abused __read_mostly; +EXPORT_SYMBOL_GPL(pm_trace_rtc_abused); + static unsigned int dev_hash_value; static int set_magic_time(unsigned int user, unsigned int file, unsigned int device) @@ -104,6 +108,7 @@ static int set_magic_time(unsigned int user, unsigned int file, unsigned int dev time.tm_min = (n % 20) * 3; n /= 20; mc146818_set_time(&time); + pm_trace_rtc_abused = true; return n ? -1 : 0; } @@ -239,9 +244,31 @@ int show_trace_dev_match(char *buf, size_t size) return ret; } +static int +pm_trace_notify(struct notifier_block *nb, unsigned long mode, void *_unused) +{ + switch (mode) { + case PM_POST_HIBERNATION: + case PM_POST_SUSPEND: + if (pm_trace_rtc_abused) { + pm_trace_rtc_abused = false; + pr_warn("Possible incorrect RTC due to pm_trace, please use 'ntpdate' or 'rdate' to reset it.\n"); + } + break; + default: + break; + } + return 0; +} + +static struct notifier_block pm_trace_nb = { + .notifier_call = pm_trace_notify, +}; + static int early_resume_init(void) { hash_value_early_read = read_magic_time(); + register_pm_notifier(&pm_trace_nb); return 0; } diff --git a/drivers/rtc/rtc-cmos.c b/drivers/rtc/rtc-cmos.c index dd3d598..b27a189 100644 --- a/drivers/rtc/rtc-cmos.c +++ b/drivers/rtc/rtc-cmos.c @@ -191,6 +191,13 @@ static inline void cmos_write_bank2(unsigned char val, unsigned char addr) static int cmos_read_time(struct device *dev, struct rtc_time *t) { + /* + * If pm_trace abused the RTC for storage, set the timespec to 0, + * which tells the caller that this RTC value is unusable. + */ + if (!pm_trace_rtc_valid()) + return -EIO; + /* REVISIT: if the clock has a "century" register, use * that instead of the heuristic in mc146818_get_time(). * That'll make Y3K compatility (year > 2070) easy! diff --git a/include/linux/mc146818rtc.h b/include/linux/mc146818rtc.h index a585b4b..0661af1 100644 --- a/include/linux/mc146818rtc.h +++ b/include/linux/mc146818rtc.h @@ -16,6 +16,7 @@ #include <asm/mc146818rtc.h> /* register access macros */ #include <linux/bcd.h> #include <linux/delay.h> +#include <linux/pm-trace.h> #ifdef __KERNEL__ #include <linux/spinlock.h> /* spinlock_t */ diff --git a/include/linux/pm-trace.h b/include/linux/pm-trace.h index ecbde7a..7b78793 100644 --- a/include/linux/pm-trace.h +++ b/include/linux/pm-trace.h @@ -1,11 +1,17 @@ #ifndef PM_TRACE_H #define PM_TRACE_H +#include <linux/types.h> #ifdef CONFIG_PM_TRACE #include <asm/pm-trace.h> -#include <linux/types.h> extern int pm_trace_enabled; +extern bool pm_trace_rtc_abused; + +static inline bool pm_trace_rtc_valid(void) +{ + return !pm_trace_rtc_abused; +} static inline int pm_trace_is_enabled(void) { @@ -24,6 +30,7 @@ extern int show_trace_dev_match(char *buf, size_t size); #else +static inline bool pm_trace_rtc_valid(void) { return true; } static inline int pm_trace_is_enabled(void) { return 0; } #define TRACE_DEVICE(dev) do { } while (0) ^ permalink raw reply related [flat|nested] 29+ messages in thread
* [PATCH 3/7] timekeeping: clocksource_cyc2ns: Document intended range limitation 2016-11-28 22:35 [GIT PULL][PATCH 0/7] Timekeeping changes for 4.10 (take 2) John Stultz 2016-11-28 22:35 ` [PATCH 1/7] selftests/timers: Fix spelling mistake "Asyncrhonous" -> "Asynchronous" John Stultz 2016-11-28 22:35 ` [PATCH 2/7] timekeeping: Ignore the bogus sleep time if pm_trace is enabled John Stultz @ 2016-11-28 22:35 ` John Stultz 2016-11-29 17:11 ` [tip:timers/core] timekeeping/clocksource_cyc2ns: " tip-bot for Chris Metcalf 2016-11-28 22:35 ` [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer John Stultz ` (3 subsequent siblings) 6 siblings, 1 reply; 29+ messages in thread From: John Stultz @ 2016-11-28 22:35 UTC (permalink / raw) To: lkml Cc: Chris Metcalf, Richard Cochran, Ingo Molnar, Prarit Bhargava, Thomas Gleixner, John Stultz From: Chris Metcalf <cmetcalf@mellanox.com> The "cycles" argument should not be an absolute clocksource cycle value, as the implementation's arithmetic will overflow relatively easily with wide (64 bit) clocksource counters. For performance, the implementation is simple and fast, since the function is intended for only relatively small delta values of clocksource cycles. Cc: Richard Cochran <richardcochran@gmail.com> Cc: Ingo Molnar <mingo@kernel.org> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Thomas Gleixner <tglx@linutronix.de> Signed-off-by: Chris Metcalf <cmetcalf@mellanox.com> [jstultz: Fixed up to merge against HEAD & commit message tweaks, also included rewording suggestion by Ingo] Signed-off-by: John Stultz <john.stultz@linaro.org> --- v2: Reworded comments as suggested by Ingo --- include/linux/clocksource.h | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/include/linux/clocksource.h b/include/linux/clocksource.h index 0839818..65602d3 100644 --- a/include/linux/clocksource.h +++ b/include/linux/clocksource.h @@ -169,7 +169,10 @@ static inline u32 clocksource_hz2mult(u32 hz, u32 shift_constant) * @mult: cycle to nanosecond multiplier * @shift: cycle to nanosecond divisor (power of two) * - * Converts cycles to nanoseconds, using the given mult and shift. + * Converts clocksource cycles to nanoseconds, using the given @mult and @shift. + * The code is optimized for performance and is not intended to work + * with absolute clocksource cycles (as those will easily overflow), + * but is only intended to be used with relative (delta) clocksource cycles. * * XXX - This could use some mult_lxl_ll() asm optimization */ -- 2.7.4 ^ permalink raw reply related [flat|nested] 29+ messages in thread
* [tip:timers/core] timekeeping/clocksource_cyc2ns: Document intended range limitation 2016-11-28 22:35 ` [PATCH 3/7] timekeeping: clocksource_cyc2ns: Document intended range limitation John Stultz @ 2016-11-29 17:11 ` tip-bot for Chris Metcalf 0 siblings, 0 replies; 29+ messages in thread From: tip-bot for Chris Metcalf @ 2016-11-29 17:11 UTC (permalink / raw) To: linux-tip-commits Cc: richardcochran, linux-kernel, prarit, tglx, mingo, cmetcalf, hpa, john.stultz Commit-ID: ec4101e8903e318b9fd4e3bbf72b1eaba53c64e1 Gitweb: http://git.kernel.org/tip/ec4101e8903e318b9fd4e3bbf72b1eaba53c64e1 Author: Chris Metcalf <cmetcalf@mellanox.com> AuthorDate: Mon, 28 Nov 2016 14:35:20 -0800 Committer: Thomas Gleixner <tglx@linutronix.de> CommitDate: Tue, 29 Nov 2016 18:02:58 +0100 timekeeping/clocksource_cyc2ns: Document intended range limitation The "cycles" argument should not be an absolute clocksource cycle value, as the implementation's arithmetic will overflow relatively easily with wide (64 bit) clocksource counters. For performance, the implementation is simple and fast, since the function is intended for only relatively small delta values of clocksource cycles. [jstultz: Fixed up to merge against HEAD & commit message tweaks, also included rewording suggestion by Ingo] Signed-off-by: Chris Metcalf <cmetcalf@mellanox.com> Signed-off-by: John Stultz <john.stultz@linaro.org> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Link: http://lkml.kernel.org/r/1480372524-15181-4-git-send-email-john.stultz@linaro.org Signed-off-by: Thomas Gleixner <tglx@linutronix.de> --- include/linux/clocksource.h | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/include/linux/clocksource.h b/include/linux/clocksource.h index 0839818..65602d3 100644 --- a/include/linux/clocksource.h +++ b/include/linux/clocksource.h @@ -169,7 +169,10 @@ static inline u32 clocksource_hz2mult(u32 hz, u32 shift_constant) * @mult: cycle to nanosecond multiplier * @shift: cycle to nanosecond divisor (power of two) * - * Converts cycles to nanoseconds, using the given mult and shift. + * Converts clocksource cycles to nanoseconds, using the given @mult and @shift. + * The code is optimized for performance and is not intended to work + * with absolute clocksource cycles (as those will easily overflow), + * but is only intended to be used with relative (delta) clocksource cycles. * * XXX - This could use some mult_lxl_ll() asm optimization */ ^ permalink raw reply related [flat|nested] 29+ messages in thread
* [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer 2016-11-28 22:35 [GIT PULL][PATCH 0/7] Timekeeping changes for 4.10 (take 2) John Stultz ` (2 preceding siblings ...) 2016-11-28 22:35 ` [PATCH 3/7] timekeeping: clocksource_cyc2ns: Document intended range limitation John Stultz @ 2016-11-28 22:35 ` John Stultz 2016-11-29 7:23 ` Ingo Molnar ` (2 more replies) 2016-11-28 22:35 ` [PATCH 5/7] timekeeping: Add a fast and NMI safe boot clock John Stultz ` (2 subsequent siblings) 6 siblings, 3 replies; 29+ messages in thread From: John Stultz @ 2016-11-28 22:35 UTC (permalink / raw) To: lkml Cc: Baolin Wang, Thomas Gleixner, Richard Cochran, Prarit Bhargava, Ingo Molnar, Steven Rostedt, John Stultz From: Baolin Wang <baolin.wang@linaro.org> For system debugging, we sometimes want to know who sets one alarm timer, the time of the timer, when the timer started and fired and so on. Thus adding tracepoints can help us trace the alarmtimer information. For example, when we debug the system supend/resume, if the system is always resumed by RTC alarm, we can find out which process set the alarm timer to resume system by below trace log: ...... Binder:3292_2-3304 [000] d..2 149.981123: alarmtimer_cancel: alarmtimer:ffffffc1319a7800 type:REALTIME expires:1325463120000000000 now:1325376810370370245 Binder:3292_2-3304 [000] d..2 149.981136: alarmtimer_start: alarmtimer:ffffffc1319a7800 type:REALTIME expires:1325376840000000000 now:1325376810370384591 Binder:3292_9-3953 [000] d..2 150.212991: alarmtimer_cancel: alarmtimer:ffffffc1319a5a00 type:BOOTTIME expires:179552000000 now:150154008122 Binder:3292_9-3953 [000] d..2 150.213006: alarmtimer_start: alarmtimer:ffffffc1319a5a00 type:BOOTTIME expires:179551000000 now:150154025622 ...... system_server-3000 [002] ...1 162.701940: alarmtimer_suspend: alarmtimer type:REALTIME expires:1325376839802714584 ...... >From the trace log, we can find out the 'Binder:3292_2' process set one alarm timer which resumes the system. Cc: Thomas Gleixner <tglx@linutronix.de> Cc: Richard Cochran <richardcochran@gmail.com> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Ingo Molnar <mingo@kernel.org> Cc: Steven Rostedt <rostedt@goodmis.org> Signed-off-by: Baolin Wang <baolin.wang@linaro.org> Acked-by: Steven Rostedt <rostedt@goodmis.org> Signed-off-by: John Stultz <john.stultz@linaro.org> --- Changes since v4: - Initialize 'type' to -1 and rename it in alarmtimer_suspend(). - Fix typo in subject line. Changes since v3: - Remove the "ALARM_" prefix in the string. - Add the ACK by Steven Rostedt. Changes since v2: - Save time as s64 type. - Remove 'process_name' parameter and add 'now' parameter. - Rename the trace event name. - Remove restart trace event. - Other optimization. --- include/trace/events/alarmtimer.h | 92 +++++++++++++++++++++++++++++++++++++++ kernel/time/alarmtimer.c | 16 ++++++- 2 files changed, 106 insertions(+), 2 deletions(-) create mode 100644 include/trace/events/alarmtimer.h diff --git a/include/trace/events/alarmtimer.h b/include/trace/events/alarmtimer.h new file mode 100644 index 0000000..61ea556 --- /dev/null +++ b/include/trace/events/alarmtimer.h @@ -0,0 +1,92 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM alarmtimer + +#if !defined(_TRACE_ALARMTIMER_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_ALARMTIMER_H + +#include <linux/alarmtimer.h> +#include <linux/rtc.h> +#include <linux/tracepoint.h> + +TRACE_DEFINE_ENUM(ALARM_REALTIME); +TRACE_DEFINE_ENUM(ALARM_BOOTTIME); + +#define show_alarm_type(type) __print_flags(type, " | ", \ + { 1 << ALARM_REALTIME, "REALTIME" }, \ + { 1 << ALARM_BOOTTIME, "BOOTTIME" }) + +TRACE_EVENT(alarmtimer_suspend, + + TP_PROTO(ktime_t expires, int flag), + + TP_ARGS(expires, flag), + + TP_STRUCT__entry( + __field(s64, expires) + __field(unsigned char, alarm_type) + ), + + TP_fast_assign( + __entry->expires = expires.tv64; + __entry->alarm_type = flag; + ), + + TP_printk("alarmtimer type:%s expires:%llu", + show_alarm_type((1 << __entry->alarm_type)), + __entry->expires + ) +); + +DECLARE_EVENT_CLASS(alarm_class, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now), + + TP_STRUCT__entry( + __field(void *, alarm) + __field(unsigned char, alarm_type) + __field(s64, expires) + __field(s64, now) + ), + + TP_fast_assign( + __entry->alarm = alarm; + __entry->alarm_type = alarm->type; + __entry->expires = alarm->node.expires.tv64; + __entry->now = now.tv64; + ), + + TP_printk("alarmtimer:%p type:%s expires:%llu now:%llu", + __entry->alarm, + show_alarm_type((1 << __entry->alarm_type)), + __entry->expires, + __entry->now + ) +); + +DEFINE_EVENT(alarm_class, alarmtimer_fired, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +DEFINE_EVENT(alarm_class, alarmtimer_start, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +DEFINE_EVENT(alarm_class, alarmtimer_cancel, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +#endif /* _TRACE_ALARMTIMER_H */ + +/* This part must be outside protection */ +#include <trace/define_trace.h> diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c index 12dd190..4590f23 100644 --- a/kernel/time/alarmtimer.c +++ b/kernel/time/alarmtimer.c @@ -26,6 +26,9 @@ #include <linux/workqueue.h> #include <linux/freezer.h> +#define CREATE_TRACE_POINTS +#include <trace/events/alarmtimer.h> + /** * struct alarm_base - Alarm timer bases * @lock: Lock for syncrhonized access to the base @@ -194,6 +197,7 @@ static enum hrtimer_restart alarmtimer_fired(struct hrtimer *timer) } spin_unlock_irqrestore(&base->lock, flags); + trace_alarmtimer_fired(alarm, base->gettime()); return ret; } @@ -222,7 +226,7 @@ static int alarmtimer_suspend(struct device *dev) ktime_t min, now; unsigned long flags; struct rtc_device *rtc; - int i; + int i, min_type = -1; int ret; spin_lock_irqsave(&freezer_delta_lock, flags); @@ -247,8 +251,10 @@ static int alarmtimer_suspend(struct device *dev) if (!next) continue; delta = ktime_sub(next->expires, base->gettime()); - if (!min.tv64 || (delta.tv64 < min.tv64)) + if (!min.tv64 || (delta.tv64 < min.tv64)) { min = delta; + min_type = i; + } } if (min.tv64 == 0) return 0; @@ -264,6 +270,8 @@ static int alarmtimer_suspend(struct device *dev) now = rtc_tm_to_ktime(tm); now = ktime_add(now, min); + trace_alarmtimer_suspend(now, min_type); + /* Set alarm, if in the past reject suspend briefly to handle */ ret = rtc_timer_start(rtc, &rtctimer, now, ktime_set(0, 0)); if (ret < 0) @@ -342,6 +350,8 @@ void alarm_start(struct alarm *alarm, ktime_t start) alarmtimer_enqueue(base, alarm); hrtimer_start(&alarm->timer, alarm->node.expires, HRTIMER_MODE_ABS); spin_unlock_irqrestore(&base->lock, flags); + + trace_alarmtimer_start(alarm, base->gettime()); } EXPORT_SYMBOL_GPL(alarm_start); @@ -390,6 +400,8 @@ int alarm_try_to_cancel(struct alarm *alarm) if (ret >= 0) alarmtimer_dequeue(base, alarm); spin_unlock_irqrestore(&base->lock, flags); + + trace_alarmtimer_cancel(alarm, base->gettime()); return ret; } EXPORT_SYMBOL_GPL(alarm_try_to_cancel); -- 2.7.4 ^ permalink raw reply related [flat|nested] 29+ messages in thread
* Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer 2016-11-28 22:35 ` [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer John Stultz @ 2016-11-29 7:23 ` Ingo Molnar 2016-11-29 8:23 ` Baolin Wang 2016-11-29 12:06 ` Thomas Gleixner 2016-12-01 13:52 ` [tip:timers/core] alarmtimer: Add tracepoints for alarm timers tip-bot for Baolin Wang 2 siblings, 1 reply; 29+ messages in thread From: Ingo Molnar @ 2016-11-29 7:23 UTC (permalink / raw) To: John Stultz Cc: lkml, Baolin Wang, Thomas Gleixner, Richard Cochran, Prarit Bhargava, Steven Rostedt * John Stultz <john.stultz@linaro.org> wrote: > From: Baolin Wang <baolin.wang@linaro.org> > > For system debugging, we sometimes want to know who sets one > alarm timer, the time of the timer, when the timer started and > fired and so on. Thus adding tracepoints can help us trace the > alarmtimer information. s/one alarm timer/an alarm timer > For example, when we debug the system supend/resume, if the > system is always resumed by RTC alarm, we can find out which > process set the alarm timer to resume system by below trace log: s/when we debug the system/when we debug system s/supend/suspend s/resume system/resume the system s/by below trace log/by the trace log below > From the trace log, we can find out the 'Binder:3292_2' process > set one alarm timer which resumes the system. s/set one alarm timer/set an alarm timer > Changes since v4: > - Initialize 'type' to -1 and rename it in alarmtimer_suspend(). > - Fix typo in subject line. > > Changes since v3: > - Remove the "ALARM_" prefix in the string. > - Add the ACK by Steven Rostedt. > > Changes since v2: > - Save time as s64 type. > - Remove 'process_name' parameter and add 'now' parameter. > - Rename the trace event name. > - Remove restart trace event. > - Other optimization. I find it really sad that a patch that has gone through 4 iterations still has so many typos and grammar errors in its changelog :-( Thanks, Ingo ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer 2016-11-29 7:23 ` Ingo Molnar @ 2016-11-29 8:23 ` Baolin Wang 2016-11-29 9:12 ` Ingo Molnar 0 siblings, 1 reply; 29+ messages in thread From: Baolin Wang @ 2016-11-29 8:23 UTC (permalink / raw) To: Ingo Molnar Cc: John Stultz, lkml, Thomas Gleixner, Richard Cochran, Prarit Bhargava, Steven Rostedt On 29 November 2016 at 15:23, Ingo Molnar <mingo@kernel.org> wrote: > > * John Stultz <john.stultz@linaro.org> wrote: > >> From: Baolin Wang <baolin.wang@linaro.org> >> >> For system debugging, we sometimes want to know who sets one >> alarm timer, the time of the timer, when the timer started and >> fired and so on. Thus adding tracepoints can help us trace the >> alarmtimer information. > > s/one alarm timer/an alarm timer > >> For example, when we debug the system supend/resume, if the >> system is always resumed by RTC alarm, we can find out which >> process set the alarm timer to resume system by below trace log: > > s/when we debug the system/when we debug system > s/supend/suspend > s/resume system/resume the system > s/by below trace log/by the trace log below > >> From the trace log, we can find out the 'Binder:3292_2' process >> set one alarm timer which resumes the system. > > s/set one alarm timer/set an alarm timer > >> Changes since v4: >> - Initialize 'type' to -1 and rename it in alarmtimer_suspend(). >> - Fix typo in subject line. >> >> Changes since v3: >> - Remove the "ALARM_" prefix in the string. >> - Add the ACK by Steven Rostedt. >> >> Changes since v2: >> - Save time as s64 type. >> - Remove 'process_name' parameter and add 'now' parameter. >> - Rename the trace event name. >> - Remove restart trace event. >> - Other optimization. > > I find it really sad that a patch that has gone through 4 iterations still has so > many typos and grammar errors in its changelog :-( Really sorry for these elementary errors, I will fix these errors in new patch. Sorry for troubles again. -- Baolin.wang Best Regards ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer 2016-11-29 8:23 ` Baolin Wang @ 2016-11-29 9:12 ` Ingo Molnar 2016-11-29 11:52 ` Baolin Wang 0 siblings, 1 reply; 29+ messages in thread From: Ingo Molnar @ 2016-11-29 9:12 UTC (permalink / raw) To: Baolin Wang Cc: John Stultz, lkml, Thomas Gleixner, Richard Cochran, Prarit Bhargava, Steven Rostedt * Baolin Wang <baolin.wang@linaro.org> wrote: > On 29 November 2016 at 15:23, Ingo Molnar <mingo@kernel.org> wrote: > > > > * John Stultz <john.stultz@linaro.org> wrote: > > > >> From: Baolin Wang <baolin.wang@linaro.org> > >> > >> For system debugging, we sometimes want to know who sets one > >> alarm timer, the time of the timer, when the timer started and > >> fired and so on. Thus adding tracepoints can help us trace the > >> alarmtimer information. > > > > s/one alarm timer/an alarm timer > > > >> For example, when we debug the system supend/resume, if the > >> system is always resumed by RTC alarm, we can find out which > >> process set the alarm timer to resume system by below trace log: > > > > s/when we debug the system/when we debug system > > s/supend/suspend > > s/resume system/resume the system > > s/by below trace log/by the trace log below > > > >> From the trace log, we can find out the 'Binder:3292_2' process > >> set one alarm timer which resumes the system. > > > > s/set one alarm timer/set an alarm timer > > > >> Changes since v4: > >> - Initialize 'type' to -1 and rename it in alarmtimer_suspend(). > >> - Fix typo in subject line. > >> > >> Changes since v3: > >> - Remove the "ALARM_" prefix in the string. > >> - Add the ACK by Steven Rostedt. > >> > >> Changes since v2: > >> - Save time as s64 type. > >> - Remove 'process_name' parameter and add 'now' parameter. > >> - Rename the trace event name. > >> - Remove restart trace event. > >> - Other optimization. > > > > I find it really sad that a patch that has gone through 4 iterations still has so > > many typos and grammar errors in its changelog :-( > > Really sorry for these elementary errors, I will fix these errors in > new patch. Sorry for troubles again. No problem - the code looks fine to me, so we can fix this when applying the patches. Thanks, Ingo ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer 2016-11-29 9:12 ` Ingo Molnar @ 2016-11-29 11:52 ` Baolin Wang 0 siblings, 0 replies; 29+ messages in thread From: Baolin Wang @ 2016-11-29 11:52 UTC (permalink / raw) To: Ingo Molnar Cc: John Stultz, lkml, Thomas Gleixner, Richard Cochran, Prarit Bhargava, Steven Rostedt On 29 November 2016 at 17:12, Ingo Molnar <mingo@kernel.org> wrote: > > * Baolin Wang <baolin.wang@linaro.org> wrote: > >> On 29 November 2016 at 15:23, Ingo Molnar <mingo@kernel.org> wrote: >> > >> > * John Stultz <john.stultz@linaro.org> wrote: >> > >> >> From: Baolin Wang <baolin.wang@linaro.org> >> >> >> >> For system debugging, we sometimes want to know who sets one >> >> alarm timer, the time of the timer, when the timer started and >> >> fired and so on. Thus adding tracepoints can help us trace the >> >> alarmtimer information. >> > >> > s/one alarm timer/an alarm timer >> > >> >> For example, when we debug the system supend/resume, if the >> >> system is always resumed by RTC alarm, we can find out which >> >> process set the alarm timer to resume system by below trace log: >> > >> > s/when we debug the system/when we debug system >> > s/supend/suspend >> > s/resume system/resume the system >> > s/by below trace log/by the trace log below >> > >> >> From the trace log, we can find out the 'Binder:3292_2' process >> >> set one alarm timer which resumes the system. >> > >> > s/set one alarm timer/set an alarm timer >> > >> >> Changes since v4: >> >> - Initialize 'type' to -1 and rename it in alarmtimer_suspend(). >> >> - Fix typo in subject line. >> >> >> >> Changes since v3: >> >> - Remove the "ALARM_" prefix in the string. >> >> - Add the ACK by Steven Rostedt. >> >> >> >> Changes since v2: >> >> - Save time as s64 type. >> >> - Remove 'process_name' parameter and add 'now' parameter. >> >> - Rename the trace event name. >> >> - Remove restart trace event. >> >> - Other optimization. >> > >> > I find it really sad that a patch that has gone through 4 iterations still has so >> > many typos and grammar errors in its changelog :-( >> >> Really sorry for these elementary errors, I will fix these errors in >> new patch. Sorry for troubles again. > > No problem - the code looks fine to me, so we can fix this when applying the > patches. Okay, thanks a lot. -- Baolin.wang Best Regards ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer 2016-11-28 22:35 ` [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer John Stultz 2016-11-29 7:23 ` Ingo Molnar @ 2016-11-29 12:06 ` Thomas Gleixner 2016-11-30 11:43 ` Baolin Wang 2016-12-01 2:34 ` Baolin Wang 2016-12-01 13:52 ` [tip:timers/core] alarmtimer: Add tracepoints for alarm timers tip-bot for Baolin Wang 2 siblings, 2 replies; 29+ messages in thread From: Thomas Gleixner @ 2016-11-29 12:06 UTC (permalink / raw) To: John Stultz Cc: lkml, Baolin Wang, Richard Cochran, Prarit Bhargava, Ingo Molnar, Steven Rostedt On Mon, 28 Nov 2016, John Stultz wrote: > From: Baolin Wang <baolin.wang@linaro.org> > > For system debugging, we sometimes want to know who sets one > alarm timer, the time of the timer, when the timer started and > fired and so on. Thus adding tracepoints can help us trace the > alarmtimer information. > > For example, when we debug the system supend/resume, if the > system is always resumed by RTC alarm, we can find out which > process set the alarm timer to resume system by below trace log: > > ...... > > Binder:3292_2-3304 [000] d..2 149.981123: alarmtimer_cancel: > alarmtimer:ffffffc1319a7800 type:REALTIME > expires:1325463120000000000 now:1325376810370370245 > > Binder:3292_2-3304 [000] d..2 149.981136: alarmtimer_start: > alarmtimer:ffffffc1319a7800 type:REALTIME > expires:1325376840000000000 now:1325376810370384591 > > Binder:3292_9-3953 [000] d..2 150.212991: alarmtimer_cancel: > alarmtimer:ffffffc1319a5a00 type:BOOTTIME > expires:179552000000 now:150154008122 > > Binder:3292_9-3953 [000] d..2 150.213006: alarmtimer_start: > alarmtimer:ffffffc1319a5a00 type:BOOTTIME > expires:179551000000 now:150154025622 > > ...... > > system_server-3000 [002] ...1 162.701940: alarmtimer_suspend: > alarmtimer type:REALTIME expires:1325376839802714584 > ...... > > >From the trace log, we can find out the 'Binder:3292_2' process > set one alarm timer which resumes the system. To be honest. I have a hard time to figure out that Binder:3292_2 armed the timer. suspend: expires:1325376839802714584 Binder start: expires:1325376840000000000 That does not make any sense at all. And this is a result of how that suspend tracepoint got glued into alarmtimer_suspend(): > @@ -222,7 +226,7 @@ static int alarmtimer_suspend(struct device *dev) > ktime_t min, now; > unsigned long flags; > struct rtc_device *rtc; > - int i; > + int i, min_type = -1; > int ret; > > spin_lock_irqsave(&freezer_delta_lock, flags); > @@ -247,8 +251,10 @@ static int alarmtimer_suspend(struct device *dev) > if (!next) > continue; > delta = ktime_sub(next->expires, base->gettime()); > - if (!min.tv64 || (delta.tv64 < min.tv64)) > + if (!min.tv64 || (delta.tv64 < min.tv64)) { > min = delta; > + min_type = i; > + } > } > if (min.tv64 == 0) > return 0; > @@ -264,6 +270,8 @@ static int alarmtimer_suspend(struct device *dev) > now = rtc_tm_to_ktime(tm); > now = ktime_add(now, min); > > + trace_alarmtimer_suspend(now, min_type); So first we calculate the relative expiry time from now, add it to the RTC and then print out the sum. That's utter crap especially if the first expiring timer is based on CLOCK_BOOTTIME. Even with CLOCK_REALTIME you do not get matching expiry time as you can see above. Now looking at the other possibility to arm the resume time: freezer_delta. That's even more undebuggable because the freezer time is stored as relative timeout without any type information. How is one supposed to map that back to an alarm timer start? Find below a revamped version (untested) of this including a proper written changelog. Thanks, tglx 8<-------------- Subject: time/alarmtimer: Add tracepoints for alarmtimer From: John Stultz <john.stultz@linaro.org> Date: Mon, 28 Nov 2016 14:35:21 -0800 From: Baolin Wang <baolin.wang@linaro.org> Alarm timers are one of the mechanisms to wake up a system from suspend, but there exist no tracepoints to analyse which process/thread armed an alarmtimer. Add tracepoints for start/cancel/expire of individual alarm timers and one for tracing the suspend time decision when to resume the system. The following trace excerpt illustrates the new mechanism: Binder:3292_2-3304 [000] d..2 149.981123: alarmtimer_cancel: alarmtimer:ffffffc1319a7800 type:REALTIME expires:1325463120000000000 now:1325376810370370245 Binder:3292_2-3304 [000] d..2 149.981136: alarmtimer_start: alarmtimer:ffffffc1319a7800 type:REALTIME expires:1325376840000000000 now:1325376810370384591 Binder:3292_9-3953 [000] d..2 150.212991: alarmtimer_cancel: alarmtimer:ffffffc1319a5a00 type:BOOTTIME expires:179552000000 now:150154008122 Binder:3292_9-3953 [000] d..2 150.213006: alarmtimer_start: alarmtimer:ffffffc1319a5a00 type:BOOTTIME expires:179551000000 now:150154025622 system_server-3000 [002] ...1 162.701940: alarmtimer_suspend: alarmtimer type:REALTIME expires:1325376840000000000 The wakeup time which is selected at suspend time allows to map it back to the task arming the timer: Binder:3292_2. [ tglx: Store real alarm timer expiry time instead of some useless RTC relative information, add proper type information for wakeups which are handled via the clock_nanosleep/freezer and massage the changelog. ] Signed-off-by: Baolin Wang <baolin.wang@linaro.org> Signed-off-by: John Stultz <john.stultz@linaro.org> Acked-by: Steven Rostedt <rostedt@goodmis.org> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Link: http://lkml.kernel.org/r/1480372524-15181-5-git-send-email-john.stultz@linaro.org Signed-off-by: Thomas Gleixner <tglx@linutronix.de> --- Changes since v4: - Initialize 'type' to -1 and rename it in alarmtimer_suspend(). - Fix typo in subject line. Changes since v3: - Remove the "ALARM_" prefix in the string. - Add the ACK by Steven Rostedt. Changes since v2: - Save time as s64 type. - Remove 'process_name' parameter and add 'now' parameter. - Rename the trace event name. - Remove restart trace event. - Other optimization. --- include/linux/alarmtimer.h | 5 + include/trace/events/alarmtimer.h | 96 ++++++++++++++++++++++++++++++++++++++ kernel/time/alarmtimer.c | 53 +++++++++++++++++--- 3 files changed, 144 insertions(+), 10 deletions(-) create mode 100644 include/trace/events/alarmtimer.h --- a/include/linux/alarmtimer.h +++ b/include/linux/alarmtimer.h @@ -10,7 +10,12 @@ enum alarmtimer_type { ALARM_REALTIME, ALARM_BOOTTIME, + /* Supported types end here */ ALARM_NUMTYPE, + + /* Used for tracing information. No usable types. */ + ALARM_REALTIME_FREEZER, + ALARM_BOOTTIME_FREEZER, }; enum alarmtimer_restart { --- /dev/null +++ b/include/trace/events/alarmtimer.h @@ -0,0 +1,96 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM alarmtimer + +#if !defined(_TRACE_ALARMTIMER_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_ALARMTIMER_H + +#include <linux/alarmtimer.h> +#include <linux/rtc.h> +#include <linux/tracepoint.h> + +TRACE_DEFINE_ENUM(ALARM_REALTIME); +TRACE_DEFINE_ENUM(ALARM_BOOTTIME); +TRACE_DEFINE_ENUM(ALARM_REALTIME_FREEZER); +TRACE_DEFINE_ENUM(ALARM_BOOTTIME_FREEZER); + +#define show_alarm_type(type) __print_flags(type, " | ", \ + { 1 << ALARM_REALTIME, "REALTIME" }, \ + { 1 << ALARM_BOOTTIME, "BOOTTIME" }, \ + { 1 << ALARM_REALTIME_FREEZER, "REALTIME Freezer" }, \ + { 1 << ALARM_BOOTTIME_FREEZER, "BOOTTIME Freezer" }) + +TRACE_EVENT(alarmtimer_suspend, + + TP_PROTO(ktime_t expires, int flag), + + TP_ARGS(expires, flag), + + TP_STRUCT__entry( + __field(s64, expires) + __field(unsigned char, alarm_type) + ), + + TP_fast_assign( + __entry->expires = expires.tv64; + __entry->alarm_type = flag; + ), + + TP_printk("alarmtimer type:%s expires:%llu", + show_alarm_type((1 << __entry->alarm_type)), + __entry->expires + ) +); + +DECLARE_EVENT_CLASS(alarm_class, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now), + + TP_STRUCT__entry( + __field(void *, alarm) + __field(unsigned char, alarm_type) + __field(s64, expires) + __field(s64, now) + ), + + TP_fast_assign( + __entry->alarm = alarm; + __entry->alarm_type = alarm->type; + __entry->expires = alarm->node.expires.tv64; + __entry->now = now.tv64; + ), + + TP_printk("alarmtimer:%p type:%s expires:%llu now:%llu", + __entry->alarm, + show_alarm_type((1 << __entry->alarm_type)), + __entry->expires, + __entry->now + ) +); + +DEFINE_EVENT(alarm_class, alarmtimer_fired, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +DEFINE_EVENT(alarm_class, alarmtimer_start, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +DEFINE_EVENT(alarm_class, alarmtimer_cancel, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +#endif /* _TRACE_ALARMTIMER_H */ + +/* This part must be outside protection */ +#include <trace/define_trace.h> --- a/kernel/time/alarmtimer.c +++ b/kernel/time/alarmtimer.c @@ -26,6 +26,9 @@ #include <linux/workqueue.h> #include <linux/freezer.h> +#define CREATE_TRACE_POINTS +#include <trace/events/alarmtimer.h> + /** * struct alarm_base - Alarm timer bases * @lock: Lock for syncrhonized access to the base @@ -40,7 +43,9 @@ static struct alarm_base { clockid_t base_clockid; } alarm_bases[ALARM_NUMTYPE]; -/* freezer delta & lock used to handle clock_nanosleep triggered wakeups */ +/* freezer information to handle clock_nanosleep triggered wakeups */ +static enum alarmtimer_type freezer_alarmtype; +static ktime_t freezer_expires; static ktime_t freezer_delta; static DEFINE_SPINLOCK(freezer_delta_lock); @@ -194,6 +199,7 @@ static enum hrtimer_restart alarmtimer_f } spin_unlock_irqrestore(&base->lock, flags); + trace_alarmtimer_fired(alarm, base->gettime()); return ret; } @@ -218,15 +224,16 @@ EXPORT_SYMBOL_GPL(alarm_expires_remainin */ static int alarmtimer_suspend(struct device *dev) { - struct rtc_time tm; - ktime_t min, now; - unsigned long flags; + ktime_t min, now, expires; + int i, ret, type; struct rtc_device *rtc; - int i; - int ret; + unsigned long flags; + struct rtc_time tm; spin_lock_irqsave(&freezer_delta_lock, flags); min = freezer_delta; + expires = freezer_expires; + type = freezer_alarmtype; freezer_delta = ktime_set(0, 0); spin_unlock_irqrestore(&freezer_delta_lock, flags); @@ -247,8 +254,11 @@ static int alarmtimer_suspend(struct dev if (!next) continue; delta = ktime_sub(next->expires, base->gettime()); - if (!min.tv64 || (delta.tv64 < min.tv64)) + if (!min.tv64 || (delta.tv64 < min.tv64)) { + expires = next->expires; min = delta; + type = i; + } } if (min.tv64 == 0) return 0; @@ -258,6 +268,8 @@ static int alarmtimer_suspend(struct dev return -EBUSY; } + trace_alarmtimer_suspend(expires, type); + /* Setup an rtc timer to fire that far in the future */ rtc_timer_cancel(rtc, &rtctimer); rtc_read_time(rtc, &tm); @@ -295,15 +307,32 @@ static int alarmtimer_resume(struct devi static void alarmtimer_freezerset(ktime_t absexp, enum alarmtimer_type type) { - ktime_t delta; + struct alarm_base *base; unsigned long flags; - struct alarm_base *base = &alarm_bases[type]; + ktime_t delta; + + switch(type) { + case ALARM_REALTIME: + base = &alarm_bases[ALARM_REALTIME]; + type = ALARM_REALTIME_FREEZER; + break; + case ALARM_BOOTTIME: + base = &alarm_bases[ALARM_BOOTTIME]; + type = ALARM_BOOTTIME_FREEZER; + break; + default: + WARN_ONCE(1, "Invalid alarm type: %d\n", type); + return; + } delta = ktime_sub(absexp, base->gettime()); spin_lock_irqsave(&freezer_delta_lock, flags); - if (!freezer_delta.tv64 || (delta.tv64 < freezer_delta.tv64)) + if (!freezer_delta.tv64 || (delta.tv64 < freezer_delta.tv64)) { freezer_delta = delta; + freezer_expires = absexp; + freezer_alarmtype = type; + } spin_unlock_irqrestore(&freezer_delta_lock, flags); } @@ -342,6 +371,8 @@ void alarm_start(struct alarm *alarm, kt alarmtimer_enqueue(base, alarm); hrtimer_start(&alarm->timer, alarm->node.expires, HRTIMER_MODE_ABS); spin_unlock_irqrestore(&base->lock, flags); + + trace_alarmtimer_start(alarm, base->gettime()); } EXPORT_SYMBOL_GPL(alarm_start); @@ -390,6 +421,8 @@ int alarm_try_to_cancel(struct alarm *al if (ret >= 0) alarmtimer_dequeue(base, alarm); spin_unlock_irqrestore(&base->lock, flags); + + trace_alarmtimer_cancel(alarm, base->gettime()); return ret; } EXPORT_SYMBOL_GPL(alarm_try_to_cancel); ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer 2016-11-29 12:06 ` Thomas Gleixner @ 2016-11-30 11:43 ` Baolin Wang 2016-12-01 2:34 ` Baolin Wang 1 sibling, 0 replies; 29+ messages in thread From: Baolin Wang @ 2016-11-30 11:43 UTC (permalink / raw) To: Thomas Gleixner Cc: John Stultz, lkml, Richard Cochran, Prarit Bhargava, Ingo Molnar, Steven Rostedt On 29 November 2016 at 20:06, Thomas Gleixner <tglx@linutronix.de> wrote: > On Mon, 28 Nov 2016, John Stultz wrote: > >> From: Baolin Wang <baolin.wang@linaro.org> >> >> For system debugging, we sometimes want to know who sets one >> alarm timer, the time of the timer, when the timer started and >> fired and so on. Thus adding tracepoints can help us trace the >> alarmtimer information. >> >> For example, when we debug the system supend/resume, if the >> system is always resumed by RTC alarm, we can find out which >> process set the alarm timer to resume system by below trace log: >> >> ...... >> >> Binder:3292_2-3304 [000] d..2 149.981123: alarmtimer_cancel: >> alarmtimer:ffffffc1319a7800 type:REALTIME >> expires:1325463120000000000 now:1325376810370370245 >> >> Binder:3292_2-3304 [000] d..2 149.981136: alarmtimer_start: >> alarmtimer:ffffffc1319a7800 type:REALTIME >> expires:1325376840000000000 now:1325376810370384591 >> >> Binder:3292_9-3953 [000] d..2 150.212991: alarmtimer_cancel: >> alarmtimer:ffffffc1319a5a00 type:BOOTTIME >> expires:179552000000 now:150154008122 >> >> Binder:3292_9-3953 [000] d..2 150.213006: alarmtimer_start: >> alarmtimer:ffffffc1319a5a00 type:BOOTTIME >> expires:179551000000 now:150154025622 >> >> ...... >> >> system_server-3000 [002] ...1 162.701940: alarmtimer_suspend: >> alarmtimer type:REALTIME expires:1325376839802714584 >> ...... >> >> >From the trace log, we can find out the 'Binder:3292_2' process >> set one alarm timer which resumes the system. > > To be honest. I have a hard time to figure out that Binder:3292_2 armed the > timer. > > suspend: expires:1325376839802714584 > Binder start: expires:1325376840000000000 > > That does not make any sense at all. And this is a result of how that > suspend tracepoint got glued into alarmtimer_suspend(): > >> @@ -222,7 +226,7 @@ static int alarmtimer_suspend(struct device *dev) >> ktime_t min, now; >> unsigned long flags; >> struct rtc_device *rtc; >> - int i; >> + int i, min_type = -1; >> int ret; >> >> spin_lock_irqsave(&freezer_delta_lock, flags); >> @@ -247,8 +251,10 @@ static int alarmtimer_suspend(struct device *dev) >> if (!next) >> continue; >> delta = ktime_sub(next->expires, base->gettime()); >> - if (!min.tv64 || (delta.tv64 < min.tv64)) >> + if (!min.tv64 || (delta.tv64 < min.tv64)) { >> min = delta; >> + min_type = i; >> + } >> } >> if (min.tv64 == 0) >> return 0; >> @@ -264,6 +270,8 @@ static int alarmtimer_suspend(struct device *dev) >> now = rtc_tm_to_ktime(tm); >> now = ktime_add(now, min); >> >> + trace_alarmtimer_suspend(now, min_type); > > So first we calculate the relative expiry time from now, add it to the RTC > and then print out the sum. That's utter crap especially if the first > expiring timer is based on CLOCK_BOOTTIME. Even with CLOCK_REALTIME you do > not get matching expiry time as you can see above. > > Now looking at the other possibility to arm the resume time: freezer_delta. > That's even more undebuggable because the freezer time is stored as > relative timeout without any type information. How is one supposed to map > that back to an alarm timer start? > > Find below a revamped version (untested) of this including a proper written > changelog. Make sense. Thanks for your patch and I will help to test it. -- Baolin.wang Best Regards ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer 2016-11-29 12:06 ` Thomas Gleixner 2016-11-30 11:43 ` Baolin Wang @ 2016-12-01 2:34 ` Baolin Wang 1 sibling, 0 replies; 29+ messages in thread From: Baolin Wang @ 2016-12-01 2:34 UTC (permalink / raw) To: Thomas Gleixner Cc: John Stultz, lkml, Richard Cochran, Prarit Bhargava, Ingo Molnar, Steven Rostedt On 29 November 2016 at 20:06, Thomas Gleixner <tglx@linutronix.de> wrote: > On Mon, 28 Nov 2016, John Stultz wrote: > >> From: Baolin Wang <baolin.wang@linaro.org> >> >> For system debugging, we sometimes want to know who sets one >> alarm timer, the time of the timer, when the timer started and >> fired and so on. Thus adding tracepoints can help us trace the >> alarmtimer information. >> >> For example, when we debug the system supend/resume, if the >> system is always resumed by RTC alarm, we can find out which >> process set the alarm timer to resume system by below trace log: >> >> ...... >> >> Binder:3292_2-3304 [000] d..2 149.981123: alarmtimer_cancel: >> alarmtimer:ffffffc1319a7800 type:REALTIME >> expires:1325463120000000000 now:1325376810370370245 >> >> Binder:3292_2-3304 [000] d..2 149.981136: alarmtimer_start: >> alarmtimer:ffffffc1319a7800 type:REALTIME >> expires:1325376840000000000 now:1325376810370384591 >> >> Binder:3292_9-3953 [000] d..2 150.212991: alarmtimer_cancel: >> alarmtimer:ffffffc1319a5a00 type:BOOTTIME >> expires:179552000000 now:150154008122 >> >> Binder:3292_9-3953 [000] d..2 150.213006: alarmtimer_start: >> alarmtimer:ffffffc1319a5a00 type:BOOTTIME >> expires:179551000000 now:150154025622 >> >> ...... >> >> system_server-3000 [002] ...1 162.701940: alarmtimer_suspend: >> alarmtimer type:REALTIME expires:1325376839802714584 >> ...... >> >> >From the trace log, we can find out the 'Binder:3292_2' process >> set one alarm timer which resumes the system. > > To be honest. I have a hard time to figure out that Binder:3292_2 armed the > timer. > > suspend: expires:1325376839802714584 > Binder start: expires:1325376840000000000 > > That does not make any sense at all. And this is a result of how that > suspend tracepoint got glued into alarmtimer_suspend(): > >> @@ -222,7 +226,7 @@ static int alarmtimer_suspend(struct device *dev) >> ktime_t min, now; >> unsigned long flags; >> struct rtc_device *rtc; >> - int i; >> + int i, min_type = -1; >> int ret; >> >> spin_lock_irqsave(&freezer_delta_lock, flags); >> @@ -247,8 +251,10 @@ static int alarmtimer_suspend(struct device *dev) >> if (!next) >> continue; >> delta = ktime_sub(next->expires, base->gettime()); >> - if (!min.tv64 || (delta.tv64 < min.tv64)) >> + if (!min.tv64 || (delta.tv64 < min.tv64)) { >> min = delta; >> + min_type = i; >> + } >> } >> if (min.tv64 == 0) >> return 0; >> @@ -264,6 +270,8 @@ static int alarmtimer_suspend(struct device *dev) >> now = rtc_tm_to_ktime(tm); >> now = ktime_add(now, min); >> >> + trace_alarmtimer_suspend(now, min_type); > > So first we calculate the relative expiry time from now, add it to the RTC > and then print out the sum. That's utter crap especially if the first > expiring timer is based on CLOCK_BOOTTIME. Even with CLOCK_REALTIME you do > not get matching expiry time as you can see above. > > Now looking at the other possibility to arm the resume time: freezer_delta. > That's even more undebuggable because the freezer time is stored as > relative timeout without any type information. How is one supposed to map > that back to an alarm timer start? > > Find below a revamped version (untested) of this including a proper written > changelog. > > Thanks, > > tglx > > 8<-------------- > Subject: time/alarmtimer: Add tracepoints for alarmtimer > From: John Stultz <john.stultz@linaro.org> > Date: Mon, 28 Nov 2016 14:35:21 -0800 > > From: Baolin Wang <baolin.wang@linaro.org> > > Alarm timers are one of the mechanisms to wake up a system from suspend, > but there exist no tracepoints to analyse which process/thread armed an > alarmtimer. > > Add tracepoints for start/cancel/expire of individual alarm timers and one > for tracing the suspend time decision when to resume the system. > > The following trace excerpt illustrates the new mechanism: > > Binder:3292_2-3304 [000] d..2 149.981123: alarmtimer_cancel: > alarmtimer:ffffffc1319a7800 type:REALTIME > expires:1325463120000000000 now:1325376810370370245 > > Binder:3292_2-3304 [000] d..2 149.981136: alarmtimer_start: > alarmtimer:ffffffc1319a7800 type:REALTIME > expires:1325376840000000000 now:1325376810370384591 > > Binder:3292_9-3953 [000] d..2 150.212991: alarmtimer_cancel: > alarmtimer:ffffffc1319a5a00 type:BOOTTIME > expires:179552000000 now:150154008122 > > Binder:3292_9-3953 [000] d..2 150.213006: alarmtimer_start: > alarmtimer:ffffffc1319a5a00 type:BOOTTIME > expires:179551000000 now:150154025622 > > system_server-3000 [002] ...1 162.701940: alarmtimer_suspend: > alarmtimer type:REALTIME expires:1325376840000000000 > > The wakeup time which is selected at suspend time allows to map it back to > the task arming the timer: Binder:3292_2. > > [ tglx: Store real alarm timer expiry time instead of some useless RTC > relative information, add proper type information for wakeups which > are handled via the clock_nanosleep/freezer and massage the > changelog. ] > > Signed-off-by: Baolin Wang <baolin.wang@linaro.org> > Signed-off-by: John Stultz <john.stultz@linaro.org> > Acked-by: Steven Rostedt <rostedt@goodmis.org> > Cc: Prarit Bhargava <prarit@redhat.com> > Cc: Richard Cochran <richardcochran@gmail.com> > Link: http://lkml.kernel.org/r/1480372524-15181-5-git-send-email-john.stultz@linaro.org > Signed-off-by: Thomas Gleixner <tglx@linutronix.de> Tested-by: Baolin Wang <baolin.wang@linaro.org> -- Baolin.wang Best Regards ^ permalink raw reply [flat|nested] 29+ messages in thread
* [tip:timers/core] alarmtimer: Add tracepoints for alarm timers 2016-11-28 22:35 ` [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer John Stultz 2016-11-29 7:23 ` Ingo Molnar 2016-11-29 12:06 ` Thomas Gleixner @ 2016-12-01 13:52 ` tip-bot for Baolin Wang 2 siblings, 0 replies; 29+ messages in thread From: tip-bot for Baolin Wang @ 2016-12-01 13:52 UTC (permalink / raw) To: linux-tip-commits Cc: baolin.wang, john.stultz, richardcochran, hpa, tglx, mingo, linux-kernel, rostedt, prarit Commit-ID: 4a057549d6044c2dea47e80f8369a76225ec9d90 Gitweb: http://git.kernel.org/tip/4a057549d6044c2dea47e80f8369a76225ec9d90 Author: Baolin Wang <baolin.wang@linaro.org> AuthorDate: Mon, 28 Nov 2016 14:35:21 -0800 Committer: Thomas Gleixner <tglx@linutronix.de> CommitDate: Thu, 1 Dec 2016 14:45:08 +0100 alarmtimer: Add tracepoints for alarm timers Alarm timers are one of the mechanisms to wake up a system from suspend, but there exist no tracepoints to analyse which process/thread armed an alarmtimer. Add tracepoints for start/cancel/expire of individual alarm timers and one for tracing the suspend time decision when to resume the system. The following trace excerpt illustrates the new mechanism: Binder:3292_2-3304 [000] d..2 149.981123: alarmtimer_cancel: alarmtimer:ffffffc1319a7800 type:REALTIME expires:1325463120000000000 now:1325376810370370245 Binder:3292_2-3304 [000] d..2 149.981136: alarmtimer_start: alarmtimer:ffffffc1319a7800 type:REALTIME expires:1325376840000000000 now:1325376810370384591 Binder:3292_9-3953 [000] d..2 150.212991: alarmtimer_cancel: alarmtimer:ffffffc1319a5a00 type:BOOTTIME expires:179552000000 now:150154008122 Binder:3292_9-3953 [000] d..2 150.213006: alarmtimer_start: alarmtimer:ffffffc1319a5a00 type:BOOTTIME expires:179551000000 now:150154025622 system_server-3000 [002] ...1 162.701940: alarmtimer_suspend: alarmtimer type:REALTIME expires:1325376840000000000 The wakeup time which is selected at suspend time allows to map it back to the task arming the timer: Binder:3292_2. [ tglx: Store alarm timer expiry time instead of some useless RTC relative information, add proper type information for wakeups which are handled via the clock_nanosleep/freezer and massage the changelog. ] Signed-off-by: Baolin Wang <baolin.wang@linaro.org> Signed-off-by: John Stultz <john.stultz@linaro.org> Acked-by: Steven Rostedt <rostedt@goodmis.org> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Link: http://lkml.kernel.org/r/1480372524-15181-5-git-send-email-john.stultz@linaro.org Signed-off-by: Thomas Gleixner <tglx@linutronix.de> --- include/linux/alarmtimer.h | 5 ++ include/trace/events/alarmtimer.h | 96 +++++++++++++++++++++++++++++++++++++++ kernel/time/alarmtimer.c | 53 +++++++++++++++++---- 3 files changed, 144 insertions(+), 10 deletions(-) diff --git a/include/linux/alarmtimer.h b/include/linux/alarmtimer.h index 9d80312..c70aac1 100644 --- a/include/linux/alarmtimer.h +++ b/include/linux/alarmtimer.h @@ -10,7 +10,12 @@ enum alarmtimer_type { ALARM_REALTIME, ALARM_BOOTTIME, + /* Supported types end here */ ALARM_NUMTYPE, + + /* Used for tracing information. No usable types. */ + ALARM_REALTIME_FREEZER, + ALARM_BOOTTIME_FREEZER, }; enum alarmtimer_restart { diff --git a/include/trace/events/alarmtimer.h b/include/trace/events/alarmtimer.h new file mode 100644 index 0000000..a1c108c --- /dev/null +++ b/include/trace/events/alarmtimer.h @@ -0,0 +1,96 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM alarmtimer + +#if !defined(_TRACE_ALARMTIMER_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_ALARMTIMER_H + +#include <linux/alarmtimer.h> +#include <linux/rtc.h> +#include <linux/tracepoint.h> + +TRACE_DEFINE_ENUM(ALARM_REALTIME); +TRACE_DEFINE_ENUM(ALARM_BOOTTIME); +TRACE_DEFINE_ENUM(ALARM_REALTIME_FREEZER); +TRACE_DEFINE_ENUM(ALARM_BOOTTIME_FREEZER); + +#define show_alarm_type(type) __print_flags(type, " | ", \ + { 1 << ALARM_REALTIME, "REALTIME" }, \ + { 1 << ALARM_BOOTTIME, "BOOTTIME" }, \ + { 1 << ALARM_REALTIME_FREEZER, "REALTIME Freezer" }, \ + { 1 << ALARM_BOOTTIME_FREEZER, "BOOTTIME Freezer" }) + +TRACE_EVENT(alarmtimer_suspend, + + TP_PROTO(ktime_t expires, int flag), + + TP_ARGS(expires, flag), + + TP_STRUCT__entry( + __field(s64, expires) + __field(unsigned char, alarm_type) + ), + + TP_fast_assign( + __entry->expires = expires.tv64; + __entry->alarm_type = flag; + ), + + TP_printk("alarmtimer type:%s expires:%llu", + show_alarm_type((1 << __entry->alarm_type)), + __entry->expires + ) +); + +DECLARE_EVENT_CLASS(alarm_class, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now), + + TP_STRUCT__entry( + __field(void *, alarm) + __field(unsigned char, alarm_type) + __field(s64, expires) + __field(s64, now) + ), + + TP_fast_assign( + __entry->alarm = alarm; + __entry->alarm_type = alarm->type; + __entry->expires = alarm->node.expires.tv64; + __entry->now = now.tv64; + ), + + TP_printk("alarmtimer:%p type:%s expires:%llu now:%llu", + __entry->alarm, + show_alarm_type((1 << __entry->alarm_type)), + __entry->expires, + __entry->now + ) +); + +DEFINE_EVENT(alarm_class, alarmtimer_fired, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +DEFINE_EVENT(alarm_class, alarmtimer_start, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +DEFINE_EVENT(alarm_class, alarmtimer_cancel, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +#endif /* _TRACE_ALARMTIMER_H */ + +/* This part must be outside protection */ +#include <trace/define_trace.h> diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c index a15caa3..9b08ca3 100644 --- a/kernel/time/alarmtimer.c +++ b/kernel/time/alarmtimer.c @@ -26,6 +26,9 @@ #include <linux/workqueue.h> #include <linux/freezer.h> +#define CREATE_TRACE_POINTS +#include <trace/events/alarmtimer.h> + /** * struct alarm_base - Alarm timer bases * @lock: Lock for syncrhonized access to the base @@ -40,7 +43,9 @@ static struct alarm_base { clockid_t base_clockid; } alarm_bases[ALARM_NUMTYPE]; -/* freezer delta & lock used to handle clock_nanosleep triggered wakeups */ +/* freezer information to handle clock_nanosleep triggered wakeups */ +static enum alarmtimer_type freezer_alarmtype; +static ktime_t freezer_expires; static ktime_t freezer_delta; static DEFINE_SPINLOCK(freezer_delta_lock); @@ -194,6 +199,7 @@ static enum hrtimer_restart alarmtimer_fired(struct hrtimer *timer) } spin_unlock_irqrestore(&base->lock, flags); + trace_alarmtimer_fired(alarm, base->gettime()); return ret; } @@ -218,15 +224,16 @@ EXPORT_SYMBOL_GPL(alarm_expires_remaining); */ static int alarmtimer_suspend(struct device *dev) { - struct rtc_time tm; - ktime_t min, now; - unsigned long flags; + ktime_t min, now, expires; + int i, ret, type; struct rtc_device *rtc; - int i; - int ret; + unsigned long flags; + struct rtc_time tm; spin_lock_irqsave(&freezer_delta_lock, flags); min = freezer_delta; + expires = freezer_expires; + type = freezer_alarmtype; freezer_delta = ktime_set(0, 0); spin_unlock_irqrestore(&freezer_delta_lock, flags); @@ -247,8 +254,11 @@ static int alarmtimer_suspend(struct device *dev) if (!next) continue; delta = ktime_sub(next->expires, base->gettime()); - if (!min.tv64 || (delta.tv64 < min.tv64)) + if (!min.tv64 || (delta.tv64 < min.tv64)) { + expires = next->expires; min = delta; + type = i; + } } if (min.tv64 == 0) return 0; @@ -258,6 +268,8 @@ static int alarmtimer_suspend(struct device *dev) return -EBUSY; } + trace_alarmtimer_suspend(expires, type); + /* Setup an rtc timer to fire that far in the future */ rtc_timer_cancel(rtc, &rtctimer); rtc_read_time(rtc, &tm); @@ -295,15 +307,32 @@ static int alarmtimer_resume(struct device *dev) static void alarmtimer_freezerset(ktime_t absexp, enum alarmtimer_type type) { - ktime_t delta; + struct alarm_base *base; unsigned long flags; - struct alarm_base *base = &alarm_bases[type]; + ktime_t delta; + + switch(type) { + case ALARM_REALTIME: + base = &alarm_bases[ALARM_REALTIME]; + type = ALARM_REALTIME_FREEZER; + break; + case ALARM_BOOTTIME: + base = &alarm_bases[ALARM_BOOTTIME]; + type = ALARM_BOOTTIME_FREEZER; + break; + default: + WARN_ONCE(1, "Invalid alarm type: %d\n", type); + return; + } delta = ktime_sub(absexp, base->gettime()); spin_lock_irqsave(&freezer_delta_lock, flags); - if (!freezer_delta.tv64 || (delta.tv64 < freezer_delta.tv64)) + if (!freezer_delta.tv64 || (delta.tv64 < freezer_delta.tv64)) { freezer_delta = delta; + freezer_expires = absexp; + freezer_alarmtype = type; + } spin_unlock_irqrestore(&freezer_delta_lock, flags); } @@ -342,6 +371,8 @@ void alarm_start(struct alarm *alarm, ktime_t start) alarmtimer_enqueue(base, alarm); hrtimer_start(&alarm->timer, alarm->node.expires, HRTIMER_MODE_ABS); spin_unlock_irqrestore(&base->lock, flags); + + trace_alarmtimer_start(alarm, base->gettime()); } EXPORT_SYMBOL_GPL(alarm_start); @@ -390,6 +421,8 @@ int alarm_try_to_cancel(struct alarm *alarm) if (ret >= 0) alarmtimer_dequeue(base, alarm); spin_unlock_irqrestore(&base->lock, flags); + + trace_alarmtimer_cancel(alarm, base->gettime()); return ret; } EXPORT_SYMBOL_GPL(alarm_try_to_cancel); ^ permalink raw reply related [flat|nested] 29+ messages in thread
* [PATCH 5/7] timekeeping: Add a fast and NMI safe boot clock 2016-11-28 22:35 [GIT PULL][PATCH 0/7] Timekeeping changes for 4.10 (take 2) John Stultz ` (3 preceding siblings ...) 2016-11-28 22:35 ` [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer John Stultz @ 2016-11-28 22:35 ` John Stultz 2016-11-29 17:11 ` [tip:timers/core] " tip-bot for Joel Fernandes 2016-11-28 22:35 ` [PATCH 6/7] trace: Add an option for boot clock as trace clock John Stultz 2016-11-28 22:35 ` [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock John Stultz 6 siblings, 1 reply; 29+ messages in thread From: John Stultz @ 2016-11-28 22:35 UTC (permalink / raw) To: lkml Cc: Joel Fernandes, Steven Rostedt, Thomas Gleixner, Ingo Molnar, Richard Cochran, Prarit Bhargava, John Stultz From: Joel Fernandes <joelaf@google.com> This boot clock can be used as a tracing clock and will account for suspend time. To keep it NMI safe since we're accessing from tracing, we're not using a separate timekeeper with updates to monotonic clock and boot offset protected with seqlocks. This has the following minor side effects: (1) Its possible that a timestamp be taken after the boot offset is updated but before the timekeeper is updated. If this happens, the new boot offset is added to the old timekeeping making the clock appear to update slightly earlier: CPU 0 CPU 1 timekeeping_inject_sleeptime64() __timekeeping_inject_sleeptime(tk, delta); timestamp(); timekeeping_update(tk, TK_CLEAR_NTP...); (2) On 32-bit systems, the 64-bit boot offset (tk->offs_boot) may be partially updated. Since the tk->offs_boot update is a rare event, this should be a rare occurrence which postprocessing should be able to handle. Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: Ingo Molnar <mingo@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Cc: Prarit Bhargava <prarit@redhat.com> Reviewed-by: Thomas Gleixner <tglx@linutronix.de> Signed-off-by: Joel Fernandes <joelaf@google.com> Signed-off-by: John Stultz <john.stultz@linaro.org> --- include/linux/timekeeping.h | 1 + kernel/time/timekeeping.c | 29 +++++++++++++++++++++++++++++ 2 files changed, 30 insertions(+) diff --git a/include/linux/timekeeping.h b/include/linux/timekeeping.h index 09168c5..361f8bf 100644 --- a/include/linux/timekeeping.h +++ b/include/linux/timekeeping.h @@ -249,6 +249,7 @@ static inline u64 ktime_get_raw_ns(void) extern u64 ktime_get_mono_fast_ns(void); extern u64 ktime_get_raw_fast_ns(void); +extern u64 ktime_get_boot_fast_ns(void); /* * Timespec interfaces utilizing the ktime based ones diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c index 37dec7e..b2286e9 100644 --- a/kernel/time/timekeeping.c +++ b/kernel/time/timekeeping.c @@ -425,6 +425,35 @@ u64 ktime_get_raw_fast_ns(void) } EXPORT_SYMBOL_GPL(ktime_get_raw_fast_ns); +/** + * ktime_get_boot_fast_ns - NMI safe and fast access to boot clock. + * + * To keep it NMI safe since we're accessing from tracing, we're not using a + * separate timekeeper with updates to monotonic clock and boot offset + * protected with seqlocks. This has the following minor side effects: + * + * (1) Its possible that a timestamp be taken after the boot offset is updated + * but before the timekeeper is updated. If this happens, the new boot offset + * is added to the old timekeeping making the clock appear to update slightly + * earlier: + * CPU 0 CPU 1 + * timekeeping_inject_sleeptime64() + * __timekeeping_inject_sleeptime(tk, delta); + * timestamp(); + * timekeeping_update(tk, TK_CLEAR_NTP...); + * + * (2) On 32-bit systems, the 64-bit boot offset (tk->offs_boot) may be + * partially updated. Since the tk->offs_boot update is a rare event, this + * should be a rare occurrence which postprocessing should be able to handle. + */ +u64 notrace ktime_get_boot_fast_ns(void) +{ + struct timekeeper *tk = &tk_core.timekeeper; + + return (ktime_get_mono_fast_ns() + ktime_to_ns(tk->offs_boot)); +} +EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns); + /* Suspend-time cycles value for halted fast timekeeper. */ static cycle_t cycles_at_suspend; -- 2.7.4 ^ permalink raw reply related [flat|nested] 29+ messages in thread
* [tip:timers/core] timekeeping: Add a fast and NMI safe boot clock 2016-11-28 22:35 ` [PATCH 5/7] timekeeping: Add a fast and NMI safe boot clock John Stultz @ 2016-11-29 17:11 ` tip-bot for Joel Fernandes 0 siblings, 0 replies; 29+ messages in thread From: tip-bot for Joel Fernandes @ 2016-11-29 17:11 UTC (permalink / raw) To: linux-tip-commits Cc: prarit, tglx, rostedt, mingo, linux-kernel, richardcochran, john.stultz, hpa, joelaf Commit-ID: 948a5312f41658f7b76a598a139ef1f4dea09ca9 Gitweb: http://git.kernel.org/tip/948a5312f41658f7b76a598a139ef1f4dea09ca9 Author: Joel Fernandes <joelaf@google.com> AuthorDate: Mon, 28 Nov 2016 14:35:22 -0800 Committer: Thomas Gleixner <tglx@linutronix.de> CommitDate: Tue, 29 Nov 2016 18:02:59 +0100 timekeeping: Add a fast and NMI safe boot clock This boot clock can be used as a tracing clock and will account for suspend time. To keep it NMI safe since we're accessing from tracing, we're not using a separate timekeeper with updates to monotonic clock and boot offset protected with seqlocks. This has the following minor side effects: (1) Its possible that a timestamp be taken after the boot offset is updated but before the timekeeper is updated. If this happens, the new boot offset is added to the old timekeeping making the clock appear to update slightly earlier: CPU 0 CPU 1 timekeeping_inject_sleeptime64() __timekeeping_inject_sleeptime(tk, delta); timestamp(); timekeeping_update(tk, TK_CLEAR_NTP...); (2) On 32-bit systems, the 64-bit boot offset (tk->offs_boot) may be partially updated. Since the tk->offs_boot update is a rare event, this should be a rare occurrence which postprocessing should be able to handle. Signed-off-by: Joel Fernandes <joelaf@google.com> Signed-off-by: John Stultz <john.stultz@linaro.org> Reviewed-by: Thomas Gleixner <tglx@linutronix.de> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Cc: Steven Rostedt <rostedt@goodmis.org> Link: http://lkml.kernel.org/r/1480372524-15181-6-git-send-email-john.stultz@linaro.org Signed-off-by: Thomas Gleixner <tglx@linutronix.de> --- include/linux/timekeeping.h | 1 + kernel/time/timekeeping.c | 29 +++++++++++++++++++++++++++++ 2 files changed, 30 insertions(+) diff --git a/include/linux/timekeeping.h b/include/linux/timekeeping.h index 09168c5..361f8bf 100644 --- a/include/linux/timekeeping.h +++ b/include/linux/timekeeping.h @@ -249,6 +249,7 @@ static inline u64 ktime_get_raw_ns(void) extern u64 ktime_get_mono_fast_ns(void); extern u64 ktime_get_raw_fast_ns(void); +extern u64 ktime_get_boot_fast_ns(void); /* * Timespec interfaces utilizing the ktime based ones diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c index 37dec7e..b2286e9 100644 --- a/kernel/time/timekeeping.c +++ b/kernel/time/timekeeping.c @@ -425,6 +425,35 @@ u64 ktime_get_raw_fast_ns(void) } EXPORT_SYMBOL_GPL(ktime_get_raw_fast_ns); +/** + * ktime_get_boot_fast_ns - NMI safe and fast access to boot clock. + * + * To keep it NMI safe since we're accessing from tracing, we're not using a + * separate timekeeper with updates to monotonic clock and boot offset + * protected with seqlocks. This has the following minor side effects: + * + * (1) Its possible that a timestamp be taken after the boot offset is updated + * but before the timekeeper is updated. If this happens, the new boot offset + * is added to the old timekeeping making the clock appear to update slightly + * earlier: + * CPU 0 CPU 1 + * timekeeping_inject_sleeptime64() + * __timekeeping_inject_sleeptime(tk, delta); + * timestamp(); + * timekeeping_update(tk, TK_CLEAR_NTP...); + * + * (2) On 32-bit systems, the 64-bit boot offset (tk->offs_boot) may be + * partially updated. Since the tk->offs_boot update is a rare event, this + * should be a rare occurrence which postprocessing should be able to handle. + */ +u64 notrace ktime_get_boot_fast_ns(void) +{ + struct timekeeper *tk = &tk_core.timekeeper; + + return (ktime_get_mono_fast_ns() + ktime_to_ns(tk->offs_boot)); +} +EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns); + /* Suspend-time cycles value for halted fast timekeeper. */ static cycle_t cycles_at_suspend; ^ permalink raw reply related [flat|nested] 29+ messages in thread
* [PATCH 6/7] trace: Add an option for boot clock as trace clock 2016-11-28 22:35 [GIT PULL][PATCH 0/7] Timekeeping changes for 4.10 (take 2) John Stultz ` (4 preceding siblings ...) 2016-11-28 22:35 ` [PATCH 5/7] timekeeping: Add a fast and NMI safe boot clock John Stultz @ 2016-11-28 22:35 ` John Stultz 2016-11-28 23:05 ` Steven Rostedt 2016-11-29 17:12 ` [tip:timers/core] " tip-bot for Joel Fernandes 2016-11-28 22:35 ` [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock John Stultz 6 siblings, 2 replies; 29+ messages in thread From: John Stultz @ 2016-11-28 22:35 UTC (permalink / raw) To: lkml Cc: Joel Fernandes, Steven Rostedt, Thomas Gleixner, Ingo Molnar, Richard Cochran, Prarit Bhargava, John Stultz From: Joel Fernandes <joelaf@google.com> Unlike monotonic clock, boot clock as a trace clock will account for time spent in suspend useful for tracing suspend/resume. This uses earlier introduced infrastructure for using the fast boot clock. Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: Ingo Molnar <mingo@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Cc: Prarit Bhargava <prarit@redhat.com> Reviewed-by: Thomas Gleixner <tglx@linutronix.de> Signed-off-by: Joel Fernandes <joelaf@google.com> Signed-off-by: John Stultz <john.stultz@linaro.org> --- kernel/trace/trace.c | 1 + 1 file changed, 1 insertion(+) diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 8696ce6..f7b64db 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -1125,6 +1125,7 @@ static struct { { trace_clock, "perf", 1 }, { ktime_get_mono_fast_ns, "mono", 1 }, { ktime_get_raw_fast_ns, "mono_raw", 1 }, + { ktime_get_boot_fast_ns, "boot", 1 }, ARCH_TRACE_CLOCKS }; -- 2.7.4 ^ permalink raw reply related [flat|nested] 29+ messages in thread
* Re: [PATCH 6/7] trace: Add an option for boot clock as trace clock 2016-11-28 22:35 ` [PATCH 6/7] trace: Add an option for boot clock as trace clock John Stultz @ 2016-11-28 23:05 ` Steven Rostedt 2016-11-29 17:12 ` [tip:timers/core] " tip-bot for Joel Fernandes 1 sibling, 0 replies; 29+ messages in thread From: Steven Rostedt @ 2016-11-28 23:05 UTC (permalink / raw) To: John Stultz Cc: lkml, Joel Fernandes, Thomas Gleixner, Ingo Molnar, Richard Cochran, Prarit Bhargava On Mon, 28 Nov 2016 14:35:23 -0800 John Stultz <john.stultz@linaro.org> wrote: > From: Joel Fernandes <joelaf@google.com> > > Unlike monotonic clock, boot clock as a trace clock will account for > time spent in suspend useful for tracing suspend/resume. This uses > earlier introduced infrastructure for using the fast boot clock. > Acked-by: Steven Rostedt <rostedt@goodmis.org> -- Steve > Cc: Steven Rostedt <rostedt@goodmis.org> > Cc: Thomas Gleixner <tglx@linutronix.de> > Cc: Ingo Molnar <mingo@redhat.com> > Cc: Richard Cochran <richardcochran@gmail.com> > Cc: Prarit Bhargava <prarit@redhat.com> > Reviewed-by: Thomas Gleixner <tglx@linutronix.de> > Signed-off-by: Joel Fernandes <joelaf@google.com> > Signed-off-by: John Stultz <john.stultz@linaro.org> > --- > kernel/trace/trace.c | 1 + > 1 file changed, 1 insertion(+) > > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index 8696ce6..f7b64db 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -1125,6 +1125,7 @@ static struct { > { trace_clock, "perf", 1 }, > { ktime_get_mono_fast_ns, "mono", 1 }, > { ktime_get_raw_fast_ns, "mono_raw", 1 }, > + { ktime_get_boot_fast_ns, "boot", 1 }, > ARCH_TRACE_CLOCKS > }; > ^ permalink raw reply [flat|nested] 29+ messages in thread
* [tip:timers/core] trace: Add an option for boot clock as trace clock 2016-11-28 22:35 ` [PATCH 6/7] trace: Add an option for boot clock as trace clock John Stultz 2016-11-28 23:05 ` Steven Rostedt @ 2016-11-29 17:12 ` tip-bot for Joel Fernandes 1 sibling, 0 replies; 29+ messages in thread From: tip-bot for Joel Fernandes @ 2016-11-29 17:12 UTC (permalink / raw) To: linux-tip-commits Cc: mingo, richardcochran, tglx, rostedt, joelaf, hpa, prarit, john.stultz, linux-kernel Commit-ID: 80ec3552107ac16a836dbff4cf3c23fdd3256ee3 Gitweb: http://git.kernel.org/tip/80ec3552107ac16a836dbff4cf3c23fdd3256ee3 Author: Joel Fernandes <joelaf@google.com> AuthorDate: Mon, 28 Nov 2016 14:35:23 -0800 Committer: Thomas Gleixner <tglx@linutronix.de> CommitDate: Tue, 29 Nov 2016 18:02:59 +0100 trace: Add an option for boot clock as trace clock Unlike monotonic clock, boot clock as a trace clock will account for time spent in suspend useful for tracing suspend/resume. This uses earlier introduced infrastructure for using the fast boot clock. Signed-off-by: Joel Fernandes <joelaf@google.com> Signed-off-by: John Stultz <john.stultz@linaro.org> Reviewed-by: Thomas Gleixner <tglx@linutronix.de> Acked-by: Steven Rostedt <rostedt@goodmis.org> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Link: http://lkml.kernel.org/r/1480372524-15181-7-git-send-email-john.stultz@linaro.org Signed-off-by: Thomas Gleixner <tglx@linutronix.de> --- kernel/trace/trace.c | 1 + 1 file changed, 1 insertion(+) diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 8696ce6..f7b64db 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -1125,6 +1125,7 @@ static struct { { trace_clock, "perf", 1 }, { ktime_get_mono_fast_ns, "mono", 1 }, { ktime_get_raw_fast_ns, "mono_raw", 1 }, + { ktime_get_boot_fast_ns, "boot", 1 }, ARCH_TRACE_CLOCKS }; ^ permalink raw reply related [flat|nested] 29+ messages in thread
* [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock 2016-11-28 22:35 [GIT PULL][PATCH 0/7] Timekeeping changes for 4.10 (take 2) John Stultz ` (5 preceding siblings ...) 2016-11-28 22:35 ` [PATCH 6/7] trace: Add an option for boot clock as trace clock John Stultz @ 2016-11-28 22:35 ` John Stultz 2016-11-28 23:07 ` Steven Rostedt ` (2 more replies) 6 siblings, 3 replies; 29+ messages in thread From: John Stultz @ 2016-11-28 22:35 UTC (permalink / raw) To: lkml Cc: Joel Fernandes, Steven Rostedt, Thomas Gleixner, Ingo Molnar, Richard Cochran, Prarit Bhargava, John Stultz From: Joel Fernandes <joelaf@google.com> Documentation was missing for mono and mono_raw, add them and also for the boot clock introduced in this series. Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: Ingo Molnar <mingo@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Cc: Prarit Bhargava <prarit@redhat.com> Reviewed-by: Thomas Gleixner <tglx@linutronix.de> Signed-off-by: Joel Fernandes <joelaf@google.com> Signed-off-by: John Stultz <john.stultz@linaro.org> --- Documentation/trace/ftrace.txt | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt index 185c39f..5180b09 100644 --- a/Documentation/trace/ftrace.txt +++ b/Documentation/trace/ftrace.txt @@ -362,6 +362,26 @@ of ftrace. Here is a list of some of the key files: to correlate events across hypervisor/guest if tb_offset is known. + mono: This uses the fast monotonic clock (CLOCK_MONOTONIC) + which is monotonic and is subject to NTP rate adjustments. + + mono_raw: + This is the raw monotonic clock (CLOCK_MONOTONIC_RAW) + which is montonic but is not subject to any rate adjustments + and ticks at the same rate as the hardware clocksource. + + boot: This is the boot clock (CLOCK_BOOTTIME) and is based on the + fast monotonic clock, but also accounts for time spent in + suspend. Since the clock access is designed for use in + tracing in the suspend path, some side effects are possible + if clock is accessed after the suspend time is accounted before + the fast mono clock is updated. In this case, the clock update + appears to happen slightly sooner than it normally would have. + Also on 32-bit systems, its possible that the 64-bit boot offset + sees a partial update. These effects are rare and post + processing should be able to handle them. See comments on + ktime_get_boot_fast_ns function for more information. + To set a clock, simply echo the clock name into this file. echo global > trace_clock -- 2.7.4 ^ permalink raw reply related [flat|nested] 29+ messages in thread
* Re: [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock 2016-11-28 22:35 ` [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock John Stultz @ 2016-11-28 23:07 ` Steven Rostedt 2016-11-29 7:26 ` Ingo Molnar 2016-11-29 17:13 ` [tip:timers/core] " tip-bot for Joel Fernandes 2 siblings, 0 replies; 29+ messages in thread From: Steven Rostedt @ 2016-11-28 23:07 UTC (permalink / raw) To: John Stultz Cc: lkml, Joel Fernandes, Thomas Gleixner, Ingo Molnar, Richard Cochran, Prarit Bhargava On Mon, 28 Nov 2016 14:35:24 -0800 John Stultz <john.stultz@linaro.org> wrote: > From: Joel Fernandes <joelaf@google.com> > > Documentation was missing for mono and mono_raw, add them and also for > the boot clock introduced in this series. > > Cc: Steven Rostedt <rostedt@goodmis.org> Acked-by: Steven Rostedt <rostedt@goodmis.org> -- Steve > Cc: Thomas Gleixner <tglx@linutronix.de> > Cc: Ingo Molnar <mingo@redhat.com> > Cc: Richard Cochran <richardcochran@gmail.com> > Cc: Prarit Bhargava <prarit@redhat.com> > Reviewed-by: Thomas Gleixner <tglx@linutronix.de> > Signed-off-by: Joel Fernandes <joelaf@google.com> > Signed-off-by: John Stultz <john.stultz@linaro.org> > --- ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock 2016-11-28 22:35 ` [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock John Stultz 2016-11-28 23:07 ` Steven Rostedt @ 2016-11-29 7:26 ` Ingo Molnar 2016-11-29 16:10 ` Joel Fernandes 2016-11-29 17:13 ` [tip:timers/core] " tip-bot for Joel Fernandes 2 siblings, 1 reply; 29+ messages in thread From: Ingo Molnar @ 2016-11-29 7:26 UTC (permalink / raw) To: John Stultz Cc: lkml, Joel Fernandes, Steven Rostedt, Thomas Gleixner, Ingo Molnar, Richard Cochran, Prarit Bhargava * John Stultz <john.stultz@linaro.org> wrote: > + boot: This is the boot clock (CLOCK_BOOTTIME) and is based on the > + fast monotonic clock, but also accounts for time spent in > + suspend. Since the clock access is designed for use in > + tracing in the suspend path, some side effects are possible > + if clock is accessed after the suspend time is accounted before > + the fast mono clock is updated. In this case, the clock update > + appears to happen slightly sooner than it normally would have. > + Also on 32-bit systems, its possible that the 64-bit boot offset > + sees a partial update. These effects are rare and post > + processing should be able to handle them. See comments on > + ktime_get_boot_fast_ns function for more information. s/its possible/it's possible s/comments on ktime_get_boost_fast_ns function/comments in the ktime_get_boost_fast_ns() function Thanks, Ingo ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock 2016-11-29 7:26 ` Ingo Molnar @ 2016-11-29 16:10 ` Joel Fernandes 2016-11-29 16:11 ` Thomas Gleixner 0 siblings, 1 reply; 29+ messages in thread From: Joel Fernandes @ 2016-11-29 16:10 UTC (permalink / raw) To: Ingo Molnar Cc: John Stultz, lkml, Steven Rostedt, Thomas Gleixner, Ingo Molnar, Richard Cochran, Prarit Bhargava On Mon, Nov 28, 2016 at 11:26 PM, Ingo Molnar <mingo@kernel.org> wrote: > > * John Stultz <john.stultz@linaro.org> wrote: > >> + boot: This is the boot clock (CLOCK_BOOTTIME) and is based on the >> + fast monotonic clock, but also accounts for time spent in >> + suspend. Since the clock access is designed for use in >> + tracing in the suspend path, some side effects are possible >> + if clock is accessed after the suspend time is accounted before >> + the fast mono clock is updated. In this case, the clock update >> + appears to happen slightly sooner than it normally would have. >> + Also on 32-bit systems, its possible that the 64-bit boot offset >> + sees a partial update. These effects are rare and post >> + processing should be able to handle them. See comments on >> + ktime_get_boot_fast_ns function for more information. > > s/its possible/it's possible > s/comments on ktime_get_boost_fast_ns function/comments in the ktime_get_boost_fast_ns() function > Thanks, I'll fix these up and repost. Regards, Joel > Thanks, > > Ingo ^ permalink raw reply [flat|nested] 29+ messages in thread
* Re: [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock 2016-11-29 16:10 ` Joel Fernandes @ 2016-11-29 16:11 ` Thomas Gleixner 0 siblings, 0 replies; 29+ messages in thread From: Thomas Gleixner @ 2016-11-29 16:11 UTC (permalink / raw) To: Joel Fernandes Cc: Ingo Molnar, John Stultz, lkml, Steven Rostedt, Ingo Molnar, Richard Cochran, Prarit Bhargava On Tue, 29 Nov 2016, Joel Fernandes wrote: > On Mon, Nov 28, 2016 at 11:26 PM, Ingo Molnar <mingo@kernel.org> wrote: > > > > * John Stultz <john.stultz@linaro.org> wrote: > > > >> + boot: This is the boot clock (CLOCK_BOOTTIME) and is based on the > >> + fast monotonic clock, but also accounts for time spent in > >> + suspend. Since the clock access is designed for use in > >> + tracing in the suspend path, some side effects are possible > >> + if clock is accessed after the suspend time is accounted before > >> + the fast mono clock is updated. In this case, the clock update > >> + appears to happen slightly sooner than it normally would have. > >> + Also on 32-bit systems, its possible that the 64-bit boot offset > >> + sees a partial update. These effects are rare and post > >> + processing should be able to handle them. See comments on > >> + ktime_get_boot_fast_ns function for more information. > > > > s/its possible/it's possible > > s/comments on ktime_get_boost_fast_ns function/comments in the ktime_get_boost_fast_ns() function > > > > Thanks, I'll fix these up and repost. Don't bother. I have fixed it up locally already. Thanks, tglx ^ permalink raw reply [flat|nested] 29+ messages in thread
* [tip:timers/core] trace: Update documentation for mono, mono_raw and boot clock 2016-11-28 22:35 ` [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock John Stultz 2016-11-28 23:07 ` Steven Rostedt 2016-11-29 7:26 ` Ingo Molnar @ 2016-11-29 17:13 ` tip-bot for Joel Fernandes 2 siblings, 0 replies; 29+ messages in thread From: tip-bot for Joel Fernandes @ 2016-11-29 17:13 UTC (permalink / raw) To: linux-tip-commits Cc: rostedt, linux-kernel, richardcochran, tglx, hpa, joelaf, prarit, mingo, john.stultz Commit-ID: 2924ecd441f3c12da59b297daade265f49d0831b Gitweb: http://git.kernel.org/tip/2924ecd441f3c12da59b297daade265f49d0831b Author: Joel Fernandes <joelaf@google.com> AuthorDate: Mon, 28 Nov 2016 14:35:24 -0800 Committer: Thomas Gleixner <tglx@linutronix.de> CommitDate: Tue, 29 Nov 2016 18:03:00 +0100 trace: Update documentation for mono, mono_raw and boot clock Documentation was missing for mono and mono_raw, add them and also for the boot clock introduced in this series. Signed-off-by: Joel Fernandes <joelaf@google.com> Signed-off-by: John Stultz <john.stultz@linaro.org> Reviewed-by: Thomas Gleixner <tglx@linutronix.de> Acked-by: Steven Rostedt <rostedt@goodmis.org> Cc: Prarit Bhargava <prarit@redhat.com> Cc: Richard Cochran <richardcochran@gmail.com> Link: http://lkml.kernel.org/r/1480372524-15181-8-git-send-email-john.stultz@linaro.org Signed-off-by: Thomas Gleixner <tglx@linutronix.de> --- Documentation/trace/ftrace.txt | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt index 185c39f..5596e2d 100644 --- a/Documentation/trace/ftrace.txt +++ b/Documentation/trace/ftrace.txt @@ -362,6 +362,26 @@ of ftrace. Here is a list of some of the key files: to correlate events across hypervisor/guest if tb_offset is known. + mono: This uses the fast monotonic clock (CLOCK_MONOTONIC) + which is monotonic and is subject to NTP rate adjustments. + + mono_raw: + This is the raw monotonic clock (CLOCK_MONOTONIC_RAW) + which is montonic but is not subject to any rate adjustments + and ticks at the same rate as the hardware clocksource. + + boot: This is the boot clock (CLOCK_BOOTTIME) and is based on the + fast monotonic clock, but also accounts for time spent in + suspend. Since the clock access is designed for use in + tracing in the suspend path, some side effects are possible + if clock is accessed after the suspend time is accounted before + the fast mono clock is updated. In this case, the clock update + appears to happen slightly sooner than it normally would have. + Also on 32-bit systems, it's possible that the 64-bit boot offset + sees a partial update. These effects are rare and post + processing should be able to handle them. See comments in the + ktime_get_boot_fast_ns() function for more information. + To set a clock, simply echo the clock name into this file. echo global > trace_clock ^ permalink raw reply related [flat|nested] 29+ messages in thread
end of thread, other threads:[~2016-12-01 13:52 UTC | newest] Thread overview: 29+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2016-11-28 22:35 [GIT PULL][PATCH 0/7] Timekeeping changes for 4.10 (take 2) John Stultz 2016-11-28 22:35 ` [PATCH 1/7] selftests/timers: Fix spelling mistake "Asyncrhonous" -> "Asynchronous" John Stultz 2016-11-29 17:10 ` [tip:timers/core] " tip-bot for Colin Ian King 2016-11-28 22:35 ` [PATCH 2/7] timekeeping: Ignore the bogus sleep time if pm_trace is enabled John Stultz 2016-11-29 7:19 ` Ingo Molnar 2016-11-29 9:38 ` Chen Yu 2016-11-29 17:10 ` [tip:timers/core] " tip-bot for Chen Yu 2016-11-28 22:35 ` [PATCH 3/7] timekeeping: clocksource_cyc2ns: Document intended range limitation John Stultz 2016-11-29 17:11 ` [tip:timers/core] timekeeping/clocksource_cyc2ns: " tip-bot for Chris Metcalf 2016-11-28 22:35 ` [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer John Stultz 2016-11-29 7:23 ` Ingo Molnar 2016-11-29 8:23 ` Baolin Wang 2016-11-29 9:12 ` Ingo Molnar 2016-11-29 11:52 ` Baolin Wang 2016-11-29 12:06 ` Thomas Gleixner 2016-11-30 11:43 ` Baolin Wang 2016-12-01 2:34 ` Baolin Wang 2016-12-01 13:52 ` [tip:timers/core] alarmtimer: Add tracepoints for alarm timers tip-bot for Baolin Wang 2016-11-28 22:35 ` [PATCH 5/7] timekeeping: Add a fast and NMI safe boot clock John Stultz 2016-11-29 17:11 ` [tip:timers/core] " tip-bot for Joel Fernandes 2016-11-28 22:35 ` [PATCH 6/7] trace: Add an option for boot clock as trace clock John Stultz 2016-11-28 23:05 ` Steven Rostedt 2016-11-29 17:12 ` [tip:timers/core] " tip-bot for Joel Fernandes 2016-11-28 22:35 ` [PATCH 7/7] trace: Update documentation for mono, mono_raw and boot clock John Stultz 2016-11-28 23:07 ` Steven Rostedt 2016-11-29 7:26 ` Ingo Molnar 2016-11-29 16:10 ` Joel Fernandes 2016-11-29 16:11 ` Thomas Gleixner 2016-11-29 17:13 ` [tip:timers/core] " tip-bot for Joel Fernandes
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.