Re: [PATCH 2/2] time: alarmtimer: Add the trcepoints for alarmtimer

[Steven Rostedt]

On Wed, 21 Sep 2016 14:36:23 +0200 (CEST)
Thomas Gleixner  wrote:

> On Wed, 21 Sep 2016, Steven Rostedt wrote:
> > On Wed, 21 Sep 2016 09:26:20 +0200 (CEST)
> > Thomas Gleixner  wrote:  
> > > A single u64 does not take more storage space than this and it's a single
> > > store.  
> > 
> > So to use rtc_tm_to_time64()? Is the work to do the calculations of the
> > conversion faster than a bunch of stores that are going to be in hot
> > cache?  
> 
> Look at the call site. It has already the scalar nsec value and it does a
> conversion to rtc time in order to trace it.

OK. I haven't looked at the callsite. I just did a quick look at the
patch as is, and noticed the wasted space in the buffer for storing a
bunch of ints that will never be bigger than 256.

> 
> Ditto for the other tracepoints where the conversion from scalar nsec is
> done in the tracepoint itself.

This is why I like to have the maintainers review the rest.

-- Steve

Re: [PATCH 2/2] time: alarmtimer: Add the trcepoints for alarmtimer

[Thomas Gleixner]

On Wed, 21 Sep 2016, Steven Rostedt wrote:
> On Wed, 21 Sep 2016 09:26:20 +0200 (CEST)
> Thomas Gleixner  wrote:
> > A single u64 does not take more storage space than this and it's a single
> > store.
> 
> So to use rtc_tm_to_time64()? Is the work to do the calculations of the
> conversion faster than a bunch of stores that are going to be in hot
> cache?

Look at the call site. It has already the scalar nsec value and it does a
conversion to rtc time in order to trace it.

Ditto for the other tracepoints where the conversion from scalar nsec is
done in the tracepoint itself.

Thanks,

tglx

Re: [PATCH 2/2] time: alarmtimer: Add the trcepoints for alarmtimer

[Steven Rostedt]

On Wed, 21 Sep 2016 09:26:20 +0200 (CEST)
Thomas Gleixner  wrote:

> > As suggested by Steven, change the type of RTC value to save trace buffer.  

The original code did everything just like the above but stored every
value into ints, I just said that the value could be stored in chars to
save space.

> 
> A single u64 does not take more storage space than this and it's a single
> store.

So to use rtc_tm_to_time64()? Is the work to do the calculations of the
conversion faster than a bunch of stores that are going to be in hot
cache?

-- Steve

Re: [PATCH 2/2] time: alarmtimer: Add the trcepoints for alarmtimer

[Baolin Wang]

On 21 September 2016 at 15:26, Thomas Gleixner  wrote:
> On Wed, 21 Sep 2016, Baolin Wang wrote:
>> On 21 September 2016 at 06:27, Thomas Gleixner  wrote:
>> >> + 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;
>> >
>> > What's the value of storing the alarm time in RTC format?
>>
>> As suggested by Steven, change the type of RTC value to save trace buffer.
>
> A single u64 does not take more storage space than this and it's a single
> store.

OK.

>
>> > 2) You store the expiry time again in RTC format. Store the information in
>> >a plain u64 and be done with it.
>>
>> But I still think the RTC format is more readable for debugging alarm timer.
>
> That's what post processing is for.
>
>> > What's the point of this conditional? Avoiding rtc_ktime_to_tm() ? Oh 
>> > well...
>> >
>> >> + tm_set = rtc_ktime_to_tm(now);
>> >> + trace_alarmtimer_suspend(&tm_set, type);
>> >
>> > "now" is CLOCK_REALTIME based. You store the type of the alarm timer which
>> > is the first to expire and therefor is the one setting the RTC value, but
>> > we don't know which timer it is. Useful - NOT!
>>
>> We can know the timer by comparing the expire time.
>
> Please make it similar to the timer/hrtimer tracing so people can reuse
> their postprocessing scripts with minimial tweaks.

OK. Thanks.

-- 
Baolin.wang
Best Regards

Re: [PATCH 2/2] time: alarmtimer: Add the trcepoints for alarmtimer

[Thomas Gleixner]

On Wed, 21 Sep 2016, Baolin Wang wrote:
> On 21 September 2016 at 06:27, Thomas Gleixner  wrote:
> >> + 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;
> >
> > What's the value of storing the alarm time in RTC format?
> 
> As suggested by Steven, change the type of RTC value to save trace buffer.

A single u64 does not take more storage space than this and it's a single
store.
 
> > 2) You store the expiry time again in RTC format. Store the information in
> >a plain u64 and be done with it.
> 
> But I still think the RTC format is more readable for debugging alarm timer.

That's what post processing is for.
 
> > What's the point of this conditional? Avoiding rtc_ktime_to_tm() ? Oh 
> > well...
> >
> >> + tm_set = rtc_ktime_to_tm(now);
> >> + trace_alarmtimer_suspend(&tm_set, type);
> >
> > "now" is CLOCK_REALTIME based. You store the type of the alarm timer which
> > is the first to expire and therefor is the one setting the RTC value, but
> > we don't know which timer it is. Useful - NOT!
> 
> We can know the timer by comparing the expire time.

Please make it similar to the timer/hrtimer tracing so people can reuse
their postprocessing scripts with minimial tweaks.

Thanks,

tglx

Re: [PATCH 2/2] time: alarmtimer: Add the trcepoints for alarmtimer

[Baolin Wang]

