Ubuntu
linux package

Triggers permanent high i/o load after upgrade

Bug #549428 reported by Loïc Minier on 2010-03-27

This bug report is a duplicate of: Bug #565981: [KMS] gem objects not deallocated. Edit Remove

This bug affects 3 people

Affects		Status	Importance	Assigned to	Milestone
	linux (Ubuntu)	Invalid	Undecided	Unassigned

Bug Description

Binary package hint: apparmor

So this is the second time this happens after an upgrade of my laptop: i run a package upgrade using aptitude, and when it's done, some background I/O is happening after completion. This I/O never ends. The first time this happened was on 2010/03/09 after my morning upgrade; list of packages upgraded from aptitude.log:
mar., mars 9 2010 10:32:47 +0100

IMPORTANT : ce journal ne contient que les actions demandées ; certaines actions qui
échouent à cause d'erreurs de dpkg peuvent donc ne pas être réalisées.

90 paquets vont être installés, et 2 retirés.
893ko d'espace disque vont être utilisés
===============================================================================
[SUPPRIMÉ, NON UTILISÉ] libparted-2.1-0
[SUPPRIMÉ, NON UTILISÉ] libparted1.8-12
[INSTALLÉ, DÉPENDANCES] libaio1
[INSTALLÉ, DÉPENDANCES] libparted0
[MIS A JOUR] apparmor 2.5~pre+bzr1364-0ubuntu1 -> 2.5~pre+bzr1367-0ubuntu1
[MIS A JOUR] apparmor-utils 2.5~pre+bzr1364-0ubuntu1 -> 2.5~pre+bzr1367-0ubuntu1
[MIS A JOUR] apturl 0.4.1ubuntu2 -> 0.4.1ubuntu3
[MIS A JOUR] apturl-common 0.4.1ubuntu2 -> 0.4.1ubuntu3
[MIS A JOUR] at-spi 1.29.90-0ubuntu2 -> 1.29.92-0ubuntu1
[MIS A JOUR] binutils 2.20.1-1ubuntu1 -> 2.20.1-2ubuntu1
[MIS A JOUR] binutils-doc 2.20.1-1ubuntu1 -> 2.20.1-2ubuntu1
[MIS A JOUR] binutils-static 2.20.1-1ubuntu1 -> 2.20.1-2ubuntu1
[MIS A JOUR] empathy 2.29.91.2-0ubuntu1 -> 2.29.91.2-0ubuntu2
[MIS A JOUR] empathy-common 2.29.91.2-0ubuntu1 -> 2.29.91.2-0ubuntu2
[MIS A JOUR] euca2ools 1.2-0ubuntu5 -> 1.2-0ubuntu6
[MIS A JOUR] evince 2.29.91-0ubuntu1 -> 2.29.91-0ubuntu2
[MIS A JOUR] firefox 3.6+nobinonly-0ubuntu5 -> 3.6+nobinonly-0ubuntu6
[MIS A JOUR] firefox-branding 3.6+nobinonly-0ubuntu5 -> 3.6+nobinonly-0ubuntu6
[MIS A JOUR] firefox-gnome-support 3.6+nobinonly-0ubuntu5 -> 3.6+nobinonly-0ubuntu6
[MIS A JOUR] gbrainy 1.30-1ubuntu5 -> 1.40-1ubuntu1
[MIS A JOUR] gcalctool 5.29.92~20100301.2-0ubuntu1 -> 5.29.92-0ubuntu1
[MIS A JOUR] gnome-about 1:2.29.91-0ubuntu1 -> 1:2.29.92-0ubuntu1
[MIS A JOUR] gnome-accessibility-themes 2.29.91-0ubuntu1 -> 2.29.92-0ubuntu1
[MIS A JOUR] gnome-desktop-data 1:2.29.91-0ubuntu1 -> 1:2.29.92-0ubuntu1
[MIS A JOUR] gnome-menus 2.29.91-0ubuntu2 -> 2.29.92-0ubuntu2
[MIS A JOUR] gnome-themes-selected 2.29.91-0ubuntu1 -> 2.29.92-0ubuntu1
[MIS A JOUR] gstreamer0.10-alsa 0.10.26.3-1 -> 0.10.27-1
[MIS A JOUR] gstreamer0.10-ffmpeg 0.10.9.3-1 -> 0.10.10-1
[MIS A JOUR] gstreamer0.10-gnomevfs 0.10.26.3-1 -> 0.10.27-1
[MIS A JOUR] gstreamer0.10-plugins-base 0.10.26.3-1 -> 0.10.27-1
[MIS A JOUR] gstreamer0.10-plugins-base-apps 0.10.26.3-1 -> 0.10.27-1
[MIS A JOUR] gstreamer0.10-plugins-ugly 0.10.13.3-1 -> 0.10.14-1
[MIS A JOUR] gstreamer0.10-tools 0.10.26.3-1 -> 0.10.27-1
[MIS A JOUR] gstreamer0.10-x 0.10.26.3-1 -> 0.10.27-1
[MIS A JOUR] gvfs 1.5.4-0ubuntu1 -> 1.5.5-0ubuntu1
[MIS A JOUR] gvfs-backends 1.5.4-0ubuntu1 -> 1.5.5-0ubuntu1
[MIS A JOUR] gvfs-bin 1.5.4-0ubuntu1 -> 1.5.5-0ubuntu1
[MIS A JOUR] gvfs-fuse 1.5.4-0ubuntu1 -> 1.5.5-0ubuntu1
[MIS A JOUR] humanity-icon-theme 0.5.1.2 -> 0.5.1.3
[MIS A JOUR] libapparmor-perl 2.5~pre+bzr1364-0ubuntu1 -> 2.5~pre+bzr1367-0ubuntu1
[MIS A JOUR] libapparmor1 2.5~pre+bzr1364-0ubuntu1 -> 2.5~pre+bzr1367-0ubuntu1
[MIS A JOUR] libatk1.0-0 1.29.4-0ubuntu1 -> 1.29.92-0ubuntu1
[MIS A JOUR] libatk1.0-data 1.29.4-0ubuntu1 -> 1.29.92-0ubuntu1
[MIS A JOUR] libatk1.0-doc 1.29.4-0ubuntu1 -> 1.29.92-0ubuntu1
[MIS A JOUR] libatspi1.0-0 1.29.90-0ubuntu2 -> 1.29.92-0ubuntu1
[MIS A JOUR] libcap2 1:2.17-2 -> 1:2.17-2ubuntu1
[MIS A JOUR] libcap2-bin 1:2.17-2 -> 1:2.17-2ubuntu1
[MIS A JOUR] libevdocument2 2.29.91-0ubuntu1 -> 2.29.91-0ubuntu2
[MIS A JOUR] libevview2 2.29.91-0ubuntu1 -> 2.29.91-0ubuntu2
[MIS A JOUR] libglib2.0-0 2.23.4-1ubuntu1 -> 2.23.4-1ubuntu2
[MIS A JOUR] libglib2.0-data 2.23.4-1ubuntu1 -> 2.23.4-1ubuntu2
[MIS A JOUR] libglib2.0-dev 2.23.4-1ubuntu1 -> 2.23.4-1ubuntu2
[MIS A JOUR] libglib2.0-doc 2.23.4-1ubuntu1 -> 2.23.4-1ubuntu2
[MIS A JOUR] libgnome-desktop-2-17 1:2.29.91-0ubuntu1 -> 1:2.29.92-0ubuntu1
[MIS A JOUR] libgnome-menu2 2.29.91-0ubuntu2 -> 2.29.92-0ubuntu2
[MIS A JOUR] libgstreamer-plugins-base0.10-0 0.10.26.3-1 -> 0.10.27-1
[MIS A JOUR] libgstreamer0.10-0 0.10.26.3-1 -> 0.10.27-1
[MIS A JOUR] libgvfscommon0 1.5.4-0ubuntu1 -> 1.5.5-0ubuntu1
[MIS A JOUR] libnautilus-extension1 1:2.29.91-0ubuntu2 -> 1:2.29.92-0ubuntu1
[MIS A JOUR] libsmbclient 2:3.4.6~dfsg-1ubuntu1 -> 2:3.4.6~dfsg-1ubuntu2
[MIS A JOUR] libtaglib2.0-cil 2.0.3.4+dfsg-2 -> 2.0.3.6+dfsg-1
[MIS A JOUR] libvirt-bin 0.7.5-5ubuntu10 -> 0.7.5-5ubuntu12
[MIS A JOUR] libvirt0 0.7.5-5ubuntu10 -> 0.7.5-5ubuntu12
[MIS A JOUR] libwbclient0 2:3.4.6~dfsg-1ubuntu1 -> 2:3.4.6~dfsg-1ubuntu2
[MIS A JOUR] nautilus 1:2.29.91-0ubuntu2 -> 1:2.29.92-0ubuntu1
[MIS A JOUR] nautilus-data 1:2.29.91-0ubuntu2 -> 1:2.29.92-0ubuntu1
[MIS A JOUR] openssh-client 1:5.3p1-3ubuntu2 -> 1:5.3p1-3ubuntu3
[MIS A JOUR] openssh-server 1:5.3p1-3ubuntu2 -> 1:5.3p1-3ubuntu3
[MIS A JOUR] parted 2.1-4ubuntu1 -> 2.2-1ubuntu2
[MIS A JOUR] pidgin-libnotify 0.14-1ubuntu13 -> 0.14-1ubuntu14
[MIS A JOUR] python-gmenu 2.29.91-0ubuntu2 -> 2.29.92-0ubuntu2
[MIS A JOUR] python-gtkspell 2.25.3-4.1ubuntu1 -> 2.25.3-4.1ubuntu2
[MIS A JOUR] python-libvirt 0.7.5-5ubuntu10 -> 0.7.5-5ubuntu12
[MIS A JOUR] python-pyatspi 1.29.90-0ubuntu2 -> 1.29.92-0ubuntu1
[MIS A JOUR] qemu-arm-static 0.12.3-0ubuntu10 -> 0.12.3-0ubuntu11
[MIS A JOUR] qemu-kvm 0.12.3-0ubuntu10 -> 0.12.3-0ubuntu11
[MIS A JOUR] qemu-kvm-extras 0.12.3-0ubuntu10 -> 0.12.3-0ubuntu11
[MIS A JOUR] qemu-kvm-extras-static 0.12.3-0ubuntu10 -> 0.12.3-0ubuntu11
[MIS A JOUR] samba-common 2:3.4.6~dfsg-1ubuntu1 -> 2:3.4.6~dfsg-1ubuntu2
[MIS A JOUR] samba-common-bin 2:3.4.6~dfsg-1ubuntu1 -> 2:3.4.6~dfsg-1ubuntu2
[MIS A JOUR] simple-scan 0.9.6-1ubuntu1 -> 0.9.7-0ubuntu1
[MIS A JOUR] smbclient 2:3.4.6~dfsg-1ubuntu1 -> 2:3.4.6~dfsg-1ubuntu2
[MIS A JOUR] ssh-askpass-gnome 1:5.3p1-3ubuntu2 -> 1:5.3p1-3ubuntu3
[MIS A JOUR] telepathy-haze 0.3.3-1 -> 0.3.4-1
[MIS A JOUR] udisks 1.0.0~git20100227.36c8a4-1 -> 1.0.0~git20100305.fa313b2-1ubuntu1
[MIS A JOUR] update-manager 1:0.132.1 -> 1:0.133
[MIS A JOUR] update-manager-core 1:0.132.1 -> 1:0.133
[MIS A JOUR] vim 2:7.2.245-2ubuntu3 -> 2:7.2.330-1ubuntu2
[MIS A JOUR] vim-common 2:7.2.245-2ubuntu3 -> 2:7.2.330-1ubuntu2
[MIS A JOUR] vim-runtime 2:7.2.245-2ubuntu3 -> 2:7.2.330-1ubuntu2
[MIS A JOUR] vim-tiny 2:7.2.245-2ubuntu3 -> 2:7.2.330-1ubuntu2
[MIS A JOUR] watershed 4build1 -> 5
===============================================================================

