]> git.karo-electronics.de Git - karo-tx-linux.git/blobdiff - kernel/printk/printk.c
Merge branch 'akpm-current/current'
[karo-tx-linux.git] / kernel / printk / printk.c
index 221229cf019020838faaa697102e58fe6d36e2dc..ea2d5f6962edd7d7530c0e5766ea3517d5515e25 100644 (file)
 #include "console_cmdline.h"
 #include "braille.h"
 
-/* printk's without a loglevel use this.. */
-#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL
-
-/* We show everything that is MORE important than this.. */
-#define MINIMUM_CONSOLE_LOGLEVEL 1 /* Minimum loglevel we let people use */
-#define DEFAULT_CONSOLE_LOGLEVEL 7 /* anything MORE serious than KERN_DEBUG */
-
 int console_printk[4] = {
-       DEFAULT_CONSOLE_LOGLEVEL,       /* console_loglevel */
+       CONSOLE_LOGLEVEL_DEFAULT,       /* console_loglevel */
        DEFAULT_MESSAGE_LOGLEVEL,       /* default_message_loglevel */
-       MINIMUM_CONSOLE_LOGLEVEL,       /* minimum_console_loglevel */
-       DEFAULT_CONSOLE_LOGLEVEL,       /* default_console_loglevel */
+       CONSOLE_LOGLEVEL_MIN,           /* minimum_console_loglevel */
+       CONSOLE_LOGLEVEL_DEFAULT,       /* default_console_loglevel */
 };
 
+/* Deferred messaged from sched code are marked by this special level */
+#define SCHED_MESSAGE_LOGLEVEL -2
+
 /*
  * Low level drivers may need that to know if they can schedule in
  * their unblank() callback or not. So let's export it.
@@ -90,6 +86,29 @@ static struct lockdep_map console_lock_dep_map = {
 };
 #endif
 
+/*
+ * Helper macros to handle lockdep when locking/unlocking console_sem. We use
+ * macros instead of functions so that _RET_IP_ contains useful information.
+ */
+#define down_console_sem() do { \
+       down(&console_sem);\
+       mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);\
+} while (0)
+
+static int __down_trylock_console_sem(unsigned long ip)
+{
+       if (down_trylock(&console_sem))
+               return 1;
+       mutex_acquire(&console_lock_dep_map, 0, 1, ip);
+       return 0;
+}
+#define down_trylock_console_sem() __down_trylock_console_sem(_RET_IP_)
+
+#define up_console_sem() do { \
+       mutex_release(&console_lock_dep_map, 1, _RET_IP_);\
+       up(&console_sem);\
+} while (0)
+
 /*
  * This is used for debugging the mess that is the VT code by
  * keeping track if we have the console semaphore held. It's
@@ -206,8 +225,9 @@ struct printk_log {
 };
 
 /*
- * The logbuf_lock protects kmsg buffer, indices, counters. It is also
- * used in interesting ways to provide interlocking in console_unlock();
+ * The logbuf_lock protects kmsg buffer, indices, counters.  This can be taken
+ * within the scheduler's rq lock. It must be released before calling
+ * console_unlock() or anything else that might wake up a process.
  */
 static DEFINE_RAW_SPINLOCK(logbuf_lock);
 
@@ -250,9 +270,6 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
-/* cpu currently holding logbuf_lock */
-static volatile unsigned int logbuf_cpu = UINT_MAX;
-
 /* human readable text of the record */
 static char *log_text(const struct printk_log *msg)
 {
@@ -297,34 +314,106 @@ static u32 log_next(u32 idx)
        return idx + msg->len;
 }
 
