mirrors/linux-stable
1
0
Fork 0
mirror of https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git synced 2024-10-01 06:33:07 +00:00
Code Issues Releases Wiki Activity

printk: refactor and rework printing logic

Browse source 
Refactor/rework printing logic in order to prepare for moving to
threaded console printing.

- Move @console_seq into struct console so that the current
  "position" of each console can be tracked individually.

- Move @console_dropped into struct console so that the current drop
  count of each console can be tracked individually.

- Modify printing logic so that each console independently loads,
  prepares, and prints its next record.

- Remove exclusive_console logic. Since console positions are
  handled independently, replaying past records occurs naturally.

- Update the comments explaining why preemption is disabled while
  printing from printk() context.

With these changes, there is a change in behavior: the console
replaying the log (formerly exclusive console) will no longer block
other consoles. New messages appear on the other consoles while the
newly added console is still replaying.

Signed-off-by: John Ogness <john.ogness@linutronix.de>
Reviewed-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Petr Mladek <pmladek@suse.com>
Link: https://lore.kernel.org/r/20220421212250.565456-10-john.ogness@linutronix.de
This commit is contained in:
John Ogness 2022-04-21 23:28:44 +02:06 committed by Petr Mladek
parent 1fc0ca9e0d
commit a699449bb1
2 changed files with 231 additions and 214 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
include/linux/console.h
View file

@ -151,6 +151,8 @@ struct console {
int cflag;
uint ispeed;
uint ospeed;
u64 seq;
unsigned long dropped;
void *data;
struct console *next;
};

443
kernel/printk/printk.c
View file