I couldn't find the source of the I/O in top or iotop; either it was in the kernel or it was spread on many processes.
I asked for some help diagnosing it on irc:
11:47 < lool> Something is adding massive load to my laptop since the latest upgrade
11:47 < lool> I can't figure out what it is; I see one of my CPU is busy in kernel space
11:47 < lool> iotop shows nothing (nor top obviously)
11:48 < lool> I have a long list of console-kit processes though

I ended up rebooting.

This happened yesterday evening again; much shorter upgrade log:
ven., mars 26 2010 23:36:36 +0100

IMPORTANT : ce journal ne contient que les actions demandées ; certaines actions qui
échouent à cause d'erreurs de dpkg peuvent donc ne pas être réalisées.

41 paquets vont être installés, et 1 retirés.
1 122ko d'espace disque vont être utilisés
===============================================================================
[SUPPRIMÉ, NON UTILISÉ] libntfs-3g54
[INSTALLÉ, DÉPENDANCES] libntfs-3g75
[MIS A JOUR] apparmor 2.5-0ubuntu1 -> 2.5-0ubuntu2
[MIS A JOUR] apparmor-utils 2.5-0ubuntu1 -> 2.5-0ubuntu2
[MIS A JOUR] apt 0.7.25.3ubuntu3 -> 0.7.25.3ubuntu4
[MIS A JOUR] apt-transport-https 0.7.25.3ubuntu3 -> 0.7.25.3ubuntu4
[MIS A JOUR] apt-utils 0.7.25.3ubuntu3 -> 0.7.25.3ubuntu4
[MIS A JOUR] apt-xapian-index 0.22 -> 0.25
[MIS A JOUR] capplets-data 1:2.29.92-0ubuntu2 -> 1:2.29.92-0ubuntu3
[MIS A JOUR] console-setup 1.34ubuntu12 -> 1.34ubuntu13
[MIS A JOUR] gnome-control-center 1:2.29.92-0ubuntu2 -> 1:2.29.92-0ubuntu3
[MIS A JOUR] gnome-power-manager 2.29.91-0ubuntu8 -> 2.29.91-0ubuntu9
[MIS A JOUR] indicator-session 0.2.7-0ubuntu2 -> 0.2.7-0ubuntu3
[MIS A JOUR] initramfs-tools 0.92bubuntu69 -> 0.92bubuntu71
[MIS A JOUR] initramfs-tools-bin 0.92bubuntu69 -> 0.92bubuntu71
[MIS A JOUR] jockey-common 0.5.8-0ubuntu3 -> 0.5.8-0ubuntu5
[MIS A JOUR] jockey-gtk 0.5.8-0ubuntu3 -> 0.5.8-0ubuntu5
[MIS A JOUR] language-selector 0.5.3 -> 0.5.4
[MIS A JOUR] language-selector-common 0.5.3 -> 0.5.4
[MIS A JOUR] libapparmor-perl 2.5-0ubuntu1 -> 2.5-0ubuntu2
[MIS A JOUR] libapparmor1 2.5-0ubuntu1 -> 2.5-0ubuntu2
[MIS A JOUR] libgnome-window-settings1 1:2.29.92-0ubuntu2 -> 1:2.29.92-0ubuntu3
[MIS A JOUR] libssl0.9.8 0.9.8k-7ubuntu6 -> 0.9.8k-7ubuntu7
[MIS A JOUR] light-themes 0.1.5.9 -> 0.1.6.0
[MIS A JOUR] ntfs-3g 1:2009.4.4-1ubuntu5 -> 1:2010.3.6-1ubuntu1
[MIS A JOUR] openssl 0.9.8k-7ubuntu6 -> 0.9.8k-7ubuntu7
[MIS A JOUR] python-cupshelpers 1.1.17+20100217-0ubuntu6 -> 1.1.17+20100217-0ubuntu9
[MIS A JOUR] python-distutils-extra 2.18 -> 2.18bzr1
[MIS A JOUR] python-software-properties 0.75.7 -> 0.75.8
[MIS A JOUR] python-twisted-bin 9.0.0-1 -> 10.0.0-2
[MIS A JOUR] python-twisted-core 9.0.0-1 -> 10.0.0-2
[MIS A JOUR] python-twisted-names 9.0.0-1 -> 10.0.0-1
[MIS A JOUR] python-twisted-web 9.0.0-1 -> 10.0.0-1
[MIS A JOUR] python-xkit 0.4.2 -> 0.4.2.1
[MIS A JOUR] software-properties-gtk 0.75.7 -> 0.75.8
[MIS A JOUR] sudo 1.7.2p1-1ubuntu3 -> 1.7.2p1-1ubuntu4
[MIS A JOUR] synaptic 0.63.1ubuntu1 -> 0.63.1ubuntu2
[MIS A JOUR] system-config-printer-common 1.1.17+20100217-0ubuntu6 -> 1.1.17+20100217-0ubuntu9
[MIS A JOUR] system-config-printer-gnome 1.1.17+20100217-0ubuntu6 -> 1.1.17+20100217-0ubuntu9
[MIS A JOUR] system-config-printer-udev 1.1.17+20100217-0ubuntu6 -> 1.1.17+20100217-0ubuntu7
[MIS A JOUR] ubuntu-mono 0.0.10 -> 0.0.11
[MIS A JOUR] valgrind 1:3.6.0~svn20100212-0ubuntu3 -> 1:3.6.0~svn20100212-0ubuntu4
===============================================================================

