Re: [PATCH v3] rtc: Add tracepoints for RTC system

[Alexandre Belloni]

On 14/12/2017 at 13:31:43 +0800, Baolin Wang wrote:
> It will be more helpful to add some tracepoints to track RTC actions when
> debugging RTC driver. Below sample is that we set/read the RTC time, then
> set 2 alarms, so we can see the trace logs:
> 
> set/read RTC time:
> kworker/0:1-67 [000] 21.814245: rtc_set_time: UTC (1510301580) (0)
> kworker/0:1-67 [000] 21.814312: rtc_read_time: UTC (1510301580) (0)
> 
> set the first alarm timer:
> kworker/0:1-67 [000] 21.829238: rtc_timer_enqueue: RTC 
> timer:(ffc15eb49bc8) expires:15103017000 period:0
> kworker/0:1-67 [000] 22.018279: rtc_set_alarm: UTC (1510301700) (0)
> 
> set the second alarm timer:
> kworker/0:1-67 [000] 22.230284: rtc_timer_enqueue: RTC 
> timer:(ff80088e6430) expires:15103018200 period:0
> 
> the first alarm timer was expired:
> kworker/0:1-67 [000] 145.155584: rtc_timer_dequeue: RTC 
> timer:(ffc15eb49bc8) expires:15103017000 period:0
> kworker/0:1-67 [000] 145.155593: rtc_timer_fired: RTC 
> timer:(ffc15eb49bc8) expires:15103017000 period:0
> kworker/0:1-67 [000] 145.172504: rtc_set_alarm: UTC (1510301820) (0)
> 
> the second alarm timer was expired:
> kworker/0:1-67 [000] 269.102353: rtc_timer_dequeue: RTC 
> timer:(ff80088e6430) expires:15103018200 period:0
> kworker/0:1-67 [000] 269.102360: rtc_timer_fired: RTC 
> timer:(ff80088e6430) expires:15103018200 period:0
> 
> disable alarm irq:
> kworker/0:1-67 [000] 269.102469: rtc_alarm_irq_enable: disable RTC alarm IRQ 
> (0)
> 
> Signed-off-by: Baolin Wang 
> ---
> Changes since v2:
>  - Only keep time64_t in the buffer.
> 
> Changes since v1:
>  - Use unconditional tracepoints with tracing the failures.
>  - Simplify the rtc_timer_class.
> ---
>  drivers/rtc/interface.c|   30 +++
>  include/trace/events/rtc.h |  206 
> 
>  2 files changed, 236 insertions(+)
>  create mode 100644 include/trace/events/rtc.h
> 
Applied, thanks.

-- 
Alexandre Belloni, Bootlin (formerly Free Electrons)
Embedded Linux and Kernel engineering
http://bootlin.com

Re: [PATCH v3] rtc: Add tracepoints for RTC system

[Alexandre Belloni]

On 14/12/2017 at 13:31:43 +0800, Baolin Wang wrote:
> It will be more helpful to add some tracepoints to track RTC actions when
> debugging RTC driver. Below sample is that we set/read the RTC time, then
> set 2 alarms, so we can see the trace logs:
> 
> set/read RTC time:
> kworker/0:1-67 [000] 21.814245: rtc_set_time: UTC (1510301580) (0)
> kworker/0:1-67 [000] 21.814312: rtc_read_time: UTC (1510301580) (0)
> 
> set the first alarm timer:
> kworker/0:1-67 [000] 21.829238: rtc_timer_enqueue: RTC 
> timer:(ffc15eb49bc8) expires:15103017000 period:0
> kworker/0:1-67 [000] 22.018279: rtc_set_alarm: UTC (1510301700) (0)
> 
> set the second alarm timer:
> kworker/0:1-67 [000] 22.230284: rtc_timer_enqueue: RTC 
> timer:(ff80088e6430) expires:15103018200 period:0
> 
> the first alarm timer was expired:
> kworker/0:1-67 [000] 145.155584: rtc_timer_dequeue: RTC 
> timer:(ffc15eb49bc8) expires:15103017000 period:0
> kworker/0:1-67 [000] 145.155593: rtc_timer_fired: RTC 
> timer:(ffc15eb49bc8) expires:15103017000 period:0
> kworker/0:1-67 [000] 145.172504: rtc_set_alarm: UTC (1510301820) (0)
> 
> the second alarm timer was expired:
> kworker/0:1-67 [000] 269.102353: rtc_timer_dequeue: RTC 
> timer:(ff80088e6430) expires:15103018200 period:0
> kworker/0:1-67 [000] 269.102360: rtc_timer_fired: RTC 
> timer:(ff80088e6430) expires:15103018200 period:0
> 
> disable alarm irq:
> kworker/0:1-67 [000] 269.102469: rtc_alarm_irq_enable: disable RTC alarm IRQ 
> (0)
> 
> Signed-off-by: Baolin Wang 
> ---
> Changes since v2:
>  - Only keep time64_t in the buffer.
> 
> Changes since v1:
>  - Use unconditional tracepoints with tracing the failures.
>  - Simplify the rtc_timer_class.
> ---
>  drivers/rtc/interface.c|   30 +++
>  include/trace/events/rtc.h |  206 
> 
>  2 files changed, 236 insertions(+)
>  create mode 100644 include/trace/events/rtc.h
> 
Applied, thanks.

