unix stream: Fix use-after-free crashes

Commit 0856a30409 (Scm: Remove unnecessary pid & credential references in Unix socket's send and receive path) introduced a use-after-free bug. It passes the scm reference to the first skb. Skb(s) afterwards may reference freed data structure because the first skb can be destructed by the receiver at anytime. The fix is by passing the scm reference to the very last skb.

---

index e6d9d10..77ec8e8 100644
@@ -1577,6 +1577,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	int sent = 0;
 	struct scm_cookie tmp_scm;
 	bool fds_sent = false;
+	bool scm_ref = true;
 	int max_level;
 
 	if (NULL == siocb->scm)

@@ -1637,12 +1638,15 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		 */
 		size = min_t(int, size, skb_tailroom(skb));
 
+		/* pass the scm reference to the very last skb */
+		if (sent + size >= len)
+			scm_ref = false;
 
-		/* Only send the fds and no ref to pid in the first buffer */
-		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+		/* Only send the fds in the first buffer */
+		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, scm_ref);
 		if (err < 0) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 		max_level = err + 1;
 		fds_sent = true;

@@ -1650,7 +1654,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		err = memcpy_fromiovec(skb_put(skb, size), msg->msg_iov, size);
 		if (err) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 
 		unix_state_lock(other);

@@ -1667,10 +1671,10 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		sent += size;
 	}
 
-	if (skb)
-		scm_release(siocb->scm);
-	else
+	if (scm_ref)
 		scm_destroy(siocb->scm);
+	else
+		scm_release(siocb->scm);
 	siocb->scm = NULL;
 
 	return sent;

@@ -1683,9 +1687,10 @@ pipe_err:
 		send_sig(SIGPIPE, current, 0);
 	err = -EPIPE;
 out_err:
-	if (skb == NULL)
+	if (scm_ref)
 		scm_destroy(siocb->scm);
-out:
+	else
+		scm_release(siocb->scm);
 	siocb->scm = NULL;
 	return sent ? : err;
 }

s/by passing/bypassing ?

Tested on i386 against linux-next (next-20110831).

- Sedat -

No

Thank you.

(putting on my Randy Dunlap hat)

The issue was fixed by passing...
or maybe
The fix is to pass...

Maybe it is a clearer to say

The fix is by withholding the scm reference obtained at the beginning of unix_stream_sendmsg via scm_send and pass it to the very last skb.

Tim

Thanks for finding this bug in my original patch. I've missed the case where receiving side could have released the all the references to the credential before the send side is using the credential again for subsequent skbs in the stream, thus causing the problem we saw. Getting an extra reference for pid/credentials at the beginning of the stream and not getting reference for the last skb is the right approach.

Thanks also to Sedat, Valdis and Jiri for their extensive testing to discover the bug and testing the subsequent fixes.

What happens if message must be split in two skb, first skb is built, queued (without scm reference)

Second skb allocation fails.

Rule about refs/norefs games is : As soon as you put skb into a list, it should have all appropriate references if this skb has pointer(s) to objects(s)

We should revert 0856a304091b33a and code the thing differently.

Instead of storing pointer to pid and cred in UNIXSKB(), why dont we copy all needed information ? No ref counts at all.

skb->cb[] is large enough.

An extra scm reference is already first obtained in scm_send at the beginning of unix_stream_sendmsg in Yan Zheng's patch. So things should be okay as long as we only use this extra reference we got in scm_send for the last skb in unix_stream_sendmsg instead of the first skb.

All the skbs put on the list does have proper reference on pid/scm. In the example you give, the first skb got the reference at this line:

err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);

the second skb use the reference already obtained at the beginning of unix_stream_sendmsg if the skb allocation is successful:

err = scm_send(sock, msg, siocb->scm);

Now if the second skb allocation failed, the extra scm reference will be released by scm_destroy in the error handling path.

If we can simply copy some information over, that will be ideal and will resolve all the scalability problems.

However, I don't see other obvious info that we can pass to avoid passing pid. Our current credential is pid and uid based, and requires the knowledge of sender's pid to interpret uid to do credentials checking. So without passing the sender pid, I don't see an easy way for the receive side to interpret sender uid it got, which is needed in user_ns_map_uid function when we call cred_to_ucred.

I was trying to do minimal changes to gain some performance. The approach you suggest is great but will probably require much more changes to the credentials infrastructure. Or maybe there are some easy way to do it that I don't see.

Thanks.

Tim

This is the current code. We know its buggy.

I was discussing of things after proposed patch, not current net-next.

This reads :

err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, scm_ref);

So first skb is sent without ref taken, as mentioned in Changelog ?

If second skb cannot be built, we exit this system call with an already queued skb. Receiver can then access to freed memory.

My approach would basically revert the 7361c36c commit too :(

I am sorry, but the only way to avoid too many pid/cred references is to lock the socket [aka unix_state_lock(other);] for the whole send() duration.

This way, you can really increment the pid/cred reference on the last pushed skb, because no reader can 'catch first skb'

As soon as unix_state_unlock(other) is called, everything can happen, so skb must be self contained, as I stated in my earlier mail.

I think we are on the same page.

I think so. I was not fond of commit 7361c36c as it caused a 90% regression in threaded case of hackbench that we noticed back in 2.6.36 days. If there's some way to undo its evil, I'm all for it.

Yes, I think locking the sendmsg for the entire duration of unix_stream_sendmsg makes a lot of sense. It simplifies the logic a lot more. I'll try to cook something up in the next couple of days.

Thanks.

Tim

Thats not really possible, we cant hold a spinlock and call sock_alloc_send_skb() and/or memcpy_fromiovec(), wich might sleep.

You would need to prepare the full skb list, then :
- stick the ref on the last skb of the list.

Transfert the whole skb list in other->sk_receive_queue in one go, instead of one after another.

Unfortunately, this would break streaming (big send(), and another thread doing the receive)

Listen, I am wondering why hackbench even triggers SCM code. This is really odd. We should not have a _single_ pid/cred ref/unref at all.

Hackbench triggers the code because it has a bunch of threads sending msgs on UNIX socket.

Well, if the lock socket approach doesn't work, then my original patch plus Yan Zheng's fix should still work. I'll try to answer your objections below:

No. the first skb is sent *with* ref taken, as scm_ref is set to true for first skb.

No, we do have reference set. For first skb, in unix_scm_to_skb. For the second skb (which is the last skb), in scm_sent. Should the second skb alloc failed, we'll release the ref in scm_destroy. Otherwise, the receiver will release the references will consuming the skb.

Tim

This is crap. This is not the intent of the code I read from the patch.

unless scm_ref really means scm_noref ?

I really hate this patch. I mean it.

I read it 10 times, spent 2 hours and still dont understand it.

@@ -1577,6 +1577,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,

        int sent = 0;
        struct scm_cookie tmp_scm;
        bool fds_sent = false;
+       bool scm_ref = true;
        int max_level;
 
        if (NULL == siocb->scm)
@@ -1637,12 +1638,15 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
                 */
                size = min_t(int, size, skb_tailroom(skb));

+ /* pass the scm reference to the very last skb */

HERE: I understand : on the last skb, set scm_ref to false. So comment is wrong.

+ if (sent + size >= len)
+ scm_ref = false;

-               /* Only send the fds and no ref to pid in the first buffer */
-               err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+               /* Only send the fds in the first buffer */
+               err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, scm_ref);
                if (err < 0) {
                        kfree_skb(skb);
-                       goto out;
+                       goto out_err;
                }

As I said, we should revert the buggy patch, and rewrite a performance fix from scratch, with not a single get_pid()/put_pid() in fast path.

read()/write() on AF_UNIX sockets should not use a single get_pid()/put_pid().

This is a serious regression we should fix at 100%, not 50% or even 75%, adding serious bugs.

Eric,

I've tried another patch to fix my original one. I've used a boolean ref_avail to indicate if there is an outstanding ref to scm not yet encoded into the skb. Hopefully the logic is clearer in this new patch.

That will be ideal if there is another way to fix it 100%, other than reverting commit 7361c36c. Probably if there is some way we know beforehand that both sender and receiver share the same pid, which is quite common, a lot of these pid code can be bypassed.

Tim

---

index 136298c..78be921 100644
@@ -1582,11 +1582,13 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	struct scm_cookie tmp_scm;
 	bool fds_sent = false;
 	int max_level;
+	bool ref_avail; /* scm ref not yet used in skb */
 
 	if (NULL == siocb->scm)
 		siocb->scm = &tmp_scm;
 	wait_for_unix_gc();
 	err = scm_send(sock, msg, siocb->scm);
+	ref_avail = true;
 	if (err < 0)
 		return err;
 

@@ -1642,11 +1644,18 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		size = min_t(int, size, skb_tailroom(skb));
 
 
-		/* Only send the fds and no ref to pid in the first buffer */
-		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+		/* encode scm in skb and use the scm ref */
+		ref_avail = false;
+		if (sent + size < len) { 
+			/* Only send the fds in the first buffer */
+			/* get additional ref if more skbs will be created */
+			err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, true);
+			ref_avail = true;
+		} else
+			err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, false);
 		if (err < 0) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 		max_level = err + 1;
 		fds_sent = true;

@@ -1654,7 +1663,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		err = memcpy_fromiovec(skb_put(skb, size), msg->msg_iov, size);
 		if (err) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 
 		unix_state_lock(other);

@@ -1671,10 +1680,10 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		sent += size;
 	}
 
-	if (skb)
-		scm_release(siocb->scm);
-	else
+	if (ref_avail)
 		scm_destroy(siocb->scm);
+	else
+		scm_release(siocb->scm);
 	siocb->scm = NULL;
 
 	return sent;

@@ -1687,9 +1696,10 @@ pipe_err:
 		send_sig(SIGPIPE, current, 0);
 	err = -EPIPE;
 out_err:
-	if (skb == NULL)
+	if (ref_avail)
 		scm_destroy(siocb->scm);
-out:
+	else
+		scm_release(siocb->scm);
 	siocb->scm = NULL;
 	return sent ? : err;
 }

Let me restate : Its should be obvious to fix the performance hit for good.

If namespaces are not used (CONFIG_PID_NS is not set), we can use the old code, prior to commit 7361c36c : store pid/uid/gid in skb->cb[]

But more generally, when a write() is done on AF_UNIX socket, we pass a NULL siocb->scm to unix_{dgram|stream}_sendmsg()

if (NULL == siocb->scm)

	siocb->scm = &tmp_scm;

There is no need in this case to copy in each skb->cb, pointers to struct pid and struct cred with their atomic reference being changed in the sender and receiver.

We try to remove _all_ atomic ops on refcounts not only because atomic ops are expensive by themselves, but also because of the cache line ping pongs.

When a patch is wrong, you can admit it and ask for a revert, instead of obfuscating the code so much that even a netdev guy like me doesnt understand it anymore.

We speak of a very recent patch in net-next, not yet published to Linus tree. There is no shame to revert it right now and work on a new patch.

I want to be able to track future bugs on this code, and your patch and their fixes made functions too hard to read.

If you dont want to work on it, I'll do it myself.

Sorry, scm_ref means "sender hold a scm reference". I should add comment for it.

There is no "sender holds a scm reference" requirement.

The process is running, so holds a pid and cred by itself.

If pid/cred pointers are stuffed into skb->cb[], then each last skb must holds its own reference to pid and cred.

Problem is : we dont know wich skb _is_ the last one, because we can fail skb allocation or user->kernel copy any time.

Please David just revert 0856a304091b33a8e

I'll work today on a fix to performance regression added in 7361c36c

From: Eric Dumazet <[email protected]>
Date: Wed, 07 Sep 2011 04:55:26 +0200

Done.

Eric,

Can you re-spin a patch that incorporates your idea that we don't add pid/credential references when we are not requesting credentials in the socket. And probably another one that remove unnecessary pid/credentials references in send/receive when we do use credentials?

Tim

Sure, I did it this morning, please review it if you have some time.

If we find a regression (some popular app doing write() and expecting credential to be sent to receiver), we could test the SOCK_PASSCRED flag on receiver socket.

I guess you misunderstood this code. Set scm_ref to false means skb will inherit sender's reference. Then we call unix_scm_to_skb() with parameter 'ref' == false.
So it doesn't get additional reference. I admit my patch is confusing, but I think
Tim's new patch is OK. (even in the case of fail skb allocation or user->kernel copy)

Regards

I want to be able to review the code now, and in two or three years too, without spending hours and hours.

Could you _please_ guys send a patch, with :

1) A good changelog : In this confusing area, this is probably more important than actual code.

2) right logic and right variable names

I am sorry, but this is not good :

+               /* encode scm in skb and use the scm ref */
+               ref_avail = false;
+               if (sent + size < len) { 
+                       /* Only send the fds in the first buffer */
+                       /* get additional ref if more skbs will be created */
+                       err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, true);
+                       ref_avail = true;

+ } else
+ err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, false);

Sorry for my poor English.

	if (sent + size < len) { 
		/* Only send the fds in the first buffer */
		/* get additional ref if more skbs will be created */
		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, true);
	} else {
		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, false);
		ref_avail = false;
	}

Eric,

Your updated patch looks good when I tested it on my side. It makes the patch much more readable. If this patch looks good with you and Yan Zheng, can you and Yan Zheng add your Signed-off-by to the patch?

Jiri, Sedat or Valdis, if you can verify that the patch fixed commit 0856a30409, that will be appreciated.

Eric, are you planning to do a fast path patch that doesn't do pid ref for the case where CONFIG_PID_NS is not set?

Thanks.

Tim

---

Commit 0856a30409 (Scm: Remove unnecessary pid & credential references in Unix socket's send and receive path) introduced a use-after-free bug. The sent skbs from unix_stream_sendmsg could be consumed and destructed by the receive side, removing all references to the credentials, before the send side has finished sending out all
packets. However, send side could continue to consturct new packets in the stream, using credentials that have lost its last reference and been freed.

In this fix, we don't steal the reference to credentials we have obtained in scm_send at beginning of unix_stream_sendmsg, till we've reached the last packet. This fixes the problem in commit 0856a30409.

---

index 136298c..4a324a0 100644
@@ -1383,10 +1383,11 @@ static int unix_attach_fds(struct scm_cookie *scm, struct sk_buff *skb)
 }
 
 static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb,
