Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Raspbian: swapper page allocation failure #153

Closed
MilhouseVH opened this issue Nov 7, 2012 · 61 comments
Closed

Raspbian: swapper page allocation failure #153

MilhouseVH opened this issue Nov 7, 2012 · 61 comments

Comments

@MilhouseVH
Copy link

Running Transmission on a 512MB Pi, and with just two concurrent downloads, it's commonplace to see swapper page allocation failures:

Nov  7 00:15:59 raspberrypi kernel: [264587.158502] warn_alloc_failed: 5676 callbacks suppressed
Nov  7 00:15:59 raspberrypi kernel: [264587.158522] swapper: page allocation failure: order:3, mode:0x20
Nov  7 00:15:59 raspberrypi kernel: [264587.158568] [<c0013e1c>] (unwind_backtrace+0x0/0xf0) from [<c008e01c>] (warn_alloc_failed+0xc4/0x11c)
Nov  7 00:15:59 raspberrypi kernel: [264587.158596] [<c008e01c>] (warn_alloc_failed+0xc4/0x11c) from [<c00901f8>] (__alloc_pages_nodemask+0x410/0x630)
Nov  7 00:15:59 raspberrypi kernel: [264587.158630] [<c00901f8>] (__alloc_pages_nodemask+0x410/0x630) from [<c0378804>] (cache_alloc_refill+0x2b4/0x560)
Nov  7 00:15:59 raspberrypi kernel: [264587.158654] [<c0378804>] (cache_alloc_refill+0x2b4/0x560) from [<c00b5994>] (__kmalloc+0xcc/0xdc)
Nov  7 00:15:59 raspberrypi kernel: [264587.158674] [<c00b5994>] (__kmalloc+0xcc/0xdc) from [<c02ca770>] (__alloc_skb+0x48/0xe8)
Nov  7 00:15:59 raspberrypi kernel: [264587.158698] [<c02ca770>] (__alloc_skb+0x48/0xe8) from [<c0251c8c>] (rx_submit+0x24/0x1fc)
Nov  7 00:15:59 raspberrypi kernel: [264587.158725] [<c0251c8c>] (rx_submit+0x24/0x1fc) from [<c0259938>] (usb_hcd_giveback_urb+0x60/0xf4)
Nov  7 00:15:59 raspberrypi kernel: [264587.158752] [<c0259938>] (usb_hcd_giveback_urb+0x60/0xf4) from [<c027f194>] (_complete+0xb8/0x1dc)
Nov  7 00:15:59 raspberrypi kernel: [264587.158775] [<c027f194>] (_complete+0xb8/0x1dc) from [<c0281130>] (handle_hc_xfercomp_intr+0x2fc/0x41c)
Nov  7 00:15:59 raspberrypi kernel: [264587.158797] [<c0281130>] (handle_hc_xfercomp_intr+0x2fc/0x41c) from [<c0281b10>] (dwc_otg_hcd_handle_hc_n_intr+0x3a4/0x5c0)
Nov  7 00:15:59 raspberrypi kernel: [264587.158820] [<c0281b10>] (dwc_otg_hcd_handle_hc_n_intr+0x3a4/0x5c0) from [<c0281d98>] (dwc_otg_hcd_handle_hc_intr+0x6c/0x80)
Nov  7 00:15:59 raspberrypi kernel: [264587.158842] [<c0281d98>] (dwc_otg_hcd_handle_hc_intr+0x6c/0x80) from [<c0281f48>] (dwc_otg_hcd_handle_intr+0x19c/0x1e0)
Nov  7 00:15:59 raspberrypi kernel: [264587.158863] [<c0281f48>] (dwc_otg_hcd_handle_intr+0x19c/0x1e0) from [<c027f8e8>] (dwc_otg_hcd_irq+0xc/0x18)
Nov  7 00:15:59 raspberrypi kernel: [264587.158884] [<c027f8e8>] (dwc_otg_hcd_irq+0xc/0x18) from [<c0258f38>] (usb_hcd_irq+0x30/0x90)
Nov  7 00:15:59 raspberrypi kernel: [264587.158909] [<c0258f38>] (usb_hcd_irq+0x30/0x90) from [<c0074c90>] (handle_irq_event_percpu+0x50/0x194)
Nov  7 00:15:59 raspberrypi kernel: [264587.158930] [<c0074c90>] (handle_irq_event_percpu+0x50/0x194) from [<c0074e28>] (handle_irq_event+0x54/0x84)
Nov  7 00:15:59 raspberrypi kernel: [264587.158952] [<c0074e28>] (handle_irq_event+0x54/0x84) from [<c007704c>] (handle_level_irq+0x98/0xf8)
Nov  7 00:15:59 raspberrypi kernel: [264587.158974] [<c007704c>] (handle_level_irq+0x98/0xf8) from [<c0074588>] (generic_handle_irq+0x28/0x40)
Nov  7 00:15:59 raspberrypi kernel: [264587.159002] [<c0074588>] (generic_handle_irq+0x28/0x40) from [<c000e87c>] (handle_IRQ+0x30/0x84)
Nov  7 00:15:59 raspberrypi kernel: [264587.159027] [<c000e87c>] (handle_IRQ+0x30/0x84) from [<c037c974>] (__irq_svc+0x34/0xc8)
Nov  7 00:15:59 raspberrypi kernel: [264587.159048] [<c037c974>] (__irq_svc+0x34/0xc8) from [<c000e990>] (default_idle+0x24/0x28)
Nov  7 00:15:59 raspberrypi kernel: [264587.159069] [<c000e990>] (default_idle+0x24/0x28) from [<c000eb78>] (cpu_idle+0x9c/0xc4)
Nov  7 00:15:59 raspberrypi kernel: [264587.159097] [<c000eb78>] (cpu_idle+0x9c/0xc4) from [<c04c1718>] (start_kernel+0x280/0x2c8)
Nov  7 00:15:59 raspberrypi kernel: [264587.159108] Mem-info:
Nov  7 00:15:59 raspberrypi kernel: [264587.159114] Normal per-cpu:
Nov  7 00:15:59 raspberrypi kernel: [264587.159123] CPU    0: hi:  186, btch:  31 usd: 186
Nov  7 00:15:59 raspberrypi kernel: [264587.159141] active_anon:10144 inactive_anon:23787 isolated_anon:0
Nov  7 00:15:59 raspberrypi kernel: [264587.159147]  active_file:25069 inactive_file:25089 isolated_file:0
Nov  7 00:15:59 raspberrypi kernel: [264587.159152]  unevictable:0 dirty:5801 writeback:3822 unstable:0
Nov  7 00:15:59 raspberrypi kernel: [264587.159158]  free:10736 slab_reclaimable:1540 slab_unreclaimable:27013
Nov  7 00:15:59 raspberrypi kernel: [264587.159163]  mapped:1524 shmem:1 pagetables:279 bounce:0
Nov  7 00:15:59 raspberrypi kernel: [264587.159194] Normal free:42944kB min:16384kB low:20480kB high:24576kB active_anon:40576kB inactive_anon:95148kB active_file:100276kB inactive_file:100356kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:503936kB mlocked:0kB dirty:23204kB writeback:15288kB mapped:6096kB shmem:4kB slab_reclaimable:6160kB slab_unreclaimable:108052kB kernel_stack:680kB pagetables:1116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Nov  7 00:15:59 raspberrypi kernel: [264587.159226] lowmem_reserve[]: 0 0
Nov  7 00:15:59 raspberrypi kernel: [264587.159234] Normal: 1662*4kB 1845*8kB 1296*16kB 1*32kB 0*64kB 0*128kB 1*256kB 1*512kB 0*1024kB 0*2048kB 0*4096kB = 42944kB
Nov  7 00:15:59 raspberrypi kernel: [264587.159266] 62215 total pagecache pages
Nov  7 00:15:59 raspberrypi kernel: [264587.159273] 12056 pages in swap cache
Nov  7 00:15:59 raspberrypi kernel: [264587.159281] Swap cache stats: add 41064, delete 29008, find 29816/31783
Nov  7 00:15:59 raspberrypi kernel: [264587.159289] Free swap  = 38996kB
Nov  7 00:15:59 raspberrypi kernel: [264587.159295] Total swap = 102396kB
Nov  7 00:15:59 raspberrypi kernel: [264587.175484] 126976 pages of RAM
Nov  7 00:15:59 raspberrypi kernel: [264587.175491] 11100 free pages
Nov  7 00:15:59 raspberrypi kernel: 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 00:15:59 raspberrypi kernel: [264591.095934] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 00:15:59 raspberrypi kernel: [264591.095948] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 00:15:59 raspberrypi kernel: [264591.095962] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 00:15:59 raspberrypi kernel: [264591.095977] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 00:15:59 raspberrypi kernel: [264591.095992] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 00:15:59 raspberrypi kernel: [264591.096007] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped

also:

Nov  7 01:06:18 raspberrypi kernel: [267609.763694] kswapd0: page allocation failure: order:3, mode:0x20
Nov  7 01:06:18 raspberrypi kernel: [267609.763749] [<c0013e1c>] (unwind_backtrace+0x0/0xf0) from [<c008e01c>] (warn_alloc_failed+0xc4/0x11c)
Nov  7 01:06:18 raspberrypi kernel: [267609.763776] [<c008e01c>] (warn_alloc_failed+0xc4/0x11c) from [<c00901f8>] (__alloc_pages_nodemask+0x410/0x630)
Nov  7 01:06:18 raspberrypi kernel: [267609.763811] [<c00901f8>] (__alloc_pages_nodemask+0x410/0x630) from [<c0378804>] (cache_alloc_refill+0x2b4/0x560)
Nov  7 01:06:18 raspberrypi kernel: [267609.763834] [<c0378804>] (cache_alloc_refill+0x2b4/0x560) from [<c00b5994>] (__kmalloc+0xcc/0xdc)
Nov  7 01:06:18 raspberrypi kernel: [267609.763855] [<c00b5994>] (__kmalloc+0xcc/0xdc) from [<c02ca770>] (__alloc_skb+0x48/0xe8)
Nov  7 01:06:18 raspberrypi kernel: [267609.763879] [<c02ca770>] (__alloc_skb+0x48/0xe8) from [<c0251c8c>] (rx_submit+0x24/0x1fc)
Nov  7 01:06:18 raspberrypi kernel: [267609.763906] [<c0251c8c>] (rx_submit+0x24/0x1fc) from [<c0259938>] (usb_hcd_giveback_urb+0x60/0xf4)
Nov  7 01:06:18 raspberrypi kernel: [267609.763933] [<c0259938>] (usb_hcd_giveback_urb+0x60/0xf4) from [<c027f194>] (_complete+0xb8/0x1dc)
Nov  7 01:06:18 raspberrypi kernel: [267609.763956] [<c027f194>] (_complete+0xb8/0x1dc) from [<c0281130>] (handle_hc_xfercomp_intr+0x2fc/0x41c)
Nov  7 01:06:18 raspberrypi kernel: [267609.763978] [<c0281130>] (handle_hc_xfercomp_intr+0x2fc/0x41c) from [<c0281b10>] (dwc_otg_hcd_handle_hc_n_intr+0x3a4/0x5c0)
Nov  7 01:06:18 raspberrypi kernel: [267609.764001] [<c0281b10>] (dwc_otg_hcd_handle_hc_n_intr+0x3a4/0x5c0) from [<c0281d98>] (dwc_otg_hcd_handle_hc_intr+0x6c/0x80)
Nov  7 01:06:18 raspberrypi kernel: [267609.764023] [<c0281d98>] (dwc_otg_hcd_handle_hc_intr+0x6c/0x80) from [<c0281f48>] (dwc_otg_hcd_handle_intr+0x19c/0x1e0)
Nov  7 01:06:18 raspberrypi kernel: [267609.764044] [<c0281f48>] (dwc_otg_hcd_handle_intr+0x19c/0x1e0) from [<c027f8e8>] (dwc_otg_hcd_irq+0xc/0x18)
Nov  7 01:06:18 raspberrypi kernel: [267609.764066] [<c027f8e8>] (dwc_otg_hcd_irq+0xc/0x18) from [<c0258f38>] (usb_hcd_irq+0x30/0x90)
Nov  7 01:06:18 raspberrypi kernel: [267609.764090] [<c0258f38>] (usb_hcd_irq+0x30/0x90) from [<c0074c90>] (handle_irq_event_percpu+0x50/0x194)
Nov  7 01:06:18 raspberrypi kernel: [267609.764112] [<c0074c90>] (handle_irq_event_percpu+0x50/0x194) from [<c0074e28>] (handle_irq_event+0x54/0x84)
Nov  7 01:06:18 raspberrypi kernel: [267609.764134] [<c0074e28>] (handle_irq_event+0x54/0x84) from [<c007704c>] (handle_level_irq+0x98/0xf8)
Nov  7 01:06:18 raspberrypi kernel: [267609.764156] [<c007704c>] (handle_level_irq+0x98/0xf8) from [<c0074588>] (generic_handle_irq+0x28/0x40)
Nov  7 01:06:18 raspberrypi kernel: [267609.764183] [<c0074588>] (generic_handle_irq+0x28/0x40) from [<c000e87c>] (handle_IRQ+0x30/0x84)
Nov  7 01:06:18 raspberrypi kernel: [267609.764208] [<c000e87c>] (handle_IRQ+0x30/0x84) from [<c037c974>] (__irq_svc+0x34/0xc8)
Nov  7 01:06:18 raspberrypi kernel: [267609.764229] [<c037c974>] (__irq_svc+0x34/0xc8) from [<c0095b8c>] (__remove_mapping+0xe4/0x188)
Nov  7 01:06:18 raspberrypi kernel: [267609.764250] [<c0095b8c>] (__remove_mapping+0xe4/0x188) from [<c0097314>] (shrink_page_list+0x2ec/0x998)
Nov  7 01:06:18 raspberrypi kernel: 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 01:06:18 raspberrypi kernel: [267610.093783] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 01:06:18 raspberrypi kernel: [267610.093798] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped

I've tried various settings for vm.min_free_kbytes, but I still see these swapper allocation failures even with 16384 and 32768.

When these errors occur, I typically have over 350MB free memory, according to free:

             total       used       free     shared    buffers     cached
Mem:        497764     308904     188860          0        392     178568
-/+ buffers/cache:     129944     367820
Swap:       102396      76996      25400

Once the page allocation error occurs, syslog and kern.log are spammed with 10's of thousands of kevent 2 messages being logged in a short space of time (almost 180K messages in 20 minutes, once to syslog and again to kern.log - see issue #154) - these message need to be rate limited.

Forum discussion link

@MilhouseVH
Copy link
Author

These Pandaboard/Beagleboard bug reports may be relevant:

Strange out of memory on pandaboard
Page allocation failure on Pandaboard and Beagle XM

The culprit seems to be the usbnet driver, specifically turbo mode.

Unfortunately the proposed solutions are to cut USB/eth performance by disabling turbo mode, or bump up the minimum free memory (I've already tried 32MB, no luck).

Does the network-over-USB really need this much memory to function properly?

@MilhouseVH
Copy link
Author

I now see this has already been discussed previously, issue #9

Is the patch from Ming Lei applicable to the Pi?

@popcornmix
Copy link
Collaborator

The Ming Lei patch looks plausible. Have you tried it?

I just tried applying it, and it applies and builds. Can you test it?
https://dl.dropbox.com/u/3669512/temp/kernel.img

@asb
Copy link

asb commented Nov 7, 2012

Last time I tried the Ming Lei patch it didn't solve the issue for me, but that was a very long time ago and it's very possible there were other factors involved. I'm also very interested in whether Dom's updated kernel.img is better for you.

@MilhouseVH
Copy link
Author

Just downloaded it, will give it a go and report back. Many thanks.

@MilhouseVH
Copy link
Author

Argh... I haven't even got around to testing the torrent download yet and I've already got a mass of "kevent 2" messages being spammed to syslog/kern.log - it's not looking good.

Between 18:21:17 and 18:25:20 this patched kernel spammed 606,002 kevent 2 messages to both syslog and kern.log (see separate issue 154 about that!)

I need to stop this test before it kills my SD card... sorry, reverting to release kernel.img.

@popcornmix
Copy link
Collaborator

Can you try:
smsc95xx.turbo_mode=N

I'm not concinved there is any difference in performance, and it will probably fix this problem. See:
http://www.raspberrypi.org/phpBB3/viewtopic.php?t=14394&p=192727#p182663

@MilhouseVH
Copy link
Author

Do you want me to try that with the patched kernel, or stock kernel?

@popcornmix
Copy link
Collaborator

The stock kernel. The patched kernel doesn't work...

@MilhouseVH
Copy link
Author

I'd say iperf is a bit slower:

smsc95xx.turbo_mode=Y

[  4]  0.0-30.0 sec   337 MBytes  94.1 Mbits/sec

smsc95xx.turbo_mode=N

[  4]  0.0-30.0 sec   274 MBytes  76.6 Mbits/sec

Testing Transmission will take a little while... fingers crossed...

@MilhouseVH
Copy link
Author

So far so good with smsc95xx.turbo_mode=N.

I have 5 (FIVE!) concurrent torrents maxing out my 20Mbit/s connection, and after 15 minutes I have no allocation failures (or kevent 2 spam). Will allow the torrents to complete, check there are no errors and post an update.

However, I was under the impression that disabling turbo_mode was bad for performance, but apparently not (or at least, not significantly). Maybe disabling it should be the default until such time as turbo_mode can be made reliable?

@popcornmix
Copy link
Collaborator

Yes, I asked the question if turbo_mode=N caused a problem for anyone in the linked thread, and there didn't seem to be any problems. It seems to have a fairly minor performance hit (I thought my iperf drop was less than MillhouseVH's.)

I think it's worth considering as a default.

@MilhouseVH
Copy link
Author

I'm afraid I missed that thread, but I'll post to it once I've completed this test.

@asb
Copy link

asb commented Nov 7, 2012

Yes, I had been under the impression that issues with turbo_mode no longer came up in normal usage. However, if issues like this are trivially reproducible with a torrent client it probably makes a lot of sense to disable turbo_mode by default. If anyone has use cases where they suffer a significant degradation with turbo_mode disabled do let us know.

@popcornmix
Copy link
Collaborator

@MillHouseVH
I'd be interested if you spot any problem with XBMC and 1080p files with turbo_mode=N.
Although xbmc distributions can always choose a different default to raspbian.

@MilhouseVH
Copy link
Author

My XBMC of choice is OpenELEC, not sure if that would support this option - its cmdline.txt looks to be non-standard.

@popcornmix
Copy link
Collaborator

I would expect it to work. Just add
smsc95xx.turbo_mode=N
to (start of) existing command line.

@MilhouseVH
Copy link
Author

Is there any way to tell if the option has been honoured, as I don't normally see kevent2/swapper problems in OpenELEC so not seeing a problem won't mean much...

@popcornmix
Copy link
Collaborator

Try copying a large file over network, the speed should be reduced a little.

@MilhouseVH
Copy link
Author

This is with OpenELEC build r12322, over NFS:

#smsc95xx.turbo_mode=N
root ~ # dd if=./freenas/test.avi of=/dev/null bs=1M
699+1 records in
699+1 records out
733927424 bytes (699.9MB) copied, 74.652255 seconds, 9.4MB/s

#smsc95xx.turbo_mode=Y
root ~ # dd if=./freenas/test.avi of=/dev/null bs=1M
699+1 records in
699+1 records out
733927424 bytes (699.9MB) copied, 63.588526 seconds, 11.0MB/s

About the same ~1.5MB/s difference from the iperf test.

So it looks like OpenELEC is honouring the option, and I couldn't see any obvious difference when playing back a 1080p/DTS5.1 movie - it played without any stutter or buffering. However if the bitrate where high enough, maybe it would be the difference between stutter free playback and not (OE should probably stick to keeping turbo_mode enabled by default, IMHO).

Obviously the ideal scenario would be to have turbo_mode enabled, but without these allocation failures... I'm assuming this isn't possible, or likely?

@MilhouseVH
Copy link
Author

All 5 torrents completed without any error - looks like smsc95xx.turbo_mode=N is a keeper!

@steveglen
Copy link
Contributor

I'm the author of the smsc95xx driver, and I would recommend turning this feature off on a slower Host CPU like Raspberry Pi's.

This feature enables the USB device to send multiple received ethernet packets in one USB transaction. This enables more efficient usage of the USB bus, and therefore higher throughput, but it causes multiple RAM allocation requests to happen at once as multiple incoming packets are processed. Turning it off means memory allocations happen in a less bursty fashion, so are less likely to fail when RAM is scarce.

I hope this helps.

@popcornmix
Copy link
Collaborator

@MilhouseVH and others:
I'm thinking of enabling smsc95xx.turbo_mode=N as a default.
I believe this means we can reduce the rather excessive vm.min_free_kbytes.

Can you try transmission with vm.min_free_kbytes reduced to 2048 or 1024?

@MilhouseVH
Copy link
Author

Test setup:

  • Transmission, 5 concurrent torrent downloads (each download ~700MB, average of 25 peers per torrent)
  • 512MB Pi (16MB for GPU), stable (and recently updated) Raspbian, though not bleeding edge
  • vcgencmd version:
    Oct 25 2012 16:36:25 Copyright (c) 2012 Broadcom version 346337 (release)
  • uname -a: Linux raspberrypi 3.2.27+ #250 PREEMPT Thu Oct 18 19:03:02 BST 2012 armv6l GNU/Linux
  • 20Mbit DL/2.5Mbit UL ADSL with the Pi maxing out the downlink during downloads (~2MB/second on eth0 RX).

smsc95xx.turbo_mode=N, vm.min_free_kbytes=1024

Started well, but after about 20 minutes a series of page allocation failures occurred, each followed by multiple "kevent 2 may have been dropped" messages.

Result: FAIL

smsc95xx.turbo_mode=N, vm.min_free_kbytes=2048

All downloads completed successfully after 45 minutes, and with no errors.

Result: SUCCESS

So, 2048 looks good.

To see if 2048 was at all marginal, I ran the same Transmission test, but this time with 10 concurrent downloads (again, each ~700MB, average 25 peers per torrent) and this also completed without any errors.

Finally, I tried the same 10 concurrent downloads, this time with vm.min_free_kbytes=1536, and this too succeeded, so it would appear there is some headroom with 2048.

@popcornmix
Copy link
Collaborator

Thanks. That's useful to know.

@popcornmix
Copy link
Collaborator

Closing, as smsc95xx.turbo_mode=N seems to be the correct workaround.
The next official image will likely switch to that as a default.

@MilhouseVH
Copy link
Author

Overnight I had 16 torrents downloading continuously for several hours, with vm.min_free_kbytes=1536 and smsc95xx.turbo_mode=N, and experienced no problems whatsoever so unless you're being cautious and fancy some extra headroom, 1536 seems like an OK figure.

@popcornmix
Copy link
Collaborator

Thanks for info.

@MilhouseVH
Copy link
Author

Testing with the latest kernel & firmware:

pi@raspberrypi ~ $ uname -a && vcgencmd version
Linux raspberrypi 3.6.11+ #362 PREEMPT Tue Jan 22 14:52:21 GMT 2013 armv6l GNU/Linux
Jan 26 2013 19:20:16
Copyright (c) 2012 Broadcom
version 365344 (release)

With vm.min_free_kbytes=8192, the swapper page allocation message is a little different - I don't recall seeing the SLAB entries before (see end of log):

Jan 29 01:42:13 raspberrypi kernel: [23178.419715] swapper: page allocation failure: order:0, mode:0x20
Jan 29 01:42:13 raspberrypi kernel: [23178.419757] [<c0013a7c>] (unwind_backtrace+0x0/0xf0) from [<c0092760>] (warn_alloc_failed+0xc4/0x11c)
Jan 29 01:42:13 raspberrypi kernel: [23178.419779] [<c0092760>] (warn_alloc_failed+0xc4/0x11c) from [<c0094a70>] (__alloc_pages_nodemask+0x3e0/0x63c)
Jan 29 01:42:13 raspberrypi kernel: [23178.419799] [<c0094a70>] (__alloc_pages_nodemask+0x3e0/0x63c) from [<c02e458c>] (__netdev_alloc_frag+0x90/0x118)
Jan 29 01:42:13 raspberrypi kernel: [23178.419819] [<c02e458c>] (__netdev_alloc_frag+0x90/0x118) from [<c02e86fc>] (__netdev_alloc_skb+0x40/0xd0)
Jan 29 01:42:13 raspberrypi kernel: [23178.419840] [<c02e86fc>] (__netdev_alloc_skb+0x40/0xd0) from [<c026a870>] (rx_submit+0x1c/0x1f8)
Jan 29 01:42:13 raspberrypi kernel: [23178.419862] [<c026a870>] (rx_submit+0x1c/0x1f8) from [<c02721f0>] (usb_hcd_giveback_urb+0x60/0xf4)
Jan 29 01:42:13 raspberrypi kernel: [23178.419885] [<c02721f0>] (usb_hcd_giveback_urb+0x60/0xf4) from [<c02985b4>] (_complete+0xb8/0x1dc)
Jan 29 01:42:13 raspberrypi kernel: [23178.419904] [<c02985b4>] (_complete+0xb8/0x1dc) from [<c029a57c>] (handle_hc_xfercomp_intr+0x2fc/0x41c)
Jan 29 01:42:13 raspberrypi kernel: [23178.419922] [<c029a57c>] (handle_hc_xfercomp_intr+0x2fc/0x41c) from [<c029af5c>] (dwc_otg_hcd_handle_hc_n_intr+0x3a4/0x5c0)
Jan 29 01:42:13 raspberrypi kernel: [23178.419939] [<c029af5c>] (dwc_otg_hcd_handle_hc_n_intr+0x3a4/0x5c0) from [<c029b1e4>] (dwc_otg_hcd_handle_hc_intr+0x6c/0x80)
Jan 29 01:42:13 raspberrypi kernel: [23178.419955] [<c029b1e4>] (dwc_otg_hcd_handle_hc_intr+0x6c/0x80) from [<c029b3a8>] (dwc_otg_hcd_handle_intr+0x1b0/0x1f4)
Jan 29 01:42:13 raspberrypi kernel: [23178.419972] [<c029b3a8>] (dwc_otg_hcd_handle_intr+0x1b0/0x1f4) from [<c0298d08>] (dwc_otg_hcd_irq+0xc/0x18)
Jan 29 01:42:13 raspberrypi kernel: [23178.419990] [<c0298d08>] (dwc_otg_hcd_irq+0xc/0x18) from [<c02717a0>] (usb_hcd_irq+0x2c/0x44)
Jan 29 01:42:13 raspberrypi kernel: [23178.420015] [<c02717a0>] (usb_hcd_irq+0x2c/0x44) from [<c0078560>] (handle_irq_event_percpu+0x50/0x1b0)
Jan 29 01:42:13 raspberrypi kernel: [23178.420034] [<c0078560>] (handle_irq_event_percpu+0x50/0x1b0) from [<c0078714>] (handle_irq_event+0x54/0x84)
Jan 29 01:42:13 raspberrypi kernel: [23178.420053] [<c0078714>] (handle_irq_event+0x54/0x84) from [<c007aab0>] (handle_level_irq+0x98/0x108)
Jan 29 01:42:13 raspberrypi kernel: [23178.420071] [<c007aab0>] (handle_level_irq+0x98/0x108) from [<c0077e58>] (generic_handle_irq+0x28/0x40)
Jan 29 01:42:13 raspberrypi kernel: [23178.420095] [<c0077e58>] (generic_handle_irq+0x28/0x40) from [<c000e91c>] (handle_IRQ+0x30/0x84)
Jan 29 01:42:13 raspberrypi kernel: [23178.420112] [<c000e91c>] (handle_IRQ+0x30/0x84) from [<c03997d4>] (__irq_svc+0x34/0xc8)
Jan 29 01:42:13 raspberrypi kernel: [23178.420137] [<c03997d4>] (__irq_svc+0x34/0xc8) from [<c0025808>] (__do_softirq+0x54/0x154)
Jan 29 01:42:13 raspberrypi kernel: [23178.420156] [<c0025808>] (__do_softirq+0x54/0x154) from [<c0025d1c>] (irq_exit+0x8c/0x94)
Jan 29 01:42:13 raspberrypi kernel: [23178.420172] [<c0025d1c>] (irq_exit+0x8c/0x94) from [<c000e920>] (handle_IRQ+0x34/0x84)
Jan 29 01:42:13 raspberrypi kernel: [23178.420187] [<c000e920>] (handle_IRQ+0x34/0x84) from [<c03997d4>] (__irq_svc+0x34/0xc8)
Jan 29 01:42:13 raspberrypi kernel: [23178.420202] [<c03997d4>] (__irq_svc+0x34/0xc8) from [<c000ea60>] (default_idle+0x28/0x30)
Jan 29 01:42:13 raspberrypi kernel: [23178.420218] [<c000ea60>] (default_idle+0x28/0x30) from [<c000ec10>] (cpu_idle+0x90/0xb8)
Jan 29 01:42:13 raspberrypi kernel: [23178.420239] [<c000ec10>] (cpu_idle+0x90/0xb8) from [<c04e673c>] (start_kernel+0x28c/0x2d4)
Jan 29 01:42:13 raspberrypi kernel: [23178.420246] Mem-info:
Jan 29 01:42:13 raspberrypi kernel: [23178.420251] Normal per-cpu:
Jan 29 01:42:13 raspberrypi kernel: [23178.420259] CPU    0: hi:  186, btch:  31 usd:  16
Jan 29 01:42:13 raspberrypi kernel: [23178.420275] active_anon:33407 inactive_anon:3601 isolated_anon:0
Jan 29 01:42:13 raspberrypi kernel: [23178.420275]  active_file:20756 inactive_file:49383 isolated_file:0
Jan 29 01:42:13 raspberrypi kernel: [23178.420275]  unevictable:0 dirty:4029 writeback:1178 unstable:0
Jan 29 01:42:13 raspberrypi kernel: [23178.420275]  free:3004 slab_reclaimable:2318 slab_unreclaimable:1064
Jan 29 01:42:13 raspberrypi kernel: [23178.420275]  mapped:3363 shmem:57 pagetables:277 bounce:0
Jan 29 01:42:13 raspberrypi kernel: [23178.420311] Normal free:12016kB min:8192kB low:10240kB high:12288kB active_anon:133628kB inactive_anon:14404kB active_file:83024kB inactive_file:197532kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:503936kB mlocked:0kB dirty:16116kB writeback:4712kB mapped:13452kB shmem:228kB slab_reclaimable:9272kB slab_unreclaimable:4256kB kernel_stack:736kB pagetables:1108kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:2842 all_unreclaimable? no
Jan 29 01:42:13 raspberrypi kernel: [23178.420320] lowmem_reserve[]: 0 0
Jan 29 01:42:13 raspberrypi kernel: [23178.420331] Normal: 64*4kB 64*8kB 63*16kB 64*32kB 64*64kB 32*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 12016kB
Jan 29 01:42:13 raspberrypi kernel: [23178.420363] 70196 total pagecache pages
Jan 29 01:42:13 raspberrypi kernel: [23178.420369] 0 pages in swap cache
Jan 29 01:42:13 raspberrypi kernel: [23178.420375] Swap cache stats: add 0, delete 0, find 0/0
Jan 29 01:42:13 raspberrypi kernel: [23178.420380] Free swap  = 102396kB
Jan 29 01:42:13 raspberrypi kernel: [23178.420385] Total swap = 102396kB
Jan 29 01:42:13 raspberrypi kernel: [23178.437447] 126976 pages of RAM
Jan 29 01:42:13 raspberrypi kernel: [23178.437454] 3211 free pages
Jan 29 01:42:13 raspberrypi kernel: [23178.437458] 2590 reserved pages
Jan 29 01:42:13 raspberrypi kernel: [23178.437463] 3382 slab pages
Jan 29 01:42:13 raspberrypi kernel: [23178.437467] 142918 pages shared
Jan 29 01:42:13 raspberrypi kernel: [23178.437471] 0 pages swap cached
Jan 29 01:42:13 raspberrypi kernel: [23178.437492] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Jan 29 01:42:13 raspberrypi kernel: [23178.437651] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Jan 29 01:42:13 raspberrypi kernel: [23178.437749] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Jan 29 01:42:13 raspberrypi kernel: [23178.456181] SLAB: Unable to allocate memory on node 0 (gfp=0x20)
Jan 29 01:42:13 raspberrypi kernel: [23178.456203]   cache: request_sock_TCP, object size: 96, order: 0
Jan 29 01:42:13 raspberrypi kernel: [23178.456213]   node 0: slabs: 2/2, objs: 80/80, free: 0
Jan 29 01:42:14 raspberrypi kernel: [23179.829791] SLAB: Unable to allocate memory on node 0 (gfp=0x20)
Jan 29 01:42:14 raspberrypi kernel: [23179.829811]   cache: TCP, object size: 1248, order: 0
Jan 29 01:42:14 raspberrypi kernel: [23179.829837]   node 0: slabs: 111/111, objs: 333/333, free: 0

vm.min_free_kbytes=10240 is error free, but I'm not really sure how valid my testing is after last time - given the nature of torrents it's all a bit random! I'm sticking with 10240 for now and will see how it goes - seems a bit high given the total memory available (512MB), but maybe that's the price to pay when using torrents.

I'm not really sure that 10240 is "safe", it's just a figure that in my very limited testing was sufficient at this point in time.

@ghalfacree
Copy link

This issue is still outstanding. With vm.min_free_kbytes=16536 and smsc95xx.turbo_mode=N I'm still seeing allocation failures on a Raspberry Pi Model B Revision 2.

[413169.145882] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
[413169.145952] ksoftirqd/0: page allocation failure: order:0, mode:0x20
[413169.146003] [<c0013a7c>] (unwind_backtrace+0x0/0xf0) from [<c009274c>] (warn_alloc_failed+0xc4/0x11c)
[413169.146030] [<c009274c>] (warn_alloc_failed+0xc4/0x11c) from [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c)
[413169.146054] [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c) from [<c02e49e4>] (__netdev_alloc_frag+0x90/0x118)
[413169.146079] [<c02e49e4>] (__netdev_alloc_frag+0x90/0x118) from [<c02e8b54>] (__netdev_alloc_skb+0x40/0xd0)
[413169.146104] [<c02e8b54>] (__netdev_alloc_skb+0x40/0xd0) from [<c026aac0>] (rx_submit+0x1c/0x1f8)
[413169.146132] [<c026aac0>] (rx_submit+0x1c/0x1f8) from [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4)
[413169.146158] [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4) from [<c0296220>] (completion_tasklet_func+0x68/0x94)
[413169.146191] [<c0296220>] (completion_tasklet_func+0x68/0x94) from [<c029fb88>] (tasklet_callback+0x10/0x14)
[413169.146225] [<c029fb88>] (tasklet_callback+0x10/0x14) from [<c002565c>] (tasklet_hi_action+0x60/0xb4)
[413169.146247] [<c002565c>] (tasklet_hi_action+0x60/0xb4) from [<c0025840>] (__do_softirq+0xa0/0x154)
[413169.146267] [<c0025840>] (__do_softirq+0xa0/0x154) from [<c00259ac>] (run_ksoftirqd+0xb8/0x15c)
[413169.146297] [<c00259ac>] (run_ksoftirqd+0xb8/0x15c) from [<c003a7b4>] (kthread+0x88/0x94)
[413169.146328] [<c003a7b4>] (kthread+0x88/0x94) from [<c000e9fc>] (kernel_thread_exit+0x0/0x8)
[413169.146335] Mem-info:
[413169.146342] Normal per-cpu:
[413169.146350] CPU    0: hi:  186, btch:  31 usd:  45
[413169.146369] active_anon:555 inactive_anon:5525 isolated_anon:0
[413169.146369]  active_file:30639 inactive_file:79502 isolated_file:0
[413169.146369]  unevictable:0 dirty:4140 writeback:0 unstable:0
[413169.146369]  free:2654 slab_reclaimable:2182 slab_unreclaimable:1054
[413169.146369]  mapped:1477 shmem:96 pagetables:202 bounce:0
[413169.146410] Normal free:10616kB min:8192kB low:10240kB high:12288kB active_anon:2220kB inactive_anon:22100kB active_file:122556kB inactive_file:318008kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:503936kB mlocked:0kB dirty:16560kB writeback:0kB mapped:5908kB shmem:384kB slab_reclaimable:8728kB slab_unreclaimable:4216kB kernel_stack:1256kB pagetables:808kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[413169.146421] lowmem_reserve[]: 0 0
[413169.146436] Normal: 410*4kB 378*8kB 266*16kB 47*32kB 3*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 10616kB
[413169.146472] 110243 total pagecache pages
[413169.146479] 0 pages in swap cache
[413169.146486] Swap cache stats: add 0, delete 0, find 0/0
[413169.146492] Free swap  = 102396kB
[413169.146497] Total swap = 102396kB
[413169.170099] 126976 pages of RAM
[413169.170108] 2956 free pages
[413169.170113] 2590 reserved pages
[413169.170118] 3236 slab pages
[413169.170123] 97503 pages shared
[413169.170128] 0 pages swap cached
[413169.170277] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
[413169.170369] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped

This is occuring with nothing more than lightweight network traffic - I'm running wget to download some PDF files at a peak rate of around 300Kb/s. I'm only running a single wget process at a time, so there's only ever one HTTP connection - meaning it's not a case of flooding the Pi with BitTorrent traffic, but a flaw that can be exploited even in a light usage scenario.

Kernel version 3.6.11+ #399.

@popcornmix
Copy link
Collaborator

@ghalfacree
That's surprising, I've not seen these errors for months, and never given the scenario you describe.

Can you produce a set of instructions for reproducing this? E.g. start with fresh raspbian image, and produce a sequence of commands that results in this failure?

@popcornmix popcornmix reopened this Apr 5, 2013
@ghalfacree
Copy link

@popcornmix It's not easy, sadly: the problem only tends to crop up after the device has been running for quite some time - the first hit in the kernel log, pasted above, is from running the device solidly for nearly five days.

