brightness keys are handled slower in Yakkety than Xenial

[Colin Ian King]

I've noticed on Lenovo X220 and X230 laptops that pressing brightness keys on Yakkety seems less responsive and slower than Xenial. I ran forkstat on Xenial and just observed udev being forked off:

Xenial:
$ sudo forkstat
Time Event PID Info Duration Process
17:37:35 fork 273 parent /lib/systemd/systemd-udevd
17:37:35 fork 1977 child /lib/systemd/systemd-udevd
17:37:35 exit 1977 0 0.008 /lib/systemd/systemd-udevd

Whereas on Yakkety, there is far more activity:
Time Event PID Info Duration Process
16:35:34 fork 2626 parent update-notifier
16:35:34 fork 2645 child update-notifier
16:35:34 exec 2645 /usr/bin/python3 /usr/share/apport/apport-checkreports
16:35:34 exit 2645 256 0.221 /usr/bin/python3 /usr/share/apport/apport-checkreports
16:35:34 fork 2626 parent update-notifier
16:35:34 fork 2646 child update-notifier
16:35:34 exec 2646 /usr/bin/python3 /usr/share/apport/apport-checkreports --system
16:35:34 exit 2646 256 0.188 /usr/bin/python3 /usr/share/apport/apport-checkreports --system
16:35:36 fork 1576 parent /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 fork 2647 child /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 exec 2647 /usr/lib/unity-settings-daemon/usd-backlight-helper --get-max-brightness
16:35:36 exit 2647 0 0.008 /usr/lib/unity-settings-daemon/usd-backlight-helper --get-max-brightness
16:35:36 fork 1576 parent /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 fork 2648 child /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 exec 2648 /usr/lib/unity-settings-daemon/usd-backlight-helper --get-brightness
16:35:36 exit 2648 0 0.006 /usr/lib/unity-settings-daemon/usd-backlight-helper --get-brightness
16:35:36 fork 1576 parent /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 fork 2649 child /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 exec 2649 /usr/lib/unity-settings-daemon/usd-backlight-helper --get-brightness
16:35:36 exit 2649 0 0.007 /usr/lib/unity-settings-daemon/usd-backlight-helper --get-brightness
16:35:36 fork 1576 parent /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 fork 2650 child /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 exec 2650 /usr/lib/unity-settings-daemon/usd-backlight-helper --get-max-brightness
16:35:36 exit 2650 0 0.006 /usr/lib/unity-settings-daemon/usd-backlight-helper --get-max-brightness
16:35:36 fork 1576 parent /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 fork 2651 child /usr/lib/unity-settings-daemon/unity-settings-daemon
16:35:36 exec 2651 pkexec /usr/lib/unity-settings-daemon/usd-backlight-helper --set-brightness 2250
16:35:36 clone 2651 parent pkexec /usr/lib/unity-settings-daemon/usd-backlight-helper --set-brightness 2250
16:35:36 clone 2652 thread pkexec /usr/lib/unity-settings-daemon/usd-backlight-helper --set-brightness 2250
16:35:36 clone 2651 parent pkexec /usr/lib/unity-settings-daemon/usd-backlight-helper --set-brightness 2250
16:35:36 clone 2653 thread pkexec /usr/lib/unity-settings-daemon/usd-backlight-helper --set-brightness 2250
16:35:36 fork 1 parent /sbin/init splash
16:35:36 fork 2654 child /sbin/init splash
Time Event PID Info Duration Process
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2655 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2656 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2657 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2658 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2659 child /lib/systemd/systemd-udevd
16:35:36 exit 2659 0 0.005 /lib/systemd/systemd-udevd
16:35:36 exit 2658 0 0.006 /lib/systemd/systemd-udevd
16:35:36 exit 2657 0 0.007 /lib/systemd/systemd-udevd
16:35:36 exit 2656 0 0.008 /lib/systemd/systemd-udevd
16:35:36 exit 2655 0 0.008 /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2660 child /lib/systemd/systemd-udevd
16:35:36 exit 2660 0 0.001 /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2661 child /lib/systemd/systemd-udevd
16:35:36 exit 2661 0 0.002 /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2662 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2663 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2664 child /lib/systemd/systemd-udevd
16:35:36 fork 2654 parent /sbin/init splash
16:35:36 fork 2665 child (systemd)
16:35:36 exec 2654 /lib/systemd/systemd --user
16:35:36 exit 2662 0 0.010 /lib/systemd/systemd-udevd
16:35:36 exit 2664 0 0.007 /lib/systemd/systemd-udevd
Time Event PID Info Duration Process
16:35:36 exit 2663 0 0.009 /lib/systemd/systemd-udevd
16:35:36 fork 2654 parent /lib/systemd/systemd --user
16:35:36 fork 2666 child /lib/systemd/systemd --user
16:35:36 exit 2666 0 0.001 /lib/systemd/systemd --user
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2667 child /lib/systemd/systemd-udevd
16:35:36 exit 2667 0 0.003 /lib/systemd/systemd-udevd
16:35:36 fork 2654 parent /lib/systemd/systemd --user
16:35:36 fork 2668 child /lib/systemd/systemd --user
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2669 child /lib/systemd/systemd-udevd
16:35:36 exit 2669 0 0.002 /lib/systemd/systemd-udevd
16:35:36 exec 2668 /bin/systemctl --user set-environment DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/0/bus
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2670 child /lib/systemd/systemd-udevd
16:35:36 exit 2670 0 0.001 /lib/systemd/systemd-udevd
16:35:36 exit 2668 0 0.009 /bin/systemctl --user set-environment DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/0/bus
16:35:36 fork 2 parent [kthreadd]
16:35:36 fork 2671 child [kworker/u16:4]
16:35:36 exec 2671 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/[e-mail]/dbus.socket]
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2672 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2673 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2674 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2675 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2676 child /lib/systemd/systemd-udevd
16:35:36 exit 2671 0 0.005 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/[e-mail]/dbus.socket]
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
Time Event PID Info Duration Process
16:35:36 fork 2677 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2678 child /lib/systemd/systemd-udevd
16:35:36 exit 2653 0 0.126 pkexec /usr/lib/unity-settings-daemon/usd-backlight-helper --set-brightness 2250
16:35:36 exit 2652 0 0.126 pkexec /usr/lib/unity-settings-daemon/usd-backlight-helper --set-brightness 2250
16:35:36 exec 2651 /usr/lib/unity-settings-daemon/usd-backlight-helper --set-brightness 2250
16:35:36 exit 2673 0 0.013 /lib/systemd/systemd-udevd
16:35:36 exit 2672 0 0.013 /lib/systemd/systemd-udevd
16:35:36 exit 2678 0 0.011 /lib/systemd/systemd-udevd
16:35:36 exit 2675 0 0.013 /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2679 child /lib/systemd/systemd-udevd
16:35:36 exit 2674 0 0.020 /lib/systemd/systemd-udevd
16:35:36 exit 2651 0 0.146 /usr/lib/unity-settings-daemon/usd-backlight-helper --set-brightness 2250
16:35:36 fork 2 parent [kthreadd]
16:35:36 fork 2680 child [kworker/u16:5]
16:35:36 exec 2680 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/session-2.scope]
16:35:36 exit 2676 0 0.022 /lib/systemd/systemd-udevd
16:35:36 exit 2679 0 0.003 /lib/systemd/systemd-udevd
16:35:36 exit 2677 0 0.022 /lib/systemd/systemd-udevd
16:35:36 exit 2680 0 0.003 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/session-2.scope]
16:35:36 fork 2654 parent /lib/systemd/systemd --user
16:35:36 fork 2681 child /lib/systemd/systemd --user
16:35:36 exec 2681 /bin/kill -s 58 2654
16:35:36 exit 2681 0 0.200 /bin/kill -s 58 2654
16:35:36 fork 2 parent [kthreadd]
16:35:36 fork 2682 child [kworker/u16:5]
16:35:36 exec 2682 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/[e-mail]/systemd-exit.service]
16:35:36 exit 2654 0 0.294 /lib/systemd/systemd --user
16:35:36 exit 2682 0 0.004 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/[e-mail]/systemd-exit.service]
16:35:36 exit 2665 9 0.272 (systemd)
16:35:36 fork 2 parent [kthreadd]
Time Event PID Info Duration Process
16:35:36 fork 2683 child [kworker/u16:5]
16:35:36 exec 2683 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/[e-mail]/init.scope]
16:35:36 fork 2 parent [kthreadd]
16:35:36 fork 2684 child [kworker/u16:4]
16:35:36 fork 2 parent [kthreadd]
16:35:36 fork 2685 child [systemd-cgroups]
16:35:36 exec 2684 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/[e-mail]]
16:35:36 exec 2685 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice]
16:35:36 exit 2683 0 0.005 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/[e-mail]/init.scope]
16:35:36 exit 2685 0 0.005 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice]
16:35:36 exit 2684 0 0.007 [/lib/systemd/systemd-cgroups-agent /user.slice/user-0.slice/[e-mail]]
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2686 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2687 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2688 child /lib/systemd/systemd-udevd
16:35:36 fork 233 parent /lib/systemd/systemd-udevd
16:35:36 fork 2689 child /lib/systemd/systemd-udevd
16:35:36 exit 2687 0 0.014 /lib/systemd/systemd-udevd
16:35:36 exit 2689 0 0.013 /lib/systemd/systemd-udevd
16:35:36 exit 2686 0 0.015 /lib/systemd/systemd-udevd
16:35:36 exit 2688 0 0.015 /lib/systemd/systemd-udevd

