ftrace: add tracepoint for timer event

new file mode 100644
index 0000000..ff2754a
@@ -0,0 +1,116 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM timer
+
+#if !defined(_TRACE_TIMER_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_TIMER_H
+
+#include <linux/tracepoint.h>
+#include <linux/timer.h>
+#include <linux/hrtimer.h>
+
+/**
+ * timer_entry - called immediately before the timer callback
+ * @timer: pointer to struct timer_list
+ *
+ * When used in combination with the timer_exit tracepoint we can
+ * determine the timer latency.
+ **/
+TRACE_EVENT(timer_entry,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field(void *, function)
+	),
+
+	TP_fast_assign(
+		__entry->function = timer->function;
+	),
+
+	TP_printk("func=%pf", __entry->function)
+);
+
+/**
+ * timer_exit - called immediately after the timer returns
+ * @timer: pointer to struct timer_list
+ *
+ * When used in combination with the timer_entry tracepoint we can
+ * determine the timer latency.
+ **/
+TRACE_EVENT(timer_exit,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field(void *, function)
+	),
+
+	TP_fast_assign(
+		__entry->function = timer->function;
+	),
+
+	TP_printk("func=%pf", __entry->function)
+);
+
+/**
+ * hrtimer_entry - called immediately before the high res timer callback
+ * @timer: pointer to struct hrtimer
+ *
+ * When used in combination with the hrtimer_exit tracepoint we can
+ * determine the high res timer latency.
+ **/
+TRACE_EVENT(hrtimer_entry,
+
+	TP_PROTO(struct hrtimer *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field(void *, function)
+	),
+
+	TP_fast_assign(
+		__entry->function = timer->function;
+	),
+
+	TP_printk("func=%pf", __entry->function)
+);
+
+/**
+ * hrtimer_exit - called immediately after the high res timer returns
+ * @timer: pointer to struct hrtimer
+ * @restart: high res timer return value
+ *
+ * High res timer will restart if @restart is set to HRTIMER_RESTART.
+ * When used in combination with the hrtimer_entry tracepoint we can
+ * determine the high res timer latency.
+ **/
+TRACE_EVENT(hrtimer_exit,
+
+	TP_PROTO(struct hrtimer *timer, int restart),
+
+	TP_ARGS(timer, restart),
+
+	TP_STRUCT__entry(
+		__field(void *, function)
+		__field(int, restart)
+	),
+
+	TP_fast_assign(
+		__entry->function = timer->function;
+		__entry->restart = restart;
+	),
+
+	TP_printk("func=%pf restart=%s", __entry->function,
+		(__entry->restart == HRTIMER_RESTART) ?
+			"HRTIMER_RESTART" : "HRTIMER_NORESTART")
+);
+
+#endif /*  _TRACE_TIMER_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

index ab5eb70..33317e4 100644
@@ -47,6 +47,7 @@
 #include <linux/timer.h>
 
 #include <asm/uaccess.h>
+#include <trace/events/timer.h>
 
 /*
  * The timer bases:

@@ -1161,7 +1162,9 @@ static void __run_hrtimer(struct hrtimer *timer)
 	 * the timer base.
 	 */
 	spin_unlock(&cpu_base->lock);
+	trace_hrtimer_entry(timer);
 	restart = fn(timer);
+	trace_hrtimer_exit(timer, restart);
 	spin_lock(&cpu_base->lock);
 
 	/*

index 0b36b9e..9385ad5 100644
@@ -46,6 +46,9 @@
 #include <asm/timex.h>
 #include <asm/io.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/timer.h>
+
 u64 jiffies_64 __cacheline_aligned_in_smp = INITIAL_JIFFIES;
 
 EXPORT_SYMBOL(jiffies_64);

@@ -984,7 +987,9 @@ static inline void __run_timers(struct tvec_base *base)
 				 */
 				lock_map_acquire(&lockdep_map);
 
+				trace_timer_entry(timer);
 				fn(data);
+				trace_timer_exit(timer);
 
 				lock_map_release(&lockdep_map);
 

index ff2754a..967e225 100644
@@ -8,52 +8,112 @@
 #include <linux/timer.h>
 #include <linux/hrtimer.h>
 
