Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1531747 > unrolled thread

[PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer John Stultz <john.stultz@linaro.org> - 2016-11-28 23:40 +0100
    Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer Ingo Molnar <mingo@kernel.org> - 2016-11-29 08:30 +0100
      Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer Baolin Wang <baolin.wang@linaro.org> - 2016-11-29 09:30 +0100
        Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer Ingo Molnar <mingo@kernel.org> - 2016-11-29 10:20 +0100
          Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer Baolin Wang <baolin.wang@linaro.org> - 2016-11-29 13:00 +0100
    Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for  alarmtimer Thomas Gleixner <tglx@linutronix.de> - 2016-11-29 13:10 +0100
      Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer Baolin Wang <baolin.wang@linaro.org> - 2016-11-30 12:50 +0100
      Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer Baolin Wang <baolin.wang@linaro.org> - 2016-12-01 03:40 +0100
    [tip:timers/core] alarmtimer: Add tracepoints for alarm timers tip-bot for Baolin Wang <tipbot@zytor.com> - 2016-12-01 15:00 +0100

#1531747 — [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer

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

[toc] | [next] | [standalone]

#1531965

* 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

[toc] | [prev] | [next] | [standalone]

#1531990

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

[toc] | [prev] | [next] | [standalone]

#1532022

* 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

[toc] | [prev] | [next] | [standalone]

#1532210

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

[toc] | [prev] | [next] | [standalone]

#1532229 — Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer

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);

[toc] | [prev] | [next] | [standalone]

#1533246

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

[toc] | [prev] | [next] | [standalone]

#1533757

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

[toc] | [prev] | [next] | [standalone]

#1534108 — [tip:timers/core] alarmtimer: Add tracepoints for alarm timers

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);

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web