-- 
Alexandre Belloni, Bootlin (formerly Free Electrons)
Embedded Linux and Kernel engineering
http://bootlin.com

Re: [PATCH v3] rtc: Add tracepoints for RTC system

[Alexandre Belloni]

Hi Steve,

(Writing from my @kernel.org email to ensure you receive it)

On 14/12/2017 at 12:49:12 -0500, Steven Rostedt wrote:
> On Thu, 14 Dec 2017 13:31:43 +0800
> Baolin Wang  wrote:
> 
> 
> > @@ -53,6 +56,8 @@ int rtc_read_time(struct rtc_device *rtc, struct rtc_time 
> > *tm)
> >  
> > err = __rtc_read_time(rtc, tm);
> > mutex_unlock(>ops_lock);
> > +
> > +   trace_rtc_read_time(rtc_tm_to_time64(tm), err);
> 
> There's a possibility that gcc may put the call to rt_tm_to_time64()
> outside the tracepoint area that gets nop'd out. Could you just pass in
> the tm to the tracepoint, and have the call to rtc_tm_to_time64() done
> within the TP_fast_assign? This would guarantee that we don't incur
> overhead when tracing is off.
> 

Actually, I've asked for that as rtc_time64_to_tm is really heavier than
rtc_tm_to_time64 and both set_time and set_alarm will soon have a call
to rtc_tm_to_time64 anyway. read_time and read_alarm will probably end
up having one in the long term too.

