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

[Baolin Wang]

Hi Steven,

On 18 August 2016 at 22:33, Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> 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);

OK.

>
>> +
>> +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.

Make sense. Will fix in next version.

>
>
>> +     ),
>> +
>> +     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.

Great, will fix it. Thanks for your comments.

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



-- 
Baolin.wang
Best Regards