+TRACE_EVENT(timer_init,
+
+	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)
+);
+
+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( int,		timeout		)
+	),
+
+	TP_fast_assign(
+		__entry->timer		= timer;
+		__entry->function	= timer->function;
+		__entry->expires	= expires;
+		__entry->timeout	= timer->expires - jiffies;
+	),
+
+	TP_printk("timer=%p func=%pf expires=%lu timeout=%d", __entry->timer,
+		  __entry->function, __entry->expires, __entry->timeout)
+);
+
 /**
- * timer_entry - called immediately before the timer callback
+ * timer_expire - called immediately before the timer callback
  * @timer: pointer to struct timer_list
  *
- * When used in combination with the timer_exit tracepoint we can
+ * When used in combination with the timer_callback_done tracepoint we can
  * determine the timer latency.
  **/
-TRACE_EVENT(timer_entry,
+TRACE_EVENT(timer_expire,
 
 	TP_PROTO(struct timer_list *timer),
 
 	TP_ARGS(timer),
 
 	TP_STRUCT__entry(
-		__field(void *, function)
+		__field( void *,	timer	)
+		__field( unsigned long,	jiffies	)
 	),
 
 	TP_fast_assign(
-		__entry->function = timer->function;
+		__entry->timer		= timer;
+		__entry->jiffies	= jiffies;
 	),
 
-	TP_printk("func=%pf", __entry->function)
+	TP_printk("timer=%p jiffies=%lu", __entry->timer, __entry->jiffies)
 );
 
 /**
- * timer_exit - called immediately after the timer returns
+ * timer_callback_done - called immediately after the timer returns
  * @timer: pointer to struct timer_list
  *
- * When used in combination with the timer_entry tracepoint we can
+ * When used in combination with the timer_expire tracepoint we can
  * determine the timer latency.
  **/
-TRACE_EVENT(timer_exit,
+TRACE_EVENT(timer_callback_done,
 
 	TP_PROTO(struct timer_list *timer),
 
 	TP_ARGS(timer),
 
 	TP_STRUCT__entry(
-		__field(void *, function)
+		__field(void *,	timer	)
 	),
 
 	TP_fast_assign(
-		__entry->function = timer->function;
+		__entry->timer	= timer;
 	),
 
-	TP_printk("func=%pf", __entry->function)
+	TP_printk("func=%p", __entry->timer)
+);
+
+TRACE_EVENT(timer_cancel,
+
+	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)
 );
 
 /**

index 9385ad5..0f53710 100644
@@ -523,6 +523,25 @@ static inline void debug_timer_activate(struct timer_list *timer) { }
 static inline void debug_timer_deactivate(struct timer_list *timer) { }
 #endif
 
+static inline void debug_and_trace_timer_init(struct timer_list *timer)
+{
+	debug_timer_init(timer);
+	trace_timer_init(timer);
+}
+
+static inline void
+debug_and_trace_timer_activate(struct timer_list *timer, unsigned long expires)
+{
+	debug_timer_activate(timer);
+	trace_timer_start(timer, expires);
+}
+
+static inline void debug_and_trace_timer_deactivate(struct timer_list *timer)
+{
+	debug_timer_deactivate(timer);
+	trace_timer_cancel(timer);
+}
+
 static void __init_timer(struct timer_list *timer,
 			 const char *name,
 			 struct lock_class_key *key)

@@ -551,7 +570,7 @@ void init_timer_key(struct timer_list *timer,
 		    const char *name,
 		    struct lock_class_key *key)
 {
-	debug_timer_init(timer);
+	debug_and_trace_timer_init(timer);
 	__init_timer(timer, name, key);
 }
 EXPORT_SYMBOL(init_timer_key);

@@ -570,7 +589,7 @@ static inline void detach_timer(struct timer_list *timer,
 {
 	struct list_head *entry = &timer->entry;
 
-	debug_timer_deactivate(timer);
+	debug_and_trace_timer_deactivate(timer);
 
 	__list_del(entry->prev, entry->next);
 	if (clear_pending)

@@ -631,7 +650,7 @@ __mod_timer(struct timer_list *timer, unsigned long expires,
 			goto out_unlock;
 	}
 
-	debug_timer_activate(timer);
+	debug_and_trace_timer_activate(timer, expires);
 
 	new_base = __get_cpu_var(tvec_bases);
 

@@ -783,7 +802,7 @@ void add_timer_on(struct timer_list *timer, int cpu)
 	BUG_ON(timer_pending(timer) || !timer->function);
 	spin_lock_irqsave(&base->lock, flags);
 	timer_set_base(timer, base);
-	debug_timer_activate(timer);
+	debug_and_trace_timer_activate(timer, timer->expires);
 	internal_add_timer(base, timer);
 	/*
 	 * Check whether the other CPU is idle and needs to be

@@ -987,9 +1006,9 @@ static inline void __run_timers(struct tvec_base *base)
 				 */
 				lock_map_acquire(&lockdep_map);
 
-				trace_timer_entry(timer);
+				trace_timer_expire(timer);
 				fn(data);
-				trace_timer_exit(timer);
+				trace_timer_callback_done(timer);
 
 				lock_map_release(&lockdep_map);
 

index 967e225..8b22b12 100644
@@ -116,58 +116,125 @@ TRACE_EVENT(timer_cancel,
 	TP_printk("timer=%p", __entry->timer)
 );
 
+TRACE_EVENT(hrtimer_init,
+
+	TP_PROTO(struct hrtimer *timer, clockid_t clockid, enum hrtimer_mode mode),
+
+	TP_ARGS(timer, clockid, mode),
+
+	TP_STRUCT__entry(
+		__field( void *,		timer		)
+		__field( clockid_t,		clockid		)
+		__field( enum hrtimer_mode,	mode		)
+	),
+
+	TP_fast_assign(
+		__entry->timer		= timer;
+		__entry->clockid	= clockid;
+		__entry->mode		= mode;
+	),
+
+	TP_printk("timer=%p clockid=%s mode=%s", __entry->timer,
+		  __entry->clockid == CLOCK_REALTIME ?
+			"CLOCK_REALTIME" : "CLOCK_MONOTONIC",
+		  __entry->mode == HRTIMER_MODE_ABS ?
+			"HRTIMER_MODE_ABS" : "HRTIMER_MODE_REL")
+);
+
+TRACE_EVENT(hrtimer_start,
+
+	TP_PROTO(struct hrtimer *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer		)
+		__field( void *,	function	)
+		__field( s64,		expires		)
+		__field( s64,		softexpires	)
+	),
+
+	TP_fast_assign(
+		__entry->timer		= timer;
+		__entry->function	= timer->function;
+		__entry->expires	= hrtimer_get_expires(timer).tv64;
+		__entry->softexpires	= hrtimer_get_softexpires(timer).tv64;
+	),
+
+	TP_printk("timer=%p func=%pf expires=%llu ns softexpires=%llu ns",
+		  __entry->timer, __entry->function,
+		 (unsigned long long)__entry->expires,
+		 (unsigned long long)__entry->softexpires)
+);
+
 /**
- * hrtimer_entry - called immediately before the high res timer callback
+ * htimmer_expire - called before the high res timer callback
  * @timer: pointer to struct hrtimer
  *
- * When used in combination with the hrtimer_exit tracepoint we can
+ * When used in combination with the hrtimer_callback_done tracepoint we can
  * determine the high res timer latency.
  **/
