salt: Remote state execution is much slower on 2016.11.1 compared to 2016.3.4

Description of Issue/Question

Master:

Salt Version:
           Salt: 2016.11.1

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: 2.2
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.8
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.2
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
         pygit2: Not Installed
         Python: 2.7.9 (default, Jun 29 2016, 13:08:31)
   python-gnupg: 0.3.6
         PyYAML: 3.11
          PyZMQ: 14.4.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.0.5

System Versions:
           dist: debian 8.6
        machine: x86_64
        release: 4.4.36-cloudflare
         system: Linux
        version: debian 8.6

Minion on 2016.3.4:

Salt Version:
           Salt: 2016.3.4

Dependency Versions:
           cffi: 0.8.6
       cherrypy: Not Installed
       dateutil: 2.2
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.8
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.2
   mysql-python: Not Installed
      pycparser: 2.10
       pycrypto: 2.6.1
         pygit2: Not Installed
         Python: 2.7.9 (default, Jun 29 2016, 13:08:31)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 14.4.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.0.5

System Versions:
           dist: debian 8.6
        machine: x86_64
        release: 4.4.36-cloudflare
         system: Linux
        version: debian 8.6

Minion on 2016.11.1:

Salt Version:
           Salt: 2016.11.1

Dependency Versions:
           cffi: 0.8.6
       cherrypy: Not Installed
       dateutil: 2.2
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.8
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.2
   mysql-python: Not Installed
      pycparser: 2.10
       pycrypto: 2.6.1
         pygit2: Not Installed
         Python: 2.7.9 (default, Jun 29 2016, 13:08:31)
   python-gnupg: Not Installed
         PyYAML: 3.11
          PyZMQ: 14.4.0
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.0.5

System Versions:
           dist: debian 8.6
        machine: x86_64
        release: 4.4.36-cloudflare
         system: Linux
        version: debian 8.6

Setup

Both machines are identical apart from salt minion versions.

Consider the following state:

/tmp/test.txt:
  file.managed:
    - source: salt://test/templates/test.txt

Both machines have comparable timings with salt-call:

ivan@salt-master:~$ sudo salt-master-pdx salt --output highstate -L salt-2016-11-1,salt-2016-3-4 cmd.run 'salt-call state.apply test'
salt-2016-11-1:
    local:
    ----------
              ID: /tmp/test.txt
        Function: file.managed
          Result: True
         Comment: File /tmp/test.txt is in the correct state
         Started: 00:31:58.971728
        Duration: 13.96 ms
         Changes:

    Summary for local
    ------------
    Succeeded: 1
    Failed:    0
    ------------
    Total states run:     1
    Total run time:  13.960 ms
salt-2016-3-4:
    local:
    ----------
              ID: /tmp/test.txt
        Function: file.managed
          Result: True
         Comment: File /tmp/test.txt is in the correct state
         Started: 00:31:59.359181
        Duration: 37.646 ms
         Changes:

    Summary for local
    ------------
    Succeeded: 1
    Failed:    0
    ------------
    Total states run:     1
    Total run time:  37.646 ms

Timings are dramatically different with salt call from master:

ivan@salt-master:~$ sudo salt-master-pdx salt --output highstate -L salt-2016-11-1,salt-2016-3-4 state.apply test
salt-2016-3-4:

Summary for salt-2016-3-4
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:  35.249 ms
salt-2016-11-1:

Summary for salt-2016-11-1
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   1.568 s

But they get the same without template:

/tmp/test.txt:
  file.managed:
    - contents: so sad

ivan@salt-master:~$ sudo salt-master-pdx salt --output highstate -L salt-2016-11-1,salt-2016-3-4 state.apply test
salt-2016-3-4:

Summary for salt-2016-3-4
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   8.456 ms
salt-2016-11-1:

Summary for salt-2016-11-1
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   6.039 ms

This gets very bad very quickly: 71s vs 750s for local vs remote mode on 2016.11.1.

Debug logs from minions:

  • 2016.3.4:
[INFO    ] Starting a new job with PID 3226
[DEBUG   ] LazyLoaded saltutil.find_job
[DEBUG   ] LazyLoaded direct_call.get
[DEBUG   ] Minion return retry timer set to 10 seconds (randomized)
[INFO    ] Returning information for job: 20170117003546157530
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'salt-2016-3-4', 'tcp://10.36.11.18:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt-2016-3-4', 'tcp://10.36.11.18:4506')
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] Could not find file from saltenv 'base', 'salt://test.sls'
[DEBUG   ] In saltenv 'base', looking at rel_path 'test/init.sls' to resolve 'salt://test/init.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/test/init.sls' to resolve 'salt://test/init.sls'
[DEBUG   ] Fetching file from saltenv 'base', ** attempting ** 'salt://test/init.sls'
[DEBUG   ] No dest file found
[INFO    ] Fetching file from saltenv 'base', ** done ** 'test/init.sls'
[DEBUG   ] compile template: /var/cache/salt/minion/files/base/test/init.sls
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test/init.sls' using 'jinja' renderer: 0.00490188598633
[DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/test/init.sls:
/tmp/test.txt:
  file.managed:
#    - contents: so sad
    - source: salt://test/templates/test.txt

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering:
OrderedDict([('/tmp/test.txt', OrderedDict([('file.managed', [OrderedDict([('source', 'salt://test/templates/test.txt')])])]))])
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test/init.sls' using 'yaml' renderer: 0.0020899772644
[DEBUG   ] LazyLoaded file.managed
[INFO    ] Running state [/tmp/test.txt] at time 00:35:53.662503
[INFO    ] Executing state file.managed for /tmp/test.txt
[DEBUG   ] LazyLoaded file.source_list
[DEBUG   ] LazyLoaded cp.hash_file
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'salt-2016-3-4', 'tcp://10.36.11.18:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt-2016-3-4', 'tcp://10.36.11.18:4506')
[DEBUG   ] In saltenv 'base', looking at rel_path 'test/templates/test.txt' to resolve 'salt://test/templates/test.txt'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/test/templates/test.txt' to resolve 'salt://test/templates/test.txt'
[DEBUG   ] Fetching file from saltenv 'base', ** attempting ** 'salt://test/templates/test.txt'
[DEBUG   ] No dest file found
[INFO    ] Fetching file from saltenv 'base', ** done ** 'test/templates/test.txt'
[INFO    ] File /tmp/test.txt is in the correct state
[INFO    ] Completed state [/tmp/test.txt] at time 00:35:53.706404 duration_in_ms=43.901
[DEBUG   ] File /var/cache/salt/minion/accumulator/140439475305104 does not exist, no need to cleanup.
[DEBUG   ] Minion return retry timer set to 9 seconds (randomized)
[INFO    ] Returning information for job: 20170117003531051037
  • 2016.11.1:
[INFO    ] Starting a new job with PID 20435
[DEBUG   ] LazyLoaded saltutil.find_job
[DEBUG   ] LazyLoaded direct_call.get
[DEBUG   ] Minion return retry timer set to 9 seconds (randomized)
[INFO    ] Returning information for job: 20170117003556166921
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'salt-2016-11-1', 'tcp://10.36.11.18:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt-2016-11-1', 'tcp://10.36.11.18:4506')
[DEBUG   ] In saltenv 'base', looking at rel_path 'test/init.sls' to resolve 'salt://test/init.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/test/init.sls' to resolve 'salt://test/init.sls'
[DEBUG   ] Fetching file from saltenv 'base', ** attempting ** 'salt://test/init.sls'
[DEBUG   ] No dest file found
[INFO    ] Fetching file from saltenv 'base', ** done ** 'test/init.sls'
[DEBUG   ] compile template: /var/cache/salt/minion/files/base/test/init.sls
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test/init.sls' using 'jinja' renderer: 0.00338506698608
[DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/test/init.sls:
/tmp/test.txt:
  file.managed:
#    - contents: so sad
    - source: salt://test/templates/test.txt

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering:
OrderedDict([('/tmp/test.txt', OrderedDict([('file.managed', [OrderedDict([('source', 'salt://test/templates/test.txt')])])]))])
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test/init.sls' using 'yaml' renderer: 0.00159597396851
[DEBUG   ] LazyLoaded file.managed
[INFO    ] Running state [/tmp/test.txt] at time 00:35:58.212000
[INFO    ] Executing state file.managed for /tmp/test.txt
[DEBUG   ] LazyLoaded file.source_list
[DEBUG   ] LazyLoaded cp.hash_file
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'salt-2016-11-1', 'tcp://10.36.11.18:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt-2016-11-1', 'tcp://10.36.11.18:4506')
[DEBUG   ] In saltenv 'base', looking at rel_path 'test/templates/test.txt' to resolve 'salt://test/templates/test.txt'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/test/templates/test.txt' to resolve 'salt://test/templates/test.txt'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://test/templates/test.txt', mode up-to-date
[INFO    ] File /tmp/test.txt is in the correct state
[INFO    ] Completed state [/tmp/test.txt] at time 00:35:59.820315 duration_in_ms=1608.315
[DEBUG   ] File /var/cache/salt/minion/accumulator/140688738910288 does not exist, no need to cleanup.
[DEBUG   ] Minion return retry timer set to 10 seconds (randomized)
[INFO    ] Returning information for job: 20170117003531051037

About this issue

  • Original URL
  • State: closed
  • Created 7 years ago
  • Comments: 16 (16 by maintainers)

Most upvoted comments

@cachedout, I did a test run for a state with many templates and yuge complex pillar.

  • 2016.11.1 without the patch applied (I almost fell asleep):

    --------------
Succeeded: 175 (unchanged=2, changed=1)
Failed:      0
--------------
Total states run:     175
Total run time:   240.048 s

real	5m5.030s
user	0m4.075s
sys	0m0.375s

  • 2016.11.1 with the patch applied:

    --------------
Succeeded: 175 (unchanged=2, changed=1)
Failed:      0
--------------
Total states run:     175
Total run time:     8.280 s

real	0m58.984s
user	0m1.094s
sys	0m0.219s

Looking forward to upgrading to 2016.11.3 with this patch applied.

+2
bobrik on Feb 19, 2017
Read more comments on GitHub
← salt: Release notes for v3000 do not mention changes to `slspath` variable
salt: Rendering SLS 'base:XXXXX' failed: found unexpected ':' →