tracing/fastboot: Add a time field on the sched_switch entry

Add a time field on the sched_switch entry to have a better view of the sched events during initcalls.
Also make the boot tracer able to handle the sched_switches events.

Signed-off-by Frederic Weisbecker <[email protected]>

Cc Arjan van de Ven <[email protected]>

Cc Steven Rostedt <[email protected]>

---
 kernel/trace/trace.c      |    4 +-
 kernel/trace/trace.h      |    2 +
 kernel/trace/trace_boot.c |  101 +++++++++++++++++++++++++++++++++++---------
 3 files changed, 85 insertions(+), 22 deletions(-)

kernel/trace/trace.c +1 -1

index acc21bb..e7d659a 100644
@@ -622,7 +622,7 @@ static void trace_save_cmdline(struct task_struct *tsk)
 	spin_unlock(&trace_cmdline_lock);
 }
 
-static char *trace_find_cmdline(int pid)
+char *trace_find_cmdline(int pid)
 {
 	char *cmdline = "<...>";
 	unsigned map;

kernel/trace/trace_boot.c +77 -21

 	unsigned long sec, nsec_rem;
 	unsigned long long duration = it->rettime - it->calltime;
 
-	if (entry->type == TRACE_BOOT) {
-		nsec_rem = do_div(it->calltime, 1000000000);
-		sec = (unsigned long) it->calltime;
-		ret = trace_seq_printf(s, "[%5lu.%09lu] calling  %s @ %i\n",
-					  sec, nsec_rem, it->func, it->caller);
-		if (!ret)
-			return TRACE_TYPE_PARTIAL_LINE;
-
-		nsec_rem = do_div(it->rettime, 1000000000);
-		sec = (unsigned long) it->rettime;
-		do_div(duration, 1000);
-		ret = trace_seq_printf(s, "[%5lu.%09lu] initcall %s "
-					  "returned %d after %lld msecs\n",
-					  sec, nsec_rem, it->func, it->result,
-					  duration);
-
-		if (!ret)
-			return TRACE_TYPE_PARTIAL_LINE;
-		return TRACE_TYPE_HANDLED;
-	}
+	nsec_rem = do_div(it->calltime, 1000000000);
+	sec = (unsigned long) it->calltime;
+	ret = trace_seq_printf(s, "[%5lu.%09lu] calling  %s @ %i\n",
+				  sec, nsec_rem, it->func, it->caller);
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+
+	nsec_rem = do_div(it->rettime, 1000000000);
+	sec = (unsigned long) it->rettime;
+	do_div(duration, 1000);
+	ret = trace_seq_printf(s, "[%5lu.%09lu] initcall %s "
+				  "returned %d after %llu msecs\n",
+				  sec, nsec_rem, it->func, it->result,
+				  duration);
+
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+
+	return TRACE_TYPE_HANDLED;
+}
+
+static enum print_line_t sched_switch_print_line(struct trace_iterator *iter)
+{
+	int ret;
+	struct trace_entry *entry = iter->ent;
+	struct ctx_switch_entry *field;
+	struct trace_seq *s = &iter->seq;
+	int S, T;
+	char *comm;
+	unsigned long sec, nsec_rem;
+
+	trace_assign_type(field, entry);
+	nsec_rem = do_div(field->time, 1000000000);
+	sec = (unsigned long) field->time;
+
+	comm = trace_find_cmdline(iter->ent->pid);
+
+	ret = trace_seq_printf(s, "[%5lu.%09lu] ",
+				  sec, nsec_rem);
+
+	ret = trace_seq_printf(s, "%16s-%-5d ", comm, entry->pid);
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+	ret = trace_seq_printf(s, "[%03d] ", iter->cpu);
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+
+	S = field->prev_state < sizeof(state_to_char) ?
+		state_to_char[field->prev_state] : 'X';
+	T = field->next_state < sizeof(state_to_char) ?
+		state_to_char[field->next_state] : 'X';
+	ret = trace_seq_printf(s, " %5d:%3d:%c %s [%03d] %5d:%3d:%c\n",
+			       field->prev_pid,
+			       field->prev_prio,
+			       S,
+			       entry->type == TRACE_CTX ? "==>" : "  +",
+			       field->next_cpu,
+			       field->next_pid,
+			       field->next_prio,
+			       T);
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
+	return TRACE_TYPE_HANDLED;
+}
+
+static enum print_line_t boot_trace_print_line(struct trace_iterator *iter)
+{
+	struct trace_entry *entry = iter->ent;
+
+	if (entry->type == TRACE_BOOT)
+		return initcall_print_line(iter);
+	if (entry->type == TRACE_CTX || entry->type == TRACE_WAKE)
+		return sched_switch_print_line(iter);
 	return TRACE_TYPE_UNHANDLED;
 }
 

