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

thigg · 29 November 2021 12:41

are we sure that this is not caused by the cpu going to deep sleep and the usage only counts the time when it’s active?

nephros · 29 November 2021 14:26

If you look at this using strace you’ll see that at least the file I/O, if that is to blame, starts as soon as the display is turned off. So no I don’t think it’s a timing/measuring issue.

Although I’m not sure if a timing case wouldn’t look just like that.

karry · 30 November 2021 07:24

Please consider to fill upstream bug, I don’t think that this issue is Jolla specific.

nephros · 30 November 2021 15:50

I would rather avoid dealing with upstream of this particular piece of software.

(Oh and should’t it be Jolla who file it? They are “my distro” in this scenario, and upstream bugs should be done through the “distro maintainer” usually.)

But if it’s unavoidable, any hints on how to gather proper logs from logind and udevd in order to be able to make a proper bug report there?

nephros · 13 December 2021 14:18

Sooo, doing a little more research:

logind reads lots of sound-and video related devices, and their uevent files. Looking at one of those, one notices:

 udevadm info -p /devices/platform/soc/soc:sound/sound/card0
P: /devices/platform/soc/soc:sound/sound/card0
E: DEVPATH=/devices/platform/soc/soc:sound/sound/card0
E: ID_FOR_SEAT=sound-platform-soc_sound
E: ID_PATH=platform-soc:sound
E: ID_PATH_TAG=platform-soc_sound
E: PLATFORM_DEVICE=soc:sound
E: PLATFORM_FOLDER=soc
E: PULSE_IGNORE=1
E: SOUND_FORM_FACTOR=internal
E: SOUND_INITIALIZED=1
E: SUBSYSTEM=sound
E: SYSTEMD_WANTS=sound.target
E: TAGS=:seat:systemd:
E: USEC_INITIALIZED=15434191
E: androidboot.bootdevice=c0c4000.sdhci

So, this is tagged as a “seat”, which means logind is reponsible for it, as: sd-login sais

… and further down:

which I guess is what’s happening, as at the end of one of those scanning runs, strace shows some of these:

setxattr("/dev/snd/hwC0D44", "system.posix_acl_access", "\2\0\0\0\1\0\6\0\377\377\377\377\2\0\6\0\240\206\1\0\4\0\6\0\377\377\377\377\20\0\6", 44, 0) = 0

Also, more info here which explains what and how happens here.

So this explains why udev and logind use CPU in concerto, and in principle all of that is expected behavior (except that this is a single-seat system all of that is kinda pointlessly overcomplicated, (like almost anything what comes out of freedesktop.org)).

(Sorry if you’re bored by this if it seems common knowledge to you. Myself I find it new, if annyong-to-get, knowledge.)

My TL;DR for now is, all those file accesses are cause by the set-ACL-if-user-becomes-inactive feature, and are therefore normal.

Which brings me back to the original topic: if this is NOT what is causing the load, what is?

nephros · 13 December 2021 16:56

Aaand another one:

Looking at udev straces this time, I see a lot of execve and related syscalls. Now, spawning external processes, that’s something we want to avoid. What could cause it?

A little grepping leads quickly to /lib/udev/rules.d/999-android-system.rules which is an autogenerated config file and is full of things like this:

#:/sys/devices/system/cpu/cpu*   cpufreq/scaling_min_freq   0664  system system
# sys rule
DEVPATH=="/devices/system/cpu/cpu*", TEST=="/sys/$devpath/cpufreq/scaling_min_freq", RUN+="/bin/chmod 0664 /sys/$devpath/cpufreq/scaling_min_freq", RUN+="/bin/chown system:system /sys/$devpath/cpufreq/scaling_min_freq"

so this spawns a chown and a chmod every time CPU device nodes change (which due to power saving is rather often).

QUESTION: to someone with udev knowledge:

Am I correct in assuming that a

DEVPATH=="/devices/system/cpu/cpu*", TEST=="/sys/$devpath/cpufreq/scaling_min_freq", MODE="0664", GROUP="system", OWNER="system"

does the same thing as the chown/chmod combination above?

poetaster · 13 December 2021 18:06

And now you know why all my server systems are sans systemd Not to kick at that bucket, but one note on your comment before this one, this IS a multi-user system, though we want it to behave like a single seat, it isn’t.

Did you note the device node perms before and after sleep/wake? I don’t see a reason for the perms to change on wake/sleep.
Did you try commenting The rule out I haven’t looked at it, but would guess it’s superfluous. That’s what’d I’d try if I wasn’t so busy debugging QML

nephros · 13 December 2021 18:22

Well,

grep -c RUN+= 999*
999-aliendalvik.rules:0
999-android-system.rules:31

(EDIT: no, the following sentences are wrong. See the source code comments linked below.)

I have as a test replaced all the RUNs with corresponding OWNER, GROUP, MODE lines. Now many of those relate to cpuN paths, which appear and disappear as power saving turns the cores on and off.
So correcting/setting ownerships through udev is okay in this case I think.

Also, that RUN+="chown/chgrp" has been a best practice in past udev rule days, and that file is autogenerated by some droid-hal-* script from Android configuration.
I wonder if that script just uses Ye Olde Way because it has always done that, and the OWNER, GROUP, MODE would be better. If it is indeed equivalent.

poetaster · 13 December 2021 18:37