-			   bool send_fds, bool ref)
+			   bool send_fds, bool steal_refs)
 {
 	int err = 0;
-	if (ref) {
+
+	if (!steal_refs) {
 		UNIXCB(skb).pid  = get_pid(scm->pid);
 		UNIXCB(skb).cred = get_cred(scm->cred);
 	} else {

@@ -1458,7 +1459,7 @@ static int unix_dgram_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (skb == NULL)
 		goto out;
 
-	err = unix_scm_to_skb(siocb->scm, skb, true, false);
+	err = unix_scm_to_skb(siocb->scm, skb, true, true);
 	if (err < 0)
 		goto out_free;
 	max_level = err + 1;

@@ -1581,6 +1582,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	int sent = 0;
 	struct scm_cookie tmp_scm;
 	bool fds_sent = false;
+	bool steal_refs = false;
 	int max_level;
 
 	if (NULL == siocb->scm)

@@ -1642,8 +1644,11 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		size = min_t(int, size, skb_tailroom(skb));
 
 
-		/* Only send the fds and no ref to pid in the first buffer */
-		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+		/* Only send the fds in first buffer
+		 * Last buffer can steal our references to pid/cred
+		 */
+		steal_refs = (sent + size >= len);
+		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, steal_refs);
 		if (err < 0) {
 			kfree_skb(skb);
 			goto out;

@@ -1671,7 +1676,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		sent += size;
 	}
 
-	if (skb)
+	if (steal_refs)
 		scm_release(siocb->scm);
 	else
 		scm_destroy(siocb->scm);

Replaced v2 with this patch (against next-20110831), I see now some different call-traces which I did not see with v1 or v2. Can't say if it's related to the new patch or not.
( dmesg attached. )

- Sedat -

[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Linux version 3.1.0-rc4-next20110831.6-686-small (Debian 3.1.0~rc4-6~next20110831.dileks6) ([email protected]) (gcc version 4.6.1 (Debian 4.6.1-9) ) #1 SMP Wed Sep 7 22:00:52 CEST 2011
[    0.000000] BIOS-provided physical RAM map:
[    0.000000]  BIOS-e820: 0000000000000000 - 000000000009f000 (usable)
[    0.000000]  BIOS-e820: 000000000009f000 - 00000000000a0000 (reserved)
[    0.000000]  BIOS-e820: 00000000000d2000 - 00000000000d4000 (reserved)
[    0.000000]  BIOS-e820: 00000000000dc000 - 0000000000100000 (reserved)
[    0.000000]  BIOS-e820: 0000000000100000 - 000000003ff60000 (usable)
[    0.000000]  BIOS-e820: 000000003ff60000 - 000000003ff77000 (ACPI data)
[    0.000000]  BIOS-e820: 000000003ff77000 - 000000003ff79000 (ACPI NVS)
[    0.000000]  BIOS-e820: 000000003ff80000 - 0000000040000000 (reserved)
[    0.000000]  BIOS-e820: 00000000ff800000 - 0000000100000000 (reserved)
[    0.000000] Notice: NX (Execute Disable) protection missing in CPU!
[    0.000000] DMI present.
[    0.000000] DMI: IBM 2374SG6/2374SG6, BIOS 1RETDRWW (3.23 ) 06/18/2007
[    0.000000] e820 update range: 0000000000000000 - 0000000000010000 (usable) ==> (reserved)
[    0.000000] e820 remove range: 00000000000a0000 - 0000000000100000 (usable)
[    0.000000] last_pfn = 0x3ff60 max_arch_pfn = 0x100000
[    0.000000] MTRR default type: uncachable
[    0.000000] MTRR fixed ranges enabled:
[    0.000000]   00000-9FFFF write-back
[    0.000000]   A0000-BFFFF uncachable
[    0.000000]   C0000-CFFFF write-protect
[    0.000000]   D0000-DBFFF uncachable
[    0.000000]   DC000-DFFFF write-back
[    0.000000]   E0000-FFFFF write-protect
[    0.000000] MTRR variable ranges enabled:
[    0.000000]   0 base 000000000 mask FC0000000 write-back
[    0.000000]   1 base 03FF80000 mask FFFF80000 uncachable
[    0.000000]   2 disabled
[    0.000000]   3 disabled
[    0.000000]   4 disabled
[    0.000000]   5 disabled
[    0.000000]   6 disabled
[    0.000000]   7 disabled
[    0.000000] PAT not supported by CPU.
[    0.000000] initial memory mapped : 0 - 01800000
[    0.000000] Base memory trampoline at [c009b000] 9b000 size 16384
[    0.000000] init_memory_mapping: 0000000000000000-00000000377fe000
[    0.000000]  0000000000 - 0000400000 page 4k
[    0.000000]  0000400000 - 0037400000 page 2M
[    0.000000]  0037400000 - 00377fe000 page 4k
[    0.000000] kernel direct mapping tables up to 377fe000 @ 17ff000-1800000
[    0.000000] RAMDISK: 37830000 - 37c10000
[    0.000000] Allocated new RAMDISK: 3741e000 - 377fd6fc
[    0.000000] Move RAMDISK from 0000000037830000 - 0000000037c0f6fb to 3741e000 - 377fd6fb
[    0.000000] ACPI: RSDP 000f6d70 00024 (v02 IBM   )
[    0.000000] ACPI: XSDT 3ff6a672 0004C (v01 IBM    TP-1R    00003230  LTP 00000000)
[    0.000000] ACPI: FACP 3ff6a700 000F4 (v03 IBM    TP-1R    00003230 IBM  00000001)
[    0.000000] ACPI Warning: 32/64X length mismatch in Gpe1Block: 0/32 (20110623/tbfadt-529)
[    0.000000] ACPI Warning: Optional field Gpe1Block has zero address or length: 0x000000000000102C/0x0 (20110623/tbfadt-560)
[    0.000000] ACPI: DSDT 3ff6a8e7 0C530 (v01 IBM    TP-1R    00003230 MSFT 0100000E)
[    0.000000] ACPI: FACS 3ff78000 00040
[    0.000000] ACPI: SSDT 3ff6a8b4 00033 (v01 IBM    TP-1R    00003230 MSFT 0100000E)
[    0.000000] ACPI: ECDT 3ff76e17 00052 (v01 IBM    TP-1R    00003230 IBM  00000001)
[    0.000000] ACPI: TCPA 3ff76e69 00032 (v01 IBM    TP-1R    00003230 PTL  00000001)
[    0.000000] ACPI: BOOT 3ff76fd8 00028 (v01 IBM    TP-1R    00003230  LTP 00000001)
[    0.000000] 135MB HIGHMEM available.
[    0.000000] 887MB LOWMEM available.
[    0.000000]   mapped low ram: 0 - 377fe000
[    0.000000]   low ram: 0 - 377fe000
[    0.000000] Zone PFN ranges:
[    0.000000]   DMA      0x00000010 -> 0x00001000
[    0.000000]   Normal   0x00001000 -> 0x000377fe
[    0.000000]   HighMem  0x000377fe -> 0x0003ff60
[    0.000000] Movable zone start PFN for each node
[    0.000000] early_node_map[2] active PFN ranges
[    0.000000]     0: 0x00000010 -> 0x0000009f
[    0.000000]     0: 0x00000100 -> 0x0003ff60
[    0.000000] On node 0 totalpages: 261871
[    0.000000] free_area_init_node: node 0, pgdat c1426a40, node_mem_map f6c1d200
[    0.000000]   DMA zone: 32 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 3951 pages, LIFO batch:0
[    0.000000]   Normal zone: 1744 pages used for memmap
[    0.000000]   Normal zone: 221486 pages, LIFO batch:31
[    0.000000]   HighMem zone: 271 pages used for memmap
[    0.000000]   HighMem zone: 34387 pages, LIFO batch:7
[    0.000000] Using APIC driver default
[    0.000000] ACPI: PM-Timer IO Port: 0x1008
[    0.000000] SMP: Allowing 1 CPUs, 0 hotplug CPUs
[    0.000000] Local APIC disabled by BIOS -- reenabling.
[    0.000000] Found and enabled local APIC!
[    0.000000] nr_irqs_gsi: 16
[    0.000000] Allocating PCI resources starting at 40000000 (gap: 40000000:bf800000)
[    0.000000] Booting paravirtualized kernel on bare hardware
[    0.000000] setup_percpu: NR_CPUS:32 nr_cpumask_bits:32 nr_cpu_ids:1 nr_node_ids:1
[    0.000000] PERCPU: Embedded 13 pages/cpu @f6800000 s29120 r0 d24128 u4194304
[    0.000000] pcpu-alloc: s29120 r0 d24128 u4194304 alloc=1*4194304
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 259824
[    0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-3.1.0-rc4-next20110831.6-686-small root=UUID=1ceb69a7-ecf4-47e9-a231-b74e0f0a9b62 ro init=/bin/systemd radeon.modeset=1 lapic 3
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Initializing CPU#0
[    0.000000] Initializing HighMem for node 0 (000377fe:0003ff60)
[    0.000000] Memory: 1028908k/1047936k available (2742k kernel code, 18576k reserved, 1536k data, 376k init, 138632k highmem)
[    0.000000] virtual kernel memory layout:
[    0.000000]     fixmap  : 0xffd36000 - 0xfffff000   (2852 kB)
[    0.000000]     pkmap   : 0xff800000 - 0xffc00000   (4096 kB)
[    0.000000]     vmalloc : 0xf7ffe000 - 0xff7fe000   ( 120 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xf77fe000   ( 887 MB)
[    0.000000]       .init : 0xc142e000 - 0xc148c000   ( 376 kB)
[    0.000000]       .data : 0xc12adb9b - 0xc142dc00   (1536 kB)
[    0.000000]       .text : 0xc1000000 - 0xc12adb9b   (2742 kB)
[    0.000000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[    0.000000] SLUB: Genslabs=15, HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	RCU debugfs-based tracing is enabled.
[    0.000000] 	RCU dyntick-idle grace-period acceleration is enabled.
[    0.000000] NR_IRQS:1280
[    0.000000] CPU 0 irqstacks, hard=f6418000 soft=f641a000
[    0.000000] Extended CMOS year: 2000
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] Fast TSC calibration using PIT
[    0.000000] Detected 1694.278 MHz processor.
[    0.008003] Calibrating delay loop (skipped), value calculated using timer frequency.. 3388.55 BogoMIPS (lpj=6777112)
[    0.008077] pid_max: default: 32768 minimum: 301
[    0.008233] Security Framework initialized
[    0.008276] SELinux:  Disabled at boot.
[    0.008420] Mount-cache hash table entries: 512
[    0.008981] Initializing cgroup subsys debug
[    0.009019] Initializing cgroup subsys cpuacct
[    0.009087] Initializing cgroup subsys devices
[    0.009122] Initializing cgroup subsys freezer
[    0.009158] Initializing cgroup subsys net_cls
[    0.009193] Initializing cgroup subsys blkio
[    0.009288] mce: CPU supports 5 MCE banks
[    0.009334] CPU0: Thermal monitoring enabled (TM2)
[    0.009446] SMP alternatives: switching to UP code
[    0.012380] Freeing SMP alternatives: 8k freed
[    0.012418] ACPI: Core revision 20110623
[    0.018869] ACPI: setting ELCR to 0200 (from 0800)
[    0.020093] weird, boot CPU (#0) not listed by the BIOS.
[    0.020130] SMP motherboard not detected.
[    0.024008] Enabling APIC mode:  Flat.  Using 0 I/O APICs
[    0.028001] SMP disabled
[    0.028001] Performance Events: p6 PMU driver.
[    0.028001] ... version:                0
[    0.028001] ... bit width:              32
[    0.028001] ... generic registers:      2
[    0.028001] ... value mask:             00000000ffffffff
[    0.028001] ... max period:             000000007fffffff
[    0.028001] ... fixed-purpose events:   0
[    0.028001] ... event mask:             0000000000000003
[    0.028001] NMI watchdog enabled, takes one hw-pmu counter.
[    0.028001] Brought up 1 CPUs
[    0.028001] Total of 1 processors activated (3388.55 BogoMIPS).
[    0.028001] devtmpfs: initialized
[    0.028001] print_constraints: dummy: 
[    0.028001] NET: Registered protocol family 16
[    0.028001] ACPI: bus type pci registered
[    0.028001] PCI: PCI BIOS revision 2.10 entry at 0xfd8d6, last bus=8
[    0.028001] PCI: Using configuration type 1 for base access
[    0.028001] bio: create slab <bio-0> at 0
[    0.028001] ACPI: Added _OSI(Module Device)
[    0.028001] ACPI: Added _OSI(Processor Device)
[    0.028001] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.028001] ACPI: Added _OSI(Processor Aggregator Device)
[    0.029762] ACPI: EC: EC description table is found, configuring boot EC
[    0.040960] ACPI: Interpreter enabled
[    0.041001] ACPI: (supports S0 S3 S5)
[    0.041114] ACPI: Using PIC for interrupt routing
[    0.044634] ACPI: Power Resource [PUBS] (on)
[    0.048546] ACPI: EC: GPE = 0x1c, I/O: command/status = 0x66, data = 0x62
[    0.049111] ACPI: ACPI Dock Station Driver: 3 docks/bays found
[    0.049111] HEST: Table not found.
[    0.049111] PCI: Ignoring host bridge windows from ACPI; if necessary, use "pci=use_crs" and report a bug
[    0.049111] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.049111] pci_root PNP0A03:00: host bridge window [io  0x0000-0x0cf7] (ignored)
[    0.049111] pci_root PNP0A03:00: host bridge window [io  0x0d00-0xffff] (ignored)
[    0.049111] pci_root PNP0A03:00: host bridge window [mem 0x000a0000-0x000bffff] (ignored)
[    0.049111] pci_root PNP0A03:00: host bridge window [mem 0x000d4000-0x000d7fff] (ignored)
[    0.049111] pci_root PNP0A03:00: host bridge window [mem 0x000d8000-0x000dbfff] (ignored)
[    0.049111] pci_root PNP0A03:00: host bridge window [mem 0x40000000-0xfebfffff] (ignored)
[    0.049111] pci 0000:00:00.0: [8086:3340] type 0 class 0x000600
[    0.049111] pci 0000:00:00.0: reg 10: [mem 0xd0000000-0xdfffffff pref]
[    0.049111] pci 0000:00:01.0: [8086:3341] type 1 class 0x000604
[    0.049158] pci 0000:00:1d.0: [8086:24c2] type 0 class 0x000c03
[    0.049204] pci 0000:00:1d.0: reg 20: [io  0x1800-0x181f]
[    0.049239] pci 0000:00:1d.1: [8086:24c4] type 0 class 0x000c03
[    0.049285] pci 0000:00:1d.1: reg 20: [io  0x1820-0x183f]
[    0.049320] pci 0000:00:1d.2: [8086:24c7] type 0 class 0x000c03
[    0.049366] pci 0000:00:1d.2: reg 20: [io  0x1840-0x185f]
[    0.049412] pci 0000:00:1d.7: [8086:24cd] type 0 class 0x000c03
[    0.049436] pci 0000:00:1d.7: reg 10: [mem 0xc0000000-0xc00003ff]
[    0.049517] pci 0000:00:1d.7: PME# supported from D0 D3hot D3cold
[    0.052010] pci 0000:00:1d.7: PME# disabled
[    0.052031] pci 0000:00:1e.0: [8086:2448] type 1 class 0x000604
[    0.052076] pci 0000:00:1f.0: [8086:24cc] type 0 class 0x000601
[    0.052145] pci 0000:00:1f.0: quirk: [io  0x1000-0x107f] claimed by ICH4 ACPI/GPIO/TCO
[    0.052195] pci 0000:00:1f.0: quirk: [io  0x1180-0x11bf] claimed by ICH4 GPIO
[    0.052248] pci 0000:00:1f.1: [8086:24ca] type 0 class 0x000101
[    0.052263] pci 0000:00:1f.1: reg 10: [io  0x0000-0x0007]
[    0.052275] pci 0000:00:1f.1: reg 14: [io  0x0000-0x0003]
[    0.052286] pci 0000:00:1f.1: reg 18: [io  0x0000-0x0007]
[    0.052297] pci 0000:00:1f.1: reg 1c: [io  0x0000-0x0003]
[    0.052309] pci 0000:00:1f.1: reg 20: [io  0x1860-0x186f]
[    0.052320] pci 0000:00:1f.1: reg 24: [mem 0x00000000-0x000003ff]
[    0.052350] pci 0000:00:1f.3: [8086:24c3] type 0 class 0x000c05
[    0.052396] pci 0000:00:1f.3: reg 20: [io  0x1880-0x189f]
[    0.052435] pci 0000:00:1f.5: [8086:24c5] type 0 class 0x000401
[    0.052451] pci 0000:00:1f.5: reg 10: [io  0x1c00-0x1cff]
[    0.052462] pci 0000:00:1f.5: reg 14: [io  0x18c0-0x18ff]
[    0.052473] pci 0000:00:1f.5: reg 18: [mem 0xc0000c00-0xc0000dff]
[    0.052483] pci 0000:00:1f.5: reg 1c: [mem 0xc0000800-0xc00008ff]
[    0.052523] pci 0000:00:1f.5: PME# supported from D0 D3hot D3cold
[    0.052528] pci 0000:00:1f.5: PME# disabled
[    0.052546] pci 0000:00:1f.6: [8086:24c6] type 0 class 0x000703
[    0.052563] pci 0000:00:1f.6: reg 10: [io  0x2400-0x24ff]
[    0.052573] pci 0000:00:1f.6: reg 14: [io  0x2000-0x207f]
[    0.052626] pci 0000:00:1f.6: PME# supported from D0 D3hot D3cold
[    0.052631] pci 0000:00:1f.6: PME# disabled
[    0.052659] pci 0000:01:00.0: [1002:4c66] type 0 class 0x000300
[    0.052675] pci 0000:01:00.0: reg 10: [mem 0xe0000000-0xe7ffffff pref]
[    0.052684] pci 0000:01:00.0: reg 14: [io  0x3000-0x30ff]
[    0.052693] pci 0000:01:00.0: reg 18: [mem 0xc0100000-0xc010ffff]
[    0.052718] pci 0000:01:00.0: reg 30: [mem 0x00000000-0x0001ffff pref]
[    0.052738] pci 0000:01:00.0: supports D1 D2
[    0.052774] pci 0000:00:01.0: PCI bridge to [bus 01-01]
[    0.052811] pci 0000:00:01.0:   bridge window [io  0x3000-0x3fff]
[    0.052817] pci 0000:00:01.0:   bridge window [mem 0xc0100000-0xc01fffff]
[    0.052822] pci 0000:00:01.0:   bridge window [mem 0xe0000000-0xe7ffffff pref]
[    0.052848] pci 0000:02:00.0: [104c:ac55] type 2 class 0x000607
[    0.052867] pci 0000:02:00.0: reg 10: [mem 0xb0000000-0xb0000fff]
[    0.052887] pci 0000:02:00.0: supports D1 D2
[    0.052890] pci 0000:02:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.052896] pci 0000:02:00.0: PME# disabled
[    0.052917] pci 0000:02:00.1: [104c:ac55] type 2 class 0x000607
[    0.052935] pci 0000:02:00.1: reg 10: [mem 0xb1000000-0xb1000fff]
[    0.052955] pci 0000:02:00.1: supports D1 D2
[    0.052959] pci 0000:02:00.1: PME# supported from D0 D1 D2 D3hot D3cold
[    0.052964] pci 0000:02:00.1: PME# disabled
[    0.052992] pci 0000:02:01.0: [8086:101e] type 0 class 0x000200
[    0.053013] pci 0000:02:01.0: reg 10: [mem 0xc0220000-0xc023ffff]
[    0.053024] pci 0000:02:01.0: reg 14: [mem 0xc0200000-0xc020ffff]
[    0.053035] pci 0000:02:01.0: reg 18: [io  0x8000-0x803f]
[    0.053068] pci 0000:02:01.0: reg 30: [mem 0x00000000-0x0000ffff pref]
[    0.053093] pci 0000:02:01.0: PME# supported from D0 D3hot D3cold
[    0.053098] pci 0000:02:01.0: PME# disabled
[    0.053119] pci 0000:02:02.0: [168c:1014] type 0 class 0x000200
[    0.053138] pci 0000:02:02.0: reg 10: [mem 0xc0210000-0xc021ffff]
[    0.053238] pci 0000:00:1e.0: PCI bridge to [bus 02-08] (subtractive decode)
[    0.053279] pci 0000:00:1e.0:   bridge window [io  0x4000-0x8fff]
[    0.053285] pci 0000:00:1e.0:   bridge window [mem 0xc0200000-0xcfffffff]
[    0.053291] pci 0000:00:1e.0:   bridge window [mem 0xe8000000-0xefffffff pref]
[    0.053295] pci 0000:00:1e.0:   bridge window [io  0x0000-0xffff] (subtractive decode)
[    0.053299] pci 0000:00:1e.0:   bridge window [mem 0x00000000-0xffffffff] (subtractive decode)
[    0.053378] pci_bus 0000:00: on NUMA node 0
[    0.053383] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[    0.053436] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.AGP_._PRT]
[    0.053463] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCI1._PRT]
[    0.053571]  pci0000:00: Unable to request _OSC control (_OSC support mask: 0x1e)
[    0.056910] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 9 10 *11)
[    0.057251] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 9 10 *11)
[    0.057589] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 6 7 9 10 *11)
[    0.057926] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 9 10 *11)
[    0.058245] ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 6 7 9 10 11) *0, disabled.
[    0.058613] ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 6 7 9 10 11) *0, disabled.
[    0.058987] ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 9 10 11) *0, disabled.
[    0.059376] ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 6 7 9 10 *11)
[    0.059753] vgaarb: device added: PCI:0000:01:00.0,decodes=io+mem,owns=io+mem,locks=none
[    0.059802] vgaarb: loaded
[    0.059835] vgaarb: bridge control possible 0000:01:00.0
[    0.059920] PCI: Using ACPI for IRQ routing
[    0.060098] PCI: pci_cache_line_size set to 64 bytes
[    0.060167] reserve RAM buffer: 000000000009f000 - 000000000009ffff 
[    0.060172] reserve RAM buffer: 000000003ff60000 - 000000003fffffff 
[    0.062719] pnp: PnP ACPI init
[    0.062784] ACPI: bus type pnp registered
[    0.063451] pnp 00:00: [mem 0x00000000-0x0009ffff]
[    0.063455] pnp 00:00: [mem 0x000c0000-0x000c3fff]
[    0.063459] pnp 00:00: [mem 0x000c4000-0x000c7fff]
[    0.063462] pnp 00:00: [mem 0x000c8000-0x000cbfff]
[    0.063466] pnp 00:00: [mem 0x000cc000-0x000cffff]
[    0.063469] pnp 00:00: [mem 0x000d0000-0x000d3fff]
[    0.063473] pnp 00:00: [mem 0x000d4000-0x000d3fff disabled]
[    0.063476] pnp 00:00: [mem 0x000d8000-0x000d7fff disabled]
[    0.063480] pnp 00:00: [mem 0x000dc000-0x000dffff]
[    0.063483] pnp 00:00: [mem 0x000e0000-0x000e3fff]
[    0.063487] pnp 00:00: [mem 0x000e4000-0x000e7fff]
[    0.063490] pnp 00:00: [mem 0x000e8000-0x000ebfff]
[    0.063493] pnp 00:00: [mem 0x000ec000-0x000effff]
[    0.063497] pnp 00:00: [mem 0x000f0000-0x000fffff]
[    0.063500] pnp 00:00: [mem 0x00100000-0x3fffffff]
[    0.063504] pnp 00:00: [mem 0xfec00000-0xffffffff]
[    0.063596] system 00:00: [mem 0x00000000-0x0009ffff] could not be reserved
[    0.063637] system 00:00: [mem 0x000c0000-0x000c3fff] could not be reserved
[    0.063677] system 00:00: [mem 0x000c4000-0x000c7fff] could not be reserved
[    0.063716] system 00:00: [mem 0x000c8000-0x000cbfff] could not be reserved
[    0.063755] system 00:00: [mem 0x000cc000-0x000cffff] could not be reserved
[    0.063795] system 00:00: [mem 0x000d0000-0x000d3fff] could not be reserved
[    0.063834] system 00:00: [mem 0x000dc000-0x000dffff] could not be reserved
[    0.063874] system 00:00: [mem 0x000e0000-0x000e3fff] could not be reserved
[    0.063913] system 00:00: [mem 0x000e4000-0x000e7fff] could not be reserved
[    0.063952] system 00:00: [mem 0x000e8000-0x000ebfff] could not be reserved
[    0.063992] system 00:00: [mem 0x000ec000-0x000effff] could not be reserved
[    0.064019] system 00:00: [mem 0x000f0000-0x000fffff] could not be reserved
[    0.064058] system 00:00: [mem 0x00100000-0x3fffffff] could not be reserved
[    0.064098] system 00:00: [mem 0xfec00000-0xffffffff] could not be reserved
[    0.064139] system 00:00: Plug and Play ACPI device, IDs PNP0c01 (active)
[    0.064175] pnp 00:01: [bus 00-ff]
[    0.064179] pnp 00:01: [io  0x0cf8-0x0cff]
[    0.064182] pnp 00:01: [io  0x0000-0x0cf7 window]
[    0.064186] pnp 00:01: [io  0x0d00-0xffff window]
[    0.064196] pnp 00:01: [mem 0x000a0000-0x000bffff window]
[    0.064200] pnp 00:01: [mem 0x000c0000-0x000c3fff window]
[    0.064203] pnp 00:01: [mem 0x000c4000-0x000c7fff window]
[    0.064207] pnp 00:01: [mem 0x000c8000-0x000cbfff window]
[    0.064211] pnp 00:01: [mem 0x000cc000-0x000cffff window]
[    0.064215] pnp 00:01: [mem 0x000d0000-0x000d3fff window]
[    0.064218] pnp 00:01: [mem 0x000d4000-0x000d7fff window]
[    0.064222] pnp 00:01: [mem 0x000d8000-0x000dbfff window]
[    0.064226] pnp 00:01: [mem 0x000dc000-0x000dffff window]
[    0.064229] pnp 00:01: [mem 0x000e0000-0x000e3fff window]
[    0.064233] pnp 00:01: [mem 0x000e4000-0x000e7fff window]
[    0.064237] pnp 00:01: [mem 0x000e8000-0x000ebfff window]
[    0.064240] pnp 00:01: [mem 0x000ec000-0x000effff window]
[    0.064244] pnp 00:01: [mem 0x40000000-0xfebfffff window]
[    0.064312] pnp 00:01: Plug and Play ACPI device, IDs PNP0a03 (active)
[    0.064424] pnp 00:02: [io  0x0010-0x001f]
[    0.064428] pnp 00:02: [io  0x0090-0x009f]
[    0.064431] pnp 00:02: [io  0x0024-0x0025]
[    0.064434] pnp 00:02: [io  0x0028-0x0029]
[    0.064437] pnp 00:02: [io  0x002c-0x002d]
[    0.064440] pnp 00:02: [io  0x0030-0x0031]
[    0.064444] pnp 00:02: [io  0x0034-0x0035]
[    0.064447] pnp 00:02: [io  0x0038-0x0039]
[    0.064450] pnp 00:02: [io  0x003c-0x003d]
[    0.064453] pnp 00:02: [io  0x00a4-0x00a5]
[    0.064456] pnp 00:02: [io  0x00a8-0x00a9]
[    0.064459] pnp 00:02: [io  0x00ac-0x00ad]
[    0.064462] pnp 00:02: [io  0x00b0-0x00b5]
[    0.064466] pnp 00:02: [io  0x00b8-0x00b9]
[    0.064469] pnp 00:02: [io  0x00bc-0x00bd]
[    0.064472] pnp 00:02: [io  0x0050-0x0053]
[    0.064475] pnp 00:02: [io  0x0072-0x0077]
[    0.064478] pnp 00:02: [io  0x002e-0x002f]
[    0.064482] pnp 00:02: [io  0x1000-0x107f]
[    0.064485] pnp 00:02: [io  0x1180-0x11bf]
[    0.064488] pnp 00:02: [io  0x15e0-0x15ef]
[    0.064491] pnp 00:02: [io  0x1600-0x162f]
[    0.064494] pnp 00:02: [io  0x1632-0x167f]
[    0.064497] pnp 00:02: [io  0x004e-0x004f]
[    0.064501] pnp 00:02: [io  0x1630-0x1631]
[    0.064589] system 00:02: [io  0x1000-0x107f] has been reserved
[    0.064628] system 00:02: [io  0x1180-0x11bf] has been reserved
[    0.064667] system 00:02: [io  0x15e0-0x15ef] has been reserved
[    0.064705] system 00:02: [io  0x1600-0x162f] has been reserved
[    0.064743] system 00:02: [io  0x1632-0x167f] has been reserved
[    0.064781] system 00:02: [io  0x1630-0x1631] has been reserved
[    0.064819] system 00:02: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.064839] pnp 00:03: [io  0x0000-0x000f]
[    0.064842] pnp 00:03: [io  0x0080-0x008f]
[    0.064846] pnp 00:03: [io  0x00c0-0x00df]
[    0.064849] pnp 00:03: [dma 4]
[    0.064888] pnp 00:03: Plug and Play ACPI device, IDs PNP0200 (active)
[    0.064901] pnp 00:04: [io  0x0061]
[    0.064944] pnp 00:04: Plug and Play ACPI device, IDs PNP0800 (active)
[    0.064957] pnp 00:05: [io  0x00f0]
[    0.064963] pnp 00:05: [irq 13]
[    0.065002] pnp 00:05: Plug and Play ACPI device, IDs PNP0c04 (active)
[    0.065015] pnp 00:06: [io  0x0070-0x0071]
[    0.065018] pnp 00:06: [irq 8]
[    0.065060] pnp 00:06: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.065074] pnp 00:07: [io  0x0060]
[    0.065077] pnp 00:07: [io  0x0064]
[    0.065080] pnp 00:07: [irq 1]
[    0.065119] pnp 00:07: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.065132] pnp 00:08: [irq 12]
[    0.065182] pnp 00:08: Plug and Play ACPI device, IDs IBM0057 PNP0f13 (active)
[    0.065219] pnp 00:09: [io  0x03f0-0x03f5]
[    0.065222] pnp 00:09: [io  0x03f7]
[    0.065226] pnp 00:09: [irq 6]
[    0.065229] pnp 00:09: [dma 2]
[    0.065290] pnp 00:09: Plug and Play ACPI device, IDs PNP0700 (active)
[    0.065388] pnp 00:0a: [io  0x03f8-0x03ff]
[    0.065392] pnp 00:0a: [irq 4]
[    0.065506] pnp 00:0a: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.065625] pnp 00:0b: [io  0x03bc-0x03be]
[    0.065628] pnp 00:0b: [irq 7]
[    0.065728] pnp 00:0b: Plug and Play ACPI device, IDs PNP0400 (active)
[    0.065894] pnp 00:0c: Plug and Play ACPI device, IDs IBM0071 PNP0511 (disabled)
[    0.065961] pnp: PnP ACPI: found 13 devices
[    0.068009] ACPI: ACPI bus type pnp unregistered
[    0.106702] Switching to clocksource acpi_pm
[    0.106765] PCI: max bus depth: 2 pci_try_num: 3
[    0.106795] pci 0000:00:1f.1: BAR 5: assigned [mem 0x40000000-0x400003ff]
[    0.106839] pci 0000:00:1f.1: BAR 5: set to [mem 0x40000000-0x400003ff] (PCI address [0x40000000-0x400003ff])
[    0.106892] pci 0000:01:00.0: BAR 6: assigned [mem 0xc0120000-0xc013ffff pref]
[    0.106939] pci 0000:00:01.0: PCI bridge to [bus 01-01]
[    0.106976] pci 0000:00:01.0:   bridge window [io  0x3000-0x3fff]
[    0.107015] pci 0000:00:01.0:   bridge window [mem 0xc0100000-0xc01fffff]
[    0.107055] pci 0000:00:01.0:   bridge window [mem 0xe0000000-0xe7ffffff pref]
[    0.107108] pci 0000:02:01.0: BAR 6: assigned [mem 0xe8000000-0xe800ffff pref]
[    0.107155] pci 0000:02:00.1: BAR 16: assigned [mem 0xc4000000-0xc7ffffff]
[    0.107194] pci 0000:02:00.1: BAR 15: assigned [mem 0xec000000-0xefffffff pref]
[    0.107241] pci 0000:02:00.1: BAR 14: assigned [io  0x4000-0x40ff]
[    0.107279] pci 0000:02:00.1: BAR 13: assigned [io  0x4400-0x44ff]
[    0.107317] pci 0000:02:00.0: BAR 16: assigned [mem 0xc8000000-0xcbffffff]
[    0.107357] pci 0000:02:00.0: BAR 15: assigned [mem 0xcc000000-0xcfffffff pref]
[    0.107404] pci 0000:02:00.0: BAR 14: assigned [io  0x4800-0x48ff]
[    0.107442] pci 0000:02:00.0: BAR 13: assigned [io  0x4c00-0x4cff]
[    0.107479] pci 0000:02:00.0: CardBus bridge to [bus 03-06]
[    0.107516] pci 0000:02:00.0:   bridge window [io  0x4c00-0x4cff]
[    0.107556] pci 0000:02:00.0:   bridge window [io  0x4800-0x48ff]
[    0.107595] pci 0000:02:00.0:   bridge window [mem 0xcc000000-0xcfffffff pref]
[    0.107643] pci 0000:02:00.0:   bridge window [mem 0xc8000000-0xcbffffff]
[    0.107683] pci 0000:02:00.1: CardBus bridge to [bus 07-07]
[    0.107720] pci 0000:02:00.1:   bridge window [io  0x4400-0x44ff]
[    0.107759] pci 0000:02:00.1:   bridge window [io  0x4000-0x40ff]
[    0.107798] pci 0000:02:00.1:   bridge window [mem 0xec000000-0xefffffff pref]
[    0.107846] pci 0000:02:00.1:   bridge window [mem 0xc4000000-0xc7ffffff]
[    0.107886] pci 0000:00:1e.0: PCI bridge to [bus 02-08]
[    0.107923] pci 0000:00:1e.0:   bridge window [io  0x4000-0x8fff]
[    0.107964] pci 0000:00:1e.0:   bridge window [mem 0xc0200000-0xcfffffff]
[    0.107964] Switched to NOHz mode on CPU #0
[    0.107964] pci 0000:00:1e.0:   bridge window [mem 0xe8000000-0xefffffff pref]
[    0.107964] pci 0000:00:1e.0: setting latency timer to 64
[    0.107964] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 11
[    0.107964] PCI: setting IRQ 11 as level-triggered
[    0.107964] pci 0000:02:00.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
[    0.107964] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 11
[    0.107964] pci 0000:02:00.1: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[    0.107964] pci_bus 0000:00: resource 0 [io  0x0000-0xffff]
[    0.107964] pci_bus 0000:00: resource 1 [mem 0x00000000-0xffffffff]
[    0.107964] pci_bus 0000:01: resource 0 [io  0x3000-0x3fff]
[    0.107964] pci_bus 0000:01: resource 1 [mem 0xc0100000-0xc01fffff]
[    0.107964] pci_bus 0000:01: resource 2 [mem 0xe0000000-0xe7ffffff pref]
[    0.107964] pci_bus 0000:02: resource 0 [io  0x4000-0x8fff]
[    0.107964] pci_bus 0000:02: resource 1 [mem 0xc0200000-0xcfffffff]
[    0.107964] pci_bus 0000:02: resource 2 [mem 0xe8000000-0xefffffff pref]
[    0.107964] pci_bus 0000:02: resource 4 [io  0x0000-0xffff]
[    0.107964] pci_bus 0000:02: resource 5 [mem 0x00000000-0xffffffff]
[    0.107964] pci_bus 0000:03: resource 0 [io  0x4c00-0x4cff]
[    0.107964] pci_bus 0000:03: resource 1 [io  0x4800-0x48ff]
[    0.107964] pci_bus 0000:03: resource 2 [mem 0xcc000000-0xcfffffff pref]
[    0.107964] pci_bus 0000:03: resource 3 [mem 0xc8000000-0xcbffffff]
[    0.107964] pci_bus 0000:07: resource 0 [io  0x4400-0x44ff]
[    0.107964] pci_bus 0000:07: resource 1 [io  0x4000-0x40ff]
[    0.107964] pci_bus 0000:07: resource 2 [mem 0xec000000-0xefffffff pref]
[    0.107964] pci_bus 0000:07: resource 3 [mem 0xc4000000-0xc7ffffff]
[    0.107964] NET: Registered protocol family 2
[    0.107964] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.107964] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.108715] TCP bind hash table entries: 65536 (order: 7, 524288 bytes)
[    0.109904] TCP: Hash tables configured (established 131072 bind 65536)
[    0.109945] TCP reno registered
[    0.109983] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.110055] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.110403] NET: Registered protocol family 1
[    0.110580] pci 0000:01:00.0: Boot video device
[    0.110598] PCI: CLS 32 bytes, default 64
[    0.110714] Unpacking initramfs...
[    0.273404] Freeing initrd memory: 3968k freed
[    0.279885] Simple Boot Flag at 0x35 set to 0x1
[    0.280582] audit: initializing netlink socket (disabled)
[    0.280643] type=2000 audit(1315433090.280:1): initialized
[    0.307695] highmem bounce pool size: 64 pages
[    0.307740] HugeTLB registered 4 MB page size, pre-allocated 0 pages
[    0.310612] VFS: Disk quotas dquot_6.5.2
[    0.310820] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.311083] msgmni has been set to 1746
[    0.311400] alg: No test for stdrng (krng)
[    0.311513] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[    0.311595] io scheduler noop registered
[    0.311631] io scheduler deadline registered
[    0.311672] io scheduler cfq registered (default)
[    0.311988] ERST: Table is not found!
[    0.312128] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.312257] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a NS16550A
[    0.312806] 00:0a: ttyS0 at I/O 0x3f8 (irq = 4) is a NS16550A
[    0.312995] serial 0000:00:1f.6: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[    0.313068] serial 0000:00:1f.6: PCI INT B disabled
[    0.313253] Linux agpgart interface v0.103
[    0.313450] agpgart-intel 0000:00:00.0: Intel 855PM Chipset
[    0.326779] agpgart-intel 0000:00:00.0: AGP aperture is 256M @ 0xd0000000
[    0.327026] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[    0.332952] serio: i8042 KBD port at 0x60,0x64 irq 1
[    0.332995] serio: i8042 AUX port at 0x60,0x64 irq 12
[    0.333201] mousedev: PS/2 mouse device common for all mice
[    0.333296] rtc_cmos 00:06: RTC can wake from S4
[    0.333450] rtc_cmos 00:06: rtc core: registered rtc_cmos as rtc0
[    0.333504] rtc0: alarms up to one month, y3k, 114 bytes nvram
[    0.333552] cpuidle: using governor ladder
[    0.333587] cpuidle: using governor menu
[    0.333955] TCP cubic registered
[    0.334234] NET: Registered protocol family 10
[    0.335129] Mobile IPv6
[    0.335163] NET: Registered protocol family 17
[    0.335202] Registering the dns_resolver key type
[    0.335262] Using IPI No-Shortcut mode
[    0.335448] registered taskstats version 1
[    0.335796] rtc_cmos 00:06: setting system clock to 2011-09-07 22:04:50 UTC (1315433090)
[    0.335898] Initializing network drop monitor service
[    0.336064] Freeing unused kernel memory: 376k freed
[    0.337464] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    0.356203] udevd[44]: starting version 172
[    0.472235] usbcore: registered new interface driver usbfs
[    0.472313] usbcore: registered new interface driver hub
[    0.478464] SCSI subsystem initialized
[    0.480544] usbcore: registered new device driver usb
[    0.481488] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.481573] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
[    0.481614] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
[    0.481900] ACPI: PCI Interrupt Link [LNKH] enabled at IRQ 11
[    0.481942] ehci_hcd 0000:00:1d.7: PCI INT D -> Link[LNKH] -> GSI 11 (level, low) -> IRQ 11
[    0.482011] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[    0.482016] ehci_hcd 0000:00:1d.7: EHCI Host Controller
[    0.482111] ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 1
[    0.482197] ehci_hcd 0000:00:1d.7: debug port 1
[    0.486107] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported
[    0.487116] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[    0.487157] e1000: Copyright (c) 1999-2006 Intel Corporation.
[    0.487232] e1000 0000:02:01.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
[    0.767515] libata version 3.00 loaded.
[    0.769309] thermal LNXTHERM:00: registered as thermal_zone0
[    0.769353] ACPI: Thermal Zone [THM0] (58 C)
[    1.381611] irq 11: nobody cared (try booting with the "irqpoll" option)
[    1.381652] Pid: 76, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[    1.381699] Call Trace:
[    1.381742]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[    1.381779]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[    1.381818]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[    1.381857]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[    1.381893]  [<c10748a0>] handle_irq_event+0x24/0x3c
[    1.381930]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[    1.381967]  [<c1076116>] handle_level_irq+0x4d/0x66
[    1.382003]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[    1.382069]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    1.382109]  [<c12ad230>] ? common_interrupt+0x30/0x38
[    1.382147]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    1.382188]  [<c10700e0>] ? kdb_ps1.part.7+0x72/0xc2
[    1.382226]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[    1.382263]  [<c1034753>] ? __do_softirq+0x42/0x137
[    1.382301]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    1.382336]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[    1.382397]  [<c1003d70>] ? do_IRQ+0x6c/0x80
[    1.382433]  [<c12ad230>] ? common_interrupt+0x30/0x38
[    1.382471]  [<c10700e0>] ? kdb_ps1.part.7+0x72/0xc2
[    1.382513]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[    1.382553]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[    1.382591]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[    1.382629]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[    1.382681]  [<f80a46f5>] ? register_root_hub+0xee/0xee [usbcore]
[    1.382720]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[    1.382764]  [<f80a42a1>] ? usb_hcd_request_irqs+0x52/0x106 [usbcore]
[    1.382811]  [<f80a5176>] ? usb_add_hcd.part.24+0xdd/0x26b [usbcore]
[    1.382857]  [<f80a5369>] ? usb_add_hcd+0x65/0x6d [usbcore]
[    1.382904]  [<f80ae84a>] ? usb_hcd_pci_probe+0x1d6/0x2ce [usbcore]
[    1.382945]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[    1.382984]  [<c11d403b>] ? really_probe+0x72/0xe9
[    1.383021]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[    1.383059]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[    1.383096]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[    1.383134]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[    1.383171]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[    1.383208]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[    1.383246]  [<c11d4593>] ? driver_register+0x77/0xd6
[    1.383285]  [<c107bf2a>] ? tracepoint_module_notify+0x1d/0x21
[    1.383324]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[    1.383369]  [<f82af05d>] ? ehci_hcd_init+0x5d/0x6b [ehci_hcd]
[    1.383407]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[    1.383444]  [<f82af000>] ? 0xf82aefff
[    1.383482]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[    1.383520]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[    1.383556] handlers:
[    1.383595] [<f80a46f5>] usb_hcd_irq
[    1.384008] Disabling IRQ #11
[    1.386522] Refined TSC clocksource calibration: 1694.501 MHz.
[    1.386564] Switching to clocksource tsc
[    1.413999] e1000 0000:02:01.0: eth0: (PCI:33MHz:32-bit) 00:0d:60:b0:62:87
[    1.414050] e1000 0000:02:01.0: eth0: Intel(R) PRO/1000 Network Connection
[    1.414979] ehci_hcd 0000:00:1d.7: irq 11, io mem 0xc0000000
[    1.428012] ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00
[    1.428089] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.428127] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.428174] usb usb1: Product: EHCI Host Controller
[    1.428210] usb usb1: Manufacturer: Linux 3.1.0-rc4-next20110831.6-686-small ehci_hcd
[    1.428258] usb usb1: SerialNumber: 0000:00:1d.7
[    1.428467] hub 1-0:1.0: USB hub found
[    1.428519] hub 1-0:1.0: 6 ports detected
[    1.429365] uhci_hcd: USB Universal Host Controller Interface driver
[    1.429455] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[    1.429494] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[    1.429543] uhci_hcd 0000:00:1d.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
[    1.429602] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[    1.429607] uhci_hcd 0000:00:1d.0: UHCI Host Controller
[    1.429655] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    2.110380] irq 11: nobody cared (try booting with the "irqpoll" option)
[    2.110420] Pid: 76, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[    2.110467] Call Trace:
[    2.110510]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[    2.110548]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[    2.110586]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[    2.110625]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[    2.110661]  [<c10748a0>] handle_irq_event+0x24/0x3c
[    2.110699]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[    2.110736]  [<c1076116>] handle_level_irq+0x4d/0x66
[    2.110771]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[    2.110837]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    2.110877]  [<c12ad230>] ? common_interrupt+0x30/0x38
[    2.110915]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    2.110955]  [<c10700e0>] ? kdb_ps1.part.7+0x72/0xc2
[    2.110993]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[    2.111030]  [<c1034753>] ? __do_softirq+0x42/0x137
[    2.111068]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    2.111103]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[    2.111166]  [<c1015873>] ? smp_apic_timer_interrupt+0x72/0x80
[    2.111207]  [<c12a7f21>] ? apic_timer_interrupt+0x31/0x38
[    2.111249]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[    2.111288]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[    2.111326]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[    2.111363]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[    2.111415]  [<f80a46f5>] ? register_root_hub+0xee/0xee [usbcore]
[    2.111453]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[    2.111498]  [<f80a42a1>] ? usb_hcd_request_irqs+0x52/0x106 [usbcore]
[    2.111544]  [<f80a5176>] ? usb_add_hcd.part.24+0xdd/0x26b [usbcore]
[    2.111590]  [<f80a5369>] ? usb_add_hcd+0x65/0x6d [usbcore]
[    2.111636]  [<f80ae84a>] ? usb_hcd_pci_probe+0x1d6/0x2ce [usbcore]
[    2.111677]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[    2.111716]  [<c11d403b>] ? really_probe+0x72/0xe9
[    2.111753]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[    2.111791]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[    2.111828]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[    2.111865]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[    2.111902]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[    2.111940]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[    2.111977]  [<c11d4593>] ? driver_register+0x77/0xd6
[    2.112006]  [<c10bec3f>] ? kmem_cache_create+0x127/0x164
[    2.112006]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[    2.112006]  [<f8303072>] ? uhci_hcd_init+0x72/0xb0 [uhci_hcd]
[    2.112006]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[    2.112006]  [<f8303000>] ? 0xf8302fff
[    2.112006]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[    2.112006]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[    2.112006] handlers:
[    2.112006] [<f80a46f5>] usb_hcd_irq
[    2.112006] [<f80a46f5>] usb_hcd_irq
[    2.112006] Disabling IRQ #11
[    2.114796] uhci_hcd 0000:00:1d.0: irq 11, io base 0x00001800
[    2.114900] usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
[    2.114940] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.114986] usb usb2: Product: UHCI Host Controller
[    2.115022] usb usb2: Manufacturer: Linux 3.1.0-rc4-next20110831.6-686-small uhci_hcd
[    2.115069] usb usb2: SerialNumber: 0000:00:1d.0
[    2.115289] hub 2-0:1.0: USB hub found
[    2.115328] hub 2-0:1.0: 2 ports detected
[    2.115470] ata_piix 0000:00:1f.1: version 2.13
[    2.115486] ata_piix 0000:00:1f.1: enabling device (0005 -> 0007)
[    2.115762] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
[    2.115803] ata_piix 0000:00:1f.1: PCI INT A -> Link[LNKC] -> GSI 11 (level, low) -> IRQ 11
[    2.115903] ata_piix 0000:00:1f.1: setting latency timer to 64
[    2.116411] scsi0 : ata_piix
[    2.116558] scsi1 : ata_piix
[    2.117206] ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0x1860 irq 14
[    2.117245] ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0x1868 irq 15
[    2.117356] uhci_hcd 0000:00:1d.1: power state changed by ACPI to D0
[    2.117396] uhci_hcd 0000:00:1d.1: power state changed by ACPI to D0
[    2.117608] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
[    2.117647] uhci_hcd 0000:00:1d.1: PCI INT B -> Link[LNKD] -> GSI 11 (level, low) -> IRQ 11
[    2.117700] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[    2.117705] uhci_hcd 0000:00:1d.1: UHCI Host Controller
[    2.117753] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3
[    2.861914] irq 11: nobody cared (try booting with the "irqpoll" option)
[    2.861955] Pid: 76, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[    2.862002] Call Trace:
[    2.862044]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[    2.862082]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[    2.862121]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[    2.862160]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[    2.862196]  [<c10748a0>] handle_irq_event+0x24/0x3c
[    2.862234]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[    2.862270]  [<c1076116>] handle_level_irq+0x4d/0x66
[    2.862306]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[    2.862372]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    2.862413]  [<c12ad230>] ? common_interrupt+0x30/0x38
[    2.862450]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    2.862491]  [<c10700e0>] ? kdb_ps1.part.7+0x72/0xc2
[    2.862528]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[    2.862566]  [<c1034753>] ? __do_softirq+0x42/0x137
[    2.862603]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    2.862639]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[    2.862701]  [<c1015873>] ? smp_apic_timer_interrupt+0x72/0x80
[    2.862742]  [<c12a7f21>] ? apic_timer_interrupt+0x31/0x38
[    2.862784]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[    2.862823]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[    2.862861]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[    2.862898]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[    2.862951]  [<f80a46f5>] ? register_root_hub+0xee/0xee [usbcore]
[    2.862989]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[    2.863034]  [<f80a42a1>] ? usb_hcd_request_irqs+0x52/0x106 [usbcore]
[    2.863080]  [<f80a5176>] ? usb_add_hcd.part.24+0xdd/0x26b [usbcore]
[    2.863126]  [<f80a5369>] ? usb_add_hcd+0x65/0x6d [usbcore]
[    2.863172]  [<f80ae84a>] ? usb_hcd_pci_probe+0x1d6/0x2ce [usbcore]
[    2.863213]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[    2.863252]  [<c11d403b>] ? really_probe+0x72/0xe9
[    2.863289]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[    2.863327]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[    2.863364]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[    2.863401]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[    2.863438]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[    2.863476]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[    2.863513]  [<c11d4593>] ? driver_register+0x77/0xd6
[    2.863552]  [<c10bec3f>] ? kmem_cache_create+0x127/0x164
[    2.863590]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[    2.863634]  [<f8303072>] ? uhci_hcd_init+0x72/0xb0 [uhci_hcd]
[    2.863672]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[    2.863709]  [<f8303000>] ? 0xf8302fff
[    2.863747]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[    2.863785]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[    2.863821] handlers:
[    2.863860] [<f80a46f5>] usb_hcd_irq
[    2.863921] [<f80a46f5>] usb_hcd_irq
[    2.863982] [<f80a46f5>] usb_hcd_irq
[    2.864002] Disabling IRQ #11
[    2.864471] uhci_hcd 0000:00:1d.1: irq 11, io base 0x00001820
[    2.864551] usb usb3: New USB device found, idVendor=1d6b, idProduct=0001
[    2.864591] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.864637] usb usb3: Product: UHCI Host Controller
[    2.864673] usb usb3: Manufacturer: Linux 3.1.0-rc4-next20110831.6-686-small uhci_hcd
[    2.864719] usb usb3: SerialNumber: 0000:00:1d.1
[    2.864913] hub 3-0:1.0: USB hub found
[    2.864951] hub 3-0:1.0: 2 ports detected
[    2.865077] uhci_hcd 0000:00:1d.2: PCI INT C -> Link[LNKC] -> GSI 11 (level, low) -> IRQ 11
[    2.865130] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[    2.865134] uhci_hcd 0000:00:1d.2: UHCI Host Controller
[    2.865181] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4
[    3.669962] irq 11: nobody cared (try booting with the "irqpoll" option)
[    3.670001] Pid: 76, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[    3.670048] Call Trace:
[    3.670084]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[    3.670121]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[    3.670159]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[    3.670197]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[    3.670234]  [<c10748a0>] handle_irq_event+0x24/0x3c
[    3.670271]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[    3.672007]  [<c1076116>] handle_level_irq+0x4d/0x66
[    3.672007]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[    3.672007]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    3.672007]  [<c12ad230>] ? common_interrupt+0x30/0x38
[    3.672007]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    3.672007]  [<c10700e0>] ? kdb_ps1.part.7+0x72/0xc2
[    3.672007]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[    3.672007]  [<c1034753>] ? __do_softirq+0x42/0x137
[    3.672007]  [<c1034711>] ? local_bh_enable+0xa/0xa
[    3.672007]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[    3.672007]  [<c1015873>] ? smp_apic_timer_interrupt+0x72/0x80
[    3.672007]  [<c12a7f21>] ? apic_timer_interrupt+0x31/0x38
[    3.672007]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[    3.672007]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[    3.672007]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[    3.672007]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[    3.672007]  [<f80a46f5>] ? register_root_hub+0xee/0xee [usbcore]
[    3.672007]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[    3.672007]  [<f80a42a1>] ? usb_hcd_request_irqs+0x52/0x106 [usbcore]
[    3.672007]  [<f80a5176>] ? usb_add_hcd.part.24+0xdd/0x26b [usbcore]
[    3.672007]  [<f80a5369>] ? usb_add_hcd+0x65/0x6d [usbcore]
[    3.672007]  [<f80ae84a>] ? usb_hcd_pci_probe+0x1d6/0x2ce [usbcore]
[    3.672007]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[    3.672007]  [<c11d403b>] ? really_probe+0x72/0xe9
[    3.672007]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[    3.672007]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[    3.672007]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[    3.672007]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[    3.672007]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[    3.672007]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[    3.672007]  [<c11d4593>] ? driver_register+0x77/0xd6
[    3.672007]  [<c10bec3f>] ? kmem_cache_create+0x127/0x164
[    3.672007]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[    3.672007]  [<f8303072>] ? uhci_hcd_init+0x72/0xb0 [uhci_hcd]
[    3.672007]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[    3.672007]  [<f8303000>] ? 0xf8302fff
[    3.672007]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[    3.672007]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[    3.672007] handlers:
[    3.672007] [<f80a46f5>] usb_hcd_irq
[    3.672007] [<f80a46f5>] usb_hcd_irq
[    3.672007] [<f80a46f5>] usb_hcd_irq
[    3.672007] [<f80a46f5>] usb_hcd_irq
[    3.672007] Disabling IRQ #11
[    3.675487] ata2.01: NODEV after polling detection
[    3.675634] uhci_hcd 0000:00:1d.2: irq 11, io base 0x00001840
[    3.675712] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001
[    3.675751] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    3.675797] usb usb4: Product: UHCI Host Controller
[    3.675832] usb usb4: Manufacturer: Linux 3.1.0-rc4-next20110831.6-686-small uhci_hcd
[    3.675879] usb usb4: SerialNumber: 0000:00:1d.2
[    3.676089] hub 4-0:1.0: USB hub found
[    3.676126] hub 4-0:1.0: 2 ports detected
[    3.680947] ata2.00: ATAPI: UJDA755yDVD/CDRW, 1.70, max UDMA/33
[    3.681159] ata1.00: HPA detected: current 110257519, native 117210240
[    3.681199] ata1.00: ATA-6: HTS726060M9AT00, MH4OA6BA, max UDMA/100
[    3.681237] ata1.00: 110257519 sectors, multi 16: LBA 
[    3.696664] ata2.00: configured for UDMA/33
[    3.697042] ata1.00: configured for UDMA/100
[    3.697365] scsi 0:0:0:0: Direct-Access     ATA      HTS726060M9AT00  MH4O PQ: 0 ANSI: 5
[    3.700297] scsi 1:0:0:0: CD-ROM            MATSHITA UJDA755yDVD/CDRW 1.70 PQ: 0 ANSI: 5
[    3.715423] sd 0:0:0:0: [sda] 110257519 512-byte logical blocks: (56.4 GB/52.5 GiB)
[    3.715666] sd 0:0:0:0: [sda] Write Protect is off
[    3.715703] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    3.715735] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    3.717500] sr0: scsi3-mmc drive: 24x/24x writer cd/rw xa/form2 cdda tray
[    3.717541] cdrom: Uniform CD-ROM driver Revision: 3.20
[    3.717967] sr 1:0:0:0: Attached scsi CD-ROM sr0
[    3.773787]  sda: sda1 sda2 sda3 sda4 < sda5 sda6 >
[    3.774654] sd 0:0:0:0: [sda] Attached SCSI disk
[    3.779192] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    3.779340] sr 1:0:0:0: Attached scsi generic sg1 type 5
[    3.784123] usb 1-4: new high speed USB device number 3 using ehci_hcd
[    4.192018] usb 1-4: New USB device found, idVendor=152d, idProduct=2329
[    4.192065] usb 1-4: New USB device strings: Mfr=10, Product=11, SerialNumber=3
[    4.192113] usb 1-4: Product: Storagebird 35EV821
[    4.192149] usb 1-4: Manufacturer: 0123456
[    4.192184] usb 1-4: SerialNumber: 000000000340
[    4.231566] usbcore: registered new interface driver uas
[    4.233349] Initializing USB Mass Storage driver...
[    4.233506] scsi2 : usb-storage 1-4:1.0
[    4.233720] usbcore: registered new interface driver usb-storage
[    4.233758] USB Mass Storage support registered.
[    4.340018] usb 3-1: new low speed USB device number 2 using uhci_hcd
[    4.449286] Btrfs loaded
[    4.581277] EXT4-fs (sda5): mounted filesystem with ordered data mode. Opts: (null)
[    5.368071] usb 3-1: New USB device found, idVendor=046d, idProduct=c00e
[    5.368117] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    5.368157] usb 3-1: Product: USB-PS/2 Optical Mouse
[    5.368193] usb 3-1: Manufacturer: Logitech
[    5.380061] scsi 2:0:0:0: Direct-Access     WDC WD10 EAVS-00D7B0           PQ: 0 ANSI: 2 CCS
[    5.381478] sd 2:0:0:0: Attached scsi generic sg2 type 0
[    5.580031] sd 2:0:0:0: [sdb] 1953525168 512-byte logical blocks: (1.00 TB/931 GiB)
[    5.880053] sd 2:0:0:0: [sdb] Write Protect is off
[    5.880096] sd 2:0:0:0: [sdb] Mode Sense: 34 00 00 00
[    6.052421] systemd[1]: systemd 29 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +SYSVINIT +LIBCRYPTSETUP; debian)
[    6.180039] sd 2:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[    7.480022]  sdb: sdb1 sdb2 sdb3 sdb4 < sdb5 sdb6 sdb7 sdb8 >
[    8.380020] sd 2:0:0:0: [sdb] Attached SCSI disk
[    8.393566] systemd[1]: Set hostname to <tbox>.
[   10.252330] cfg80211: Calling CRDA to update world regulatory domain
[   10.695345] ath5k 0000:02:02.0: PCI INT A -> Link[LNKC] -> GSI 11 (level, low) -> IRQ 11
[   10.695468] ath5k 0000:02:02.0: registered as 'phy0'
[   11.500031] irq 11: nobody cared (try booting with the "irqpoll" option)
[   11.500072] Pid: 207, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[   11.500119] Call Trace:
[   11.500162]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[   11.500200]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[   11.500238]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[   11.500277]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   11.500314]  [<c10748a0>] handle_irq_event+0x24/0x3c
[   11.500352]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   11.500389]  [<c1076116>] handle_level_irq+0x4d/0x66
[   11.500424]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[   11.500491]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   11.500532]  [<c12ad230>] ? common_interrupt+0x30/0x38
[   11.500570]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   11.500611]  [<c11400e0>] ? init_tag_map+0x2a/0x76
[   11.500648]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[   11.500686]  [<c1034753>] ? __do_softirq+0x42/0x137
[   11.500723]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   11.500758]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[   11.500821]  [<c1015873>] ? smp_apic_timer_interrupt+0x72/0x80
[   11.500863]  [<c12a7f21>] ? apic_timer_interrupt+0x31/0x38
[   11.500905]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[   11.500943]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[   11.500982]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[   11.501019]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[   11.501071]  [<f86fc575>] ? ath5k_intr.part.29+0x2ec/0x2ec [ath5k]
[   11.501110]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[   11.501159]  [<f8703f8f>] ? ath5k_init_ah+0xcd/0x36e [ath5k]
[   11.501203]  [<c11d1f03>] ? _dev_info+0x28/0x2a
[   11.501251]  [<f87044d4>] ? ath5k_pci_probe+0x199/0x1db [ath5k]
[   11.501291]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[   11.501329]  [<c11d403b>] ? really_probe+0x72/0xe9
[   11.501366]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[   11.501404]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[   11.501441]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[   11.501479]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[   11.501516]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[   11.501553]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[   11.501591]  [<c11d4593>] ? driver_register+0x77/0xd6
[   11.504005]  [<c107bf2a>] ? tracepoint_module_notify+0x1d/0x21
[   11.504005]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[   11.504005]  [<f8714018>] ? init_ath5k_pci+0x18/0x30 [ath5k]
[   11.504005]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[   11.504005]  [<f8714000>] ? 0xf8713fff
[   11.504005]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[   11.504005]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[   11.504005] handlers:
[   11.504005] [<f80a46f5>] usb_hcd_irq
[   11.504005] [<f80a46f5>] usb_hcd_irq
[   11.504005] [<f80a46f5>] usb_hcd_irq
[   11.504005] [<f80a46f5>] usb_hcd_irq
[   11.504005] [<f86fc575>] ath5k_intr
[   11.504005] Disabling IRQ #11
[   11.793389] ath: EEPROM regdomain: 0x61
[   11.793393] ath: EEPROM indicates we should expect a direct regpair map
[   11.793399] ath: Country alpha2 being used: 00
[   11.793401] ath: Regpair used: 0x61
[   11.862418] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
[   11.863296] Registered led device: ath5k-phy0::rx
[   11.863330] Registered led device: ath5k-phy0::tx
[   11.863346] ath5k phy0: Atheros AR5212 chip found (MAC: 0x56, PHY: 0x41)
[   11.863389] ath5k phy0: RF5111 5GHz radio found (0x17)
[   11.863426] ath5k phy0: RF2111 2GHz radio found (0x23)
[   12.223704] udevd[234]: starting version 172
[   13.612380] systemd-fsck[211]: /dev/sda5: clean, 186542/640848 files, 2339358/2560351 blocks (Prüfung nach 2 Einhängevorgängen)
[   14.111684] Non-volatile memory driver v1.3
[   14.154191] input: Video Bus as /devices/LNXSYSTM:00/device:00/PNP0A03:00/device:03/LNXVIDEO:00/input/input1
[   14.154256] ACPI: Video Device [VID] (multi-head: yes  rom: no  post: no)
[   14.321059] input: Lid Switch as /devices/LNXSYSTM:00/device:00/PNP0C0D:00/input/input2
[   14.322513] ACPI: Lid Switch [LID]
[   14.322659] input: Sleep Button as /devices/LNXSYSTM:00/device:00/PNP0C0E:00/input/input3
[   14.322712] ACPI: Sleep Button [SLPB]
[   14.322848] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input4
[   14.322896] ACPI: Power Button [PWRF]
[   14.336427] input: PC Speaker as /devices/platform/pcspkr/input/input5
[   14.400627] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[   14.421973] parport_pc 00:0b: reported by Plug and Play ACPI
[   14.422057] parport0: PC-style at 0x3bc, irq 7 [PCSPP,TRISTATE]
[   14.422787] i801_smbus 0000:00:1f.3: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[   14.427447] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[   14.510982] ACPI: acpi_idle registered with cpuidle
[   14.511504] Marking TSC unstable due to TSC halts in idle
[   14.513739] Switching to clocksource acpi_pm
[   14.689650] EXT4-fs (sda5): re-mounted. Opts: (null)
[   14.711920] ACPI: AC Adapter [AC] (on-line)
[   14.731214] ACPI: Battery Slot [BAT0] (battery present)
[   14.773440] yenta_cardbus 0000:02:00.0: CardBus bridge found [1014:0512]
[   14.773498] yenta_cardbus 0000:02:00.0: Using INTVAL to route CSC interrupts to PCI
[   14.773545] yenta_cardbus 0000:02:00.0: Routing CardBus interrupts to PCI
[   14.773585] yenta_cardbus 0000:02:00.0: TI: mfunc 0x01d21022, devctl 0x64
[   15.916743] irq 11: nobody cared (try booting with the "irqpoll" option)
[   15.916784] Pid: 399, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[   15.916831] Call Trace:
[   15.916875]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[   15.916912]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[   15.916951]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[   15.916990]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   15.917026]  [<c10748a0>] handle_irq_event+0x24/0x3c
[   15.917064]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   15.917100]  [<c1076116>] handle_level_irq+0x4d/0x66
[   15.917136]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[   15.917202]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   15.917244]  [<c12ad230>] ? common_interrupt+0x30/0x38
[   15.917281]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   15.917322]  [<c11400e0>] ? init_tag_map+0x2a/0x76
[   15.917359]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[   15.917397]  [<c1034753>] ? __do_softirq+0x42/0x137
[   15.917434]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   15.917469]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[   15.917532]  [<c1015873>] ? smp_apic_timer_interrupt+0x72/0x80
[   15.917574]  [<c12a7f21>] ? apic_timer_interrupt+0x31/0x38
[   15.917616]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[   15.917655]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[   15.917693]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[   15.917730]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[   15.917772]  [<f8a3d3be>] ? yenta_sock_suspend+0x16/0x16 [yenta_socket]
[   15.917812]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[   15.917854]  [<c11d1ed0>] ? __dev_printk+0x3e/0x49
[   15.917894]  [<f8a3d7c1>] ? yenta_probe_cb_irq+0x37/0x10e [yenta_socket]
[   15.917937]  [<f8a3e3f1>] ? ti12xx_irqroute_func0+0x53/0x20e [yenta_socket]
[   15.917980]  [<f8a3e699>] ? ti12xx_override+0xed/0x10d [yenta_socket]
[   15.918022]  [<f8a3f43b>] ? yenta_probe+0x17b/0x2fc [yenta_socket]
[   15.918062]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[   15.918100]  [<c11d403b>] ? really_probe+0x72/0xe9
[   15.918137]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[   15.918175]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[   15.918212]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[   15.918249]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[   15.918286]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[   15.918324]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[   15.918361]  [<c11d4593>] ? driver_register+0x77/0xd6
[   15.918401]  [<c107bf2a>] ? tracepoint_module_notify+0x1d/0x21
[   15.918439]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[   15.918480]  [<f8a42017>] ? yenta_socket_init+0x17/0x19 [yenta_socket]
[   15.918519]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[   15.918561]  [<f8a42000>] ? 0xf8a41fff
[   15.918599]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[   15.918637]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[   15.918673] handlers:
[   15.918718] [<f80a46f5>] usb_hcd_irq
[   15.918780] [<f80a46f5>] usb_hcd_irq
[   15.918842] [<f80a46f5>] usb_hcd_irq
[   15.918903] [<f80a46f5>] usb_hcd_irq
[   15.918968] [<f86fc575>] ath5k_intr
[   15.919025] [<f8a3d3be>] yenta_probe_handler
[   15.919080] Disabling IRQ #11
[   15.920963] [drm] Initialized drm 1.1.0 20060810
[   17.167176] irq 11: nobody cared (try booting with the "irqpoll" option)
[   17.167224] Pid: 399, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[   17.167271] Call Trace:
[   17.167315]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[   17.167352]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[   17.167391]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[   17.167430]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   17.167466]  [<c10748a0>] handle_irq_event+0x24/0x3c
[   17.167503]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   17.167540]  [<c1076116>] handle_level_irq+0x4d/0x66
[   17.167576]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[   17.167641]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   17.167682]  [<c12ad230>] ? common_interrupt+0x30/0x38
[   17.167720]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   17.167760]  [<c10700e0>] ? kdb_ps1.part.7+0x72/0xc2
[   17.167798]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[   17.167836]  [<c1034753>] ? __do_softirq+0x42/0x137
[   17.167873]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   17.167908]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[   17.167971]  [<c1015873>] ? smp_apic_timer_interrupt+0x72/0x80
[   17.168012]  [<c12a7f21>] ? apic_timer_interrupt+0x31/0x38
[   17.168012]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[   17.168012]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[   17.168012]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[   17.168012]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[   17.168012]  [<f8a3d3fd>] ? yenta_probe_handler+0x3f/0x3f [yenta_socket]
[   17.168012]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[   17.168012]  [<f8a3f463>] ? yenta_probe+0x1a3/0x2fc [yenta_socket]
[   17.168012]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[   17.168012]  [<c11d403b>] ? really_probe+0x72/0xe9
[   17.168012]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[   17.168012]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[   17.168012]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[   17.168012]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[   17.168012]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[   17.168012]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[   17.168012]  [<c11d4593>] ? driver_register+0x77/0xd6
[   17.168012]  [<c107bf2a>] ? tracepoint_module_notify+0x1d/0x21
[   17.168012]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[   17.168012]  [<f8a42017>] ? yenta_socket_init+0x17/0x19 [yenta_socket]
[   17.168012]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[   17.168012]  [<f8a42000>] ? 0xf8a41fff
[   17.168012]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[   17.168012]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[   17.168012] handlers:
[   17.168012] [<f80a46f5>] usb_hcd_irq
[   17.168012] [<f80a46f5>] usb_hcd_irq
[   17.168012] [<f80a46f5>] usb_hcd_irq
[   17.168012] [<f80a46f5>] usb_hcd_irq
[   17.168012] [<f86fc575>] ath5k_intr
[   17.168012] [<f8a3d3fd>] yenta_interrupt
[   17.168012] Disabling IRQ #11
[   17.201477] NET: Registered protocol family 23
[   17.244258] Synaptics Touchpad, model: 1, fw: 5.9, id: 0x2c6ab1, caps: 0x884793/0x0/0x0
[   17.247204] serio: Synaptics pass-through port at isa0060/serio1/input0
[   17.292065] input: SynPS/2 Synaptics TouchPad as /devices/platform/i8042/serio1/input/input6
[   17.301315] yenta_cardbus 0000:02:00.0: ISA IRQ mask 0x0438, PCI irq 11
[   17.301362] yenta_cardbus 0000:02:00.0: Socket status: 30000006
[   17.302056] yenta_cardbus 0000:02:00.0: pcmcia: parent PCI bridge window: [io  0x4000-0x8fff]
[   17.302108] yenta_cardbus 0000:02:00.0: pcmcia: parent PCI bridge window: [mem 0xc0200000-0xcfffffff]
[   17.302158] pcmcia_socket pcmcia_socket0: cs: memory probe 0xc0200000-0xcfffffff: excluding 0xc0200000-0xc09fffff 0xc3a00000-0xd01fffff
[   17.302317] yenta_cardbus 0000:02:00.0: pcmcia: parent PCI bridge window: [mem 0xe8000000-0xefffffff pref]
[   17.302366] pcmcia_socket pcmcia_socket0: cs: memory probe 0xe8000000-0xefffffff: excluding 0xe8000000-0xefffffff
[   17.305691] yenta_cardbus 0000:02:00.1: CardBus bridge found [1014:0512]
[   17.305749] yenta_cardbus 0000:02:00.1: Using INTVAL to route CSC interrupts to PCI
[   17.305795] yenta_cardbus 0000:02:00.1: Routing CardBus interrupts to PCI
[   17.305836] yenta_cardbus 0000:02:00.1: TI: mfunc 0x01d21022, devctl 0x64
[   18.696503] irq 11: nobody cared (try booting with the "irqpoll" option)
[   18.696545] Pid: 399, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[   18.696592] Call Trace:
[   18.696635]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[   18.696673]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[   18.696711]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[   18.696750]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   18.696787]  [<c10748a0>] handle_irq_event+0x24/0x3c
[   18.696824]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   18.696861]  [<c1076116>] handle_level_irq+0x4d/0x66
[   18.696897]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[   18.696962]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   18.697003]  [<c12ad230>] ? common_interrupt+0x30/0x38
[   18.697040]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   18.697081]  [<c10700e0>] ? kdb_ps1.part.7+0x72/0xc2
[   18.697119]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[   18.697157]  [<c1034753>] ? __do_softirq+0x42/0x137
[   18.697194]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   18.697229]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[   18.697292]  [<c1015873>] ? smp_apic_timer_interrupt+0x72/0x80
[   18.697333]  [<c12a7f21>] ? apic_timer_interrupt+0x31/0x38
[   18.697375]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[   18.697414]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[   18.697452]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[   18.697489]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[   18.697538]  [<f8a3d3be>] ? yenta_sock_suspend+0x16/0x16 [yenta_socket]
[   18.697577]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[   18.697619]  [<f8a3d7c1>] ? yenta_probe_cb_irq+0x37/0x10e [yenta_socket]
[   18.697662]  [<f8a3de70>] ? ti12xx_irqroute_func1+0x6f/0x190 [yenta_socket]
[   18.697704]  [<f8a3e6a0>] ? ti12xx_override+0xf4/0x10d [yenta_socket]
[   18.697747]  [<f8a3f43b>] ? yenta_probe+0x17b/0x2fc [yenta_socket]
[   18.697787]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[   18.697827]  [<c11d403b>] ? really_probe+0x72/0xe9
[   18.697864]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[   18.697902]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[   18.697939]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[   18.697976]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[   18.698013]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[   18.698051]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[   18.698088]  [<c11d4593>] ? driver_register+0x77/0xd6
[   18.698128]  [<c107bf2a>] ? tracepoint_module_notify+0x1d/0x21
[   18.698166]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[   18.698208]  [<f8a42017>] ? yenta_socket_init+0x17/0x19 [yenta_socket]
[   18.698247]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[   18.698302]  [<f8a42000>] ? 0xf8a41fff
[   18.698340]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[   18.698378]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[   18.698414] handlers:
[   18.698459] [<f80a46f5>] usb_hcd_irq
[   18.698521] [<f80a46f5>] usb_hcd_irq
[   18.698582] [<f80a46f5>] usb_hcd_irq
[   18.698644] [<f80a46f5>] usb_hcd_irq
[   18.698709] [<f86fc575>] ath5k_intr
[   18.698766] [<f8a3d3fd>] yenta_interrupt
[   18.698824] [<f8a3d3be>] yenta_probe_handler
[   18.698879] Disabling IRQ #11
[   18.730807] thinkpad_acpi: ThinkPad ACPI Extras v0.24
[   18.730850] thinkpad_acpi: http://ibm-acpi.sf.net/
[   18.730886] thinkpad_acpi: ThinkPad BIOS 1RETDRWW (3.23 ), EC 1RHT71WW-3.04
[   18.730924] thinkpad_acpi: IBM ThinkPad T40p, model 2374SG6
[   18.733373] thinkpad_acpi: detected a 8-level brightness capable ThinkPad
[   18.741263] thinkpad_acpi: rfkill switch tpacpi_bluetooth_sw: radio is blocked
[   18.742250] Registered led device: tpacpi::thinklight
[   18.742583] Registered led device: tpacpi::power
[   18.742888] Registered led device: tpacpi::standby
[   18.748174] thinkpad_acpi: Console audio control enabled, mode: monitor (read only)
[   18.751681] input: ThinkPad Extra Buttons as /devices/platform/thinkpad_acpi/input/input7
[   18.797894] snd_intel8x0 0000:00:1f.5: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[   18.797984] snd_intel8x0 0000:00:1f.5: setting latency timer to 64
[   20.190625] irq 11: nobody cared (try booting with the "irqpoll" option)
[   20.190666] Pid: 399, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[   20.190713] Call Trace:
[   20.190757]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[   20.190795]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[   20.190833]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[   20.190872]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   20.190909]  [<c10748a0>] handle_irq_event+0x24/0x3c
[   20.190946]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   20.190983]  [<c1076116>] handle_level_irq+0x4d/0x66
[   20.191019]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[   20.191084]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   20.191125]  [<c12ad230>] ? common_interrupt+0x30/0x38
[   20.191163]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   20.191203]  [<c10700e0>] ? kdb_ps1.part.7+0x72/0xc2
[   20.191241]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[   20.191279]  [<c1034753>] ? __do_softirq+0x42/0x137
[   20.191316]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   20.191352]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[   20.191415]  [<c1015873>] ? smp_apic_timer_interrupt+0x72/0x80
[   20.191456]  [<c12a7f21>] ? apic_timer_interrupt+0x31/0x38
[   20.191498]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[   20.191537]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[   20.191576]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[   20.191613]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[   20.191661]  [<f8a3d3fd>] ? yenta_probe_handler+0x3f/0x3f [yenta_socket]
[   20.191701]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[   20.191743]  [<f8a3f463>] ? yenta_probe+0x1a3/0x2fc [yenta_socket]
[   20.191784]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[   20.191822]  [<c11d403b>] ? really_probe+0x72/0xe9
[   20.191859]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[   20.191897]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[   20.191935]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[   20.191972]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[   20.192009]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[   20.192015]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[   20.192015]  [<c11d4593>] ? driver_register+0x77/0xd6
[   20.192015]  [<c107bf2a>] ? tracepoint_module_notify+0x1d/0x21
[   20.192015]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[   20.192015]  [<f8a42017>] ? yenta_socket_init+0x17/0x19 [yenta_socket]
[   20.192015]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[   20.192015]  [<f8a42000>] ? 0xf8a41fff
[   20.192015]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[   20.192015]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[   20.192015] handlers:
[   20.192015] [<f80a46f5>] usb_hcd_irq
[   20.192015] [<f80a46f5>] usb_hcd_irq
[   20.192015] [<f80a46f5>] usb_hcd_irq
[   20.192015] [<f80a46f5>] usb_hcd_irq
[   20.192015] [<f86fc575>] ath5k_intr
[   20.192015] [<f8a3d3fd>] yenta_interrupt
[   20.192015] [<f8a3d3fd>] yenta_interrupt
[   20.192015] Disabling IRQ #11
[   20.320908] yenta_cardbus 0000:02:00.1: ISA IRQ mask 0x0438, PCI irq 11
[   20.320962] yenta_cardbus 0000:02:00.1: Socket status: 30000006
[   20.321009] yenta_cardbus 0000:02:00.1: pcmcia: parent PCI bridge window: [io  0x4000-0x8fff]
[   20.321059] yenta_cardbus 0000:02:00.1: pcmcia: parent PCI bridge window: [mem 0xc0200000-0xcfffffff]
[   20.321109] pcmcia_socket pcmcia_socket1: cs: memory probe 0xc0200000-0xcfffffff: excluding 0xc0200000-0xc09fffff 0xc3a00000-0xd01fffff
[   20.321268] yenta_cardbus 0000:02:00.1: pcmcia: parent PCI bridge window: [mem 0xe8000000-0xefffffff pref]
[   20.321318] pcmcia_socket pcmcia_socket1: cs: memory probe 0xe8000000-0xefffffff: excluding 0xe8000000-0xefffffff
[   21.909958] irq 11: nobody cared (try booting with the "irqpoll" option)
[   21.910006] Pid: 356, comm: modprobe Not tainted 3.1.0-rc4-next20110831.6-686-small #1
[   21.910054] Call Trace:
[   21.910098]  [<c10758f9>] __report_bad_irq+0x1f/0x95
[   21.910136]  [<c1075bb2>] note_interrupt+0xb4/0x11e
[   21.910174]  [<c1074866>] handle_irq_event_percpu+0x141/0x157
[   21.910213]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   21.910250]  [<c10748a0>] handle_irq_event+0x24/0x3c
[   21.910287]  [<c10760c9>] ? unmask_irq+0x1e/0x1e
[   21.910324]  [<c1076116>] handle_level_irq+0x4d/0x66
[   21.910360]  <IRQ>  [<c1003d39>] ? do_IRQ+0x35/0x80
[   21.910425]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   21.910466]  [<c12ad230>] ? common_interrupt+0x30/0x38
[   21.910504]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   21.910544]  [<c12a00d8>] ? alloc_debug_processing+0xa4/0xbe
[   21.910582]  [<c1033d31>] ? arch_local_irq_enable+0x5/0xb
[   21.910620]  [<c1034753>] ? __do_softirq+0x42/0x137
[   21.910657]  [<c1034711>] ? local_bh_enable+0xa/0xa
[   21.910692]  <IRQ>  [<c10349a6>] ? irq_exit+0x35/0x84
[   21.910755]  [<c1015873>] ? smp_apic_timer_interrupt+0x72/0x80
[   21.910796]  [<c12a7f21>] ? apic_timer_interrupt+0x31/0x38
[   21.910838]  [<c1057459>] ? arch_local_irq_restore+0x5/0xb
[   21.912008]  [<c12a733d>] ? _raw_spin_unlock_irqrestore+0xe/0x10
[   21.912008]  [<c107566a>] ? __setup_irq+0x2a1/0x319
[   21.912008]  [<c1075750>] ? request_threaded_irq+0x6e/0xd4
[   21.912008]  [<f8cb6a1e>] ? snd_intel8x0_pcm_prepare+0x6a/0x6a [snd_intel8x0]
[   21.912008]  [<c107578f>] ? request_threaded_irq+0xad/0xd4
[   21.912008]  [<f8cb7711>] ? snd_intel8x0_chip_init.part.15+0xaf/0xd7 [snd_intel8x0]
[   21.912008]  [<f8cb8330>] ? snd_intel8x0_create+0x37d/0x3f4 [snd_intel8x0]
[   21.912008]  [<f8cb8809>] ? snd_intel8x0_probe+0xf8/0x23a [snd_intel8x0]
[   21.912008]  [<c11d9757>] ? pm_runtime_enable+0x50/0x58
[   21.912008]  [<c1166a4d>] ? pci_device_probe+0x5a/0xa3
[   21.912008]  [<c11d403b>] ? really_probe+0x72/0xe9
[   21.912008]  [<c11d4191>] ? driver_probe_device+0x2c/0x41
[   21.912008]  [<c11d41e9>] ? __driver_attach+0x43/0x5f
[   21.912008]  [<c11d3642>] ? bus_for_each_dev+0x3d/0x66
[   21.912008]  [<c11d3e90>] ? driver_attach+0x17/0x1c
[   21.912008]  [<c11d41a6>] ? driver_probe_device+0x41/0x41
[   21.912008]  [<c11d3baa>] ? bus_add_driver+0x88/0x1b2
[   21.912008]  [<c11d4593>] ? driver_register+0x77/0xd6
[   21.912008]  [<c107bf2a>] ? tracepoint_module_notify+0x1d/0x21
[   21.912008]  [<c1166e14>] ? __pci_register_driver+0x35/0x91
[   21.912008]  [<f8cbc017>] ? alsa_card_intel8x0_init+0x17/0x19 [snd_intel8x0]
[   21.912008]  [<c100116f>] ? do_one_initcall+0x71/0x11a
[   21.912008]  [<f8cbc000>] ? 0xf8cbbfff
[   21.912008]  [<c105b22e>] ? sys_init_module+0x64/0x18a
[   21.912008]  [<c12acc9f>] ? sysenter_do_call+0x12/0x28
[   21.912008] handlers:
[   21.912008] [<f80a46f5>] usb_hcd_irq
[   21.912008] [<f80a46f5>] usb_hcd_irq
[   21.912008] [<f80a46f5>] usb_hcd_irq
[   21.912008] [<f80a46f5>] usb_hcd_irq
[   21.912008] [<f86fc575>] ath5k_intr
[   21.912008] [<f8a3d3fd>] yenta_interrupt
[   21.912008] [<f8a3d3fd>] yenta_interrupt
[   21.912008] [<f8cb6a1e>] snd_intel8x0_interrupt
[   21.912008] Disabling IRQ #11
[   21.967300] nsc-ircc 00:0c: [io  0x02f8-0x02ff]
[   21.967369] nsc-ircc 00:0c: [irq 3]
[   21.967375] nsc-ircc 00:0c: [dma 1]
[   21.967831] nsc-ircc 00:0c: activated
[   21.968080] nsc-ircc, chip->init
[   21.968121] nsc-ircc, Found chip at base=0x02e
[   21.968177] nsc-ircc, driver loaded (Dag Brattli)
[   21.971645] IrDA: Registered device irda0
[   21.971687] nsc-ircc, Using dongle: IBM31T1100 or Temic TFDS6000/TFDS6500
[   21.973723] [drm] radeon kernel modesetting enabled.
[   21.973893] radeon 0000:01:00.0: power state changed by ACPI to D0
[   21.973934] radeon 0000:01:00.0: power state changed by ACPI to D0
[   21.973982] radeon 0000:01:00.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
[   21.976372] [drm] initializing kernel modesetting (RV250 0x1002:0x4C66 0x1014:0x054D).
[   21.976451] [drm] register mmio base: 0xC0100000
[   21.976485] [drm] register mmio size: 65536
[   21.976846] agpgart-intel 0000:00:00.0: AGP 2.0 bridge
[   21.976896] agpgart-intel 0000:00:00.0: putting AGP V2 device into 4x mode
[   21.976970] radeon 0000:01:00.0: putting AGP V2 device into 4x mode
[   21.977033] radeon 0000:01:00.0: GTT: 256M 0xD0000000 - 0xDFFFFFFF
[   21.977077] radeon 0000:01:00.0: VRAM: 128M 0x00000000E0000000 - 0x00000000E7FFFFFF (64M used)
[   21.977131] [drm] Supports vblank timestamp caching Rev 1 (10.10.2010).
[   21.977168] [drm] Driver supports precise vblank timestamp query.
[   21.977223] [drm] radeon: irq initialized.
[   21.980627] [drm] Detected VRAM RAM=128M, BAR=128M
[   21.980669] [drm] RAM width 128bits DDR
[   21.983409] [TTM] Zone  kernel: Available graphics memory: 447314 kiB.
[   21.983453] [TTM] Zone highmem: Available graphics memory: 516630 kiB.
[   21.983491] [TTM] Initializing pool allocator.
[   21.983701] [drm] radeon: 64M of VRAM memory ready
[   21.983737] [drm] radeon: 256M of GTT memory ready.
[   21.985319] radeon 0000:01:00.0: WB enabled
[   21.986295] [drm] Loading R200 Microcode
[   22.044684] mtp-probe[392]: checking bus 1, device 3: "/sys/devices/pci0000:00/0000:00:1d.7/usb1/1-4"
[   22.044799] mtp-probe[390]: checking bus 3, device 2: "/sys/devices/pci0000:00/0000:00:1d.1/usb3/3-1"
[   22.121186] pcmcia_socket pcmcia_socket0: cs: memory probe 0x0c0000-0x0fffff: excluding 0xc0000-0xd3fff 0xdc000-0xfffff
[   22.121357] pcmcia_socket pcmcia_socket0: cs: memory probe 0xa0000000-0xa0ffffff: clean.
[   22.121455] pcmcia_socket pcmcia_socket0: cs: memory probe 0x60000000-0x60ffffff: clean.
[   22.121737] pcmcia_socket pcmcia_socket1: cs: memory probe 0x0c0000-0x0fffff: excluding 0xc0000-0xd3fff 0xdc000-0xfffff
[   22.121897] pcmcia_socket pcmcia_socket1: cs: memory probe 0xa0000000-0xa0ffffff: clean.
[   22.121995] pcmcia_socket pcmcia_socket1: cs: memory probe 0x60000000-0x60ffffff: clean.
[   22.124288] mtp-probe[392]: bus: 1, device: 3 was not an MTP device
[   22.124474] mtp-probe[390]: bus: 3, device: 2 was not an MTP device
[   22.153067] ata_id[502]: HDIO_GET_IDENTITY failed for '/dev/sdb': Invalid argument
[   22.266318] [drm] radeon: ring at 0x00000000D0001000
[   22.425068] [drm:r100_ring_test] *ERROR* radeon: ring test failed (scratch(0x15E4)=0xCAFEDEAD)
[   22.425117] [drm:r100_cp_init] *ERROR* radeon: cp isn't working (-22).
[   22.425156] radeon 0000:01:00.0: failed initializing CP (-22).
[   22.425192] radeon 0000:01:00.0: Disabling GPU acceleration
[   22.426561] [drm] radeon: cp finalized
[   22.426626] [drm] radeon: cp finalized
[   22.426678] [TTM] Finalizing pool allocator.
[   22.427442] [TTM] Zone  kernel: Used memory at exit: 0 kiB.
[   22.427481] [TTM] Zone highmem: Used memory at exit: 0 kiB.
[   22.427518] [drm] radeon: ttm finalized
[   22.427553] [drm] Forcing AGP to PCI mode
[   22.427926] radeon 0000:01:00.0: VRAM: 128M 0x00000000E0000000 - 0x00000000E7FFFFFF (64M used)
[   22.427974] radeon 0000:01:00.0: GTT: 512M 0x00000000C0000000 - 0x00000000DFFFFFFF
[   22.428067] [drm] Supports vblank timestamp caching Rev 1 (10.10.2010).
[   22.428103] [drm] Driver supports precise vblank timestamp query.
[   22.428154] [drm] radeon: irq initialized.
[   22.428195] [drm] Detected VRAM RAM=128M, BAR=128M
[   22.428230] [drm] RAM width 128bits DDR
[   22.428511] [TTM] Zone  kernel: Available graphics memory: 447314 kiB.
[   22.428563] [TTM] Zone highmem: Available graphics memory: 516630 kiB.
[   22.428600] [TTM] Initializing pool allocator.
[   22.428662] [drm] radeon: 64M of VRAM memory ready
[   22.428697] [drm] radeon: 512M of GTT memory ready.
[   22.428738] [drm] GART: num cpu pages 131072, num gpu pages 131072
[   22.434053] radeon 0000:01:00.0: WB enabled
[   22.434344] [drm] radeon: ring at 0x00000000C0001000
[   22.434401] [drm] ring test succeeded in 2 usecs
[   22.434610] [drm] radeon: ib pool ready.
[   22.434802] [drm] ib test succeeded in 0 usecs
[   22.436868] [drm] Panel ID String: SXGA+ Single (85MHz)    
[   22.436910] [drm] Panel Size 1400x1050
[   22.448035] [drm] radeon legacy LVDS backlight initialized
[   22.448245] [drm] No TV DAC info found in BIOS
[   22.448358] [drm] Radeon Display Connectors
[   22.448393] [drm] Connector 0:
[   22.448426] [drm]   VGA
[   22.448459] [drm]   DDC: 0x60 0x60 0x60 0x60 0x60 0x60 0x60 0x60
[   22.448496] [drm]   Encoders:
[   22.448528] [drm]     CRT1: INTERNAL_DAC1
[   22.448563] [drm] Connector 1:
[   22.448595] [drm]   DVI-D
[   22.448627] [drm]   HPD1
[   22.448661] [drm]   DDC: 0x64 0x64 0x64 0x64 0x64 0x64 0x64 0x64
[   22.448697] [drm]   Encoders:
[   22.448729] [drm]     DFP1: INTERNAL_TMDS1
[   22.448763] [drm] Connector 2:
[   22.448796] [drm]   LVDS
[   22.448828] [drm]   Encoders:
[   22.448860] [drm]     LCD1: INTERNAL_LVDS
[   22.448894] [drm] Connector 3:
[   22.448926] [drm]   S-video
[   22.448958] [drm]   Encoders:
[   22.448991] [drm]     TV1: INTERNAL_DAC2
[   22.459262] [drm] Radeon display connector VGA-1: No monitor connected or invalid EDID
[   22.469490] [drm] Radeon display connector DVI-D-1: No monitor connected or invalid EDID
[   22.469585] [drm] radeon: power management initialized
[   22.489845] intel8x0_measure_ac97_clock: measured 55861 usecs (2691 samples)
[   22.489884] intel8x0: clocking to 48000
[   22.491422] snd_intel8x0m 0000:00:1f.6: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[   22.491495] snd_intel8x0m 0000:00:1f.6: setting latency timer to 64
[   22.563354] [drm] fb mappable at 0xE0040000
[   22.563398] [drm] vram apper at 0xE0000000
[   22.563434] [drm] size 5914624
[   22.563470] [drm] fb depth is 24
[   22.563504] [drm]    pitch is 5632
[   22.563665] fbcon: radeondrmfb (fb0) is primary device
[   22.597922] input: Logitech USB-PS/2 Optical Mouse as /devices/pci0000:00/0000:00:1d.1/usb3/3-1/3-1:1.0/input/input8
[   22.598198] generic-usb 0003:046D:C00E.0001: input,hidraw0: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1d.1-1/input0
[   22.598514] usbcore: registered new interface driver usbhid
[   22.598517] usbhid: USB HID core driver
[   22.655874] Console: switching to colour frame buffer device 175x65
[   22.691894] fb0: radeondrmfb frame buffer device
[   22.692072] drm: registered panic notifier
[   22.693553] [drm] Initialized radeon 2.11.0 20080528 for 0000:01:00.0 on minor 0
[   23.208495] cfg80211: World regulatory domain updated:
[   23.208718] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[   23.209013] cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   23.209296] cfg80211:     (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[   23.209578] cfg80211:     (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[   23.209860] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   23.210140] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   24.227108] Adding 1052244k swap on /dev/sda2.  Priority:0 extents:1 across:1052244k 
[   24.356442] systemd-fsck[588]: /dev/sda3: clean, 161967/640848 files, 1879236/2560359 blocks
[   24.497683] EXT4-fs (sda3): mounted filesystem with ordered data mode. Opts: (null)
[   24.696423] fuse init (API version 7.17)
[   26.157651] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   27.150329] /usr/sbin/cron[946]: (CRON) INFO (pidfile fd = 3)
[   27.190445] /usr/sbin/cron[981]: (CRON) STARTUP (fork ok)
[   27.255546] acpid[990]: starting up with netlink and the input layer
[   27.280273] acpid[990]: 0 rules loaded
[   27.280383] acpid[990]: waiting for events: event logging is off
[   27.334989] /usr/sbin/gpm[996]: *** info [daemon/startup.c(131)]:
[   27.335027] /usr/sbin/gpm[996]: Started gpm successfully. Entered daemon mode.
[   27.401476] anacron[1009]: Anacron 2.3 started on 2011-09-07
[   27.466502] anacron[1009]: Will run job `cron.daily' in 5 min.
[   27.466536] anacron[1009]: Will run job `cron.weekly' in 10 min.
[   27.466563] anacron[1009]: Jobs will be executed sequentially
[   27.548166] /usr/sbin/cron[981]: (CRON) INFO (Running @reboot jobs)
[   27.696807] lp0: using parport0 (interrupt-driven).
[   27.746452] ppdev: user-space parallel port driver
[   27.971093] IBM TrackPoint firmware: 0x0e, buttons: 3/3
[   28.203048] input: TPPS/2 IBM TrackPoint as /devices/platform/i8042/serio1/serio2/input/input9
[   30.026306] sshd[1088]: Server listening on 0.0.0.0 port 22.
[   30.031464] sshd[1088]: Server listening on :: port 22.
[   30.558388] wlan0: authenticate with 00:04:0e:e4:00:3d (try 1)
[   30.559946] wlan0: authenticated
[   30.560229] wlan0: associate with 00:04:0e:e4:00:3d (try 1)
[   30.563486] wlan0: RX AssocResp from 00:04:0e:e4:00:3d (capab=0x411 status=0 aid=1)
[   30.563497] wlan0: associated
[   30.565235] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   70.174418] EXT4-fs (sda5): re-mounted. Opts: commit=0
[   70.412754] EXT4-fs (sda3): re-mounted. Opts: commit=0