@@ -100,7 +159,7 @@ struct tracer boot_tracer __read_mostly =
 	.init		= boot_trace_init,
 	.reset		= reset_boot_trace,
 	.ctrl_update	= boot_trace_ctrl_update,
-	.print_line	= initcall_print_line,
+	.print_line	= boot_trace_print_line,
 };
 
 void trace_boot(struct boot_trace *it, initcall_t fn)

Quoted 29 lines

Add a time field on the sched_switch entry to have a better view of the sched events during initcalls.
Also make the boot tracer able to handle the sched_switches events.

Signed-off-by Frederic Weisbecker <[email protected]>

Cc Arjan van de Ven <[email protected]>

Cc Steven Rostedt <[email protected]>

---
 kernel/trace/trace.c      |    4 +-
 kernel/trace/trace.h      |    2 +
 kernel/trace/trace_boot.c |  101 +++++++++++++++++++++++++++++++++++---------
 3 files changed, 85 insertions(+), 22 deletions(-)

kernel/trace/trace.c +1 -1

index acc21bb..e7d659a 100644
@@ -622,7 +622,7 @@ static void trace_save_cmdline(struct task_struct *tsk)
      spin_unlock(&trace_cmdline_lock);
 }
 
-static char *trace_find_cmdline(int pid)
+char *trace_find_cmdline(int pid)
 {
      char *cmdline = "<...>";
      unsigned map;

kernel/trace/trace.c tracing_sched_switch_trace(struct trace_array *tr, · line 804

Quoted 6 lines

kernel/trace/trace.c +1 -0

@@ -799,6 +799,7 @@ tracing_sched_switch_trace(struct trace_array *tr,
      entry->next_prio                = next->prio;
      entry->next_state               = next->state;
      entry->next_cpu = task_cpu(next);
+     entry->time                     = cpu_clock(raw_smp_processor_id());
      ring_buffer_unlock_commit(tr->buffer, event, irq_flags);
      ftrace_trace_stack(tr, data, flags, 5, pc);

NACK. We already have a time field in the trace buffer.

kernel/trace/trace_boot.c static enum print_line_t initcall_print_line(struct trace_iterator *iter)

Quoted 51 lines

kernel/trace/trace.c +1 -0

 }

@@ -828,6 +829,7 @@ tracing_sched_wakeup_trace(struct trace_array *tr,
      entry->next_prio                = wakee->prio;
      entry->next_state               = wakee->state;
      entry->next_cpu                 = task_cpu(wakee);
+     entry->time                     = cpu_clock(raw_smp_processor_id());
      ring_buffer_unlock_commit(tr->buffer, event, irq_flags);
      ftrace_trace_stack(tr, data, flags, 6, pc);
 

kernel/trace/trace.h +2 -0

index d45a3cd..707620c 100644
@@ -63,6 +63,7 @@ struct ctx_switch_entry {
      unsigned char           next_prio;
      unsigned char           next_state;
      unsigned int            next_cpu;
+     unsigned long long      time;
 };
 
 /*

@@ -392,6 +393,7 @@ extern ssize_t trace_seq_to_user(struct trace_seq *s, char __user *ubuf,
                               size_t cnt);
 extern long ns2usecs(cycle_t nsec);
 extern int trace_vprintk(unsigned long ip, const char *fmt, va_list args);
+extern char *trace_find_cmdline(int pid);
 
 extern unsigned long trace_flags;
 

kernel/trace/trace_boot.c +3 -0

index 20d326b..316085e 100644
@@ -3,6 +3,8 @@
  *
  * Copyright (C) 2008 Frederic Weisbecker <[email protected]>
  *
+ * Some parts of code (IE: sched_switch_print_line function)
+ * have been borrowed from trace.c
  */
 
 #include <linux/init.h>

@@ -14,6 +16,7 @@
 
 static struct trace_array *boot_trace;
 static bool pre_initcalls_finished;
+static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
 
 /* Tells the boot tracer that the pre_smp_initcalls are finished.
  * So we are ready .

@@ -71,26 +74,82 @@ static enum print_line_t initcall_print_line(struct trace_iterator *iter)

iter->ts has the time value already for you.

-- Steve

Quoted 110 lines

kernel/trace/trace_boot.c +77 -21

      unsigned long sec, nsec_rem;
      unsigned long long duration = it->rettime - it->calltime;
 
-     if (entry->type == TRACE_BOOT) {
-             nsec_rem = do_div(it->calltime, 1000000000);
-             sec = (unsigned long) it->calltime;
-             ret = trace_seq_printf(s, "[%5lu.%09lu] calling  %s @ %i\n",
-                                       sec, nsec_rem, it->func, it->caller);
-             if (!ret)
-                     return TRACE_TYPE_PARTIAL_LINE;
-
-             nsec_rem = do_div(it->rettime, 1000000000);
-             sec = (unsigned long) it->rettime;
-             do_div(duration, 1000);
-             ret = trace_seq_printf(s, "[%5lu.%09lu] initcall %s "
-                                       "returned %d after %lld msecs\n",
-                                       sec, nsec_rem, it->func, it->result,
-                                       duration);
-
-             if (!ret)
-                     return TRACE_TYPE_PARTIAL_LINE;
-             return TRACE_TYPE_HANDLED;
-     }
+     nsec_rem = do_div(it->calltime, 1000000000);
+     sec = (unsigned long) it->calltime;
+     ret = trace_seq_printf(s, "[%5lu.%09lu] calling  %s @ %i\n",
+                               sec, nsec_rem, it->func, it->caller);
+     if (!ret)
+             return TRACE_TYPE_PARTIAL_LINE;
+
+     nsec_rem = do_div(it->rettime, 1000000000);
+     sec = (unsigned long) it->rettime;
+     do_div(duration, 1000);
+     ret = trace_seq_printf(s, "[%5lu.%09lu] initcall %s "
+                               "returned %d after %llu msecs\n",
+                               sec, nsec_rem, it->func, it->result,
+                               duration);
+
+     if (!ret)
+             return TRACE_TYPE_PARTIAL_LINE;
+
+     return TRACE_TYPE_HANDLED;
+}
+
+static enum print_line_t sched_switch_print_line(struct trace_iterator *iter)
+{
+     int ret;
+     struct trace_entry *entry = iter->ent;
+     struct ctx_switch_entry *field;
+     struct trace_seq *s = &iter->seq;
+     int S, T;
+     char *comm;
+     unsigned long sec, nsec_rem;
+
+     trace_assign_type(field, entry);
+     nsec_rem = do_div(field->time, 1000000000);
+     sec = (unsigned long) field->time;
+
+     comm = trace_find_cmdline(iter->ent->pid);
+
+     ret = trace_seq_printf(s, "[%5lu.%09lu] ",
+                               sec, nsec_rem);
+
+     ret = trace_seq_printf(s, "%16s-%-5d ", comm, entry->pid);
+     if (!ret)
+             return TRACE_TYPE_PARTIAL_LINE;
+     ret = trace_seq_printf(s, "[%03d] ", iter->cpu);
+     if (!ret)
+             return TRACE_TYPE_PARTIAL_LINE;
+
+     if (!ret)
+             return TRACE_TYPE_PARTIAL_LINE;
+
+     S = field->prev_state < sizeof(state_to_char) ?
+             state_to_char[field->prev_state] : 'X';
+     T = field->next_state < sizeof(state_to_char) ?
+             state_to_char[field->next_state] : 'X';
+     ret = trace_seq_printf(s, " %5d:%3d:%c %s [%03d] %5d:%3d:%c\n",
+                            field->prev_pid,
+                            field->prev_prio,
+                            S,
+                            entry->type == TRACE_CTX ? "==>" : "  +",
+                            field->next_cpu,
+                            field->next_pid,
+                            field->next_prio,
+                            T);
+     if (!ret)
+             return TRACE_TYPE_PARTIAL_LINE;
+     return TRACE_TYPE_HANDLED;
+}
+
+static enum print_line_t boot_trace_print_line(struct trace_iterator *iter)
+{
+     struct trace_entry *entry = iter->ent;
+
+     if (entry->type == TRACE_BOOT)
+             return initcall_print_line(iter);
+     if (entry->type == TRACE_CTX || entry->type == TRACE_WAKE)
+             return sched_switch_print_line(iter);
      return TRACE_TYPE_UNHANDLED;
 }
 

@@ -100,7 +159,7 @@ struct tracer boot_tracer __read_mostly =
      .init           = boot_trace_init,
      .reset          = reset_boot_trace,
      .ctrl_update    = boot_trace_ctrl_update,
-     .print_line     = initcall_print_line,
+     .print_line     = boot_trace_print_line,
 };
 

kernel/trace/trace_boot.c struct tracer boot_tracer __read_mostly = · line 165

Quoted 3 lines

kernel/trace/trace_boot.c +0 -0

 void trace_boot(struct boot_trace *it, initcall_t fn)

2008/10/11 Steven Rostedt <[email protected]>:

Quoted 20 lines

Quoted 20 lines

kernel/trace/trace_boot.c +10 -1

+
+static enum print_line_t boot_trace_print_line(struct trace_iterator *iter)
+{
+     struct trace_entry *entry = iter->ent;
+
+     if (entry->type == TRACE_BOOT)
+             return initcall_print_line(iter);
+     if (entry->type == TRACE_CTX || entry->type == TRACE_WAKE)
+             return sched_switch_print_line(iter);
      return TRACE_TYPE_UNHANDLED;
 }

@@ -100,7 +159,7 @@ struct tracer boot_tracer __read_mostly =
      .init           = boot_trace_init,
      .reset          = reset_boot_trace,
      .ctrl_update    = boot_trace_ctrl_update,
-     .print_line     = initcall_print_line,
+     .print_line     = boot_trace_print_line,
 };
 

Quoted 4 lines

kernel/trace/trace_boot.c struct tracer boot_tracer __read_mostly = · line 165

Quoted 3 lines

kernel/trace/trace_boot.c +0 -0

 void trace_boot(struct boot_trace *it, initcall_t fn)

Yes but this one doesn't seem to start at zero at the boot time. There is a big difference between those two ...

You can tap into the context switch trace_point too, and have that record a special trace entry for you instead.

2008/10/12 Steven Rostedt <[email protected]>:

Quoted 2 lines

You can tap into the context switch trace_point too, and have that record a special trace entry for you instead.

2008/10/12 Fr�d�ric Weisbecker <[email protected]>:

Quoted 3 lines

2008/10/12 Steven Rostedt <[email protected]>:

Quoted 2 lines

You can tap into the context switch trace_point too, and have that record a special trace entry for you instead.

Another thing I could do: when a sched switch entry occurs, I could send a special timestamp entry that
fits my needs just before the commit of the sched entry, only if the current tracer is the boot tracer. This way I can output the appropriate timestamp just before output the sched entry.

What do you think?

I may have lost context here, but what's the purpose of the extra timestamp again? If it's just to have zero-based timestamps on the ultimate output, can't you just put a single special "start" timestamp in the trace log. Then that can be subtraced from all tracer-generated stamps in post-processing. I'm not familiar enough with the tracer to know if the post-processing is done in kernel space. But in any event you could use something like scripts/show_delta to get relative timestamps (in user space). Right now, scripts/show_delta doesn't act like a filter - I'll have to look at that.