[Bug 1458014] Re: audit_printk_skb slowing down boot
pito, it'd probably be best to head to https://askubuntu.com/ or #ubuntu on irc.freenode.net to try to figure out where exactly your slow performance is coming from. Install the systemd-bootchart package, then at grub's kernel command line, add init=/lib/systemd/systemd-bootchart Attach the stripchart to the bug report. Thanks -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
Similarly here with even longer delay: [ 30.704627] aufs 4.15-20180219 [ 146.736081] kauditd_printk_skb: 5 callbacks suppressed -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
thx, for your time Johansen. -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
** Changed in: apparmor (Ubuntu) Importance: Undecided => Low -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
Alessio, so from the boot chart I am not able to say what is causing the delay. What I do see is a large gap in activity for both the cpu and i/o. That gap lines up roughly with the start of pulse audio, but that doesn't necessarily make it the culprit. We then get a large gap of little to no activity and then what looks like the user sessions starting up, another pulse daemon, notify osd, compiz, nautilus, ... So it looks to me like there is something waiting, and then timing out, the question is what. The apparmor logging you are seeing is largely an artifact of policy being loaded piece meal. Apparmor actually does at least some of its load during second 4 of your boot (look for apparmor_parser), the load around 34s appears to be a secondary load initiated by cups, which is being started, and it is ensuring its policy is loaded. -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
Sorry for late, here the bootchart... ** Attachment added: "godisadj-trusty-20160330-1.png" https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+attachment/4616671/+files/godisadj-trusty-20160330-1.png -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
Robin, you do indeed have a painfully slow boot, but the audit_skb_entries in your logs are, like the others here, just the last thing the kernel happened to log. The AppArmor processes in your boot take ~1.6 seconds (if I've estimated them correctly), most of which appears to be spent asleep waiting on IO. Even if we could cut the AppArmor time in half (we can't, btw) it wouldn't even come close to denting your boot up time -- while those tasks are running your system is busy doing disk IO. Thanks -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
Hello I am tracking this bug as a very bemused sufferer. Please see attached bootchart from my system - hope it helps. ** Attachment added: "mopsie-trusty-20160301-1.png" https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+attachment/4585443/+files/mopsie-trusty-20160301-1.png -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
Alessio, please attach bootcharts to allow better investigating the isssue. Thanks. -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
Status changed to 'Confirmed' because the bug affects multiple users. ** Changed in: apparmor (Ubuntu) Status: New => Confirmed -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
I confirm this bug, still alive... ... [5.995186] vboxdrv: Found 4 processor cores. [5.995409] vboxdrv: fAsync=0 offMin=0x3de offMax=0x1b0c [5.995486] vboxdrv: TSC mode is 'synchronous', kernel timer mode is 'normal'. [5.995488] vboxdrv: Successfully loaded version 4.3.34 (interface 0x001a000b). [6.042370] init: plymouth-upstart-bridge main process ended, respawning [6.050689] init: plymouth-upstart-bridge main process (1274) terminated with status 1 [6.050708] init: plymouth-upstart-bridge main process ended, respawning [6.207649] vboxpci: IOMMU not found (not registered) [6.278948] init: plymouth-stop pre-start process (1344) terminated with status 1 [ 34.573827] audit_printk_skb: 153 callbacks suppressed [ 34.573832] type=1400 audit(1453101557.556:62): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/lib/cups/backend/cups-pdf" pid=2344 comm="apparmor_parser" [ 34.573842] type=1400 audit(1453101557.556:63): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/sbin/cupsd" pid=2344 comm="apparmor_parser" [ 34.574413] type=1400 audit(1453101557.560:64): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/sbin/cupsd" pid=2344 comm="apparmor_parser" [ 37.117995] e1000e: eth0 NIC Link is Up 10 Mbps Full Duplex, Flow Control: None [ 37.118003] e1000e :00:19.0 eth0: 10/100 speed: disabling TSO [ 37.118055] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
You will find attached a sample bootchart. ** Attachment added: "x-trusty-20150801-1.png" https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+attachment/4437539/+files/x-trusty-20150801-1.png -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
I will look into bootcharts as soon as possible. I was expecting more info from the log of step #6. You will recall that rate limiting gave the following kind of output: [ 17.062400] init: plymouth-upstart-bridge main process ended, respawning [ 42.218430] audit_printk_skb: 177 callbacks suppressed When /etc/sysctl.d/99-printk_ratelimiting.conf with kernel.printk_ratelimit=0 was implemented, I expected detail on those callbacks. Instead, I got: [ 17.530175] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 19.396738] init: plymouth-upstart-bridge main process ended, respawning [ 44.236269] type=1400 audit(1437703237.706:71): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/lib/cups/backend/cups-pdf" pid=2413 comm="apparmor_parser" What happened between 19 secs and 44 secs? Remember, this is a fast 4 core machine. I would appreciate your thoughts on that? Then we can look at bootcharts. Thanks. ** Changed in: apparmor (Ubuntu) Status: Incomplete => New -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
[ 15.940712] vboxdrv: Successfully loaded version 4.3.10_Ubuntu (interface 0x001a0007). [ 14.431291] vboxdrv: Successfully loaded version 4.3.10_Ubuntu (interface 0x001a0007). Drawing conclusions from only two tests may be asking for trouble, but it looks like you've experienced 1.5 seconds of difference in the first few seconds of the system's boot. This large of a difference seems worth investigating further. If you've got the time and inclination, please generate some detailed bootcharts: https://wiki.ubuntu.com/BootCharting Thanks ** Changed in: apparmor (Ubuntu) Status: New => Incomplete -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
I have added /etc/sysctl.d/99-printk_ratelimiting.conf with kernel.printk_ratelimit=0 and rebooted. Then I removed the file and rebooted yet again. Each time I captured the last few lines of dmesg | less The log is attached. Could you please explain the first log output (kernel.printk_ratelimit=0) and the time lag. Thanks. ** Attachment added: "99-log-dmesg-less" https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+attachment/4433367/+files/99-log-dmesg-less ** Changed in: apparmor (Ubuntu) Status: Incomplete => New -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
You're not seeing what has happened in the meantime because of printk rate limiting, as evidenced by "[ 41.489482] audit_printk_skb: 159 callbacks suppressed". To stop rate limiting kernel printk output, temporarily add a file in /etc/sysctl.d/ named something like 99-printk_ratelimiting.conf (the suffix is the important part of the name) that contains: kernel.printk_ratelimit=0 and then reboot. This will let you see the audit messages that the kernel is dropping due to rate limiting. ** Changed in: apparmor (Ubuntu) Status: Confirmed => Incomplete -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
Status changed to 'Confirmed' because the bug affects multiple users. ** Changed in: apparmor (Ubuntu) Status: New => Confirmed -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
Here are the outputs of 2 consecutive boots for dmesg | less, they both indicate 26 "lost" CPU seconds: [ 12.580984] vboxdrv: Successfully loaded version 4.3.10_Ubuntu (interface 0x001a0007). [ 12.593834] vboxpci: IOMMU not found (not registered) [ 13.307547] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 13.307807] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 13.671770] r8169 :04:00.0 eth0: link down [ 13.671790] r8169 :04:00.0 eth0: link down [ 13.671819] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 13.672126] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 15.219548] r8169 :04:00.0 eth0: link up [ 15.219570] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 15.687163] init: plymouth-upstart-bridge main process ended, respawning [ 41.953317] audit_printk_skb: 177 callbacks suppressed [ 41.953319] type=1400 audit(1432326862.429:71): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/lib/cups/backend/cups-pdf" pid=2677 comm="apparmor_parser" [ 41.953324] type=1400 audit(1432326862.429:72): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/sbin/cupsd" pid=2677 comm="apparmor_parser" [ 41.953664] type=1400 audit(1432326862.429:73): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/sbin/cupsd" pid=2677 comm="apparmor_parser" (END) [ 12.716182] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 12.861751] vboxdrv: module verification failed: signature and/or required key missing - tainting kernel [ 12.864483] vboxdrv: Found 4 processor cores. [ 12.864950] vboxdrv: fAsync=0 offMin=0x214 offMax=0x1658 [ 12.865004] vboxdrv: TSC mode is 'synchronous', kernel timer mode is 'normal'. [ 12.865006] vboxdrv: Successfully loaded version 4.3.10_Ubuntu (interface 0x001a0007). [ 12.878317] vboxpci: IOMMU not found (not registered) [ 14.374026] r8169 :04:00.0 eth0: link up [ 14.374033] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 15.556422] init: plymouth-upstart-bridge main process ended, respawning [ 41.489482] audit_printk_skb: 159 callbacks suppressed [ 41.489484] type=1400 audit(1432327140.961:65): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/lib/cups/backend/cups-pdf" pid=2788 comm="apparmor_parser" [ 41.489489] type=1400 audit(1432327140.961:66): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/sbin/cupsd" pid=2788 comm="apparmor_parser" [ 41.489832] type=1400 audit(1432327140.961:67): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/sbin/cupsd" pid=2788 comm="apparmor_parser" (END) The PC is a Dell Inspiron 660 Core i5-3330 quad core (physical, not virtual) all running at 3GHz. 26 "lost" CPU seconds on this machine is a long time. Is this ok? -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1458014] Re: audit_printk_skb slowing down boot
It's highly unlikely that the audit_printk_skb() function is itself slowing down your boot; it is designed to operate with extremely low overhead, and the ratelimiting that is in effect here means that the slowest portion of the function, actually writing characters to the system log, is skipped entirely. Probably what is actually slow is recompiling AppArmor policies; this is an extremely computational heavy task that has been subject to extensive optimization. We're planning further caching efforts in the future to reduce the number of times that the policies must be recomputed. Chances are quite good a second reboot, immediately after this one, would run faster, since the profiles would probably not need to be rebuilt immediately. Thanks -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1458014 Title: audit_printk_skb slowing down boot To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1458014/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