-/* insert record into the buffer, discard old ones, update heads */
-static void log_store(int facility, int level,
-                     enum log_flags flags, u64 ts_nsec,
-                     const char *dict, u16 dict_len,
-                     const char *text, u16 text_len)
+/*
+ * Check whether there is enough free space for the given message.
+ *
+ * The same values of first_idx and next_idx mean that the buffer
+ * is either empty or full.
+ *
+ * If the buffer is empty, we must respect the position of the indexes.
+ * They cannot be reset to the beginning of the buffer.
+ */
+static int logbuf_has_space(u32 msg_size, bool empty)
 {
-       struct printk_log *msg;
-       u32 size, pad_len;
+       u32 free;
 
-       /* number of '\0' padding bytes to next message */
-       size = sizeof(struct printk_log) + text_len + dict_len;
-       pad_len = (-size) & (LOG_ALIGN - 1);
-       size += pad_len;
+       if (log_next_idx > log_first_idx || empty)
+               free = max(log_buf_len - log_next_idx, log_first_idx);
+       else
+               free = log_first_idx - log_next_idx;
 
+       /*
+        * We need space also for an empty header that signalizes wrapping
+        * of the buffer.
+        */
+       return free >= msg_size + sizeof(struct printk_log);
+}
+
+static int log_make_free_space(u32 msg_size)
+{
        while (log_first_seq < log_next_seq) {
-               u32 free;
+               if (logbuf_has_space(msg_size, false))
+                       return 0;
+               /* drop old messages until we have enough continuous space */
+               log_first_idx = log_next(log_first_idx);
+               log_first_seq++;
+       }
 
-               if (log_next_idx > log_first_idx)
-                       free = max(log_buf_len - log_next_idx, log_first_idx);
-               else
-                       free = log_first_idx - log_next_idx;
+       /* sequence numbers are equal, so the log buffer is empty */
+       if (logbuf_has_space(msg_size, true))
+               return 0;
 
-               if (free >= size + sizeof(struct printk_log))
-                       break;
+       return -ENOMEM;
+}
 
