search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.02k stars 4.95k forks source link

Raspbian: swapper page allocation failure #153

Closed MilhouseVH closed 10 years ago

MilhouseVH commented 11 years ago

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 commented 11 years ago

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 commented 11 years ago

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

Is the patch from Ming Lei applicable to the Pi?

popcornmix commented 11 years ago

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 commented 11 years ago

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 commented 11 years ago

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

MilhouseVH commented 11 years ago

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 commented 11 years ago

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 commented 11 years ago

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

popcornmix commented 11 years ago

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

MilhouseVH commented 11 years ago

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 commented 11 years ago

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 commented 11 years ago

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 commented 11 years ago

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

asb commented 11 years ago

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 commented 11 years ago

@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 commented 11 years ago

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

popcornmix commented 11 years ago

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

MilhouseVH commented 11 years ago

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 commented 11 years ago

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

MilhouseVH commented 11 years ago

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 commented 11 years ago

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

steveglen commented 11 years ago

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 commented 11 years ago

@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 commented 11 years ago

Test setup:

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 commented 11 years ago

Thanks. That's useful to know.

popcornmix commented 11 years ago

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 commented 11 years ago

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 commented 11 years ago

Thanks for info.

MilhouseVH commented 11 years ago

Running the latest Raspbian and recent kernel/firmware, and while downloading single torrents (tv shows with Transmission) I've noticed a number of swapper/kevent 2 problems when vm.min_free_kbytes is set to 2048 and smsc95xx.turbo_mode=N, so even this figure may not be enough to eradicate the problem entirely. I'm presuming I must of had a very large number of peer connections which may have triggered the problem. Thankfully the kevent 2 messages are now rate limited so are much less of a problem than they were before - thanks so much @steveglen!

I would say that 2048 and turbo=N is entirely satisfactory for non-torrent situations, though. I'll try bumping vm.min_free_kbytes to 3096 and see if that helps with torrents.

My current setup (I'm not using CMA):

pi@raspberrypi /etc $ uname -a
Linux raspberrypi 3.6.11+ #350 PREEMPT Mon Jan 7 21:51:11 GMT 2013 armv6l GNU/Linux
pi@raspberrypi /etc $ vcgencmd version
Jan  7 2013 21:59:59
Copyright (c) 2012 Broadcom
version 360961 (release)
popcornmix commented 11 years ago

@MilhouseVH Noted.

MilhouseVH commented 11 years ago

Weird, I'm still getting kevent 2/swapper page allocation failures with vm.min_free_kbytes=4096 and turbo_mode disabled, and this while downloading just a single torrent.

Has something changed in the firmware/kernel since my testing 2 months ago? I'm now on a later version of the firmware/kernel (see my previous comment for details).

popcornmix commented 11 years ago

Can you revert to Jan 7 kernel and confirm it still works better? The only likely change is this one: https://github.com/raspberrypi/linux/pull/190 although all evidence suggests this change is beneficial. Can you try with that reverted?

MilhouseVH commented 11 years ago

Where can I get the Jan 7 kernel? Am I not already on it (uname says 7 Jan 21:51:11). If you have a direct link for the kernel you want me to test I'll certainly give it a go.

MilhouseVH commented 11 years ago

Ideally I'd like to compare the 18 Oct kernel I tested with 2 months ago, against what we have now, to confirm if my testing from 2 months ago was at fault. Is this possible?

popcornmix commented 11 years ago

sudo rpi-update 32115795dc2b6a3b5dadea6ab151d60432e08e21 should get you back to 7th January firmware. (remove from git hash)

(rebuilding kernel from git would be another solution)

MilhouseVH commented 11 years ago

Do you have the commit for 18 Oct so that I can also try that, compare/contrast?

popcornmix commented 11 years ago

They are all here: https://github.com/Hexxeh/rpi-firmware/commits/master

18 Oct is a6dff06b034400800112d87f61bd795fe5a27a2d (remove )

MilhouseVH commented 11 years ago

Thanks. Just backing up the SD card of the system (32GB at 18MB/s...) and then I'll run some tests working forwards from 18 Oct... hopefully have some news in a few hours.

MilhouseVH commented 11 years ago

Can vm.min_free_kbytes by set interactively (using sysctl -w) or does it require a reboot for the new value to take effect? Not sure if I rebooted when increasing from 2048 to 3072, and I certainly didn't reboot when changing it again to 4096. So far I've downloaded the same torrent as last night, using the same kernel, and no problem. Grrrr.

MilhouseVH commented 11 years ago

Never mind, have now triggered swapper errors with the latest kernel and 4096. Starting to test some older kernels....

MilhouseVH commented 11 years ago

OK, I'm seeing swapper/kevent 2 errors with the 18 Oct kernel and vm.min_free_kbytes=2048, so I guess my previous testing wasn't sufficiently rigorous/stressful.

I upped vm.min_free_kbytes to 4096, and I'm still seeing swapper/kevent errors with the 18 Oct kernel, so this latest torrent is obviously putting a lot more stress on the system than before.

Should this ticket be reopened? I'm not sure what value of vm.min_free_kbytes will prove sufficient.

popcornmix commented 11 years ago

Can you find a safe value for vm.min_free_kbytes?

MilhouseVH commented 11 years ago

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 commented 11 years ago

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 commented 11 years ago

@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?

ghalfacree commented 11 years ago

@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 commented 11 years ago

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 notifications@github.com<mailto:notifications@github.com> 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/raspberrypi/linux/issues/153#issuecomment-15955082.

popcornmix commented 11 years ago

@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 commented 11 years ago

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 commented 11 years ago

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