On 2018/10/10 6:19, Tetsuo Handa wrote:
> Do you think that adding cmpxchg() & retry logic to this API generates better
> result than simple fallback? buffered_printk() does not add a new locking
> dependency
> is a good point of this API. Showing the backtrace (by enabling a debug
> kernel config
> option for this API) will be sufficient.
>
This is an idea for reporting out of buffers event. I would add a kernel config
option for whether to report that event. Maybe I should offload the reporting
to a workqueue context, for reporting from get_printk_context() requires that
get_printk_context() callers have to be printk()-safe, and
get_printk_context() callers might be already in vprintk_safe()/vprintk_nmi()
context even if it is possible to call printk().
include/linux/printk.h | 71 +++++++++++++++++
kernel/printk/printk.c | 201 +++++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 272 insertions(+)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index cf3eccf..bcccf1f 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -173,6 +173,36 @@ int printk_emit(int facility, int level,
asmlinkage __printf(1, 2) __cold
int printk(const char *fmt, ...);
+/*
+ * A structure for line-buffering printk() output.
+ */
+struct printk_buffer {
+ unsigned short int used; /* Valid bytes in buf[]. */
+ char buf[1024 - 32]; /* This is LOG_LINE_MAX bytes. */
+};
+/*
+ * A macro for allowing "struct printk_buffer" on stack or in .bss section.
+ *
+ * You can use this macro for allocation on stack only when you are sure that
+ * that location is never tight about stack usage, for e.g. interrupt might
+ * consume some stack from that location. You can use this macro for allocation
+ * in .bss section only when you are sure that access to this variable is
+ * appropriately serialized, for concurrent access to this variable can lead to
+ * memory corruption.
+ *
+ * If you are not sure, you should use get_printk_buffer()/put_printk_buffer()
+ * instead. You don't need to check for get_printk_buffer() == NULL, for
+ * buffered_printk()/buffered_vprintk() will fallback to printk()/vprintk()
+ * in that case.
+ */
+#define DEFINE_PRINTK_BUFFER(name) struct printk_buffer name = { }
+struct printk_buffer *get_printk_buffer(void);
+void flush_printk_buffer(struct printk_buffer *ptr);
+__printf(2, 3)
+int buffered_printk(struct printk_buffer *ptr, const char *fmt, ...);
+__printf(2, 0)
+int buffered_vprintk(struct printk_buffer *ptr, const char *fmt, va_list args);
+void put_printk_buffer(struct printk_buffer *ptr);
/*
* Special printk facility for scheduler/timekeeping use only, _DO_NOT_USE_ !
@@ -220,6 +250,30 @@ int printk(const char *s, ...)
{
return 0;
}
+struct printk_buffer {
+ char dummy; /* Not used. */
+};
+#define DEFINE_PRINTK_BUFFER(name) struct printk_buffer name
+static inline struct printk_buffer *get_printk_buffer(void)
+{
+ return NULL;
+}
+static inline __printf(2, 3)
+int buffered_printk(struct printk_buffer *ptr, const char *fmt, ...)
+{
+ return 0;
+}
+static inline __printf(2, 0)
+int buffered_vprintk(struct printk_buffer *ptr, const char *fmt, va_list args)
+{
+ return 0;
+}
+static inline void flush_printk_buffer(struct printk_buffer *ptr)
+{
+}
+static inline void put_printk_buffer(struct printk_buffer *ptr)
+{
+}
static inline __printf(1, 2) __cold
int printk_deferred(const char *s, ...)
{
@@ -300,19 +354,34 @@ static inline void printk_safe_flush_on_panic(void)
*/
#define pr_emerg(fmt, ...) \
printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_emerg(ptr, fmt, ...) \
+ buffered_printk(ptr, KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
#define pr_alert(fmt, ...) \
printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_alert(ptr, fmt, ...) \
+ buffered_printk(ptr, KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
#define pr_crit(fmt, ...) \
printk(KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_crit(ptr, fmt, ...) \
+ buffered_printk(ptr, KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
#define pr_err(fmt, ...) \
printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_err(ptr, fmt, ...) \
+ buffered_printk(ptr, KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
#define pr_warning(fmt, ...) \
printk(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_warning(ptr, fmt, ...) \
+ buffered_printk(ptr, KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
#define pr_warn pr_warning
+#define bpr_warn bpr_warning
#define pr_notice(fmt, ...) \
printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_notice(ptr, fmt, ...) \
+ buffered_printk(ptr, KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
#define pr_info(fmt, ...) \
printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
+#define bpr_info(ptr, fmt, ...) \
+ buffered_printk(ptr, KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
/*
* Like KERN_CONT, pr_cont() should only be used when continuing
* a line with no newline ('\n') enclosed. Otherwise it defaults
@@ -320,6 +389,8 @@ static inline void printk_safe_flush_on_panic(void)
*/
#define pr_cont(fmt, ...) \
printk(KERN_CONT fmt, ##__VA_ARGS__)
+#define bpr_cont(ptr, fmt, ...) \
+ buffered_printk(ptr, KERN_CONT fmt, ##__VA_ARGS__)
/* pr_devel() should produce zero code unless DEBUG is defined */
#ifdef DEBUG
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9bf5404..453db95 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1949,6 +1949,207 @@ asmlinkage int printk_emit(int facility, int level,
}
EXPORT_SYMBOL(printk_emit);
+#define MAX_PRINTK_BUFFERS 16
+static struct printk_buffer printk_buffers[MAX_PRINTK_BUFFERS];
+static DECLARE_BITMAP(printk_buffers_in_use, MAX_PRINTK_BUFFERS);
+
+/**
+ * get_printk_buffer - Try to get printk_buffer.
+ *
+ * Returns pointer to "struct printk_buffer" on success, NULL otherwise.
+ *
+ * If this function returned "struct printk_buffer", the caller is responsible
+ * for passing it to put_printk_buffer() so that "struct printk_buffer" can be
+ * reused in the future.
+ *
+ * Even if this function returned NULL, the caller does not need to check for
+ * NULL, for passing NULL to buffered_printk() simply acts like normal printk()
+ * and passing NULL to flush_printk_buffer()/put_printk_buffer() is a no-op.
+ */
+struct printk_buffer *get_printk_buffer(void)
+{
+#ifdef CONFIG_STACKTRACE
+ static unsigned long trace_entries[MAX_PRINTK_BUFFERS][20];
+ static struct stack_trace trace[MAX_PRINTK_BUFFERS];
+ static unsigned long stamp[MAX_PRINTK_BUFFERS];
+ static int reported;
+#endif
+ long i;
+
+ for (i = 0; i < MAX_PRINTK_BUFFERS; i++) {
+ if (test_bit(i, printk_buffers_in_use) ||
+ test_and_set_bit(i, printk_buffers_in_use))
+ continue;
+ printk_buffers[i].used = 0;
+#ifdef CONFIG_STACKTRACE
+ if (!reported) {
+ stamp[i] = jiffies;
+ trace[i].nr_entries = 0;
+ trace[i].entries = trace_entries[i];
+ trace[i].max_entries = 20;
+ trace[i].skip = 0;
+ save_stack_trace(&trace[i]);
+ }
+#endif
+ return &printk_buffers[i];
+ }
+#ifdef CONFIG_STACKTRACE
+ if (!cmpxchg(&reported, 0, 1)) {
+ /*
+ * Report who is reserving the buffers, for it might be due to
+ * missing put_printk_buffer() calls.
+ *
+ * Note that this report is racy.
+ * Someone might be about to call put_printk_buffer().
+ * Someone might be about to set stamp[i] to jiffies.
+ * Someone might have just set trace[i].nr_entries to 0.
+ * But it does not worth introducing a lock dependency.
+ */
+ pr_info("printk: All buffers are in use. Falling back to
unbuffered mode.\n");
+ for (i = 0; i < MAX_PRINTK_BUFFERS; i++) {
+ unsigned int j;
+
+ if (!test_bit(i, printk_buffers_in_use))
+ continue;
+ pr_info("buffer[%lu] was reserved %lu jiffies ago by\n",
+ i, jiffies - stamp[i]);
+ for (j = 0; j < trace[i].nr_entries; j++)
+ pr_info(" %pS\n", (void *)trace[i].entries[j]);
+ }
+ }
+#endif
+ return NULL;
+}
+EXPORT_SYMBOL(get_printk_buffer);
+
+/**
+ * buffered_vprintk - Try to vprintk() in line buffered mode.
+ *
+ * @ptr: Pointer to "struct printk_buffer". It can be NULL.
+ * @fmt: printk() format string.
+ * @args: va_list structure.
+ *
+ * Returns the return value of vprintk().
+ *
+ * Try to store to @ptr first. If it fails, flush @ptr and then try to store to
+ * @ptr again. If it still fails, use unbuffered printing.
+ */
+int buffered_vprintk(struct printk_buffer *ptr, const char *fmt, va_list args)
+{
+ va_list tmp_args;
+ unsigned short int i;
+ int r;
+
+ BUILD_BUG_ON(sizeof(ptr->buf) != LOG_LINE_MAX);
+ if (!ptr)
+ goto unbuffered;
+ for (i = 0; i < 2; i++) {
+ unsigned int pos = ptr->used;
+ char *text = ptr->buf + pos;
+
+ va_copy(tmp_args, args);
+ r = vsnprintf(text, sizeof(ptr->buf) - pos, fmt, tmp_args);
+ va_end(tmp_args);
+ if (r + pos < sizeof(ptr->buf)) {
+ /*
+ * Eliminate KERN_CONT at this point because we can
+ * concatenate incomplete lines inside printk_buffer.
+ */
+ if (r >= 2 && printk_get_level(text) == 'c') {
+ memmove(text, text + 2, r - 2);
+ ptr->used += r - 2;
+ } else {
+ ptr->used += r;
+ }
+ /* Flush already completed lines if any. */
+ while (1) {
+ char *cp = memchr(ptr->buf, '\n', ptr->used);
+
+ if (!cp)
+ break;
+ *cp = '\0';
+ printk("%s\n", ptr->buf);
+ i = cp - ptr->buf + 1;
+ ptr->used -= i;
+ memmove(ptr->buf, ptr->buf + i, ptr->used);
+ }
+ return r;
+ }
+ if (i)
+ break;
+ flush_printk_buffer(ptr);
+ }
+ unbuffered:
+ return vprintk(fmt, args);
+}
+
+/**
+ * buffered_printk - Try to printk() in line buffered mode.
+ *
+ * @ptr: Pointer to "struct printk_buffer". It can be NULL.
+ * @fmt: printk() format string, followed by arguments.
+ *
+ * Returns the return value of printk().
+ *
+ * Try to store to @ptr first. If it fails, flush @ptr and then try to store to
+ * @ptr again. If it still fails, use unbuffered printing.
+ */
+int buffered_printk(struct printk_buffer *ptr, const char *fmt, ...)
+{
+ va_list args;
+ int r;
+
+ va_start(args, fmt);
+ r = buffered_vprintk(ptr, fmt, args);
+ va_end(args);
+ return r;
+}
+EXPORT_SYMBOL(buffered_printk);
+
+/**
+ * flush_printk_buffer - Flush incomplete line in printk_buffer.
+ *
+ * @ptr: Pointer to "struct printk_buffer". It can be NULL.
+ *
+ * Returns nothing.
+ *
+ * Flush if @ptr contains partial data. But usually there is no need to call
+ * this function because @ptr is flushed by put_printk_buffer().
+ */
+void flush_printk_buffer(struct printk_buffer *ptr)
+{
+ if (!ptr || !ptr->used)
+ return;
+ /* buffered_vprintk() keeps 0 <= ptr->used < sizeof(ptr->buf) true. */
+ ptr->buf[ptr->used] = '\0';
+ printk("%s", ptr->buf);
+ ptr->used = 0;
+}
+EXPORT_SYMBOL(flush_printk_buffer);
+
+/**
+ * put_printk_buffer - Release printk_buffer.
+ *
+ * @ptr: Pointer to "struct printk_buffer". It can be NULL.
+ *
+ * Returns nothing.
+ *
+ * Flush and release @ptr.
+ */
+void put_printk_buffer(struct printk_buffer *ptr)
+{
+ long i = ptr - printk_buffers;
+
+ if (!ptr || i < 0 || i >= MAX_PRINTK_BUFFERS)
+ return;
+ if (ptr->used)
+ flush_printk_buffer(ptr);
+ /* Make sure in_use flag is cleared after setting ptr->used = 0. */
+ wmb();
+ clear_bit(i, printk_buffers_in_use);
+}
+EXPORT_SYMBOL(put_printk_buffer);
+
int vprintk_default(const char *fmt, va_list args)
{
int r;
--
1.8.3.1
