Kernel trace buffer should be cleared and size restored after profiling

Same issue here with normal up-to-date Karmic.
I was trying to trigger a re-profiling and ran
  ureadahead --force-trace
The memory usage increased immediately and was never released. I only realized afterwards that this wasn't the good approach for doing what I wanted, and removed merely the pack. After next reboot, memory was high, get never free'd after some time but another reboot later all was normal.
It seems I've understood why sometimes a huge amount of my 1Go memory was eaten... the strange thing is this memory doesn't show in any monitor like top etc.

This is insidious. I was wondering where 500MB of my memory went, and ps, top, etc, didn't report who stole it. I upgraded some packages to make sure it wasn't a memory leak and rebooted.

Unfortunately the package upgrade either invalidated the ureadahead pack, or reset it or something, because after a fresh reboot with just GDM running, free looked like this:

             total used free shared buffers cached
Mem: 2016984 761844 1255110 0 988 144416
-/+ buffers/cache: 607580 1409404
Swap: 2104472 0 2104472

Upgrading to Karmic proposed packages did *not* fix this. Rebooting twice in a row without logging in, did. Now I guess Ubuntu is worse than Windows in this respect, since it takes *two* consecutive reboots to fix a problematic system instead of one. I'm tempted to just remove ureadahead and call it a day.

Removing ureadahead didn't have much effect for me, though subsequent boots following its removal did feel a lot faster. Running Google Chrome, Pidgin, and Gnome (with Tracker in the background) takes up 670 MB. I don't think this has to do with ureadahead.

I found a few forum threads that seem to be about the same problem but haven't realized it's caused by ureadahead yet:
http://ubuntuforums.org/showthread.php?p=8641459
http://swiss.ubuntuforums.org/showthread.php?p=8643666

I'm observing the same thing at work (64-bit) and at home (32-bit). Even when I drop to single user mode with no processes running and unload all kernel modules, the memory usage is still about 300 MB and no indication where the memory is used. Very frustrating.

Since I don't reboot often it took me weeks to make the connection to ureadahead.

Since the used memory doesn't seem to belong to a process, and ureadahead requires the kernel to be patched, it seems that the issue might be in the kernel patch.
Is there any information on what the patch is, or where to get the source?

Hello people, it seems to me that this bug and bug 499773 are related.

In other word: when ureadahead does its retrace thing on boot, I see BOTH symptoms:

- the memory usage is very high

- the /var/lib/ureadahead/debugfs entry not removed from /etc/mtab

For a normal boot, when ureadahead retracing is not triggered, everything is normal.

I see the debugfs mount also. Maybe it is related.
I think this is also related to many users stability issues.
If this doesn't get fixed, I would recommend disabling ureadahead for Lucid.

It could be a bug in the kernel too.

I noticed that the first lines of dumping the pack file show the size of the pack which is pretty close to the size of the missing memory:

Fri Jan 22 10:22:38 CST 2010
             total used free shared buffers cached
Mem: 1021768 444560 577208 0 22568 106268
-/+ buffers/cache: 315724 706044
Swap: 329292 0 329292
-----------------
Fri Jan 22 10:58:27 CST 2010
             total used free shared buffers cached
Mem: 1021768 344036 677732 0 37752 119860
-/+ buffers/cache: 186424 835344
Swap: 329292 0 329292
/var/lib/ureadahead/pack: created Fri, 22 Jan 2010 16:23:23 +0000 for hdd 8:1
16 inode groups, 1819 files, 1793 blocks (114844 kB)

315724-186424=129300

I am not getting anymore segfaults in X when I remove the pack file. (this is a lucid test machine so there were many updates since then.)

In response to Davide Dente at comment #7 :

Just got a reprofiling, and of course my memory usage is higher than usual.
The debugfs DID appear in df :
none debugfs 18G 12G 4,8G 72% /var/lib/ureadahead/debugfs

So I tried to unmount it :
$ sudo umount /var/lib/ureadahead/debugfs
umount: /var/lib/ureadahead/debugfs: n'est pas monté (french of "is not mounted")

But after some time (say 20 min), the debugfs disappeared! But no memory were released.
Bugs seem disconnected to me though, now...

This may need to fall under another bug report:
Today I booted into recovery mode to recover some data from a failed drive, then resumed the normal boot into a console. I then moved a large number of files from one drive to another. During the transfer I thought that the system was acting sluggish so I switched to console 2 and started htop. Htop showed that all of my memory (4g) was in use and my swap was pretty much full (994/996M.)