Call-traces seem to go away when adding "irqpoll" to Kernel command line. ( See dmesg_irqpoll.txt )

- Sedat -

[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Linux version 3.1.0-rc4-next20110831.6-686-small (Debian 3.1.0~rc4-6~next20110831.dileks6) ([email protected]) (gcc version 4.6.1 (Debian 4.6.1-9) ) #1 SMP Wed Sep 7 22:00:52 CEST 2011
[    0.000000] BIOS-provided physical RAM map:
[    0.000000]  BIOS-e820: 0000000000000000 - 000000000009f000 (usable)
[    0.000000]  BIOS-e820: 000000000009f000 - 00000000000a0000 (reserved)
[    0.000000]  BIOS-e820: 00000000000d2000 - 00000000000d4000 (reserved)
[    0.000000]  BIOS-e820: 00000000000dc000 - 0000000000100000 (reserved)
[    0.000000]  BIOS-e820: 0000000000100000 - 000000003ff60000 (usable)
[    0.000000]  BIOS-e820: 000000003ff60000 - 000000003ff77000 (ACPI data)
[    0.000000]  BIOS-e820: 000000003ff77000 - 000000003ff79000 (ACPI NVS)
[    0.000000]  BIOS-e820: 000000003ff80000 - 0000000040000000 (reserved)
[    0.000000]  BIOS-e820: 00000000ff800000 - 0000000100000000 (reserved)
[    0.000000] Notice: NX (Execute Disable) protection missing in CPU!
[    0.000000] DMI present.
[    0.000000] DMI: IBM 2374SG6/2374SG6, BIOS 1RETDRWW (3.23 ) 06/18/2007
[    0.000000] e820 update range: 0000000000000000 - 0000000000010000 (usable) ==> (reserved)
[    0.000000] e820 remove range: 00000000000a0000 - 0000000000100000 (usable)
[    0.000000] last_pfn = 0x3ff60 max_arch_pfn = 0x100000
[    0.000000] MTRR default type: uncachable
[    0.000000] MTRR fixed ranges enabled:
[    0.000000]   00000-9FFFF write-back
[    0.000000]   A0000-BFFFF uncachable
[    0.000000]   C0000-CFFFF write-protect
[    0.000000]   D0000-DBFFF uncachable
[    0.000000]   DC000-DFFFF write-back
[    0.000000]   E0000-FFFFF write-protect
[    0.000000] MTRR variable ranges enabled:
[    0.000000]   0 base 000000000 mask FC0000000 write-back
[    0.000000]   1 base 03FF80000 mask FFFF80000 uncachable
[    0.000000]   2 disabled
[    0.000000]   3 disabled
[    0.000000]   4 disabled
[    0.000000]   5 disabled
[    0.000000]   6 disabled
[    0.000000]   7 disabled
[    0.000000] PAT not supported by CPU.
[    0.000000] initial memory mapped : 0 - 01800000
[    0.000000] Base memory trampoline at [c009b000] 9b000 size 16384
[    0.000000] init_memory_mapping: 0000000000000000-00000000377fe000
[    0.000000]  0000000000 - 0000400000 page 4k
[    0.000000]  0000400000 - 0037400000 page 2M
[    0.000000]  0037400000 - 00377fe000 page 4k
[    0.000000] kernel direct mapping tables up to 377fe000 @ 17ff000-1800000
[    0.000000] RAMDISK: 37830000 - 37c10000
[    0.000000] Allocated new RAMDISK: 3741e000 - 377fd6fc
[    0.000000] Move RAMDISK from 0000000037830000 - 0000000037c0f6fb to 3741e000 - 377fd6fb
[    0.000000] ACPI: RSDP 000f6d70 00024 (v02 IBM   )
[    0.000000] ACPI: XSDT 3ff6a672 0004C (v01 IBM    TP-1R    00003230  LTP 00000000)
[    0.000000] ACPI: FACP 3ff6a700 000F4 (v03 IBM    TP-1R    00003230 IBM  00000001)
[    0.000000] ACPI Warning: 32/64X length mismatch in Gpe1Block: 0/32 (20110623/tbfadt-529)
[    0.000000] ACPI Warning: Optional field Gpe1Block has zero address or length: 0x000000000000102C/0x0 (20110623/tbfadt-560)
[    0.000000] ACPI: DSDT 3ff6a8e7 0C530 (v01 IBM    TP-1R    00003230 MSFT 0100000E)
[    0.000000] ACPI: FACS 3ff78000 00040
[    0.000000] ACPI: SSDT 3ff6a8b4 00033 (v01 IBM    TP-1R    00003230 MSFT 0100000E)
[    0.000000] ACPI: ECDT 3ff76e17 00052 (v01 IBM    TP-1R    00003230 IBM  00000001)
[    0.000000] ACPI: TCPA 3ff76e69 00032 (v01 IBM    TP-1R    00003230 PTL  00000001)
[    0.000000] ACPI: BOOT 3ff76fd8 00028 (v01 IBM    TP-1R    00003230  LTP 00000001)
[    0.000000] 135MB HIGHMEM available.
[    0.000000] 887MB LOWMEM available.
[    0.000000]   mapped low ram: 0 - 377fe000
[    0.000000]   low ram: 0 - 377fe000
[    0.000000] Zone PFN ranges:
[    0.000000]   DMA      0x00000010 -> 0x00001000
[    0.000000]   Normal   0x00001000 -> 0x000377fe
[    0.000000]   HighMem  0x000377fe -> 0x0003ff60
[    0.000000] Movable zone start PFN for each node
[    0.000000] early_node_map[2] active PFN ranges
[    0.000000]     0: 0x00000010 -> 0x0000009f
[    0.000000]     0: 0x00000100 -> 0x0003ff60
[    0.000000] On node 0 totalpages: 261871
[    0.000000] free_area_init_node: node 0, pgdat c1426a40, node_mem_map f6c1d200
[    0.000000]   DMA zone: 32 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 3951 pages, LIFO batch:0
[    0.000000]   Normal zone: 1744 pages used for memmap
[    0.000000]   Normal zone: 221486 pages, LIFO batch:31
[    0.000000]   HighMem zone: 271 pages used for memmap
[    0.000000]   HighMem zone: 34387 pages, LIFO batch:7
[    0.000000] Using APIC driver default
[    0.000000] ACPI: PM-Timer IO Port: 0x1008
[    0.000000] SMP: Allowing 1 CPUs, 0 hotplug CPUs
[    0.000000] Local APIC disabled by BIOS -- reenabling.
[    0.000000] Found and enabled local APIC!
[    0.000000] nr_irqs_gsi: 16
[    0.000000] Allocating PCI resources starting at 40000000 (gap: 40000000:bf800000)
[    0.000000] Booting paravirtualized kernel on bare hardware
[    0.000000] setup_percpu: NR_CPUS:32 nr_cpumask_bits:32 nr_cpu_ids:1 nr_node_ids:1
[    0.000000] PERCPU: Embedded 13 pages/cpu @f6800000 s29120 r0 d24128 u4194304
[    0.000000] pcpu-alloc: s29120 r0 d24128 u4194304 alloc=1*4194304
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 259824
[    0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-3.1.0-rc4-next20110831.6-686-small root=UUID=1ceb69a7-ecf4-47e9-a231-b74e0f0a9b62 ro init=/bin/systemd radeon.modeset=1 lapic irqpoll 3
[    0.000000] Misrouted IRQ fixup and polling support enabled
[    0.000000] This may significantly impact system performance
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Initializing CPU#0
[    0.000000] Initializing HighMem for node 0 (000377fe:0003ff60)
[    0.000000] Memory: 1028908k/1047936k available (2742k kernel code, 18576k reserved, 1536k data, 376k init, 138632k highmem)
[    0.000000] virtual kernel memory layout:
[    0.000000]     fixmap  : 0xffd36000 - 0xfffff000   (2852 kB)
[    0.000000]     pkmap   : 0xff800000 - 0xffc00000   (4096 kB)
[    0.000000]     vmalloc : 0xf7ffe000 - 0xff7fe000   ( 120 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xf77fe000   ( 887 MB)
[    0.000000]       .init : 0xc142e000 - 0xc148c000   ( 376 kB)
[    0.000000]       .data : 0xc12adb9b - 0xc142dc00   (1536 kB)
[    0.000000]       .text : 0xc1000000 - 0xc12adb9b   (2742 kB)
[    0.000000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[    0.000000] SLUB: Genslabs=15, HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	RCU debugfs-based tracing is enabled.
[    0.000000] 	RCU dyntick-idle grace-period acceleration is enabled.
[    0.000000] NR_IRQS:1280
[    0.000000] CPU 0 irqstacks, hard=f6418000 soft=f641a000
[    0.000000] Extended CMOS year: 2000
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] Fast TSC calibration using PIT
[    0.000000] Detected 1694.278 MHz processor.
[    0.004003] Calibrating delay loop (skipped), value calculated using timer frequency.. 3388.55 BogoMIPS (lpj=6777112)
[    0.004077] pid_max: default: 32768 minimum: 301
[    0.004232] Security Framework initialized
[    0.004275] SELinux:  Disabled at boot.
[    0.004419] Mount-cache hash table entries: 512
[    0.004979] Initializing cgroup subsys debug
[    0.005019] Initializing cgroup subsys cpuacct
[    0.005086] Initializing cgroup subsys devices
[    0.005121] Initializing cgroup subsys freezer
[    0.005157] Initializing cgroup subsys net_cls
[    0.005192] Initializing cgroup subsys blkio
[    0.005287] mce: CPU supports 5 MCE banks
[    0.005334] CPU0: Thermal monitoring enabled (TM2)
[    0.005446] SMP alternatives: switching to UP code
[    0.008372] Freeing SMP alternatives: 8k freed
[    0.008411] ACPI: Core revision 20110623
[    0.014859] ACPI: setting ELCR to 0200 (from 0800)
[    0.020022] weird, boot CPU (#0) not listed by the BIOS.
[    0.020059] SMP motherboard not detected.
[    0.020096] Enabling APIC mode:  Flat.  Using 0 I/O APICs
[    0.024001] SMP disabled
[    0.024001] Performance Events: p6 PMU driver.
[    0.024001] ... version:                0
[    0.024001] ... bit width:              32
[    0.024001] ... generic registers:      2
[    0.024001] ... value mask:             00000000ffffffff
[    0.024001] ... max period:             000000007fffffff
[    0.024001] ... fixed-purpose events:   0
[    0.024001] ... event mask:             0000000000000003
[    0.024001] NMI watchdog enabled, takes one hw-pmu counter.
[    0.024001] Brought up 1 CPUs
[    0.024001] Total of 1 processors activated (3388.55 BogoMIPS).
[    0.024001] devtmpfs: initialized
[    0.024001] print_constraints: dummy: 
[    0.024001] NET: Registered protocol family 16
[    0.024001] ACPI: bus type pci registered
[    0.024001] PCI: PCI BIOS revision 2.10 entry at 0xfd8d6, last bus=8
[    0.024001] PCI: Using configuration type 1 for base access
[    0.024001] bio: create slab <bio-0> at 0
[    0.024001] ACPI: Added _OSI(Module Device)
[    0.024001] ACPI: Added _OSI(Processor Device)
[    0.024001] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.024001] ACPI: Added _OSI(Processor Aggregator Device)
[    0.025763] ACPI: EC: EC description table is found, configuring boot EC
[    0.036958] ACPI: Interpreter enabled
[    0.036998] ACPI: (supports S0 S3 S5)
[    0.037112] ACPI: Using PIC for interrupt routing
[    0.040602] ACPI: Power Resource [PUBS] (on)
[    0.044547] ACPI: EC: GPE = 0x1c, I/O: command/status = 0x66, data = 0x62
[    0.045112] ACPI: ACPI Dock Station Driver: 3 docks/bays found
[    0.045112] HEST: Table not found.
[    0.045112] PCI: Ignoring host bridge windows from ACPI; if necessary, use "pci=use_crs" and report a bug
[    0.045112] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.045112] pci_root PNP0A03:00: host bridge window [io  0x0000-0x0cf7] (ignored)
[    0.045112] pci_root PNP0A03:00: host bridge window [io  0x0d00-0xffff] (ignored)
[    0.045112] pci_root PNP0A03:00: host bridge window [mem 0x000a0000-0x000bffff] (ignored)
[    0.045112] pci_root PNP0A03:00: host bridge window [mem 0x000d4000-0x000d7fff] (ignored)
[    0.045112] pci_root PNP0A03:00: host bridge window [mem 0x000d8000-0x000dbfff] (ignored)
[    0.045112] pci_root PNP0A03:00: host bridge window [mem 0x40000000-0xfebfffff] (ignored)
[    0.045112] pci 0000:00:00.0: [8086:3340] type 0 class 0x000600
[    0.045112] pci 0000:00:00.0: reg 10: [mem 0xd0000000-0xdfffffff pref]
[    0.045112] pci 0000:00:01.0: [8086:3341] type 1 class 0x000604
[    0.045158] pci 0000:00:1d.0: [8086:24c2] type 0 class 0x000c03
[    0.045204] pci 0000:00:1d.0: reg 20: [io  0x1800-0x181f]
[    0.045239] pci 0000:00:1d.1: [8086:24c4] type 0 class 0x000c03
[    0.045285] pci 0000:00:1d.1: reg 20: [io  0x1820-0x183f]
[    0.045320] pci 0000:00:1d.2: [8086:24c7] type 0 class 0x000c03
[    0.045366] pci 0000:00:1d.2: reg 20: [io  0x1840-0x185f]
[    0.045412] pci 0000:00:1d.7: [8086:24cd] type 0 class 0x000c03
[    0.045436] pci 0000:00:1d.7: reg 10: [mem 0xc0000000-0xc00003ff]
[    0.045517] pci 0000:00:1d.7: PME# supported from D0 D3hot D3cold
[    0.045524] pci 0000:00:1d.7: PME# disabled
[    0.045545] pci 0000:00:1e.0: [8086:2448] type 1 class 0x000604
[    0.045590] pci 0000:00:1f.0: [8086:24cc] type 0 class 0x000601
[    0.045658] pci 0000:00:1f.0: quirk: [io  0x1000-0x107f] claimed by ICH4 ACPI/GPIO/TCO
[    0.048010] pci 0000:00:1f.0: quirk: [io  0x1180-0x11bf] claimed by ICH4 GPIO
[    0.048063] pci 0000:00:1f.1: [8086:24ca] type 0 class 0x000101
[    0.048079] pci 0000:00:1f.1: reg 10: [io  0x0000-0x0007]
[    0.048090] pci 0000:00:1f.1: reg 14: [io  0x0000-0x0003]
[    0.048101] pci 0000:00:1f.1: reg 18: [io  0x0000-0x0007]
[    0.048112] pci 0000:00:1f.1: reg 1c: [io  0x0000-0x0003]
[    0.048124] pci 0000:00:1f.1: reg 20: [io  0x1860-0x186f]
[    0.048135] pci 0000:00:1f.1: reg 24: [mem 0x00000000-0x000003ff]
[    0.048165] pci 0000:00:1f.3: [8086:24c3] type 0 class 0x000c05
[    0.048211] pci 0000:00:1f.3: reg 20: [io  0x1880-0x189f]
[    0.048250] pci 0000:00:1f.5: [8086:24c5] type 0 class 0x000401
[    0.048267] pci 0000:00:1f.5: reg 10: [io  0x1c00-0x1cff]
[    0.048277] pci 0000:00:1f.5: reg 14: [io  0x18c0-0x18ff]
[    0.048288] pci 0000:00:1f.5: reg 18: [mem 0xc0000c00-0xc0000dff]
[    0.048298] pci 0000:00:1f.5: reg 1c: [mem 0xc0000800-0xc00008ff]
[    0.048338] pci 0000:00:1f.5: PME# supported from D0 D3hot D3cold
[    0.048343] pci 0000:00:1f.5: PME# disabled
[    0.048361] pci 0000:00:1f.6: [8086:24c6] type 0 class 0x000703
[    0.048378] pci 0000:00:1f.6: reg 10: [io  0x2400-0x24ff]
[    0.048388] pci 0000:00:1f.6: reg 14: [io  0x2000-0x207f]
[    0.048441] pci 0000:00:1f.6: PME# supported from D0 D3hot D3cold
[    0.048446] pci 0000:00:1f.6: PME# disabled
[    0.048473] pci 0000:01:00.0: [1002:4c66] type 0 class 0x000300
[    0.048489] pci 0000:01:00.0: reg 10: [mem 0xe0000000-0xe7ffffff pref]
[    0.048498] pci 0000:01:00.0: reg 14: [io  0x3000-0x30ff]
[    0.048507] pci 0000:01:00.0: reg 18: [mem 0xc0100000-0xc010ffff]
[    0.048533] pci 0000:01:00.0: reg 30: [mem 0x00000000-0x0001ffff pref]
[    0.048553] pci 0000:01:00.0: supports D1 D2
[    0.048588] pci 0000:00:01.0: PCI bridge to [bus 01-01]
[    0.048626] pci 0000:00:01.0:   bridge window [io  0x3000-0x3fff]
[    0.048631] pci 0000:00:01.0:   bridge window [mem 0xc0100000-0xc01fffff]
[    0.048636] pci 0000:00:01.0:   bridge window [mem 0xe0000000-0xe7ffffff pref]
[    0.048662] pci 0000:02:00.0: [104c:ac55] type 2 class 0x000607
[    0.048681] pci 0000:02:00.0: reg 10: [mem 0xb0000000-0xb0000fff]
[    0.048701] pci 0000:02:00.0: supports D1 D2
[    0.048704] pci 0000:02:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.048710] pci 0000:02:00.0: PME# disabled
[    0.048731] pci 0000:02:00.1: [104c:ac55] type 2 class 0x000607
[    0.048750] pci 0000:02:00.1: reg 10: [mem 0xb1000000-0xb1000fff]
[    0.048770] pci 0000:02:00.1: supports D1 D2
[    0.048773] pci 0000:02:00.1: PME# supported from D0 D1 D2 D3hot D3cold
[    0.048779] pci 0000:02:00.1: PME# disabled
[    0.048807] pci 0000:02:01.0: [8086:101e] type 0 class 0x000200
[    0.048827] pci 0000:02:01.0: reg 10: [mem 0xc0220000-0xc023ffff]
[    0.048838] pci 0000:02:01.0: reg 14: [mem 0xc0200000-0xc020ffff]
[    0.048849] pci 0000:02:01.0: reg 18: [io  0x8000-0x803f]
[    0.048882] pci 0000:02:01.0: reg 30: [mem 0x00000000-0x0000ffff pref]
[    0.048907] pci 0000:02:01.0: PME# supported from D0 D3hot D3cold
[    0.048913] pci 0000:02:01.0: PME# disabled
[    0.048934] pci 0000:02:02.0: [168c:1014] type 0 class 0x000200
[    0.048952] pci 0000:02:02.0: reg 10: [mem 0xc0210000-0xc021ffff]
[    0.049053] pci 0000:00:1e.0: PCI bridge to [bus 02-08] (subtractive decode)
[    0.049093] pci 0000:00:1e.0:   bridge window [io  0x4000-0x8fff]
[    0.049099] pci 0000:00:1e.0:   bridge window [mem 0xc0200000-0xcfffffff]
[    0.049105] pci 0000:00:1e.0:   bridge window [mem 0xe8000000-0xefffffff pref]
[    0.049110] pci 0000:00:1e.0:   bridge window [io  0x0000-0xffff] (subtractive decode)
[    0.049114] pci 0000:00:1e.0:   bridge window [mem 0x00000000-0xffffffff] (subtractive decode)
[    0.049192] pci_bus 0000:00: on NUMA node 0
[    0.049197] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[    0.049248] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.AGP_._PRT]
[    0.049275] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCI1._PRT]
[    0.049383]  pci0000:00: Unable to request _OSC control (_OSC support mask: 0x1e)
[    0.052752] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 9 10 *11)
[    0.053092] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 9 10 *11)
[    0.053430] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 6 7 9 10 *11)
[    0.053768] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 9 10 *11)
[    0.054086] ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 6 7 9 10 11) *0, disabled.
[    0.054455] ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 6 7 9 10 11) *0, disabled.
[    0.054829] ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 9 10 11) *0, disabled.
[    0.055217] ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 6 7 9 10 *11)
[    0.055592] vgaarb: device added: PCI:0000:01:00.0,decodes=io+mem,owns=io+mem,locks=none
[    0.055641] vgaarb: loaded
[    0.055674] vgaarb: bridge control possible 0000:01:00.0
[    0.055760] PCI: Using ACPI for IRQ routing
[    0.055931] PCI: pci_cache_line_size set to 64 bytes
[    0.056007] reserve RAM buffer: 000000000009f000 - 000000000009ffff 
[    0.056012] reserve RAM buffer: 000000003ff60000 - 000000003fffffff 
[    0.058565] pnp: PnP ACPI init
[    0.058627] ACPI: bus type pnp registered
[    0.059298] pnp 00:00: [mem 0x00000000-0x0009ffff]
[    0.059302] pnp 00:00: [mem 0x000c0000-0x000c3fff]
[    0.059306] pnp 00:00: [mem 0x000c4000-0x000c7fff]
[    0.059309] pnp 00:00: [mem 0x000c8000-0x000cbfff]
[    0.059313] pnp 00:00: [mem 0x000cc000-0x000cffff]
[    0.059316] pnp 00:00: [mem 0x000d0000-0x000d3fff]
[    0.059320] pnp 00:00: [mem 0x000d4000-0x000d3fff disabled]
[    0.059323] pnp 00:00: [mem 0x000d8000-0x000d7fff disabled]
[    0.059327] pnp 00:00: [mem 0x000dc000-0x000dffff]
[    0.059330] pnp 00:00: [mem 0x000e0000-0x000e3fff]
[    0.059334] pnp 00:00: [mem 0x000e4000-0x000e7fff]
[    0.059337] pnp 00:00: [mem 0x000e8000-0x000ebfff]
[    0.059340] pnp 00:00: [mem 0x000ec000-0x000effff]
[    0.059344] pnp 00:00: [mem 0x000f0000-0x000fffff]
[    0.059347] pnp 00:00: [mem 0x00100000-0x3fffffff]
[    0.059351] pnp 00:00: [mem 0xfec00000-0xffffffff]
[    0.059440] system 00:00: [mem 0x00000000-0x0009ffff] could not be reserved
[    0.059481] system 00:00: [mem 0x000c0000-0x000c3fff] could not be reserved
[    0.059520] system 00:00: [mem 0x000c4000-0x000c7fff] could not be reserved
[    0.059560] system 00:00: [mem 0x000c8000-0x000cbfff] could not be reserved
[    0.059599] system 00:00: [mem 0x000cc000-0x000cffff] could not be reserved
[    0.059639] system 00:00: [mem 0x000d0000-0x000d3fff] could not be reserved
[    0.059678] system 00:00: [mem 0x000dc000-0x000dffff] could not be reserved
[    0.059717] system 00:00: [mem 0x000e0000-0x000e3fff] could not be reserved
[    0.059757] system 00:00: [mem 0x000e4000-0x000e7fff] could not be reserved
[    0.059796] system 00:00: [mem 0x000e8000-0x000ebfff] could not be reserved
[    0.059835] system 00:00: [mem 0x000ec000-0x000effff] could not be reserved
[    0.059875] system 00:00: [mem 0x000f0000-0x000fffff] could not be reserved
[    0.059914] system 00:00: [mem 0x00100000-0x3fffffff] could not be reserved
[    0.059954] system 00:00: [mem 0xfec00000-0xffffffff] could not be reserved
[    0.059994] system 00:00: Plug and Play ACPI device, IDs PNP0c01 (active)
[    0.060047] pnp 00:01: [bus 00-ff]
[    0.060051] pnp 00:01: [io  0x0cf8-0x0cff]
[    0.060054] pnp 00:01: [io  0x0000-0x0cf7 window]
[    0.060058] pnp 00:01: [io  0x0d00-0xffff window]
[    0.060068] pnp 00:01: [mem 0x000a0000-0x000bffff window]
[    0.060072] pnp 00:01: [mem 0x000c0000-0x000c3fff window]
[    0.060075] pnp 00:01: [mem 0x000c4000-0x000c7fff window]
[    0.060079] pnp 00:01: [mem 0x000c8000-0x000cbfff window]
[    0.060083] pnp 00:01: [mem 0x000cc000-0x000cffff window]
[    0.060086] pnp 00:01: [mem 0x000d0000-0x000d3fff window]
[    0.060090] pnp 00:01: [mem 0x000d4000-0x000d7fff window]
[    0.060094] pnp 00:01: [mem 0x000d8000-0x000dbfff window]
[    0.060098] pnp 00:01: [mem 0x000dc000-0x000dffff window]
[    0.060101] pnp 00:01: [mem 0x000e0000-0x000e3fff window]
[    0.060105] pnp 00:01: [mem 0x000e4000-0x000e7fff window]
[    0.060109] pnp 00:01: [mem 0x000e8000-0x000ebfff window]
[    0.060112] pnp 00:01: [mem 0x000ec000-0x000effff window]
[    0.060116] pnp 00:01: [mem 0x40000000-0xfebfffff window]
[    0.060183] pnp 00:01: Plug and Play ACPI device, IDs PNP0a03 (active)
[    0.060295] pnp 00:02: [io  0x0010-0x001f]
[    0.060299] pnp 00:02: [io  0x0090-0x009f]
[    0.060302] pnp 00:02: [io  0x0024-0x0025]
[    0.060305] pnp 00:02: [io  0x0028-0x0029]
[    0.060308] pnp 00:02: [io  0x002c-0x002d]
[    0.060312] pnp 00:02: [io  0x0030-0x0031]
[    0.060315] pnp 00:02: [io  0x0034-0x0035]
[    0.060318] pnp 00:02: [io  0x0038-0x0039]
[    0.060321] pnp 00:02: [io  0x003c-0x003d]
[    0.060324] pnp 00:02: [io  0x00a4-0x00a5]
[    0.060327] pnp 00:02: [io  0x00a8-0x00a9]
[    0.060330] pnp 00:02: [io  0x00ac-0x00ad]
[    0.060334] pnp 00:02: [io  0x00b0-0x00b5]
[    0.060337] pnp 00:02: [io  0x00b8-0x00b9]
[    0.060340] pnp 00:02: [io  0x00bc-0x00bd]
[    0.060343] pnp 00:02: [io  0x0050-0x0053]
[    0.060346] pnp 00:02: [io  0x0072-0x0077]
[    0.060349] pnp 00:02: [io  0x002e-0x002f]
[    0.060353] pnp 00:02: [io  0x1000-0x107f]
[    0.060356] pnp 00:02: [io  0x1180-0x11bf]
[    0.060359] pnp 00:02: [io  0x15e0-0x15ef]
[    0.060362] pnp 00:02: [io  0x1600-0x162f]
[    0.060365] pnp 00:02: [io  0x1632-0x167f]
[    0.060369] pnp 00:02: [io  0x004e-0x004f]
[    0.060372] pnp 00:02: [io  0x1630-0x1631]
[    0.060462] system 00:02: [io  0x1000-0x107f] has been reserved
[    0.060501] system 00:02: [io  0x1180-0x11bf] has been reserved
[    0.060539] system 00:02: [io  0x15e0-0x15ef] has been reserved
[    0.060577] system 00:02: [io  0x1600-0x162f] has been reserved
[    0.060615] system 00:02: [io  0x1632-0x167f] has been reserved
[    0.063348] system 00:02: [io  0x1630-0x1631] has been reserved
[    0.063386] system 00:02: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.063406] pnp 00:03: [io  0x0000-0x000f]
[    0.063410] pnp 00:03: [io  0x0080-0x008f]
[    0.063413] pnp 00:03: [io  0x00c0-0x00df]
[    0.063416] pnp 00:03: [dma 4]
[    0.063455] pnp 00:03: Plug and Play ACPI device, IDs PNP0200 (active)
[    0.063468] pnp 00:04: [io  0x0061]
[    0.063512] pnp 00:04: Plug and Play ACPI device, IDs PNP0800 (active)
[    0.063525] pnp 00:05: [io  0x00f0]
[    0.063531] pnp 00:05: [irq 13]
[    0.063570] pnp 00:05: Plug and Play ACPI device, IDs PNP0c04 (active)
[    0.063583] pnp 00:06: [io  0x0070-0x0071]
[    0.063586] pnp 00:06: [irq 8]
[    0.063629] pnp 00:06: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.063642] pnp 00:07: [io  0x0060]
[    0.063645] pnp 00:07: [io  0x0064]
[    0.063648] pnp 00:07: [irq 1]
[    0.063687] pnp 00:07: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.063700] pnp 00:08: [irq 12]
[    0.063750] pnp 00:08: Plug and Play ACPI device, IDs IBM0057 PNP0f13 (active)
[    0.063787] pnp 00:09: [io  0x03f0-0x03f5]
[    0.063790] pnp 00:09: [io  0x03f7]
[    0.063793] pnp 00:09: [irq 6]
[    0.063796] pnp 00:09: [dma 2]
[    0.063858] pnp 00:09: Plug and Play ACPI device, IDs PNP0700 (active)
[    0.063955] pnp 00:0a: [io  0x03f8-0x03ff]
[    0.063959] pnp 00:0a: [irq 4]
[    0.064096] pnp 00:0a: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.064215] pnp 00:0b: [io  0x03bc-0x03be]
[    0.064218] pnp 00:0b: [irq 7]
[    0.064318] pnp 00:0b: Plug and Play ACPI device, IDs PNP0400 (active)
[    0.064484] pnp 00:0c: Plug and Play ACPI device, IDs IBM0071 PNP0511 (disabled)
[    0.064550] pnp: PnP ACPI: found 13 devices
[    0.064550] ACPI: ACPI bus type pnp unregistered
[    0.102519] Switching to clocksource acpi_pm
[    0.102582] PCI: max bus depth: 2 pci_try_num: 3
[    0.102613] pci 0000:00:1f.1: BAR 5: assigned [mem 0x40000000-0x400003ff]
[    0.102656] pci 0000:00:1f.1: BAR 5: set to [mem 0x40000000-0x400003ff] (PCI address [0x40000000-0x400003ff])
[    0.102709] pci 0000:01:00.0: BAR 6: assigned [mem 0xc0120000-0xc013ffff pref]
[    0.102756] pci 0000:00:01.0: PCI bridge to [bus 01-01]
[    0.102793] pci 0000:00:01.0:   bridge window [io  0x3000-0x3fff]
[    0.102833] pci 0000:00:01.0:   bridge window [mem 0xc0100000-0xc01fffff]
[    0.102873] pci 0000:00:01.0:   bridge window [mem 0xe0000000-0xe7ffffff pref]
[    0.102926] pci 0000:02:01.0: BAR 6: assigned [mem 0xe8000000-0xe800ffff pref]
[    0.102973] pci 0000:02:00.1: BAR 16: assigned [mem 0xc4000000-0xc7ffffff]
[    0.103012] pci 0000:02:00.1: BAR 15: assigned [mem 0xec000000-0xefffffff pref]
[    0.103059] pci 0000:02:00.1: BAR 14: assigned [io  0x4000-0x40ff]
[    0.103097] pci 0000:02:00.1: BAR 13: assigned [io  0x4400-0x44ff]
[    0.103135] pci 0000:02:00.0: BAR 16: assigned [mem 0xc8000000-0xcbffffff]
[    0.103175] pci 0000:02:00.0: BAR 15: assigned [mem 0xcc000000-0xcfffffff pref]
[    0.103222] pci 0000:02:00.0: BAR 14: assigned [io  0x4800-0x48ff]
[    0.103260] pci 0000:02:00.0: BAR 13: assigned [io  0x4c00-0x4cff]
[    0.103298] pci 0000:02:00.0: CardBus bridge to [bus 03-06]
[    0.103335] pci 0000:02:00.0:   bridge window [io  0x4c00-0x4cff]
[    0.103374] pci 0000:02:00.0:   bridge window [io  0x4800-0x48ff]
[    0.103413] pci 0000:02:00.0:   bridge window [mem 0xcc000000-0xcfffffff pref]
[    0.103461] pci 0000:02:00.0:   bridge window [mem 0xc8000000-0xcbffffff]
[    0.103501] pci 0000:02:00.1: CardBus bridge to [bus 07-07]
[    0.103538] pci 0000:02:00.1:   bridge window [io  0x4400-0x44ff]
[    0.103577] pci 0000:02:00.1:   bridge window [io  0x4000-0x40ff]
[    0.103616] pci 0000:02:00.1:   bridge window [mem 0xec000000-0xefffffff pref]
[    0.103664] pci 0000:02:00.1:   bridge window [mem 0xc4000000-0xc7ffffff]
[    0.103704] pci 0000:00:1e.0: PCI bridge to [bus 02-08]
[    0.103741] pci 0000:00:1e.0:   bridge window [io  0x4000-0x8fff]
[    0.103782] pci 0000:00:1e.0:   bridge window [mem 0xc0200000-0xcfffffff]
[    0.103823] pci 0000:00:1e.0:   bridge window [mem 0xe8000000-0xefffffff pref]
[    0.103886] pci 0000:00:1e.0: setting latency timer to 64
[    0.103886] Switched to NOHz mode on CPU #0
[    0.103886] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 11
[    0.103886] PCI: setting IRQ 11 as level-triggered
[    0.103886] pci 0000:02:00.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
[    0.103886] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 11
[    0.103886] pci 0000:02:00.1: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[    0.103886] pci_bus 0000:00: resource 0 [io  0x0000-0xffff]
[    0.103886] pci_bus 0000:00: resource 1 [mem 0x00000000-0xffffffff]
[    0.103886] pci_bus 0000:01: resource 0 [io  0x3000-0x3fff]
[    0.103886] pci_bus 0000:01: resource 1 [mem 0xc0100000-0xc01fffff]
[    0.103886] pci_bus 0000:01: resource 2 [mem 0xe0000000-0xe7ffffff pref]
[    0.103886] pci_bus 0000:02: resource 0 [io  0x4000-0x8fff]
[    0.103886] pci_bus 0000:02: resource 1 [mem 0xc0200000-0xcfffffff]
[    0.103886] pci_bus 0000:02: resource 2 [mem 0xe8000000-0xefffffff pref]
[    0.103886] pci_bus 0000:02: resource 4 [io  0x0000-0xffff]
[    0.103886] pci_bus 0000:02: resource 5 [mem 0x00000000-0xffffffff]
[    0.103886] pci_bus 0000:03: resource 0 [io  0x4c00-0x4cff]
[    0.103886] pci_bus 0000:03: resource 1 [io  0x4800-0x48ff]
[    0.103886] pci_bus 0000:03: resource 2 [mem 0xcc000000-0xcfffffff pref]
[    0.103886] pci_bus 0000:03: resource 3 [mem 0xc8000000-0xcbffffff]
[    0.103886] pci_bus 0000:07: resource 0 [io  0x4400-0x44ff]
[    0.103886] pci_bus 0000:07: resource 1 [io  0x4000-0x40ff]
[    0.103886] pci_bus 0000:07: resource 2 [mem 0xec000000-0xefffffff pref]
[    0.103886] pci_bus 0000:07: resource 3 [mem 0xc4000000-0xc7ffffff]
[    0.103886] NET: Registered protocol family 2
[    0.103886] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.103886] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.104723] TCP bind hash table entries: 65536 (order: 7, 524288 bytes)
[    0.105913] TCP: Hash tables configured (established 131072 bind 65536)
[    0.105954] TCP reno registered
[    0.105991] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.106064] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.106407] NET: Registered protocol family 1
[    0.106586] pci 0000:01:00.0: Boot video device
[    0.106604] PCI: CLS 32 bytes, default 64
[    0.106722] Unpacking initramfs...
[    0.269429] Freeing initrd memory: 3968k freed
[    0.275899] Simple Boot Flag at 0x35 set to 0x1
[    0.276587] audit: initializing netlink socket (disabled)
[    0.276648] type=2000 audit(1315434406.276:1): initialized
[    0.303705] highmem bounce pool size: 64 pages
[    0.303751] HugeTLB registered 4 MB page size, pre-allocated 0 pages
[    0.306620] VFS: Disk quotas dquot_6.5.2
[    0.306827] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.307090] msgmni has been set to 1746
[    0.307407] alg: No test for stdrng (krng)
[    0.307520] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[    0.307602] io scheduler noop registered
[    0.307637] io scheduler deadline registered
[    0.307678] io scheduler cfq registered (default)
[    0.307995] ERST: Table is not found!
[    0.308134] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.308263] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a NS16550A
[    0.308810] 00:0a: ttyS0 at I/O 0x3f8 (irq = 4) is a NS16550A
[    0.308999] serial 0000:00:1f.6: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[    0.309072] serial 0000:00:1f.6: PCI INT B disabled
[    0.309258] Linux agpgart interface v0.103
[    0.309455] agpgart-intel 0000:00:00.0: Intel 855PM Chipset
[    0.322787] agpgart-intel 0000:00:00.0: AGP aperture is 256M @ 0xd0000000
[    0.323034] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[    0.329112] serio: i8042 KBD port at 0x60,0x64 irq 1
[    0.329155] serio: i8042 AUX port at 0x60,0x64 irq 12
[    0.329360] mousedev: PS/2 mouse device common for all mice
[    0.329455] rtc_cmos 00:06: RTC can wake from S4
[    0.329609] rtc_cmos 00:06: rtc core: registered rtc_cmos as rtc0
[    0.329663] rtc0: alarms up to one month, y3k, 114 bytes nvram
[    0.329711] cpuidle: using governor ladder
[    0.329746] cpuidle: using governor menu
[    0.330113] TCP cubic registered
[    0.330374] NET: Registered protocol family 10
[    0.331285] Mobile IPv6
[    0.331319] NET: Registered protocol family 17
[    0.331357] Registering the dns_resolver key type
[    0.331421] Using IPI No-Shortcut mode
[    0.331607] registered taskstats version 1
[    0.331954] rtc_cmos 00:06: setting system clock to 2011-09-07 22:26:47 UTC (1315434407)
[    0.332082] Initializing network drop monitor service
[    0.332224] Freeing unused kernel memory: 376k freed
[    0.333629] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    0.352199] udevd[44]: starting version 172
[    0.469067] usbcore: registered new interface driver usbfs
[    0.469149] usbcore: registered new interface driver hub
[    0.477010] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[    0.477057] e1000: Copyright (c) 1999-2006 Intel Corporation.
[    0.477151] e1000 0000:02:01.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
[    0.478287] SCSI subsystem initialized
[    0.487332] usbcore: registered new device driver usb
[    0.488235] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.488320] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
[    0.488361] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
[    0.488624] ACPI: PCI Interrupt Link [LNKH] enabled at IRQ 11
[    0.488665] ehci_hcd 0000:00:1d.7: PCI INT D -> Link[LNKH] -> GSI 11 (level, low) -> IRQ 11
[    0.488733] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[    0.488738] ehci_hcd 0000:00:1d.7: EHCI Host Controller
[    0.488831] ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 1
[    0.488914] ehci_hcd 0000:00:1d.7: debug port 1
[    0.492819] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported
[    0.755758] thermal LNXTHERM:00: registered as thermal_zone0
[    0.755802] ACPI: Thermal Zone [THM0] (50 C)
[    0.760478] ehci_hcd 0000:00:1d.7: irq 11, io mem 0xc0000000
[    0.773826] libata version 3.00 loaded.
[    0.788025] ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00
[    0.788135] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    0.788174] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.788221] usb usb1: Product: EHCI Host Controller
[    0.788257] usb usb1: Manufacturer: Linux 3.1.0-rc4-next20110831.6-686-small ehci_hcd
[    0.788304] usb usb1: SerialNumber: 0000:00:1d.7
[    0.788520] hub 1-0:1.0: USB hub found
[    0.788560] hub 1-0:1.0: 6 ports detected
[    0.789402] uhci_hcd: USB Universal Host Controller Interface driver
[    0.789493] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[    0.789532] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[    0.789580] uhci_hcd 0000:00:1d.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
[    0.789639] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[    0.789645] uhci_hcd 0000:00:1d.0: UHCI Host Controller
[    0.789693] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    0.789768] uhci_hcd 0000:00:1d.0: irq 11, io base 0x00001800
[    0.789848] usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
[    0.789888] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.789933] usb usb2: Product: UHCI Host Controller
[    0.789969] usb usb2: Manufacturer: Linux 3.1.0-rc4-next20110831.6-686-small uhci_hcd
[    0.790016] usb usb2: SerialNumber: 0000:00:1d.0
[    0.791056] hub 2-0:1.0: USB hub found
[    0.791097] hub 2-0:1.0: 2 ports detected
[    0.791232] ata_piix 0000:00:1f.1: version 2.13
[    0.791246] ata_piix 0000:00:1f.1: enabling device (0005 -> 0007)
[    0.791523] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
[    0.791563] ata_piix 0000:00:1f.1: PCI INT A -> Link[LNKC] -> GSI 11 (level, low) -> IRQ 11
[    0.791665] ata_piix 0000:00:1f.1: setting latency timer to 64
[    0.793604] scsi0 : ata_piix
[    0.794483] scsi1 : ata_piix
[    0.795195] ata1: PATA max UDMA/100 cmd 0x1f0 ctl 0x3f6 bmdma 0x1860 irq 14
[    0.795235] ata2: PATA max UDMA/100 cmd 0x170 ctl 0x376 bmdma 0x1868 irq 15
[    0.795465] uhci_hcd 0000:00:1d.1: power state changed by ACPI to D0
[    0.795505] uhci_hcd 0000:00:1d.1: power state changed by ACPI to D0
[    0.795733] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
[    0.795773] uhci_hcd 0000:00:1d.1: PCI INT B -> Link[LNKD] -> GSI 11 (level, low) -> IRQ 11
[    0.795832] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[    0.795837] uhci_hcd 0000:00:1d.1: UHCI Host Controller
[    0.795889] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3
[    0.795965] uhci_hcd 0000:00:1d.1: irq 11, io base 0x00001820
[    0.796096] usb usb3: New USB device found, idVendor=1d6b, idProduct=0001
[    0.796136] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.798877] usb usb3: Product: UHCI Host Controller
[    0.798913] usb usb3: Manufacturer: Linux 3.1.0-rc4-next20110831.6-686-small uhci_hcd
[    0.798959] usb usb3: SerialNumber: 0000:00:1d.1
[    0.799413] hub 3-0:1.0: USB hub found
[    0.799453] hub 3-0:1.0: 2 ports detected
[    0.799586] uhci_hcd 0000:00:1d.2: PCI INT C -> Link[LNKC] -> GSI 11 (level, low) -> IRQ 11
[    0.799640] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[    0.799644] uhci_hcd 0000:00:1d.2: UHCI Host Controller
[    0.799688] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4
[    0.799757] uhci_hcd 0000:00:1d.2: irq 11, io base 0x00001840
[    0.799841] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001
[    0.799880] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.799926] usb usb4: Product: UHCI Host Controller
[    0.799962] usb usb4: Manufacturer: Linux 3.1.0-rc4-next20110831.6-686-small uhci_hcd
[    0.800044] usb usb4: SerialNumber: 0000:00:1d.2
[    0.800470] hub 4-0:1.0: USB hub found
[    0.800508] hub 4-0:1.0: 2 ports detected
[    0.821665] e1000 0000:02:01.0: eth0: (PCI:33MHz:32-bit) 00:0d:60:b0:62:87
[    0.821714] e1000 0000:02:01.0: eth0: Intel(R) PRO/1000 Network Connection
[    0.956402] ata2.01: NODEV after polling detection
[    0.964894] ata2.00: ATAPI: UJDA755yDVD/CDRW, 1.70, max UDMA/33
[    0.965113] ata1.00: HPA detected: current 110257519, native 117210240
[    0.965153] ata1.00: ATA-6: HTS726060M9AT00, MH4OA6BA, max UDMA/100
[    0.965191] ata1.00: 110257519 sectors, multi 16: LBA 
[    0.980660] ata2.00: configured for UDMA/33
[    0.980748] ata1.00: configured for UDMA/100
[    0.981028] scsi 0:0:0:0: Direct-Access     ATA      HTS726060M9AT00  MH4O PQ: 0 ANSI: 5
[    0.984313] scsi 1:0:0:0: CD-ROM            MATSHITA UJDA755yDVD/CDRW 1.70 PQ: 0 ANSI: 5
[    1.000202] sd 0:0:0:0: [sda] 110257519 512-byte logical blocks: (56.4 GB/52.5 GiB)
[    1.000327] sd 0:0:0:0: [sda] Write Protect is off
[    1.000364] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    1.000396] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.003541] sr0: scsi3-mmc drive: 24x/24x writer cd/rw xa/form2 cdda tray
[    1.003583] cdrom: Uniform CD-ROM driver Revision: 3.20
[    1.004039] sr 1:0:0:0: Attached scsi CD-ROM sr0
[    1.058788]  sda: sda1 sda2 sda3 sda4 < sda5 sda6 >
[    1.059630] sd 0:0:0:0: [sda] Attached SCSI disk
[    1.064333] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    1.064481] sr 1:0:0:0: Attached scsi generic sg1 type 5
[    1.156025] usb 1-4: new high speed USB device number 3 using ehci_hcd
[    1.288973] usb 1-4: New USB device found, idVendor=152d, idProduct=2329
[    1.289020] usb 1-4: New USB device strings: Mfr=10, Product=11, SerialNumber=3
[    1.289068] usb 1-4: Product: Storagebird 35EV821
[    1.289104] usb 1-4: Manufacturer: 0123456
[    1.289138] usb 1-4: SerialNumber: 000000000340
[    1.294317] usbcore: registered new interface driver uas
[    1.296124] Refined TSC clocksource calibration: 1694.501 MHz.
[    1.296169] Switching to clocksource tsc
[    1.296237] Initializing USB Mass Storage driver...
[    1.296386] scsi2 : usb-storage 1-4:1.0
[    1.296601] usbcore: registered new interface driver usb-storage
[    1.296639] USB Mass Storage support registered.
[    1.528019] usb 3-1: new low speed USB device number 2 using uhci_hcd
[    1.704958] usb 3-1: New USB device found, idVendor=046d, idProduct=c00e
[    1.705012] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    1.705050] usb 3-1: Product: USB-PS/2 Optical Mouse
[    1.705086] usb 3-1: Manufacturer: Logitech
[    1.735723] Btrfs loaded
[    1.746479] input: Logitech USB-PS/2 Optical Mouse as /devices/pci0000:00/0000:00:1d.1/usb3/3-1/3-1:1.0/input/input1
[    1.746791] generic-usb 0003:046D:C00E.0001: input,hidraw0: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1d.1-1/input0
[    1.746876] usbcore: registered new interface driver usbhid
[    1.746913] usbhid: USB HID core driver
[    1.891205] EXT4-fs (sda5): mounted filesystem with ordered data mode. Opts: (null)
[    2.509177] scsi 2:0:0:0: Direct-Access     WDC WD10 EAVS-00D7B0           PQ: 0 ANSI: 2 CCS
[    2.510640] sd 2:0:0:0: Attached scsi generic sg2 type 0
[    2.511149] sd 2:0:0:0: [sdb] 1953525168 512-byte logical blocks: (1.00 TB/931 GiB)
[    2.512027] sd 2:0:0:0: [sdb] Write Protect is off
[    2.512067] sd 2:0:0:0: [sdb] Mode Sense: 34 00 00 00
[    2.512897] sd 2:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[    2.594761]  sdb: sdb1 sdb2 sdb3 sdb4 < sdb5 sdb6 sdb7 sdb8 >
[    2.597882] sd 2:0:0:0: [sdb] Attached SCSI disk
[    3.362362] systemd[1]: systemd 29 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +SYSVINIT +LIBCRYPTSETUP; debian)
[    3.459028] systemd[1]: Set hostname to <tbox>.
[    5.342814] cfg80211: Calling CRDA to update world regulatory domain
[    5.777505] ath5k 0000:02:02.0: PCI INT A -> Link[LNKC] -> GSI 11 (level, low) -> IRQ 11
[    5.777628] ath5k 0000:02:02.0: registered as 'phy0'
[    6.066020] ath: EEPROM regdomain: 0x61
[    6.066024] ath: EEPROM indicates we should expect a direct regpair map
[    6.066030] ath: Country alpha2 being used: 00
[    6.066033] ath: Regpair used: 0x61
[    6.104984] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
[    6.105881] Registered led device: ath5k-phy0::rx
[    6.105911] Registered led device: ath5k-phy0::tx
[    6.105926] ath5k phy0: Atheros AR5212 chip found (MAC: 0x56, PHY: 0x41)
[    6.105970] ath5k phy0: RF5111 5GHz radio found (0x17)
[    6.106006] ath5k phy0: RF2111 2GHz radio found (0x23)
[    6.466275] udevd[239]: starting version 172
[    7.447719] systemd-fsck[216]: /dev/sda5: clean, 185980/640848 files, 2329975/2560351 blocks (Prüfung nach nächstem Einhängen)
[    8.243155] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    8.283072] ACPI: Battery Slot [BAT0] (battery present)
[    8.283740] ACPI: AC Adapter [AC] (on-line)
[    8.296768] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[    8.372415] input: Lid Switch as /devices/LNXSYSTM:00/device:00/PNP0C0D:00/input/input2
[    8.373851] ACPI: Lid Switch [LID]
[    8.373996] input: Sleep Button as /devices/LNXSYSTM:00/device:00/PNP0C0E:00/input/input3
[    8.374049] ACPI: Sleep Button [SLPB]
[    8.374189] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input4
[    8.374237] ACPI: Power Button [PWRF]
[    8.446697] input: Video Bus as /devices/LNXSYSTM:00/device:00/PNP0A03:00/device:03/LNXVIDEO:00/input/input5
[    8.446761] ACPI: Video Device [VID] (multi-head: yes  rom: no  post: no)
[    8.459177] NET: Registered protocol family 23
[    8.511152] nsc-ircc 00:0c: [io  0x02f8-0x02ff]
[    8.511214] nsc-ircc 00:0c: [irq 3]
[    8.511220] nsc-ircc 00:0c: [dma 1]
[    8.511796] nsc-ircc 00:0c: activated
[    8.512025] nsc-ircc, chip->init
[    8.512065] nsc-ircc, Found chip at base=0x02e
[    8.512121] nsc-ircc, driver loaded (Dag Brattli)
[    8.513914] IrDA: Registered device irda0
[    8.513953] nsc-ircc, Using dongle: IBM31T1100 or Temic TFDS6000/TFDS6500
[    8.570091] Non-volatile memory driver v1.3
[    8.578175] yenta_cardbus 0000:02:00.0: CardBus bridge found [1014:0512]
[    8.578230] yenta_cardbus 0000:02:00.0: Using INTVAL to route CSC interrupts to PCI
[    8.578276] yenta_cardbus 0000:02:00.0: Routing CardBus interrupts to PCI
[    8.578316] yenta_cardbus 0000:02:00.0: TI: mfunc 0x01d21022, devctl 0x64
[    8.597576] i801_smbus 0000:00:1f.3: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[    8.747877] [drm] Initialized drm 1.1.0 20060810
[    8.802223] ACPI: acpi_idle registered with cpuidle
[    8.802755] Marking TSC unstable due to TSC halts in idle
[    8.803506] input: PC Speaker as /devices/platform/pcspkr/input/input6
[    8.805532] Switching to clocksource acpi_pm
[    8.809167] yenta_cardbus 0000:02:00.0: ISA IRQ mask 0x04b8, PCI irq 11
[    8.809212] yenta_cardbus 0000:02:00.0: Socket status: 30000006
[    8.809257] yenta_cardbus 0000:02:00.0: pcmcia: parent PCI bridge window: [io  0x4000-0x8fff]
[    8.809306] yenta_cardbus 0000:02:00.0: pcmcia: parent PCI bridge window: [mem 0xc0200000-0xcfffffff]
[    8.809355] pcmcia_socket pcmcia_socket0: cs: memory probe 0xc0200000-0xcfffffff: excluding 0xc0200000-0xc09fffff 0xc3a00000-0xd01fffff
[    8.812395] yenta_cardbus 0000:02:00.0: pcmcia: parent PCI bridge window: [mem 0xe8000000-0xefffffff pref]
[    8.814319] parport_pc 00:0b: reported by Plug and Play ACPI
[    8.814398] parport0: PC-style at 0x3bc, irq 7 [PCSPP,TRISTATE]
[    8.818290] pcmcia_socket pcmcia_socket0: cs: memory probe 0xe8000000-0xefffffff: excluding 0xe8000000-0xefffffff
[    8.826119] yenta_cardbus 0000:02:00.1: CardBus bridge found [1014:0512]
[    8.826180] yenta_cardbus 0000:02:00.1: Using INTVAL to route CSC interrupts to PCI
[    8.826228] yenta_cardbus 0000:02:00.1: Routing CardBus interrupts to PCI
[    8.826420] yenta_cardbus 0000:02:00.1: TI: mfunc 0x01d21022, devctl 0x64
[    9.057039] yenta_cardbus 0000:02:00.1: ISA IRQ mask 0x0438, PCI irq 11
[    9.057084] yenta_cardbus 0000:02:00.1: Socket status: 30000006
[    9.057129] yenta_cardbus 0000:02:00.1: pcmcia: parent PCI bridge window: [io  0x4000-0x8fff]
[    9.057178] yenta_cardbus 0000:02:00.1: pcmcia: parent PCI bridge window: [mem 0xc0200000-0xcfffffff]
[    9.057227] pcmcia_socket pcmcia_socket1: cs: memory probe 0xc0200000-0xcfffffff: excluding 0xc0200000-0xc09fffff 0xc3a00000-0xd01fffff
[    9.057383] yenta_cardbus 0000:02:00.1: pcmcia: parent PCI bridge window: [mem 0xe8000000-0xefffffff pref]
[    9.057432] pcmcia_socket pcmcia_socket1: cs: memory probe 0xe8000000-0xefffffff: excluding 0xe8000000-0xefffffff
[    9.091151] snd_intel8x0 0000:00:1f.5: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[    9.091238] snd_intel8x0 0000:00:1f.5: setting latency timer to 64
[    9.132973] Synaptics Touchpad, model: 1, fw: 5.9, id: 0x2c6ab1, caps: 0x884793/0x0/0x0
[    9.133030] serio: Synaptics pass-through port at isa0060/serio1/input0
[    9.173774] input: SynPS/2 Synaptics TouchPad as /devices/platform/i8042/serio1/input/input7
[    9.264515] pcmcia_socket pcmcia_socket1: cs: memory probe 0x0c0000-0x0fffff: excluding 0xc0000-0xd3fff 0xdc000-0xfffff
[    9.264688] pcmcia_socket pcmcia_socket1: cs: memory probe 0xa0000000-0xa0ffffff: clean.
[    9.264787] pcmcia_socket pcmcia_socket1: cs: memory probe 0x60000000-0x60ffffff: clean.
[    9.265060] pcmcia_socket pcmcia_socket0: cs: memory probe 0x0c0000-0x0fffff: excluding 0xc0000-0xd3fff 0xdc000-0xfffff
[    9.265221] pcmcia_socket pcmcia_socket0: cs: memory probe 0xa0000000-0xa0ffffff: clean.
[    9.265319] pcmcia_socket pcmcia_socket0: cs: memory probe 0x60000000-0x60ffffff: clean.
[    9.424854] [drm] radeon kernel modesetting enabled.
[    9.425041] radeon 0000:01:00.0: power state changed by ACPI to D0
[    9.425082] radeon 0000:01:00.0: power state changed by ACPI to D0
[    9.425130] radeon 0000:01:00.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
[    9.426081] [drm] initializing kernel modesetting (RV250 0x1002:0x4C66 0x1014:0x054D).
[    9.426157] [drm] register mmio base: 0xC0100000
[    9.426193] [drm] register mmio size: 65536
[    9.426545] agpgart-intel 0000:00:00.0: AGP 2.0 bridge
[    9.426596] agpgart-intel 0000:00:00.0: putting AGP V2 device into 4x mode
[    9.426674] radeon 0000:01:00.0: putting AGP V2 device into 4x mode
[    9.426740] radeon 0000:01:00.0: GTT: 256M 0xD0000000 - 0xDFFFFFFF
[    9.426786] radeon 0000:01:00.0: VRAM: 128M 0x00000000E0000000 - 0x00000000E7FFFFFF (64M used)
[    9.426841] [drm] Supports vblank timestamp caching Rev 1 (10.10.2010).
[    9.426879] [drm] Driver supports precise vblank timestamp query.
[    9.426932] [drm] radeon: irq initialized.
[    9.428114] [drm] Detected VRAM RAM=128M, BAR=128M
[    9.428156] [drm] RAM width 128bits DDR
[    9.429719] [TTM] Zone  kernel: Available graphics memory: 447314 kiB.
[    9.429760] [TTM] Zone highmem: Available graphics memory: 516630 kiB.
[    9.429797] [TTM] Initializing pool allocator.
[    9.429867] [drm] radeon: 64M of VRAM memory ready
[    9.429902] [drm] radeon: 256M of GTT memory ready.
[    9.431328] radeon 0000:01:00.0: WB enabled
[    9.432196] [drm] Loading R200 Microcode
[    9.524246] mtp-probe[349]: checking bus 3, device 2: "/sys/devices/pci0000:00/0000:00:1d.1/usb3/3-1"
[    9.524683] mtp-probe[354]: checking bus 1, device 3: "/sys/devices/pci0000:00/0000:00:1d.7/usb1/1-4"
[    9.574693] thinkpad_acpi: ThinkPad ACPI Extras v0.24
[    9.574736] thinkpad_acpi: http://ibm-acpi.sf.net/
[    9.574771] thinkpad_acpi: ThinkPad BIOS 1RETDRWW (3.23 ), EC 1RHT71WW-3.04
[    9.574809] thinkpad_acpi: IBM ThinkPad T40p, model 2374SG6
[    9.579127] thinkpad_acpi: detected a 8-level brightness capable ThinkPad
[    9.599954] thinkpad_acpi: rfkill switch tpacpi_bluetooth_sw: radio is blocked
[    9.600977] EXT4-fs (sda5): re-mounted. Opts: (null)
[    9.607299] mtp-probe[349]: bus: 3, device: 2 was not an MTP device
[    9.607494] mtp-probe[354]: bus: 1, device: 3 was not an MTP device
[    9.610186] Registered led device: tpacpi::thinklight
[    9.610372] Registered led device: tpacpi::power
[    9.610443] Registered led device: tpacpi::standby
[    9.622213] thinkpad_acpi: Console audio control enabled, mode: monitor (read only)
[    9.636445] input: ThinkPad Extra Buttons as /devices/platform/thinkpad_acpi/input/input8
[    9.654117] ata_id[503]: HDIO_GET_IDENTITY failed for '/dev/sdb': Invalid argument
[   10.016074] intel8x0_measure_ac97_clock: measured 55416 usecs (2670 samples)
[   10.016142] intel8x0: clocking to 48000
[   10.018479] snd_intel8x0m 0000:00:1f.6: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11
[   10.018614] snd_intel8x0m 0000:00:1f.6: setting latency timer to 64
[   10.066876] [drm] radeon: ring at 0x00000000D0001000
[   10.225537] [drm:r100_ring_test] *ERROR* radeon: ring test failed (scratch(0x15E4)=0xCAFEDEAD)
[   10.225587] [drm:r100_cp_init] *ERROR* radeon: cp isn't working (-22).
[   10.225626] radeon 0000:01:00.0: failed initializing CP (-22).
[   10.225662] radeon 0000:01:00.0: Disabling GPU acceleration
[   10.226187] [drm] radeon: cp finalized
[   10.226247] [drm] radeon: cp finalized
[   10.226300] [TTM] Finalizing pool allocator.
[   10.226897] [TTM] Zone  kernel: Used memory at exit: 0 kiB.
[   10.226936] [TTM] Zone highmem: Used memory at exit: 0 kiB.
[   10.226973] [drm] radeon: ttm finalized
[   10.227008] [drm] Forcing AGP to PCI mode
[   10.227378] radeon 0000:01:00.0: VRAM: 128M 0x00000000E0000000 - 0x00000000E7FFFFFF (64M used)
[   10.227427] radeon 0000:01:00.0: GTT: 512M 0x00000000C0000000 - 0x00000000DFFFFFFF
[   10.227475] [drm] Supports vblank timestamp caching Rev 1 (10.10.2010).
[   10.227511] [drm] Driver supports precise vblank timestamp query.
[   10.227562] [drm] radeon: irq initialized.
[   10.227603] [drm] Detected VRAM RAM=128M, BAR=128M
[   10.227638] [drm] RAM width 128bits DDR
[   10.227734] [TTM] Zone  kernel: Available graphics memory: 447314 kiB.
[   10.227772] [TTM] Zone highmem: Available graphics memory: 516630 kiB.
[   10.227809] [TTM] Initializing pool allocator.
[   10.227872] [drm] radeon: 64M of VRAM memory ready
[   10.227907] [drm] radeon: 512M of GTT memory ready.
[   10.227948] [drm] GART: num cpu pages 131072, num gpu pages 131072
[   10.232622] radeon 0000:01:00.0: WB enabled
[   10.232909] [drm] radeon: ring at 0x00000000C0001000
[   10.232963] [drm] ring test succeeded in 1 usecs
[   10.233171] [drm] radeon: ib pool ready.
[   10.233349] [drm] ib test succeeded in 0 usecs
[   10.235305] [drm] Panel ID String: SXGA+ Single (85MHz)    
[   10.235344] [drm] Panel Size 1400x1050
[   10.246471] [drm] radeon legacy LVDS backlight initialized
[   10.246512] [drm] No TV DAC info found in BIOS
[   10.246633] [drm] Radeon Display Connectors
[   10.246668] [drm] Connector 0:
[   10.246701] [drm]   VGA
[   10.246734] [drm]   DDC: 0x60 0x60 0x60 0x60 0x60 0x60 0x60 0x60
[   10.246770] [drm]   Encoders:
[   10.246802] [drm]     CRT1: INTERNAL_DAC1
[   10.246837] [drm] Connector 1:
[   10.246869] [drm]   DVI-D
[   10.246901] [drm]   HPD1
[   10.246934] [drm]   DDC: 0x64 0x64 0x64 0x64 0x64 0x64 0x64 0x64
[   10.246970] [drm]   Encoders:
[   10.247002] [drm]     DFP1: INTERNAL_TMDS1
[   10.247036] [drm] Connector 2:
[   10.247069] [drm]   LVDS
[   10.247100] [drm]   Encoders:
[   10.247133] [drm]     LCD1: INTERNAL_LVDS
[   10.247167] [drm] Connector 3:
[   10.247199] [drm]   S-video
[   10.247231] [drm]   Encoders:
[   10.247264] [drm]     TV1: INTERNAL_DAC2
[   10.257223] [drm] Radeon display connector VGA-1: No monitor connected or invalid EDID
[   10.267063] [drm] Radeon display connector DVI-D-1: No monitor connected or invalid EDID
[   10.267154] [drm] radeon: power management initialized
[   10.331538] [drm] fb mappable at 0xE0040000
[   10.331577] [drm] vram apper at 0xE0000000
[   10.331611] [drm] size 5914624
[   10.331644] [drm] fb depth is 24
[   10.331677] [drm]    pitch is 5632
[   10.331903] fbcon: radeondrmfb (fb0) is primary device
[   10.400428] Console: switching to colour frame buffer device 175x65
[   10.434897] fb0: radeondrmfb frame buffer device
[   10.435064] drm: registered panic notifier
[   10.435476] [drm] Initialized radeon 2.11.0 20080528 for 0000:01:00.0 on minor 0
[   10.762948] cfg80211: World regulatory domain updated:
[   10.763149] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[   10.763464] cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   10.763745] cfg80211:     (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[   10.764055] cfg80211:     (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[   10.764337] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   10.764619] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   11.586468] Adding 1052244k swap on /dev/sda2.  Priority:0 extents:1 across:1052244k 
[   11.640926] systemd-fsck[588]: /dev/sda3: clean, 161967/640848 files, 1879236/2560359 blocks
[   11.775376] EXT4-fs (sda3): mounted filesystem with ordered data mode. Opts: (null)
[   12.366618] fuse init (API version 7.17)
[   13.376217] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   14.422795] acpid[1002]: starting up with netlink and the input layer
[   14.449164] /usr/sbin/gpm[1006]: *** info [daemon/startup.c(131)]:
[   14.452176] /usr/sbin/gpm[1006]: Started gpm successfully. Entered daemon mode.
[   14.499284] acpid[1002]: 0 rules loaded
[   14.499391] acpid[1002]: waiting for events: event logging is off
[   14.607257] anacron[1024]: Anacron 2.3 started on 2011-09-07
[   14.637932] lp0: using parport0 (interrupt-driven).
[   14.682449] ppdev: user-space parallel port driver
[   14.692310] /usr/sbin/cron[979]: (CRON) INFO (pidfile fd = 3)
[   14.695030] /usr/sbin/cron[1039]: (CRON) STARTUP (fork ok)
[   15.076074] anacron[1024]: Normal exit (0 jobs run)
[   15.098779] /usr/sbin/cron[1039]: (CRON) INFO (Running @reboot jobs)
[   15.628324] IBM TrackPoint firmware: 0x0e, buttons: 3/3
[   15.862729] input: TPPS/2 IBM TrackPoint as /devices/platform/i8042/serio1/serio2/input/input9
[   17.047469] sshd[1094]: Server listening on 0.0.0.0 port 22.
[   17.047883] sshd[1094]: Server listening on :: port 22.
[   17.733643] wpa_supplicant[791]: Trying to authenticate with 00:04:0e:e4:00:3d (SSID='myCastle-WLAN WPA (Wireless LAN)' freq=2442 MHz)
[   17.739827] wlan0: authenticate with 00:04:0e:e4:00:3d (try 1)
[   17.741300] wlan0: authenticated
[   17.741742] wpa_supplicant[791]: Trying to associate with 00:04:0e:e4:00:3d (SSID='myCastle-WLAN WPA (Wireless LAN)' freq=2442 MHz)
[   17.742353] wlan0: associate with 00:04:0e:e4:00:3d (try 1)
[   17.745565] wlan0: RX AssocResp from 00:04:0e:e4:00:3d (capab=0x411 status=0 aid=1)
[   17.745576] wlan0: associated
[   17.747275] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   17.750680] wpa_supplicant[791]: Associated with 00:04:0e:e4:00:3d
[   52.514311] EXT4-fs (sda5): re-mounted. Opts: commit=0
[   52.793219] EXT4-fs (sda3): re-mounted. Opts: commit=0

