Bug 1045658

Summary: yast2 services-manager is very slow after 3.1.44 update
Product: [openSUSE] openSUSE Distribution Reporter: Andrew Daugherity <adaugherity>
Component: YaST2Assignee: Martin Vidner <mvidner>
Status: RESOLVED FIXED QA Contact: Jiri Srain <jsrain>
Severity: Normal    
Priority: P2 - High CC: adaugherity, igonzalezsosa, jreidinger, mfilka, opensuse.lietuviu.kalba
Version: Leap 42.2   
Target Milestone: ---   
Hardware: Other   
OS: Other   
URL: https://trello.com/c/IiJYLiBk/1618-speedup-reading-services-state-services-manager
Whiteboard:
Found By: --- Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---
Attachments: YaST2 logs for version 3.1.42 (fast)
YasT2 logs for version 3.1.44 (slow)
YaST logs for autoyast & services-manager, SLES 12 SP2 vs. Leap 42.3

Description Andrew Daugherity 2017-06-23 00:07:57 UTC
User-Agent:       Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_4) AppleWebKit/603.1.30 (KHTML, like Gecko) Version/10.0.1 Safari/602.2.14
Build Identifier: 

On my most recent autoyast installation, I noticed it appeared to hang in the 2nd stage after auth-client had finished, but it eventually unfroze and finished successfully.  Inspecting the YaST logs, I see that it was services-manager at fault, as it took 3m45s to run!

Launching services-manager in the installed system is likewise very slow, taking about 47 seconds every time (6 seconds to launch, then 41 seconds while "Reading services status..." is displayed).

If I roll back to yast2-services-manager-3.1.43, then it launches much quicker, in about 9 seconds (6 to launch + 3 reading status).


Reproducible: Always

Steps to Reproduce:
1. Install yast2-services-manager-3.1.44 update or enable the updates repo during [auto]installation.
2. Launch YaST2 services-manager.
3. Go grab some coffee...
Actual Results:  
services-manager takes 47 sec to launch, or 3:45 to run during autoinstallation.

Expected Results:  
services-manager should launch in < 10 sec, as it did before.

Perhaps the systemctl calls added in this update may be the bottleneck?  It takes a fraction of a second for each, but does several hundred of them...

====
2017-06-22 17:45:05 <1> nfs-next(9284) [liby2] genericfrontend.cc(main):617 Launched YaST2 component 'y2base' 'services-manager'
 'ncurses'
2017-06-22 17:45:05 <1> nfs-next(9284) [ui-component] YUIComponentCreator.cc(createInternal):124 Creating UI component for ""
2017-06-22 17:45:05 <1> nfs-next(9284) [liby2] genericfrontend.cc(main):806 YAST_IS_RUNNING is yes
2017-06-22 17:45:05 <1> nfs-next(9284) [Ruby] yast/wfm.rb:211 Call client /usr/share/YaST2/clients/services-manager.rb
[...]
2017-06-22 17:45:05 <1> nfs-next(9284) [Ruby] yast2/systemd_unit.rb:122 `systemctl show multi-user.target  --property=AllowIsolate  --property=Id  --property=MainPID  --property=Description  --property=LoadState  --property=ActiveState  --property=SubState  --property=UnitFileState  --property=FragmentPath `
2017-06-22 17:45:06 <1> nfs-next(9284) [Ruby] yast2/systemd_unit.rb:122 `systemctl show basic.target  --property=AllowIsolate  --property=Id  --property=MainPID  --property=Description  --property=LoadState  --property=ActiveState  --property=SubState  --property=UnitFileState  --property=FragmentPath `
2017-06-22 17:45:06 <1> nfs-next(9284) [Ruby] yast2/systemd_unit.rb:122 `systemctl is-enabled basic.target `
2017-06-22 17:45:06 <1> nfs-next(9284) [Ruby] yast2/systemd_unit.rb:122 `systemctl show bluetooth.target  --property=AllowIsolate  --property=Id  --property=MainPID  --property=Description  --property=LoadState  --property=ActiveState  --property=SubState  --property=UnitFileState  --property=FragmentPath `
[...]
2017-06-22 17:45:51 <1> nfs-next(9284) [Ruby] yast2/systemd_unit.rb:122 `systemctl show user@0.service  --property=Id  --property=MainPID  --property=Description  --property=LoadState  --property=ActiveState  --property=SubState  --property=UnitFileState  --property=FragmentPath `
2017-06-22 17:45:51 <1> nfs-next(9284) [Ruby] yast2/systemd_unit.rb:122 `systemctl is-enabled user@0.service `
====

Strangely, if I extract all these systemctl commands to a shell script, and run 'time systemctl.sh', it runs in 5.97 seconds.  Does that mean the overhead is actually in YaST or ruby instead of systemctl?
Comment 1 Andrew Daugherity 2017-07-28 21:52:57 UTC
Still a problem with 42.3, and you don't have the option of rolling back to an older unaffected version here as you do on 42.2.

