Patchset for kernel 3.10 (fixing lockup in printk)
Subsystems (4)
Hallo all,
attached to this mail you will find a couple of patches fixing one bug I have with kernel 3.10 (all subreleases).
These patches have been developed originally by Jan Kara ([email protected], I guess you
know him better than I do) for kernel 3.13 and can be found here:
https://lkml.org/lkml/2014/3/25/343
I just have backported them to kernel 3.10.
Also I have created (at least it was a try by myself) a bugentry on kernel.org:
https://bugzilla.kernel.org/show_bug.cgi?id=71231
(I have to update it yet)
Summarize:
Creating lots of output on console that is going to be printed on serial port too (via kernel command line "console=ttyS0") will hang several systems (mostly Dell servers with multiple CPUs).
I can easily reproduce this behaviour by creating about 50 virtual LUNs via fibrechannel at once.
This patch from Jan introduces a buffering and better locking in printk (as far as I understood him or his patches right).
Without this patches I get teh following stacktraces and the system is not responding after a couple of seconds:
119.504736] Code: 00 48 89 f0 48 c7 06 00 00 00 00 48 89 e5 48 87 07
48 85 c0 75 09 c7 46 08 01 00 00 00 5d c3 48 89 30 8b 46 08 85 c0 75 f4 f3 90 <8b> 46 08 85 c0 74 f7 5d c3 0f 1f 44 00 00 48 8b 16 55 48 89 e5 [
119.504740] NMI backtrace for cpu 44
[ 119.504746] CPU: 44 PID: 21877 Comm: lsscsi Not tainted 3.10.32-64bit #1 [ 119.504748] Hardware name: Dell Inc. PowerEdge R910/0P658H, BIOS 1.0.1 02/19/2010 [ 119.504751] task: ffff881063510d60 ti: ffff88106351c000 task.ti: ffff88106351c000 [ 119.504760] RIP: 0010:[<ffffffff8105e505>] [<ffffffff8105e505>] mspin_lock+0x35/0x40 [ 119.504763] RSP: 0018:ffff88106351db38 EFLAGS: 00000246 [ 119.504765] RAX: 0000000000000000 RBX: ffffffff81aa9220 RCX: 0000000000000028 [ 119.504768] RDX: ffff88106351dfd8 RSI: ffff88106351db60 RDI: ffffffff81aa9240 [ 119.504770] RBP: ffff88106351db38 R08: 70722f3374736f68 R09: fefefefefefefeff [ 119.504772] R10: ffff88086ddc5bc0 R11: 8f8dd0cc8b8c9097 R12: ffff88106351db60 [ 119.504774] R13: ffffffff81aa9240 R14: ffff881063510d60 R15: ffff88106351dca8 [ 119.504777] FS: 0000000000000000(0000) GS:ffff88046fd60000(0063) knlGS:00000000f762f8d0 [ 119.504780] CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033 [ 119.504782] CR2: 00000000f777c000 CR3: 00000010684ea000 CR4: 00000000000007e0 [ 119.504785] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 119.504788] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 119.504789] Stack: [ 119.504794] ffff88106351dba8 ffffffff81766d5d ffff88106351db58 ffff88106351dfd8 [ 119.504798] ffff88106351dba8 ffff881066ebfb90 ffff881000000000 ffffffff00000003 [ 119.504803] ffff88106351db98 ffffffff81aa9220 ffff88106351dc98 ffff88046c3a94d0 [ 119.504804] Call Trace: [ 119.504812] [<ffffffff81766d5d>] __mutex_lock_slowpath+0x5d/0x1d0 [ 119.504817] [<ffffffff817667dd>] mutex_lock+0x1d/0x40 [ 119.504823] [<ffffffff81156ba5>] sysfs_dentry_revalidate+0x35/0x100 [ 119.504828] [<ffffffff810ff389>] lookup_fast+0x299/0x2e0 [ 119.504833] [<ffffffff810ff586>] ? __inode_permission+0x46/0x70 [ 119.504838] [<ffffffff810ff79a>] link_path_walk+0x19a/0x810 [ 119.504843] [<ffffffff810ff994>] link_path_walk+0x394/0x810 [ 119.504848] [<ffffffff810b9b8f>] ? release_pages+0x18f/0x1e0 [ 119.504853] [<ffffffff81103094>] path_openat.isra.72+0x94/0x460 [ 119.504859] [<ffffffff810cbf84>] ? tlb_flush_mmu+0x54/0x90 [ 119.504864] [<ffffffff810d2c79>] ? unmap_region+0xd9/0x120 [ 119.504869] [<ffffffff8110368c>] do_filp_open+0x3c/0x90 [ 119.504875] [<ffffffff8110ee52>] ? __alloc_fd+0x42/0x100 [ 119.504882] [<ffffffff810f3a3f>] do_sys_open+0xef/0x1d0 [ 119.504888] [<ffffffff8113a036>] compat_SyS_open+0x16/0x20 [ 119.504893] [<ffffffff8176b598>] sysenter_dispatch+0x7/0x25 [ 119.504938] Code: f0 48 c7 06 00 00 00 00 48 89 e5 48 87 07 48 85 c0 75 09 c7 46 08 01 00 00 00 5d c3 48 89 30 8b 46 08 85 c0 75 f4 f3 90 8b 46 08 <85> c0 74 f7 5d c3 0f 1f 44 00 00 48 8b 16 55 48 89 e5 48 85 d2 [ 119.504942] NMI backtrace for cpu 45 [ 119.504946] CPU: 45 PID: 0 Comm: swapper/45 Not tainted 3.10.32-64bit #1 [ 119.504949] Hardware name: Dell Inc. PowerEdge R910/0P658H, BIOS 1.0.1 02/19/2010 [ 119.504952] task: ffff88046dcd6b00 ti: ffff88046dcf6000 task.ti: ffff88046dcf6000 [ 119.504960] RIP: 0010:[<ffffffff8102318a>] [<ffffffff8102318a>] mwait_idle_with_hints+0x5a/0x70 [ 119.504962] RSP: 0018:ffff88046dcf7dd8 EFLAGS: 00000046 [ 119.504965] RAX: 0000000000000000 RBX: ffff88106d07d46c RCX: 0000000000000001 [ 119.504967] RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000000 [ 119.504970] RBP: ffff88046dcf7dd8 R08: ffff88046dcf7fd8 R09: 000000000000001c [ 119.504972] R10: 0000000000000166 R11: 00000000016f1e50 R12: 0000000000000001 [ 119.504975] R13: ffff88106d07d400 R14: 0000000000000001 R15: ffffffffa0004830 [ 119.504978] FS: 0000000000000000(0000) GS:ffff88086fd60000(0000) knlGS:0000000000000000 [ 119.504981] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [ 119.504984] CR2: 00000000f7746000 CR3: 000000046cb57000 CR4: 00000000000007e0 [ 119.504986] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 119.504989] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 119.504989] Stack: [ 119.504994] ffff88046dcf7de8 ffffffff810231cd ffff88046dcf7df8 ffffffffa0001515 [ 119.504999] ffff88046dcf7e28 ffffffffa000164a 00000000000000f5 ffff88106c669000 [ 119.505003] ffffffffa00047c0 0000001aaf4aa38f ffff88046dcf7e88 ffffffff8164e83a [ 119.505004] Call Trace: [ 119.505010] [<ffffffff810231cd>] acpi_processor_ffh_cstate_enter+0x2d/0x30 [ 119.505021] [<ffffffffa0001515>] acpi_idle_do_entry+0x10/0x2b [processor] [ 119.505028] [<ffffffffa000164a>] acpi_idle_enter_c1+0x5c/0x81 [processor] [ 119.505035] [<ffffffff8164e83a>] cpuidle_enter_state+0x4a/0xe0 [ 119.505041] [<ffffffff8164e96e>] cpuidle_idle_call+0x9e/0x160 [ 119.505046] [<ffffffff8106092d>] ? __atomic_notifier_call_chain+0xd/0x10 [ 119.505052] [<ffffffff8100af49>] arch_cpu_idle+0x9/0x30 [ 119.505057] [<ffffffff81073241>] cpu_startup_entry+0x91/0x180 [ 119.505063] [<ffffffff81b4be73>] start_secondary+0x1a0/0x1a4
Should these patches be merged into kernel 3.10 line? And maybe also to 3.12? Or is there any other better solution?
Best regards,
Alex
Documentation/kernel-parameters.txt +7 -6
@@ -2621,18 +2621,19 @@ bytes respectively. Such letter suffixes can also be entirely omitted. Format: <bool> (1/Y/y=enable, 0/N/n=disable) default: disabled - printk.offload_chars= + printk.offload_chars= [KNL] Printing to console can be relatively slow especially in case of serial console. When there is intensive printing happening from several cpus (as is the case during boot), a cpu can be spending significant time (seconds or more) doing printing. To avoid softlockups, lost interrupts, and similar problems other cpus - will take over printing after the currently printing - cpu has printed 'printk.offload_chars' characters. - Higher value means possibly longer interrupt and other - latencies but lower overhead of printing due to handing - over of printing. + will take over printing (if CONFIG_PRINTK_OFFLOAD=y) + after the currently printing cpu has printed + 'printk.offload_chars' characters. Higher value means + possibly longer interrupt and other latencies but + lower overhead of printing due to handing over of + printing. Format: <number> (0 = disabled) default: 1000
init/Kconfig +14 -0
@@ -1343,6 +1343,20 @@ config PRINTK very difficult to diagnose system problems, saying N here is strongly discouraged. +config PRINTK_OFFLOAD + default y + bool "Enable support for offloading printing to different CPU" + depends on PRINTK + help + Printing to console can be relatively slow especially in case of + serial console. On large machines when there is intensive printing + happening from several cpus (as is the case during boot), a cpu can + be spending significant time (seconds or more) doing printing. To + avoid softlockups, lost interrupts, and similar problems other cpus + will take over printing after the currently printing cpu has printed + certain number of characters (tunable via 'printk.offload_chars' + kernel parameter). + config BUG bool "BUG() support" if EXPERT default y
kernel/printk.c +14 -0
@@ -103,6 +103,7 @@ enum { };static long printk_handover_state; +#ifdef CONFIG_PRINTK_OFFLOAD /* * Number of kernel threads for offloading printing. We need at least two so * that they can hand over printing from one to another one and thus switch
@@ -116,6 +117,7 @@ static DEFINE_MUTEX(printk_kthread_mutex);/* Wait queue printing kthreads sleep on when idle */ static DECLARE_WAIT_QUEUE_HEAD (print_queue); +#endif /* CONFIG_PRINTK_OFFLOAD */ #ifdef CONFIG_LOCKDEP static struct lockdep_map console_lock_dep_map = {
@@ -284,6 +286,7 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);static char *log_buf = __log_buf;static u32 log_buf_len = __LOG_BUF_LEN; +#ifdef CONFIG_PRINTK_OFFLOAD static int offload_chars_set (const char *val,const struct kernel_param *kp);static struct kernel_param_ops offload_chars_ops = { .set = offload_chars_set,
@@ -302,6 +305,7 @@ module_param_cb(offload_chars, &offload_chars_ops, &printk_offload_chars, S_IRUGO | S_IWUSR);MODULE_PARM_DESC (offload_chars,"offload printing to console to a different" " cpu after this number of characters" ); +#endif /* human readable text of the record */ static char *log_text (const struct printk_log *msg)
@@ -2021,6 +2025,7 @@ int console_trylock(void) }EXPORT_SYMBOL (console_trylock); +#ifdef CONFIG_PRINTK_OFFLOAD /* * This is a version of console_lock() which spins to acquire console_sem. * It is only for use by threads that take care of flushing printk buffer so
@@ -2052,6 +2057,7 @@ static int console_lock_try_spin(void)mutex_acquire (&console_lock_dep_map,0 ,0 , _RET_IP_); return 1; } +#endif int is_console_locked (void ) {
@@ -2087,6 +2093,7 @@ out:raw_spin_unlock_irqrestore (&logbuf_lock, flags); } +#ifdef CONFIG_PRINTK_OFFLOAD /* * Returns true iff there is other cpu waiting to take over printing. This * function also takes are of setting PRINTK_HANDOVER_B if we want to hand over
@@ -2113,6 +2120,7 @@ static bool cpu_stop_printing(int printed_chars) }return false; } +#endif /** * console_unlock - unlock the console system
@@ -2155,10 +2163,12 @@ again:size_t len;int level; +#ifdef CONFIG_PRINTK_OFFLOAD if (cpu_stop_printing (printed_chars)) { hand_over = true;break ; } +#endif raw_spin_lock_irqsave (&logbuf_lock, flags);if (seen_seq != log_next_seq) {
@@ -2576,6 +2586,7 @@ int unregister_console(struct console *console) }EXPORT_SYMBOL (unregister_console); +#ifdef CONFIG_PRINTK_OFFLOAD /* Kthread which takes over printing from a CPU which asks for help */ static int printing_task (void *arg) {
@@ -2638,6 +2649,7 @@ static int offload_chars_set(const char *val, const struct kernel_param *kp)mutex_unlock (&printk_kthread_mutex); return 0; } +#endif /* CONFIG_PRINTK_OFFLOAD */ static int __init printk_late_init (void ) {
@@ -2650,9 +2662,11 @@ static int __init printk_late_init(void) }hotcpu_notifier (console_cpu_notify,0 ); +#ifdef CONFIG_PRINTK_OFFLOAD mutex_lock (&printk_kthread_mutex);printk_start_offload_kthreads ();mutex_unlock (&printk_kthread_mutex); +#endif return 0 ; }
Signature · 1 line
1.8.1.4
kernel/printk.c +17 -32
81 lines not on this page · raw message
Signature · 1 line
1.8.1.4
include/linux/console.h +1 -0
@@ -150,6 +150,7 @@ extern int console_trylock(void);extern void console_unlock (void );extern void console_conditional_schedule (void );extern void console_unblank (void ); +extern void console_flush (void );extern struct tty_driver *console_device (int *);extern void console_stop (struct console *);extern void console_start (struct console *);
kernel/printk.c +22 -0
@@ -2306,6 +2306,28 @@ struct tty_driver *console_device(int *index) }/* +* Wait until all messages accumulated in the printk buffer are printed to +* console. Note that as soon as this function returns, new messages may be +* added to the printk buffer by other CPUs. +*/ +void console_flush (void ) +{ +bool retry; +unsigned long flags; + +while (1 ) { +raw_spin_lock_irqsave (&logbuf_lock, flags); + retry = console_seq != log_next_seq; +raw_spin_unlock_irqrestore (&logbuf_lock, flags); +if (!retry || console_suspended) +break ; +/* Cycle console_sem to wait for outstanding printing */ +console_lock (); +console_unlock (); + } +} + +/* * Prevent further output on the passed console device so that (for example) * serial drivers can disable console output before suspending a port, and can * re-enable output afterwards.
kernel/stop_machine.c +9 -0
@@ -21,5 +21,6 @@#include <linux/smpboot.h> #include <linux/atomic.h> +#include <linux/console.h> /* * Structure to determine completion condition and record errors. May
@@ -574,6 +575,14 @@ int __stop_machine(int (*fn)(void *), void *data, const struct cpumask *cpus)return ret; } +/* +* If there are lots of outstanding messages, printing them can take a +* long time and all cpus would be spinning waiting for the printing to +* finish thus triggering NMI watchdog, RCU lockups etc. Wait for the +* printing here to avoid these. +*/ +console_flush (); +/* Set the initial state and stop all online cpus. */ set_state (&msdata,MULTI_STOP_PREPARE );return stop_cpus (cpu_online_mask, multi_cpu_stop, &msdata);
Signature · 1 line
1.8.1.4
kernel/printk.c +50 -16
101 lines not on this page · raw message
Signature · 1 line
1.8.1.4
kernel/printk.c +1 -2
@@ -206,8 +206,7 @@ struct printk_log { };/* -* The logbuf_lock protects kmsg buffer, indices, counters. It is also -* used in interesting ways to provide interlocking in console_unlock(); +* The logbuf_lock protects kmsg buffer, indices, counters. */ static DEFINE_RAW_SPINLOCK (logbuf_lock);
Signature · 1 line
1.8.1.4
Documentation/kernel-parameters.txt +15 -0
@@ -2621,6 +2621,21 @@ bytes respectively. Such letter suffixes can also be entirely omitted. Format: <bool> (1/Y/y=enable, 0/N/n=disable) default: disabled + printk.offload_chars= + Printing to console can be relatively slow especially + in case of serial console. When there is intensive + printing happening from several cpus (as is the case + during boot), a cpu can be spending significant time + (seconds or more) doing printing. To avoid softlockups, + lost interrupts, and similar problems other cpus + will take over printing after the currently printing + cpu has printed 'printk.offload_chars' characters. + Higher value means possibly longer interrupt and other + latencies but lower overhead of printing due to handing + over of printing. + Format: <number> (0 = disabled) + default: 1000 + printk.time= Show timing data prefixed to each printk message line Format: <bool> (1/Y/y=enable, 0/N/n=disable)
kernel/printk.c +179 -17
302 lines not on this page · raw message
Signature · 1 line
1.8.1.4
kernel/printk.c +18 -11
@@ -1314,10 +1314,9 @@ static int have_callable_console(void)/* * Can we actually use the console at this time on this cpu? * -* 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. +* 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. */ static inline int can_use_console (unsigned int cpu) {
@@ -1330,8 +1329,10 @@ static inline int can_use_console(unsigned int cpu)* console_lock held, and 'console_locked' set) if it * is successful, false otherwise. */ -static int console_trylock_for_printk (unsigned int cpu) +static int console_trylock_for_printk (void ) { +unsigned int cpu =smp_processor_id (); +if (!console_trylock ())return 0 ;/*
@@ -1501,7 +1502,8 @@ asmlinkage int vprintk_emit(int facility, int level,*/ if (!oops_in_progress && !lockdep_recursing (current)) { recursion_bug =1 ; - goto out_restore_irqs; +local_irq_restore (flags); +return 0 ; }zap_locks (); }
@@ -1597,17 +1599,22 @@ asmlinkage int vprintk_emit(int facility, int level, logbuf_cpu =UINT_MAX ;raw_spin_unlock (&logbuf_lock); +lockdep_on (); +local_irq_restore (flags); + +/* +* Disable preemption to avoid being preempted while holding +* console_sem which would prevent anyone from printing to console +*/ +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. */ -if (console_trylock_for_printk (this_cpu)) +if (console_trylock_for_printk ())console_unlock (); - -lockdep_on (); -out_restore_irqs: -local_irq_restore (flags); +preempt_enable ();return printed_len; }
Signature · 1 line
1.8.1.4
kernel/printk.c +29 -18
111 lines not on this page · raw message
Signature · 1 line
1.8.1.4
Greg KH
maintainerQuoted 9 lines · Alexander Naumann
Hallo all,
attached to this mail you will find a couple of patches fixing one bug I have with kernel 3.10 (all subreleases).
These patches have been developed originally by Jan Kara ([email protected], I guess you
know him better than I do) for kernel 3.13 and can be found here:
https://lkml.org/lkml/2014/3/25/343
I just have backported them to kernel 3.10.
Patches have to be accepted into Linus's kernel tree before I can accept them into any stable kernel release. Please see the kernel file, Documentation/stable_kernel_rules.txt for the details on how this all works.
Once the patches get merged, please let us know what the git commit ids they are in Linus's tree and I will be glad to queue them up.
thanks,
greg k-h