Sedat,

The previous patch should use the new steal_refs to check for the release of scm references in the error handling at the end. I've updated the patch to take care of it. Hopefully the traces you see will go away. Can you verify?

Thanks.

Tim

----
Commit 0856a30409 (Scm: Remove unnecessary pid & credential references in Unix socket's send and receive path) introduced a use-after-free bug. The sent skbs from unix_stream_sendmsg could be consumed and destructed by the receive side, removing all referentials to the credentials, before the send side has finished sending out all
packets. However, send side could continue to consturct new packets in the stream, using credentials that have lost its last reference and been freed.

In this fix, we don't steal the reference to credentials we have obtained in scm_send at beginning of unix_stream_sendmsg, till we've reached the last packet. This fixes the problem in commit 0856a30409.

---

index 136298c..be712ae 100644
@@ -1383,10 +1383,11 @@ static int unix_attach_fds(struct scm_cookie *scm, struct sk_buff *skb)
 }
 
 static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb,
-			   bool send_fds, bool ref)
+			   bool send_fds, bool steal_refs)
 {
 	int err = 0;
-	if (ref) {
+
+	if (!steal_refs) {
 		UNIXCB(skb).pid  = get_pid(scm->pid);
 		UNIXCB(skb).cred = get_cred(scm->cred);
 	} else {

@@ -1458,7 +1459,7 @@ static int unix_dgram_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (skb == NULL)
 		goto out;
 
-	err = unix_scm_to_skb(siocb->scm, skb, true, false);
+	err = unix_scm_to_skb(siocb->scm, skb, true, true);
 	if (err < 0)
 		goto out_free;
 	max_level = err + 1;

@@ -1581,6 +1582,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	int sent = 0;
 	struct scm_cookie tmp_scm;
 	bool fds_sent = false;
+	bool steal_refs = false;
 	int max_level;
 
 	if (NULL == siocb->scm)

@@ -1642,11 +1644,14 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		size = min_t(int, size, skb_tailroom(skb));
 
 
-		/* Only send the fds and no ref to pid in the first buffer */
-		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+		/* Only send the fds in first buffer
+		 * Last buffer can steal our references to pid/cred
+		 */
+		steal_refs = (sent + size >= len);
+		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, steal_refs);
 		if (err < 0) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 		max_level = err + 1;
 		fds_sent = true;

@@ -1654,7 +1659,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		err = memcpy_fromiovec(skb_put(skb, size), msg->msg_iov, size);
 		if (err) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 
 		unix_state_lock(other);

@@ -1671,7 +1676,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		sent += size;
 	}
 
-	if (skb)
+	if (steal_refs)
 		scm_release(siocb->scm);
 	else
 		scm_destroy(siocb->scm);

@@ -1687,9 +1692,8 @@ pipe_err:
 		send_sig(SIGPIPE, current, 0);
 	err = -EPIPE;
 out_err:
-	if (skb == NULL)
+	if (!steal_refs)
 		scm_destroy(siocb->scm);
-out:
 	siocb->scm = NULL;
 	return sent ? : err;
 }

