Re: [RFC PATCH 20/22 -v2] Add latency_trace format tor tracer

2008-01-09 Thread Daniel Walker 

On Wed, 2008-01-09 at 18:29 -0500, Steven Rostedt wrote:
> +enum trace_flag_type {
> +   TRACE_FLAG_IRQS_OFF = 0x01,
> +   TRACE_FLAG_NEED_RESCHED = 0x02,
> +   TRACE_FLAG_NEED_RESCHED_DELAYED = 0x04,
> +   TRACE_FLAG_HARDIRQ  = 0x08,
> +   TRACE_FLAG_SOFTIRQ  = 0x10,
> +   TRACE_FLAG_IRQS_HARD_OFF= 0x20,
> +};

You've got some errant flags here .. TRACE_FLAG_NEED_RESCHED_DELAYED is
-rt only , and TRACE_FLAG_IRQS_HARD_OFF is unsed (and sort of a
relic) ..

Daniel

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [EMAIL PROTECTED]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[RFC PATCH 20/22 -v2] Add latency_trace format tor tracer

2008-01-09 Thread Steven Rostedt 
This patch adds a latency_trace file with the format used
by RT in which others have created tools to disect. This
file adds some useful recording for tracing, but still
does not add actual latency tracing.

Format like:

preemption latency trace v1.1.5 on 2.6.24-rc7-tst

 latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
-
| task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
-

 _--=> CPU#
/ _-=> irqs-off
   | / _=> need-resched
   || / _---=> hardirq/softirq 
   ||| / _--=> preempt-depth   
    /  
   | delay 
   cmd pid | time  |   caller  
  \   /|   \   |   /   
 swapper-0 0d.h. 1595128us+: set_normalized_timespec+0x8/0x2d  
(ktime_get_ts+0x4a/0x4e )
 swapper-0 0d.h. 1595131us+: _spin_lock+0x8/0x18  
(hrtimer_interrupt+0x6e/0x1b0 )

Or with verbose turned on:

preemption latency trace v1.1.5 on 2.6.24-rc7-tst

 latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
-
| task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
-

 swapper 0 0 9   [f3675f41] 1595.128ms (+0.003ms): 
set_normalized_timespec+0x8/0x2d  (ktime_get_ts+0x4a/0x4e )
 swapper 0 0 9  0001 [f3675f45] 1595.131ms (+0.003ms): 
_spin_lock+0x8/0x18  (hrtimer_interrupt+0x6e/0x1b0 )
 swapper 0 0 9  0002 [f3675f48] 1595.135ms (+0.003ms): 
_spin_lock+0x8/0x18  (hrtimer_interrupt+0x6e/0x1b0 )


Signed-off-by: Steven Rostedt <[EMAIL PROTECTED]>
---
 lib/tracing/tracer.c |  454 +--
 lib/tracing/tracer.h |   13 +
 2 files changed, 414 insertions(+), 53 deletions(-)

Index: linux-compile-i386.git/lib/tracing/tracer.c
===
--- linux-compile-i386.git.orig/lib/tracing/tracer.c2008-01-09 
14:38:55.0 -0500
+++ linux-compile-i386.git/lib/tracing/tracer.c 2008-01-09 15:17:22.0 
-0500
@@ -20,7 +20,9 @@
 #include 
 #include 
 #include 
+#include 
 #include 
+#include 
 #include 
 
 #include "tracer.h"
@@ -34,16 +36,27 @@ static inline notrace cycle_t now(void)
 static struct mctracer_trace mctracer_trace;
 static DEFINE_PER_CPU(struct mctracer_trace_cpu, mctracer_trace_cpu);
 