-TRACE_EVENT(hrtimer_entry,
+TRACE_EVENT(hrtimer_expire,
 
-	TP_PROTO(struct hrtimer *timer),
+	TP_PROTO(struct hrtimer *timer, s64 now),
 
-	TP_ARGS(timer),
+	TP_ARGS(timer, now),
 
 	TP_STRUCT__entry(
-		__field(void *, function)
+		__field( void *,	timer	)
+		__field( s64,		now	)
 	),
 
 	TP_fast_assign(
-		__entry->function = timer->function;
+		__entry->timer	= timer;
+		__entry->now	= now;
 	),
 
-	TP_printk("func=%pf", __entry->function)
+	TP_printk("timer=%p now=%llu ns", __entry->timer,
+		 (unsigned long long)__entry->now)
 );
 
 /**
- * hrtimer_exit - called immediately after the high res timer returns
+ * hrtimer_callback_done - called immediately after the high res timer returns
  * @timer: pointer to struct hrtimer
  * @restart: high res timer return value
  *
  * High res timer will restart if @restart is set to HRTIMER_RESTART.
- * When used in combination with the hrtimer_entry tracepoint we can
+ * When used in combination with the hrtimer_expire tracepoint we can
  * determine the high res timer latency.
  **/
-TRACE_EVENT(hrtimer_exit,
+TRACE_EVENT(hrtimer_callback_done,
 
-	TP_PROTO(struct hrtimer *timer, int restart),
+	TP_PROTO(struct hrtimer *timer),
 
-	TP_ARGS(timer, restart),
+	TP_ARGS(timer),
 
 	TP_STRUCT__entry(
-		__field(void *, function)
-		__field(int, restart)
+		__field( void *,	timer	)
 	),
 
 	TP_fast_assign(
-		__entry->function = timer->function;
-		__entry->restart = restart;
+		__entry->timer	= timer;
 	),
 
-	TP_printk("func=%pf restart=%s", __entry->function,
-		(__entry->restart == HRTIMER_RESTART) ?
-			"HRTIMER_RESTART" : "HRTIMER_NORESTART")
+	TP_printk("timer=%p", __entry->timer)
+);
+
+TRACE_EVENT(hrtimer_cancel,
+
+	TP_PROTO(struct hrtimer *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer	)
+	),
+
+	TP_fast_assign(
+		__entry->timer	= timer;
+	),
+
+	TP_printk("timer=%p", __entry->timer)
 );
 
 #endif /*  _TRACE_TIMER_H */

index 33317e4..bd21c9b 100644
@@ -442,6 +442,26 @@ static inline void debug_hrtimer_activate(struct hrtimer *timer) { }
 static inline void debug_hrtimer_deactivate(struct hrtimer *timer) { }
 #endif
 
+static inline void
+debug_and_trace_hrtimer_init(struct hrtimer *timer, clockid_t clockid,
+			     enum hrtimer_mode mode)
+{
+	debug_hrtimer_init(timer);
+	trace_hrtimer_init(timer, clockid, mode);
+}
+
+static inline void debug_and_trace_hrtimer_activate(struct hrtimer *timer)
+{
+	debug_hrtimer_activate(timer);
+	trace_hrtimer_start(timer);
+}
+
+static inline void debug_and_trace_hrtimer_deactivate(struct hrtimer *timer)
+{
+	debug_hrtimer_deactivate(timer);
+	trace_hrtimer_cancel(timer);
+}
+
 /* High resolution timer related functions */
 #ifdef CONFIG_HIGH_RES_TIMERS
 

@@ -798,7 +818,7 @@ static int enqueue_hrtimer(struct hrtimer *timer,
 	struct hrtimer *entry;
 	int leftmost = 1;
 
-	debug_hrtimer_activate(timer);
+	debug_and_trace_hrtimer_activate(timer);
 
 	/*
 	 * Find the right place in the rbtree:

@@ -884,7 +904,7 @@ remove_hrtimer(struct hrtimer *timer, struct hrtimer_clock_base *base)
 		 * reprogramming happens in the interrupt handler. This is a
 		 * rare case and less expensive than a smp call.
 		 */
-		debug_hrtimer_deactivate(timer);
+		debug_and_trace_hrtimer_deactivate(timer);
 		timer_stats_hrtimer_clear_start_info(timer);
 		reprogram = base->cpu_base == &__get_cpu_var(hrtimer_bases);
 		__remove_hrtimer(timer, base, HRTIMER_STATE_INACTIVE,

@@ -1118,7 +1138,7 @@ static void __hrtimer_init(struct hrtimer *timer, clockid_t clock_id,
 void hrtimer_init(struct hrtimer *timer, clockid_t clock_id,
 		  enum hrtimer_mode mode)
 {
-	debug_hrtimer_init(timer);
+	debug_and_trace_hrtimer_init(timer, clock_id, mode);
 	__hrtimer_init(timer, clock_id, mode);
 }
 EXPORT_SYMBOL_GPL(hrtimer_init);

@@ -1151,7 +1171,7 @@ static void __run_hrtimer(struct hrtimer *timer)
 
 	WARN_ON(!irqs_disabled());
 
-	debug_hrtimer_deactivate(timer);
+	debug_and_trace_hrtimer_deactivate(timer);
 	__remove_hrtimer(timer, base, HRTIMER_STATE_CALLBACK, 0);
 	timer_stats_account_hrtimer(timer);
 	fn = timer->function;

@@ -1162,9 +1182,8 @@ static void __run_hrtimer(struct hrtimer *timer)
 	 * the timer base.
 	 */
 	spin_unlock(&cpu_base->lock);
-	trace_hrtimer_entry(timer);
 	restart = fn(timer);
-	trace_hrtimer_exit(timer, restart);
+	trace_hrtimer_callback_done(timer);
 	spin_lock(&cpu_base->lock);
 
 	/*

@@ -1275,6 +1294,7 @@ void hrtimer_interrupt(struct clock_event_device *dev)
 				break;
 			}
 
+			trace_hrtimer_expire(timer, basenow.tv64);
 			__run_hrtimer(timer);
 		}
 		base++;

@@ -1397,6 +1417,7 @@ void hrtimer_run_queues(void)
 					hrtimer_get_expires_tv64(timer))
 				break;
 
+			trace_hrtimer_expire(timer, base->softirq_time.tv64);
 			__run_hrtimer(timer);
 		}
 		spin_unlock(&cpu_base->lock);

@@ -1573,7 +1594,7 @@ static void migrate_hrtimer_list(struct hrtimer_clock_base *old_base,
 	while ((node = rb_first(&old_base->active))) {
 		timer = rb_entry(node, struct hrtimer, node);
 		BUG_ON(hrtimer_callback_running(timer));
-		debug_hrtimer_deactivate(timer);
+		debug_and_trace_hrtimer_deactivate(timer);
 
 		/*
 		 * Mark it as STATE_MIGRATE not INACTIVE otherwise the

index 8b22b12..0a77f34 100644
@@ -237,6 +237,58 @@ TRACE_EVENT(hrtimer_cancel,
 	TP_printk("timer=%p", __entry->timer)
 );
 
+TRACE_EVENT(itimer_state,
+
+	TP_PROTO(int which, struct itimerval *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=%lu it_value=%lu.%lu it_interval=%lu.%lu",
+		  __entry->which, __entry->expires,
+		  __entry->value_sec, __entry->value_usec,
+		  __entry->interval_sec, __entry->interval_usec)
+);
+
+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( int,		pid	)
+		__field( cputime_t,	now	)
+	),
+
+	TP_fast_assign(
+		__entry->which	= which;
+		__entry->now	= now;
+		__entry->pid	= pid_vnr(pid);
+	),
+
+	TP_printk("pid=%d which=%d now=%lu", __entry->pid, __entry->which,
+		  __entry->now)
+);
+
 #endif /*  _TRACE_TIMER_H */
 
 /* This part must be outside protection */

index 58762f7..7e9ee89 100644
@@ -12,6 +12,7 @@
 #include <linux/time.h>
 #include <linux/posix-timers.h>
 #include <linux/hrtimer.h>
+#include <trace/events/timer.h>
 
 #include <asm/uaccess.h>
 

@@ -123,6 +124,7 @@ enum hrtimer_restart it_real_fn(struct hrtimer *timer)
 	struct signal_struct *sig =
 		container_of(timer, struct signal_struct, real_timer);
 
+	trace_itimer_expire(ITIMER_REAL, sig->leader_pid, 0);
 	kill_pid_info(SIGALRM, SEND_SIG_PRIV, sig->leader_pid);
 
 	return HRTIMER_NORESTART;

@@ -139,7 +141,7 @@ int do_setitimer(int which, struct itimerval *value, struct itimerval *ovalue)
 	struct task_struct *tsk = current;
 	struct hrtimer *timer;
 	ktime_t expires;
-	cputime_t cval, cinterval, nval, ninterval;
+	cputime_t cval, cinterval, nval = 0, ninterval;
 
 	/*
 	 * Validate the timevals in value.

@@ -220,6 +222,7 @@ again:
 	default:
 		return -EINVAL;
 	}
+	trace_itimer_state(which, value, nval);
 	return 0;
 }
 

index bece7c0..63e93bf 100644
@@ -8,6 +8,7 @@
 #include <linux/math64.h>
 #include <asm/uaccess.h>
 #include <linux/kernel_stat.h>
+#include <trace/events/timer.h>
 
 /*
  * Called after updating RLIMIT_CPU to set timer expiration if necessary.

@@ -1160,6 +1161,7 @@ static void check_process_timers(struct task_struct *tsk,
 				sig->it_prof_expires = cputime_add(
 					sig->it_prof_expires, ptime);
 			}
+			trace_itimer_expire(ITIMER_PROF, sig->leader_pid, ptime);
 			__group_send_sig_info(SIGPROF, SEND_SIG_PRIV, tsk);
 		}
 		if (!cputime_eq(sig->it_prof_expires, cputime_zero) &&

@@ -1176,6 +1178,7 @@ static void check_process_timers(struct task_struct *tsk,
 				sig->it_virt_expires = cputime_add(
 					sig->it_virt_expires, utime);
 			}
+			trace_itimer_expire(ITIMER_VIRTUAL, sig->leader_pid, utime);
 			__group_send_sig_info(SIGVTALRM, SEND_SIG_PRIV, tsk);
 		}
 		if (!cputime_eq(sig->it_virt_expires, cputime_zero) &&