I was able to get a single instance of this failure captured in the
log files that is a little more manageable (about an 800k syslog) over
a 6 minute period which was approximately how long the system went
completely unresponsive. It appears that problem starts with the page
allocation failures, which results in packets being dropped while the
kernel is busy trying to free memory, it's also possible that all this
logging activity snowballs dropping more packets... that it then needs
to log as well. The problem finally seems to resolve itself when all
productive activity has essentially halted and the system is able to
get caught up with the log messages and then performance and
responsiveness return to normal. Again, while this instance is
occurring with MythTV (only the backend is running on the -xM), I've
seen the same issue when sending large files via sftp and the thing
both activities seem to have in common is they are over long
timeframes (minutes to hours) reading several megabytes a second via
Ethernet and writing it out to local disk (USB or microSD). Here's a
bit more detail as to what is being logged:
On Nov 21, 2:40 am, Phil <
phil.bellalo...@gmail.com> wrote:
>
> 1) kernel: smsc95xx usb1: kevent 2 may have been dropped (hundreds of
> messages per second... despite the fact that $RepeatedMsgReduction is
These messages begin occurring after the page allocation errors
below. 3500 occurrences of these messages.
> on in rsyslog.conf)
> 2) numerous page allocation failures with backtraces
>
There were 90 page allocation failures, here is the first one:
Nov 21 14:09:19 cortex kernel: [50205.769378] __alloc_pages_slowpath:
308 callbacks suppressed
Nov 21 14:09:19 cortex kernel: [50205.769409] mythfilldatabas: page
allocation failure. order:3, mode:0x4020
Nov 21 14:09:19 cortex kernel: [50205.769470] [<c00512a0>]
(unwind_backtrace+0x0/0x100) from [<c06386c0>] (dump_stack+0x18/0x1c)
Nov 21 14:09:19 cortex kernel: [50205.769500] [<c06386c0>] (dump_stack
+0x18/0x1c) from [<c011a7f4>] (__alloc_pages_nodemask+0x60c/0x69c)
Nov 21 14:09:19 cortex kernel: [50205.769531] [<c011a7f4>]
(__alloc_pages_nodemask+0x60c/0x69c) from [<c011a8a0>]
(__get_free_pages+0x1c/0x44)
Nov 21 14:09:19 cortex kernel: [50205.769531] [<c011a8a0>]
(__get_free_pages+0x1c/0x44) from [<c0147818>] (__kmalloc_track_caller
+0x174/0x208)
Nov 21 14:09:19 cortex kernel: [50205.769561] [<c0147818>]
(__kmalloc_track_caller+0x174/0x208) from [<c052ef24>] (__alloc_skb
+0x5c/0xe8)
Nov 21 14:09:19 cortex kernel: [50205.769592] [<c052ef24>] (__alloc_skb
+0x5c/0xe8) from [<c044e714>] (rx_submit+0x2c/0x260)
Nov 21 14:09:19 cortex kernel: [50205.769622] [<c044e714>] (rx_submit
+0x2c/0x260) from [<c044eea8>] (rx_complete+0x1b4/0x1b8)
Nov 21 14:09:19 cortex kernel: [50205.769653] [<c044eea8>] (rx_complete
+0x1b4/0x1b8) from [<c045e188>] (usb_hcd_giveback_urb+0x6c/0x100)
Nov 21 14:09:19 cortex kernel: [50205.769683] [<c045e188>]
(usb_hcd_giveback_urb+0x6c/0x100) from [<c047320c>] (ehci_urb_done
+0xa8/0xc8)
Nov 21 14:09:19 cortex kernel: [50205.769683] [<c047320c>]
(ehci_urb_done+0xa8/0xc8) from [<c04734b4>] (qh_completions
+0x288/0x53c)
Nov 21 14:09:19 cortex kernel: [50205.769714] [<c04734b4>]
(qh_completions+0x288/0x53c) from [<c0475268>] (ehci_work+0x9c/0x109c)
Nov 21 14:09:19 cortex kernel: [50205.769714] [<c0475268>] (ehci_work
+0x9c/0x109c) from [<c0479230>] (ehci_irq+0x314/0x390)
Nov 21 14:09:19 cortex kernel: [50205.769744] [<c0479230>] (ehci_irq
+0x314/0x390) from [<c045d288>] (usb_hcd_irq+0x40/0xa4)
Nov 21 14:09:19 cortex kernel: [50205.769775] [<c045d288>] (usb_hcd_irq
+0x40/0xa4) from [<c00e4708>] (handle_IRQ_event+0x78/0x238)
Nov 21 14:09:19 cortex kernel: [50205.769805] [<c00e4708>]
(handle_IRQ_event+0x78/0x238) from [<c00e6de8>] (handle_level_irq
+0xb0/0x174)
Nov 21 14:09:19 cortex kernel: [50205.769836] [<c00e6de8>]
(handle_level_irq+0xb0/0x174) from [<c004a04c>] (asm_do_IRQ+0x4c/0x98)
Nov 21 14:09:19 cortex kernel: [50205.769866] [<c004a04c>] (asm_do_IRQ
+0x4c/0x98) from [<c063bb6c>] (__irq_svc+0xac/0x144)
Nov 21 14:09:19 cortex kernel: [50205.769866] Exception
stack(0xcfd81c58 to 0xcfd81ca0)
Nov 21 14:09:19 cortex kernel: [50205.769897]
1c40: 00000001
c1658040
Nov 21 14:09:19 cortex kernel: [50205.769897] 1c60: c1658040 c1658040
a0000013 00000000 c1658040 00000001 00000001 cfd81e18
Nov 21 14:09:19 cortex kernel: [50205.769927] 1c80: d4776cac cfd81ccc
c1658034 cfd81ca0 c007f774 c007e0e4 60000013 ffffffff
Nov 21 14:09:19 cortex kernel: [50205.769958] [<c063bb6c>] (__irq_svc
+0xac/0x144) from [<c007e0e4>] (__wake_up_sync_key+0x54/0x84)
Nov 21 14:09:19 cortex kernel: [50205.769958] [<c007e0e4>]
(__wake_up_sync_key+0x54/0x84) from [<c007e128>] (__wake_up_sync
+0x14/0x18)
Nov 21 14:09:19 cortex kernel: [50205.769989] [<c007e128>]
(__wake_up_sync+0x14/0x18) from [<c05bda70>] (unix_write_space+0x4c/
0x98)
Nov 21 14:09:19 cortex kernel: [50205.770019] [<c05bda70>]
(unix_write_space+0x4c/0x98) from [<c0529670>] (sock_wfree+0x74/0x7c)
Nov 21 14:09:19 cortex kernel: [50205.770050] [<c0529670>] (sock_wfree
+0x74/0x7c) from [<c052dfec>] (skb_release_head_state+0x8c/0x134)
Nov 21 14:09:19 cortex kernel: [50205.770050] [<c052dfec>]
(skb_release_head_state+0x8c/0x134) from [<c052dcec>] (__kfree_skb
+0x14/0xcc)
Nov 21 14:09:19 cortex kernel: [50205.770080] [<c052dcec>] (__kfree_skb
+0x14/0xcc) from [<c052de34>] (kfree_skb+0x44/0xcc)
Nov 21 14:09:19 cortex kernel: [50205.770111] [<c052de34>] (kfree_skb
+0x44/0xcc) from [<c05bd0f0>] (unix_stream_recvmsg+0x2bc/0x6a8)
Nov 21 14:09:19 cortex kernel: [50205.770111] [<c05bd0f0>]
(unix_stream_recvmsg+0x2bc/0x6a8) from [<c0524fd8>] (sock_aio_read
+0x174/0x17c)
Nov 21 14:09:19 cortex kernel: [50205.770141] [<c0524fd8>]
(sock_aio_read+0x174/0x17c) from [<c0151578>] (do_sync_read+0xb4/0xf4)
Nov 21 14:09:19 cortex kernel: [50205.770172] [<c0151578>]
(do_sync_read+0xb4/0xf4) from [<c01524e4>] (vfs_read+0x1b0/0x1b8)
Nov 21 14:09:19 cortex kernel: [50205.770202] [<c01524e4>] (vfs_read
+0x1b0/0x1b8) from [<c01525bc>] (sys_read+0x44/0x74)
Nov 21 14:09:19 cortex kernel: [50205.770202] [<c01525bc>] (sys_read
+0x44/0x74) from [<c004aae0>] (ret_fast_syscall+0x0/0x30)
Nov 21 14:09:19 cortex kernel: [50205.770233] Mem-info:
Nov 21 14:09:19 cortex kernel: [50205.770233] Normal per-cpu:
Nov 21 14:09:19 cortex kernel: [50205.770233] CPU 0: hi: 186,
btch: 31 usd: 207
Nov 21 14:09:19 cortex kernel: [50205.770263] active_anon:2758
inactive_anon:8787 isolated_anon:0
Nov 21 14:09:19 cortex kernel: [50205.770263] active_file:49967
inactive_file:24828 isolated_file:0
Nov 21 14:09:19 cortex kernel: [50205.770263] unevictable:0 dirty:330
writeback:0 unstable:0
Nov 21 14:09:19 cortex kernel: [50205.770294] free:28320
slab_reclaimable:4700 slab_unreclaimable:1447
Nov 21 14:09:19 cortex kernel: [50205.770294] mapped:5846 shmem:157
pagetables:320 bounce:0
Nov 21 14:09:19 cortex kernel: [50205.770324] Normal free:113280kB min:
2884kB low:3604kB high:4324kB active_anon:11032kB inactive_anon:
35148kB active_file:199868kB inactive_file:99312kB unevictable:0kB
isolated(anon):0kB isolated(file):0kB present:520192kB mlocked:0kB
dirty:1320kB writeback:0kB mapped:23384kB shmem:628kB slab_reclaimable:
18800kB slab_unreclaimable:5788kB kernel_stack:1960kB pagetables:
1280kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0
all_unreclaimable? no
Nov 21 14:09:19 cortex kernel: [50205.770355] lowmem_reserve[]: 0 0
Nov 21 14:09:19 cortex kernel: [50205.770385] Normal: 446*4kB 7305*8kB
3306*16kB 5*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB
0*4096kB = 113280kB
Nov 21 14:09:19 cortex kernel: [50205.770416] 74955 total pagecache
pages
Nov 21 14:09:19 cortex kernel: [50205.770416] 0 pages in swap cache
Nov 21 14:09:19 cortex kernel: [50205.770446] Swap cache stats: add 0,
delete 0, find 0/0
Nov 21 14:09:19 cortex kernel: [50205.770446] Free swap = 0kB
Nov 21 14:09:19 cortex kernel: [50205.770446] Total swap = 0kB
Nov 21 14:09:19 cortex kernel: [50205.786865] 131072 pages of RAM
Nov 21 14:09:19 cortex kernel: [50205.786865] 28877 free pages
Nov 21 14:09:19 cortex kernel: [50205.786895] 8735 reserved pages
Nov 21 14:09:19 cortex kernel: [50205.786895] 5641 slab pages
Nov 21 14:09:19 cortex kernel: [50205.786895] 50406 pages shared
Nov 21 14:09:19 cortex kernel: [50205.786895] 0 pages swap cached
Any ideas are appreciated,
Phil