using df I saw that /var/lib/ureadahead/debugfs was listed so apparently ureadahead was profiling my actions while in single user mode.

Maybe ureadahead should not run in single mode.

I suspect this memory is, as discussed above, the tracing memory in the kernel rather than that used by ureadahead itself

I wrote my observations about the memory usage here: http://ubuntuforums.org/showpost.php?p=9012493&postcount=55
I can confirm this phenomenon in both karmic and lucid.

I have the same problem with kubuntu lucid beta1.

The only measure for me to reduce this high memory usage, is always starting with an empty session and remove ureadahead.

Normally I like intelligent memory usage, but it´s not funny when my system will be slower and slower when it begins to swaping.

Just found out about /sys/kernel/debug/tracing/buffer_size_kb
It reads 128000 on my vm which is currently showing about 322M (tracing on) 182M (tracing off) diff=140M so it looks like it is the tracing buffer.

Some questions:
1. Why is it that no application can differentiate memory used by the tracing buffer...it just looks like missing memory to everything. Is this because the tracing feature of the kernel is still new?

2. What determines the tracing buffer size? Is this a preset value?
3. Is there a way to determine how much of the tracing buffer is getting used?

Being that the minimum memory requirement for Xubuntu is 256M and 384M for Ubuntu...does it seem wise to use half of the memory for boot optimization?

Maybe a temporary fix could be to have ureadahead do nothing on systems with less than 512M of memory. Systems with this restriction would likely be old and too slow for a user to care about boot speeds anyway...especially if using ureadahead is causing the system to swap.

I am curious if ureadahead would still work if the tracing buffer size was something like 32M. 32M would be small enough for users to ignore. I don't know a lot about how tracing works, but it might be nice to have a kernel option to set the buffer size, or even control tracing.

Would like to hear a little feedback on this from the devs, why is this still in Lucid, with an impending release. Just spend half a day debugging my machine which was down to a crawl thanks to this, luckily someone on the forums heard about this bug.

It was mentioned in this thread: http://ubuntuforums.org/showthread.php?t=1434502
that once online profiling is implemented, this issue will go away.

I am wondering if a bug needs to be filed for the kernel because there is nothing to indicate that the memory is being used for tracing memory. Using tools like ps just shows that memory isn't being accounted for.

I see 128000 kb was hardcoded into the source of ureadahead. I also see in mmiotrace.txt where this is used as an example:
-------------------
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.
-------------------

The size of the trace buffer actually used can be determined with
wc -c /sys/kernel/debug/tracing/trace
(The size will be in bytes)
So far I have seen sizes range from 2-30Mb
I have yet to check some of my larger systems, but it seems possible that 128M could be necessary in some cases.

...
I have found a hackish solution for recovering the memory after the profile.

First ensure the profile is complete (it waits a while even after you log in) by checking that the pack files exist. You should also check that they are somewhat recent too since I don't know if a reprofile triggered by age will remove these files.
You can then recover the memory by reducing the buffer size:
echo 2048|sudo tee /sys/kernel/debug/tracing/buffer_size_kb

2048 was just an arbitrary size. You can use 1 if you really want to save memory.

I do not know of the consequences of resizing the buffer afterwards, but it seems to work fine.

@Scott: Could you provide some feedback if this is a reasonable solution for the time being?

Thanks god someone else noticed this high memory usage. I kept asking people on #ubuntu+1 and all I got was: "This is normal for Linux". This high caching memory usage would be normal, if my system didn't start using the swap file once the RAM memory gets used by the caching memory. I never noticed this problem in Karmic, probably because I did a clean install and used the vanilla kernels from http://kernel.ubuntu.com/~kernel-ppa/mainline/ in the last 4 or 5 months. Previously (in Karmic) "Reclaim memory" function in Ailurus would reclaim almost all of the caching memory, but now it fails to do that. Something is eating the memory.

This is how my computer behaves:
I have 2GiB of Ram installed
System monitor reports that 38% of the Memory is used by programs, 62% of Memory is in use as cash, and I have for instance 160MiB used from the swap space (and once the swap is being used, the system erformance is hit seriously).
If I try: sudo swapoff -a , the swapoff process dies and the swap partition is not disabled. Why? Because there is not enough RAM memory available to transfer the data contained into the swap partition. But how can this be when 62% of it is "free"? 62% of 2GiB of ram is a lot more than 160MiB. I even tried uninstalling ureadahead but that doesn't help. So I'm not sure that the problem is strictly located in ureadahead.

