linux-kernel - Re: soft lockup - CPU#1 stuck for 15s! [swapper:0]

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <alpine.LFD.0.99999.0712172208500.3670@localhost.localdomain>
Date:	Mon, 17 Dec 2007 23:05:55 +0100 (CET)
From:	Thomas Gleixner <tglx@...utronix.de>
To:	Parag Warudkar <parag.warudkar@...il.com>
cc:	Len Brown <lenb@...nel.org>,
	Arjan van de Ven <arjan@...radead.org>,
	Ingo Molnar <mingo@...e.hu>,
	"Pallipadi, Venkatesh" <venkatesh.pallipadi@...el.com>,
	LKML <linux-kernel@...r.kernel.org>,
	Andrew Morton <akpm@...ux-foundation.org>,
	Linus Torvalds <torvalds@...ux-foundation.org>
Subject: Re: soft lockup - CPU#1 stuck for 15s! [swapper:0]

On Mon, 17 Dec 2007, Parag Warudkar wrote:
> On Dec 17, 2007 3:05 AM, Thomas Gleixner <tglx@...utronix.de> wrote:
> > Sigh. You did not have the debug patch applied anymore, which printks
> > the timer_list data ? Can you apply it again and provide the output
> > please ?
> >
> 
> This keeps getting more and more weird - This time I was running with
> CONFIG_CPU_IDLE=N and I have ton of soft lockups after 14hr uptime.

It's more than weird.
 
> now at 39080147128907 nsecs

>   .idle_entrytime : 39080384013047 nsecs

The time, when we entered idle on CPU#0 is in the future. 

>   .tick_stopped   : 0

But the tick is not stopped, that means CPU#0 has work to do

On CPU#1 idle entry just happened:

>   .idle_entrytime : 39079996603653 nsecs

> now at 40490254040892 nsecs

>   .idle_entrytime : 40490492012833 nsecs

Again, idle_entry on CPU#0 is in the future.

On CPU#1 the idle entry was at: 
>   .idle_entrytime : 40489996578090 nsecs

which means: 0.257462802 sec. ago

> now at 40700144217096 nsecs

Aarg. On CPU#0 this is consistently in the future:

>   .idle_entrytime : 40700372012887 nsecs

I'm really confused.

>   .idle_entrytime : 40699996620694 nsecs
>   .idle_sleeptime : 40540536046589 nsecs
>   .last_jiffies   : 10100000
>   .next_jiffies   : 10100467
>   .idle_expires   : 40701864000000 nsecs
> jiffies: 10100158
> 
> 
> Tick Device: mode:     1
> Clock Event Device: hpet
>  max_delta_ns:   2147483647
>  min_delta_ns:   3352
>  mult:           61496110
>  shift:          32
>  mode:           3
>  next_event:     40700692000000 nsecs
>  set_next_event: hpet_legacy_next_event
>  set_mode:       hpet_legacy_set_mode
>  event_handler:  tick_handle_oneshot_broadcast
> tick_broadcast_mask: 00000003

Here is the next inconsistent data:

> tick_broadcast_oneshot_mask: 00000003

CPU#1 just woke up. That means the broadcast oneshot mask must be
cleared for CPU#1.

Some real strange thing is going on in your box.

I try to come up with some more debug patches tomorrow.

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