> > diff --git a/include/trace/events/rtc.h b/include/trace/events/rtc.h
> > new file mode 100644
> > index 000..621333f
> > --- /dev/null
> > +++ b/include/trace/events/rtc.h
> > @@ -0,0 +1,206 @@
> > +#undef TRACE_SYSTEM
> > +#define TRACE_SYSTEM rtc
> > +
> > +#if !defined(_TRACE_RTC_H) || defined(TRACE_HEADER_MULTI_READ)
> > +#define _TRACE_RTC_H
> > +
> > +#include 
> > +#include 
> > +
> > +DECLARE_EVENT_CLASS(rtc_time_alarm_class,
> > +
> > +   TP_PROTO(time64_t secs, int err),
> > +
> > +   TP_ARGS(secs, err),
> > +
> > +   TP_STRUCT__entry(
> > +   __field(time64_t, secs)
> > +   __field(int, err)
> > +   ),
> > +
> > +   TP_fast_assign(
> > +   __entry->secs = secs;
> > +   __entry->err = err;
> > +   ),
> > +
> > +   TP_printk("UTC (%lld) (%d)",
> > + __entry->secs, __entry->err

Can't TP_printk do the rtc_time64_to_tm conversion to pretty print the
date? Or do we have to implement it in vsprintf?

-- 
Alexandre Belloni

Re: [PATCH v3] rtc: Add tracepoints for RTC system

[Alexandre Belloni]

Hi Steve,

(Writing from my @kernel.org email to ensure you receive it)

On 14/12/2017 at 12:49:12 -0500, Steven Rostedt wrote:
> On Thu, 14 Dec 2017 13:31:43 +0800
> Baolin Wang  wrote:
> 
> 
> > @@ -53,6 +56,8 @@ int rtc_read_time(struct rtc_device *rtc, struct rtc_time 
> > *tm)
> >  
> > err = __rtc_read_time(rtc, tm);
> > mutex_unlock(>ops_lock);
> > +
> > +   trace_rtc_read_time(rtc_tm_to_time64(tm), err);
> 
> There's a possibility that gcc may put the call to rt_tm_to_time64()
> outside the tracepoint area that gets nop'd out. Could you just pass in
> the tm to the tracepoint, and have the call to rtc_tm_to_time64() done
> within the TP_fast_assign? This would guarantee that we don't incur
> overhead when tracing is off.
> 

Actually, I've asked for that as rtc_time64_to_tm is really heavier than
rtc_tm_to_time64 and both set_time and set_alarm will soon have a call
to rtc_tm_to_time64 anyway. read_time and read_alarm will probably end
up having one in the long term too.

> > diff --git a/include/trace/events/rtc.h b/include/trace/events/rtc.h
> > new file mode 100644
> > index 000..621333f
> > --- /dev/null
> > +++ b/include/trace/events/rtc.h
> > @@ -0,0 +1,206 @@
> > +#undef TRACE_SYSTEM
> > +#define TRACE_SYSTEM rtc
> > +
> > +#if !defined(_TRACE_RTC_H) || defined(TRACE_HEADER_MULTI_READ)
> > +#define _TRACE_RTC_H
> > +
> > +#include 
> > +#include 
> > +
> > +DECLARE_EVENT_CLASS(rtc_time_alarm_class,
> > +
> > +   TP_PROTO(time64_t secs, int err),
> > +
> > +   TP_ARGS(secs, err),
> > +
> > +   TP_STRUCT__entry(
> > +   __field(time64_t, secs)
> > +   __field(int, err)
> > +   ),
> > +
> > +   TP_fast_assign(
> > +   __entry->secs = secs;
> > +   __entry->err = err;
> > +   ),
> > +
> > +   TP_printk("UTC (%lld) (%d)",
> > + __entry->secs, __entry->err

Can't TP_printk do the rtc_time64_to_tm conversion to pretty print the
date? Or do we have to implement it in vsprintf?

-- 
Alexandre Belloni

Re: [PATCH v3] rtc: Add tracepoints for RTC system

[Steven Rostedt]

On Thu, 14 Dec 2017 13:31:43 +0800
Baolin Wang  wrote:


> @@ -53,6 +56,8 @@ int rtc_read_time(struct rtc_device *rtc, struct rtc_time 
> *tm)
>  
>   err = __rtc_read_time(rtc, tm);
>   mutex_unlock(>ops_lock);
> +
> + trace_rtc_read_time(rtc_tm_to_time64(tm), err);

There's a possibility that gcc may put the call to rt_tm_to_time64()
outside the tracepoint area that gets nop'd out. Could you just pass in
the tm to the tracepoint, and have the call to rtc_tm_to_time64() done
within the TP_fast_assign? This would guarantee that we don't incur
overhead when tracing is off.

TP_PROTO(struct rtc_time *tm, int err),

TP_ARGS(tm, err),

TP_fast_assign(
__entry->secs = rt_tm_to_time64(tm);

-- Steve


> diff --git a/include/trace/events/rtc.h b/include/trace/events/rtc.h
> new file mode 100644
> index 000..621333f
> --- /dev/null
> +++ b/include/trace/events/rtc.h
> @@ -0,0 +1,206 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM rtc
> +
> +#if !defined(_TRACE_RTC_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_RTC_H
> +
> +#include 
> +#include 
> +
> +DECLARE_EVENT_CLASS(rtc_time_alarm_class,
> +
> + TP_PROTO(time64_t secs, int err),
> +
> + TP_ARGS(secs, err),
> +
> + TP_STRUCT__entry(
> + __field(time64_t, secs)
> + __field(int, err)
> + ),
> +
> + TP_fast_assign(
> + __entry->secs = secs;
> + __entry->err = err;
> + ),
> +
> + TP_printk("UTC (%lld) (%d)",
> +   __entry->secs, __entry->err
> + )
> +);
> +
> +DEFINE_EVENT(rtc_time_alarm_class, rtc_set_time,
> +
> + TP_PROTO(time64_t secs, int err),
> +
> + TP_ARGS(secs, err)
> +);
> +
> +DEFINE_EVENT(rtc_time_alarm_class, rtc_read_time,
> +
> + TP_PROTO(time64_t secs, int err),
> +
> + TP_ARGS(secs, err)
> +);
> +

Re: [PATCH v3] rtc: Add tracepoints for RTC system

[Steven Rostedt]

On Thu, 14 Dec 2017 13:31:43 +0800
Baolin Wang  wrote:


> @@ -53,6 +56,8 @@ int rtc_read_time(struct rtc_device *rtc, struct rtc_time 
> *tm)
>  
>   err = __rtc_read_time(rtc, tm);
>   mutex_unlock(>ops_lock);
> +
> + trace_rtc_read_time(rtc_tm_to_time64(tm), err);

There's a possibility that gcc may put the call to rt_tm_to_time64()
outside the tracepoint area that gets nop'd out. Could you just pass in
the tm to the tracepoint, and have the call to rtc_tm_to_time64() done
within the TP_fast_assign? This would guarantee that we don't incur
overhead when tracing is off.

TP_PROTO(struct rtc_time *tm, int err),

TP_ARGS(tm, err),

TP_fast_assign(
__entry->secs = rt_tm_to_time64(tm);

-- Steve


> diff --git a/include/trace/events/rtc.h b/include/trace/events/rtc.h
> new file mode 100644
> index 000..621333f
> --- /dev/null
> +++ b/include/trace/events/rtc.h
> @@ -0,0 +1,206 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM rtc
> +
> +#if !defined(_TRACE_RTC_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_RTC_H
> +
> +#include 
> +#include 
> +
> +DECLARE_EVENT_CLASS(rtc_time_alarm_class,
> +
> + TP_PROTO(time64_t secs, int err),
> +
> + TP_ARGS(secs, err),
> +
> + TP_STRUCT__entry(
> + __field(time64_t, secs)
> + __field(int, err)
> + ),
> +
> + TP_fast_assign(
> + __entry->secs = secs;
> + __entry->err = err;
> + ),
> +
> + TP_printk("UTC (%lld) (%d)",
> +   __entry->secs, __entry->err
> + )
> +);
> +
> +DEFINE_EVENT(rtc_time_alarm_class, rtc_set_time,
> +
> + TP_PROTO(time64_t secs, int err),
> +
> + TP_ARGS(secs, err)
> +);
> +
> +DEFINE_EVENT(rtc_time_alarm_class, rtc_read_time,
> +
> + TP_PROTO(time64_t secs, int err),
> +
> + TP_ARGS(secs, err)
> +);
> +