From e54456f5bc70a46e11d23e1e3b2ae70bcda4c49f Mon Sep 17 00:00:00 2001 From: Mathieu Desnoyers Date: Thu, 16 Feb 2012 11:00:43 -0500 Subject: [PATCH] Add timer instrumentation Signed-off-by: Mathieu Desnoyers --- instrumentation/events/lttng-module/timer.h | 333 ++++++++++++++++++++ instrumentation/events/mainline/timer.h | 329 +++++++++++++++++++ probes/Makefile | 1 + probes/lttng-probe-timer.c | 31 ++ 4 files changed, 694 insertions(+) create mode 100644 instrumentation/events/lttng-module/timer.h create mode 100644 instrumentation/events/mainline/timer.h create mode 100644 probes/lttng-probe-timer.c diff --git a/instrumentation/events/lttng-module/timer.h b/instrumentation/events/lttng-module/timer.h new file mode 100644 index 00000000..fa89f663 --- /dev/null +++ b/instrumentation/events/lttng-module/timer.h @@ -0,0 +1,333 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM timer + +#if !defined(_TRACE_TIMER_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_TIMER_H + +#include + +#ifndef _TRACE_TIMER_DEF_ +#define _TRACE_TIMER_DEF_ +#include +#include +#endif /* _TRACE_TIMER_DEF_ */ + +DECLARE_EVENT_CLASS(timer_class, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer), + + TP_STRUCT__entry( + __field( void *, timer ) + ), + + TP_fast_assign( + tp_assign(timer, timer) + ), + + TP_printk("timer=%p", __entry->timer) +) + +/** + * timer_init - called when the timer is initialized + * @timer: pointer to struct timer_list + */ +DEFINE_EVENT(timer_class, timer_init, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer) +) + +/** + * timer_start - called when the timer is started + * @timer: pointer to struct timer_list + * @expires: the timers expiry time + */ +TRACE_EVENT(timer_start, + + TP_PROTO(struct timer_list *timer, unsigned long expires), + + TP_ARGS(timer, expires), + + TP_STRUCT__entry( + __field( void *, timer ) + __field( void *, function ) + __field( unsigned long, expires ) + __field( unsigned long, now ) + ), + + TP_fast_assign( + tp_assign(timer, timer) + tp_assign(function, timer->function) + tp_assign(expires, expires) + tp_assign(now, jiffies) + ), + + TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld]", + __entry->timer, __entry->function, __entry->expires, + (long)__entry->expires - __entry->now) +) + +/** + * timer_expire_entry - called immediately before the timer callback + * @timer: pointer to struct timer_list + * + * Allows to determine the timer latency. + */ +TRACE_EVENT(timer_expire_entry, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer), + + TP_STRUCT__entry( + __field( void *, timer ) + __field( unsigned long, now ) + __field( void *, function) + ), + + TP_fast_assign( + tp_assign(timer, timer) + tp_assign(now, jiffies) + tp_assign(function, timer->function) + ), + + TP_printk("timer=%p function=%pf now=%lu", __entry->timer, __entry->function,__entry->now) +) + +/** + * timer_expire_exit - called immediately after the timer callback returns + * @timer: pointer to struct timer_list + * + * When used in combination with the timer_expire_entry tracepoint we can + * determine the runtime of the timer callback function. + * + * NOTE: Do NOT derefernce timer in TP_fast_assign. The pointer might + * be invalid. We solely track the pointer. + */ +DEFINE_EVENT(timer_class, timer_expire_exit, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer) +) + +/** + * timer_cancel - called when the timer is canceled + * @timer: pointer to struct timer_list + */ +DEFINE_EVENT(timer_class, timer_cancel, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer) +) + +/** + * hrtimer_init - called when the hrtimer is initialized + * @timer: pointer to struct hrtimer + * @clockid: the hrtimers clock + * @mode: the hrtimers mode + */ +TRACE_EVENT(hrtimer_init, + + TP_PROTO(struct hrtimer *hrtimer, clockid_t clockid, + enum hrtimer_mode mode), + + TP_ARGS(hrtimer, clockid, mode), + + TP_STRUCT__entry( + __field( void *, hrtimer ) + __field( clockid_t, clockid ) + __field( enum hrtimer_mode, mode ) + ), + + TP_fast_assign( + tp_assign(hrtimer, hrtimer) + tp_assign(clockid, clockid) + tp_assign(mode, mode) + ), + + TP_printk("hrtimer=%p clockid=%s mode=%s", __entry->hrtimer, + __entry->clockid == CLOCK_REALTIME ? + "CLOCK_REALTIME" : "CLOCK_MONOTONIC", + __entry->mode == HRTIMER_MODE_ABS ? + "HRTIMER_MODE_ABS" : "HRTIMER_MODE_REL") +) + +/** + * hrtimer_start - called when the hrtimer is started + * @timer: pointer to struct hrtimer + */ +TRACE_EVENT(hrtimer_start, + + TP_PROTO(struct hrtimer *hrtimer), + + TP_ARGS(hrtimer), + + TP_STRUCT__entry( + __field( void *, hrtimer ) + __field( void *, function ) + __field( s64, expires ) + __field( s64, softexpires ) + ), + + TP_fast_assign( + tp_assign(hrtimer, hrtimer) + tp_assign(function, hrtimer->function) + tp_assign(expires, hrtimer_get_expires(hrtimer).tv64) + tp_assign(softexpires, hrtimer_get_softexpires(hrtimer).tv64) + ), + + TP_printk("hrtimer=%p function=%pf expires=%llu softexpires=%llu", + __entry->hrtimer, __entry->function, + (unsigned long long)ktime_to_ns((ktime_t) { + .tv64 = __entry->expires }), + (unsigned long long)ktime_to_ns((ktime_t) { + .tv64 = __entry->softexpires })) +) + +/** + * htimmer_expire_entry - called immediately before the hrtimer callback + * @timer: pointer to struct hrtimer + * @now: pointer to variable which contains current time of the + * timers base. + * + * Allows to determine the timer latency. + */ +TRACE_EVENT(hrtimer_expire_entry, + + TP_PROTO(struct hrtimer *hrtimer, ktime_t *now), + + TP_ARGS(hrtimer, now), + + TP_STRUCT__entry( + __field( void *, hrtimer ) + __field( s64, now ) + __field( void *, function) + ), + + TP_fast_assign( + tp_assign(hrtimer, hrtimer) + tp_assign(now, now->tv64) + tp_assign(function, hrtimer->function) + ), + + TP_printk("hrtimer=%p function=%pf now=%llu", __entry->hrtimer, __entry->function, + (unsigned long long)ktime_to_ns((ktime_t) { .tv64 = __entry->now })) +) + +DECLARE_EVENT_CLASS(hrtimer_class, + + TP_PROTO(struct hrtimer *hrtimer), + + TP_ARGS(hrtimer), + + TP_STRUCT__entry( + __field( void *, hrtimer ) + ), + + TP_fast_assign( + tp_assign(hrtimer, hrtimer) + ), + + TP_printk("hrtimer=%p", __entry->hrtimer) +) + +/** + * hrtimer_expire_exit - called immediately after the hrtimer callback returns + * @timer: pointer to struct hrtimer + * + * When used in combination with the hrtimer_expire_entry tracepoint we can + * determine the runtime of the callback function. + */ +DEFINE_EVENT(hrtimer_class, hrtimer_expire_exit, + + TP_PROTO(struct hrtimer *hrtimer), + + TP_ARGS(hrtimer) +) + +/** + * hrtimer_cancel - called when the hrtimer is canceled + * @hrtimer: pointer to struct hrtimer + */ +DEFINE_EVENT(hrtimer_class, hrtimer_cancel, + + TP_PROTO(struct hrtimer *hrtimer), + + TP_ARGS(hrtimer) +) + +/** + * itimer_state - called when itimer is started or canceled + * @which: name of the interval timer + * @value: the itimers value, itimer is canceled if value->it_value is + * zero, otherwise it is started + * @expires: the itimers expiry time + */ +TRACE_EVENT(itimer_state, + + TP_PROTO(int which, const struct itimerval *const value, + cputime_t expires), + + TP_ARGS(which, value, expires), + + TP_STRUCT__entry( + __field( int, which ) + __field( cputime_t, expires ) + __field( long, value_sec ) + __field( long, value_usec ) + __field( long, interval_sec ) + __field( long, interval_usec ) + ), + + TP_fast_assign( + tp_assign(which, which) + tp_assign(expires, expires) + tp_assign(value_sec, value->it_value.tv_sec) + tp_assign(value_usec, value->it_value.tv_usec) + tp_assign(interval_sec, value->it_interval.tv_sec) + tp_assign(interval_usec, value->it_interval.tv_usec) + ), + + TP_printk("which=%d expires=%llu it_value=%ld.%ld it_interval=%ld.%ld", + __entry->which, (unsigned long long)__entry->expires, + __entry->value_sec, __entry->value_usec, + __entry->interval_sec, __entry->interval_usec) +) + +/** + * itimer_expire - called when itimer expires + * @which: type of the interval timer + * @pid: pid of the process which owns the timer + * @now: current time, used to calculate the latency of itimer + */ +TRACE_EVENT(itimer_expire, + + TP_PROTO(int which, struct pid *pid, cputime_t now), + + TP_ARGS(which, pid, now), + + TP_STRUCT__entry( + __field( int , which ) + __field( pid_t, pid ) + __field( cputime_t, now ) + ), + + TP_fast_assign( + tp_assign(which, which) + tp_assign(now, now) + tp_assign(pid, pid_nr(pid)) + ), + + TP_printk("which=%d pid=%d now=%llu", __entry->which, + (int) __entry->pid, (unsigned long long)__entry->now) +) + +#endif /* _TRACE_TIMER_H */ + +/* This part must be outside protection */ +#include "../../../probes/define_trace.h" diff --git a/instrumentation/events/mainline/timer.h b/instrumentation/events/mainline/timer.h new file mode 100644 index 00000000..425bcfe5 --- /dev/null +++ b/instrumentation/events/mainline/timer.h @@ -0,0 +1,329 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM timer + +#if !defined(_TRACE_TIMER_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_TIMER_H + +#include +#include +#include + +DECLARE_EVENT_CLASS(timer_class, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer), + + TP_STRUCT__entry( + __field( void *, timer ) + ), + + TP_fast_assign( + __entry->timer = timer; + ), + + TP_printk("timer=%p", __entry->timer) +); + +/** + * timer_init - called when the timer is initialized + * @timer: pointer to struct timer_list + */ +DEFINE_EVENT(timer_class, timer_init, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer) +); + +/** + * timer_start - called when the timer is started + * @timer: pointer to struct timer_list + * @expires: the timers expiry time + */ +TRACE_EVENT(timer_start, + + TP_PROTO(struct timer_list *timer, unsigned long expires), + + TP_ARGS(timer, expires), + + TP_STRUCT__entry( + __field( void *, timer ) + __field( void *, function ) + __field( unsigned long, expires ) + __field( unsigned long, now ) + ), + + TP_fast_assign( + __entry->timer = timer; + __entry->function = timer->function; + __entry->expires = expires; + __entry->now = jiffies; + ), + + TP_printk("timer=%p function=%pf expires=%lu [timeout=%ld]", + __entry->timer, __entry->function, __entry->expires, + (long)__entry->expires - __entry->now) +); + +/** + * timer_expire_entry - called immediately before the timer callback + * @timer: pointer to struct timer_list + * + * Allows to determine the timer latency. + */ +TRACE_EVENT(timer_expire_entry, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer), + + TP_STRUCT__entry( + __field( void *, timer ) + __field( unsigned long, now ) + __field( void *, function) + ), + + TP_fast_assign( + __entry->timer = timer; + __entry->now = jiffies; + __entry->function = timer->function; + ), + + TP_printk("timer=%p function=%pf now=%lu", __entry->timer, __entry->function,__entry->now) +); + +/** + * timer_expire_exit - called immediately after the timer callback returns + * @timer: pointer to struct timer_list + * + * When used in combination with the timer_expire_entry tracepoint we can + * determine the runtime of the timer callback function. + * + * NOTE: Do NOT derefernce timer in TP_fast_assign. The pointer might + * be invalid. We solely track the pointer. + */ +DEFINE_EVENT(timer_class, timer_expire_exit, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer) +); + +/** + * timer_cancel - called when the timer is canceled + * @timer: pointer to struct timer_list + */ +DEFINE_EVENT(timer_class, timer_cancel, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer) +); + +/** + * hrtimer_init - called when the hrtimer is initialized + * @timer: pointer to struct hrtimer + * @clockid: the hrtimers clock + * @mode: the hrtimers mode + */ +TRACE_EVENT(hrtimer_init, + + TP_PROTO(struct hrtimer *hrtimer, clockid_t clockid, + enum hrtimer_mode mode), + + TP_ARGS(hrtimer, clockid, mode), + + TP_STRUCT__entry( + __field( void *, hrtimer ) + __field( clockid_t, clockid ) + __field( enum hrtimer_mode, mode ) + ), + + TP_fast_assign( + __entry->hrtimer = hrtimer; + __entry->clockid = clockid; + __entry->mode = mode; + ), + + TP_printk("hrtimer=%p clockid=%s mode=%s", __entry->hrtimer, + __entry->clockid == CLOCK_REALTIME ? + "CLOCK_REALTIME" : "CLOCK_MONOTONIC", + __entry->mode == HRTIMER_MODE_ABS ? + "HRTIMER_MODE_ABS" : "HRTIMER_MODE_REL") +); + +/** + * hrtimer_start - called when the hrtimer is started + * @timer: pointer to struct hrtimer + */ +TRACE_EVENT(hrtimer_start, + + TP_PROTO(struct hrtimer *hrtimer), + + TP_ARGS(hrtimer), + + TP_STRUCT__entry( + __field( void *, hrtimer ) + __field( void *, function ) + __field( s64, expires ) + __field( s64, softexpires ) + ), + + TP_fast_assign( + __entry->hrtimer = hrtimer; + __entry->function = hrtimer->function; + __entry->expires = hrtimer_get_expires(hrtimer).tv64; + __entry->softexpires = hrtimer_get_softexpires(hrtimer).tv64; + ), + + TP_printk("hrtimer=%p function=%pf expires=%llu softexpires=%llu", + __entry->hrtimer, __entry->function, + (unsigned long long)ktime_to_ns((ktime_t) { + .tv64 = __entry->expires }), + (unsigned long long)ktime_to_ns((ktime_t) { + .tv64 = __entry->softexpires })) +); + +/** + * htimmer_expire_entry - called immediately before the hrtimer callback + * @timer: pointer to struct hrtimer + * @now: pointer to variable which contains current time of the + * timers base. + * + * Allows to determine the timer latency. + */ +TRACE_EVENT(hrtimer_expire_entry, + + TP_PROTO(struct hrtimer *hrtimer, ktime_t *now), + + TP_ARGS(hrtimer, now), + + TP_STRUCT__entry( + __field( void *, hrtimer ) + __field( s64, now ) + __field( void *, function) + ), + + TP_fast_assign( + __entry->hrtimer = hrtimer; + __entry->now = now->tv64; + __entry->function = hrtimer->function; + ), + + TP_printk("hrtimer=%p function=%pf now=%llu", __entry->hrtimer, __entry->function, + (unsigned long long)ktime_to_ns((ktime_t) { .tv64 = __entry->now })) + ); + +DECLARE_EVENT_CLASS(hrtimer_class, + + TP_PROTO(struct hrtimer *hrtimer), + + TP_ARGS(hrtimer), + + TP_STRUCT__entry( + __field( void *, hrtimer ) + ), + + TP_fast_assign( + __entry->hrtimer = hrtimer; + ), + + TP_printk("hrtimer=%p", __entry->hrtimer) +); + +/** + * hrtimer_expire_exit - called immediately after the hrtimer callback returns + * @timer: pointer to struct hrtimer + * + * When used in combination with the hrtimer_expire_entry tracepoint we can + * determine the runtime of the callback function. + */ +DEFINE_EVENT(hrtimer_class, hrtimer_expire_exit, + + TP_PROTO(struct hrtimer *hrtimer), + + TP_ARGS(hrtimer) +); + +/** + * hrtimer_cancel - called when the hrtimer is canceled + * @hrtimer: pointer to struct hrtimer + */ +DEFINE_EVENT(hrtimer_class, hrtimer_cancel, + + TP_PROTO(struct hrtimer *hrtimer), + + TP_ARGS(hrtimer) +); + +/** + * itimer_state - called when itimer is started or canceled + * @which: name of the interval timer + * @value: the itimers value, itimer is canceled if value->it_value is + * zero, otherwise it is started + * @expires: the itimers expiry time + */ +TRACE_EVENT(itimer_state, + + TP_PROTO(int which, const struct itimerval *const value, + cputime_t expires), + + TP_ARGS(which, value, expires), + + TP_STRUCT__entry( + __field( int, which ) + __field( cputime_t, expires ) + __field( long, value_sec ) + __field( long, value_usec ) + __field( long, interval_sec ) + __field( long, interval_usec ) + ), + + TP_fast_assign( + __entry->which = which; + __entry->expires = expires; + __entry->value_sec = value->it_value.tv_sec; + __entry->value_usec = value->it_value.tv_usec; + __entry->interval_sec = value->it_interval.tv_sec; + __entry->interval_usec = value->it_interval.tv_usec; + ), + + TP_printk("which=%d expires=%llu it_value=%ld.%ld it_interval=%ld.%ld", + __entry->which, (unsigned long long)__entry->expires, + __entry->value_sec, __entry->value_usec, + __entry->interval_sec, __entry->interval_usec) +); + +/** + * itimer_expire - called when itimer expires + * @which: type of the interval timer + * @pid: pid of the process which owns the timer + * @now: current time, used to calculate the latency of itimer + */ +TRACE_EVENT(itimer_expire, + + TP_PROTO(int which, struct pid *pid, cputime_t now), + + TP_ARGS(which, pid, now), + + TP_STRUCT__entry( + __field( int , which ) + __field( pid_t, pid ) + __field( cputime_t, now ) + ), + + TP_fast_assign( + __entry->which = which; + __entry->now = now; + __entry->pid = pid_nr(pid); + ), + + TP_printk("which=%d pid=%d now=%llu", __entry->which, + (int) __entry->pid, (unsigned long long)__entry->now) +); + +#endif /* _TRACE_TIMER_H */ + +/* This part must be outside protection */ +#include diff --git a/probes/Makefile b/probes/Makefile index d86ee87d..698a9c9c 100644 --- a/probes/Makefile +++ b/probes/Makefile @@ -13,6 +13,7 @@ obj-m += lttng-probe-lttng.o obj-m += lttng-probe-sched.o obj-m += lttng-probe-irq.o obj-m += lttng-probe-signal.o +obj-m += lttng-probe-timer.o obj-m += lttng-probe-statedump.o diff --git a/probes/lttng-probe-timer.c b/probes/lttng-probe-timer.c new file mode 100644 index 00000000..8abde6df --- /dev/null +++ b/probes/lttng-probe-timer.c @@ -0,0 +1,31 @@ +/* + * probes/lttng-probe-timer.c + * + * Copyright 2012 (c) - Mathieu Desnoyers + * + * LTTng timer probes. + * + * Dual LGPL v2.1/GPL v2 license. + */ + +#include + +/* + * Create the tracepoint static inlines from the kernel to validate that our + * trace event macros match the kernel we run on. + */ +#include +#include + +/* + * Create LTTng tracepoint probes. + */ +#define LTTNG_PACKAGE_BUILD +#define CREATE_TRACE_POINTS +#define TRACE_INCLUDE_PATH ../instrumentation/events/lttng-module + +#include "../instrumentation/events/lttng-module/timer.h" + +MODULE_LICENSE("GPL and additional rights"); +MODULE_AUTHOR("Mathieu Desnoyers "); +MODULE_DESCRIPTION("LTTng timer probes"); -- 2.34.1