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

LOCKDEP In review Joseph Fannin 4 participants 7 messages Jul 9, 2006 – Aug 5, 2006 Char and misc drivers

Share & tools

Andrew Morton

2006-07-09 06:25 UTC #1 lore raw

Quoted 7 lines · On Sun, 9 Jul 2006 01:05:26 -0400 [email protected] (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

Quoted 8 lines

[   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.

arch/i386/kernel/time.c renamed from arch/i386/kernel/time.c~get_cmos_time-locking-fix +3 -2

@@ -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;
 }

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

Joseph Fannin

author

2006-07-11 05:11 UTC #3 lore raw

Quoted 13 lines · Ingo Molnar

Quoted 10 lines · Andrew Morton
yup, thanks, bug.
arch/i386/kernel/time.c renamed from arch/i386/kernel/time.c~get_cmos_time-locking-fix +1 -0
@@ -206,15 +206,16 @@ irqreturn_t timer_interrupt(int irq, voi
 unsigned long get_cmos_time(void)
 {
 	unsigned long retval;
+	unsigned long flags;
 

Quoted 8 lines

arch/i386/kernel/time.c irqreturn_t timer_interrupt(int irq, voi · line 211
Quoted 2 lines
arch/i386/kernel/time.c renamed from arch/i386/kernel/time.c~get_cmos_time-locking-fix +1 -1
-	spin_lock(&rtc_lock);
+	spin_lock_irqsave(&rtc_lock, flags);
Acked-by Ingo Molnar <[email protected]>
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
[email protected]

Ingo Molnar

2006-07-11 07:51 UTC #4 lore raw

PATCH 1/1 lockdep: HPET/RTC fix

Quoted 16 lines · Joseph Fannin

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 <[email protected]>

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 <[email protected]>

---
 drivers/char/rtc.c |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

drivers/char/rtc.c +3 -3

Index: 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)
 	{

Steven Rostedt

2006-07-14 03:58 UTC #5 lore raw

PATCH 1/1 remove unnecessary barrier in rtc_get_rtc_time

Quoted 9 lines · Ingo Molnar

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 <[email protected]>

drivers/char/rtc.c +1 -3

Index: linux-2.6.18-rc1/drivers/char/rtc.c
===================================================================
@@ -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

Joseph Fannin

author

2006-08-05 22:00 UTC #6 lore raw

Re: [patch] lockdep: HPET/RTC fix

In reply to Ingo Molnar

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.]

Quoted 27 lines

Subject: lockdep: HPET/RTC fix
From: Ingo Molnar <[email protected]>

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

drivers/char/rtc.c +2 -2

@@ -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);

drivers/char/rtc.c void rtc_get_rtc_time(struct rtc_time *r · line 1269

Quoted 8 lines

drivers/char/rtc.c +1 -1

@@ -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
[email protected]