Re: Watchdog detected hard lockup.

[Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>]

Hello Sumit,

please Cc kernel mailing list.

Cc Petr, Peter, Steven, kernel-list

On (05/18/17 12:22), Sumit Gemini wrote:
>    Hi Sergey,
> 
>  I read your comment on [1]https://lkml.org/lkml/2016/9/27/279. Here you were talking about using alt_printk instead of printk.
>  I Got this crash, could this crash related to call printk recursively?
>  Could you please tell me why i got this crash? Do you see any suspicious entry here?
> 
>  [2324956.184374] Kernel panic - not syncing: Watchdog detected hard LOCKUP on cpu 1
>  [2324956.184374] Pid: 0, comm: kworker/0:0 Tainted: P            3.1.10-gb20-default #1
>  [2324956.184374] Call Trace:
>  [2324956.184374]  [<ffffffff81003add>] dump_trace+0x98/0x223
>  [2324956.184374]  [<ffffffff813dc659>] dump_stack+0x69/0x6f
>  [2324956.184374]  [<ffffffff813def08>] panic+0xa4/0x1b4
>  [2324956.184374]  [<ffffffff81094b48>] watchdog_overflow_callback+0x79/0x9e
>  [2324956.184374]  [<ffffffff810b66b5>] __perf_event_overflow+0xf9/0x185
>  [2324956.184374]  [<ffffffff81010a2c>] intel_pmu_handle_irq+0x15d/0x1be
>  [2324956.184374]  [<ffffffff813f375b>] perf_event_nmi_handler+0x3e/0x87
>  [2324956.184374]  [<ffffffff813f4c0f>] notifier_call_chain+0x2e/0x5b
>  [2324956.184374]  [<ffffffff813f4c76>] __atomic_notifier_call_chain+0x3a/0x4d
>  [2324956.184374]  [<ffffffff813f4cc1>] notify_die+0x2d/0x32
>  [2324956.184374]  [<ffffffff813f2bbb>] default_do_nmi+0x29/0x1b5
>  [2324956.184374]  [<ffffffff813f2eb7>] do_nmi+0x47/0x6f
>  [2324956.184374]  [<ffffffff813f2a30>] nmi+0x20/0x30
>  [2324956.184374]  [<ffffffff8106b725>] arch_local_irq_save+0x1/0x17
>  [2324956.184374]  [<ffffffff813f1e9b>] _raw_spin_lock_irqsave+0xf/0x39
>  [2324956.184374]  [<ffffffff8105d9b7>] down_trylock+0xb/0x29
>  [2324956.184374]  [<ffffffff810409c2>] console_trylock+0xf/0x47
>  [2324956.184374]  [<ffffffff81040dc9>] console_unlock+0x100/0x129
>  [2324956.184374]  [<ffffffff8104120b>] vprintk+0x348/0x394
>  [2324956.184374]  [<ffffffff813df06b>] printk+0x53/0x58
>  [2324956.184374]  [<ffffffff81359902>] ip_handle_martian_source+0x6d/0xf6
>  [2324956.184374]  [<ffffffff8135b980>] ip_route_input_slow+0x45d/0x462
>  [2324956.184374]  [<ffffffff8135c02f>] ip_route_input_common+0x217/0x231
>  [2324956.184374]  [<ffffffff8137e995>] arp_process+0x181/0x4ac
>  [2324956.184374]  [<ffffffff81337bf5>] __netif_receive_skb+0x317/0x36b
>  [2324956.184374]  [<ffffffff81337b44>] __netif_receive_skb+0x266/0x36b
>  [2324956.184374]  [<ffffffff81339722>] netif_receive_skb+0x7e/0x84
>  [2324956.184374]  [<ffffffff8133979e>] napi_skb_finish+0x1c/0x31
>  [2324956.184374]  [<ffffffffa02e1dee>] igb_clean_rx_irq+0x30d/0x39e [igb]
>  [2324956.184374]  [<ffffffffa02e1ecd>] igb_poll+0x4e/0x74 [igb]
>  [2324956.184374]  [<ffffffff81339c88>] net_rx_action+0x65/0x178
>  [2324956.184374]  [<ffffffff81045c73>] __do_softirq+0xb2/0x19d
>  [2324956.184374]  [<ffffffff813f9aac>] call_softirq+0x1c/0x30
>  [2324956.184374]  [<ffffffff81003931>] do_softirq+0x3c/0x7b
>  [2324956.184374]  [<ffffffff81045f98>] irq_exit+0x3c/0xac
>  [2324956.184374]  [<ffffffff81003655>] do_IRQ+0x82/0x98
>  [2324956.184374]  [<ffffffff813f24ee>] common_interrupt+0x6e/0x6e
>  [2324956.184374]  [<ffffffff8123f91d>] intel_idle+0xdd/0x104
>  [2324956.184374]  [<ffffffff8130b76b>] cpuidle_idle_call+0xdf/0x181
>  [2324956.184374]  [<ffffffff81001201>] cpu_idle+0x56/0xa9
> 
>  I shell be very greatful to you.
> 

your CPU1 couldn't acquire console_sem spin_lock

	down_trylock()
		raw_spin_lock_irqsave(&sem->lock, flags);

and _probably_ looped on it with local IRQs disabled long enough to
disappoint the NMI watchdog, which eventually declared a hard lockup
condition. but I'm not entirely sure it stuck looping on sem->lock,
it could be the case that your net IRQ took too much time and by the
time NMI declared hard lockup we were just unlucky to execute
down_trylock().

on the other hand, the fact that you see

	IRQ
	 ip_handle_martian_source()
	  printk()
	    console_unlock()

is already not really good. first of all, you had hit ip_route_input slow
path; second, you hit pr_warn()/pr_err or print_hex_dump(), so the kernel
was reporting you something abnormal. printk() invoked from IRQ context
managed to acquire the console_sem and spent some time printing the messages
to the serial console, console_unlock() in the call trace. which sometimes
can be a call for troubles. printk() can't always be safely called from
atomic contexts, just because of cases like this.

I don't know how big ->hard_header_len can be, but that print_hex_dump()
can take some extra time. if you also happened to have other printk messages
coming from other CPUs in the meantime, then CPU1 had have to spent even
more time in console_unlock() printing those messages; from IRQ handler.


hm, this doesn't look to me as a printk recursion, at least after a
quick look. either,

a) something was holding sem->lock, can't tell what exactly  (unlikely)

or

b) your IRQ handler just happened to execute way too long. given that
   there was printk()->console_unlock() and probably a hex dump of
   skb, this is a more likely root cause.

	-ss