I suspect some of this overhead explains the slower responsive feel to the brightness buttons. Anyhow, seems like a bit of an overkill for all these processes to be running especially compared to Xenial.

[Brad Figg (brad-figg)]

This bug is missing log files that will aid in diagnosing the problem. From a terminal window please run:

apport-collect 1626651

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Colin Ian King (colin-king)]

I think this is a systemd/udevd kinda bug isn't it?

[Colin Ian King (colin-king)]

OK, a bit more data:

Xenial with 4.4 and 4.8 kernels - works fine (so not a 4.8 kernel regression)
Yakkety with 4.4 and 4.8 kernels - shows the slow behavior (so not a kernel issue)

So I think this is a problem in the plumbing layer.

[Martin Pitt (pitti)]

This looks like one keypress would cause a massive spew of uevents and/or evdev events. Can you please run "sudo evtest" and "udevadm monitor -e", then press a brightness key once, then ^C both and copy&paste the output?

I don't get this on my ThinkPad X230, I have the opposite problem (brightness keys not working at all any more with 4.8 due to acpi_video0 disappearing, bug 1626429).

[Martin Pitt (pitti)]

Oh, forgot: for evtest you might need to try with several devices, such as "ThinkPad Extra Buttons" and the actual keyboard.

[Andy Whitcroft (apw)]

