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

Groups > linux.kernel > #1477977 > unrolled thread

[PATCH v4] time: alarmtimer: Add the trcepoints for alarmtimer

Back to article view | Back to linux.kernel

Contents

  [PATCH v4] time: alarmtimer: Add the trcepoints for alarmtimer Baolin Wang <baolin.wang@linaro.org> - 2016-09-07 08:10 +0200
    Re: [PATCH v4] time: alarmtimer: Add the trcepoints for alarmtimer John Stultz <john.stultz@linaro.org> - 2016-09-07 08:20 +0200
      Re: [PATCH v4] time: alarmtimer: Add the trcepoints for alarmtimer Baolin Wang <baolin.wang@linaro.org> - 2016-09-07 08:30 +0200
      Re: [PATCH v4] time: alarmtimer: Add the trcepoints for alarmtimer Thomas Gleixner <tglx@linutronix.de> - 2016-09-07 18:10 +0200
        Re: [PATCH v4] time: alarmtimer: Add the trcepoints for alarmtimer Baolin Wang <baolin.wang@linaro.org> - 2016-09-08 04:50 +0200

#1477977 — [PATCH v4] time: alarmtimer: Add the trcepoints for alarmtimer

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:2976_6-3473  [005] d..2  1076.587732: alarmtimer_start:
process:Binder:2976_6
alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1
0:20:35

Binder:2976_7-3480  [002] d..2  1076.592707: alarmtimer_cancel:
process:Binder:2976_7
alarmtimer type:ALARM_BOOTTIME expires:1325463060000000000 time:
2012-1-2 0:11:0

Binder:2976_7-3480  [002] d..2  1076.592731: alarmtimer_start:
process:Binder:2976_7
alarmtimer type:ALARM_BOOTTIME expires:1325378040000000000 time:
2012-1-1 0:34:0

system_server-2976  [003] d..2  1076.605587: alarmtimer_cancel:
process:system_server
alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1
0:20:35

system_server-2976  [003] d..2  1076.605608: alarmtimer_start:
process:system_server
alarmtimer type:ALARM_BOOTTIME expires:1234155000000 time: 1970-1-1
0:20:35

system_server-3000  [002] ...1  1087.737565: alarmtimer_suspend:
alarmtimer type:ALARM_BOOTTIME
expires time: 2012-1-1 0:34:0
......

From the trace log, we can find out the 'Binder:2976_7' process
set one alarm timer which resumes the system.

Signed-off-by: Baolin Wang <baolin.wang@linaro.org>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
---
Changes since v3:
 - Fix the build error on S390.

Changes since v2:
 - Add TRACE_DEFINE_ENUM() macros.
 - Change the time variables type to save space in the ring buffer.
 - Add trace_alarmtimer_suspend_enabled() in case of tracing is not enabled.

Changes since v1:
 - Fix the kbuild error.
 - Modify the changelog with adding trace log.
---
 include/trace/events/alarmtimer.h |  146 +++++++++++++++++++++++++++++++++++++
 kernel/time/alarmtimer.c          |   23 +++++-
 2 files changed, 166 insertions(+), 3 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..7ab9a36
