Messages in this thread | | | Date | Fri, 10 Oct 2008 15:02:49 +0200 | From | "Frédéric Weisbecker" <> | Subject | Re: [PATCH 6/6] tracing/fastboot: Print ktime of sched events when boot tracing |
| |
2008/10/10 Frederic Weisbecker <fweisbec@gmail.com>: > > When we use the boot tracer, we want the sched events to be printed with the > same timestamp than initcall events. > So we have to create a new type of entry which contains sched event attributes > and the ktime of the creation of the entry. > Then the output is handled by the boot tracer. > > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com> > CC: Steven Rostedt <rostedt@goodmis.org> > CC: Arjan van de Ven <arjan@infradead.org> > --- > kernel/trace/trace.c | 107 ++++++++++++++++++++++++++++++++++++++++---- > kernel/trace/trace.h | 22 +++++++++ > kernel/trace/trace_boot.c | 96 ++++++++++++++++++++++++++++++++-------- > 3 files changed, 196 insertions(+), 29 deletions(-) > > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index acc21bb..4300521 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -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; > @@ -774,12 +774,12 @@ __trace_special(void *__tr, void *__data, > ftrace_trace_special(__tr, __data, arg1, arg2, arg3, preempt_count()); > } > > -void > -tracing_sched_switch_trace(struct trace_array *tr, > - struct trace_array_cpu *data, > - struct task_struct *prev, > - struct task_struct *next, > - unsigned long flags, int pc) > +static void > +__tracing_sched_switch_trace(struct trace_array *tr, > + struct trace_array_cpu *data, > + struct task_struct *prev, > + struct task_struct *next, > + unsigned long flags, int pc) > { > struct ring_buffer_event *event; > struct ctx_switch_entry *entry; > @@ -803,13 +803,85 @@ tracing_sched_switch_trace(struct trace_array *tr, > ftrace_trace_stack(tr, data, flags, 5, pc); > } > > +static void > +__tracing_sched_switch_boot_trace(struct trace_array *tr, > + struct trace_array_cpu *data, > + struct task_struct *prev, > + struct task_struct *next, > + unsigned long flags, int pc) > +{ > + struct ring_buffer_event *event; > + struct ctx_switch_boot_entry *entry; > + unsigned long irq_flags; > + > + event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry), > + &irq_flags); > + if (!event) > + return; > + entry = ring_buffer_event_data(event); > + tracing_generic_entry_update(&entry->ent, flags, pc); > + entry->ent.type = TRACE_CTX_BOOT; > + entry->prev_pid = prev->pid; > + entry->prev_prio = prev->prio; > + entry->prev_state = prev->state; > + entry->next_pid = next->pid; > + entry->next_prio = next->prio; > + entry->next_state = next->state; > + entry->next_cpu = task_cpu(next); > + entry->time = ktime_get(); > + ring_buffer_unlock_commit(tr->buffer, event, irq_flags); > +} > + > void > -tracing_sched_wakeup_trace(struct trace_array *tr, > +tracing_sched_switch_trace(struct trace_array *tr, > struct trace_array_cpu *data, > - struct task_struct *wakee, > - struct task_struct *curr, > + struct task_struct *prev, > + struct task_struct *next, > unsigned long flags, int pc) > { > + if (current_trace == &boot_tracer) > + __tracing_sched_switch_boot_trace(tr, data, prev, > + next, flags, pc); > + else > + __tracing_sched_switch_trace(tr, data, prev, next, flags, pc); > +} > + > +static void > +__tracing_sched_wakeup_boot_trace(struct trace_array *tr, > + struct trace_array_cpu *data, > + struct task_struct *wakee, > + struct task_struct *curr, > + unsigned long flags, int pc) > +{ > + struct ring_buffer_event *event; > + struct ctx_switch_boot_entry *entry; > + unsigned long irq_flags; > + > + event = ring_buffer_lock_reserve(tr->buffer, sizeof(*entry), > + &irq_flags); > + if (!event) > + return; > + entry = ring_buffer_event_data(event); > + tracing_generic_entry_update(&entry->ent, flags, pc); > + entry->ent.type = TRACE_WAKE_BOOT; > + entry->prev_pid = curr->pid; > + entry->prev_prio = curr->prio; > + entry->prev_state = curr->state; > + entry->next_pid = wakee->pid; > + entry->next_prio = wakee->prio; > + entry->next_state = wakee->state; > + entry->next_cpu = task_cpu(wakee); > + entry->time = ktime_get(); > + ring_buffer_unlock_commit(tr->buffer, event, irq_flags); > +} > + > +static void > +__tracing_sched_wakeup_trace(struct trace_array *tr, > + struct trace_array_cpu *data, > + struct task_struct *wakee, > + struct task_struct *curr, > + unsigned long flags, int pc) > +{ > struct ring_buffer_event *event; > struct ctx_switch_entry *entry; > unsigned long irq_flags; > @@ -835,6 +907,21 @@ tracing_sched_wakeup_trace(struct trace_array *tr, > } > > void > +tracing_sched_wakeup_trace(struct trace_array *tr, > + struct trace_array_cpu *data, > + struct task_struct *wakee, > + struct task_struct *curr, > + unsigned long flags, int pc) > +{ > + > + if (current_trace == &boot_tracer) > + __tracing_sched_wakeup_boot_trace(tr, data, wakee, > + curr, flags, pc); > + else > + __tracing_sched_wakeup_trace(tr, data, wakee, curr, flags, pc); > +} > + > +void > ftrace_special(unsigned long arg1, unsigned long arg2, unsigned long arg3) > { > struct trace_array *tr = &global_trace; > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h > index d45a3cd..b7fe667 100644 > --- a/kernel/trace/trace.h > +++ b/kernel/trace/trace.h > @@ -22,6 +22,8 @@ enum trace_type { > TRACE_MMIO_RW, > TRACE_MMIO_MAP, > TRACE_BOOT, > + TRACE_CTX_BOOT, > + TRACE_WAKE_BOOT, > > __TRACE_LAST_TYPE > }; > @@ -66,6 +68,24 @@ struct ctx_switch_entry { > }; > > /* > + * Context switch trace entry with ktime timestamp. > + * It is required for the boot tracer which needs unified > + * time measure between initcalls and sched events. > + */ > + > +struct ctx_switch_boot_entry { > + struct trace_entry ent; > + unsigned int prev_pid; > + unsigned char prev_prio; > + unsigned char prev_state; > + unsigned int next_pid; > + unsigned char next_prio; > + unsigned char next_state; > + unsigned int next_cpu; > + ktime_t time; > +}; > + > +/* > * Special (free-form) trace entry: > */ > struct special_entry { > @@ -218,6 +238,7 @@ extern void __ftrace_bad_type(void); > IF_ASSIGN(var, ent, struct trace_mmiotrace_map, \ > TRACE_MMIO_MAP); \ > IF_ASSIGN(var, ent, struct trace_boot, TRACE_BOOT); \ > + IF_ASSIGN(var, ent, struct ctx_switch_boot_entry, 0); \ > __ftrace_bad_type(); \ > } while (0) > > @@ -392,6 +413,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; > > diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c > index 6bbc879..11e6573 100644 > --- a/kernel/trace/trace_boot.c > +++ b/kernel/trace/trace_boot.c > @@ -14,6 +14,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,34 +72,91 @@ static enum print_line_t initcall_print_line(struct trace_iterator *iter) > struct timespec calltime = ktime_to_timespec(it->calltime); > struct timespec rettime = ktime_to_timespec(it->rettime); > > - if (entry->type == TRACE_BOOT) { > - ret = trace_seq_printf(s, "[%5ld.%09ld] calling %s @ %i\n", > - calltime.tv_sec, > - calltime.tv_nsec, > - it->func, it->caller); > - if (!ret) > - return TRACE_TYPE_PARTIAL_LINE; > - > - ret = trace_seq_printf(s, "[%5ld.%09ld] initcall %s " > - "returned %d after %lld msecs\n", > - rettime.tv_sec, > - rettime.tv_nsec, > - it->func, it->result, it->duration); > - > - if (!ret) > - return TRACE_TYPE_PARTIAL_LINE; > - return TRACE_TYPE_HANDLED; > - } > + ret = trace_seq_printf(s, "[%5ld.%09ld] calling %s @ %i\n", > + calltime.tv_sec, > + calltime.tv_nsec, > + it->func, it->caller); > + if (!ret) > + return TRACE_TYPE_PARTIAL_LINE; > + > + ret = trace_seq_printf(s, "[%5ld.%09ld] initcall %s " > + "returned %d after %lld msecs\n", > + rettime.tv_sec, > + rettime.tv_nsec, > + it->func, it->result, it->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_boot_entry *field; > + struct trace_seq *s = &iter->seq; > + struct timespec time; > + int S, T; > + char *comm; > + > + trace_assign_type(field, entry); > + time = ktime_to_timespec(field->time); > + > + comm = trace_find_cmdline(iter->ent->pid); > + > + ret = trace_seq_printf(s, "[%5ld.%09ld] ", > + time.tv_sec, > + time.tv_nsec); > + > + 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_BOOT || entry->type == TRACE_WAKE_BOOT) > + return sched_switch_print_line(iter); > return TRACE_TYPE_UNHANDLED; > } > > + > struct tracer boot_tracer __read_mostly = > { > .name = "initcall", > .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)
I forgot to say that a lot of this code is borrowed from trace.c (print_trace_fmt function) which is copyright...a lot of people :)
| |