Yan Zheng,

I've updated the patch. If it looks good to you now, can you add your Signed-off-by to the patch. Pending Sedat's testing on this patch, I think it is good to go.

Tim

---
Commit 0856a30409 (Scm: Remove unnecessary pid & credential references in Unix socket's send and receive path) introduced a use-after-free bug. The sent skbs from unix_stream_sendmsg could be consumed and destructed by the receive side, removing all references to the credentials, before the send side has finished sending out all
packets. However, send side could continue to consturct new packets in the stream, using credentials that have lost its last reference and been freed.

In this fix, we don't steal the reference to credentials we have obtained in scm_send at beginning of unix_stream_sendmsg, till we've reached the last packet. This fixes the problem in commit 0856a30409.

---

index 136298c..47780dc 100644
@@ -1383,10 +1383,11 @@ static int unix_attach_fds(struct scm_cookie *scm, struct sk_buff *skb)
 }
 
 static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb,
-			   bool send_fds, bool ref)
+			   bool send_fds, bool steal_refs)
 {
 	int err = 0;
-	if (ref) {
+
+	if (!steal_refs) {
 		UNIXCB(skb).pid  = get_pid(scm->pid);
 		UNIXCB(skb).cred = get_cred(scm->cred);
 	} else {

@@ -1458,7 +1459,7 @@ static int unix_dgram_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (skb == NULL)
 		goto out;
 
-	err = unix_scm_to_skb(siocb->scm, skb, true, false);
+	err = unix_scm_to_skb(siocb->scm, skb, true, true);
 	if (err < 0)
 		goto out_free;
 	max_level = err + 1;

@@ -1581,6 +1582,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	int sent = 0;
 	struct scm_cookie tmp_scm;
 	bool fds_sent = false;
+	bool steal_refs = false;
 	int max_level;
 
 	if (NULL == siocb->scm)

@@ -1642,11 +1644,14 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		size = min_t(int, size, skb_tailroom(skb));
 
 
-		/* Only send the fds and no ref to pid in the first buffer */
-		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+		/* Only send the fds in first buffer
+		 * Last buffer can steal our references to pid/cred
+		 */
+		steal_refs = (sent + size >= len);
+		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, steal_refs);
 		if (err < 0) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 		max_level = err + 1;
 		fds_sent = true;

@@ -1654,7 +1659,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		err = memcpy_fromiovec(skb_put(skb, size), msg->msg_iov, size);
 		if (err) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 
 		unix_state_lock(other);

@@ -1671,7 +1676,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		sent += size;
 	}
 
-	if (skb)
+	if (steal_refs)
 		scm_release(siocb->scm);
 	else
 		scm_destroy(siocb->scm);

@@ -1687,9 +1692,10 @@ pipe_err:
 		send_sig(SIGPIPE, current, 0);
 	err = -EPIPE;
 out_err:
-	if (skb == NULL)
+	if (steal_refs)
+		scm_release(siocb->scm);
+	else
 		scm_destroy(siocb->scm);
-out:
 	siocb->scm = NULL;
 	return sent ? : err;
 }

