From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1760671AbYJKUU7 (ORCPT ); Sat, 11 Oct 2008 16:20:59 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1753854AbYJKUUv (ORCPT ); Sat, 11 Oct 2008 16:20:51 -0400 Received: from fk-out-0910.google.com ([209.85.128.189]:41767 "EHLO fk-out-0910.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754142AbYJKUUu (ORCPT ); Sat, 11 Oct 2008 16:20:50 -0400 DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=message-id:date:from:user-agent:mime-version:to:cc:subject :content-type:content-transfer-encoding; b=L+LRLlGgKyiYlrkAvuhXEspIQCb0joWaqtXG9qOeiCTBAo+65ECqBBY7eJosyK2/pE q5DjPpUP74lxoXAEN1/SBOiffQfbCEMcSwG68quMjnFwNpgTEFXyHZfXek/dJ0jZCD2c i0JTbskBmiF7u4Ie5eUVuDXWTaXjfdtejTwwE= Message-ID: <48F10A9D.3030705@gmail.com> Date: Sat, 11 Oct 2008 22:20:45 +0200 From: Frederic Weisbecker User-Agent: Thunderbird 2.0.0.17 (Windows/20080914) MIME-Version: 1.0 To: Ingo Molnar CC: Steven Rostedt , linux-kernel@vger.kernel.org, Arjan van de Ven Subject: [PATCH 4/5] tracing/fastboot: Add a time field on the sched_switch entry Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 Cc: Arjan van de Ven Cc: Steven Rostedt --- 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 * + * Some parts of code (IE: sched_switch_print_line function) + * have been borrowed from trace.c */ #include @@ -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)