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(-)
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);
}
@@ -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 <[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)
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)
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 <[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(-)
>
> 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 <[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
> 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)
>
>
2008/10/11 Steven Rostedt <[email protected]>:
>
> 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 <[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(-)
>>
>> 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 <[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
>
>> 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 ...
On Sat, 11 Oct 2008, Fr?d?ric Weisbecker wrote:
> 2008/10/11 Steven Rostedt <[email protected]>:
> >> +
> >> +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 ...
Even so, I disagree having the context switch tracer hold another 8 byte
timestamp. If you want to add something to the boot tracer, than fine.
But not to something that other tracers use.
You can tap into the context switch trace_point too, and have that record
a special trace entry for you instead.
-- Steve
2008/10/12 Steven Rostedt <[email protected]>:
> You can tap into the context switch trace_point too, and have that record
> a special trace entry for you instead.
That's what I did first.
See ctx_switch_boot_entry on this patch: http://lkml.org/lkml/2008/10/10/194
But Ingo suggested that it would be better to add a the time field on
the usual ctx entry.
I don't know....
2008/10/12 Fr?d?ric Weisbecker <[email protected]>:
> 2008/10/12 Steven Rostedt <[email protected]>:
>> 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?
� wrote:
> 2008/10/12 Fr�d�ric Weisbecker <[email protected]>:
>> 2008/10/12 Steven Rostedt <[email protected]>:
>>> 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.
Sorry if I'm just adding noise...
-- Tim
=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================
2008/10/18 Tim Bird <[email protected]>:
> 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.
Actually the problem is not really to have a zero-based timestamp but I need
to have a timestamp which is the same than the one used by the boot tracer.
If the boot tracer had only to capture one time per entry, I would use
the internal
timestamp of the ring-buffer. But the boot tracer must capture two
times: the call
time of an initcall and the time it returns.
At the same time I want to know the schedule events that occur during
the initcalls
and then the latency they raise. For that I need to have the same
timestamp than the boot
tracer to have a consistent view of these schedule events inside the initcalls.
But you just gave me a new idea :-)
If I split the initcall in two parts: the call and the return, I will
be able to drop these
boot-tracer-specific timestamps and just use the ring-buffer timestamp used
when an entry is appended into the buffer.
And so I can use the usual sched_switch events whithout additional field.
Seems to me really better.
But there is one thing that changes with this new way. It seems that
the ring buffer's timestamp
is based on the sched-clock and so I guess that's why it doesn't start
when the cpu boot but some
times after.
Arjan would you agree with this new time capture system?