+enum trace_flag_type {
+   TRACE_FLAG_IRQS_OFF = 0x01,
+   TRACE_FLAG_NEED_RESCHED = 0x02,
+   TRACE_FLAG_NEED_RESCHED_DELAYED = 0x04,
+   TRACE_FLAG_HARDIRQ  = 0x08,
+   TRACE_FLAG_SOFTIRQ  = 0x10,
+   TRACE_FLAG_IRQS_HARD_OFF= 0x20,
+};
+
 static inline notrace void
 mctracer_add_trace_entry(struct mctracer_trace *tr,
 int cpu,
 const unsigned long ip,
-const unsigned long parent_ip)
+const unsigned long parent_ip,
+unsigned long flags)
 {
unsigned long idx, idx_next;
struct mctracer_entry *entry;
struct task_struct *tsk = current;
struct mctracer_trace_cpu *data = tr->data[cpu];
+   unsigned long pc;
 
idx = data->trace_idx;
idx_next = idx + 1;
@@ -58,11 +71,18 @@ mctracer_add_trace_entry(struct mctracer
if (unlikely(idx_next != 0 && atomic_read(>underrun)))
atomic_inc(>underrun);
 
+   pc = preempt_count();
+
entry = data->trace + idx * MCTRACER_ENTRY_SIZE;
+   entry->preempt_count = pc & 0xff;
entry->ip= ip;
entry->parent_ip = parent_ip;
entry->pid   = tsk->pid;
entry->t = now();
+   entry->flags = (irqs_disabled_flags(flags) ? TRACE_FLAG_IRQS_OFF : 0) |
+   ((pc & HARDIRQ_MASK) ? TRACE_FLAG_HARDIRQ : 0) |
+   ((pc & SOFTIRQ_MASK) ? TRACE_FLAG_SOFTIRQ : 0) |
+   (need_resched() ? TRACE_FLAG_NEED_RESCHED : 0);
memcpy(entry->comm, tsk->comm, TASK_COMM_LEN);
 }
 
@@ -80,7 +100,7 @@ static notrace void trace_function(const
 
atomic_inc(>data[cpu]->disabled);
if (likely(atomic_read(>data[cpu]->disabled) == 1))
-   mctracer_add_trace_entry(tr, cpu, ip, parent_ip);
+   mctracer_add_trace_entry(tr, cpu, ip, parent_ip, flags);
 
atomic_dec(>data[cpu]->disabled);
 
@@ -91,6 +111,11 @@ static notrace void mctracer_reset(struc
 {
int cpu;
 
+   tr->time_start = now();
+   tr->saved_latency = 0;
+   tr->critical_start = 0;
+   tr->critical_end = 0;
+
for_each_online_cpu(cpu) {
tr->data[cpu]->trace_idx = 0;

[RFC PATCH 20/22 -v2] Add latency_trace format tor tracer

2008-01-09 Thread Steven Rostedt 
This patch adds a latency_trace file with the format used
by RT in which others have created tools to disect. This
file adds some useful recording for tracing, but still
does not add actual latency tracing.

Format like:

preemption latency trace v1.1.5 on 2.6.24-rc7-tst

 latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
-
| task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
-

 _--= CPU#
/ _-= irqs-off
   | / _= need-resched
   || / _---= hardirq/softirq 
   ||| / _--= preempt-depth   
    /  
   | delay 
   cmd pid | time  |   caller  
  \   /|   \   |   /   
 swapper-0 0d.h. 1595128us+: set_normalized_timespec+0x8/0x2d c043841d 
(ktime_get_ts+0x4a/0x4e c04499d4)
 swapper-0 0d.h. 1595131us+: _spin_lock+0x8/0x18 c0630690 
(hrtimer_interrupt+0x6e/0x1b0 c0449c56)

Or with verbose turned on:

preemption latency trace v1.1.5 on 2.6.24-rc7-tst

 latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
-
| task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
-

 swapper 0 0 9   [f3675f41] 1595.128ms (+0.003ms): 
set_normalized_timespec+0x8/0x2d c043841d (ktime_get_ts+0x4a/0x4e c04499d4)
 swapper 0 0 9  0001 [f3675f45] 1595.131ms (+0.003ms): 
_spin_lock+0x8/0x18 c0630690 (hrtimer_interrupt+0x6e/0x1b0 c0449c56)
 swapper 0 0 9  0002 [f3675f48] 1595.135ms (+0.003ms): 
_spin_lock+0x8/0x18 c0630690 (hrtimer_interrupt+0x6e/0x1b0 c0449c56)


Signed-off-by: Steven Rostedt [EMAIL PROTECTED]
---
 lib/tracing/tracer.c |  454 +--
 lib/tracing/tracer.h |   13 +
 2 files changed, 414 insertions(+), 53 deletions(-)

Index: linux-compile-i386.git/lib/tracing/tracer.c
===
--- linux-compile-i386.git.orig/lib/tracing/tracer.c2008-01-09 
14:38:55.0 -0500
+++ linux-compile-i386.git/lib/tracing/tracer.c 2008-01-09 15:17:22.0 
-0500
@@ -20,7 +20,9 @@
 #include linux/debugfs.h
 #include linux/kallsyms.h
 #include linux/clocksource.h
+#include linux/utsrelease.h
 #include linux/uaccess.h
+#include linux/hardirq.h
 #include linux/mcount.h
 
 #include tracer.h
@@ -34,16 +36,27 @@ static inline notrace cycle_t now(void)
 static struct mctracer_trace mctracer_trace;
 static DEFINE_PER_CPU(struct mctracer_trace_cpu, mctracer_trace_cpu);
 
+enum trace_flag_type {
+   TRACE_FLAG_IRQS_OFF = 0x01,
+   TRACE_FLAG_NEED_RESCHED = 0x02,
+   TRACE_FLAG_NEED_RESCHED_DELAYED = 0x04,
+   TRACE_FLAG_HARDIRQ  = 0x08,
+   TRACE_FLAG_SOFTIRQ  = 0x10,
+   TRACE_FLAG_IRQS_HARD_OFF= 0x20,
+};
+
 static inline notrace void
 mctracer_add_trace_entry(struct mctracer_trace *tr,
 int cpu,
 const unsigned long ip,
-const unsigned long parent_ip)
+const unsigned long parent_ip,
+unsigned long flags)
 {
unsigned long idx, idx_next;
struct mctracer_entry *entry;
struct task_struct *tsk = current;
struct mctracer_trace_cpu *data = tr-data[cpu];
+   unsigned long pc;
 
idx = data-trace_idx;
idx_next = idx + 1;
@@ -58,11 +71,18 @@ mctracer_add_trace_entry(struct mctracer
if (unlikely(idx_next != 0  atomic_read(data-underrun)))
atomic_inc(data-underrun);
 
+   pc = preempt_count();
+
entry = data-trace + idx * MCTRACER_ENTRY_SIZE;
+   entry-preempt_count = pc  0xff;
entry-ip= ip;
entry-parent_ip = parent_ip;
entry-pid   = tsk-pid;
entry-t = now();
+   entry-flags = (irqs_disabled_flags(flags) ? TRACE_FLAG_IRQS_OFF : 0) |
+   ((pc  HARDIRQ_MASK) ? TRACE_FLAG_HARDIRQ : 0) |
+   ((pc  SOFTIRQ_MASK) ? TRACE_FLAG_SOFTIRQ : 0) |
+   (need_resched() ? TRACE_FLAG_NEED_RESCHED : 0);
memcpy(entry-comm, tsk-comm, TASK_COMM_LEN);
 }
 
@@ -80,7 +100,7 @@ static notrace void trace_function(const
 
atomic_inc(tr-data[cpu]-disabled);
if (likely(atomic_read(tr-data[cpu]-disabled) == 1))
-   mctracer_add_trace_entry(tr, cpu, ip, parent_ip);
+   mctracer_add_trace_entry(tr, cpu, ip, parent_ip, flags);
 
atomic_dec(tr-data[cpu]-disabled);
 
@@ -91,6 +111,11 @@ static notrace void mctracer_reset(struc
 {
int cpu;
 
+   tr-time_start = now();
+   tr-saved_latency = 0;
+

Re: [RFC PATCH 20/22 -v2] Add latency_trace format tor tracer

2008-01-09 Thread Daniel Walker 

On Wed, 2008-01-09 at 18:29 -0500, Steven Rostedt wrote:
 +enum trace_flag_type {
 +   TRACE_FLAG_IRQS_OFF = 0x01,
 +   TRACE_FLAG_NEED_RESCHED = 0x02,
 +   TRACE_FLAG_NEED_RESCHED_DELAYED = 0x04,
 +   TRACE_FLAG_HARDIRQ  = 0x08,
 +   TRACE_FLAG_SOFTIRQ  = 0x10,
 +   TRACE_FLAG_IRQS_HARD_OFF= 0x20,
 +};

You've got some errant flags here .. TRACE_FLAG_NEED_RESCHED_DELAYED is
-rt only , and TRACE_FLAG_IRQS_HARD_OFF is unsed (and sort of a
relic) ..

Daniel

--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to [EMAIL PROTECTED]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/