[PATCH v2 3/3] ftrace: add tracepoint for itimer

Xiao Guangrong
2009-07-06T09:42:18Z

Those tracepoints are wanted and useful:
1: We can detect a itimer's delay
2: We can monitor the lifecycle and behaviors of a itimer

Thus they help in analysing and debuging.

Great thanks to Thomas for giving me so many valuable advices.

There have two case:
case 1, if we use ITIMER_REAL itimer:
Example ftrace output:
main-1649 [001] 1674.034138: hrtimer_start: timer=ce97d3a4 func=it_real_fn expires=1679993510723 ns softexpires=1679993510723 ns
main-1649 [001] 1674.034140: itimer_state: task=main which=0 state:start timer=ce97d3a4 expires=0 it_value=2.0 it_interval=0.500000
main-1649 [001] 1676.029184: hrtimer_expire: timer=ce97d3a4 func=it_real_fn now=1679993511197
main-1649 [001] 1676.029185: hrtimer_cancel: timer=ce97d3a4 func=it_real_fn
main-1649 [001] 1676.029190: itimer_expire: task=main which=0 now=0
main-1649 [001] 1676.034744: itimer_state: task=main which=0 state:cancel timer=ce97d3a4 expires=0 it_value=0.0 it_interval=0.0

ITIMER_REAL itime use hrtimer to calculate time, so we can cooperate with
hrtimer's tracepoint to get it's delay.

from this output information, the process set up a ITIMER_REAL
iteimr(which=0), use a hrtime which address is ce97d3a4, we can get the
delay is 1679993511197-1679993510723 = 474 ns

case 2, if we use ITIMER_VIRTUAL/ITIMER_PROF itimer:
Example ftrace output:
main-1600 [000] 524.081367: itimer_state: task=main which=2 state:start timer=(null) expires=2008 it_value=2.0 it_interval=0.500000
main-1600 [000] 526.084820: itimer_expire: task=main which=2 now=2008
main-1600 [000] 526.088912: itimer_state: task=main which=2 state:cancel timer=(null) expires=0 it_value=0.0 it_interval=0.0

from this, we can know the itimer delay is 2008-2008=0 jiffies.

Changelog v1->v2:
1: Remove ktime_to_ns() in TP_fast_assign()
2: Combine debugobjects and trace as Thomas's suggestion

Signed-off-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
---
include/trace/events/timer.h | 66 ++++++++++++++++++++++++++++++++++++++++++
kernel/itimer.c | 3 ++
kernel/posix-cpu-timers.c | 3 ++
3 files changed, 72 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index 8ffb2e2..66d33e1 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -4,6 +4,7 @@
#include <linux/tracepoint.h>
#include <linux/timer.h>
#include <linux/hrtimer.h>
+#include <linux/time.h>

#undef TRACE_SYSTEM
#define TRACE_SYSTEM timer
@@ -282,6 +283,71 @@ TRACE_EVENT(hrtimer_cancel,
TP_printk("timer=%p func=%pf", __entry->timer, __entry->function)
);

+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( void *, timer )
+ __field( int, state )
+ __field( cputime_t, expires )
+ __field( long, value_sec )
+ __field( long, value_usec )
+ __field( long, interval_sec )
+ __field( long, interval_usec )
+ __string( comm, current->comm )
+ ),
+
+ TP_fast_assign(
+ __entry->which = which;
+ __entry->timer = which == ITIMER_REAL ?
+ &current->signal->real_timer : NULL;
+ __entry->state = (value->it_value.tv_sec != 0 ||
+ value->it_value.tv_usec != 0) ? 1 : 0;
+ __entry->expires = which == ITIMER_REAL ? 0 : 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;
+ __assign_str(comm, current->comm);
+ ),
+
+ TP_printk("task=%s which=%d state:%s timer=%p expires=%lu "
+ "it_value=%lu.%lu it_interval=%lu.%lu",
+ __get_str(comm), __entry->which,
+ __entry->state ? "start" : "cancel", __entry->timer,
+ __entry->expires, __entry->value_sec, __entry->value_usec,
+ __entry->interval_sec, __entry->interval_usec)
+);
+
+TRACE_EVENT(itimer_expire,
+
+ TP_PROTO(int which, struct task_struct *task, struct pid *pid, cputime_t now),
+
+ TP_ARGS(which, task, pid, now),
+
+ TP_STRUCT__entry(
+ __field( int , which )
+ __field( cputime_t, now )
+ __array( char, comm, TASK_COMM_LEN )
+ ),
+
+ TP_fast_assign(
+ __entry->which = which;
+ __entry->now = now;
+ if (pid)
+ strcpy(__entry->comm, pid_task(pid, PIDTYPE_PID)->comm);
+ else
+ strcpy(__entry->comm, task->comm);
+ ),
+
+ TP_printk("task=%s which=%d now=%lu", __entry->comm, __entry->which,
+ __entry->now)
+);
+
#endif /* _TRACE_TIMER_H */

/* This part must be outside protection */
diff --git a/kernel/itimer.c b/kernel/itimer.c
index 58762f7..ee3a810 100644
--- a/kernel/itimer.c
+++ b/kernel/itimer.c
@@ -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, NULL, sig->leader_pid, 0);
kill_pid_info(SIGALRM, SEND_SIG_PRIV, sig->leader_pid);

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

diff --git a/kernel/posix-cpu-timers.c b/kernel/posix-cpu-timers.c
index bece7c0..66d0e28 100644
--- a/kernel/posix-cpu-timers.c
+++ b/kernel/posix-cpu-timers.c
@@ -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, tsk, NULL, 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, tsk, NULL, utime);
__group_send_sig_info(SIGVTALRM, SEND_SIG_PRIV, tsk);
}
if (!cputime_eq(sig->it_virt_expires, cputime_zero) &&
--
1.6.1.2