Re: [PATCH v3] printk: add halt_delay parameter for printk delay in halt phase

[Dave Young]

On Tue, Jun 9, 2009 at 1:15 AM, Ingo Molnar<mingo@xxxxxxx> wrote:
>
> * Andrew Morton <akpm@xxxxxxxxxxxxxxxxxxxx> wrote:
>
>> On Mon, 8 Jun 2009 10:48:07 +0200 Ingo Molnar <mingo@xxxxxxx> wrote:
>>
>> >
>> > * Dave Young <hidave.darkstar@xxxxxxxxx> wrote:
>> >
>> > > On Mon, Jun 8, 2009 at 4:28 PM, Andrew Morton<akpm@xxxxxxxxxxxxxxxxxxxx> wrote:
>> > > > On Mon, 8 Jun 2009 10:14:39 +0200 Ingo Molnar <mingo@xxxxxxx> wrote:
>> > > >
>> > > >>
>> > > >> * Dave Young <hidave.darkstar@xxxxxxxxx> wrote:
>> > > >>
>> > > >> > Add a halt_delay module parameter in printk.c used to read the
>> > > >> > printk messages in halt/poweroff/restart phase, delay each printk
>> > > >> > messages by halt_delay milliseconds. It is useful for debugging if
>> > > >> > there's no other way to dump kernel messages that time.
>> > > >> >
>> > > >> > The halt_delay max value is 65535, default value is 0, change it
>> > > >> > by:
>> > > >> >
>> > > >> > echo xxx > /sys/module/printk/parameters/halt_delay
>> > > >> >
>> > > >> > Signed-off-by: Dave Young <hidave.darkstar@xxxxxxxxx>
>> > > >> > ---
>> > > >> > Documentation/kernel-parameters.txt | __ __5 +++++
>> > > >> > kernel/printk.c __ __ __ __ __ __ __ __ __ __ | __ 17 +++++++++++++++++
>> > > >> > 2 files changed, 22 insertions(+)
>> > > >> >
>> > > >> > --- linux-2.6.orig/kernel/printk.c __2009-06-08 13:55:35.000000000 +0800
>> > > >> > +++ linux-2.6/kernel/printk.c __ __ __ 2009-06-08 13:56:23.000000000 +0800
>> > > >> > @@ -250,6 +250,22 @@ static inline void boot_delay_msec(void)
>> > > >> > __}
>> > > >> > __#endif
>> > > >> >
>> > > >> > +/* msecs delay after each halt/poweroff/restart phase printk,
>> > > >> > + unsigned short is enough for delay in milliseconds */
>> > > >> > +static unsigned short halt_delay;
>> > > >> > +
>> > > >> > +static inline void halt_delay_msec(void)
>> > > >> > +{
>> > > >> > + __ if (unlikely(halt_delay == 0 || !(system_state == SYSTEM_HALT
>> > > >> > + __ __ __ __ __ __ __ __ __ __ __ __ __ || system_state == SYSTEM_POWER_OFF
>> > > >> > + __ __ __ __ __ __ __ __ __ __ __ __ __ || system_state == SYSTEM_RESTART)))
>> > > >> > + __ __ __ __ __ return;
>> > > >>
>> > > >> This is a tiny bit ugly (and goes into the vprintf path) but i can
>> > > >> see no other way either - a system_state > SYSTEM_RUNNING check
>> > > >> would needlessly include the suspend-to-disk state (which we dont
>> > > >> want to include here).
>> > > >>
>> > > >> In theory we could turn system_state into a bitmask and have a
>> > > >> print_delay_mask check instead of these flags ... but that is a far
>> > > >> wider change and i'm not sure it's a net step forwards.
>> > > >>
>> > > >> I've applied your patch to tip:core/printk with small edits to the
>> > > >> changelog - Linus & Andrew is Cc:ed, should they have any
>> > > >> objections.
>> > > >
>> > > > Could we not put just a single delay in there, immediately prior to halting,
>> > > > restarting or poweroffing?
>> > >
>> > > But, then prink messages will still flush too fast for us to see
>> > > the detail.
>>
>> Only if there are so many unlogged messages that they scroll of the
>> screen. ÂIs that the case?
>
> i have such an example in my logs:
>
> [ Â390.206118] md: stopping all md devices.
> [ Â391.208259] sd 0:0:0:0: [sda] Synchronizing SCSI cache
> [ Â391.214877] igb 0000:01:00.1: PCI INT B disabled
> [ Â391.220445] igb 0000:01:00.0: PCI INT A disabled
> [ Â391.225897] Restarting system.
> [ Â391.229213] machine restart
> [ Â391.232833] ------------[ cut here ]------------
> [ Â391.237718] WARNING: at arch/x86/kernel/smp.c:117 native_smp_send_reschedule+0x55/0x83()
> [ Â391.246276] Hardware name: X8DTN
> [ Â391.249762] Modules linked in:
> [ Â391.253146] Pid: 19807, comm: reboot Not tainted 2.6.30-rc8-tip #8
> [ Â391.259580] Call Trace:
> [ Â391.262287] Â<IRQ> Â[<ffffffff81021525>] ? native_smp_send_reschedule+0x55/0x83
> [ Â391.270136] Â[<ffffffff8104a316>] warn_slowpath_common+0x77/0xa4
> [ Â391.276395] Â[<ffffffff8104a352>] warn_slowpath_null+0xf/0x11
> [ Â391.282399] Â[<ffffffff81021525>] native_smp_send_reschedule+0x55/0x83
> [ Â391.289182] Â[<ffffffff8103629f>] resched_task+0x60/0x62
> [ Â391.294752] Â[<ffffffff8103d976>] resched_cpu+0x4a/0x5e
> [ Â391.300237] Â[<ffffffff8104627f>] scheduler_tick+0x19a/0x249
> [ Â391.306154] Â[<ffffffff81054576>] update_process_times+0x4f/0x5f
> [ Â391.312417] Â[<ffffffff8106ad80>] tick_sched_timer+0x76/0x96
> [ Â391.318331] Â[<ffffffff8106ad0a>] ? tick_sched_timer+0x0/0x96
> [ Â391.324334] Â[<ffffffff81061ea2>] __run_hrtimer+0x80/0xb4
> [ Â391.329993] Â[<ffffffff81062abe>] hrtimer_interrupt+0xe7/0x145
> [ Â391.336081] Â[<ffffffff81022801>] smp_apic_timer_interrupt+0x83/0x96
> [ Â391.342692] Â[<ffffffff8100c6d3>] apic_timer_interrupt+0x13/0x20
> [ Â391.348953] Â<EOI> Â[<ffffffff81022a7c>] ? default_send_IPI_mask_allbutself_phys+0x67/0x73
> [ Â391.357752] Â[<ffffffff8102532d>] ? physflat_send_IPI_allbutself+0x14/0x16
> [ Â391.364877] Â[<ffffffff8102166a>] ? native_send_call_func_ipi+0x83/0xa5
> [ Â391.371747] Â[<ffffffff81070cff>] ? smp_call_function_many+0x19b/0x1bb
> [ Â391.378529] Â[<ffffffff810128b0>] ? stop_this_cpu+0x0/0x1c
> [ Â391.384270] Â[<ffffffff81070d3f>] ? smp_call_function+0x20/0x24
> [ Â391.390448] Â[<ffffffff81021575>] ? native_smp_send_stop+0x22/0x30
> [ Â391.396882] Â[<ffffffff81020f93>] ? native_machine_shutdown+0x49/0x62
> [ Â391.403578] Â[<ffffffff81020d62>] ? native_machine_restart+0x21/0x33
> [ Â391.410187] Â[<ffffffff81020cd9>] ? machine_restart+0xa/0xc
> [ Â391.416016] Â[<ffffffff81059d67>] ? kernel_restart+0x3f/0x43
> [ Â391.421935] Â[<ffffffff81059eb8>] ? sys_reboot+0x140/0x174
> [ Â391.427677] Â[<ffffffff810628c6>] ? hrtimer_nanosleep+0x104/0x119
> [ Â391.434025] Â[<ffffffff81061e01>] ? hrtimer_wakeup+0x0/0x21
> [ Â391.439857] Â[<ffffffff8106272d>] ? hrtimer_start_range_ns+0xf/0x11
> [ Â391.446379] Â[<ffffffff8106292f>] ? sys_nanosleep+0x54/0x6c
> [ Â391.452210] Â[<ffffffff8100bbeb>] ? system_call_fastpath+0x16/0x1b
> [ Â391.458643] ---[ end trace 4b05cad362f39345 ]---
>
> that's 44 lines so yes it can happen.

For lockdep issue, there will be more

>
>> > Plus often there's a loop in architecture code that tries various
>> > methods of reboot. We dont know which one works - and any of them
>> > could produce warning messages. (and this happened a number of times
>> > in the past)
>> >
>> > So this would mean having to find up to a hundred of 'reboot now'
>> > places in a two dozen architectures (and keeping them all maintained
>> > ongoing as well). Does not seem like a good choice to me.
>> >
>>
>> hm. ÂIf we need to actually capture all of those.
>>
>> questions: is it possible for interrupts to be disabled at this
>> time? If so, can we get an NMI watchdog hit?
>
> no, we generally turn off the nmi watchdog during shutdown, disable
> the lapic and io-apic, etc.
>
>> Is the softlockup detector still running and if so, can it
>> trigger?
>
> in (non-emergency) reboot, last i checked, we stopped all other CPUs
> first, and then killed the current one. There's no chance for the
> watchdog thread to run.
>
> Anyway ... you seem to be uncomfortable about this patch - should i
> delay it for now to let it all play out? We are close to the merge
> window.
>
> Â Â Â ÂIngo
>



-- 
Regards
dave
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/