Kernel trace buffer should be set to less unrealistic value

Bug #491943 reported by Michael Frey on 2009-12-03
136
This bug affects 28 people
Affects Status Importance Assigned to Milestone
ureadahead
Invalid
High
Unassigned
ureadahead (Ubuntu)
High
Tim Gardner
Lucid
High
Tim Gardner

Bug Description

When ureadahead tries to profile on a system with 512MB of memory. The kernel gets an OOM error.
Below is the kernel stack dump.

[ 2.912175] Freeing unused kernel memory: 336k freed
[ 2.912713] Write protecting the kernel text: 4536k
[ 2.913052] Write protecting the kernel read-only data: 2004k
[ 4.335798] ureadahead invoked oom-killer: gfp_mask=0xd0, order=0, oomkilladj=0
[ 4.335820] Pid: 64, comm: ureadahead Not tainted 2.6.31-15-generic #50fastboot9-Ubuntu
[ 4.335832] Call Trace:
[ 4.335859] [<c1077c61>] T.393+0x61/0x1be
[ 4.335879] [<c1077ded>] __out_of_memory+0x2f/0x113
[ 4.335896] [<c1077f2f>] out_of_memory+0x5e/0x86
[ 4.335914] [<c107a20f>] __alloc_pages_nodemask+0x36a/0x42f
[ 4.335933] [<c107a309>] __get_free_pages+0xf/0x21
[ 4.335951] [<c106227b>] ring_buffer_resize+0x139/0x238
[ 4.335970] [<c1062c03>] tracing_resize_ring_buffer+0x2f/0x70
[ 4.335987] [<c1065ba2>] tracing_entries_write+0xb2/0x136
[ 4.336005] [<c10651d3>] ? trace_nowake_buffer_unlock_commit+0x3f/0x46
[ 4.336051] [<c10982a6>] ? ftrace_raw_event_do_sys_open+0x85/0x8d
[ 4.336069] [<c109a599>] vfs_write+0x8a/0x112
[ 4.336086] [<c1065af0>] ? tracing_entries_write+0x0/0x136
[ 4.336103] [<c109a6b8>] sys_write+0x3b/0x60
[ 4.336121] [<c1002af4>] sysenter_do_call+0x12/0x26
[ 4.336132] Mem-Info:
[ 4.336140] DMA per-cpu:
[ 4.336150] CPU 0: hi: 0, btch: 1 usd: 0
[ 4.336161] CPU 1: hi: 0, btch: 1 usd: 0
[ 4.336170] Normal per-cpu:
[ 4.336181] CPU 0: hi: 186, btch: 31 usd: 156
[ 4.336192] CPU 1: hi: 186, btch: 31 usd: 161
[ 4.336212] Active_anon:326 active_file:13 inactive_anon:352
[ 4.336218] inactive_file:4 unevictable:0 dirty:6 writeback:0 unstable:0
[ 4.336224] free:1176 slab:3013 mapped:0 pagetables:3 bounce:0
[ 4.336245] DMA free:2000kB min:88kB low:108kB high:132kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB present:15836kB pages_scanned:0 all_unreclaimable? yes
[ 4.336270] lowmem_reserve[]: 0 482 482 482
[ 4.336312] Normal free:2704kB min:2760kB low:3448kB high:4140kB active_anon:1304kB inactive_anon:1408kB active_file:52kB inactive_file:16kB unevictable:0kB present:493624kB pages_scanned:0 all_unreclaimable? no
[ 4.336338] lowmem_reserve[]: 0 0 0 0
[ 4.336362] DMA: 0*4kB 0*8kB 1*16kB 0*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2000kB
[ 4.336414] Normal: 0*4kB 0*8kB 1*16kB 0*32kB 0*64kB 1*128kB 0*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 2704kB
[ 4.336464] 644 total pagecache pages
[ 4.336473] 0 pages in swap cache
[ 4.336482] Swap cache stats: add 0, delete 0, find 0/0
[ 4.336491] Free swap = 0kB
[ 4.336499] Total swap = 0kB
[ 4.344121] 128720 pages RAM
[ 4.344132] 0 pages HighMem
[ 4.344140] 3428 pages reserved
[ 4.344148] 630 pages shared
[ 4.344155] 122976 pages non-shared
[ 4.344169] Out of memory: kill process 64 (ureadahead) score 33 or a child
[ 4.344199] Killed process 64 (ureadahead)
[ 4.344353] ureadahead: page allocation failure. order:0, mode:0xd0
[ 4.344372] Pid: 64, comm: ureadahead Not tainted 2.6.31-15-generic #50fastboot9-Ubuntu
[ 4.344382] Call Trace:
[ 4.344407] [<c146ac77>] ? printk+0xf/0x11
[ 4.344429] [<c107a292>] __alloc_pages_nodemask+0x3ed/0x42f
[ 4.344449] [<c107a309>] __get_free_pages+0xf/0x21
[ 4.344468] [<c106227b>] ring_buffer_resize+0x139/0x238
[ 4.344486] [<c1062c03>] tracing_resize_ring_buffer+0x2f/0x70
[ 4.344503] [<c1065ba2>] tracing_entries_write+0xb2/0x136
[ 4.344521] [<c10651d3>] ? trace_nowake_buffer_unlock_commit+0x3f/0x46
[ 4.344541] [<c10982a6>] ? ftrace_raw_event_do_sys_open+0x85/0x8d
[ 4.344559] [<c109a599>] vfs_write+0x8a/0x112
[ 4.344575] [<c1065af0>] ? tracing_entries_write+0x0/0x136
[ 4.344592] [<c109a6b8>] sys_write+0x3b/0x60
[ 4.344610] [<c1002af4>] sysenter_do_call+0x12/0x26
[ 4.344621] Mem-Info:
[ 4.344629] DMA per-cpu:
[ 4.344638] CPU 0: hi: 0, btch: 1 usd: 0
[ 4.344649] CPU 1: hi: 0, btch: 1 usd: 0
[ 4.344658] Normal per-cpu:
[ 4.344669] CPU 0: hi: 186, btch: 31 usd: 156
[ 4.344689] CPU 1: hi: 186, btch: 31 usd: 161
[ 4.344700] Active_anon:326 active_file:13 inactive_anon:352
[ 4.344703] inactive_file:4 unevictable:0 dirty:6 writeback:0 unstable:0
[ 4.344706] free:1176 slab:3013 mapped:0 pagetables:3 bounce:0
[ 4.344717] DMA free:2000kB min:88kB low:108kB high:132kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB present:15836kB pages_scanned:0 all_unreclaimable? yes
[ 4.344725] lowmem_reserve[]: 0 482 482 482
[ 4.344740] Normal free:2704kB min:2760kB low:3448kB high:4140kB active_anon:1304kB inactive_anon:1408kB active_file:52kB inactive_file:16kB unevictable:0kB present:493624kB pages_scanned:0 all_unreclaimable? no
[ 4.344748] lowmem_reserve[]: 0 0 0 0
[ 4.344758] DMA: 0*4kB 0*8kB 1*16kB 0*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2000kB
[ 4.344783] Normal: 0*4kB 0*8kB 1*16kB 0*32kB 0*64kB 1*128kB 0*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 2704kB
[ 4.344808] 644 total pagecache pages
[ 4.344813] 0 pages in swap cache
[ 4.344818] Swap cache stats: add 0, delete 0, find 0/0
[ 4.344822] Free swap = 0kB
[ 4.344826] Total swap = 0kB
[ 4.348583] 128720 pages RAM
[ 4.348588] 0 pages HighMem
[ 4.348592] 3428 pages reserved
[ 4.348596] 630 pages shared
[ 4.348600] 122976 pages non-shared
[ 4.982732] wl: module license 'MIXED/Proprietary' taints kernel.
[ 4.982744] Disabling lock debugging due to kernel taint
[ 4.990532] wl 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[ 4.990555] wl 0000:03:00.0: setting latency timer to 64
[ 5.427550] ACPI: Battery Slot [BAT1] (battery present)
[ 5.617895] compal-laptop: Identified laptop model 'Dell Mini 10v'.
[ 5.618487] compal-laptop: driver 0.2.6 successfully loaded.
[ 5.629208] lib80211_crypt: registered algorithm 'TKIP'

Michael Frey (mfrey) on 2009-12-03
description: updated
Changed in ureadahead:
status: New → Confirmed
importance: Undecided → High

Moved to Ubuntu bug tracker

Changed in ureadahead (Ubuntu):
status: New → Confirmed
importance: Undecided → High
Changed in ureadahead:
status: Confirmed → Invalid

This is set to 128MB or something at the moment; that's ridiculously high

summary: - When trying to profile on a system with 512MB -- get a kernel OOM
+ Kernel trace buffer should be set to less unrealistic value
Changed in ureadahead (Ubuntu):
status: Confirmed → Triaged

Another point is that the trace buffer is not shrunk after profiling; this was for my own debugging, but I think by default we should reclaim this kernel memory

Will use bug #501715 for that

TimArbuckle (timarbuckle) wrote :

I get this in dmesg every boot (multiple times) and I have 2 GB:

[ 12.742072] ureadahead invoked oom-killer: gfp_mask=0xd0, order=0, oom_adj=0
[ 12.742076] ureadahead cpuset=/ mems_allowed=0-1
[ 12.742080] Pid: 578, comm: ureadahead Not tainted 2.6.32-18-server #27-Ubuntu
[ 12.742082] Call Trace:
[ 12.742090] [<ffffffff810b319d>] ? cpuset_print_task_mems_allowed+0x9d/0xb0
[ 12.742095] [<ffffffff810f5d74>] oom_kill_process+0xd4/0x2f0
[ 12.742099] [<ffffffff810f6330>] ? select_bad_process+0xd0/0x110
[ 12.742102] [<ffffffff810f63c8>] __out_of_memory+0x58/0xc0
[ 12.742104] [<ffffffff810f655e>] out_of_memory+0x12e/0x1a0
[ 12.742110] [<ffffffff81556f5e>] ? _spin_lock+0xe/0x20
[ 12.742114] [<ffffffff810f95a1>] __alloc_pages_slowpath+0x511/0x580
[ 12.742117] [<ffffffff810f9781>] __alloc_pages_nodemask+0x171/0x180
[ 12.742122] [<ffffffff8112c6c7>] alloc_pages_current+0x87/0xd0
[ 12.742124] [<ffffffff810f868e>] __get_free_pages+0xe/0x50
[ 12.742129] [<ffffffff810d4284>] ring_buffer_resize+0x204/0x340
[ 12.742133] [<ffffffff810d5c9d>] tracing_resize_ring_buffer+0x2d/0xa0
[ 12.742135] [<ffffffff810da277>] tracing_entries_write+0x137/0x1d0
[ 12.742139] [<ffffffff810d9b53>] ? trace_nowake_buffer_unlock_commit+0x43/0x60
[ 12.742144] [<ffffffff812504b6>] ? security_file_permission+0x16/0x20
[ 12.742148] [<ffffffff81143238>] vfs_write+0xb8/0x1a0
[ 12.742151] [<ffffffff81143aa1>] sys_write+0x51/0x80
[ 12.742157] [<ffffffff810131b2>] system_call_fastpath+0x16/0x1b

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu lucid (development branch)
Release: 10.04
Codename: lucid

$ uname -a
Linux hostname 2.6.32-18-server #27-Ubuntu SMP Fri Mar 26 22:21:21 UTC 2010 x86_64 GNU/Linux

$ cat /proc/meminfo
MemTotal: 2044892 kB
MemFree: 1766344 kB
Buffers: 12744 kB
Cached: 94456 kB
SwapCached: 0 kB
Active: 67472 kB
Inactive: 80856 kB
Active(anon): 44016 kB
Inactive(anon): 376 kB
Active(file): 23456 kB
Inactive(file): 80480 kB
Unevictable: 0 kB
Mlocked: 0 kB
SwapTotal: 5988344 kB
SwapFree: 5988344 kB
Dirty: 16 kB
Writeback: 0 kB
AnonPages: 41404 kB
Mapped: 24144 kB
Shmem: 3264 kB
Slab: 34712 kB
SReclaimable: 13444 kB
SUnreclaim: 21268 kB
KernelStack: 3032 kB
PageTables: 5884 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
WritebackTmp: 0 kB
CommitLimit: 7010788 kB
Committed_AS: 415540 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 279140 kB
VmallocChunk: 34358413300 kB
HardwareCorrupted: 0 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
HugePages_Surp: 0
Hugepagesize: 2048 kB
DirectMap4k: 8192 kB
DirectMap2M: 2080768 kB

Frits Jalvingh (fjalvingh) wrote :

Same here: on every machine I have, all having 4GB or more memory available. It always kills plymouthd process when called.

dino99 (9d9) wrote :
Download full text (5.0 KiB)

kernel 34-5 generic-pae on maverick:

ureadahead invoked oom-killer: gfp_mask=0xd0, order=0, oom_adj=0
 kernel: [ 8.729062] ureadahead cpuset=/ mems_allowed=0
 kernel: [ 8.741183] Pid: 343, comm: ureadahead Not tainted 2.6.34-5-generic-pae #12-Ubuntu
 kernel: [ 8.753804] Call Trace:
 kernel: [ 8.766178] [<c01dc2da>] dump_header+0x7a/0xb0
 kernel: [ 8.778538] [<c01dc36c>] oom_kill_process+0x5c/0x160
 kernel: [ 8.790755] [<c01dc8d9>] ? select_bad_process+0xa9/0xe0
 kernel: [ 8.802973] [<c01dc961>] __out_of_memory+0x51/0xb0
 kernel: [ 8.815039] [<c01dca18>] out_of_memory+0x58/0xd0
 kernel: [ 8.827234] [<c01df446>] __alloc_pages_slowpath+0x416/0x4b0
 kernel: [ 8.839506] [<c01df61a>] __alloc_pages_nodemask+0x13a/0x170
 kernel: [ 8.851563] [<c01df66c>] __get_free_pages+0x1c/0x30
 kernel: [ 8.863486] [<c01b8d77>] ring_buffer_resize+0x1b7/0x390
 kernel: [ 8.875423] [<c01b9f07>] tracing_resize_ring_buffer+0x37/0x80
 kernel: [ 8.887397] [<c01bddc2>] tracing_entries_write+0xe2/0x160
 kernel: [ 8.899340] [<c03047d4>] ? security_file_permission+0x14/0x20
 kernel: [ 8.911211] [<c021a2b4>] ? rw_verify_area+0x64/0xe0
 kernel: [ 8.911214] [<c021a3d2>] vfs_write+0xa2/0x1a0
 kernel: [ 8.911225] [<c01bdce0>] ? tracing_entries_write+0x0/0x160
kernel: [ 8.911228] [<c021acb2>] sys_write+0x42/0x70
 kernel: [ 8.911234] [<c0109463>] sysenter_do_call+0x12/0x28
 kernel: [ 8.911236] Mem-Info:
 kernel: [ 8.911238] DMA per-cpu:
 kernel: [ 8.911240] CPU 0: hi: 0, btch: 1 usd: 0
kernel: [ 8.911241] CPU 1: hi: 0, btch: 1 usd: 0
 kernel: [ 8.911243] CPU 2: hi: 0, btch: 1 usd: 0
 kernel: [ 8.911244] CPU 3: hi: 0, btch: 1 usd: 0
 kernel: [ 8.911245] Normal per-cpu:
 kernel: [ 8.911247] CPU 0: hi: 186, btch: 31 usd: 161
 kernel: [ 8.911249] CPU 1: hi: 186, btch: 31 usd: 176
 kernel: [ 8.911250] CPU 2: hi: 186, btch: 31 usd: 184
 kernel: [ 8.911252] CPU 3: hi: 186, btch: 31 usd: 66
 kernel: [ 8.911253] HighMem per-cpu:
 kernel: [ 8.911254] CPU 0: hi: 186, btch: 31 usd: 154
 kernel: [ 8.911256] CPU 1: hi: 186, btch: 31 usd: 35
 kernel: [ 8.911257] CPU 2: hi: 186, btch: 31 usd: 167
 kernel: [ 8.911259] CPU 3: hi: 186, btch: 31 usd: 77
 kernel: [ 8.911263] active_anon:121 inactive_anon:64 isolated_anon:0
 kernel: [ 8.911264] active_file:205 inactive_file:659 isolated_file:0
kernel: [ 8.911264] unevictable:0 dirty:0 writeback:0 unstable:0
kernel: [ 8.911265] free:820438 slab_reclaimable:686 slab_unreclaimable:4224
 kernel: [ 8.911266] mapped:289 shmem:48 pagetables:3 bounce:0
 kernel: [ 8.911271] DMA free:3516kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15804kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:64kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
