Re: [PATCH v3] time: alarmtimer: Add the trcepoints for alarmtimer

From: Baolin Wang
Date: Tue Aug 30 2016 - 07:50:29 EST

Next message: cheng chao: "[PATCH] Subject: [PATCH] SCHEDULER: remove unnecessary code of sched_init()"
Previous message: Heikki Krogerus: "Re: [PATCHv6 1/3] usb: USB Type-C connector class"
Next in thread: Steven Rostedt: "Re: [PATCH v3] time: alarmtimer: Add the trcepoints for alarmtimer"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hi,

On 22 August 2016 at 12:23, Baolin Wang <baolin.wang@xxxxxxxxxx> wrote:
> For system debugging, we usually 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.

Do you have any comments about this patch? Thanks.

>
> Signed-off-by: Baolin Wang <baolin.wang@xxxxxxxxxx>
> ---
> 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 | 137 +++++++++++++++++++++++++++++++++++++
> kernel/time/alarmtimer.c | 23 ++++++-
> 2 files changed, 157 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..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);
> --
> 1.7.9.5
>

--
Baolin.wang
Best Regards

Next message: cheng chao: "[PATCH] Subject: [PATCH] SCHEDULER: remove unnecessary code of sched_init()"
Previous message: Heikki Krogerus: "Re: [PATCHv6 1/3] usb: USB Type-C connector class"
Next in thread: Steven Rostedt: "Re: [PATCH v3] time: alarmtimer: Add the trcepoints for alarmtimer"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]