{"action":"created","issue":{"url":"https://api.github.com/repos/saltstack/salt/issues/37217","repository_url":"https://api.github.com/repos/saltstack/salt","labels_url":"https://api.github.com/repos/saltstack/salt/issues/37217/labels{/name}","comments_url":"https://api.github.com/repos/saltstack/salt/issues/37217/comments","events_url":"https://api.github.com/repos/saltstack/salt/issues/37217/events","html_url":"https://github.com/saltstack/salt/issues/37217","id":185075029,"number":37217,"title":"State is slower than cmd.run","user":{"login":"szin2012","id":3438471,"avatar_url":"https://avatars.githubusercontent.com/u/3438471?v=3","gravatar_id":"","url":"https://api.github.com/users/szin2012","html_url":"https://github.com/szin2012","followers_url":"https://api.github.com/users/szin2012/followers","following_url":"https://api.github.com/users/szin2012/following{/other_user}","gists_url":"https://api.github.com/users/szin2012/gists{/gist_id}","starred_url":"https://api.github.com/users/szin2012/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/szin2012/subscriptions","organizations_url":"https://api.github.com/users/szin2012/orgs","repos_url":"https://api.github.com/users/szin2012/repos","events_url":"https://api.github.com/users/szin2012/events{/privacy}","received_events_url":"https://api.github.com/users/szin2012/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/saltstack/salt/labels/Info%20Needed","name":"Info Needed","color":"c7def8"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":{"url":"https://api.github.com/repos/saltstack/salt/milestones/37","html_url":"https://github.com/saltstack/salt/milestones/Blocked","labels_url":"https://api.github.com/repos/saltstack/salt/milestones/37/labels","id":343741,"number":37,"title":"Blocked","description":"Issues which are blocked in some way, whether they need further discussion, clarification, justification, or are blocked for some other reason.","creator":{"login":"basepi","id":702318,"avatar_url":"https://avatars.githubusercontent.com/u/702318?v=3","gravatar_id":"","url":"https://api.github.com/users/basepi","html_url":"https://github.com/basepi","followers_url":"https://api.github.com/users/basepi/followers","following_url":"https://api.github.com/users/basepi/following{/other_user}","gists_url":"https://api.github.com/users/basepi/gists{/gist_id}","starred_url":"https://api.github.com/users/basepi/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/basepi/subscriptions","organizations_url":"https://api.github.com/users/basepi/orgs","repos_url":"https://api.github.com/users/basepi/repos","events_url":"https://api.github.com/users/basepi/events{/privacy}","received_events_url":"https://api.github.com/users/basepi/received_events","type":"User","site_admin":false},"open_issues":623,"closed_issues":1071,"state":"open","created_at":"2013-05-28T22:24:12Z","updated_at":"2016-10-25T20:29:57Z","due_on":null,"closed_at":null},"comments":1,"created_at":"2016-10-25T10:15:14Z","updated_at":"2016-10-26T04:06:24Z","closed_at":null,"body":"### Description of Issue/Question\r\n\r\nwhy State is slower than cmd.run How to speed up, thanks all.\r\n\r\n### Setup\r\n\r\n\r\n1 :\r\n\r\n```\r\n[root@localhost salt]# time salt '102' state.sls action1\r\n102:\r\n----------\r\n          ID: action\r\n    Function: cmd.run\r\n        Name: w\r\n      Result: True\r\n     Comment: Command \"w\" run\r\n     Started: 17:09:17.734251\r\n    Duration: 17.366 ms\r\n     Changes:   \r\n              ----------\r\n              pid:\r\n                  13560\r\n              retcode:\r\n                  0\r\n              stderr:\r\n              stdout:\r\n                   17:09:17 up 17 days,  6:27,  2 users,  load average: 0.06, 0.02, 0.00\r\n                  USER     TTY      FROM              LOGIN@   IDLE   JCPU   PCPU WHAT\r\n                  root     pts/1    192.168.70.61    14:38    1:14m  0.08s  0.06s tail -f /var/lo\r\n                  root     pts/3    192.168.70.61    15:59   12:41   0.04s  0.04s -bash\r\n\r\nSummary\r\n------------\r\nSucceeded: 1 (changed=1)\r\nFailed:    0\r\n------------\r\nTotal states run:     1\r\n\r\nreal\t0m18.330s\r\nuser\t0m0.702s\r\nsys\t0m0.111s\r\n```\r\n\r\n2: \r\n\r\n```\r\n[root@localhost salt]# time salt '102' cmd.run w\r\n102:\r\n     17:09:28 up 17 days,  6:27,  2 users,  load average: 0.05, 0.01, 0.00\r\n    USER     TTY      FROM              LOGIN@   IDLE   JCPU   PCPU WHAT\r\n    root     pts/1    192.168.70.61    14:38    1:14m  0.08s  0.06s tail -f /var/lo\r\n    root     pts/3    192.168.70.61    15:59   12:52   0.04s  0.04s -bash\r\n\r\nreal\t0m0.684s\r\nuser\t0m0.451s\r\nsys\t0m0.034s\r\n```\r\n\r\n3:\r\n\r\n```\r\n[root@localhost salt]# cat action1.sls \r\naction:\r\n  cmd.run:\r\n    - name: w\r\n```\r\n \r\n### Versions Report\r\n\r\n```\r\n[root@localhost salt]# salt --versions-report\r\n           Salt: 2015.5.10\r\n         Python: 2.6.6 (r266:84292, Aug 18 2016, 15:13:37)\r\n         Jinja2: 2.8\r\n       M2Crypto: 0.20.2\r\n msgpack-python: 0.4.6\r\n   msgpack-pure: Not Installed\r\n       pycrypto: 2.6.1\r\n        libnacl: Not Installed\r\n         PyYAML: 3.10\r\n          ioflo: Not Installed\r\n          PyZMQ: 14.3.1\r\n           RAET: Not Installed\r\n            ZMQ: 3.2.5\r\n           Mako: Not Installed\r\n        Tornado: 4.2.1\r\n        timelib: Not Installed\r\n       dateutil: 1.4.1\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/saltstack/salt/issues/comments/256244442","html_url":"https://github.com/saltstack/salt/issues/37217#issuecomment-256244442","issue_url":"https://api.github.com/repos/saltstack/salt/issues/37217","id":256244442,"user":{"login":"szin2012","id":3438471,"avatar_url":"https://avatars.githubusercontent.com/u/3438471?v=3","gravatar_id":"","url":"https://api.github.com/users/szin2012","html_url":"https://github.com/szin2012","followers_url":"https://api.github.com/users/szin2012/followers","following_url":"https://api.github.com/users/szin2012/following{/other_user}","gists_url":"https://api.github.com/users/szin2012/gists{/gist_id}","starred_url":"https://api.github.com/users/szin2012/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/szin2012/subscriptions","organizations_url":"https://api.github.com/users/szin2012/orgs","repos_url":"https://api.github.com/users/szin2012/repos","events_url":"https://api.github.com/users/szin2012/events{/privacy}","received_events_url":"https://api.github.com/users/szin2012/received_events","type":"User","site_admin":false},"created_at":"2016-10-26T04:06:23Z","updated_at":"2016-10-26T04:06:23Z","body":"@timcharper Thank your support\r\n\r\n```[root@localhost model]# date +\"%Y-%m-%d %H:%M:%S,%N\";time salt '102' state.sls action1\r\n2016-10-26 12:04:12,056070507\r\n102:\r\n----------\r\n          ID: action\r\n    Function: cmd.run\r\n        Name: w\r\n      Result: True\r\n     Comment: Command \"w\" run\r\n     Started: 12:04:24.082187\r\n    Duration: 17.41 ms\r\n     Changes:   \r\n              ----------\r\n              pid:\r\n                  17688\r\n              retcode:\r\n                  0\r\n              stderr:\r\n              stdout:\r\n                   12:04:24 up 18 days,  1:23,  2 users,  load average: 0.06, 0.02, 0.00\r\n                  USER     TTY      FROM              LOGIN@   IDLE   JCPU   PCPU WHAT\r\n                  root     pts/1    192.168.70.61    Tue14    1:27m  0.05s  0.03s tail -f /var/lo\r\n                  root     pts/3    192.168.70.61    Tue15   21.00s  0.09s  0.09s -bash\r\n\r\nSummary\r\n------------\r\nSucceeded: 1 (changed=1)\r\nFailed:    0\r\n------------\r\nTotal states run:     1\r\n\r\nreal\t0m11.779s\r\nuser\t0m0.632s\r\nsys\t0m0.091s```\r\n\r\n\r\nminion log \r\n\r\n```2016-10-26 12:04:13,014 [salt.minion                              ][INFO    ][17615] User root Executing command state.sls with jid 20161026120412536356\r\n2016-10-26 12:04:13,014 [salt.minion                              ][DEBUG   ][17615] Command details {'tgt_type': 'glob', 'jid': '20161026120412536356', 'tgt': '102', 'ret': '', 'user': 'root', 'arg': ['action1'], 'fun': 'state.sls'}\r\n2016-10-26 12:04:13,026 [salt.minion                              ][INFO    ][17666] Starting a new job with PID 17666\r\n2016-10-26 12:04:13,039 [salt.utils.lazy                          ][DEBUG   ][17666] LazyLoaded state.sls\r\n2016-10-26 12:04:13,057 [salt.utils.lazy                          ][DEBUG   ][17666] LazyLoaded saltutil.is_running\r\n2016-10-26 12:04:13,059 [salt.utils.lazy                          ][DEBUG   ][17666] LazyLoaded grains.get\r\n2016-10-26 12:04:13,061 [salt.crypt                               ][DEBUG   ][17666] Re-using SAuth for ('/etc/salt/pki/minion', '102', 'tcp://192.168.70.77:4506')\r\n2016-10-26 12:04:13,489 [salt.config                              ][DEBUG   ][17666] Reading configuration from /etc/salt/minion\r\n2016-10-26 12:04:13,580 [salt.config                              ][DEBUG   ][17666] Including configuration from '/etc/salt/minion.d/_schedule.conf'\r\n2016-10-26 12:04:13,580 [salt.config                              ][DEBUG   ][17666] Reading configuration from /etc/salt/minion.d/_schedule.conf\r\n2016-10-26 12:04:18,028 [salt.minion                              ][INFO    ][17615] User root Executing command saltutil.find_job with jid 20161026120417544821\r\n2016-10-26 12:04:18,028 [salt.minion                              ][DEBUG   ][17615] Command details {'tgt_type': 'glob', 'jid': '20161026120417544821', 'tgt': '102', 'ret': '', 'user': 'root', 'arg': ['20161026120412536356'], 'fun': 'saltutil.find_job'}\r\n2016-10-26 12:04:18,041 [salt.minion                              ][INFO    ][17673] Starting a new job with PID 17673\r\n2016-10-26 12:04:18,068 [salt.utils.lazy                          ][DEBUG   ][17673] LazyLoaded saltutil.find_job\r\n2016-10-26 12:04:18,072 [salt.minion                              ][DEBUG   ][17673] Minion return retry timer set to 7 seconds (randomized)\r\n2016-10-26 12:04:18,072 [salt.minion                              ][INFO    ][17673] Returning information for job: 20161026120417544821\r\n2016-10-26 12:04:18,073 [salt.crypt                               ][DEBUG   ][17673] Re-using SAuth for ('/etc/salt/pki/minion', '102', 'tcp://192.168.70.77:4506')\r\n2016-10-26 12:04:23,995 [salt.crypt                               ][DEBUG   ][17666] Re-using SAuth for ('/etc/salt/pki/minion', '102', 'tcp://192.168.70.77:4506')\r\n2016-10-26 12:04:24,013 [salt.crypt                               ][DEBUG   ][17666] Loaded minion key: /etc/salt/pki/minion/minion.pem\r\n2016-10-26 12:04:24,029 [salt.state                               ][INFO    ][17666] Loading fresh modules for state activity\r\n2016-10-26 12:04:24,053 [salt.utils.lazy                          ][DEBUG   ][17666] LazyLoaded jinja.render\r\n2016-10-26 12:04:24,055 [salt.utils.lazy                          ][DEBUG   ][17666] LazyLoaded yaml.render\r\n2016-10-26 12:04:24,067 [salt.fileclient                          ][INFO    ][17666] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://action1.sls'\r\n2016-10-26 12:04:24,068 [salt.utils.jinja                         ][DEBUG   ][17666] Jinja search path: ['/var/cache/salt/minion/files/base']\r\n2016-10-26 12:04:24,076 [salt.template                            ][DEBUG   ][17666] Rendered data from file: /var/cache/salt/minion/files/base/action1.sls:\r\naction:\r\n  cmd.run:\r\n    - name: w\r\n\r\n2016-10-26 12:04:24,080 [salt.utils.lazy                          ][DEBUG   ][17666] LazyLoaded config.get\r\n2016-10-26 12:04:24,080 [salt.loaded.int.render.yaml              ][DEBUG   ][17666] Results of YAML rendering: \r\nOrderedDict([('action', OrderedDict([('cmd.run', [OrderedDict([('name', 'w')])])]))])\r\n2016-10-26 12:04:24,082 [salt.utils.lazy                          ][DEBUG   ][17666] LazyLoaded cmd.run\r\n2016-10-26 12:04:24,082 [salt.state                               ][INFO    ][17666] Running state [w] at time 12:04:24.082187\r\n2016-10-26 12:04:24,083 [salt.state                               ][INFO    ][17666] Executing state cmd.run for w\r\n2016-10-26 12:04:24,085 [salt.utils.lazy                          ][DEBUG   ][17666] LazyLoaded cmd.run_all\r\n2016-10-26 12:04:24,086 [salt.loaded.int.module.cmdmod            ][INFO    ][17666] Executing command 'w' in directory '/root'\r\n2016-10-26 12:04:24,098 [salt.loaded.int.module.cmdmod            ][DEBUG   ][17666] stdout:  12:04:24 up 18 days,  1:23,  2 users,  load average: 0.06, 0.02, 0.00\r\nUSER     TTY      FROM              LOGIN@   IDLE   JCPU   PCPU WHAT\r\nroot     pts/1    192.168.70.61    Tue14    1:27m  0.05s  0.03s tail -f /var/lo\r\nroot     pts/3    192.168.70.61    Tue15   21.00s  0.09s  0.09s -bash\r\n2016-10-26 12:04:24,099 [salt.state                               ][INFO    ][17666] {'pid': 17688, 'retcode': 0, 'stderr': '', 'stdout': ' 12:04:24 up 18 days,  1:23,  2 users,  load average: 0.06, 0.02, 0.00\\nUSER     TTY      FROM              LOGIN@   IDLE   JCPU   PCPU WHAT\\nroot     pts/1    192.168.70.61    Tue14    1:27m  0.05s  0.03s tail -f /var/lo\\nroot     pts/3    192.168.70.61    Tue15   21.00s  0.09s  0.09s -bash'}\r\n2016-10-26 12:04:24,100 [salt.state                               ][INFO    ][17666] Completed state [w] at time 12:04:24.099597\r\n2016-10-26 12:04:24,100 [salt.state                               ][DEBUG   ][17666] File /var/cache/salt/minion/accumulator/56340048 does not exist, no need to cleanup.\r\n2016-10-26 12:04:24,102 [salt.minion                              ][DEBUG   ][17666] Minion return retry timer set to 5 seconds (randomized)\r\n2016-10-26 12:04:24,102 [salt.minion                              ][INFO    ][17666] Returning information for job: 20161026120412536356\r\n2016-10-26 12:04:24,103 [salt.crypt                               ][DEBUG   ][17666] Re-using SAuth for ('/etc/salt/pki/minion', '102', 'tcp://192.168.70.77:4506')```"}}
{"actor":{"display_login":"szin2012"}}