| Message ID | 64a38f4a15a2f8dae4a9fd0a3fc2a312e86c733d.1510749847.git.baolin.wang@linaro.org |
|---|---|
| State | Superseded |
| Headers | show |
| Series | [v2] rtc: Add tracepoints for RTC system | expand |
Hi Alexandre and Ingo, On 16 November 2017 at 13:59, Baolin Wang <baolin.wang@linaro.org> 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: 2017-11-10 08:13:00 UTC (1510301580) (0) > kworker/0:1-67 [000] 21.814312: rtc_read_time: 2017-11-10 08:13:00 UTC (1510301580) (0) > > set the first alarm timer: > kworker/0:1-67 [000] 21.829238: rtc_timer_enqueue: RTC timer:(ffffffc15eb49bc8) expires:1510301700000000000 period:0 > kworker/0:1-67 [000] 22.018279: rtc_set_alarm: 2017-11-10 08:15:00 UTC (1510301700) (0) > > set the second alarm timer: > kworker/0:1-67 [000] 22.230284: rtc_timer_enqueue: RTC timer:(ffffff80088e6430) expires:1510301820000000000 period:0 > > the first alarm timer was expired: > kworker/0:1-67 [000] 145.155584: rtc_timer_dequeue: RTC timer:(ffffffc15eb49bc8) expires:1510301700000000000 period:0 > kworker/0:1-67 [000] 145.155593: rtc_timer_fired: RTC timer:(ffffffc15eb49bc8) expires:1510301700000000000 period:0 > kworker/0:1-67 [000] 145.172504: rtc_set_alarm: 2017-11-10 08:17:00 UTC (1510301820) (0) > > the second alarm timer was expired: > kworker/0:1-67 [000] 269.102353: rtc_timer_dequeue: RTC timer:(ffffff80088e6430) expires:1510301820000000000 period:0 > kworker/0:1-67 [000] 269.102360: rtc_timer_fired: RTC timer:(ffffff80088e6430) expires:1510301820000000000 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 <baolin.wang@linaro.org> > --- > Changes since v1: > - Use unconditional tracepoints with tracing the failures. > - Simplify the rtc_timer_class. > --- Do you have any comments for this patch? Thanks. -- Baolin Wang Best Regards
Hi Baolin, On 16/11/2017 at 13:59:28 +0800, Baolin Wang wrote: > @@ -779,6 +797,7 @@ static int rtc_timer_enqueue(struct rtc_device *rtc, struct rtc_timer *timer) > } > > timerqueue_add(&rtc->timerqueue, &timer->node); > + trace_rtc_timer_enqueue(timer); This doesn't apply because of 74717b28cb32e1ad3c1042cafd76b264c8c0f68d. Can you rebase? > diff --git a/include/trace/events/rtc.h b/include/trace/events/rtc.h > new file mode 100644 > index 0000000..b5a4add > --- /dev/null > +++ b/include/trace/events/rtc.h > @@ -0,0 +1,220 @@ > +#undef TRACE_SYSTEM > +#define TRACE_SYSTEM rtc > + > +#if !defined(_TRACE_RTC_H) || defined(TRACE_HEADER_MULTI_READ) > +#define _TRACE_RTC_H > + > +#include <linux/rtc.h> > +#include <linux/tracepoint.h> > + > +DECLARE_EVENT_CLASS(rtc_time_alarm_class, > + > + TP_PROTO(struct rtc_time *tm, int err), > + > + TP_ARGS(tm, err), > + > + TP_STRUCT__entry( > + __field(int, sec) > + __field(int, min) > + __field(int, hour) > + __field(int, mday) > + __field(int, mon) > + __field(int, year) > + __field(time64_t, secs) > + __field(int, err) > + ), > + > + TP_fast_assign( > + __entry->sec = tm->tm_sec; > + __entry->min = tm->tm_min; > + __entry->hour = tm->tm_hour; > + __entry->mday = tm->tm_mday; > + __entry->mon = tm->tm_mon; > + __entry->year = tm->tm_year; > + __entry->secs = rtc_tm_to_time64(tm); > + __entry->err = err; > + ), > + > + TP_printk("%d-%02d-%02d %02d:%02d:%02d UTC (%lld) (%d)", > + __entry->year + 1900, __entry->mon + 1, __entry->mday, > + __entry->hour, __entry->min, __entry->sec, __entry->secs, > + __entry->err > + ) > +); > + Also, I'm a bit concerned about having a struct rtc_time here. I think its goal is mainly to have a nice representation on the time but maybe the best would be to make printk able to pretty print the time (some patches were proposed). How bad would that be to change it later? I didn't follow the whole tracepoint ABI issue closely. -- Alexandre Belloni, Free Electrons Embedded Linux and Kernel engineering http://free-electrons.com
Hi Alexandre, On 13 December 2017 at 06:16, Alexandre Belloni <alexandre.belloni@free-electrons.com> wrote: > Hi Baolin, > > On 16/11/2017 at 13:59:28 +0800, Baolin Wang wrote: >> @@ -779,6 +797,7 @@ static int rtc_timer_enqueue(struct rtc_device *rtc, struct rtc_timer *timer) >> } >> >> timerqueue_add(&rtc->timerqueue, &timer->node); >> + trace_rtc_timer_enqueue(timer); > > This doesn't apply because of 74717b28cb32e1ad3c1042cafd76b264c8c0f68d. > Can you rebase? Sure. > >> diff --git a/include/trace/events/rtc.h b/include/trace/events/rtc.h >> new file mode 100644 >> index 0000000..b5a4add >> --- /dev/null >> +++ b/include/trace/events/rtc.h >> @@ -0,0 +1,220 @@ >> +#undef TRACE_SYSTEM >> +#define TRACE_SYSTEM rtc >> + >> +#if !defined(_TRACE_RTC_H) || defined(TRACE_HEADER_MULTI_READ) >> +#define _TRACE_RTC_H >> + >> +#include <linux/rtc.h> >> +#include <linux/tracepoint.h> >> + >> +DECLARE_EVENT_CLASS(rtc_time_alarm_class, >> + >> + TP_PROTO(struct rtc_time *tm, int err), >> + >> + TP_ARGS(tm, err), >> + >> + TP_STRUCT__entry( >> + __field(int, sec) >> + __field(int, min) >> + __field(int, hour) >> + __field(int, mday) >> + __field(int, mon) >> + __field(int, year) >> + __field(time64_t, secs) >> + __field(int, err) >> + ), >> + >> + TP_fast_assign( >> + __entry->sec = tm->tm_sec; >> + __entry->min = tm->tm_min; >> + __entry->hour = tm->tm_hour; >> + __entry->mday = tm->tm_mday; >> + __entry->mon = tm->tm_mon; >> + __entry->year = tm->tm_year; >> + __entry->secs = rtc_tm_to_time64(tm); >> + __entry->err = err; >> + ), >> + >> + TP_printk("%d-%02d-%02d %02d:%02d:%02d UTC (%lld) (%d)", >> + __entry->year + 1900, __entry->mon + 1, __entry->mday, >> + __entry->hour, __entry->min, __entry->sec, __entry->secs, >> + __entry->err >> + ) >> +); >> + > > Also, I'm a bit concerned about having a struct rtc_time here. I think > its goal is mainly to have a nice representation on the time but maybe Yes. > the best would be to make printk able to pretty print the time (some > patches were proposed). If I understood your point correctly, you did not like the format of TP_printk() here, right? So how about if I remove the 'struct rtc_time' and just pass one 'ktime_t' parameter? But it will be not readable for user to trace the RTC time/alarm. > > How bad would that be to change it later? I didn't follow the whole > tracepoint ABI issue closely. -- Baolin.wang Best Regards
On Wed, Dec 13, 2017 at 6:47 AM, Baolin Wang <baolin.wang@linaro.org> wrote: > >>> diff --git a/include/trace/events/rtc.h b/include/trace/events/rtc.h >>> new file mode 100644 >>> index 0000000..b5a4add >>> --- /dev/null >>> +++ b/include/trace/events/rtc.h >>> + >> >> Also, I'm a bit concerned about having a struct rtc_time here. I think >> its goal is mainly to have a nice representation on the time but maybe > > Yes. > >> the best would be to make printk able to pretty print the time (some >> patches were proposed). > > If I understood your point correctly, you did not like the format of > TP_printk() here, right? So how about if I remove the 'struct > rtc_time' and just pass one 'ktime_t' parameter? But it will be not > readable for user to trace the RTC time/alarm. > >> >> How bad would that be to change it later? I didn't follow the whole >> tracepoint ABI issue closely. There is no general rule here other than "if it breaks for existing users, we have to fix it". Anyone who uses the tracepoints correctly would end up showing zero-date if we change all the fields, but it should not crash here. Printing a time64_t instead of rtc_time may be better here, as it's cheaper to convert rtc_time to time64_t that vice versa. User space looking at the trace data can then do the conversion back to struct tm for printing in a C program or using /bin/date from a shell script, but I agree it's an extra step. It's also possible that we don't care about the overhead of doing a time64_to_tm() or rtc_time64_to_tm() in the trace function, as long as that only needs to be done if the tracepoint is active. I find trace points a bit confusing, so I don't know if that is the case or not when the tracepoint is compiled into the kernel but disabled at run time. Arnd
On 13/12/2017 at 09:33:23 +0100, Arnd Bergmann wrote: > On Wed, Dec 13, 2017 at 6:47 AM, Baolin Wang <baolin.wang@linaro.org> wrote: > > > >>> diff --git a/include/trace/events/rtc.h b/include/trace/events/rtc.h > >>> new file mode 100644 > >>> index 0000000..b5a4add > >>> --- /dev/null > >>> +++ b/include/trace/events/rtc.h > >>> + > >> > >> Also, I'm a bit concerned about having a struct rtc_time here. I think > >> its goal is mainly to have a nice representation on the time but maybe > > > > Yes. > > > >> the best would be to make printk able to pretty print the time (some > >> patches were proposed). > > > > If I understood your point correctly, you did not like the format of > > TP_printk() here, right? So how about if I remove the 'struct > > rtc_time' and just pass one 'ktime_t' parameter? But it will be not > > readable for user to trace the RTC time/alarm. > > > >> > >> How bad would that be to change it later? I didn't follow the whole > >> tracepoint ABI issue closely. > > There is no general rule here other than "if it breaks for existing > users, we have to fix it". Anyone who uses the tracepoints correctly > would end up showing zero-date if we change all the fields, but > it should not crash here. > > Printing a time64_t instead of rtc_time may be better here, as it's > cheaper to convert rtc_time to time64_t that vice versa. User space > looking at the trace data can then do the conversion back to struct tm > for printing in a C program or using /bin/date from a shell > script, but I agree it's an extra step. > > It's also possible that we don't care about the overhead of doing > a time64_to_tm() or rtc_time64_to_tm() in the trace function, as long > as that only needs to be done if the tracepoint is active. I find trace > points a bit confusing, so I don't know if that is the case or not when > the tracepoint is compiled into the kernel but disabled at run time. > Sorry, I was not clear and I never actually used tracepoints. My point was that the printk format is nice and can probably be kept as is. But I would like tracepoint to take a time64_t instead of an rtc_time even if that means having a conversion before calling the tracepoint and converting back to display the date/time. Also, I think we could try having only the time64_t in the ring buffer. Maybe I'm wrong but I think tools reading that buffer can do the conversion themselves. Maybe I don't understand correctly how tracepoints work and this doesn't make sense, tell me. The printk patches I was referring to are: https://marc.info/?l=linux-rtc&m=149693060517054&w=2 But they don't provide a way to pretty print a time64_t yet (it was just suggested by Arnd). -- Alexandre Belloni, Free Electrons Embedded Linux and Kernel engineering http://free-electrons.com
On Wed, Dec 13, 2017 at 12:04:26PM +0100, Alexandre Belloni wrote: > Also, I think we could try having only the time64_t in the ring buffer. > Maybe I'm wrong but I think tools reading that buffer can do the > conversion themselves. Maybe I don't understand correctly how > tracepoints work and this doesn't make sense, tell me. Tools reading the buffer can do the conversion themselves but it's also useful for users to just view the log directly via tracing/trace sometimes. OTOH the whole point is to be low overhead so...
On 13/12/2017 at 12:16:03 +0000, Mark Brown wrote: > On Wed, Dec 13, 2017 at 12:04:26PM +0100, Alexandre Belloni wrote: > > > Also, I think we could try having only the time64_t in the ring buffer. > > Maybe I'm wrong but I think tools reading that buffer can do the > > conversion themselves. Maybe I don't understand correctly how > > tracepoints work and this doesn't make sense, tell me. > > Tools reading the buffer can do the conversion themselves but it's also > useful for users to just view the log directly via tracing/trace > sometimes. OTOH the whole point is to be low overhead so... Yes, that is why I suggest keeping both representation in the printk but only time64_t in the buffer. And this would be more convenient if we add a way to pretty print a time64_t in vsprintf. -- Alexandre Belloni, Free Electrons Embedded Linux and Kernel engineering http://free-electrons.com
On Wed, 13 Dec 2017 09:33:23 +0100 Arnd Bergmann <arnd@arndb.de> wrote: > >> How bad would that be to change it later? I didn't follow the whole > >> tracepoint ABI issue closely. > > There is no general rule here other than "if it breaks for existing > users, we have to fix it". Anyone who uses the tracepoints correctly > would end up showing zero-date if we change all the fields, but > it should not crash here. But if a tool depends on that value correct, that still is a user space breakage, even though it was using tracepoints correctly. > > Printing a time64_t instead of rtc_time may be better here, as it's > cheaper to convert rtc_time to time64_t that vice versa. User space > looking at the trace data can then do the conversion back to struct tm > for printing in a C program or using /bin/date from a shell > script, but I agree it's an extra step. > > It's also possible that we don't care about the overhead of doing > a time64_to_tm() or rtc_time64_to_tm() in the trace function, as long > as that only needs to be done if the tracepoint is active. I find trace > points a bit confusing, so I don't know if that is the case or not when > the tracepoint is compiled into the kernel but disabled at run time. Everything that is done in TP_fast_assign() is only performed when the tracepoint is active. It adds no more overhead when tracing is disabled, as tracepoints incorporate jump labels, and the call itself is a nop. As long as the parameters to the trace_*() functions don't do logic, all should be fine: like if you had: trace_rtc_set_alarm(call_some_function_to_return_tm(), err); gcc could make that call_some_function_to_return_tm() happen even when the tracepoint is not enabled. But that's not the case with this patch. -- Steve
On Wed, 13 Dec 2017 12:16:03 +0000 Mark Brown <broonie@kernel.org> wrote: > On Wed, Dec 13, 2017 at 12:04:26PM +0100, Alexandre Belloni wrote: > > > Also, I think we could try having only the time64_t in the ring buffer. > > Maybe I'm wrong but I think tools reading that buffer can do the > > conversion themselves. Maybe I don't understand correctly how > > tracepoints work and this doesn't make sense, tell me. > > Tools reading the buffer can do the conversion themselves but it's also > useful for users to just view the log directly via tracing/trace > sometimes. OTOH the whole point is to be low overhead so... Ideally, we want TP_fast_assign() do as little as possible, and put all the work in TP_printk() as the printk happens on read of the trace buffer and TP_fast_assign() happens at the tracepoint invocation. -- Steve
On 13 December 2017 at 20:23, Alexandre Belloni <alexandre.belloni@free-electrons.com> wrote: > On 13/12/2017 at 12:16:03 +0000, Mark Brown wrote: >> On Wed, Dec 13, 2017 at 12:04:26PM +0100, Alexandre Belloni wrote: >> >> > Also, I think we could try having only the time64_t in the ring buffer. >> > Maybe I'm wrong but I think tools reading that buffer can do the >> > conversion themselves. Maybe I don't understand correctly how >> > tracepoints work and this doesn't make sense, tell me. >> >> Tools reading the buffer can do the conversion themselves but it's also >> useful for users to just view the log directly via tracing/trace >> sometimes. OTOH the whole point is to be low overhead so... > > Yes, that is why I suggest keeping both representation in the printk > but only time64_t in the buffer. And this would be more convenient if we > add a way to pretty print a time64_t in vsprintf. OK. I will only keep time64_t in the buffer. Thanks for all your comments. -- Baolin.wang Best Regards
diff --git a/drivers/rtc/interface.c b/drivers/rtc/interface.c index 8cec9a0..879e40d 100644 --- a/drivers/rtc/interface.c +++ b/drivers/rtc/interface.c @@ -17,6 +17,9 @@ #include <linux/log2.h> #include <linux/workqueue.h> +#define CREATE_TRACE_POINTS +#include <trace/events/rtc.h> + static int rtc_timer_enqueue(struct rtc_device *rtc, struct rtc_timer *timer); static void rtc_timer_remove(struct rtc_device *rtc, struct rtc_timer *timer); @@ -53,6 +56,8 @@ int rtc_read_time(struct rtc_device *rtc, struct rtc_time *tm) err = __rtc_read_time(rtc, tm); mutex_unlock(&rtc->ops_lock); + + trace_rtc_read_time(tm, err); return err; } EXPORT_SYMBOL_GPL(rtc_read_time); @@ -87,6 +92,8 @@ int rtc_set_time(struct rtc_device *rtc, struct rtc_time *tm) mutex_unlock(&rtc->ops_lock); /* A timer might have just expired */ schedule_work(&rtc->irqwork); + + trace_rtc_set_time(tm, err); return err; } EXPORT_SYMBOL_GPL(rtc_set_time); @@ -119,6 +126,8 @@ static int rtc_read_alarm_internal(struct rtc_device *rtc, struct rtc_wkalrm *al } mutex_unlock(&rtc->ops_lock); + + trace_rtc_read_alarm(&alarm->time, err); return err; } @@ -316,6 +325,7 @@ int rtc_read_alarm(struct rtc_device *rtc, struct rtc_wkalrm *alarm) } mutex_unlock(&rtc->ops_lock); + trace_rtc_read_alarm(&alarm->time, err); return err; } EXPORT_SYMBOL_GPL(rtc_read_alarm); @@ -352,6 +362,7 @@ static int __rtc_set_alarm(struct rtc_device *rtc, struct rtc_wkalrm *alarm) else err = rtc->ops->set_alarm(rtc->dev.parent, alarm); + trace_rtc_set_alarm(&alarm->time, err); return err; } @@ -406,6 +417,7 @@ int rtc_initialize_alarm(struct rtc_device *rtc, struct rtc_wkalrm *alarm) rtc->aie_timer.enabled = 1; timerqueue_add(&rtc->timerqueue, &rtc->aie_timer.node); + trace_rtc_timer_enqueue(&rtc->aie_timer); } mutex_unlock(&rtc->ops_lock); return err; @@ -435,6 +447,8 @@ int rtc_alarm_irq_enable(struct rtc_device *rtc, unsigned int enabled) err = rtc->ops->alarm_irq_enable(rtc->dev.parent, enabled); mutex_unlock(&rtc->ops_lock); + + trace_rtc_alarm_irq_enable(enabled, err); return err; } EXPORT_SYMBOL_GPL(rtc_alarm_irq_enable); @@ -709,6 +723,8 @@ int rtc_irq_set_state(struct rtc_device *rtc, struct rtc_task *task, int enabled rtc->pie_enabled = enabled; } spin_unlock_irqrestore(&rtc->irq_task_lock, flags); + + trace_rtc_irq_set_state(enabled, err); return err; } EXPORT_SYMBOL_GPL(rtc_irq_set_state); @@ -745,6 +761,8 @@ int rtc_irq_set_freq(struct rtc_device *rtc, struct rtc_task *task, int freq) } } spin_unlock_irqrestore(&rtc->irq_task_lock, flags); + + trace_rtc_irq_set_freq(freq, err); return err; } EXPORT_SYMBOL_GPL(rtc_irq_set_freq); @@ -779,6 +797,7 @@ static int rtc_timer_enqueue(struct rtc_device *rtc, struct rtc_timer *timer) } timerqueue_add(&rtc->timerqueue, &timer->node); + trace_rtc_timer_enqueue(timer); if (!next) { struct rtc_wkalrm alarm; int err; @@ -790,6 +809,7 @@ static int rtc_timer_enqueue(struct rtc_device *rtc, struct rtc_timer *timer) schedule_work(&rtc->irqwork); } else if (err) { timerqueue_del(&rtc->timerqueue, &timer->node); + trace_rtc_timer_dequeue(timer); timer->enabled = 0; return err; } @@ -803,6 +823,7 @@ static void rtc_alarm_disable(struct rtc_device *rtc) return; rtc->ops->alarm_irq_enable(rtc->dev.parent, false); + trace_rtc_alarm_irq_enable(0, 0); } /** @@ -821,6 +842,7 @@ static void rtc_timer_remove(struct rtc_device *rtc, struct rtc_timer *timer) { struct timerqueue_node *next = timerqueue_getnext(&rtc->timerqueue); timerqueue_del(&rtc->timerqueue, &timer->node); + trace_rtc_timer_dequeue(timer); timer->enabled = 0; if (next == &timer->node) { struct rtc_wkalrm alarm; @@ -871,16 +893,19 @@ void rtc_timer_do_work(struct work_struct *work) /* expire timer */ timer = container_of(next, struct rtc_timer, node); timerqueue_del(&rtc->timerqueue, &timer->node); + trace_rtc_timer_dequeue(timer); timer->enabled = 0; if (timer->task.func) timer->task.func(timer->task.private_data); + trace_rtc_timer_fired(timer); /* Re-add/fwd periodic timers */ if (ktime_to_ns(timer->period)) { timer->node.expires = ktime_add(timer->node.expires, timer->period); timer->enabled = 1; timerqueue_add(&rtc->timerqueue, &timer->node); + trace_rtc_timer_enqueue(timer); } } @@ -902,6 +927,7 @@ void rtc_timer_do_work(struct work_struct *work) timer = container_of(next, struct rtc_timer, node); timerqueue_del(&rtc->timerqueue, &timer->node); + trace_rtc_timer_dequeue(timer); timer->enabled = 0; dev_err(&rtc->dev, "__rtc_set_alarm: err=%d\n", err); goto again; @@ -992,6 +1018,8 @@ int rtc_read_offset(struct rtc_device *rtc, long *offset) mutex_lock(&rtc->ops_lock); ret = rtc->ops->read_offset(rtc->dev.parent, offset); mutex_unlock(&rtc->ops_lock); + + trace_rtc_read_offset(*offset, ret); return ret; } @@ -1021,5 +1049,7 @@ int rtc_set_offset(struct rtc_device *rtc, long offset) mutex_lock(&rtc->ops_lock); ret = rtc->ops->set_offset(rtc->dev.parent, offset); mutex_unlock(&rtc->ops_lock); + + trace_rtc_set_offset(offset, ret); return ret; } diff --git a/include/trace/events/rtc.h b/include/trace/events/rtc.h new file mode 100644 index 0000000..b5a4add --- /dev/null +++ b/include/trace/events/rtc.h @@ -0,0 +1,220 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM rtc + +#if !defined(_TRACE_RTC_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_RTC_H + +#include <linux/rtc.h> +#include <linux/tracepoint.h> + +DECLARE_EVENT_CLASS(rtc_time_alarm_class, + + TP_PROTO(struct rtc_time *tm, int err), + + TP_ARGS(tm, err), + + TP_STRUCT__entry( + __field(int, sec) + __field(int, min) + __field(int, hour) + __field(int, mday) + __field(int, mon) + __field(int, year) + __field(time64_t, secs) + __field(int, err) + ), + + TP_fast_assign( + __entry->sec = tm->tm_sec; + __entry->min = tm->tm_min; + __entry->hour = tm->tm_hour; + __entry->mday = tm->tm_mday; + __entry->mon = tm->tm_mon; + __entry->year = tm->tm_year; + __entry->secs = rtc_tm_to_time64(tm); + __entry->err = err; + ), + + TP_printk("%d-%02d-%02d %02d:%02d:%02d UTC (%lld) (%d)", + __entry->year + 1900, __entry->mon + 1, __entry->mday, + __entry->hour, __entry->min, __entry->sec, __entry->secs, + __entry->err + ) +); + +DEFINE_EVENT(rtc_time_alarm_class, rtc_set_time, + + TP_PROTO(struct rtc_time *tm, int err), + + TP_ARGS(tm, err) +); + +DEFINE_EVENT(rtc_time_alarm_class, rtc_read_time, + + TP_PROTO(struct rtc_time *tm, int err), + + TP_ARGS(tm, err) +); + +DEFINE_EVENT(rtc_time_alarm_class, rtc_set_alarm, + + TP_PROTO(struct rtc_time *tm, int err), + + TP_ARGS(tm, err) +); + +DEFINE_EVENT(rtc_time_alarm_class, rtc_read_alarm, + + TP_PROTO(struct rtc_time *tm, int err), + + TP_ARGS(tm, err) +); + +TRACE_EVENT(rtc_irq_set_freq, + + TP_PROTO(int freq, int err), + + TP_ARGS(freq, err), + + TP_STRUCT__entry( + __field(int, freq) + __field(int, err) + ), + + TP_fast_assign( + __entry->freq = freq; + __entry->err = err; + ), + + TP_printk("set RTC periodic IRQ frequency:%u (%d)", + __entry->freq, __entry->err + ) +); + +TRACE_EVENT(rtc_irq_set_state, + + TP_PROTO(int enabled, int err), + + TP_ARGS(enabled, err), + + TP_STRUCT__entry( + __field(int, enabled) + __field(int, err) + ), + + TP_fast_assign( + __entry->enabled = enabled; + __entry->err = err; + ), + + TP_printk("%s RTC 2^N Hz periodic IRQs (%d)", + __entry->enabled ? "enable" : "disable", + __entry->err + ) +); + +TRACE_EVENT(rtc_alarm_irq_enable, + + TP_PROTO(unsigned int enabled, int err), + + TP_ARGS(enabled, err), + + TP_STRUCT__entry( + __field(unsigned int, enabled) + __field(int, err) + ), + + TP_fast_assign( + __entry->enabled = enabled; + __entry->err = err; + ), + + TP_printk("%s RTC alarm IRQ (%d)", + __entry->enabled ? "enable" : "disable", + __entry->err + ) +); + +DECLARE_EVENT_CLASS(rtc_offset_class, + + TP_PROTO(long offset, int err), + + TP_ARGS(offset, err), + + TP_STRUCT__entry( + __field(long, offset) + __field(int, err) + ), + + TP_fast_assign( + __entry->offset = offset; + __entry->err = err; + ), + + TP_printk("RTC offset: %ld (%d)", + __entry->offset, __entry->err + ) +); + +DEFINE_EVENT(rtc_offset_class, rtc_set_offset, + + TP_PROTO(long offset, int err), + + TP_ARGS(offset, err) +); + +DEFINE_EVENT(rtc_offset_class, rtc_read_offset, + + TP_PROTO(long offset, int err), + + TP_ARGS(offset, err) +); + +DECLARE_EVENT_CLASS(rtc_timer_class, + + TP_PROTO(struct rtc_timer *timer), + + TP_ARGS(timer), + + TP_STRUCT__entry( + __field(struct rtc_timer *, timer) + __field(ktime_t, expires) + __field(ktime_t, period) + ), + + TP_fast_assign( + __entry->timer = timer; + __entry->expires = timer->node.expires; + __entry->period = timer->period; + ), + + TP_printk("RTC timer:(%p) expires:%lld period:%lld", + __entry->timer, __entry->expires, __entry->period + ) +); + +DEFINE_EVENT(rtc_timer_class, rtc_timer_enqueue, + + TP_PROTO(struct rtc_timer *timer), + + TP_ARGS(timer) +); + +DEFINE_EVENT(rtc_timer_class, rtc_timer_dequeue, + + TP_PROTO(struct rtc_timer *timer), + + TP_ARGS(timer) +); + +DEFINE_EVENT(rtc_timer_class, rtc_timer_fired, + + TP_PROTO(struct rtc_timer *timer), + + TP_ARGS(timer) +); + +#endif /* _TRACE_RTC_H */ + +/* This part must be outside protection */ +#include <trace/define_trace.h>
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: 2017-11-10 08:13:00 UTC (1510301580) (0) kworker/0:1-67 [000] 21.814312: rtc_read_time: 2017-11-10 08:13:00 UTC (1510301580) (0) set the first alarm timer: kworker/0:1-67 [000] 21.829238: rtc_timer_enqueue: RTC timer:(ffffffc15eb49bc8) expires:1510301700000000000 period:0 kworker/0:1-67 [000] 22.018279: rtc_set_alarm: 2017-11-10 08:15:00 UTC (1510301700) (0) set the second alarm timer: kworker/0:1-67 [000] 22.230284: rtc_timer_enqueue: RTC timer:(ffffff80088e6430) expires:1510301820000000000 period:0 the first alarm timer was expired: kworker/0:1-67 [000] 145.155584: rtc_timer_dequeue: RTC timer:(ffffffc15eb49bc8) expires:1510301700000000000 period:0 kworker/0:1-67 [000] 145.155593: rtc_timer_fired: RTC timer:(ffffffc15eb49bc8) expires:1510301700000000000 period:0 kworker/0:1-67 [000] 145.172504: rtc_set_alarm: 2017-11-10 08:17:00 UTC (1510301820) (0) the second alarm timer was expired: kworker/0:1-67 [000] 269.102353: rtc_timer_dequeue: RTC timer:(ffffff80088e6430) expires:1510301820000000000 period:0 kworker/0:1-67 [000] 269.102360: rtc_timer_fired: RTC timer:(ffffff80088e6430) expires:1510301820000000000 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 <baolin.wang@linaro.org> --- 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 | 220 ++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 250 insertions(+) create mode 100644 include/trace/events/rtc.h -- 1.7.9.5