--- /dev/null
+++ b/include/trace/events/alarmtimer.h
@@ -0,0 +1,146 @@
+#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, "ALARM_REALTIME" },		\
+	{ 1 << ALARM_BOOTTIME, "ALARM_BOOTTIME" })
+
+DECLARE_EVENT_CLASS(alarm_setting,
+
+	TP_PROTO(struct rtc_time *rtc_time, int flag),
+
+	TP_ARGS(rtc_time, flag),
+
+	TP_STRUCT__entry(
+		__field(unsigned char, second)
+		__field(unsigned char, minute)
+		__field(unsigned char, hour)
+		__field(unsigned char, day)
+		__field(unsigned char, mon)
+		__field(unsigned short, year)
+		__field(unsigned char, alarm_type)
+	),
+
+	TP_fast_assign(
+		__entry->second = rtc_time->tm_sec;
+		__entry->minute = rtc_time->tm_min;
+		__entry->hour = rtc_time->tm_hour;
+		__entry->day = rtc_time->tm_mday;
+		__entry->mon = rtc_time->tm_mon;
+		__entry->year = rtc_time->tm_year;
+		__entry->alarm_type = flag;
+	),
+
+	TP_printk("alarmtimer type:%s expires time: %hu-%u-%u %u:%u:%u",
+		  show_alarm_type((1 << __entry->alarm_type)),
+		  __entry->year + 1900,
+		  __entry->mon + 1,
+		  __entry->day,
+		  __entry->hour,
+		  __entry->minute,
+		  __entry->second
+	)
+);
+
+DEFINE_EVENT(alarm_setting, alarmtimer_suspend,
+
+	TP_PROTO(struct rtc_time *time, int flag),
+
+	TP_ARGS(time, flag)
+);
+
+DECLARE_EVENT_CLASS(alarm_processing,
+
+	TP_PROTO(struct alarm *alarm, char *process_name),
+
+	TP_ARGS(alarm, process_name),
+
+	TP_STRUCT__entry(
+		__field(unsigned long long, expires)
+		__field(unsigned char, second)
+		__field(unsigned char, minute)
+		__field(unsigned char, hour)
+		__field(unsigned char, day)
+		__field(unsigned char, mon)
+		__field(unsigned short, year)
+		__field(unsigned char, alarm_type)
+		__string(name, process_name)
+	),
+
+	TP_fast_assign(
+		__entry->expires = alarm->node.expires.tv64;
+		__entry->alarm_type = alarm->type;
+		__assign_str(name, process_name);
+#ifdef CONFIG_RTC_LIB
+		__entry->second = rtc_ktime_to_tm(alarm->node.expires).tm_sec;
+		__entry->minute = rtc_ktime_to_tm(alarm->node.expires).tm_min;
+		__entry->hour = rtc_ktime_to_tm(alarm->node.expires).tm_hour;
+		__entry->day = rtc_ktime_to_tm(alarm->node.expires).tm_mday;
+		__entry->mon = rtc_ktime_to_tm(alarm->node.expires).tm_mon;
+		__entry->year = rtc_ktime_to_tm(alarm->node.expires).tm_year;
+#else
+		__entry->second = 0;
+		__entry->minute = 0;
+		__entry->hour = 0;
+		__entry->day = 0;
+		__entry->mon = 0;
+		__entry->year = 0;
+#endif
+	),
+
+	TP_printk("process:%s alarmtimer type:%s expires:%llu "
+		  "time: %hu-%u-%u %u:%u:%u",
+		  __get_str(name),
+		  show_alarm_type((1 << __entry->alarm_type)),
+		  __entry->expires,
+		  __entry->year + 1900,
+		  __entry->mon + 1,
+		  __entry->day,
+		  __entry->hour,
+		  __entry->minute,
+		  __entry->second
+	)
+);
+
+DEFINE_EVENT(alarm_processing, alarmtimer_fired,
+
+	TP_PROTO(struct alarm *alarm, char *process_name),
+
+	TP_ARGS(alarm, process_name)
+);
+
+DEFINE_EVENT(alarm_processing, alarmtimer_start,
+
+	TP_PROTO(struct alarm *alarm, char *process_name),
+
+	TP_ARGS(alarm, process_name)
+);
+
+DEFINE_EVENT(alarm_processing, alarmtimer_restart,
+
+	TP_PROTO(struct alarm *alarm, char *process_name),
+
+	TP_ARGS(alarm, process_name)
+);
+
+DEFINE_EVENT(alarm_processing, alarmtimer_cancel,
+
+	TP_PROTO(struct alarm *alarm, char *process_name),
+
+	TP_ARGS(alarm, process_name)
+);
+
+#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 c3aad68..7cd15eb 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, NULL);
 	return ret;
 
 }