-               /* drop old messages until we have enough contiuous space */
-               log_first_idx = log_next(log_first_idx);
-               log_first_seq++;
+/* compute the message size including the padding bytes */
+static u32 msg_used_size(u16 text_len, u16 dict_len, u32 *pad_len)
+{
+       u32 size;
+
+       size = sizeof(struct printk_log) + text_len + dict_len;
+       *pad_len = (-size) & (LOG_ALIGN - 1);
+       size += *pad_len;
+
+       return size;
+}
+
+/*
+ * Define how much of the log buffer we could take at maximum. The value
+ * must be greater than two. Note that only half of the buffer is available
+ * when the index points to the middle.
+ */
+#define MAX_LOG_TAKE_PART 4
+static const char trunc_msg[] = "<truncated>";
+
+static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
+                       u16 *dict_len, u32 *pad_len)
+{
+       /*
+        * The message should not take the whole buffer. Otherwise, it might
+        * get removed too soon.
+        */
+       u32 max_text_len = log_buf_len / MAX_LOG_TAKE_PART;
+       if (*text_len > max_text_len)
+               *text_len = max_text_len;
+       /* enable the warning message */
+       *trunc_msg_len = strlen(trunc_msg);
+       /* disable the "dict" completely */
+       *dict_len = 0;
+       /* compute the size again, count also the warning message */
+       return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
+}
+
+/* insert record into the buffer, discard old ones, update heads */
+static int log_store(int facility, int level,
+                    enum log_flags flags, u64 ts_nsec,
+                    const char *dict, u16 dict_len,
+                    const char *text, u16 text_len)
+{
+       struct printk_log *msg;
+       u32 size, pad_len;
+       u16 trunc_msg_len = 0;
+
+       /* number of '\0' padding bytes to next message */
+       size = msg_used_size(text_len, dict_len, &pad_len);
+
+       if (log_make_free_space(size)) {
+               /* truncate the message if it is too long for empty buffer */
+               size = truncate_msg(&text_len, &trunc_msg_len,
+                                   &dict_len, &pad_len);
+               /* survive when the log buffer is too small for trunc_msg */
+               if (log_make_free_space(size))
+                       return 0;
        }
 
        if (log_next_idx + size + sizeof(struct printk_log) > log_buf_len) {
@@ -341,6 +430,10 @@ static void log_store(int facility, int level,
        msg = (struct printk_log *)(log_buf + log_next_idx);
        memcpy(log_text(msg), text, text_len);
        msg->text_len = text_len;
+       if (trunc_msg_len) {
+               memcpy(log_text(msg) + text_len, trunc_msg, trunc_msg_len);
+               msg->text_len += trunc_msg_len;
+       }
        memcpy(log_dict(msg), dict, dict_len);
        msg->dict_len = dict_len;
        msg->facility = facility;
@@ -356,6 +449,8 @@ static void log_store(int facility, int level,
        /* insert message */
        log_next_idx += msg->len;
        log_next_seq++;
+
+       return msg->text_len;
 }
 
 #ifdef CONFIG_SECURITY_DMESG_RESTRICT
@@ -1303,7 +1398,10 @@ static void zap_locks(void)
        sema_init(&console_sem, 1);
 }
 
-/* Check if we have any console registered that can be called early in boot. */
+/*
+ * Check if we have any console that is capable of printing while cpu is
+ * booting or shutting down. Requires console_sem.
+ */
 static int have_callable_console(void)
 {
        struct console *con;
@@ -1318,10 +1416,9 @@ static int have_callable_console(void)
 /*
  * Can we actually use the console at this time on this cpu?
  *
- * Console drivers may assume that per-cpu resources have
- * been allocated. So unless they're explicitly marked as
- * being able to cope (CON_ANYTIME) don't call them until
- * this CPU is officially up.
+ * Console drivers may assume that per-cpu resources have been allocated. So
+ * unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
+ * call them until this CPU is officially up.
  */
 static inline int can_use_console(unsigned int cpu)
 {
@@ -1333,36 +1430,24 @@ static inline int can_use_console(unsigned int cpu)
  * messages from a 'printk'. Return true (and with the
  * console_lock held, and 'console_locked' set) if it
  * is successful, false otherwise.
- *
- * This gets called with the 'logbuf_lock' spinlock held and
- * interrupts disabled. It should return with 'lockbuf_lock'
- * released but interrupts still disabled.
  */
-static int console_trylock_for_printk(unsigned int cpu)
-       __releases(&logbuf_lock)
+static int console_trylock_for_printk(void)
 {
-       int retval = 0, wake = 0;
-
-       if (console_trylock()) {
-               retval = 1;
+       unsigned int cpu = smp_processor_id();
 
-               /*
-                * If we can't use the console, we need to release
-                * the console semaphore by hand to avoid flushing
-                * the buffer. We need to hold the console semaphore
-                * in order to do this test safely.
-                */
-               if (!can_use_console(cpu)) {
-                       console_locked = 0;
-                       wake = 1;
-                       retval = 0;
-               }
+       if (!console_trylock())
+               return 0;
+       /*
+        * If we can't use the console, we need to release the console
+        * semaphore by hand to avoid flushing the buffer. We need to hold the
+        * console semaphore in order to do this test safely.
+        */
+       if (!can_use_console(cpu)) {
+               console_locked = 0;
+               up_console_sem();
+               return 0;
        }
-       logbuf_cpu = UINT_MAX;
-       raw_spin_unlock(&logbuf_lock);
-       if (wake)
-               up(&console_sem);
-       return retval;
+       return 1;
 }
 
 int printk_delay_msec __read_mostly;
@@ -1490,11 +1575,19 @@ asmlinkage int vprintk_emit(int facility, int level,
        static int recursion_bug;
        static char textbuf[LOG_LINE_MAX];
        char *text = textbuf;
-       size_t text_len;
+       size_t text_len = 0;
        enum log_flags lflags = 0;
        unsigned long flags;
        int this_cpu;
        int printed_len = 0;
+       bool in_sched = false;
+       /* cpu currently holding logbuf_lock in this function */
+       static volatile unsigned int logbuf_cpu = UINT_MAX;
+
+       if (level == SCHED_MESSAGE_LOGLEVEL) {
+               level = -1;
+               in_sched = true;
+       }
 
        boot_delay_msec(level);
        printk_delay();
@@ -1516,7 +1609,8 @@ asmlinkage int vprintk_emit(int facility, int level,
                 */
                if (!oops_in_progress && !lockdep_recursing(current)) {
                        recursion_bug = 1;
-                       goto out_restore_irqs;
+                       local_irq_restore(flags);
+                       return 0;
                }
                zap_locks();
        }
@@ -1530,17 +1624,22 @@ asmlinkage int vprintk_emit(int facility, int level,
                        "BUG: recent printk recursion!";
 
                recursion_bug = 0;
-               printed_len += strlen(recursion_msg);
+               text_len = strlen(recursion_msg);
                /* emit KERN_CRIT message */
-               log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
-                         NULL, 0, recursion_msg, printed_len);
+               printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
+                                        NULL, 0, recursion_msg, text_len);
        }
 
        /*
         * The printf needs to come first; we need the syslog
         * prefix which might be passed-in as a parameter.
         */
-       text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
+       if (in_sched)
+               text_len = scnprintf(text, sizeof(textbuf),
+                                    KERN_WARNING "[sched_delayed] ");
+
+       text_len += vscnprintf(text + text_len,
+                              sizeof(textbuf) - text_len, fmt, args);
 
        /* mark and strip a trailing newline */
        if (text_len && text[text_len-1] == '\n') {
@@ -1586,9 +1685,12 @@ asmlinkage int vprintk_emit(int facility, int level,
                        cont_flush(LOG_NEWLINE);
 
                /* buffer line if possible, otherwise store it right away */
-               if (!cont_add(facility, level, text, text_len))
-                       log_store(facility, level, lflags | LOG_CONT, 0,
-                                 dict, dictlen, text, text_len);
+               if (cont_add(facility, level, text, text_len))
+                       printed_len += text_len;
+               else
+                       printed_len += log_store(facility, level,
+                                                lflags | LOG_CONT, 0,
+                                                dict, dictlen, text, text_len);
        } else {
                bool stored = false;
 
@@ -1607,26 +1709,35 @@ asmlinkage int vprintk_emit(int facility, int level,
                        cont_flush(LOG_NEWLINE);
                }
 
-               if (!stored)
-                       log_store(facility, level, lflags, 0,
-                                 dict, dictlen, text, text_len);
+               if (stored)
+                       printed_len += text_len;
+               else
+                       printed_len += log_store(facility, level, lflags, 0,
+                                                dict, dictlen, text, text_len);
        }
-       printed_len += text_len;
 
+       logbuf_cpu = UINT_MAX;
+       raw_spin_unlock(&logbuf_lock);
+       lockdep_on();
+       local_irq_restore(flags);
+
+       /* If called from the scheduler, we can not call up(). */
+       if (in_sched)
+               return printed_len;
+
+       /*
+        * Disable preemption to avoid being preempted while holding
+        * console_sem which would prevent anyone from printing to console
+        */
+       preempt_disable();
        /*
         * Try to acquire and then immediately release the console semaphore.
         * The release will print out buffers and wake up /dev/kmsg and syslog()
         * users.
-        *
-        * The console_trylock_for_printk() function will release 'logbuf_lock'
-        * regardless of whether it actually gets the console semaphore or not.
         */
-       if (console_trylock_for_printk(this_cpu))
+       if (console_trylock_for_printk())
                console_unlock();
-
-       lockdep_on();
-out_restore_irqs:
-       local_irq_restore(flags);
+       preempt_enable();
 
        return printed_len;
 }
@@ -1882,16 +1993,14 @@ void suspend_console(void)
        printk("Suspending console(s) (use no_console_suspend to debug)\n");
        console_lock();
        console_suspended = 1;
-       up(&console_sem);
-       mutex_release(&console_lock_dep_map, 1, _RET_IP_);
+       up_console_sem();
 }
 
 void resume_console(void)
 {
        if (!console_suspend_enabled)
                return;
-       down(&console_sem);
-       mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);
+       down_console_sem();
        console_suspended = 0;
        console_unlock();
 }
@@ -1933,12 +2042,11 @@ void console_lock(void)
 {
        might_sleep();
 
-       down(&console_sem);
+       down_console_sem();
        if (console_suspended)
                return;
        console_locked = 1;
        console_may_schedule = 1;
-       mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);
 }
 EXPORT_SYMBOL(console_lock);
 
@@ -1952,15 +2060,14 @@ EXPORT_SYMBOL(console_lock);
  */
 int console_trylock(void)
 {
-       if (down_trylock(&console_sem))
+       if (down_trylock_console_sem())
                return 0;
        if (console_suspended) {
-               up(&console_sem);
+               up_console_sem();
                return 0;
        }
        console_locked = 1;
        console_may_schedule = 0;
-       mutex_acquire(&console_lock_dep_map, 0, 1, _RET_IP_);
        return 1;
 }
 EXPORT_SYMBOL(console_trylock);
@@ -2022,7 +2129,7 @@ void console_unlock(void)
        bool retry;
 
        if (console_suspended) {
-               up(&console_sem);
+               up_console_sem();
                return;
        }
 
@@ -2043,10 +2150,15 @@ again:
                }
 
                if (console_seq < log_first_seq) {
+                       len = sprintf(text, "** %u printk messages dropped ** ",
+                                     (unsigned)(log_first_seq - console_seq));
+
                        /* messages are gone, move to first one */
                        console_seq = log_first_seq;
                        console_idx = log_first_idx;
                        console_prev = 0;
+               } else {
+                       len = 0;
                }
 skip:
                if (console_seq == log_next_seq)