Ok this is not the same system but a similar lenovo with lagging brightness. I could not get evtest to tell me about the event on any sensible channel. But I am attaching the udev monitor and forkstat output. This shows a single kernel backlight event and a single synthetic udev event for the backlight. From that there are 34 forks.

[Andy Whitcroft (apw)]

This seems to trigger gnome-settings-daemon to do the following execs:

24323 execve("/usr/lib/unity-settings-daemon/usd-backlight-helper", ["/usr/lib/unity-settings-daemon/u"..., "--get-max-brightness"], [/* 47 vars */] <unfinished ...>
24323 <... execve resumed> ) = 0
24324 execve("/usr/lib/unity-settings-daemon/usd-backlight-helper", ["/usr/lib/unity-settings-daemon/u"..., "--get-brightness"], [/* 47 vars */] <unfinished ...>
24324 <... execve resumed> ) = 0
24325 execve("/usr/lib/unity-settings-daemon/usd-backlight-helper", ["/usr/lib/unity-settings-daemon/u"..., "--get-brightness"], [/* 47 vars */] <unfinished ...>
24325 <... execve resumed> ) = 0
24326 execve("/usr/lib/unity-settings-daemon/usd-backlight-helper", ["/usr/lib/unity-settings-daemon/u"..., "--get-max-brightness"], [/* 47 vars */] <unfinished ...>
24326 <... execve resumed> ) = 0
24327 execve("/usr/local/sbin/pkexec", ["pkexec", "/usr/lib/unity-settings-daemon/u"..., "--set-brightness", "211"], [/* 47 vars */]) = -1 ENOENT (No such file or directory)
24327 execve("/usr/local/bin/pkexec", ["pkexec", "/usr/lib/unity-settings-daemon/u"..., "--set-brightness", "211"], [/* 47 vars */]) = -1 ENOENT (No such file or directory)
24327 execve("/usr/sbin/pkexec", ["pkexec", "/usr/lib/unity-settings-daemon/u"..., "--set-brightness", "211"], [/* 47 vars */]) = -1 ENOENT (No such file or directory)
24327 execve("/usr/bin/pkexec", ["pkexec", "/usr/lib/unity-settings-daemon/u"..., "--set-brightness", "211"], [/* 47 vars */] <unfinished ...>
24327 <... execve resumed> ) = 0
24327 sendto(7, "<86>Sep 22 19:47:03 pkexec: pam_"..., 98, MSG_NOSIGNAL, NULL, 0) = 98
24327 <... readlink resumed> "/usr/bin/pkexec", 4096) = 15
24327 sendto(7, "<85>Sep 22 19:47:03 pkexec[24327"..., 182, MSG_NOSIGNAL, NULL, 0) = 182
24327 execve("/usr/lib/unity-settings-daemon/usd-backlight-helper", ["/usr/lib/unity-settings-daemon/u"..., "--set-brightness", "211"], [/* 10 vars */] <unfinished ...>
24327 <... execve resumed> ) = 0

