Re: [PATCH v2] printk: Avoid softlockups in console_unlock()

[Hugh Dickins <hughd@google.com>]

On Wed, 6 Feb 2013, Jan Kara wrote:
> On Wed 06-02-13 09:58:48, David Rientjes wrote:
> > On Wed, 6 Feb 2013, Jan Kara wrote:
> > 
> > >   Yes, I noticed that thread just yesterday and also though that using
> > > similar trick might be viable. I'll experiment if we could use the same
> > > method for handling lockup problems I hit. Steven seems to have already
> > > tweaked PRINTK_PENDING stuff to be usable more easily...
> > > 
> > 
> > Are these new build failures in linux-next coming from this patch?
> > 
> > kernel/printk.c: In function 'console_unlock':
> > kernel/printk.c:2156:18: error: 'printk_work' undeclared (first use in this function)
> > kernel/printk.c:2156:18: note: each undeclared identifier is reported only once for each function it appears in
> > kernel/printk.c: At top level:
> > kernel/printk.c:2167:13: warning: 'printk_worker' defined but not used [-Wunused-function]
>   Yes, I already sent a patch to fix these (attached if you need it).
> Thanks for notice.

Is the console_unlock patch actually intended to be a console load test?
Could we just revert it until it's baked?

This little hunk from __console_unlock():

 	console_may_schedule = 0;
+	cur_cpu = smp_processor_id();

I have CONFIG_PREEMPT=y CONFIG_DEBUG_PREEMPT=y,
so that fills the console with messages:

BUG: using smp_processor_id() in preemptible [00000000] code: systemd/1
caller is __console_unlock+0x3c/0x39c
Pid: 1, comm: systemd Tainted: G        W    3.8.0-rc6-mm1 #1
Call Trace:
 [<ffffffff81223ee2>] debug_smp_processor_id+0xbe/0xd8
 [<ffffffff810615d8>] __console_unlock+0x3c/0x39c
 [<ffffffff810a6a38>] ? trace_hardirqs_on+0xd/0xf
 [<ffffffff8154a997>] ? _raw_spin_unlock_irqrestore+0x46/0x64
 [<ffffffff81061941>] console_unlock+0x9/0x1b
 [<ffffffff812955ab>] con_shutdown+0x29/0x2d
 [<ffffffff81295582>] ? visual_init+0x10d/0x10d
 [<ffffffff812857ed>] release_tty+0x4d/0x91
 [<ffffffff8128644f>] tty_release+0x421/0x460
 [<ffffffff81120c57>] __fput+0x104/0x1e9
 [<ffffffff81120d45>] ____fput+0x9/0xb
 [<ffffffff8107a6c3>] task_work_run+0x79/0xa6
 [<ffffffff8102f4a6>] do_notify_resume+0x55/0x66
 [<ffffffff8121e29e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff8154b898>] int_signal+0x12/0x17

As a quick and obviously wrong hack, I replace the call to
smp_processor_id() by call to raw_smp_processor_id() and then:

+	/*
+	 * We give us some headroom because we check the time only after
+	 * printing the whole message
+	 */
+	end_time = sched_clock_cpu(cur_cpu) +
+				max_interrupt_disabled_duration() / 2;

Oh, sched_clock_cpu() is also giving me such BUGs,
but also (phew, it's a WARN_ON_ONCE):
 
00000] WARNING: at kernel/sched/clock.c:219 sched_clock_cpu+0x2e/0xcf()
00000] Hardware name: 4174AY9
00000] Modules linked in:
00000] Pid: 0, comm: swapper/0 Not tainted 3.8.0-rc6-mm1 #2
00000] Call Trace:
00000]  [<ffffffff8106018b>] warn_slowpath_common+0x7e/0x99
00000]  [<ffffffff810601bb>] warn_slowpath_null+0x15/0x17
00000]  [<ffffffff8108a683>] sched_clock_cpu+0x2e/0xcf
00000]  [<ffffffff810615e4>] __console_unlock+0x48/0x39e
00000]  [<ffffffff8153e648>] ? printk+0x48/0x4a
00000]  [<ffffffff81061943>] console_unlock+0x9/0x1b
00000]  [<ffffffff818f7ebc>] con_init+0x252/0x27d
00000]  [<ffffffff818f75b4>] console_init+0x16/0x27
00000]  [<ffffffff818d4c34>] start_kernel+0x243/0x322
00000]  [<ffffffff818d476b>] ? repair_env_string+0x5a/0x5a
00000]  [<ffffffff818d4485>] x86_64_start_reservations+0x2a/0x2c
00000]  [<ffffffff818d454f>] x86_64_start_kernel+0xc8/0xcc

Please fix or revert; though whether yesterday's mmotm then becomes usable,
I'm not so sure (iwlwifi broken? characters dropped from i915 screen? oops
in find_pid_ns? I'd better move on to something else).

Hugh