Oops, I've forgotten to add Eric's previous Signed-off-by in my latest patch log. David, please add that when you pick up the patch. Once Yan Zheng added his sign off and Sedat tested the patch, I think it will be good to go.

Thanks.

Tim

Tim, as soon as you post another patch version, you must remove all prior Signed-off-by, and only add yours.

So it was fine to do so.

By the way your last version introduce a new bug, so I would rather NACK it ;)

I don't think so. unix_scm_to_skb() calls unix_attach_fds(), it always duplicates scm->fp.

Regards

What a mess. This code is a nightmare.

Part of the mess comes from scm_destroy() and scm_release() duplication.

We should have scm_destroy() only, as before, and NULLify scm->pid/cred in unix_scm_to_skb() when we steal references.

It makes more sense and keeps things clearer.

 include/net/scm.h  |    9 ---------
 net/unix/af_unix.c |   27 +++++++++++++++------------
 2 files changed, 15 insertions(+), 21 deletions(-)

index 68e1e48..2a5b42f 100644
@@ -78,15 +78,6 @@ static __inline__ void scm_destroy(struct scm_cookie *scm)
 		__scm_destroy(scm);
 }
 
-static __inline__ void scm_release(struct scm_cookie *scm)
-{
-	/* keep ref on pid and cred */
-	scm->pid = NULL;
-	scm->cred = NULL;
-	if (scm->fp)
-		__scm_destroy(scm);
-}
-
 static __inline__ int scm_send(struct socket *sock, struct msghdr *msg,
 			       struct scm_cookie *scm)
 {

index e6d9d10..1fa270a 100644
@@ -1379,15 +1379,18 @@ static int unix_attach_fds(struct scm_cookie *scm, struct sk_buff *skb)
 }
 
 static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb,