@@ -2071,8 +2183,8 @@ skip:
                }
 
                level = msg->level;
-               len = msg_print_text(msg, console_prev, false,
-                                    text, sizeof(text));
+               len += msg_print_text(msg, console_prev, false,
+                                     text + len, sizeof(text) - len);
                console_idx = log_next(console_idx);
                console_seq++;
                console_prev = msg->flags;
@@ -2084,7 +2196,6 @@ skip:
                local_irq_restore(flags);
        }
        console_locked = 0;
-       mutex_release(&console_lock_dep_map, 1, _RET_IP_);
 
        /* Release the exclusive_console once it is used */
        if (unlikely(exclusive_console))
@@ -2092,7 +2203,7 @@ skip:
 
        raw_spin_unlock(&logbuf_lock);
 
-       up(&console_sem);
+       up_console_sem();
 
        /*
         * Someone could have filled up the buffer again, so re-check if there's
@@ -2137,7 +2248,7 @@ void console_unblank(void)
         * oops_in_progress is set to 1..
         */
        if (oops_in_progress) {
-               if (down_trylock(&console_sem) != 0)
+               if (down_trylock_console_sem() != 0)
                        return;
        } else
                console_lock();
@@ -2438,21 +2549,19 @@ late_initcall(printk_late_init);
 /*
  * Delayed printk version, for scheduler-internal messages:
  */