@Petar: I don't think this bug is your issue if uninstalling ureadahead didn't help.

i had this issue on one one laptop

00:00.0 Host bridge: Intel Corporation Mobile 945GM/PM/GMS, 943/940GML and 945GT Express Memory Controller Hub (rev 03)
00:01.0 PCI bridge: Intel Corporation Mobile 945GM/PM/GMS, 943/940GML and 945GT Express PCI Express Root Port (rev 03)
00:1b.0 Audio device: Intel Corporation N10/ICH 7 Family High Definition Audio Controller (rev 02)
00:1c.0 PCI bridge: Intel Corporation N10/ICH 7 Family PCI Express Port 1 (rev 02)
00:1c.1 PCI bridge: Intel Corporation N10/ICH 7 Family PCI Express Port 2 (rev 02)
00:1c.2 PCI bridge: Intel Corporation N10/ICH 7 Family PCI Express Port 3 (rev 02)
00:1d.0 USB Controller: Intel Corporation N10/ICH7 Family USB UHCI Controller #1 (rev 02)
00:1d.1 USB Controller: Intel Corporation N10/ICH 7 Family USB UHCI Controller #2 (rev 02)
00:1d.2 USB Controller: Intel Corporation N10/ICH 7 Family USB UHCI Controller #3 (rev 02)
00:1d.3 USB Controller: Intel Corporation N10/ICH 7 Family USB UHCI Controller #4 (rev 02)
00:1d.7 USB Controller: Intel Corporation N10/ICH 7 Family USB2 EHCI Controller (rev 02)
00:1e.0 PCI bridge: Intel Corporation 82801 Mobile PCI Bridge (rev e2)
00:1f.0 ISA bridge: Intel Corporation 82801GHM (ICH7-M DH) LPC Interface Bridge (rev 02)
00:1f.1 IDE interface: Intel Corporation 82801G (ICH7 Family) IDE Controller (rev 02)
00:1f.2 RAID bus controller: Intel Corporation 82801GHM (ICH7-M DH) SATA RAID Controller (rev 02)
00:1f.3 SMBus: Intel Corporation N10/ICH 7 Family SMBus Controller (rev 02)
01:00.0 VGA compatible controller: nVidia Corporation G71 [GeForce Go 7900 GTX] (rev a1)
02:00.0 Network controller: Intel Corporation PRO/Wireless 3945ABG [Golan] Network Connection (rev 02)
06:07.0 CardBus bridge: Texas Instruments PCIxx12 Cardbus Controller
06:07.1 FireWire (IEEE 1394): Texas Instruments PCIxx12 OHCI Compliant IEEE 1394 Host Controller
06:07.2 Mass storage controller: Texas Instruments 5-in-1 Multimedia Card Reader (SD/MMC/MS/MS PRO/xD)
06:07.3 SD Host controller: Texas Instruments PCIxx12 SDA Standard Compliant SD Host Controller
06:0b.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL-8169 Gigabit Ethernet (rev 10)

I fixed it by removing ureadahead and my ram usage dropped from 800 megs at start to 400 megs.

This didn't occur on my other lucid systems.

I am experiencing the same problem as Petar, after several hours the swap file starts to get heavily used despite free showing less than half my memory being used by applications and having vm.swappiness=0. I have 2G of RAM and 2.5G of swap, and the system behaves normally up until the swap partition starts to get used at which point the system becomes almost unusable. Attempting sudo swapoff -a fails for me as well.

I have the same problem about very high ram and swap usage, and the system becoming very slow. But removing ureadahead and using the Karmic 2.6.31-20 kernel didn't help, so ureadahead is not the problem in my system.
For this other problem maybe bug 560859 is better.

If it shows that you still have free memory (ram) then this probably isn't the right bug for you.

I also want to point out that this bug only happens on a reprofile so if you're having high memory consumption all the time then that's another indicator that something else is wrong.

Yes :) that is why I said that bug 560859 is better to discuses that. Richard Luther, Petar Velkovski and others may be interested in that bug also.

Any updates on this issue??

I know an extra 100-200mb used is nothing to those with systems with several gbs in them... But many of us use Ubuntu on lowend/modest systems.