-			   bool send_fds, bool ref)
+			   bool send_fds, bool steal_refs)
 {
 	int err = 0;
-	if (ref) {
+
+	if (!steal_refs) {
 		UNIXCB(skb).pid  = get_pid(scm->pid);
 		UNIXCB(skb).cred = get_cred(scm->cred);
 	} else {
 		UNIXCB(skb).pid  = scm->pid;
 		UNIXCB(skb).cred = scm->cred;
+		scm->pid = NULL;
+		scm->cred = NULL;
 	}
 	UNIXCB(skb).fp = NULL;
 	if (scm->fp && send_fds)

@@ -1454,7 +1457,7 @@ static int unix_dgram_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (skb == NULL)
 		goto out;
 
-	err = unix_scm_to_skb(siocb->scm, skb, true, false);
+	err = unix_scm_to_skb(siocb->scm, skb, true, true);
 	if (err < 0)
 		goto out_free;
 	max_level = err + 1;

@@ -1550,7 +1553,7 @@ restart:
 	unix_state_unlock(other);
 	other->sk_data_ready(other, len);
 	sock_put(other);
-	scm_release(siocb->scm);
+	scm_destroy(siocb->scm);
 	return len;
 
 out_unlock:

@@ -1577,6 +1580,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	int sent = 0;
 	struct scm_cookie tmp_scm;
 	bool fds_sent = false;
+	bool steal_refs = false;
 	int max_level;
 
 	if (NULL == siocb->scm)

@@ -1638,8 +1642,11 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		size = min_t(int, size, skb_tailroom(skb));
 
 
-		/* Only send the fds and no ref to pid in the first buffer */
-		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+		/* Only send the fds in first buffer
+		 * Last buffer can steal our references to pid/cred
+		 */
+		steal_refs = (sent + size >= len);
+		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, steal_refs);
 		if (err < 0) {
 			kfree_skb(skb);
 			goto out;

@@ -1667,10 +1674,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		sent += size;
 	}
 
-	if (skb)
-		scm_release(siocb->scm);
-	else
-		scm_destroy(siocb->scm);
+	scm_destroy(siocb->scm);
 	siocb->scm = NULL;
 
 	return sent;

@@ -1683,8 +1687,7 @@ pipe_err:
 		send_sig(SIGPIPE, current, 0);
 	err = -EPIPE;
 out_err:
-	if (skb == NULL)
-		scm_destroy(siocb->scm);
+	scm_destroy(siocb->scm);
 out:
 	siocb->scm = NULL;
 	return sent ? : err;

Indeed, you're right, thanks

 include/net/scm.h  |    9 ---------
 net/unix/af_unix.c |   32 +++++++++++++++++---------------
 2 files changed, 17 insertions(+), 24 deletions(-)

index 68e1e48..2a5b42f 100644
@@ -78,15 +78,6 @@ static __inline__ void scm_destroy(struct scm_cookie *scm)
 		__scm_destroy(scm);
 }
 
-static __inline__ void scm_release(struct scm_cookie *scm)
-{
-	/* keep ref on pid and cred */
-	scm->pid = NULL;
-	scm->cred = NULL;
-	if (scm->fp)
-		__scm_destroy(scm);
-}
-
 static __inline__ int scm_send(struct socket *sock, struct msghdr *msg,
 			       struct scm_cookie *scm)
 {

index e6d9d10..c8a08ba 100644
@@ -1379,15 +1379,18 @@ static int unix_attach_fds(struct scm_cookie *scm, struct sk_buff *skb)
 }
 
 static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb,
-			   bool send_fds, bool ref)
+			   bool send_fds, bool steal_refs)
 {
 	int err = 0;
-	if (ref) {
+
+	if (!steal_refs) {
 		UNIXCB(skb).pid  = get_pid(scm->pid);
 		UNIXCB(skb).cred = get_cred(scm->cred);
 	} else {
 		UNIXCB(skb).pid  = scm->pid;
 		UNIXCB(skb).cred = scm->cred;
+		scm->pid = NULL;
+		scm->cred = NULL;
 	}
 	UNIXCB(skb).fp = NULL;
 	if (scm->fp && send_fds)

@@ -1454,7 +1457,7 @@ static int unix_dgram_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (skb == NULL)
 		goto out;
 
-	err = unix_scm_to_skb(siocb->scm, skb, true, false);
+	err = unix_scm_to_skb(siocb->scm, skb, true, true);
 	if (err < 0)
 		goto out_free;
 	max_level = err + 1;

@@ -1550,7 +1553,7 @@ restart:
 	unix_state_unlock(other);
 	other->sk_data_ready(other, len);
 	sock_put(other);
-	scm_release(siocb->scm);
+	scm_destroy(siocb->scm);
 	return len;
 
 out_unlock:

@@ -1577,6 +1580,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	int sent = 0;
 	struct scm_cookie tmp_scm;
 	bool fds_sent = false;
+	bool steal_refs = false;
 	int max_level;
 
 	if (NULL == siocb->scm)

@@ -1638,11 +1642,14 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		size = min_t(int, size, skb_tailroom(skb));
 
 
-		/* Only send the fds and no ref to pid in the first buffer */
-		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+		/* Only send the fds in first buffer
+		 * Last buffer can steal our references to pid/cred
+		 */
+		steal_refs = (sent + size >= len);
+		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, steal_refs);
 		if (err < 0) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 		max_level = err + 1;
 		fds_sent = true;

@@ -1650,7 +1657,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		err = memcpy_fromiovec(skb_put(skb, size), msg->msg_iov, size);
 		if (err) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 
 		unix_state_lock(other);

@@ -1667,10 +1674,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		sent += size;
 	}
 
-	if (skb)
-		scm_release(siocb->scm);
-	else
-		scm_destroy(siocb->scm);
+	scm_destroy(siocb->scm);
 	siocb->scm = NULL;
 
 	return sent;

@@ -1683,9 +1687,7 @@ pipe_err:
 		send_sig(SIGPIPE, current, 0);
 	err = -EPIPE;
 out_err:
-	if (skb == NULL)
-		scm_destroy(siocb->scm);
-out:
+	scm_destroy(siocb->scm);
 	siocb->scm = NULL;
 	return sent ? : err;
 }

I have tested this fixup patch on i386.
Can we have a separate patch with corrected descriptive text?

Thanks to all involved people.

- Sedat -

Here it is :

[PATCH net-next v3] af_unix: Fix use-after-free crashes

Commit 0856a30409 (Scm: Remove unnecessary pid & credential references in Unix socket's send and receive path) introduced an use-after-free bug.

We are allowed to steal the references to pid/cred only in the last skb sent from unix_stream_sendmsg(), because first skbs might be consumed by the receiver before we finish our sendmsg() call.

Remove scm_release() helper, since its cleaner to clear pid/cred fields in unix_scm_to_skb() when we steal them.

Based on prior patches from Yan Zheng and Tim Chen

---
 include/net/scm.h  |    9 ---------
 net/unix/af_unix.c |   32 +++++++++++++++++---------------
 2 files changed, 17 insertions(+), 24 deletions(-)

index 68e1e48..2a5b42f 100644
@@ -78,15 +78,6 @@ static __inline__ void scm_destroy(struct scm_cookie *scm)
 		__scm_destroy(scm);
 }
 
-static __inline__ void scm_release(struct scm_cookie *scm)
-{
-	/* keep ref on pid and cred */
-	scm->pid = NULL;
-	scm->cred = NULL;
-	if (scm->fp)
-		__scm_destroy(scm);
-}
-
 static __inline__ int scm_send(struct socket *sock, struct msghdr *msg,
 			       struct scm_cookie *scm)
 {

index e6d9d10..c8a08ba 100644
@@ -1379,15 +1379,18 @@ static int unix_attach_fds(struct scm_cookie *scm, struct sk_buff *skb)
 }
 
 static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb,
-			   bool send_fds, bool ref)
+			   bool send_fds, bool steal_refs)
 {
 	int err = 0;
-	if (ref) {
+
+	if (!steal_refs) {
 		UNIXCB(skb).pid  = get_pid(scm->pid);
 		UNIXCB(skb).cred = get_cred(scm->cred);
 	} else {
 		UNIXCB(skb).pid  = scm->pid;
 		UNIXCB(skb).cred = scm->cred;
+		scm->pid = NULL;
+		scm->cred = NULL;
 	}
 	UNIXCB(skb).fp = NULL;
 	if (scm->fp && send_fds)

@@ -1454,7 +1457,7 @@ static int unix_dgram_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (skb == NULL)
 		goto out;
 
-	err = unix_scm_to_skb(siocb->scm, skb, true, false);
+	err = unix_scm_to_skb(siocb->scm, skb, true, true);
 	if (err < 0)
 		goto out_free;
 	max_level = err + 1;

@@ -1550,7 +1553,7 @@ restart:
 	unix_state_unlock(other);
 	other->sk_data_ready(other, len);
 	sock_put(other);
-	scm_release(siocb->scm);
+	scm_destroy(siocb->scm);
 	return len;
 
 out_unlock:

@@ -1577,6 +1580,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	int sent = 0;
 	struct scm_cookie tmp_scm;
 	bool fds_sent = false;
+	bool steal_refs = false;
 	int max_level;
 
 	if (NULL == siocb->scm)

@@ -1638,11 +1642,14 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		size = min_t(int, size, skb_tailroom(skb));
 
 
-		/* Only send the fds and no ref to pid in the first buffer */
-		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+		/* Only send the fds in first buffer
+		 * Last buffer can steal our references to pid/cred
+		 */
+		steal_refs = (sent + size >= len);
+		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, steal_refs);
 		if (err < 0) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 		max_level = err + 1;
 		fds_sent = true;

@@ -1650,7 +1657,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		err = memcpy_fromiovec(skb_put(skb, size), msg->msg_iov, size);
 		if (err) {
 			kfree_skb(skb);
-			goto out;
+			goto out_err;
 		}
 
 		unix_state_lock(other);

@@ -1667,10 +1674,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		sent += size;
 	}
 
-	if (skb)
-		scm_release(siocb->scm);
-	else
-		scm_destroy(siocb->scm);
+	scm_destroy(siocb->scm);
 	siocb->scm = NULL;
 
 	return sent;

@@ -1683,9 +1687,7 @@ pipe_err:
 		send_sig(SIGPIPE, current, 0);
 	err = -EPIPE;
 out_err:
-	if (skb == NULL)
-		scm_destroy(siocb->scm);
-out:
+	scm_destroy(siocb->scm);
 	siocb->scm = NULL;
 	return sent ? : err;
 }

Thanks.

Now we have to fix a bug in unix_stream_recvmsg() as well.

consume_skb() call actually releases pid/cred references, and we can use them after their eventual freeing.

Keep also in mind that receiver can provides a too short user buffer, and skb can be put back to head of sk_receive_queue

Tim, your 0856a304091b33 commit introduced a lot of bugs, I was right asking a revert.

If we revert your patch, my litle patch (af_unix: dont send SCM_CREDENTIALS by default) is enough to solve performance problems.

Here is the patch to address this point.

Apply it after (af_unix: Fix use-after-free crashes)

I can make a combo patch once everybody agrees.

[PATCH net-next] af_unix: fix use after free in unix_stream_recvmsg()

