tracing: Make timer tracing actually useful

PATCH In review Arjan van de Ven 1 participant 2 messages Aug 18, 2010 – Aug 19, 2010

Subsystems (2)

Tracing Posix clocks and timers

lore

Share & tools

lore

Arjan van de Ven

author

2010-08-18 22:33 UTC #0 lore raw

PATCH 1/1 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(-)

include/trace/events/timer.h +6 -2

index c624126..94511c8 100644
@@ -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 }))
);

Signature · 1 line

1.6.1.3

Quoted 1 line

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.

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(-)

include/trace/events/timer.h +6 -2

index c624126..94511c8 100644
@@ -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 }))
  );

Signature · 1 line

1.6.1.3

tip-bot for Arjan van de Ven

author

2010-08-19 11:25 UTC #1 lore raw

[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.

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(-)

include/trace/events/timer.h +6 -2

index c624126..425bcfe 100644
@@ -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 }))
  );