Re: [2.6.29-rc2] Inconsistent lock state on resume in hres_timers_resume

From: Andrey Borzenkov
Date: Sun Jan 18 2009 - 23:23:22 EST

On 19 ÑÐÐÐÑÑ 2009 03:17:49 Rafael J. Wysocki wrote:
> On Sunday 18 January 2009, Andrey Borzenkov wrote:
> > On 18 ÑÐÐÐÑÑ 2009 23:21:24 Rafael J. Wysocki wrote:
> > > > > As far as I can tell, timekeeping_resume is called via class
> > > > > ->resume method; and according to comments in sysdev_resume()
> > > > > and device_power_up(), they are called with interrupts
> > > > > disabled.
> > > > >
> > > > > Looking at suspend_enter, irqs *are* disabled at this point.
> > > > >
> > > > > So it actually looks like something (may be some driver)
> > > > > unconditionally enabled irqs in resume path.
> > > > >
> > > > > I believe the patch should be hold back until this is
> > > > > clarified.
> > > >
> > > > That's a nice theory!
> > >
> > > That would be a bad bug.
> >

With sligtly modified patch:

[ 133.000279] PM: Syncing filesystems ... done.
[ 133.062027] orinoco_cs 0.0: firmware: requesting agere_sta_fw.bin
[ 133.102942] Freezing user space processes ... (elapsed 0.02 seconds)
done.
[ 133.123635] Freezing remaining freezable tasks ... (elapsed 0.00 seconds)
done.
[ 133.124813] Suspending console(s) (use no_console_suspend to debug)
[ 133.136151] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 133.648916] sd 0:0:0:0: [sda] Stopping disk
[ 134.339703] pci 0000:01:00.0: power state changed by ACPI to D3
[ 134.354447] e100 0000:00:0a.0: PME# enabled
[ 134.354679] e100 0000:00:0a.0: wake-up capability enabled by ACPI
[ 134.354845] e100 0000:00:0a.0: PCI INT A disabled
[ 134.420836] ALI 5451 0000:00:06.0: PCI INT A disabled
[ 134.433823] ALI 5451 0000:00:06.0: power state changed by ACPI to D3
[ 135.192366] pata_ali 0000:00:04.0: can't derive routing for PCI INT A
[ 135.203635] ohci_hcd 0000:00:02.0: PME# enabled
[ 135.203854] ohci_hcd 0000:00:02.0: wake-up capability enabled by ACPI
[ 135.203886] ohci_hcd 0000:00:02.0: PCI INT A disabled
[ 135.220184] ACPI: Preparing to enter system sleep state S3
[ 135.233610] ------------[ cut here ]------------
[ 135.233624] WARNING: at /home/bor/src/linux-
git/kernel/time/timekeeping.c:357 timekeeping_suspend+0xe9/0x230()
[ 135.233633] Hardware name: PORTEGE 4000
[ 135.233638] [0] Interrupts enabled in timekeeping_suspend
[ 135.233772] Pid: 4232, comm: pm-suspend Not tainted 2.6.29-rc2-1avb #7
[ 135.233779] Call Trace:
[ 135.233809] [<c011f8b3>] warn_slowpath+0x73/0xd0
[ 135.233825] [<c0143419>] ? trace_hardirqs_on_caller+0x139/0x190
[ 135.233835] [<c014347b>] ? trace_hardirqs_on+0xb/0x10
[ 135.233844] [<c013831a>] ? up+0x2a/0x40
[ 135.233870] [<c02346ba>] ? acpi_os_signal_semaphore+0x25/0x29
[ 135.233902] [<c024aea0>] ? acpi_ut_release_mutex+0x54/0x58
[ 135.233935] [<c02423f9>] ? acpi_get_data+0x51/0x60
[ 135.233952] [<c024c5c7>] ? acpi_bus_data_handler+0x0/0x5
[ 135.233962] [<c024be26>] ? acpi_bus_get_device+0x20/0x32
[ 135.233973] [<c024bec6>] ? acpi_bus_power_manageable+0xe/0x25
[ 135.234002] [<c02226a4>] ? acpi_pci_power_manageable+0x14/0x20
[ 135.234012] [<c021c972>] ? pci_set_power_state+0x92/0x2c0
[ 135.234049] [<c021ab5a>] ? pci_find_capability+0x5a/0x80
[ 135.234059] [<c013ac19>] timekeeping_suspend+0xe9/0x230
[ 135.234090] [<c0273825>] sysdev_suspend+0xb5/0x270
[ 135.234119] [<c0278adf>] ? device_pm_lock+0xf/0x20
[ 135.234128] [<c027944f>] device_power_down+0xef/0x110
[ 135.234156] [<c0150612>] suspend_devices_and_enter+0xb2/0x150
[ 135.234167] [<c0150e1f>] ? freeze_processes+0x3f/0x90
[ 135.234176] [<c0150804>] enter_state+0xf4/0x140
[ 135.234185] [<c01508cd>] state_store+0x7d/0xc0
[ 135.234193] [<c0150850>] ? state_store+0x0/0xc0
[ 135.234219] [<c0202f94>] kobj_attr_store+0x24/0x30
[ 135.234229] [<c01dd72c>] sysfs_write_file+0x9c/0x100
[ 135.234262] [<c019935c>] vfs_write+0x9c/0x160
[ 135.234277] [<c0103494>] ? restore_nocheck_notrace+0x0/0xe
[ 135.234285] [<c01dd690>] ? sysfs_write_file+0x0/0x100
[ 135.234294] [<c01994dd>] sys_write+0x3d/0x70
[ 135.234303] [<c0103371>] sysenter_do_call+0x12/0x31
[ 135.234310] ---[ end trace 0160afff8645b4ac ]---

I am absolutely confused. According to Documentation/power/devices.txt,
timekeeping_suspend and timekeeping_resume are class interfaces and allowed
to sleep. "Allowed to sleep" means to me - irqa enabled? But
device_power_down obviously runs under irqs disabled?


diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 900f1b6..1f9f98f 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -353,15 +353,35 @@ static int timekeeping_suspend(struct sys_device *dev,
pm_message_t state)
{
unsigned long flags;

+ WARN_ONCE(!irqs_disabled(),
+ "[0] Interrupts enabled in timekeeping_suspend\n");
+
timekeeping_suspend_time = read_persistent_clock();

+ WARN_ONCE(!irqs_disabled(),
+ "[1] Interrupts enabled in timekeeping_suspend\n");
+
write_seqlock_irqsave(&xtime_lock, flags);
+
+ WARN_ONCE(!irqs_disabled(),
+ "[2] Interrupts enabled in timekeeping_suspend\n");
+
clocksource_forward_now();
+
+ WARN_ONCE(!irqs_disabled(),
+ "[3] Interrupts enabled in timekeeping_suspend\n");
+
timekeeping_suspended = 1;
write_sequnlock_irqrestore(&xtime_lock, flags);

+ WARN_ONCE(!irqs_disabled(),
+ "[4] Interrupts enabled in timekeeping_suspend\n");
+
clockevents_notify(CLOCK_EVT_NOTIFY_SUSPEND, NULL);

+ WARN_ONCE(!irqs_disabled(),
+ "[5] Interrupts enabled in timekeeping_suspend\n");
+
return 0;
}


Attachment: signature.asc
Description: This is a digitally signed message part.