Since apparmor appears in both and probably impacts kernel-ish stuff too, I figured it could be the culprit, and hence I'm filing the bug here.

I couldn't find anything in syslog, kernel.log, dmesg (just the regular spam I get from other bugs).

I left my computer running all night, this morning I/O was still happening at a high rate (my disk activity LED was blinking fast as if doing lots of small I/O, my sysmon applet showed load and 100% CPU used in the system for one of my CPUs).

The next time this happens, I'll try echo-ing to /proc/sys/vm/block_dump to see where I/O is happening, but I wanted to report the bug as it seems like a serious one. I don't see anything special in my setup which would trigger this, it's quite boring. I have my /home on ecryptfs and am using LVM. The disk is a 120 GB SSD, so should have gone through any global file scan over night.

I couldn't reproduce the bug by dpkg-reconfiguring *apparmor*, jockey*, *ntfs*, apt-xapian-index nor by reinstalling them.

Bye,

ProblemType: Bug
ApparmorStatusOutput:
Error: command /usr/sbin/apparmor_status failed with exit code 4: You do not have enough privilege to read the profile set.
apparmor module is loaded.
Architecture: amd64
Date: Sat Mar 27 10:46:05 2010
DistroRelease: Ubuntu 10.04
Package: apparmor 2.5-0ubuntu2
ProcEnviron:
LANGUAGE=fr_FR:fr:en_GB:en
PATH=(custom, user)
LANG=fr_FR.UTF-8
SHELL=/bin/zsh
ProcVersionSignature: Ubuntu 2.6.32-17.26-generic 2.6.32.10+drm33.1
SourcePackage: apparmor
Uname: Linux 2.6.32-17-generic x86_64

