Hey all,
I ran 2.6.19-rc3 for almost two weeks or so with no difficulties (none related
to the bcm43xx driver, at least). However, Andrew asked me to double check the
latest release to see if my problem report against 2.6.18 (hard locks) was
fixed. Good news is that it still is fixed. Bad news is that 2.6.19-rc5 is
worse than rc3 in other ways.
I've come back to my laptop being mostly dead after hours of it being off on
its own (twice now). Mostly dead meaning the keyboard is nearly
non-responsive, but the mouse works great (I'm in X, of course). I say 'nearly
dead' as sysrq-t,b works, so I'm sorta stumped there. (x-session seems to use
netlink, so perhaps that's the connection? ctrl-alt-f[1-7] don't do anything,
however.)
It seems to be a locking problem, though lockdep isn't catching it. I'll let
you guys decide though.
Regardless, here's what's I can see. My logs start filling with:
$ grep 'NETDEV WATCHDOG:' /var/log/messages | cut -d '[' -f 2- | head
50025.388173] NETDEV WATCHDOG: eth1: transmit timed out
50029.019574] NETDEV WATCHDOG: eth1: transmit timed out
50030.835313] NETDEV WATCHDOG: eth1: transmit timed out
50032.651049] NETDEV WATCHDOG: eth1: transmit timed out
50034.466785] NETDEV WATCHDOG: eth1: transmit timed out
50036.282523] NETDEV WATCHDOG: eth1: transmit timed out
50038.098237] NETDEV WATCHDOG: eth1: transmit timed out
50039.913974] NETDEV WATCHDOG: eth1: transmit timed out
50041.729709] NETDEV WATCHDOG: eth1: transmit timed out
50043.545447] NETDEV WATCHDOG: eth1: transmit timed out
(...1249 of these, so it doesn't fix itself.)
and then the system becomes pretty worthless. (Full /var/log/messages with
sysrq-t at: http://madrabbit.org/~ray/messages.gz ).
Interesting bits of that:
$ grep -B5 -A10 'Nov 13 01:5.*mutex' /var/log/messages | cut -d ']' -f2-
DWARF2 unwinder stuck at child_rip+0xa/0x12
Leftover inexact backtrace:
[restore_args+0/48] restore_args+0x0/0x30
[mutex_lock+9/16] mutex_lock+0x9/0x10
[kthread+0/272] kthread+0x0/0x110
[child_rip+0/18] child_rip+0x0/0x12
khelper S ffff810037fbe318 0 5 1 6 4 (L-TLB)
ffff810037907e60 0000000000000046 ffff810037907e70 ffff810037fbe140
ffff81001095f140 0000000000003b5d ffff810001e3e668 0000000000000286
ffff810037907e40 ffffffff8026bbb2 ffff810037907e70 ffff810001e3e600
Call Trace:
[worker_thread+236/352] worker_thread+0xec/0x160
[kthread+211/272] kthread+0xd3/0x110
--
DWARF2 unwinder stuck at child_rip+0xa/0x12
Leftover inexact backtrace:
[restore_args+0/48] restore_args+0x0/0x30
[mutex_lock+9/16] mutex_lock+0x9/0x10
[kthread+0/272] kthread+0x0/0x110
[child_rip+0/18] child_rip+0x0/0x12
kthread S ffff810037fad218 0 6 1 25 2129 5 (L-TLB)
ffff810037f01e60 0000000000000046 ffff810037f01e70 ffff810037fad040
ffff81002b3df140 000000000000062b ffff810001e3e468 0000000000000286
ffff810037f01e40 ffffffff8026bbb2 ffff810037f01e70 ffff810001e3e400
Call Trace:
[worker_thread+236/352] worker_thread+0xec/0x160
[kthread+211/272] kthread+0xd3/0x110
--
DWARF2 unwinder stuck at child_rip+0xa/0x12
Leftover inexact backtrace:
[restore_args+0/48] restore_args+0x0/0x30
[mutex_lock+9/16] mutex_lock+0x9/0x10
[kthread+0/272] kthread+0x0/0x110
[child_rip+0/18] child_rip+0x0/0x12
kblockd/0 S ffff810037989318 0 25 6 26 (L-TLB)
ffff81003798fe60 0000000000000046 ffff81003798fe70 ffff810037989140
ffff8100379a5100 000000000000078b ffff810037fa2468 0000000000000286
ffff81003798fe40 ffffffff8026bbb2 ffff81003798fe70 ffff810037fa2400
Call Trace:
[worker_thread+236/352] worker_thread+0xec/0x160
[kthread+211/272] kthread+0xd3/0x110
--
NetworkManage D ffff810037943258 0 4833 1 4853 4809 (NOTLB)
ffff81002bfefbe8 0000000000000046 ffff81002bfefb98 ffff810037943080
ffff81002e6d2100 00000000000122a6 ffffffff8062ce80 0000000000000046
0000000000000246 ffff810037943080 ffff81002e47b3f0 ffff81002e47b3a0
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[_end+126343345/2126632680] :bcm43xx:bcm43xx_wx_get_mode+0x29/0x60
[ioctl_standard_call+139/944] ioctl_standard_call+0x8b/0x3b0
[wireless_process_ioctl+260/976] wireless_process_ioctl+0x104/0x3d0
[dev_ioctl+854/944] dev_ioctl+0x356/0x3b0
[sock_ioctl+576/624] sock_ioctl+0x240/0x270
[do_ioctl+49/160] do_ioctl+0x31/0xa0
[vfs_ioctl+683/720] vfs_ioctl+0x2ab/0x2d0
[sys_ioctl+106/160] sys_ioctl+0x6a/0xa0
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83
--
x-session-man D ffff81002ef02298 0 5625 4565 5672 4586 (NOTLB)
ffff810028a1fad8 0000000000000046 ffffffff8062c500 ffff81002ef020c0
ffff8100249a6040 0000000000008c5d 0000000000000000 0000000000000046
0000000000000246 ffff81002ef020c0 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnetlink_rcv+44/96] rtnetlink_rcv+0x2c/0x60
[netlink_data_ready+26/96] netlink_data_ready+0x1a/0x60
[netlink_sendskb+51/96] netlink_sendskb+0x33/0x60
[netlink_unicast+536/592] netlink_unicast+0x218/0x250
[netlink_sendmsg+704/736] netlink_sendmsg+0x2c0/0x2e0
[sock_sendmsg+271/320] sock_sendmsg+0x10f/0x140
[sys_sendto+273/320] sys_sendto+0x111/0x140
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83
--
gweather-appl D ffff810023b43218 0 7198 1 7199 3540 (NOTLB)
ffff810033315ad8 0000000000000046 0000000000000000 ffff810023b43040
ffff81001f47a0c0 000000000001215f 0000000000000000 0000000000000046
0000000000000246 ffff810023b43040 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnetlink_rcv+44/96] rtnetlink_rcv+0x2c/0x60
[netlink_data_ready+26/96] netlink_data_ready+0x1a/0x60
[netlink_sendskb+51/96] netlink_sendskb+0x33/0x60
[netlink_unicast+536/592] netlink_unicast+0x218/0x250
[netlink_sendmsg+704/736] netlink_sendmsg+0x2c0/0x2e0
[sock_sendmsg+271/320] sock_sendmsg+0x10f/0x140
[sys_sendto+273/320] sys_sendto+0x111/0x140
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83
--
gweather-appl D ffff81001f47a298 0 7199 1 7200 7198 (NOTLB)
ffff8100338efad8 0000000000000046 0000000000000000 ffff81001f47a0c0
ffff81000eee2040 0000000000009ce2 0000000000000000 0000000000000046
0000000000000246 ffff81001f47a0c0 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnetlink_rcv+44/96] rtnetlink_rcv+0x2c/0x60
[netlink_data_ready+26/96] netlink_data_ready+0x1a/0x60
[netlink_sendskb+51/96] netlink_sendskb+0x33/0x60
[netlink_unicast+536/592] netlink_unicast+0x218/0x250
[netlink_sendmsg+704/736] netlink_sendmsg+0x2c0/0x2e0
[sock_sendmsg+271/320] sock_sendmsg+0x10f/0x140
[sys_sendto+273/320] sys_sendto+0x111/0x140
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83
--
gweather-appl D ffff81000eee2218 0 7200 1 9252 7199 (NOTLB)
ffff810019d3dad8 0000000000000046 0000000000000000 ffff81000eee2040
ffff81002178d0c0 000000000000cb7b ffffffff8062ce80 0000000000000046
0000000000000246 ffff81000eee2040 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnetlink_rcv+44/96] rtnetlink_rcv+0x2c/0x60
[netlink_data_ready+26/96] netlink_data_ready+0x1a/0x60
[netlink_sendskb+51/96] netlink_sendskb+0x33/0x60
[netlink_unicast+536/592] netlink_unicast+0x218/0x250
[netlink_sendmsg+704/736] netlink_sendmsg+0x2c0/0x2e0
[sock_sendmsg+271/320] sock_sendmsg+0x10f/0x140
[sys_sendto+273/320] sys_sendto+0x111/0x140
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83
--
wpa_supplican D ffff810026e9a218 0 8058 1 19402 6666 (NOTLB)
ffff81001bf81ad8 0000000000000046 0000000000000002 ffff810026e9a040
ffff8100072e4140 000000000001b54f 0000000000000000 0000000000000046
0000000000000246 ffff810026e9a040 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnetlink_rcv+44/96] rtnetlink_rcv+0x2c/0x60
[netlink_data_ready+26/96] netlink_data_ready+0x1a/0x60
[netlink_sendskb+51/96] netlink_sendskb+0x33/0x60
[netlink_unicast+536/592] netlink_unicast+0x218/0x250
[netlink_sendmsg+704/736] netlink_sendmsg+0x2c0/0x2e0
[sock_sendmsg+271/320] sock_sendmsg+0x10f/0x140
[sys_sendto+273/320] sys_sendto+0x111/0x140
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83
--
dhclient D ffff8100353092d8 0 9218 4784 (NOTLB)
ffff810007811d28 0000000000000046 00000000000000e2 ffff810035309100
ffffffff80518520 000000000000920c 0000000000000000 0000000000000046
0000000000000246 ffff810035309100 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnl_lock+16/32] rtnl_lock+0x10/0x20
[dev_ioctl+53/944] dev_ioctl+0x35/0x3b0
[sock_ioctl+576/624] sock_ioctl+0x240/0x270
[do_ioctl+49/160] do_ioctl+0x31/0xa0
[vfs_ioctl+683/720] vfs_ioctl+0x2ab/0x2d0
[sys_ioctl+106/160] sys_ioctl+0x6a/0xa0
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83
Leftover inexact backtrace:
--
ip D ffff8100072e4318 0 9221 4809 (NOTLB)
ffff8100073e5ad8 0000000000000046 ffff810037bcbbf8 ffff8100072e4140
ffffffff80518520 000000000002322b 0000000000000000 0000000000000046
0000000000000246 ffff8100072e4140 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnetlink_rcv+44/96] rtnetlink_rcv+0x2c/0x60
[netlink_data_ready+26/96] netlink_data_ready+0x1a/0x60
[netlink_sendskb+51/96] netlink_sendskb+0x33/0x60
[netlink_unicast+536/592] netlink_unicast+0x218/0x250
[netlink_sendmsg+704/736] netlink_sendmsg+0x2c0/0x2e0
[sock_sendmsg+271/320] sock_sendmsg+0x10f/0x140
[sys_sendto+273/320] sys_sendto+0x111/0x140
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83
[...]
52234.341105] Showing all locks held in the system:
52234.341113]
52234.341114] =============================================
52234.341115]
52234.394782] NETDEV WATCHDOG: eth1: transmit timed out
52236.210364] NETDEV WATCHDOG: eth1: transmit timed out
52238.026024] NETDEV WATCHDOG: eth1: transmit timed out
[...more of these, 'til I reboot with sysrq-b]
Notice that 'all locks held in the system' is empty.
There were three changes between rc3 and rc5:
$ hg log -rv2.6.19-rc3:v2.6.19-rc5 -I drivers/net/wireless/bcm43xx/
changeset: 40500:4ef6746b2f06
user: Al Viro <[email protected]>
date: Wed Oct 25 12:01:11 2006 +0700
summary: [PATCH] missing include of dma-mapping.h
changeset: 40964:ca97546422bd
user: Michael Buesch <[email protected]>
date: Wed Nov 01 08:15:40 2006 +0500
summary: [PATCH] bcm43xx: Fix low-traffic netdev watchdog TX timeouts
changeset: 40965:f5021f3521c2
user: Larry Finger <[email protected]>
date: Wed Nov 01 08:15:41 2006 +0500
summary: [PATCH] bcm43xx: fix unexpected LED control values in BCM4303 sprom
Of those, the middle one is the most suspicious.
ray@phoenix:~/work/kernel/linux-2.6$ hg log -v -p -r 40964
changeset: 40964:ca97546422bd9a52a7000607d657ca2915f31104
user: Michael Buesch <[email protected]>
date: Wed Nov 01 08:15:40 2006 +0500
files: drivers/net/wireless/bcm43xx/bcm43xx_main.c
description:
[PATCH] bcm43xx: Fix low-traffic netdev watchdog TX timeouts
This fixes a netdev watchdog timeout problem.
The software needs to call netif_tx_disable before running the
hardware calibration code. The problem condition can be shown by the
following timegraph.
|---5secs - ~10 jiffies time---|---|OOPS
^ ^
last real TX periodic work stops netif
At OOPS, the following happens:
The watchdog timer triggers, because the timeout of 5secs
is over. The watchdog first checks for stopped TX.
_Usually_ TX is only stopped from the TX handler to indicate
a full TX queue. But this is different. We need to stop TX here,
regardless of the TX queue state. So the watchdog recognizes
the stopped device and assumes it is stopped due to full
TX queues (Which is a _wrong_ assumption in this case). It then
tests how far the last TX has been in the past. If it's more than
5secs (which is the case for low or no traffic), it will fire
a TX timeout.
Signed-off-by: Michael Buesch <[email protected]>
Signed-off-by: Larry Finger <[email protected]>
Signed-off-by: John W. Linville <[email protected]>
committer: John W. Linville <linville@laptop.(none)> 1162350940 -0500
diff -r 41ff0150cbadd56e692f148adb1bfd4ca420e3e0 -r
ca97546422bd9a52a7000607d657ca2915f31104
drivers/net/wireless/bcm43xx/bcm43xx_main.c
--- a/drivers/net/wireless/bcm43xx/bcm43xx_main.c Wed Nov 01 08:15:39
2006 +0500
+++ b/drivers/net/wireless/bcm43xx/bcm43xx_main.c Wed Nov 01 08:15:40
2006 +0500
@@ -3163,9 +3163,11 @@ static void bcm43xx_periodic_work_handle
static void bcm43xx_periodic_work_handler(void *d)
{
struct bcm43xx_private *bcm = d;
+ struct net_device *net_dev = bcm->net_dev;
unsigned long flags;
u32 savedirqs = 0;
int badness;
+ unsigned long orig_trans_start = 0;
mutex_lock(&bcm->mutex);
badness = estimate_periodic_work_badness(bcm->periodic_state);
@@ -3173,7 +3175,18 @@ static void bcm43xx_periodic_work_handle
/* Periodic work will take a long time, so we want it to
* be preemtible.
*/
- netif_tx_disable(bcm->net_dev);
+
+ netif_tx_lock_bh(net_dev);
+ /* We must fake a started transmission here, as we are going to
+ * disable TX. If we wouldn't fake a TX, it would be possible to
+ * trigger the netdev watchdog, if the last real TX is already
+ * some time on the past (slightly less than 5secs)
+ */
+ orig_trans_start = net_dev->trans_start;
+ net_dev->trans_start = jiffies;
+ netif_stop_queue(net_dev);
+ netif_tx_unlock_bh(net_dev);
+
spin_lock_irqsave(&bcm->irq_lock, flags);
bcm43xx_mac_suspend(bcm);
if (bcm43xx_using_pio(bcm))
@@ -3198,6 +3211,7 @@ static void bcm43xx_periodic_work_handle
bcm43xx_pio_thaw_txqueues(bcm);
bcm43xx_mac_enable(bcm);
netif_wake_queue(bcm->net_dev);
+ net_dev->trans_start = orig_trans_start;
}
mmiowb();
spin_unlock_irqrestore(&bcm->irq_lock, flags);
...so, could someone with more of a clue than I review the locking here?
In the meantime, I could try to revert this and run with the changed kernel,
but I've only had this happen twice in the past four days (dunno how to
trigger it other than walking away from the laptop). As rc3 didn't give me any
troubles for the 13 some-odd days I ran it, I think it's safe to say this is a
new behavior with rc5 vs rc3.
Suggestions? Requests for <shudder> even more info?
Ray
On Wednesday 15 November 2006 20:01, Ray Lee wrote:
> Suggestions? Requests for <shudder> even more info?
Yeah, enable bcm43xx debugging.
--
Greetings Michael.
Michael Buesch wrote:
> On Wednesday 15 November 2006 20:01, Ray Lee wrote:
>> Suggestions? Requests for <shudder> even more info?
>
> Yeah, enable bcm43xx debugging.
Sigh, didn't even think to look for that. Okay, enabled and compiling a new
kernel. This will take a few days to trigger, if the pattern holds, so in the
meantime, any *other* thoughts?
Ray Lee wrote:
> Michael Buesch wrote:
>> On Wednesday 15 November 2006 20:01, Ray Lee wrote:
>>> Suggestions? Requests for <shudder> even more info?
>> Yeah, enable bcm43xx debugging.
>
> Sigh, didn't even think to look for that. Okay, enabled and compiling a new
> kernel. This will take a few days to trigger, if the pattern holds, so in the
> meantime, any *other* thoughts?
>
Which chip and revision do you have? Send me your equivalent of the line "bcm43xx: Chip ID 0x4306,
rev 0x2".
Thanks,
Larry
Larry Finger wrote:
> Ray Lee wrote:
>> Michael Buesch wrote:
>>> On Wednesday 15 November 2006 20:01, Ray Lee wrote:
>>>> Suggestions? Requests for <shudder> even more info?
>>> Yeah, enable bcm43xx debugging.
>>
>> Sigh, didn't even think to look for that. Okay, enabled and compiling
>> a new kernel. This will take a few days to trigger, if the pattern holds, so
>> in the meantime, any *other* thoughts?
>
> Which chip and revision do you have? Send me your equivalent of the line
> "bcm43xx: Chip ID 0x4306, rev 0x2".
bcm43xx: Chip ID 0x4306, rev 0x3
Also, another thing I wasn't clear about in my first email was that the netdev
watchdog timeouts are new with rc5:
$ zgrep 'NETDEV WATCH' /var/log/messages{,.0,.1.gz} | cut -d: -f2| cut -c 1-6
| uniq -c
1249 Nov 13
6 Nov 6
1 Nov 7
3 Nov 8
2 Nov 9
5717 Nov 10
5652 Nov 11
5 Oct 29
3 Oct 30
3 Oct 31
4 Nov 1
1 Nov 2
1 Nov 3
I booted into 2.6.19-rc5 on November 10th. Previous to that was 2.6.19-rc3.
There really does seem to be something suspicious with that patch, yes?
Thanks,
Ray
On Wed, Nov 15, 2006 at 11:01:00AM -0800, Ray Lee wrote:
> I've come back to my laptop being mostly dead after hours of it being off on
> its own (twice now). Mostly dead meaning the keyboard is nearly
> non-responsive, but the mouse works great (I'm in X, of course). I say 'nearly
> dead' as sysrq-t,b works, so I'm sorta stumped there. (x-session seems to use
> netlink, so perhaps that's the connection? ctrl-alt-f[1-7] don't do anything,
> however.)
This sounds like what my laptop was doing in -rc5, though mine
didn't take hours to start acting up.
I *think* it was the MSI troubles, causing interrupts to get
lost forever. Anyway, it went away in -rc6.
I don't have the broadcom hardware.
--
Joseph Fannin
[email protected] || [email protected]
On Sat, 2006-11-18 at 06:24 -0500, Joseph Fannin wrote:
> This sounds like what my laptop was doing in -rc5, though mine
> didn't take hours to start acting up.
>
> I *think* it was the MSI troubles, causing interrupts to get
> lost forever. Anyway, it went away in -rc6.
Hah, that's a lot more plausible than bcm43xx's drain patch actually
causing this. So maybe somehow interrupts for bcm43xx aren't routed
properly or something...
Ray, please check /proc/interrupts when this happens.
I am convinced that the patch in question (drain tx status) is not
causing this -- the patch should be a no-op in most cases anyway, and in
those cases where it isn't a no-op it'll run only once at card init and
remove some things from a hardware-internal FIFO.
johannes
Johannes Berg wrote:
> On Sat, 2006-11-18 at 06:24 -0500, Joseph Fannin wrote:
>
>> This sounds like what my laptop was doing in -rc5, though mine
>> didn't take hours to start acting up.
>>
>> I *think* it was the MSI troubles, causing interrupts to get
>> lost forever. Anyway, it went away in -rc6.
>
> Hah, that's a lot more plausible than bcm43xx's drain patch actually
> causing this. So maybe somehow interrupts for bcm43xx aren't routed
> properly or something...
>
> Ray, please check /proc/interrupts when this happens.
>
> I am convinced that the patch in question (drain tx status) is not
> causing this -- the patch should be a no-op in most cases anyway, and in
> those cases where it isn't a no-op it'll run only once at card init and
> remove some things from a hardware-internal FIFO.
I agree that drain tx status should not cause the problem.
Ray, does -rc6 solve your problem as it did for Joseph?
Larry
Larry Finger wrote:
> Johannes Berg wrote:
>> Hah, that's a lot more plausible than bcm43xx's drain patch actually
>> causing this. So maybe somehow interrupts for bcm43xx aren't routed
>> properly or something...
>>
>> Ray, please check /proc/interrupts when this happens.
When it happens, I can't. The keyboard is entirely dead (I'm in X, perhaps at
a console it would be okay). The only thing that works is magic SysRq. even
ctrl-alt-f1 to get to a console doesn't work.
That said, /proc/interrupts doesn't show MSI routed things on my AMD64 laptop.
>> I am convinced that the patch in question (drain tx status) is not
>> causing this -- the patch should be a no-op in most cases anyway, and in
>> those cases where it isn't a no-op it'll run only once at card init and
>> remove some things from a hardware-internal FIFO.
>
Okay, I can buy that.
> I agree that drain tx status should not cause the problem.
>
> Ray, does -rc6 solve your problem as it did for Joseph?
I can't get it to repeat other than the first two times. However, I
accidentally stopped NetworkManager from handling my wireless a few days ago,
and haven't restarted it, so that may play into this.
Humor me one last time, I beg. Did you look at the messages file I posted? (Or
maybe I didn't include this second bit... Damn, I need to be more careful with
cutting and pasting...)
The second sysrq-t shows locking stuff going on, can you tell me if it looks
reasonable? It still seems to me that something acquiring and not releasing
rtnl_lock explains what I was seeing (rtnl lock is implicated in both sysrq-t
backtraces). I don't know if that thing is bcm43xx, though.
Is this part reasonable?:
1 lock held by events/0/4:
#0: (&bcm->mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
2 locks held by NetworkManager/4837:
#0: (rtnl_mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
#1: (&bcm->mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
1 lock held by wpa_supplicant/5953:
#0: (rtnl_mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
(So locks A, A&B, B)
...of the below...
Showing all locks held in the system:
1 lock held by events/0/4:
#0: (&bcm->mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
1 lock held by getty/4224:
#0: (&tty->atomic_read_lock){--..}, at: [mutex_lock_interruptible+9/16]
mutex_lock_interruptible+0x9/0x10
1 lock held by getty/4225:
#0: (&tty->atomic_read_lock){--..}, at: [mutex_lock_interruptible+9/16]
mutex_lock_interruptible+0x9/0x10
1 lock held by getty/4226:
#0: (&tty->atomic_read_lock){--..}, at: [mutex_lock_interruptible+9/16]
mutex_lock_interruptible+0x9/0x10
1 lock held by getty/4227:
#0: (&tty->atomic_read_lock){--..}, at: [mutex_lock_interruptible+9/16]
mutex_lock_interruptible+0x9/0x10
1 lock held by getty/4228:
#0: (&tty->atomic_read_lock){--..}, at: [mutex_lock_interruptible+9/16]
mutex_lock_interruptible+0x9/0x10
1 lock held by getty/4229:
#0: (&tty->atomic_read_lock){--..}, at: [mutex_lock_interruptible+9/16]
mutex_lock_interruptible+0x9/0x10
2 locks held by NetworkManager/4837:
#0: (rtnl_mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
#1: (&bcm->mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
1 lock held by wpa_supplicant/5953:
#0: (rtnl_mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
1 lock held by less/29492:
#0: (&tty->atomic_read_lock){--..}, at: [mutex_lock_interruptible+9/16]
mutex_lock_interruptible+0x9/0x10
1 lock held by bash/9871:
#0: (&tty->atomic_read_lock){--..}, at: [mutex_lock_interruptible+9/16]
mutex_lock_interruptible+0x9/0x10
=============================================
Regardless, I'm going to withdraw my regression report until I can reproduce
this. I can't justify holding anything up if we can't even finger a culprit to
look at. In the meantime I'll try running with rc6.
Ray
On Sat, Nov 18, 2006 at 09:27:13AM -0800, Ray Lee wrote:
> Larry Finger wrote:
> > Johannes Berg wrote:
> >> Hah, that's a lot more plausible than bcm43xx's drain patch actually
> >> causing this. So maybe somehow interrupts for bcm43xx aren't routed
> >> properly or something...
> >>
> >> Ray, please check /proc/interrupts when this happens.
>
> When it happens, I can't. The keyboard is entirely dead (I'm in X, perhaps at
> a console it would be okay). The only thing that works is magic SysRq. even
> ctrl-alt-f1 to get to a console doesn't work.
>
> That said, /proc/interrupts doesn't show MSI routed things on my AMD64 laptop.
>...
If there is any interrupt related problem involved, it should be visible
from dmesg.
Can you send the complete dmesg's from -rc3, -rc5 and -rc6?
> Ray
cu
Adrian
--
"Is there not promise of rain?" Ling Tan asked suddenly out
of the darkness. There had been need of rain for many days.
"Only a promise," Lao Er said.
Pearl S. Buck - Dragon Seed
Ray Lee wrote:
> Larry Finger wrote:
>> Johannes Berg wrote:
>>> Hah, that's a lot more plausible than bcm43xx's drain patch actually
>>> causing this. So maybe somehow interrupts for bcm43xx aren't routed
>>> properly or something...
>>>
>>> Ray, please check /proc/interrupts when this happens.
>
> When it happens, I can't. The keyboard is entirely dead (I'm in X, perhaps at
> a console it would be okay). The only thing that works is magic SysRq. even
> ctrl-alt-f1 to get to a console doesn't work.
>
> That said, /proc/interrupts doesn't show MSI routed things on my AMD64 laptop.
>
>>> I am convinced that the patch in question (drain tx status) is not
>>> causing this -- the patch should be a no-op in most cases anyway, and in
>>> those cases where it isn't a no-op it'll run only once at card init and
>>> remove some things from a hardware-internal FIFO.
>
> Okay, I can buy that.
>
>> I agree that drain tx status should not cause the problem.
>>
>> Ray, does -rc6 solve your problem as it did for Joseph?
>
> I can't get it to repeat other than the first two times. However, I
> accidentally stopped NetworkManager from handling my wireless a few days ago,
> and haven't restarted it, so that may play into this.
>
> Humor me one last time, I beg. Did you look at the messages file I posted? (Or
> maybe I didn't include this second bit... Damn, I need to be more careful with
> cutting and pasting...)
The locking stuff wasn't in any of the messages that I received.
> The second sysrq-t shows locking stuff going on, can you tell me if it looks
> reasonable? It still seems to me that something acquiring and not releasing
> rtnl_lock explains what I was seeing (rtnl lock is implicated in both sysrq-t
> backtraces). I don't know if that thing is bcm43xx, though.
>
> Is this part reasonable?:
> 1 lock held by events/0/4:
> #0: (&bcm->mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
> 2 locks held by NetworkManager/4837:
> #0: (rtnl_mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
> #1: (&bcm->mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
> 1 lock held by wpa_supplicant/5953:
> #0: (rtnl_mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
I'm not an expert on locking, but it certainly looks as if bcm43xx and wpa_supplicant are OK by
themselves, but that NetworkManager interferes. This behavior matches what I see - I don't have
NetworkManager on my system, but I do use wpa_supplicant, with no lockups. Of course, I have i386
architecture.
Although NetworkManager may be the catalyst to trigger the bug, I doubt that it is the cause.
Strictly as a guess, I would suspect that the locking problem is in SoftMAC, where we know there can
be locking difficulties, but no one is fixing them because EOL is near for that component.
Larry
I am trying to debug a bcm43xx DMA problem on an x86_64 system with 3 GB RAM. Depending on the
particular chip and its implementation, dma transfers may use 64-, 32-, or 30-bit addressing, with
the problem interface using 30-bit addressing. From test prints, the correct mask (0x3FFFFFFF) is
supplied to pci_set_dma_mask and pci_set_consistent_dma_mask. Neither call returns an error. In
addition, several x86_64 systems with more than 1 GB RAM have worked with the current code.
If the system is booted with mem=1024M on the command line, it operates normally; however, it gets a
kernel NULL pointer dereference and panics when booted with either 2 or 3 GB RAM.
The config parameters in the processor section are as follows:
CONFIG_X86_64=y
CONFIG_64BIT=y
CONFIG_X86=y
CONFIG_ZONE_DMA32=y
CONFIG_LOCKDEP_SUPPORT=y
CONFIG_STACKTRACE_SUPPORT=y
CONFIG_SEMAPHORE_SLEEPERS=y
CONFIG_MMU=y
CONFIG_RWSEM_GENERIC_SPINLOCK=y
CONFIG_GENERIC_HWEIGHT=y
CONFIG_GENERIC_CALIBRATE_DELAY=y
CONFIG_X86_CMPXCHG=y
CONFIG_EARLY_PRINTK=y
CONFIG_GENERIC_ISA_DMA=y
CONFIG_GENERIC_IOMAP=y
CONFIG_ARCH_MAY_HAVE_PC_FDC=y
CONFIG_ARCH_POPULATES_NODE_MAP=y
CONFIG_DMI=y
CONFIG_AUDIT_ARCH=y
CONFIG_DEFCONFIG_LIST="/lib/modules/$UNAME_RELEASE/.config"
I would appreciate any tips on debugging this problem. Are there any quantities that should be
dumped, etc?
Thanks,
Larry
On Saturday 18 November 2006 20:02, Larry Finger wrote:
> Ray Lee wrote:
> > Larry Finger wrote:
> >> Johannes Berg wrote:
> >>> Hah, that's a lot more plausible than bcm43xx's drain patch actually
> >>> causing this. So maybe somehow interrupts for bcm43xx aren't routed
> >>> properly or something...
> >>>
> >>> Ray, please check /proc/interrupts when this happens.
> >
> > When it happens, I can't. The keyboard is entirely dead (I'm in X, perhaps at
> > a console it would be okay). The only thing that works is magic SysRq. even
> > ctrl-alt-f1 to get to a console doesn't work.
> >
> > That said, /proc/interrupts doesn't show MSI routed things on my AMD64 laptop.
> >
> >>> I am convinced that the patch in question (drain tx status) is not
> >>> causing this -- the patch should be a no-op in most cases anyway, and in
> >>> those cases where it isn't a no-op it'll run only once at card init and
> >>> remove some things from a hardware-internal FIFO.
> >
> > Okay, I can buy that.
> >
> >> I agree that drain tx status should not cause the problem.
> >>
> >> Ray, does -rc6 solve your problem as it did for Joseph?
> >
> > I can't get it to repeat other than the first two times. However, I
> > accidentally stopped NetworkManager from handling my wireless a few days ago,
> > and haven't restarted it, so that may play into this.
> >
> > Humor me one last time, I beg. Did you look at the messages file I posted? (Or
> > maybe I didn't include this second bit... Damn, I need to be more careful with
> > cutting and pasting...)
>
> The locking stuff wasn't in any of the messages that I received.
>
> > The second sysrq-t shows locking stuff going on, can you tell me if it looks
> > reasonable? It still seems to me that something acquiring and not releasing
> > rtnl_lock explains what I was seeing (rtnl lock is implicated in both sysrq-t
> > backtraces). I don't know if that thing is bcm43xx, though.
> >
> > Is this part reasonable?:
> > 1 lock held by events/0/4:
> > #0: (&bcm->mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
> > 2 locks held by NetworkManager/4837:
> > #0: (rtnl_mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
> > #1: (&bcm->mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
> > 1 lock held by wpa_supplicant/5953:
> > #0: (rtnl_mutex){--..}, at: [mutex_lock+9/16] mutex_lock+0x9/0x10
>
> I'm not an expert on locking, but it certainly looks as if bcm43xx and wpa_supplicant are OK by
> themselves, but that NetworkManager interferes. This behavior matches what I see - I don't have
> NetworkManager on my system, but I do use wpa_supplicant, with no lockups. Of course, I have i386
> architecture.
>
> Although NetworkManager may be the catalyst to trigger the bug, I doubt that it is the cause.
> Strictly as a guess, I would suspect that the locking problem is in SoftMAC, where we know there can
> be locking difficulties, but no one is fixing them because EOL is near for that component.
Well, this is different. The (known) locking problems are of type "missing locking".
But this seems to be a deadlock or something, so clearly a bug that
must be fixed. Even in softmac.
I don't know yet how this can happen, though.
--
Greetings Michael.
Hey there,
Haven't seen any follow ups to this, so I'm going to ask stupid questions. (I
only have 1G of RAM on my x86_64, so I'm no help.)
First off, have you pinged David Miller (davem at davemloft.net)? He seems to
have the DMA API tattooed on a body part, I think.
Larry Finger wrote:
> I am trying to debug a bcm43xx DMA problem on an x86_64 system with 3 GB
> RAM. Depending on the particular chip and its implementation, dma
> transfers may use 64-, 32-, or 30-bit addressing, with the problem
> interface using 30-bit addressing. From test prints, the correct mask
> (0x3FFFFFFF) is supplied to pci_set_dma_mask and
> pci_set_consistent_dma_mask. Neither call returns an error. In addition,
> several x86_64 systems with more than 1 GB RAM have worked with the
> current code.
>
> If the system is booted with mem=1024M on the command line, it operates
> normally; however, it gets a kernel NULL pointer dereference and panics
> when booted with either 2 or 3 GB RAM.
Confused. As in, once the bcm43xx module initcall happens? Or without bcm43xx
at all? If the former, is the behavior different when built as a module versus
built-in? (ie, are there ordering problems.)
> The config parameters in the processor section are as follows:
>
> CONFIG_X86_64=y
> CONFIG_64BIT=y
> CONFIG_X86=y
> CONFIG_ZONE_DMA32=y
> CONFIG_LOCKDEP_SUPPORT=y
> CONFIG_STACKTRACE_SUPPORT=y
> CONFIG_SEMAPHORE_SLEEPERS=y
> CONFIG_MMU=y
> CONFIG_RWSEM_GENERIC_SPINLOCK=y
> CONFIG_GENERIC_HWEIGHT=y
> CONFIG_GENERIC_CALIBRATE_DELAY=y
> CONFIG_X86_CMPXCHG=y
> CONFIG_EARLY_PRINTK=y
> CONFIG_GENERIC_ISA_DMA=y
> CONFIG_GENERIC_IOMAP=y
> CONFIG_ARCH_MAY_HAVE_PC_FDC=y
> CONFIG_ARCH_POPULATES_NODE_MAP=y
> CONFIG_DMI=y
> CONFIG_AUDIT_ARCH=y
> CONFIG_DEFCONFIG_LIST="/lib/modules/$UNAME_RELEASE/.config"
>
> I would appreciate any tips on debugging this problem. Are there any
> quantities that should be dumped, etc?
Adrian Bunk wrote:
>> That said, /proc/interrupts doesn't show MSI routed things on my AMD64 laptop.
>> ...
>
> If there is any interrupt related problem involved, it should be visible
> from dmesg.
This was useful, thanks. There were other differences I should have looked at.
I'd added noapic to rc5 to avoid problems you'll see in rc3's boot log below.
> Can you send the complete dmesg's from -rc3, -rc5 and -rc6?
I don't have rc6 compiled yet (sorry -- didn't want that to hold me up any
longer on this message), but pulling dmesg from boot logs of rc3 versus rc5,
the diff is shows that one had the apic enabled, the other didn't. So the
interrupt routing did change, with rc5 (the problematic kernel) having the
apic disabled.
There's still debate over whether this is a locking problem or something else,
so the following may just send everyone off the wrong direction.
In the meantime, I'm offline for travel through Tuesday evening.
--- rc3-diffable 2006-11-20 21:53:50.000000000 -0800
+++ rc5-diffable 2006-11-20 21:53:43.000000000 -0800
@@ -1,10 +1,10 @@
restart.
- Inspecting /boot/System.map-2.6.19-rc3
- Loaded 25288 symbols from /boot/System.map-2.6.19-rc3.
+ Inspecting /boot/System.map-2.6.19-rc5
+ Loaded 25298 symbols from /boot/System.map-2.6.19-rc5.
Symbols match kernel version 2.6.19.
No module symbols loaded - kernel modules not enabled.
- Linux version 2.6.19-rc3 (ray@phoenix) (gcc version 4.1.2 20060928
(prerelease) (Ubuntu 4.1.1-13ubuntu5)) #3 PREEMPT Sat Oct 28 13:50:27 PDT 2006
- Command line: root=UUID=bf7dc35f-5eff-4a85-b398-590f37c5679e ro quiet splash
+ Linux version 2.6.19-rc5 (ray@phoenix) (gcc version 4.1.2 20060928
(prerelease) (Ubuntu 4.1.1-13ubuntu5)) #1 PREEMPT Thu Nov 9 21:25:32 PST 2006
+ Command line: root=UUID=bf7dc35f-5eff-4a85-b398-590f37c5679e ro noapic
BIOS-provided physical RAM map:
BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
@@ -32,24 +32,21 @@
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled)
Processor #0 (Bootup-CPU)
ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
- ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0])
- IOAPIC[0]: apic_id 1, address 0xfec00000, GSI 0-23
- ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
- ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 21 low level)
- Setting APIC routing to flat
- Using ACPI (MADT) for SMP configuration information
+ ACPI: Skipping IOAPIC probe due to 'noapic' option.
+ arch/x86_64/mm/init.c:145: bad pte ffff810001c58fe8(80000000fec01173).
Nosave address range: 000000000009f000 - 00000000000a0000
Nosave address range: 00000000000a0000 - 00000000000e0000
Nosave address range: 00000000000e0000 - 0000000000100000
Allocating PCI resources starting at 50000000 (gap: 40000000:a0000000)
- Built 1 zonelists. Total pages: 224075
- Kernel command line: root=UUID=bf7dc35f-5eff-4a85-b398-590f37c5679e ro quiet
splash
+ Built 1 zonelists. Total pages: 224073
+ Kernel command line: root=UUID=bf7dc35f-5eff-4a85-b398-590f37c5679e ro noapic
Initializing CPU#0
PID hash table entries: 4096 (order: 12, 32768 bytes)
time.c: Using 3.579545 MHz WALL PM GTOD PIT/TSC timer.
- time.c: Detected 2194.547 MHz processor.
+ time.c: Detected 2194.622 MHz processor.
Console: colour VGA+ 80x25
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
+ 1.6.9 accepting connections at 2208...
... MAX_LOCKDEP_SUBCLASSES: 8
... MAX_LOCK_DEPTH: 30
... MAX_LOCKDEP_KEYS: 2048
@@ -62,11 +59,11 @@
Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
Checking aperture...
- CPU 0: aperture @ 838c000000 size 32 MB
+ CPU 0: aperture @ c048000000 size 32 MB
Aperture too small (32 MB)
No AGP bridge found
- Memory: 887264k/917312k available (2275k kernel code, 29428k reserved, 1621k
data, 200k init)
- Calibrating delay using timer specific routine.. 4392.30 BogoMIPS (lpj=2196151)
+ Memory: 887256k/917312k available (2278k kernel code, 29436k reserved, 1623k
data, 200k init)
+ Calibrating delay using timer specific routine.. 4392.21 BogoMIPS (lpj=2196106)
Security Framework v1.0.0 initialized
SELinux: Disabled at boot.
Mount-cache hash table entries: 256
@@ -79,12 +76,13 @@
Table [DSDT](id 0006) - 953 Objects with 106 Devices 297 Methods 26 Regions
Parsing all Control Methods:
Table [SSDT](id 0004) - 8 Objects with 0 Devices 6 Methods 0 Regions
- ACPI Namespace successfully loaded at root ffffffff809be7c0
+ ACPI Namespace successfully loaded at root ffffffff809c07c0
+ ACPI: setting ELCR to 0200 (from 0e20)
evxfevnt-0089 [02] enable : Transition to ACPI mode successful
Using local APIC timer interrupts.
- result 12469039
- Detected 12.469 MHz APIC timer.
- testing NMI watchdog ... OK.
+ result 0
+ Detected 0.000 MHz APIC timer.
+ testing NMI watchdog ... CPU#0: NMI appears to be stuck (0->0)!
checking if image is initramfs... it is
Freeing initrd memory: 6884k freed
NET: Registered protocol family 16
@@ -98,24 +96,23 @@
Initializing Device/Processor/Thermal objects by executing _INI methods:......
Executed 6 _INI methods requiring 2 _STA executions (examined 113 objects)
ACPI: Interpreter enabled
- ACPI: Using IOAPIC for interrupt routing
+ ACPI: Using PIC for interrupt routing
ACPI: PCI Root Bridge [C047] (0000:00)
ACPI: Assume root bridge [\_SB_.C047] bus is 0
PCI: Ignoring BAR0-3 of IDE controller 0000:00:14.1
PCI: Transparent bridge - 0000:00:14.4
PCI: Bus #03 (-#06) is hidden behind transparent bridge #02 (-#03) (try
'pci=assign-busses')
Please report the result to linux-kernel to fix this permanently
- 1.6.9 accepting connections at 2208...
ACPI: Power Resource [C1D3] (off)
ACPI: Power Resource [C1BB] (on)
ACPI: Power Resource [C1CB] (on)
- ACPI: PCI Interrupt Link [C0F0] (IRQs 10 11) *0, disabled.
- ACPI: PCI Interrupt Link [C0F1] (IRQs 10 11) *0, disabled.
+ ACPI: PCI Interrupt Link [C0F0] (IRQs *10 11)
+ ACPI: PCI Interrupt Link [C0F1] (IRQs 10 11) *5
ACPI: PCI Interrupt Link [C0F2] (IRQs 10 11) *0, disabled.
- ACPI: PCI Interrupt Link [C0F3] (IRQs 10 11) *0, disabled.
- ACPI: PCI Interrupt Link [C0F4] (IRQs 10 11) *0, disabled.
- ACPI: PCI Interrupt Link [C0F5] (IRQs 9) *0, disabled.
- ACPI: PCI Interrupt Link [C0F6] (IRQs 10 11) *0, disabled.
+ ACPI: PCI Interrupt Link [C0F3] (IRQs *10 11)
+ ACPI: PCI Interrupt Link [C0F4] (IRQs 10 *11)
+ ACPI: PCI Interrupt Link [C0F5] (IRQs *9)
+ ACPI: PCI Interrupt Link [C0F6] (IRQs 10 11) *5
ACPI: PCI Interrupt Link [C0F7] (IRQs *10 11)
ACPI: Power Resource [C251] (off)
ACPI: Power Resource [C252] (off)
@@ -153,7 +150,8 @@
IO window: 2000-2fff
MEM window: d0000000-d05fffff
PREFETCH window: 50000000-51ffffff
- ACPI: PCI Interrupt 0000:02:04.0[A] -> GSI 20 (level, low) -> IRQ 20
+ ACPI: PCI Interrupt Link [C0F4] enabled at IRQ 11
+ ACPI: PCI Interrupt 0000:02:04.0[A] -> Link [C0F4] -> GSI 11 (level, low) ->
IRQ 11
NET: Registered protocol family 2
IP route cache hash table entries: 32768 (order: 6, 262144 bytes)
TCP established hash table entries: 32768 (order: 9, 2359296 bytes)
@@ -161,7 +159,7 @@
TCP: Hash tables configured (established 32768 bind 16384)
TCP reno registered
audit: initializing netlink socket (disabled)
- audit(1162046376.916:1): initialized
+ audit(1163383174.925:1): initialized
VFS: Disk quotas dquot_6.5.1
Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
io scheduler noop registered
@@ -172,12 +170,14 @@
assign_interrupt_mode Found MSI capability
pcie_portdrv_probe->Dev[5a37:1002] has invalid IRQ. Check vendor BIOS
assign_interrupt_mode Found MSI capability
+ Started up.
aer: probe of 0000:00:04.0:pcie01 failed with error 1
aer: probe of 0000:00:05.0:pcie01 failed with error 1
Real Time Clock Driver v1.12ac
Linux agpgart interface v0.101 (c) Dave Jones
Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing enabled
- ACPI: PCI Interrupt 0000:00:14.6[B] -> GSI 17 (level, low) -> IRQ 17
+ ACPI: PCI Interrupt Link [C0F1] enabled at IRQ 10
+ ACPI: PCI Interrupt 0000:00:14.6[B] -> Link [C0F1] -> GSI 10 (level, low) ->
IRQ 10
ACPI: PCI interrupt for device 0000:00:14.6 disabled
RAMDISK driver initialized: 16 RAM disks of 65536K size 1024 blocksize
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
@@ -198,8 +198,6 @@
drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
Freeing unused kernel memory: 200k freed
input: AT Translated Set 2 keyboard as /class/input/input0
- vga16fb: mapped to 0xffff8100000a0000
- fb0: VGA16 VGA frame buffer device
ACPI: Transitioning device [C255] to D3
ACPI: Transitioning device [C255] to D3
ACPI: Fan [C255] (off)
@@ -214,12 +212,13 @@
ACPI: Fan [C258] (off)
ACPI: CPU0 (power states: C1[C1] C3[C3])
ACPI: Processor [C000] (supports 8 throttling states)
- ACPI: Thermal Zone [TZ1] (77 C)
- ACPI: Thermal Zone [TZ2] (60 C)
- ACPI: Thermal Zone [TZ3] (30 C)
- ACPI: Thermal Zone [TZ4] (34 C)
+ ACPI: Thermal Zone [TZ1] (72 C)
+ ACPI: Thermal Zone [TZ2] (53 C)
+ ACPI: Thermal Zone [TZ3] (31 C)
+ ACPI: Thermal Zone [TZ4] (39 C)
ATIIXP: IDE controller at PCI slot 0000:00:14.1
- ACPI: PCI Interrupt 0000:00:14.1[A] -> GSI 16 (level, low) -> IRQ 16
+ ACPI: PCI Interrupt Link [C0F0] enabled at IRQ 10
+ ACPI: PCI Interrupt 0000:00:14.1[A] -> Link [C0F0] -> GSI 10 (level, low) ->
IRQ 10
ATIIXP: chipset revision 0
ATIIXP: not 100%% native mode: will probe irqs later
ide0: BM-DMA at 0x4010-0x4017, BIOS settings: hda:DMA, hdb:pio
@@ -237,121 +236,96 @@
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
- ACPI: PCI Interrupt 0000:00:13.0[A] -> GSI 19 (level, low) -> IRQ 19
+ ACPI: PCI Interrupt Link [C0F3] enabled at IRQ 10
+ ACPI: PCI Interrupt 0000:00:13.0[A] -> Link [C0F3] -> GSI 10 (level, low) ->
IRQ 10
ohci_hcd 0000:00:13.0: OHCI Host Controller
ohci_hcd 0000:00:13.0: new USB bus registered, assigned bus number 1
- ohci_hcd 0000:00:13.0: irq 19, io mem 0xd0a00000
+ ohci_hcd 0000:00:13.0: irq 10, io mem 0xd0a00000
usb usb1: configuration #1 chosen from 1 choice
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 4 ports detected
- ACPI: PCI Interrupt 0000:00:13.2[A] -> GSI 19 (level, low) -> IRQ 19
+ ACPI: PCI Interrupt 0000:00:13.2[A] -> Link [C0F3] -> GSI 10 (level, low) ->
IRQ 10
ehci_hcd 0000:00:13.2: EHCI Host Controller
ehci_hcd 0000:00:13.2: new USB bus registered, assigned bus number 2
- ehci_hcd 0000:00:13.2: irq 19, io mem 0xd0a02000
+ ehci_hcd 0000:00:13.2: irq 10, io mem 0xd0a02000
ehci_hcd 0000:00:13.2: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
usb usb2: configuration #1 chosen from 1 choice
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 8 ports detected
- ACPI: PCI Interrupt 0000:02:04.2[C] -> GSI 21 (level, low) -> IRQ 21
- ACPI: PCI Interrupt 0000:00:13.1[A] -> GSI 19 (level, low) -> IRQ 19
+ ACPI: PCI Interrupt Link [C0F5] enabled at IRQ 9
+ ACPI: PCI Interrupt 0000:02:04.2[C] -> Link [C0F5] -> GSI 9 (level, low) ->
IRQ 9
+ ACPI: PCI Interrupt 0000:00:13.1[A] -> Link [C0F3] -> GSI 10 (level, low) ->
IRQ 10
ohci_hcd 0000:00:13.1: OHCI Host Controller
ohci_hcd 0000:00:13.1: new USB bus registered, assigned bus number 3
- ohci_hcd 0000:00:13.1: irq 19, io mem 0xd0a01000
- ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[21] MMIO=[d0013000-d00137ff]
Max Packet=[2048] IR/IT contexts=[4/8]
+ ohci_hcd 0000:00:13.1: irq 10, io mem 0xd0a01000
+ ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[9] MMIO=[d0013000-d00137ff]
Max Packet=[2048] IR/IT contexts=[4/8]
usb usb3: configuration #1 chosen from 1 choice
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 4 ports detected
Attempting manual resume
- kjournald starting. Commit interval 5 seconds
- EXT3-fs: mounted filesystem with writeback data mode.
+ EXT3-fs: INFO: recovery required on readonly filesystem.
+ EXT3-fs: write access will be enabled during recovery.
usb 3-1: new full speed USB device using ohci_hcd and address 2
usb 3-1: configuration #1 chosen from 1 choice
- Started up.
usb 1-2: new full speed USB device using ohci_hcd and address 2
usb 1-2: configuration #1 chosen from 1 choice
-
- Call Trace:
- [dump_trace+185/992] dump_trace+0xb9/0x3e0
- [show_trace+67/96] show_trace+0x43/0x60
- [dump_stack+21/32] dump_stack+0x15/0x20
- [__report_bad_irq+56/144] __report_bad_irq+0x38/0x90
- [note_interrupt+561/640] note_interrupt+0x231/0x280
- [handle_fasteoi_irq+167/224] handle_fasteoi_irq+0xa7/0xe0
- [do_IRQ+113/192] do_IRQ+0x71/0xc0
- [ret_from_intr+0/15] ret_from_intr+0x0/0xf
- DWARF2 unwinder stuck at ret_from_intr+0x0/0xf
-
- Leftover inexact backtrace:
-
- <IRQ> <EOI> [_end+123922454/2126640872] :processor:acpi_safe_halt+0x2c/0x40
- [_end+123922456/2126640872] :processor:acpi_safe_halt+0x2e/0x40
- [_end+123922454/2126640872] :processor:acpi_safe_halt+0x2c/0x40
- [_end+123922995/2126640872] :processor:acpi_processor_idle+0x181/0x402
- [atomic_notifier_call_chain+69/112] atomic_notifier_call_chain+0x45/0x70
- [_end+123922610/2126640872] :processor:acpi_processor_idle+0x0/0x402
- [cpu_idle+78/144] cpu_idle+0x4e/0x90
- [rest_init+58/64] rest_init+0x3a/0x40
- [start_kernel+607/624] start_kernel+0x25f/0x270
- [x86_64_start_kernel+329/336] _sinittext+0x149/0x150
-
- warning: process `ckbcomp' used the removed sysctl system call
- input: PC Speaker as /class/input/input1
+ kjournald starting. Commit interval 5 seconds
+ EXT3-fs: recovery complete.
+ EXT3-fs: mounted filesystem with writeback data mode.
pci_hotplug: PCI Hot Plug PCI Core version: 0.5
- sdhci: Secure Digital Host Controller Interface driver, 0.12
- sdhci: Copyright(c) Pierre Ossman
- sdhci: SDHCI controller found at 0000:02:04.4 [104c:8034] (rev 0)
- ACPI: PCI Interrupt 0000:02:04.4[C] -> GSI 21 (level, low) -> IRQ 21
- mmc0: SDHCI at 0xd001a000 irq 21 DMA
- mmc1: SDHCI at 0xd001b000 irq 21 DMA
- mmc2: SDHCI at 0xd001c000 irq 21 DMA
- ACPI: PCI Interrupt 0000:02:04.3[B] -> GSI 21 (level, low) -> IRQ 21
shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
+ ACPI: PCI Interrupt 0000:00:14.6[B] -> Link [C0F1] -> GSI 10 (level, low) ->
IRQ 10
+ MC'97 0 converters and GPIO not ready (0x1)
Yenta: CardBus bridge found at 0000:02:04.0 [103c:308b]
Yenta: Enabling burst memory read transactions
Yenta: Using INTVAL to route CSC interrupts to PCI
Yenta: Routing CardBus interrupts to PCI
Yenta TI: socket 0000:02:04.0, mfunc 0x01a11b22, devctl 0x64
- parport: PnPBIOS parport detected.
- parport0: PC-style at 0x378 (0x778), irq 7, dma 1
[PCSPP,TRISTATE,COMPAT,ECP,DMA]
ieee80211: 802.11 data/management/control stack, git-1.1.13
ieee80211: Copyright (C) 2004-2005 Intel Corporation <[email protected]>
- bcm43xx driver
- Yenta: ISA IRQ mask 0x0c78, PCI irq 20
+ sdhci: Secure Digital Host Controller Interface driver, 0.12
+ sdhci: Copyright(c) Pierre Ossman
+ input: PC Speaker as /class/input/input1
+ Yenta: ISA IRQ mask 0x00f8, PCI irq 11
Socket status: 30000006
Yenta: Raising subordinate bus# of parent bus (#02) from #03 to #06
pcmcia: parent PCI bridge I/O window: 0x2000 - 0x2fff
pcmcia: parent PCI bridge Memory window: 0xd0000000 - 0xd05fffff
pcmcia: parent PCI bridge Memory window: 0x50000000 - 0x51ffffff
- ACPI: PCI Interrupt 0000:02:02.0[A] -> GSI 22 (level, low) -> IRQ 22
- ACPI: PCI Interrupt 0000:00:14.5[B] -> GSI 17 (level, low) -> IRQ 17
- PCI: Enabling device 0000:00:14.6 (0000 -> 0002)
- ACPI: PCI Interrupt 0000:00:14.6[B] -> GSI 17 (level, low) -> IRQ 17
- MC'97 0 converters and GPIO not ready (0x1)
- piix4_smbus 0000:00:14.0: Found 0000:00:14.0 device
- tg3.c:v3.67 (October 18, 2006)
- ACPI: PCI Interrupt 0000:02:01.0[A] -> GSI 23 (level, low) -> IRQ 23
- eth1: Tigon3 [partno(BCM95788A50) rev 3003 PHY(5705)] (PCI:33MHz:32-bit)
10/100/1000BaseT Ethernet 00:0f:b0:bb:bc:f8
- eth1: RXcsums[1] LinkChgREG[0] MIirq[0] ASF[0] Split[0] WireSpeed[0] TSOcap[1]
- eth1: dma_rwctrl[763f0000] dma_mask[32-bit]
+ sdhci: SDHCI controller found at 0000:02:04.4 [104c:8034] (rev 0)
+ ACPI: PCI Interrupt 0000:02:04.4[C] -> Link [C0F5] -> GSI 9 (level, low) ->
IRQ 9
+ mmc0: SDHCI at 0xd001a000 irq 9 DMA
+ mmc1: SDHCI at 0xd001b000 irq 9 DMA
+ mmc2: SDHCI at 0xd001c000 irq 9 DMA
+ ACPI: PCI Interrupt 0000:02:04.3[B] -> Link [C0F5] -> GSI 9 (level, low) ->
IRQ 9
+ ACPI: PCI Interrupt 0000:00:14.5[B] -> Link [C0F1] -> GSI 10 (level, low) ->
IRQ 10
+ tg3.c:v3.68 (November 02, 2006)
+ ACPI: PCI Interrupt Link [C0F7] enabled at IRQ 10
+ ACPI: PCI Interrupt 0000:02:01.0[A] -> Link [C0F7] -> GSI 10 (level, low) ->
IRQ 10
+ eth0: Tigon3 [partno(BCM95788A50) rev 3003 PHY(5705)] (PCI:33MHz:32-bit)
10/100/1000BaseT Ethernet 00:0f:b0:bb:bc:f8
+ eth0: RXcsums[1] LinkChgREG[0] MIirq[0] ASF[0] Split[0] WireSpeed[0] TSOcap[1]
+ eth0: dma_rwctrl[763f0000] dma_mask[32-bit]
+ parport: PnPBIOS parport detected.
+ parport0: PC-style at 0x378 (0x778), irq 7, dma 1
[PCSPP,TRISTATE,COMPAT,ECP,DMA]
Bluetooth: Core ver 2.11
NET: Registered protocol family 31
Bluetooth: HCI device and connection manager initialized
Bluetooth: HCI socket layer initialized
- Synaptics Touchpad, model: 1, fw: 6.2, id: 0x1a0b1, caps: 0xa04713/0x200000
- input: SynPS/2 Synaptics TouchPad as /class/input/input2
Bluetooth: HCI USB driver ver 2.9
- usbcore: registered new interface driver hci_usb
- warning: process `alsactl' used the removed sysctl system call
- warning: process `alsactl' used the removed sysctl system call
- warning: process `alsactl' used the removed sysctl system call
SCSI subsystem initialized
- warning: process `amixer' used the removed sysctl system call
+ piix4_smbus 0000:00:14.0: Found 0000:00:14.0 device
+ bcm43xx driver
+ ACPI: PCI Interrupt Link [C0F6] enabled at IRQ 11
+ ACPI: PCI Interrupt 0000:02:02.0[A] -> Link [C0F6] -> GSI 11 (level, low) ->
IRQ 11
+ Synaptics Touchpad, model: 1, fw: 6.2, id: 0x1a0b1, caps: 0xa04713/0x200000
+ usbcore: registered new interface driver hci_usb
+ input: SynPS/2 Synaptics TouchPad as /class/input/input2
lp0: using parport0 (interrupt-driven).
ieee1394: sbp2: Driver forced to serialize I/O (serialize_io=1)
ieee1394: sbp2: Try serialize_io=0 for better performance
Adding 1116476k swap on
/dev/disk/by-uuid/45b6bcfd-44ec-4878-8110-f2164f9e8051. Priority:-1 extents:1
across:1116476k
- EXT3 FS on hda2, internal journal
NET: Registered protocol family 17
+ EXT3 FS on hda2, internal journal
device-mapper: ioctl: 4.10.0-ioctl (2006-09-14) initialised: [email protected]
device-mapper: ioctl: error adding target to table
device-mapper: ioctl: error adding target to table
@@ -382,13 +356,11 @@
powernow-k8: 4 : fid 0x0 (800 MHz), vid 0x16
NET: Registered protocol family 10
lo: Disabled Privacy Extensions
- ADDRCONF(NETDEV_UP): eth1: link is not ready
ADDRCONF(NETDEV_UP): eth0: link is not ready
+ ADDRCONF(NETDEV_UP): eth1: link is not ready
Capability LSM initialized
- SoftMAC: Open Authentication completed with 00:06:25:60:b6:81
+ SoftMAC: Open Authentication completed with 00:11:50:3c:6c:2f
ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
- device eth0 entered promiscuous mode
- audit(1162071626.136:2): dev=eth0 prom=256 old_prom=0 auid=4294967295
Bluetooth: L2CAP ver 2.8
Bluetooth: L2CAP socket layer initialized
Bluetooth: RFCOMM socket layer initialized
Larry Finger <[email protected]> writes:
> I am trying to debug a bcm43xx DMA problem on an x86_64 system with 3
> GB RAM. Depending on the particular chip and its implementation, dma
> transfers may use 64-, 32-, or 30-bit addressing, with the problem
> interface using 30-bit addressing. From test prints, the correct mask
> (0x3FFFFFFF) is supplied to pci_set_dma_mask and
> pci_set_consistent_dma_mask. Neither call returns an error. In
> addition, several x86_64 systems with more than 1 GB RAM have worked
> with the current code.
30bit DMA has be bounced through GFP_DMA. The driver needs special
code for this. You can look at the b44 driver for a working reference.
The pci_dma_* interfaces on x86-64 only support masks >= 0xffffffff,
anything smaller has to be handled manually.
-Andi
> Confused. As in, once the bcm43xx module initcall happens? Or without bcm43xx
> at all? If the former, is the behavior different when built as a module versus
> built-in? (ie, are there ordering problems.)
The pci_dma code on the x86_64 platform is broken for the case of PCI
devices with < 32bit DMA. Has been forever, this is a problem with
various devices, although most of the others are obsolete except for the
bcm43xx and b44 (the latter has hacks to work around the x86-64
brokenness).
At the very least the pci_set_dma_mask should error in this situation or
switch to using GFP_DMA (24bit) memory spaces. Having it error isn't the
whole solution as you still need some way to handle the "what do I do
next".
Alan
Alan wrote:
>> Confused. As in, once the bcm43xx module initcall happens? Or without bcm43xx
>> at all? If the former, is the behavior different when built as a module versus
>> built-in? (ie, are there ordering problems.)
>
> The pci_dma code on the x86_64 platform is broken for the case of PCI
> devices with < 32bit DMA. Has been forever, this is a problem with
> various devices, although most of the others are obsolete except for the
> bcm43xx and b44 (the latter has hacks to work around the x86-64
> brokenness).
>
> At the very least the pci_set_dma_mask should error in this situation or
> switch to using GFP_DMA (24bit) memory spaces. Having it error isn't the
> whole solution as you still need some way to handle the "what do I do
> next".
I agree that pci_set_dma_mask should at least return an error. That will protect the ignorant!
Thanks for the pointer to the b44 code. I'll try to fix bcm43xx the same way.
Larry
Andi Kleen wrote:
> Larry Finger <[email protected]> writes:
>
>> I am trying to debug a bcm43xx DMA problem on an x86_64 system with 3
>> GB RAM. Depending on the particular chip and its implementation, dma
>> transfers may use 64-, 32-, or 30-bit addressing, with the problem
>> interface using 30-bit addressing. From test prints, the correct mask
>> (0x3FFFFFFF) is supplied to pci_set_dma_mask and
>> pci_set_consistent_dma_mask. Neither call returns an error. In
>> addition, several x86_64 systems with more than 1 GB RAM have worked
>> with the current code.
>
> 30bit DMA has be bounced through GFP_DMA. The driver needs special
> code for this. You can look at the b44 driver for a working reference.
>
> The pci_dma_* interfaces on x86-64 only support masks >= 0xffffffff,
> anything smaller has to be handled manually.
Thanks for the info. I obviously get to devote some effort to seeing how the b44 code handles the
same problem.
Shouldn't this problem be mentioned somewhere in the documentation, or did I miss something?
Larry
> Shouldn't this problem be mentioned somewhere in the documentation, or did I miss something?
Possibly, but devices that cannot address at least 4GB are normally
categorized as "hardware bugs" (or less polite descriptions) and those don't
tend to get much airtime in documentation.
-Andi
On Tue, 21 Nov 2006 17:46:39 +0100
Andi Kleen <[email protected]> wrote:
>
> > Shouldn't this problem be mentioned somewhere in the documentation, or did I miss something?
The documentation is correct, the implementation is broken. The
documented behaviour works for all platforms except one whose maintainer
has a problem with it and refuses to follow the spec.
> Possibly, but devices that cannot address at least 4GB are normally
> categorized as "hardware bugs" (or less polite descriptions) and those don't
> tend to get much airtime in documentation.
The rest of the kernel deals with hardware limitations, 30bit DMA works
on the other platforms. This is an x86-64 platform problem. It
misimplements the basic pci_ functionality. If it doesn't wish to
implement the stuff (and there btw Andi I do think your view has
considerable merit) it should fail the set_mask requests.
Alan
> The documentation is correct, the implementation is broken. The
> documented behaviour works for all platforms except one whose maintainer
> has a problem with it and refuses to follow the spec.
The reference is still what i386 does.
> > Possibly, but devices that cannot address at least 4GB are normally
> > categorized as "hardware bugs" (or less polite descriptions) and those don't
> > tend to get much airtime in documentation.
>
> The rest of the kernel deals with hardware limitations,
Yes, but you don't find it normally in the documentation, just
in some very dark corners of the code.
> 30bit DMA works
> on the other platforms. This is an x86-64 platform problem. It
> misimplements the basic pci_ functionality.
Well, if you claim that then i386 misimplements it too.
Normally people don't hit it on 32bit because with the default user/kernel split
the limit is 900MB, which tends to be ok for most hardware. But you
could easily hit it with non standard __PAGE_OFFSET as it is now
possible to configure.
I claim x86-64 is bug to bug compatible to i386 as far as possible.
Since that is what drivers are typically written for it's the most
important specification.
> If it doesn't wish to
> implement the stuff (and there btw Andi I do think your view has
> considerable merit) it should fail the set_mask requests.
If it did like you're recommending a huge number of drivers
in the tree wouldn't work anymore (just think about what pci_alloc_consistent
does)
I have a long term master plan to merge GFP_DMA and swiotlb
into a single pool -- if that ever happens it might be possible
to fix it properly. But probably most of the drivers who needed
it wouldn't work anyways because they typically tend to forget
enough *_sync calls to make software bounce buffering work.
-Andi
> If it did like you're recommending a huge number of drivers
> in the tree wouldn't work anymore (just think about what pci_alloc_consistent
> does)
There are very few drivers who actually request less than 32bit DMA
and those would (and should) fail or be forced to do their own fallbacks.
Alan
Hey all, more data on my bcm43xx problem report from a few weeks back.
By random chance I acquired a brain, and decided to rebuild my latest kernel
pull with as many debugging options on as I could stand. Got the below, plus
a dead keyboard (except for Magic SysRq) (but only if I let userspace come up
fully -- booting with init=/bin/bash is fine). Since the trace below mentions
scans, I'm hoping it's related to my problem.
In other news, now that I've moved my laptop back to my home office, I'm able
to recreate the dead-keyboard lockups I've been having again, about once every
day or two. What fun. So if there are patches I should try ontop of the latest
git, let me know. (Though I'm hoping the below will be a smoking gun to someone
who has a clue, i.e., not me.)
Ray
Dec 11 19:34:18 phoenix syslogd 1.4.1#18ubuntu6: restart.
Dec 11 19:34:18 phoenix kernel: Inspecting /boot/System.map-2.6.19
Dec 11 19:34:19 phoenix kernel: Loaded 26330 symbols from /boot/System.map-2.6.19.
Dec 11 19:34:19 phoenix kernel: Symbols match kernel version 2.6.19.
Dec 11 19:34:19 phoenix kernel: No module symbols loaded - kernel modules not enabled.
Dec 11 19:34:19 phoenix kernel: [ 0.000000] Linux version 2.6.19 (ray@phoenix) (gcc version 4.1.2 20060928 (prerelease) (Ubuntu 4.1.1-13ubuntu5)) #1 PREEMPT Mon Dec 11 12:52:41 PST 2006
Dec 11 19:34:19 phoenix kernel: [ 0.000000] Command line: root=UUID=bf7dc35f-5eff-4a85-b398-590f37c5679e ro noapic
Dec 11 19:34:19 phoenix kernel: [ 0.000000] BIOS-provided physical RAM map:
Dec 11 19:34:19 phoenix kernel: [ 0.000000] BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
Dec 11 19:34:19 phoenix kernel: [ 0.000000] BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
Dec 11 19:34:19 phoenix kernel: [ 0.000000] BIOS-e820: 00000000000e0000 - 0000000000100000 (reserved)
Dec 11 19:34:20 phoenix kernel: [ 0.000000] BIOS-e820: 0000000000100000 - 0000000037fd0000 (usable)
Dec 11 19:34:21 phoenix kernel: [ 0.000000] BIOS-e820: 0000000037fd0000 - 0000000037fefc00 (reserved)
Dec 11 19:34:21 phoenix kernel: [ 0.000000] BIOS-e820: 0000000037fefc00 - 0000000037ffb000 (ACPI NVS)
Dec 11 19:34:21 phoenix kernel: [ 0.000000] BIOS-e820: 0000000037ffb000 - 0000000040000000 (reserved)
Dec 11 19:34:21 phoenix kernel: [ 0.000000] BIOS-e820: 00000000e0000000 - 00000000f0000000 (reserved)
Dec 11 19:34:21 phoenix kernel: [ 0.000000] BIOS-e820: 00000000fec00000 - 00000000fec02000 (reserved)
Dec 11 19:34:21 phoenix kernel: [ 0.000000] BIOS-e820: 00000000ffb80000 - 00000000ffc00000 (reserved)
Dec 11 19:34:21 phoenix kernel: [ 0.000000] BIOS-e820: 00000000fff80000 - 0000000100000000 (reserved)
Dec 11 19:34:21 phoenix kernel: [ 0.000000] end_pfn_map = 1048576
Dec 11 19:34:21 phoenix kernel: [ 0.000000] DMI 2.3 present.
Dec 11 19:34:23 phoenix kernel: [ 0.000000] No mptable found.
Dec 11 19:34:23 phoenix kernel: [ 0.000000] Zone PFN ranges:
Dec 11 19:34:23 phoenix kernel: [ 0.000000] DMA 0 -> 4096
Dec 11 19:34:23 phoenix kernel: [ 0.000000] DMA32 4096 -> 1048576
Dec 11 19:34:24 phoenix kernel: [ 0.000000] Normal 1048576 -> 1048576
Dec 11 19:34:24 phoenix kernel: [ 0.000000] early_node_map[2] active PFN ranges
Dec 11 19:34:24 phoenix kernel: [ 0.000000] 0: 0 -> 159
Dec 11 19:34:24 phoenix kernel: [ 0.000000] 0: 256 -> 229328
Dec 11 19:34:24 phoenix hpiod: 1.6.9 accepting connections at 2208...
Dec 11 19:34:25 phoenix kernel: [ 0.000000] ACPI: PM-Timer IO Port: 0x8008
Dec 11 19:34:25 phoenix kernel: [ 0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled)
Dec 11 19:34:25 phoenix kernel: [ 0.000000] Processor #0 (Bootup-CPU)
Dec 11 19:34:25 phoenix kernel: [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
Dec 11 19:34:25 phoenix kernel: [ 0.000000] ACPI: Skipping IOAPIC probe due to 'noapic' option.
Dec 11 19:34:25 phoenix kernel: [ 0.000000] arch/x86_64/mm/init.c:145: bad pte ffff810001c58fe8(80000000fec01173).
Dec 11 19:34:25 phoenix kernel: [ 0.000000] Nosave address range: 000000000009f000 - 00000000000a0000
Dec 11 19:34:25 phoenix kernel: [ 0.000000] Nosave address range: 00000000000a0000 - 00000000000e0000
Dec 11 19:34:25 phoenix kernel: [ 0.000000] Nosave address range: 00000000000e0000 - 0000000000100000
Dec 11 19:34:25 phoenix kernel: [ 0.000000] Allocating PCI resources starting at 50000000 (gap: 40000000:a0000000)
Dec 11 19:34:25 phoenix kernel: [ 0.000000] Built 1 zonelists. Total pages: 223940
Dec 11 19:34:25 phoenix kernel: [ 0.000000] Kernel command line: root=UUID=bf7dc35f-5eff-4a85-b398-590f37c5679e ro noapic
Dec 11 19:34:25 phoenix kernel: [ 0.000000] Initializing CPU#0
Dec 11 19:34:25 phoenix kernel: [ 0.000000] PID hash table entries: 4096 (order: 12, 32768 bytes)
Dec 11 19:34:25 phoenix kernel: [ 13.705535] time.c: Using 3.579545 MHz WALL PM GTOD PIT/TSC timer.
Dec 11 19:34:25 phoenix kernel: [ 13.705537] time.c: Detected 2194.592 MHz processor.
Dec 11 19:34:25 phoenix kernel: [ 13.711138] Console: colour VGA+ 80x25
Dec 11 19:34:25 phoenix kernel: [ 13.713451] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
Dec 11 19:34:25 phoenix kernel: [ 13.713539] ... MAX_LOCKDEP_SUBCLASSES: 8
Dec 11 19:34:25 phoenix kernel: [ 13.713597] ... MAX_LOCK_DEPTH: 30
Dec 11 19:34:25 phoenix kernel: [ 13.713655] ... MAX_LOCKDEP_KEYS: 2048
Dec 11 19:34:25 phoenix kernel: [ 13.713713] ... CLASSHASH_SIZE: 1024
Dec 11 19:34:25 phoenix kernel: [ 13.713771] ... MAX_LOCKDEP_ENTRIES: 8192
Dec 11 19:34:25 phoenix kernel: [ 13.713828] ... MAX_LOCKDEP_CHAINS: 16384
Dec 11 19:34:25 phoenix kernel: [ 13.713886] ... CHAINHASH_SIZE: 8192
Dec 11 19:34:26 phoenix kernel: [ 13.713944] memory used by lock dependency info: 1584 kB
Dec 11 19:34:26 phoenix kernel: [ 13.714003] per task-struct memory footprint: 1680 bytes
Dec 11 19:34:26 phoenix kernel: [ 13.715083] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
Dec 11 19:34:26 phoenix kernel: [ 13.715971] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
Dec 11 19:34:26 phoenix kernel: [ 13.716128] Checking aperture...
Dec 11 19:34:26 phoenix kernel: [ 13.716187] CPU 0: aperture @ e04a000000 size 32 MB
Dec 11 19:34:26 phoenix kernel: [ 13.716246] Aperture too small (32 MB)
Dec 11 19:34:26 phoenix kernel: [ 13.728439] No AGP bridge found
Dec 11 19:34:26 phoenix kernel: [ 13.743894] Memory: 875716k/917312k available (2352k kernel code, 40852k reserved, 1749k data, 200k init)
Dec 11 19:34:26 phoenix kernel: [ 13.803377] Calibrating delay using timer specific routine.. 4392.18 BogoMIPS (lpj=2196094)
Dec 11 19:34:26 phoenix kernel: [ 13.803975] Security Framework v1.0.0 initialized
Dec 11 19:34:26 phoenix kernel: [ 13.804041] SELinux: Disabled at boot.
Dec 11 19:34:26 phoenix kernel: [ 13.804231] Mount-cache hash table entries: 256
Dec 11 19:34:26 phoenix kernel: [ 13.807735] CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
Dec 11 19:34:26 phoenix kernel: [ 13.807796] CPU: L2 Cache: 1024K (64 bytes/line)
Dec 11 19:34:26 phoenix kernel: [ 13.807866] CPU: AMD Turion(tm) 64 Mobile ML-40 stepping 02
Dec 11 19:34:26 phoenix kernel: [ 13.808007] ACPI: Core revision 20060707
Dec 11 19:34:26 phoenix kernel: [ 13.808609] tbxface-0107 [01] load_tables : ACPI Tables successfully acquired
Dec 11 19:34:26 phoenix kernel: [ 13.815260] Parsing all Control Methods:
Dec 11 19:34:26 phoenix kernel: [ 13.815533] Table [DSDT](id 0006) - 953 Objects with 106 Devices 297 Methods 26 Regions
Dec 11 19:34:26 phoenix kernel: [ 13.815739] Parsing all Control Methods:
Dec 11 19:34:26 phoenix kernel: [ 13.815962] Table [SSDT](id 0004) - 8 Objects with 0 Devices 6 Methods 0 Regions
Dec 11 19:34:26 phoenix kernel: [ 13.816096] ACPI Namespace successfully loaded at root ffffffff80a52500
Dec 11 19:34:26 phoenix kernel: [ 13.816161] ACPI: setting ELCR to 0200 (from 0e20)
Dec 11 19:34:26 phoenix kernel: [ 13.849445] evxfevnt-0089 [02] enable : Transition to ACPI mode successful
Dec 11 19:34:26 phoenix kernel: [ 13.864288] Using local APIC timer interrupts.
Dec 11 19:34:26 phoenix kernel: [ 13.909867] result 0
Dec 11 19:34:26 phoenix kernel: [ 13.909924] Detected 0.000 MHz APIC timer.
Dec 11 19:34:26 phoenix kernel: [ 13.910236] testing NMI watchdog ... CPU#0: NMI appears to be stuck (0->0)!
Dec 11 19:34:26 phoenix kernel: [ 13.935758] checking if image is initramfs... it is
Dec 11 19:34:26 phoenix kernel: [ 15.418743] Freeing initrd memory: 17762k freed
Dec 11 19:34:26 phoenix kernel: [ 15.465890] NET: Registered protocol family 16
Dec 11 19:34:26 phoenix kernel: [ 15.492746] ACPI: bus type pci registered
Dec 11 19:34:26 phoenix kernel: [ 15.503568] PCI: Using MMCONFIG at e0000000
Dec 11 19:34:26 phoenix kernel: [ 15.504265] PCI: No mmconfig possible on device 00:18
Dec 11 19:34:26 phoenix kernel: [ 15.517096] evgpeblk-0951 [04] ev_create_gpe_block : GPE 00 to 1F [_GPE] 4 regs on int 0x9
Dec 11 19:34:26 phoenix kernel: [ 15.517699] evgpeblk-1048 [03] ev_initialize_gpe_bloc: Found 4 Wake, Enabled 9 Runtime GPEs in this block
Dec 11 19:34:27 phoenix kernel: [ 15.519686] Completing Region/Field/Buffer/Package
initialization:............................................................................................................
Dec 11 19:34:27 phoenix kernel: [ 15.526864] Initialized 25/26 Regions 0/0 Fields 30/30 Buffers 53/61 Packages (970 nodes)
Dec 11 19:34:27 phoenix kernel: [ 15.526996] Initializing Device/Processor/Thermal objects by executing _INI methods:......
Dec 11 19:34:27 phoenix kernel: [ 15.547491] Executed 6 _INI methods requiring 2 _STA executions (examined 113 objects)
Dec 11 19:34:27 phoenix kernel: [ 15.547644] ACPI: Interpreter enabled
Dec 11 19:34:27 phoenix kernel: [ 15.547704] ACPI: Using PIC for interrupt routing
Dec 11 19:34:27 phoenix kernel: [ 15.556017] ACPI: PCI Root Bridge [C047] (0000:00)
Dec 11 19:34:27 phoenix kernel: [ 15.560815] ACPI: Assume root bridge [\_SB_.C047] bus is 0
Dec 11 19:34:27 phoenix kernel: [ 15.578179] PCI: Transparent bridge - 0000:00:14.4
Dec 11 19:34:27 phoenix kernel: [ 15.578335] PCI: Bus #03 (-#06) is hidden behind transparent bridge #02 (-#03) (try 'pci=assign-busses')
Dec 11 19:34:27 phoenix kernel: [ 15.578417] Please report the result to linux-kernel to fix this permanently
Dec 11 19:34:28 phoenix dhcdbd: Started up.
Dec 11 19:34:29 phoenix kernel: [ 15.616016] ACPI: Power Resource [C1D3] (off)
Dec 11 19:34:29 phoenix kernel: [ 15.634482] ACPI: Power Resource [C1BB] (on)
Dec 11 19:34:29 phoenix kernel: [ 15.635496] ACPI: Power Resource [C1CB] (on)
Dec 11 19:34:29 phoenix kernel: [ 15.641079] ACPI: PCI Interrupt Link [C0F0] (IRQs *10 11)
Dec 11 19:34:29 phoenix kernel: [ 15.642080] ACPI: PCI Interrupt Link [C0F1] (IRQs 10 11) *5
Dec 11 19:34:29 phoenix kernel: [ 15.643069] ACPI: PCI Interrupt Link [C0F2] (IRQs 10 11) *0, disabled.
Dec 11 19:34:29 phoenix kernel: [ 15.644131] ACPI: PCI Interrupt Link [C0F3] (IRQs *10 11)
Dec 11 19:34:29 phoenix kernel: [ 15.645093] ACPI: PCI Interrupt Link [C0F4] (IRQs 10 *11)
Dec 11 19:34:29 phoenix kernel: [ 15.646066] ACPI: PCI Interrupt Link [C0F5] (IRQs *9)
Dec 11 19:34:29 phoenix kernel: [ 15.646988] ACPI: PCI Interrupt Link [C0F6] (IRQs 10 11) *5
Dec 11 19:34:29 phoenix kernel: [ 15.647989] ACPI: PCI Interrupt Link [C0F7] (IRQs *10 11)
Dec 11 19:34:29 phoenix kernel: [ 15.652776] ACPI: Power Resource [C251] (off)
Dec 11 19:34:29 phoenix kernel: [ 15.653084] ACPI: Power Resource [C252] (off)
Dec 11 19:34:29 phoenix kernel: [ 15.653391] ACPI: Power Resource [C253] (off)
Dec 11 19:34:29 phoenix kernel: [ 15.653729] ACPI: Power Resource [C254] (off)
Dec 11 19:34:29 phoenix kernel: [ 15.654372] Linux Plug and Play Support v0.97 (c) Adam Belay
Dec 11 19:34:29 phoenix kernel: [ 15.654455] pnp: PnP ACPI init
Dec 11 19:34:29 phoenix flow-capture[4835]: chdir(/var/flow/myrouter): No such file or directory
Dec 11 19:34:29 phoenix flow-capture[4837]: chdir(/var/flow/mysecondrouter): No such file or directory
Dec 11 19:34:29 phoenix flow-capture[4839]: chdir(/var/flow/mysecondrouter): No such file or directory
Dec 11 19:34:31 phoenix kernel: [ 15.674799] pnp: PnP ACPI: found 12 devices
Dec 11 19:34:31 phoenix kernel: [ 15.677467] SCSI subsystem initialized
Dec 11 19:34:31 phoenix kernel: [ 15.681729] PCI: Using ACPI for IRQ routing
Dec 11 19:34:31 phoenix kernel: [ 15.681788] PCI: If a device doesn't work, try "pci=routeirq". If it helps, post a report
Dec 11 19:34:32 phoenix kernel: [ 15.700020] pnp: 00:09: ioport range 0x40b-0x40b has been reserved
Dec 11 19:34:32 phoenix kernel: [ 15.700084] pnp: 00:09: ioport range 0x4d0-0x4d1 has been reserved
Dec 11 19:34:32 phoenix kernel: [ 15.700144] pnp: 00:09: ioport range 0x4d6-0x4d6 has been reserved
Dec 11 19:34:32 phoenix kernel: [ 15.700211] pnp: 00:0a: ioport range 0x8000-0x802f could not be reserved
Dec 11 19:34:32 phoenix kernel: [ 15.700272] pnp: 00:0a: ioport range 0x8100-0x811f could not be reserved
Dec 11 19:34:33 phoenix kernel: [ 15.702637] PCI: Bridge: 0000:00:01.0
Dec 11 19:34:33 phoenix kernel: [ 15.702697] IO window: 3000-3fff
Dec 11 19:34:33 phoenix kernel: [ 15.702756] MEM window: d0600000-d09fffff
Dec 11 19:34:33 phoenix kernel: [ 15.702816] PREFETCH window: c0000000-cfffffff
Dec 11 19:34:33 phoenix kernel: [ 15.702875] PCI: Bridge: 0000:00:04.0
Dec 11 19:34:33 phoenix kernel: [ 15.702933] IO window: disabled.
Dec 11 19:34:33 phoenix kernel: [ 15.702991] MEM window: disabled.
Dec 11 19:34:33 phoenix kernel: [ 15.703049] PREFETCH window: disabled.
Dec 11 19:34:33 phoenix kernel: [ 15.703107] PCI: Bridge: 0000:00:05.0
Dec 11 19:34:33 phoenix kernel: [ 15.703165] IO window: disabled.
Dec 11 19:34:33 phoenix kernel: [ 15.703222] MEM window: disabled.
Dec 11 19:34:33 phoenix kernel: [ 15.703280] PREFETCH window: disabled.
Dec 11 19:34:33 phoenix kernel: [ 15.703343] PCI: Bus 3, cardbus bridge: 0000:02:04.0
Dec 11 19:34:33 phoenix kernel: [ 15.703402] IO window: 00002000-000020ff
Dec 11 19:34:33 phoenix kernel: [ 15.703460] IO window: 00002400-000024ff
Dec 11 19:34:33 phoenix kernel: [ 15.703519] PREFETCH window: 50000000-51ffffff
Dec 11 19:34:33 phoenix kernel: [ 15.703596] MEM window: 52000000-53ffffff
Dec 11 19:34:33 phoenix kernel: [ 15.703655] PCI: Bridge: 0000:00:14.4
Dec 11 19:34:33 phoenix kernel: [ 15.703715] IO window: 2000-2fff
Dec 11 19:34:33 phoenix kernel: [ 15.703773] MEM window: d0000000-d05fffff
Dec 11 19:34:33 phoenix kernel: [ 15.703832] PREFETCH window: 50000000-51ffffff
Dec 11 19:34:33 phoenix kernel: [ 15.705872] ACPI: PCI Interrupt Link [C0F4] enabled at IRQ 11
Dec 11 19:34:34 phoenix kernel: [ 15.705940] ACPI: PCI Interrupt 0000:02:04.0[A] -> Link [C0F4] -> GSI 11 (level, low) -> IRQ 11
Dec 11 19:34:34 phoenix kernel: [ 15.706136] NET: Registered protocol family 2
Dec 11 19:34:34 phoenix kernel: [ 15.726869] IP route cache hash table entries: 32768 (order: 6, 262144 bytes)
Dec 11 19:34:34 phoenix kernel: [ 15.734280] TCP established hash table entries: 32768 (order: 9, 2359296 bytes)
Dec 11 19:34:34 phoenix kernel: [ 15.737493] TCP bind hash table entries: 16384 (order: 8, 1310720 bytes)
Dec 11 19:34:34 phoenix kernel: [ 15.739563] TCP: Hash tables configured (established 32768 bind 16384)
Dec 11 19:34:34 phoenix kernel: [ 15.741473] TCP reno registered
Dec 11 19:34:34 phoenix kernel: [ 15.757199] audit: initializing netlink socket (disabled)
Dec 11 19:34:34 phoenix kernel: [ 15.758441] audit(1165865627.922:1): initialized
Dec 11 19:34:34 phoenix kernel: [ 15.788398] VFS: Disk quotas dquot_6.5.1
Dec 11 19:34:34 phoenix kernel: [ 15.788493] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
Dec 11 19:34:34 phoenix kernel: [ 15.821812] io scheduler noop registered
Dec 11 19:34:34 phoenix kernel: [ 15.821908] io scheduler anticipatory registered
Dec 11 19:34:34 phoenix kernel: [ 15.822002] io scheduler deadline registered
Dec 11 19:34:34 phoenix kernel: [ 15.822110] io scheduler cfq registered (default)
Dec 11 19:34:34 phoenix kernel: [ 15.823056] pcie_portdrv_probe->Dev[5a36:1002] has invalid IRQ. Check vendor BIOS
Dec 11 19:34:34 phoenix kernel: [ 15.823156] assign_interrupt_mode Found MSI capability
Dec 11 19:34:34 phoenix kernel: [ 15.824702] pcie_portdrv_probe->Dev[5a37:1002] has invalid IRQ. Check vendor BIOS
Dec 11 19:34:34 phoenix kernel: [ 15.824801] assign_interrupt_mode Found MSI capability
Dec 11 19:34:34 phoenix kernel: [ 15.825216] aer: probe of 0000:00:04.0:pcie01 failed with error 2
Dec 11 19:34:35 phoenix kernel: [ 15.825315] aer: probe of 0000:00:05.0:pcie01 failed with error 2
Dec 11 19:34:43 phoenix kernel: [ 15.871372] Real Time Clock Driver v1.12ac
Dec 11 19:34:43 phoenix kernel: [ 15.871520] Linux agpgart interface v0.101 (c) Dave Jones
Dec 11 19:34:43 phoenix kernel: [ 15.871579] Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing enabled
Dec 11 19:34:43 phoenix kernel: [ 15.894952] ACPI: PCI Interrupt Link [C0F1] enabled at IRQ 10
Dec 11 19:34:43 phoenix kernel: [ 15.895024] ACPI: PCI Interrupt 0000:00:14.6[B] -> Link [C0F1] -> GSI 10 (level, low) -> IRQ 10
Dec 11 19:34:43 phoenix kernel: [ 15.895183] ACPI: PCI interrupt for device 0000:00:14.6 disabled
Dec 11 19:34:43 phoenix kernel: [ 15.898084] RAMDISK driver initialized: 16 RAM disks of 65536K size 1024 blocksize
Dec 11 19:34:43 phoenix kernel: [ 15.923187] ACPI: PCI Interrupt Link [C0F0] enabled at IRQ 10
Dec 11 19:34:43 phoenix kernel: [ 15.923264] ACPI: PCI Interrupt 0000:00:14.1[A] -> Link [C0F0] -> GSI 10 (level, low) -> IRQ 10
Dec 11 19:34:43 phoenix kernel: [ 15.927095] ata1: PATA max UDMA/100 cmd 0x1F0 ctl 0x3F6 bmdma 0x4010 irq 14
Dec 11 19:34:43 phoenix kernel: [ 15.927202] ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0x4018 irq 15
Dec 11 19:34:43 phoenix kernel: [ 15.927291] scsi0 : pata_atiixp
Dec 11 19:34:43 phoenix kernel: [ 16.082954] ata1.00: ATA-6, max UDMA/100, 156301488 sectors: LBA48
Dec 11 19:34:43 phoenix kernel: [ 16.083025] ata1.00: ata1: dev 0 multi count 16
Dec 11 19:34:43 phoenix kernel: [ 16.088495] ata1.00: configured for UDMA/100
Dec 11 19:34:43 phoenix kernel: [ 16.088560] scsi1 : pata_atiixp
Dec 11 19:34:43 phoenix kernel: [ 16.393148] ata2.00: ATAPI, max MWDMA2
Dec 11 19:34:43 phoenix kernel: [ 16.547931] ata2.00: configured for MWDMA2
Dec 11 19:34:43 phoenix kernel: [ 16.569703] scsi 0:0:0:0: Direct-Access ATA ST9808211A 3.02 PQ: 0 ANSI: 5
Dec 11 19:34:43 phoenix kernel: [ 16.587951] scsi 1:0:0:0: CD-ROM MATSHITA UJ-840D 1.02 PQ: 0 ANSI: 5
Dec 11 19:34:43 phoenix kernel: [ 16.588314] PNP: PS/2 Controller [PNP0303:C1C8,PNP0f13:C1C9] at 0x60,0x64 irq 1,12
Dec 11 19:34:43 phoenix kernel: [ 16.595027] i8042.c: Detected active multiplexing controller, rev 1.1.
Dec 11 19:34:43 phoenix kernel: [ 16.595855] serio: i8042 KBD port at 0x60,0x64 irq 1
Dec 11 19:34:43 phoenix kernel: [ 16.613453] serio: i8042 AUX0 port at 0x60,0x64 irq 12
Dec 11 19:34:43 phoenix kernel: [ 16.613514] serio: i8042 AUX1 port at 0x60,0x64 irq 12
Dec 11 19:34:43 phoenix kernel: [ 16.613574] serio: i8042 AUX2 port at 0x60,0x64 irq 12
Dec 11 19:34:43 phoenix kernel: [ 16.613635] serio: i8042 AUX3 port at 0x60,0x64 irq 12
Dec 11 19:34:43 phoenix kernel: [ 16.615107] mice: PS/2 mouse device common for all mice
Dec 11 19:34:43 phoenix kernel: [ 16.621147] TCP cubic registered
Dec 11 19:34:43 phoenix kernel: [ 16.621225] NET: Registered protocol family 1
Dec 11 19:34:43 phoenix kernel: [ 16.621290] NET: Registered protocol family 8
Dec 11 19:34:43 phoenix kernel: [ 16.621348] NET: Registered protocol family 20
Dec 11 19:34:43 phoenix kernel: [ 16.623192] IO APIC resources could be not be allocated.
Dec 11 19:34:43 phoenix kernel: [ 16.647119] ACPI: (supports S0 S3 S4 S5)
Dec 11 19:34:43 phoenix kernel: [ 16.647435] drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
Dec 11 19:34:43 phoenix kernel: [ 16.647538] Freeing unused kernel memory: 200k freed
Dec 11 19:34:44 phoenix kernel: [ 16.793068] input: AT Translated Set 2 keyboard as /class/input/input0
Dec 11 19:34:44 phoenix kernel: [ 16.842305] ACPI: Transitioning device [C255] to D3
Dec 11 19:34:44 phoenix kernel: [ 16.842371] ACPI: Transitioning device [C255] to D3
Dec 11 19:34:44 phoenix kernel: [ 16.842432] ACPI: Fan [C255] (off)
Dec 11 19:34:44 phoenix kernel: [ 16.842669] ACPI: Transitioning device [C256] to D3
Dec 11 19:34:44 phoenix kernel: [ 16.842728] ACPI: Transitioning device [C256] to D3
Dec 11 19:34:44 phoenix kernel: [ 16.842788] ACPI: Fan [C256] (off)
Dec 11 19:34:44 phoenix kernel: [ 16.843039] ACPI: Transitioning device [C257] to D3
Dec 11 19:34:44 phoenix kernel: [ 16.843098] ACPI: Transitioning device [C257] to D3
Dec 11 19:34:44 phoenix kernel: [ 16.843158] ACPI: Fan [C257] (off)
Dec 11 19:34:44 phoenix kernel: [ 16.843392] ACPI: Transitioning device [C258] to D3
Dec 11 19:34:44 phoenix kernel: [ 16.843451] ACPI: Transitioning device [C258] to D3
Dec 11 19:34:44 phoenix kernel: [ 16.843512] ACPI: Fan [C258] (off)
Dec 11 19:34:44 phoenix kernel: [ 16.853651] ACPI: CPU0 (power states: C1[C1] C3[C3])
Dec 11 19:34:44 phoenix kernel: [ 16.853826] ACPI: Processor [C000] (supports 8 throttling states)
Dec 11 19:34:44 phoenix kernel: [ 16.872777] ACPI: Thermal Zone [TZ1] (63 C)
Dec 11 19:34:44 phoenix kernel: [ 16.879674] ACPI: Thermal Zone [TZ2] (50 C)
Dec 11 19:34:44 phoenix kernel: [ 16.888955] ACPI: Thermal Zone [TZ3] (32 C)
Dec 11 19:34:44 phoenix kernel: [ 16.892594] ACPI: Thermal Zone [TZ4] (36 C)
Dec 11 19:34:44 phoenix kernel: [ 17.581262] SCSI device sda: 156301488 512-byte hdwr sectors (80026 MB)
Dec 11 19:34:44 phoenix kernel: [ 17.581345] sda: Write Protect is off
Dec 11 19:34:44 phoenix kernel: [ 17.581430] SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Dec 11 19:34:44 phoenix kernel: [ 17.599290] SCSI device sda: 156301488 512-byte hdwr sectors (80026 MB)
Dec 11 19:34:44 phoenix kernel: [ 17.599366] sda: Write Protect is off
Dec 11 19:34:44 phoenix kernel: [ 17.599449] SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Dec 11 19:34:44 phoenix kernel: [ 17.601968] sda: sda1 sda2 sda3 < sda5 >
Dec 11 19:34:44 phoenix kernel: [ 17.715966] sd 0:0:0:0: Attached scsi disk sda
Dec 11 19:34:44 phoenix kernel: [ 18.075866] Attempting manual resume
Dec 11 19:34:44 phoenix kernel: [ 18.094894] usbcore: registered new interface driver usbfs
Dec 11 19:34:44 phoenix kernel: [ 18.099177] usbcore: registered new interface driver hub
Dec 11 19:34:44 phoenix kernel: [ 18.100772] usbcore: registered new device driver usb
Dec 11 19:34:44 phoenix kernel: [ 18.103152] ACPI: PCI Interrupt Link [C0F3] enabled at IRQ 10
Dec 11 19:34:44 phoenix kernel: [ 18.103216] ACPI: PCI Interrupt 0000:00:13.0[A] -> Link [C0F3] -> GSI 10 (level, low) -> IRQ 10
Dec 11 19:34:44 phoenix kernel: [ 18.103385] ohci_hcd 0000:00:13.0: OHCI Host Controller
Dec 11 19:34:44 phoenix kernel: [ 18.146488] ohci_hcd 0000:00:13.0: new USB bus registered, assigned bus number 1
Dec 11 19:34:44 phoenix kernel: [ 18.146594] ohci_hcd 0000:00:13.0: irq 10, io mem 0xd0a00000
Dec 11 19:34:44 phoenix kernel: [ 18.227984] usb usb1: configuration #1 chosen from 1 choice
Dec 11 19:34:44 phoenix kernel: [ 18.231927] hub 1-0:1.0: USB hub found
Dec 11 19:34:44 phoenix kernel: [ 18.232653] hub 1-0:1.0: 4 ports detected
Dec 11 19:34:44 phoenix kernel: [ 18.233401] ACPI: PCI Interrupt 0000:00:13.1[A] -> Link [C0F3] -> GSI 10 (level, low) -> IRQ 10
Dec 11 19:34:44 phoenix kernel: [ 18.233572] ohci_hcd 0000:00:13.1: OHCI Host Controller
Dec 11 19:34:44 phoenix kernel: [ 18.233679] ohci_hcd 0000:00:13.1: new USB bus registered, assigned bus number 2
Dec 11 19:34:44 phoenix kernel: [ 18.233776] ohci_hcd 0000:00:13.1: irq 10, io mem 0xd0a01000
Dec 11 19:34:44 phoenix kernel: [ 18.292860] usb usb2: configuration #1 chosen from 1 choice
Dec 11 19:34:44 phoenix kernel: [ 18.292975] hub 2-0:1.0: USB hub found
Dec 11 19:34:44 phoenix kernel: [ 18.293048] hub 2-0:1.0: 4 ports detected
Dec 11 19:34:44 phoenix kernel: [ 18.293517] ACPI: PCI Interrupt 0000:00:13.2[A] -> Link [C0F3] -> GSI 10 (level, low) -> IRQ 10
Dec 11 19:34:44 phoenix kernel: [ 18.293689] ehci_hcd 0000:00:13.2: EHCI Host Controller
Dec 11 19:34:44 phoenix kernel: [ 18.294109] ehci_hcd 0000:00:13.2: new USB bus registered, assigned bus number 3
Dec 11 19:34:44 phoenix kernel: [ 18.294254] ehci_hcd 0000:00:13.2: irq 10, io mem 0xd0a02000
Dec 11 19:34:44 phoenix kernel: [ 18.294322] ehci_hcd 0000:00:13.2: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
Dec 11 19:34:44 phoenix kernel: [ 18.297111] usb usb3: configuration #1 chosen from 1 choice
Dec 11 19:34:44 phoenix kernel: [ 18.297209] hub 3-0:1.0: USB hub found
Dec 11 19:34:44 phoenix kernel: [ 18.297278] hub 3-0:1.0: 8 ports detected
Dec 11 19:34:44 phoenix kernel: [ 18.302946] ACPI: PCI Interrupt Link [C0F5] enabled at IRQ 9
Dec 11 19:34:44 phoenix kernel: [ 18.303018] ACPI: PCI Interrupt 0000:02:04.2[C] -> Link [C0F5] -> GSI 9 (level, low) -> IRQ 9
Dec 11 19:34:44 phoenix kernel: [ 18.406203] ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[9] MMIO=[d0013000-d00137ff] Max Packet=[2048] IR/IT contexts=[4/8]
Dec 11 19:34:44 phoenix kernel: [ 18.441953] kjournald starting. Commit interval 5 seconds
Dec 11 19:34:44 phoenix kernel: [ 18.452886] EXT3-fs: mounted filesystem with writeback data mode.
Dec 11 19:34:44 phoenix kernel: [ 19.143568] usb 2-1: new full speed USB device using ohci_hcd and address 2
Dec 11 19:34:44 phoenix kernel: [ 19.329404] usb 2-1: configuration #1 chosen from 1 choice
Dec 11 19:34:44 phoenix kernel: [ 19.591799] usb 1-2: new full speed USB device using ohci_hcd and address 2
Dec 11 19:34:44 phoenix kernel: [ 19.778061] usb 1-2: configuration #1 chosen from 1 choice
Dec 11 19:34:45 phoenix kernel: [ 34.149057] tg3.c:v3.70 (December 1, 2006)
Dec 11 19:34:45 phoenix kernel: [ 34.151188] ACPI: PCI Interrupt Link [C0F7] enabled at IRQ 10
Dec 11 19:34:45 phoenix kernel: [ 34.151262] ACPI: PCI Interrupt 0000:02:01.0[A] -> Link [C0F7] -> GSI 10 (level, low) -> IRQ 10
Dec 11 19:34:45 phoenix kernel: [ 34.201471] eth0: Tigon3 [partno(BCM95788A50) rev 3003 PHY(5705)] (PCI:33MHz:32-bit) 10/100/1000Base-T Ethernet 00:0f:b0:bb:bc:f8
Dec 11 19:34:45 phoenix kernel: [ 34.201775] eth0: RXcsums[1] LinkChgREG[0] MIirq[0] ASF[0] Split[0] WireSpeed[0] TSOcap[1]
Dec 11 19:34:45 phoenix kernel: [ 34.201855] eth0: dma_rwctrl[763f0000] dma_mask[32-bit]
Dec 11 19:34:45 phoenix kernel: [ 34.311449] ieee80211: 802.11 data/management/control stack, git-1.1.13
Dec 11 19:34:45 phoenix kernel: [ 34.311515] ieee80211: Copyright (C) 2004-2005 Intel Corporation <[email protected]>
Dec 11 19:34:45 phoenix kernel: [ 34.798739] Yenta: CardBus bridge found at 0000:02:04.0 [103c:308b]
Dec 11 19:34:45 phoenix kernel: [ 34.798821] Yenta: Enabling burst memory read transactions
Dec 11 19:34:45 phoenix kernel: [ 34.798883] Yenta: Using INTVAL to route CSC interrupts to PCI
Dec 11 19:34:45 phoenix kernel: [ 34.798942] Yenta: Routing CardBus interrupts to PCI
Dec 11 19:34:45 phoenix kernel: [ 34.799005] Yenta TI: socket 0000:02:04.0, mfunc 0x01a11b22, devctl 0x64
Dec 11 19:34:45 phoenix kernel: [ 34.856577] input: PC Speaker as /class/input/input1
Dec 11 19:34:45 phoenix kernel: [ 34.919822] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
Dec 11 19:34:45 phoenix kernel: [ 35.000682] sdhci: Secure Digital Host Controller Interface driver, 0.12
Dec 11 19:34:45 phoenix kernel: [ 35.000750] sdhci: Copyright(c) Pierre Ossman
Dec 11 19:34:45 phoenix kernel: [ 35.024581] Yenta: ISA IRQ mask 0x00f8, PCI irq 11
Dec 11 19:34:45 phoenix kernel: [ 35.024650] Socket status: 30000006
Dec 11 19:34:45 phoenix kernel: [ 35.024709] Yenta: Raising subordinate bus# of parent bus (#02) from #03 to #06
Dec 11 19:34:45 phoenix kernel: [ 35.024797] pcmcia: parent PCI bridge I/O window: 0x2000 - 0x2fff
Dec 11 19:34:45 phoenix kernel: [ 35.026860] pcmcia: parent PCI bridge Memory window: 0xd0000000 - 0xd05fffff
Dec 11 19:34:45 phoenix kernel: [ 35.026931] pcmcia: parent PCI bridge Memory window: 0x50000000 - 0x51ffffff
Dec 11 19:34:45 phoenix kernel: [ 35.035897] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
Dec 11 19:34:45 phoenix kernel: [ 35.035992] sdhci: SDHCI controller found at 0000:02:04.4 [104c:8034] (rev 0)
Dec 11 19:34:45 phoenix kernel: [ 35.036096] ACPI: PCI Interrupt 0000:02:04.4[C] -> Link [C0F5] -> GSI 9 (level, low) -> IRQ 9
Dec 11 19:34:45 phoenix kernel: [ 35.041391] mmc0: SDHCI at 0xd001a000 irq 9 DMA
Dec 11 19:34:45 phoenix kernel: [ 35.041589] mmc1: SDHCI at 0xd001b000 irq 9 DMA
Dec 11 19:34:45 phoenix kernel: [ 35.041772] mmc2: SDHCI at 0xd001c000 irq 9 DMA
Dec 11 19:34:45 phoenix kernel: [ 35.101044] ACPI: PCI Interrupt 0000:02:04.3[B] -> Link [C0F5] -> GSI 9 (level, low) -> IRQ 9
Dec 11 19:34:45 phoenix kernel: [ 35.204904] sd 0:0:0:0: Attached scsi generic sg0 type 0
Dec 11 19:34:45 phoenix kernel: [ 35.205007] scsi 1:0:0:0: Attached scsi generic sg1 type 5
Dec 11 19:34:45 phoenix kernel: [ 35.306529] piix4_smbus 0000:00:14.0: Found 0000:00:14.0 device
Dec 11 19:34:45 phoenix kernel: [ 35.776690] Synaptics Touchpad, model: 1, fw: 6.2, id: 0x1a0b1, caps: 0xa04713/0x200000
Dec 11 19:34:45 phoenix kernel: [ 35.831125] input: SynPS/2 Synaptics TouchPad as /class/input/input2
Dec 11 19:34:45 phoenix kernel: [ 35.928637] bcm43xx driver
Dec 11 19:34:45 phoenix kernel: [ 35.943733] ACPI: PCI Interrupt Link [C0F6] enabled at IRQ 11
Dec 11 19:34:45 phoenix kernel: [ 35.943797] ACPI: PCI Interrupt 0000:02:02.0[A] -> Link [C0F6] -> GSI 11 (level, low) -> IRQ 11
Dec 11 19:34:45 phoenix kernel: [ 35.943999] bcm43xx: Chip ID 0x4306, rev 0x3
Dec 11 19:34:45 phoenix kernel: [ 35.944057] bcm43xx: Number of cores: 5
Dec 11 19:34:45 phoenix kernel: [ 35.944115] bcm43xx: Core 0: ID 0x800, rev 0x4, vendor 0x4243
Dec 11 19:34:45 phoenix kernel: [ 35.944179] bcm43xx: Core 1: ID 0x812, rev 0x5, vendor 0x4243
Dec 11 19:34:45 phoenix kernel: [ 35.944245] bcm43xx: Core 2: ID 0x80d, rev 0x2, vendor 0x4243
Dec 11 19:34:45 phoenix kernel: [ 35.944309] bcm43xx: Core 3: ID 0x807, rev 0x2, vendor 0x4243
Dec 11 19:34:45 phoenix kernel: [ 35.944373] bcm43xx: Core 4: ID 0x804, rev 0x9, vendor 0x4243
Dec 11 19:34:45 phoenix kernel: [ 35.947805] bcm43xx: PHY connected
Dec 11 19:34:45 phoenix kernel: [ 35.947877] bcm43xx: Detected PHY: Version: 2, Type 2, Revision 2
Dec 11 19:34:45 phoenix kernel: [ 35.947956] bcm43xx: Detected Radio: ID: 2205017f (Manuf: 17f Ver: 2050 Rev: 2)
Dec 11 19:34:45 phoenix kernel: [ 35.948053] bcm43xx: Radio turned off
Dec 11 19:34:45 phoenix kernel: [ 35.948118] bcm43xx: Radio turned off
Dec 11 19:34:45 phoenix kernel: [ 36.113323] bcm43xx: PHY connected
Dec 11 19:34:45 phoenix kernel: [ 36.245291] NET: Registered protocol family 17
Dec 11 19:34:45 phoenix kernel: [ 36.370059] Bluetooth: Core ver 2.11
Dec 11 19:34:45 phoenix kernel: [ 36.370229] NET: Registered protocol family 31
Dec 11 19:34:45 phoenix kernel: [ 36.370287] Bluetooth: HCI device and connection manager initialized
Dec 11 19:34:45 phoenix kernel: [ 36.372847] Bluetooth: HCI socket layer initialized
Dec 11 19:34:45 phoenix kernel: [ 36.498861] ACPI: PCI Interrupt 0000:00:14.5[B] -> Link [C0F1] -> GSI 10 (level, low) -> IRQ 10
Dec 11 19:34:45 phoenix kernel: [ 36.613387] bcm43xx: Microcode rev 0x118, pl 0x17 (2004-05-06 21:34:00)
Dec 11 19:34:45 phoenix kernel: [ 36.641430] bcm43xx: Radio turned on
Dec 11 19:34:45 phoenix kernel: [ 36.710731] ACPI: PCI Interrupt 0000:00:14.6[B] -> Link [C0F1] -> GSI 10 (level, low) -> IRQ 10
Dec 11 19:34:45 phoenix kernel: [ 36.813305] MC'97 0 converters and GPIO not ready (0x1)
Dec 11 19:34:45 phoenix kernel: [ 36.853497] bcm43xx: Chip initialized
Dec 11 19:34:45 phoenix kernel: [ 36.856370] bcm43xx: 30-bit DMA initialized
Dec 11 19:34:45 phoenix kernel: [ 36.856647] bcm43xx: Keys cleared
Dec 11 19:34:45 phoenix kernel: [ 36.860366] bcm43xx: Selected 802.11 core (phytype 2)
Dec 11 19:34:45 phoenix kernel: [ 36.967185] Bluetooth: HCI USB driver ver 2.9
Dec 11 19:34:46 phoenix kernel: [ 37.079153] usbcore: registered new interface driver hci_usb
Dec 11 19:34:46 phoenix kernel: [ 37.439428] Adding 1116476k swap on /dev/disk/by-uuid/45b6bcfd-44ec-4878-8110-f2164f9e8051. Priority:-1 extents:1 across:1116476k
Dec 11 19:34:46 phoenix kernel: [ 37.530100] EXT3 FS on sda2, internal journal
Dec 11 19:34:46 phoenix kernel: [ 38.224955] device-mapper: ioctl: 4.11.0-ioctl (2006-10-12) initialised: [email protected]
Dec 11 19:34:46 phoenix kernel: [ 40.175486] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.182346] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.184468] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.186756] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.189790] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.192714] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.195561] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.197103] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.198961] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.200469] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.203465] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.206225] device-mapper: ioctl: error adding target to table
Dec 11 19:34:46 phoenix kernel: [ 40.567879] NTFS driver 2.1.27 [Flags: R/O MODULE].
Dec 11 19:34:46 phoenix kernel: [ 40.655469] NTFS volume version 3.1.
Dec 11 19:34:47 phoenix kernel: [ 44.462601] ACPI: Battery Slot [C17C] (battery present)
Dec 11 19:34:47 phoenix kernel: [ 44.463083] ACPI: Battery Slot [C17B] (battery absent)
Dec 11 19:34:47 phoenix kernel: [ 44.495008] ACPI: Video Device [C049] (multi-head: yes rom: no post: no)
Dec 11 19:34:47 phoenix kernel: [ 44.583263] ACPI: AC Adapter [C17A] (on-line)
Dec 11 19:34:47 phoenix kernel: [ 44.631033] ACPI: Power Button (FF) [PWRF]
Dec 11 19:34:47 phoenix kernel: [ 44.631076] ACPI: Sleep Button (CM) [C1F4]
Dec 11 19:34:47 phoenix kernel: [ 44.631084] ACPI: Lid Switch [C1F5]
Dec 11 19:34:47 phoenix kernel: [ 45.144920] powernow-k8: Found 1 AMD Turion(tm) 64 Mobile ML-40 processors (version 2.00.00)
Dec 11 19:34:47 phoenix kernel: [ 45.171761] powernow-k8: 0 : fid 0xe (2200 MHz), vid 0x4
Dec 11 19:34:47 phoenix kernel: [ 45.171766] powernow-k8: 1 : fid 0xc (2000 MHz), vid 0x6
Dec 11 19:34:47 phoenix kernel: [ 45.171769] powernow-k8: 2 : fid 0xa (1800 MHz), vid 0x8
Dec 11 19:34:47 phoenix kernel: [ 45.171771] powernow-k8: 3 : fid 0x8 (1600 MHz), vid 0xa
Dec 11 19:34:47 phoenix kernel: [ 45.171773] powernow-k8: 4 : fid 0x0 (800 MHz), vid 0x16
Dec 11 19:34:47 phoenix kernel: [ 47.225768] NET: Registered protocol family 10
Dec 11 19:34:47 phoenix kernel: [ 47.229617] lo: Disabled Privacy Extensions
Dec 11 19:34:47 phoenix kernel: [ 47.257499] ADDRCONF(NETDEV_UP): eth0: link is not ready
Dec 11 19:34:47 phoenix kernel: [ 47.257502] ADDRCONF(NETDEV_UP): eth1: link is not ready
Dec 11 19:34:47 phoenix kernel: [ 55.777972] Capability LSM initialized
Dec 11 19:34:47 phoenix kernel: [ 56.625268] SoftMAC: Scanning finished: scanned 14 channels starting with channel 1
Dec 11 19:34:47 phoenix kernel: [ 57.010533] SoftMAC: Associate: Scanning for networks first.
Dec 11 19:34:47 phoenix kernel: [ 57.011861] SoftMAC: Associate: failed to initiate scan. Is device up?
Dec 11 19:34:47 phoenix kernel: [ 57.044649] SoftMAC: Scanning finished: scanned 14 channels starting with channel 1
Dec 11 19:34:47 phoenix kernel: [ 57.044691] WARNING at kernel/mutex.c:132 __mutex_lock_common()
Dec 11 19:34:47 phoenix kernel: [ 57.044694]
Dec 11 19:34:47 phoenix kernel: [ 57.044695] Call Trace:
Dec 11 19:34:47 phoenix kernel: [ 57.044712] [dump_trace+193/1008] dump_trace+0xc1/0x3f0
Dec 11 19:34:47 phoenix kernel: [ 57.044718] [show_trace+67/96] show_trace+0x43/0x60
Dec 11 19:34:47 phoenix kernel: [ 57.044723] [dump_stack+21/32] dump_stack+0x15/0x20
Dec 11 19:34:47 phoenix kernel: [ 57.044733] [__mutex_lock_slowpath+192/672] __mutex_lock_slowpath+0xc0/0x2a0
Dec 11 19:34:47 phoenix kernel: [ 57.044738] [mutex_lock+37/48] mutex_lock+0x25/0x30
Dec 11 19:34:47 phoenix kernel: [ 57.044764] [_end+125206182/2126088072] :ieee80211softmac:ieee80211softmac_assoc_work+0x2e/0x570
Dec 11 19:34:47 phoenix kernel: [ 57.044782] [_end+125207544/2126088072] :ieee80211softmac:ieee80211softmac_assoc_notify_scan+0x10/0x20
Dec 11 19:34:47 phoenix kernel: [ 57.044792] [_end+125209290/2126088072] :ieee80211softmac:ieee80211softmac_notify_callback+0x62/0x78
Dec 11 19:34:47 phoenix kernel: [ 57.044801] [run_workqueue+196/432] run_workqueue+0xc4/0x1b0
Dec 11 19:34:47 phoenix kernel: [ 57.044807] [worker_thread+321/384] worker_thread+0x141/0x180
Dec 11 19:34:47 phoenix kernel: [ 57.044813] [kthread+211/272] kthread+0xd3/0x110
Dec 11 19:34:47 phoenix kernel: [ 57.044819] [child_rip+10/18] child_rip+0xa/0x12
Dec 11 19:34:47 phoenix kernel: [ 57.045434] DWARF2 unwinder stuck at child_rip+0xa/0x12
Dec 11 19:34:47 phoenix kernel: [ 57.045437] Leftover inexact backtrace:
Dec 11 19:34:47 phoenix kernel: [ 57.045453] [_spin_unlock_irq+43/96] _spin_unlock_irq+0x2b/0x60
Dec 11 19:34:47 phoenix kernel: [ 57.045457] [restore_args+0/48] restore_args+0x0/0x30
Dec 11 19:34:47 phoenix kernel: [ 57.045463] [kthread+0/272] kthread+0x0/0x110
Dec 11 19:34:47 phoenix kernel: [ 57.045466] [child_rip+0/18] child_rip+0x0/0x12
Dec 11 19:34:47 phoenix kernel: [ 57.045469]
Dec 11 19:34:47 phoenix kernel: [ 57.045487] PGD 3040c067 PUD 0
Dec 11 19:34:47 phoenix kernel: [ 57.045494] CPU 0
Dec 11 19:34:47 phoenix kernel: [ 57.045495] Modules linked in: capability commoncap ipv6 powernow_k8 cpufreq_conservative cpufreq_ondemand cpufreq_userspace cpufreq_stats freq_table
cpufreq_powersave button container ac asus_acpi video battery nls_utf8 ntfs dm_mod md_mod sbp2 hci_usb snd_atiixp_modem snd_pcm_oss snd_mixer_oss joydev tsdev snd_atiixp snd_ac97_codec snd_ac97_bus
bluetooth af_packet snd_pcm snd_timer bcm43xx serio_raw pcmcia snd soundcore i2c_piix4 ieee80211softmac sg psmouse tifm_7xx1 tifm_core evdev sdhci mmc_core shpchp pci_hotplug snd_page_alloc pcspkr
ata_generic yenta_socket rsrc_nonstatic pcmcia_core i2c_core ieee80211 ieee80211_crypt k8temp tg3 ext3 ohci1394 ieee1394 jbd mbcache ehci_hcd ohci_hcd usbcore sd_mod thermal processor fan
Dec 11 19:34:47 phoenix kernel: [ 57.045536] Pid: 4, comm: events/0 Not tainted 2.6.19 #1
Dec 11 19:34:47 phoenix kernel: [ 57.045539] RIP: 0010:[__mutex_lock_slowpath+263/672] [__mutex_lock_slowpath+263/672] __mutex_lock_slowpath+0x107/0x2a0
Dec 11 19:34:47 phoenix kernel: [ 57.045545] RSP: 0018:ffff810037f19c40 EFLAGS: 00010086
Dec 11 19:34:47 phoenix kernel: [ 57.045548] RAX: 0000003c00000000 RBX: ffff810032100d88 RCX: 0000000000000000
Dec 11 19:34:47 phoenix kernel: [ 57.045552] RDX: ffff810037f18000 RSI: ffff810037f19c40 RDI: ffff810032100d88
Dec 11 19:34:47 phoenix kernel: [ 57.045554] RBP: ffff810037f19ca0 R08: 0000000000000002 R09: 0000000000000001
Dec 11 19:34:47 phoenix kernel: [ 57.045557] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000246
Dec 11 19:34:47 phoenix kernel: [ 57.045561] R13: ffff810037fbf100 R14: ffff810032100dd8 R15: ffff810037f19c40
Dec 11 19:34:47 phoenix kernel: [ 57.045564] FS: 00002b392ed8b6d0(0000) GS:ffffffff80602000(0000) knlGS:0000000000000000
Dec 11 19:34:47 phoenix kernel: [ 57.045567] CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
Dec 11 19:34:47 phoenix kernel: [ 57.045570] CR2: 0000003c00000000 CR3: 00000000304ee000 CR4: 00000000000006e0
Dec 11 19:34:47 phoenix kernel: [ 57.045573] Process events/0 (pid: 4, threadinfo ffff810037f18000, task ffff810037fbf100)
Dec 11 19:34:47 phoenix kernel: [ 57.045575] Stack: ffff810032100dd8 ffff810037f19c40 1111111111111111 ffff810032100d88
Dec 11 19:34:47 phoenix kernel: [ 57.045583] ffff810037f19c40 ffff810036e5f800 0000000000000086 ffff810032100d88
Dec 11 19:34:47 phoenix kernel: [ 57.045588] 0000000000000000 ffff810032100e70 0000000000000000 ffff810032100cd0
Dec 11 19:34:47 phoenix kernel: [ 57.045592] Call Trace:
Dec 11 19:34:47 phoenix kernel: [ 57.045598] [mutex_lock+37/48] mutex_lock+0x25/0x30
Dec 11 19:34:47 phoenix kernel: [ 57.045605] [_end+125206182/2126088072] :ieee80211softmac:ieee80211softmac_assoc_work+0x2e/0x570
Dec 11 19:34:47 phoenix kernel: [ 57.045616] [_end+125207544/2126088072] :ieee80211softmac:ieee80211softmac_assoc_notify_scan+0x10/0x20
Dec 11 19:34:47 phoenix kernel: [ 57.045627] [_end+125209290/2126088072] :ieee80211softmac:ieee80211softmac_notify_callback+0x62/0x78
Dec 11 19:34:47 phoenix kernel: [ 57.045635] [run_workqueue+196/432] run_workqueue+0xc4/0x1b0
Dec 11 19:34:47 phoenix kernel: [ 57.045640] [worker_thread+321/384] worker_thread+0x141/0x180
Dec 11 19:34:47 phoenix kernel: [ 57.045645] [kthread+211/272] kthread+0xd3/0x110
Dec 11 19:34:47 phoenix kernel: [ 57.045650] [child_rip+10/18] child_rip+0xa/0x12
Dec 11 19:34:47 phoenix kernel: [ 57.046211] DWARF2 unwinder stuck at child_rip+0xa/0x12
Dec 11 19:34:47 phoenix kernel: [ 57.046213] Leftover inexact backtrace:
Dec 11 19:34:47 phoenix kernel: [ 57.046219] [_spin_unlock_irq+43/96] _spin_unlock_irq+0x2b/0x60
Dec 11 19:34:47 phoenix kernel: [ 57.046223] [restore_args+0/48] restore_args+0x0/0x30
Dec 11 19:34:47 phoenix kernel: [ 57.046229] [kthread+0/272] kthread+0x0/0x110
Dec 11 19:34:47 phoenix kernel: [ 57.046232] [child_rip+0/18] child_rip+0x0/0x12
Dec 11 19:34:47 phoenix kernel: [ 57.046235]
Dec 11 19:34:47 phoenix kernel: [ 57.046236]
Dec 11 19:34:47 phoenix kernel: [ 57.046237] Code: 4c 89 38 48 89 45 a8 4c 89 6d b0 48 c7 c0 ff ff ff ff 87 03
Dec 11 19:34:47 phoenix kernel: [ 57.046254] RSP <ffff810037f19c40>
Dec 11 19:34:47 phoenix kernel: [ 57.046258] <3>BUG: sleeping function called from invalid context at kernel/rwsem.c:20
Dec 11 19:34:48 phoenix kernel: [ 57.046262] in_atomic():0, irqs_disabled():1
Dec 11 19:34:48 phoenix kernel: [ 57.046264] no locks held by events/0/4.
Dec 11 19:34:48 phoenix kernel: [ 57.046265]
Dec 11 19:34:48 phoenix kernel: [ 57.046266] Call Trace:
Dec 11 19:34:48 phoenix kernel: [ 57.046270] [dump_trace+193/1008] dump_trace+0xc1/0x3f0
Dec 11 19:34:48 phoenix kernel: [ 57.046275] [show_trace+67/96] show_trace+0x43/0x60
Dec 11 19:34:48 phoenix kernel: [ 57.046280] [dump_stack+21/32] dump_stack+0x15/0x20
Dec 11 19:34:48 phoenix kernel: [ 57.046285] [__might_sleep+197/208] __might_sleep+0xc5/0xd0
Dec 11 19:34:48 phoenix kernel: [ 57.046292] [down_read+29/80] down_read+0x1d/0x50
Dec 11 19:34:48 phoenix kernel: [ 57.046298] [blocking_notifier_call_chain+34/80] blocking_notifier_call_chain+0x22/0x50
Dec 11 19:34:48 phoenix kernel: [ 57.046305] [profile_task_exit+21/32] profile_task_exit+0x15/0x20
Dec 11 19:34:48 phoenix kernel: [ 57.046310] [do_exit+37/2272] do_exit+0x25/0x8e0
Dec 11 19:34:48 phoenix kernel: [ 57.046316] [do_page_fault+2032/2288] do_page_fault+0x7f0/0x8f0
Dec 11 19:34:48 phoenix kernel: [ 57.046321] [error_exit+0/150] error_exit+0x0/0x96
Dec 11 19:34:48 phoenix kernel: [ 57.046879] DWARF2 unwinder stuck at error_exit+0x0/0x96
Dec 11 19:34:48 phoenix kernel: [ 57.046881] Leftover inexact backtrace:
Dec 11 19:34:48 phoenix kernel: [ 57.046891] [__mutex_lock_slowpath+263/672] __mutex_lock_slowpath+0x107/0x2a0
Dec 11 19:34:48 phoenix kernel: [ 57.046901] [mutex_lock+37/48] mutex_lock+0x25/0x30
Dec 11 19:34:48 phoenix kernel: [ 57.046908] [_end+125206182/2126088072] :ieee80211softmac:ieee80211softmac_assoc_work+0x2e/0x570
Dec 11 19:34:48 phoenix kernel: [ 57.046911] [kfree+216/240] kfree+0xd8/0xf0
Dec 11 19:34:48 phoenix kernel: [ 57.046917] [trace_hardirqs_on+309/368] trace_hardirqs_on+0x135/0x170
Dec 11 19:34:48 phoenix kernel: [ 57.046924] [_end+125207528/2126088072] :ieee80211softmac:ieee80211softmac_assoc_notify_scan+0x0/0x20
Dec 11 19:34:48 phoenix kernel: [ 57.046931] [_end+125207544/2126088072] :ieee80211softmac:ieee80211softmac_assoc_notify_scan+0x10/0x20
Dec 11 19:34:48 phoenix kernel: [ 57.046938] [_end+125209290/2126088072] :ieee80211softmac:ieee80211softmac_notify_callback+0x62/0x78
Dec 11 19:34:48 phoenix kernel: [ 57.046946] [_end+125209192/2126088072] :ieee80211softmac:ieee80211softmac_notify_callback+0x0/0x78
Dec 11 19:34:48 phoenix kernel: [ 57.046954] [_end+125207528/2126088072] :ieee80211softmac:ieee80211softmac_assoc_notify_scan+0x0/0x20
Dec 11 19:34:48 phoenix kernel: [ 57.046959] [trace_hardirqs_on+309/368] trace_hardirqs_on+0x135/0x170
Dec 11 19:34:48 phoenix kernel: [ 57.046966] [_end+125209192/2126088072] :ieee80211softmac:ieee80211softmac_notify_callback+0x0/0x78
Dec 11 19:34:48 phoenix kernel: [ 57.046970] [run_workqueue+196/432] run_workqueue+0xc4/0x1b0
Dec 11 19:34:48 phoenix kernel: [ 57.046976] [worker_thread+321/384] worker_thread+0x141/0x180
Dec 11 19:34:48 phoenix kernel: [ 57.046982] [default_wake_function+0/16] default_wake_function+0x0/0x10
Dec 11 19:34:48 phoenix kernel: [ 57.046989] [worker_thread+0/384] worker_thread+0x0/0x180
Dec 11 19:34:48 phoenix kernel: [ 57.046993] [kthread+211/272] kthread+0xd3/0x110
Dec 11 19:34:48 phoenix kernel: [ 57.046999] [child_rip+10/18] child_rip+0xa/0x12
Dec 11 19:34:48 phoenix kernel: [ 57.047004] [_spin_unlock_irq+43/96] _spin_unlock_irq+0x2b/0x60
Dec 11 19:34:48 phoenix kernel: [ 57.047008] [restore_args+0/48] restore_args+0x0/0x30
Dec 11 19:34:48 phoenix kernel: [ 57.047014] [kthread+0/272] kthread+0x0/0x110
Dec 11 19:34:48 phoenix kernel: [ 57.047017] [child_rip+0/18] child_rip+0x0/0x12
Dec 11 19:34:48 phoenix kernel: [ 57.047020]
Dec 11 19:34:48 phoenix kernel: [ 59.017762] bcm43xx: set security called, .level = 0, .enabled = 0, .encrypt = 0
Dec 11 19:34:48 phoenix kernel: [ 63.944120] Bluetooth: L2CAP ver 2.8
Dec 11 19:34:48 phoenix kernel: [ 63.944123] Bluetooth: L2CAP socket layer initialized
Dec 11 19:34:48 phoenix kernel: [ 64.024249] Bluetooth: RFCOMM socket layer initialized
Dec 11 19:34:48 phoenix kernel: [ 64.024261] Bluetooth: RFCOMM TTY layer initialized
Dec 11 19:34:48 phoenix kernel: [ 64.024263] Bluetooth: RFCOMM ver 1.8
Dec 11 19:35:19 phoenix kernel: [ 80.556717] SysRq : Emergency Sync
Dec 11 19:35:19 phoenix kernel: [ 80.556760] Emergency Sync complete
Dec 11 19:35:21 phoenix kernel: [ 81.396409] SysRq : Emergency Sync
Dec 11 19:35:21 phoenix kernel: [ 81.396773] Emergency Sync complete
On Tuesday 12 December 2006 05:06, Ray Lee wrote:
> Hey all, more data on my bcm43xx problem report from a few weeks back.
>
> By random chance I acquired a brain, and decided to rebuild my latest kernel
Congratulations to your decision ;)
> Dec 11 19:34:47 phoenix kernel: [ 57.044691] WARNING at kernel/mutex.c:132 __mutex_lock_common()
> Dec 11 19:34:47 phoenix kernel: [ 57.044694]
I'm not sure what's happening here. Either one of the following
assertions is failing:
038 #define spin_lock_mutex(lock, flags) \
039 do { \
040 struct mutex *l = container_of(lock, struct mutex, wait_lock); \
041 \
042 DEBUG_LOCKS_WARN_ON(in_interrupt()); \
043 local_irq_save(flags); \
044 __raw_spin_lock(&(lock)->raw_lock); \
045 DEBUG_LOCKS_WARN_ON(l->magic != l); \
046 } while (0)
Which kernel are you using?
There is some locking breakage in latest kernels with softmac.
I attached the fixes for the known bugs.
From: Michael Buesch <[email protected]>
To: [email protected]
Date: Sun, 10 Dec 2006 18:39:28 +0100
Message-Id: <[email protected]>
Cc: Andrew Morton <[email protected]>, Johannes Berg <[email protected]>, "John W. Linville" <[email protected]>, [email protected]
Subject: ieee80211softmac: Fix mutex_lock at exit of ieee80211_softmac_get_genie
From: Ulrich Kunitz <[email protected]>
ieee80211softmac_wx_get_genie locks the associnfo mutex at
function exit. This patch fixes it. The patch is against Linus'
tree (commit af1713e0).
Signed-off-by: Ulrich Kunitz <[email protected]>
Signed-off-by: Michael Buesch <[email protected]>
Signed-off-by: Chris Wright <[email protected]>
---
net/ieee80211/softmac/ieee80211softmac_wx.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
--- linux-2.6.19.1.orig/net/ieee80211/softmac/ieee80211softmac_wx.c
+++ linux-2.6.19.1/net/ieee80211/softmac/ieee80211softmac_wx.c
@@ -463,7 +463,7 @@ ieee80211softmac_wx_get_genie(struct net
err = -E2BIG;
}
spin_unlock_irqrestore(&mac->lock, flags);
- mutex_lock(&mac->associnfo.mutex);
+ mutex_unlock(&mac->associnfo.mutex);
return err;
}
From: Ulrich Kunitz <[email protected]>
The signature of work functions changed recently from a context
pointer to the work structure pointer. This caused a problem in
the ieee80211softmac code, because the ieee80211softmac_assox_work
function has been called directly with a parameter explicitly
casted to (void*). This compiled correctly but resulted in a
softlock, because mutex_lock was called with the wrong memory
address. The patch fixes the problem. Another issue was a wrong
call of the schedule_work function. Softmac works again and this
fixes the problem I mentioned earlier in the zd1211rw rx tasklet
patch. The patch is against Linus' tree (commit af1713e0).
Signed-off-by: Ulrich Kunitz <[email protected]>
Acked-by: Michael Buesch <[email protected]>
Signed-off-by: Larry Finger <[email protected]>
---
John,
This patch should be pushed upstream to 2.6.20. At the moment, the work
struct changes have not yet propagated to wireless-2.6. When they do,
it will be needed there as well.
Larry
net/ieee80211/softmac/ieee80211softmac_assoc.c | 6 +++---
1 files changed, 3 insertions(+), 3 deletions(-)
diff --git a/net/ieee80211/softmac/ieee80211softmac_assoc.c b/net/ieee80211/softmac/ieee80211softmac_assoc.c
index eec1a1d..a824852 100644
--- a/net/ieee80211/softmac/ieee80211softmac_assoc.c
+++ b/net/ieee80211/softmac/ieee80211softmac_assoc.c
@@ -167,7 +167,7 @@ static void
ieee80211softmac_assoc_notify_scan(struct net_device *dev, int event_type, void *context)
{
struct ieee80211softmac_device *mac = ieee80211_priv(dev);
- ieee80211softmac_assoc_work((void*)mac);
+ ieee80211softmac_assoc_work(&mac->associnfo.work.work);
}
static void
@@ -177,7 +177,7 @@ ieee80211softmac_assoc_notify_auth(struc
switch (event_type) {
case IEEE80211SOFTMAC_EVENT_AUTHENTICATED:
- ieee80211softmac_assoc_work((void*)mac);
+ ieee80211softmac_assoc_work(&mac->associnfo.work.work);
break;
case IEEE80211SOFTMAC_EVENT_AUTH_FAILED:
case IEEE80211SOFTMAC_EVENT_AUTH_TIMEOUT:
@@ -438,7 +438,7 @@ ieee80211softmac_try_reassoc(struct ieee
spin_lock_irqsave(&mac->lock, flags);
mac->associnfo.associating = 1;
- schedule_work(&mac->associnfo.work);
+ schedule_delayed_work(&mac->associnfo.work, 0);
spin_unlock_irqrestore(&mac->lock, flags);
}
--
Greetings Michael.
Michael Buesch wrote:
> Congratulations to your decision ;)
Sometimes making decisions via Brownian motion has its advantages.
> Which kernel are you using?
Hmm, I'm using the mercurial repository, let me see if I can translate that to a git
head... Looks like git tree c2bb88baa52429b6b76e3ba4272cb2b29713c5a8 . (Which is from
less than 24 hours ago.)
> There is some locking breakage in latest kernels with softmac.
> I attached the fixes for the known bugs.
Okay, I'll apply to my local copy, rebuild, and try again. I'll let you know what
happens.
Ray
Ray Lee wrote:
> Michael Buesch wrote:
>> Congratulations to your decision ;)
>
> Sometimes making decisions via Brownian motion has its advantages.
>
>> Which kernel are you using?
>
> Hmm, I'm using the mercurial repository, let me see if I can translate that to a git
> head... Looks like git tree c2bb88baa52429b6b76e3ba4272cb2b29713c5a8 . (Which is from
> less than 24 hours ago.)
>
>> There is some locking breakage in latest kernels with softmac.
>> I attached the fixes for the known bugs.
>
> Okay, I'll apply to my local copy, rebuild, and try again. I'll let you know what
> happens.
Please note that the 3rd hunk of the second patch that Michael sent is already in Linus's
2.6.19-gitXX tree. You may get that part rejected by patch.
Larry