-#define PRINTK_BUF_SIZE                512
-
 #define PRINTK_PENDING_WAKEUP  0x01
-#define PRINTK_PENDING_SCHED   0x02
+#define PRINTK_PENDING_OUTPUT  0x02
 
 static DEFINE_PER_CPU(int, printk_pending);
-static DEFINE_PER_CPU(char [PRINTK_BUF_SIZE], printk_sched_buf);
 
 static void wake_up_klogd_work_func(struct irq_work *irq_work)
 {
        int pending = __this_cpu_xchg(printk_pending, 0);
 
-       if (pending & PRINTK_PENDING_SCHED) {
-               char *buf = __get_cpu_var(printk_sched_buf);
-               pr_warn("[sched_delayed] %s", buf);
+       if (pending & PRINTK_PENDING_OUTPUT) {
+               /* If trylock fails, someone else is doing the printing */
+               if (console_trylock())
+                       console_unlock();
        }
 
        if (pending & PRINTK_PENDING_WAKEUP)
@@ -2474,23 +2583,19 @@ void wake_up_klogd(void)
        preempt_enable();
 }
 
-int printk_sched(const char *fmt, ...)
+int printk_deferred(const char *fmt, ...)
 {
-       unsigned long flags;
        va_list args;
-       char *buf;
        int r;
 
-       local_irq_save(flags);
-       buf = __get_cpu_var(printk_sched_buf);
-
+       preempt_disable();
        va_start(args, fmt);
-       r = vsnprintf(buf, PRINTK_BUF_SIZE, fmt, args);
+       r = vprintk_emit(0, SCHED_MESSAGE_LOGLEVEL, NULL, 0, fmt, args);
        va_end(args);
 
-       __this_cpu_or(printk_pending, PRINTK_PENDING_SCHED);
+       __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
        irq_work_queue(&__get_cpu_var(wake_up_klogd_work));
-       local_irq_restore(flags);
+       preempt_enable();
 
        return r;
 }