@@ -218,11 +222,11 @@ EXPORT_SYMBOL_GPL(alarm_expires_remaining);
  */
 static int alarmtimer_suspend(struct device *dev)
 {
-	struct rtc_time tm;
+	struct rtc_time tm, tm_set;
 	ktime_t min, now;
 	unsigned long flags;
 	struct rtc_device *rtc;
-	int i;
+	int i, type = 0;
 	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;
+			type = i;
+		}
 	}
 	if (min.tv64 == 0)
 		return 0;
@@ -264,6 +270,11 @@ static int alarmtimer_suspend(struct device *dev)
 	now = rtc_tm_to_ktime(tm);
 	now = ktime_add(now, min);
 
+	if (trace_alarmtimer_suspend_enabled()) {
+		tm_set = rtc_ktime_to_tm(now);
+		trace_alarmtimer_suspend(&tm_set, 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 +353,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, current->comm);
 }
 EXPORT_SYMBOL_GPL(alarm_start);
 
@@ -369,6 +382,8 @@ void alarm_restart(struct alarm *alarm)
 	hrtimer_restart(&alarm->timer);
 	alarmtimer_enqueue(base, alarm);
 	spin_unlock_irqrestore(&base->lock, flags);
+
+	trace_alarmtimer_restart(alarm, current->comm);
 }
 EXPORT_SYMBOL_GPL(alarm_restart);
 
@@ -390,6 +405,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, current->comm);
 	return ret;
 }
 EXPORT_SYMBOL_GPL(alarm_try_to_cancel);
-- 
1.7.9.5

[toc] | [next] | [standalone]

#1477979

On Tue, Sep 6, 2016 at 11:06 PM, Baolin Wang <baolin.wang@linaro.org> wrote:
> 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:2976_6-3473  [005] d..2  1076.587732: alarmtimer_start:
> process:Binder:2976_6
> alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1
> 0:20:35
>
> Binder:2976_7-3480  [002] d..2  1076.592707: alarmtimer_cancel:
> process:Binder:2976_7
> alarmtimer type:ALARM_BOOTTIME expires:1325463060000000000 time:
> 2012-1-2 0:11:0
>
> Binder:2976_7-3480  [002] d..2  1076.592731: alarmtimer_start:
> process:Binder:2976_7
> alarmtimer type:ALARM_BOOTTIME expires:1325378040000000000 time:
> 2012-1-1 0:34:0
>
> system_server-2976  [003] d..2  1076.605587: alarmtimer_cancel:
> process:system_server
> alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1
> 0:20:35
>
> system_server-2976  [003] d..2  1076.605608: alarmtimer_start:
> process:system_server
> alarmtimer type:ALARM_BOOTTIME expires:1234155000000 time: 1970-1-1
> 0:20:35
>
> system_server-3000  [002] ...1  1087.737565: alarmtimer_suspend:
> alarmtimer type:ALARM_BOOTTIME
> expires time: 2012-1-1 0:34:0
> ......
>
> From the trace log, we can find out the 'Binder:2976_7' process
> set one alarm timer which resumes the system.
>
> Signed-off-by: Baolin Wang <baolin.wang@linaro.org>
> Acked-by: Steven Rostedt <rostedt@goodmis.org>
> ---
> Changes since v3:
>  - Fix the build error on S390.

Since the original change is already applied to tip/timers/core, can
you provide an incremental patch (a patch against tip/timers/core)
that fixes the issue, rather then resending the entire patch?

Also, the "#ifdef CONFIG_RTC_LIB" solution I proposed was sort of a
hack, so I'd hope to see something better.

One better solution would be to add a dummy static inline
implementation of rtc_ktime_to_tm() in include/linux/rtc.h.

ie something like:
#ifdef CONFIG_RTC_LIB
struct rtc_time rtc_ktime_to_tm(ktime_t kt);
#else
static inline rtc_time rtc_ktime_to_tm(ktime_t kt)
{
    struct rt_time ret;
    memset(&ret, 0,  sizeof(struct rt_time));
    return ret;
}
#endif

thanks
-john

thanks
-john

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

#1477983

Hi John,