The last of these uses pkexec which will trigger a new session.

[Martin Pitt (pitti)]

I just dist-upgraded again, and with 4.8.0-14 my brightness keys work again (bug 1626429). Under i3 (no unity-settings-daemon), I get a tame and immediate reaction:

UDEV [38372.886325] change /devices/pci0000:00/0000:00:02.0/backlight/acpi_video0 (backlight)
ACTION=change
DEVPATH=/devices/pci0000:00/0000:00:02.0/backlight/acpi_video0
ID_PATH=pci-0000:00:02.0
ID_PATH_TAG=pci-0000_00_02_0
SEQNUM=2735
SOURCE=hotkey
SUBSYSTEM=backlight
SYSTEMD_WANTS=systemd-backlight@backlight:acpi_video0.service
TAGS=:systemd:
USEC_INITIALIZED=9377712

21:07:21 fork 1298 parent /lib/systemd/systemd-udevd
21:07:21 fork 25614 child /lib/systemd/systemd-udevd
21:07:21 exit 25614 0 0.002 /lib/systemd/systemd-udevd

which matches the one uevent, but there is no userspace helper involved. Brightness change still works as it's hardwired into the driver. This proves that with just kernel and udev rules there is no delay and waste.

Under unity, with unity-settings-daemon, I now confirm the flurry of userspace action. The main pain point is the pkexec in

  pkexec /usr/lib/unity-settings-daemon/usd-backlight-helper --get-brightness

as that starts a full new PAM session, including systemd --user and other expensive stuff. Our /etc/pam.d/polkit-1 pulls in "common-session"; when changing this to "common-session-noninteractive" it becomes muuuch cheaper, but this would again be wrong for cases where we actually do want to run a new session for whatever we run there -- I'm trying to think about cases where this would break. I. e. should pk-exec behave more like "su" or "su -".

It would probably be best to grep the archive for usage of pk-exec, review whether any of it requires an interactive PAM session, and if not switch it to noninteractive.

[Martin Pitt (pitti)]

Changing tasks as this is somewhere between unity-settings-daemon and polkit.

[Martin Pitt (pitti)]

On the u-s-d side there is some potential optimization: Ideally the brightness would always be set through xrandr XBACKLIGHT, which works unprivileged, and only fall back to the helper if that is not available and the brightness needs to be set via sysfs properties. However, even then there is no reason why --get-brightness would need particular privileges: these sysfs attributes are world-readable, and only --set-brightness (writing the attribute) needs root. This would already cut away half of the overhead.

[Zero (zeugentor)]

Confirm on Yakkety 16.10 on notebook HP Pavilion g7 smbios-2.7 dmi-2.7 smp vsyscall32
Very very slow and inert reaction on pressing brightness keys

$ uname -r
4.8.0-17-generic

