--- zzzz-none-000/linux-4.9.325/kernel/printk/printk.c 2022-07-29 15:05:48.000000000 +0000 +++ seale-7590ax-800/linux-4.9.325/kernel/printk/printk.c 2024-09-18 09:50:47.000000000 +0000 @@ -45,6 +45,7 @@ #include #include #include +#include #include #include @@ -79,6 +80,18 @@ struct console *console_drivers; EXPORT_SYMBOL_GPL(console_drivers); +/* AVM RTE extension for caller_id */ +#define PRINTK_CALLER_IRQ 0x80000000 /* Same as in mainline */ +#define PRINTK_CALLER_AVM_RTE 0x40000000 +#define PRINTK_CALLER_MASK (PRINTK_CALLER_IRQ | PRINTK_CALLER_AVM_RTE) +/* + * Decode RTE context from caller_id. + * We can assume less than 255 cpus on AVM products, + * and yield TC is one byte. + */ +#define __avm_caller_cpu(id) (id & 0xff) +#define __avm_caller_tc(id) ((id >> 8) & 0xff) + #ifdef CONFIG_LOCKDEP static struct lockdep_map console_lock_dep_map = { .name = "console_lock" @@ -130,13 +143,10 @@ /* * Set sysctl string accordingly: */ - if (devkmsg_log == DEVKMSG_LOG_MASK_ON) { - memset(devkmsg_log_str, 0, DEVKMSG_STR_MAX_SIZE); - strncpy(devkmsg_log_str, "on", 2); - } else if (devkmsg_log == DEVKMSG_LOG_MASK_OFF) { - memset(devkmsg_log_str, 0, DEVKMSG_STR_MAX_SIZE); - strncpy(devkmsg_log_str, "off", 3); - } + if (devkmsg_log == DEVKMSG_LOG_MASK_ON) + strcpy(devkmsg_log_str, "on"); + else if (devkmsg_log == DEVKMSG_LOG_MASK_OFF) + strcpy(devkmsg_log_str, "off"); /* else "ratelimit" which is set by default. */ /* @@ -215,16 +225,18 @@ static int __down_trylock_console_sem(unsigned long ip) { - if (down_trylock(&console_sem)) + if (yield_down_trylock(&console_sem)) return 1; - mutex_acquire(&console_lock_dep_map, 0, 1, ip); + if (yield_is_linux_context()) + mutex_acquire(&console_lock_dep_map, 0, 1, ip); return 0; } #define down_trylock_console_sem() __down_trylock_console_sem(_RET_IP_) #define up_console_sem() do { \ - mutex_release(&console_lock_dep_map, 1, _RET_IP_);\ - up(&console_sem);\ + if (yield_is_linux_context())\ + mutex_release(&console_lock_dep_map, 1, _RET_IP_);\ + yield_up(&console_sem);\ } while (0) /* @@ -340,6 +352,9 @@ u8 facility; /* syslog facility */ u8 flags:5; /* internal record flags */ u8 level:3; /* syslog level */ +#ifdef CONFIG_PRINTK_CALLER + u32 caller_id; /* thread id or processor id */ +#endif } #ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS __packed __aligned(4) @@ -376,7 +391,11 @@ static u64 clear_seq; static u32 clear_idx; +#ifdef CONFIG_PRINTK_CALLER +#define PREFIX_MAX 48 +#else #define PREFIX_MAX 32 +#endif #define LOG_LINE_MAX (1024 - PREFIX_MAX) #define LOG_LEVEL(v) ((v) & 0x07) @@ -531,7 +550,7 @@ } /* insert record into the buffer, discard old ones, update heads */ -static int log_store(int facility, int level, +static int log_store(u32 caller_id, int facility, int level, enum log_flags flags, u64 ts_nsec, const char *dict, u16 dict_len, const char *text, u16 text_len) @@ -578,7 +597,10 @@ if (ts_nsec > 0) msg->ts_nsec = ts_nsec; else - msg->ts_nsec = local_clock(); + msg->ts_nsec = yield_local_clock(); +#ifdef CONFIG_PRINTK_CALLER + msg->caller_id = caller_id; +#endif memset(log_dict(msg) + dict_len, 0, pad_len); msg->len = size; @@ -639,16 +661,35 @@ *(*pp)++ = c; } +static void __maybe_unused __print_caller(u32 id, char *buf, size_t size) +{ + if (id & PRINTK_CALLER_AVM_RTE) + snprintf(buf, size, "Y%u:%u", + __avm_caller_cpu(id), __avm_caller_tc(id)); + else + snprintf(buf, size, "%c%u", + id & PRINTK_CALLER_IRQ ? 'C' : 'T', + id & ~PRINTK_CALLER_MASK); +} + static ssize_t msg_print_ext_header(char *buf, size_t size, struct printk_log *msg, u64 seq) { u64 ts_usec = msg->ts_nsec; + char caller[20]; +#ifdef CONFIG_PRINTK_CALLER + size_t len = sprintf(caller, ",caller="); + + __print_caller(msg->caller_id, &caller[len], sizeof(caller) - len); +#else + caller[0] = '\0'; +#endif do_div(ts_usec, 1000); - return scnprintf(buf, size, "%u,%llu,%llu,%c;", - (msg->facility << 3) | msg->level, seq, ts_usec, - msg->flags & LOG_CONT ? 'c' : '-'); + return scnprintf(buf, size, "%u,%llu,%llu,%c%s;", + (msg->facility << 3) | msg->level, seq, ts_usec, + msg->flags & LOG_CONT ? 'c' : '-', caller); } static ssize_t msg_print_ext_body(char *buf, size_t size, @@ -979,6 +1020,9 @@ VMCOREINFO_OFFSET(printk_log, len); VMCOREINFO_OFFSET(printk_log, text_len); VMCOREINFO_OFFSET(printk_log, dict_len); +#ifdef CONFIG_PRINTK_CALLER + VMCOREINFO_OFFSET(printk_log, caller_id); +#endif } #endif @@ -1168,6 +1212,11 @@ static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME); module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR); +static size_t print_syslog(unsigned int level, char *buf) +{ + return sprintf(buf, "<%u>", level); +} + static size_t print_time(u64 ts, char *buf) { unsigned long rem_nsec; @@ -1177,33 +1226,38 @@ rem_nsec = do_div(ts, 1000000000); - if (!buf) - return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts); - - return sprintf(buf, "[%5lu.%06lu] ", + return sprintf(buf, "[%5lu.%06lu]", (unsigned long)ts, rem_nsec / 1000); } +#ifdef CONFIG_PRINTK_CALLER +static size_t print_caller(u32 id, char *buf) +{ + char caller[12]; + + __print_caller(id, caller, sizeof(caller)); + return sprintf(buf, "[%6s]", caller); +} +#else +#define print_caller(id, buf) 0 +#endif + static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf) { size_t len = 0; - unsigned int prefix = (msg->facility << 3) | msg->level; - if (syslog) { - if (buf) { - len += sprintf(buf, "<%u>", prefix); - } else { - len += 3; - if (prefix > 999) - len += 3; - else if (prefix > 99) - len += 2; - else if (prefix > 9) - len++; - } + if (syslog) + len = print_syslog((msg->facility << 3) | msg->level, buf); + + len += print_time(msg->ts_nsec, buf + len); + + len += print_caller(msg->caller_id, buf + len); + + if (IS_ENABLED(CONFIG_PRINTK_CALLER) || printk_time) { + buf[len++] = ' '; + buf[len] = '\0'; } - len += print_time(msg->ts_nsec, buf ? buf + len : NULL); return len; } @@ -1212,6 +1266,8 @@ const char *text = log_text(msg); size_t text_size = msg->text_len; size_t len = 0; + char prefix[PREFIX_MAX]; + const size_t prefix_len = print_prefix(msg, syslog, prefix); do { const char *next = memchr(text, '\n', text_size); @@ -1226,19 +1282,17 @@ } if (buf) { - if (print_prefix(msg, syslog, NULL) + - text_len + 1 >= size - len) + if (prefix_len + text_len + 1 >= size - len) break; - len += print_prefix(msg, syslog, buf + len); + memcpy(buf + len, prefix, prefix_len); + len += prefix_len; memcpy(buf + len, text, text_len); len += text_len; buf[len++] = '\n'; } else { /* SYSLOG_ACTION_* buffer size only calculation */ - len += print_prefix(msg, syslog, NULL); - len += text_len; - len++; + len += prefix_len + text_len + 1; } text = next; @@ -1522,6 +1576,7 @@ * Call the console drivers, asking them to write out * log_buf[start] to log_buf[end - 1]. * The console_lock must be held. + * YIELD-Kontext-fest */ static void call_console_drivers(int level, const char *ext_text, size_t ext_len, @@ -1529,8 +1584,11 @@ { struct console *con; + if (!yield_is_linux_context()) { + /*--- niemals Std-Konsole fuer yield-context! ---*/ + return; + } trace_console_rcuidle(text, len); - if (!console_drivers) return; @@ -1587,6 +1645,19 @@ } } +static inline u32 printk_caller_id(void) +{ + u32 tc = is_yield_context(); + + BUILD_BUG_ON(PID_MAX_LIMIT > ~PRINTK_CALLER_MASK); + if (tc) + return PRINTK_CALLER_AVM_RTE + ((tc-1) << 8) + raw_smp_processor_id(); + + /* In Linux context, use unchanged upstream format */ + return in_task() ? task_pid_nr(current) : + PRINTK_CALLER_IRQ + raw_smp_processor_id(); +} + /* * Continuation lines are buffered, and not committed to the record buffer * until the line is complete, or a race forces it. The line fragments @@ -1596,46 +1667,26 @@ static struct cont { char buf[LOG_LINE_MAX]; size_t len; /* length == 0 means unused buffer */ - size_t cons; /* bytes written to console */ - struct task_struct *owner; /* task of first print*/ + u32 caller_id; /* printk_caller_id() of first print */ u64 ts_nsec; /* time of first print */ u8 level; /* log level of first message */ u8 facility; /* log facility of first message */ enum log_flags flags; /* prefix, newline flags */ - bool flushed:1; /* buffer sealed and committed */ } cont; static void cont_flush(void) { - if (cont.flushed) - return; if (cont.len == 0) return; - if (cont.cons) { - /* - * If a fragment of this line was directly flushed to the - * console; wait for the console to pick up the rest of the - * line. LOG_NOCONS suppresses a duplicated output. - */ - log_store(cont.facility, cont.level, cont.flags | LOG_NOCONS, - cont.ts_nsec, NULL, 0, cont.buf, cont.len); - cont.flushed = true; - } else { - /* - * If no fragment of this line ever reached the console, - * just submit it to the store and free the buffer. - */ - log_store(cont.facility, cont.level, cont.flags, 0, - NULL, 0, cont.buf, cont.len); - cont.len = 0; - } + + log_store(cont.caller_id, cont.facility, cont.level, cont.flags, + cont.ts_nsec, NULL, 0, cont.buf, cont.len); + cont.len = 0; } -static bool cont_add(int facility, int level, enum log_flags flags, const char *text, size_t len) +static bool cont_add(u32 caller_id, int facility, int level, + enum log_flags flags, const char *text, size_t len) { - if (cont.len && cont.flushed) - return false; - /* * If ext consoles are present, flush and skip in-kernel * continuation. See nr_ext_console_drivers definition. Also, if @@ -1649,11 +1700,9 @@ if (!cont.len) { cont.facility = facility; cont.level = level; - cont.owner = current; - cont.ts_nsec = local_clock(); + cont.caller_id = caller_id; + cont.ts_nsec = yield_local_clock(); cont.flags = flags; - cont.cons = 0; - cont.flushed = false; } memcpy(cont.buf + cont.len, text, len); @@ -1672,43 +1721,17 @@ return true; } -static size_t cont_print_text(char *text, size_t size) -{ - size_t textlen = 0; - size_t len; - - if (cont.cons == 0) { - textlen += print_time(cont.ts_nsec, text); - size -= textlen; - } - - len = cont.len - cont.cons; - if (len > 0) { - if (len+1 > size) - len = size-1; - memcpy(text + textlen, cont.buf + cont.cons, len); - textlen += len; - cont.cons = cont.len; - } - - if (cont.flushed) { - if (cont.flags & LOG_NEWLINE) - text[textlen++] = '\n'; - /* got everything, release buffer */ - cont.len = 0; - } - return textlen; -} - static size_t log_output(int facility, int level, enum log_flags lflags, const char *dict, size_t dictlen, char *text, size_t text_len) { + const u32 caller_id = printk_caller_id(); + /* * If an earlier line was buffered, and we're a continuation - * write from the same process, try to add it to the buffer. + * write from the same context, try to add it to the buffer. */ if (cont.len) { - if (cont.owner == current && (lflags & LOG_CONT)) { - if (cont_add(facility, level, lflags, text, text_len)) + if (cont.caller_id == caller_id && (lflags & LOG_CONT)) { + if (cont_add(caller_id, facility, level, lflags, text, text_len)) return text_len; } /* Otherwise, make sure it's flushed */ @@ -1721,12 +1744,13 @@ /* If it doesn't end in a newline, try to buffer the current line */ if (!(lflags & LOG_NEWLINE)) { - if (cont_add(facility, level, lflags, text, text_len)) + if (cont_add(caller_id, facility, level, lflags, text, text_len)) return text_len; } /* Store it in the record log */ - return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len); + return log_store(caller_id, facility, level, lflags, 0, + dict, dictlen, text, text_len); } asmlinkage int vprintk_emit(int facility, int level, @@ -1738,7 +1762,7 @@ char *text = textbuf; size_t text_len = 0; enum log_flags lflags = 0; - unsigned long flags; + unsigned long flags = 0; int this_cpu; int printed_len = 0; int nmi_message_lost; @@ -1751,16 +1775,18 @@ in_sched = true; } - boot_delay_msec(level); - printk_delay(); + if (yield_is_linux_context()) { + boot_delay_msec(level); + printk_delay(); + } - local_irq_save(flags); + yield_local_irq_save(flags); this_cpu = smp_processor_id(); /* * Ouch, printk recursed into itself! */ - if (unlikely(logbuf_cpu == this_cpu)) { + if (unlikely(yield_is_linux_context() && logbuf_cpu == this_cpu)) { /* * If a crash is occurring during printk() on this CPU, * then try to get the crash message out but make sure @@ -1776,9 +1802,11 @@ zap_locks(); } - lockdep_off(); + if (yield_is_linux_context()) { + lockdep_off(); + } /* This stops the holder of console_sem just where we want him */ - raw_spin_lock(&logbuf_lock); + yield_raw_spin_lock(&logbuf_lock); logbuf_cpu = this_cpu; if (unlikely(recursion_bug)) { @@ -1787,7 +1815,8 @@ recursion_bug = false; /* emit KERN_CRIT message */ - printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0, + printed_len += log_store(printk_caller_id(), 0, 2, + LOG_PREFIX|LOG_NEWLINE, 0, NULL, 0, recursion_msg, strlen(recursion_msg)); } @@ -1797,7 +1826,8 @@ text_len = scnprintf(textbuf, sizeof(textbuf), "BAD LUCK: lost %d message(s) from NMI context!", nmi_message_lost); - printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0, + printed_len += log_store(printk_caller_id(), 0, 2, + LOG_PREFIX|LOG_NEWLINE, 0, NULL, 0, textbuf, text_len); } @@ -1844,13 +1874,17 @@ printed_len += log_output(facility, level, lflags, dict, dictlen, text, text_len); logbuf_cpu = UINT_MAX; - raw_spin_unlock(&logbuf_lock); - lockdep_on(); - local_irq_restore(flags); + yield_raw_spin_unlock(&logbuf_lock); + if (yield_is_linux_context()) { + lockdep_on(); + } + yield_local_irq_restore(flags); /* If called from the scheduler, we can not call up(). */ if (!in_sched) { - lockdep_off(); + if (yield_is_linux_context()) { + lockdep_off(); + } /* * Try to acquire and then immediately release the console * semaphore. The release will print out buffers and wake up @@ -1858,7 +1892,9 @@ */ if (console_trylock()) console_unlock(); - lockdep_on(); + if (yield_is_linux_context()) { + lockdep_on(); + } } return printed_len; @@ -1948,12 +1984,6 @@ static u64 log_first_seq; static u32 log_first_idx; static u64 log_next_seq; -static struct cont { - size_t len; - size_t cons; - u8 level; - bool flushed:1; -} cont; static char *log_text(const struct printk_log *msg) { return NULL; } static char *log_dict(const struct printk_log *msg) { return NULL; } static struct printk_log *log_from_idx(u32 idx) { return NULL; } @@ -1969,7 +1999,6 @@ const char *text, size_t len) {} static size_t msg_print_text(const struct printk_log *msg, bool syslog, char *buf, size_t size) { return 0; } -static size_t cont_print_text(char *text, size_t size) { return 0; } static bool suppress_message_printing(int level) { return false; } /* Still needs to be defined for users */ @@ -2189,6 +2218,7 @@ * access to the console system and the console_drivers list. * * returns 1 on success, and 0 on failure to acquire the lock. + * YIELD-Kontext fest */ int console_trylock(void) { @@ -2210,7 +2240,7 @@ * rcu_preempt_depth(), otherwise RCU read sections modify * preempt_count(). */ - console_may_schedule = !oops_in_progress && + console_may_schedule = yield_is_linux_context() && !oops_in_progress && preemptible() && !rcu_preempt_depth(); return 1; @@ -2250,42 +2280,6 @@ return cpu_online(raw_smp_processor_id()) || have_callable_console(); } -static void console_cont_flush(char *text, size_t size) -{ - unsigned long flags; - size_t len; - - raw_spin_lock_irqsave(&logbuf_lock, flags); - - if (!cont.len) - goto out; - - if (suppress_message_printing(cont.level)) { - cont.cons = cont.len; - if (cont.flushed) - cont.len = 0; - goto out; - } - - /* - * We still queue earlier records, likely because the console was - * busy. The earlier ones need to be printed before this one, we - * did not flush any fragment so far, so just let it queue up. - */ - if (console_seq < log_next_seq && !cont.cons) - goto out; - - len = cont_print_text(text, size); - raw_spin_unlock(&logbuf_lock); - stop_critical_timings(); - call_console_drivers(cont.level, NULL, 0, text, len); - start_critical_timings(); - local_irq_restore(flags); - return; -out: - raw_spin_unlock_irqrestore(&logbuf_lock, flags); -} - /** * console_unlock - unlock the console system * @@ -2299,6 +2293,7 @@ * If there is output waiting, we wake /dev/kmsg and syslog() users. * * console_unlock(); may be called from any context. + * YIELD-Kontext fest */ void console_unlock(void) { @@ -2343,16 +2338,13 @@ return; } - /* flush buffered message fragment immediately to console */ - console_cont_flush(text, sizeof(text)); - for (;;) { struct printk_log *msg; size_t ext_len = 0; size_t len; int level; - raw_spin_lock_irqsave(&logbuf_lock, flags); + yield_raw_spin_lock_irqsave(&logbuf_lock, flags); if (seen_seq != log_next_seq) { wake_klogd = true; seen_seq = log_next_seq; @@ -2374,8 +2366,7 @@ msg = log_from_idx(console_idx); level = msg->level; - if ((msg->flags & LOG_NOCONS) || - suppress_message_printing(level)) { + if (suppress_message_printing(level)) { /* * Skip record we have buffered and already printed * directly to the console when we received it, and @@ -2383,12 +2374,6 @@ */ console_idx = log_next(console_idx); console_seq++; - /* - * We will get here again when we register a new - * CON_PRINTBUFFER console. Clear the flag so we - * will properly dump everything later. - */ - msg->flags &= ~LOG_NOCONS; goto skip; } @@ -2404,12 +2389,12 @@ } console_idx = log_next(console_idx); console_seq++; - raw_spin_unlock(&logbuf_lock); + yield_raw_spin_unlock(&logbuf_lock); - stop_critical_timings(); /* don't trace print latency */ + yield_stop_critical_timings(); /* don't trace print latency */ call_console_drivers(level, ext_text, ext_len, text, len); - start_critical_timings(); - local_irq_restore(flags); + yield_start_critical_timings(); + yield_local_irq_restore(flags); if (do_cond_resched) cond_resched(); @@ -2420,7 +2405,7 @@ if (unlikely(exclusive_console)) exclusive_console = NULL; - raw_spin_unlock(&logbuf_lock); + yield_raw_spin_unlock(&logbuf_lock); up_console_sem(); @@ -2430,14 +2415,14 @@ * there's a new owner and the console_unlock() from them will do the * flush, no worries. */ - raw_spin_lock(&logbuf_lock); + yield_raw_spin_lock(&logbuf_lock); retry = console_seq != log_next_seq; - raw_spin_unlock_irqrestore(&logbuf_lock, flags); + yield_raw_spin_unlock_irqrestore(&logbuf_lock, flags); if (retry && console_trylock()) goto again; - if (wake_klogd) + if (wake_klogd && yield_is_linux_context()) wake_up_klogd(); } EXPORT_SYMBOL(console_unlock);