~120mb burnt for nothing is 50% of my meager 256mb available on my laptop. For us, this bug is a show stopper.

Seems strange that this was allowed to make it into Lucid. Ureadahead is great - hopefully this can be fixed with an update.

Keybuk mentionned in the forums on March 20th that a fix for this bug was pending next week. Any updates on that?

@james79: if the issue is that you are low on memory, you can release the trace buffer with:
echo 1|sudo tee /sys/kernel/debug/tracing/buffer_size_kb

I wrote a init script that does this automatically after a trace. I can clean it up and post it if it will help.

If the issue is that you run out of memory during boot, your only option is to disable ureadahead. Ureadahead is only useful if you have the memory for caching the files.

I suspect fixing this bug would be counter productive if the goal is to change the way tracing is accomplished.

Thanks lavinog for that info.

This immediately cleared up about 250MB of lost memory for me. Usually my server uses about 60MB but now and then after a reboot it will use 315MB and I can't find where it's gone. Dropping caches didn't help.

This bug doesn't appear to be taken seriously. Perhaps it needs to be filed in a better place where the right devs will see it?

I can confirm that this bug is present on my newly created Lucid 10.4 server install and that the above echo command will fix it.

I am sure it is taken seriously. The dev is likely tending to more important issues at the moment.
The issue isn't a security issue, and it doesn't seem to cause any data loss.

lavinog you sound like one of the creators of Windows Vista. :) I'm sorry, but as a long time Linux user, I'm somehow spoiled by the idea/reassurance that my OS is not eating parts of my RAM if there are no objective reasons for it do so. I agree that security issues and data loss problems are extremely important, but fixing a loss of 250MB of RAM is equally important for me.

@Petar: I replied to your comment at this thread: http://ubuntuforums.org/showthread.php?t=1363165
I do not think this bug is related to your issue. I would like to help you figure out what is going on, but not here.

To everyone else: The cause of the bug is known. Maybe Scott can give us some insight on when or how it will be addressed, but the forums might be a better place for discussions.

lavinog, I'm commenting this bug. The other HUGE memory leak problem I was having, and thought that was connected to this bug, was confirmed and fixed (it was bug #565981).

I posted a upstart script that can recover the memory used after a profile:
http://ubuntuforums.org/showpost.php?p=9271524&postcount=9

Hi lavinog

Thanks for the proposed fix. It does appear to work, but I'm worried about unintended consequences. I can't install OSs with such bugs and hacked workarounds in them.

It's a shame because Lucid seems like an otherwise fine release but for the time being I'm going to have to stick to Karmic.

Hopefully it will be fixed shortly.

This bug exists in karmic also.

Probably - however, it's not installed by default on Karmic. At least not when doing a minimal install like I do.

I'm getting this. From mount.
none on /var/lib/ureadahead/debugfs type debugfs (rw,relatime)

However is it related to high memory usage on boot up.

With just firefox and a terminal I'm getting this.
free -m
             total used free shared buffers cached
Mem: 2009 1034 974 0 37 295
-/+ buffers/cache: 701 1307
Swap: 1906 0 1906

This is Lucid 64bit clean install.

Update rebooted and found the /var/lib//ureadahead/debugfs not mounted. Memory steady at 500 meg after 1 hour. Using firefox, evolution and terminal.

status ureadahead
ureadahead stop/waiting

mount
/dev/sda1 on / type ext4 (rw,errors=remount-ro)
proc on /proc type proc (rw,noexec,nosuid,nodev)
none on /sys type sysfs (rw,noexec,nosuid,nodev)
none on /sys/fs/fuse/connections type fusectl (rw)
none on /sys/kernel/debug type debugfs (rw)
none on /sys/kernel/security type securityfs (rw)
none on /dev type devtmpfs (rw,mode=0755)
none on /dev/pts type devpts (rw,noexec,nosuid,gid=5,mode=0620)
none on /dev/shm type tmpfs (rw,nosuid,nodev)
none on /var/run type tmpfs (rw,nosuid,mode=0755)
none on /var/lock type tmpfs (rw,noexec,nosuid,nodev)
none on /lib/init/rw type tmpfs (rw,nosuid,mode=0755)
/dev/sda3 on /home type ext4 (rw)
binfmt_misc on /proc/sys/fs/binfmt_misc type binfmt_misc (rw,noexec,nosuid,nodev)
gvfs-fuse-daemon on /home/philcb/.gvfs type fuse.gvfs-fuse-daemon (rw,nosuid,nodev,user=philcb)

