@@ -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_thread_sleep,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
+
+DEFINE_EVENT(printk_class, printk_thread_woken,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
+
+DEFINE_EVENT(printk_class, printk_thread_locked,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
+
+DEFINE_EVENT(printk_class, printk_printing,
+ TP_PROTO(int u),
+ TP_ARGS(u)
+);
#endif /* _TRACE_PRINTK_H */
/* This part must be outside protection */
@@ -23,6 +23,7 @@
#include <linux/console.h>
#include <linux/init.h>
#include <linux/jiffies.h>
+#include <linux/stacktrace.h>
#include <linux/nmi.h>
#include <linux/module.h>
#include <linux/moduleparam.h>
@@ -90,6 +91,8 @@ EXPORT_SYMBOL_GPL(console_drivers);
/* This gets set if the currently printing task wants to hand over printing */
static int printk_handover;
+static int thread_woken;
+
/*
* Number of kernel threads for offloading printing. We need at least two so
* that they can hand over printing from one to another one and thus switch
@@ -1308,6 +1311,22 @@ static void call_console_drivers(int level, const char *text, size_t len)
}
}
+static void printk_echo(char *fmt, ...)
+{
+ unsigned long flags;
+ va_list args;
+ char buf[128];
+ int len;
+
+ len = sprintf(buf, "P%d ", task_pid_nr(current));
+ va_start(args, fmt);
+ len += vsprintf(buf + len, fmt, args);
+ va_end(args);
+ local_irq_save(flags);
+ call_console_drivers(0, buf, len);
+ 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
@@ -1512,6 +1531,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 == SCHED_MESSAGE_LOGLEVEL) {
level = -1;
@@ -1566,6 +1586,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);
@@ -2030,6 +2052,31 @@ out:
raw_spin_unlock_irqrestore(&logbuf_lock, flags);
}
+static struct task_struct *resched_task = NULL;
+static unsigned long last_traced;
+
+static void echo_trace(struct task_struct *task)
+{
+ struct stack_trace trace;
+ unsigned long entries[16];
+ int i;
+
+ trace.nr_entries = 0;
+ trace.max_entries = 16;
+ trace.entries = entries;
+ trace.skip = 0;
+
+ save_stack_trace_tsk(task, &trace);
+ for (i = 0; i < trace.nr_entries; i++)
+ printk_echo("%pS\n", (void *)entries[i]);
+ last_traced = jiffies;
+}
+
+static void ipi_stacktrace(void *info)
+{
+ echo_trace(current);
+}
+
/*
* Returns true iff there is other cpu waiting to take over printing. This
* function also takes are of setting printk_handover if we want to hand over
@@ -2043,16 +2090,33 @@ static bool cpu_stop_printing(int printed_chars)
if (!printk_offload_chars || printed_chars < printk_offload_chars)
return false;
/* Someone is sleeping on console_sem? Give away to him. */
- if (sema_contended(&console_sem))
+ if (sema_contended(&console_sem)) {
+ printk_echo("Handing over printing\n");
+ trace_printk_hand_over(0);
return true;
+ }
if (!printk_handover) {
+ unsigned long flags;
+
printk_handover = 1;
+ spin_lock_irqsave(&print_queue.lock, flags);
+ if (!list_empty(&print_queue.task_list))
+ resched_task = list_entry(print_queue.task_list.next, wait_queue_t, task_list)->private;
+ spin_unlock_irqrestore(&print_queue.lock, flags);
+ printk_echo("Asking for help %p (%d)\n", resched_task, (resched_task ? task_pid_nr(resched_task) : 0));
+ trace_printk_ask_help(0);
/*
* Paired with barrier in prepare_to_wait_exclusive() in
* printing_task()
*/
smp_mb();
wake_up(&print_queue);
+ if (resched_task) {
+ printk_echo("Task state %ld, cpu %u, cur cpu %u\n",
+ resched_task->state, task_cpu(resched_task),
+ task_cpu(current));
+ on_each_cpu(ipi_stacktrace, NULL, 1);
+ }
}
return false;
}
@@ -2088,6 +2152,9 @@ void console_unlock(void)
return;
}
+ if (oops_in_progress)
+ printk_echo("Oops!\n");
+ trace_printk_printing(0);
console_may_schedule = 0;
/* flush buffered message fragment immediately to console */
@@ -2148,9 +2215,24 @@ skip:
raw_spin_unlock(&logbuf_lock);
stop_critical_timings(); /* don't trace print latency */
+ if (printk_handover) {
+ if (sema_contended(&console_sem))
+ printk_echo("B ");
+ else if (thread_woken)
+ printk_echo("A ");
+ else if (resched_task) {
+ printk_echo("X%ld ", resched_task->state);
+ if (time_is_before_jiffies(last_traced + HZ)) {
+ smp_call_function_single(
+ task_cpu(resched_task),
+ ipi_stacktrace, NULL, 1);
+ }
+ }
+ }
call_console_drivers(level, text, len);
start_critical_timings();
printed_chars += len;
+ mdelay(len);
local_irq_restore(flags);
}
@@ -2159,6 +2241,7 @@ skip:
exclusive_console = NULL;
printk_handover = 0;
+ resched_task = NULL;
console_locked = 0;
mutex_release(&console_lock_dep_map, 1, _RET_IP_);
up(&console_sem);
@@ -2499,23 +2582,46 @@ static int printing_task(void *arg)
DEFINE_WAIT(wait);
while (1) {
- prepare_to_wait_exclusive(&print_queue, &wait,
+ prepare_to_wait(&print_queue, &wait,
TASK_INTERRUPTIBLE);
- if (!printk_handover)
+ if (!printk_handover) {
+ trace_printk_thread_sleep(0);
schedule();
+ }
finish_wait(&print_queue, &wait);
+ trace_printk_thread_woken(0);
+ thread_woken = 1;
console_lock();
+ thread_woken = 0;
+ trace_printk_thread_locked(0);
console_unlock();
}
return 0;
}
+static 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;
struct task_struct *task;
+ 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) {
printk(KERN_INFO "turn off boot console %s%d\n",
Signed-off-by: Jan Kara <jack@suse.cz> --- include/trace/events/printk.h | 42 ++++++++++++++++ kernel/printk/printk.c | 112 ++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 151 insertions(+), 3 deletions(-)