LKML Archive on lore.kernel.org
 help / color / Atom feed
From: Tetsuo Handa <penguin-kernel@i-love.sakura.ne.jp>
To: Petr Mladek <pmladek@suse.com>
Cc: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>,
	Dmitriy Vyukov <dvyukov@google.com>,
	Linus Torvalds <torvalds@linux-foundation.org>,
	Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
	Steven Rostedt <rostedt@goodmis.org>,
	Alexander Potapenko <glider@google.com>,
	kbuild test robot <fengguang.wu@intel.com>,
	syzkaller <syzkaller@googlegroups.com>,
	LKML <linux-kernel@vger.kernel.org>,
	Andrew Morton <akpm@linux-foundation.org>
Subject: Re: [PATCH] printk: inject caller information into the body of message
Date: Wed, 10 Oct 2018 19:14:57 +0900
Message-ID: <d3e76073-c896-5807-1a2d-fe320643617d@i-love.sakura.ne.jp> (raw)
In-Reply-To: <a4a2ecae-3c47-db1f-8124-4d2d0ab8b91c@i-love.sakura.ne.jp>

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


  reply index

Thread overview: 94+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
     [not found] <201804232233.CIC65675.OJSOMFQOFFHVtL@I-love.SAKURA.ne.jp>
     [not found] ` <CACT4Y+boyw_Qy=y-iTnsKZrtTgF0Hk3nHN_xtqUdX4etgiYDQw@mail.gmail.com>
2018-04-24  1:33   ` printk feature for syzbot? Sergey Senozhatsky
2018-04-24 14:40     ` Steven Rostedt
2018-04-26 10:06     ` Petr Mladek
2018-05-10  4:22       ` Sergey Senozhatsky
2018-05-10 11:30         ` Petr Mladek
2018-05-10 12:11           ` Sergey Senozhatsky
2018-05-10 14:22             ` Steven Rostedt
2018-05-10 14:50         ` Tetsuo Handa
2018-05-11  1:45           ` Sergey Senozhatsky
     [not found]             ` <201805110238.w4B2cIGH079602@www262.sakura.ne.jp>
2018-05-11  6:21               ` Sergey Senozhatsky
2018-05-11  9:17                 ` Dmitry Vyukov
2018-05-11  9:50                   ` Sergey Senozhatsky
2018-05-11 11:58                     ` [PATCH] printk: inject caller information into the body of message Tetsuo Handa
2018-05-17 11:21                       ` Sergey Senozhatsky
2018-05-17 11:52                         ` Sergey Senozhatsky
2018-05-18 12:15                         ` Petr Mladek
2018-05-18 12:25                           ` Dmitry Vyukov
2018-05-18 12:54                             ` Petr Mladek
2018-05-18 13:08                               ` Dmitry Vyukov
2018-05-24  2:21                                 ` Sergey Senozhatsky
2018-05-23 10:19                           ` Tetsuo Handa
2018-05-24  2:14                           ` Sergey Senozhatsky
2018-05-26  6:36                             ` Dmitry Vyukov
2018-06-20  5:44                               ` Dmitry Vyukov
2018-06-20  8:31                                 ` Sergey Senozhatsky
2018-06-20  8:45                                   ` Dmitry Vyukov
2018-06-20  9:06                                     ` Sergey Senozhatsky
2018-06-20  9:18                                       ` Sergey Senozhatsky
2018-06-20  9:31                                         ` Dmitry Vyukov
2018-06-20 11:07                                           ` Sergey Senozhatsky
2018-06-20 11:32                                             ` Dmitry Vyukov
2018-06-20 13:06                                               ` Sergey Senozhatsky
2018-06-22 13:06                                                 ` Tetsuo Handa
2018-06-25  1:41                                                   ` Sergey Senozhatsky
2018-06-25  9:36                                                     ` Dmitry Vyukov
2018-06-27 10:29                                                       ` Tetsuo Handa
2018-09-10 11:20                                                 ` Alexander Potapenko
2018-09-12  6:53                                                   ` Sergey Senozhatsky
2018-09-12 16:05                                                     ` Steven Rostedt
2018-09-13  7:12                                                       ` Sergey Senozhatsky
2018-09-13 12:26                                                         ` Petr Mladek
2018-09-13 14:28                                                           ` Sergey Senozhatsky
2018-09-14  1:22                                                             ` Steven Rostedt
2018-09-14  2:15                                                               ` Sergey Senozhatsky
2018-09-14  6:57                                                             ` Sergey Senozhatsky
2018-09-14 10:37                                                               ` Tetsuo Handa
2018-09-14 11:50                                                                 ` Sergey Senozhatsky
2018-09-14 12:03                                                                   ` Tetsuo Handa
2018-09-14 12:22                                                                     ` Sergey Senozhatsky
2018-09-19 11:02                                                                       ` Tetsuo Handa
2018-09-24  8:11                                                                         ` Tetsuo Handa
2018-09-27 16:10                                                                           ` Tetsuo Handa
2018-09-28  9:02                                                                             ` Sergey Senozhatsky
2018-09-28  9:09                                                                           ` Sergey Senozhatsky
2018-09-28 11:01                                                                             ` Tetsuo Handa
2018-09-29 10:51                                                                               ` Sergey Senozhatsky
2018-09-29 11:15                                                                                 ` Tetsuo Handa
2018-10-01  2:37                                                                                   ` Sergey Senozhatsky
2018-10-01  2:58                                                                                     ` Sergey Senozhatsky
2018-10-01 11:21                                                                                     ` Tetsuo Handa
2018-10-02  6:38                                                                                       ` Sergey Senozhatsky
2018-10-08 10:31                                                                                         ` Tetsuo Handa
2018-10-08 16:03                                                                                           ` Petr Mladek
2018-10-08 20:48                                                                                             ` Tetsuo Handa
2018-10-09 14:52                                                                                               ` Petr Mladek
2018-10-09 21:19                                                                                                 ` Tetsuo Handa
2018-10-10 10:14                                                                                                   ` Tetsuo Handa [this message]
2018-10-11 10:20                                                                                                     ` Tetsuo Handa
2018-10-11 13:47                                                                                                       ` Steven Rostedt
2018-10-08 15:43                                                                                         ` Petr Mladek
2018-09-28  8:56                                                                         ` Sergey Senozhatsky
2018-09-28 11:21                                                                           ` Tetsuo Handa
2018-09-29 11:13                                                                             ` Sergey Senozhatsky
2018-09-29 11:39                                                                               ` Tetsuo Handa
2018-10-01  5:52                                                                               ` Sergey Senozhatsky
2018-10-01  8:37                                                                                 ` Sergey Senozhatsky
2018-10-01 18:06                                                                               ` Steven Rostedt
2018-09-14  1:12                                                         ` Steven Rostedt
2018-09-14  1:55                                                           ` Sergey Senozhatsky
2018-06-21  8:29                                               ` Sergey Senozhatsky
2018-06-20  9:30                                       ` Dmitry Vyukov
2018-06-20 11:19                                         ` Sergey Senozhatsky
2018-06-20 11:25                                           ` Dmitry Vyukov
2018-06-20 11:37                                         ` Fengguang Wu
2018-06-20 12:31                                           ` Dmitry Vyukov
2018-06-20 12:41                                             ` Fengguang Wu
2018-06-20 12:45                                               ` Dmitry Vyukov
2018-06-20 12:48                                                 ` Fengguang Wu
2018-05-11 13:37                     ` printk feature for syzbot? Steven Rostedt
2018-05-15  5:20                       ` Sergey Senozhatsky
2018-05-15 14:39                         ` Steven Rostedt
2018-05-11 11:02                 ` [PATCH] printk: fix possible reuse of va_list variable Tetsuo Handa
2018-05-11 11:27                   ` Sergey Senozhatsky
2018-05-17 11:57                   ` Petr Mladek

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=d3e76073-c896-5807-1a2d-fe320643617d@i-love.sakura.ne.jp \
    --to=penguin-kernel@i-love.sakura.ne.jp \
    --cc=akpm@linux-foundation.org \
    --cc=dvyukov@google.com \
    --cc=fengguang.wu@intel.com \
    --cc=glider@google.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=pmladek@suse.com \
    --cc=rostedt@goodmis.org \
    --cc=sergey.senozhatsky.work@gmail.com \
    --cc=sergey.senozhatsky@gmail.com \
    --cc=syzkaller@googlegroups.com \
    --cc=torvalds@linux-foundation.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

LKML Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/lkml/0 lkml/git/0.git
	git clone --mirror https://lore.kernel.org/lkml/1 lkml/git/1.git
	git clone --mirror https://lore.kernel.org/lkml/2 lkml/git/2.git
	git clone --mirror https://lore.kernel.org/lkml/3 lkml/git/3.git
	git clone --mirror https://lore.kernel.org/lkml/4 lkml/git/4.git
	git clone --mirror https://lore.kernel.org/lkml/5 lkml/git/5.git
	git clone --mirror https://lore.kernel.org/lkml/6 lkml/git/6.git
	git clone --mirror https://lore.kernel.org/lkml/7 lkml/git/7.git
	git clone --mirror https://lore.kernel.org/lkml/8 lkml/git/8.git
	git clone --mirror https://lore.kernel.org/lkml/9 lkml/git/9.git
	git clone --mirror https://lore.kernel.org/lkml/10 lkml/git/10.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 lkml lkml/ https://lore.kernel.org/lkml \
		linux-kernel@vger.kernel.org
	public-inbox-index lkml

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-kernel


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git