Uploaded image for project: 'RHEL'
  1. RHEL
  2. RHEL-5777

Repetitive and redundant "CheckAuthorization" queries performed against polkitd causing high CPU load spikes

    • Icon: Bug Bug
    • Resolution: Duplicate
    • Icon: Normal Normal
    • None
    • rhel-8.7.0
    • polkit
    • None
    • Moderate
    • rhel-sst-cs-plumbers
    • ssg_core_services
    • 5
    • False
    • Hide

      None

      Show
      None
    • None
    • None
    • None
    • None
    • If docs needed, set a value
    • None

      Description of problem:

      We have a customer seeing spikes of CPU consumption of polkitd and dbus-daemon happening every minute:
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
      PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
      902 polkitd 20 0 1670256 51696 16964 R 44.4 0.2 250:00.33 polkitd
      917 dbus 20 0 88132 8884 4888 R 11.1 0.0 46:21.10 dbus-da+
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      This spike is due to "CheckAuthorization" queries being performed by every single graphical session instance, and this twice, every time the number of user sessions changes (e.g. a new session appears or a session is destroyed):
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      1. grep "CheckAuthorization" gnome-shell.strace
        1717 09:48:13.930859 sendmsg(6<UNIX:[35289->35290]>, {msg_name=NULL, msg_namelen=0, msg_iov=[
        Unknown macro: {iov_base="l101211000\200245000101g020(sa{sv})sa{ss}us\0\0\0\1\1o\0%\0\0\0/org/freedesktop/PolicyKit1/Authority\0\0\0\3\1s\0\22\0\0\0CheckAuthorization\0\0\0\0\0\0\2\1s\0$\0\0\0org.freedesktop.PolicyKit1.Authority\0\0\0\0\6\1s\0\4\0\0\0:1.7\0\0\0\0\f\0\0\0unix-process\0\0\0\0@\0\0\0\3\0\0\0pid\0\1u\0\0\201\6\0\0\n\0\0\0start-time\0\1t\0\0\0\0\0\0\0\264\3\0\0\0\0\0\0\3\0\0\0uid\0\1i\0\0*\0\0\0\33\0\0\0org.freedesktop.bolt.enroll\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=321}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 321 <0.000015>
        1717 09:48:13.931141 sendmsg(6<UNIX:[35289->35290]>, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\241\0\0\0]\2\0\0\245\0\0\0\10\1g\0\20(sa{sv})sa{ss}us\0\0\0\1\1o\0%\0\0\0/org/freedesktop/PolicyKit1/Authority\0\0\0\3\1s\0\22\0\0\0CheckAuthorization\0\0\0\0\0\0\2\1s\0$\0\0\0org.freedesktop.PolicyKit1.Authority\0\0\0\0\6\1s\0\4\0\0\0:1.7\0\0\0\0\f\0\0\0unix-process\0\0\0\0@\0\0\0\3\0\0\0pid\0\1u\0\0\201\6\0\0\n\0\0\0start-time\0\1t\0\0\0\0\0\0\0\264\3\0\0\0\0\0\0\3\0\0\0uid\0\1i\0\0*\0\0\0001\0\0\0org.freedesktop.packagekit.trigger-offline-update\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=345}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL <unfinished ...>
        1717 09:48:13.931486 sendmsg(6<UNIX:[35289->35290]>, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\231\0\0\0^\2\0\0\245\0\0\0\10\1g\0\20(sa{sv})sa{ss}us00011o0%000/org/freedesktop/PolicyKit1/Authority00031s022000CheckAuthorization00000021s0$000org.freedesktop.PolicyKit1.Authority000061s04000}

        ], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 337 <0.000007>
        1717 09:48:13.932241 sendmsg(6<UNIX:[35289->35290]>, {msg_name=NULL, msg_namelen=0, msg_iov=[

        Unknown macro: {iov_base="l101211000_200245000101g020(sa{sv})sa{ss}us\0\0\0\1\1o\0%\0\0\0/org/freedesktop/PolicyKit1/Authority\0\0\0\3\1s\0\22\0\0\0CheckAuthorization\0\0\0\0\0\0\2\1s\0$\0\0\0org.freedesktop.PolicyKit1.Authority\0\0\0\0\6\1s\0\4\0\0\0:1.7\0\0\0\0\f\0\0\0unix-process\0\0\0\0@\0\0\0\3\0\0\0pid\0\1u\0\0\201\6\0\0\n\0\0\0start-time\0\1t\0\0\0\0\0\0\0\264\3\0\0\0\0\0\0\3\0\0\0uid\0\1i\0\0*\0\0\0\33\0\0\0org.freedesktop.bolt.enroll\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=321}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 321 <0.000011>
        1717 09:48:13.932370 sendmsg(6<UNIX:[35289->35290]>, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\241\0\0\0`\2\0\0\245\0\0\0\10\1g\0\20(sa{sv})sa{ss}us\0\0\0\1\1o\0%\0\0\0/org/freedesktop/PolicyKit1/Authority\0\0\0\3\1s\0\22\0\0\0CheckAuthorization\0\0\0\0\0\0\2\1s\0$\0\0\0org.freedesktop.PolicyKit1.Authority\0\0\0\0\6\1s\0\4\0\0\0:1.7\0\0\0\0\f\0\0\0unix-process\0\0\0\0@\0\0\0\3\0\0\0pid\0\1u\0\0\201\6\0\0\n\0\0\0start-time\0\1t\0\0\0\0\0\0\0\264\3\0\0\0\0\0\0\3\0\0\0uid\0\1i\0\0*\0\0\0001\0\0\0org.freedesktop.packagekit.trigger-offline-update\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=345}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 345 <0.000009>
        1717 09:48:13.932475 sendmsg(6<UNIX:[35289->35290]>, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\231\0\0\0a\2\0\0\245\0\0\0\10\1g\0\20(sa{sv})sa{ss}us00011o0%000/org/freedesktop/PolicyKit1/Authority00031s022000CheckAuthorization00000021s0$000org.freedesktop.PolicyKit1.Authority000061s04000}

        ], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 337 <0.000006>
        1717 09:48:13.932552 sendmsg(6<UNIX:[35289->35290]>, {msg_name=NULL, msg_namelen=0, msg_iov=[

        Unknown macro: {iov_base="l101211000b200245000101g020(sa{sv})sa{ss}us\0\0\0\1\1o\0%\0\0\0/org/freedesktop/PolicyKit1/Authority\0\0\0\3\1s\0\22\0\0\0CheckAuthorization\0\0\0\0\0\0\2\1s\0$\0\0\0org.freedesktop.PolicyKit1.Authority\0\0\0\0\6\1s\0\4\0\0\0:1.7\0\0\0\0\f\0\0\0unix-process\0\0\0\0@\0\0\0\3\0\0\0pid\0\1u\0\0\201\6\0\0\n\0\0\0start-time\0\1t\0\0\0\0\0\0\0\264\3\0\0\0\0\0\0\3\0\0\0uid\0\1i\0\0*\0\0\0\33\0\0\0org.freedesktop.bolt.enroll\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=321}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 321 <0.000006>
        1717 09:48:13.932637 sendmsg(6<UNIX:[35289->35290]>, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\241\0\0\0c\2\0\0\245\0\0\0\10\1g\0\20(sa{sv})sa{ss}us\0\0\0\1\1o\0%\0\0\0/org/freedesktop/PolicyKit1/Authority\0\0\0\3\1s\0\22\0\0\0CheckAuthorization\0\0\0\0\0\0\2\1s\0$\0\0\0org.freedesktop.PolicyKit1.Authority\0\0\0\0\6\1s\0\4\0\0\0:1.7\0\0\0\0\f\0\0\0unix-process\0\0\0\0@\0\0\0\3\0\0\0pid\0\1u\0\0\201\6\0\0\n\0\0\0start-time\0\1t\0\0\0\0\0\0\0\264\3\0\0\0\0\0\0\3\0\0\0uid\0\1i\0\0*\0\0\0001\0\0\0org.freedesktop.packagekit.trigger-offline-update\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=345}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 345 <0.000006>
        1717 09:48:13.932715 sendmsg(6<UNIX:[35289->35290]>, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\231\0\0\0d\2\0\0\245\0\0\0\10\1g\0\20(sa{sv})sa{ss}us00011o0%000/org/freedesktop/PolicyKit1/Authority00031s022000CheckAuthorization00000021s0$000org.freedesktop.PolicyKit1.Authority000061s04000}

        ], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 337 <0.000006>

                    • 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      Such operation is performed by all gnome-shell processes executing on the system, which can be high, e.g. when having VNC servers.
      Note that the spike can be seen as soon as a few gnome-shell are executing (e.g. GDM greeter + 2 VNC servers).

      After much digging, I was able to find out that this operation was due to reloading systemd sessions, which happens due to changes in /run/systemd/sessions directory upon session creation/deleting:
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
      (gdb) bt
      #0 _GI__open64_nocancel (file=0x7efe1063fb1e "/run/systemd/sessions/", oflag=591872)
      at ../sysdeps/unix/sysv/linux/open64_nocancel.c:45
      #1 0x00007efe122d6309 in __opendir (name=name@entry=0x7efe1063fb1e "/run/systemd/sessions/")
      at ../sysdeps/posix/opendir.c:92
      #2 0x00007efe105f5a68 in get_files_in_directory (path=0x7efe1063fb1e "/run/systemd/sessions/", list=0x7fff1fadda88)
      at ../src/basic/fs-util.c:450
      #3 0x00007efe105bc3d7 in sd_get_sessions (sessions=sessions@entry=0x7fff1fadda88)
      at ../src/libsystemd/sd-login/sd-login.c:790
      #4 0x00007efdc432058a in reload_systemd_sessions (manager=0x561685af95e0)
      at ../src/libaccountsservice/act-user-manager.c:1988
      #5 0x00007efdc4320961 in on_session_monitor_event (stream=<optimized out>, manager=0x561685af95e0)
      at ../src/libaccountsservice/act-user-manager.c:2040
      #6 0x00007efe141c995d in g_main_dispatch (context=0x561685af4b40) at gmain.c:3193
      #7 g_main_context_dispatch (context=context@entry=0x561685af4b40) at gmain.c:3873
      #8 0x00007efe141c9d18 in g_main_context_iterate (context=0x561685af4b40, block=block@entry=1,
      dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3946
      #9 0x00007efe141ca042 in g_main_loop_run (loop=0x561686913400) at gmain.c:4142
      #10 0x00007efe1265bf00 in meta_run () at ../src/core/main.c:685
      #11 0x000056168415256f in main (argc=<optimized out>, argv=<optimized out>) at ../src/main.c:503
      (gdb) f 5
      #5 0x00007efdc4320961 in on_session_monitor_event (stream=<optimized out>, manager=0x561685af95e0)
      at ../src/libaccountsservice/act-user-manager.c:2040
      2040 reload_systemd_sessions (manager);
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      Clearly this code is sub-optimal and needs enhancement.

      Version-Release number of selected component (if applicable):

      accountsservice-0.6.55-4.el8.x86_64

      How reproducible:

      Always

      Steps to Reproduce:
      1. Set up several users that will have VNC services

      1. for i in $(seq 1 10); do useradd user$i; done
      2. for i in $(seq 1 10); do mkdir /home/user$i/.vnc; echo -n "redhat" | vncpasswd -f > /home/user$i/.vnc/passwd; chmod 600 /home/user$i/.vnc/passwd; chown -R user$i:user$i /home/user$i/.vnc; done

      2. Enable+Start the services

      1. for i in $(seq 1 10); do systemctl enable vncserver@:$i.service --now; done

      3. Login, logout or execute a cron (anything that creates a session)

      $ ssh localhost

      Actual results:

      Spike of polkitd and dbus-daemon

      Expected results:

      No spike, no CheckAuthorization for current sessions

      Additional info:

      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      1. top -d 1 -b -p 899 -p 905
        [...]
        top - 10:11:48 up 5 min, 2 users, load average: 1.02, 4.16, 2.54
        Tasks: 2 total, 1 running, 1 sleeping, 0 stopped, 0 zombie
        %Cpu(s): 12.6 us, 9.6 sy, 0.0 ni, 76.3 id, 0.5 wa, 0.5 hi, 0.5 si, 0.0 st
        MiB Mem : 7955.7 total, 675.0 free, 6126.2 used, 1154.5 buff/cache
        MiB Swap: 2048.0 total, 2048.0 free, 0.0 used. 1474.6 avail Mem

      PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
      905 polkitd 20 0 1823904 34672 18316 S 5.9 0.4 0:11.55 polkitd
      899 dbus 20 0 71516 16564 4268 R 3.0 0.2 0:02.60 dbus-daemon

      top - 10:11:49 up 5 min, 2 users, load average: 1.02, 4.16, 2.54
      Tasks: 2 total, 1 running, 1 sleeping, 0 stopped, 0 zombie
      %Cpu(s): 32.0 us, 22.3 sy, 0.0 ni, 43.7 id, 0.0 wa, 1.0 hi, 0.5 si, 0.5 st
      MiB Mem : 7955.7 total, 675.0 free, 6126.2 used, 1154.5 buff/cache
      MiB Swap: 2048.0 total, 2048.0 free, 0.0 used. 1474.6 avail Mem

      PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
      905 polkitd 20 0 1823904 34792 18316 S 30.0 0.4 0:11.85 polkitd
      899 dbus 20 0 71516 16564 4268 R 10.0 0.2 0:02.70 dbus-daemon

      top - 10:11:50 up 5 min, 2 users, load average: 1.02, 4.16, 2.54
      Tasks: 2 total, 0 running, 2 sleeping, 0 stopped, 0 zombie
      %Cpu(s): 7.0 us, 4.0 sy, 0.0 ni, 88.0 id, 0.0 wa, 0.5 hi, 0.5 si, 0.0 st
      MiB Mem : 7955.7 total, 670.5 free, 6130.6 used, 1154.6 buff/cache
      MiB Swap: 2048.0 total, 2048.0 free, 0.0 used. 1470.2 avail Mem

      PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
      905 polkitd 20 0 1824928 34828 18316 S 6.0 0.4 0:11.91 polkitd
      899 dbus 20 0 71516 16564 4268 S 2.0 0.2 0:02.72 dbus-daemon
      [...]
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      With stracing polkit and logging in:
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      1. strace -fttTvyy -s 512 -p 905 -o polkit.strace
        strace: Process 905 attached with 6 threads
        strace: Process 12194 attached
        strace: Process 12201 attached
        strace: Process 12206 attached
        strace: Process 12235 attached
        strace: Process 12236 attached
        ...
        ^C
      1. grep -c CheckAuthorization polkit.strace
        43
      1. grep CheckAuthorization polkit.strace | grep -c trigger-offline-update
        21
                    • 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      If you enable sssd and use remote users, the spike is even more visible because of the sssd work induced by querying the users.

              jrybar@redhat.com Jan Rybar
              rhn-support-rmetrich Renaud Métrich
              Jan Rybar Jan Rybar
              qe-baseos-daemons qe-baseos-daemons
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated:
                Resolved: