Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757135AbZGFJmS (ORCPT ); Mon, 6 Jul 2009 05:42:18 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1753026AbZGFJmJ (ORCPT ); Mon, 6 Jul 2009 05:42:09 -0400 Received: from cn.fujitsu.com ([222.73.24.84]:64740 "EHLO song.cn.fujitsu.com" rhost-flags-OK-FAIL-OK-OK) by vger.kernel.org with ESMTP id S1751028AbZGFJmI (ORCPT ); Mon, 6 Jul 2009 05:42:08 -0400 Message-ID: <4A51C6F9.3080100@cn.fujitsu.com> Date: Mon, 06 Jul 2009 17:42:17 +0800 From: Xiao Guangrong User-Agent: Thunderbird 2.0.0.6 (Windows/20070728) MIME-Version: 1.0 To: Ingo Molnar CC: Thomas Gleixner , Steven Rostedt , Frederic Weisbecker , Mathieu Desnoyers , Zhaolei , kosaki.motohiro@jp.fujitsu.com, LKML Subject: [PATCH v2 3/3] ftrace: add tracepoint for itimer References: <4A51C5C2.20802@cn.fujitsu.com> In-Reply-To: <4A51C5C2.20802@cn.fujitsu.com> Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 6620 Lines: 193 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 --- 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 #include #include +#include #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 ? + ¤t->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 #include #include +#include #include @@ -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 #include #include +#include /* * 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 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/