Commit 0856a30409 (Scm: Remove unnecessary pid & credential references in Unix socket's send and receive path) introduced an use-after-free bug in unix_stream_recvmsg().

We should call consume_skb(skb) only after our possible use of pid/cred.

---
 net/unix/af_unix.c |   13 +++++++++----
 1 file changed, 9 insertions(+), 4 deletions(-)

index c8a08ba..1bd4ecf 100644
@@ -1873,6 +1873,7 @@ static int unix_stream_recvmsg(struct kiocb *iocb, struct socket *sock,
 	int target;
 	int err = 0;
 	long timeo;
+	struct sk_buff *skb;
 
 	err = -EINVAL;
 	if (sk->sk_state != TCP_ESTABLISHED)

@@ -1904,7 +1905,6 @@ static int unix_stream_recvmsg(struct kiocb *iocb, struct socket *sock,
 
 	do {
 		int chunk;
-		struct sk_buff *skb;
 
 		unix_state_lock(sk);
 		skb = skb_dequeue(&sk->sk_receive_queue);

@@ -1949,6 +1949,7 @@ static int unix_stream_recvmsg(struct kiocb *iocb, struct socket *sock,
 			if ((UNIXCB(skb).pid  != siocb->scm->pid) ||
 			    (UNIXCB(skb).cred != siocb->scm->cred)) {
 				skb_queue_head(&sk->sk_receive_queue, skb);
+				skb = NULL;
 				break;
 			}
 		} else {

@@ -1967,6 +1968,7 @@ static int unix_stream_recvmsg(struct kiocb *iocb, struct socket *sock,
 		chunk = min_t(unsigned int, skb->len, size);
 		if (memcpy_toiovec(msg->msg_iov, skb->data, chunk)) {
 			skb_queue_head(&sk->sk_receive_queue, skb);
+			skb = NULL;
 			if (copied == 0)
 				copied = -EFAULT;
 			break;

@@ -1984,13 +1986,14 @@ static int unix_stream_recvmsg(struct kiocb *iocb, struct socket *sock,
 			/* put the skb back if we didn't use it up.. */
 			if (skb->len) {
 				skb_queue_head(&sk->sk_receive_queue, skb);
+				skb = NULL;
 				break;
 			}
 
-			consume_skb(skb);
-
-			if (siocb->scm->fp)
+			if (UNIXCB(skb).pid || siocb->scm->fp)
 				break;
+			consume_skb(skb);
+			skb = NULL;
 		} else {
 			/* It is questionable, see note in unix_dgram_recvmsg.
 			 */

@@ -1999,12 +2002,14 @@ static int unix_stream_recvmsg(struct kiocb *iocb, struct socket *sock,
 
 			/* put message back and return */
 			skb_queue_head(&sk->sk_receive_queue, skb);
+			skb = NULL;
 			break;
 		}
 	} while (size);
 
 	mutex_unlock(&u->readlock);
 	scm_recv(sock, msg, siocb->scm, flags);
+	consume_skb(skb);
 out:
 	return copied ? : err;
 }

Thanks for your careful review to catch the bugs. Wish I had thought about the stream msg case more in my original patch.

But the regression where we do send SCM_CREDENTIALS is not addressed, right? I don't mind reverting my patch if there's a better solution.

Tim

This patch works for me. I haven't tried the out_err fixup from the followup, but I assume I won't spot a difference as those are fail paths anyway...

thanks,

js

I have tested the same patch here (before shopping, but can test the "final" patch, too.).

- Sedat -

Good morning,

/me sees so many patches :-).
Yes, I guess the patch by Eric has nothing to do with seen call-traces, adding "irqpoll" to Kernel command line seems to fix them (my uptime: approx. 10:30, Eric's proposal patch in my last patch-series is attached).

- Sedat -

Commit 0856a30409 (Scm: Remove unnecessary pid & credential references in Unix socket's send and receive path) introduced a use-after-free bug. The sent skbs from unix_stream_sendmsg could be consumed and destructed by the receive side, removing all references to the credentials, before the send side has finished sending out all
packets. However, send side could continue to consturct new packets in the stream, using credentials that have lost its last reference and been freed.

In this fix, we don't steal the reference to credentials we have obtained in scm_send at beginning of unix_stream_sendmsg, till we've reached the last packet. This fixes the problem in commit 0856a30409.

---

index 136298c..4a324a0 100644
@@ -1383,10 +1383,11 @@ static int unix_attach_fds(struct scm_cookie *scm, struct sk_buff *skb)
 }
 
 static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb,
-			   bool send_fds, bool ref)
+			   bool send_fds, bool steal_refs)
 {
 	int err = 0;
-	if (ref) {
+
+	if (!steal_refs) {
 		UNIXCB(skb).pid  = get_pid(scm->pid);
 		UNIXCB(skb).cred = get_cred(scm->cred);
 	} else {

@@ -1458,7 +1459,7 @@ static int unix_dgram_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (skb == NULL)
 		goto out;
 
-	err = unix_scm_to_skb(siocb->scm, skb, true, false);
+	err = unix_scm_to_skb(siocb->scm, skb, true, true);
 	if (err < 0)
 		goto out_free;
 	max_level = err + 1;

@@ -1581,6 +1582,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	int sent = 0;
 	struct scm_cookie tmp_scm;
 	bool fds_sent = false;
+	bool steal_refs = false;
 	int max_level;
 
 	if (NULL == siocb->scm)

@@ -1642,8 +1644,11 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		size = min_t(int, size, skb_tailroom(skb));
 
 
-		/* Only send the fds and no ref to pid in the first buffer */
-		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, fds_sent);
+		/* Only send the fds in first buffer
+		 * Last buffer can steal our references to pid/cred
+		 */
+		steal_refs = (sent + size >= len);
+		err = unix_scm_to_skb(siocb->scm, skb, !fds_sent, steal_refs);
 		if (err < 0) {
 			kfree_skb(skb);
 			goto out;

@@ -1671,7 +1676,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		sent += size;
 	}
 
-	if (skb)
+	if (steal_refs)
 		scm_release(siocb->scm);
 	else
 		scm_destroy(siocb->scm);

Yes, I'll try to cook a patch.

Thanks !

Thinking a bit more on this issue, I really believe we should not stick pid/cred in skbs sent from a write() system call.

That would break following use case :

An application uses a write(fd) and expects a receiver using recvmsg() to get process credentials (SCM_CREDENTIALS)

This is currently working, but not documented (man unix says ancillary data are sent with sendmsg())

If everybody agrees, I can send a patch for this : This would speedup write()/read() af_unix by an order of magnitude.

I prefer this approach too.

Looking forward to the patch. This should improve the scalability of af_unix.

Tim

Here it is, based on top on previous one [af_unix: Fix use-after-free crashes]

Thanks

[PATCH net-next] af_unix: dont send SCM_CREDENTIALS by default

Since commit 7361c36c5224 (af_unix: Allow credentials to work across user and pid namespaces) af_unix performance dropped a lot.

This is because we now take a reference on pid and cred in each write(), and release them in read(), usually done from another process, eventually from another cpu. This triggers false sharing.

# Events: 154K cycles
#
# Overhead Command Shared Object Symbol

# ........  .......  ..................  ...................................
#
    10.40%  hackbench  [kernel.kallsyms]   [k] put_pid
     8.60%  hackbench  [kernel.kallsyms]   [k] unix_stream_recvmsg
     7.87%  hackbench  [kernel.kallsyms]   [k] unix_stream_sendmsg
     6.11%  hackbench  [kernel.kallsyms]   [k] do_raw_spin_lock
     4.95%  hackbench  [kernel.kallsyms]   [k] unix_scm_to_skb
     4.87%  hackbench  [kernel.kallsyms]   [k] pid_nr_ns
     4.34%  hackbench  [kernel.kallsyms]   [k] cred_to_ucred
     2.39%  hackbench  [kernel.kallsyms]   [k] unix_destruct_scm
     2.24%  hackbench  [kernel.kallsyms]   [k] sub_preempt_count
     1.75%  hackbench  [kernel.kallsyms]   [k] fget_light
     1.51%  hackbench  [kernel.kallsyms]   [k] __mutex_lock_interruptible_slowpath
     1.42%  hackbench  [kernel.kallsyms]   [k] sock_alloc_send_pskb

This patch includes SCM_CREDENTIALS information in a af_unix message/skb only if requested by the sender, [man 7 unix for details how to include ancillary data using sendmsg() system call]

Note: This might break buggy applications that expected SCM_CREDENTIAL from an unaware write() system call.

Performance boost in hackbench : more than 50% gain on a 16 thread machine (2 quad-core cpus, 2 threads per core)

hackbench 20 thread 2000

4.224 sec instead of 9.102 sec

---
 include/net/scm.h        |   11 +----------
 net/core/scm.c           |   10 ++++++----
 net/netlink/af_netlink.c |    5 ++---
 net/unix/af_unix.c       |    9 +++++----
 4 files changed, 14 insertions(+), 21 deletions(-)

index 2a5b42f..74c8fdc 100644
@@ -45,14 +45,6 @@ static __inline__ void unix_get_peersec_dgram(struct socket *sock, struct scm_co
 { }
 #endif /* CONFIG_SECURITY_NETWORK */
 
-static __inline__ void scm_set_cred(struct scm_cookie *scm,
-				    struct pid *pid, const struct cred *cred)
-{
-	scm->pid  = get_pid(pid);
-	scm->cred = get_cred(cred);
-	cred_to_ucred(pid, cred, &scm->creds);
-}
-
 static __inline__ void scm_set_cred_noref(struct scm_cookie *scm,
 				    struct pid *pid, const struct cred *cred)
 {

@@ -81,8 +73,7 @@ static __inline__ void scm_destroy(struct scm_cookie *scm)
 static __inline__ int scm_send(struct socket *sock, struct msghdr *msg,
 			       struct scm_cookie *scm)
 {
-	scm_set_cred(scm, task_tgid(current), current_cred());
-	scm->fp = NULL;
+	memset(scm, 0, sizeof(*scm));
 	unix_get_peersec_dgram(sock, scm);
 	if (msg->msg_controllen <= 0)
 		return 0;

index 811b53f..ff52ad0 100644
@@ -173,7 +173,7 @@ int __scm_send(struct socket *sock, struct msghdr *msg, struct scm_cookie *p)
 			if (err)
 				goto error;
 
-			if (pid_vnr(p->pid) != p->creds.pid) {
+			if (!p->pid || pid_vnr(p->pid) != p->creds.pid) {
 				struct pid *pid;
 				err = -ESRCH;
 				pid = find_get_pid(p->creds.pid);

@@ -183,8 +183,9 @@ int __scm_send(struct socket *sock, struct msghdr *msg, struct scm_cookie *p)
 				p->pid = pid;
 			}
 
-			if ((p->cred->euid != p->creds.uid) ||
-				(p->cred->egid != p->creds.gid)) {
+			if (!p->cred ||
+			    (p->cred->euid != p->creds.uid) ||
+			    (p->cred->egid != p->creds.gid)) {
 				struct cred *cred;
 				err = -ENOMEM;
 				cred = prepare_creds();

@@ -193,7 +194,8 @@ int __scm_send(struct socket *sock, struct msghdr *msg, struct scm_cookie *p)
 
 				cred->uid = cred->euid = p->creds.uid;
 				cred->gid = cred->egid = p->creds.gid;
-				put_cred(p->cred);
+				if (p->cred)
+					put_cred(p->cred);
 				p->cred = cred;
 			}
 			break;

index 4330db9..1201b6d 100644
@@ -1324,10 +1324,9 @@ static int netlink_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (msg->msg_flags&MSG_OOB)
 		return -EOPNOTSUPP;
 
-	if (NULL == siocb->scm) {
+	if (NULL == siocb->scm)
 		siocb->scm = &scm;
-		memset(&scm, 0, sizeof(scm));
-	}
+
 	err = scm_send(sock, msg, siocb->scm);
 	if (err < 0)
 		return err;

index c8a08ba..4c77385 100644
@@ -1383,12 +1383,13 @@ static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb,
 {
 	int err = 0;
 
+	UNIXCB(skb).pid  = scm->pid;
+	UNIXCB(skb).cred = scm->cred;
 	if (!steal_refs) {
-		UNIXCB(skb).pid  = get_pid(scm->pid);
-		UNIXCB(skb).cred = get_cred(scm->cred);
+		get_pid(scm->pid);
+		if (scm->cred)
+			get_cred(scm->cred);
 	} else {
-		UNIXCB(skb).pid  = scm->pid;
-		UNIXCB(skb).cred = scm->cred;
 		scm->pid = NULL;
 		scm->cred = NULL;
 	}

This speeds up the case where we're not passing SCM_CREDENTIALS nicely.

Eric, please respin your patches against current net-next, thanks!

Sure, here it is :

Its a bit different, so I didnt add Tim 'Acked-by'

[PATCH net-next] af_unix: dont send SCM_CREDENTIALS by default

Since commit 7361c36c5224 (af_unix: Allow credentials to work across user and pid namespaces) af_unix performance dropped a lot.

This is because we now take a reference on pid and cred in each write(), and release them in read(), usually done from another process, eventually from another cpu. This triggers false sharing.

# Events: 154K cycles
#
# Overhead Command Shared Object Symbol

# ........  .......  ..................  .........................
#
    10.40%  hackbench  [kernel.kallsyms]   [k] put_pid
     8.60%  hackbench  [kernel.kallsyms]   [k] unix_stream_recvmsg
     7.87%  hackbench  [kernel.kallsyms]   [k] unix_stream_sendmsg
     6.11%  hackbench  [kernel.kallsyms]   [k] do_raw_spin_lock
     4.95%  hackbench  [kernel.kallsyms]   [k] unix_scm_to_skb
     4.87%  hackbench  [kernel.kallsyms]   [k] pid_nr_ns
     4.34%  hackbench  [kernel.kallsyms]   [k] cred_to_ucred
     2.39%  hackbench  [kernel.kallsyms]   [k] unix_destruct_scm
     2.24%  hackbench  [kernel.kallsyms]   [k] sub_preempt_count
     1.75%  hackbench  [kernel.kallsyms]   [k] fget_light
     1.51%  hackbench  [kernel.kallsyms]   [k]
__mutex_lock_interruptible_slowpath
     1.42%  hackbench  [kernel.kallsyms]   [k] sock_alloc_send_pskb

This patch includes SCM_CREDENTIALS information in a af_unix message/skb only if requested by the sender, [man 7 unix for details how to include ancillary data using sendmsg() system call]

Note: This might break buggy applications that expected SCM_CREDENTIAL from an unaware write() system call.

Performance boost in hackbench : more than 50% gain on a 16 thread machine (2 quad-core cpus, 2 threads per core)

hackbench 20 thread 2000

4.228 sec instead of 9.102 sec

---
 include/net/scm.h        |    5 ++---
 net/core/scm.c           |   10 ++++++----
 net/netlink/af_netlink.c |    5 ++---
 net/unix/af_unix.c       |    4 +++-
 4 files changed, 13 insertions(+), 11 deletions(-)

index 745460f..d456f4c 100644
@@ -49,7 +49,7 @@ static __inline__ void scm_set_cred(struct scm_cookie *scm,
 				    struct pid *pid, const struct cred *cred)
 {
 	scm->pid  = get_pid(pid);
-	scm->cred = get_cred(cred);
+	scm->cred = cred ? get_cred(cred) : NULL;
 	cred_to_ucred(pid, cred, &scm->creds);
 }
 

@@ -73,8 +73,7 @@ static __inline__ void scm_destroy(struct scm_cookie *scm)
 static __inline__ int scm_send(struct socket *sock, struct msghdr *msg,
 			       struct scm_cookie *scm)
 {
-	scm_set_cred(scm, task_tgid(current), current_cred());
-	scm->fp = NULL;
+	memset(scm, 0, sizeof(*scm));
 	unix_get_peersec_dgram(sock, scm);
 	if (msg->msg_controllen <= 0)
 		return 0;

index 811b53f..ff52ad0 100644
@@ -173,7 +173,7 @@ int __scm_send(struct socket *sock, struct msghdr *msg, struct scm_cookie *p)
 			if (err)
 				goto error;
 
-			if (pid_vnr(p->pid) != p->creds.pid) {
+			if (!p->pid || pid_vnr(p->pid) != p->creds.pid) {
 				struct pid *pid;
 				err = -ESRCH;
 				pid = find_get_pid(p->creds.pid);

@@ -183,8 +183,9 @@ int __scm_send(struct socket *sock, struct msghdr *msg, struct scm_cookie *p)
 				p->pid = pid;
 			}
 
-			if ((p->cred->euid != p->creds.uid) ||
-				(p->cred->egid != p->creds.gid)) {
+			if (!p->cred ||
+			    (p->cred->euid != p->creds.uid) ||
+			    (p->cred->egid != p->creds.gid)) {
 				struct cred *cred;
 				err = -ENOMEM;
 				cred = prepare_creds();

@@ -193,7 +194,8 @@ int __scm_send(struct socket *sock, struct msghdr *msg, struct scm_cookie *p)
 
 				cred->uid = cred->euid = p->creds.uid;
 				cred->gid = cred->egid = p->creds.gid;
-				put_cred(p->cred);
+				if (p->cred)
+					put_cred(p->cred);
 				p->cred = cred;
 			}
 			break;

index 4330db9..1201b6d 100644
@@ -1324,10 +1324,9 @@ static int netlink_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (msg->msg_flags&MSG_OOB)
 		return -EOPNOTSUPP;
 
-	if (NULL == siocb->scm) {
+	if (NULL == siocb->scm)
 		siocb->scm = &scm;
-		memset(&scm, 0, sizeof(scm));
-	}
+
 	err = scm_send(sock, msg, siocb->scm);
 	if (err < 0)
 		return err;

index ec68e1c..90c55c6 100644
@@ -1381,8 +1381,10 @@ static int unix_attach_fds(struct scm_cookie *scm, struct sk_buff *skb)
 static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb, bool send_fds)
 {
 	int err = 0;
+
 	UNIXCB(skb).pid  = get_pid(scm->pid);
-	UNIXCB(skb).cred = get_cred(scm->cred);
+	if (scm->cred)
+		UNIXCB(skb).cred = get_cred(scm->cred);
 	UNIXCB(skb).fp = NULL;
 	if (scm->fp && send_fds)
 		err = unix_attach_fds(scm, skb);

I appears udevd is such an application.

I am trying testing SOCK_PASSCRED flag and include SCM_CREDENTIALS if set.

Since commit 7361c36c5224 (af_unix: Allow credentials to work across user and pid namespaces) af_unix performance dropped a lot.

This is because we now take a reference on pid and cred in each write(), and release them in read(), usually done from another process, eventually from another cpu. This triggers false sharing.

# Events: 154K cycles
#
# Overhead Command Shared Object Symbol

# ........  .......  ..................  .........................
#
    10.40%  hackbench  [kernel.kallsyms]   [k] put_pid
     8.60%  hackbench  [kernel.kallsyms]   [k] unix_stream_recvmsg
     7.87%  hackbench  [kernel.kallsyms]   [k] unix_stream_sendmsg
     6.11%  hackbench  [kernel.kallsyms]   [k] do_raw_spin_lock
     4.95%  hackbench  [kernel.kallsyms]   [k] unix_scm_to_skb
     4.87%  hackbench  [kernel.kallsyms]   [k] pid_nr_ns
     4.34%  hackbench  [kernel.kallsyms]   [k] cred_to_ucred
     2.39%  hackbench  [kernel.kallsyms]   [k] unix_destruct_scm
     2.24%  hackbench  [kernel.kallsyms]   [k] sub_preempt_count
     1.75%  hackbench  [kernel.kallsyms]   [k] fget_light
     1.51%  hackbench  [kernel.kallsyms]   [k]
__mutex_lock_interruptible_slowpath
     1.42%  hackbench  [kernel.kallsyms]   [k] sock_alloc_send_pskb

This patch includes SCM_CREDENTIALS information in a af_unix message/skb only if requested by the sender, [man 7 unix for details how to include ancillary data using sendmsg() system call]

Note: This might break buggy applications that expected SCM_CREDENTIAL from an unaware write() system call, and receiver not using SO_PASSCRED socket option.

If SOCK_PASSCRED is set on source or destination socket, we still include credentials for mere write() syscalls.

Performance boost in hackbench : more than 50% gain on a 16 thread machine (2 quad-core cpus, 2 threads per core)

hackbench 20 thread 2000

4.228 sec instead of 9.102 sec

---
net/netlink/af_netlink.c net/unix/af_unix.c|diffstat -p1 -w70

 include/net/scm.h        |    5 ++---
 net/core/scm.c           |   10 ++++++----
 net/netlink/af_netlink.c |    5 ++---
 net/unix/af_unix.c       |   24 +++++++++++++++++++++++--
 4 files changed, 33 insertions(+), 11 deletions(-)

index 745460f..d456f4c 100644
@@ -49,7 +49,7 @@ static __inline__ void scm_set_cred(struct scm_cookie *scm,
 				    struct pid *pid, const struct cred *cred)
 {
 	scm->pid  = get_pid(pid);
-	scm->cred = get_cred(cred);
+	scm->cred = cred ? get_cred(cred) : NULL;
 	cred_to_ucred(pid, cred, &scm->creds);
 }
 

@@ -73,8 +73,7 @@ static __inline__ void scm_destroy(struct scm_cookie *scm)
 static __inline__ int scm_send(struct socket *sock, struct msghdr *msg,
 			       struct scm_cookie *scm)
 {
-	scm_set_cred(scm, task_tgid(current), current_cred());
-	scm->fp = NULL;
+	memset(scm, 0, sizeof(*scm));
 	unix_get_peersec_dgram(sock, scm);
 	if (msg->msg_controllen <= 0)
 		return 0;

index 811b53f..ff52ad0 100644
@@ -173,7 +173,7 @@ int __scm_send(struct socket *sock, struct msghdr *msg, struct scm_cookie *p)
 			if (err)
 				goto error;
 
-			if (pid_vnr(p->pid) != p->creds.pid) {
+			if (!p->pid || pid_vnr(p->pid) != p->creds.pid) {
 				struct pid *pid;
 				err = -ESRCH;
 				pid = find_get_pid(p->creds.pid);

@@ -183,8 +183,9 @@ int __scm_send(struct socket *sock, struct msghdr *msg, struct scm_cookie *p)
 				p->pid = pid;
 			}
 
-			if ((p->cred->euid != p->creds.uid) ||
-				(p->cred->egid != p->creds.gid)) {
+			if (!p->cred ||
+			    (p->cred->euid != p->creds.uid) ||
+			    (p->cred->egid != p->creds.gid)) {
 				struct cred *cred;
 				err = -ENOMEM;
 				cred = prepare_creds();

@@ -193,7 +194,8 @@ int __scm_send(struct socket *sock, struct msghdr *msg, struct scm_cookie *p)
 
 				cred->uid = cred->euid = p->creds.uid;
 				cred->gid = cred->egid = p->creds.gid;
-				put_cred(p->cred);
+				if (p->cred)
+					put_cred(p->cred);
 				p->cred = cred;
 			}
 			break;

index 4330db9..1201b6d 100644
@@ -1324,10 +1324,9 @@ static int netlink_sendmsg(struct kiocb *kiocb, struct socket *sock,
 	if (msg->msg_flags&MSG_OOB)
 		return -EOPNOTSUPP;
 
-	if (NULL == siocb->scm) {
+	if (NULL == siocb->scm)
 		siocb->scm = &scm;
-		memset(&scm, 0, sizeof(scm));
-	}
+
 	err = scm_send(sock, msg, siocb->scm);
 	if (err < 0)
 		return err;

index ec68e1c..466fbcc 100644
@@ -1381,8 +1381,10 @@ static int unix_attach_fds(struct scm_cookie *scm, struct sk_buff *skb)
 static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb, bool send_fds)
 {
 	int err = 0;
+
 	UNIXCB(skb).pid  = get_pid(scm->pid);
-	UNIXCB(skb).cred = get_cred(scm->cred);
+	if (scm->cred)
+		UNIXCB(skb).cred = get_cred(scm->cred);
 	UNIXCB(skb).fp = NULL;
 	if (scm->fp && send_fds)
 		err = unix_attach_fds(scm, skb);

@@ -1392,6 +1394,24 @@ static int unix_scm_to_skb(struct scm_cookie *scm, struct sk_buff *skb, bool sen
 }
 
 /*
+ * Some apps rely on write() giving SCM_CREDENTIALS
+ * We include credentials if source or destination socket
+ * asserted SOCK_PASSCRED.
+ */
+static void maybe_add_creds(struct sk_buff *skb, const struct socket *sock,
+			    const struct sock *other)
+{
+	if (UNIXCB(skb).cred)
+		return;
+	if (test_bit(SOCK_PASSCRED, &sock->flags) ||
+	    !other->sk_socket ||
+	    test_bit(SOCK_PASSCRED, &other->sk_socket->flags)) {
+		UNIXCB(skb).pid  = get_pid(task_tgid(current));
+		UNIXCB(skb).cred = get_current_cred();
+	}
+}
+
+/*
  *	Send AF_UNIX data.
  */
 

@@ -1538,6 +1558,7 @@ restart:
 
 	if (sock_flag(other, SOCK_RCVTSTAMP))
 		__net_timestamp(skb);
+	maybe_add_creds(skb, sock, other);
 	skb_queue_tail(&other->sk_receive_queue, skb);
 	if (max_level > unix_sk(other)->recursion_level)
 		unix_sk(other)->recursion_level = max_level;

@@ -1652,6 +1673,7 @@ static int unix_stream_sendmsg(struct kiocb *kiocb, struct socket *sock,
 		    (other->sk_shutdown & RCV_SHUTDOWN))
 			goto pipe_err_free;
 
+		maybe_add_creds(skb, sock, other);
 		skb_queue_tail(&other->sk_receive_queue, skb);
 		if (max_level > unix_sk(other)->recursion_level)
 			unix_sk(other)->recursion_level = max_level;

Do we have to worry about the case where peer socket changes its flag to SOCK_PASSCRED while packets are in flight? If there isn't such pathological use case, the patch looks fine to me.

I wouldn't think so - if you're sending a packet, and retroactively trying to change the flag and expect it to work, your program is too ugly to live. After all, if the scheduler had cut off your timeslice and scheduledthe receiving process before you set the flag, that packet would be delivered and done with anyhow, and no amount of wishing will set that flag on an already-delivered packet.

What *is* worth checking is that we DTRT if a process/thread is doing a send on one CPU, and another process/thread with a shared file descriptor for that socket is diddling the flag. But if we just define it as "atomic op to change the flag and other observers get whatever value their CPU sees at that instant", I'm OK with that too.. ;)

Le lundi 19 septembre 2011 à 22:10 -0400, [email protected] a écrit :

Note : The man page does states :

"To receive a struct ucred message the SO_PASSCRED option must be enabled on the socket."

But it doesnt say if the SO_PASSCRED option must be enabled before the sender sends its message, or before receiver attempts to read it.

Once a message is queued on an unix socket, flipping SO_PASSCRED cant change its content (adding or removing credentials), since sender might already have disappeared.

So current code includes credentials in all sent messages, just in case receiver actually fetch credentials.

There are probably programs that assume they can set SO_PASSCRED right before calling recvmsg(). Are we taking risk to break them, or are we gentle and provide a sysctl option to ease the transition, I dont know...

Should we reconsider the original approach of reducing the pid/credential references, with your fixes to correct its flaws in the streaming msg case?

Tim

Such a case has just appeared:
https://bugzilla.redhat.com/show_bug.cgi?id=757628

systemd allows on-demand socket activation of services. It creates a listening socket without the SO_PASSCRED flag. When the first message arrives to the socket, systemd spawns the service and passes the socket's fd to it. The service sets SO_PASSCRED before actually receiving the message.

I can fix that in systemd, but there may be more cases like this.

Michal

Yes, we were afraid of this.

Performance drop is really huge and deserves some fixes in userland...

People add features to kernel (in this case namespaces) without thinking on performance regression. So poor guys like us have to "fix" things later, in a reasonable way.

From: Eric Dumazet <[email protected]>
Date: Mon, 19 Sep 2011 17:52:27 +0200

I thought a lot about this and I think we should be able to get away with this trick, so I've added this patch to net-next, thanks!

# lsof | grep socket | wc -l
198

Aprrox 200 sockets in usage here, can you post your hackbench line, please? I would compare hackbench results with and without new improvements in SCM code.

- Sedat -

[...]

The hackbench line I used was

./hackbench 50 thread 2000

You will need to use the threaded case for testing to see the issue. I was running on a 4 socket, 40 cores total Westmere-EX machine. The improvement may depend on your machine size, probably with more improvement on larger multi-socket machine as smaller ones don't have as big a problem.

Tim