Tags:

Related branches

lp://staging/ubuntu/lucid/linux-mvl-dove

lp://staging/ubuntu/lucid/linux-ec2

Revision history for this message

Loïc Minier (lool) wrote on 2010-03-27:

ApparmorPackages.txt Edit (267 bytes, text/plain; charset="utf-8")
Dependencies.txt Edit (1.2 KiB, text/plain; charset="utf-8")
KernLog.txt Edit (16.3 KiB, text/plain; charset="utf-8")
PstreeP.txt Edit (10.4 KiB, text/plain; charset="utf-8")

Revision history for this message

John Johansen (jjohansen) wrote on 2010-03-27:

Loïc,

are you using auditd? If so can you attach output for /var/log/audit/audit.log
Also if you run into this again can you attach the output of aa_status.

Revision history for this message

Loïc Minier (lool) wrote on 2010-03-27:

I don't have any /var/log/audit*; I'll check aa_status next time this happens, thanks for the advice

Revision history for this message

Loïc Minier (lool) wrote on 2010-03-27:

Actually aa_status isn't on my system, is it still relevant

Revision history for this message

John Johansen (jjohansen) wrote on 2010-03-27:

Yes, it is part of the apparmor-utils package so it isn't a required part of the default install, you will need to run it as root to be able to collect as much information as possible. All the information collected by aa-status is available manually (its just raw in a raw form) if you don't want to or can't install apparmor-utils. via.
> sudo cat /sys/kernel/security/apparmor/profiles
> sudo ps auxZ

Another package you might consider installing is apparmor-notify which will give you gui notifications when apparmor is blocking access. If you do install it see man aa-notify for information on how to turn it on, as there is currently a bug where it isn't turned on by default when it is installed.

Revision history for this message

petdog (petdog) wrote on 2010-03-31:

Download full text (7.4 KiB)

I've seen this behaviour at least five times in the last month too; it probably happens when there's an apparmor upgrade. Both the cpu cores are in wait mode, the load average skyrockets to ~25 and the system becomes unusable. With some patience I usually switch to tty, login as root and kill some random stuff. Usually killing networkmanager and nm-applet brings things back to normal. One time I fixed it rmmod-ing and reloading 'iwlagn'.
Here's some junk from `dmesg` that probably explains it:

I've seen this behaviour at least five times in the last month too; it probably happens when there's an apparmor upgrade. Both the cpu cores are in wait mode, the load average skyrockets to ~25 and the system becomes unusable. With some patience  I usually switch to tty, login as root and kill some random stuff. Usually killing networkmanager and nm-applet brings things back to normal. One time I fixed it rmmod-ing and reloading 'iwlagn'.
Here's some junk from `dmesg` that probably explains it:

[1138553.650102] udev: starting version 151
[1138562.167699] type=1505 audit(1270041415.954:56):  operation="profile_replace" pid=26791 name="/usr/share/gdm/guest-session/Xsession"
[1138562.177594] type=1505 audit(1270041415.964:57):  operation="profile_replace" pid=26792 name="/sbin/dhclient3"
[1138562.179275] type=1505 audit(1270041415.964:58):  operation="profile_replace" pid=26792 name="/usr/lib/NetworkManager/nm-dhcp-client.action"
[1138562.180189] type=1505 audit(1270041415.974:59):  operation="profile_replace" pid=26792 name="/usr/lib/connman/scripts/dhclient-script"
[1138562.401339] apparmor_parser: page allocation failure. order:8, mode:0x40d0
[1138562.401349] Pid: 26793, comm: apparmor_parser Not tainted 2.6.32-16-generic #25-Ubuntu
[1138562.401356] Call Trace:
[1138562.401376]  [<ffffffff810f742e>] __alloc_pages_slowpath+0x56e/0x580
[1138562.401386]  [<ffffffff810f759e>] __alloc_pages_nodemask+0x15e/0x1a0
[1138562.401397]  [<ffffffff8112a3d7>] alloc_pages_current+0x87/0xd0
[1138562.401405]  [<ffffffff810f64ae>] __get_free_pages+0xe/0x50
[1138562.401413]  [<ffffffff81133c4b>] __kmalloc+0x14b/0x1d0
[1138562.401426]  [<ffffffff81279a62>] kvmalloc+0x22/0x40
[1138562.401434]  [<ffffffff81279aee>] aa_simple_write_to_buffer+0x6e/0x140
[1138562.401446]  [<ffffffff810397c9>] ? default_spin_lock_flags+0x9/0x10
[1138562.401454]  [<ffffffff81279c41>] aa_profile_replace+0x21/0x60
[1138562.401464]  [<ffffffff811400b8>] vfs_write+0xb8/0x1a0
[1138562.401472]  [<ffffffff81140951>] sys_write+0x51/0x80
[1138562.401483]  [<ffffffff810131f2>] system_call_fastpath+0x16/0x1b
[1138562.401488] Mem-Info:
[1138562.401492] Node 0 DMA per-cpu:
[1138562.401499] CPU    0: hi:    0, btch:   1 usd:   0
[1138562.401504] CPU    1: hi:    0, btch:   1 usd:   0
[1138562.401508] Node 0 DMA32 per-cpu:
[1138562.401514] CPU    0: hi:  186, btch:  31 usd:   0
[1138562.401520] CPU    1: hi:  186, btch:  31 usd:   0
[1138562.401524] Node 0 Normal per-cpu:
[1138562.401530] CPU    0: hi:  186, btch:  31 usd:   0
[1138562.401535] CPU    1: hi:  186, btch:  31 usd:   0
[1138562.401547] active_anon:289113 inactive_anon:118219 isolated_anon:0
[1138562.401550]  active_file:160971 inactive_file:239394 isolated_file:136
[1138562.401552]  unevictable:12 dirty:1306 writeback:0 unstable:0
[1138562.401555]  free:10068 slab_reclaimable:39329 slab_unreclaimable:24299
[1138562.401557]  mapped:35072 shmem:74660 pagetables:10268 bounce:0
[1138562.401563] Node 0 DMA free:15648kB min:28kB low:32kB high:40kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:16kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15304kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:224kB slab_unreclaimable:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[1138562.401587] lowmem_reserve[]: 0 2958 3905 3905
[1138562.401599] Node 0 DMA32 free:21348kB min:6044kB low:7552kB high:9064kB active_anon:974156kB inactive_anon:263260kB active_file:572620kB inactive_file:888084kB unevictable:32kB isolated(anon):0kB isolated(file):544kB present:3029636kB mlocked:32kB dirty:5072kB writeback:0kB mapped:81636kB shmem:175948kB slab_reclaimable:141856kB slab_unreclaimable:62984kB kernel_stack:976kB pagetables:18592kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[1138562.401625] lowmem_reserve[]: 0 0 946 946
[1138562.401635] Node 0 Normal free:3276kB min:1932kB low:2412kB high:2896kB active_anon:182296kB inactive_anon:209616kB active_file:71264kB inactive_file:69476kB unevictable:16kB isolated(anon):0kB isolated(file):0kB present:969600kB mlocked:16kB dirty:152kB writeback:0kB mapped:58652kB shmem:122692kB slab_reclaimable:15236kB slab_unreclaimable:34204kB kernel_stack:2280kB pagetables:22480kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[1138562.401661] lowmem_reserve[]: 0 0 0 0
[1138562.401671] Node 0 DMA: 0*4kB 2*8kB 1*16kB 4*32kB 4*64kB 1*128kB 3*256kB 2*512kB 3*1024kB 3*2048kB 1*4096kB = 15648kB
[1138562.401696] Node 0 DMA32: 1839*4kB 293*8kB 136*16kB 220*32kB 6*64kB 2*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 21348kB
[1138562.401720] Node 0 Normal: 593*4kB 31*8kB 1*16kB 0*32kB 2*64kB 0*128kB 2*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3276kB
[1138562.401743] 475038 total pagecache pages
[1138562.401747] 0 pages in swap cache
[1138562.401753] Swap cache stats: add 54728, delete 54728, find 83949/85128
[1138562.401758] Free swap  = 0kB
[1138562.401761] Total swap = 0kB
[1138562.442506] 1032192 pages RAM
[1138562.442511] 44196 pages reserved
[1138562.442515] 442162 pages shared
[1138562.442519] 703082 pages non-shared
[1138562.444565] type=1505 audit(1270041416.235:60):  operation="profile_replace" pid=26793 name="/usr/bin/evince"
[1138562.455414] type=1505 audit(1270041416.245:61):  operation="profile_replace" pid=26793 name="/usr/bin/evince-previewer"
[1138562.459073] type=1505 audit(1270041416.245:62):  operation="profile_replace" pid=26793 name="/usr/bin/evince-thumbnailer"
[1138562.516253] type=1505 audit(1270041416.305:63):  operation="profile_load" pid=26795 name="/usr/lib/firefox-3.7a3pre/firefox{,*[^s][^h]}"
[1138600.751741] __ratelimit: 15 callbacks suppressed
[1138600.751748] type=1505 audit(1270041454.544:69):  operation="profile_replace" pid=26827 name="/usr/share/gdm/guest-session/Xsession"
[1138635.007138] type=1505 audit(1270041488.795:70):  operation="profile_replace" pid=26837 name="/sbin/dhclient3"
[1138635.007380] type=1505 audit(1270041488.795:71):  operation="profile_replace" pid=26837 name="/usr/lib/NetworkManager/nm-dhcp-client.action"
[1138635.007548] type=1505 audit(1270041488.795:72):  operation="profile_replace" pid=26837 name="/usr/lib/connman/scripts/dhclient-script"
[1138641.200432] type=1505 audit(1270041494.985:73):  operation="profile_replace" pid=26843 name="/usr/bin/evince"
[1138641.202107] type=1505 audit(1270041494.995:74):  operation="profile_replace" pid=26843 name="/usr/bin/evince-previewer"
[1138641.203564] type=1505 audit(1270041494.995:75):  operation="profile_replace" pid=26843 name="/usr/bin/evince-thumbnailer"
[1138643.522317] type=1505 audit(1270041497.314:76):  operation="profile_replace" pid=26857 name="/usr/lib/firefox-3.7a3pre/firefox{,*[^s][^h]}"
[1138645.187709] type=1505 audit(1270041498.974:77):  operation="profile_replace" pid=26863 name="/usr/lib/cups/backend/cups-pdf"
[1138645.187845] type=1505 audit(1270041498.974:78):  operation="profile_replace" pid=26863 name="/usr/sbin/cupsd"
[1138646.801729] type=1505 audit(1270041500.594:79):  operation="profile_replace" pid=26866 name="/usr/sbin/mysqld-akonadi"
[1138653.180926] type=1505 audit(1270041506.974:80):  operation="profile_replace" pid=26923 name="/usr/sbin/named"
[1138657.904154] type=1505 audit(1270041511.694:81):  operation="profile_replace" pid=26924 name="/usr/sbin/tcpdump"
[1138703.573151] type=1505 audit(1270041557.365:82):  operation="profile_remove" pid=26977 name="/usr/lib/firefox-3.7a3pre/firefox{,*[^s][^h]}" namespace="root"

