#include <linux/uaccess.h>
#include <asm/sections.h>
-
+#include <linux/rtc.h>
#define CREATE_TRACE_POINTS
#include <trace/events/printk.h>
u8 facility; /* syslog facility */
u8 flags:5; /* internal record flags */
u8 level:3; /* syslog level */
+ u8 cpu; /* cpu id */
#ifdef CONFIG_PRINTK_PROCESS
char process[16]; /* process name */
pid_t pid; /* process id */
- u8 cpu; /* cpu id */
u8 in_interrupt; /* interrupt context */
#endif
}
static u64 clear_seq;
static u32 clear_idx;
-#ifdef CONFIG_PRINTK_PROCESS
+#ifdef CONFIG_PRINTK_UTC_TIME
+#define PREFIX_MAX 100
+#elif defined(CONFIG_PRINTK_PROCESS)
#define PREFIX_MAX 48
#else
#define PREFIX_MAX 32
#endif
-#define LOG_LINE_MAX (1024 - PREFIX_MAX)
+#define LOG_LINE_MAX (2048 - PREFIX_MAX)
#define LOG_LEVEL(v) ((v) & 0x07)
#define LOG_FACILITY(v) ((v) >> 3 & 0xff)
#ifdef CONFIG_PRINTK_PROCESS
static bool printk_process = 1;
+#ifndef CONFIG_PRINTK_UTC_TIME
static size_t print_process(const struct printk_log *msg, char *buf)
{
return 0;
if (!buf)
- return snprintf(NULL, 0, "%c[%1d:%15s:%5d] ", ' ', 0, " ", 0);
+ return snprintf(NULL, 0, "%c[%15s:%5d] ", ' ', " ", 0);
- return sprintf(buf, "%c[%1d:%15s:%5d] ",
+ return sprintf(buf, "%c[%15s:%5d] ",
msg->in_interrupt ? 'I' : ' ',
- msg->cpu,
msg->process,
msg->pid);
}
+#endif
#else
static bool printk_process = 0;
+#ifndef CONFIG_PRINTK_UTC_TIME
static size_t print_process(const struct printk_log *msg, char *buf)
{
return 0;
}
#endif
+#endif
module_param_named(process, printk_process, bool, S_IRUGO | S_IWUSR);
#ifdef CONFIG_DEBUG_SNAPSHOT
/* compute the size again, count also the warning message */
return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
}
+#ifdef CONFIG_PRINTK_UTC_TIME
+static void log_store_utc_time(char *buf, u32 buf_size, u16 *len) {
+ struct timespec ts;
+ struct rtc_time tm;
+ ts = current_kernel_time();
+ rtc_time_to_tm(ts.tv_sec, &tm);
+ *len += snprintf(buf, buf_size, "[%lu:%.2d:%.2d %.2d:%.2d:%.2d.%09lu]",
+ 1900 + tm.tm_year, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,ts.tv_nsec);
+ *len += snprintf(buf + *len, buf_size-*len, "[pid:%d,cpu%d,%s]",
+ current->pid, smp_processor_id(), in_irq() ? "in irq" : current->comm);
+ return;
+}
+#endif
/* 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,
struct printk_log *msg;
u32 size, pad_len;
u16 trunc_msg_len = 0;
+#ifdef CONFIG_PRINTK_UTC_TIME
+ char tmp_buf[100];
+ u16 tmp_len = 0;
+ log_store_utc_time(tmp_buf, sizeof(tmp_buf), &tmp_len);
+ text_len += tmp_len;
+#endif
/* number of '\0' padding bytes to next message */
size = msg_used_size(text_len, dict_len, &pad_len);
/* fill message */
msg = (struct printk_log *)(log_buf + log_next_idx);
memcpy(log_text(msg), text, text_len);
+#ifdef CONFIG_PRINTK_UTC_TIME
+ memcpy(log_text(msg), tmp_buf, tmp_len);
+ memcpy(log_text(msg)+tmp_len, text, text_len-tmp_len);
+#else
+ memcpy(log_text(msg), text, text_len);
+#endif
+
msg->text_len = text_len;
if (trunc_msg_len) {
memcpy(log_text(msg) + text_len, trunc_msg, trunc_msg_len);
memset(log_dict(msg) + dict_len, 0, pad_len);
msg->len = size;
+ msg->cpu = smp_processor_id();
#ifdef CONFIG_PRINTK_PROCESS
if (printk_process) {
strncpy(msg->process, current->comm, sizeof(msg->process) - 1);
msg->process[sizeof(msg->process) - 1] = '\0';
msg->pid = task_pid_nr(current);
- msg->cpu = smp_processor_id();
msg->in_interrupt = in_interrupt() ? 1 : 0;
}
#endif
/* save requested log_buf_len since it's too early to process it */
static int __init log_buf_len_setup(char *str)
{
- unsigned size = memparse(str, &str);
+ unsigned int size;
+
+ if (!str)
+ return -EINVAL;
+
+ size = memparse(str, &str);
log_buf_len_update(size);
static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
-static size_t print_time(u64 ts, char *buf)
+static size_t print_time(u64 ts, char *buf, u8 cpu)
{
unsigned long rem_nsec;
rem_nsec = do_div(ts, 1000000000);
if (!buf)
- return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
+ return snprintf(NULL, 0, "[%5lu.000000,%u] ", (unsigned long)ts, cpu);
- return sprintf(buf, "[%5lu.%06lu] ",
- (unsigned long)ts, rem_nsec / 1000);
+ return sprintf(buf, "[%5lu.%06lu,%u] ",
+ (unsigned long)ts, rem_nsec / 1000,cpu);
}
static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf)
}
}
- len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
+ len += print_time(msg->ts_nsec, buf ? buf + len : NULL,
+ msg->cpu);
+#ifndef CONFIG_PRINTK_UTC_TIME
len += print_process(msg, buf ? buf + len : NULL);
+#endif
return len;
}
return do_syslog(type, buf, len, SYSLOG_FROM_READER);
}
+/*
+ * Special console_lock variants that help to reduce the risk of soft-lockups.
+ * They allow to pass console_lock to another printk() call using a busy wait.
+ */
+
+#ifdef CONFIG_LOCKDEP
+static struct lockdep_map console_owner_dep_map = {
+ .name = "console_owner"
+};
+#endif
+
+static DEFINE_RAW_SPINLOCK(console_owner_lock);
+static struct task_struct *console_owner;
+static bool console_waiter;
+
+/**
+ * console_lock_spinning_enable - mark beginning of code where another
+ * thread might safely busy wait
+ *
+ * This basically converts console_lock into a spinlock. This marks
+ * the section where the console_lock owner can not sleep, because
+ * there may be a waiter spinning (like a spinlock). Also it must be
+ * ready to hand over the lock at the end of the section.
+ */
+static void console_lock_spinning_enable(void)
+{
+ raw_spin_lock(&console_owner_lock);
+ console_owner = current;
+ raw_spin_unlock(&console_owner_lock);
+
+ /* The waiter may spin on us after setting console_owner */
+ spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
+}
+
+/**
+ * console_lock_spinning_disable_and_check - mark end of code where another
+ * thread was able to busy wait and check if there is a waiter
+ *
+ * This is called at the end of the section where spinning is allowed.
+ * It has two functions. First, it is a signal that it is no longer
+ * safe to start busy waiting for the lock. Second, it checks if
+ * there is a busy waiter and passes the lock rights to her.
+ *
+ * Important: Callers lose the lock if there was a busy waiter.
+ * They must not touch items synchronized by console_lock
+ * in this case.
+ *
+ * Return: 1 if the lock rights were passed, 0 otherwise.
+ */
+static int console_lock_spinning_disable_and_check(void)
+{
+ int waiter;
+
+ raw_spin_lock(&console_owner_lock);
+ waiter = READ_ONCE(console_waiter);
+ console_owner = NULL;
+ raw_spin_unlock(&console_owner_lock);
+
+ if (!waiter) {
+ spin_release(&console_owner_dep_map, 1, _THIS_IP_);
+ return 0;
+ }
+
+ /* The waiter is now free to continue */
+ WRITE_ONCE(console_waiter, false);
+
+ spin_release(&console_owner_dep_map, 1, _THIS_IP_);
+
+ /*
+ * Hand off console_lock to waiter. The waiter will perform
+ * the up(). After this, the waiter is the console_lock owner.
+ */
+ mutex_release(&console_lock_dep_map, 1, _THIS_IP_);
+ return 1;
+}
+
+/**
+ * console_trylock_spinning - try to get console_lock by busy waiting
+ *
+ * This allows to busy wait for the console_lock when the current
+ * owner is running in specially marked sections. It means that
+ * the current owner is running and cannot reschedule until it
+ * is ready to lose the lock.
+ *
+ * Return: 1 if we got the lock, 0 othrewise
+ */
+static int console_trylock_spinning(void)
+{
+ struct task_struct *owner = NULL;
+ bool waiter;
+ bool spin = false;
+ unsigned long flags;
+
+ if (console_trylock())
+ return 1;
+
+ printk_safe_enter_irqsave(flags);
+
+ raw_spin_lock(&console_owner_lock);
+ owner = READ_ONCE(console_owner);
+ waiter = READ_ONCE(console_waiter);
+ if (!waiter && owner && owner != current) {
+ WRITE_ONCE(console_waiter, true);
+ spin = true;
+ }
+ raw_spin_unlock(&console_owner_lock);
+
+ /*
+ * If there is an active printk() writing to the
+ * consoles, instead of having it write our data too,
+ * see if we can offload that load from the active
+ * printer, and do some printing ourselves.
+ * Go into a spin only if there isn't already a waiter
+ * spinning, and there is an active printer, and
+ * that active printer isn't us (recursive printk?).
+ */
+ if (!spin) {
+ printk_safe_exit_irqrestore(flags);
+ return 0;
+ }
+
+ /* We spin waiting for the owner to release us */
+ spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
+ /* Owner will clear console_waiter on hand off */
+ while (READ_ONCE(console_waiter))
+ cpu_relax();
+ spin_release(&console_owner_dep_map, 1, _THIS_IP_);
+
+ printk_safe_exit_irqrestore(flags);
+ /*
+ * The owner passed the console lock to us.
+ * Since we did not spin on console lock, annotate
+ * this as a trylock. Otherwise lockdep will
+ * complain.
+ */
+ mutex_acquire(&console_lock_dep_map, 0, 1, _THIS_IP_);
+
+ return 1;
+}
+
/*
* Call the console drivers, asking them to write out
* log_buf[start] to log_buf[end - 1].
return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
}
-asmlinkage int vprintk_emit(int facility, int level,
- const char *dict, size_t dictlen,
- const char *fmt, va_list args)
+/* Must be called under logbuf_lock. */
+int vprintk_store(int facility, int level,
+ const char *dict, size_t dictlen,
+ const char *fmt, va_list args)
{
static char textbuf[LOG_LINE_MAX];
char *text = textbuf;
size_t text_len;
enum log_flags lflags = 0;
- unsigned long flags;
- int this_cpu;
- int printed_len;
- bool in_sched = false;
-
- if (level == LOGLEVEL_SCHED) {
- level = LOGLEVEL_DEFAULT;
- in_sched = true;
- }
-
- boot_delay_msec(level);
- printk_delay();
-
- /* This stops the holder of console_sem just where we want him */
- logbuf_lock_irqsave(flags);
- this_cpu = smp_processor_id();
/*
* The printf needs to come first; we need the syslog
* prefix which might be passed-in as a parameter.
if (dict)
lflags |= LOG_PREFIX|LOG_NEWLINE;
- printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
+ return log_output(facility, level, lflags,
+ dict, dictlen, text, text_len);
+}
+
+asmlinkage int vprintk_emit(int facility, int level,
+ const char *dict, size_t dictlen,
+ const char *fmt, va_list args)
+{
+ int printed_len;
+ bool in_sched = false;
+ unsigned long flags;
+ if (level == LOGLEVEL_SCHED) {
+ level = LOGLEVEL_DEFAULT;
+ in_sched = true;
+ }
+
+ boot_delay_msec(level);
+ printk_delay();
+
+ /* This stops the holder of console_sem just where we want him */
+ logbuf_lock_irqsave(flags);
+ printed_len = vprintk_store(facility, level, dict, dictlen, fmt, args);
logbuf_unlock_irqrestore(flags);
/* If called from the scheduler, we can not call up(). */
if (!in_sched) {
+ /*
+ * 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.
*/
- if (console_trylock())
+ if (console_trylock_spinning())
console_unlock();
+ preempt_enable();
}
return printed_len;
static ssize_t msg_print_ext_body(char *buf, size_t size,
char *dict, size_t dict_len,
char *text, size_t text_len) { return 0; }
+static void console_lock_spinning_enable(void) { }
+static int console_lock_spinning_disable_and_check(void) { return 0; }
static void call_console_drivers(const char *ext_text, size_t ext_len,
const char *text, size_t len) {}
static size_t msg_print_text(const struct printk_log *msg,
return 0;
}
console_locked = 1;
- /*
- * When PREEMPT_COUNT disabled we can't reliably detect if it's
- * safe to schedule (e.g. calling printk while holding a spin_lock),
- * because preempt_disable()/preempt_enable() are just barriers there
- * and preempt_count() is always 0.
- *
- * RCU read sections have a separate preemption counter when
- * PREEMPT_RCU enabled thus we must take extra care and check
- * rcu_preempt_depth(), otherwise RCU read sections modify
- * preempt_count().
- */
- console_may_schedule = !oops_in_progress &&
- preemptible() &&
- !rcu_preempt_depth();
+ console_may_schedule = 0;
return 1;
}
EXPORT_SYMBOL(console_trylock);
console_seq++;
raw_spin_unlock(&logbuf_lock);
+ /*
+ * While actively printing out messages, if another printk()
+ * were to occur on another CPU, it may wait for this one to
+ * finish. This task can not be preempted if there is a
+ * waiter waiting to take over.
+ */
+ console_lock_spinning_enable();
+
stop_critical_timings(); /* don't trace print latency */
call_console_drivers(ext_text, ext_len, text, len);
start_critical_timings();
+
+ if (console_lock_spinning_disable_and_check()) {
+ printk_safe_exit_irqrestore(flags);
+ goto out;
+ }
+
printk_safe_exit_irqrestore(flags);
if (do_cond_resched)
cond_resched();
}
+
console_locked = 0;
/* Release the exclusive_console once it is used */
if (retry && console_trylock())
goto again;
+out:
if (wake_klogd)
wake_up_klogd();
}
preempt_enable();
}
-int vprintk_deferred(const char *fmt, va_list args)
+void defer_console_output(void)
{
- int r;
-
- r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
-
preempt_disable();
__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
preempt_enable();
+}
+
+int vprintk_deferred(const char *fmt, va_list args)
+{
+ int r;
+
+ r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+ defer_console_output();
return r;
}
projects / GitHub / moto-9609 / android_kernel_motorola_exynos9610.git / blobdiff