salt 2018.3.2 py3 on Ubuntu 18.04 takes a long time to run test.true

[kartiksubbarao]

I'm running salt 2018.3.2+ds-1 with python 3 on Ubuntu 18.04, and am finding that it takes over 5 seconds to run salt-call --local test.true. If I use --skip-grains, it cuts the time down to 1 second (which is still somewhat slower than expected). While searching around I came across #26255, but in my case the number of file descriptors isn't the issue -- setting ulimit -n 1024 doesn't fix it. Here's the output from both runs. The numerous Depends decorator instantiated... messages seem to chew up most of the time.

time salt-call --local test.true -l trace

[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Changed git to gitfs in minion opts' fileserver_backend list
[DEBUG   ] Using cached minion ID from /etc/salt/minion_id: [...]
[TRACE   ] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
[TRACE   ] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
[DEBUG   ] Configuration file path: /etc/salt/minion
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Grains refresh requested. Refreshing grains.
[DEBUG   ] Reading configuration from /etc/salt/minion
[TRACE   ] 'drill' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
[TRACE   ] 'esxcli' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (True,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Depends decorator instantiated with dep list of (False,)
[TRACE   ] Error loading grains.napalm: "napalm"" (/usr/lib/python3/dist-packages/salt/grains/__pycache__/napalm.cpython-36.pyc) cannot be loaded: NAPALM is not installed or not running in a (proxy) minion
[TRACE   ] Loading core.append_domain grain
[TRACE   ] Loading core.default_gateway grain
[TRACE   ] Loading core.dns grain
[TRACE   ] Loading core.get_machine_id grain
[TRACE   ] Loading core.get_master grain
[TRACE   ] Loading core.get_server_id grain
[TRACE   ] Loading core.hostname grain
[TRACE   ] Loading core.hwaddr_interfaces grain
[TRACE   ] Loading core.id_ grain
[TRACE   ] Loading core.ip4_interfaces grain
[TRACE   ] Loading core.ip6_interfaces grain
[TRACE   ] Loading core.ip_fqdn grain
[TRACE   ] Loading core.ip_interfaces grain
[TRACE   ] Loading core.linux_distribution grain
[TRACE   ] Loading core.locale_info grain
[TRACE   ] Loading core.os_data grain
[TRACE   ] Loading core.path grain
[TRACE   ] Loading core.pythonexecutable grain
[TRACE   ] Loading core.pythonpath grain
[TRACE   ] Loading core.pythonversion grain
[TRACE   ] Loading core.saltpath grain
[TRACE   ] Loading core.saltversion grain
[TRACE   ] Loading core.saltversioninfo grain
[TRACE   ] Loading core.zmqversion grain
[TRACE   ] Loading disks.disks grain
[TRACE   ] Device loop1 reports itself as an HDD
[TRACE   ] Device loop6 reports itself as an HDD
[TRACE   ] Device loop4 reports itself as an HDD
[TRACE   ] Device sr0 reports itself as an HDD
[TRACE   ] Device loop2 reports itself as an HDD
[TRACE   ] Device loop0 reports itself as an HDD
[TRACE   ] Device loop7 reports itself as an HDD
[TRACE   ] Device vda reports itself as an HDD
[TRACE   ] Device loop5 reports itself as an HDD
[TRACE   ] Device loop3 reports itself as an HDD
[TRACE   ] Loading extra.config grain
[DEBUG   ] Loading static grains from /etc/salt/grains
[TRACE   ] Loading extra.shell grain
[TRACE   ] Loading mdadm.mdadm grain
[TRACE   ] Loading minion_process.grains grain
[TRACE   ] Loading opts.opts grain
[TRACE   ] Loading zfs.zfs grain
[TRACE   ] 'zfs-fuse' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
[TRACE   ] 'zpool' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
[DEBUG   ] Determining pillar cache
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[TRACE   ] Depends decorator instantiated with dep list of ('non_existantmodulename',)
[TRACE   ] Unloading test.missing_func because dependency (non_existantmodulename) is not imported
[DEBUG   ] LazyLoaded test.true
[DEBUG   ] LazyLoaded nested.output
[TRACE   ] data = {'local': True}
local:
    True
5.48user 0.19system 0:05.67elapsed 100%CPU (0avgtext+0avgdata 62488maxresident)k
0inputs+8outputs (0major+53578minor)pagefaults 0swaps

time salt-call --local --skip-grains test.true -l trace

[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Changed git to gitfs in minion opts' fileserver_backend list
[DEBUG   ] Using cached minion ID from /etc/salt/minion_id: [...]
[TRACE   ] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
[TRACE   ] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
[DEBUG   ] Configuration file path: /etc/salt/minion
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Grains refresh requested. Refreshing grains.
[DEBUG   ] Determining pillar cache
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[TRACE   ] Depends decorator instantiated with dep list of ('non_existantmodulename',)
[TRACE   ] Unloading test.missing_func because dependency (non_existantmodulename) is not imported
[DEBUG   ] LazyLoaded test.true
[DEBUG   ] LazyLoaded nested.output
[TRACE   ] data = {'local': True}
local:
    True
1.06user 0.11system 0:01.18elapsed 99%CPU (0avgtext+0avgdata 58560maxresident)k
0inputs+24outputs (0major+28912minor)pagefaults 0swaps

Versions Report

Salt Version:
           Salt: 2018.3.2
 
Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: 2.6.1
      docker-py: Not Installed
          gitdb: 2.0.3
      gitpython: 2.1.8
          ioflo: Not Installed
         Jinja2: 2.10
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 3.6.5 (default, Apr  1 2018, 05:46:30)
   python-gnupg: 0.4.1
         PyYAML: 3.12
          PyZMQ: 16.0.2
           RAET: Not Installed
          smmap: 2.0.3
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.2.5
 
System Versions:
           dist: Ubuntu 18.04 bionic
         locale: UTF-8
        machine: x86_64
        release: 4.15.0-23-generic
         system: Linux
        version: Ubuntu 18.04 bionic

[Ch3LL]

i am not seeing >5 seconds when I attempt to replicate i'm seeing about 3 seconds, but still longer then we want.

I believe you are right I believe the culprit is the @depends decorator particularly in the vsphere.py file. If i remove that file my time goes back down to 0.94s

ping @saltstack/team-cloud is there a reason we are using this decorator instead of handling the dependencies in virtual?

[gtmanfred]

@Depends allows for using some functions inside of a module when others cant be used.

__virtual__ cannot specify which functions can be used even if the main library is not installed.

For example, lets say part of a module uses a commandline utility, and the other functions actually use the imported library. and then lets say that you can only pip install the python package on 2.7, 3.5 and 3.6, centos 7 uses python3.4, so you can never install for 3.4, so the stuff using the imported library cannot be used, but the stuff that can still use the command line utility can still be used if you just pip install it on 2.7.

That is why we use @Depends and @salt.utils.decorators.path.which.

Both of these are resolved at the load time though, so it should not affect already loaded modules, just the first time they are loaded for an instance. which is why it affects salt-call.

[angeloudy]

We are also seeing this problem and its causing us some grief. Although

Depends decorator instantiated with dep list of (False,)

only adds 6-7 seconds to every state run, some of our orchestrations are taking 10 minutes to execute instead of 2 minutes because all that overhead adds up.

@gtmanfred I don't quite understand your point about python versions, but if our environment is tightly controlled to use only a single python version, is there any workaround to avoid the poor performance behaviour?

[angeloudy]

After I configured disable_modules on the minion

disable_modules:
  - vsphere
  - esxi
  - esxcli

, it runs a little bit faster, but still quite slow. I can still see @Depends in the trace. It seems disable_modules does not prevent loading the module.

[gtmanfred]

Sure, you may only use one python version, but we are supporting several.

[gtmanfred]

How long does it take to run when you run the salt-minion and make the calls through the publish bus from the master using salt <minion> test.true?

[angeloudy]

There's no difference if I run salt-call or salt <minion> on the master(probably a few ms ).
I have now made it much faster by adding grains_cache: True to the minion config.

[max-arnold]

@kartiksubbarao Could you try undocumented disable_grains minion option?

disable_grains:
  - esxi

disable_modules:
  - vsphere

[kartiksubbarao]

@max-arnold That definitely helps. I ran a comparison just now, it cuts down the runtime from 6 seconds to 1.7 seconds.

[stromnet]

FYI; I have had the same slowness issues on multiple FreeBSD 11.2 machines with salt 2019.2.0.

Adding disabled_grains & disabled_modules (both vsphare and esxi* as from examples above) gave great performance boost in running pretty simple states, with a total execution time from ~15-30s down to ~3s for 2 local hosts.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

If this issue is closed prematurely, please leave a comment and we will gladly reopen the issue.

[bobrik]

I don't think this should've been closed. The issue still exists in the latest release.

[bobrik]

I opened #57062 to fix this for good.