On 7 September 2016 at 14:17, John Stultz <john.stultz@linaro.org> wrote:
> On Tue, Sep 6, 2016 at 11:06 PM, Baolin Wang <baolin.wang@linaro.org> wrote:
>> 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:2976_6-3473  [005] d..2  1076.587732: alarmtimer_start:
>> process:Binder:2976_6
>> alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1
>> 0:20:35
>>
>> Binder:2976_7-3480  [002] d..2  1076.592707: alarmtimer_cancel:
>> process:Binder:2976_7
>> alarmtimer type:ALARM_BOOTTIME expires:1325463060000000000 time:
>> 2012-1-2 0:11:0
>>
>> Binder:2976_7-3480  [002] d..2  1076.592731: alarmtimer_start:
>> process:Binder:2976_7
>> alarmtimer type:ALARM_BOOTTIME expires:1325378040000000000 time:
>> 2012-1-1 0:34:0
>>
>> system_server-2976  [003] d..2  1076.605587: alarmtimer_cancel:
>> process:system_server
>> alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1
>> 0:20:35
>>
>> system_server-2976  [003] d..2  1076.605608: alarmtimer_start:
>> process:system_server
>> alarmtimer type:ALARM_BOOTTIME expires:1234155000000 time: 1970-1-1
>> 0:20:35
>>
>> system_server-3000  [002] ...1  1087.737565: alarmtimer_suspend:
>> alarmtimer type:ALARM_BOOTTIME
>> expires time: 2012-1-1 0:34:0
>> ......
>>
>> From the trace log, we can find out the 'Binder:2976_7' process
>> set one alarm timer which resumes the system.
>>
>> Signed-off-by: Baolin Wang <baolin.wang@linaro.org>
>> Acked-by: Steven Rostedt <rostedt@goodmis.org>
>> ---
>> Changes since v3:
>>  - Fix the build error on S390.
>
> Since the original change is already applied to tip/timers/core, can
> you provide an incremental patch (a patch against tip/timers/core)
> that fixes the issue, rather then resending the entire patch?

OK.

>
> Also, the "#ifdef CONFIG_RTC_LIB" solution I proposed was sort of a
> hack, so I'd hope to see something better.
>
> One better solution would be to add a dummy static inline
> implementation of rtc_ktime_to_tm() in include/linux/rtc.h.
>
> ie something like:
> #ifdef CONFIG_RTC_LIB
> struct rtc_time rtc_ktime_to_tm(ktime_t kt);
> #else
> static inline rtc_time rtc_ktime_to_tm(ktime_t kt)
> {
>     struct rt_time ret;
>     memset(&ret, 0,  sizeof(struct rt_time));
>     return ret;
> }
> #endif

Make sense. Thanks.

>
> thanks
> -john
>
> thanks
> -john



-- 
Baolin.wang
Best Regards

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

#1478455

On Tue, 6 Sep 2016, John Stultz wrote:
> > Changes since v3:
> >  - Fix the build error on S390.
> 
> Since the original change is already applied to tip/timers/core, can
> you provide an incremental patch (a patch against tip/timers/core)
> that fixes the issue, rather then resending the entire patch?

I zapped it from timers/core as it was the top commit. So we can redo it
completely, but we can do it incremental as well. Whatever you prefer.

Thanks,

	tglx

 

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

#1478747

Hi Thomas,

On 8 September 2016 at 00:03, Thomas Gleixner <tglx@linutronix.de> wrote:
> On Tue, 6 Sep 2016, John Stultz wrote:
>> > Changes since v3:
>> >  - Fix the build error on S390.
>>
>> Since the original change is already applied to tip/timers/core, can
>> you provide an incremental patch (a patch against tip/timers/core)
>> that fixes the issue, rather then resending the entire patch?
>
> I zapped it from timers/core as it was the top commit. So we can redo it
> completely, but we can do it incremental as well. Whatever you prefer.

I've send out one incremental patch to fix this issue[1]. Thanks.

[1] https://lkml.org/lkml/2016/9/7/828

-- 
Baolin.wang
Best Regards

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web