Ok, I’m on a community device so it looks a bit different (21 matches in 999-android-system). I don’t think my naive approach will work, but I also don’t think it’s relevant. Even with the frequency, the cpu usage doesn’t make sense. BUT you said above that strace reveals it’s I/O that’s to blame.

I just did a quick and dirty check (4.3 on the volla) using the dbus-monitor --system approach and got tons of serial (comms/wifi connma and co., dhcp) activity which DOES seem a bit frequent for a phone that’s in sleep/idle. But I didn’t see anything related to sound?!

On the other hand, in idle:

  452     1 root     S    19208  0.4   1  0.0 /usr/lib/systemd/systemd-journald
 1364     1 root     S     347m  9.0   3  0.0 /usr/sbin/connmand -n -W nl80211 --nobacktrace --noplugin=wifi

… snip

 1096   622 mediaex  S     258g6916.5   4  0.0 {mediaextractor} media.extractor aextractor
 1136   622 mediacod S     258g6916.4   5  0.0 {mediaswcodec} media.swcodec oid.media.swcodec/bin/mediaswcodec

WTF? (ps, that journald produces so much load … ducks and runs).

But realistically, only lipstick is producing any load. I think this may be device dependant? And I’m running community, so…

Erg. What’s really disturbing is how much cpu Tidings eats in idle. Sigh. I have even more work to do.

EDIT, like 3. So, sitting here watching htop, lipstick and journald produce between 2-5% of cpu load with the phone in sleep (well, is it in sleep if I’m running htop, not really). Connman runs a steady 0.6 almost constantly.

nephros · 13 December 2021 18:51

Oh, it seems upstream knows about all the chown/chmods:

github.com

mer-hybris/droid-hal-device/blob/master/helpers/makeudev#L50

    
      
          print "#:$_";                 # after including them
          next if /^\w*#/ or /^\w*$/ ;  # skip comments and blank lines
          
          
# Android .rc files for ueventd /sys are :
          # <devicepath_or_glob>  <attr> <perms>  <owner> <group>
          # This is because uevent only allows a single simple glob within the path
          # Udev handles this by simply concatenating with a /
          # However udev builtins only operate on /dev nodes (AFAICT)
          # Matching is done on events without the /sys/ (which is a userspace
          # convention) but chmod/chown needs the /sys
          # FIXME: consider replacing chmod/chown with an all-in-one to avoid extra exec()s
          if (m{^/sys/}) {
            print "# sys rule\n";
            s{^/sys/}{};
            my ($dev, $key, $mode, $owner, $group) = split;
            print qq{DEVPATH=="/$dev", TEST=="/sys/\$devpath/$key", RUN+="/bin/chmod $mode /sys/\$devpath/$key", RUN+="/bin/chown $owner:$group /sys/\$devpath/$key"\n} ;
            next;
          }
          
          
# Android .rc files for ueventd /dev are :
          # <devicepath_or_glob>  <perms>  <owner> <group>

And this answers my question above, the owner/group/mode thing is not equivalent.

poetaster · 13 December 2021 18:53

cool, but I’d guess that’s only a small part of the problem? Or I just see completely different problems. What device were you testing with?

nephros · 13 December 2021 18:57

Yeah, still not quite there what the actual problem is, all those device nodes might be the wrong thing to look at.

Xperia10 Dual-Sim

poetaster · 13 December 2021 19:07

After closing everything, I now see lipstick talking to the lipstick scanner and at about one 5th the period, connman. dbus-monitor. and journald really sucks. in comparison to rsyslogd.

nephros · 13 December 2021 19:14

journald gets loaded if something is spamming it.

You can try editing /etc/systemd/journald.conf and either playing with the rate limiter, or settting something like MaxLevelStore=warning so it drops less interesting messages. But then you also can’t see them in the logs…

poetaster · 13 December 2021 20:14

In parallel I was sitting on a web proxy (haproxy), which does a fair bit of logging, watching rsyslog (so, web traffic, constant) not register. That machine, of course has a lot more cores

I’m wondering, though, wouldn’t journald be set to be very conservative as a default? I’ll have to ask @piggz. It might be that he ships with somewhat more noisy logging.

nephros · 24 May 2022 14:03

I cannot edit the original post any more, and I can only add three tags

So I’ll add here that more or less the same happens on 4.4.0.64 / Xperia 10iii as well as my original 4.2 / Xperia 10DS.

All of the information above this post was collected on the 10ds with 4.2.

flypig · 22 June 2022 23:19

Thanks @nephros for the original report and all the additional info and discussion. I’ve created a report on our internal bug tracker, so have tagged this as “tracked”.

nephros · 23 June 2022 09:50

Good to know.

I have two ways to improve the exec() detail, one of which is a very K&R hodgepodge of chown+chmod, the other is this - but I suppose having udev depend on perl is not really feasible…

Although in synthetic performance (well, syscall count) benchmarks, perl is surprisingly lightweight, and does the job.

Speedy-10 · 6 May 2023 07:07

@Jolla: Has this issue been checked by Jolla, is there a solution ahead, which could be expected with a soon update?

phil4444 · 20 September 2023 09:08

@nephros - thank you for the bug report! In the last weeks/months I noticed a similar behaviour on my XA2 (4.5.0.24) which got worse until I found an Android app (Ö1) which was desperately trying to login - it was enabled to be started on boot (Settings => Apps => Allow background service to start on bootup)
Once I disabled this, my battery life went back to normal.
Systemd-logind is now at 2.1% CPU time when the display is on. I never did any traces …