Revision history for this message

Loïc Minier (lool) wrote on 2010-03-31:

The latest apparmor upgrade (2.5-0ubuntu3) didn't trigger this for me; it mentions:
  [ Kees Cook ]
  * debian/apparmor.functions: do not load in parallel, this is causing
    weird side-effects.

Changed in apparmor (Ubuntu):
status:	New → Incomplete

Revision history for this message

Kees Cook (kees) wrote on 2010-03-31:

We've seen several IO and memory pressure problems as a result of the parallel load. The true root cause is still unknown, but it seems that the parallel load makes it worse, so I've removed it for now.

John Johansen (jjohansen) on 2010-04-13

Changed in apparmor (Ubuntu):
assignee:	nobody → John Johansen (jjohansen)
status:	Incomplete → In Progress

Andy Whitcroft (apw) on 2010-04-13

Changed in apparmor (Ubuntu):
status:	In Progress → Fix Committed

Revision history for this message

Loïc Minier (lool) wrote on 2010-04-19:

So I hit this today, it looks like the same bug, but no apparmor update.

My system has permanent IO load, and all apps hit the disk hard whenever they do something.

sudo cat /sys/kernel/security/apparmor/profiles
/usr/sbin/tcpdump (enforce)
/usr/sbin/libvirtd (enforce)
/usr/sbin/cupsd (enforce)
/usr/lib/cups/backend/cups-pdf (enforce)
/usr/lib/libvirt/virt-aa-helper (enforce)
/usr/bin/evince-thumbnailer (enforce)
/usr/bin/evince-previewer (enforce)
/usr/bin/evince (enforce)
/usr/lib/connman/scripts/dhclient-script (enforce)
/usr/lib/NetworkManager/nm-dhcp-client.action (enforce)
/sbin/dhclient3 (enforce)
/usr/share/gdm/guest-session/Xsession (enforce)

aa-status reports similar output
apparmor module is loaded.
12 profiles are loaded.
12 profiles are in enforce mode.
   /sbin/dhclient3
   /usr/bin/evince
   /usr/bin/evince-previewer
   /usr/bin/evince-thumbnailer
   /usr/lib/NetworkManager/nm-dhcp-client.action
   /usr/lib/connman/scripts/dhclient-script
   /usr/lib/cups/backend/cups-pdf
   /usr/lib/libvirt/virt-aa-helper
   /usr/sbin/cupsd
   /usr/sbin/libvirtd
   /usr/sbin/tcpdump
   /usr/share/gdm/guest-session/Xsession
0 profiles are in complain mode.
3 processes have profiles defined.
3 processes are in enforce mode :
   /sbin/dhclient3 (7660)
   /usr/sbin/cupsd (1547)
   /usr/sbin/libvirtd (1331)
0 processes are in complain mode.
0 processes are unconfined but have a profile defined.

I wonder whether this is really apport; perhaps it's ecryptfs.