@ -280,11 +280,6 @@ static bool panic_in_progress(void)
*/
static int console_locked, console_suspended;
/*
* If exclusive_console is non-NULL then only this console is to be printed to.
*/
static struct console *exclusive_console;
/*
* Array of consoles built from command line options (console=)
*/
@ -374,12 +369,6 @@ static u64 syslog_seq;
static size_t syslog_partial;
static bool syslog_time;
/* All 3 protected by @console_sem. */
/* the next printk record to write to the console */
static u64 console_seq;
static u64 exclusive_console_stop_seq;
static unsigned long console_dropped;
struct latched_seq {
seqcount_latch_t latch;
u64 val[2];
@ -1933,47 +1922,26 @@ static int console_trylock_spinning(void)
}
/*
* Call the console drivers, asking them to write out
* log_buf[start] to log_buf[end - 1].
* The console_lock must be held.
* Call the specified console driver, asking it to write out the specified
* text and length. For non-extended consoles, if any records have been
* dropped, a dropped message will be written out first.
*/
static void call_console_drivers(const char *ext_text, size_t ext_len,
const char *text, size_t len)
static void call_console_driver(struct console *con, const char *text, size_t len)
{
static char dropped_text[64];
size_t dropped_len = 0;
struct console *con;
size_t dropped_len;
trace_console_rcuidle(text, len);
if (!console_drivers)
return;
if (console_dropped) {
if (con->dropped && !(con->flags & CON_EXTENDED)) {
dropped_len = snprintf(dropped_text, sizeof(dropped_text),
"** %lu printk messages dropped **\n",
console_dropped);
console_dropped = 0;
con->dropped);
con->dropped = 0;
con->write(con, dropped_text, dropped_len);
}
for_each_console(con) {
if (exclusive_console && con != exclusive_console)
continue;
if (!(con->flags & CON_ENABLED))
continue;
if (!con->write)
continue;
if (!cpu_online(smp_processor_id()) &&
!(con->flags & CON_ANYTIME))
continue;
if (con->flags & CON_EXTENDED)
con->write(con, ext_text, ext_len);
else {
if (dropped_len)
con->write(con, dropped_text, dropped_len);
con->write(con, text, len);
}
}
con->write(con, text, len);
}
/*
@ -2283,15 +2251,18 @@ asmlinkage int vprintk_emit(int facility, int level,
/* If called from the scheduler, we can not call up(). */
if (!in_sched) {
/*
* Disable preemption to avoid being preempted while holding
* console_sem which would prevent anyone from printing to
* console
* The caller may be holding system-critical or
* timing-sensitive locks. Disable preemption during
* printing of all remaining records to all consoles so that
* this context can return as soon as possible. Hopefully
* another printk() caller will take over the printing.
*/
preempt_disable();
/*
* Try to acquire and then immediately release the console
* semaphore. The release will print out buffers and wake up
* /dev/kmsg and syslog() users.
* semaphore. The release will print out buffers. With the
* spinning variant, this context tries to take over the
* printing from another printing context.
*/
if (console_trylock_spinning())
console_unlock();
@ -2329,11 +2300,9 @@ EXPORT_SYMBOL(_printk);
#define prb_read_valid(rb, seq, r) false
#define prb_first_valid_seq(rb) 0
#define prb_next_seq(rb) 0
static u64 syslog_seq;
static u64 console_seq;
static u64 exclusive_console_stop_seq;
static unsigned long console_dropped;
static size_t record_print_text(const struct printk_record *r,
bool syslog, bool time)
@ -2350,8 +2319,7 @@ static ssize_t msg_print_ext_body(char *buf, size_t size,
struct dev_printk_info *dev_info) { return 0; }
static void console_lock_spinning_enable(void) { }
static int console_lock_spinning_disable_and_check(void) { return 0; }
static void call_console_drivers(const char *ext_text, size_t ext_len,
const char *text, size_t len) {}
static void call_console_driver(struct console *con, const char *text, size_t len) { }
static bool suppress_message_printing(int level) { return false; }
#endif /* CONFIG_PRINTK */
@ -2621,22 +2589,6 @@ int is_console_locked(void)
}
EXPORT_SYMBOL(is_console_locked);
/*
* Check if we have any console that is capable of printing while cpu is
* booting or shutting down. Requires console_sem.
*/
static int have_callable_console(void)
{
struct console *con;
for_each_console(con)
if ((con->flags & CON_ENABLED) &&
(con->flags & CON_ANYTIME))
return 1;
return 0;
}
/*
* Return true when this CPU should unlock console_sem without pushing all
* messages to the console. This reduces the chance that the console is
@ -2657,15 +2609,182 @@ static bool abandon_console_lock_in_panic(void)
}
/*
* Can we actually use the console at this time on this cpu?
* Check if the given console is currently capable and allowed to print
* records.
*
* Console drivers may assume that per-cpu resources have been allocated. So
* unless they're explicitly marked as being able to cope (CON_ANYTIME) don't
* call them until this CPU is officially up.
* Requires the console_lock.
*/
static inline int can_use_console(void)
static inline bool console_is_usable(struct console *con)
{
return cpu_online(raw_smp_processor_id()) || have_callable_console();
if (!(con->flags & CON_ENABLED))
return false;
if (!con->write)
return false;
/*
* Console drivers may assume that per-cpu resources have been
* allocated. So unless they're explicitly marked as being able to
* cope (CON_ANYTIME) don't call them until this CPU is officially up.
*/
if (!cpu_online(raw_smp_processor_id()) &&
!(con->flags & CON_ANYTIME))
return false;
return true;
}
static void __console_unlock(void)
{
console_locked = 0;
up_console_sem();
}
/*
* Print one record for the given console. The record printed is whatever
* record is the next available record for the given console.
*
* @handover will be set to true if a printk waiter has taken over the
* console_lock, in which case the caller is no longer holding the
* console_lock. Otherwise it is set to false.
*
* Returns false if the given console has no next record to print, otherwise
* true.
*
* Requires the console_lock.
*/
static bool console_emit_next_record(struct console *con, bool *handover)
{
static char ext_text[CONSOLE_EXT_LOG_MAX];
static char text[CONSOLE_LOG_MAX];
static int panic_console_dropped;
struct printk_info info;
struct printk_record r;
unsigned long flags;
char *write_text;
size_t len;
prb_rec_init_rd(&r, &info, text, sizeof(text));
*handover = false;
if (!prb_read_valid(prb, con->seq, &r))
return false;
if (con->seq != r.info->seq) {
con->dropped += r.info->seq - con->seq;
con->seq = r.info->seq;
if (panic_in_progress() && panic_console_dropped++ > 10) {
suppress_panic_printk = 1;
pr_warn_once("Too many dropped messages. Suppress messages on non-panic CPUs to prevent livelock.\n");
}
}
/* Skip record that has level above the console loglevel. */
if (suppress_message_printing(r.info->level)) {
con->seq++;
goto skip;
}
if (con->flags & CON_EXTENDED) {
write_text = &ext_text[0];
len = info_print_ext_header(ext_text, sizeof(ext_text), r.info);
len += msg_print_ext_body(ext_text + len, sizeof(ext_text) - len,
&r.text_buf[0], r.info->text_len, &r.info->dev_info);
} else {
write_text = &text[0];
len = record_print_text(&r, console_msg_format & MSG_FORMAT_SYSLOG, printk_time);
}
/*
* While actively printing out messages, if another printk()
* were to occur on another CPU, it may wait for this one to
* finish. This task can not be preempted if there is a
* waiter waiting to take over.
*
* Interrupts are disabled because the hand over to a waiter
* must not be interrupted until the hand over is completed
* (@console_waiter is cleared).
*/
printk_safe_enter_irqsave(flags);
console_lock_spinning_enable();
stop_critical_timings(); /* don't trace print latency */
call_console_driver(con, write_text, len);
start_critical_timings();
con->seq++;
*handover = console_lock_spinning_disable_and_check();
printk_safe_exit_irqrestore(flags);
skip:
return true;
}
/*
* Print out all remaining records to all consoles.
*
* @do_cond_resched is set by the caller. It can be true only in schedulable
* context.
*
* @next_seq is set to the sequence number after the last available record.
* The value is valid only when this function returns true. It means that all
* usable consoles are completely flushed.
*
* @handover will be set to true if a printk waiter has taken over the
* console_lock, in which case the caller is no longer holding the
* console_lock. Otherwise it is set to false.
*
* Returns true when there was at least one usable console and all messages
* were flushed to all usable consoles. A returned false informs the caller
* that everything was not flushed (either there were no usable consoles or
* another context has taken over printing or it is a panic situation and this
* is not the panic CPU). Regardless the reason, the caller should assume it
* is not useful to immediately try again.
*
* Requires the console_lock.
*/
static bool console_flush_all(bool do_cond_resched, u64 *next_seq, bool *handover)
{
bool any_usable = false;
struct console *con;
bool any_progress;
*next_seq = 0;
*handover = false;
do {
any_progress = false;
for_each_console(con) {
bool progress;
if (!console_is_usable(con))
continue;
any_usable = true;
progress = console_emit_next_record(con, handover);
if (*handover)
return false;
/* Track the next of the highest seq flushed. */
if (con->seq > *next_seq)
*next_seq = con->seq;
if (!progress)
continue;
any_progress = true;
/* Allow panic_cpu to take over the consoles safely. */
if (abandon_console_lock_in_panic())
return false;
if (do_cond_resched)
cond_resched();
}
} while (any_progress);
return any_usable;
}
/**
@ -2678,28 +2797,20 @@ static inline int can_use_console(void)
* by printk(). If this is the case, console_unlock(); emits
* the output prior to releasing the lock.
*
* If there is output waiting, we wake /dev/kmsg and syslog() users.
*
* console_unlock(); may be called from any context.
*/
void console_unlock(void)
{
static char ext_text[CONSOLE_EXT_LOG_MAX];
static char text[CONSOLE_LOG_MAX];
static int panic_console_dropped;
unsigned long flags;
bool do_cond_resched, retry;
struct printk_info info;
struct printk_record r;
u64 __maybe_unused next_seq;
bool do_cond_resched;
bool handover;
bool flushed;
u64 next_seq;
if (console_suspended) {
up_console_sem();
return;
}
prb_rec_init_rd(&r, &info, text, sizeof(text));
/*
* Console drivers are called with interrupts disabled, so
* @console_may_schedule should be cleared before; however, we may
@ -2708,125 +2819,34 @@ void console_unlock(void)
* between lines if allowable. Not doing so can cause a very long
* scheduling stall on a slow console leading to RCU stall and
* softlockup warnings which exacerbate the issue with more
* messages practically incapacitating the system.
*
* console_trylock() is not able to detect the preemptive
* context reliably. Therefore the value must be stored before
* and cleared after the "again" goto label.
* messages practically incapacitating the system. Therefore, create
* a local to use for the printing loop.
*/
do_cond_resched = console_may_schedule;
again:
console_may_schedule = 0;
/*
* We released the console_sem lock, so we need to recheck if
* cpu is online and (if not) is there at least one CON_ANYTIME
* console.
*/
if (!can_use_console()) {
console_locked = 0;
up_console_sem();
return;
}
do {
console_may_schedule = 0;
for (;;) {
size_t ext_len = 0;
int handover;
size_t len;
skip:
if (!prb_read_valid(prb, console_seq, &r))
break;
if (console_seq != r.info->seq) {
console_dropped += r.info->seq - console_seq;
console_seq = r.info->seq;
if (panic_in_progress() && panic_console_dropped++ > 10) {
suppress_panic_printk = 1;
pr_warn_once("Too many dropped messages. Suppress messages on non-panic CPUs to prevent livelock.\n");
}
}
if (suppress_message_printing(r.info->level)) {
/*
* Skip record we have buffered and already printed
* directly to the console when we received it, and
* record that has level above the console loglevel.
*/
console_seq++;
goto skip;
}
/* Output to all consoles once old messages replayed. */
if (unlikely(exclusive_console &&
console_seq >= exclusive_console_stop_seq)) {
exclusive_console = NULL;
}
flushed = console_flush_all(do_cond_resched, &next_seq, &handover);
if (!handover)
__console_unlock();
/*
* Handle extended console text first because later
* record_print_text() will modify the record buffer in-place.
* Abort if there was a failure to flush all messages to all
* usable consoles. Either it is not possible to flush (in
* which case it would be an infinite loop of retrying) or
* another context has taken over printing.
*/
if (nr_ext_console_drivers) {
ext_len = info_print_ext_header(ext_text,
sizeof(ext_text),
r.info);
ext_len += msg_print_ext_body(ext_text + ext_len,
sizeof(ext_text) - ext_len,
&r.text_buf[0],
r.info->text_len,
&r.info->dev_info);
}
len = record_print_text(&r,
console_msg_format & MSG_FORMAT_SYSLOG,
printk_time);
console_seq++;
/*
* While actively printing out messages, if another printk()
* were to occur on another CPU, it may wait for this one to
* finish. This task can not be preempted if there is a
* waiter waiting to take over.
*
* Interrupts are disabled because the hand over to a waiter
* must not be interrupted until the hand over is completed
* (@console_waiter is cleared).
*/
printk_safe_enter_irqsave(flags);
console_lock_spinning_enable();
stop_critical_timings(); /* don't trace print latency */
call_console_drivers(ext_text, ext_len, text, len);
start_critical_timings();
handover = console_lock_spinning_disable_and_check();
printk_safe_exit_irqrestore(flags);
if (handover)
return;
/* Allow panic_cpu to take over the consoles safely */
if (abandon_console_lock_in_panic())
if (!flushed)
break;
if (do_cond_resched)
cond_resched();
}
/* Get consistent value of the next-to-be-used sequence number. */
next_seq = console_seq;
console_locked = 0;
up_console_sem();
/*
* Someone could have filled up the buffer again, so re-check if there's
* something to flush. In case we cannot trylock the console_sem again,
* there's a new owner and the console_unlock() from them will do the
* flush, no worries.
*/
retry = prb_read_valid(prb, next_seq, NULL);
if (retry && !abandon_console_lock_in_panic() && console_trylock())
goto again;
/*
* Some context may have added new records after
* console_flush_all() but before unlocking the console.
* Re-check if there is a new record to flush. If the trylock
* fails, another context is already handling the printing.
*/
} while (prb_read_valid(prb, next_seq, NULL) && console_trylock());
}
EXPORT_SYMBOL(console_unlock);
@ -2886,8 +2906,14 @@ void console_flush_on_panic(enum con_flush_mode mode)
console_trylock();
console_may_schedule = 0;
if (mode == CONSOLE_REPLAY_ALL)
console_seq = prb_first_valid_seq(prb);
if (mode == CONSOLE_REPLAY_ALL) {
struct console *c;
u64 seq;
seq = prb_first_valid_seq(prb);
for_each_console(c)
c->seq = seq;
}
console_unlock();
}
@ -3127,26 +3153,15 @@ void register_console(struct console *newcon)
if (newcon->flags & CON_EXTENDED)
nr_ext_console_drivers++;
newcon->dropped = 0;
if (newcon->flags & CON_PRINTBUFFER) {
/*
* console_unlock(); will print out the buffered messages
* for us.
*
* We're about to replay the log buffer. Only do this to the
* just-registered console to avoid excessive message spam to
* the already-registered consoles.
*
* Set exclusive_console with disabled interrupts to reduce
* race window with eventual console_flush_on_panic() that
* ignores console_lock.
*/
exclusive_console = newcon;
exclusive_console_stop_seq = console_seq;
/* Get a consistent copy of @syslog_seq. */
mutex_lock(&syslog_lock);
console_seq = syslog_seq;
newcon->seq = syslog_seq;
mutex_unlock(&syslog_lock);
} else {
/* Begin with next message. */
newcon->seq = prb_next_seq(prb);
}
console_unlock();
console_sysfs_notify();