Re: [PATCH] printk: inject caller information into the body of message
On Thu, 11 Oct 2018 19:20:34 +0900 Tetsuo Handa wrote: > Thus, here is v4. > > >From a65f018d563928c7b7e4a9bec1d1a564dd8b4635 Mon Sep 17 00:00:00 2001 > From: Tetsuo Handa > Date: Thu, 11 Oct 2018 14:21:22 +0900 > Subject: [PATCH v4] printk: Add line-buffered printk() API. Hi Tetsuo, Can you resend this as a separate patch starting a new thread? Having v4 hidden deep in another thread makes it hard to find patches like these searching mail archives. If you want to reference back to this discussion, just add in the v4 change log: Link: https://lore.kernel.org/lkml/201805112058.aab05258.hjqffomfovt...@i-love.sakura.ne.jp/ Thanks! -- Steve
Re: [PATCH] printk: inject caller information into the body of message
On Thu, 11 Oct 2018 19:20:34 +0900 Tetsuo Handa wrote: > Thus, here is v4. > > >From a65f018d563928c7b7e4a9bec1d1a564dd8b4635 Mon Sep 17 00:00:00 2001 > From: Tetsuo Handa > Date: Thu, 11 Oct 2018 14:21:22 +0900 > Subject: [PATCH v4] printk: Add line-buffered printk() API. Hi Tetsuo, Can you resend this as a separate patch starting a new thread? Having v4 hidden deep in another thread makes it hard to find patches like these searching mail archives. If you want to reference back to this discussion, just add in the v4 change log: Link: https://lore.kernel.org/lkml/201805112058.aab05258.hjqffomfovt...@i-love.sakura.ne.jp/ Thanks! -- Steve
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/10 19:14, Tetsuo Handa wrote: > 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(). > I dropped DEFINE_PRINTK_BUFFER() in order to hide "struct printk_buffer" because I added reporting functionality for out of static "struct printk_buffer" and made that number configurable at kernel compile option. I think we can start evaluating with only static buffers. Then, we will consider whether we need to expose "struct printk_buffer" in order to allow allocating from kernel stack memory. Maybe allocating from slab memory is sufficient if someone happened to want to reserve several "struct printk_buffer" buffers for its lifetime. Thus, here is v4. >From a65f018d563928c7b7e4a9bec1d1a564dd8b4635 Mon Sep 17 00:00:00 2001 From: Tetsuo Handa Date: Thu, 11 Oct 2018 14:21:22 +0900 Subject: [PATCH v4] printk: Add line-buffered printk() API. Sometimes we want to print a whole line without being disturbed by concurrent printk() from interrupts and/or other threads, for printk() which does not end with '\n' can be disturbed. Mixed printk() output makes it hard to interpret. Assuming that we will go to a direction that we allow prefixing context identifier to each line of printk() output (so that we can group multiple lines into one block when parsing), this patch introduces API for line-buffered printk() output (so that we can make sure that printk() ends with '\n'). Since functions introduced by this patch are merely wrapping printk()/vprintk() calls in order to minimize possibility of using "struct cont", it is safe to replace printk()/vprintk() with this API. Details: A structure named "struct printk_buffer" is introduced for buffering up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'. get_printk_buffer() tries to assign a "struct printk_buffer" from statically preallocated array. get_printk_buffer() returns NULL if all "struct printk_buffer" are in use, but the caller does not need to check for NULL. put_printk_buffer() flushes and releases the "struct printk_buffer". put_printk_buffer() must match corresponding get_printk_buffer() as with rcu_read_unlock() must match corresponding rcu_read_lock(). Three functions buffered_vprintk(), buffered_printk() and flush_printk_buffer() are provided for using "struct printk_buffer". These are like vfprintf(), fprintf(), fflush() except that these receive "struct printk_buffer *" for the first argument. buffered_vprintk() and buffered_printk() behave like vprintk() and printk() respectively if "struct printk_buffer *" argument is NULL. flush_printk_buffer() and put_printk_buffer() become no-op if "struct printk_buffer *" argument is NULL. Therefore, the caller of get_printk_buffer() does not need to check for NULL. How to configure this API: For those who want to save memory footprint, this API is enabled only if CONFIG_PRINTK_LINE_BUFFERED option is selected. For those who want to tune the number of statically preallocated buffers, CONFIG_PRINTK_NUM_LINE_BUFFERS option is available. The default value is 16. Since "struct printk_buffer" makes difference only when there are multiple threads concurrently calling printk() which does not end with '\n', and this API will fallback to normal printk() when all CONFIG_PRINTK_NUM_LINE_BUFFERS buffers are in use, you won't need to specify a large number. But somebody might forget to call put_printk_buffer(). For those who want to know why all CONFIG_PRINTK_NUM_LINE_BUFFERS buffers are in use, CONFIG_PRINTK_REPORT_OUT_OF_LINE_BUFFERS option is available. This option reports when/where get_printk_buffer() was called and put_printk_buffer() is not yet called, up to once per a minute. How to use this API: (1) Call get_printk_buffer() and acquire "struct printk_buffer *". (2) Rewrite printk() calls in the following way. The "ptr" is "struct printk_buffer *" obtained in step (1). printk(fmt, ...) => buffered_printk(ptr, fmt, ...) vprintk(fmt, args) => buffered_vprintk(ptr, fmt, args) pr_emerg(fmt, ...) => bpr_emerg(ptr, fmt, ...) pr_alert(fmt, ...) => bpr_alert(ptr, fmt, ...) pr_crit(fmt, ...)=> bpr_crit(ptr, fmt, ...) pr_err(fmt, ...) =>
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/10 19:14, Tetsuo Handa wrote: > 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(). > I dropped DEFINE_PRINTK_BUFFER() in order to hide "struct printk_buffer" because I added reporting functionality for out of static "struct printk_buffer" and made that number configurable at kernel compile option. I think we can start evaluating with only static buffers. Then, we will consider whether we need to expose "struct printk_buffer" in order to allow allocating from kernel stack memory. Maybe allocating from slab memory is sufficient if someone happened to want to reserve several "struct printk_buffer" buffers for its lifetime. Thus, here is v4. >From a65f018d563928c7b7e4a9bec1d1a564dd8b4635 Mon Sep 17 00:00:00 2001 From: Tetsuo Handa Date: Thu, 11 Oct 2018 14:21:22 +0900 Subject: [PATCH v4] printk: Add line-buffered printk() API. Sometimes we want to print a whole line without being disturbed by concurrent printk() from interrupts and/or other threads, for printk() which does not end with '\n' can be disturbed. Mixed printk() output makes it hard to interpret. Assuming that we will go to a direction that we allow prefixing context identifier to each line of printk() output (so that we can group multiple lines into one block when parsing), this patch introduces API for line-buffered printk() output (so that we can make sure that printk() ends with '\n'). Since functions introduced by this patch are merely wrapping printk()/vprintk() calls in order to minimize possibility of using "struct cont", it is safe to replace printk()/vprintk() with this API. Details: A structure named "struct printk_buffer" is introduced for buffering up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'. get_printk_buffer() tries to assign a "struct printk_buffer" from statically preallocated array. get_printk_buffer() returns NULL if all "struct printk_buffer" are in use, but the caller does not need to check for NULL. put_printk_buffer() flushes and releases the "struct printk_buffer". put_printk_buffer() must match corresponding get_printk_buffer() as with rcu_read_unlock() must match corresponding rcu_read_lock(). Three functions buffered_vprintk(), buffered_printk() and flush_printk_buffer() are provided for using "struct printk_buffer". These are like vfprintf(), fprintf(), fflush() except that these receive "struct printk_buffer *" for the first argument. buffered_vprintk() and buffered_printk() behave like vprintk() and printk() respectively if "struct printk_buffer *" argument is NULL. flush_printk_buffer() and put_printk_buffer() become no-op if "struct printk_buffer *" argument is NULL. Therefore, the caller of get_printk_buffer() does not need to check for NULL. How to configure this API: For those who want to save memory footprint, this API is enabled only if CONFIG_PRINTK_LINE_BUFFERED option is selected. For those who want to tune the number of statically preallocated buffers, CONFIG_PRINTK_NUM_LINE_BUFFERS option is available. The default value is 16. Since "struct printk_buffer" makes difference only when there are multiple threads concurrently calling printk() which does not end with '\n', and this API will fallback to normal printk() when all CONFIG_PRINTK_NUM_LINE_BUFFERS buffers are in use, you won't need to specify a large number. But somebody might forget to call put_printk_buffer(). For those who want to know why all CONFIG_PRINTK_NUM_LINE_BUFFERS buffers are in use, CONFIG_PRINTK_REPORT_OUT_OF_LINE_BUFFERS option is available. This option reports when/where get_printk_buffer() was called and put_printk_buffer() is not yet called, up to once per a minute. How to use this API: (1) Call get_printk_buffer() and acquire "struct printk_buffer *". (2) Rewrite printk() calls in the following way. The "ptr" is "struct printk_buffer *" obtained in step (1). printk(fmt, ...) => buffered_printk(ptr, fmt, ...) vprintk(fmt, args) => buffered_vprintk(ptr, fmt, args) pr_emerg(fmt, ...) => bpr_emerg(ptr, fmt, ...) pr_alert(fmt, ...) => bpr_alert(ptr, fmt, ...) pr_crit(fmt, ...)=> bpr_crit(ptr, fmt, ...) pr_err(fmt, ...) =>
Re: [PATCH] printk: inject caller information into the body of message
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
Re: [PATCH] printk: inject caller information into the body of message
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
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/09 23:52, Petr Mladek wrote:
> On Tue 2018-10-09 05:48:33, Tetsuo Handa wrote:
>> On 2018/10/09 1:03, Petr Mladek wrote:
>>> On Mon 2018-10-08 19:31:58, Tetsuo Handa wrote:
A structure named "struct printk_buffer" is introduced for buffering
up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.
A caller is allowed to allocate/free "struct printk_buffer" using
kzalloc()/kfree() if that caller is in a location where it is possible
to do so.
A macro named "DEFINE_PRINTK_BUFFER()" is defined for allocating
"struct printk_buffer" from the stack memory or in the .bss section.
But since sizeof("struct printk_buffer") is nearly 1KB, it might not be
preferable to allocate "struct printk_buffer" from the stack memory.
In that case, a caller can use best-effort buffering mode. Two functions
get_printk_buffer() and put_printk_buffer() are provided for that mode.
get_printk_buffer() tries to assign a "struct printk_buffer" from
statically preallocated array. It returns NULL if all static
"struct printk_buffer" are in use.
put_printk_buffer() flushes and releases the "struct printk_buffer".
put_printk_buffer() must match corresponding get_printk_buffer() as with
rcu_read_unlock() must match corresponding rcu_read_lock().
>>>
>>> One problem with this API is when it is used in more complicated code
>>> and put_printk_buffer() is not called in some path. I mean leaking.
>>> We might get out of buffers easily.
>>
>> Then, as an debugging config option for statically preallocated buffers,
>> we could record how get_printk_buffer() was called, like lockdep records
>> where a lock was taken.
>
> Another solution might be to store some timestamp (jiffies?) into
> struct printk_buffer when a new message is added. Then we could flush
> stalled buffers in get_printk_buffer() with some warning.
I don't think it will work. What the threshold should be? It is possible that
a thread spends very long time (many seconds for e.g. SysRq-t) between
get_printk_buffer() and put_printk_buffer(). Therefore, the threshold will
have to be very very long. As soon as we reach out of statically preallocated
buffers, we need to fallback to unbuffered printk() before such threshold
elapses.
>
> Unfortunately, it might be unsafe to put the stalled buffers.
> Well, it might be safe if there is a lock less access. I wonder
> if we could reuse the printk_safe code here.
>
> Anyway, I would like to have a solution before we add the new
> API into the kernel. We would need it sooner or later anyway.
> And I would like to be sure that the API is sane.
If we worry about get_printk_buffer() without corresponding put_printk_buffer(),
we will also need to worry about a "struct printk_buffer" returned by
get_printk_buffer() is by error shared by multiple threads. We will have to
complicate buffered_printk() by using cmpxchg() & retry logic, but the output is
after all mixed as with simply fallback to unbuffered printk() does.
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.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/09 23:52, Petr Mladek wrote:
> On Tue 2018-10-09 05:48:33, Tetsuo Handa wrote:
>> On 2018/10/09 1:03, Petr Mladek wrote:
>>> On Mon 2018-10-08 19:31:58, Tetsuo Handa wrote:
A structure named "struct printk_buffer" is introduced for buffering
up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.
A caller is allowed to allocate/free "struct printk_buffer" using
kzalloc()/kfree() if that caller is in a location where it is possible
to do so.
A macro named "DEFINE_PRINTK_BUFFER()" is defined for allocating
"struct printk_buffer" from the stack memory or in the .bss section.
But since sizeof("struct printk_buffer") is nearly 1KB, it might not be
preferable to allocate "struct printk_buffer" from the stack memory.
In that case, a caller can use best-effort buffering mode. Two functions
get_printk_buffer() and put_printk_buffer() are provided for that mode.
get_printk_buffer() tries to assign a "struct printk_buffer" from
statically preallocated array. It returns NULL if all static
"struct printk_buffer" are in use.
put_printk_buffer() flushes and releases the "struct printk_buffer".
put_printk_buffer() must match corresponding get_printk_buffer() as with
rcu_read_unlock() must match corresponding rcu_read_lock().
>>>
>>> One problem with this API is when it is used in more complicated code
>>> and put_printk_buffer() is not called in some path. I mean leaking.
>>> We might get out of buffers easily.
>>
>> Then, as an debugging config option for statically preallocated buffers,
>> we could record how get_printk_buffer() was called, like lockdep records
>> where a lock was taken.
>
> Another solution might be to store some timestamp (jiffies?) into
> struct printk_buffer when a new message is added. Then we could flush
> stalled buffers in get_printk_buffer() with some warning.
I don't think it will work. What the threshold should be? It is possible that
a thread spends very long time (many seconds for e.g. SysRq-t) between
get_printk_buffer() and put_printk_buffer(). Therefore, the threshold will
have to be very very long. As soon as we reach out of statically preallocated
buffers, we need to fallback to unbuffered printk() before such threshold
elapses.
>
> Unfortunately, it might be unsafe to put the stalled buffers.
> Well, it might be safe if there is a lock less access. I wonder
> if we could reuse the printk_safe code here.
>
> Anyway, I would like to have a solution before we add the new
> API into the kernel. We would need it sooner or later anyway.
> And I would like to be sure that the API is sane.
If we worry about get_printk_buffer() without corresponding put_printk_buffer(),
we will also need to worry about a "struct printk_buffer" returned by
get_printk_buffer() is by error shared by multiple threads. We will have to
complicate buffered_printk() by using cmpxchg() & retry logic, but the output is
after all mixed as with simply fallback to unbuffered printk() does.
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.
Re: [PATCH] printk: inject caller information into the body of message
On Tue 2018-10-09 05:48:33, Tetsuo Handa wrote:
> On 2018/10/09 1:03, Petr Mladek wrote:
> > On Mon 2018-10-08 19:31:58, Tetsuo Handa wrote:
> >> A structure named "struct printk_buffer" is introduced for buffering
> >> up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.
> >>
> >> A caller is allowed to allocate/free "struct printk_buffer" using
> >> kzalloc()/kfree() if that caller is in a location where it is possible
> >> to do so.
> >>
> >> A macro named "DEFINE_PRINTK_BUFFER()" is defined for allocating
> >> "struct printk_buffer" from the stack memory or in the .bss section.
> >>
> >> But since sizeof("struct printk_buffer") is nearly 1KB, it might not be
> >> preferable to allocate "struct printk_buffer" from the stack memory.
> >> In that case, a caller can use best-effort buffering mode. Two functions
> >> get_printk_buffer() and put_printk_buffer() are provided for that mode.
> >>
> >> get_printk_buffer() tries to assign a "struct printk_buffer" from
> >> statically preallocated array. It returns NULL if all static
> >> "struct printk_buffer" are in use.
> >>
> >> put_printk_buffer() flushes and releases the "struct printk_buffer".
> >> put_printk_buffer() must match corresponding get_printk_buffer() as with
> >> rcu_read_unlock() must match corresponding rcu_read_lock().
> >
> > One problem with this API is when it is used in more complicated code
> > and put_printk_buffer() is not called in some path. I mean leaking.
> > We might get out of buffers easily.
>
> Then, as an debugging config option for statically preallocated buffers,
> we could record how get_printk_buffer() was called, like lockdep records
> where a lock was taken.
Another solution might be to store some timestamp (jiffies?) into
struct printk_buffer when a new message is added. Then we could flush
stalled buffers in get_printk_buffer() with some warning.
Unfortunately, it might be unsafe to put the stalled buffers.
Well, it might be safe if there is a lock less access. I wonder
if we could reuse the printk_safe code here.
Anyway, I would like to have a solution before we add the new
API into the kernel. We would need it sooner or later anyway.
And I would like to be sure that the API is sane.
> > A solution might be to store some information about the owner and
> > put the buffer also when a non-buffered printk is called from
> > the same context.
> >
> > It might even make it easier to use. If we are able to guess the
> > buffer by the context, we do not need to pass it as an argument.
>
> It would be nice if we can omit passing "struct printk_buffer" argument.
> But that results in "implicit contexts" which Linus has rejected
> (
> https://lkml.kernel.org/ca+55afx+5r-vfqfr7+ok9yrs2adq2ma4fz+s6ncywhy_-2m...@mail.gmail.com
> ).
Yeah and the arguments for explicit context make sense when
I reread them again.
Best Regards,
Petr
Re: [PATCH] printk: inject caller information into the body of message
On Tue 2018-10-09 05:48:33, Tetsuo Handa wrote:
> On 2018/10/09 1:03, Petr Mladek wrote:
> > On Mon 2018-10-08 19:31:58, Tetsuo Handa wrote:
> >> A structure named "struct printk_buffer" is introduced for buffering
> >> up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.
> >>
> >> A caller is allowed to allocate/free "struct printk_buffer" using
> >> kzalloc()/kfree() if that caller is in a location where it is possible
> >> to do so.
> >>
> >> A macro named "DEFINE_PRINTK_BUFFER()" is defined for allocating
> >> "struct printk_buffer" from the stack memory or in the .bss section.
> >>
> >> But since sizeof("struct printk_buffer") is nearly 1KB, it might not be
> >> preferable to allocate "struct printk_buffer" from the stack memory.
> >> In that case, a caller can use best-effort buffering mode. Two functions
> >> get_printk_buffer() and put_printk_buffer() are provided for that mode.
> >>
> >> get_printk_buffer() tries to assign a "struct printk_buffer" from
> >> statically preallocated array. It returns NULL if all static
> >> "struct printk_buffer" are in use.
> >>
> >> put_printk_buffer() flushes and releases the "struct printk_buffer".
> >> put_printk_buffer() must match corresponding get_printk_buffer() as with
> >> rcu_read_unlock() must match corresponding rcu_read_lock().
> >
> > One problem with this API is when it is used in more complicated code
> > and put_printk_buffer() is not called in some path. I mean leaking.
> > We might get out of buffers easily.
>
> Then, as an debugging config option for statically preallocated buffers,
> we could record how get_printk_buffer() was called, like lockdep records
> where a lock was taken.
Another solution might be to store some timestamp (jiffies?) into
struct printk_buffer when a new message is added. Then we could flush
stalled buffers in get_printk_buffer() with some warning.
Unfortunately, it might be unsafe to put the stalled buffers.
Well, it might be safe if there is a lock less access. I wonder
if we could reuse the printk_safe code here.
Anyway, I would like to have a solution before we add the new
API into the kernel. We would need it sooner or later anyway.
And I would like to be sure that the API is sane.
> > A solution might be to store some information about the owner and
> > put the buffer also when a non-buffered printk is called from
> > the same context.
> >
> > It might even make it easier to use. If we are able to guess the
> > buffer by the context, we do not need to pass it as an argument.
>
> It would be nice if we can omit passing "struct printk_buffer" argument.
> But that results in "implicit contexts" which Linus has rejected
> (
> https://lkml.kernel.org/ca+55afx+5r-vfqfr7+ok9yrs2adq2ma4fz+s6ncywhy_-2m...@mail.gmail.com
> ).
Yeah and the arguments for explicit context make sense when
I reread them again.
Best Regards,
Petr
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/09 1:03, Petr Mladek wrote:
> On Mon 2018-10-08 19:31:58, Tetsuo Handa wrote:
>> A structure named "struct printk_buffer" is introduced for buffering
>> up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.
>>
>> A caller is allowed to allocate/free "struct printk_buffer" using
>> kzalloc()/kfree() if that caller is in a location where it is possible
>> to do so.
>>
>> A macro named "DEFINE_PRINTK_BUFFER()" is defined for allocating
>> "struct printk_buffer" from the stack memory or in the .bss section.
>>
>> But since sizeof("struct printk_buffer") is nearly 1KB, it might not be
>> preferable to allocate "struct printk_buffer" from the stack memory.
>> In that case, a caller can use best-effort buffering mode. Two functions
>> get_printk_buffer() and put_printk_buffer() are provided for that mode.
>>
>> get_printk_buffer() tries to assign a "struct printk_buffer" from
>> statically preallocated array. It returns NULL if all static
>> "struct printk_buffer" are in use.
>>
>> put_printk_buffer() flushes and releases the "struct printk_buffer".
>> put_printk_buffer() must match corresponding get_printk_buffer() as with
>> rcu_read_unlock() must match corresponding rcu_read_lock().
>
> One problem with this API is when it is used in more complicated code
> and put_printk_buffer() is not called in some path. I mean leaking.
> We might get out of buffers easily.
Then, as an debugging config option for statically preallocated buffers,
we could record how get_printk_buffer() was called, like lockdep records
where a lock was taken.
>
> A solution might be to store some information about the owner and
> put the buffer also when a non-buffered printk is called from
> the same context.
>
> It might even make it easier to use. If we are able to guess the
> buffer by the context, we do not need to pass it as an argument.
It would be nice if we can omit passing "struct printk_buffer" argument.
But that results in "implicit contexts" which Linus has rejected
(
https://lkml.kernel.org/ca+55afx+5r-vfqfr7+ok9yrs2adq2ma4fz+s6ncywhy_-2m...@mail.gmail.com
).
>
> Well, I would like to avoid having the buffer connected with CPU.
> It would require to disable preemption in get_printk_buffer().
> IMHO, it would be a unintuitive and even unwanted side effect.
get_printk_buffer() is connected with the context who called "struct
printk_buffer".
There is no need to disable preemption.
>
> Best Regards,
> Petr
>
>
> PS: I am sorry for the late reply. I was busy with some other
> important stuff. I still have to think more about it and look
> mode deeply into the implementation.
No problem. Thank you for replying.
>
> In each case, we need to be careful about the design.
> The API has to be easy and safe to use. Also the implementation
> should not complicate the printk design too much.
>
> It looks promising. Also there is a high chance that it would
> be much more straightforward than the current code around
> the cont buffer ;-)
>
We could eventually remove "struct cont" buffer.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/09 1:03, Petr Mladek wrote:
> On Mon 2018-10-08 19:31:58, Tetsuo Handa wrote:
>> A structure named "struct printk_buffer" is introduced for buffering
>> up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.
>>
>> A caller is allowed to allocate/free "struct printk_buffer" using
>> kzalloc()/kfree() if that caller is in a location where it is possible
>> to do so.
>>
>> A macro named "DEFINE_PRINTK_BUFFER()" is defined for allocating
>> "struct printk_buffer" from the stack memory or in the .bss section.
>>
>> But since sizeof("struct printk_buffer") is nearly 1KB, it might not be
>> preferable to allocate "struct printk_buffer" from the stack memory.
>> In that case, a caller can use best-effort buffering mode. Two functions
>> get_printk_buffer() and put_printk_buffer() are provided for that mode.
>>
>> get_printk_buffer() tries to assign a "struct printk_buffer" from
>> statically preallocated array. It returns NULL if all static
>> "struct printk_buffer" are in use.
>>
>> put_printk_buffer() flushes and releases the "struct printk_buffer".
>> put_printk_buffer() must match corresponding get_printk_buffer() as with
>> rcu_read_unlock() must match corresponding rcu_read_lock().
>
> One problem with this API is when it is used in more complicated code
> and put_printk_buffer() is not called in some path. I mean leaking.
> We might get out of buffers easily.
Then, as an debugging config option for statically preallocated buffers,
we could record how get_printk_buffer() was called, like lockdep records
where a lock was taken.
>
> A solution might be to store some information about the owner and
> put the buffer also when a non-buffered printk is called from
> the same context.
>
> It might even make it easier to use. If we are able to guess the
> buffer by the context, we do not need to pass it as an argument.
It would be nice if we can omit passing "struct printk_buffer" argument.
But that results in "implicit contexts" which Linus has rejected
(
https://lkml.kernel.org/ca+55afx+5r-vfqfr7+ok9yrs2adq2ma4fz+s6ncywhy_-2m...@mail.gmail.com
).
>
> Well, I would like to avoid having the buffer connected with CPU.
> It would require to disable preemption in get_printk_buffer().
> IMHO, it would be a unintuitive and even unwanted side effect.
get_printk_buffer() is connected with the context who called "struct
printk_buffer".
There is no need to disable preemption.
>
> Best Regards,
> Petr
>
>
> PS: I am sorry for the late reply. I was busy with some other
> important stuff. I still have to think more about it and look
> mode deeply into the implementation.
No problem. Thank you for replying.
>
> In each case, we need to be careful about the design.
> The API has to be easy and safe to use. Also the implementation
> should not complicate the printk design too much.
>
> It looks promising. Also there is a high chance that it would
> be much more straightforward than the current code around
> the cont buffer ;-)
>
We could eventually remove "struct cont" buffer.
Re: [PATCH] printk: inject caller information into the body of message
On Mon 2018-10-08 19:31:58, Tetsuo Handa wrote:
> On 2018/10/02 15:38, Sergey Senozhatsky wrote:
> > I have sketched a very silly, quick-and-dirty implementation using
> > struct cont. It derives all the good features of the existing pr_cont.
> > I didn't spend enough time on this. It's just a sketch... which compiles
> > and that's it.
>
> Sergey and I had off-list discussion about an implementation above. But
> I concluded that I should update my version than updating Sergey's sketch.
>
> The origin ( https://groups.google.com/forum/#!topic/syzkaller/ttZehjXiHTU )
> is
> how to prefix caller information to each line of printk() messages so that
> syzbot
> can group messages from each context and do the better processing.
>
> We know that Linus has refused injecting extra data into message body
> (
> https://lkml.kernel.org/r/ca+55afynkjsl1nnzbx6m1ie2hjzaggk09rar5-haz4ep2ew...@mail.gmail.com
> )
>
> On 2017/09/18 0:35, Linus Torvalds wrote:
> > On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
> > wrote:
> >>
> >> so... I think we don't have to update 'struct printk_log'. we can store
> >> that "extended data" at the beginning of every message, right after the
> >> prefix.
> >
> > No, we really can't. That just means that all the tools would have to
> > be changed to get the normal messages without the extra crud. And
> > since it will have lost the difference, that's not even easy to do.
> >
> > So this is exactly the wrong way around.
> >
> > If people want to see the extra data, it really should be extra data
> > that you can get with a new interface from the kernel logs. Not a
> > "let's just a add it to all lines and make every line uglier and
> > harder to read.
> >
> > Linus
>
> but we also know that syzbot cannot count on a new interface
> (
> https://lkml.kernel.org/r/CACT4Y+aFO+yZ7ovkxJOJfz=jgse3yr+ywlq9kvurohymbgf...@mail.gmail.com
> )
>
> On 2018/05/18 22:08, Dmitry Vyukov wrote:
> > On Fri, May 18, 2018 at 2:54 PM, Petr Mladek wrote:
> >> On Fri 2018-05-18 14:25:57, Dmitry Vyukov wrote:
> On Thu 2018-05-17 20:21:35, Sergey Senozhatsky wrote:
> > Dunno...
> > For instance, can we store context tracking info as a extended record
> > data? We have that dict/dict_len thing. So may we can store tracking
> > info there? Extended records will appear on the serial console /* if
> > console supports extended data */ or can be read in via
> devkmsg_read().
> >>>
> >>> What consoles do support it?
> >>> We are interested at least in qemu console, GCE console and Android
> >>> phone consoles. But it would be pity if this can't be used on various
> >>> development boards too.
> >>
> >> Only the netconsole is able to show the extended (dict)
> >> information at the moment. Search for CON_EXTENDED flag.
> >
> > Then we won't be able to use it. And we can't pipe from devkmsg_read
> > in user-space, because we need this to work when kernel is broken in
> > various ways...
>
> and we have to allow normal consoles to inject caller information into message
> body. Since syzbot can modify kernel configurations and kernel boot command
> line options, if Linus permits, we can enable injecting caller information to
> only syzbot environments.
>
> Regarding a concern Linus mentioned
> (
> https://lkml.kernel.org/r/CA+55aFwmwdY_mMqdEyFPpRhCKRyeqj=+acqe5nn108v8elf...@mail.gmail.com
> ),
> we would be able to convert
>
> printk("Testing feature XYZ..");
> this_may_blow_up_because_of_hw_bugs();
> printk(KERN_CONT " ... ok\n");
>
> to
>
> printk("Testing feature XYZ..\n");
> this_may_blow_up_because_of_hw_bugs();
> printk("... feature XYZ ok\n");
>
> and eventually remove pr_cont/printk(KERN_CONT) support (i.e. printk() will
> always
> emit '\n').
>
>
>
> >From df59a431b1af3bdc9a90d03f1a9d63a12c3e Mon Sep 17 00:00:00 2001
> From: Tetsuo Handa
> Date: Sun, 7 Oct 2018 10:20:38 +0900
> Subject: [PATCH v3] printk: Add line-buffered printk() API.
>
> Sometimes we want to print a whole line without being disturbed by
> concurrent printk() from interrupts and/or other threads, for printk()
> which does not end with '\n' can be disturbed.
>
> Mixed printk() output makes it hard to interpret. Assuming that we will go
> to a direction that we allow prefixing context identifier to each line of
> printk() output (so that we can group multiple lines into one block when
> parsing), this patch introduces API for line-buffered printk() output
> (so that we can make sure that printk() ends with '\n').
>
> Since functions introduced by this patch are merely wrapping
> printk()/vprintk() calls in order to minimize possibility of using
> "struct cont", it is safe to replace printk()/vprintk() with this API.
>
> Details:
>
> A structure named "struct printk_buffer" is introduced for buffering
> up to LOG_LINE_MAX bytes of printk() output which
Re: [PATCH] printk: inject caller information into the body of message
On Mon 2018-10-08 19:31:58, Tetsuo Handa wrote:
> On 2018/10/02 15:38, Sergey Senozhatsky wrote:
> > I have sketched a very silly, quick-and-dirty implementation using
> > struct cont. It derives all the good features of the existing pr_cont.
> > I didn't spend enough time on this. It's just a sketch... which compiles
> > and that's it.
>
> Sergey and I had off-list discussion about an implementation above. But
> I concluded that I should update my version than updating Sergey's sketch.
>
> The origin ( https://groups.google.com/forum/#!topic/syzkaller/ttZehjXiHTU )
> is
> how to prefix caller information to each line of printk() messages so that
> syzbot
> can group messages from each context and do the better processing.
>
> We know that Linus has refused injecting extra data into message body
> (
> https://lkml.kernel.org/r/ca+55afynkjsl1nnzbx6m1ie2hjzaggk09rar5-haz4ep2ew...@mail.gmail.com
> )
>
> On 2017/09/18 0:35, Linus Torvalds wrote:
> > On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
> > wrote:
> >>
> >> so... I think we don't have to update 'struct printk_log'. we can store
> >> that "extended data" at the beginning of every message, right after the
> >> prefix.
> >
> > No, we really can't. That just means that all the tools would have to
> > be changed to get the normal messages without the extra crud. And
> > since it will have lost the difference, that's not even easy to do.
> >
> > So this is exactly the wrong way around.
> >
> > If people want to see the extra data, it really should be extra data
> > that you can get with a new interface from the kernel logs. Not a
> > "let's just a add it to all lines and make every line uglier and
> > harder to read.
> >
> > Linus
>
> but we also know that syzbot cannot count on a new interface
> (
> https://lkml.kernel.org/r/CACT4Y+aFO+yZ7ovkxJOJfz=jgse3yr+ywlq9kvurohymbgf...@mail.gmail.com
> )
>
> On 2018/05/18 22:08, Dmitry Vyukov wrote:
> > On Fri, May 18, 2018 at 2:54 PM, Petr Mladek wrote:
> >> On Fri 2018-05-18 14:25:57, Dmitry Vyukov wrote:
> On Thu 2018-05-17 20:21:35, Sergey Senozhatsky wrote:
> > Dunno...
> > For instance, can we store context tracking info as a extended record
> > data? We have that dict/dict_len thing. So may we can store tracking
> > info there? Extended records will appear on the serial console /* if
> > console supports extended data */ or can be read in via
> devkmsg_read().
> >>>
> >>> What consoles do support it?
> >>> We are interested at least in qemu console, GCE console and Android
> >>> phone consoles. But it would be pity if this can't be used on various
> >>> development boards too.
> >>
> >> Only the netconsole is able to show the extended (dict)
> >> information at the moment. Search for CON_EXTENDED flag.
> >
> > Then we won't be able to use it. And we can't pipe from devkmsg_read
> > in user-space, because we need this to work when kernel is broken in
> > various ways...
>
> and we have to allow normal consoles to inject caller information into message
> body. Since syzbot can modify kernel configurations and kernel boot command
> line options, if Linus permits, we can enable injecting caller information to
> only syzbot environments.
>
> Regarding a concern Linus mentioned
> (
> https://lkml.kernel.org/r/CA+55aFwmwdY_mMqdEyFPpRhCKRyeqj=+acqe5nn108v8elf...@mail.gmail.com
> ),
> we would be able to convert
>
> printk("Testing feature XYZ..");
> this_may_blow_up_because_of_hw_bugs();
> printk(KERN_CONT " ... ok\n");
>
> to
>
> printk("Testing feature XYZ..\n");
> this_may_blow_up_because_of_hw_bugs();
> printk("... feature XYZ ok\n");
>
> and eventually remove pr_cont/printk(KERN_CONT) support (i.e. printk() will
> always
> emit '\n').
>
>
>
> >From df59a431b1af3bdc9a90d03f1a9d63a12c3e Mon Sep 17 00:00:00 2001
> From: Tetsuo Handa
> Date: Sun, 7 Oct 2018 10:20:38 +0900
> Subject: [PATCH v3] printk: Add line-buffered printk() API.
>
> Sometimes we want to print a whole line without being disturbed by
> concurrent printk() from interrupts and/or other threads, for printk()
> which does not end with '\n' can be disturbed.
>
> Mixed printk() output makes it hard to interpret. Assuming that we will go
> to a direction that we allow prefixing context identifier to each line of
> printk() output (so that we can group multiple lines into one block when
> parsing), this patch introduces API for line-buffered printk() output
> (so that we can make sure that printk() ends with '\n').
>
> Since functions introduced by this patch are merely wrapping
> printk()/vprintk() calls in order to minimize possibility of using
> "struct cont", it is safe to replace printk()/vprintk() with this API.
>
> Details:
>
> A structure named "struct printk_buffer" is introduced for buffering
> up to LOG_LINE_MAX bytes of printk() output which
Re: [PATCH] printk: inject caller information into the body of message
On Tue 2018-10-02 15:38:51, Sergey Senozhatsky wrote: > On (10/01/18 20:21), Tetsuo Handa wrote: > > Maybe "struct printk_buffer" after all becomes identical to "struct cont". > > But > > I guess that even 16 printk_buffer-s is practically sufficient for 1024 CPUs > > system, and allocating NR_CPUS printk_buffer-s will be too wasteful. > > NR_CPUS buffers is quite a lot, indeed. Maybe we can do something like > NR_CPUS/4 + 1, etc. Kconfig option will be super hard to get right for > distributions. If people who wrote the code didn't agree on the correct > number of buffers and passed it to the distributions, then it's a good > sign than distributions will have problems picking up the good number as > well. I am afraid that only some testing or real life experience might tell us what number is good enough. The good thing is that it could only be better than the current state when we have only one cont buffer. Also I would not be so much afraid of the per-cpu buffer. We already use 16kB per-CPU for printk_safe and printk_nmi. One more kB should no be that big deal. Best Regards, Petr
Re: [PATCH] printk: inject caller information into the body of message
On Tue 2018-10-02 15:38:51, Sergey Senozhatsky wrote: > On (10/01/18 20:21), Tetsuo Handa wrote: > > Maybe "struct printk_buffer" after all becomes identical to "struct cont". > > But > > I guess that even 16 printk_buffer-s is practically sufficient for 1024 CPUs > > system, and allocating NR_CPUS printk_buffer-s will be too wasteful. > > NR_CPUS buffers is quite a lot, indeed. Maybe we can do something like > NR_CPUS/4 + 1, etc. Kconfig option will be super hard to get right for > distributions. If people who wrote the code didn't agree on the correct > number of buffers and passed it to the distributions, then it's a good > sign than distributions will have problems picking up the good number as > well. I am afraid that only some testing or real life experience might tell us what number is good enough. The good thing is that it could only be better than the current state when we have only one cont buffer. Also I would not be so much afraid of the per-cpu buffer. We already use 16kB per-CPU for printk_safe and printk_nmi. One more kB should no be that big deal. Best Regards, Petr
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/02 15:38, Sergey Senozhatsky wrote:
> I have sketched a very silly, quick-and-dirty implementation using
> struct cont. It derives all the good features of the existing pr_cont.
> I didn't spend enough time on this. It's just a sketch... which compiles
> and that's it.
Sergey and I had off-list discussion about an implementation above. But
I concluded that I should update my version than updating Sergey's sketch.
The origin ( https://groups.google.com/forum/#!topic/syzkaller/ttZehjXiHTU ) is
how to prefix caller information to each line of printk() messages so that
syzbot
can group messages from each context and do the better processing.
We know that Linus has refused injecting extra data into message body
(
https://lkml.kernel.org/r/ca+55afynkjsl1nnzbx6m1ie2hjzaggk09rar5-haz4ep2ew...@mail.gmail.com
)
On 2017/09/18 0:35, Linus Torvalds wrote:
> On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
> wrote:
>>
>> so... I think we don't have to update 'struct printk_log'. we can store
>> that "extended data" at the beginning of every message, right after the
>> prefix.
>
> No, we really can't. That just means that all the tools would have to
> be changed to get the normal messages without the extra crud. And
> since it will have lost the difference, that's not even easy to do.
>
> So this is exactly the wrong way around.
>
> If people want to see the extra data, it really should be extra data
> that you can get with a new interface from the kernel logs. Not a
> "let's just a add it to all lines and make every line uglier and
> harder to read.
>
> Linus
but we also know that syzbot cannot count on a new interface
(
https://lkml.kernel.org/r/CACT4Y+aFO+yZ7ovkxJOJfz=jgse3yr+ywlq9kvurohymbgf...@mail.gmail.com
)
On 2018/05/18 22:08, Dmitry Vyukov wrote:
> On Fri, May 18, 2018 at 2:54 PM, Petr Mladek wrote:
>> On Fri 2018-05-18 14:25:57, Dmitry Vyukov wrote:
On Thu 2018-05-17 20:21:35, Sergey Senozhatsky wrote:
> Dunno...
> For instance, can we store context tracking info as a extended record
> data? We have that dict/dict_len thing. So may we can store tracking
> info there? Extended records will appear on the serial console /* if
> console supports extended data */ or can be read in via devkmsg_read().
>>>
>>> What consoles do support it?
>>> We are interested at least in qemu console, GCE console and Android
>>> phone consoles. But it would be pity if this can't be used on various
>>> development boards too.
>>
>> Only the netconsole is able to show the extended (dict)
>> information at the moment. Search for CON_EXTENDED flag.
>
> Then we won't be able to use it. And we can't pipe from devkmsg_read
> in user-space, because we need this to work when kernel is broken in
> various ways...
and we have to allow normal consoles to inject caller information into message
body. Since syzbot can modify kernel configurations and kernel boot command
line options, if Linus permits, we can enable injecting caller information to
only syzbot environments.
Regarding a concern Linus mentioned
(
https://lkml.kernel.org/r/CA+55aFwmwdY_mMqdEyFPpRhCKRyeqj=+acqe5nn108v8elf...@mail.gmail.com
),
we would be able to convert
printk("Testing feature XYZ..");
this_may_blow_up_because_of_hw_bugs();
printk(KERN_CONT " ... ok\n");
to
printk("Testing feature XYZ..\n");
this_may_blow_up_because_of_hw_bugs();
printk("... feature XYZ ok\n");
and eventually remove pr_cont/printk(KERN_CONT) support (i.e. printk() will
always
emit '\n').
>From df59a431b1af3bdc9a90d03f1a9d63a12c3e Mon Sep 17 00:00:00 2001
From: Tetsuo Handa
Date: Sun, 7 Oct 2018 10:20:38 +0900
Subject: [PATCH v3] printk: Add line-buffered printk() API.
Sometimes we want to print a whole line without being disturbed by
concurrent printk() from interrupts and/or other threads, for printk()
which does not end with '\n' can be disturbed.
Mixed printk() output makes it hard to interpret. Assuming that we will go
to a direction that we allow prefixing context identifier to each line of
printk() output (so that we can group multiple lines into one block when
parsing), this patch introduces API for line-buffered printk() output
(so that we can make sure that printk() ends with '\n').
Since functions introduced by this patch are merely wrapping
printk()/vprintk() calls in order to minimize possibility of using
"struct cont", it is safe to replace printk()/vprintk() with this API.
Details:
A structure named "struct printk_buffer" is introduced for buffering
up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.
A caller is allowed to allocate/free "struct printk_buffer" using
kzalloc()/kfree() if that caller is in a location where it is possible
to do so.
A macro named "DEFINE_PRINTK_BUFFER()" is defined for allocating
"struct printk_buffer" from the stack
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/02 15:38, Sergey Senozhatsky wrote:
> I have sketched a very silly, quick-and-dirty implementation using
> struct cont. It derives all the good features of the existing pr_cont.
> I didn't spend enough time on this. It's just a sketch... which compiles
> and that's it.
Sergey and I had off-list discussion about an implementation above. But
I concluded that I should update my version than updating Sergey's sketch.
The origin ( https://groups.google.com/forum/#!topic/syzkaller/ttZehjXiHTU ) is
how to prefix caller information to each line of printk() messages so that
syzbot
can group messages from each context and do the better processing.
We know that Linus has refused injecting extra data into message body
(
https://lkml.kernel.org/r/ca+55afynkjsl1nnzbx6m1ie2hjzaggk09rar5-haz4ep2ew...@mail.gmail.com
)
On 2017/09/18 0:35, Linus Torvalds wrote:
> On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
> wrote:
>>
>> so... I think we don't have to update 'struct printk_log'. we can store
>> that "extended data" at the beginning of every message, right after the
>> prefix.
>
> No, we really can't. That just means that all the tools would have to
> be changed to get the normal messages without the extra crud. And
> since it will have lost the difference, that's not even easy to do.
>
> So this is exactly the wrong way around.
>
> If people want to see the extra data, it really should be extra data
> that you can get with a new interface from the kernel logs. Not a
> "let's just a add it to all lines and make every line uglier and
> harder to read.
>
> Linus
but we also know that syzbot cannot count on a new interface
(
https://lkml.kernel.org/r/CACT4Y+aFO+yZ7ovkxJOJfz=jgse3yr+ywlq9kvurohymbgf...@mail.gmail.com
)
On 2018/05/18 22:08, Dmitry Vyukov wrote:
> On Fri, May 18, 2018 at 2:54 PM, Petr Mladek wrote:
>> On Fri 2018-05-18 14:25:57, Dmitry Vyukov wrote:
On Thu 2018-05-17 20:21:35, Sergey Senozhatsky wrote:
> Dunno...
> For instance, can we store context tracking info as a extended record
> data? We have that dict/dict_len thing. So may we can store tracking
> info there? Extended records will appear on the serial console /* if
> console supports extended data */ or can be read in via devkmsg_read().
>>>
>>> What consoles do support it?
>>> We are interested at least in qemu console, GCE console and Android
>>> phone consoles. But it would be pity if this can't be used on various
>>> development boards too.
>>
>> Only the netconsole is able to show the extended (dict)
>> information at the moment. Search for CON_EXTENDED flag.
>
> Then we won't be able to use it. And we can't pipe from devkmsg_read
> in user-space, because we need this to work when kernel is broken in
> various ways...
and we have to allow normal consoles to inject caller information into message
body. Since syzbot can modify kernel configurations and kernel boot command
line options, if Linus permits, we can enable injecting caller information to
only syzbot environments.
Regarding a concern Linus mentioned
(
https://lkml.kernel.org/r/CA+55aFwmwdY_mMqdEyFPpRhCKRyeqj=+acqe5nn108v8elf...@mail.gmail.com
),
we would be able to convert
printk("Testing feature XYZ..");
this_may_blow_up_because_of_hw_bugs();
printk(KERN_CONT " ... ok\n");
to
printk("Testing feature XYZ..\n");
this_may_blow_up_because_of_hw_bugs();
printk("... feature XYZ ok\n");
and eventually remove pr_cont/printk(KERN_CONT) support (i.e. printk() will
always
emit '\n').
>From df59a431b1af3bdc9a90d03f1a9d63a12c3e Mon Sep 17 00:00:00 2001
From: Tetsuo Handa
Date: Sun, 7 Oct 2018 10:20:38 +0900
Subject: [PATCH v3] printk: Add line-buffered printk() API.
Sometimes we want to print a whole line without being disturbed by
concurrent printk() from interrupts and/or other threads, for printk()
which does not end with '\n' can be disturbed.
Mixed printk() output makes it hard to interpret. Assuming that we will go
to a direction that we allow prefixing context identifier to each line of
printk() output (so that we can group multiple lines into one block when
parsing), this patch introduces API for line-buffered printk() output
(so that we can make sure that printk() ends with '\n').
Since functions introduced by this patch are merely wrapping
printk()/vprintk() calls in order to minimize possibility of using
"struct cont", it is safe to replace printk()/vprintk() with this API.
Details:
A structure named "struct printk_buffer" is introduced for buffering
up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.
A caller is allowed to allocate/free "struct printk_buffer" using
kzalloc()/kfree() if that caller is in a location where it is possible
to do so.
A macro named "DEFINE_PRINTK_BUFFER()" is defined for allocating
"struct printk_buffer" from the stack
Re: [PATCH] printk: inject caller information into the body of message
On (10/01/18 20:21), Tetsuo Handa wrote:
> >> Because there is no guarantee that memory information is dumped under the
> >> oom_lock mutex. The oom_lock is held when calling out_of_memory(), and it
> >> cannot be held when reporting GFP_ATOMIC memory allocation failures.
> >
> > IOW, static pr_line buffer needs additional synchronization for OOM.
> > Correct?
>
> Yes (assuming that your OOM refer to both out_of_memory() and warn_alloc()).
Yes, both out_of_memory() and warn_alloc().
> By the way, only up to two threads (the active printer thread and a thread
> which is marked as console_waiter) can stall inside printk(), doesn't it?
Correct.
> Then, can you imagine a situation where 1024 (NR_CPUS) threads are stalling
> inside printk() waiting for flush?
No, not really. Both console_sem owner and waiter should spin outside of
logbuf_lock, so other CPUs can flush/log_store() in the meantime.
> Maybe "struct printk_buffer" after all becomes identical to "struct cont". But
> I guess that even 16 printk_buffer-s is practically sufficient for 1024 CPUs
> system, and allocating NR_CPUS printk_buffer-s will be too wasteful.
NR_CPUS buffers is quite a lot, indeed. Maybe we can do something like
NR_CPUS/4 + 1, etc. Kconfig option will be super hard to get right for
distributions. If people who wrote the code didn't agree on the correct
number of buffers and passed it to the distributions, then it's a good
sign than distributions will have problems picking up the good number as
well.
I'm not experienced enough, and need more opinions here.
I have sketched a very silly, quick-and-dirty implementation using
struct cont. It derives all the good features of the existing pr_cont.
I didn't spend enough time on this. It's just a sketch... which compiles
and that's it.
> I'm saying that I don't like discarding overflowed part because you are
> using seq_buf_vprintf() which just marks "overflowed" rather than
> "flush incomplete line" and "store the new data".
[..]
> Your DEFINE_PR_LINE() is limiting to far smaller than LOG_LINE_MAX.
Yes, you are right, and I was wrong about it (like I said in my email
elsewhere).
The existing cont support is "special", apparently. And it does automatic
flushing and split cont line in separate records when the cont buffer is
about of overflow. So the following loop can pr_cont() more than 1024 bytes
in total:
for (..)
pr_cont(.);
pr_cont("\n");
Thus new API should have exactly the same characteristics/guarantees. Agreed.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (10/01/18 20:21), Tetsuo Handa wrote:
> >> Because there is no guarantee that memory information is dumped under the
> >> oom_lock mutex. The oom_lock is held when calling out_of_memory(), and it
> >> cannot be held when reporting GFP_ATOMIC memory allocation failures.
> >
> > IOW, static pr_line buffer needs additional synchronization for OOM.
> > Correct?
>
> Yes (assuming that your OOM refer to both out_of_memory() and warn_alloc()).
Yes, both out_of_memory() and warn_alloc().
> By the way, only up to two threads (the active printer thread and a thread
> which is marked as console_waiter) can stall inside printk(), doesn't it?
Correct.
> Then, can you imagine a situation where 1024 (NR_CPUS) threads are stalling
> inside printk() waiting for flush?
No, not really. Both console_sem owner and waiter should spin outside of
logbuf_lock, so other CPUs can flush/log_store() in the meantime.
> Maybe "struct printk_buffer" after all becomes identical to "struct cont". But
> I guess that even 16 printk_buffer-s is practically sufficient for 1024 CPUs
> system, and allocating NR_CPUS printk_buffer-s will be too wasteful.
NR_CPUS buffers is quite a lot, indeed. Maybe we can do something like
NR_CPUS/4 + 1, etc. Kconfig option will be super hard to get right for
distributions. If people who wrote the code didn't agree on the correct
number of buffers and passed it to the distributions, then it's a good
sign than distributions will have problems picking up the good number as
well.
I'm not experienced enough, and need more opinions here.
I have sketched a very silly, quick-and-dirty implementation using
struct cont. It derives all the good features of the existing pr_cont.
I didn't spend enough time on this. It's just a sketch... which compiles
and that's it.
> I'm saying that I don't like discarding overflowed part because you are
> using seq_buf_vprintf() which just marks "overflowed" rather than
> "flush incomplete line" and "store the new data".
[..]
> Your DEFINE_PR_LINE() is limiting to far smaller than LOG_LINE_MAX.
Yes, you are right, and I was wrong about it (like I said in my email
elsewhere).
The existing cont support is "special", apparently. And it does automatic
flushing and split cont line in separate records when the cont buffer is
about of overflow. So the following loop can pr_cont() more than 1024 bytes
in total:
for (..)
pr_cont(.);
pr_cont("\n");
Thus new API should have exactly the same characteristics/guarantees. Agreed.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On Sat, 29 Sep 2018 20:13:17 +0900
Sergey Senozhatsky wrote:
> On (09/28/18 20:21), Tetsuo Handa wrote:
> > On 2018/09/28 17:56, Sergey Senozhatsky wrote:
> > > The good thing about cont buffer is that we flush it on panic. E.g.
> > > core/arch early boot stage can do:
> > >
> > > pr_cont("going to call early_init_foo()...");
> > > early_init_foo();
> > > pr_cont("OK\n");
> > >
> >
> > Is printing
> >
> > going to call early_init_foo()...OK
> >
> > in one line so critically important?
>
Yes. My testing infrastructure tests for this on boot up for the ftrace
self tests.
-- Steve
Re: [PATCH] printk: inject caller information into the body of message
On Sat, 29 Sep 2018 20:13:17 +0900
Sergey Senozhatsky wrote:
> On (09/28/18 20:21), Tetsuo Handa wrote:
> > On 2018/09/28 17:56, Sergey Senozhatsky wrote:
> > > The good thing about cont buffer is that we flush it on panic. E.g.
> > > core/arch early boot stage can do:
> > >
> > > pr_cont("going to call early_init_foo()...");
> > > early_init_foo();
> > > pr_cont("OK\n");
> > >
> >
> > Is printing
> >
> > going to call early_init_foo()...OK
> >
> > in one line so critically important?
>
Yes. My testing infrastructure tests for this on boot up for the ftrace
self tests.
-- Steve
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/01 11:37, Sergey Senozhatsky wrote: > On (09/29/18 20:15), Tetsuo Handa wrote: >> >> Because there is no guarantee that memory information is dumped under the >> oom_lock mutex. The oom_lock is held when calling out_of_memory(), and it >> cannot be held when reporting GFP_ATOMIC memory allocation failures. > > IOW, static pr_line buffer needs additional synchronization for OOM. Correct? Yes (assuming that your OOM refer to both out_of_memory() and warn_alloc()). And since warn_alloc() might be called from atomic/intrrupt contexts, we can't use locks for synchronization. > > If we are about to have a list of printk buffers then we probably can > define a list of NR_CPUS cont buffers. And we probably can reuse the > existing struct cont for buffered printk, having 2 different struct-s > for the same thing - struct cont and struct printk_buffer - is not very > cool. My plan is to remove "struct cont" after most of KERN_CONT users are converted to use buffered_printk(). There will be 2 different struct-s only during transition period. By the way, only up to two threads (the active printer thread and a thread which is marked as console_waiter) can stall inside printk(), doesn't it? Then, can you imagine a situation where 1024 (NR_CPUS) threads are stalling inside printk() waiting for flush? Such system is already dead. All callers but the two should release printk_buffer as soon as their printk() added their message to the log buffer. Maybe "struct printk_buffer" after all becomes identical to "struct cont". But I guess that even 16 printk_buffer-s is practically sufficient for 1024 CPUs system, and allocating NR_CPUS printk_buffer-s will be too wasteful. > >> But I don't want line buffered printk() API to truncate upon out of >> space for line buffered printk() API. > > All printk()-s are limited by LOG_LINE_MAX. Buffered printk() is not > special. I'm saying that I don't like discarding overflowed part because you are using seq_buf_vprintf() which just marks "overflowed" rather than "flush incomplete line" and "store the new data". DEFINE_PR_LINE(pr); pr_line(, "1234567890123456789012345678901234567890123456789012345678901234567890"); pr_line(, "1234567890abcde\n"); will discard "1234567890abcde\n" part, won't it? I think that getting 1234567890123456789012345678901234567890123456789012345678901234567890\n 1234567890abcde\n is better than getting 1234567890123456789012345678901234567890123456789012345678901234567890\n because we can still understand such output by prefixing caller information. Your DEFINE_PR_LINE() is limiting to far smaller than LOG_LINE_MAX. Since your version has to worry about "buffer full" (i.e. hitting seq_buf_set_overflow()) case, it might become a headache for API users.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/10/01 11:37, Sergey Senozhatsky wrote: > On (09/29/18 20:15), Tetsuo Handa wrote: >> >> Because there is no guarantee that memory information is dumped under the >> oom_lock mutex. The oom_lock is held when calling out_of_memory(), and it >> cannot be held when reporting GFP_ATOMIC memory allocation failures. > > IOW, static pr_line buffer needs additional synchronization for OOM. Correct? Yes (assuming that your OOM refer to both out_of_memory() and warn_alloc()). And since warn_alloc() might be called from atomic/intrrupt contexts, we can't use locks for synchronization. > > If we are about to have a list of printk buffers then we probably can > define a list of NR_CPUS cont buffers. And we probably can reuse the > existing struct cont for buffered printk, having 2 different struct-s > for the same thing - struct cont and struct printk_buffer - is not very > cool. My plan is to remove "struct cont" after most of KERN_CONT users are converted to use buffered_printk(). There will be 2 different struct-s only during transition period. By the way, only up to two threads (the active printer thread and a thread which is marked as console_waiter) can stall inside printk(), doesn't it? Then, can you imagine a situation where 1024 (NR_CPUS) threads are stalling inside printk() waiting for flush? Such system is already dead. All callers but the two should release printk_buffer as soon as their printk() added their message to the log buffer. Maybe "struct printk_buffer" after all becomes identical to "struct cont". But I guess that even 16 printk_buffer-s is practically sufficient for 1024 CPUs system, and allocating NR_CPUS printk_buffer-s will be too wasteful. > >> But I don't want line buffered printk() API to truncate upon out of >> space for line buffered printk() API. > > All printk()-s are limited by LOG_LINE_MAX. Buffered printk() is not > special. I'm saying that I don't like discarding overflowed part because you are using seq_buf_vprintf() which just marks "overflowed" rather than "flush incomplete line" and "store the new data". DEFINE_PR_LINE(pr); pr_line(, "1234567890123456789012345678901234567890123456789012345678901234567890"); pr_line(, "1234567890abcde\n"); will discard "1234567890abcde\n" part, won't it? I think that getting 1234567890123456789012345678901234567890123456789012345678901234567890\n 1234567890abcde\n is better than getting 1234567890123456789012345678901234567890123456789012345678901234567890\n because we can still understand such output by prefixing caller information. Your DEFINE_PR_LINE() is limiting to far smaller than LOG_LINE_MAX. Since your version has to worry about "buffer full" (i.e. hitting seq_buf_set_overflow()) case, it might become a headache for API users.
Re: [PATCH] printk: inject caller information into the body of message
On (10/01/18 14:52), Sergey Senozhatsky wrote:
> On (09/29/18 20:13), Sergey Senozhatsky wrote:
> > We used to flush "incomplete" cont lines (fragments) from console_unlock().
> >
> > void console_unlock(void)
> > {
> > ...
> > /* flush buffered message fragment immediately to console */
> > console_cont_flush(text, sizeof(text));
> > again:
> > for (;;) {
> > ...
> > }
> > ...
> > }
> >
> > Unless I'm missing something, we don't anymore.
> > Since 5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb.
> > Now we print only log_buf entries. So we either wait for a \n to flush
> > a complete cont buffer, or for a race to preliminary flush cont buffer.
>
> BTW, it just crossed my mind:
One more thing.
Since we don't print cont fragments to the consoles anymore, do we still
need the "extended consoles disable kernel cont support" thing?
cont lines are proper log_buf entries now, there is nothing to reassemble
according to "consecutive continuation flags". Or am I wrong?
---
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 308497194bd4..e72cb793aff1 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -192,16 +192,7 @@ int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int
write,
return 0;
}
-/*
- * Number of registered extended console drivers.
- *
- * If extended consoles are present, in-kernel cont reassembly is disabled
- * and each fragment is stored as a separate log entry with proper
- * continuation flag so that every emitted message has full metadata. This
- * doesn't change the result for regular consoles or /proc/kmsg. For
- * /dev/kmsg, as long as the reader concatenates messages according to
- * consecutive continuation flags, the end result should be the same too.
- */
+/* Number of registered extended console drivers. */
static int nr_ext_console_drivers;
/*
@@ -1806,12 +1797,8 @@ static void cont_flush(void)
static bool cont_add(int facility, int level, enum log_flags flags, const char
*text, size_t len)
{
- /*
-* If ext consoles are present, flush and skip in-kernel
-* continuation. See nr_ext_console_drivers definition. Also, if
-* the line gets too long, split it up in separate records.
-*/
- if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
+ /* If the line gets too long, split it up in separate records. */
+ if (cont.len + len > sizeof(cont.buf)) {
cont_flush();
return false;
}
@@ -2731,8 +2718,7 @@ void register_console(struct console *newcon)
}
if (newcon->flags & CON_EXTENDED)
- if (!nr_ext_console_drivers++)
- pr_info("printk: continuation disabled due to ext
consoles, expect more fragments in /dev/kmsg\n");
+ nr_ext_console_drivers++;
if (newcon->flags & CON_PRINTBUFFER) {
/*
---
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (10/01/18 14:52), Sergey Senozhatsky wrote:
> On (09/29/18 20:13), Sergey Senozhatsky wrote:
> > We used to flush "incomplete" cont lines (fragments) from console_unlock().
> >
> > void console_unlock(void)
> > {
> > ...
> > /* flush buffered message fragment immediately to console */
> > console_cont_flush(text, sizeof(text));
> > again:
> > for (;;) {
> > ...
> > }
> > ...
> > }
> >
> > Unless I'm missing something, we don't anymore.
> > Since 5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb.
> > Now we print only log_buf entries. So we either wait for a \n to flush
> > a complete cont buffer, or for a race to preliminary flush cont buffer.
>
> BTW, it just crossed my mind:
One more thing.
Since we don't print cont fragments to the consoles anymore, do we still
need the "extended consoles disable kernel cont support" thing?
cont lines are proper log_buf entries now, there is nothing to reassemble
according to "consecutive continuation flags". Or am I wrong?
---
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 308497194bd4..e72cb793aff1 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -192,16 +192,7 @@ int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int
write,
return 0;
}
-/*
- * Number of registered extended console drivers.
- *
- * If extended consoles are present, in-kernel cont reassembly is disabled
- * and each fragment is stored as a separate log entry with proper
- * continuation flag so that every emitted message has full metadata. This
- * doesn't change the result for regular consoles or /proc/kmsg. For
- * /dev/kmsg, as long as the reader concatenates messages according to
- * consecutive continuation flags, the end result should be the same too.
- */
+/* Number of registered extended console drivers. */
static int nr_ext_console_drivers;
/*
@@ -1806,12 +1797,8 @@ static void cont_flush(void)
static bool cont_add(int facility, int level, enum log_flags flags, const char
*text, size_t len)
{
- /*
-* If ext consoles are present, flush and skip in-kernel
-* continuation. See nr_ext_console_drivers definition. Also, if
-* the line gets too long, split it up in separate records.
-*/
- if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
+ /* If the line gets too long, split it up in separate records. */
+ if (cont.len + len > sizeof(cont.buf)) {
cont_flush();
return false;
}
@@ -2731,8 +2718,7 @@ void register_console(struct console *newcon)
}
if (newcon->flags & CON_EXTENDED)
- if (!nr_ext_console_drivers++)
- pr_info("printk: continuation disabled due to ext
consoles, expect more fragments in /dev/kmsg\n");
+ nr_ext_console_drivers++;
if (newcon->flags & CON_PRINTBUFFER) {
/*
---
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/29/18 20:13), Sergey Senozhatsky wrote:
> We used to flush "incomplete" cont lines (fragments) from console_unlock().
>
> void console_unlock(void)
> {
> ...
> /* flush buffered message fragment immediately to console */
> console_cont_flush(text, sizeof(text));
> again:
> for (;;) {
> ...
> }
> ...
> }
>
> Unless I'm missing something, we don't anymore.
> Since 5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb.
> Now we print only log_buf entries. So we either wait for a \n to flush
> a complete cont buffer, or for a race to preliminary flush cont buffer.
BTW, it just crossed my mind:
Previously, we would do console_cont_flush() for each pr_cont(),
so console_unlock() would print data:
pr_cont();
console_lock();
console_unlock()
console_cont_flush(); // print cont fragment
...
pr_cont();
console_lock();
console_unlock()
console_cont_flush(); // print cont fragment
We don't console_cont_flush() anymore, so when we do pr_cont()
console_unlock() does nothing (unless we flushed the cont buffer):
pr_cont();
console_lock();
console_unlock(); // noop
...
pr_cont();
console_lock();
console_unlock(); // noop
...
pr_cont();
cont_flush();
console_lock();
console_unlock(); // print data
console_lock()/console_unlock() makes sense only when we flush cont
buffer.
We also wakeup klogd purposelessly for pr_cont() output - un-flushed
is not stored in log_buf; there is nothing to pull.
So we can console_lock()/console_unlock()/wake_up_klogd() only when we
know that we log_stor()-ed a message.
A quick-n-dirty patch (I can send a formal one) which compares log_next_seq
before and after vprintk_store(). log_next_seq is getting incremented each
time we log_store() a new log_buf message:
---
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 308497194bd4..53d9134f02a6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1931,6 +1931,7 @@ asmlinkage int vprintk_emit(int facility, int level,
int printed_len;
bool in_sched = false;
unsigned long flags;
+ u64 curr_log_seq;
if (level == LOGLEVEL_SCHED) {
level = LOGLEVEL_DEFAULT;
@@ -1942,11 +1943,12 @@ asmlinkage int vprintk_emit(int facility, int level,
/* This stops the holder of console_sem just where we want him */
logbuf_lock_irqsave(flags);
+ curr_log_seq = log_next_seq;
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) {
+ if (!in_sched && (curr_log_seq != log_next_seq)) {
/*
* Disable preemption to avoid being preempted while holding
* console_sem which would prevent anyone from printing to
@@ -1963,7 +1965,8 @@ asmlinkage int vprintk_emit(int facility, int level,
preempt_enable();
}
- wake_up_klogd();
+ if (curr_log_seq != log_next_seq)
+ wake_up_klogd();
return printed_len;
}
EXPORT_SYMBOL(vprintk_emit);
---
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/29/18 20:13), Sergey Senozhatsky wrote:
> We used to flush "incomplete" cont lines (fragments) from console_unlock().
>
> void console_unlock(void)
> {
> ...
> /* flush buffered message fragment immediately to console */
> console_cont_flush(text, sizeof(text));
> again:
> for (;;) {
> ...
> }
> ...
> }
>
> Unless I'm missing something, we don't anymore.
> Since 5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb.
> Now we print only log_buf entries. So we either wait for a \n to flush
> a complete cont buffer, or for a race to preliminary flush cont buffer.
BTW, it just crossed my mind:
Previously, we would do console_cont_flush() for each pr_cont(),
so console_unlock() would print data:
pr_cont();
console_lock();
console_unlock()
console_cont_flush(); // print cont fragment
...
pr_cont();
console_lock();
console_unlock()
console_cont_flush(); // print cont fragment
We don't console_cont_flush() anymore, so when we do pr_cont()
console_unlock() does nothing (unless we flushed the cont buffer):
pr_cont();
console_lock();
console_unlock(); // noop
...
pr_cont();
console_lock();
console_unlock(); // noop
...
pr_cont();
cont_flush();
console_lock();
console_unlock(); // print data
console_lock()/console_unlock() makes sense only when we flush cont
buffer.
We also wakeup klogd purposelessly for pr_cont() output - un-flushed
is not stored in log_buf; there is nothing to pull.
So we can console_lock()/console_unlock()/wake_up_klogd() only when we
know that we log_stor()-ed a message.
A quick-n-dirty patch (I can send a formal one) which compares log_next_seq
before and after vprintk_store(). log_next_seq is getting incremented each
time we log_store() a new log_buf message:
---
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 308497194bd4..53d9134f02a6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1931,6 +1931,7 @@ asmlinkage int vprintk_emit(int facility, int level,
int printed_len;
bool in_sched = false;
unsigned long flags;
+ u64 curr_log_seq;
if (level == LOGLEVEL_SCHED) {
level = LOGLEVEL_DEFAULT;
@@ -1942,11 +1943,12 @@ asmlinkage int vprintk_emit(int facility, int level,
/* This stops the holder of console_sem just where we want him */
logbuf_lock_irqsave(flags);
+ curr_log_seq = log_next_seq;
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) {
+ if (!in_sched && (curr_log_seq != log_next_seq)) {
/*
* Disable preemption to avoid being preempted while holding
* console_sem which would prevent anyone from printing to
@@ -1963,7 +1965,8 @@ asmlinkage int vprintk_emit(int facility, int level,
preempt_enable();
}
- wake_up_klogd();
+ if (curr_log_seq != log_next_seq)
+ wake_up_klogd();
return printed_len;
}
EXPORT_SYMBOL(vprintk_emit);
---
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (10/01/18 11:37), Sergey Senozhatsky wrote: > If we are about to have a list of printk buffers then we probably can > define a list of NR_CPUS cont buffers. And we probably can reuse the > existing struct cont for buffered printk, having 2 different struct-s > for the same thing - struct cont and struct printk_buffer - is not very > cool. And we also can re-use cont_add() / cont_flush() / etc. Just pass a specific struct cont *cont to those functions. > All printk()-s are limited by LOG_LINE_MAX. Buffered printk() is not > special. Correction: I was wrong about this. Looking at cont handling, it seems that buffered printk is special after all. We do let it to be over LOG_LINE_MAX: if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) cont_flush(); -ss
Re: [PATCH] printk: inject caller information into the body of message
On (10/01/18 11:37), Sergey Senozhatsky wrote: > If we are about to have a list of printk buffers then we probably can > define a list of NR_CPUS cont buffers. And we probably can reuse the > existing struct cont for buffered printk, having 2 different struct-s > for the same thing - struct cont and struct printk_buffer - is not very > cool. And we also can re-use cont_add() / cont_flush() / etc. Just pass a specific struct cont *cont to those functions. > All printk()-s are limited by LOG_LINE_MAX. Buffered printk() is not > special. Correction: I was wrong about this. Looking at cont handling, it seems that buffered printk is special after all. We do let it to be over LOG_LINE_MAX: if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) cont_flush(); -ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/29/18 20:15), Tetsuo Handa wrote: > > Because there is no guarantee that memory information is dumped under the > oom_lock mutex. The oom_lock is held when calling out_of_memory(), and it > cannot be held when reporting GFP_ATOMIC memory allocation failures. IOW, static pr_line buffer needs additional synchronization for OOM. Correct? If we are about to have a list of printk buffers then we probably can define a list of NR_CPUS cont buffers. And we probably can reuse the existing struct cont for buffered printk, having 2 different struct-s for the same thing - struct cont and struct printk_buffer - is not very cool. > But I don't want line buffered printk() API to truncate upon out of > space for line buffered printk() API. All printk()-s are limited by LOG_LINE_MAX. Buffered printk() is not special. -ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/29/18 20:15), Tetsuo Handa wrote: > > Because there is no guarantee that memory information is dumped under the > oom_lock mutex. The oom_lock is held when calling out_of_memory(), and it > cannot be held when reporting GFP_ATOMIC memory allocation failures. IOW, static pr_line buffer needs additional synchronization for OOM. Correct? If we are about to have a list of printk buffers then we probably can define a list of NR_CPUS cont buffers. And we probably can reuse the existing struct cont for buffered printk, having 2 different struct-s for the same thing - struct cont and struct printk_buffer - is not very cool. > But I don't want line buffered printk() API to truncate upon out of > space for line buffered printk() API. All printk()-s are limited by LOG_LINE_MAX. Buffered printk() is not special. -ss
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/29 20:13, Sergey Senozhatsky wrote:
> On (09/28/18 20:21), Tetsuo Handa wrote:
>> On 2018/09/28 17:56, Sergey Senozhatsky wrote:
>>> The good thing about cont buffer is that we flush it on panic. E.g.
>>> core/arch early boot stage can do:
>>>
>>> pr_cont("going to call early_init_foo()...");
>>> early_init_foo();
>>> pr_cont("OK\n");
>>>
>>
>> Is printing
>>
>> going to call early_init_foo()...OK
>>
>> in one line so critically important?
>
> Could be. If this is the last thing you are about to see on your
> serial console. panic_on_flush() is not guaranteed to succeed.
Doing
printk("going to call early_init_foo()...\n");
early_init_foo();
printk("OK\n");
and getting
T0: going to call early_init_foo()...
as the last line we see on our serial console will not be so bad.
Implicitly flushing incomplete lines might disturb automated processing.
But there is after all other factors which can disturb automated
processing (e.g. "** %u printk messages dropped **\n" in printk(),
UDP packet being lost when transmitting via netconsole). After all,
we cannot allow perfect automated processing. The last help is
human's eyes and brain.
Then, prefixing caller information helps even if incomplete line
is implicitly flushed by line buffered printk() API...
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/29 20:13, Sergey Senozhatsky wrote:
> On (09/28/18 20:21), Tetsuo Handa wrote:
>> On 2018/09/28 17:56, Sergey Senozhatsky wrote:
>>> The good thing about cont buffer is that we flush it on panic. E.g.
>>> core/arch early boot stage can do:
>>>
>>> pr_cont("going to call early_init_foo()...");
>>> early_init_foo();
>>> pr_cont("OK\n");
>>>
>>
>> Is printing
>>
>> going to call early_init_foo()...OK
>>
>> in one line so critically important?
>
> Could be. If this is the last thing you are about to see on your
> serial console. panic_on_flush() is not guaranteed to succeed.
Doing
printk("going to call early_init_foo()...\n");
early_init_foo();
printk("OK\n");
and getting
T0: going to call early_init_foo()...
as the last line we see on our serial console will not be so bad.
Implicitly flushing incomplete lines might disturb automated processing.
But there is after all other factors which can disturb automated
processing (e.g. "** %u printk messages dropped **\n" in printk(),
UDP packet being lost when transmitting via netconsole). After all,
we cannot allow perfect automated processing. The last help is
human's eyes and brain.
Then, prefixing caller information helps even if incomplete line
is implicitly flushed by line buffered printk() API...
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/29 19:51, Sergey Senozhatsky wrote:
> On (09/28/18 20:01), Tetsuo Handa wrote:
>>> Yes, this makes sense. At the same time we can keep pr_line buffer
>>> in .bss
>>>
>>> static char buffer[1024];
>>> static DEFINE_PR_LINE_BUF(..., buffer);
>>>
>>> just like you have already mentioned. But that's going to require a
>>> case-by-case handling; so a big list of printk buffers is a simpler
>>> option. Fallback, tho, can be painful. On a system with 1024 CPUs can
>>> one have more than 16 concurrent cont printks? If the answer is yes,
>>> then we are looking at the same broken cont output as before.
>>
>> I'm OK with making "16" configurable (at kernel configuration and/or
>> at kernel boot like log_buf_len= kernel command line parameter).
>
> Do we really want this? Why .bss placement doesn't work for you?
>
> void oom(...)
> {
> static DEFINE_PR_LINE(KERN_ERR, pr);
>
> pr_line(, );
> pr_line(, "\n");
> }
>
> the underlying buffer will be static; the pr_line will get re-init
> (offset = 0) every time we call the function, which is OK. And we can
> pass to any function oom() invokes. What am I missing?
Because there is no guarantee that memory information is dumped under the
oom_lock mutex. The oom_lock is held when calling out_of_memory(), and it
cannot be held when reporting GFP_ATOMIC memory allocation failures.
>
>> We could even allow each "struct task_struct" to have corresponding
>> "struct printk_buffer".
>
> Tetsuo, realistically, we can't. Sorry. No one will let us to have a printk
> buffer on per-task_struct basis. Even if someone will let us to do this,
> a miracle, a single per-task_struct buffer won't work. Because, then
> someone will discover that a very simple API
>
> buffered_printk(current->printk_buffer, "..");
>
> does not work if buffered_printk() gets interrupted by IRQ, etc. in case
> if that new context also does
>
> buffered_printk(current->printk_buffer, "..");
>
> So then we will have per-context per-task_struct printk buffer: for task,
> for exceptions, for softirq, for hardirq, for NMI, etc. This is not worth
> it.
The number of "struct task_struct" instances is volatile. But number of non
"struct task_struct" contexts is finite which can be determined at boot (or
initialization) time.
My intention is that allocate "struct printk_buffer" when "struct task_struct"
is created (i.e. upon dup_task_struct()) and release "struct printk_buffer"
when "struct task_struct" is destroyed (i.e. upon free_task_struct()), and
allocate "struct printk_buffer" for non "struct task_struct" contexts when a
CPU is onlined and release "struct printk_buffer" for non "struct task_struct"
contexts when a CPU is offlined. Then, it will be guaranteed that there is
enough "struct printk_buffer" for any callers.
>
> Let's just have a very simple seq_buf based pr_line API. No config options,
> no command line arguments - heap, bss or stack for buffer placement. Or even
> simpler.
We cannot avoid "** %u printk messages dropped **\n" inside printk() upon out
of space. But I don't want line buffered printk() API to truncate upon out of
space for line buffered printk() API. I want buffered printk() API to flush
incomplete line even if it resulted in printed in multiple lines.
Injecting caller information can mitigate "printed in multiple lines" case.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/29 19:51, Sergey Senozhatsky wrote:
> On (09/28/18 20:01), Tetsuo Handa wrote:
>>> Yes, this makes sense. At the same time we can keep pr_line buffer
>>> in .bss
>>>
>>> static char buffer[1024];
>>> static DEFINE_PR_LINE_BUF(..., buffer);
>>>
>>> just like you have already mentioned. But that's going to require a
>>> case-by-case handling; so a big list of printk buffers is a simpler
>>> option. Fallback, tho, can be painful. On a system with 1024 CPUs can
>>> one have more than 16 concurrent cont printks? If the answer is yes,
>>> then we are looking at the same broken cont output as before.
>>
>> I'm OK with making "16" configurable (at kernel configuration and/or
>> at kernel boot like log_buf_len= kernel command line parameter).
>
> Do we really want this? Why .bss placement doesn't work for you?
>
> void oom(...)
> {
> static DEFINE_PR_LINE(KERN_ERR, pr);
>
> pr_line(, );
> pr_line(, "\n");
> }
>
> the underlying buffer will be static; the pr_line will get re-init
> (offset = 0) every time we call the function, which is OK. And we can
> pass to any function oom() invokes. What am I missing?
Because there is no guarantee that memory information is dumped under the
oom_lock mutex. The oom_lock is held when calling out_of_memory(), and it
cannot be held when reporting GFP_ATOMIC memory allocation failures.
>
>> We could even allow each "struct task_struct" to have corresponding
>> "struct printk_buffer".
>
> Tetsuo, realistically, we can't. Sorry. No one will let us to have a printk
> buffer on per-task_struct basis. Even if someone will let us to do this,
> a miracle, a single per-task_struct buffer won't work. Because, then
> someone will discover that a very simple API
>
> buffered_printk(current->printk_buffer, "..");
>
> does not work if buffered_printk() gets interrupted by IRQ, etc. in case
> if that new context also does
>
> buffered_printk(current->printk_buffer, "..");
>
> So then we will have per-context per-task_struct printk buffer: for task,
> for exceptions, for softirq, for hardirq, for NMI, etc. This is not worth
> it.
The number of "struct task_struct" instances is volatile. But number of non
"struct task_struct" contexts is finite which can be determined at boot (or
initialization) time.
My intention is that allocate "struct printk_buffer" when "struct task_struct"
is created (i.e. upon dup_task_struct()) and release "struct printk_buffer"
when "struct task_struct" is destroyed (i.e. upon free_task_struct()), and
allocate "struct printk_buffer" for non "struct task_struct" contexts when a
CPU is onlined and release "struct printk_buffer" for non "struct task_struct"
contexts when a CPU is offlined. Then, it will be guaranteed that there is
enough "struct printk_buffer" for any callers.
>
> Let's just have a very simple seq_buf based pr_line API. No config options,
> no command line arguments - heap, bss or stack for buffer placement. Or even
> simpler.
We cannot avoid "** %u printk messages dropped **\n" inside printk() upon out
of space. But I don't want line buffered printk() API to truncate upon out of
space for line buffered printk() API. I want buffered printk() API to flush
incomplete line even if it resulted in printed in multiple lines.
Injecting caller information can mitigate "printed in multiple lines" case.
Re: [PATCH] printk: inject caller information into the body of message
On (09/28/18 20:21), Tetsuo Handa wrote:
> On 2018/09/28 17:56, Sergey Senozhatsky wrote:
> > The good thing about cont buffer is that we flush it on panic. E.g.
> > core/arch early boot stage can do:
> >
> > pr_cont("going to call early_init_foo()...");
> > early_init_foo();
> > pr_cont("OK\n");
> >
>
> Is printing
>
> going to call early_init_foo()...OK
>
> in one line so critically important?
Could be. If this is the last thing you are about to see on your
serial console. panic_on_flush() is not guaranteed to succeed.
... Hmm. But it seems that this has changed.
We used to flush "incomplete" cont lines (fragments) from console_unlock().
void console_unlock(void)
{
...
/* flush buffered message fragment immediately to console */
console_cont_flush(text, sizeof(text));
again:
for (;;) {
...
}
...
}
Unless I'm missing something, we don't anymore.
Since 5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb.
Now we print only log_buf entries. So we either wait for a \n to flush
a complete cont buffer, or for a race to preliminary flush cont buffer.
> > Tetsuo, do you still want to have a fixed size array of printk buffers?
>
> For my intended users where printk() is used for reporting errors (e.g.
> stack backtrace, GFP_ATOMIC memory allocation failure, lockdep splat),
> being prepared for already tight stack is preferable.
Agreed. A list of printk buffers has some interesting features and may
be we will use it after all.
At the same time the functions you have mentioned can use static char
buffers for pr_line.
> > What do others think?
>
> Yes, I want to hear from others.
Yep.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/28/18 20:21), Tetsuo Handa wrote:
> On 2018/09/28 17:56, Sergey Senozhatsky wrote:
> > The good thing about cont buffer is that we flush it on panic. E.g.
> > core/arch early boot stage can do:
> >
> > pr_cont("going to call early_init_foo()...");
> > early_init_foo();
> > pr_cont("OK\n");
> >
>
> Is printing
>
> going to call early_init_foo()...OK
>
> in one line so critically important?
Could be. If this is the last thing you are about to see on your
serial console. panic_on_flush() is not guaranteed to succeed.
... Hmm. But it seems that this has changed.
We used to flush "incomplete" cont lines (fragments) from console_unlock().
void console_unlock(void)
{
...
/* flush buffered message fragment immediately to console */
console_cont_flush(text, sizeof(text));
again:
for (;;) {
...
}
...
}
Unless I'm missing something, we don't anymore.
Since 5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb.
Now we print only log_buf entries. So we either wait for a \n to flush
a complete cont buffer, or for a race to preliminary flush cont buffer.
> > Tetsuo, do you still want to have a fixed size array of printk buffers?
>
> For my intended users where printk() is used for reporting errors (e.g.
> stack backtrace, GFP_ATOMIC memory allocation failure, lockdep splat),
> being prepared for already tight stack is preferable.
Agreed. A list of printk buffers has some interesting features and may
be we will use it after all.
At the same time the functions you have mentioned can use static char
buffers for pr_line.
> > What do others think?
>
> Yes, I want to hear from others.
Yep.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/28/18 20:01), Tetsuo Handa wrote:
> > Yes, this makes sense. At the same time we can keep pr_line buffer
> > in .bss
> >
> > static char buffer[1024];
> > static DEFINE_PR_LINE_BUF(..., buffer);
> >
> > just like you have already mentioned. But that's going to require a
> > case-by-case handling; so a big list of printk buffers is a simpler
> > option. Fallback, tho, can be painful. On a system with 1024 CPUs can
> > one have more than 16 concurrent cont printks? If the answer is yes,
> > then we are looking at the same broken cont output as before.
>
> I'm OK with making "16" configurable (at kernel configuration and/or
> at kernel boot like log_buf_len= kernel command line parameter).
Do we really want this? Why .bss placement doesn't work for you?
void oom(...)
{
static DEFINE_PR_LINE(KERN_ERR, pr);
pr_line(, );
pr_line(, "\n");
}
the underlying buffer will be static; the pr_line will get re-init
(offset = 0) every time we call the function, which is OK. And we can
pass to any function oom() invokes. What am I missing?
> We could even allow each "struct task_struct" to have corresponding
> "struct printk_buffer".
Tetsuo, realistically, we can't. Sorry. No one will let us to have a printk
buffer on per-task_struct basis. Even if someone will let us to do this,
a miracle, a single per-task_struct buffer won't work. Because, then
someone will discover that a very simple API
buffered_printk(current->printk_buffer, "..");
does not work if buffered_printk() gets interrupted by IRQ, etc. in case
if that new context also does
buffered_printk(current->printk_buffer, "..");
So then we will have per-context per-task_struct printk buffer: for task,
for exceptions, for softirq, for hardirq, for NMI, etc. This is not worth
it.
Let's just have a very simple seq_buf based pr_line API. No config options,
no command line arguments - heap, bss or stack for buffer placement. Or even
simpler.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/28/18 20:01), Tetsuo Handa wrote:
> > Yes, this makes sense. At the same time we can keep pr_line buffer
> > in .bss
> >
> > static char buffer[1024];
> > static DEFINE_PR_LINE_BUF(..., buffer);
> >
> > just like you have already mentioned. But that's going to require a
> > case-by-case handling; so a big list of printk buffers is a simpler
> > option. Fallback, tho, can be painful. On a system with 1024 CPUs can
> > one have more than 16 concurrent cont printks? If the answer is yes,
> > then we are looking at the same broken cont output as before.
>
> I'm OK with making "16" configurable (at kernel configuration and/or
> at kernel boot like log_buf_len= kernel command line parameter).
Do we really want this? Why .bss placement doesn't work for you?
void oom(...)
{
static DEFINE_PR_LINE(KERN_ERR, pr);
pr_line(, );
pr_line(, "\n");
}
the underlying buffer will be static; the pr_line will get re-init
(offset = 0) every time we call the function, which is OK. And we can
pass to any function oom() invokes. What am I missing?
> We could even allow each "struct task_struct" to have corresponding
> "struct printk_buffer".
Tetsuo, realistically, we can't. Sorry. No one will let us to have a printk
buffer on per-task_struct basis. Even if someone will let us to do this,
a miracle, a single per-task_struct buffer won't work. Because, then
someone will discover that a very simple API
buffered_printk(current->printk_buffer, "..");
does not work if buffered_printk() gets interrupted by IRQ, etc. in case
if that new context also does
buffered_printk(current->printk_buffer, "..");
So then we will have per-context per-task_struct printk buffer: for task,
for exceptions, for softirq, for hardirq, for NMI, etc. This is not worth
it.
Let's just have a very simple seq_buf based pr_line API. No config options,
no command line arguments - heap, bss or stack for buffer placement. Or even
simpler.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/28 17:56, Sergey Senozhatsky wrote:
> The good thing about cont buffer is that we flush it on panic. E.g.
> core/arch early boot stage can do:
>
> pr_cont("going to call early_init_foo()...");
> early_init_foo();
> pr_cont("OK\n");
>
Is printing
going to call early_init_foo()...OK
in one line so critically important? If caller information is prefixed,
we would no longer need to support KERN_CONT. That is, we could do
printk("going to call early_init_foo()...\n");
early_init_foo();
printk("OK\n");
and get output like below.
T0: going to call early_init_foo()...
T0: OK
Even if "going to call early_init_foo()..." part became too long,
T0: going to call
T0: early_init_foo()...
T0: OK
will not be so bad.
> should early_init_foo() panic the system we will have
> "going to call early_init_foo()" on the serial console. This can
> be addressed if you'd iterate printk_buffers[] in flush_on_panic().
Yes, flush on panic() would also be possible.
> Tetsuo, do you still want to have a fixed size array of printk buffers?
For my intended users where printk() is used for reporting errors (e.g.
stack backtrace, GFP_ATOMIC memory allocation failure, lockdep splat),
being prepared for already tight stack is preferable.
>
> What do others think?
Yes, I want to hear from others.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/28 17:56, Sergey Senozhatsky wrote:
> The good thing about cont buffer is that we flush it on panic. E.g.
> core/arch early boot stage can do:
>
> pr_cont("going to call early_init_foo()...");
> early_init_foo();
> pr_cont("OK\n");
>
Is printing
going to call early_init_foo()...OK
in one line so critically important? If caller information is prefixed,
we would no longer need to support KERN_CONT. That is, we could do
printk("going to call early_init_foo()...\n");
early_init_foo();
printk("OK\n");
and get output like below.
T0: going to call early_init_foo()...
T0: OK
Even if "going to call early_init_foo()..." part became too long,
T0: going to call
T0: early_init_foo()...
T0: OK
will not be so bad.
> should early_init_foo() panic the system we will have
> "going to call early_init_foo()" on the serial console. This can
> be addressed if you'd iterate printk_buffers[] in flush_on_panic().
Yes, flush on panic() would also be possible.
> Tetsuo, do you still want to have a fixed size array of printk buffers?
For my intended users where printk() is used for reporting errors (e.g.
stack backtrace, GFP_ATOMIC memory allocation failure, lockdep splat),
being prepared for already tight stack is preferable.
>
> What do others think?
Yes, I want to hear from others.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/28 18:09, Sergey Senozhatsky wrote: > On (09/24/18 17:11), Tetsuo Handa wrote: >> The reason of using statically preallocated global buffers is that I think >> that it is inconvenient for KERN_CONT users to calculate necessary bytes >> only for avoiding message truncation. The pr_line might be passed to deep >> into the callchain and adjusting buffer size whenever the content's possible >> max length changes is as much painful as changing printk() to accept only >> one "const char *" argument. Even if we guarantee that any context can >> allocate buffer from kernel stack, we cannot guarantee that many concurrent >> printk() won't trigger lockup. Thus, I think that trying to allocate from >> finite static buffers with a fallback to unbuffered printk() upon failure >> is sufficient. > > Yes, this makes sense. At the same time we can keep pr_line buffer > in .bss > > static char buffer[1024]; > static DEFINE_PR_LINE_BUF(..., buffer); > > just like you have already mentioned. But that's going to require a > case-by-case handling; so a big list of printk buffers is a simpler > option. Fallback, tho, can be painful. On a system with 1024 CPUs can > one have more than 16 concurrent cont printks? If the answer is yes, > then we are looking at the same broken cont output as before. I'm OK with making "16" configurable (at kernel configuration and/or at kernel boot like log_buf_len= kernel command line parameter). We could even allow each "struct task_struct" to have corresponding "struct printk_buffer". But if there are such many concurrent callers, the printk() would have already locked up the system to death. ;-)
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/28 18:09, Sergey Senozhatsky wrote: > On (09/24/18 17:11), Tetsuo Handa wrote: >> The reason of using statically preallocated global buffers is that I think >> that it is inconvenient for KERN_CONT users to calculate necessary bytes >> only for avoiding message truncation. The pr_line might be passed to deep >> into the callchain and adjusting buffer size whenever the content's possible >> max length changes is as much painful as changing printk() to accept only >> one "const char *" argument. Even if we guarantee that any context can >> allocate buffer from kernel stack, we cannot guarantee that many concurrent >> printk() won't trigger lockup. Thus, I think that trying to allocate from >> finite static buffers with a fallback to unbuffered printk() upon failure >> is sufficient. > > Yes, this makes sense. At the same time we can keep pr_line buffer > in .bss > > static char buffer[1024]; > static DEFINE_PR_LINE_BUF(..., buffer); > > just like you have already mentioned. But that's going to require a > case-by-case handling; so a big list of printk buffers is a simpler > option. Fallback, tho, can be painful. On a system with 1024 CPUs can > one have more than 16 concurrent cont printks? If the answer is yes, > then we are looking at the same broken cont output as before. I'm OK with making "16" configurable (at kernel configuration and/or at kernel boot like log_buf_len= kernel command line parameter). We could even allow each "struct task_struct" to have corresponding "struct printk_buffer". But if there are such many concurrent callers, the printk() would have already locked up the system to death. ;-)
Re: [PATCH] printk: inject caller information into the body of message
On (09/24/18 17:11), Tetsuo Handa wrote: > The reason of using statically preallocated global buffers is that I think > that it is inconvenient for KERN_CONT users to calculate necessary bytes > only for avoiding message truncation. The pr_line might be passed to deep > into the callchain and adjusting buffer size whenever the content's possible > max length changes is as much painful as changing printk() to accept only > one "const char *" argument. Even if we guarantee that any context can > allocate buffer from kernel stack, we cannot guarantee that many concurrent > printk() won't trigger lockup. Thus, I think that trying to allocate from > finite static buffers with a fallback to unbuffered printk() upon failure > is sufficient. Yes, this makes sense. At the same time we can keep pr_line buffer in .bss static char buffer[1024]; static DEFINE_PR_LINE_BUF(..., buffer); just like you have already mentioned. But that's going to require a case-by-case handling; so a big list of printk buffers is a simpler option. Fallback, tho, can be painful. On a system with 1024 CPUs can one have more than 16 concurrent cont printks? If the answer is yes, then we are looking at the same broken cont output as before. -ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/24/18 17:11), Tetsuo Handa wrote: > The reason of using statically preallocated global buffers is that I think > that it is inconvenient for KERN_CONT users to calculate necessary bytes > only for avoiding message truncation. The pr_line might be passed to deep > into the callchain and adjusting buffer size whenever the content's possible > max length changes is as much painful as changing printk() to accept only > one "const char *" argument. Even if we guarantee that any context can > allocate buffer from kernel stack, we cannot guarantee that many concurrent > printk() won't trigger lockup. Thus, I think that trying to allocate from > finite static buffers with a fallback to unbuffered printk() upon failure > is sufficient. Yes, this makes sense. At the same time we can keep pr_line buffer in .bss static char buffer[1024]; static DEFINE_PR_LINE_BUF(..., buffer); just like you have already mentioned. But that's going to require a case-by-case handling; so a big list of printk buffers is a simpler option. Fallback, tho, can be painful. On a system with 1024 CPUs can one have more than 16 concurrent cont printks? If the answer is yes, then we are looking at the same broken cont output as before. -ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/28/18 01:10), Tetsuo Handa wrote: > > Therefore, I think that "Either we need to require synchronization - umm... > and > document it - or to provide some means of synchronization in pr_line()." is a > pointless worry. It is only existing printk() API which needs > synchronization. I > think that line buffered printk() API does not need to talk about > synchronization. > Just saying "don't share DEFINE_PR_LINE()/DEFINE_PR_LINE_BUF() variables" > will be > sufficient. Agreed. My conclusion at the end was that - "pr_line is going to do as much as seq_buf does". So pr_line won't provide any additional synchronization mechanisms. -ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/28/18 01:10), Tetsuo Handa wrote: > > Therefore, I think that "Either we need to require synchronization - umm... > and > document it - or to provide some means of synchronization in pr_line()." is a > pointless worry. It is only existing printk() API which needs > synchronization. I > think that line buffered printk() API does not need to talk about > synchronization. > Just saying "don't share DEFINE_PR_LINE()/DEFINE_PR_LINE_BUF() variables" > will be > sufficient. Agreed. My conclusion at the end was that - "pr_line is going to do as much as seq_buf does". So pr_line won't provide any additional synchronization mechanisms. -ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/19/18 20:02), Tetsuo Handa wrote:
> I'm inclined to propose a simple one shown below, similar to just having
> several "struct cont" for concurrent printk() users.
Tetsuo, thanks for the patch.
> What Linus has commented is that implicit context is bad, and below one
> uses explicit context.
> After almost all users are converted to use below one, we might be able
> to get rid of KERN_CONT support.
The good thing about cont buffer is that we flush it on panic. E.g.
core/arch early boot stage can do:
pr_cont("going to call early_init_foo()...");
early_init_foo();
pr_cont("OK\n");
should early_init_foo() panic the system we will have
"going to call early_init_foo()" on the serial console. This can
be addressed if you'd iterate printk_buffers[] in flush_on_panic().
> +#define MAX_PRINTK_BUFFERS 16
> +static struct printk_buffer printk_buffers[MAX_PRINTK_BUFFERS];
Well, hmm, maybe. Now can we have a problem of either too-small or too-large
MAX_PRINTK_BUFFERS. 16 buffers on a 4 CPU arm board most probably will just
waste some memory. At the same time we probably don't want to have NR_CPUS
buffers. The fallback to "regular printk" is still a bit troubling - technically
there may be cases when we don't fix anything.
So, overall, I'm not against your patch. There are some pros and cons,
however.
pr_line() patch seems to be simpler [probably] and smaller [definitely].
The only problem, as you have mentioned, is that people may miscalculate
the size of the buffer, which won't crash us or anything; people can overshot
even a LOG_LINE_MAX buffer. So probably I'm not completely sold on having
a fixed size printk_buffers[].
May be all we want at the end is to drop explicit buffer API and have just
two options in pr_line:
DEFINE_PR_LINE() -- 80-bytes (or 256) pr_line // implicit buffer
DEFINE_PR_LINE_HUGE() -- 1024-bytes pr_line// implicit buffer
So, no explicit buffers, just "a normal" pr_line or "a huge" pr_line.
And no "normal printk" fallback; buffered printk line stays buffered.
The 80-bytes limit can be lifted to, say, 256-bytes.
Tetsuo, do you still want to have a fixed size array of printk buffers?
What do others think?
BTW, Tetsuo, I have addressed your pr_line suggestions/corrections.
Couldn't send the patch or reply to emails because I was offline for
a week due to personal reasons; but I can send it now - it does not
have DEFINE_PR_LINE_HUGE() macro. Just a previous version with
corrections which you have pointed out.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/19/18 20:02), Tetsuo Handa wrote:
> I'm inclined to propose a simple one shown below, similar to just having
> several "struct cont" for concurrent printk() users.
Tetsuo, thanks for the patch.
> What Linus has commented is that implicit context is bad, and below one
> uses explicit context.
> After almost all users are converted to use below one, we might be able
> to get rid of KERN_CONT support.
The good thing about cont buffer is that we flush it on panic. E.g.
core/arch early boot stage can do:
pr_cont("going to call early_init_foo()...");
early_init_foo();
pr_cont("OK\n");
should early_init_foo() panic the system we will have
"going to call early_init_foo()" on the serial console. This can
be addressed if you'd iterate printk_buffers[] in flush_on_panic().
> +#define MAX_PRINTK_BUFFERS 16
> +static struct printk_buffer printk_buffers[MAX_PRINTK_BUFFERS];
Well, hmm, maybe. Now can we have a problem of either too-small or too-large
MAX_PRINTK_BUFFERS. 16 buffers on a 4 CPU arm board most probably will just
waste some memory. At the same time we probably don't want to have NR_CPUS
buffers. The fallback to "regular printk" is still a bit troubling - technically
there may be cases when we don't fix anything.
So, overall, I'm not against your patch. There are some pros and cons,
however.
pr_line() patch seems to be simpler [probably] and smaller [definitely].
The only problem, as you have mentioned, is that people may miscalculate
the size of the buffer, which won't crash us or anything; people can overshot
even a LOG_LINE_MAX buffer. So probably I'm not completely sold on having
a fixed size printk_buffers[].
May be all we want at the end is to drop explicit buffer API and have just
two options in pr_line:
DEFINE_PR_LINE() -- 80-bytes (or 256) pr_line // implicit buffer
DEFINE_PR_LINE_HUGE() -- 1024-bytes pr_line// implicit buffer
So, no explicit buffers, just "a normal" pr_line or "a huge" pr_line.
And no "normal printk" fallback; buffered printk line stays buffered.
The 80-bytes limit can be lifted to, say, 256-bytes.
Tetsuo, do you still want to have a fixed size array of printk buffers?
What do others think?
BTW, Tetsuo, I have addressed your pr_line suggestions/corrections.
Couldn't send the patch or reply to emails because I was offline for
a week due to personal reasons; but I can send it now - it does not
have DEFINE_PR_LINE_HUGE() macro. Just a previous version with
corrections which you have pointed out.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/24 17:11, Tetsuo Handa wrote: > On 2018/09/19 20:02, Tetsuo Handa wrote: >> On 2018/09/14 21:22, Sergey Senozhatsky wrote: >>> The "SMP-safe" comment becomes a bit tricky when pr_line is used with a >>> static buffer. Either we need to require synchronization - umm... and >>> document it - or to provide some means of synchronization in pr_line(). >>> Let's think what pr_line API should do about it. >>> >>> Any thoughts? >>> >> >> I'm inclined to propose a simple one shown below, similar to just having >> several "struct cont" for concurrent printk() users. >> What Linus has commented is that implicit context is bad, and below one >> uses explicit context. >> After almost all users are converted to use below one, we might be able >> to get rid of KERN_CONT support. > > The reason of using statically preallocated global buffers is that I think > that it is inconvenient for KERN_CONT users to calculate necessary bytes > only for avoiding message truncation. The pr_line might be passed to deep > into the callchain and adjusting buffer size whenever the content's possible > max length changes is as much painful as changing printk() to accept only > one "const char *" argument. Even if we guarantee that any context can > allocate buffer from kernel stack, we cannot guarantee that many concurrent > printk() won't trigger lockup. Thus, I think that trying to allocate from > finite static buffers with a fallback to unbuffered printk() upon failure > is sufficient. > Hmm, what problem is blocking this topic? I think that the SMP-safe comment is unnecessary for line buffered printk() API. What we want to do is to avoid mixing incomplete lines from concurrent printk() callers (and then, prefix caller's information in order to help grouping multiple lines) rather than avoid stalls / crashes / lost messages caused by concurrent printk() callers. We could avoid crashes if there is no bug in printk() related code. But we can never avoid stalls / lost messages as long as we floodly call printk(). Even if line buffered printk() API were SMP-safe, printk() might have to discard the output. We need to try to avoid too much printk() - as if there is no concept of SMP-safeness regardless of whether pr_line() is used with a static buffer. Therefore, I think that "Either we need to require synchronization - umm... and document it - or to provide some means of synchronization in pr_line()." is a pointless worry. It is only existing printk() API which needs synchronization. I think that line buffered printk() API does not need to talk about synchronization. Just saying "don't share DEFINE_PR_LINE()/DEFINE_PR_LINE_BUF() variables" will be sufficient.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/24 17:11, Tetsuo Handa wrote: > On 2018/09/19 20:02, Tetsuo Handa wrote: >> On 2018/09/14 21:22, Sergey Senozhatsky wrote: >>> The "SMP-safe" comment becomes a bit tricky when pr_line is used with a >>> static buffer. Either we need to require synchronization - umm... and >>> document it - or to provide some means of synchronization in pr_line(). >>> Let's think what pr_line API should do about it. >>> >>> Any thoughts? >>> >> >> I'm inclined to propose a simple one shown below, similar to just having >> several "struct cont" for concurrent printk() users. >> What Linus has commented is that implicit context is bad, and below one >> uses explicit context. >> After almost all users are converted to use below one, we might be able >> to get rid of KERN_CONT support. > > The reason of using statically preallocated global buffers is that I think > that it is inconvenient for KERN_CONT users to calculate necessary bytes > only for avoiding message truncation. The pr_line might be passed to deep > into the callchain and adjusting buffer size whenever the content's possible > max length changes is as much painful as changing printk() to accept only > one "const char *" argument. Even if we guarantee that any context can > allocate buffer from kernel stack, we cannot guarantee that many concurrent > printk() won't trigger lockup. Thus, I think that trying to allocate from > finite static buffers with a fallback to unbuffered printk() upon failure > is sufficient. > Hmm, what problem is blocking this topic? I think that the SMP-safe comment is unnecessary for line buffered printk() API. What we want to do is to avoid mixing incomplete lines from concurrent printk() callers (and then, prefix caller's information in order to help grouping multiple lines) rather than avoid stalls / crashes / lost messages caused by concurrent printk() callers. We could avoid crashes if there is no bug in printk() related code. But we can never avoid stalls / lost messages as long as we floodly call printk(). Even if line buffered printk() API were SMP-safe, printk() might have to discard the output. We need to try to avoid too much printk() - as if there is no concept of SMP-safeness regardless of whether pr_line() is used with a static buffer. Therefore, I think that "Either we need to require synchronization - umm... and document it - or to provide some means of synchronization in pr_line()." is a pointless worry. It is only existing printk() API which needs synchronization. I think that line buffered printk() API does not need to talk about synchronization. Just saying "don't share DEFINE_PR_LINE()/DEFINE_PR_LINE_BUF() variables" will be sufficient.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/19 20:02, Tetsuo Handa wrote: > On 2018/09/14 21:22, Sergey Senozhatsky wrote: >> The "SMP-safe" comment becomes a bit tricky when pr_line is used with a >> static buffer. Either we need to require synchronization - umm... and >> document it - or to provide some means of synchronization in pr_line(). >> Let's think what pr_line API should do about it. >> >> Any thoughts? >> > > I'm inclined to propose a simple one shown below, similar to just having > several "struct cont" for concurrent printk() users. > What Linus has commented is that implicit context is bad, and below one > uses explicit context. > After almost all users are converted to use below one, we might be able > to get rid of KERN_CONT support. The reason of using statically preallocated global buffers is that I think that it is inconvenient for KERN_CONT users to calculate necessary bytes only for avoiding message truncation. The pr_line might be passed to deep into the callchain and adjusting buffer size whenever the content's possible max length changes is as much painful as changing printk() to accept only one "const char *" argument. Even if we guarantee that any context can allocate buffer from kernel stack, we cannot guarantee that many concurrent printk() won't trigger lockup. Thus, I think that trying to allocate from finite static buffers with a fallback to unbuffered printk() upon failure is sufficient. By the way, kbuild test robot told me that I forgot to drop asmlinkage keyword. include/linux/printk.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/include/linux/printk.h b/include/linux/printk.h index 889491b..3347442 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -178,7 +178,7 @@ asmlinkage __printf(1, 2) __cold void flush_printk_buffer(struct printk_buffer *ptr); __printf(2, 3) int buffered_printk(struct printk_buffer *ptr, const char *fmt, ...); -asmlinkage __printf(2, 0) +__printf(2, 0) int buffered_vprintk(struct printk_buffer *ptr, const char *fmt, va_list args); void put_printk_buffer(struct printk_buffer *ptr);
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/19 20:02, Tetsuo Handa wrote: > On 2018/09/14 21:22, Sergey Senozhatsky wrote: >> The "SMP-safe" comment becomes a bit tricky when pr_line is used with a >> static buffer. Either we need to require synchronization - umm... and >> document it - or to provide some means of synchronization in pr_line(). >> Let's think what pr_line API should do about it. >> >> Any thoughts? >> > > I'm inclined to propose a simple one shown below, similar to just having > several "struct cont" for concurrent printk() users. > What Linus has commented is that implicit context is bad, and below one > uses explicit context. > After almost all users are converted to use below one, we might be able > to get rid of KERN_CONT support. The reason of using statically preallocated global buffers is that I think that it is inconvenient for KERN_CONT users to calculate necessary bytes only for avoiding message truncation. The pr_line might be passed to deep into the callchain and adjusting buffer size whenever the content's possible max length changes is as much painful as changing printk() to accept only one "const char *" argument. Even if we guarantee that any context can allocate buffer from kernel stack, we cannot guarantee that many concurrent printk() won't trigger lockup. Thus, I think that trying to allocate from finite static buffers with a fallback to unbuffered printk() upon failure is sufficient. By the way, kbuild test robot told me that I forgot to drop asmlinkage keyword. include/linux/printk.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/include/linux/printk.h b/include/linux/printk.h index 889491b..3347442 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -178,7 +178,7 @@ asmlinkage __printf(1, 2) __cold void flush_printk_buffer(struct printk_buffer *ptr); __printf(2, 3) int buffered_printk(struct printk_buffer *ptr, const char *fmt, ...); -asmlinkage __printf(2, 0) +__printf(2, 0) int buffered_vprintk(struct printk_buffer *ptr, const char *fmt, va_list args); void put_printk_buffer(struct printk_buffer *ptr);
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/14 21:22, Sergey Senozhatsky wrote:
> The "SMP-safe" comment becomes a bit tricky when pr_line is used with a
> static buffer. Either we need to require synchronization - umm... and
> document it - or to provide some means of synchronization in pr_line().
> Let's think what pr_line API should do about it.
>
> Any thoughts?
>
I'm inclined to propose a simple one shown below, similar to just having
several "struct cont" for concurrent printk() users.
What Linus has commented is that implicit context is bad, and below one
uses explicit context.
After almost all users are converted to use below one, we might be able
to get rid of KERN_CONT support.
>From d5e0e422142ced2b7097040e96ba7c5528a460db Mon Sep 17 00:00:00 2001
From: Tetsuo Handa
Date: Wed, 19 Sep 2018 14:39:07 +0900
Subject: [PATCH v2] printk: Add best-effort printk() buffering.
Sometimes we want to printk() a line without being disturbed by concurrent
printk() from interrupts and/or other threads. For example, mixed printk()
output of multiple thread's dump makes it hard to interpret.
Assuming that we will go to a direction that we add context identifier to
each line of printk() output (so that we can group multiple lines into one
block when parsing), this patch introduces functions for using fixed-sized
statically allocated buffers for line-buffering printk() output for best
effort basis (i.e. up to LOG_LINE_MAX bytes, up to 16 concurrent printk()
users).
If there happened to be more than 16 concurrent printk() users, existing
printk() will be used for users who failed to get buffers. Of course, if
there were more than 16 concurrent printk() users, the printk() output
would flood the console and the system would be already unusable (e.g.
RCU lockup or hung task watchdog would fire under such situation). Thus,
I think that 16 buffers should be sufficient.
Five functions (get_printk_buffer(), buffered_vprintk(), buffered_printk(),
flush_printk_buffer() and put_printk_buffer()) are provided for printk()
buffering.
get_printk_buffer() tries to assign a "struct printk_buffer".
buffered_vprintk()/buffered_printk() tries to use line-buffered printk()
by holding incomplete line into "struct printk_buffer".
flush_printk_buffer() flushes the "struct printk_buffer".
put_printk_buffer() flushes and releases the "struct printk_buffer".
put_printk_buffer() must match corresponding get_printk_buffer() as with
rcu_read_unlock() must match corresponding rcu_read_lock().
These functions are safe to be called from any context, for these are
merely wrapping printk()/vprintk() calls in order to minimize possibility
of using "struct cont" by managing 16 buffers outside of the logbuf_lock
spinlock. Thus, any caller can be updated to use these functions.
Signed-off-by: Tetsuo Handa
---
include/linux/printk.h | 28 +
kernel/printk/printk.c | 160 +
2 files changed, 188 insertions(+)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index cf3eccf..889491b 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -157,6 +157,7 @@ static inline void printk_nmi_direct_enter(void) { }
static inline void printk_nmi_direct_exit(void) { }
#endif /* PRINTK_NMI */
+struct printk_buffer;
#ifdef CONFIG_PRINTK
asmlinkage __printf(5, 0)
int vprintk_emit(int facility, int level,
@@ -173,6 +174,13 @@ int printk_emit(int facility, int level,
asmlinkage __printf(1, 2) __cold
int printk(const char *fmt, ...);
+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, ...);
+asmlinkage __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 +228,26 @@ int printk(const char *s, ...)
{
return 0;
}
+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, ...)
{
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9bf5404..c9e9f5d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1949,6 +1949,166 @@ asmlinkage int printk_emit(int facility, int level,
}
EXPORT_SYMBOL(printk_emit);
+struct printk_buffer {
+ unsigned short int used; /* Valid bytes in buf[]. */
+ char buf[LOG_LINE_MAX];
+ bool in_use;
+}
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/14 21:22, Sergey Senozhatsky wrote:
> The "SMP-safe" comment becomes a bit tricky when pr_line is used with a
> static buffer. Either we need to require synchronization - umm... and
> document it - or to provide some means of synchronization in pr_line().
> Let's think what pr_line API should do about it.
>
> Any thoughts?
>
I'm inclined to propose a simple one shown below, similar to just having
several "struct cont" for concurrent printk() users.
What Linus has commented is that implicit context is bad, and below one
uses explicit context.
After almost all users are converted to use below one, we might be able
to get rid of KERN_CONT support.
>From d5e0e422142ced2b7097040e96ba7c5528a460db Mon Sep 17 00:00:00 2001
From: Tetsuo Handa
Date: Wed, 19 Sep 2018 14:39:07 +0900
Subject: [PATCH v2] printk: Add best-effort printk() buffering.
Sometimes we want to printk() a line without being disturbed by concurrent
printk() from interrupts and/or other threads. For example, mixed printk()
output of multiple thread's dump makes it hard to interpret.
Assuming that we will go to a direction that we add context identifier to
each line of printk() output (so that we can group multiple lines into one
block when parsing), this patch introduces functions for using fixed-sized
statically allocated buffers for line-buffering printk() output for best
effort basis (i.e. up to LOG_LINE_MAX bytes, up to 16 concurrent printk()
users).
If there happened to be more than 16 concurrent printk() users, existing
printk() will be used for users who failed to get buffers. Of course, if
there were more than 16 concurrent printk() users, the printk() output
would flood the console and the system would be already unusable (e.g.
RCU lockup or hung task watchdog would fire under such situation). Thus,
I think that 16 buffers should be sufficient.
Five functions (get_printk_buffer(), buffered_vprintk(), buffered_printk(),
flush_printk_buffer() and put_printk_buffer()) are provided for printk()
buffering.
get_printk_buffer() tries to assign a "struct printk_buffer".
buffered_vprintk()/buffered_printk() tries to use line-buffered printk()
by holding incomplete line into "struct printk_buffer".
flush_printk_buffer() flushes the "struct printk_buffer".
put_printk_buffer() flushes and releases the "struct printk_buffer".
put_printk_buffer() must match corresponding get_printk_buffer() as with
rcu_read_unlock() must match corresponding rcu_read_lock().
These functions are safe to be called from any context, for these are
merely wrapping printk()/vprintk() calls in order to minimize possibility
of using "struct cont" by managing 16 buffers outside of the logbuf_lock
spinlock. Thus, any caller can be updated to use these functions.
Signed-off-by: Tetsuo Handa
---
include/linux/printk.h | 28 +
kernel/printk/printk.c | 160 +
2 files changed, 188 insertions(+)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index cf3eccf..889491b 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -157,6 +157,7 @@ static inline void printk_nmi_direct_enter(void) { }
static inline void printk_nmi_direct_exit(void) { }
#endif /* PRINTK_NMI */
+struct printk_buffer;
#ifdef CONFIG_PRINTK
asmlinkage __printf(5, 0)
int vprintk_emit(int facility, int level,
@@ -173,6 +174,13 @@ int printk_emit(int facility, int level,
asmlinkage __printf(1, 2) __cold
int printk(const char *fmt, ...);
+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, ...);
+asmlinkage __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 +228,26 @@ int printk(const char *s, ...)
{
return 0;
}
+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, ...)
{
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9bf5404..c9e9f5d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1949,6 +1949,166 @@ asmlinkage int printk_emit(int facility, int level,
}
EXPORT_SYMBOL(printk_emit);
+struct printk_buffer {
+ unsigned short int used; /* Valid bytes in buf[]. */
+ char buf[LOG_LINE_MAX];
+ bool in_use;
+}
Re: [PATCH] printk: inject caller information into the body of message
On (09/14/18 21:03), Tetsuo Handa wrote: > > 80 bytes is quite short for OOM, agreed. > > > >> static char oom_print_buf[1024]; > >> DEFINE_PR_LINE_BUF(level, oom_print_buf); > > > > Do I get it right that you suggest to drop the "size" param? > > No. I just forgot to add params. ;-) > > > Do OOM people agree on 1024 bytes stack usage? > > I won't allocate oom_print_buf on the stack. Since its usage is serialized > by oom_lock mutex, we don't need to allocate from stack. Since memory > allocation request might happen when stack is already tight, we should not > try to allocate much from stack. ... by "OOM people" I meant "MM people". "MM people" is a subset of "OOM people". OK, so I didn't notice the "static" part of the `oom_print_buf'. I need some rest, I guess. The "SMP-safe" comment becomes a bit tricky when pr_line is used with a static buffer. Either we need to require synchronization - umm... and document it - or to provide some means of synchronization in pr_line(). Let's think what pr_line API should do about it. Any thoughts? -ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/14/18 21:03), Tetsuo Handa wrote: > > 80 bytes is quite short for OOM, agreed. > > > >> static char oom_print_buf[1024]; > >> DEFINE_PR_LINE_BUF(level, oom_print_buf); > > > > Do I get it right that you suggest to drop the "size" param? > > No. I just forgot to add params. ;-) > > > Do OOM people agree on 1024 bytes stack usage? > > I won't allocate oom_print_buf on the stack. Since its usage is serialized > by oom_lock mutex, we don't need to allocate from stack. Since memory > allocation request might happen when stack is already tight, we should not > try to allocate much from stack. ... by "OOM people" I meant "MM people". "MM people" is a subset of "OOM people". OK, so I didn't notice the "static" part of the `oom_print_buf'. I need some rest, I guess. The "SMP-safe" comment becomes a bit tricky when pr_line is used with a static buffer. Either we need to require synchronization - umm... and document it - or to provide some means of synchronization in pr_line(). Let's think what pr_line API should do about it. Any thoughts? -ss
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/14 20:50, Sergey Senozhatsky wrote:
>>> +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
>>> + struct pr_line name = {\
>>> + .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
>>> + .level = lev, \
>>> + }
>>> +
>>
>> I would use this one for the OOM killer. 80 bytes is too short.
>
> 80 bytes is quite short for OOM, agreed.
>
>> static char oom_print_buf[1024];
>> DEFINE_PR_LINE_BUF(level, oom_print_buf);
>
> Do I get it right that you suggest to drop the "size" param?
No. I just forgot to add params. ;-)
> Do OOM people agree on 1024 bytes stack usage?
I won't allocate oom_print_buf on the stack. Since its usage is serialized
by oom_lock mutex, we don't need to allocate from stack. Since memory
allocation request might happen when stack is already tight, we should not
try to allocate much from stack.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/14 20:50, Sergey Senozhatsky wrote:
>>> +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
>>> + struct pr_line name = {\
>>> + .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
>>> + .level = lev, \
>>> + }
>>> +
>>
>> I would use this one for the OOM killer. 80 bytes is too short.
>
> 80 bytes is quite short for OOM, agreed.
>
>> static char oom_print_buf[1024];
>> DEFINE_PR_LINE_BUF(level, oom_print_buf);
>
> Do I get it right that you suggest to drop the "size" param?
No. I just forgot to add params. ;-)
> Do OOM people agree on 1024 bytes stack usage?
I won't allocate oom_print_buf on the stack. Since its usage is serialized
by oom_lock mutex, we don't need to allocate from stack. Since memory
allocation request might happen when stack is already tight, we should not
try to allocate much from stack.
Re: [PATCH] printk: inject caller information into the body of message
On (09/14/18 19:37), Tetsuo Handa wrote:
> > @@ -20,6 +20,9 @@
> > * Annotation for a "continued" line of log printout (only done after a
> > * line that had no enclosing \n). Only to be used by core/arch code
> > * during early bootup (a continued line is not SMP-safe otherwise).
> > + *
> > + * Please consider pr_line()/vpr_line() functions for SMP-safe continued
> > + * line printing.
>
> I think the advantage is not limited to SMP-safeness. Reducing the frequency
> of
> calling printk() will reduce overhead. Also, latency for netconsole will be
> reduced by sending a whole line in one printk().
Hmm. These are very good points, indeed. But do we want to list all
advantages here? I just wanted to mention SMP-unsafe pr_cont/printk(KERN_CONT),
because I also mention pr_line in kern_levels.h.
> > + * Defines a new pr_line varialbe, which would use an implicit
>
> s/varialbe/variable/ .
Thanks.
> > +#define DEFINE_PR_LINE(lev, name) \
> > + char__line_##name[__PR_LINE_BUF_SZ];\
> > + struct pr_line name = {\
> > + .sb = __SEQ_BUF_INITIALIZER(__line_##name, \
> > + __PR_LINE_BUF_SZ), \
> > + .level = lev, \
> > + }
>
> Want a note that
>
> static DEFINE_PR_LINE(lev, name);
>
> won't make "name" variable "static" ?
Interesting point. Any hint what the comment should look like?
Do we want to have static pr_line buffers?
> > +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
> > + struct pr_line name = {\
> > + .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
> > + .level = lev, \
> > + }
> > +
>
> I would use this one for the OOM killer. 80 bytes is too short.
80 bytes is quite short for OOM, agreed.
> static char oom_print_buf[1024];
> DEFINE_PR_LINE_BUF(level, oom_print_buf);
Do I get it right that you suggest to drop the "size" param?
Do OOM people agree on 1024 bytes stack usage?
> > @@ -131,4 +187,8 @@ extern int
> > seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
> > #endif
> >
> > +extern __printf(2, 0)
> > +int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
> > +extern __printf(2, 3)
> > +int pr_line(struct pr_line *pl, const char *fmt, ...);
>
> Do we want to mark "asmlinkage" like printk() ?
Dunno, do we? Does code written in assembly call pr_cont that often?
We are not turning pr_line() into syscall anyway.
> > @@ -324,3 +324,60 @@ int seq_buf_to_user(struct seq_buf *s, char __user
> > *ubuf, int cnt)
> > s->readpos += cnt;
> > return cnt;
> > }
> > +
> > +/**
> > + * vpr_line - Append data to the printk() line buffer
> > + * @pl: the pr_line descriptor
>
> s/descriptor/structure/ ?
Yeah, I used the term "descriptor", just because it's used in seq_buf.c.
So, it's sort of common in seq_buf.
E.g.
seq_buf_vprintf(), seq_buf_print_seq(), seq_buf_can_fit() and so on.
> > + * @fmt: printf format string
> > + * @args: va_list of arguments from a printf() type function
> > + *
> > + * Writes a vnprintf() format into the printk() pr_line buffer.
>
> s/vnprintf/vprintf/ ?
Indeed.
We also need to fix a typo in seq_buf_vprintf() comment then.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/14/18 19:37), Tetsuo Handa wrote:
> > @@ -20,6 +20,9 @@
> > * Annotation for a "continued" line of log printout (only done after a
> > * line that had no enclosing \n). Only to be used by core/arch code
> > * during early bootup (a continued line is not SMP-safe otherwise).
> > + *
> > + * Please consider pr_line()/vpr_line() functions for SMP-safe continued
> > + * line printing.
>
> I think the advantage is not limited to SMP-safeness. Reducing the frequency
> of
> calling printk() will reduce overhead. Also, latency for netconsole will be
> reduced by sending a whole line in one printk().
Hmm. These are very good points, indeed. But do we want to list all
advantages here? I just wanted to mention SMP-unsafe pr_cont/printk(KERN_CONT),
because I also mention pr_line in kern_levels.h.
> > + * Defines a new pr_line varialbe, which would use an implicit
>
> s/varialbe/variable/ .
Thanks.
> > +#define DEFINE_PR_LINE(lev, name) \
> > + char__line_##name[__PR_LINE_BUF_SZ];\
> > + struct pr_line name = {\
> > + .sb = __SEQ_BUF_INITIALIZER(__line_##name, \
> > + __PR_LINE_BUF_SZ), \
> > + .level = lev, \
> > + }
>
> Want a note that
>
> static DEFINE_PR_LINE(lev, name);
>
> won't make "name" variable "static" ?
Interesting point. Any hint what the comment should look like?
Do we want to have static pr_line buffers?
> > +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
> > + struct pr_line name = {\
> > + .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
> > + .level = lev, \
> > + }
> > +
>
> I would use this one for the OOM killer. 80 bytes is too short.
80 bytes is quite short for OOM, agreed.
> static char oom_print_buf[1024];
> DEFINE_PR_LINE_BUF(level, oom_print_buf);
Do I get it right that you suggest to drop the "size" param?
Do OOM people agree on 1024 bytes stack usage?
> > @@ -131,4 +187,8 @@ extern int
> > seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
> > #endif
> >
> > +extern __printf(2, 0)
> > +int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
> > +extern __printf(2, 3)
> > +int pr_line(struct pr_line *pl, const char *fmt, ...);
>
> Do we want to mark "asmlinkage" like printk() ?
Dunno, do we? Does code written in assembly call pr_cont that often?
We are not turning pr_line() into syscall anyway.
> > @@ -324,3 +324,60 @@ int seq_buf_to_user(struct seq_buf *s, char __user
> > *ubuf, int cnt)
> > s->readpos += cnt;
> > return cnt;
> > }
> > +
> > +/**
> > + * vpr_line - Append data to the printk() line buffer
> > + * @pl: the pr_line descriptor
>
> s/descriptor/structure/ ?
Yeah, I used the term "descriptor", just because it's used in seq_buf.c.
So, it's sort of common in seq_buf.
E.g.
seq_buf_vprintf(), seq_buf_print_seq(), seq_buf_can_fit() and so on.
> > + * @fmt: printf format string
> > + * @args: va_list of arguments from a printf() type function
> > + *
> > + * Writes a vnprintf() format into the printk() pr_line buffer.
>
> s/vnprintf/vprintf/ ?
Indeed.
We also need to fix a typo in seq_buf_vprintf() comment then.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/14 15:57, Sergey Senozhatsky wrote:
> On (09/13/18 23:28), Sergey Senozhatsky wrote:
>> Not that I see any problems with pr_line_flush(). But can drop it, sure.
>> pr_line() is a replacement for pr_cont() and as such it's not for multi-line
>> buffering.
>
> OK, attached.
> Let me know if anything needs to improved (including broken English).
> Will we keep in the printk tree or shall I send a formal patch to Andrew?
> @@ -20,6 +20,9 @@
> * Annotation for a "continued" line of log printout (only done after a
> * line that had no enclosing \n). Only to be used by core/arch code
> * during early bootup (a continued line is not SMP-safe otherwise).
> + *
> + * Please consider pr_line()/vpr_line() functions for SMP-safe continued
> + * line printing.
I think the advantage is not limited to SMP-safeness. Reducing the frequency of
calling printk() will reduce overhead. Also, latency for netconsole will be
reduced by sending a whole line in one printk().
> +/**
> + * DEFINE_PR_LINE - define a new pr_line variable
> + * @lev: printk() log level
> + * @name:variable name
> + *
> + * Defines a new pr_line varialbe, which would use an implicit
s/varialbe/variable/ .
> + * stack buffer of size __PR_LINE_BUF_SZ.
> + */
> +#define DEFINE_PR_LINE(lev, name)\
> + char__line_##name[__PR_LINE_BUF_SZ];\
> + struct pr_line name = {\
> + .sb = __SEQ_BUF_INITIALIZER(__line_##name, \
> + __PR_LINE_BUF_SZ), \
> + .level = lev, \
> + }
Want a note that
static DEFINE_PR_LINE(lev, name);
won't make "name" variable "static" ?
> +/**
> + * DEFINE_PR_LINE_BUF - define a new pr_line variable
> + * @lev: printk() log level
> + * @name:variable name
> + * @buf: external buffer
> + * @sz: external buffer size
> + *
> + * Defines a new pr_line variable, which would use an external
> + * buffer for printk line.
> + */
> +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
> + struct pr_line name = {\
> + .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
> + .level = lev, \
> + }
> +
I would use this one for the OOM killer. 80 bytes is too short.
static char oom_print_buf[1024];
DEFINE_PR_LINE_BUF(level, oom_print_buf);
> @@ -131,4 +187,8 @@ extern int
> seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
> #endif
>
> +extern __printf(2, 0)
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
> +extern __printf(2, 3)
> +int pr_line(struct pr_line *pl, const char *fmt, ...);
Do we want to mark "asmlinkage" like printk() ?
> @@ -324,3 +324,60 @@ int seq_buf_to_user(struct seq_buf *s, char __user
> *ubuf, int cnt)
> s->readpos += cnt;
> return cnt;
> }
> +
> +/**
> + * vpr_line - Append data to the printk() line buffer
> + * @pl: the pr_line descriptor
s/descriptor/structure/ ?
> + * @fmt: printf format string
> + * @args: va_list of arguments from a printf() type function
> + *
> + * Writes a vnprintf() format into the printk() pr_line buffer.
s/vnprintf/vprintf/ ?
Re: [PATCH] printk: inject caller information into the body of message
On 2018/09/14 15:57, Sergey Senozhatsky wrote:
> On (09/13/18 23:28), Sergey Senozhatsky wrote:
>> Not that I see any problems with pr_line_flush(). But can drop it, sure.
>> pr_line() is a replacement for pr_cont() and as such it's not for multi-line
>> buffering.
>
> OK, attached.
> Let me know if anything needs to improved (including broken English).
> Will we keep in the printk tree or shall I send a formal patch to Andrew?
> @@ -20,6 +20,9 @@
> * Annotation for a "continued" line of log printout (only done after a
> * line that had no enclosing \n). Only to be used by core/arch code
> * during early bootup (a continued line is not SMP-safe otherwise).
> + *
> + * Please consider pr_line()/vpr_line() functions for SMP-safe continued
> + * line printing.
I think the advantage is not limited to SMP-safeness. Reducing the frequency of
calling printk() will reduce overhead. Also, latency for netconsole will be
reduced by sending a whole line in one printk().
> +/**
> + * DEFINE_PR_LINE - define a new pr_line variable
> + * @lev: printk() log level
> + * @name:variable name
> + *
> + * Defines a new pr_line varialbe, which would use an implicit
s/varialbe/variable/ .
> + * stack buffer of size __PR_LINE_BUF_SZ.
> + */
> +#define DEFINE_PR_LINE(lev, name)\
> + char__line_##name[__PR_LINE_BUF_SZ];\
> + struct pr_line name = {\
> + .sb = __SEQ_BUF_INITIALIZER(__line_##name, \
> + __PR_LINE_BUF_SZ), \
> + .level = lev, \
> + }
Want a note that
static DEFINE_PR_LINE(lev, name);
won't make "name" variable "static" ?
> +/**
> + * DEFINE_PR_LINE_BUF - define a new pr_line variable
> + * @lev: printk() log level
> + * @name:variable name
> + * @buf: external buffer
> + * @sz: external buffer size
> + *
> + * Defines a new pr_line variable, which would use an external
> + * buffer for printk line.
> + */
> +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
> + struct pr_line name = {\
> + .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
> + .level = lev, \
> + }
> +
I would use this one for the OOM killer. 80 bytes is too short.
static char oom_print_buf[1024];
DEFINE_PR_LINE_BUF(level, oom_print_buf);
> @@ -131,4 +187,8 @@ extern int
> seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
> #endif
>
> +extern __printf(2, 0)
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
> +extern __printf(2, 3)
> +int pr_line(struct pr_line *pl, const char *fmt, ...);
Do we want to mark "asmlinkage" like printk() ?
> @@ -324,3 +324,60 @@ int seq_buf_to_user(struct seq_buf *s, char __user
> *ubuf, int cnt)
> s->readpos += cnt;
> return cnt;
> }
> +
> +/**
> + * vpr_line - Append data to the printk() line buffer
> + * @pl: the pr_line descriptor
s/descriptor/structure/ ?
> + * @fmt: printf format string
> + * @args: va_list of arguments from a printf() type function
> + *
> + * Writes a vnprintf() format into the printk() pr_line buffer.
s/vnprintf/vprintf/ ?
Re: [PATCH] printk: inject caller information into the body of message
On (09/13/18 23:28), Sergey Senozhatsky wrote:
> Not that I see any problems with pr_line_flush(). But can drop it, sure.
> pr_line() is a replacement for pr_cont() and as such it's not for multi-line
> buffering.
OK, attached.
Let me know if anything needs to improved (including broken English).
Will we keep in the printk tree or shall I send a formal patch to Andrew?
===
From: Sergey Senozhatsky
Subject: [PATCH] lib/seq_buf: add pr_line buffering API
Signed-off-by: Sergey Senozhatsky
---
include/linux/kern_levels.h | 3 ++
include/linux/seq_buf.h | 60 +
lib/seq_buf.c | 57 +++
3 files changed, 120 insertions(+)
diff --git a/include/linux/kern_levels.h b/include/linux/kern_levels.h
index d237fe854ad9..9c281ac745b3 100644
--- a/include/linux/kern_levels.h
+++ b/include/linux/kern_levels.h
@@ -20,6 +20,9 @@
* Annotation for a "continued" line of log printout (only done after a
* line that had no enclosing \n). Only to be used by core/arch code
* during early bootup (a continued line is not SMP-safe otherwise).
+ *
+ * Please consider pr_line()/vpr_line() functions for SMP-safe continued
+ * line printing.
*/
#define KERN_CONT KERN_SOH "c"
diff --git a/include/linux/seq_buf.h b/include/linux/seq_buf.h
index aa5deb041c25..b33aeea14803 100644
--- a/include/linux/seq_buf.h
+++ b/include/linux/seq_buf.h
@@ -23,6 +23,62 @@ struct seq_buf {
loff_t readpos;
};
+#define __SEQ_BUF_INITIALIZER(buf, length) \
+{ \
+ .buffer = (buf),\
+ .size = (length), \
+ .len= 0,\
+ .readpos= 0,\
+}
+
+#ifdef CONFIG_PRINTK
+#define __PR_LINE_BUF_SZ 80
+#else
+#define __PR_LINE_BUF_SZ 0
+#endif
+
+/**
+ * pr_line - printk() line buffer structure
+ * @sb:underlying seq buffer, which holds the data
+ * @level: printk() log level (KERN_ERR, etc.)
+ */
+struct pr_line {
+ struct seq_buf sb;
+ char*level;
+};
+
+/**
+ * DEFINE_PR_LINE - define a new pr_line variable
+ * @lev: printk() log level
+ * @name: variable name
+ *
+ * Defines a new pr_line varialbe, which would use an implicit
+ * stack buffer of size __PR_LINE_BUF_SZ.
+ */
+#define DEFINE_PR_LINE(lev, name) \
+ char__line_##name[__PR_LINE_BUF_SZ];\
+ struct pr_line name = {\
+ .sb = __SEQ_BUF_INITIALIZER(__line_##name, \
+ __PR_LINE_BUF_SZ), \
+ .level = lev, \
+ }
+
+/**
+ * DEFINE_PR_LINE_BUF - define a new pr_line variable
+ * @lev: printk() log level
+ * @name: variable name
+ * @buf: external buffer
+ * @sz:external buffer size
+ *
+ * Defines a new pr_line variable, which would use an external
+ * buffer for printk line.
+ */
+#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
+ struct pr_line name = {\
+ .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
+ .level = lev, \
+ }
+
static inline void seq_buf_clear(struct seq_buf *s)
{
s->len = 0;
@@ -131,4 +187,8 @@ extern int
seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
#endif
+extern __printf(2, 0)
+int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
+extern __printf(2, 3)
+int pr_line(struct pr_line *pl, const char *fmt, ...);
#endif /* _LINUX_SEQ_BUF_H */
diff --git a/lib/seq_buf.c b/lib/seq_buf.c
index 11f2ae0f9099..fada7623f168 100644
--- a/lib/seq_buf.c
+++ b/lib/seq_buf.c
@@ -324,3 +324,60 @@ int seq_buf_to_user(struct seq_buf *s, char __user *ubuf,
int cnt)
s->readpos += cnt;
return cnt;
}
+
+/**
+ * vpr_line - Append data to the printk() line buffer
+ * @pl: the pr_line descriptor
+ * @fmt: printf format string
+ * @args: va_list of arguments from a printf() type function
+ *
+ * Writes a vnprintf() format into the printk() pr_line buffer.
+ * Terminating new-line symbol flushes (prints) the buffer.
+ *
+ * Unlike pr_cont() and printk(KERN_CONT), this function is SMP-safe
+ * and shall be used for continued line printing.
+ *
+ * Returns zero on success, -1 on overflow.
+ */
+int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
+{
+ struct seq_buf *s = >sb;
+ int ret, len;
+
+ ret = seq_buf_vprintf(s, fmt, args);
+
+ len = seq_buf_used(s);
+ if (len && s->buffer[len - 1] == '\n') {
+ printk("%s%.*s", pl->level ? : KERN_DEFAULT, len, s->buffer);
+
Re: [PATCH] printk: inject caller information into the body of message
On (09/13/18 23:28), Sergey Senozhatsky wrote:
> Not that I see any problems with pr_line_flush(). But can drop it, sure.
> pr_line() is a replacement for pr_cont() and as such it's not for multi-line
> buffering.
OK, attached.
Let me know if anything needs to improved (including broken English).
Will we keep in the printk tree or shall I send a formal patch to Andrew?
===
From: Sergey Senozhatsky
Subject: [PATCH] lib/seq_buf: add pr_line buffering API
Signed-off-by: Sergey Senozhatsky
---
include/linux/kern_levels.h | 3 ++
include/linux/seq_buf.h | 60 +
lib/seq_buf.c | 57 +++
3 files changed, 120 insertions(+)
diff --git a/include/linux/kern_levels.h b/include/linux/kern_levels.h
index d237fe854ad9..9c281ac745b3 100644
--- a/include/linux/kern_levels.h
+++ b/include/linux/kern_levels.h
@@ -20,6 +20,9 @@
* Annotation for a "continued" line of log printout (only done after a
* line that had no enclosing \n). Only to be used by core/arch code
* during early bootup (a continued line is not SMP-safe otherwise).
+ *
+ * Please consider pr_line()/vpr_line() functions for SMP-safe continued
+ * line printing.
*/
#define KERN_CONT KERN_SOH "c"
diff --git a/include/linux/seq_buf.h b/include/linux/seq_buf.h
index aa5deb041c25..b33aeea14803 100644
--- a/include/linux/seq_buf.h
+++ b/include/linux/seq_buf.h
@@ -23,6 +23,62 @@ struct seq_buf {
loff_t readpos;
};
+#define __SEQ_BUF_INITIALIZER(buf, length) \
+{ \
+ .buffer = (buf),\
+ .size = (length), \
+ .len= 0,\
+ .readpos= 0,\
+}
+
+#ifdef CONFIG_PRINTK
+#define __PR_LINE_BUF_SZ 80
+#else
+#define __PR_LINE_BUF_SZ 0
+#endif
+
+/**
+ * pr_line - printk() line buffer structure
+ * @sb:underlying seq buffer, which holds the data
+ * @level: printk() log level (KERN_ERR, etc.)
+ */
+struct pr_line {
+ struct seq_buf sb;
+ char*level;
+};
+
+/**
+ * DEFINE_PR_LINE - define a new pr_line variable
+ * @lev: printk() log level
+ * @name: variable name
+ *
+ * Defines a new pr_line varialbe, which would use an implicit
+ * stack buffer of size __PR_LINE_BUF_SZ.
+ */
+#define DEFINE_PR_LINE(lev, name) \
+ char__line_##name[__PR_LINE_BUF_SZ];\
+ struct pr_line name = {\
+ .sb = __SEQ_BUF_INITIALIZER(__line_##name, \
+ __PR_LINE_BUF_SZ), \
+ .level = lev, \
+ }
+
+/**
+ * DEFINE_PR_LINE_BUF - define a new pr_line variable
+ * @lev: printk() log level
+ * @name: variable name
+ * @buf: external buffer
+ * @sz:external buffer size
+ *
+ * Defines a new pr_line variable, which would use an external
+ * buffer for printk line.
+ */
+#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
+ struct pr_line name = {\
+ .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
+ .level = lev, \
+ }
+
static inline void seq_buf_clear(struct seq_buf *s)
{
s->len = 0;
@@ -131,4 +187,8 @@ extern int
seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
#endif
+extern __printf(2, 0)
+int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
+extern __printf(2, 3)
+int pr_line(struct pr_line *pl, const char *fmt, ...);
#endif /* _LINUX_SEQ_BUF_H */
diff --git a/lib/seq_buf.c b/lib/seq_buf.c
index 11f2ae0f9099..fada7623f168 100644
--- a/lib/seq_buf.c
+++ b/lib/seq_buf.c
@@ -324,3 +324,60 @@ int seq_buf_to_user(struct seq_buf *s, char __user *ubuf,
int cnt)
s->readpos += cnt;
return cnt;
}
+
+/**
+ * vpr_line - Append data to the printk() line buffer
+ * @pl: the pr_line descriptor
+ * @fmt: printf format string
+ * @args: va_list of arguments from a printf() type function
+ *
+ * Writes a vnprintf() format into the printk() pr_line buffer.
+ * Terminating new-line symbol flushes (prints) the buffer.
+ *
+ * Unlike pr_cont() and printk(KERN_CONT), this function is SMP-safe
+ * and shall be used for continued line printing.
+ *
+ * Returns zero on success, -1 on overflow.
+ */
+int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
+{
+ struct seq_buf *s = >sb;
+ int ret, len;
+
+ ret = seq_buf_vprintf(s, fmt, args);
+
+ len = seq_buf_used(s);
+ if (len && s->buffer[len - 1] == '\n') {
+ printk("%s%.*s", pl->level ? : KERN_DEFAULT, len, s->buffer);
+
Re: [PATCH] printk: inject caller information into the body of message
On (09/13/18 21:22), Steven Rostedt wrote:
> > Good call. It was a fast path for pr_cont("\n").
> > But it made me wondering and I did some grepping
> >
>
> [..]
>
> > kernel/trace/ftrace.c: pr_cont("\n expected tramp: %lx\n", ip);
>
> Note, looking at the history of that, I was just combining a lone "\n"
> with the next string. The code before this print add info to the line
> depending on the input, thus none do a "\n". The "expected tramp" part
> is added to the next line, but I'm fine if you want to break this up.
> This print is very unlikely done with other prints happening. It
> happens when modifying (serially) ftrace nops to calls or back to nops.
>
> Feel free to send a patch that breaks it up into:
>
> pr_cont("\n");
> pr_info(" expected tramp: %lx\n", ip);
I didn't mean to criticize anyone with my "Lovely" comment. Sorry if it
appeared to sound harsh.
I'm fine with the way it is, but we *probably* (up to you) will touch
this code once pr_line is available. As of now, the less pr_cont() calls
we make the better. This
pr_cont("a");
pr_cont("b");
pr_cont("c\n");
in the worst case can be log_store-d as 3 log entries (2 preliminary
flushes). So, from this point of view, this
pr_cont("ab");
pr_cont("c\n");
is better, because it can be log_store-d as 2 log entries.
And with pr_line() we can log_store it in 1 log entry [but we will
use some extra stack space for that].
Overall, I counted around 100 cases of printk("\n"), and around 20+ cases
of pr_cont("\n...") and probably around 10 or 15 printk(KERN_CONT "\n")
cases. That's what I meant when I said that converting it to pr_line()
will take us some time. Especially given that some of lockdep developers
have really warm feelings toward printk ;)
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/13/18 21:22), Steven Rostedt wrote:
> > Good call. It was a fast path for pr_cont("\n").
> > But it made me wondering and I did some grepping
> >
>
> [..]
>
> > kernel/trace/ftrace.c: pr_cont("\n expected tramp: %lx\n", ip);
>
> Note, looking at the history of that, I was just combining a lone "\n"
> with the next string. The code before this print add info to the line
> depending on the input, thus none do a "\n". The "expected tramp" part
> is added to the next line, but I'm fine if you want to break this up.
> This print is very unlikely done with other prints happening. It
> happens when modifying (serially) ftrace nops to calls or back to nops.
>
> Feel free to send a patch that breaks it up into:
>
> pr_cont("\n");
> pr_info(" expected tramp: %lx\n", ip);
I didn't mean to criticize anyone with my "Lovely" comment. Sorry if it
appeared to sound harsh.
I'm fine with the way it is, but we *probably* (up to you) will touch
this code once pr_line is available. As of now, the less pr_cont() calls
we make the better. This
pr_cont("a");
pr_cont("b");
pr_cont("c\n");
in the worst case can be log_store-d as 3 log entries (2 preliminary
flushes). So, from this point of view, this
pr_cont("ab");
pr_cont("c\n");
is better, because it can be log_store-d as 2 log entries.
And with pr_line() we can log_store it in 1 log entry [but we will
use some extra stack space for that].
Overall, I counted around 100 cases of printk("\n"), and around 20+ cases
of pr_cont("\n...") and probably around 10 or 15 printk(KERN_CONT "\n")
cases. That's what I meant when I said that converting it to pr_line()
will take us some time. Especially given that some of lockdep developers
have really warm feelings toward printk ;)
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/13/18 21:12), Steven Rostedt wrote:
> >
> > +#define __SEQ_BUF_INITIALIZER(buf, length) {
> > \
> > + .buffer = (buf),\
> > + .size = (length), \
> > + .len= 0,\
> > + .readpos= 0, }
>
> Nit, but the end bracket '}' should be on it's own line. Even when
> part of a macro.
No prob, will change.
I thought about putting it on its own line, but then checked
include/linux/wait.h - __WAITQUEUE_INITIALIZER and
__WAIT_QUEUE_HEAD_INITIALIZER.
> > +#define DEFINE_PR_LINE(lev, name) \
> > + char__line[__PR_LINE_BUF_SZ]; \
>
> To protect against name space collision could you use:
>
> char__line_##name[__PR_LINE_BUF_SZ];
Yes.
> The rest looks fine to me.
>
> Acked-by: Steven Rostedt (VMware)
Thanks.
Just, to make sure, we are OK with seq_buf dependency and want
anyone who wants to use pr_line to include linux/seq_buf.h?
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/13/18 21:12), Steven Rostedt wrote:
> >
> > +#define __SEQ_BUF_INITIALIZER(buf, length) {
> > \
> > + .buffer = (buf),\
> > + .size = (length), \
> > + .len= 0,\
> > + .readpos= 0, }
>
> Nit, but the end bracket '}' should be on it's own line. Even when
> part of a macro.
No prob, will change.
I thought about putting it on its own line, but then checked
include/linux/wait.h - __WAITQUEUE_INITIALIZER and
__WAIT_QUEUE_HEAD_INITIALIZER.
> > +#define DEFINE_PR_LINE(lev, name) \
> > + char__line[__PR_LINE_BUF_SZ]; \
>
> To protect against name space collision could you use:
>
> char__line_##name[__PR_LINE_BUF_SZ];
Yes.
> The rest looks fine to me.
>
> Acked-by: Steven Rostedt (VMware)
Thanks.
Just, to make sure, we are OK with seq_buf dependency and want
anyone who wants to use pr_line to include linux/seq_buf.h?
-ss
Re: [PATCH] printk: inject caller information into the body of message
On Thu, 13 Sep 2018 23:28:02 +0900
Sergey Senozhatsky wrote:
> Good call. It was a fast path for pr_cont("\n").
> But it made me wondering and I did some grepping
>
[..]
> kernel/trace/ftrace.c: pr_cont("\n expected tramp: %lx\n", ip);
Note, looking at the history of that, I was just combining a lone "\n"
with the next string. The code before this print add info to the line
depending on the input, thus none do a "\n". The "expected tramp" part
is added to the next line, but I'm fine if you want to break this up.
This print is very unlikely done with other prints happening. It
happens when modifying (serially) ftrace nops to calls or back to nops.
Feel free to send a patch that breaks it up into:
pr_cont("\n");
pr_info(" expected tramp: %lx\n", ip);
-- Steve
Re: [PATCH] printk: inject caller information into the body of message
On Thu, 13 Sep 2018 23:28:02 +0900
Sergey Senozhatsky wrote:
> Good call. It was a fast path for pr_cont("\n").
> But it made me wondering and I did some grepping
>
[..]
> kernel/trace/ftrace.c: pr_cont("\n expected tramp: %lx\n", ip);
Note, looking at the history of that, I was just combining a lone "\n"
with the next string. The code before this print add info to the line
depending on the input, thus none do a "\n". The "expected tramp" part
is added to the next line, but I'm fine if you want to break this up.
This print is very unlikely done with other prints happening. It
happens when modifying (serially) ftrace nops to calls or back to nops.
Feel free to send a patch that breaks it up into:
pr_cont("\n");
pr_info(" expected tramp: %lx\n", ip);
-- Steve
Re: [PATCH] printk: inject caller information into the body of message
On Thu, 13 Sep 2018 16:12:54 +0900
Sergey Senozhatsky wrote:
Signed-off-by: Sergey Senozhatsky
> ---
> include/linux/seq_buf.h | 35 +++
> lib/seq_buf.c | 46 +
> 2 files changed, 81 insertions(+)
>
> diff --git a/include/linux/seq_buf.h b/include/linux/seq_buf.h
> index aa5deb041c25..5e9a5ff9a440 100644
> --- a/include/linux/seq_buf.h
> +++ b/include/linux/seq_buf.h
> @@ -23,6 +23,36 @@ struct seq_buf {
> loff_t readpos;
> };
>
> +#define __SEQ_BUF_INITIALIZER(buf, length) { \
> + .buffer = (buf),\
> + .size = (length), \
> + .len= 0,\
> + .readpos= 0, }
Nit, but the end bracket '}' should be on it's own line. Even when
part of a macro.
> +
> +#ifdef CONFIG_PRINTK
> +#define __PR_LINE_BUF_SZ 80
> +#else
> +#define __PR_LINE_BUF_SZ 0
> +#endif
> +
> +struct pr_line {
> + struct seq_buf sb;
> + char*level;
> +};
> +
> +#define DEFINE_PR_LINE(lev, name)\
> + char__line[__PR_LINE_BUF_SZ]; \
To protect against name space collision could you use:
char__line_##name[__PR_LINE_BUF_SZ];
> + struct pr_line name = {\
> + .sb = __SEQ_BUF_INITIALIZER(__line, __PR_LINE_BUF_SZ), \
> + .level = lev, \
> + }
> +
> +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz)
> \
> + struct pr_line name = {\
> + .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
> + .level = lev, \
> + }
> +
> static inline void seq_buf_clear(struct seq_buf *s)
> {
> s->len = 0;
> @@ -131,4 +161,9 @@ extern int
> seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
> #endif
>
> +extern __printf(2, 0)
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
> +extern __printf(2, 3)
> +int pr_line(struct pr_line *pl, const char *fmt, ...);
> +extern void pr_line_flush(struct pr_line *pl);
> #endif /* _LINUX_SEQ_BUF_H */
> diff --git a/lib/seq_buf.c b/lib/seq_buf.c
> index 11f2ae0f9099..29bc4f24b83e 100644
> --- a/lib/seq_buf.c
> +++ b/lib/seq_buf.c
> @@ -324,3 +324,49 @@ int seq_buf_to_user(struct seq_buf *s, char __user
> *ubuf, int cnt)
> s->readpos += cnt;
> return cnt;
> }
> +
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
> +{
> + struct seq_buf *s = >sb;
> + int ret, len;
> +
> + if (fmt[0] == '\n') {
> + pr_line_flush(pl);
> + return 0;
> + }
> +
> + ret = seq_buf_vprintf(s, fmt, args);
> +
> + len = seq_buf_used(s);
> + if (len && s->buffer[len - 1] == '\n')
> + pr_line_flush(pl);
> +
> + return ret;
> +}
> +EXPORT_SYMBOL(vpr_line);
> +
> +int pr_line(struct pr_line *pl, const char *fmt, ...)
> +{
> + va_list ap;
> + int ret;
> +
> + va_start(ap, fmt);
> + ret = vpr_line(pl, fmt, ap);
> + va_end(ap);
> +
> + return ret;
> +}
> +EXPORT_SYMBOL(pr_line);
> +
> +void pr_line_flush(struct pr_line *pl)
> +{
> + struct seq_buf *s = >sb;
> + int len = seq_buf_used(s);
> +
> + if (!len)
> + return;
> +
> + printk("%s%.*s", pl->level, len, s->buffer);
> + seq_buf_clear(s);
> +}
> +EXPORT_SYMBOL(pr_line_flush);
The rest looks fine to me.
Acked-by: Steven Rostedt (VMware)
-- Steve
Re: [PATCH] printk: inject caller information into the body of message
On Thu, 13 Sep 2018 16:12:54 +0900
Sergey Senozhatsky wrote:
Signed-off-by: Sergey Senozhatsky
> ---
> include/linux/seq_buf.h | 35 +++
> lib/seq_buf.c | 46 +
> 2 files changed, 81 insertions(+)
>
> diff --git a/include/linux/seq_buf.h b/include/linux/seq_buf.h
> index aa5deb041c25..5e9a5ff9a440 100644
> --- a/include/linux/seq_buf.h
> +++ b/include/linux/seq_buf.h
> @@ -23,6 +23,36 @@ struct seq_buf {
> loff_t readpos;
> };
>
> +#define __SEQ_BUF_INITIALIZER(buf, length) { \
> + .buffer = (buf),\
> + .size = (length), \
> + .len= 0,\
> + .readpos= 0, }
Nit, but the end bracket '}' should be on it's own line. Even when
part of a macro.
> +
> +#ifdef CONFIG_PRINTK
> +#define __PR_LINE_BUF_SZ 80
> +#else
> +#define __PR_LINE_BUF_SZ 0
> +#endif
> +
> +struct pr_line {
> + struct seq_buf sb;
> + char*level;
> +};
> +
> +#define DEFINE_PR_LINE(lev, name)\
> + char__line[__PR_LINE_BUF_SZ]; \
To protect against name space collision could you use:
char__line_##name[__PR_LINE_BUF_SZ];
> + struct pr_line name = {\
> + .sb = __SEQ_BUF_INITIALIZER(__line, __PR_LINE_BUF_SZ), \
> + .level = lev, \
> + }
> +
> +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz)
> \
> + struct pr_line name = {\
> + .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
> + .level = lev, \
> + }
> +
> static inline void seq_buf_clear(struct seq_buf *s)
> {
> s->len = 0;
> @@ -131,4 +161,9 @@ extern int
> seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
> #endif
>
> +extern __printf(2, 0)
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
> +extern __printf(2, 3)
> +int pr_line(struct pr_line *pl, const char *fmt, ...);
> +extern void pr_line_flush(struct pr_line *pl);
> #endif /* _LINUX_SEQ_BUF_H */
> diff --git a/lib/seq_buf.c b/lib/seq_buf.c
> index 11f2ae0f9099..29bc4f24b83e 100644
> --- a/lib/seq_buf.c
> +++ b/lib/seq_buf.c
> @@ -324,3 +324,49 @@ int seq_buf_to_user(struct seq_buf *s, char __user
> *ubuf, int cnt)
> s->readpos += cnt;
> return cnt;
> }
> +
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
> +{
> + struct seq_buf *s = >sb;
> + int ret, len;
> +
> + if (fmt[0] == '\n') {
> + pr_line_flush(pl);
> + return 0;
> + }
> +
> + ret = seq_buf_vprintf(s, fmt, args);
> +
> + len = seq_buf_used(s);
> + if (len && s->buffer[len - 1] == '\n')
> + pr_line_flush(pl);
> +
> + return ret;
> +}
> +EXPORT_SYMBOL(vpr_line);
> +
> +int pr_line(struct pr_line *pl, const char *fmt, ...)
> +{
> + va_list ap;
> + int ret;
> +
> + va_start(ap, fmt);
> + ret = vpr_line(pl, fmt, ap);
> + va_end(ap);
> +
> + return ret;
> +}
> +EXPORT_SYMBOL(pr_line);
> +
> +void pr_line_flush(struct pr_line *pl)
> +{
> + struct seq_buf *s = >sb;
> + int len = seq_buf_used(s);
> +
> + if (!len)
> + return;
> +
> + printk("%s%.*s", pl->level, len, s->buffer);
> + seq_buf_clear(s);
> +}
> +EXPORT_SYMBOL(pr_line_flush);
The rest looks fine to me.
Acked-by: Steven Rostedt (VMware)
-- Steve
Re: [PATCH] printk: inject caller information into the body of message
On (09/13/18 14:26), Petr Mladek wrote:
> > +
> > +int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
> > +{
> > + struct seq_buf *s = >sb;
> > + int ret, len;
> > +
> > + if (fmt[0] == '\n') {
> > + pr_line_flush(pl);
> > + return 0;
> > + }
>
> You would need to check if fmt[1] == '\0'. But then you would need
> to be careful about a possible buffer overflow. I would personally
> avoid this optimization.
Good call. It was a fast path for pr_cont("\n").
But it made me wondering and I did some grepping
arch/m68k/kernel/traps.c: pr_cont("\n ");
arch/m68k/kernel/traps.c: pr_cont("\n ");
kernel/trace/ftrace.c: pr_cont("\n expected tramp: %lx\n", ip);
Lovely.
It will take us some time.
> > + ret = seq_buf_vprintf(s, fmt, args);
> > +
> > + len = seq_buf_used(s);
> > + if (len && s->buffer[len - 1] == '\n')
> > + pr_line_flush(pl);
>
> This would cause that pr_line_flush() won't be strictly needed.
> Also it would encourage people to use this feature a more
> complicated way (for more lines). Do we really want this?
Not that I see any problems with pr_line_flush(). But can drop it, sure.
pr_line() is a replacement for pr_cont() and as such it's not for multi-line
buffering.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (09/13/18 14:26), Petr Mladek wrote:
> > +
> > +int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
> > +{
> > + struct seq_buf *s = >sb;
> > + int ret, len;
> > +
> > + if (fmt[0] == '\n') {
> > + pr_line_flush(pl);
> > + return 0;
> > + }
>
> You would need to check if fmt[1] == '\0'. But then you would need
> to be careful about a possible buffer overflow. I would personally
> avoid this optimization.
Good call. It was a fast path for pr_cont("\n").
But it made me wondering and I did some grepping
arch/m68k/kernel/traps.c: pr_cont("\n ");
arch/m68k/kernel/traps.c: pr_cont("\n ");
kernel/trace/ftrace.c: pr_cont("\n expected tramp: %lx\n", ip);
Lovely.
It will take us some time.
> > + ret = seq_buf_vprintf(s, fmt, args);
> > +
> > + len = seq_buf_used(s);
> > + if (len && s->buffer[len - 1] == '\n')
> > + pr_line_flush(pl);
>
> This would cause that pr_line_flush() won't be strictly needed.
> Also it would encourage people to use this feature a more
> complicated way (for more lines). Do we really want this?
Not that I see any problems with pr_line_flush(). But can drop it, sure.
pr_line() is a replacement for pr_cont() and as such it's not for multi-line
buffering.
-ss
Re: [PATCH] printk: inject caller information into the body of message
On Thu 2018-09-13 16:12:54, Sergey Senozhatsky wrote:
> On (09/12/18 12:05), Steven Rostedt wrote:
> > > : Introduce a few helper functions for it:
> > > :
> > > : init_line_buffer();
> > > : print_line(, fmt, args);
> > > : vprint_line(, fmt, vararg);
> > > : finish_line();
> > > :
> >
> --- a/lib/seq_buf.c
> +++ b/lib/seq_buf.c
> @@ -324,3 +324,49 @@ int seq_buf_to_user(struct seq_buf *s, char __user
> *ubuf, int cnt)
> s->readpos += cnt;
> return cnt;
> }
> +
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
> +{
> + struct seq_buf *s = >sb;
> + int ret, len;
> +
> + if (fmt[0] == '\n') {
> + pr_line_flush(pl);
> + return 0;
> + }
You would need to check if fmt[1] == '\0'. But then you would need
to be careful about a possible buffer overflow. I would personally
avoid this optimization.
> + ret = seq_buf_vprintf(s, fmt, args);
> +
> + len = seq_buf_used(s);
> + if (len && s->buffer[len - 1] == '\n')
> + pr_line_flush(pl);
This would cause that pr_line_flush() won't be strictly needed.
Also it would encourage people to use this feature a more
complicated way (for more lines). Do we really want this?
In general, I like this approach more than any attemps to handle
continuous lines transpatently. The other attemps were much more
complicated or were not reliable.
Best Regards,
Petr
Re: [PATCH] printk: inject caller information into the body of message
On Thu 2018-09-13 16:12:54, Sergey Senozhatsky wrote:
> On (09/12/18 12:05), Steven Rostedt wrote:
> > > : Introduce a few helper functions for it:
> > > :
> > > : init_line_buffer();
> > > : print_line(, fmt, args);
> > > : vprint_line(, fmt, vararg);
> > > : finish_line();
> > > :
> >
> --- a/lib/seq_buf.c
> +++ b/lib/seq_buf.c
> @@ -324,3 +324,49 @@ int seq_buf_to_user(struct seq_buf *s, char __user
> *ubuf, int cnt)
> s->readpos += cnt;
> return cnt;
> }
> +
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
> +{
> + struct seq_buf *s = >sb;
> + int ret, len;
> +
> + if (fmt[0] == '\n') {
> + pr_line_flush(pl);
> + return 0;
> + }
You would need to check if fmt[1] == '\0'. But then you would need
to be careful about a possible buffer overflow. I would personally
avoid this optimization.
> + ret = seq_buf_vprintf(s, fmt, args);
> +
> + len = seq_buf_used(s);
> + if (len && s->buffer[len - 1] == '\n')
> + pr_line_flush(pl);
This would cause that pr_line_flush() won't be strictly needed.
Also it would encourage people to use this feature a more
complicated way (for more lines). Do we really want this?
In general, I like this approach more than any attemps to handle
continuous lines transpatently. The other attemps were much more
complicated or were not reliable.
Best Regards,
Petr
Re: [PATCH] printk: inject caller information into the body of message
Hi, Steven
On (09/12/18 12:05), Steven Rostedt wrote:
> > : Introduce a few helper functions for it:
> > :
> > : init_line_buffer();
> > : print_line(, fmt, args);
> > : vprint_line(, fmt, vararg);
> > : finish_line();
> > :
>
> This sounds like seq_buf to me.
Correct.
> > +struct pr_line {
> > + char*buffer;
> > + int size;
> > + int len;
> > + char*level;
> > +};
>
> Can you look at implementing this with using a seq_buf?
Certainly, attached.
It doesn't seem to save us that much code, tho. It looks smaller just
because I dropped "truncated" print out and didn't include !CONFIG_PRINTK
noise this time around. And the OK thing about previous version was that
it didn't introduce any new dependencies to printk.
Making pr_line available via printk.h -- #include seq_buf.h in printk.h - at
glance looks like some fun. printk.h is getting included very early, before
we have all the stuff that seq_buf.h wants - we can remove fs.h from
seq_buf.h and add a bunch of forward declarations for path and seq_file;
but all those BUG_ON/WARN_ON/etc is another story (unless we want every
pr_line user to include seq_buf.h).
... maybe I can change API. But I sort of like that implicit buffer case:
DEFINE_PR_LINE(KERN_ERR, pl);
pr_line(, "Hello, ");
pr_line(, "%s.\n", "Steven");
And, looking at potential users of pr_line, I'd say that we better
have DEFINE_PR_LINE_BUF, because some of them do print messages longer
than 80 chars.
===
From: Sergey Senozhatsky
Subject: [PATCH] lib/seq_buf: add pr_line buffering API
Signed-off-by: Sergey Senozhatsky
---
include/linux/seq_buf.h | 35 +++
lib/seq_buf.c | 46 +
2 files changed, 81 insertions(+)
diff --git a/include/linux/seq_buf.h b/include/linux/seq_buf.h
index aa5deb041c25..5e9a5ff9a440 100644
--- a/include/linux/seq_buf.h
+++ b/include/linux/seq_buf.h
@@ -23,6 +23,36 @@ struct seq_buf {
loff_t readpos;
};
+#define __SEQ_BUF_INITIALIZER(buf, length) { \
+ .buffer = (buf),\
+ .size = (length), \
+ .len= 0,\
+ .readpos= 0, }
+
+#ifdef CONFIG_PRINTK
+#define __PR_LINE_BUF_SZ 80
+#else
+#define __PR_LINE_BUF_SZ 0
+#endif
+
+struct pr_line {
+ struct seq_buf sb;
+ char*level;
+};
+
+#define DEFINE_PR_LINE(lev, name) \
+ char__line[__PR_LINE_BUF_SZ]; \
+ struct pr_line name = {\
+ .sb = __SEQ_BUF_INITIALIZER(__line, __PR_LINE_BUF_SZ), \
+ .level = lev, \
+ }
+
+#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
+ struct pr_line name = {\
+ .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
+ .level = lev, \
+ }
+
static inline void seq_buf_clear(struct seq_buf *s)
{
s->len = 0;
@@ -131,4 +161,9 @@ extern int
seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
#endif
+extern __printf(2, 0)
+int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
+extern __printf(2, 3)
+int pr_line(struct pr_line *pl, const char *fmt, ...);
+extern void pr_line_flush(struct pr_line *pl);
#endif /* _LINUX_SEQ_BUF_H */
diff --git a/lib/seq_buf.c b/lib/seq_buf.c
index 11f2ae0f9099..29bc4f24b83e 100644
--- a/lib/seq_buf.c
+++ b/lib/seq_buf.c
@@ -324,3 +324,49 @@ int seq_buf_to_user(struct seq_buf *s, char __user *ubuf,
int cnt)
s->readpos += cnt;
return cnt;
}
+
+int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
+{
+ struct seq_buf *s = >sb;
+ int ret, len;
+
+ if (fmt[0] == '\n') {
+ pr_line_flush(pl);
+ return 0;
+ }
+
+ ret = seq_buf_vprintf(s, fmt, args);
+
+ len = seq_buf_used(s);
+ if (len && s->buffer[len - 1] == '\n')
+ pr_line_flush(pl);
+
+ return ret;
+}
+EXPORT_SYMBOL(vpr_line);
+
+int pr_line(struct pr_line *pl, const char *fmt, ...)
+{
+ va_list ap;
+ int ret;
+
+ va_start(ap, fmt);
+ ret = vpr_line(pl, fmt, ap);
+ va_end(ap);
+
+ return ret;
+}
+EXPORT_SYMBOL(pr_line);
+
+void pr_line_flush(struct pr_line *pl)
+{
+ struct seq_buf *s = >sb;
+ int len = seq_buf_used(s);
+
+ if (!len)
+ return;
+
+ printk("%s%.*s", pl->level, len, s->buffer);
+ seq_buf_clear(s);
+}
+EXPORT_SYMBOL(pr_line_flush);
--
2.19.0
Re: [PATCH] printk: inject caller information into the body of message
Hi, Steven
On (09/12/18 12:05), Steven Rostedt wrote:
> > : Introduce a few helper functions for it:
> > :
> > : init_line_buffer();
> > : print_line(, fmt, args);
> > : vprint_line(, fmt, vararg);
> > : finish_line();
> > :
>
> This sounds like seq_buf to me.
Correct.
> > +struct pr_line {
> > + char*buffer;
> > + int size;
> > + int len;
> > + char*level;
> > +};
>
> Can you look at implementing this with using a seq_buf?
Certainly, attached.
It doesn't seem to save us that much code, tho. It looks smaller just
because I dropped "truncated" print out and didn't include !CONFIG_PRINTK
noise this time around. And the OK thing about previous version was that
it didn't introduce any new dependencies to printk.
Making pr_line available via printk.h -- #include seq_buf.h in printk.h - at
glance looks like some fun. printk.h is getting included very early, before
we have all the stuff that seq_buf.h wants - we can remove fs.h from
seq_buf.h and add a bunch of forward declarations for path and seq_file;
but all those BUG_ON/WARN_ON/etc is another story (unless we want every
pr_line user to include seq_buf.h).
... maybe I can change API. But I sort of like that implicit buffer case:
DEFINE_PR_LINE(KERN_ERR, pl);
pr_line(, "Hello, ");
pr_line(, "%s.\n", "Steven");
And, looking at potential users of pr_line, I'd say that we better
have DEFINE_PR_LINE_BUF, because some of them do print messages longer
than 80 chars.
===
From: Sergey Senozhatsky
Subject: [PATCH] lib/seq_buf: add pr_line buffering API
Signed-off-by: Sergey Senozhatsky
---
include/linux/seq_buf.h | 35 +++
lib/seq_buf.c | 46 +
2 files changed, 81 insertions(+)
diff --git a/include/linux/seq_buf.h b/include/linux/seq_buf.h
index aa5deb041c25..5e9a5ff9a440 100644
--- a/include/linux/seq_buf.h
+++ b/include/linux/seq_buf.h
@@ -23,6 +23,36 @@ struct seq_buf {
loff_t readpos;
};
+#define __SEQ_BUF_INITIALIZER(buf, length) { \
+ .buffer = (buf),\
+ .size = (length), \
+ .len= 0,\
+ .readpos= 0, }
+
+#ifdef CONFIG_PRINTK
+#define __PR_LINE_BUF_SZ 80
+#else
+#define __PR_LINE_BUF_SZ 0
+#endif
+
+struct pr_line {
+ struct seq_buf sb;
+ char*level;
+};
+
+#define DEFINE_PR_LINE(lev, name) \
+ char__line[__PR_LINE_BUF_SZ]; \
+ struct pr_line name = {\
+ .sb = __SEQ_BUF_INITIALIZER(__line, __PR_LINE_BUF_SZ), \
+ .level = lev, \
+ }
+
+#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
+ struct pr_line name = {\
+ .sb = __SEQ_BUF_INITIALIZER(buf, (sz)), \
+ .level = lev, \
+ }
+
static inline void seq_buf_clear(struct seq_buf *s)
{
s->len = 0;
@@ -131,4 +161,9 @@ extern int
seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary);
#endif
+extern __printf(2, 0)
+int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
+extern __printf(2, 3)
+int pr_line(struct pr_line *pl, const char *fmt, ...);
+extern void pr_line_flush(struct pr_line *pl);
#endif /* _LINUX_SEQ_BUF_H */
diff --git a/lib/seq_buf.c b/lib/seq_buf.c
index 11f2ae0f9099..29bc4f24b83e 100644
--- a/lib/seq_buf.c
+++ b/lib/seq_buf.c
@@ -324,3 +324,49 @@ int seq_buf_to_user(struct seq_buf *s, char __user *ubuf,
int cnt)
s->readpos += cnt;
return cnt;
}
+
+int vpr_line(struct pr_line *pl, const char *fmt, va_list args)
+{
+ struct seq_buf *s = >sb;
+ int ret, len;
+
+ if (fmt[0] == '\n') {
+ pr_line_flush(pl);
+ return 0;
+ }
+
+ ret = seq_buf_vprintf(s, fmt, args);
+
+ len = seq_buf_used(s);
+ if (len && s->buffer[len - 1] == '\n')
+ pr_line_flush(pl);
+
+ return ret;
+}
+EXPORT_SYMBOL(vpr_line);
+
+int pr_line(struct pr_line *pl, const char *fmt, ...)
+{
+ va_list ap;
+ int ret;
+
+ va_start(ap, fmt);
+ ret = vpr_line(pl, fmt, ap);
+ va_end(ap);
+
+ return ret;
+}
+EXPORT_SYMBOL(pr_line);
+
+void pr_line_flush(struct pr_line *pl)
+{
+ struct seq_buf *s = >sb;
+ int len = seq_buf_used(s);
+
+ if (!len)
+ return;
+
+ printk("%s%.*s", pl->level, len, s->buffer);
+ seq_buf_clear(s);
+}
+EXPORT_SYMBOL(pr_line_flush);
--
2.19.0
Re: [PATCH] printk: inject caller information into the body of message
On Wed, 12 Sep 2018 15:53:07 +0900
Sergey Senozhatsky wrote:
> I scanned some of Linus' emails, and skimmed through previous discussions
> on this topic. Let me quote Linus:
>
> :
> : My preference as a user is actually to just have a dynamically
> : re-sizable buffer (that's pretty much what I've done in *every* single
> : user space project I've had in the last decade), but because some
> : users might have atomicity issues I do suspect that we should just use
> : a stack buffer.
> :
> : And then perhaps say that the buffer size has to be capped at 80 characters.
> :
> : Because if you're printing more than 80 characters and expecting it
> : all to fit on a line, you're doing something else wrong anyway.
> :
> : And hide it not as a explicit "char buffer[80]]" allocation, but as a
> : "struct line_buffer" or similar, so that
> :
> : (a) people don't get the line size wrong
> :
> : (b) the buffering code can add a few fields for length etc in there too
> :
> : Introduce a few helper functions for it:
> :
> : init_line_buffer();
> : print_line(, fmt, args);
> : vprint_line(, fmt, vararg);
> : finish_line();
> :
This sounds like seq_buf to me.
>
>
>
> And this is, basically, what I have attached to this email. It's very
> simple and very short. And I think this is what Linus wanted us to do.
>
> - usage example
>
>DEFINE_PR_LINE(KERN_ERR, pl);
>
>pr_line(, "Hello, %s!\n", "buffer");
>pr_line(, "%s", "OK.\n");
>pr_line(, "Goodbye, %s", "buffer");
>pr_line(, "\n");
>
> dmesg | tail
>
> [ 69.908542] Hello, buffer!
> [ 69.908544] OK.
> [ 69.908545] Goodbye, buffer
>
>
> - pr_cont-like usage
>
>DEFINE_PR_LINE(KERN_ERR, pl);
>
>pr_line(,"%d ", 1);
>pr_line(,"%d ", 3);
>pr_line(,"%d ", 5);
>pr_line(,"%d ", 7);
>pr_line(,"%d\n", 9);
>
> dmesg | tail
>
> [ 69.908546] 1 3 5 7 9
>
>
> - An explicit, aux buffer // output should be truncated
>
>char buf[16];
>DEFINE_PR_LINE_BUF(KERN_ERR, ps, buf, sizeof(buf));
>
>pr_line(, "Test test test test test test test test test\n");
>pr_line(, "\n");
>
>
> dmesg | tail
>
> [ 69.908547] Test test test ** truncated **
>
>
> Opinions? Will this work for us?
>
>
>
> >From 7fd8407e0081d8979f08dec48e88364d6210b4ab Mon Sep 17 00:00:00 2001
> From: Sergey Senozhatsky
> Subject: [PATCH] printk: add pr_line buffering API
>
> Signed-off-by: Sergey Senozhatsky
> ---
> include/linux/printk.h | 63 ++
> kernel/printk/printk.c | 55
> 2 files changed, 118 insertions(+)
>
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index cf3eccfe1543..fc5f11c7579c 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -157,6 +157,15 @@ static inline void printk_nmi_direct_enter(void) { }
> static inline void printk_nmi_direct_exit(void) { }
> #endif /* PRINTK_NMI */
>
> +#define PRINTK_PR_LINE_BUF_SZ80
> +
> +struct pr_line {
> + char*buffer;
> + int size;
> + int len;
> + char*level;
> +};
Can you look at implementing this with using a seq_buf?
-- Steve
> +
> #ifdef CONFIG_PRINTK
> asmlinkage __printf(5, 0)
> int vprintk_emit(int facility, int level,
> @@ -209,6 +218,30 @@ extern asmlinkage void dump_stack(void) __cold;
> extern void printk_safe_init(void);
> extern void printk_safe_flush(void);
> extern void printk_safe_flush_on_panic(void);
> +
> +#define DEFINE_PR_LINE(lev, name)\
> + char__pr_line_buf[PRINTK_PR_LINE_BUF_SZ]; \
> + struct pr_line name = {\
> + .buffer = __pr_line_buf,\
> + .size = PRINTK_PR_LINE_BUF_SZ,\
> + .len= 0,\
> + .level = lev, \
> + }
> +
> +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
> + struct pr_line name = {\
> + .buffer = buf, \
> + .size = (sz), \
> + .len= 0,\
> + .level = lev, \
> + }
> +
> +extern __printf(2, 3)
> +int pr_line(struct pr_line *pl, const char *fmt, ...);
> +extern __printf(2, 0)
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
> +extern void pr_line_flush(struct pr_line *pl);
> +
> #else
> static inline __printf(1, 0)
> int vprintk(const char *s, va_list args)
> @@ -284,6 +317,36 @@ static inline void printk_safe_flush(void)
> static inline void printk_safe_flush_on_panic(void)
> {
> }
> +
> +#define DEFINE_PR_LINE(lev,
Re: [PATCH] printk: inject caller information into the body of message
On Wed, 12 Sep 2018 15:53:07 +0900
Sergey Senozhatsky wrote:
> I scanned some of Linus' emails, and skimmed through previous discussions
> on this topic. Let me quote Linus:
>
> :
> : My preference as a user is actually to just have a dynamically
> : re-sizable buffer (that's pretty much what I've done in *every* single
> : user space project I've had in the last decade), but because some
> : users might have atomicity issues I do suspect that we should just use
> : a stack buffer.
> :
> : And then perhaps say that the buffer size has to be capped at 80 characters.
> :
> : Because if you're printing more than 80 characters and expecting it
> : all to fit on a line, you're doing something else wrong anyway.
> :
> : And hide it not as a explicit "char buffer[80]]" allocation, but as a
> : "struct line_buffer" or similar, so that
> :
> : (a) people don't get the line size wrong
> :
> : (b) the buffering code can add a few fields for length etc in there too
> :
> : Introduce a few helper functions for it:
> :
> : init_line_buffer();
> : print_line(, fmt, args);
> : vprint_line(, fmt, vararg);
> : finish_line();
> :
This sounds like seq_buf to me.
>
>
>
> And this is, basically, what I have attached to this email. It's very
> simple and very short. And I think this is what Linus wanted us to do.
>
> - usage example
>
>DEFINE_PR_LINE(KERN_ERR, pl);
>
>pr_line(, "Hello, %s!\n", "buffer");
>pr_line(, "%s", "OK.\n");
>pr_line(, "Goodbye, %s", "buffer");
>pr_line(, "\n");
>
> dmesg | tail
>
> [ 69.908542] Hello, buffer!
> [ 69.908544] OK.
> [ 69.908545] Goodbye, buffer
>
>
> - pr_cont-like usage
>
>DEFINE_PR_LINE(KERN_ERR, pl);
>
>pr_line(,"%d ", 1);
>pr_line(,"%d ", 3);
>pr_line(,"%d ", 5);
>pr_line(,"%d ", 7);
>pr_line(,"%d\n", 9);
>
> dmesg | tail
>
> [ 69.908546] 1 3 5 7 9
>
>
> - An explicit, aux buffer // output should be truncated
>
>char buf[16];
>DEFINE_PR_LINE_BUF(KERN_ERR, ps, buf, sizeof(buf));
>
>pr_line(, "Test test test test test test test test test\n");
>pr_line(, "\n");
>
>
> dmesg | tail
>
> [ 69.908547] Test test test ** truncated **
>
>
> Opinions? Will this work for us?
>
>
>
> >From 7fd8407e0081d8979f08dec48e88364d6210b4ab Mon Sep 17 00:00:00 2001
> From: Sergey Senozhatsky
> Subject: [PATCH] printk: add pr_line buffering API
>
> Signed-off-by: Sergey Senozhatsky
> ---
> include/linux/printk.h | 63 ++
> kernel/printk/printk.c | 55
> 2 files changed, 118 insertions(+)
>
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index cf3eccfe1543..fc5f11c7579c 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -157,6 +157,15 @@ static inline void printk_nmi_direct_enter(void) { }
> static inline void printk_nmi_direct_exit(void) { }
> #endif /* PRINTK_NMI */
>
> +#define PRINTK_PR_LINE_BUF_SZ80
> +
> +struct pr_line {
> + char*buffer;
> + int size;
> + int len;
> + char*level;
> +};
Can you look at implementing this with using a seq_buf?
-- Steve
> +
> #ifdef CONFIG_PRINTK
> asmlinkage __printf(5, 0)
> int vprintk_emit(int facility, int level,
> @@ -209,6 +218,30 @@ extern asmlinkage void dump_stack(void) __cold;
> extern void printk_safe_init(void);
> extern void printk_safe_flush(void);
> extern void printk_safe_flush_on_panic(void);
> +
> +#define DEFINE_PR_LINE(lev, name)\
> + char__pr_line_buf[PRINTK_PR_LINE_BUF_SZ]; \
> + struct pr_line name = {\
> + .buffer = __pr_line_buf,\
> + .size = PRINTK_PR_LINE_BUF_SZ,\
> + .len= 0,\
> + .level = lev, \
> + }
> +
> +#define DEFINE_PR_LINE_BUF(lev, name, buf, sz) \
> + struct pr_line name = {\
> + .buffer = buf, \
> + .size = (sz), \
> + .len= 0,\
> + .level = lev, \
> + }
> +
> +extern __printf(2, 3)
> +int pr_line(struct pr_line *pl, const char *fmt, ...);
> +extern __printf(2, 0)
> +int vpr_line(struct pr_line *pl, const char *fmt, va_list args);
> +extern void pr_line_flush(struct pr_line *pl);
> +
> #else
> static inline __printf(1, 0)
> int vprintk(const char *s, va_list args)
> @@ -284,6 +317,36 @@ static inline void printk_safe_flush(void)
> static inline void printk_safe_flush_on_panic(void)
> {
> }
> +
> +#define DEFINE_PR_LINE(lev,
Re: [PATCH] printk: inject caller information into the body of message
On (09/10/18 13:20), Alexander Potapenko wrote:
> > Awesome. If you and Fengguang can combine forces and lead the
> > whole thing towards "we couldn't care of pr_cont() less", it
> > would be really huge. Go for it!
>
> Sorry, folks, am I understanding right that pr_cont() and flushing the
> buffer on "\n" are two separate problems that can be handled outside
> Tetsuo's patchset, just assuming pr_cont() is unsupported?
> Or should the pr_cont() cleanup be a prerequisite for that?
Oh... Sorry. I'm quite overloaded at the moment and simply forgot about
this thread.
So what is exactly our problem with pr_cont -- it's not SMP friendly.
And this leads to various things, the most annoying of which is a
preliminary flush.
E.g. let me do a simple thing on my box:
ps aux | grep firefox
kill 2727
dmesg | tail
[ 554.098341] Chrome_~dThread[2823]: segfault at 0 ip 7f5df153a1f3 sp
7f5ded47ab00 error 6 in libxul.so[7f5df1531000+4b01000]
[ 554.098348] Code: e7 04 48 8d 15 a6 94 ae 03 48 89 10 c7 04 25 00 00 00 00
00 00 00 00 0f 0b 48 8b 05 57 d0 e7 04 48 8d 0d b0 94 ae 03 48 89 08 04 25
00 00 00 00 00 00 00 00 0f 0b e8 4d f4 ff ff 48 8b 05 34
[ 554.109418] Chrome_~dThread[3047]: segfault at 0 ip 7f3d5bdba1f3 sp
7f3d57cfab00 error 6
[ 554.109421] Chrome_~dThread[3077]: segfault at 0 ip 7fe773f661f3 sp
7fe76fea6b00 error 6
[ 554.109424] in libxul.so[7f3d5bdb1000+4b01000]
[ 554.109426] in libxul.so[7fe773f5d000+4b01000]
[ 554.109429] Code: e7 04 48 8d 15 a6 94 ae 03 48 89 10 c7 04 25 00 00 00 00
00 00 00 00 0f 0b 48 8b 05 57 d0 e7 04 48 8d 0d b0 94 ae 03 48 89 08 04 25
00 00 00 00 00 00 00 00 0f 0b e8 4d f4 ff ff 48 8b 05 34
Even such a simple thing as "printk several lines per-crashed process"
is broken. Look at line #0 and lines #2-#5.
And this is the only problem we probably need to address. Overlapping
printk lines -- when several CPUs printk simultaneously, or same CPUs
printk-s from IRQ, etc -- are here by design and it's not going to be
easy to change that (and maybe we shouldn't try).
Buffering multiple lines in printk buffer does not look so simple and
perhaps we should not try to do this, as well. Why:
- it's hard to decide what to do when buffer overflows
Switching to "normal printk" defeats the reason we do buffering in the
first place. Because "normal printk" permits overlapping. So buffering
makes a little sense if we are OK with switching to a "normal printk".
- the more we buffer the more we can lose in case of panic.
We can't flush_on_panic() printk buffers which were allocated on stack.
- flushing multiple lines should be more complex than just a simple
printk loop
while (1) {
x = memchr(buf, '\n', sz);
...
print("%s", buf);
...
}
Because "printk() loop" permits lines overlap. Hence buffering makes
little sense, once again.
So let's reduce the problem scope to "we want to have a replacement for
pr_cont()". And let's address pr_cont()'s "preliminary flush" issue only.
I scanned some of Linus' emails, and skimmed through previous discussions
on this topic. Let me quote Linus:
:
: My preference as a user is actually to just have a dynamically
: re-sizable buffer (that's pretty much what I've done in *every* single
: user space project I've had in the last decade), but because some
: users might have atomicity issues I do suspect that we should just use
: a stack buffer.
:
: And then perhaps say that the buffer size has to be capped at 80 characters.
:
: Because if you're printing more than 80 characters and expecting it
: all to fit on a line, you're doing something else wrong anyway.
:
: And hide it not as a explicit "char buffer[80]]" allocation, but as a
: "struct line_buffer" or similar, so that
:
: (a) people don't get the line size wrong
:
: (b) the buffering code can add a few fields for length etc in there too
:
: Introduce a few helper functions for it:
:
: init_line_buffer();
: print_line(, fmt, args);
: vprint_line(, fmt, vararg);
: finish_line();
:
And this is, basically, what I have attached to this email. It's very
simple and very short. And I think this is what Linus wanted us to do.
- usage example
DEFINE_PR_LINE(KERN_ERR, pl);
pr_line(, "Hello, %s!\n", "buffer");
pr_line(, "%s", "OK.\n");
pr_line(, "Goodbye, %s", "buffer");
pr_line(, "\n");
dmesg | tail
[ 69.908542] Hello, buffer!
[ 69.908544] OK.
[ 69.908545] Goodbye, buffer
- pr_cont-like usage
DEFINE_PR_LINE(KERN_ERR, pl);
pr_line(,"%d ", 1);
pr_line(,"%d ", 3);
pr_line(,"%d ", 5);
pr_line(,"%d ", 7);
pr_line(,"%d\n", 9);
dmesg | tail
[ 69.908546] 1 3 5 7 9
- An explicit, aux buffer // output should be truncated
char buf[16];
DEFINE_PR_LINE_BUF(KERN_ERR, ps, buf, sizeof(buf));
pr_line(, "Test test test test test test test test test\n");
pr_line(, "\n");
dmesg | tail
[
Re: [PATCH] printk: inject caller information into the body of message
On (09/10/18 13:20), Alexander Potapenko wrote:
> > Awesome. If you and Fengguang can combine forces and lead the
> > whole thing towards "we couldn't care of pr_cont() less", it
> > would be really huge. Go for it!
>
> Sorry, folks, am I understanding right that pr_cont() and flushing the
> buffer on "\n" are two separate problems that can be handled outside
> Tetsuo's patchset, just assuming pr_cont() is unsupported?
> Or should the pr_cont() cleanup be a prerequisite for that?
Oh... Sorry. I'm quite overloaded at the moment and simply forgot about
this thread.
So what is exactly our problem with pr_cont -- it's not SMP friendly.
And this leads to various things, the most annoying of which is a
preliminary flush.
E.g. let me do a simple thing on my box:
ps aux | grep firefox
kill 2727
dmesg | tail
[ 554.098341] Chrome_~dThread[2823]: segfault at 0 ip 7f5df153a1f3 sp
7f5ded47ab00 error 6 in libxul.so[7f5df1531000+4b01000]
[ 554.098348] Code: e7 04 48 8d 15 a6 94 ae 03 48 89 10 c7 04 25 00 00 00 00
00 00 00 00 0f 0b 48 8b 05 57 d0 e7 04 48 8d 0d b0 94 ae 03 48 89 08 04 25
00 00 00 00 00 00 00 00 0f 0b e8 4d f4 ff ff 48 8b 05 34
[ 554.109418] Chrome_~dThread[3047]: segfault at 0 ip 7f3d5bdba1f3 sp
7f3d57cfab00 error 6
[ 554.109421] Chrome_~dThread[3077]: segfault at 0 ip 7fe773f661f3 sp
7fe76fea6b00 error 6
[ 554.109424] in libxul.so[7f3d5bdb1000+4b01000]
[ 554.109426] in libxul.so[7fe773f5d000+4b01000]
[ 554.109429] Code: e7 04 48 8d 15 a6 94 ae 03 48 89 10 c7 04 25 00 00 00 00
00 00 00 00 0f 0b 48 8b 05 57 d0 e7 04 48 8d 0d b0 94 ae 03 48 89 08 04 25
00 00 00 00 00 00 00 00 0f 0b e8 4d f4 ff ff 48 8b 05 34
Even such a simple thing as "printk several lines per-crashed process"
is broken. Look at line #0 and lines #2-#5.
And this is the only problem we probably need to address. Overlapping
printk lines -- when several CPUs printk simultaneously, or same CPUs
printk-s from IRQ, etc -- are here by design and it's not going to be
easy to change that (and maybe we shouldn't try).
Buffering multiple lines in printk buffer does not look so simple and
perhaps we should not try to do this, as well. Why:
- it's hard to decide what to do when buffer overflows
Switching to "normal printk" defeats the reason we do buffering in the
first place. Because "normal printk" permits overlapping. So buffering
makes a little sense if we are OK with switching to a "normal printk".
- the more we buffer the more we can lose in case of panic.
We can't flush_on_panic() printk buffers which were allocated on stack.
- flushing multiple lines should be more complex than just a simple
printk loop
while (1) {
x = memchr(buf, '\n', sz);
...
print("%s", buf);
...
}
Because "printk() loop" permits lines overlap. Hence buffering makes
little sense, once again.
So let's reduce the problem scope to "we want to have a replacement for
pr_cont()". And let's address pr_cont()'s "preliminary flush" issue only.
I scanned some of Linus' emails, and skimmed through previous discussions
on this topic. Let me quote Linus:
:
: My preference as a user is actually to just have a dynamically
: re-sizable buffer (that's pretty much what I've done in *every* single
: user space project I've had in the last decade), but because some
: users might have atomicity issues I do suspect that we should just use
: a stack buffer.
:
: And then perhaps say that the buffer size has to be capped at 80 characters.
:
: Because if you're printing more than 80 characters and expecting it
: all to fit on a line, you're doing something else wrong anyway.
:
: And hide it not as a explicit "char buffer[80]]" allocation, but as a
: "struct line_buffer" or similar, so that
:
: (a) people don't get the line size wrong
:
: (b) the buffering code can add a few fields for length etc in there too
:
: Introduce a few helper functions for it:
:
: init_line_buffer();
: print_line(, fmt, args);
: vprint_line(, fmt, vararg);
: finish_line();
:
And this is, basically, what I have attached to this email. It's very
simple and very short. And I think this is what Linus wanted us to do.
- usage example
DEFINE_PR_LINE(KERN_ERR, pl);
pr_line(, "Hello, %s!\n", "buffer");
pr_line(, "%s", "OK.\n");
pr_line(, "Goodbye, %s", "buffer");
pr_line(, "\n");
dmesg | tail
[ 69.908542] Hello, buffer!
[ 69.908544] OK.
[ 69.908545] Goodbye, buffer
- pr_cont-like usage
DEFINE_PR_LINE(KERN_ERR, pl);
pr_line(,"%d ", 1);
pr_line(,"%d ", 3);
pr_line(,"%d ", 5);
pr_line(,"%d ", 7);
pr_line(,"%d\n", 9);
dmesg | tail
[ 69.908546] 1 3 5 7 9
- An explicit, aux buffer // output should be truncated
char buf[16];
DEFINE_PR_LINE_BUF(KERN_ERR, ps, buf, sizeof(buf));
pr_line(, "Test test test test test test test test test\n");
pr_line(, "\n");
dmesg | tail
[
Re: [PATCH] printk: inject caller information into the body of message
On Wed, Jun 20, 2018 at 3:06 PM Sergey Senozhatsky wrote: > > On (06/20/18 13:32), Dmitry Vyukov wrote: > > > So, if we could get rid of pr_cont() from the most important parts > > > (instruction dumps, etc) then I would just vote to leave pr_cont() > > > alone and avoid any handling of it in printk context tracking. Simply > > > because we wouldn't care about pr_cont(). This also could simplify > > > Tetsuo's patch significantly. > > > > Sounds good to me. > > Awesome. If you and Fengguang can combine forces and lead the > whole thing towards "we couldn't care of pr_cont() less", it > would be really huge. Go for it! Sorry, folks, am I understanding right that pr_cont() and flushing the buffer on "\n" are two separate problems that can be handled outside Tetsuo's patchset, just assuming pr_cont() is unsupported? Or should the pr_cont() cleanup be a prerequisite for that? > -ss > > -- > You received this message because you are subscribed to the Google Groups > "syzkaller" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to syzkaller+unsubscr...@googlegroups.com. > For more options, visit https://groups.google.com/d/optout. -- Alexander Potapenko Software Engineer Google Germany GmbH Erika-Mann-Straße, 33 80636 München Geschäftsführer: Paul Manicle, Halimah DeLaine Prado Registergericht und -nummer: Hamburg, HRB 86891 Sitz der Gesellschaft: Hamburg
Re: [PATCH] printk: inject caller information into the body of message
On Wed, Jun 20, 2018 at 3:06 PM Sergey Senozhatsky wrote: > > On (06/20/18 13:32), Dmitry Vyukov wrote: > > > So, if we could get rid of pr_cont() from the most important parts > > > (instruction dumps, etc) then I would just vote to leave pr_cont() > > > alone and avoid any handling of it in printk context tracking. Simply > > > because we wouldn't care about pr_cont(). This also could simplify > > > Tetsuo's patch significantly. > > > > Sounds good to me. > > Awesome. If you and Fengguang can combine forces and lead the > whole thing towards "we couldn't care of pr_cont() less", it > would be really huge. Go for it! Sorry, folks, am I understanding right that pr_cont() and flushing the buffer on "\n" are two separate problems that can be handled outside Tetsuo's patchset, just assuming pr_cont() is unsupported? Or should the pr_cont() cleanup be a prerequisite for that? > -ss > > -- > You received this message because you are subscribed to the Google Groups > "syzkaller" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to syzkaller+unsubscr...@googlegroups.com. > For more options, visit https://groups.google.com/d/optout. -- Alexander Potapenko Software Engineer Google Germany GmbH Erika-Mann-Straße, 33 80636 München Geschäftsführer: Paul Manicle, Halimah DeLaine Prado Registergericht und -nummer: Hamburg, HRB 86891 Sitz der Gesellschaft: Hamburg
Re: [PATCH] printk: inject caller information into the body of message
On 2018/06/25 18:36, Dmitry Vyukov wrote:
> On Mon, Jun 25, 2018 at 3:41 AM, Sergey Senozhatsky
> wrote:
>> On (06/22/18 22:06), Tetsuo Handa wrote:
Awesome. If you and Fengguang can combine forces and lead the
whole thing towards "we couldn't care of pr_cont() less", it
would be really huge. Go for it!
>>>
>>> Can't we have seq_printf()-like one which flushes automatically upon seeing
>>> '\n'
>>> or buffer full? Printing memory information is using a lot of pr_cont(),
>>> even in
>>> function names (e.g.
>>> http://lkml.kernel.org/r/20180622083949.gr10...@dhcp22.suse.cz ).
>>> Since OOM killer code is serialized by oom_lock, we can use static buffer
>>> for
>>> OOM killer messages.
>>
>> I'm not the right guy to answer this question. Sorry. We need to Cc MM
>> people on this.
>>
>> Does OOM's pr_cont() usage cause too much disturbance to syzkaller? I thought
>> that OOM was slightly out of sight.
>
> Hard to tell. Nothing specific comes to mind.
> We do see lines like these:
>
> BUG: unable to handle kernel [ 110.NUM] device gre0 entered promiscuous mode
> BUG:[ cut here ]
>
> and frequently it's also required to look deep inside of crash message
> to understand what they really mean. Hard to tell how random pr_cont's
> contribute to the problem. We now throw away everything that looks any
> corrupted right away.
> I guess the main requirement is that the crash report itself does not
> use pr_cont and provided we have task/cpu context we can separate the
> crash report lines from everything else (assuming that random
> pr_cont's on other CPUs won't glue to the report lines).
>
PATCH 1/3 below is a sample implementation of seq_printf()-like one which
flushes automatically upon seeing '\n' or buffer full. PATCH 2/3 is a
straightforward user of such function. (Well, since it is so simple,
we could rewrite it using snprintf() before PATCH 1/3 is accepted.)
PATCH 3/3 is a complicated user of such function. (Well, we could reduce
pr_cont() before PATCH 1/3 is accepted.) Can we agree with PATCH 1/3 ?
>From 485406f585e566dccdfb85a1afbae460b8756457 Mon Sep 17 00:00:00 2001
From: Tetsuo Handa
Date: Wed, 27 Jun 2018 16:29:14 +0900
Subject: [PATCH 1/3] printk: Introduce buffered_printk().
Linus suggested in "printk: what is going on with additional newlines?"
thread [1] that
Making the buffer explicit is (a) cheaper and (b) better. Now you can
put the buffer on the stack, you never have to worry about where you
need to track context, and you have no buffering limits (ie you can
buffer across any event).
I definitely suspect that "single line" is often sufficient. I
mean, that's all that KERN_CONT ever gave you anyway (and not reliably).
And then a 80 character buffer really isn't any different from having
a structure with a few pointers in it, which we do on the stack all
the time.
Now, since syzbot is bothered by concurrent printk() messages (e.g.
memory allocation fault injection), we started thinking about adding
prefix to each line of printk() output. This matches the suggestion that
buffering single line will be sufficient if we add caller's context
information for distinguishing concurrent printk() messages.
Thus, this patch introduces buffered_printk() which spools printk() output
and automatically flushes when '\n' was found or buffer became full (and
related structure/macro/functions).
[1]
http://lkml.kernel.org/r/ca+55afx+5r-vfqfr7+ok9yrs2adq2ma4fz+s6ncywhy_-2m...@mail.gmail.com
Signed-off-by: Tetsuo Handa
---
include/linux/printk.h | 28
kernel/printk/printk.c | 86 ++
2 files changed, 114 insertions(+)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 6d7e800..81bc12a 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -153,6 +153,23 @@ static inline void printk_nmi_enter(void) { }
static inline void printk_nmi_exit(void) { }
#endif /* PRINTK_NMI */
+struct printk_buffer {
+ unsigned short int size;
+ unsigned short int used;
+ char *buf;
+};
+
+#define DEFINE_PRINTK_BUFFER(name, size, buf) \
+ struct printk_buffer name = { size, 0, buf }
+
+static inline void INIT_PRINTK_BUFFER(struct printk_buffer *ptr,
+ unsigned short int size, char *buf)
+{
+ ptr->size = size;
+ ptr->used = 0;
+ ptr->buf = buf;
+}
+
#ifdef CONFIG_PRINTK
asmlinkage __printf(5, 0)
int vprintk_emit(int facility, int level,
@@ -169,6 +186,9 @@ int printk_emit(int facility, int level,
asmlinkage __printf(1, 2) __cold
int printk(const char *fmt, ...);
+asmlinkage __printf(2, 3) __cold
+int buffered_printk(struct printk_buffer *ptr, const char *fmt, ...);
+void flush_buffered_printk(struct printk_buffer *ptr);
/*
* Special printk facility for scheduler/timekeeping use only, _DO_NOT_USE_ !
@@ -216,6 +236,14 @@ int printk(const char *s, ...)
{
return
Re: [PATCH] printk: inject caller information into the body of message
On 2018/06/25 18:36, Dmitry Vyukov wrote:
> On Mon, Jun 25, 2018 at 3:41 AM, Sergey Senozhatsky
> wrote:
>> On (06/22/18 22:06), Tetsuo Handa wrote:
Awesome. If you and Fengguang can combine forces and lead the
whole thing towards "we couldn't care of pr_cont() less", it
would be really huge. Go for it!
>>>
>>> Can't we have seq_printf()-like one which flushes automatically upon seeing
>>> '\n'
>>> or buffer full? Printing memory information is using a lot of pr_cont(),
>>> even in
>>> function names (e.g.
>>> http://lkml.kernel.org/r/20180622083949.gr10...@dhcp22.suse.cz ).
>>> Since OOM killer code is serialized by oom_lock, we can use static buffer
>>> for
>>> OOM killer messages.
>>
>> I'm not the right guy to answer this question. Sorry. We need to Cc MM
>> people on this.
>>
>> Does OOM's pr_cont() usage cause too much disturbance to syzkaller? I thought
>> that OOM was slightly out of sight.
>
> Hard to tell. Nothing specific comes to mind.
> We do see lines like these:
>
> BUG: unable to handle kernel [ 110.NUM] device gre0 entered promiscuous mode
> BUG:[ cut here ]
>
> and frequently it's also required to look deep inside of crash message
> to understand what they really mean. Hard to tell how random pr_cont's
> contribute to the problem. We now throw away everything that looks any
> corrupted right away.
> I guess the main requirement is that the crash report itself does not
> use pr_cont and provided we have task/cpu context we can separate the
> crash report lines from everything else (assuming that random
> pr_cont's on other CPUs won't glue to the report lines).
>
PATCH 1/3 below is a sample implementation of seq_printf()-like one which
flushes automatically upon seeing '\n' or buffer full. PATCH 2/3 is a
straightforward user of such function. (Well, since it is so simple,
we could rewrite it using snprintf() before PATCH 1/3 is accepted.)
PATCH 3/3 is a complicated user of such function. (Well, we could reduce
pr_cont() before PATCH 1/3 is accepted.) Can we agree with PATCH 1/3 ?
>From 485406f585e566dccdfb85a1afbae460b8756457 Mon Sep 17 00:00:00 2001
From: Tetsuo Handa
Date: Wed, 27 Jun 2018 16:29:14 +0900
Subject: [PATCH 1/3] printk: Introduce buffered_printk().
Linus suggested in "printk: what is going on with additional newlines?"
thread [1] that
Making the buffer explicit is (a) cheaper and (b) better. Now you can
put the buffer on the stack, you never have to worry about where you
need to track context, and you have no buffering limits (ie you can
buffer across any event).
I definitely suspect that "single line" is often sufficient. I
mean, that's all that KERN_CONT ever gave you anyway (and not reliably).
And then a 80 character buffer really isn't any different from having
a structure with a few pointers in it, which we do on the stack all
the time.
Now, since syzbot is bothered by concurrent printk() messages (e.g.
memory allocation fault injection), we started thinking about adding
prefix to each line of printk() output. This matches the suggestion that
buffering single line will be sufficient if we add caller's context
information for distinguishing concurrent printk() messages.
Thus, this patch introduces buffered_printk() which spools printk() output
and automatically flushes when '\n' was found or buffer became full (and
related structure/macro/functions).
[1]
http://lkml.kernel.org/r/ca+55afx+5r-vfqfr7+ok9yrs2adq2ma4fz+s6ncywhy_-2m...@mail.gmail.com
Signed-off-by: Tetsuo Handa
---
include/linux/printk.h | 28
kernel/printk/printk.c | 86 ++
2 files changed, 114 insertions(+)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 6d7e800..81bc12a 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -153,6 +153,23 @@ static inline void printk_nmi_enter(void) { }
static inline void printk_nmi_exit(void) { }
#endif /* PRINTK_NMI */
+struct printk_buffer {
+ unsigned short int size;
+ unsigned short int used;
+ char *buf;
+};
+
+#define DEFINE_PRINTK_BUFFER(name, size, buf) \
+ struct printk_buffer name = { size, 0, buf }
+
+static inline void INIT_PRINTK_BUFFER(struct printk_buffer *ptr,
+ unsigned short int size, char *buf)
+{
+ ptr->size = size;
+ ptr->used = 0;
+ ptr->buf = buf;
+}
+
#ifdef CONFIG_PRINTK
asmlinkage __printf(5, 0)
int vprintk_emit(int facility, int level,
@@ -169,6 +186,9 @@ int printk_emit(int facility, int level,
asmlinkage __printf(1, 2) __cold
int printk(const char *fmt, ...);
+asmlinkage __printf(2, 3) __cold
+int buffered_printk(struct printk_buffer *ptr, const char *fmt, ...);
+void flush_buffered_printk(struct printk_buffer *ptr);
/*
* Special printk facility for scheduler/timekeeping use only, _DO_NOT_USE_ !
@@ -216,6 +236,14 @@ int printk(const char *s, ...)
{
return
Re: [PATCH] printk: inject caller information into the body of message
On Mon, Jun 25, 2018 at 3:41 AM, Sergey Senozhatsky wrote: > On (06/22/18 22:06), Tetsuo Handa wrote: >> > >> > Awesome. If you and Fengguang can combine forces and lead the >> > whole thing towards "we couldn't care of pr_cont() less", it >> > would be really huge. Go for it! >> >> Can't we have seq_printf()-like one which flushes automatically upon seeing >> '\n' >> or buffer full? Printing memory information is using a lot of pr_cont(), >> even in >> function names (e.g. >> http://lkml.kernel.org/r/20180622083949.gr10...@dhcp22.suse.cz ). >> Since OOM killer code is serialized by oom_lock, we can use static buffer for >> OOM killer messages. > > I'm not the right guy to answer this question. Sorry. We need to Cc MM > people on this. > > Does OOM's pr_cont() usage cause too much disturbance to syzkaller? I thought > that OOM was slightly out of sight. Hard to tell. Nothing specific comes to mind. We do see lines like these: BUG: unable to handle kernel [ 110.NUM] device gre0 entered promiscuous mode BUG:[ cut here ] and frequently it's also required to look deep inside of crash message to understand what they really mean. Hard to tell how random pr_cont's contribute to the problem. We now throw away everything that looks any corrupted right away. I guess the main requirement is that the crash report itself does not use pr_cont and provided we have task/cpu context we can separate the crash report lines from everything else (assuming that random pr_cont's on other CPUs won't glue to the report lines).
Re: [PATCH] printk: inject caller information into the body of message
On Mon, Jun 25, 2018 at 3:41 AM, Sergey Senozhatsky wrote: > On (06/22/18 22:06), Tetsuo Handa wrote: >> > >> > Awesome. If you and Fengguang can combine forces and lead the >> > whole thing towards "we couldn't care of pr_cont() less", it >> > would be really huge. Go for it! >> >> Can't we have seq_printf()-like one which flushes automatically upon seeing >> '\n' >> or buffer full? Printing memory information is using a lot of pr_cont(), >> even in >> function names (e.g. >> http://lkml.kernel.org/r/20180622083949.gr10...@dhcp22.suse.cz ). >> Since OOM killer code is serialized by oom_lock, we can use static buffer for >> OOM killer messages. > > I'm not the right guy to answer this question. Sorry. We need to Cc MM > people on this. > > Does OOM's pr_cont() usage cause too much disturbance to syzkaller? I thought > that OOM was slightly out of sight. Hard to tell. Nothing specific comes to mind. We do see lines like these: BUG: unable to handle kernel [ 110.NUM] device gre0 entered promiscuous mode BUG:[ cut here ] and frequently it's also required to look deep inside of crash message to understand what they really mean. Hard to tell how random pr_cont's contribute to the problem. We now throw away everything that looks any corrupted right away. I guess the main requirement is that the crash report itself does not use pr_cont and provided we have task/cpu context we can separate the crash report lines from everything else (assuming that random pr_cont's on other CPUs won't glue to the report lines).
Re: [PATCH] printk: inject caller information into the body of message
On (06/22/18 22:06), Tetsuo Handa wrote: > > > > Awesome. If you and Fengguang can combine forces and lead the > > whole thing towards "we couldn't care of pr_cont() less", it > > would be really huge. Go for it! > > Can't we have seq_printf()-like one which flushes automatically upon seeing > '\n' > or buffer full? Printing memory information is using a lot of pr_cont(), even > in > function names (e.g. > http://lkml.kernel.org/r/20180622083949.gr10...@dhcp22.suse.cz ). > Since OOM killer code is serialized by oom_lock, we can use static buffer for > OOM killer messages. I'm not the right guy to answer this question. Sorry. We need to Cc MM people on this. Does OOM's pr_cont() usage cause too much disturbance to syzkaller? I thought that OOM was slightly out of sight. -ss
Re: [PATCH] printk: inject caller information into the body of message
On (06/22/18 22:06), Tetsuo Handa wrote: > > > > Awesome. If you and Fengguang can combine forces and lead the > > whole thing towards "we couldn't care of pr_cont() less", it > > would be really huge. Go for it! > > Can't we have seq_printf()-like one which flushes automatically upon seeing > '\n' > or buffer full? Printing memory information is using a lot of pr_cont(), even > in > function names (e.g. > http://lkml.kernel.org/r/20180622083949.gr10...@dhcp22.suse.cz ). > Since OOM killer code is serialized by oom_lock, we can use static buffer for > OOM killer messages. I'm not the right guy to answer this question. Sorry. We need to Cc MM people on this. Does OOM's pr_cont() usage cause too much disturbance to syzkaller? I thought that OOM was slightly out of sight. -ss
Re: [PATCH] printk: inject caller information into the body of message
On 2018/06/20 22:06, Sergey Senozhatsky wrote: > On (06/20/18 13:32), Dmitry Vyukov wrote: >>> So, if we could get rid of pr_cont() from the most important parts >>> (instruction dumps, etc) then I would just vote to leave pr_cont() >>> alone and avoid any handling of it in printk context tracking. Simply >>> because we wouldn't care about pr_cont(). This also could simplify >>> Tetsuo's patch significantly. >> >> Sounds good to me. > > Awesome. If you and Fengguang can combine forces and lead the > whole thing towards "we couldn't care of pr_cont() less", it > would be really huge. Go for it! Can't we have seq_printf()-like one which flushes automatically upon seeing '\n' or buffer full? Printing memory information is using a lot of pr_cont(), even in function names (e.g. http://lkml.kernel.org/r/20180622083949.gr10...@dhcp22.suse.cz ). Since OOM killer code is serialized by oom_lock, we can use static buffer for OOM killer messages.
Re: [PATCH] printk: inject caller information into the body of message
On 2018/06/20 22:06, Sergey Senozhatsky wrote: > On (06/20/18 13:32), Dmitry Vyukov wrote: >>> So, if we could get rid of pr_cont() from the most important parts >>> (instruction dumps, etc) then I would just vote to leave pr_cont() >>> alone and avoid any handling of it in printk context tracking. Simply >>> because we wouldn't care about pr_cont(). This also could simplify >>> Tetsuo's patch significantly. >> >> Sounds good to me. > > Awesome. If you and Fengguang can combine forces and lead the > whole thing towards "we couldn't care of pr_cont() less", it > would be really huge. Go for it! Can't we have seq_printf()-like one which flushes automatically upon seeing '\n' or buffer full? Printing memory information is using a lot of pr_cont(), even in function names (e.g. http://lkml.kernel.org/r/20180622083949.gr10...@dhcp22.suse.cz ). Since OOM killer code is serialized by oom_lock, we can use static buffer for OOM killer messages.
Re: [PATCH] printk: inject caller information into the body of message
On (06/20/18 13:32), Dmitry Vyukov wrote:
> >>
> >> So this is another reason to get rid of pr_cont entirely, right?
> >
> > Getting rid of pr_cont() from important output would be totally cool.
> > Quoting Linus:
> >
> > Only acceptable use of continuations is basically boot-time testing,
> > when you do things like
> >
> > printk("Testing feature XYZ..");
> > this_may_blow_up_because_of_hw_bugs();
> > printk(KERN_CONT " ... ok\n");
> >
> >
> > I can recall at least 4 attempts when people tried to introduce new
> > pr_cont()
> > or some concept with similar functionality to pr_cont(), but SMP safe. We
> > brought the first one - per-CPU pr_cont() buffers - to KS several years ago
> > but Linus didn't like it. Then there was a buffered printk() mode patch from
> > Tetsuo, then a solution from Steven, then I had my second try with a
> > soft-of-pr_cont() replacement.
> >
> > So, if we could get rid of pr_cont() from the most important parts
> > (instruction dumps, etc) then I would just vote to leave pr_cont()
> > alone and avoid any handling of it in printk context tracking. Simply
> > because we wouldn't care about pr_cont(). This also could simplify
> > Tetsuo's patch significantly.
>
> Sounds good to me.
Another thing about pr_cont() is that as long as pr_cont() does not race
with pr_cont() from another task or from IRQ, the task that is the owner
(see struct cont in printk.c) of the existing continuation line can migrate,
IOW we can have
CPU0CPU1CPU2CPU3
task A
pr_cont()
task A
pr_cont()
task A
pr_cont()
task A
pr_cont("\n") << flush
The line was printed from 4 CPUs, but appears as a single line
in the logbuf. Should we account CPU0 or CPU3 as the line origin?
That's another reason why I don't really want to handle pr_cont in
any special way in context tracking.
So, currently, context tracking looks like this:
---
char mode = 'T';
if (in_serving_softirq())
mode = 'S';
if (in_irq())
mode = 'I';
if (in_nmi())
mode = 'N';
ret = snprintf(buf, buf_len, "%c<%d>%c",
mode,
raw_smp_processor_id(),
cont.len ? '+' : ' ');
---
I add a '+' symbol to continuation lines. Which should simply hint
that tracking info for that particular line is not entirely trustworthy.
I also don't add any tracking info for printk_safe output. We get
tracking info for such lines from the printk_safe flush path
(irq work that happens on the same CPU that added printk_safe output).
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (06/20/18 13:32), Dmitry Vyukov wrote:
> >>
> >> So this is another reason to get rid of pr_cont entirely, right?
> >
> > Getting rid of pr_cont() from important output would be totally cool.
> > Quoting Linus:
> >
> > Only acceptable use of continuations is basically boot-time testing,
> > when you do things like
> >
> > printk("Testing feature XYZ..");
> > this_may_blow_up_because_of_hw_bugs();
> > printk(KERN_CONT " ... ok\n");
> >
> >
> > I can recall at least 4 attempts when people tried to introduce new
> > pr_cont()
> > or some concept with similar functionality to pr_cont(), but SMP safe. We
> > brought the first one - per-CPU pr_cont() buffers - to KS several years ago
> > but Linus didn't like it. Then there was a buffered printk() mode patch from
> > Tetsuo, then a solution from Steven, then I had my second try with a
> > soft-of-pr_cont() replacement.
> >
> > So, if we could get rid of pr_cont() from the most important parts
> > (instruction dumps, etc) then I would just vote to leave pr_cont()
> > alone and avoid any handling of it in printk context tracking. Simply
> > because we wouldn't care about pr_cont(). This also could simplify
> > Tetsuo's patch significantly.
>
> Sounds good to me.
Another thing about pr_cont() is that as long as pr_cont() does not race
with pr_cont() from another task or from IRQ, the task that is the owner
(see struct cont in printk.c) of the existing continuation line can migrate,
IOW we can have
CPU0CPU1CPU2CPU3
task A
pr_cont()
task A
pr_cont()
task A
pr_cont()
task A
pr_cont("\n") << flush
The line was printed from 4 CPUs, but appears as a single line
in the logbuf. Should we account CPU0 or CPU3 as the line origin?
That's another reason why I don't really want to handle pr_cont in
any special way in context tracking.
So, currently, context tracking looks like this:
---
char mode = 'T';
if (in_serving_softirq())
mode = 'S';
if (in_irq())
mode = 'I';
if (in_nmi())
mode = 'N';
ret = snprintf(buf, buf_len, "%c<%d>%c",
mode,
raw_smp_processor_id(),
cont.len ? '+' : ' ');
---
I add a '+' symbol to continuation lines. Which should simply hint
that tracking info for that particular line is not entirely trustworthy.
I also don't add any tracking info for printk_safe output. We get
tracking info for such lines from the printk_safe flush path
(irq work that happens on the same CPU that added printk_safe output).
-ss
Re: [PATCH] printk: inject caller information into the body of message
On (06/20/18 13:32), Dmitry Vyukov wrote: > > So, if we could get rid of pr_cont() from the most important parts > > (instruction dumps, etc) then I would just vote to leave pr_cont() > > alone and avoid any handling of it in printk context tracking. Simply > > because we wouldn't care about pr_cont(). This also could simplify > > Tetsuo's patch significantly. > > Sounds good to me. Awesome. If you and Fengguang can combine forces and lead the whole thing towards "we couldn't care of pr_cont() less", it would be really huge. Go for it! -ss
Re: [PATCH] printk: inject caller information into the body of message
On (06/20/18 13:32), Dmitry Vyukov wrote: > > So, if we could get rid of pr_cont() from the most important parts > > (instruction dumps, etc) then I would just vote to leave pr_cont() > > alone and avoid any handling of it in printk context tracking. Simply > > because we wouldn't care about pr_cont(). This also could simplify > > Tetsuo's patch significantly. > > Sounds good to me. Awesome. If you and Fengguang can combine forces and lead the whole thing towards "we couldn't care of pr_cont() less", it would be really huge. Go for it! -ss
Re: [PATCH] printk: inject caller information into the body of message
On Wed, Jun 20, 2018 at 02:45:25PM +0200, Dmitry Vyukov wrote: On Wed, Jun 20, 2018 at 2:41 PM, Fengguang Wu wrote: On Wed, Jun 20, 2018 at 02:31:51PM +0200, Dmitry Vyukov wrote: On Wed, Jun 20, 2018 at 1:37 PM, Fengguang Wu wrote: On Wed, Jun 20, 2018 at 11:30:05AM +0200, Dmitry Vyukov wrote: On Wed, Jun 20, 2018 at 11:06 AM, Sergey Senozhatsky wrote: Hi Dmitry, On (06/20/18 10:45), Dmitry Vyukov wrote: Hi Sergey, What are the visible differences between this patch and Tetsuo's patch? I guess none, and looking at your requirements below I tend to agree that Tetsuo's approach is probably what you need at the end of the day. The only thing that will matter for syzkaller parsing in the end is the resulting text format as it appears on console. But you say "I'm not pushing for this particular message format", so what exactly do you want me to provide feedback on? I guess we need to handle pr_cont properly whatever approach we take. Mostly, was wondering about if: a) you need pr_cont() handling b) you need printk_safe() handling The reasons I left those things behind: a) pr_cont() is officially hated. It was never supposed to be used on SMP systems. So I wasn't sure if we need all that effort and add tricky code to handle pr_cont(). Given that syzkaller is probably the only user of that functionality. Well, if I put my syzkaller hat on, then I don't care what exactly happens in the kernel, the only thing I care is well-formed output on console that can be parsed unambiguously in all cases. +1 for 0day kernel testing. I admit that goal may never be 100% achievable -- at least some serial console logs can sometimes become messy. So we'll have to write dmesg parsing code in defensive ways. But some unnecessary pr_cont() broken-up messages can obviously be avoided. For example, arch/x86/mm/fault.c: printk(KERN_ALERT "BUG: unable to handle kernel "); if (address < PAGE_SIZE) printk(KERN_CONT "NULL pointer dereference"); else printk(KERN_CONT "paging request"); I've actually proposed to remove the above KERN_CONT, unfortunately the patch was silently ignored. I've just cooked this change too, but do you mind reviving your patch? Yes, sure. My version is more dumb. Since I'm not sure if it's OK to do string formatting at this critical point. Let's see how others think about the 2 approaches. I'm fine as long as our problem is fixed. :) It already does string formatting for address. And I think we also need to get rid of KERN_CONT for address while we are here. Ah yes, sorry I overlooked the next KERN_CONT.. diff --git a/arch/x86/mm/fault.c b/arch/x86/mm/fault.c index 9a84a0d08727..c7b068c6b010 100644 --- a/arch/x86/mm/fault.c +++ b/arch/x86/mm/fault.c @@ -671,11 +671,10 @@ show_fault_oops(struct pt_regs *regs, unsigned long error_code, printk(smep_warning, from_kuid(_user_ns, current_uid())); } - printk(KERN_ALERT "BUG: unable to handle kernel "); if (address < PAGE_SIZE) - printk(KERN_CONT "NULL pointer dereference"); + printk(KERN_ALERT "BUG: unable to handle kernel NULL pointer dereference"); else - printk(KERN_CONT "paging request"); + printk(KERN_ALERT "BUG: unable to handle kernel paging request"); printk(KERN_CONT " at %px\n", (void *) address); It actually makes the code even shorter, which is nice: --- a/arch/x86/mm/fault.c +++ b/arch/x86/mm/fault.c @@ -671,13 +671,9 @@ show_fault_oops(struct pt_regs *regs, unsigned long error_code, printk(smep_warning, from_kuid(_user_ns, current_uid())); } - printk(KERN_ALERT "BUG: unable to handle kernel "); - if (address < PAGE_SIZE) - printk(KERN_CONT "NULL pointer dereference"); - else - printk(KERN_CONT "paging request"); - - printk(KERN_CONT " at %px\n", (void *) address); + printk(KERN_ALERT "BUG: unable to handle kernel %s at %px\n", + (address < PAGE_SIZE ? "NULL pointer dereference" : + "paging request"), (void *) address); dump_pagetable(address); }
Re: [PATCH] printk: inject caller information into the body of message
On Wed, Jun 20, 2018 at 02:45:25PM +0200, Dmitry Vyukov wrote: On Wed, Jun 20, 2018 at 2:41 PM, Fengguang Wu wrote: On Wed, Jun 20, 2018 at 02:31:51PM +0200, Dmitry Vyukov wrote: On Wed, Jun 20, 2018 at 1:37 PM, Fengguang Wu wrote: On Wed, Jun 20, 2018 at 11:30:05AM +0200, Dmitry Vyukov wrote: On Wed, Jun 20, 2018 at 11:06 AM, Sergey Senozhatsky wrote: Hi Dmitry, On (06/20/18 10:45), Dmitry Vyukov wrote: Hi Sergey, What are the visible differences between this patch and Tetsuo's patch? I guess none, and looking at your requirements below I tend to agree that Tetsuo's approach is probably what you need at the end of the day. The only thing that will matter for syzkaller parsing in the end is the resulting text format as it appears on console. But you say "I'm not pushing for this particular message format", so what exactly do you want me to provide feedback on? I guess we need to handle pr_cont properly whatever approach we take. Mostly, was wondering about if: a) you need pr_cont() handling b) you need printk_safe() handling The reasons I left those things behind: a) pr_cont() is officially hated. It was never supposed to be used on SMP systems. So I wasn't sure if we need all that effort and add tricky code to handle pr_cont(). Given that syzkaller is probably the only user of that functionality. Well, if I put my syzkaller hat on, then I don't care what exactly happens in the kernel, the only thing I care is well-formed output on console that can be parsed unambiguously in all cases. +1 for 0day kernel testing. I admit that goal may never be 100% achievable -- at least some serial console logs can sometimes become messy. So we'll have to write dmesg parsing code in defensive ways. But some unnecessary pr_cont() broken-up messages can obviously be avoided. For example, arch/x86/mm/fault.c: printk(KERN_ALERT "BUG: unable to handle kernel "); if (address < PAGE_SIZE) printk(KERN_CONT "NULL pointer dereference"); else printk(KERN_CONT "paging request"); I've actually proposed to remove the above KERN_CONT, unfortunately the patch was silently ignored. I've just cooked this change too, but do you mind reviving your patch? Yes, sure. My version is more dumb. Since I'm not sure if it's OK to do string formatting at this critical point. Let's see how others think about the 2 approaches. I'm fine as long as our problem is fixed. :) It already does string formatting for address. And I think we also need to get rid of KERN_CONT for address while we are here. Ah yes, sorry I overlooked the next KERN_CONT.. diff --git a/arch/x86/mm/fault.c b/arch/x86/mm/fault.c index 9a84a0d08727..c7b068c6b010 100644 --- a/arch/x86/mm/fault.c +++ b/arch/x86/mm/fault.c @@ -671,11 +671,10 @@ show_fault_oops(struct pt_regs *regs, unsigned long error_code, printk(smep_warning, from_kuid(_user_ns, current_uid())); } - printk(KERN_ALERT "BUG: unable to handle kernel "); if (address < PAGE_SIZE) - printk(KERN_CONT "NULL pointer dereference"); + printk(KERN_ALERT "BUG: unable to handle kernel NULL pointer dereference"); else - printk(KERN_CONT "paging request"); + printk(KERN_ALERT "BUG: unable to handle kernel paging request"); printk(KERN_CONT " at %px\n", (void *) address); It actually makes the code even shorter, which is nice: --- a/arch/x86/mm/fault.c +++ b/arch/x86/mm/fault.c @@ -671,13 +671,9 @@ show_fault_oops(struct pt_regs *regs, unsigned long error_code, printk(smep_warning, from_kuid(_user_ns, current_uid())); } - printk(KERN_ALERT "BUG: unable to handle kernel "); - if (address < PAGE_SIZE) - printk(KERN_CONT "NULL pointer dereference"); - else - printk(KERN_CONT "paging request"); - - printk(KERN_CONT " at %px\n", (void *) address); + printk(KERN_ALERT "BUG: unable to handle kernel %s at %px\n", + (address < PAGE_SIZE ? "NULL pointer dereference" : + "paging request"), (void *) address); dump_pagetable(address); }
