[LOCKDEP] 2.6.18-rc1: inconsistent {hardirq-on-W} -> {in-hardirq-W} usage

[LOCKDEP] 2.6.18-rc1: inconsistent {hardirq-on-W} -> {in-hardirq-W} usage

[Joseph Fannin]

    [ resending -- original msg was > 100k ]

    Hello,

    I haven't seen this one cross the LKML.  I'm seeing it in both
2.6.18-rc1 and in .17-mm6.  I hope it's useful.

    The stack backtrace and offending executable varies from boot to
boot, so lockdep messages from two boots follow, and I've posted a
full dmesg from a third boot and my .config:

http://home.columbus.rr.com/jfannin3/dmesg.txt

http://home.columbus.rr.com/jfannin3/config.txt

[   22.488000]
[   22.488000] =================================
[   22.488000] [ INFO: inconsistent lock state ]
[   22.488000] ---------------------------------
[   22.488000] inconsistent {hardirq-on-W} -> {in-hardirq-W} usage.
[   22.488000] udevd/2684 [HC1[1]:SC0[0]:HE0:SE1] takes:
[   22.488000]  (rtc_lock){+-..}, at: [<c0278c1c>] rtc_get_rtc_time+0x2c/0x1a0
[   22.488000] {hardirq-on-W} state was registered at:
[   22.488000]   [<c0144229>] lock_acquire+0x69/0x90
[   22.488000]   [<c033c020>] _spin_lock+0x40/0x50
[   22.488000]   [<c0106fa3>] get_cmos_time+0x13/0x170
[   22.488000]   [<c048daeb>] hpet_time_init+0xb/0x70
[   22.488000]   [<c0487744>] start_kernel+0x1f4/0x470
[   22.488000]   [<c0100210>] 0xc0100210
[   22.488000] irq event stamp: 193648
[   22.488000] hardirqs last  enabled at (193647): [<c033c331>] _write_unlock_irq+0x31/0x60
[   22.488000] hardirqs last disabled at (193648): [<c0103e0f>] common_interrupt+0x1b/0x2c
[   22.488000] softirqs last  enabled at (193582): [<c012b229>] __do_softirq+0x109/0x140
[   22.488000] softirqs last disabled at (193575): [<c012b2d9>] do_softirq+0x79/0x80
[   22.488000]
[   22.488000] other info that might help us debug this:
[   22.488000] no locks held by udevd/2684.
[   22.488000]
[   22.488000] stack backtrace:
[   22.488000]  [<c0104728>] show_trace_log_lvl+0x148/0x170
[   22.488000]  [<c010591b>] show_trace+0x1b/0x20
[   22.488000]  [<c0105944>] dump_stack+0x24/0x30
[   22.488000]  [<c0142a85>] print_usage_bug+0x255/0x260
[   22.488000]  [<c0142fc7>] mark_lock+0x537/0x620
[   22.488000]  [<c01436b2>] __lock_acquire+0x602/0xdf0
[   22.488000]  [<c0144229>] lock_acquire+0x69/0x90
[   22.488000]  [<c033c476>] _spin_lock_irq+0x46/0x60
[   22.488000]  [<c0278c1c>] rtc_get_rtc_time+0x2c/0x1a0
[   22.488000]  [<c0117d02>] hpet_rtc_interrupt+0x152/0x1b0
[   22.488000]  [<c01588d1>] handle_IRQ_event+0x31/0x70
[   22.488000]  [<c01589a9>] __do_IRQ+0x99/0x110
[   22.488000]  [<c0105d97>] do_IRQ+0x47/0xa0
[   22.488000]  [<c0103e19>] common_interrupt+0x25/0x2c
[   22.488000]  [<c01440d2>] lock_release+0xb2/0x1a0
[   22.488000]  [<c033c814>] _spin_unlock+0x24/0x60
[   22.488000]  [<c016a7b0>] unmap_vmas+0x300/0x640
[   22.488000]  [<c016d84a>] exit_mmap+0x8a/0x140
[   22.488000]  [<c01227e9>] mmput+0x39/0xb0
[   22.488000]  [<c01235b3>] copy_process+0x833/0x1510
[   22.488000]  [<c01242fb>] do_fork+0x6b/0x210
[   22.488000]  [<c01011f9>] sys_clone+0x39/0x40
[   22.488000]  [<c01032f9>] sysenter_past_esp+0x56/0x8d
[   22.488000]  [<b7ef6410>] 0xb7ef6410
[   22.620000] sd 0:0:1:0: Attached scsi generic sg0 type 0
[   22.620000] sd 2:0:0:0: Attached scsi generic sg1 type 0
[   22.840000] md: md driver 0.90.3 MAX_MD_DEVS=256, MD_SB_DISKS=27
[   22.840000] md: bitmap version 4.39