I did a sudo perf top, and got:
             3415.00 - 19.8% : read_hpet
             1398.00 - 8.1% : find_vma
             1151.00 - 6.7% : drm_clflush_pages [drm]
              948.00 - 5.5% : __ticket_spin_lock
              582.00 - 3.4% : rb_next
              334.00 - 1.9% : acpi_os_read_port
              290.00 - 1.7% : fget_light
              274.00 - 1.6% : page_check_address
              252.00 - 1.5% : schedule
              233.00 - 1.3% : copy_user_generic_string
              201.00 - 1.2% : kref_put
              199.00 - 1.2% : unix_poll
              182.00 - 1.1% : _spin_unlock_irqrestore
              177.00 - 1.0% : clear_page_c
              165.00 - 1.0% : kref_get

or is this drm? that sounds really heavy

So I hit this today, it looks like the same bug, but no apparmor update.

My system has permanent IO load, and all apps hit the disk hard whenever they do something.

aa-status reports similar output
apparmor module is loaded.
12 profiles are loaded.
12 profiles are in enforce mode.
   /sbin/dhclient3
   /usr/bin/evince
   /usr/bin/evince-previewer
   /usr/bin/evince-thumbnailer
   /usr/lib/NetworkManager/nm-dhcp-client.action
   /usr/lib/connman/scripts/dhclient-script
   /usr/lib/cups/backend/cups-pdf
   /usr/lib/libvirt/virt-aa-helper
   /usr/sbin/cupsd
   /usr/sbin/libvirtd
   /usr/sbin/tcpdump
   /usr/share/gdm/guest-session/Xsession
0 profiles are in complain mode.
3 processes have profiles defined.
3 processes are in enforce mode :
   /sbin/dhclient3 (7660) 
   /usr/sbin/cupsd (1547) 
   /usr/sbin/libvirtd (1331) 
0 processes are in complain mode.
0 processes are unconfined but have a profile defined.

I wonder whether this is really apport; perhaps it's ecryptfs.

I did a sudo perf top, and got:
             3415.00 - 19.8% : read_hpet
             1398.00 -  8.1% : find_vma
             1151.00 -  6.7% : drm_clflush_pages        [drm]
              948.00 -  5.5% : __ticket_spin_lock
              582.00 -  3.4% : rb_next
              334.00 -  1.9% : acpi_os_read_port
              290.00 -  1.7% : fget_light
              274.00 -  1.6% : page_check_address
              252.00 -  1.5% : schedule
              233.00 -  1.3% : copy_user_generic_string
              201.00 -  1.2% : kref_put
              199.00 -  1.2% : unix_poll
              182.00 -  1.1% : _spin_unlock_irqrestore
              177.00 -  1.0% : clear_page_c
              165.00 -  1.0% : kref_get

or is this drm?  that sounds really heavy

Revision history for this message

Kees Cook (kees) wrote on 2010-04-19: Re: [Bug 549428] Re: Triggers permanent high i/o load after upgrade

#10

> I did a sudo perf top, and got:

Try catching it with latencytop? That's how I managed to isolate my ext4
umount issues.

Revision history for this message

Loïc Minier (lool) wrote on 2010-04-19:

#11

So itseems it's some shortage of RAM somewhere:
I joined #ubuntu-kernel:
20:10 < lool> My kernel is doing stuff but I dont know what
20:10 < lool> and my machine is dying under background IO load
20:10 < lool> I tried sudo perf top, iotop, regular top, and can't tell what's
              happening
20:10 < lool> see bug #549428
20:10 < ubot3> Malone bug 549428 in apparmor "Triggers permanent high i/o load
               after upgrade" [Undecided,Fix committed]
               https://launchpad.net/bugs/549428
20:10 < lool> I get this regularly, but not daily
20:11 < lool> I will have to reboot the system pretty soon given that it's
              almost unusable now; anything I can do?
20:12 < lool> I don't know whether that's expected, but cat
              /sys/kernel/debug/dri/64/vma returns
20:12 < lool> cat: /sys/kernel/debug/dri/64/vma: Cannot allocate memory
20:13 < lool> sudo cat i915_ringbuffer_data
20:13 < lool> cat: i915_ringbuffer_data: Ne peut allouer de la mémoire
20:13 < lool> that sounds bad
20:13 < smb> At least like something went crazy requesting memory
20:14 < lool> oddly, meminfo lists plenty of cached stuff
20:14 < lool> Oh I know
20:14 < lool> So I'm using ecryptfs
20:14 < lool> and I use unison in the background
20:14 < lool> Every so many days, this starts happening
20:14 < lool> I bet it's not giving back some memory to the OS
20:14 < lool> smb: How could I track memory down?
20:15 < lool> http://paste.ubuntu.com/418779/ < meminfo
20:15 < lool> Cached: 2492220 kB
20:15 < smb> Maybe one could keep tracking memory allocation while running
20:15 < smb> apparently you cannot even look right now
20:15 < lool> smb: Well my system still runs for some rason
20:15 < lool> reason
20:15 < smb> A high cached value is normal
20:15 < lool> I suspect the background load is swapping
20:16 < lool> Except I dont have any hmm
20:16 < lool> smb: Yes, but I mean this should be reclaimable to allocate memory
20:16 < lool> smb: I would expect that if my kernel used all available mem,
              this value would be small
20:16 < lool> VmallocTotal: 34359738367 kB
20:16 < lool> VmallocChunk: 34359353372 kB
20:17 < lool> that's.... too much
20:17 < lool> I don't have 34 TB of vm
20:17 < lool> Hmm apparently that's normal
20:17 < lool> it matches another host
20:18 < lool> probably some addressable range
20:20 < smb> I would believe so
20:24 < smb> lool, The thing is that you seem to be unable to start new tasks
             which sounds like shortage of allocable memory
