Kernel trace buffer should be set to less unrealistic value

Moved to Ubuntu bug tracker

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

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

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

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

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...

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

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

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

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.

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.

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...

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

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.

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

This fix works for me as well. Thanks Tim.

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?

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.

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

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.

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

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

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

Tim,

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

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.

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

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!

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!

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