SRU Justification

Impact: Low memory platforms suffer OOM crashes because of memory exhaustion

Patch Description: Read the initial value of buffer_size_kb and restore on exit.

Patch: attached

This patch has been reported by Bryan Wu to have fixed an issue on an ARM OEM platform.
This bug cause some real issues on low memory ARM platforms.

Patch looks good. ACK from SRU team.

Accepted 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!

For us using -proposed, it would be nice if the SRU changelogs would be a bit more descriptive so we have an idea of what changes can be expected. Something like "Fixes kernel memory leak when reprofiling" in this case. BTW this changelog missed the "#" in the bug number so it did not get linkified in Update Manager. Thanks.

Scott says this is wrong, I'll let him elaborate.

I've asked pitti to reject this upload.

The patch is wrong; it restores the buffer size before using any of the contents of the buffer, which will either truncate it or clear it entirely. The effect would be the same as simply never increasing the size in the first place - or worse, making all profiles come out with no files.

As per Scott's request I removed this SRU, since it severely regresses ureadahead to the point where it entirely stops working.

2010-07-14 14:23:16 INFO Removing candidates:
2010-07-14 14:23:16 INFO ureadahead 0.100.0-4.1.1 in lucid amd64
2010-07-14 14:23:16 INFO ureadahead 0.100.0-4.1.1 in lucid armel
2010-07-14 14:23:16 INFO ureadahead 0.100.0-4.1.1 in lucid i386
2010-07-14 14:23:16 INFO ureadahead 0.100.0-4.1.1 in lucid ia64
2010-07-14 14:23:16 INFO ureadahead 0.100.0-4.1.1 in lucid powerpc
2010-07-14 14:23:16 INFO ureadahead 0.100.0-4.1.1 in lucid sparc
2010-07-14 14:23:16 INFO Removed-by: Martin Pitt
2010-07-14 14:23:16 INFO Comment: SRU regression
2010-07-14 14:23:16 INFO 6 packages successfully removed.

Noted, how about this patch:

SRU Justification:

Impact: Low memory platforms suffer OOM crashes because of memory exhaustion

Patch Description: Read the initial value of buffer_size_kb and restore on exit.

Patch: http://launchpadlibrarian.net/51934423/trace.txt

This patch has been reported by Bryan Wu to have fixed an issue on an ARM OEM platform.
This bug cause some real issues on low memory ARM platforms.

Scott Remnant has also concurred that the patch is correct this time.

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!

Ureadahead is not creating pack files now.

$ cat /sys/kernel/debug/tracing/buffer_size_kb
128000

$ cat /sys/kernel/debug/tracing/buffer_size_kb
1408

$ ls /var/lib/ureadahead/
debugfs

I was using a custom version before, the proposed patch should have overwritten it though.
Can someone else confirm that the patch is not creating pack files?

Package: ureadahead
State: installed
Automatically installed: no
Version: 0.100.0-4.1.1

lavinog, you must upgrade to 0.100.0-4.1.2. It creates the pack here.

I think I'm receiving a similar bug where I supposedly have 0 swap space left, then get a plymouthd OoM error, then ureadaheadd OoM error.

Linux ubuntu 2.6.35-8-generic-pae #13-Ubuntu SMP Wed Jul 14 04:40:11 UTC 2010 i686 GNU/Linux

ureadahead:
  Installed: 0.100.0-5

plymouth:
  Installed: 0.8.2-2ubuntu3

Tested the ureadahead deb on r2d2/c3po-amd Dell systems. The systems had X07 bios on the system. This issue was fixed with this deb package with the X07 bios. http://us.archive.ubuntu.com/ubuntu/pool/main/u/ureadahead/ureadahead_0.100.0-4.1.2_i386.deb package works

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

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

  * Restore buffer_size_kb upon exit, but do it _after_
    the trace buffer has been read. This frees the memory
    consumed by the trace operation (which can be a lot).
    -LP: #501715
 -- Tim Gardner <email address hidden> Thu, 22 Jul 2010 04:04:36 -0600

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

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

  * Restore buffer_size_kb upon exit, but do it _after_
    the trace buffer has been read. This frees the memory
    consumed by the trace operation (which can be a lot).
    -LP: #501715
 -- Tim Gardner <email address hidden> Wed, 14 Jul 2010 11:00:54 -0600