kernel: [ 8.911274] lowmem_reserve[]: 0 869 4039 4039
kernel: [ 8.91...

Read more...

dino99 (9d9) wrote :

same errors with 35-1-generic-pae on maverick a1 with 4 go ram

Joshua R. Poulson (jrp) wrote :

Another system with 4GB of memory (Lenovo Thinkpad W510):

Jun 6 20:57:26 bigthink kernel: [ 4.392338] ureadahead invoked oom-killer: gfp_mask=0xd0, order=0, oom_adj=0
Jun 6 20:57:26 bigthink kernel: [ 4.392342] ureadahead cpuset=/ mems_allowed=0
Jun 6 20:57:26 bigthink kernel: [ 4.392345] Pid: 474, comm: ureadahead Tainted: G W 2.6.32-22-generic-pae #36-Ubuntu
Jun 6 20:57:26 bigthink kernel: [ 4.392346] Call Trace:
Jun 6 20:57:26 bigthink kernel: [ 4.392352] [<c01d4d34>] oom_kill_process+0xa4/0x2b0
Jun 6 20:57:26 bigthink kernel: [ 4.392355] [<c01d53a9>] ? select_bad_process+0xa9/0xe0
Jun 6 20:57:26 bigthink kernel: [ 4.392357] [<c01d5431>] __out_of_memory+0x51/0xa0
Jun 6 20:57:26 bigthink kernel: [ 4.392359] [<c01d54d8>] out_of_memory+0x58/0xb0
Jun 6 20:57:26 bigthink kernel: [ 4.392361] [<c01d7d17>] __alloc_pages_slowpath+0x407/0x4a0
Jun 6 20:57:26 bigthink kernel: [ 4.392364] [<c01d7eea>] __alloc_pages_nodemask+0x13a/0x170
Jun 6 20:57:26 bigthink kernel: [ 4.392366] [<c01d7f3c>] __get_free_pages+0x1c/0x30
Jun 6 20:57:26 bigthink kernel: [ 4.392369] [<c01b5a5a>] ring_buffer_resize+0x18a/0x2a0
Jun 6 20:57:26 bigthink kernel: [ 4.392371] [<c01b7035>] tracing_resize_ring_buffer+0x25/0x80
Jun 6 20:57:26 bigthink kernel: [ 4.392374] [<c01bad92>] tracing_entries_write+0xe2/0x160
Jun 6 20:57:26 bigthink kernel: [ 4.392376] [<c01ba5a7>] ? trace_nowake_buffer_unlock_commit+0x37/0x50
Jun 6 20:57:26 bigthink kernel: [ 4.392379] [<c02fe3b4>] ? security_file_permission+0x14/0x20
Jun 6 20:57:26 bigthink kernel: [ 4.392383] [<c0211984>] ? rw_verify_area+0x64/0xe0
Jun 6 20:57:26 bigthink kernel: [ 4.392385] [<c0211aa2>] vfs_write+0xa2/0x1a0
Jun 6 20:57:26 bigthink kernel: [ 4.392387] [<c01bacb0>] ? tracing_entries_write+0x0/0x160
Jun 6 20:57:26 bigthink kernel: [ 4.392390] [<c02123c2>] sys_write+0x42/0x70
Jun 6 20:57:26 bigthink kernel: [ 4.392392] [<c0109763>] sysenter_do_call+0x12/0x28

psychaos (goatrancer) wrote :

uname -r
2.6.35-2-generic-pae

[ 7.973371] Out of memory: kill process 375 (ureadahead) score 37 or a child
[ 7.973373] Killed process 375 (ureadahead) vsz:2372kB, anon-rss:132kB, file-rss:560kB
[ 7.975277] ureadahead: page allocation failure. order:0, mode:0xd0
[ 7.975278] Pid: 375, comm: ureadahead Not tainted 2.6.35-2-generic-pae #3-Ubuntu
[ 7.975280] Call Trace:
[ 7.975287] [<c05f2121>] ? printk+0x2d/0x34
[ 7.975292] [<c01e904a>] __alloc_pages_slowpath+0x47a/0x4b0
[ 7.975295] [<c01e91ef>] __alloc_pages_nodemask+0x16f/0x1c0
[ 7.975299] [<c01e925c>] __get_free_pages+0x1c/0x30
[ 7.975302] [<c01c0947>] ring_buffer_resize+0x1b7/0x390
[ 7.975306] [<c01c2107>] tracing_resize_ring_buffer+0x37/0x80
[ 7.975309] [<c01c5f82>] tracing_entries_write+0xe2/0x160
[ 7.975312] [<c01c56f7>] ? trace_nowake_buffer_unlock_commit+0x37/0x50
[ 7.975316] [<c030e3b4>] ? security_file_permission+0x14/0x20
[ 7.975320] [<c02235b4>] ? rw_verify_area+0x64/0xe0
[ 7.975323] [<c02236d2>] vfs_write+0xa2/0x1a0
[ 7.975326] [<c01c5ea0>] ? tracing_entries_write+0x0/0x160
[ 7.975329] [<c0223fb2>] sys_write+0x42/0x70
[ 7.975332] [<c0109463>] sysenter_do_call+0x12/0x28

Any news?

Also seen on a 2GB machine with the server kernel.

Note that you can do an:

    apt-get --purge remove ureadahead

as a workaround, with largely no ill effects, if you aren't relying on any of its functionality directly.

This will remove the meta-package ubuntu-minimal, so once this bug is fixed, you can do

    apt-get install ubuntu-minimal

to get back ureadahead and the meta package at the same time

k3lt01 (keltoiboy) wrote :

If you take a look at the forums you will notice that there are alot of threads where I have recommended this for low RAM systems. The last time ureadahead was on my laptop it took over 2 hours to get anywhere after a reprofile. I just automatically remove it on low RAM systems now because of this.

Bryan Wu (cooloney) wrote :

We got a very critical issue on an Intel machine with 4 cores and 8 threads CPUs. Since we got 4G RAM, we are using 32bits -pae kernel. ureadahead will try to get 128M trace buffer percpu, so it will allocate 128M * 8 = 1G RAM. Normally it will be killed by OOM, but system cann't boot at all mostly.

After it killed ureadahead, it hangs there. Kernel is still alive, since I can use SysRq magic key to get some information. It seems like it is waiting for something but never continue.

After totally disabling the ureadahead, we got system booting and working properly.

Bob Blanchard (blabj) wrote :
Download full text (5.4 KiB)

I have a 12 GB system with 2 quad-core Xeons running with lucid 32-bit PAE kernel, and am getting this as well.

[ 13.068253] ureadahead invoked oom-killer: gfp_mask=0xd0, order=0, oom_adj=0
[ 13.068348] ureadahead cpuset=/ mems_allowed=0
[ 13.068433] Pid: 434, comm: ureadahead Not tainted 2.6.32-24-generic-pae #39-Ubuntu
[ 13.068542] Call Trace:
[ 13.068626] [<c01d5714>] oom_kill_process+0xa4/0x2b0
[ 13.068712] [<c01d5d89>] ? select_bad_process+0xa9/0xe0
[ 13.068800] [<c01d5e11>] __out_of_memory+0x51/0xa0
[ 13.068883] [<c01d5eb8>] out_of_memory+0x58/0xb0
[ 13.068969] [<c01d86f7>] __alloc_pages_slowpath+0x407/0x4a0
[ 13.069057] [<c01d88ca>] __alloc_pages_nodemask+0x13a/0x170
[ 13.069143] [<c01d891c>] __get_free_pages+0x1c/0x30
[ 13.069227] [<c01b643a>] ring_buffer_resize+0x18a/0x2a0
[ 13.069313] [<c01b7a15>] tracing_resize_ring_buffer+0x25/0x80
[ 13.069402] [<c01bb772>] tracing_entries_write+0xe2/0x160
[ 13.069485] [<c01baf87>] ? trace_nowake_buffer_unlock_commit+0x37/0x50
[ 13.069573] [<c02ff724>] ? security_file_permission+0x14/0x20
[ 13.069659] [<c02123b4>] ? rw_verify_area+0x64/0xe0
[ 13.069743] [<c05b3347>] ? unlock_kernel+0x27/0x30
[ 13.069828] [<c02124d2>] vfs_write+0xa2/0x1a0
[ 13.069911] [<c035e7c9>] ? copy_to_user+0x39/0x130
[ 13.069994] [<c01bb690>] ? tracing_entries_write+0x0/0x160
[ 13.070078] [<c0212df2>] sys_write+0x42/0x70
[ 13.070161] [<c0109763>] sysenter_do_call+0x12/0x28
[ 13.070243] Mem-Info:
[ 13.070322] DMA per-cpu:
[ 13.070459] CPU 0: hi: 0, btch: 1 usd: 0
[ 13.070542] CPU 1: hi: 0, btch: 1 usd: 0
[ 13.070623] CPU 2: hi: 0, btch: 1 usd: 0
[ 13.070705] CPU 3: hi: 0, btch: 1 usd: 0
[ 13.070786] CPU 4: hi: 0, btch: 1 usd: 0
[ 13.070870] CPU 5: hi: 0, btch: 1 usd: 0
[ 13.070951] CPU 6: hi: 0, btch: 1 usd: 0
[ 13.071032] CPU 7: hi: 0, btch: 1 usd: 0
[ 13.071114] Normal per-cpu:
[ 13.071192] CPU 0: hi: 186, btch: 31 usd: 176
[ 13.071274] CPU 1: hi: 186, btch: 31 usd: 178
[ 13.071359] CPU 2: hi: 186, btch: 31 usd: 76
[ 13.071442] CPU 3: hi: 186, btch: 31 usd: 118
[ 13.071524] CPU 4: hi: 186, btch: 31 usd: 135
[ 13.071609] CPU 5: hi: 186, btch: 31 usd: 184
[ 13.071692] CPU 6: hi: 186, btch: 31 usd: 172
[ 13.071773] CPU 7: hi: 186, btch: 31 usd: 90
[ 13.071854] HighMem per-cpu:
[ 13.071932] CPU 0: hi: 186, btch: 31 usd: 172
[ 13.072014] CPU 1: hi: 186, btch: 31 usd: 159
[ 13.072096] CPU 2: hi: 186, btch: 31 usd: 166
[ 13.072177] CPU 3: hi: 186, btch: 31 usd: 166
[ 13.072259] CPU 4: hi: 186, btch: 31 usd: 40
[ 13.072343] CPU 5: hi: 186, btch: 31 usd: 107
[ 13.072426] CPU 6: hi: 186, btch: 31 usd: 185
[ 13.072510] CPU 7: hi: 186, btch: 31 usd: 42
[ 13.072593] active_anon:204 inactive_anon:96 isolated_anon:0
[ 13.072593] active_file:122 inactive_file:618 isolated_file:0
[ 13.072594] unevictable:0 dirty:0 writeback:0 unstable:0
[ 13.072595] free:2914842 slab_reclaimable:404 slab_unreclaimable:5300
[ 13.072596] mapped:335 shmem:52 pagetabl...

Read more...

Bob Blanchard (blabj) wrote :

An easy way to disable ureadahead without uninstalling is to just move /etc/init/ureadahead* someplace else. eg. "mv /etc/init/ureadahead* /root"

Tim Gardner (timg-tpi) on 2010-08-13
Changed in ureadahead (Ubuntu):
assignee: nobody → Tim Gardner (timg-tpi)
status: Triaged → In Progress
Tim Gardner (timg-tpi) wrote :

Bryan - please try ureadahead 0.100.0-4.1.3 in my PPA at 'deb http://ppa.launchpad.net/timg-tpi/ppa/ubuntu lucid main'. This version divides buffer_size_kb by the number of CPUs so that the total allocation does not exceed 128000.

Bryan Wu (cooloney) wrote :

Tim,

Thanks, I will try it on our testing machine.

-Bryan

Good news here.

I had the same issue as described by Bryan in comment #14 on my Sony VPCF11C5E: Core i7 4 GB, the system cannot boot most of the times unless /sbin/ureadahead is removed.

Now it works with ureadahead 0.100.0-4.1.3 from timg-tpi PPA.

Thanks,
stefano

Bob Blanchard (blabj) wrote :

This fix works for me as well. Thanks Tim.

Chris Van Hoof (vanhoof) on 2010-08-16
Changed in hwe-somerville:
assignee: nobody → Bryan Wu (cooloney)
importance: Undecided → High
status: New → In Progress
Tim Gardner (timg-tpi) wrote :

Scott - how can I tell if the trace buffers are not big enough? Is there some indication of overflow, or do you just get inadequate readahead?

lavinog (lavinog) wrote :

http://alinux.tv/Kernel-2.6.34/trace/mmiotrace.txt

Check that mmiotrace did not lose events due to a buffer filling up. Either
$ grep -i lost mydump.txt
which tells you exactly how many events were lost, or use
$ dmesg
to view your kernel log and look for "mmiotrace has lost events" warning. If
events were lost, the trace is incomplete. You should enlarge the buffers and
try again. Buffers are enlarged by first seeing how large the current buffers
are:
$ cat /sys/kernel/debug/tracing/buffer_size_kb
gives you a number. Approximately double this number and write it back, for
instance:
$ echo 128000 > /sys/kernel/debug/tracing/buffer_size_kb
Then start again from the top.

tags: added: patch
Bryan Wu (cooloney) wrote :

Tim,

We tested on our buggy machine, this patch fixes that issue. Thanks a lot.

Just one question, if the /proc filesystem is not ready before ureadahead, how can we get the right CPU numbers of a system.

-Bryan

Tim Gardner (timg-tpi) wrote :

Bryan - Have you checked for "mmiotrace has lost events" in dmesg according to comment #23 ? As for /proc getting mounted before ureadahead starts, I assume upstart is in charge of prioritizing those actions.

Bryan Wu (cooloney) wrote :

Tim,

The testing machine is occupied by other team. As long as we got the machine, I will check that mmiotrace warning.

But according to comment #23, it seems like that we cannot make sure 128M is enough for every machine, right? IMHO, kernel is supposed to know such requirement, userspace application such as ureadahead is not easy to set a right buffer size for every machine.

-Bryan

Tim Gardner (timg-tpi) wrote :

SRU Justification

Impact: ureadahead can cause the kernel to allocate too much RAM for tracing on a hyper-threaded system.
Symptoms vary, but can result in an unbootable machine.

Patch Description: Count the number of CPUs and divide the amount allocated of trace buffer by that number.
ureadahead allocates trace buffers using 'echo 128000 > /sys/kernel/debug/tracing/buffer_size_kb". Since this is a per-CPU allocation, a multi-core system can end up allocating quite a lot of RAM.

Patch: see attached

Changed in ureadahead (Ubuntu Lucid):
assignee: nobody → Tim Gardner (timg-tpi)
importance: Undecided → High
milestone: none → ubuntu-10.04.2
status: New → In Progress
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package ureadahead - 0.100.0-7

---------------
ureadahead (0.100.0-7) maverick; urgency=low

  * Count the number of CPUs and divide buffer_size_kb by the number of CPUs.
    Users should watch for instances of "mmiotrace has lost events" in dmesg to make
    sure the trace buffers are not too small. The original value for
    buffer_size_kb was chosen somewhat arbitrarily. Empirical testing
    has shown that its large enough, so we don't actually know where the lower
    boundary lies.
    -LP: #491943
 -- Tim Gardner <email address hidden> Fri, 20 Aug 2010 12:19:31 -0600

Changed in ureadahead (Ubuntu):
status: In Progress → Fix Released
Chris Van Hoof (vanhoof) on 2010-08-24
affects: hwe-somerville → null
Changed in null:
status: In Progress → Invalid
assignee: Bryan Wu (cooloney) → Chris Van Hoof (vanhoof)
Martin Pitt (pitti) wrote :

Tim,

can you please explain why the buffer should get smaller with the number of CPUs? Why are these figures related?

Tim Gardner (timg-tpi) wrote :

Martin - the value written to /sys/kernel/debug/tracing/buffer_size_kb is the amount of _contiguous_ RAM allocated for each CPU. The initial value of 128000 was somewhat arbitrary, so I decided to proceed likewise and arbitrarily divide the value by the number of CPUs. I've tried it on an Emerald class server (64 CPU) without any complaints in dmesg. It appears to have solved the issue on low RAM systems as indicated above.

Martin Pitt (pitti) wrote :

Ah, so buffer_size_kb is _per CPU_; that makes sense then, thanks!

Changed in ureadahead (Ubuntu Lucid):
status: In Progress → Fix Committed
tags: added: verification-needed

Accepted ureadahead into lucid-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

Joseph Trent (yyz-cs) wrote :

Installed ureadahead-0.100.0-4.1.3 from lucid-proposed.
oom-killer not invoked and no mmiotrace lost errors in dmesg.

Now we can reliably boot linux-image-2.6.32-24-generic-pae-2.6.32-24.42.
We had been using 2.6.32-22.36 which had allowed us to finish booting.

So, it works for us, thanks!

Martin Pitt (pitti) on 2010-09-16
tags: added: verification-done
removed: verification-needed
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package ureadahead - 0.100.0-4.1.3

---------------
ureadahead (0.100.0-4.1.3) lucid-proposed; urgency=low

  * Count the number of CPUs and divide buffer_size_kb by the number of CPUs.
    Users should watch for instances of "mmiotrace has lost events" in dmesg to make
    sure the trace buffers are not too small. The original value for
    buffer_size_kb was chosen somewhat arbitrarily. Empirical testing
    has shown that its large enough, so we don't actually know where the lower
    boundary lies.
    -LP: #491943
 -- Tim Gardner <email address hidden> Fri, 13 Aug 2010 12:44:12 -0700

Changed in ureadahead (Ubuntu Lucid):
status: Fix Committed → Fix Released
Curtis Hovey (sinzui) on 2011-11-11
no longer affects: null
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Bug attachments