Re: 2.6.18-rc3-g3b445eea BUG: warning at /usr/src/linux-git/kernel/cpu.c:51/unlock_cpu_hotplug()

From: Michal Piotrowski
Date: Sat Aug 05 2006 - 06:51:51 EST

On 05/08/06, Dave Jones <davej@xxxxxxxxxx> wrote:
On Fri, Aug 04, 2006 at 10:49:47PM -0400, Dave Jones wrote:

This trace now makes a lot more sense to me.

> CPU1 called lock_cpu_hotplug() for app cpuspeed. recursive_depth=0
> [<c0104edc>] show_trace_log_lvl+0x58/0x152
> [<c01054c2>] show_trace+0xd/0x10
> [<c01055db>] dump_stack+0x19/0x1b
> [<c013e8c3>] lock_cpu_hotplug+0x39/0xbf
> [<c029fbae>] store_scaling_governor+0x142/0x1a3
> [<c029f1a5>] store+0x37/0x48
> [<c01a6561>] sysfs_write_file+0xab/0xd1
> [<c016f99f>] vfs_write+0xab/0x157
> [<c016ffe4>] sys_write+0x3b/0x60
> [<c0103db9>] sysenter_past_esp+0x56/0x8d
> cpuspeed acquired cpu_bitmask_lock
>
> CPU1 called lock_cpu_hotplug() for app cpuspeed. recursive_depth=0
> [<c0104edc>] show_trace_log_lvl+0x58/0x152
> [<c01054c2>] show_trace+0xd/0x10
> [<c01055db>] dump_stack+0x19/0x1b
> [<c013e8c3>] lock_cpu_hotplug+0x39/0xbf
> [<c0132f3c>] __create_workqueue+0x52/0x122
> [<f901234b>] cpufreq_governor_dbs+0x9f/0x2c3 [cpufreq_ondemand]
> [<c029f7b6>] __cpufreq_governor+0x57/0xd8
> [<c029f985>] __cpufreq_set_policy+0x14e/0x1bc
> [<c029fbc5>] store_scaling_governor+0x159/0x1a3
> [<c029f1a5>] store+0x37/0x48
> [<c01a6561>] sysfs_write_file+0xab/0xd1
> [<c016f99f>] vfs_write+0xab/0x157
> [<c016ffe4>] sys_write+0x3b/0x60
> [<c0103db9>] sysenter_past_esp+0x56/0x8d
> Lukewarm IQ detected in hotplug locking
> BUG: warning at kernel/cpu.c:46/lock_cpu_hotplug()

So when we write to sysfs to set the governor, we end up in store_scaling_governor()
which takes the hotplug lock, and then calls off into the governor to let it
do its thing. Part of ondemand's "thing" is to create a workqueue.
unfortunatly, __create_workqueue also takes the hotplug lock.

Creating a variant of __create_workqueue that doesn't take the lock
seems really nasty.

We could remove the locking from store_scaling_governor() and make the governors
themselves have to do the locking, but I'm not sure that's entirely safe.

We could do something really disgusting like ...

unlock_cpu_hotplug()
...
create_workqueue()
...
lock_cpu_hotplug()

in ondemand, which opens up a tiny race window, but as ugly as it is,
looks to be the best solution of the bunch right now.

Comments?

The really sad part is this is completely unrelated to the original bug reported
in this thread, which shows just how widespread this braindamage is.
Michal's traces really don't really scream anything obvious to me.
(Though given it took me 4 hours to decode my own traces above, this is no
real sign of how big a problem this might be).

Michal, could you apply this diff.. http://lkml.org/lkml/diff/2006/8/4/381/1
(change the '120' to '60' first), and send me the debug spew that you get ?
You'll have to wait until a minute of uptime has passed. Oh, and edit
include/linux/jiffies.h to change INITIAL_JIFFIES to '0'.

p4-clockmod: P4/Xeon(TM) CPU On-Demand Clock Modulation available
ip_tables: (C) 2000-2006 Netfilter Core Team
Netfilter messages via NETLINK v0.30.
BUG: warning at /usr/src/linux-git/kernel/cpu.c:69/unlock_cpu_hotplug()
[<c0132a91>] unlock_cpu_hotplug+0x63/0xb2
[<c013a3a0>] stop_machine_run+0x2e/0x34
[<c013573a>] sys_init_module+0x15a0/0x178a
[<c015b86b>] do_sync_read+0xb6/0xf1
[<c0102d51>] sysenter_past_esp+0x56/0x79
ip_conntrack version 2.4 (8192 buckets, 65536 max) - 224 bytes per conntrack
NET: Registered protocol family 17
skge eth0: enabling interface
skge eth0: Link is up at 100 Mbps, full duplex, flow control tx and rx
w83627hf 9191-0290: Reading VID from GPIO5
NET: Registered protocol family 10
IPv6 over IPv4 tunneling driver
audit(1154774854.770:5): avc: denied { write } for pid=1360
comm="cpuspeed" name="cpufreq" dev=sysfs ino=4863
scontext=system_u:system_r:cpuspeed_t:s0
tcontext=system_u:object_r:sysfs_t:s0 tclass=dir
eth0: no IPv6 routers present
CPU0 called lock_cpu_hotplug() for app amarokapp. recursive_depth=0
[<c01329ab>] lock_cpu_hotplug+0x36/0xb9
[<c01182ce>] sched_getaffinity+0xf/0x83
[<c0118361>] sys_sched_getaffinity+0x1f/0x41
[<c0102d51>] sysenter_past_esp+0x56/0x79
amarokapp acquired cpu_bitmask_lock
CPU0 called unlock_cpu_hotplug() for app amarokapp. recursive_depth=0
[<c0132a62>] unlock_cpu_hotplug+0x34/0xb2
[<c0118323>] sched_getaffinity+0x64/0x83
[<c0118361>] sys_sched_getaffinity+0x1f/0x41
[<c0102d51>] sysenter_past_esp+0x56/0x79
amarokapp released cpu_bitmask_lock
CPU0 called lock_cpu_hotplug() for app amarokapp. recursive_depth=0
[<c01329ab>] lock_cpu_hotplug+0x36/0xb9
[<c01195ca>] sched_setaffinity+0xf/0xd5
[<c01196cb>] sys_sched_setaffinity+0x3b/0x41
[<c0102d51>] sysenter_past_esp+0x56/0x79
amarokapp acquired cpu_bitmask_lock
CPU0 called unlock_cpu_hotplug() for app amarokapp. recursive_depth=0
[<c0132a62>] unlock_cpu_hotplug+0x34/0xb2
[<c0119689>] sched_setaffinity+0xce/0xd5
[<c01196cb>] sys_sched_setaffinity+0x3b/0x41
[<c0102d51>] sysenter_past_esp+0x56/0x79
amarokapp released cpu_bitmask_lock


Dave

--
http://www.codemonkey.org.uk


Regards,
Michal

--
Michal K. K. Piotrowski
LTG - Linux Testers Group
(http://www.stardust.webpages.pl/ltg/wiki/)
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/