Pillar rendering blocks file fetches

[bobrik]

Description of Issue/Question

Long pillar rendering blocks unrelated requests like file fetches, even though there are multiple idle workers.

Setup

Have the following external pillar that simulates 5s rendering time:

import time
import os

def ext_pillar(minion_id, pillar, *args):
    time.sleep(5)
    return {'pid': os.getpid()}

Have the following state that install 10 files:

$ tree -h states/derp
states/derp
|-- [  96]  files
|   |-- [   0]  0
|   |-- [   0]  1
|   |-- [   0]  2
|   |-- [   0]  3
|   |-- [   0]  4
|   |-- [   0]  5
|   |-- [   0]  6
|   |-- [   0]  7
|   |-- [   0]  8
|   `-- [   0]  9
`-- [ 113]  init.sls

1 directory, 11 files

{% for i in range(10) %}
/tmp/derp-{{ i }}:
  file.managed:
    - source: salt://derp/files/{{ i }}
{% endfor %}

Steps to Reproduce Issue

Ping master continuously from one terminal:

$ while true; do /usr/bin/time -f '>> real %e / user %U / sys %S' sudo salt-call --output txt test.ping || break; done
local: True
>> real 6.77 / user 0.80 / sys 0.37
local: True
>> real 6.76 / user 0.82 / sys 0.39
local: True
>> real 7.93 / user 0.78 / sys 0.39
local: True
>> real 6.89 / user 0.78 / sys 0.38
local: True
...

Run the state from another terminal:

$ sudo rm -f /tmp/derp-*; /usr/bin/time -f '>> real %e / user %U / sys %S' sudo salt-call --log-level info state.apply derp

From time to time state will hung for the duration of pillar render:

[INFO    ] Completed state [/tmp/derp-0] at time 04:10:40.226489 duration_in_ms=115.981
[INFO    ] Completed state [/tmp/derp-1] at time 04:10:40.285079 duration_in_ms=58.326
[INFO    ] Completed state [/tmp/derp-2] at time 04:10:40.343943 duration_in_ms=58.551
[INFO    ] Completed state [/tmp/derp-3] at time 04:10:40.402265 duration_in_ms=58.051
[INFO    ] Completed state [/tmp/derp-4] at time 04:10:40.460659 duration_in_ms=58.126
[INFO    ] Completed state [/tmp/derp-5] at time 04:10:40.519086 duration_in_ms=58.181
[INFO    ] Completed state [/tmp/derp-6] at time 04:10:40.577988 duration_in_ms=58.623
[INFO    ] Completed state [/tmp/derp-7] at time 04:10:45.615252 duration_in_ms=5036.928
[INFO    ] Completed state [/tmp/derp-8] at time 04:10:45.700198 duration_in_ms=84.685
[INFO    ] Completed state [/tmp/derp-9] at time 04:10:45.758285 duration_in_ms=57.868

This is SUPER painful if pillar takes a long time to render and state fetches tons of files from master.

Ideally we'd want for fetch requests to be picked up by any available worker.

Versions Report

Master is in Docker:

$ salt-master --versions
Salt Version:
           Salt: 2017.7.2

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: 2.5.3
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.9.4
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.8
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.13 (default, Nov 24 2017, 17:33:09)
   python-gnupg: 0.3.9
         PyYAML: 3.12
          PyZMQ: 16.0.2
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.4.3
            ZMQ: 4.2.1

System Versions:
           dist: debian 9.4
         locale: ANSI_X3.4-1968
        machine: x86_64
        release: 4.14.15-cloudflare-2018.2.0
         system: Linux
        version: debian 9.4

Minion is on bare metal:

$ salt-call --versions
Salt Version:
           Salt: 2017.7.2

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: 2.5.3
      docker-py: Not Installed
          gitdb: Not Installed
      gitpython: Not Installed
          ioflo: Not Installed
         Jinja2: 2.9.4
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.8
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.13 (default, Sep 26 2018, 18:42:22)
   python-gnupg: Not Installed
         PyYAML: 3.12
          PyZMQ: 16.0.2
           RAET: Not Installed
          smmap: Not Installed
        timelib: Not Installed
        Tornado: 4.4.3
            ZMQ: 4.2.1

