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

[Steven Rostedt]

On Thu, 18 Aug 2016 16:47:39 +0800
Baolin Wang <baolin.wang@xxxxxxxxxx> wrote:
 since v1:
>  - Fix the kbuild error.
>  - Modify the changelog with adding trace log.
> ---
>  include/trace/events/alarmtimer.h |  134 +++++++++++++++++++++++++++++++++++++
>  kernel/time/alarmtimer.c          |   21 +++++-
>  2 files changed, 152 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..eea4e12
> --- /dev/null
> +++ b/include/trace/events/alarmtimer.h
> @@ -0,0 +1,134 @@
> +#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>
> +
> +#define show_alarm_type(type)	__print_flags(type, " | ",	\
> +	{ 1 << ALARM_REALTIME, "ALARM_REALTIME" },		\
> +	{ 1 << ALARM_BOOTTIME, "ALARM_BOOTTIME" })

As ALARM_REALTIME and ALARM_BOOTTIME are both enums, they will not be
converted for userspace. Can you add the following:

TRACE_DEFINE_ENUM(ALARM_REALTIME);
TRACE_DEFINE_ENUM(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 int, second)
> +		__field(unsigned int, minute)
> +		__field(unsigned int, hour)
> +		__field(unsigned int, day)
> +		__field(unsigned int, mon)
> +		__field(unsigned int, year)
> +		__field(unsigned int, alarm_type)

To save space in the ring buffer, perhaps we can make the above not
take up so much space:

	unsigned char, second
	unsigned char, minute
	unsigned char, hour
	unsigned char, day
	unsigned char, mon
	unsigned char, alarm_type
	unsigned short, year

Why use 32 bits when most of the values fit nicely in one byte, and no
more than a 16 bytes. Also, order doesn't really matter for output, but
works well for compacting, as the above is only 8 bytes total.


> +	),
> +
> +	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: %u-%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 int, second)
> +		__field(unsigned int, minute)
> +		__field(unsigned int, hour)
> +		__field(unsigned int, day)
> +		__field(unsigned int, mon)
> +		__field(unsigned int, year)
> +		__field(unsigned int, alarm_type)

Same here.

> +		__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: %u-%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..866d668 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,9 @@ static int alarmtimer_suspend(struct device *dev)
>  	now = rtc_tm_to_ktime(tm);
>  	now = ktime_add(now, min);
>  
> +	tm_set = rtc_ktime_to_tm(now);
> +	trace_alarmtimer_suspend(&tm_set, type);

To keep from having to call rtc_ktime_to_tm(now) when not tracing, add:

	if (trace_alarmtimer_suspend_enabled()) {
		tm_set = rtc_ktime_to_tm(now);
		trace_alarmtimer_suspend(&tm_set, type);
	}

As trace_alarmtimer_suspend_enabled() is a static key and not a cmp
branch. That is, it's dynamically enabled or disabled and is always a
static branch.

-- Steve


> +
>  	/* 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 +351,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 +380,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 +403,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);