20:25 < lool> smb: I can actually start other tasks
20:25 < lool> Could at least
20:25 < lool> smb: I could open an xterm for instance
20:25 < lool> albeit slowly

I suspect it's ecryptfs or drm; drm because it shows up frequently in perf top, and because cat on some /sys/kernel/debug files would fail before reboot and now works fine, but that could be due to memory having been eaten by someone else.
ecryptfs could be related because I see disk activity and because this would explain the delay before this happens; I run unison over a GB of data every 5 minutes, so that would expose a memleak after a while.

So itseems it's some shortage of RAM somewhere:
I joined #ubuntu-kernel:
20:10 < lool> My kernel is doing stuff but I dont know what
20:10 < lool> and my machine is dying under background IO load
20:10 < lool> I tried sudo perf top, iotop, regular top, and can't tell what's 
              happening
20:10 < lool> see bug #549428
20:10 < ubot3> Malone bug 549428 in apparmor "Triggers permanent high i/o load 
               after upgrade" [Undecided,Fix committed] 
               https://launchpad.net/bugs/549428
20:10 < lool> I get this regularly, but not daily
20:11 < lool> I will have to reboot the system pretty soon given that it's 
              almost unusable now; anything I can do?
20:12 < lool> I don't know whether that's expected, but cat 
              /sys/kernel/debug/dri/64/vma returns
20:12 < lool> cat: /sys/kernel/debug/dri/64/vma: Cannot allocate memory
20:13 < lool> sudo cat i915_ringbuffer_data
20:13 < lool> cat: i915_ringbuffer_data: Ne peut allouer de la mémoire
20:13 < lool> that sounds bad
20:13 < smb> At least like something went crazy requesting memory
20:14 < lool> oddly, meminfo lists plenty of cached stuff
20:14 < lool> Oh I know
20:14 < lool> So I'm using ecryptfs
20:14 < lool> and I use unison in the background
20:14 < lool> Every so many days, this starts happening
20:14 < lool> I bet it's not giving back some memory to the OS
20:14 < lool> smb: How could I track memory down?
20:15 < lool> http://paste.ubuntu.com/418779/ < meminfo
20:15 < lool> Cached:          2492220 kB
20:15 < smb> Maybe one could keep tracking memory allocation while running
20:15 < smb> apparently you cannot even look right now
20:15 < lool> smb: Well my system still runs for some rason
20:15 < lool> reason
20:15 < smb> A high cached value is normal
20:15 < lool> I suspect the background load is swapping
20:16 < lool> Except I dont have any hmm
20:16 < lool> smb: Yes, but I mean this should be reclaimable to allocate memory
20:16 < lool> smb: I would expect that if my kernel used all available mem, 
              this value would be small
20:16 < lool> VmallocTotal:   34359738367 kB
20:16 < lool> VmallocChunk:   34359353372 kB
20:17 < lool> that's.... too much
20:17 < lool> I don't have 34 TB of vm
20:17 < lool> Hmm apparently that's normal
20:17 < lool> it matches another host
20:18 < lool> probably some addressable range
20:20 < smb> I would believe so
20:24 < smb> lool, The thing is that you seem to be unable to start new tasks 
             which sounds like shortage of allocable memory
20:25 < lool> smb: I can actually start other tasks
20:25 < lool> Could at least
20:25 < lool> smb: I could open an xterm for instance
20:25 < lool> albeit slowly

Revision history for this message

Loïc Minier (lool) wrote on 2010-04-21:

#12

Next time I hit this, I will try running latencytop, but I suspect I'm entering into a memory pressure situation and latencytop might show the results of the pressured system, but not the reason for the pressure :-/

Revision history for this message

Loïc Minier (lool) wrote on 2010-04-21:

#13

I'm moving this bug to linux, as I didn't see any improvements with the uploaded patches and I'm not really sure it's apparmor related anymore, or perhaps multiple issues were conflated in one.

affects:	apparmor (Ubuntu) → linux (Ubuntu)
Changed in linux (Ubuntu):
assignee:	John Johansen (jjohansen) → nobody
status:	Fix Committed → New

Revision history for this message

Dustin Kirkland  (kirkland) wrote on 2010-04-21:

#14

Tyler-

I subscribed you to this bug.

Loic is seeing an abnormally high IO load on his system, which is using eCryptfs for his $HOME. He's thinking there might be a memory leak somewhere, perhaps?

Can you offer any pointers as to how to debug this? Tools you might use to profile or instrument this sort of thing?

Revision history for this message

Loïc Minier (lool) wrote on 2010-04-21:

#15

Looks like I got hit by bug #565981; not clear how many bugs affected my system here though.

Revision history for this message

Jamie Strandboge (jdstrand) wrote on 2010-04-21:

#16

Loic, based on your comments, it is believed the remaining memory pressure issue may be bug #565981. Marking as a duplicate for now. If you find this is in error, please feel free to adjust this bug accordingly.

Changed in linux (Ubuntu):
status:	New → Invalid

Report a bug

This report contains Public information

Everyone can see this information.

Duplicate of bug #565981 Remove

You are

Subscribing...

Edit bug mail

Other bug subscribers

Bug attachments

Add attachment

Remote bug watches

Bug watches keep track of this bug in other bug trackers.

Ubuntulinux package

Triggers permanent high i/o load after upgrade

Bug Description

Related branches

Other bug subscribers

Bug attachments

Remote bug watches

Ubuntu
linux package