| Message ID | 1480372524-15181-5-git-send-email-john.stultz@linaro.org |
|---|---|
| State | New |
| Headers | show |
* 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
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
* 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
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
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
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
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);