2010-08-18 22:33:15

by Arjan van de Ven

[permalink] [raw]
Subject: [PATCH] tracing: Make timer tracing actually useful



From fe9633af11395d339880417439a1931bb9e7e493 Mon Sep 17 00:00:00 2001
From: Arjan van de Ven <[email protected]>
Date: Wed, 18 Aug 2010 15:28:59 -0400
Subject: [PATCH] tracing: Make timer tracing actually useful

PowerTOP would like to be able to trace timers.
Unfortunately, the current timer tracing is not very useful, the actual
timer function is not recorded in the trace at the start of timer execution.

Although this is recorded for timer "start" time (when it gets armed), this
is not useful; most timers get started early, and a tracer like PowerTOP
will never see this event, but will only see the actual running of the
timer.

This patch just adds the function to the timer tracing; I've verified with
PowerTOP that now it can get useful information about timers.

Signed-off-by: Arjan van de Ven <[email protected]>
---
include/trace/events/timer.h | 8 ++++++--
1 files changed, 6 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index c624126..94511c8 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -81,14 +81,16 @@ TRACE_EVENT(timer_expire_entry,
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 now=%lu", __entry->timer, __entry->now)
+ TP_printk("timer=%p function=%pf now=%lu", __entry->timer,
__entry->function,__entry->now)
);

/**
@@ -200,14 +202,16 @@ TRACE_EVENT(hrtimer_expire_entry,
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 now=%llu", __entry->hrtimer,
+ TP_printk("hrtimer=%p function=%pf now=%llu", __entry->hrtimer,
__entry->function,
(unsigned long long)ktime_to_ns((ktime_t) { .tv64 =
__entry->now }))
);

--
1.6.1.3


Attachments:
0001-tracing-Make-timer-tracing-actually-useful.patch (2.05 kB)

2010-08-19 11:25:49

by Arjan van de Ven

[permalink] [raw]
Subject: [tip:perf/urgent] tracing: Fix timer tracing

Commit-ID: ede1b4290781ae82ccf0f2ecc6dada8d3dd35779
Gitweb: http://git.kernel.org/tip/ede1b4290781ae82ccf0f2ecc6dada8d3dd35779
Author: Arjan van de Ven <[email protected]>
AuthorDate: Wed, 18 Aug 2010 15:33:13 -0700
Committer: Ingo Molnar <[email protected]>
CommitDate: Thu, 19 Aug 2010 13:00:41 +0200

tracing: Fix timer tracing

PowerTOP would like to be able to trace timers.

Unfortunately, the current timer tracing is not very useful: the
actual timer function is not recorded in the trace at the start
of timer execution.

Although this is recorded for timer "start" time (when it gets
armed), this is not useful; most timers get started early, and a
tracer like PowerTOP will never see this event, but will only
see the actual running of the timer.

This patch just adds the function to the timer tracing; I've
verified with PowerTOP that now it can get useful information
about timers.

Signed-off-by: Arjan van de Ven <[email protected]>
Cc: [email protected]
Cc: Steven Rostedt <[email protected]>
Cc: Frederic Weisbecker <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: <[email protected]> # .35.x, .34.x, .33.x
LKML-Reference: <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
---
include/trace/events/timer.h | 8 ++++++--
1 files changed, 6 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index c624126..425bcfe 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -81,14 +81,16 @@ TRACE_EVENT(timer_expire_entry,
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 now=%lu", __entry->timer, __entry->now)
+ TP_printk("timer=%p function=%pf now=%lu", __entry->timer, __entry->function,__entry->now)
);

/**
@@ -200,14 +202,16 @@ TRACE_EVENT(hrtimer_expire_entry,
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 now=%llu", __entry->hrtimer,
+ TP_printk("hrtimer=%p function=%pf now=%llu", __entry->hrtimer, __entry->function,
(unsigned long long)ktime_to_ns((ktime_t) { .tv64 = __entry->now }))
);