[tip:timers/core] time: alarmtimer: Add tracepoints for alarmtimers

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Commit-ID:  a0a6e06d545a753740c9d8d5ce2c4fdd3ab1c021
Gitweb:     http://git.kernel.org/tip/a0a6e06d545a753740c9d8d5ce2c4fdd3ab1c021
Author:     Baolin Wang <baolin.wang@xxxxxxxxxx>
AuthorDate: Mon, 22 Aug 2016 12:23:14 +0800
Committer:  John Stultz <john.stultz@xxxxxxxxxx>
CommitDate: Wed, 31 Aug 2016 14:44:18 -0700

time: alarmtimer: Add tracepoints for alarmtimers

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.

Cc: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
Cc: Ingo Molnar <mingo@xxxxxxxxxx>
Cc: Richard Cochran <richardcochran@xxxxxxxxx>
Cc: Prarit Bhargava <prarit@xxxxxxxxxx>
Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
Acked-by: Steven Rostedt <rostedt@xxxxxxxxxxx>
Signed-off-by: Baolin Wang <baolin.wang@xxxxxxxxxx>
[jstultz: tweaked commit message]
Signed-off-by: John Stultz <john.stultz@xxxxxxxxxx>
---
 include/trace/events/alarmtimer.h | 137 ++++++++++++++++++++++++++++++++++++++
 kernel/time/alarmtimer.c          |  23 ++++++-
 2 files changed, 157 insertions(+), 3 deletions(-)

diff --git a/include/trace/events/alarmtimer.h b/include/trace/events/alarmtimer.h
new file mode 100644
index 0000000..6a34bc9
--- /dev/null
+++ b/include/trace/events/alarmtimer.h
@@ -0,0 +1,137 @@
+#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->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;
+		__entry->alarm_type = alarm->type;
+		__assign_str(name, process_name);
+	),
+
+	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);
--
To unsubscribe from this list: send the line "unsubscribe linux-tip-commits" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html



[Index of Archives]     [Linux Stable Commits]     [Linux Stable Kernel]     [Linux Kernel]     [Linux USB Devel]     [Linux Video &Media]     [Linux Audio Users]     [Yosemite News]     [Linux SCSI]

  Powered by Linux