On 21 September 2016 at 06:27, Thomas Gleixner  wrote:
> On Sun, 18 Sep 2016, Baolin Wang wrote:
>> +DECLARE_EVENT_CLASS(alarm_setting,
>
> What is alarm_setting? Without looking at the DEFINE_EVENT which uses this
> I cannot decode the meaning.

Will rename it.

>
>> + 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;
>
> What's the value of storing the alarm time in RTC format?

As suggested by Steven, change the type of RTC value to save trace buffer.

>
> What's wrong with simply storing the flat u64 based wall clock time?
> Nothing, because you can do the RTC format conversion in user space.
>
>> +DECLARE_EVENT_CLASS(alarm_processing,
>
> Again alarm_processing is not telling me anything.

Is alarm_class OK?

>
>> +
>> + TP_PROTO(struct alarm *alarm, char *process_name),
>
> Why do you want to store process_name? The tracer already tracks the name
> of the process in which context the tracepoint is taken. So what's the
> point of this? Look at the output:
>
> system_server-2976  [003] d..2  1076.605608: alarmtimer_start: 
> process:system_server
>
> Completely pointless duplicated information.

OK. Will remove it.

>
>> +
>> + 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);
>> + __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;
>
> This is utter crap for various reasons:
>
> 1) You store the expiry time over and over and in most cases it's simply
>pointless.

I will remove the 'expires' variable.

>
>- If the timer is started then we want to store the expiry time.
>
>- If the timer fires then the programmed expiry time is available from
>  the start trace point and you miss to store the information which is
>  really interesting: The actual time at which the timer expires
>  (REAL/BOOT)
>
>- If the timer is canceled then the expiry time in the timer is not
>  interesting at all. All you care is about the fact that the timer has
>  been canceled. The expiry time can still be retrieved from the start
>  trace point.
>
>- The restart tracepoint is redundant as well because either you see:
>
>  start -> expire -> start or start -> start which is clearly a restart.
>
>  If you put the start trace point into alarmtimer_enqueue() then you
>  spare the extra code size for two tracepoints because that is used in
>  start and restart

Make sense.

>
>See the hrtimer and timer tracepoints for reference.
>
>
> 2) You store the expiry time again in RTC format. Store the information in
>a plain u64 and be done with it.

But I still think the RTC format is more readable for debugging alarm timer.

>
>
>> +DEFINE_EVENT(alarm_processing, alarmtimer_fired,
>> +
>> + TP_PROTO(struct alarm *alarm, char *process_name),
>
> So you hand in a NULL pointer to this tracepoint to have even more useless
> information in the trace.

Will remove 'process_name' parameter.

>
>> @@ -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()) {
>
> What's the point of this conditional? Avoiding rtc_ktime_to_tm() ? Oh well...
>
>> + tm_set = rtc_ktime_to_tm(now);
>> +

Re: [PATCH 2/2] time: alarmtimer: Add the trcepoints for alarmtimer

[Thomas Gleixner]

On Sun, 18 Sep 2016, Baolin Wang wrote:
> +DECLARE_EVENT_CLASS(alarm_setting,

What is alarm_setting? Without looking at the DEFINE_EVENT which uses this
I cannot decode the meaning.

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

What's the value of storing the alarm time in RTC format?

What's wrong with simply storing the flat u64 based wall clock time?
Nothing, because you can do the RTC format conversion in user space.

> +DECLARE_EVENT_CLASS(alarm_processing,

Again alarm_processing is not telling me anything. 

> +
> + TP_PROTO(struct alarm *alarm, char *process_name),

Why do you want to store process_name? The tracer already tracks the name
of the process in which context the tracepoint is taken. So what's the
point of this? Look at the output:

system_server-2976  [003] d..2  1076.605608: alarmtimer_start: 
process:system_server

Completely pointless duplicated information.

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

This is utter crap for various reasons:

1) You store the expiry time over and over and in most cases it's simply
   pointless.

   - If the timer is started then we want to store the expiry time.

   - If the timer fires then the programmed expiry time is available from
 the start trace point and you miss to store the information which is
 really interesting: The actual time at which the timer expires
 (REAL/BOOT)

   - If the timer is canceled then the expiry time in the timer is not
 interesting at all. All you care is about the fact that the timer has
 been canceled. The expiry time can still be retrieved from the start
 trace point.

   - The restart tracepoint is redundant as well because either you see:

 start -> expire -> start or start -> start which is clearly a restart.

 If you put the start trace point into alarmtimer_enqueue() then you
 spare the extra code size for two tracepoints because that is used in
 start and restart

   See the hrtimer and timer tracepoints for reference. 


2) You store the expiry time again in RTC format. Store the information in
   a plain u64 and be done with it.


> +DEFINE_EVENT(alarm_processing, alarmtimer_fired,
> +
> + TP_PROTO(struct alarm *alarm, char *process_name),

So you hand in a NULL pointer to this tracepoint to have even more useless
information in the trace.

> @@ -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()) {

What's the point of this conditional? Avoiding rtc_ktime_to_tm() ? Oh well...

> + tm_set = rtc_ktime_to_tm(now);
> + trace_alarmtimer_suspend(&tm_set, type);

"now" is CLOCK_REALTIME based. You store the type of the alarm timer which
is the first to expire and therefor is the one setting the RTC value, but
we don't know which timer it is. Useful - NOT!

Thanks,

tglx

[PATCH 2/2] time: alarmtimer: Add the trcepoints for alarmtimer

[Baolin Wang]

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:123415400 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:13254630600 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:13253780400 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:123415400 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:123415500 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 
Acked-by: Steven Rostedt 
---
 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 000..a7eba5a
--- /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 
+#include 
+#include 
+
+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);
+   __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;
+   __ent