With yast2-services-manager-3.2.1-1.4.noarch, launching services-manager is slightly improved (but still far too slow), taking 34 seconds now.  However during autoyast installation it's even slower, taking 5m11s.  FYI, services configuration appears to have moved to the first stage now.

My 42.3 VM installation took 25 minutes thanks to this (used to be 10-15min).
Comment 2 Lukas Ocilka 2017-07-31 07:28:46 UTC
Andrew, plese attach YaST logs. It really sounds strange.
Might be related to the fact that it's a VM - which kind do you use?
Comment 3 Imobach Gonzalez Sosa 2017-07-31 08:49:45 UTC
The difference between 3.1.144 and previous versions is quite noticiable, although in my case it "only" went from 1 second to 5 when reading the services configuration.

I'm attaching YaST2 logs for both cases.
Comment 4 Imobach Gonzalez Sosa 2017-07-31 08:50:29 UTC
Created attachment 734519 [details]
YaST2 logs for version 3.1.42 (fast)
Comment 5 Imobach Gonzalez Sosa 2017-07-31 08:51:28 UTC
Created attachment 734520 [details]
YasT2 logs for version 3.1.44 (slow)
Comment 6 Lukas Ocilka 2017-07-31 09:13:13 UTC
New Tracking URL (sorry, it's internal)
Comment 7 Imobach Gonzalez Sosa 2017-08-08 13:17:08 UTC
Sorry, I removed NEEDINFO on Andrew, but I think that it would be interesting having his logs (although we already have a bug to fix).
Comment 8 Andrew Daugherity 2017-08-16 18:58:55 UTC
Strangely, it does appear to be much worse on a VM than on physical hardware, although it is still noticeably slower even on physical hardware (shiny new stuff launches services-manager in about 4 sec, older stuff around 15-18).  The VMs are Xen PV running under a SLES 11 SP4 Dom0 (Xen 4.4.4) and are configured with 2x vCPU and 1GB RAM.  Performance of the VMs is otherwise fine.

I didn't have any 42.2 installations which were old enough to be pre-3.1.44, and I've updated my openSUSE autoyast profiles to 42.3 already, so the easiest test was to use my SLES autoyast profile to do a SLES 12 SP2 installation and not register it (so the update repo was not used and it still had yast2-services-manager 3.1.42).


== AutoYast time comparisons ==
See YaST logs (uploading soon) for details.  There seems to be three places where YaST
services-manager gets run:
* checking services before RPM installation
* users/security checking needed services
* applying autoyast services-manager settings (1st stage in 42.3; previously 2nd stage)

These are listed in the following table, plus total 1st & 2nd stage AutoYaST
times:
               | pre-RPM | users/sec | s-m  | AY 1st | AY 2nd | Total AY
---------------+---------+-----------+------+--------+--------+---------
SLES 12 SP2 VM |    0:39 |      1:26 | 0:18 |   8:48 |   1:32 |    10:20
Leap 42.3 VM   |    2:32 |      2:51 | 5:09 |  23:12 |   1:56 |    25:08
Leap 42.3 phys |    1:31 |      0:37 | 1:08 |  16:58 |   1:55 |    18:53

Also included are times from an AutoYast installation of 42.3 on old physical
hardware (slower CPU but more cores & RAM -- 8 x Xeon E5335 2.0 GHz, 16GB RAM).  As you can see, this is quite the increase in installation time for both physical and virtual, but the VM is much worse.

== yast2 services-manager time comparisons ==
Time taken to launch 'yast2 services-manager' in ncurses mode on the same
installations:
---------------+-------
SLES 12 SP2 VM |  0:05
Leap 42.3 VM   |  0:39
Leap 42.3 phys |  0:18
Comment 9 Andrew Daugherity 2017-08-16 19:02:18 UTC
Created attachment 736908 [details]
YaST logs for autoyast & services-manager, SLES 12 SP2 vs. Leap 42.3
Comment 10 Lukas Ocilka 2017-08-17 08:26:51 UTC
Great analysis, Andrew. Thank you!

FYI, Martin (new assignee) took over the tasks and he currently
works on the fix.
Comment 11 Ladislav Slezák 2017-09-05 07:16:51 UTC
*** Bug 1056961 has been marked as a duplicate of this bug. ***
Comment 12 Martin Vidner 2017-09-11 13:52:40 UTC
SLE12-SP3, Leap 42.3:

RPM: yast2-3.2.37.2
Git: https://github.com/yast/yast-yast2/pull/613
IBS: https://build.suse.de/request/show/140607

RPM: yast2-services-manager-3.2.2
Git: https://github.com/yast/yast-services-manager/pull/130
IBS: https://build.suse.de/request/show/140608

(Tumbleweed, SLE 15: Pending)
Comment 13 Josef Reidinger 2017-09-12 11:23:17 UTC
TW and SLE-15 merged. So closing.
Comment 14 Andrew Daugherity 2017-10-20 01:48:20 UTC
Is there an ETA on an update for this?  The bug was closed over a month ago but I haven't seen anything in 42.3-test yet (or Tumbleweed, for that matter), let alone 42.3-Updates or SLE12-SP3-Updates.  (And 42.2/SLE12-SP2 also need the fix.)

I did find some new packages in the OBS about a week ago (e.g. https://build.opensuse.org/package/show/YaST%3ASLE-12%3ASP3/yast2-services-manager) and after installing them, yast2 services-manager launches in 9 sec -- massive improvement.

Since a lot of this affects the 1st-stage installer, I created a DUD containing these two RPMs:
yast2-3.2.37.3-1.1.x86_64.rpm
yast2-services-manager-3.2.2-1.1.noarch.rpm

It definitely speeds up the installation, although it still takes significantly longer than SP2/42.2 did, including parts involving services-manager.  Something seems to make it go into one-by-one mode:
====
2017-10-19 20:22:20 <1> dhcp-116(9487) [Ruby] services-manager/services_manager_profile.rb:109 Extracted services from autoyast
profile: [#<struct Yast::ServicesManagerProfile::Service name="sshd", status="enable">]
2017-10-19 20:22:20 <1> dhcp-116(9487) [Ruby] modules/services_manager_target.rb:115 New default target has been set: multi-user
2017-10-19 20:22:20 <1> dhcp-116(9487) [Ruby] modules/services_manager_service.rb:350 List of services from autoyast profile: ["sshd"]
2017-10-19 20:22:21 <3> dhcp-116(9487) [bash] ShellCommand.cc(shellcommand):78 Failed to list units: Failed to execute program org.freedesktop.systemd1: Success
2017-10-19 20:22:21 <1> dhcp-116(9487) [Ruby] modules/systemd_service.rb:124 Retrying one by one
2017-10-19 20:22:21 <1> dhcp-116(9487) [Ruby] yast2/systemctl.rb:32 systemctl is-enabled YaST2-Firstboot.service
2017-10-19 20:22:21 <1> dhcp-116(9487) [Ruby] yast2/systemctl.rb:32 systemctl is-enabled YaST2-Second-Stage.service
[ hundreds more services, at the rate of 6 per second ]
====

Since SLES 12 SP3 has now been released, I also did some test installations with it.

Here are times matching the chart in c8:
               | pre-RPM | users/sec | s-m  | AY 1st | AY 2nd | Total AY
---------------+---------+-----------+------+--------+--------+---------
SLES 12 SP2 VM |    0:39 |      1:26 | 0:18 |   8:48 |   1:32 |    10:20
Leap 42.3 VM   |    2:32 |      2:51 | 5:09 |  23:12 |   1:56 |    25:08
(above copied from #c8)
----
42.3 + DUD     |    1:04 |      3:00 | 1:19 |  18:04 |   1:59 |    20:03
SLES 12 SP3    |    2:01 |      1:39 | 2:59 |  15:44 |   1:25 |    17:09
SP3 + DUD      |    0:47 |      1:40 | 0:43 |  12:33 |   1:32 |    14:05
(all 5 of these are on the same VM configuration; not sure why Leap is slower than SLE)
Comment 15 Swamp Workflow Management 2018-03-07 23:10:11 UTC
SUSE-RU-2018:0634-1: An update that has 10 recommended fixes can now be installed.

Category: recommended (moderate)
Bug References: 1037214,1037891,1045658,1049138,1058376,1061306,1064437,1075535,1077310,956755
CVE References: 
Sources used:
SUSE Linux Enterprise Server 12-SP3 (src):    yast2-3.2.43-3.20.4, yast2-nfs-client-3.1.18-1.1, yast2-services-manager-3.2.2-2.4.3
SUSE Linux Enterprise Desktop 12-SP3 (src):    yast2-3.2.43-3.20.4, yast2-nfs-client-3.1.18-1.1, yast2-services-manager-3.2.2-2.4.3
Comment 16 Swamp Workflow Management 2018-03-09 11:13:40 UTC
openSUSE-RU-2018:0649-1: An update that has 10 recommended fixes can now be installed.

Category: recommended (moderate)
Bug References: 1037214,1037891,1045658,1049138,1058376,1061306,1064437,1075535,1077310,956755
CVE References: 
Sources used:
openSUSE Leap 42.3 (src):    yast2-3.2.43-2.3.1, yast2-nfs-client-3.1.18-4.3.1, yast2-services-manager-3.2.2-2.3.1