I've upgraded to the very latest firmware and kernel - 3.6.11+ #403 - and will monitor it. For what it's worth, my usage is as follows:
2x 2TB USB 3.0 external hard drives connected to the Pi's USB 2.0 ports, formatted as btrfs and joined in a btrfs RAID1 array (via brtfs itself, not mdadm), mounted with LZO compression and space caching options.
Connected to 100Mb/s network
Daily backups from a desktop via SSH (typically ~100MB in size, occasionally as big as 10GB)
Occasional sustained but slow wget downloads (as with when the problem occurred most recently)
Occasional media streaming via minidlna

CPU usage often hits 100% during SSH backup, but I use arcfour when doing big transfers and it sits at around 70% then. I guess, compared to other's usage of the Pi, I could be stressing the USB bus more than most: all network data is either being read from or written to the two hard drives simultaneously.

I've boosted vm.min_free_kbytes by 10MB, and I'll keep monitoring the situation. If it happens again - and I should know in a week, from past experience - I'll set up a fresh install with a single USB hard drive and see if I can reliably trigger the problem on that, too.

@ghollingworth
Copy link

Also note that the callstack is different to before, this call stack includes the new tasklet from P33M, it is possible there is some sort of locking problem between the tasklet and the main code…

Gordon

On 5 Apr 2013, at 14:21, Gareth Halfacree <[email protected]mailto:[email protected]>
wrote:

@popcornmixhttps://github.com/popcornmix It's not easy, sadly: the problem only tends to crop up after the device has been running for quite some time - the first hit in the kernel log, pasted above, is from running the device solidly for nearly five days.

I've upgraded to the very latest firmware and kernel - 3.6.11+ #403 - and will monitor it. For what it's worth, my usage is as follows:
2x 2TB USB 3.0 external hard drives connected to the Pi's USB 2.0 ports, formatted as btrfs and joined in a btrfs RAID1 array (via brtfs itself, not mdadm)
Connected to 100Mb/s network
Daily backups from a desktop via SSH (typically ~100MB in size, occasionally as big as 10GB)
Occasional sustained but slow wget downloads (as with when the problem occurred most recently)
Occasional media streaming via minidlna

CPU usage often hits 100% during SSH backup, but I use arcfour when doing big transfers and it sits at around 70% then. I guess, compared to other's usage of the Pi, I could be stressing the USB bus more than most: all network data is either being read from or written to the two hard drives simultaneously.

I've boosted vm.min_free_kbytes by 10MB, and I'll keep monitoring the situation. If it happens again - and I should know in a week, from past experience - I'll set up a fresh install with a single USB hard drive and see if I can reliably trigger the problem on that, too.


Reply to this email directly or view it on GitHubhttps://github.com//issues/153#issuecomment-15955082.

@popcornmix
Copy link
Collaborator

@ghalfacree
If you revert kernel to this one:

https://github.com/Hexxeh/rpi-firmware/commit/aea9d8e529baf2c11e0282706b71ae8cfc8ee909

(the last one before the USB tasklet was introcuded) is it any better?

@ghalfacree
Copy link

I've been able to get it to fail after just one day, during sustained wget combined with heavy SSH uploading (it's about a third the way through a 15GB upload.)

[91573.738711] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
[91573.738867] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
[91579.549733] warn_alloc_failed: 7481 callbacks suppressed
[91579.549765] swapper: page allocation failure: order:0, mode:0x20
[91579.549817] [<c0013a7c>] (unwind_backtrace+0x0/0xf0) from [<c009274c>] (warn_alloc_failed+0xc4/0x11c)
[91579.549847] [<c009274c>] (warn_alloc_failed+0xc4/0x11c) from [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c)
[91579.549876] [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c) from [<c02e49ec>] (__netdev_alloc_frag+0x90/0x118)
[91579.549906] [<c02e49ec>] (__netdev_alloc_frag+0x90/0x118) from [<c02e8b5c>] (__netdev_alloc_skb+0x40/0xd0)
[91579.549936] [<c02e8b5c>] (__netdev_alloc_skb+0x40/0xd0) from [<c026aac0>] (rx_submit+0x1c/0x1f8)
[91579.549970] [<c026aac0>] (rx_submit+0x1c/0x1f8) from [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4)
[91579.550002] [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4) from [<c0296228>] (completion_tasklet_func+0x68/0x94)
[91579.550041] [<c0296228>] (completion_tasklet_func+0x68/0x94) from [<c029fb90>] (tasklet_callback+0x10/0x14)
[91579.550080] [<c029fb90>] (tasklet_callback+0x10/0x14) from [<c002565c>] (tasklet_hi_action+0x60/0xb4)
[91579.550106] [<c002565c>] (tasklet_hi_action+0x60/0xb4) from [<c0025840>] (__do_softirq+0xa0/0x154)
[91579.550131] [<c0025840>] (__do_softirq+0xa0/0x154) from [<c0025d08>] (irq_exit+0x8c/0x94)
[91579.550163] [<c0025d08>] (irq_exit+0x8c/0x94) from [<c000e920>] (handle_IRQ+0x34/0x84)
[91579.550187] [<c000e920>] (handle_IRQ+0x34/0x84) from [<c0399c34>] (__irq_svc+0x34/0xc8)
[91579.550211] [<c0399c34>] (__irq_svc+0x34/0xc8) from [<c000ea60>] (default_idle+0x28/0x30)
[91579.550234] [<c000ea60>] (default_idle+0x28/0x30) from [<c000ec10>] (cpu_idle+0x90/0xb8)
[91579.550267] [<c000ec10>] (cpu_idle+0x90/0xb8) from [<c04e773c>] (start_kernel+0x28c/0x2d4)
[91579.550277] Mem-info:
[91579.550284] Normal per-cpu:
[91579.550295] CPU    0: hi:  186, btch:  31 usd: 167
[91579.550320] active_anon:2293 inactive_anon:3120 isolated_anon:0
[91579.550320]  active_file:47026 inactive_file:63557 isolated_file:0
[91579.550320]  unevictable:0 dirty:3079 writeback:0 unstable:0
[91579.550320]  free:2797 slab_reclaimable:1945 slab_unreclaimable:1174
[91579.550320]  mapped:1955 shmem:95 pagetables:248 bounce:0
[91579.550372] Normal free:11188kB min:8192kB low:10240kB high:12288kB active_anon:9172kB inactive_anon:12480kB active_file:188104kB inactive_file:254228kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:503936kB mlocked:0kB dirty:12316kB writeback:0kB mapped:7820kB shmem:380kB slab_reclaimable:7780kB slab_unreclaimable:4696kB kernel_stack:1336kB pagetables:992kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[91579.550385] lowmem_reserve[]: 0 0
[91579.550402] Normal: 267*4kB 261*8kB 262*16kB 86*32kB 15*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 11188kB
[91579.550444] 110682 total pagecache pages
[91579.550452] 0 pages in swap cache
[91579.550461] Swap cache stats: add 0, delete 0, find 0/0
[91579.550468] Free swap  = 102396kB
[91579.550475] Total swap = 102396kB
[91579.576620] 126976 pages of RAM
[91579.576631] 3255 free pages
[91579.576637] 2590 reserved pages
[91579.576643] 3119 slab pages
[91579.576650] 108103 pages shared
[91579.576656] 0 pages swap cached

Once the transfer has completed, I'll revert to the kernel suggested by @popcornmix and try again.

@ghalfacree
Copy link

Using the kernel from commit aea9d8e529baf2c11e0282706b71ae8cfc8ee909, the system dropped off the network entirely this morning. As I'm running the unit headless, I was unable to view the kernel messages for a reason.

I'm upgrading back to the latest kernel version, as I'd rather have recoverable errors than the entire thing become completely unresponsive to network traffic.

EDIT:
A reboot brought it back up, and looking at kern.log I can see it thinks it rebooted itself yesterday evening - but that was actually me pulling the power this morning. There's a boot event at Apr 6 11:20:34 when I switched to the recommended kernel version, then the system appears to run fine until Apr 6 18:20:43 - almost exactly seven hours after boot - when the first page allocation failure happens. The log is then spammed by continuous page allocation failures until it the reboot - at which point the clock drops back three minutes, with a claimed timestamp of Apr 6 18:17:25. The log then shows a perfectly normal boot process, followed by my upgrading the kernel/firmware and rebooting

Key log extracts below:

Booting the #397 kernel to first page allocation failure:
Apr  6 11:20:34 keylime kernel: [    0.000000] Booting Linux on physical CPU 0
Apr  6 11:20:34 keylime kernel: [    0.000000] Initializing cgroup subsys cpu
Apr  6 11:20:34 keylime kernel: [    0.000000] Linux version 3.6.11+ (dc4@dc4-arm-01) (gcc version 4.7.2 20120731 (prerelease) (crosstool-NG linaro-1.13.1+bzr2458 - Linaro GCC 2012.08) ) #397 PREEMPT Mon Mar 18 22:17:49 GMT 2013
Apr  6 11:20:34 keylime kernel: [    0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
Apr  6 11:20:34 keylime kernel: [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Apr  6 11:20:34 keylime kernel: [    0.000000] Machine: BCM2708
Apr  6 11:20:34 keylime kernel: [    0.000000] cma: CMA: reserved 16 MiB at 1e000000
Apr  6 11:20:34 keylime kernel: [    0.000000] Memory policy: ECC disabled, Data cache writeback
Apr  6 11:20:34 keylime kernel: [    0.000000] On node 0 totalpages: 126976
Apr  6 11:20:34 keylime kernel: [    0.000000] free_area_init_node: node 0, pgdat c053b834, node_mem_map c05e5000
Apr  6 11:20:34 keylime kernel: [    0.000000]   Normal zone: 992 pages used for memmap
Apr  6 11:20:34 keylime kernel: [    0.000000]   Normal zone: 0 pages reserved
Apr  6 11:20:34 keylime kernel: [    0.000000]   Normal zone: 125984 pages, LIFO batch:31
Apr  6 11:20:34 keylime kernel: [    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
Apr  6 11:20:34 keylime kernel: [    0.000000] pcpu-alloc: [0] 0 
Apr  6 11:20:34 keylime kernel: [    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 125984
Apr  6 11:20:34 keylime kernel: [    0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=720 bcm2708_fb.fbheight=480 bcm2708.boardrev=0xe bcm2708.serial=0x605a795d smsc95xx.macaddr=B8:27:EB:5A:79:5D sdhci-bcm2708.emmc_clock_freq=100000000 vc_mem.mem_base=0x1fa00000 vc_mem.mem_size=0x20000000  dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait smsc95xx.turbo_mode=N vm.min_free_kbytes=16536
Apr  6 11:20:34 keylime kernel: [    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
Apr  6 11:20:34 keylime kernel: [    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
Apr  6 11:20:34 keylime kernel: [    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
Apr  6 11:20:34 keylime kernel: [    0.000000] Memory: 496MB = 496MB total
Apr  6 11:20:34 keylime kernel: [    0.000000] Memory: 481032k/481032k available, 26872k reserved, 0K highmem
Apr  6 11:20:34 keylime kernel: [    0.000000] Virtual kernel memory layout:
Apr  6 11:20:34 keylime kernel: [    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
Apr  6 11:20:34 keylime kernel: [    0.000000]     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
Apr  6 11:20:34 keylime kernel: [    0.000000]     vmalloc : 0xdf800000 - 0xff000000   ( 504 MB)
Apr  6 11:20:34 keylime kernel: [    0.000000]     lowmem  : 0xc0000000 - 0xdf000000   ( 496 MB)
Apr  6 11:20:34 keylime kernel: [    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
Apr  6 11:20:34 keylime kernel: [    0.000000]       .text : 0xc0008000 - 0xc04e6480   (4986 kB)
Apr  6 11:20:34 keylime kernel: [    0.000000]       .init : 0xc04e7000 - 0xc0507f24   ( 132 kB)
Apr  6 11:20:34 keylime kernel: [    0.000000]       .data : 0xc0508000 - 0xc053c060   ( 209 kB)
Apr  6 11:20:34 keylime kernel: [    0.000000]        .bss : 0xc053c084 - 0xc05e4738   ( 674 kB)
Apr  6 11:20:34 keylime kernel: [    0.000000] NR_IRQS:330
Apr  6 11:20:34 keylime kernel: [    0.000000] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 4294967ms
Apr  6 11:20:34 keylime kernel: [    0.000000] Console: colour dummy device 80x30
Apr  6 11:20:34 keylime kernel: [    0.000000] console [tty1] enabled
Apr  6 11:20:34 keylime kernel: [    0.001018] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
Apr  6 11:20:34 keylime kernel: [    0.060127] pid_max: default: 32768 minimum: 301
Apr  6 11:20:34 keylime kernel: [    0.060459] Mount-cache hash table entries: 512
Apr  6 11:20:34 keylime kernel: [    0.061213] Initializing cgroup subsys cpuacct
Apr  6 11:20:34 keylime kernel: [    0.061268] Initializing cgroup subsys devices
Apr  6 11:20:34 keylime kernel: [    0.061302] Initializing cgroup subsys freezer
Apr  6 11:20:34 keylime kernel: [    0.061331] Initializing cgroup subsys blkio
Apr  6 11:20:34 keylime kernel: [    0.061421] CPU: Testing write buffer coherency: ok
Apr  6 11:20:34 keylime kernel: [    0.061753] hw perfevents: enabled with v6 PMU driver, 3 counters available
Apr  6 11:20:34 keylime kernel: [    0.061894] Setting up static identity map for 0x39d478 - 0x39d4d4
Apr  6 11:20:34 keylime kernel: [    0.063403] devtmpfs: initialized
Apr  6 11:20:34 keylime kernel: [    0.074169] NET: Registered protocol family 16
Apr  6 11:20:34 keylime kernel: [    0.080686] DMA: preallocated 4096 KiB pool for atomic coherent allocations
Apr  6 11:20:34 keylime kernel: [    0.081844] bcm2708.uart_clock = 0
Apr  6 11:20:34 keylime kernel: [    0.083197] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
Apr  6 11:20:34 keylime kernel: [    0.083252] hw-breakpoint: maximum watchpoint size is 4 bytes.
Apr  6 11:20:34 keylime kernel: [    0.083288] mailbox: Broadcom VideoCore Mailbox driver
Apr  6 11:20:34 keylime kernel: [    0.083379] bcm2708_vcio: mailbox at f200b880
Apr  6 11:20:34 keylime kernel: [    0.083479] bcm_power: Broadcom power driver
Apr  6 11:20:34 keylime kernel: [    0.083517] bcm_power_open() -> 0
Apr  6 11:20:34 keylime kernel: [    0.083542] bcm_power_request(0, 8)
Apr  6 11:20:34 keylime kernel: [    0.584229] bcm_mailbox_read -> 00000080, 0
Apr  6 11:20:34 keylime kernel: [    0.584269] bcm_power_request -> 0
Apr  6 11:20:34 keylime kernel: [    0.584294] Serial: AMBA PL011 UART driver
Apr  6 11:20:34 keylime kernel: [    0.584436] dev:f1: ttyAMA0 at MMIO 0x20201000 (irq = 83) is a PL011 rev3
Apr  6 11:20:34 keylime kernel: [    0.912336] console [ttyAMA0] enabled
Apr  6 11:20:34 keylime kernel: [    0.935748] bio: create slab <bio-0> at 0
Apr  6 11:20:34 keylime kernel: [    0.940630] SCSI subsystem initialized
Apr  6 11:20:34 keylime kernel: [    0.944722] usbcore: registered new interface driver usbfs
Apr  6 11:20:34 keylime kernel: [    0.950306] usbcore: registered new interface driver hub
Apr  6 11:20:34 keylime kernel: [    0.955902] usbcore: registered new device driver usb
Apr  6 11:20:34 keylime kernel: [    0.962306] Switching to clocksource stc
Apr  6 11:20:34 keylime kernel: [    0.966547] FS-Cache: Loaded
Apr  6 11:20:34 keylime kernel: [    0.969691] CacheFiles: Loaded
Apr  6 11:20:34 keylime kernel: [    0.984482] NET: Registered protocol family 2
Apr  6 11:20:34 keylime kernel: [    0.989766] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
Apr  6 11:20:34 keylime kernel: [    0.997506] TCP bind hash table entries: 16384 (order: 4, 65536 bytes)
Apr  6 11:20:34 keylime kernel: [    1.004296] TCP: Hash tables configured (established 16384 bind 16384)
Apr  6 11:20:34 keylime kernel: [    1.010900] TCP: reno registered
Apr  6 11:20:34 keylime kernel: [    1.014154] UDP hash table entries: 256 (order: 0, 4096 bytes)
Apr  6 11:20:34 keylime kernel: [    1.020050] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
Apr  6 11:20:34 keylime kernel: [    1.026630] NET: Registered protocol family 1
Apr  6 11:20:34 keylime kernel: [    1.031495] RPC: Registered named UNIX socket transport module.
Apr  6 11:20:34 keylime kernel: [    1.037539] RPC: Registered udp transport module.
Apr  6 11:20:34 keylime kernel: [    1.042262] RPC: Registered tcp transport module.
Apr  6 11:20:34 keylime kernel: [    1.047007] RPC: Registered tcp NFSv4.1 backchannel transport module.
Apr  6 11:20:34 keylime kernel: [    1.054178] bcm2708_dma: DMA manager at f2007000
Apr  6 11:20:34 keylime kernel: [    1.058963] bcm2708_gpio: bcm2708_gpio_probe c0515d98
Apr  6 11:20:34 keylime kernel: [    1.064427] vc-mem: phys_addr:0x00000000 mem_base=0x1fa00000 mem_size:0x20000000(512 MiB)
Apr  6 11:20:34 keylime kernel: [    1.073588] audit: initializing netlink socket (disabled)
Apr  6 11:20:34 keylime kernel: [    1.079186] type=2000 audit(0.930:1): initialized
Apr  6 11:20:34 keylime kernel: [    1.201378] VFS: Disk quotas dquot_6.5.2
Apr  6 11:20:34 keylime kernel: [    1.205414] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Apr  6 11:20:34 keylime kernel: [    1.212467] FS-Cache: Netfs 'nfs' registered for caching
Apr  6 11:20:34 keylime kernel: [    1.218210] NFS: Registering the id_resolver key type
Apr  6 11:20:34 keylime kernel: [    1.223380] Key type id_resolver registered
Apr  6 11:20:34 keylime kernel: [    1.227672] Key type id_legacy registered
Apr  6 11:20:34 keylime kernel: [    1.232041] msgmni has been set to 971
Apr  6 11:20:34 keylime kernel: [    1.237583] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
Apr  6 11:20:34 keylime kernel: [    1.245289] io scheduler noop registered
Apr  6 11:20:34 keylime kernel: [    1.249334] io scheduler deadline registered (default)
Apr  6 11:20:34 keylime kernel: [    1.254517] io scheduler cfq registered
Apr  6 11:20:34 keylime kernel: [    1.268366] Console: switching to colour frame buffer device 90x30
Apr  6 11:20:34 keylime kernel: [    1.280789] kgdb: Registered I/O driver kgdboc.
Apr  6 11:20:34 keylime kernel: [    1.288165] vc-cma: Videocore CMA driver
Apr  6 11:20:34 keylime kernel: [    1.294230] vc-cma: vc_cma_base      = 0x00000000
Apr  6 11:20:34 keylime kernel: [    1.301106] vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
Apr  6 11:20:34 keylime kernel: [    1.308666] vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
Apr  6 11:20:34 keylime kernel: [    1.325111] brd: module loaded
Apr  6 11:20:34 keylime kernel: [    1.335251] loop: module loaded
Apr  6 11:20:34 keylime kernel: [    1.340897] vchiq: vchiq_init_state: slot_zero = 0xde000000, is_master = 0
Apr  6 11:20:34 keylime kernel: [    1.350645] Loading iSCSI transport class v2.0-870.
Apr  6 11:20:34 keylime kernel: [    1.358596] usbcore: registered new interface driver smsc95xx
Apr  6 11:20:34 keylime kernel: [    1.366619] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Apr  6 11:20:34 keylime kernel: [    1.579519] Core Release: 2.80a
Apr  6 11:20:34 keylime kernel: [    1.584712] Setting default values for core params
Apr  6 11:20:34 keylime kernel: [    1.591596] Finished setting default values for core params
Apr  6 11:20:34 keylime kernel: [    1.804277] Using Buffer DMA mode
Apr  6 11:20:34 keylime kernel: [    1.809618] Periodic Transfer Interrupt Enhancement - disabled
Apr  6 11:20:34 keylime kernel: [    1.817492] Multiprocessor Interrupt Enhancement - disabled
Apr  6 11:20:34 keylime kernel: [    1.825108] OTG VER PARAM: 0, OTG VER FLAG: 0
Apr  6 11:20:34 keylime kernel: [    1.831533] Dedicated Tx FIFOs mode
Apr  6 11:20:34 keylime kernel: [    1.838029] dwc_otg: Microframe scheduler enabled
Apr  6 11:20:34 keylime kernel: [    1.838448] dwc_otg bcm2708_usb: DWC OTG Controller
Apr  6 11:20:34 keylime kernel: [    1.845410] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
Apr  6 11:20:34 keylime kernel: [    1.854810] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
Apr  6 11:20:34 keylime kernel: [    1.862487] Init: Port Power? op_state=1
Apr  6 11:20:34 keylime kernel: [    1.868466] Init: Power Port (0)
Apr  6 11:20:34 keylime kernel: [    1.873740] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Apr  6 11:20:34 keylime kernel: [    1.882602] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Apr  6 11:20:34 keylime kernel: [    1.891900] usb usb1: Product: DWC OTG Controller
Apr  6 11:20:34 keylime kernel: [    1.898675] usb usb1: Manufacturer: Linux 3.6.11+ dwc_otg_hcd
Apr  6 11:20:34 keylime kernel: [    1.906539] usb usb1: SerialNumber: bcm2708_usb
Apr  6 11:20:34 keylime kernel: [    1.913957] hub 1-0:1.0: USB hub found
Apr  6 11:20:34 keylime kernel: [    1.919929] hub 1-0:1.0: 1 port detected
Apr  6 11:20:34 keylime kernel: [    1.926292] dwc_otg: FIQ enabled
Apr  6 11:20:34 keylime kernel: [    1.926309] dwc_otg: NAK holdoff enabled
Apr  6 11:20:34 keylime kernel: [    1.926330] Module dwc_common_port init
Apr  6 11:20:34 keylime kernel: [    1.926592] Initializing USB Mass Storage driver...
Apr  6 11:20:34 keylime kernel: [    1.933786] usbcore: registered new interface driver usb-storage
Apr  6 11:20:34 keylime kernel: [    1.941972] USB Mass Storage support registered.
Apr  6 11:20:34 keylime kernel: [    1.948851] usbcore: registered new interface driver libusual
Apr  6 11:20:34 keylime kernel: [    1.957021] mousedev: PS/2 mouse device common for all mice
Apr  6 11:20:34 keylime kernel: [    1.965354] bcm2835-cpufreq: min=700000 max=900000 cur=700000
Apr  6 11:20:34 keylime kernel: [    1.973395] bcm2835-cpufreq: switching to governor powersave
Apr  6 11:20:34 keylime kernel: [    1.981191] bcm2835-cpufreq: switching to governor powersave
Apr  6 11:20:34 keylime kernel: [    1.988894] cpuidle: using governor ladder
Apr  6 11:20:34 keylime kernel: [    1.994958] cpuidle: using governor menu
Apr  6 11:20:34 keylime kernel: [    2.000872] sdhci: Secure Digital Host Controller Interface driver
Apr  6 11:20:34 keylime kernel: [    2.009044] sdhci: Copyright(c) Pierre Ossman
Apr  6 11:20:34 keylime kernel: [    2.015431] sdhci: Enable low-latency mode
Apr  6 11:20:34 keylime kernel: [    2.066576] mmc0: SDHCI controller on BCM2708_Arasan [platform] using platform's DMA
Apr  6 11:20:34 keylime kernel: [    2.076640] mmc0: BCM2708 SDHC host at 0x20300000 DMA 2 IRQ 77
Apr  6 11:20:34 keylime kernel: [    2.086752] sdhci-pltfm: SDHCI platform and OF driver helper
Apr  6 11:20:34 keylime kernel: [    2.100239] usbcore: registered new interface driver usbhid
Apr  6 11:20:34 keylime kernel: [    2.108036] usbhid: USB HID core driver
Apr  6 11:20:34 keylime kernel: [    2.118605] Indeed it is in host mode hprt0 = 00021501
Apr  6 11:20:34 keylime kernel: [    2.128184] TCP: cubic registered
Apr  6 11:20:34 keylime kernel: [    2.146429] Initializing XFRM netlink socket
Apr  6 11:20:34 keylime kernel: [    2.153144] NET: Registered protocol family 17
Apr  6 11:20:34 keylime kernel: [    2.166625] Key type dns_resolver registered
Apr  6 11:20:34 keylime kernel: [    2.196858] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
Apr  6 11:20:34 keylime kernel: [    2.208974] mmc0: read SD Status register (SSR) after 2 attempts
Apr  6 11:20:34 keylime kernel: [    2.217951] registered taskstats version 1
Apr  6 11:20:34 keylime kernel: [    2.237088] Waiting for root device /dev/mmcblk0p2...
Apr  6 11:20:34 keylime kernel: [    2.246531] mmc0: new high speed SDHC card at address b368
Apr  6 11:20:34 keylime kernel: [    2.266650] mmcblk0: mmc0:b368 SDC   3.74 GiB 
Apr  6 11:20:34 keylime kernel: [    2.274954]  mmcblk0: p1 p2
Apr  6 11:20:34 keylime kernel: [    2.372161] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Apr  6 11:20:34 keylime kernel: [    2.384859] VFS: Mounted root (ext4 filesystem) on device 179:2.
Apr  6 11:20:34 keylime kernel: [    2.393293] usb 1-1: new high-speed USB device number 2 using dwc_otg
Apr  6 11:20:34 keylime kernel: [    2.402588] Indeed it is in host mode hprt0 = 00001101
Apr  6 11:20:34 keylime kernel: [    2.418494] devtmpfs: mounted
Apr  6 11:20:34 keylime kernel: [    2.424296] Freeing init memory: 128K
Apr  6 11:20:34 keylime kernel: [    2.626933] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
Apr  6 11:20:34 keylime kernel: [    2.636111] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Apr  6 11:20:34 keylime kernel: [    2.647158] hub 1-1:1.0: USB hub found
Apr  6 11:20:34 keylime kernel: [    2.653437] hub 1-1:1.0: 3 ports detected
Apr  6 11:20:34 keylime kernel: [    2.936652] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Apr  6 11:20:34 keylime kernel: [    3.047043] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Apr  6 11:20:34 keylime kernel: [    3.059801] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Apr  6 11:20:34 keylime kernel: [    3.079382] smsc95xx v1.0.4
Apr  6 11:20:34 keylime kernel: [    3.141142] smsc95xx 1-1.1:1.0: eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:5a:79:5d
Apr  6 11:20:34 keylime kernel: [    3.266713] usb 1-1.2: new high-speed USB device number 4 using dwc_otg
Apr  6 11:20:34 keylime kernel: [    3.399247] usb 1-1.2: New USB device found, idVendor=0480, idProduct=d010
Apr  6 11:20:34 keylime kernel: [    3.413264] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Apr  6 11:20:34 keylime kernel: [    3.423345] usb 1-1.2: Product: External USB 3.0
Apr  6 11:20:34 keylime kernel: [    3.430536] usb 1-1.2: Manufacturer: Toshiba
Apr  6 11:20:34 keylime kernel: [    3.437358] usb 1-1.2: SerialNumber: 20121022010604
Apr  6 11:20:34 keylime kernel: [    3.447706] scsi0 : usb-storage 1-1.2:1.0
Apr  6 11:20:34 keylime kernel: [    3.546743] usb 1-1.3: new high-speed USB device number 5 using dwc_otg
Apr  6 11:20:34 keylime kernel: [    3.688832] usb 1-1.3: New USB device found, idVendor=0bc2, idProduct=3320
Apr  6 11:20:34 keylime kernel: [    3.706516] usb 1-1.3: New USB device strings: Mfr=2, Product=3, SerialNumber=1
Apr  6 11:20:34 keylime kernel: [    3.716316] usb 1-1.3: Product: Expansion Desk
Apr  6 11:20:34 keylime kernel: [    3.744818] usb 1-1.3: Manufacturer: Seagate
Apr  6 11:20:34 keylime kernel: [    3.756502] usb 1-1.3: SerialNumber: NA4L8GL0
Apr  6 11:20:34 keylime kernel: [    3.771213] scsi1 : usb-storage 1-1.3:1.0
Apr  6 11:20:34 keylime kernel: [    4.467879] scsi 0:0:0:0: Direct-Access     Toshiba  External USB 3.0 0201 PQ: 0 ANSI: 6
Apr  6 11:20:34 keylime kernel: [    4.507407] sd 0:0:0:0: [sda] 3907029164 512-byte logical blocks: (2.00 TB/1.81 TiB)
Apr  6 11:20:34 keylime kernel: [    4.532046] sd 0:0:0:0: [sda] Write Protect is off
Apr  6 11:20:34 keylime kernel: [    4.556493] sd 0:0:0:0: [sda] Mode Sense: 2f 00 00 00
Apr  6 11:20:34 keylime kernel: [    4.557294] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
Apr  6 11:20:34 keylime kernel: [    4.625843]  sda: unknown partition table
Apr  6 11:20:34 keylime kernel: [    4.648402] sd 0:0:0:0: [sda] Attached SCSI disk
Apr  6 11:20:34 keylime kernel: [    4.777938] scsi 1:0:0:0: Direct-Access     Seagate  Expansion Desk   070B PQ: 0 ANSI: 6
Apr  6 11:20:34 keylime kernel: [    4.808078] sd 1:0:0:0: [sdb] 3907029167 512-byte logical blocks: (2.00 TB/1.81 TiB)
Apr  6 11:20:34 keylime kernel: [    4.837456] sd 1:0:0:0: [sdb] Write Protect is off
Apr  6 11:20:34 keylime kernel: [    4.844988] sd 1:0:0:0: [sdb] Mode Sense: 43 00 00 00
Apr  6 11:20:34 keylime kernel: [    4.866531] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Apr  6 11:20:34 keylime kernel: [   12.191525]  sdb: unknown partition table
Apr  6 11:20:34 keylime kernel: [   12.204916] sd 1:0:0:0: [sdb] Attached SCSI disk
Apr  6 11:20:34 keylime kernel: [   12.219352] Registered led device: led0
Apr  6 11:20:34 keylime kernel: [   12.307801] Btrfs loaded
Apr  6 11:20:34 keylime kernel: [   12.341475] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 2 transid 15794 /dev/sda
Apr  6 11:20:34 keylime kernel: [   13.051185] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 2 transid 15794 /dev/sda
Apr  6 11:20:34 keylime kernel: [   13.087143] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 1 transid 15794 /dev/sdb
Apr  6 11:20:34 keylime kernel: [   23.138384] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Apr  6 11:20:34 keylime kernel: [   23.574079] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Apr  6 11:20:34 keylime kernel: [   24.318058] bcm2835 ALSA card created!
Apr  6 11:20:34 keylime kernel: [   24.331799] bcm2835 ALSA chip created!
Apr  6 11:20:34 keylime kernel: [   24.345636] bcm2835 ALSA chip created!
Apr  6 11:20:34 keylime kernel: [   24.357716] bcm2835 ALSA chip created!
Apr  6 11:20:34 keylime kernel: [   24.370200] bcm2835 ALSA chip created!
Apr  6 11:20:34 keylime kernel: [   24.384467] bcm2835 ALSA chip created!
Apr  6 11:20:34 keylime kernel: [   24.396172] bcm2835 ALSA chip created!
Apr  6 11:20:34 keylime kernel: [   24.405517] bcm2835 ALSA chip created!
Apr  6 11:20:34 keylime kernel: [   29.026427] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 2 transid 15794 /dev/sda
Apr  6 11:20:34 keylime kernel: [   29.039715] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 1 transid 15794 /dev/sdb
Apr  6 11:20:34 keylime kernel: [   29.053092] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 2 transid 15794 /dev/sda
Apr  6 11:20:34 keylime kernel: [   29.071790] btrfs: use lzo compression
Apr  6 11:20:34 keylime kernel: [   29.077787] btrfs: disk space caching is enabled
Apr  6 11:20:34 keylime kernel: [   33.561587] ip_tables: (C) 2000-2006 Netfilter Core Team
Apr  6 11:20:34 keylime kernel: [   33.624445] nf_conntrack version 0.5.0 (7774 buckets, 31096 max)
Apr  6 11:20:34 keylime kernel: [   35.027789] smsc95xx 1-1.1:1.0: eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
Apr  6 11:20:34 keylime kernel: [   35.925237] bcm2835-cpufreq: switching to governor ondemand
Apr  6 11:20:34 keylime kernel: [   35.925246] bcm2835-cpufreq: switching to governor ondemand
Apr  6 11:20:38 keylime kernel: [   41.923654] Adding 102396k swap on /var/swap.  Priority:-1 extents:129 across:1754856k SS
Apr  6 18:20:43 keylime kernel: [25214.525244] swapper: page allocation failure: order:0, mode:0x20
Apr  6 18:20:43 keylime kernel: [25214.525314] [<c0013a7c>] (unwind_backtrace+0x0/0xf0) from [<c009274c>] (warn_alloc_failed+0xc4/0x11c)
Apr  6 18:20:43 keylime kernel: [25214.525345] [<c009274c>] (warn_alloc_failed+0xc4/0x11c) from [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c)
Apr  6 18:20:43 keylime kernel: [25214.525375] [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c) from [<c02e4878>] (__netdev_alloc_frag+0x90/0x118)
Apr  6 18:20:43 keylime kernel: [25214.525404] [<c02e4878>] (__netdev_alloc_frag+0x90/0x118) from [<c02e89e8>] (__netdev_alloc_skb+0x40/0xd0)
Apr  6 18:20:43 keylime kernel: [25214.525434] [<c02e89e8>] (__netdev_alloc_skb+0x40/0xd0) from [<c026aac0>] (rx_submit+0x1c/0x1f8)
Apr  6 18:20:43 keylime kernel: [25214.525467] [<c026aac0>] (rx_submit+0x1c/0x1f8) from [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4)
Apr  6 18:20:43 keylime kernel: [25214.525501] [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4) from [<c029881c>] (_complete+0xb8/0x1dc)
Apr  6 18:20:43 keylime kernel: [25214.525528] [<c029881c>] (_complete+0xb8/0x1dc) from [<c029a7e4>] (handle_hc_xfercomp_intr+0x2fc/0x41c)
Apr  6 18:20:43 keylime kernel: [25214.525554] [<c029a7e4>] (handle_hc_xfercomp_intr+0x2fc/0x41c) from [<c029b22c>] (dwc_otg_hcd_handle_hc_n_intr+0x36c/0x594)
Apr  6 18:20:43 keylime kernel: [25214.525579] [<c029b22c>] (dwc_otg_hcd_handle_hc_n_intr+0x36c/0x594) from [<c029b4c0>] (dwc_otg_hcd_handle_hc_intr+0x6c/0x80)
Apr  6 18:20:43 keylime kernel: [25214.525603] [<c029b4c0>] (dwc_otg_hcd_handle_hc_intr+0x6c/0x80) from [<c029b684>] (dwc_otg_hcd_handle_intr+0x1b0/0x1f4)
Apr  6 18:20:43 keylime kernel: [25214.525626] [<c029b684>] (dwc_otg_hcd_handle_intr+0x1b0/0x1f4) from [<c0298f70>] (dwc_otg_hcd_irq+0xc/0x18)
Apr  6 18:20:43 keylime kernel: [25214.525650] [<c0298f70>] (dwc_otg_hcd_irq+0xc/0x18) from [<c02719f0>] (usb_hcd_irq+0x2c/0x44)
Apr  6 18:20:43 keylime kernel: [25214.525688] [<c02719f0>] (usb_hcd_irq+0x2c/0x44) from [<c007854c>] (handle_irq_event_percpu+0x50/0x1b0)
Apr  6 18:20:43 keylime kernel: [25214.525715] [<c007854c>] (handle_irq_event_percpu+0x50/0x1b0) from [<c0078700>] (handle_irq_event+0x54/0x84)
Apr  6 18:20:43 keylime kernel: [25214.525744] [<c0078700>] (handle_irq_event+0x54/0x84) from [<c007aa9c>] (handle_level_irq+0x98/0x108)
Apr  6 18:20:43 keylime kernel: [25214.525770] [<c007aa9c>] (handle_level_irq+0x98/0x108) from [<c0077e44>] (generic_handle_irq+0x28/0x40)
Apr  6 18:20:43 keylime kernel: [25214.525805] [<c0077e44>] (generic_handle_irq+0x28/0x40) from [<c000e91c>] (handle_IRQ+0x30/0x84)
Apr  6 18:20:43 keylime kernel: [25214.525829] [<c000e91c>] (handle_IRQ+0x30/0x84) from [<c0399ab4>] (__irq_svc+0x34/0xc8)
Apr  6 18:20:43 keylime kernel: [25214.525853] [<c0399ab4>] (__irq_svc+0x34/0xc8) from [<c000ea60>] (default_idle+0x28/0x30)
Apr  6 18:20:43 keylime kernel: [25214.525877] [<c000ea60>] (default_idle+0x28/0x30) from [<c000ec10>] (cpu_idle+0x90/0xb8)
Apr  6 18:20:43 keylime kernel: [25214.525909] [<c000ec10>] (cpu_idle+0x90/0xb8) from [<c04e773c>] (start_kernel+0x28c/0x2d4)
Apr  6 18:20:43 keylime kernel: [25214.525918] Mem-info:
Apr  6 18:20:43 keylime kernel: [25214.525927] Normal per-cpu:
Apr  6 18:20:43 keylime kernel: [25214.525937] CPU    0: hi:  186, btch:  31 usd:  50
Apr  6 18:20:43 keylime kernel: [25214.525960] active_anon:932 inactive_anon:3594 isolated_anon:0
Apr  6 18:20:43 keylime kernel: [25214.525960]  active_file:53922 inactive_file:57950 isolated_file:0
Apr  6 18:20:43 keylime kernel: [25214.525960]  unevictable:0 dirty:886 writeback:0 unstable:0
Apr  6 18:20:43 keylime kernel: [25214.525960]  free:2791 slab_reclaimable:1878 slab_unreclaimable:1054
Apr  6 18:20:43 keylime kernel: [25214.525960]  mapped:1122 shmem:93 pagetables:214 bounce:0
Apr  6 18:20:43 keylime kernel: [25214.526011] Normal free:11164kB min:8192kB low:10240kB high:12288kB active_anon:3728kB inactive_anon:14376kB active_file:215688kB inactive_file:231800kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:503936kB mlocked:0kB dirty:3544kB writeback:0kB mapped:4488kB shmem:372kB slab_reclaimable:7512kB slab_unreclaimable:4216kB kernel_stack:1280kB pagetables:856kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Apr  6 18:20:43 keylime kernel: [25214.526024] lowmem_reserve[]: 0 0
Apr  6 18:20:43 keylime kernel: [25214.526040] Normal: 275*4kB 268*8kB 265*16kB 109*32kB 3*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 11164kB
Apr  6 18:20:43 keylime kernel: [25214.526083] 111971 total pagecache pages
Apr  6 18:20:43 keylime kernel: [25214.526091] 0 pages in swap cache
Apr  6 18:20:43 keylime kernel: [25214.526100] Swap cache stats: add 0, delete 0, find 0/0
Apr  6 18:20:43 keylime kernel: [25214.526106] Free swap  = 102396kB
Apr  6 18:20:43 keylime kernel: [25214.526113] Total swap = 102396kB
Apr  6 18:20:43 keylime kernel: [25214.552225] 126976 pages of RAM
Apr  6 18:20:43 keylime kernel: [25214.552233] 3110 free pages
Apr  6 18:20:43 keylime kernel: [25214.552239] 2590 reserved pages
Apr  6 18:20:43 keylime kernel: [25214.552245] 2932 slab pages
Apr  6 18:20:43 keylime kernel: [25214.552251] 75872 pages shared
Apr  6 18:20:43 keylime kernel: [25214.552257] 0 pages swap cached
Repeated page allocation failures follow, until the Pi loses network connectivity. Oddly, this next reboot is - as far as I can tell - me pulling the plug this morning, not at 18:17 last night. Why the Pi didn't get the correct time at reboot I do not know.
Apr  6 18:17:25 keylime kernel: [    0.000000] Booting Linux on physical CPU 0
Apr  6 18:17:25 keylime kernel: [    0.000000] Initializing cgroup subsys cpu
Apr  6 18:17:25 keylime kernel: [    0.000000] Linux version 3.6.11+ (dc4@dc4-arm-01) (gcc version 4.7.2 20120731 (prerelease) (crosstool-NG linaro-1.13.1+bzr2458 - Linaro GCC 2012.08) ) #397 PREEMPT Mon Mar 18 22:17:49 GMT 2013
Apr  6 18:17:25 keylime kernel: [    0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
Apr  6 18:17:25 keylime kernel: [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Apr  6 18:17:25 keylime kernel: [    0.000000] Machine: BCM2708
Apr  6 18:17:25 keylime kernel: [    0.000000] cma: CMA: reserved 16 MiB at 1e000000
Apr  6 18:17:25 keylime kernel: [    0.000000] Memory policy: ECC disabled, Data cache writeback
Apr  6 18:17:25 keylime kernel: [    0.000000] On node 0 totalpages: 126976
Apr  6 18:17:25 keylime kernel: [    0.000000] free_area_init_node: node 0, pgdat c053b834, node_mem_map c05e5000
Apr  6 18:17:25 keylime kernel: [    0.000000]   Normal zone: 992 pages used for memmap
Apr  6 18:17:25 keylime kernel: [    0.000000]   Normal zone: 0 pages reserved
Apr  6 18:17:25 keylime kernel: [    0.000000]   Normal zone: 125984 pages, LIFO batch:31
Apr  6 18:17:25 keylime kernel: [    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
Apr  6 18:17:25 keylime kernel: [    0.000000] pcpu-alloc: [0] 0 
Apr  6 18:17:25 keylime kernel: [    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 125984
Apr  6 18:17:25 keylime kernel: [    0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=720 bcm2708_fb.fbheight=480 bcm2708.boardrev=0xe bcm2708.serial=0x605a795d smsc95xx.macaddr=B8:27:EB:5A:79:5D sdhci-bcm2708.emmc_clock_freq=100000000 vc_mem.mem_base=0x1fa00000 vc_mem.mem_size=0x20000000  dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait smsc95xx.turbo_mode=N vm.min_free_kbytes=16536
Apr  6 18:17:25 keylime kernel: [    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
Apr  6 18:17:25 keylime kernel: [    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
Apr  6 18:17:25 keylime kernel: [    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
Apr  6 18:17:25 keylime kernel: [    0.000000] Memory: 496MB = 496MB total
Apr  6 18:17:25 keylime kernel: [    0.000000] Memory: 481032k/481032k available, 26872k reserved, 0K highmem
Apr  6 18:17:25 keylime kernel: [    0.000000] Virtual kernel memory layout:
Apr  6 18:17:25 keylime kernel: [    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
Apr  6 18:17:25 keylime kernel: [    0.000000]     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
Apr  6 18:17:25 keylime kernel: [    0.000000]     vmalloc : 0xdf800000 - 0xff000000   ( 504 MB)
Apr  6 18:17:25 keylime kernel: [    0.000000]     lowmem  : 0xc0000000 - 0xdf000000   ( 496 MB)
Apr  6 18:17:25 keylime kernel: [    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
Apr  6 18:17:25 keylime kernel: [    0.000000]       .text : 0xc0008000 - 0xc04e6480   (4986 kB)
Apr  6 18:17:25 keylime kernel: [    0.000000]       .init : 0xc04e7000 - 0xc0507f24   ( 132 kB)
Apr  6 18:17:25 keylime kernel: [    0.000000]       .data : 0xc0508000 - 0xc053c060   ( 209 kB)
Apr  6 18:17:25 keylime kernel: [    0.000000]        .bss : 0xc053c084 - 0xc05e4738   ( 674 kB)
Apr  6 18:17:25 keylime kernel: [    0.000000] NR_IRQS:330
Apr  6 18:17:25 keylime kernel: [    0.000000] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 4294967ms
Apr  6 18:17:25 keylime kernel: [    0.000000] Console: colour dummy device 80x30
Apr  6 18:17:25 keylime kernel: [    0.000000] console [tty1] enabled
Apr  6 18:17:25 keylime kernel: [    0.001022] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
Apr  6 18:17:25 keylime kernel: [    0.060128] pid_max: default: 32768 minimum: 301
Apr  6 18:17:25 keylime kernel: [    0.060461] Mount-cache hash table entries: 512
Apr  6 18:17:25 keylime kernel: [    0.061217] Initializing cgroup subsys cpuacct
Apr  6 18:17:25 keylime kernel: [    0.061271] Initializing cgroup subsys devices
Apr  6 18:17:25 keylime kernel: [    0.061306] Initializing cgroup subsys freezer
Apr  6 18:17:25 keylime kernel: [    0.061336] Initializing cgroup subsys blkio
Apr  6 18:17:25 keylime kernel: [    0.061426] CPU: Testing write buffer coherency: ok
Apr  6 18:17:25 keylime kernel: [    0.061758] hw perfevents: enabled with v6 PMU driver, 3 counters available
Apr  6 18:17:25 keylime kernel: [    0.061899] Setting up static identity map for 0x39d478 - 0x39d4d4
Apr  6 18:17:25 keylime kernel: [    0.063398] devtmpfs: initialized
Apr  6 18:17:25 keylime kernel: [    0.074184] NET: Registered protocol family 16
Apr  6 18:17:25 keylime kernel: [    0.080705] DMA: preallocated 4096 KiB pool for atomic coherent allocations
Apr  6 18:17:25 keylime kernel: [    0.081868] bcm2708.uart_clock = 0
Apr  6 18:17:25 keylime kernel: [    0.083220] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
Apr  6 18:17:25 keylime kernel: [    0.083274] hw-breakpoint: maximum watchpoint size is 4 bytes.
Apr  6 18:17:25 keylime kernel: [    0.083310] mailbox: Broadcom VideoCore Mailbox driver
Apr  6 18:17:25 keylime kernel: [    0.083402] bcm2708_vcio: mailbox at f200b880
Apr  6 18:17:25 keylime kernel: [    0.083501] bcm_power: Broadcom power driver
Apr  6 18:17:25 keylime kernel: [    0.083539] bcm_power_open() -> 0
Apr  6 18:17:25 keylime kernel: [    0.083564] bcm_power_request(0, 8)
Apr  6 18:17:25 keylime kernel: [    0.584249] bcm_mailbox_read -> 00000080, 0
Apr  6 18:17:25 keylime kernel: [    0.584289] bcm_power_request -> 0
Apr  6 18:17:25 keylime kernel: [    0.584316] Serial: AMBA PL011 UART driver
Apr  6 18:17:25 keylime kernel: [    0.584458] dev:f1: ttyAMA0 at MMIO 0x20201000 (irq = 83) is a PL011 rev3
Apr  6 18:17:25 keylime kernel: [    0.912359] console [ttyAMA0] enabled
Apr  6 18:17:25 keylime kernel: [    0.935772] bio: create slab <bio-0> at 0
Apr  6 18:17:25 keylime kernel: [    0.940651] SCSI subsystem initialized
Apr  6 18:17:25 keylime kernel: [    0.944743] usbcore: registered new interface driver usbfs
Apr  6 18:17:25 keylime kernel: [    0.950325] usbcore: registered new interface driver hub
Apr  6 18:17:25 keylime kernel: [    0.955922] usbcore: registered new device driver usb
Apr  6 18:17:25 keylime kernel: [    0.962321] Switching to clocksource stc
Apr  6 18:17:25 keylime kernel: [    0.966562] FS-Cache: Loaded
Apr  6 18:17:25 keylime kernel: [    0.969707] CacheFiles: Loaded
Apr  6 18:17:25 keylime kernel: [    0.984499] NET: Registered protocol family 2
Apr  6 18:17:25 keylime kernel: [    0.989784] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
Apr  6 18:17:25 keylime kernel: [    0.997526] TCP bind hash table entries: 16384 (order: 4, 65536 bytes)
Apr  6 18:17:25 keylime kernel: [    1.004317] TCP: Hash tables configured (established 16384 bind 16384)
Apr  6 18:17:25 keylime kernel: [    1.010920] TCP: reno registered
Apr  6 18:17:25 keylime kernel: [    1.014173] UDP hash table entries: 256 (order: 0, 4096 bytes)
Apr  6 18:17:25 keylime kernel: [    1.020070] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
Apr  6 18:17:25 keylime kernel: [    1.026649] NET: Registered protocol family 1
Apr  6 18:17:25 keylime kernel: [    1.031513] RPC: Registered named UNIX socket transport module.
Apr  6 18:17:25 keylime kernel: [    1.037557] RPC: Registered udp transport module.
Apr  6 18:17:25 keylime kernel: [    1.042279] RPC: Registered tcp transport module.
Apr  6 18:17:25 keylime kernel: [    1.047024] RPC: Registered tcp NFSv4.1 backchannel transport module.
Apr  6 18:17:25 keylime kernel: [    1.054199] bcm2708_dma: DMA manager at f2007000
Apr  6 18:17:25 keylime kernel: [    1.058985] bcm2708_gpio: bcm2708_gpio_probe c0515d98
Apr  6 18:17:25 keylime kernel: [    1.064449] vc-mem: phys_addr:0x00000000 mem_base=0x1fa00000 mem_size:0x20000000(512 MiB)
Apr  6 18:17:25 keylime kernel: [    1.073607] audit: initializing netlink socket (disabled)
Apr  6 18:17:25 keylime kernel: [    1.079205] type=2000 audit(0.930:1): initialized
Apr  6 18:17:25 keylime kernel: [    1.201407] VFS: Disk quotas dquot_6.5.2
Apr  6 18:17:25 keylime kernel: [    1.205441] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Apr  6 18:17:25 keylime kernel: [    1.212502] FS-Cache: Netfs 'nfs' registered for caching
Apr  6 18:17:25 keylime kernel: [    1.218245] NFS: Registering the id_resolver key type
Apr  6 18:17:25 keylime kernel: [    1.223434] Key type id_resolver registered
Apr  6 18:17:25 keylime kernel: [    1.227729] Key type id_legacy registered
Apr  6 18:17:25 keylime kernel: [    1.232097] msgmni has been set to 971
Apr  6 18:17:25 keylime kernel: [    1.237644] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
Apr  6 18:17:25 keylime kernel: [    1.245354] io scheduler noop registered
Apr  6 18:17:25 keylime kernel: [    1.249400] io scheduler deadline registered (default)
Apr  6 18:17:25 keylime kernel: [    1.254582] io scheduler cfq registered
Apr  6 18:17:25 keylime kernel: [    1.268363] Console: switching to colour frame buffer device 90x30
Apr  6 18:17:25 keylime kernel: [    1.280788] kgdb: Registered I/O driver kgdboc.
Apr  6 18:17:25 keylime kernel: [    1.288166] vc-cma: Videocore CMA driver
Apr  6 18:17:25 keylime kernel: [    1.294229] vc-cma: vc_cma_base      = 0x00000000
Apr  6 18:17:25 keylime kernel: [    1.301110] vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
Apr  6 18:17:25 keylime kernel: [    1.308672] vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
Apr  6 18:17:25 keylime kernel: [    1.325127] brd: module loaded
Apr  6 18:17:25 keylime kernel: [    1.335270] loop: module loaded
Apr  6 18:17:25 keylime kernel: [    1.340928] vchiq: vchiq_init_state: slot_zero = 0xde000000, is_master = 0
Apr  6 18:17:25 keylime kernel: [    1.350681] Loading iSCSI transport class v2.0-870.
Apr  6 18:17:25 keylime kernel: [    1.358655] usbcore: registered new interface driver smsc95xx
Apr  6 18:17:25 keylime kernel: [    1.366684] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Apr  6 18:17:25 keylime kernel: [    1.579571] Core Release: 2.80a
Apr  6 18:17:25 keylime kernel: [    1.584773] Setting default values for core params
Apr  6 18:17:25 keylime kernel: [    1.591667] Finished setting default values for core params
Apr  6 18:17:25 keylime kernel: [    1.804354] Using Buffer DMA mode
Apr  6 18:17:25 keylime kernel: [    1.809707] Periodic Transfer Interrupt Enhancement - disabled
Apr  6 18:17:25 keylime kernel: [    1.817583] Multiprocessor Interrupt Enhancement - disabled
Apr  6 18:17:25 keylime kernel: [    1.825205] OTG VER PARAM: 0, OTG VER FLAG: 0
Apr  6 18:17:25 keylime kernel: [    1.831638] Dedicated Tx FIFOs mode
Apr  6 18:17:25 keylime kernel: [    1.838144] dwc_otg: Microframe scheduler enabled
Apr  6 18:17:25 keylime kernel: [    1.838556] dwc_otg bcm2708_usb: DWC OTG Controller
Apr  6 18:17:25 keylime kernel: [    1.845526] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
Apr  6 18:17:25 keylime kernel: [    1.854936] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
Apr  6 18:17:25 keylime kernel: [    1.862624] Init: Port Power? op_state=1
Apr  6 18:17:25 keylime kernel: [    1.868611] Init: Power Port (0)
Apr  6 18:17:25 keylime kernel: [    1.873888] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Apr  6 18:17:25 keylime kernel: [    1.882757] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Apr  6 18:17:25 keylime kernel: [    1.892066] usb usb1: Product: DWC OTG Controller
Apr  6 18:17:25 keylime kernel: [    1.898845] usb usb1: Manufacturer: Linux 3.6.11+ dwc_otg_hcd
Apr  6 18:17:25 keylime kernel: [    1.906718] usb usb1: SerialNumber: bcm2708_usb
Apr  6 18:17:25 keylime kernel: [    1.914146] hub 1-0:1.0: USB hub found
Apr  6 18:17:25 keylime kernel: [    1.920128] hub 1-0:1.0: 1 port detected
Apr  6 18:17:25 keylime kernel: [    1.926548] dwc_otg: FIQ enabled
Apr  6 18:17:25 keylime kernel: [    1.926565] dwc_otg: NAK holdoff enabled
Apr  6 18:17:25 keylime kernel: [    1.926586] Module dwc_common_port init
Apr  6 18:17:25 keylime kernel: [    1.926807] Initializing USB Mass Storage driver...
Apr  6 18:17:25 keylime kernel: [    1.934008] usbcore: registered new interface driver usb-storage
Apr  6 18:17:25 keylime kernel: [    1.942203] USB Mass Storage support registered.
Apr  6 18:17:25 keylime kernel: [    1.949080] usbcore: registered new interface driver libusual
Apr  6 18:17:25 keylime kernel: [    1.957253] mousedev: PS/2 mouse device common for all mice
Apr  6 18:17:25 keylime kernel: [    1.965587] bcm2835-cpufreq: min=700000 max=900000 cur=700000
Apr  6 18:17:25 keylime kernel: [    1.973630] bcm2835-cpufreq: switching to governor powersave
Apr  6 18:17:25 keylime kernel: [    1.981422] bcm2835-cpufreq: switching to governor powersave
Apr  6 18:17:25 keylime kernel: [    1.989122] cpuidle: using governor ladder
Apr  6 18:17:25 keylime kernel: [    1.995183] cpuidle: using governor menu
Apr  6 18:17:25 keylime kernel: [    2.001093] sdhci: Secure Digital Host Controller Interface driver
Apr  6 18:17:25 keylime kernel: [    2.009267] sdhci: Copyright(c) Pierre Ossman
Apr  6 18:17:25 keylime kernel: [    2.015652] sdhci: Enable low-latency mode
Apr  6 18:17:25 keylime kernel: [    2.066589] mmc0: SDHCI controller on BCM2708_Arasan [platform] using platform's DMA
Apr  6 18:17:25 keylime kernel: [    2.076653] mmc0: BCM2708 SDHC host at 0x20300000 DMA 2 IRQ 77
Apr  6 18:17:25 keylime kernel: [    2.086765] sdhci-pltfm: SDHCI platform and OF driver helper
Apr  6 18:17:25 keylime kernel: [    2.100252] usbcore: registered new interface driver usbhid
Apr  6 18:17:25 keylime kernel: [    2.108044] usbhid: USB HID core driver
Apr  6 18:17:25 keylime kernel: [    2.118609] Indeed it is in host mode hprt0 = 00021501
Apr  6 18:17:25 keylime kernel: [    2.128183] TCP: cubic registered
Apr  6 18:17:25 keylime kernel: [    2.146440] Initializing XFRM netlink socket
Apr  6 18:17:25 keylime kernel: [    2.153157] NET: Registered protocol family 17
Apr  6 18:17:25 keylime kernel: [    2.166636] Key type dns_resolver registered
Apr  6 18:17:25 keylime kernel: [    2.196875] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
Apr  6 18:17:25 keylime kernel: [    2.208986] mmc0: read SD Status register (SSR) after 2 attempts
Apr  6 18:17:25 keylime kernel: [    2.217958] registered taskstats version 1
Apr  6 18:17:25 keylime kernel: [    2.237103] Waiting for root device /dev/mmcblk0p2...
Apr  6 18:17:25 keylime kernel: [    2.246553] mmc0: new high speed SDHC card at address b368
Apr  6 18:17:25 keylime kernel: [    2.266666] mmcblk0: mmc0:b368 SDC   3.74 GiB 
Apr  6 18:17:25 keylime kernel: [    2.274963]  mmcblk0: p1 p2
Apr  6 18:17:25 keylime kernel: [    2.386481] usb 1-1: new high-speed USB device number 2 using dwc_otg
Apr  6 18:17:25 keylime kernel: [    2.395343] Indeed it is in host mode hprt0 = 00001101
Apr  6 18:17:25 keylime kernel: [    2.606760] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
Apr  6 18:17:25 keylime kernel: [    2.615824] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Apr  6 18:17:25 keylime kernel: [    2.629596] hub 1-1:1.0: USB hub found
Apr  6 18:17:25 keylime kernel: [    2.635811] hub 1-1:1.0: 3 ports detected
Apr  6 18:17:25 keylime kernel: [    2.926563] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Apr  6 18:17:25 keylime kernel: [    3.046860] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Apr  6 18:17:25 keylime kernel: [    3.056078] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Apr  6 18:17:25 keylime kernel: [    3.068628] smsc95xx v1.0.4
Apr  6 18:17:25 keylime kernel: [    3.131188] smsc95xx 1-1.1:1.0: eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:5a:79:5d
Apr  6 18:17:25 keylime kernel: [    3.226612] usb 1-1.2: new high-speed USB device number 4 using dwc_otg
Apr  6 18:17:25 keylime kernel: [    3.348924] usb 1-1.2: New USB device found, idVendor=0480, idProduct=d010
Apr  6 18:17:25 keylime kernel: [    3.358304] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Apr  6 18:17:25 keylime kernel: [    3.368087] usb 1-1.2: Product: External USB 3.0
Apr  6 18:17:25 keylime kernel: [    3.375125] usb 1-1.2: Manufacturer: Toshiba
Apr  6 18:17:25 keylime kernel: [    3.381813] usb 1-1.2: SerialNumber: 20121022010604
Apr  6 18:17:25 keylime kernel: [    3.390978] scsi0 : usb-storage 1-1.2:1.0
Apr  6 18:17:25 keylime kernel: [    6.644486] scsi 0:0:0:0: Direct-Access     Toshiba  External USB 3.0 0201 PQ: 0 ANSI: 6
Apr  6 18:17:25 keylime kernel: [    6.659009] sd 0:0:0:0: [sda] 3907029164 512-byte logical blocks: (2.00 TB/1.81 TiB)
Apr  6 18:17:25 keylime kernel: [    6.672239] sd 0:0:0:0: [sda] Write Protect is off
Apr  6 18:17:25 keylime kernel: [    6.679681] sd 0:0:0:0: [sda] Mode Sense: 2f 00 00 00
Apr  6 18:17:25 keylime kernel: [    6.680242] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
Apr  6 18:17:25 keylime kernel: [    6.716312]  sda: unknown partition table
Apr  6 18:17:25 keylime kernel: [    6.725608] sd 0:0:0:0: [sda] Attached SCSI disk
Apr  6 18:17:25 keylime kernel: [   10.246855] EXT4-fs (mmcblk0p2): recovery complete
Apr  6 18:17:25 keylime kernel: [   10.602517] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Apr  6 18:17:25 keylime kernel: [   10.615663] VFS: Mounted root (ext4 filesystem) on device 179:2.
Apr  6 18:17:25 keylime kernel: [   10.625339] devtmpfs: mounted
Apr  6 18:17:25 keylime kernel: [   10.631375] Freeing init memory: 128K
Apr  6 18:17:25 keylime kernel: [   11.276735] usb 1-1.3: new high-speed USB device number 5 using dwc_otg
Apr  6 18:17:25 keylime kernel: [   11.418824] usb 1-1.3: New USB device found, idVendor=0bc2, idProduct=3320
Apr  6 18:17:25 keylime kernel: [   11.435918] usb 1-1.3: New USB device strings: Mfr=2, Product=3, SerialNumber=1
Apr  6 18:17:25 keylime kernel: [   11.451170] usb 1-1.3: Product: Expansion Desk
Apr  6 18:17:25 keylime kernel: [   11.458340] usb 1-1.3: Manufacturer: Seagate
Apr  6 18:17:25 keylime kernel: [   11.469020] usb 1-1.3: SerialNumber: NA4L8GL0
Apr  6 18:17:25 keylime kernel: [   11.479474] scsi1 : usb-storage 1-1.3:1.0
Apr  6 18:17:25 keylime kernel: [   12.489066] scsi 1:0:0:0: Direct-Access     Seagate  Expansion Desk   070B PQ: 0 ANSI: 6
Apr  6 18:17:25 keylime kernel: [   12.526666] sd 1:0:0:0: [sdb] 3907029167 512-byte logical blocks: (2.00 TB/1.81 TiB)
Apr  6 18:17:25 keylime kernel: [   12.563188] sd 1:0:0:0: [sdb] Write Protect is off
Apr  6 18:17:25 keylime kernel: [   12.581213] sd 1:0:0:0: [sdb] Mode Sense: 43 00 00 00
Apr  6 18:17:25 keylime kernel: [   12.582189] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Apr  6 18:17:25 keylime kernel: [   12.648263]  sdb: unknown partition table
Apr  6 18:17:25 keylime kernel: [   12.679812] sd 1:0:0:0: [sdb] Attached SCSI disk
Apr  6 18:17:25 keylime kernel: [   13.450464] Registered led device: led0
Apr  6 18:17:25 keylime kernel: [   14.733107] Btrfs loaded
Apr  6 18:17:25 keylime kernel: [   14.811166] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 1 transid 16515 /dev/sdb
Apr  6 18:17:25 keylime kernel: [   15.505618] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 2 transid 16515 /dev/sda
Apr  6 18:17:25 keylime kernel: [   15.532292] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 1 transid 16515 /dev/sdb
Apr  6 18:17:25 keylime kernel: [   23.977832] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Apr  6 18:17:25 keylime kernel: [   24.409214] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Apr  6 18:17:25 keylime kernel: [   25.172030] bcm2835 ALSA card created!
Apr  6 18:17:25 keylime kernel: [   25.185354] bcm2835 ALSA chip created!
Apr  6 18:17:25 keylime kernel: [   25.198174] bcm2835 ALSA chip created!
Apr  6 18:17:25 keylime kernel: [   25.210887] bcm2835 ALSA chip created!
Apr  6 18:17:25 keylime kernel: [   25.224128] bcm2835 ALSA chip created!
Apr  6 18:17:25 keylime kernel: [   25.234588] bcm2835 ALSA chip created!
Apr  6 18:17:25 keylime kernel: [   25.243935] bcm2835 ALSA chip created!
Apr  6 18:17:25 keylime kernel: [   25.252504] bcm2835 ALSA chip created!
Apr  6 18:17:25 keylime kernel: [   29.896033] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 2 transid 16515 /dev/sda
Apr  6 18:17:25 keylime kernel: [   29.909397] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 1 transid 16515 /dev/sdb
Apr  6 18:17:25 keylime kernel: [   29.922772] device fsid 724daae8-2d85-4020-bd1a-6a8f852005fd devid 2 transid 16515 /dev/sda
Apr  6 18:17:25 keylime kernel: [   29.941089] btrfs: use lzo compression
Apr  6 18:17:25 keylime kernel: [   29.947081] btrfs: disk space caching is enabled
Apr  6 18:17:25 keylime kernel: [   36.166141] ip_tables: (C) 2000-2006 Netfilter Core Team
Apr  6 18:17:25 keylime kernel: [   36.235382] nf_conntrack version 0.5.0 (7774 buckets, 31096 max)
Apr  6 18:17:25 keylime kernel: [   37.469309] smsc95xx 1-1.1:1.0: eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
Apr  6 18:17:25 keylime kernel: [   38.760136] bcm2835-cpufreq: switching to governor ondemand
Apr  6 18:17:25 keylime kernel: [   38.760159] bcm2835-cpufreq: switching to governor ondemand
Apr  6 18:17:28 keylime kernel: [   43.684546] Adding 102396k swap on /var/swap.  Priority:-1 extents:129 across:1754856k SS
At this point, I upgrade the kernel again using rpi-config and the time corrects itself at reboot:
Apr  7 09:15:11 keylime kernel: imklog 5.8.11, log source = /proc/kmsg started.
Apr  7 09:15:11 keylime kernel: [    0.000000] Booting Linux on physical CPU 0
Apr  7 09:15:11 keylime kernel: [    0.000000] Initializing cgroup subsys cpu
Apr  7 09:15:11 keylime kernel: [    0.000000] Linux version 3.6.11+ (dc4@dc4-arm-01) (gcc version 4.7.2 20120731 (prerelease) (crosstool-NG linaro-1.13.1+bzr2458 - Linaro GCC 2012.08) ) #403 PREEMPT Tue Apr 2 22:48:13 BST 2013
Apr  7 09:15:11 keylime kernel: [    0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
Apr  7 09:15:11 keylime kernel: [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Apr  7 09:15:11 keylime kernel: [    0.000000] Machine: BCM2708
Apr  7 09:15:11 keylime kernel: [    0.000000] cma: CMA: reserved 16 MiB at 1e000000
Apr  7 09:15:11 keylime kernel: [    0.000000] Memory policy: ECC disabled, Data cache writeback
Apr  7 09:15:11 keylime kernel: [    0.000000] On node 0 totalpages: 126976
Apr  7 09:15:11 keylime kernel: [    0.000000] free_area_init_node: node 0, pgdat c053b854, node_mem_map c05e5000
Apr  7 09:15:11 keylime kernel: [    0.000000]   Normal zone: 992 pages used for memmap
Apr  7 09:15:11 keylime kernel: [    0.000000]   Normal zone: 0 pages reserved
Apr  7 09:15:11 keylime kernel: [    0.000000]   Normal zone: 125984 pages, LIFO batch:31
Apr  7 09:15:11 keylime kernel: [    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
Apr  7 09:15:11 keylime kernel: [    0.000000] pcpu-alloc: [0] 0 
Apr  7 09:15:11 keylime kernel: [    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 125984
Apr  7 09:15:11 keylime kernel: [    0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=720 bcm2708_fb.fbheight=480 bcm2708.boardrev=0xe bcm2708.serial=0x605a795d smsc95xx.macaddr=B8:27:EB:5A:79:5D sdhci-bcm2708.emmc_clock_freq=100000000 vc_mem.mem_base=0x1fa00000 vc_mem.mem_size=0x20000000  dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait smsc95xx.turbo_mode=N vm.min_free_kbytes=16536
Apr  7 09:15:11 keylime kernel: [    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
Apr  7 09:15:11 keylime kernel: [    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
Apr  7 09:15:11 keylime kernel: [    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
Apr  7 09:15:11 keylime kernel: [    0.000000] Memory: 496MB = 496MB total
Apr  7 09:15:11 keylime kernel: [    0.000000] Memory: 481032k/481032k available, 26872k reserved, 0K highmem
Apr  7 09:15:11 keylime kernel: [    0.000000] Virtual kernel memory layout:
Apr  7 09:15:11 keylime kernel: [    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
Apr  7 09:15:11 keylime kernel: [    0.000000]     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
Apr  7 09:15:11 keylime kernel: [    0.000000]     vmalloc : 0xdf800000 - 0xff000000   ( 504 MB)
Apr  7 09:15:11 keylime kernel: [    0.000000]     lowmem  : 0xc0000000 - 0xdf000000   ( 496 MB)
Apr  7 09:15:11 keylime kernel: [    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
Apr  7 09:15:11 keylime kernel: [    0.000000]       .text : 0xc0008000 - 0xc04e647c   (4986 kB)
Apr  7 09:15:11 keylime kernel: [    0.000000]       .init : 0xc04e7000 - 0xc0507f24   ( 132 kB)
Apr  7 09:15:11 keylime kernel: [    0.000000]       .data : 0xc0508000 - 0xc053c080   ( 209 kB)
Apr  7 09:15:11 keylime kernel: [    0.000000]        .bss : 0xc053c0a4 - 0xc05e4758   ( 674 kB)
Apr  7 09:15:11 keylime kernel: [    0.000000] NR_IRQS:330
Apr  7 09:15:11 keylime kernel: [    0.000000] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 4294967ms
Apr  7 09:15:11 keylime kernel: [    0.000000] Console: colour dummy device 80x30
Apr  7 09:15:11 keylime kernel: [    0.000000] console [tty1] enabled
Apr  7 09:15:11 keylime kernel: [    0.001016] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
Apr  7 09:15:11 keylime kernel: [    0.060124] pid_max: default: 32768 minimum: 301
Apr  7 09:15:11 keylime kernel: [    0.060458] Mount-cache hash table entries: 512
Apr  7 09:15:11 keylime kernel: [    0.061215] Initializing cgroup subsys cpuacct
Apr  7 09:15:11 keylime kernel: [    0.061270] Initializing cgroup subsys devices
Apr  7 09:15:11 keylime kernel: [    0.061303] Initializing cgroup subsys freezer
Apr  7 09:15:11 keylime kernel: [    0.061332] Initializing cgroup subsys blkio
Apr  7 09:15:11 keylime kernel: [    0.061424] CPU: Testing write buffer coherency: ok
Apr  7 09:15:11 keylime kernel: [    0.061756] hw perfevents: enabled with v6 PMU driver, 3 counters available
Apr  7 09:15:11 keylime kernel: [    0.061897] Setting up static identity map for 0x39d5f8 - 0x39d654
Apr  7 09:15:11 keylime kernel: [    0.063393] devtmpfs: initialized
Apr  7 09:15:11 keylime kernel: [    0.074204] NET: Registered protocol family 16
Apr  7 09:15:11 keylime kernel: [    0.080711] DMA: preallocated 4096 KiB pool for atomic coherent allocations
Apr  7 09:15:11 keylime kernel: [    0.081873] bcm2708.uart_clock = 0
Apr  7 09:15:11 keylime kernel: [    0.083258] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
Apr  7 09:15:11 keylime kernel: [    0.083312] hw-breakpoint: maximum watchpoint size is 4 bytes.
Apr  7 09:15:11 keylime kernel: [    0.083348] mailbox: Broadcom VideoCore Mailbox driver
Apr  7 09:15:11 keylime kernel: [    0.083443] bcm2708_vcio: mailbox at f200b880
Apr  7 09:15:11 keylime kernel: [    0.083543] bcm_power: Broadcom power driver
Apr  7 09:15:11 keylime kernel: [    0.083581] bcm_power_open() -> 0
Apr  7 09:15:11 keylime kernel: [    0.083606] bcm_power_request(0, 8)
Apr  7 09:15:11 keylime kernel: [    0.584291] bcm_mailbox_read -> 00000080, 0
Apr  7 09:15:11 keylime kernel: [    0.584331] bcm_power_request -> 0
Apr  7 09:15:11 keylime kernel: [    0.584358] Serial: AMBA PL011 UART driver
Apr  7 09:15:11 keylime kernel: [    0.584502] dev:f1: ttyAMA0 at MMIO 0x20201000 (irq = 83) is a PL011 rev3
Apr  7 09:15:11 keylime kernel: [    0.912322] console [ttyAMA0] enabled
Apr  7 09:15:11 keylime kernel: [    0.935854] bio: create slab <bio-0> at 0
Apr  7 09:15:11 keylime kernel: [    0.940739] SCSI subsystem initialized
Apr  7 09:15:11 keylime kernel: [    0.944829] usbcore: registered new interface driver usbfs
Apr  7 09:15:11 keylime kernel: [    0.950413] usbcore: registered new interface driver hub
Apr  7 09:15:11 keylime kernel: [    0.956010] usbcore: registered new device driver usb
Apr  7 09:15:11 keylime kernel: [    0.962418] Switching to clocksource stc
Apr  7 09:15:11 keylime kernel: [    0.966662] FS-Cache: Loaded
Apr  7 09:15:11 keylime kernel: [    0.969806] CacheFiles: Loaded
Apr  7 09:15:11 keylime kernel: [    0.984594] NET: Registered protocol family 2
Apr  7 09:15:11 keylime kernel: [    0.989866] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
Apr  7 09:15:11 keylime kernel: [    0.997605] TCP bind hash table entries: 16384 (order: 4, 65536 bytes)
Apr  7 09:15:11 keylime kernel: [    1.004395] TCP: Hash tables configured (established 16384 bind 16384)
Apr  7 09:15:11 keylime kernel: [    1.010998] TCP: reno registered
Apr  7 09:15:11 keylime kernel: [    1.014251] UDP hash table entries: 256 (order: 0, 4096 bytes)
Apr  7 09:15:11 keylime kernel: [    1.020147] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
Apr  7 09:15:11 keylime kernel: [    1.026731] NET: Registered protocol family 1
Apr  7 09:15:11 keylime kernel: [    1.031601] RPC: Registered named UNIX socket transport module.
Apr  7 09:15:11 keylime kernel: [    1.037644] RPC: Registered udp transport module.
Apr  7 09:15:11 keylime kernel: [    1.042366] RPC: Registered tcp transport module.
Apr  7 09:15:11 keylime kernel: [    1.047111] RPC: Registered tcp NFSv4.1 backchannel transport module.
Apr  7 09:15:11 keylime kernel: [    1.054285] bcm2708_dma: DMA manager at f2007000
Apr  7 09:15:11 keylime kernel: [    1.059069] bcm2708_gpio: bcm2708_gpio_probe c0515d98
Apr  7 09:15:11 keylime kernel: [    1.064537] vc-mem: phys_addr:0x00000000 mem_base=0x1fa00000 mem_size:0x20000000(512 MiB)
Apr  7 09:15:11 keylime kernel: [    1.073696] audit: initializing netlink socket (disabled)
Apr  7 09:15:11 keylime kernel: [    1.079290] type=2000 audit(0.930:1): initialized
Apr  7 09:15:11 keylime kernel: [    1.201513] VFS: Disk quotas dquot_6.5.2
Apr  7 09:15:11 keylime kernel: [    1.205548] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Apr  7 09:15:11 keylime kernel: [    1.212604] FS-Cache: Netfs 'nfs' registered for caching
Apr  7 09:15:11 keylime kernel: [    1.218346] NFS: Registering the id_resolver key type
Apr  7 09:15:11 keylime kernel: [    1.223526] Key type id_resolver registered
Apr  7 09:15:11 keylime kernel: [    1.227817] Key type id_legacy registered
Apr  7 09:15:11 keylime kernel: [    1.232181] msgmni has been set to 971
Apr  7 09:15:11 keylime kernel: [    1.237708] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
Apr  7 09:15:11 keylime kernel: [    1.245416] io scheduler noop registered
Apr  7 09:15:11 keylime kernel: [    1.249460] io scheduler deadline registered (default)
Apr  7 09:15:11 keylime kernel: [    1.254643] io scheduler cfq registered
Apr  7 09:15:11 keylime kernel: [    1.268266] Console: switching to colour frame buffer device 90x30
Apr  7 09:15:11 keylime kernel: [    1.280690] kgdb: Registered I/O driver kgdboc.
Apr  7 09:15:11 keylime kernel: [    1.288065] vc-cma: Videocore CMA driver
Apr  7 09:15:11 keylime kernel: [    1.294122] vc-cma: vc_cma_base      = 0x00000000
Apr  7 09:15:11 keylime kernel: [    1.300999] vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
Apr  7 09:15:11 keylime kernel: [    1.308558] vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
Apr  7 09:15:11 keylime kernel: [    1.325071] brd: module loaded
Apr  7 09:15:11 keylime kernel: [    1.335211] loop: module loaded
Apr  7 09:15:11 keylime kernel: [    1.340868] vchiq: vchiq_init_state: slot_zero = 0xde000000, is_master = 0
Apr  7 09:15:11 keylime kernel: [    1.350608] Loading iSCSI transport class v2.0-870.
Apr  7 09:15:11 keylime kernel: [    1.358595] usbcore: registered new interface driver smsc95xx
Apr  7 09:15:11 keylime kernel: [    1.366625] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Apr  7 09:15:11 keylime kernel: [    1.579505] Core Release: 2.80a
Apr  7 09:15:11 keylime kernel: [    1.584700] Setting default values for core params
Apr  7 09:15:11 keylime kernel: [    1.591581] Finished setting default values for core params
Apr  7 09:15:11 keylime kernel: [    1.804259] Using Buffer DMA mode
Apr  7 09:15:11 keylime kernel: [    1.809607] Periodic Transfer Interrupt Enhancement - disabled
Apr  7 09:15:11 keylime kernel: [    1.817476] Multiprocessor Interrupt Enhancement - disabled
Apr  7 09:15:11 keylime kernel: [    1.825091] OTG VER PARAM: 0, OTG VER FLAG: 0
Apr  7 09:15:11 keylime kernel: [    1.831517] Dedicated Tx FIFOs mode
Apr  7 09:15:11 keylime kernel: [    1.838017] dwc_otg: Microframe scheduler enabled
Apr  7 09:15:11 keylime kernel: [    1.838436] dwc_otg bcm2708_usb: DWC OTG Controller
Apr  7 09:15:11 keylime kernel: [    1.845400] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
Apr  7 09:15:11 keylime kernel: [    1.854798] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
Apr  7 09:15:11 keylime kernel: [    1.862483] Init: Port Power? op_state=1
Apr  7 09:15:11 keylime kernel: [    1.868466] Init: Power Port (0)
Apr  7 09:15:11 keylime kernel: [    1.873739] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Apr  7 09:15:11 keylime kernel: [    1.882604] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Apr  7 09:15:11 keylime kernel: [    1.891904] usb usb1: Product: DWC OTG Controller
Apr  7 09:15:11 keylime kernel: [    1.898678] usb usb1: Manufacturer: Linux 3.6.11+ dwc_otg_hcd
Apr  7 09:15:11 keylime kernel: [    1.906543] usb usb1: SerialNumber: bcm2708_usb
Apr  7 09:15:11 keylime kernel: [    1.913965] hub 1-0:1.0: USB hub found
Apr  7 09:15:11 keylime kernel: [    1.919940] hub 1-0:1.0: 1 port detected
Apr  7 09:15:11 keylime kernel: [    1.926307] dwc_otg: FIQ enabled
Apr  7 09:15:11 keylime kernel: [    1.926324] dwc_otg: NAK holdoff enabled
Apr  7 09:15:11 keylime kernel: [    1.926345] Module dwc_common_port init
Apr  7 09:15:11 keylime kernel: [    1.926618] Initializing USB Mass Storage driver...
Apr  7 09:15:11 keylime kernel: [    1.933812] usbcore: registered new interface driver usb-storage
Apr  7 09:15:11 keylime kernel: [    1.941990] USB Mass Storage support registered.
Apr  7 09:15:11 keylime kernel: [    1.948867] usbcore: registered new interface driver libusual
Apr  7 09:15:11 keylime kernel: [    1.957040] mousedev: PS/2 mouse device common for all mice
Apr  7 09:15:11 keylime kernel: [    1.965364] bcm2835-cpufreq: min=700000 max=900000 cur=700000
Apr  7 09:15:11 keylime kernel: [    1.973409] bcm2835-cpufreq: switching to governor powersave
Apr  7 09:15:11 keylime kernel: [    1.981214] bcm2835-cpufreq: switching to governor powersave
Apr  7 09:15:11 keylime kernel: [    1.988923] cpuidle: using governor ladder
Apr  7 09:15:11 keylime kernel: [    1.994982] cpuidle: using governor menu
Apr  7 09:15:11 keylime kernel: [    2.000896] sdhci: Secure Digital Host Controller Interface driver
Apr  7 09:15:11 keylime kernel: [    2.009072] sdhci: Copyright(c) Pierre Ossman
Apr  7 09:15:11 keylime kernel: [    2.015461] sdhci: Enable low-latency mode
Apr  7 09:15:11 keylime kernel: [    2.066689] mmc0: SDHCI controller on BCM2708_Arasan [platform] using platform's DMA
Apr  7 09:15:11 keylime kernel: [    2.076761] mmc0: BCM2708 SDHC host at 0x20300000 DMA 2 IRQ 77
Apr  7 09:15:11 keylime kernel: [    2.086870] sdhci-pltfm: SDHCI platform and OF driver helper
Apr  7 09:15:11 keylime kernel: [    2.100373] usbcore: registered new interface driver usbhid
Apr  7 09:15:11 keylime kernel: [    2.108170] usbhid: USB HID core driver
Apr  7 09:15:11 keylime kernel: [    2.118764] Indeed it is in host mode hprt0 = 00021501
Apr  7 09:15:11 keylime kernel: [    2.128340] TCP: cubic registered
Apr  7 09:15:11 keylime kernel: [    2.146542] I

@ghalfacree
Copy link

Back on the latest kernel, I can reliably trigger the allocation failures by just shoving a fair amount of sustained traffic through the Pi.

Apr  9 09:12:27 keylime kernel: [170238.829785] sshd: page allocation failure: order:0, mode:0x20
Apr  9 09:12:27 keylime kernel: [170238.829849] [<c0013a7c>] (unwind_backtrace+0x0/0xf0) from [<c009274c>] (warn_alloc_failed+0xc4/0x11c)
Apr  9 09:12:27 keylime kernel: [170238.829875] [<c009274c>] (warn_alloc_failed+0xc4/0x11c) from [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c)
Apr  9 09:12:27 keylime kernel: [170238.829899] [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c) from [<c02e49ec>] (__netdev_alloc_frag+0x90/0x118)
Apr  9 09:12:27 keylime kernel: [170238.829923] [<c02e49ec>] (__netdev_alloc_frag+0x90/0x118) from [<c02e8b5c>] (__netdev_alloc_skb+0x40/0xd0)
Apr  9 09:12:27 keylime kernel: [170238.829948] [<c02e8b5c>] (__netdev_alloc_skb+0x40/0xd0) from [<c026aac0>] (rx_submit+0x1c/0x1f8)
Apr  9 09:12:27 keylime kernel: [170238.829976] [<c026aac0>] (rx_submit+0x1c/0x1f8) from [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4)
Apr  9 09:12:27 keylime kernel: [170238.830003] [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4) from [<c0296228>] (completion_tasklet_func+0x68/0x94)
Apr  9 09:12:27 keylime kernel: [170238.830035] [<c0296228>] (completion_tasklet_func+0x68/0x94) from [<c029fb90>] (tasklet_callback+0x10/0x14)
Apr  9 09:12:27 keylime kernel: [170238.830070] [<c029fb90>] (tasklet_callback+0x10/0x14) from [<c002565c>] (tasklet_hi_action+0x60/0xb4)
Apr  9 09:12:27 keylime kernel: [170238.830094] [<c002565c>] (tasklet_hi_action+0x60/0xb4) from [<c0025840>] (__do_softirq+0xa0/0x154)
Apr  9 09:12:27 keylime kernel: [170238.830114] [<c0025840>] (__do_softirq+0xa0/0x154) from [<c0025d08>] (irq_exit+0x8c/0x94)
Apr  9 09:12:27 keylime kernel: [170238.830141] [<c0025d08>] (irq_exit+0x8c/0x94) from [<c000e920>] (handle_IRQ+0x34/0x84)
Apr  9 09:12:27 keylime kernel: [170238.830161] [<c000e920>] (handle_IRQ+0x34/0x84) from [<c0399e78>] (__irq_usr+0x38/0xc0)
Apr  9 09:12:27 keylime kernel: [170238.830169] Mem-info:
Apr  9 09:12:27 keylime kernel: [170238.830175] Normal per-cpu:
Apr  9 09:12:27 keylime kernel: [170238.830184] CPU    0: hi:  186, btch:  31 usd:  51
Apr  9 09:12:27 keylime kernel: [170238.830203] active_anon:1767 inactive_anon:3969 isolated_anon:0
Apr  9 09:12:27 keylime kernel: [170238.830203]  active_file:41456 inactive_file:68940 isolated_file:0
Apr  9 09:12:27 keylime kernel: [170238.830203]  unevictable:0 dirty:678 writeback:0 unstable:0
Apr  9 09:12:27 keylime kernel: [170238.830203]  free:2624 slab_reclaimable:2086 slab_unreclaimable:1222
Apr  9 09:12:27 keylime kernel: [170238.830203]  mapped:1713 shmem:97 pagetables:233 bounce:0
Apr  9 09:12:27 keylime kernel: [170238.830243] Normal free:10496kB min:8192kB low:10240kB high:12288kB active_anon:7068kB inactive_anon:15876kB active_file:165824kB inactive_file:275760kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:503936kB mlocked:0kB dirty:2712kB writeback:0kB mapped:6852kB shmem:388kB slab_reclaimable:8344kB slab_unreclaimable:4888kB kernel_stack:1304kB pagetables:932kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Apr  9 09:12:27 keylime kernel: [170238.830254] lowmem_reserve[]: 0 0
Apr  9 09:12:27 keylime kernel: [170238.830268] Normal: 432*4kB 422*8kB 235*16kB 47*32kB 2*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 10496kB
Apr  9 09:12:27 keylime kernel: [170238.830301] 110502 total pagecache pages
Apr  9 09:12:27 keylime kernel: [170238.830307] 0 pages in swap cache
Apr  9 09:12:27 keylime kernel: [170238.830314] Swap cache stats: add 0, delete 0, find 0/0
Apr  9 09:12:27 keylime kernel: [170238.830320] Free swap  = 102396kB
Apr  9 09:12:27 keylime kernel: [170238.830325] Total swap = 102396kB
Apr  9 09:12:27 keylime kernel: [170238.853908] 126976 pages of RAM
Apr  9 09:12:27 keylime kernel: [170238.853914] 2953 free pages
Apr  9 09:12:27 keylime kernel: [170238.853920] 2590 reserved pages
Apr  9 09:12:27 keylime kernel: [170238.853925] 3308 slab pages
Apr  9 09:12:27 keylime kernel: [170238.853930] 88364 pages shared
Apr  9 09:12:27 keylime kernel: [170238.853935] 0 pages swap cached

That is followed by repeated page allocation failures - up to 100 at the time of posting. The affected process varies: it starts with sshd (as I'm transferring files via ssh), then rsyslogd, then ksoftirqd/0, kswapd0, usb-storage, swapper. Strangely, at no point is the system actually running out of memory - so why it's even trying to swap I don't know.

             total       used       free     shared    buffers     cached
Mem:          485M       471M        14M         0B       376K       427M
-/+ buffers/cache:        43M       442M
Swap:          99M         0B        99M

Linux keylime 3.6.11+ #403 PREEMPT Tue Apr 2 22:48:13 BST 2013 armv6l GNU/Linux. Command line is:
dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait smsc95xx.turbo_mode=N vm.min_free_kbytes=16536

@Ferroin
Copy link
Contributor

Ferroin commented Apr 9, 2013

Have you tried with the commandline option 'elevator=noop'? elevator=dealine and elevator=cfq by default try to optimize block I/O for disk drives, not flash memory. While I don't think that this is the cause of the problem, it does affect how the kernel uses the swap space if you are swapping off a flash drive.

As for the swapping, vm.min_free_kbytes=16536 tells the kernel to try to keep at least 16M of memory free. For some reason, your page cache appears to eating a huge ammount of memory, if the kernel isn't trying to reclaim space from the cache, then it will be trying to swap instead. You might try adding:
vm.swappieness=30 vm.vfs_cache_pressure=150 vm.page-cluster=1
to the kernel commandline, this will make it swap less often, swap fewer pages at a time, and reclaim cache pages more aggressively.

@ghalfacree
Copy link

@Ferroin: Swappiness is already set to 1 by default in Raspbian, so setting it to 30 would increase, rather than decrease, how much it tries to swap out of memory. For now, I've tried turning swap off entirely in order to see what effect that has on the system. I should know in the next couple of days whether it has made any difference. Should it show the same symptoms even without a swap device, I'll try playing with the kernel options you've suggested.

@Ferroin
Copy link
Contributor

Ferroin commented Apr 9, 2013

@ghalfacree: I did not know that, as I use Gentoo, not Raspbian.

Have you tried using ext4 instead of btrfs? btrfs is unstable after all, and it has a tendency to put pretty heavy load on lower bandwidth busses like USB.

@ghalfacree
Copy link

@Ferroin: Ext4 does not support the features I require - the discussion of which is outside the scope of this issue. Btrfs may be unstable - although I think its developers would prefer you use the term "experimental" - but the fact is it's not btrfs that's failing here: it's the Raspbian kernel. I have used btrfs 0.19 on similar hardware in the past with no issues whatsoever.

@P33M
Copy link
Contributor

P33M commented Apr 10, 2013

@gordonhollingworth

#153 (comment)

The source of the allocation failure (top of the call stack) is still constant after the tasklet patch. The reason you're seeing the tasklet appear is because it is now the calling function for usb_hcd_giveback_urb rather than the interrupt handler directly. The tasklet is interrupt-safe in data transfer between the IRQ and tasklet - I have seen instances where it gets pre-empted as much as 10 times in a single run during boot.

I did try to find the source of page allocation errors in the process of finding the cause of #189 but the frustratingly infrequent occurrences and disappearance when I turned on SLUB object owner tracking made me give up. If btrfs gives a more repeatable result then I could probably start digging again.

On the latest kernel during a bit of stress testing I did try a maxed out torrent at the speed of my line. 2MB/s to USB HDD, no issues during the 30minute transfer.

@ghalfacree
Copy link

Since turning swap off entirely, I have not had any page allocation failures - unsurprisingly.

@P33M: It certainly seems that running a pair of external harddrives set up in a RAID1 array through btrfs and shoving a bunch of data at them is enough to reliably trigger the bug within a single day. To match my setup, mount the btrfs drives with LZO compression and free space caching enabled, and transfer the data via SSH.

You'll certainly need to spend more than half an hour running the test, though: the earliest I've been able to get it to trigger is after seven hours.

@szarpaj
Copy link

szarpaj commented Apr 14, 2013

Similar errors with 3.2.x series kernel are intereseting? (yeah, I know, I should upgrade, but my pi has 54 days uptime and I just don't want to brake it :P )

@ghalfacree
Copy link

Any progress on this? The errors occur even when swap is deactivated, as per the below log:

[937187.097260] sshd: page allocation failure: order:0, mode:0x20
[937187.097328] [<c0013a7c>] (unwind_backtrace+0x0/0xf0) from [<c009274c>] (warn_alloc_failed+0xc4/0x11c)
[937187.097358] [<c009274c>] (warn_alloc_failed+0xc4/0x11c) from [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c)
[937187.097387] [<c0094a5c>] (__alloc_pages_nodemask+0x3e0/0x63c) from [<c02e49ec>] (__netdev_alloc_frag+0x90/0x118)
[937187.097417] [<c02e49ec>] (__netdev_alloc_frag+0x90/0x118) from [<c02e8b5c>] (__netdev_alloc_skb+0x40/0xd0)
[937187.097447] [<c02e8b5c>] (__netdev_alloc_skb+0x40/0xd0) from [<c026aac0>] (rx_submit+0x1c/0x1f8)
[937187.097481] [<c026aac0>] (rx_submit+0x1c/0x1f8) from [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4)
[937187.097513] [<c0272440>] (usb_hcd_giveback_urb+0x60/0xf4) from [<c0296228>] (completion_tasklet_func+0x68/0x94)
[937187.097550] [<c0296228>] (completion_tasklet_func+0x68/0x94) from [<c029fb90>] (tasklet_callback+0x10/0x14)
[937187.097590] [<c029fb90>] (tasklet_callback+0x10/0x14) from [<c002565c>] (tasklet_hi_action+0x60/0xb4)
[937187.097618] [<c002565c>] (tasklet_hi_action+0x60/0xb4) from [<c0025840>] (__do_softirq+0xa0/0x154)
[937187.097642] [<c0025840>] (__do_softirq+0xa0/0x154) from [<c0025d08>] (irq_exit+0x8c/0x94)
[937187.097674] [<c0025d08>] (irq_exit+0x8c/0x94) from [<c000e920>] (handle_IRQ+0x34/0x84)
[937187.097699] [<c000e920>] (handle_IRQ+0x34/0x84) from [<c0399e78>] (__irq_usr+0x38/0xc0)
[937187.097708] Mem-info:
[937187.097716] Normal per-cpu:
[937187.097727] CPU    0: hi:  186, btch:  31 usd: 173
[937187.097751] active_anon:4664 inactive_anon:81 isolated_anon:0
[937187.097751]  active_file:47359 inactive_file:56002 isolated_file:0
[937187.097751]  unevictable:0 dirty:711 writeback:0 unstable:0
[937187.097751]  free:2628 slab_reclaimable:10057 slab_unreclaimable:1211
[937187.097751]  mapped:1589 shmem:96 pagetables:215 bounce:0
[937187.097801] Normal free:10512kB min:8192kB low:10240kB high:12288kB active_anon:18656kB inactive_anon:324kB active_file:189436kB inactive_file:224008kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:503936kB mlocked:0kB dirty:2844kB writeback:0kB mapped:6356kB shmem:384kB slab_reclaimable:40228kB slab_unreclaimable:4844kB kernel_stack:1248kB pagetables:860kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[937187.097814] lowmem_reserve[]: 0 0
[937187.097831] Normal: 438*4kB 321*8kB 219*16kB 62*32kB 11*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 10512kB
[937187.097872] 103463 total pagecache pages
[937187.097880] 0 pages in swap cache
[937187.097888] Swap cache stats: add 0, delete 0, find 0/0
[937187.097895] Free swap  = 0kB
[937187.097901] Total swap = 0kB
[937187.123857] 126976 pages of RAM
[937187.123866] 3063 free pages
[937187.123872] 2590 reserved pages
[937187.123878] 11268 slab pages
[937187.123884] 84091 pages shared
[937187.123890] 0 pages swap cached

popcornmix pushed a commit that referenced this issue Jan 22, 2014
…resume

There are cases where cpufreq_add_dev() may fail for some CPUs
during system resume. With the current code we will still have
sysfs cpufreq files for those CPUs and struct cpufreq_policy
would be already freed for them. Hence any operation on those
sysfs files would result in kernel warnings.

Example of problems resulting from resume errors (from Bjørn Mork):

WARNING: CPU: 0 PID: 6055 at fs/sysfs/file.c:343 sysfs_open_file+0x77/0x212()
missing sysfs attribute operations for kobject: (null)
Modules linked in: [stripped as irrelevant]
CPU: 0 PID: 6055 Comm: grep Tainted: G      D      3.13.0-rc2 #153
Hardware name: LENOVO 2776LEG/2776LEG, BIOS 6EET55WW (3.15 ) 12/19/2011
 0000000000000009 ffff8802327ebb78 ffffffff81380b0e 0000000000000006
 ffff8802327ebbc8 ffff8802327ebbb8 ffffffff81038635 0000000000000000
 ffffffff811823c7 ffff88021a19e688 ffff88021a19e688 ffff8802302f9310
Call Trace:
 [<ffffffff81380b0e>] dump_stack+0x55/0x76
 [<ffffffff81038635>] warn_slowpath_common+0x7c/0x96
 [<ffffffff811823c7>] ? sysfs_open_file+0x77/0x212
 [<ffffffff810386e3>] warn_slowpath_fmt+0x41/0x43
 [<ffffffff81182dec>] ? sysfs_get_active+0x6b/0x82
 [<ffffffff81182382>] ? sysfs_open_file+0x32/0x212
 [<ffffffff811823c7>] sysfs_open_file+0x77/0x212
 [<ffffffff81182350>] ? sysfs_schedule_callback+0x1ac/0x1ac
 [<ffffffff81122562>] do_dentry_open+0x17c/0x257
 [<ffffffff8112267e>] finish_open+0x41/0x4f
 [<ffffffff81130225>] do_last+0x80c/0x9ba
 [<ffffffff8112dbbd>] ? inode_permission+0x40/0x42
 [<ffffffff81130606>] path_openat+0x233/0x4a1
 [<ffffffff81130b7e>] do_filp_open+0x35/0x85
 [<ffffffff8113b787>] ? __alloc_fd+0x172/0x184
 [<ffffffff811232ea>] do_sys_open+0x6b/0xfa
 [<ffffffff811233a7>] SyS_openat+0xf/0x11
 [<ffffffff8138c812>] system_call_fastpath+0x16/0x1b

To fix this, remove those sysfs files or put the associated kobject
in case of such errors. Also, to make it simple, remove the cpufreq
sysfs links from all the CPUs (except for the policy->cpu) during
suspend, as that operation won't result in a loss of sysfs file
permissions and we can create those links during resume just fine.

Fixes: 5302c3f ("cpufreq: Perform light-weight init/teardown during suspend/resume")
Reported-and-tested-by: Bjørn Mork <[email protected]>
Signed-off-by: Viresh Kumar <[email protected]>
Cc: 3.12+ <[email protected]> # 3.12+
[rjw: Changelog]
Signed-off-by: Rafael J. Wysocki <[email protected]>
@P33M
Copy link
Contributor

P33M commented May 5, 2014

Memory fragmentation is the root cause of this issue. CONFIG_COMPACTION and CONFIG_SLUB make this orders of magnitude less likely to happen.

@P33M P33M closed this as completed May 5, 2014
popcornmix pushed a commit that referenced this issue Jun 8, 2014
... at edp_have_panel_vdd. Just return false, saying we don't have the
panel VDD since the device is suspended.

We started getting WARNs about this problem since the patch that
started checking if we're suspended while reading registers.

Example backtrace provided by Paulo:

[   63.572201] [drm:hsw_enable_pc8] Enabling package C8+
[   63.581831] [drm:i915_runtime_suspend] Device suspended
[   63.664798] ------------[ cut here ]------------
[   63.664824] WARNING: CPU: 3 PID: 828 at
drivers/gpu/drm/i915/intel_uncore.c:47
assert_device_not_suspended.isra.7+0x32/0x40 [i915]()
[   63.664826] Device suspended
[   63.664828] Modules linked in: ccm fuse ip6table_filter ip6_tables
ebtable_nat ebtables arc4 ath9k_htc ath9k_common ath9k_hw mac80211 ath
cfg80211 iTCO_wdt iTCO_vendor_support x86_pkg_temp_thermal coretemp
microcode i2c_i801 e1000e pcspkr serio_raw lpc_ich ptp pps_core mei_me
mei mfd_core dm_crypt i915 crc32_pclmul crc32c_intel
ghash_clmulni_intel i2c_algo_bit drm_kms_helper drm video
[   63.664867] CPU: 3 PID: 828 Comm: kworker/3:3 Not tainted 3.14.0+ #153
[   63.664869] Hardware name: Intel Corporation Shark Bay Client
platform/WhiteTip Mountain 1, BIOS HSWLPTU1.86C.0133.R00.1309172123
09/17/2013
[   63.664887] Workqueue: events edp_panel_vdd_work [i915]
[   63.664889]  0000000000000009 ffff88009d745c28 ffffffff8167ec6f
ffff88009d745c70
[   63.664895]  ffff88009d745c60 ffffffff8106c8ed ffff880036278000
00000000000c7204
[   63.664900]  ffff88014f2d3040 ffff880036278070 0000000000000001
ffff88009d745cc0
[   63.664905] Call Trace:
[   63.664911]  [<ffffffff8167ec6f>] dump_stack+0x4d/0x66
[   63.664916]  [<ffffffff8106c8ed>] warn_slowpath_common+0x7d/0xa0
[   63.664920]  [<ffffffff8106c95c>] warn_slowpath_fmt+0x4c/0x50
[   63.664926]  [<ffffffff810bd6be>] ? mark_held_locks+0xae/0x130
[   63.664941]  [<ffffffffa00d80d2>]
assert_device_not_suspended.isra.7+0x32/0x40 [i915]
[   63.664956]  [<ffffffffa00d99d2>] gen6_read32+0x32/0x120 [i915]
[   63.664969]  [<ffffffffa00d99a0>] ? gen6_read8+0x120/0x120 [i915]
[   63.664985]  [<ffffffffa0106f8f>] edp_have_panel_vdd+0x3f/0x50 [i915]
[   63.665000]  [<ffffffffa01074e8>] edp_panel_vdd_off_sync+0x58/0x1c0 [i915]
[   63.665004]  [<ffffffff8108a06c>] ? process_one_work+0x18c/0x560
[   63.665018]  [<ffffffffa0107684>] edp_panel_vdd_work+0x34/0x50 [i915]
[   63.665022]  [<ffffffff8108a0d7>] process_one_work+0x1f7/0x560
[   63.665026]  [<ffffffff8108a06c>] ? process_one_work+0x18c/0x560
[   63.665031]  [<ffffffff8108ae2b>] worker_thread+0x11b/0x3a0
[   63.665035]  [<ffffffff8108ad10>] ? manage_workers.isra.21+0x2a0/0x2a0
[   63.665039]  [<ffffffff810916fc>] kthread+0xfc/0x120
[   63.665043]  [<ffffffff81091600>] ? kthread_create_on_node+0x230/0x230
[   63.665048]  [<ffffffff8169082c>] ret_from_fork+0x7c/0xb0
[   63.665052]  [<ffffffff81091600>] ? kthread_create_on_node+0x230/0x230
[   63.665054] ---[ end trace 1250bcc890af9999 ]---
[   63.665060] [drm:edp_panel_vdd_off_sync] Turning eDP VDD off
[   63.665061] ------------[ cut here ]------------

Testcase: igt/pm_pc8
Signed-off-by: Paulo Zanoni <[email protected]>
Signed-off-by: Daniel Vetter <[email protected]>
popcornmix pushed a commit that referenced this issue Oct 8, 2014
Fixes the following checkpatch warnings:

    WARNING: please, no space before tabs
    #5: FILE: drivers/mfd/88pm860x-core.c:5:
    + * ^IHaojian Zhuang <[email protected]>$

    WARNING: line over 80 characters
    #143: FILE: drivers/mfd/88pm860x-core.c:143:
    +	{PM8607_IRQ_AUDIO_SHORT, PM8607_IRQ_AUDIO_SHORT, "audio-short", IORESOURCE_IRQ,},

    WARNING: line over 80 characters
    #153: FILE: drivers/mfd/88pm860x-core.c:153:
    +	{PM8607_IRQ_CHG_DONE,  PM8607_IRQ_CHG_DONE,  "charging done",       IORESOURCE_IRQ,},

    WARNING: line over 80 characters
    #154: FILE: drivers/mfd/88pm860x-core.c:154:
    +	{PM8607_IRQ_CHG_FAIL,  PM8607_IRQ_CHG_FAIL,  "charging timeout",    IORESOURCE_IRQ,},

    WARNING: line over 80 characters
    #155: FILE: drivers/mfd/88pm860x-core.c:155:
    +	{PM8607_IRQ_CHG_FAULT, PM8607_IRQ_CHG_FAULT, "charging fault",	    IORESOURCE_IRQ,},

    WARNING: line over 80 characters
    #156: FILE: drivers/mfd/88pm860x-core.c:156:
    +	{PM8607_IRQ_GPADC1,    PM8607_IRQ_GPADC1,    "battery temperature", IORESOURCE_IRQ,},

    WARNING: Avoid unnecessary line continuations
    #571: FILE: drivers/mfd/88pm860x-core.c:571:
    +	struct i2c_client *i2c = (chip->id == CHIP_PM8607) ? chip->client \

    WARNING: line over 80 characters
    #634: FILE: drivers/mfd/88pm860x-core.c:634:
    +	ret = request_threaded_irq(chip->core_irq, NULL, pm860x_irq, flags | IRQF_ONESHOT,

    WARNING: Unnecessary parentheses - maybe == should be = ?
    #874: FILE: drivers/mfd/88pm860x-core.c:874:
    +	if ((pdata == NULL))

    WARNING: quoted string split across lines
    #1001: FILE: drivers/mfd/88pm860x-core.c:1001:
    +		dev_err(chip->dev, "Failed to detect Marvell 88PM8607. "
    +			"Chip ID: %02x\n", ret);

    WARNING: quoted string split across lines
    #1124: FILE: drivers/mfd/88pm860x-core.c:1124:
    +		dev_err(dev, "Not found \"marvell,88pm860x-slave-addr\" "
    +			"property\n");

total: 0 errors, 11 warnings, 1281 lines checked

Signed-off-by: Lee Jones <[email protected]>
@Flux3PO
Copy link

Flux3PO commented Feb 23, 2015

I'm new to Linux/Raspbian.
I just got a Raspberry Pi 2 (1GB Ram) and installed Raspbian + Transmission and had a crash after a few H seeding, sometimes even after a few minutes Leeching.

smsc95xx.turbo_mode=N, vm.min_free_kbytes=2048 seems to be a good modification. Running it for 12h without an issue so far.

Any reason why this is not of the standard build ?

popcornmix pushed a commit that referenced this issue Jul 14, 2015
John Stultz reports an RCU splat on boot with ARM ipi trace
events enabled.

===============================
[ INFO: suspicious RCU usage. ]
4.1.0-rc7-00033-gb5bed2f #153 Not tainted
-------------------------------
include/trace/events/ipi.h:68 suspicious rcu_dereference_check() usage!

other info that might help us debug this:

RCU used illegally from idle CPU!
rcu_scheduler_active = 1, debug_locks = 0
RCU used illegally from extended quiescent state!
no locks held by swapper/0/0.

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.1.0-rc7-00033-gb5bed2f #153
Hardware name: Qualcomm (Flattened Device Tree)
[<c0216b08>] (unwind_backtrace) from [<c02136e8>] (show_stack+0x10/0x14)
[<c02136e8>] (show_stack) from [<c075e678>] (dump_stack+0x70/0xbc)
[<c075e678>] (dump_stack) from [<c0215a80>] (handle_IPI+0x428/0x604)
[<c0215a80>] (handle_IPI) from [<c020942c>] (gic_handle_irq+0x54/0x5c)
[<c020942c>] (gic_handle_irq) from [<c0766604>] (__irq_svc+0x44/0x7c)
Exception stack(0xc09f3f48 to 0xc09f3f90)
3f40:                   00000001 00000001 00000000 c09f73b8 c09f4528 c0a5de9c
3f60: c076b4f0 00000000 00000000 c09ef108 c0a5cec1 00000001 00000000 c09f3f90
3f80: c026bf60 c0210ab8 20000113 ffffffff
[<c0766604>] (__irq_svc) from [<c0210ab8>] (arch_cpu_idle+0x20/0x3c)
[<c0210ab8>] (arch_cpu_idle) from [<c02647f0>] (cpu_startup_entry+0x2c0/0x5dc)
[<c02647f0>] (cpu_startup_entry) from [<c099bc1c>] (start_kernel+0x358/0x3c4)
[<c099bc1c>] (start_kernel) from [<8020807c>] (0x8020807c)

At this point in the IPI handling path we haven't called
irq_enter() yet, so RCU doesn't know that we're about to exit
idle and properly warns that we're using RCU from an idle CPU.
Use trace_ipi_entry_rcuidle() instead of trace_ipi_entry() so
that RCU is informed about our exit from idle.

Fixes: 365ec7b ("ARM: add IPI tracepoints")
Reported-by: John Stultz <[email protected]>
Tested-by: John Stultz <[email protected]>
Acked-by: Steven Rostedt <[email protected]>
Reviewed-by: Paul E. McKenney <[email protected]>
Signed-off-by: Stephen Boyd <[email protected]>
Signed-off-by: Russell King <[email protected]>
davet321 pushed a commit to davet321/rpi-linux that referenced this issue Aug 4, 2015
commit 398f745 upstream.

John Stultz reports an RCU splat on boot with ARM ipi trace
events enabled.

===============================
[ INFO: suspicious RCU usage. ]
4.1.0-rc7-00033-gb5bed2f raspberrypi#153 Not tainted
-------------------------------
include/trace/events/ipi.h:68 suspicious rcu_dereference_check() usage!

other info that might help us debug this:

RCU used illegally from idle CPU!
rcu_scheduler_active = 1, debug_locks = 0
RCU used illegally from extended quiescent state!
no locks held by swapper/0/0.

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.1.0-rc7-00033-gb5bed2f raspberrypi#153
Hardware name: Qualcomm (Flattened Device Tree)
[<c0216b08>] (unwind_backtrace) from [<c02136e8>] (show_stack+0x10/0x14)
[<c02136e8>] (show_stack) from [<c075e678>] (dump_stack+0x70/0xbc)
[<c075e678>] (dump_stack) from [<c0215a80>] (handle_IPI+0x428/0x604)
[<c0215a80>] (handle_IPI) from [<c020942c>] (gic_handle_irq+0x54/0x5c)
[<c020942c>] (gic_handle_irq) from [<c0766604>] (__irq_svc+0x44/0x7c)
Exception stack(0xc09f3f48 to 0xc09f3f90)
3f40:                   00000001 00000001 00000000 c09f73b8 c09f4528 c0a5de9c
3f60: c076b4f0 00000000 00000000 c09ef108 c0a5cec1 00000001 00000000 c09f3f90
3f80: c026bf60 c0210ab8 20000113 ffffffff
[<c0766604>] (__irq_svc) from [<c0210ab8>] (arch_cpu_idle+0x20/0x3c)
[<c0210ab8>] (arch_cpu_idle) from [<c02647f0>] (cpu_startup_entry+0x2c0/0x5dc)
[<c02647f0>] (cpu_startup_entry) from [<c099bc1c>] (start_kernel+0x358/0x3c4)
[<c099bc1c>] (start_kernel) from [<8020807c>] (0x8020807c)

At this point in the IPI handling path we haven't called
irq_enter() yet, so RCU doesn't know that we're about to exit
idle and properly warns that we're using RCU from an idle CPU.
Use trace_ipi_entry_rcuidle() instead of trace_ipi_entry() so
that RCU is informed about our exit from idle.

Fixes: 365ec7b ("ARM: add IPI tracepoints")
Reported-by: John Stultz <[email protected]>
Tested-by: John Stultz <[email protected]>
Acked-by: Steven Rostedt <[email protected]>
Reviewed-by: Paul E. McKenney <[email protected]>
Signed-off-by: Stephen Boyd <[email protected]>
Signed-off-by: Russell King <[email protected]>
Signed-off-by: Greg Kroah-Hartman <[email protected]>
popcornmix pushed a commit that referenced this issue Dec 21, 2015
…ting in skbuff clones

If we attach the sk to the skb from nfnetlink_rcv_batch(), then
netlink_skb_destructor() will underflow the socket receive memory
counter and we get warning splat when releasing the socket.

$ cat /proc/net/netlink
sk       Eth Pid    Groups   Rmem     Wmem     Dump     Locks     Drops     Inode
ffff8800ca903000 12  0      00000000 -54144   0        0 2        0        17942
                                     ^^^^^^

Rmem above shows an underflow.

And here below the warning splat:

[ 1363.815976] WARNING: CPU: 2 PID: 1356 at net/netlink/af_netlink.c:958 netlink_sock_destruct+0x80/0xb9()
[...]
[ 1363.816152] CPU: 2 PID: 1356 Comm: kworker/u16:1 Tainted: G        W       4.4.0-rc1+ #153
[ 1363.816155] Hardware name: LENOVO 23259H1/23259H1, BIOS G2ET32WW (1.12 ) 05/30/2012
[ 1363.816160] Workqueue: netns cleanup_net
[ 1363.816163]  0000000000000000 ffff880119203dd0 ffffffff81240204 0000000000000000
[ 1363.816169]  ffff880119203e08 ffffffff8104db4b ffffffff813d49a1 ffff8800ca771000
[ 1363.816174]  ffffffff81a42b00 0000000000000000 ffff8800c0afe1e0 ffff880119203e18
[ 1363.816179] Call Trace:
[ 1363.816181]  <IRQ>  [<ffffffff81240204>] dump_stack+0x4e/0x79
[ 1363.816193]  [<ffffffff8104db4b>] warn_slowpath_common+0x9a/0xb3
[ 1363.816197]  [<ffffffff813d49a1>] ? netlink_sock_destruct+0x80/0xb9

skb->sk was only needed to lookup for the netns, however we don't need
this anymore since 633c9a8 ("netfilter: nfnetlink: avoid recurrent
netns lookups in call_batch") so this patch removes this manual socket
assignment to resolve this problem.

Reported-by: Arturo Borrero Gonzalez <[email protected]>
Reported-by: Ben Hutchings <[email protected]>
Signed-off-by: Pablo Neira Ayuso <[email protected]>
Tested-by: Arturo Borrero Gonzalez <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

10 participants