Re: [PATCH 4/5] tracing/fastboot: Add a time field on the sched_switch entry

From: Frédéric Weisbecker
Date: Sat Oct 11 2008 - 16:58:59 EST

Next message: Ingo Molnar: "Re: Looks broken to me: x86, cyrix: debug"
Previous message: Alexander Beregalov: "[PATCH] kernel/resource: fix printk format warning"
In reply to: Steven Rostedt: "Re: [PATCH 4/5] tracing/fastboot: Add a time field on the sched_switchentry"
Next in thread: Steven Rostedt: "Re: [PATCH 4/5] tracing/fastboot: Add a time field on the sched_switchentry"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

2008/10/11 Steven Rostedt <rostedt@xxxxxxxxxxx>:
>
> On Sat, 11 Oct 2008, Frederic Weisbecker wrote:
>
>> 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 <fweisbec@xxxxxxxxx>
>> Cc: Arjan van de Ven <arjan@xxxxxxxxxxxxxxx>
>> Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
>> ---
>> kernel/trace/trace.c | 4 +-
>> kernel/trace/trace.h | 2 +
>> kernel/trace/trace_boot.c | 101 +++++++++++++++++++++++++++++++++++---------
>> 3 files changed, 85 insertions(+), 22 deletions(-)
>>
>> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>> index acc21bb..e7d659a 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;
>> @@ -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.
>
>> }
>> @@ -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);
>>
>> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
>> index d45a3cd..707620c 100644
>> --- a/kernel/trace/trace.h
>> +++ b/kernel/trace/trace.h
>> @@ -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;
>>
>> diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
>> index 20d326b..316085e 100644
>> --- a/kernel/trace/trace_boot.c
>> +++ b/kernel/trace/trace_boot.c
>> @@ -3,6 +3,8 @@
>> *
>> * Copyright (C) 2008 Frederic Weisbecker <fweisbec@xxxxxxxxx>
>> *
>> + * 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
>
>> 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)
>>
>>
>

Yes but this one doesn't seem to start at zero at the boot time.
There is a big difference between those two ...
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Ingo Molnar: "Re: Looks broken to me: x86, cyrix: debug"
Previous message: Alexander Beregalov: "[PATCH] kernel/resource: fix printk format warning"
In reply to: Steven Rostedt: "Re: [PATCH 4/5] tracing/fastboot: Add a time field on the sched_switchentry"
Next in thread: Steven Rostedt: "Re: [PATCH 4/5] tracing/fastboot: Add a time field on the sched_switchentry"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]