Re: [RFC] printk/sysrq: Don't play with console_loglevel
On 6/12/19 1:00 PM, Petr Mladek wrote: > On Wed 2019-06-12 17:36:43, Sergey Senozhatsky wrote: >> On (06/06/19 09:10), Petr Mladek wrote: >>> Just to be sure. I wanted to say that I like the idea with >>> KERN_UNSUPRESSED. So, I think that we are on the same page. >> >> I understand. All I wanted to say is that KERN_UNSUPRESSED is >> per-message, while the most interesting (and actually broken) >> cases, IMHO, are per-context, IOW things like this one >> >> console_loglevel = NEW >> foo() >>dump_stack() >> printk >> ... >> printk >> console_loglevel = OLD >> >> KERN_UNSUPRESSED does not help here. We probably can't convert >> dump_stack() to KERN_UNSUPRESSED. > > I agree. I take KERN_UNSUPRESSED like a nice trick how to pass > the information about the unsupressed printk context via > printk_safe and printk_nmi per-CPU buffers. > > The single line in sysrq __handle_sysrq() seems to be the only > location where KERN_UNSUPRESSED can be used directly. I likely don't understand all the reasons why it's not possible. Looking at kdb - prints those can't be converted straight-away are show_regs() and show_stack().. could we add helpers those take a loglevel to show the info? (having as an example show_trace_log_lvl() that can "eat" a modifier already). Not that I want to sell the idea of KERN_UNSUPRESSED, but to my mind the alternative patches were kind of too intricate and bring more complexity to printk.. and there are only ~3(?) places those manipulate console_loglevel directly in the kernel tree (so we might want something simple and dumb as hell). Thanks, Dima
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On Wed 2019-06-12 17:36:43, Sergey Senozhatsky wrote: > On (06/06/19 09:10), Petr Mladek wrote: > > Just to be sure. I wanted to say that I like the idea with > > KERN_UNSUPRESSED. So, I think that we are on the same page. > > I understand. All I wanted to say is that KERN_UNSUPRESSED is > per-message, while the most interesting (and actually broken) > cases, IMHO, are per-context, IOW things like this one > > console_loglevel = NEW > foo() > dump_stack() >printk >... >printk > console_loglevel = OLD > > KERN_UNSUPRESSED does not help here. We probably can't convert > dump_stack() to KERN_UNSUPRESSED. I agree. I take KERN_UNSUPRESSED like a nice trick how to pass the information about the unsupressed printk context via printk_safe and printk_nmi per-CPU buffers. The single line in sysrq __handle_sysrq() seems to be the only location where KERN_UNSUPRESSED can be used directly. Best Regards, Petr
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On 2019/06/12 0:10, Petr Mladek wrote: > On Sat 2019-06-08 11:45:45, Tetsuo Handa wrote: >> On 2019/06/08 2:09, Pavel Machek wrote: >>> On Tue 2019-05-28 19:15:43, Tetsuo Handa wrote: On 2019/05/28 17:51, Sergey Senozhatsky wrote: >> You are trying to omit passing KERN_UNSUPPRESSED by utilizing implicit >> printk >> context information. But doesn't such attempt resemble >> find_printk_buffer() ? > > Adding KERN_UNSUPPRESSED to all printks down the op_p->handler() > line is hardly possible. At the same time I'd really prefer not > to have buffering for sysrq. I don't think it is hardly possible. And I really prefer having deferred printing for SysRq. > >>> >>> Well, magic SysRq was meant for situation where system is in weird/broken >>> state. >>> "Give me backtrace where it is hung", etc. Direct printing is more likely >>> to work >>> in that cases. >> >> Magic SysRq from keyboard is for situation where system is in weird/broken >> state. >> >> But I want to use Magic SysRq from /proc for situation where system is not >> fatally >> weird/broken state. I have trouble getting SysRq-t from /proc when something >> bad >> happened (e.g. some health check process did not return for 60 seconds). >> Since >> /proc/pid/wchan shows only 1 line, it is useless for understanding why that >> process >> got stuck. If direct printing is enforced, "echo t > /proc/sysrq-trigger" >> might take >> many minutes. If direct printing is not enforced, "echo t > >> /proc/sysrq-trigger" >> should complete within less than one second. If syslog is working (which is >> almost >> equivalent to being able to write to /proc/sysrq-trigger), the latter is >> more helpful >> for taking snapshots for multiple times (e.g. 5 times with 10 seconds >> interval) in >> order to understand why that process got stuck. That's why I added > > This looks like a very specific use case. But the proposal changes > the behavior for anyone. I am not persuaded that everyone would > appreciate the change. > > OK, it takes 60 seconds when the messages appear on the console and > 1 second when they are just stored to the syslog. > > Why the system is configured to show all messages on the console > when syslog is enough? We are talking about two things. First thing is about whether we should automatically add KERN_UNSUPPRESSED to all printks down the op_p->handler() line. I initially thought that we should automatically add KERN_UNSUPPRESSED, but I realized that we should not do it. I want to allow users to configure not to show all messages on the console when syslog is enough. > > If sysrq is the preferred interface, it might be used also the other > way. I mean to increase console_loglevel to hide all messages on > the console, trigger output of the system state and eventually > decrease the loglevel again. Right. Some distributions do the opposite thing in order to speed up the boot sequence; increase console_loglevel to hide most of messages on the console by default. We can trigger "SysRq-9" -> "SysRq-t" -> "SysRq-4" from keyboard in order to print all SysRq-t messages to the consoles when we need to do. Since vkdb_printf() uses CONSOLE_LOGLEVEL_SILENT, KERN_UNSUPPRESSED alone is not sufficient for avoid playing with console loglevel for tree wide. If we want to get rid of temporary manipulation of console loglevel for only SysRq, introducing KERN_UNSUPPRESSED would be OK. But we want to get rid of temporary manipulation of console loglevel for tree wide, don't we? If yes, I think that we will need per context "always print to consoles" / "never print to consoles" / "print to consoles based on console loglevel" control, for explicitly passing that control to foo()->dump_stack()->printk() will be (not impossible but) a huge change. > >> Also, regarding Magic SysRq from keyboard case, my intent is to allow SysRq >> to just store the messages to printk() buffer, in order to avoid stalls and >> take better snapshots for multiple times. And my intent of >> >> And I really prefer having deferred printing for SysRq. > > Always deferring printk() for everyone is not acceptable. It is one > extreme between printk() reliability and speed in favor of the speed. > But many people prefer reliability (high chance to see messages > when the system goes down. Second thing is about whether we can defer console_unlock() from specific callers. What I suggest is to enforce "never deferred" on e.g. SysRq-h and enforce "always deferred" on e.g. SysRq-t. Since console_unlock() enforces flushing of printk() buffer, users can trigger "SysRq-t" -> "SysRq-h" when SysRq-t failed to flush printk() buffer. > > IMHO, the only acceptable solution need to be configurable: > >+ never deffer (debugging corner cases?) >+ avoid softlockup (default on normal systems?) >+ guarantee max time (throughput oriented systems) >+ always deffer (real time, special usecases) Is this about only SysRq
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On (06/06/19 09:10), Petr Mladek wrote: > > > > > > Provide KERN_UNSUPPRESSED printk() annotation for such legacy > > > > > > places. > > > > > > Make sysrq print the headers unsuppressed instead of changing > > > > > > console_loglevel. > > > > > > I like this idea. console_loglevel is temporary manipulated only > > > when some messages should or should never appear on the console. > > > Storing this information in the message flags would help > > > to solve all the related races. > > > > I don't really like the whole system-wide console_loglevel manipulation > > thing, > > Just to be sure. I wanted to say that I like the idea with > KERN_UNSUPRESSED. So, I think that we are on the same page. I understand. All I wanted to say is that KERN_UNSUPRESSED is per-message, while the most interesting (and actually broken) cases, IMHO, are per-context, IOW things like this one console_loglevel = NEW foo() dump_stack() printk ... printk console_loglevel = OLD KERN_UNSUPRESSED does not help here. We probably can't convert dump_stack() to KERN_UNSUPRESSED. [..] > Now, KERN_EMERG might alarm some monitor of console output. It might > trigger unwanted reaction (forced reboot?) of the monitoring system > even when sysrq was not called in emergency situation. > > I am sure that we need to care about such monitors. I have to > think more about it. Sure. -ss
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On Sat 2019-06-08 11:45:45, Tetsuo Handa wrote: > On 2019/06/08 2:09, Pavel Machek wrote: > > On Tue 2019-05-28 19:15:43, Tetsuo Handa wrote: > >> On 2019/05/28 17:51, Sergey Senozhatsky wrote: > You are trying to omit passing KERN_UNSUPPRESSED by utilizing implicit > printk > context information. But doesn't such attempt resemble > find_printk_buffer() ? > >>> > >>> Adding KERN_UNSUPPRESSED to all printks down the op_p->handler() > >>> line is hardly possible. At the same time I'd really prefer not > >>> to have buffering for sysrq. > >> > >> I don't think it is hardly possible. And I really prefer having > >> deferred printing for SysRq. > > > > Well, magic SysRq was meant for situation where system is in weird/broken > > state. > > "Give me backtrace where it is hung", etc. Direct printing is more likely > > to work > > in that cases. > > Magic SysRq from keyboard is for situation where system is in weird/broken > state. > > But I want to use Magic SysRq from /proc for situation where system is not > fatally > weird/broken state. I have trouble getting SysRq-t from /proc when something > bad > happened (e.g. some health check process did not return for 60 seconds). Since > /proc/pid/wchan shows only 1 line, it is useless for understanding why that > process > got stuck. If direct printing is enforced, "echo t > /proc/sysrq-trigger" > might take > many minutes. If direct printing is not enforced, "echo t > > /proc/sysrq-trigger" > should complete within less than one second. If syslog is working (which is > almost > equivalent to being able to write to /proc/sysrq-trigger), the latter is more > helpful > for taking snapshots for multiple times (e.g. 5 times with 10 seconds > interval) in > order to understand why that process got stuck. That's why I added This looks like a very specific use case. But the proposal changes the behavior for anyone. I am not persuaded that everyone would appreciate the change. OK, it takes 60 seconds when the messages appear on the console and 1 second when they are just stored to the syslog. Why the system is configured to show all messages on the console when syslog is enough? If sysrq is the preferred interface, it might be used also the other way. I mean to increase console_loglevel to hide all messages on the console, trigger output of the system state and eventually decrease the loglevel again. > Also, regarding Magic SysRq from keyboard case, my intent is to allow SysRq > to just store the messages to printk() buffer, in order to avoid stalls and > take better snapshots for multiple times. And my intent of > > And I really prefer having deferred printing for SysRq. Always deferring printk() for everyone is not acceptable. It is one extreme between printk() reliability and speed in favor of the speed. But many people prefer reliability (high chance to see messages when the system goes down. IMHO, the only acceptable solution need to be configurable: + never deffer (debugging corner cases?) + avoid softlockup (default on normal systems?) + guarantee max time (throughput oriented systems) + always deffer (real time, special usecases) It might be based on Sergey's patchsets adding the offload logic into console_unlock(). IMHO, the most problematic thing is how to define the limit (lines?, characters?, time?). A limit bases on the data amount would also depend on console speed. Time based limit would be better but measuring time in console_unlock() is problematic (atomic context, possible deadlocks). Best Regards, Petr
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On 2019/06/08 2:09, Pavel Machek wrote:
> On Tue 2019-05-28 19:15:43, Tetsuo Handa wrote:
>> On 2019/05/28 17:51, Sergey Senozhatsky wrote:
You are trying to omit passing KERN_UNSUPPRESSED by utilizing implicit
printk
context information. But doesn't such attempt resemble
find_printk_buffer() ?
>>>
>>> Adding KERN_UNSUPPRESSED to all printks down the op_p->handler()
>>> line is hardly possible. At the same time I'd really prefer not
>>> to have buffering for sysrq.
>>
>> I don't think it is hardly possible. And I really prefer having
>> deferred printing for SysRq.
>
> Well, magic SysRq was meant for situation where system is in weird/broken
> state.
> "Give me backtrace where it is hung", etc. Direct printing is more likely to
> work
> in that cases.
Magic SysRq from keyboard is for situation where system is in weird/broken
state.
But I want to use Magic SysRq from /proc for situation where system is not
fatally
weird/broken state. I have trouble getting SysRq-t from /proc when something bad
happened (e.g. some health check process did not return for 60 seconds). Since
/proc/pid/wchan shows only 1 line, it is useless for understanding why that
process
got stuck. If direct printing is enforced, "echo t > /proc/sysrq-trigger" might
take
many minutes. If direct printing is not enforced, "echo t > /proc/sysrq-trigger"
should complete within less than one second. If syslog is working (which is
almost
equivalent to being able to write to /proc/sysrq-trigger), the latter is more
helpful
for taking snapshots for multiple times (e.g. 5 times with 10 seconds interval)
in
order to understand why that process got stuck. That's why I added
At first I though that we also want to apply temporary
manipulation of console loglevel for SysRq to the body lines, for showing
only the header line is hardly helpful. But I realized that we should not
force showing the body lines because some users might be triggering SysRq
from /proc and reading via syslog rather than via console output. Users
who need to read via console output should be able to manipulate console
loglevel by triggering SysRq from console.
part in
https://lkml.kernel.org/r/c265f674-e293-332b-a037-895025354...@i-love.sakura.ne.jp
.
A snapshot which was taken within less than one second and a snapshot which was
taken
across more than many minutes, which one likely shows more accurate "snapshot" ?
I know we need to take a snapshot like vmcore if we need a perfect snapshot
which
was taken with CPUs stopped. But in enterprise systems where it is difficult to
do "echo c > /proc/sysrq-trigger" in order to take a perfect snapshot, snapshots
which can be taken without destroying the VM comes in handy. There are
situations
where something went wrong but still able to operate.
Also, regarding Magic SysRq from keyboard case, my intent is to allow SysRq
to just store the messages to printk() buffer, in order to avoid stalls and
take better snapshots for multiple times. And my intent of
And I really prefer having deferred printing for SysRq.
is "we can let some other SysRq command (e.g. SysRq-h) to write to consoles in
printk() buffer,
when printk() buffer filled by SysRq-t did not get written to consoles
automatically".
We can implement it by introducing "printk() which uses global printk() buffer
but
do not try to write to consoles" and "passing context information which tells
whether
printk() messages should be written to consoles synchronously". An example is
shown below.
drivers/tty/sysrq.c| 3 +++
include/linux/printk.h | 15
include/linux/sched.h | 1 +
kernel/printk/printk.c | 62 +-
mm/oom_kill.c | 3 +++
mm/page_alloc.c| 3 +++
6 files changed, 86 insertions(+), 1 deletion(-)
diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index 18cb58e52e9b..135acbe5c389 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -543,6 +543,7 @@ void __handle_sysrq(int key, bool check_mask)
*/
orig_log_level = get_local_loglevel();
set_local_loglevel(CONSOLE_LOGLEVEL_DEFAULT);
+ enable_deferred_output();
op_p = __sysrq_get_key_op(key);
if (op_p) {
@@ -576,10 +577,12 @@ void __handle_sysrq(int key, bool check_mask)
pr_cont("\n");
set_local_loglevel(orig_log_level);
}
+ disable_deferred_output();
rcu_read_unlock();
rcu_sysrq_end();
suppress_printk = orig_suppress_printk;
+ trigger_deferred_output();
}
void handle_sysrq(int key)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 78b357a1b109..18392376932b 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -196,6 +196,9 @@ extern void printk_safe_flush(void);
extern void printk_safe_flush_on_panic(void);
int get_local_loglevel(void);
void set_local_loglevel(int level);
+void enable_deferred_output(void);
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On Tue 2019-05-28 19:15:43, Tetsuo Handa wrote: > On 2019/05/28 17:51, Sergey Senozhatsky wrote: > >> You are trying to omit passing KERN_UNSUPPRESSED by utilizing implicit > >> printk > >> context information. But doesn't such attempt resemble > >> find_printk_buffer() ? > > > > Adding KERN_UNSUPPRESSED to all printks down the op_p->handler() > > line is hardly possible. At the same time I'd really prefer not > > to have buffering for sysrq. > > I don't think it is hardly possible. And I really prefer having > deferred printing for SysRq. Well, magic SysRq was meant for situation where system is in weird/broken state. "Give me backtrace where it is hung", etc. Direct printing is more likely to work in that cases. Pavel
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On Mon 2019-06-03 15:51:53, Sergey Senozhatsky wrote: > On (05/28/19 15:42), Petr Mladek wrote: > > On Tue 2019-05-28 13:46:19, Sergey Senozhatsky wrote: > > > On (05/28/19 13:15), Sergey Senozhatsky wrote: > > > > On (05/28/19 01:24), Dmitry Safonov wrote: > > > > [..] > > > > > While handling sysrq the console_loglevel is bumped to default to > > > > > print > > > > > sysrq headers. It's done to print sysrq messages with WARNING level > > > > > for > > > > > consumers of /proc/kmsg, though it sucks by the following reasons: > > > > > - changing console_loglevel may produce tons of messages (especially > > > > > on > > > > > bloated with debug/info prints systems) > > > > > - it doesn't guarantee that the message will be printed as printk may > > > > > deffer the actual console output from buffer (see the comment near > > > > > printk() in kernel/printk/printk.c) > > > > > > > > > > Provide KERN_UNSUPPRESSED printk() annotation for such legacy places. > > > > > Make sysrq print the headers unsuppressed instead of changing > > > > > console_loglevel. > > > > I like this idea. console_loglevel is temporary manipulated only > > when some messages should or should never appear on the console. > > Storing this information in the message flags would help > > to solve all the related races. > > I don't really like the whole system-wide console_loglevel manipulation > thing, Just to be sure. I wanted to say that I like the idea with KERN_UNSUPRESSED. So, I think that we are on the same page. > except for console_verbose(), which seems the be the only legit > case. Note that CONSOLE_LOGLEVEL_SILENT is used in vkdb_printf(). I do not know the background. But it might make some sense in kdb context. > If KERN_UNSUPPRESSED is going to be > yet-another-way-to-print-important-messages > then I'm slightly less excited. Yes, KERN_EMERG would do similar job. Well, my understanding is that KERN_UNSUPRESSED would be used even for less critical messages because the visibility is required by the context or situation in which they are printed. For example, we want to make all information visible in Oops because the machine might be about to die. We might call there some shared functions that produce less important messages in another context. Also the pr_info() in __handle_sysrq() provides just informative content. My understanding is that we want to show it just because sysrq might be called when the system is not responding and we want to give the user some feedback that the sysrq handler was called. Now, KERN_EMERG might alarm some monitor of console output. It might trigger unwanted reaction (forced reboot?) of the monitoring system even when sysrq was not called in emergency situation. I am sure that we need to care about such monitors. I have to think more about it. Best Regards, Petr
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On (05/28/19 15:42), Petr Mladek wrote: > On Tue 2019-05-28 13:46:19, Sergey Senozhatsky wrote: > > On (05/28/19 13:15), Sergey Senozhatsky wrote: > > > On (05/28/19 01:24), Dmitry Safonov wrote: > > > [..] > > > > While handling sysrq the console_loglevel is bumped to default to print > > > > sysrq headers. It's done to print sysrq messages with WARNING level for > > > > consumers of /proc/kmsg, though it sucks by the following reasons: > > > > - changing console_loglevel may produce tons of messages (especially on > > > > bloated with debug/info prints systems) > > > > - it doesn't guarantee that the message will be printed as printk may > > > > deffer the actual console output from buffer (see the comment near > > > > printk() in kernel/printk/printk.c) > > > > > > > > Provide KERN_UNSUPPRESSED printk() annotation for such legacy places. > > > > Make sysrq print the headers unsuppressed instead of changing > > > > console_loglevel. > > I like this idea. console_loglevel is temporary manipulated only > when some messages should or should never appear on the console. > Storing this information in the message flags would help > to solve all the related races. I don't really like the whole system-wide console_loglevel manipulation thing, expect for console_verbose(), which seems the be the only legit case. Maybe we better do something about it. I like the idea of KERN_UNSUPPRESSED, especially if it will let us to completely remove those console_loglevel manipulations. E.g. console_loglevel = NEW; foo() bar() dump_stack(); console_loglevel = OLD; I understand the intent, but printk() is deferred (not always but still), so this code is not really expected to do the same thing all the time. Especially when it comes to NMI, etc. If KERN_UNSUPPRESSED is going to be yet-another-way-to-print-important-messages then I'm slightly less excited. -ss
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On 2019/05/28 22:42, Petr Mladek wrote:
> On Tue 2019-05-28 13:46:19, Sergey Senozhatsky wrote:
>> On (05/28/19 13:15), Sergey Senozhatsky wrote:
>>> On (05/28/19 01:24), Dmitry Safonov wrote:
>>> [..]
While handling sysrq the console_loglevel is bumped to default to print
sysrq headers. It's done to print sysrq messages with WARNING level for
consumers of /proc/kmsg, though it sucks by the following reasons:
- changing console_loglevel may produce tons of messages (especially on
bloated with debug/info prints systems)
- it doesn't guarantee that the message will be printed as printk may
deffer the actual console output from buffer (see the comment near
printk() in kernel/printk/printk.c)
Provide KERN_UNSUPPRESSED printk() annotation for such legacy places.
Make sysrq print the headers unsuppressed instead of changing
console_loglevel.
>
> I like this idea. console_loglevel is temporary manipulated only
> when some messages should or should never appear on the console.
> Storing this information in the message flags would help
> to solve all the related races.
Something like this?
---
arch/ia64/kernel/mca.c| 37 +++
arch/x86/platform/uv/uv_nmi.c | 6 ++---
drivers/tty/sysrq.c | 9 +++
include/linux/printk.h| 24 +-
include/linux/sched.h | 3 +++
kernel/debug/kdb/kdb_bt.c | 5 ++--
kernel/debug/kdb/kdb_io.c | 5 ++--
kernel/debug/kdb/kdb_main.c | 5 ++--
kernel/printk/printk.c| 59 +++
kernel/printk/printk_safe.c | 2 ++
10 files changed, 105 insertions(+), 50 deletions(-)
diff --git a/arch/ia64/kernel/mca.c b/arch/ia64/kernel/mca.c
index 6a52d76..5f3968c 100644
--- a/arch/ia64/kernel/mca.c
+++ b/arch/ia64/kernel/mca.c
@@ -189,19 +189,24 @@
static unsigned long mlogbuf_timestamp = 0;
static int loglevel_save = -1;
-#define BREAK_LOGLEVEL(__console_loglevel) \
- oops_in_progress = 1; \
- if (loglevel_save < 0) \
- loglevel_save = __console_loglevel; \
- __console_loglevel = 15;
-
-#define RESTORE_LOGLEVEL(__console_loglevel) \
- if (loglevel_save >= 0) { \
- __console_loglevel = loglevel_save; \
- loglevel_save = -1; \
- } \
- mlogbuf_finished = 0; \
- oops_in_progress = 0;
+#define BREAK_LOGLEVEL() \
+ do {\
+ int ret;\
+ oops_in_progress = 1; \
+ ret = set_local_loglevel(CONSOLE_LOGLEVEL_MOTORMOUTH); \
+ if (loglevel_save < 0) \
+ loglevel_save = ret;\
+ } while (0)
+
+#define RESTORE_LOGLEVEL() \
+ do {\
+ if (loglevel_save >= 0) { \
+ set_local_loglevel(loglevel_save); \
+ loglevel_save = -1; \
+ } \
+ mlogbuf_finished = 0; \
+ oops_in_progress = 0; \
+ } while (0)
/*
* Push messages into buffer, print them later if not urgent.
@@ -288,7 +293,7 @@ void ia64_mlogbuf_dump(void)
*/
static void ia64_mlogbuf_finish(int wait)
{
- BREAK_LOGLEVEL(console_loglevel);
+ BREAK_LOGLEVEL();
spin_lock_init(_rlock);
ia64_mlogbuf_dump();
@@ -1623,7 +1628,7 @@ static void mca_insert_tr(u64 iord)
* To enable show_stack from INIT, we use oops_in_progress which should
* be used in real oops. This would cause something wrong after INIT.
*/
- BREAK_LOGLEVEL(console_loglevel);
+ BREAK_LOGLEVEL();
ia64_mlogbuf_dump_from_init();
printk(KERN_ERR "Processes interrupted by INIT -");
@@ -1648,7 +1653,7 @@ static void mca_insert_tr(u64 iord)
read_unlock(_lock);
}
/* FIXME: This will not restore zapped printk locks. */
- RESTORE_LOGLEVEL(console_loglevel);
+ RESTORE_LOGLEVEL();
return NOTIFY_DONE;
}
diff --git a/arch/x86/platform/uv/uv_nmi.c b/arch/x86/platform/uv/uv_nmi.c
index b21a932..48592d1 100644
--- a/arch/x86/platform/uv/uv_nmi.c
+++ b/arch/x86/platform/uv/uv_nmi.c
@@ -766,13 +766,13 @@ static void uv_nmi_dump_state(int cpu, struct pt_regs
*regs, int master)
if (master) {
int tcpu;
Re: [RFC] printk/sysrq: Don't play with console_loglevel
Hi guys, I see that the thread is ongoing and you understand printk code much better than me or probably anybody :) So, feel free to reuse it. Or I can send v1 with split sysrq/printk parts if you think it's worth being shaped further. I think worth to mention three "features" that you might had a chance to miss from the current code: 1. op_p->handler(key) is not printed under console_loglevel hackery. So, under RFC I preserved the behavior. Probably, you don't miss it and just looking into ways to change it, but I thought worth mentioning. 2. I've found it surprising how pr_info() interacts with pr_cont(): Basically, pr_cont() without KERN_ prefix will print the resulting line with default_message_loglevel AFAIU from cont.level. Which might be higher than warning. I might miss a part that corrects cont.level to the first message's level? 3. CONSOLE_LOGLEVEL_DEFAULT is config-based, so having in mind that it can be changed and (2) - it gives me hard time to understand when the sysrq message will be printed and when will be suppressed. Thanks, Dmitry
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On 2019/05/29 0:03, Petr Mladek wrote: >> But is context dependent buffer large enough to hold SysRq-t output? >> I think that only main logbuf can become large enough to hold SysRq-t output. > > SysRq messages are stored directly into the main log buffer. > > The limited per-CPU buffers are needed only in printk_safe > and NMI context. We discussed it here because KERN_UNSUPPRESSED > allows to pass the information even from this context. > >> We can add KERN_UNSUPPRESSED to SysRq's header line. But I don't think >> that we can automatically add KERN_UNSUPPRESSED to SysRq's body lines >> based on some context information. If we want to avoid manipulating >> console_loglevel, we need to think about how to make sure that >> KERN_UNSUPPRESSED is added to all lines from such context without >> overflowing capacity of that buffer. > > We could set this context in printk_context per-CPU variable. > > Then we could easily add the set per-message flag in > vprintk_store() for the normal/atomic context. And we > could store an extra KERN_UNSUPPRESSED in printk_safe_log_store() > for printk_safe and NMI context. Now I got what you are trying to do. Borrow per-CPU printk_context flags for automatically prefixing KERN_UNSUPPRESSED, based on an assumption that any message sent during that per-CPU printk_context flag set is important enough. Then, what we need to be careful is nesting of setting/clearing of that flag, for NMI handler might be called during SysRq operation is in progress. We unconditionally prefix KERN_UNSUPPRESSED if NMI?
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On Tue 2019-05-28 23:21:17, Tetsuo Handa wrote: > On 2019/05/28 22:42, Petr Mladek wrote: > >> Ahh.. OK, now I sort of remember why I gave up on this idea (see [1] > >> at the bottom, when it comes to uv_nmi_dump_state()) - printk_NMI and > >> printk-safe redirections. > >> > >>NMI > >>loglevel = NEW > >>printk -> printk_safe_nmi > >>loglevel = OLD > >> > >>iret > >> > >>IRQ > >>flush printk_safe_nmi -> printk > >>// At this point we don't remember about > >>// loglevel manipulation anymore > >>iret > > > > printk_safe buffer preserves KERN_* headers. It should be > > possible to insert KERN_UNSUPPRESSED there. > > But is context dependent buffer large enough to hold SysRq-t output? > I think that only main logbuf can become large enough to hold SysRq-t output. SysRq messages are stored directly into the main log buffer. The limited per-CPU buffers are needed only in printk_safe and NMI context. We discussed it here because KERN_UNSUPPRESSED allows to pass the information even from this context. > We can add KERN_UNSUPPRESSED to SysRq's header line. But I don't think > that we can automatically add KERN_UNSUPPRESSED to SysRq's body lines > based on some context information. If we want to avoid manipulating > console_loglevel, we need to think about how to make sure that > KERN_UNSUPPRESSED is added to all lines from such context without > overflowing capacity of that buffer. We could set this context in printk_context per-CPU variable. Then we could easily add the set per-message flag in vprintk_store() for the normal/atomic context. And we could store an extra KERN_UNSUPPRESSED in printk_safe_log_store() for printk_safe and NMI context. Best Regards, Petr
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On 2019/05/28 22:42, Petr Mladek wrote: >> Ahh.. OK, now I sort of remember why I gave up on this idea (see [1] >> at the bottom, when it comes to uv_nmi_dump_state()) - printk_NMI and >> printk-safe redirections. >> >> NMI >> loglevel = NEW >> printk -> printk_safe_nmi >> loglevel = OLD >> >> iret >> >> IRQ >> flush printk_safe_nmi -> printk >> // At this point we don't remember about >> // loglevel manipulation anymore >> iret > > printk_safe buffer preserves KERN_* headers. It should be > possible to insert KERN_UNSUPPRESSED there. But is context dependent buffer large enough to hold SysRq-t output? I think that only main logbuf can become large enough to hold SysRq-t output. We can add KERN_UNSUPPRESSED to SysRq's header line. But I don't think that we can automatically add KERN_UNSUPPRESSED to SysRq's body lines based on some context information. If we want to avoid manipulating console_loglevel, we need to think about how to make sure that KERN_UNSUPPRESSED is added to all lines from such context without overflowing capacity of that buffer.
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On Tue 2019-05-28 19:15:43, Tetsuo Handa wrote: > On 2019/05/28 17:51, Sergey Senozhatsky wrote: > >> You are trying to omit passing KERN_UNSUPPRESSED by utilizing implicit > >> printk > >> context information. But doesn't such attempt resemble > >> find_printk_buffer() ? > > > > Adding KERN_UNSUPPRESSED to all printks down the op_p->handler() > > line is hardly possible. At the same time I'd really prefer not > > to have buffering for sysrq. > > I don't think it is hardly possible. And I really prefer having > deferred printing for SysRq. This thread is about problems with manipulating console_loglevel. "Deferred printk" is another very complicated and controversial problem. Please, discuss it in a separate thread. Thanks in advance. Best Regards, Petr Mladek
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On Tue 2019-05-28 13:46:19, Sergey Senozhatsky wrote: > On (05/28/19 13:15), Sergey Senozhatsky wrote: > > On (05/28/19 01:24), Dmitry Safonov wrote: > > [..] > > > While handling sysrq the console_loglevel is bumped to default to print > > > sysrq headers. It's done to print sysrq messages with WARNING level for > > > consumers of /proc/kmsg, though it sucks by the following reasons: > > > - changing console_loglevel may produce tons of messages (especially on > > > bloated with debug/info prints systems) > > > - it doesn't guarantee that the message will be printed as printk may > > > deffer the actual console output from buffer (see the comment near > > > printk() in kernel/printk/printk.c) > > > > > > Provide KERN_UNSUPPRESSED printk() annotation for such legacy places. > > > Make sysrq print the headers unsuppressed instead of changing > > > console_loglevel. I like this idea. console_loglevel is temporary manipulated only when some messages should or should never appear on the console. Storing this information in the message flags would help to solve all the related races. > > I've been thinking about this a while ago... So what I thought back > > then was that affected paths are atomic: sysrq, irqs, NMI, etc. Well > > at leasted it seemed to be so. Yes, this would be useful for the other situations when all printk's in a particular context should be handled this way. We could build it on top of this patch. > Ahh.. OK, now I sort of remember why I gave up on this idea (see [1] > at the bottom, when it comes to uv_nmi_dump_state()) - printk_NMI and > printk-safe redirections. > > NMI > loglevel = NEW > printk -> printk_safe_nmi > loglevel = OLD > > iret > > IRQ > flush printk_safe_nmi -> printk > // At this point we don't remember about > // loglevel manipulation anymore > iret printk_safe buffer preserves KERN_* headers. It should be possible to insert KERN_UNSUPPRESSED there. The patch itself looks fine on the first sight. If we go forward, please, split the printk and sysrq part into two patches. Best Regards, Petr
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On 2019/05/28 17:51, Sergey Senozhatsky wrote: >> You are trying to omit passing KERN_UNSUPPRESSED by utilizing implicit printk >> context information. But doesn't such attempt resemble find_printk_buffer() ? > > Adding KERN_UNSUPPRESSED to all printks down the op_p->handler() > line is hardly possible. At the same time I'd really prefer not > to have buffering for sysrq. I don't think it is hardly possible. And I really prefer having deferred printing for SysRq. SysRq is triggered by writing to /proc/sysrq-trigger or typing special keys on the keyboard. This means that SysRq can be triggered by administrator's will, and SysRq can be repeated/retried by administrator's will. Therefore, allowing SysRq-t to write to consoles after leaving the atomic context is an improvement. My proposal allows deferred printing for SysRq, dump_header() and warn_alloc(). We can try to wake up console_writer kernel thread upon leaving the atomic context. If the kernel is unhealthy enough to make console_writer kernel thread defunctional, administrator can issue other SysRq in order to forcibly write to consoles. Is the attempt of making printk() completely asynchronous going to be resumed? I think that "automatically asynchronous" won't be accepted, and I think that at best "explicitly asynchronous" (by allowing the caller to explicitly say it using printk() argument) is possible. (Maybe "asynchronous by default" and "explicitly synchronous" is possible. But "explicitly synchronous" would be told by using printk() argument rather than by implicit/global printk context information...) Anyway, forcing SysRq output to apply ignore_loglevel will be doable using printk() argument.
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On (05/28/19 17:02), Tetsuo Handa wrote: > On 2019/05/28 13:22, Sergey Senozhatsky wrote: > > On (05/28/19 12:21), Tetsuo Handa wrote: > > [..] > Dmitry's patch is changing only the header line (in other words, per printk() > call). > Since op_p->handler(key) is out of KERN_UNSUPPRESSED effect, the body lines > might > not be printed. Right. > I think that we need a way to pass KERN_UNSUPPRESSED from printk() > calls invoked from op_p->handler(key). Right. That's what the per-CPU context bit address. > You are trying to omit passing KERN_UNSUPPRESSED by utilizing implicit printk > context information. But doesn't such attempt resemble find_printk_buffer() ? Adding KERN_UNSUPPRESSED to all printks down the op_p->handler() line is hardly possible. At the same time I'd really prefer not to have buffering for sysrq. -ss
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On 2019/05/28 13:22, Sergey Senozhatsky wrote:
> On (05/28/19 12:21), Tetsuo Handa wrote:
> [..]
>> What I suggested in my proposal ("printk: Introduce "store now but print
>> later" prefix." at
>> https://lore.kernel.org/lkml/1550896930-12324-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp/T/#u
>> )
>> is "whether the caller wants to defer printing to consoles regarding
>> this printk() call". And your suggestion is "whether the caller wants
>> to apply ignore_loglevel regarding this printk() call".
>
> I'm not sure about "store now but print later" here. What Dmitry is
> talking about:
>
> bump console_loglevel on *this* particular CPU only,
> not system-wide.
> /* Which is implemented in a form of - all messages from this-CPU
> * only should be printed regardless the loglevel, the rest should
> * pass the usual suppress_message_printing() check. */
Dmitry's patch is changing only the header line (in other words, per printk()
call).
Since op_p->handler(key) is out of KERN_UNSUPPRESSED effect, the body lines
might
not be printed. I think that we need a way to pass KERN_UNSUPPRESSED from
printk()
calls invoked from op_p->handler(key).
You are trying to omit passing KERN_UNSUPPRESSED by utilizing implicit printk
context information. But doesn't such attempt resemble find_printk_buffer() ?
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On (05/28/19 13:15), Sergey Senozhatsky wrote: > On (05/28/19 01:24), Dmitry Safonov wrote: > [..] > > While handling sysrq the console_loglevel is bumped to default to print > > sysrq headers. It's done to print sysrq messages with WARNING level for > > consumers of /proc/kmsg, though it sucks by the following reasons: > > - changing console_loglevel may produce tons of messages (especially on > > bloated with debug/info prints systems) > > - it doesn't guarantee that the message will be printed as printk may > > deffer the actual console output from buffer (see the comment near > > printk() in kernel/printk/printk.c) > > > > Provide KERN_UNSUPPRESSED printk() annotation for such legacy places. > > Make sysrq print the headers unsuppressed instead of changing > > console_loglevel. > > I've been thinking about this a while ago... So what I thought back > then was that affected paths are atomic: sysrq, irqs, NMI, etc. Well > at leasted it seemed to be so. Ahh.. OK, now I sort of remember why I gave up on this idea (see [1] at the bottom, when it comes to uv_nmi_dump_state()) - printk_NMI and printk-safe redirections. NMI loglevel = NEW printk -> printk_safe_nmi loglevel = OLD iret IRQ flush printk_safe_nmi -> printk // At this point we don't remember about // loglevel manipulation anymore iret We, probably, still need some flags to pass the "this was supposed to be an important messages" info from printk-safe to normal printk. On the other hand, if NMI printk-s then it's something rather important, so we probably better print it anyway and avoid suppress_message_printing() check for messages which are coming from printk-NMI buffers. To some extent, it's the same with printk-safe: we don't use it unless we have a very good reason. So if there is something in printk-safe buffers then it better end up on consoles. So, maybe, we still can use that per-CPU printk_context thing. [1] https://lore.kernel.org/lkml/20180601044050.GA5687@jagdpanzerIV/ -ss
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On (05/28/19 12:21), Tetsuo Handa wrote:
[..]
> What I suggested in my proposal ("printk: Introduce "store now but print
> later" prefix." at
> https://lore.kernel.org/lkml/1550896930-12324-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp/T/#u
> )
> is "whether the caller wants to defer printing to consoles regarding
> this printk() call". And your suggestion is "whether the caller wants
> to apply ignore_loglevel regarding this printk() call".
I'm not sure about "store now but print later" here. What Dmitry is
talking about:
bump console_loglevel on *this* particular CPU only,
not system-wide.
/* Which is implemented in a form of - all messages from this-CPU
* only should be printed regardless the loglevel, the rest should
* pass the usual suppress_message_printing() check. */
-ss
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On (05/28/19 01:24), Dmitry Safonov wrote:
[..]
> While handling sysrq the console_loglevel is bumped to default to print
> sysrq headers. It's done to print sysrq messages with WARNING level for
> consumers of /proc/kmsg, though it sucks by the following reasons:
> - changing console_loglevel may produce tons of messages (especially on
> bloated with debug/info prints systems)
> - it doesn't guarantee that the message will be printed as printk may
> deffer the actual console output from buffer (see the comment near
> printk() in kernel/printk/printk.c)
>
> Provide KERN_UNSUPPRESSED printk() annotation for such legacy places.
> Make sysrq print the headers unsuppressed instead of changing
> console_loglevel.
I've been thinking about this a while ago... So what I thought back
then was that affected paths are atomic: sysrq, irqs, NMI, etc. Well
at leasted it seemed to be so. Hence we can use per-CPU flag to tell
printk that whatever comes from this-CPU is important and printk should
eventually print it (next time it hits console_unlock()). One candidate
for such per-CPU flag was this_cpu(printk_context). We can steal high
bit (next to NMI printk_safe bit). So the intended use case was something
like this
sysrq/etc /* atomic context */
{
printk_blah_enter();
for (...)
printk();
...
dump_bar();
prinkt_blah_exit();
}
printk_blah_enter() would set that special - printk_safe_mask_blah - bit,
and prinkt_blah_exit() would clear it. Whenever prinkt->vprintk_store()
would see printk_safe_mask_blah bit set it would mark the log_stored message
as "important, always print!", and console_unlock() would always print those
"important" messages.
-ss
Re: [RFC] printk/sysrq: Don't play with console_loglevel
On 2019/05/28 9:24, Dmitry Safonov wrote:
> Provide KERN_UNSUPPRESSED printk() annotation for such legacy places.
> Make sysrq print the headers unsuppressed instead of changing
> console_loglevel.
I think that kdb also wants to use KERN_UNSUPPRESSED for making sure
that messages are printed. But that user calls dump function which is
indirectly calling printk() many times. Thus, I think that we need a
way to explicitly pass "how the message should be treated" as a
function argument.
What I suggested in my proposal ("printk: Introduce "store now but print later"
prefix." at
https://lore.kernel.org/lkml/1550896930-12324-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp/T/#u
)
is "whether the caller wants to defer printing to consoles regarding
this printk() call". And your suggestion is "whether the caller wants
to apply ignore_loglevel regarding this printk() call".
