[PATCH 10/10] printk: debug: Slow down printing to 9600 bauds
From: Jan Kara
Date: Mon Dec 23 2013 - 15:40:22 EST
Signed-off-by: Jan Kara <jack@xxxxxxx>
---
include/trace/events/printk.h | 42 +++++++++++++++++++++++++++++++++++
kernel/printk/printk.c | 51 ++++++++++++++++++++++++++++++++++++++++++-
2 files changed, 92 insertions(+), 1 deletion(-)
diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
index c008bc99f9fa..2bd0c0e241f7 100644
--- a/include/trace/events/printk.h
+++ b/include/trace/events/printk.h
@@ -22,6 +22,48 @@ TRACE_EVENT(console,
TP_printk("%s", __get_str(msg))
);
+
+DECLARE_EVENT_CLASS(printk_class,
+ TP_PROTO(int u),
+ TP_ARGS(u),
+ TP_STRUCT__entry(
+ __field( int, u)
+ ),
+ TP_fast_assign(
+ __entry->u = u;
+ ),
+ TP_printk("arg=%d", __entry->u)
+);
+
+DEFINE_EVENT(printk_class, printk_hand_over,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
+
+DEFINE_EVENT(printk_class, printk_ask_help,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
+
+DEFINE_EVENT(printk_class, printk_send_ipi,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
+
+DEFINE_EVENT(printk_class, printk_ipi_received,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
+
+DEFINE_EVENT(printk_class, printk_set_wait,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
+
+DEFINE_EVENT(printk_class, printk_sem_spin,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
#endif /* _TRACE_PRINTK_H */
/* This part must be outside protection */
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 8abbb5373999..e78fe2dc280f 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1337,6 +1337,15 @@ static void call_console_drivers(int level, const char *text, size_t len)
}
}
+static void printk_echo(char *txt)
+{
+ unsigned long flags;
+
+ local_irq_save(flags);
+ call_console_drivers(0, txt, strlen(txt));
+ local_irq_restore(flags);
+}
+
/*
* Zap console related locks when oopsing. Only zap at most once
* every 10 seconds, to leave time for slow consoles to print a
@@ -1406,10 +1415,14 @@ static int console_trylock_for_printk(void)
if (hand_over_cpu == cpu)
return 0;
+ printk_echo("Setting PS_WAITING\n");
+ trace_printk_set_wait(0);
state = cmpxchg(&printing_state, PS_HANDOVER, PS_WAITING);
if (state != PS_HANDOVER)
return 0;
+ printk_echo("Spinning on console_sem\n");
+ trace_printk_sem_spin(0);
/*
* Since PS_HANDOVER state is set only in console_unlock()
* we shouldn't spin for long here. And we cannot sleep because
@@ -1426,6 +1439,7 @@ static int console_trylock_for_printk(void)
return 0;
__delay(1);
}
+ printk_echo("Got console_sem\n");
}
/*
* If we can't use the console, we need to release the console
@@ -1574,6 +1588,7 @@ asmlinkage int vprintk_emit(int facility, int level,
bool in_sched = false;
/* cpu currently holding logbuf_lock in this function */
static volatile unsigned int logbuf_cpu = UINT_MAX;
+ bool irq_off = irqs_disabled();
if (level == -2) {
level = -1;
@@ -1628,6 +1643,8 @@ asmlinkage int vprintk_emit(int facility, int level,
if (in_sched)
text_len = scnprintf(text, sizeof(textbuf),
KERN_WARNING "[sched_delayed] ");
+ if (irq_off)
+ text[text_len++] = 'X';
text_len += vscnprintf(text + text_len,
sizeof(textbuf) - text_len, fmt, args);
@@ -2094,6 +2111,8 @@ out:
/* Handler for IPI to take over printing from another CPU */
static void printk_take_over(void *info)
{
+ printk_echo("IPI received\n");
+ trace_printk_ipi_received(smp_processor_id());
/*
* We have to clear printk_ipi_sent only after we succeed / fail the
* trylock. That way we make sure there is at most one IPI spinning
@@ -2116,13 +2135,17 @@ static void printk_take_over(void *info)
static bool cpu_stop_printing(int printed_chars)
{
cpumask_var_t mask;
+ char buf[80];
/* Oops? Print everything now to maximize chances user will see it */
if (oops_in_progress)
return false;
/* Someone is waiting. Stop printing. */
- if (printing_state == PS_WAITING)
+ if (printing_state == PS_WAITING) {
+ printk_echo("Handing over printing\n");
+ trace_printk_hand_over(0);
return true;
+ }
if (!printk_offload_chars || printed_chars <= printk_offload_chars)
return false;
if (printing_state == PS_PRINTING) {
@@ -2130,8 +2153,13 @@ static bool cpu_stop_printing(int printed_chars)
/* Paired with smp_rmb() in console_trylock_for_printk() */
smp_wmb();
printing_state = PS_HANDOVER;
+ printk_echo("Asking for help\n");
+ trace_printk_ask_help(0);
return false;
}
+
+ sprintf(buf, "Checking IPI: %d %d > %d\n", (int)printk_ipi_sent, printed_chars, 2*printk_offload_chars);
+ printk_echo(buf);
/*
* We ping another CPU with IPI only if noone took over printing for a
* long time - we prefer other printk() to take over printing since it
@@ -2140,6 +2168,8 @@ static bool cpu_stop_printing(int printed_chars)
if (!printk_ipi_sent && printed_chars > 2 * printk_offload_chars) {
struct call_single_data *csd = &hand_over_csd[current_csd];
+ trace_printk_send_ipi(hand_over_cpu);
+ printk_echo("Sending IPI\n");
/* Ping another cpu to take printing from us */
cpumask_copy(mask, cpu_online_mask);
cpumask_clear_cpu(hand_over_cpu, mask);
@@ -2245,6 +2275,7 @@ skip:
call_console_drivers(level, text, len);
start_critical_timings();
printed_chars += len;
+ mdelay(len);
local_irq_restore(flags);
}
@@ -2588,9 +2619,27 @@ int unregister_console(struct console *console)
}
EXPORT_SYMBOL(unregister_console);
+void do_print(struct work_struct *work)
+{
+ char buf[75];
+ int i;
+
+ sprintf(buf, "%p: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\n", work);
+ for (i = 0; i < 15; i++)
+ printk(buf);
+}
+
+static struct delayed_work print_work[100];
+
static int __init printk_late_init(void)
{
struct console *con;
+ int i;
+
+ for (i = 0; i < 100; i++) {
+ INIT_DELAYED_WORK(&print_work[i], do_print);
+ schedule_delayed_work(&print_work[i], HZ * 180);
+ }
for_each_console(con) {
if (!keep_bootcon && con->flags & CON_BOOT) {
--
1.8.1.4
--
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/