[   22.724000]
[   22.724000] =================================
[   22.724000] [ INFO: inconsistent lock state ]
[   22.724000] ---------------------------------
[   22.724000] inconsistent {hardirq-on-W} -> {in-hardirq-W} usage.
[   22.724000] S25brltty/3382 [HC1[1]:SC0[0]:HE0:SE1] takes:
[   22.724000]  (rtc_lock){+-..}, at: [<c0278c1c>] rtc_get_rtc_time+0x2c/0x1a0
[   22.724000] {hardirq-on-W} state was registered at:
[   22.724000]   [<c0144229>] lock_acquire+0x69/0x90
[   22.724000]   [<c033c020>] _spin_lock+0x40/0x50
[   22.724000]   [<c0106fa3>] get_cmos_time+0x13/0x170
[   22.724000]   [<c048daeb>] hpet_time_init+0xb/0x70
[   22.724000]   [<c0487744>] start_kernel+0x1f4/0x470
[   22.724000]   [<c0100210>] 0xc0100210
[   22.724000] irq event stamp: 1276
[   22.724000] hardirqs last  enabled at (1275): [<c01033bf>] restore_nocheck+0x12/0x15
[   22.724000] hardirqs last disabled at (1276): [<c0103e0f>] common_interrupt+0x1b/0x2c
[   22.724000] softirqs last  enabled at (0): [<c012314b>] copy_process+0x3cb/0x1510
[   22.724000] softirqs last disabled at (0): [<00000000>] 0x0
[   22.724000]
[   22.724000] other info that might help us debug this:
[   22.724000] no locks held by S25brltty/3382.
[   22.724000]
[   22.724000] stack backtrace:
[   22.724000]  [<c0104728>] show_trace_log_lvl+0x148/0x170
[   22.724000]  [<c010591b>] show_trace+0x1b/0x20
[   22.724000]  [<c0105944>] dump_stack+0x24/0x30
[   22.724000]  [<c0142a85>] print_usage_bug+0x255/0x260
[   22.724000]  [<c0142fc7>] mark_lock+0x537/0x620
[   22.724000]  [<c01436b2>] __lock_acquire+0x602/0xdf0
[   22.724000]  [<c0144229>] lock_acquire+0x69/0x90
[   22.724000]  [<c033c476>] _spin_lock_irq+0x46/0x60
[   22.724000]  [<c0278c1c>] rtc_get_rtc_time+0x2c/0x1a0
[   22.724000]  [<c0117d02>] hpet_rtc_interrupt+0x152/0x1b0
[   22.724000]  [<c01588d1>] handle_IRQ_event+0x31/0x70
[   22.724000]  [<c01589a9>] __do_IRQ+0x99/0x110
[   22.724000]  [<c0105d97>] do_IRQ+0x47/0xa0
[   22.724000]  [<c0103e19>] common_interrupt+0x25/0x2c
[   22.724000]  [<b7f93c0a>] 0xb7f93c0a
[   22.860000] sd 0:0:1:0: Attached scsi generic sg0 type 0
[   22.860000] sd 2:0:0:0: Attached scsi generic sg1 type 0
[   22.892000] md: md driver 0.90.3 MAX_MD_DEVS=256, MD_SB_DISKS=27
[   22.892000] md: bitmap version 4.39

--
Joseph Fannin
jfannin@gmail.com

Re: [LOCKDEP] 2.6.18-rc1: inconsistent {hardirq-on-W} -> {in-hardirq-W} usage

[Andrew Morton]

On Sun, 9 Jul 2006 01:05:26 -0400
jfannin@gmail.com (Joseph Fannin) wrote:

> [   22.488000]
> [   22.488000] =================================
> [   22.488000] [ INFO: inconsistent lock state ]
> [   22.488000] ---------------------------------
> [   22.488000] inconsistent {hardirq-on-W} -> {in-hardirq-W} usage.
> [   22.488000] udevd/2684 [HC1[1]:SC0[0]:HE0:SE1] takes:
> [   22.488000]  (rtc_lock){+-..}, at: [<c0278c1c>] rtc_get_rtc_time+0x2c/0x1a0
> [   22.488000] {hardirq-on-W} state was registered at:
> [   22.488000]   [<c0144229>] lock_acquire+0x69/0x90
> [   22.488000]   [<c033c020>] _spin_lock+0x40/0x50
> [   22.488000]   [<c0106fa3>] get_cmos_time+0x13/0x170
> [   22.488000]   [<c048daeb>] hpet_time_init+0xb/0x70
> [   22.488000]   [<c0487744>] start_kernel+0x1f4/0x470
> [   22.488000]   [<c0100210>] 0xc0100210
> [   22.488000] irq event stamp: 193648

yup, thanks, bug.

--- a/arch/i386/kernel/time.c~get_cmos_time-locking-fix
+++ a/arch/i386/kernel/time.c
@@ -206,15 +206,16 @@ irqreturn_t timer_interrupt(int irq, voi
 unsigned long get_cmos_time(void)
 {
 	unsigned long retval;
+	unsigned long flags;
 
-	spin_lock(&rtc_lock);
+	spin_lock_irqsave(&rtc_lock, flags);
 
 	if (efi_enabled)
 		retval = efi_get_time();
 	else
 		retval = mach_get_cmos_time();
 
-	spin_unlock(&rtc_lock);
+	spin_unlock_irqrestore(&rtc_lock, flags);
 
 	return retval;
 }
_

Re: [LOCKDEP] 2.6.18-rc1: inconsistent {hardirq-on-W} -> {in-hardirq-W} usage

[Ingo Molnar]

* Andrew Morton <akpm@osdl.org> wrote:

> yup, thanks, bug.
> 
> --- a/arch/i386/kernel/time.c~get_cmos_time-locking-fix
> +++ a/arch/i386/kernel/time.c
> @@ -206,15 +206,16 @@ irqreturn_t timer_interrupt(int irq, voi
>  unsigned long get_cmos_time(void)
>  {
>  	unsigned long retval;
> +	unsigned long flags;
>  
> -	spin_lock(&rtc_lock);
> +	spin_lock_irqsave(&rtc_lock, flags);

Acked-by: Ingo Molnar <mingo@elte.hu>

this bug has been in the upstream kernel for a couple of years: it was
apparently introduced as part of HPET support, via the late_time_init()
hook/hack in init/main.c. The lockup window is open once, during bootup.

	Ingo

Re: [LOCKDEP] 2.6.18-rc1: inconsistent {hardirq-on-W} -> {in-hardirq-W} usage

[Joseph Fannin]

On Sun, Jul 09, 2006 at 09:45:44AM +0200, Ingo Molnar wrote:
>
> * Andrew Morton <akpm@osdl.org> wrote:
>
> > yup, thanks, bug.
> >
> > --- a/arch/i386/kernel/time.c~get_cmos_time-locking-fix
> > +++ a/arch/i386/kernel/time.c
> > @@ -206,15 +206,16 @@ irqreturn_t timer_interrupt(int irq, voi
> >  unsigned long get_cmos_time(void)
> >  {
> >  	unsigned long retval;
> > +	unsigned long flags;
> >
> > -	spin_lock(&rtc_lock);
> > +	spin_lock_irqsave(&rtc_lock, flags);
>
> Acked-by: Ingo Molnar <mingo@elte.hu>
>
> this bug has been in the upstream kernel for a couple of years: it was
> apparently introduced as part of HPET support, via the late_time_init()
> hook/hack in init/main.c. The lockup window is open once, during bootup.


    2.6.18-rc1-mm1, which includes this change, is printing this at
the same point I used to get the lockdep message:

[   25.628000] BUG: warning at kernel/lockdep.c:1803/trace_hardirqs_on()
[   25.628000]  [<c0104a18>] show_trace_log_lvl+0x148/0x170
[   25.628000]  [<c0105cab>] show_trace+0x1b/0x20
[   25.628000]  [<c0105cd4>] dump_stack+0x24/0x30
[   25.628000]  [<c014af4e>] trace_hardirqs_on+0xce/0x200
[   25.628000]  [<c036cf21>] _spin_unlock_irq+0x31/0x70
[   25.628000]  [<c0296584>] rtc_get_rtc_time+0x44/0x1a0
[   25.628000]  [<c01198bb>] hpet_rtc_interrupt+0x21b/0x280
[   25.628000]  [<c0161141>] handle_IRQ_event+0x31/0x70
[   25.628000]  [<c0162d37>] handle_edge_irq+0xe7/0x210
[   25.628000]  [<c0106192>] do_IRQ+0x92/0x120
[   25.628000]  [<c0104121>] common_interrupt+0x25/0x2c
[   25.628000]  [<b7f15410>] 0xb7f15410


    Updated dmesg and .config:

http://home.columbus.rr.com/jfannin3/dmesg-2.6.18-rc1-mm1
http://home.columbus.rr.com/jfannin3/config-2.6.18-rc1-mm1

--
Joseph Fannin
jhf@rivenstone.net

[patch] lockdep: HPET/RTC fix

[Ingo Molnar]

* Joseph Fannin <jfannin@gmail.com> wrote:

>     2.6.18-rc1-mm1, which includes this change, is printing this at 
> the same point I used to get the lockdep message:
> 
> [   25.628000] BUG: warning at kernel/lockdep.c:1803/trace_hardirqs_on()
> [   25.628000]  [<c0104a18>] show_trace_log_lvl+0x148/0x170
> [   25.628000]  [<c0105cab>] show_trace+0x1b/0x20
> [   25.628000]  [<c0105cd4>] dump_stack+0x24/0x30
> [   25.628000]  [<c014af4e>] trace_hardirqs_on+0xce/0x200
> [   25.628000]  [<c036cf21>] _spin_unlock_irq+0x31/0x70
> [   25.628000]  [<c0296584>] rtc_get_rtc_time+0x44/0x1a0
> [   25.628000]  [<c01198bb>] hpet_rtc_interrupt+0x21b/0x280
> [   25.628000]  [<c0161141>] handle_IRQ_event+0x31/0x70
> [   25.628000]  [<c0162d37>] handle_edge_irq+0xe7/0x210
> [   25.628000]  [<c0106192>] do_IRQ+0x92/0x120
> [   25.628000]  [<c0104121>] common_interrupt+0x25/0x2c
> [   25.628000]  [<b7f15410>] 0xb7f15410

ouch! That's another HPET bug i believe. AFAICS rtc_get_rtc_time() is 
really not meant to be called from any sort of timer interrupt! In 
particular this looping code:

        while (rtc_is_updating() != 0 && jiffies - uip_watchdog < 2*HZ/100) {
                barrier();
                cpu_relax();
        }

it utterly bad in any hardirq context. Also, the locking isnt 
hardirq-safe either:

        spin_lock_irq(&rtc_lock);
	...
        spin_unlock_irq(&rtc_lock);

as it will enable interrupts unconditionally - even if we are in a 
irqs-off hardirq.

John, how is this supposed to work?

	Ingo

---------------->
Subject: lockdep: HPET/RTC fix
From: Ingo Molnar <mingo@elte.hu>

Joseph Fannin reported that hpet_rtc_interrupt() enables hardirqs
in irq context:

[   25.628000]  [<c014af4e>] trace_hardirqs_on+0xce/0x200
[   25.628000]  [<c036cf21>] _spin_unlock_irq+0x31/0x70
[   25.628000]  [<c0296584>] rtc_get_rtc_time+0x44/0x1a0
[   25.628000]  [<c01198bb>] hpet_rtc_interrupt+0x21b/0x280
[   25.628000]  [<c0161141>] handle_IRQ_event+0x31/0x70
[   25.628000]  [<c0162d37>] handle_edge_irq+0xe7/0x210
[   25.628000]  [<c0106192>] do_IRQ+0x92/0x120
[   25.628000]  [<c0104121>] common_interrupt+0x25/0x2c

the call of rtc_get_rtc_time() is highly suspect. At a minimum we
need the patch below to save/restore hardirq state.

Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 drivers/char/rtc.c |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

Index: linux/drivers/char/rtc.c
===================================================================
--- linux.orig/drivers/char/rtc.c
+++ linux/drivers/char/rtc.c
@@ -1222,7 +1222,7 @@ static int rtc_proc_open(struct inode *i
 
 void rtc_get_rtc_time(struct rtc_time *rtc_tm)
 {
-	unsigned long uip_watchdog = jiffies;
+	unsigned long uip_watchdog = jiffies, flags;
 	unsigned char ctrl;
 #ifdef CONFIG_MACH_DECSTATION
 	unsigned int real_year;
@@ -1249,7 +1249,7 @@ void rtc_get_rtc_time(struct rtc_time *r
 	 * RTC has RTC_DAY_OF_WEEK, we should usually ignore it, as it is
 	 * only updated by the RTC when initially set to a non-zero value.
 	 */
-	spin_lock_irq(&rtc_lock);
+	spin_lock_irqsave(&rtc_lock, flags);
 	rtc_tm->tm_sec = CMOS_READ(RTC_SECONDS);
 	rtc_tm->tm_min = CMOS_READ(RTC_MINUTES);
 	rtc_tm->tm_hour = CMOS_READ(RTC_HOURS);
@@ -1263,7 +1263,7 @@ void rtc_get_rtc_time(struct rtc_time *r
 	real_year = CMOS_READ(RTC_DEC_YEAR);
 #endif
 	ctrl = CMOS_READ(RTC_CONTROL);
-	spin_unlock_irq(&rtc_lock);
+	spin_unlock_irqrestore(&rtc_lock, flags);
 
 	if (!(ctrl & RTC_DM_BINARY) || RTC_ALWAYS_BCD)
 	{

[PATCH] remove unnecessary barrier in rtc_get_rtc_time

[Steven Rostedt]

On Tue, 2006-07-11 at 09:45 +0200, Ingo Molnar wrote:

> 
> ouch! That's another HPET bug i believe. AFAICS rtc_get_rtc_time() is 
> really not meant to be called from any sort of timer interrupt! In 
> particular this looping code:
> 
>         while (rtc_is_updating() != 0 && jiffies - uip_watchdog < 2*HZ/100) {
>                 barrier();
>                 cpu_relax();
>         }

Seeing this after reading the volatile thread and then Chase's patch:

([PATCH] Make cpu_relax() imply barrier() on all arches)
http://marc.theaimsgroup.com/?l=linux-kernel&m=115237514517594&w=2

(yes I'm a bit behind in my LKML reading... 1663 messages to go)

There's no reason to have a barrier in this loop.

-- Steve

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

Index: linux-2.6.18-rc1/drivers/char/rtc.c
===================================================================
--- linux-2.6.18-rc1.orig/drivers/char/rtc.c	2006-07-13 23:40:58.000000000 -0400
+++ linux-2.6.18-rc1/drivers/char/rtc.c	2006-07-13 23:41:06.000000000 -0400
@@ -1238,10 +1238,8 @@ void rtc_get_rtc_time(struct rtc_time *r
 	 * Once the read clears, read the RTC time (again via ioctl). Easy.
 	 */
 
-	while (rtc_is_updating() != 0 && jiffies - uip_watchdog < 2*HZ/100) {
-		barrier();
+	while (rtc_is_updating() != 0 && jiffies - uip_watchdog < 2*HZ/100)
 		cpu_relax();
-	}
 
 	/*
 	 * Only the values that we read from the RTC are set. We leave

Re: [patch] lockdep: HPET/RTC fix

[Joseph Fannin]

On Tue, Jul 11, 2006 at 09:45:41AM +0200, Ingo Molnar wrote:

    [Apologies for the very slow turn-around time on this.  If patches
are written in the relatively-near future, I will test and report in a
more timely manner.]

> Subject: lockdep: HPET/RTC fix
> From: Ingo Molnar <mingo@elte.hu>
>
> Joseph Fannin reported that hpet_rtc_interrupt() enables hardirqs
> in irq context:

> --- linux.orig/drivers/char/rtc.c
> +++ linux/drivers/char/rtc.c
> @@ -1222,7 +1222,7 @@ static int rtc_proc_open(struct inode *i
>
>  void rtc_get_rtc_time(struct rtc_time *rtc_tm)
>  {
> -	unsigned long uip_watchdog = jiffies;
> +	unsigned long uip_watchdog = jiffies, flags;
>  	unsigned char ctrl;
>  #ifdef CONFIG_MACH_DECSTATION
>  	unsigned int real_year;
> @@ -1249,7 +1249,7 @@ void rtc_get_rtc_time(struct rtc_time *r
>  	 * RTC has RTC_DAY_OF_WEEK, we should usually ignore it, as it is
>  	 * only updated by the RTC when initially set to a non-zero value.
>  	 */
> -	spin_lock_irq(&rtc_lock);
> +	spin_lock_irqsave(&rtc_lock, flags);
>  	rtc_tm->tm_sec = CMOS_READ(RTC_SECONDS);
>  	rtc_tm->tm_min = CMOS_READ(RTC_MINUTES);
>  	rtc_tm->tm_hour = CMOS_READ(RTC_HOURS);
> @@ -1263,7 +1263,7 @@ void rtc_get_rtc_time(struct rtc_time *r
>  	real_year = CMOS_READ(RTC_DEC_YEAR);
>  #endif
>  	ctrl = CMOS_READ(RTC_CONTROL);
> -	spin_unlock_irq(&rtc_lock);
> +	spin_unlock_irqrestore(&rtc_lock, flags);
>
>  	if (!(ctrl & RTC_DM_BINARY) || RTC_ALWAYS_BCD)
>  	{


    It seems this isn't enough:

[   22.504000] EXT3 FS on sda3, internal journal
[   22.892000] BUG: warning at kernel/lockdep.c:1803/trace_hardirqs_on()
[   22.892000]  [<c0104880>] show_trace_log_lvl+0x1a0/0x1d0
[   22.892000]  [<c0105a7b>] show_trace+0x1b/0x20
[   22.892000]  [<c0105aa4>] dump_stack+0x24/0x30
[   22.892000]  [<c01451e4>] trace_hardirqs_on+0xf4/0x180
[   22.892000]  [<c032e431>] _spin_unlock_irq+0x31/0x60
[   22.892000]  [<c0278a64>] rtc_get_rtc_time+0x44/0x1a0
[   22.892000]  [<c0118742>] hpet_rtc_interrupt+0x152/0x1b0
[   22.892000]  [<c015bb51>] handle_IRQ_event+0x31/0x70
[   22.892000]  [<c015bc29>] __do_IRQ+0x99/0x110
[   22.892000]  [<c0105ef7>] do_IRQ+0x47/0xa0
[   22.892000]  [<c0103eed>] common_interrupt+0x25/0x2c
[   22.892000]  [<c032f902>] do_page_fault+0x82/0x630
[   22.892000]  [<c0104085>] error_code+0x39/0x40
[   22.892000]  [<b7e8d060>] 0xb7e8d060
[   22.892000]  [<c0105a7b>] show_trace+0x1b/0x20
[   22.892000]  [<c0105aa4>] dump_stack+0x24/0x30
[   22.892000]  [<c01451e4>] trace_hardirqs_on+0xf4/0x180
[   22.892000]  [<c032e431>] _spin_unlock_irq+0x31/0x60
[   22.892000]  [<c0278a64>] rtc_get_rtc_time+0x44/0x1a0
[   22.892000]  [<c0118742>] hpet_rtc_interrupt+0x152/0x1b0
[   22.892000]  [<c015bb51>] handle_IRQ_event+0x31/0x70
[   22.892000]  [<c015bc29>] __do_IRQ+0x99/0x110
[   22.892000]  [<c0105ef7>] do_IRQ+0x47/0xa0
[   22.892000]  [<c0103eed>] common_interrupt+0x25/0x2c
[   22.892000]  [<c0104085>] error_code+0x39/0x40

    This is from 2.6.18-rc3, but it's reproducable with pretty much
any kernel (the -rc3 backtrace is longer, it seems).

    Should I file this in Bugzilla?

--
Joseph Fannin
jfannin@gmail.com