$ lspci
00:00.0 Host bridge: Intel Corporation 3rd Gen Core processor DRAM Controller (rev 09)
00:01.0 PCI bridge: Intel Corporation Xeon E3-1200 v2/3rd Gen Core processor PCI Express Root Port (rev 09)
00:02.0 VGA compatible controller: Intel Corporation 3rd Gen Core processor Graphics Controller (rev 09)
00:14.0 USB controller: Intel Corporation 7 Series/C210 Series Chipset Family USB xHCI Host Controller (rev 04)
00:16.0 Communication controller: Intel Corporation 7 Series/C210 Series Chipset Family MEI Controller #1 (rev 04)
00:1a.0 USB controller: Intel Corporation 7 Series/C210 Series Chipset Family USB Enhanced Host Controller #2 (rev 04)
00:1b.0 Audio device: Intel Corporation 7 Series/C210 Series Chipset Family High Definition Audio Controller (rev 04)
00:1c.0 PCI bridge: Intel Corporation 7 Series/C210 Series Chipset Family PCI Express Root Port 1 (rev c4)
00:1c.1 PCI bridge: Intel Corporation 7 Series/C210 Series Chipset Family PCI Express Root Port 2 (rev c4)
00:1c.2 PCI bridge: Intel Corporation 7 Series/C210 Series Chipset Family PCI Express Root Port 3 (rev c4)
00:1d.0 USB controller: Intel Corporation 7 Series/C210 Series Chipset Family USB Enhanced Host Controller #1 (rev 04)
00:1f.0 ISA bridge: Intel Corporation HM76 Express Chipset LPC Controller (rev 04)
00:1f.2 SATA controller: Intel Corporation 7 Series Chipset Family 6-port SATA Controller [AHCI mode] (rev 04)
00:1f.3 SMBus: Intel Corporation 7 Series/C210 Series Chipset Family SMBus Controller (rev 04)
01:00.0 VGA compatible controller: Advanced Micro Devices, Inc. [AMD/ATI] Thames [Radeon HD 7500M/7600M Series] (rev ff)
07:00.0 Network controller: Broadcom Limited BCM4313 802.11bgn Wireless Network Adapter (rev 01)
08:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8101/2/6E PCI Express Fast/Gigabit Ethernet controller (rev 05)
09:00.0 Unassigned class [ff00]: Realtek Semiconductor Co., Ltd. RTS5229 PCI Express Card Reader (rev 01)

[Eduards Bezverhijs (mjasnik)]

I have similar problem on Dell XPS 15 (l521x). It is not quick and it seems that for every key-press it's trying to change brightness twice.
I'll attach evtest and udev monitor outputs.

[Eduards Bezverhijs (mjasnik)]

In contrast this is what is happening with Xenial, which works perfectly.
evtest:
Event: time 1475641421.193234, type 1 (EV_KEY), code 225 (KEY_BRIGHTNESSUP), value 1
Event: time 1475641421.193234, -------------- SYN_REPORT ------------
Event: time 1475641421.193306, type 1 (EV_KEY), code 225 (KEY_BRIGHTNESSUP), value 0
Event: time 1475641421.193306, -------------- SYN_REPORT ------------

udev monitoring in the attachment.

[Jason Gerard DeRose (jderose)]

Okay, an interesting hint is that this problem seems to be fixed if u-s-d is started under the Upstart user session instead of the systemd user session.

If anyone wants to try this, just comment out these three lines in /etc/X11/Xsession.d/00upstart:

    if [ "${1#*.target}" != "$1" ]; then
        export XDG_CONFIG_DIRS="/usr/share/upstart/systemd-session:$XDG_CONFIG_DIRS"
    fi

I'm attaching the result of me starting u-s-d under Upstart, running `sudo forkstat -D 4`, and then pressing the brightness up key.