System Versions:
           dist: debian 9.7
         locale: UTF-8
        machine: x86_64
        release: 4.19.18-cloudflare-2019.1.9
         system: Linux
        version: debian 9.7

[bobrik]

Ideally we'd want for fetch requests to be picked up by any available worker.

Alternatively, one active connection per worker model may be used.

[dwoz]

@bobrik Thanks for reporting this.

[stale[bot]]

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]

Pretty sure this is still an issue.

[stale[bot]]

Thank you for updating this issue. It is no longer marked as stale.

[bobrik]

Looks like the issue is limited to zmq transport! My test configuration is a master with two workers and two salt-call loops on the same machine. The idea is that I don't have more clients than I have workers, which means that there is room for every request to be serviced in parallel.

With tcp transport:

local: True
>> real 5.61 / user 0.45 / sys 0.10
local: True
>> real 5.60 / user 0.47 / sys 0.10
local: True
>> real 5.59 / user 0.45 / sys 0.10
local: True
>> real 5.62 / user 0.48 / sys 0.10
local: True
>> real 5.62 / user 0.47 / sys 0.11
local: True
>> real 5.60 / user 0.45 / sys 0.10
local: True
>> real 5.60 / user 0.46 / sys 0.09
local: True
>> real 5.59 / user 0.46 / sys 0.09
local: True
>> real 5.60 / user 0.47 / sys 0.09
local: True
>> real 5.59 / user 0.45 / sys 0.10
local: True
>> real 5.59 / user 0.46 / sys 0.09
local: True
>> real 5.59 / user 0.47 / sys 0.09
local: True
>> real 5.60 / user 0.45 / sys 0.10
local: True
>> real 5.71 / user 0.46 / sys 0.10
local: True
>> real 5.59 / user 0.46 / sys 0.10
local: True
>> real 5.60 / user 0.45 / sys 0.10
local: True
>> real 5.59 / user 0.45 / sys 0.10
local: True
>> real 5.60 / user 0.46 / sys 0.10
local: True
>> real 5.58 / user 0.44 / sys 0.10
local: True
>> real 5.59 / user 0.43 / sys 0.11
local: True
>> real 5.59 / user 0.46 / sys 0.09
local: True
>> real 5.63 / user 0.46 / sys 0.10
local: True
>> real 5.59 / user 0.46 / sys 0.10
local: True
>> real 5.59 / user 0.45 / sys 0.10
local: True
>> real 5.64 / user 0.50 / sys 0.09
local: True
>> real 5.59 / user 0.45 / sys 0.10

With zmq transport:

local: True
>> real 17.28 / user 0.47 / sys 0.11
local: True
>> real 5.63 / user 0.48 / sys 0.10
local: True
>> real 10.08 / user 0.46 / sys 0.10
local: True
>> real 10.10 / user 0.48 / sys 0.11
local: True
>> real 10.10 / user 0.47 / sys 0.09
local: True
>> real 10.10 / user 0.46 / sys 0.10
local: True
>> real 10.10 / user 0.46 / sys 0.10
local: True
>> real 10.10 / user 0.47 / sys 0.10
local: True
>> real 10.09 / user 0.46 / sys 0.10
local: True
>> real 10.12 / user 0.46 / sys 0.10
local: True
>> real 10.11 / user 0.47 / sys 0.09
local: True
>> real 10.10 / user 0.44 / sys 0.12
local: True
>> real 10.10 / user 0.46 / sys 0.10
local: True
>> real 10.11 / user 0.55 / sys 0.09
local: True
>> real 10.09 / user 0.45 / sys 0.11
local: True
>> real 10.11 / user 0.48 / sys 0.09
local: True
>> real 10.10 / user 0.46 / sys 0.10
local: True
>> real 10.11 / user 0.47 / sys 0.10
local: True
>> real 10.09 / user 0.46 / sys 0.09
local: True
>> real 10.10 / user 0.47 / sys 0.08
local: True
>> real 10.10 / user 0.47 / sys 0.09

I'm still on 2017.7.8.