Process systemd-logind constant 3-7%CPU usage, scanning camera and audio devices

REPRODUCIBILITY (% or how often): 80%
BUILD ID = OS VERSION (Settings > About product): 4.2.0.21 (Verla)
HARDWARE (XA2, X10, X10 II, …): X10DS
UI LANGUAGE: en
REGRESSION: (compared to previous public release: Yes, No, ?): ?

DESCRIPTION:

Several monitoring tools (ps, dstat, top, htop, collectd/systemdatascope…) show systemd-logind eating resources all the time.

Not much, but constantly.

Here’s what collectd/systemdatascope produce:

UPDATE1: It appears the phenomenon appeards while the display is OFF, not during normal use (obseved while logged in over ssh).

UPDATE2: Udevd is involved as well, if I read my graphs correctly - spikes are very similar.
Screenshot:

PRECONDITIONS:

unknown

STEPS TO REPRODUCE:

  1. have systemd-logind active (hehe)
  2. monitor CPU or I/O usage using your preferred method
  3. notice constant acticity

EXPECTED RESULT:

Which amount of load this should cause in order to be doing what it must be doing is unknown to me, but it shouldn’t actually have to do a lot on a single-user system like a SFOS phone.

ACTUAL RESULT:

3-5% CPU usage by the systemd-logind process all the time.

I also see the device not being able to put all CPUS to sleep, which might or might not be related.

Also, htop shows a particular IRQ thread busy a lot, which may or may not be related.
Kernel thread name: irq/30-1008000.
Info according to proc/interrups: 30: 17464269 0 mpm-gic 215 Level 1008000.qcom,cpu-bwmon

ADDITIONAL INFORMATION:

Using strace I find that it’s apparently looping over files (symlinks?) under
/sys/devices/platform/soc/soc, mainly sound and camera devices.

I have run something like

strace -e file -w -C -p 2910 2>&1

which results in:

strace: Process 2910 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 71.81    1.616770          43     37206           openat
 11.05    0.248774          54      4573           readlinkat
  8.12    0.182891          60      3007           access
  4.89    0.110015          76      1441           setxattr
  3.04    0.068464          47      1441           getxattr
  0.77    0.017396         527        33           rename
  0.16    0.003695         111        33        33 mkdir
  0.16    0.003571         108        33           lstat64
------ ----------- ----------- --------- --------- ----------------
100.00    2.251576          47     47767        33 total

Strace outputs:

If you do a grep ^access trace_file.log | sort | uniq -c you will find the same 131 files are accessed 16 times in the time that strace ran.

2 Likes

In case it is related, that interrupt increases its spurious count by about 200-300 per second:

 # while sleep 1 ; do awk '/count/ {print systime(),  $2}'  /proc/irq/30/spurious; done
1636633234 81830
1636633235 82072
1636633236 82324
1636633237 82560
1636633238 82819
1636633249 83052
1636633257 83297
1636633258 83547
1636633259 83796
1636633260 84046
1636633261 84292
1636633262 84537
1636633263 84793
^C

It is not normal. By documentation, it provides D-Bus api “mplementing a shutdown/sleep inhibition logic for application”. It is possible that some application uses it. Try D-Bus monitor to find more…

1 Like

UPDATE1: It appears the phenomenon appeards while the display is OFF, not during normal use (obseved while logged in over ssh).

ONe can easily see the tracing getting busy by:

  1. logon via ssh seession
  2. devel-su to root
  3. find PID of systemd-logind
  4. execute strace

As soon as the display goes to sleep, the traces show up like in the logs. Pressing power key to wake up the device stops it again.

Thanks.

Any hints on how to effectively use dbus-monitor for a newbie?

Strange, it consumes some cpu even on my idle phone :slight_smile: (~3%, but it may be misleading, I’m not sure how fast cpu is running at this state).

To dbus-monitor, it is simple. As root, just execute:

dbus-monitor  --system

There is some activity from logind (path /org/freedesktop/login1 belong to logind)

signal time=1636672660.372447 sender=:1.6 -> destination=(null destination) serial=81804 path=/org/freedesktop/login1/session/c1; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.login1.Session"
   array [
      dict entry(
         string "Active"
         variant             boolean true
      )
   ]
   array [
   ]
signal time=1636672660.377794 sender=:1.6 -> destination=(null destination) serial=81805 path=/org/freedesktop/login1/seat/seat0; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.login1.Seat"
   array [
      dict entry(
         string "ActiveSession"
         variant             struct {
               string "c1"
               object path "/org/freedesktop/login1/session/c1"
            }
      )
   ]
   array [
   ]

But I am not sure what exactly these properties mean. My guess is that it is signaling if session is active and it is caused by short cpu sleeps…? Not sure without reading documentation / source code.

But I believe that this activity is not caused by another application, they are signals triggered by logind.

1 Like