(I'll attach the same from under systemd next comment.)

From talking to Martin Pitt on IRC, sounds like switching u-s-d back to being started by Upstart might not be viable, but hopefully this at least helps narrow the search.

[Jason Gerard DeRose (jderose)]

`sudo forkstat -D 4` when u-s-d is started under systemd and I press the brightness up hotkey.

[Jason Gerard DeRose (jderose)]

I'm back to testing u-s-d started under systemd, and I found some serious wackiness observing `sudo journalctl -f` when I use the brigtness up/down hotkeys.

The attached "wacky-journalctl.txt" file has the output of `sudo journalctl -f` during which I used the brightness hotkeys *twice*, and you'll see a slew interesting things happening *each* time I press a hot key.

For example, this is a small excerpt of what I'm seeing for every hotkey press:

Oct 06 10:44:50 jason-Gazelle-Professional systemd[1]: Created slice User Slice of root.
Oct 06 10:44:50 jason-Gazelle-Professional systemd[1]: Starting User Manager for UID 0...
Oct 06 10:44:50 jason-Gazelle-Professional systemd[1]: Started Session 1 of user root.
Oct 06 10:44:50 jason-Gazelle-Professional systemd[4805]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Oct 06 10:44:50 jason-Gazelle-Professional systemd[4805]: Reached target Paths.
Oct 06 10:44:50 jason-Gazelle-Professional systemd[4805]: Starting D-Bus User Message Bus Socket.
Oct 06 10:44:50 jason-Gazelle-Professional systemd[4805]: Reached target Timers.
Oct 06 10:44:50 jason-Gazelle-Professional systemd[4805]: Listening on D-Bus User Message Bus Socket.
Oct 06 10:44:50 jason-Gazelle-Professional systemd[4805]: Reached target Sockets.
Oct 06 10:44:50 jason-Gazelle-Professional systemd[4805]: Reached target Basic System.
Oct 06 10:44:50 jason-Gazelle-Professional systemd[4805]: Starting Run Click user-level hooks...
Oct 06 10:44:50 jason-Gazelle-Professional systemd[4805]: Started D-Bus User Message Bus.
Oct 06 10:44:50 jason-Gazelle-Professional dbus-daemon[4839]: Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'

[Martin Pitt (pitti)]

The flurry of uevents like

KERNEL[2471.462139] add /kernel/slab/:atA-0000192/cgroup/dentry(4399:[e-mail]) (cgroup)
ACTION=add
DEVPATH=/kernel/slab/:atA-0000192/cgroup/dentry(4399:[e-mail])
SEQNUM=4916
SUBSYSTEM=cgroup

are new with kernel 4.8. This can easily be reproduced/observed with

  udevadm monitor -e --udev
  pkexec /usr/lib/unity-settings-daemon/usd-backlight-helper --get-brightness

This causes lots of uevents in kernel 4.8, but zero with 4.4. This explains the dozens of udev workers that get forked and slow down processing -- under 4.4 it's much faster, a latency of ~ 0.1s or 0.2s; not quite instantaneous, but much better than under 4.8.

This might be the same root cause as bug 1627108 and bug 1626436, particularly the latter -- if the creation/change of every cgroup causes 3 uevents, then during boot (when lots of services get started and lots of cgroups get created) tons of these uevents fire.

[Martin Pitt (pitti)]

The reason why it is fast under upstart is that with upstart the entire session is running in the logind scope/session, in particular unity-settings-daemon; and then pkexec causes

Okt 06 22:10:46 donald pkexec[9943]: pam_systemd(polkit-1:session): Cannot create session: Already running in a session

This is why the entire pam_systemd, systemd --user etc. for root are entirely skipped.

Under the "user session" paradigm that we get with dbus-user-session, most session processes (including gnome-terminal-server and unity-settings-daemon) run *outside* of the logind session/scope and thus not technically within a PAM session. That's why pam_systemd actually does start a new full session which makes this slow.

In conclusion: Under an upstart session we never actually had a "full" new interactive PAM session for the target user anyway, as this was *already* a PAM session. Thus changing pkexec to common-session-noninteractive is actually doing (mostly) the same as we previously did in 16.04 under an upstart session. Thus I am much more convinced now that switching to common-session-noninteractive is not only correct (and also fixing this bug), but also not actually that regression prone.

[Martin Pitt (pitti)]

> Thus I am much more convinced now that switching to common-session-noninteractive is not only correct (and also fixing this bug), but also not actually that regression prone.

To prove this:

$ diff -u /etc/pam.d/common-session{-noninteractive,}
@@ -27,5 +27,6 @@
 session optional pam_umask.so
 # and here are more per-package modules (the "Additional" block)
 session required pam_unix.so
+session optional pam_systemd.so
 session optional pam_ecryptfs.so unwrap
 # end of pam-auth-update config

(the other two hunks are just comments). I. e. the only difference between (non)interactive is pam_systemd, which was a no-op under upstart/session-centric model due to the "already running in a session" check.

[Martin Pitt (pitti)]

https://anonscm.debian.org/cgit/pkg-utopia/policykit.git/commit/?id=4299fc41

[Launchpad Janitor (janitor)]

This bug was fixed in the package policykit-1 - 0.105-16git1

---------------
policykit-1 (0.105-16git1) yakkety; urgency=medium

  Upload current Debian packaging git.

  [ Michael Biebl ]
  * Use https:// for the upstream homepage.
  * Update Vcs-Browser to use cgit.

  [ Simon McVittie ]
  * Build-depend on intltool instead of relying on gtk-doc-tools'
    dependency (Closes: #837846)

  [ Martin Pitt ]
  * Use PAM's common-session-noninteractive modules for pkexec instead of
    common-session. The latter also runs pam_systemd (the only difference
    normally) which is a no-op under the classic session-centric
    D-BUS/graphical login model (as it won't start a new one if it is already
    running within a logind session), but very expensive when using
    dbus-user-session and being called from a service that runs outside the
    PAM session. This causes long delays in e. g. gnome-settings-daemon's
    backlight helpers. (LP: #1626651)

 -- Martin Pitt <email address hidden> Thu, 06 Oct 2016 22:35:24 +0200