search

saltstack / salt

Software to automate the management and configuration of any infrastructure or application at scale. Install Salt from the Salt package repositories here:
https://docs.saltproject.io/salt/install-guide/en/latest/
Apache License 2.0
14.19k stars 5.48k forks source link

reduce state.sls excute time #30498

Closed freedba closed 8 years ago

freedba commented 8 years ago 
2016-01-21 17:38:05,550 [salt.minion                                   ][INFO    ][19813] User root Executing command test.ping with jid 20160121173805267254
2016-01-21 17:38:05,550 [salt.minion                                   ][DEBUG   ][19813] Command details {'tgt_type': 'glob', 'jid': '20160121173805267254', 'tgt': 'stage-static01.idc1.fn', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'test.ping'}
2016-01-21 17:38:05,560 [salt.minion                                   ][INFO    ][25688] Starting a new job with PID 25688
2016-01-21 17:38:05,608 [salt.utils.lazy                               ][DEBUG   ][25688] LazyLoaded test.ping
2016-01-21 17:38:05,608 [salt.minion                                   ][INFO    ][25688] Returning information for job: 20160121173805267254
2016-01-21 17:38:05,609 [salt.crypt                                    ][DEBUG   ][25688] Re-using SAuth for ('/etc/salt/pki/minion', 'stage-static01.idc1.fn', 'tcp://10.201.193.6:6054')
2016-01-21 17:38:07,563 [salt.minion                                   ][INFO    ][19813] User root Executing command state.sls with jid 20160121173805689582
2016-01-21 17:38:07,564 [salt.minion                                   ][DEBUG   ][19813] Command details {'tgt_type': 'compound', 'jid': '20160121173805689582', 'tgt': '( L@stage-static01.idc1.fn )', 'ret': '', 'user': 'root', 'arg': ['webserver.static.deploy', 'pillar={"cmd":deploy,"prjname":static,"env":preview,"newver":123344,"delver":0}', 'queue=true'], 'fun': 'state.sls'}
2016-01-21 17:38:07,573 [salt.minion                                   ][INFO    ][25717] Starting a new job with PID 25717
2016-01-21 17:38:07,580 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded state.sls
2016-01-21 17:38:07,590 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded saltutil.is_running
2016-01-21 17:38:07,591 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded grains.get
2016-01-21 17:38:07,592 [salt.crypt                                    ][DEBUG   ][25717] Re-using SAuth for ('/etc/salt/pki/minion', 'hostname', 'tcp://ip:6054')
2016-01-21 17:38:55,439 [salt.config                                   ][DEBUG   ][25717] Reading configuration from /etc/salt/minion
2016-01-21 17:38:55,495 [salt.config                                   ][DEBUG   ][25717] Including configuration from '/etc/salt/minion.d/_schedule.conf'
2016-01-21 17:38:55,495 [salt.config                                   ][DEBUG   ][25717] Reading configuration from /etc/salt/minion.d/_schedule.conf
2016-01-21 17:38:55,889 [salt.crypt                                    ][DEBUG   ][25717] Re-using SAuth for ('/etc/salt/pki/minion', 'stage-static01.idc1.fn', 'tcp://10.201.193.6:6054')
2016-01-21 17:38:55,906 [salt.crypt                                    ][DEBUG   ][25717] Loaded minion key: /etc/salt/pki/minion/minion.pem
2016-01-21 17:38:55,950 [salt.state                                    ][INFO    ][25717] Loading fresh modules for state activity
2016-01-21 17:38:55,967 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded jinja.render
2016-01-21 17:38:55,967 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded yaml.render
2016-01-21 17:38:55,973 [salt.fileclient                               ][INFO    ][25717] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://webserver/static/deploy.sls'
2016-01-21 17:38:55,974 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded cmd.run
2016-01-21 17:38:55,975 [salt.utils.jinja                              ][DEBUG   ][25717] Jinja search path: ['/var/cache/salt/minion/files/base']
2016-01-21 17:38:55,983 [salt.template                                 ][DEBUG   ][25717] Rendered data from file: /var/cache/salt/minion/files/base/webserver/static/deploy.sls:
deploy:
  cmd.script:
    - source: salt://deploy/deployrollback.py
    - args: deploy static preview  123344 0

2016-01-21 17:38:55,986 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded config.get
2016-01-21 17:38:55,986 [salt.loaded.int.render.yaml                   ][DEBUG   ][25717] Results of YAML rendering: 
OrderedDict([('deploy', OrderedDict([('cmd.script', [OrderedDict([('source', 'salt://deploy/deployrollback.py')]), OrderedDict([('args', 'deploy static preview  123344 0')])])]))])
2016-01-21 17:38:55,987 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded cmd.script
2016-01-21 17:38:55,987 [salt.state                                    ][INFO    ][25717] Running state [deploy] at time 17:38:55.987219
2016-01-21 17:38:55,988 [salt.state                                    ][INFO    ][25717] Executing state cmd.script for deploy
2016-01-21 17:38:55,989 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded cp.cache_file
2016-01-21 17:38:55,990 [salt.crypt                                    ][DEBUG   ][25717] Re-using SAuth for ('/etc/salt/pki/minion', 'stage-static01.idc1.fn', 'tcp://10.201.193.6:6054')
2016-01-21 17:38:55,992 [salt.fileclient                               ][INFO    ][25717] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://deploy/deployrollback.py'
2016-01-21 17:38:55,1000 [salt.utils.lazy                               ][DEBUG   ][25717] LazyLoaded file.user_to_uid
2016-01-21 17:38:56,000 [salt.loaded.int.module.cmdmod                 ][INFO    ][25717] Executing command '/tmp/tmpfarNkz.py deploy static preview  123344 0' in directory '/root'
2016-01-21 17:38:56,226 [salt.state                                    ][INFO    ][25717] {'pid': 25803, 'retcode': 0, 'stderr': '', 'stdout': "`/home/webdata/static/current' -> `/home/webdata/static/releases/123344'"}
2016-01-21 17:38:56,226 [salt.state                                    ][INFO    ][25717] Completed state [deploy] at time 17:38:56.226164

hi,all,

above log is the log for excute state.sls ，between 17:38:07 and 17:38:55 ,what is the minion dong? can reduce the state.sls excute time ?

Thanks.

jfindlay commented 8 years ago

@freedba, thanks for the report. What version of salt are you using? Have you tried timing the execution of your deploy/deployrollback.py manually on the minion?

local # ssh minion
remote-minion # time python deploy/deployrollback.py deploy static preview  123344 0
freedba commented 8 years ago

@jfindlay

minion version:

# salt-minion --versions
           Salt: 2015.5.3
         Python: 2.6.6 (r266:84292, Feb 22 2013, 00:00:18)
         Jinja2: unknown
       M2Crypto: 0.20.2
 msgpack-python: 0.1.13
   msgpack-pure: Not Installed
       pycrypto: 2.0.1
        libnacl: Not Installed
         PyYAML: 3.10
          ioflo: Not Installed
          PyZMQ: 14.3.1
           RAET: Not Installed
            ZMQ: 3.2.4
           Mako: Not Installed
        Tornado: Not Installed

master version

# salt-master --versions
           Salt: 2015.5.3
         Python: 2.6.6 (r266:84292, Feb 22 2013, 00:00:18)
         Jinja2: unknown
       M2Crypto: 0.20.2
 msgpack-python: 0.4.6
   msgpack-pure: Not Installed
       pycrypto: 2.6.1
        libnacl: Not Installed
         PyYAML: 3.10
          ioflo: Not Installed
          PyZMQ: 14.3.1
           RAET: Not Installed
            ZMQ: 3.2.5
           Mako: Not Installed
        Tornado: 4.2.1

minion excute python script time:

# time python deploy/deployrollback.py deploy static preview  123348 0
`/home/webdata/static/current' -> `/home/webdata/static/releases/123348'

real    0m0.208s
user    0m0.042s
sys 0m0.015s

Thanks

freedba commented 8 years ago

execute state rsync module is slow too,

minion log:

2016-01-22 09:21:51,482 [salt.minion                                   ][DEBUG   ][31344] Command details {'tgt_type': 'compound', 'jid': '20160122092149605459', 'tgt': '( L@stage-static01.idc1.fn )', 'ret': '', 'user': 'root', 'arg': ['webserver.static.rsync', 'pillar={"env":preview}', 'queue=true'], 'fun': 'state.sls'}
2016-01-22 09:21:51,491 [salt.minion                                   ][INFO    ][10676] Starting a new job with PID 10676
2016-01-22 09:21:51,498 [salt.utils.lazy                               ][DEBUG   ][10676] LazyLoaded state.sls
2016-01-22 09:21:51,507 [salt.utils.lazy                               ][DEBUG   ][10676] LazyLoaded saltutil.is_running
2016-01-22 09:21:51,508 [salt.utils.lazy                               ][DEBUG   ][10676] LazyLoaded grains.get
2016-01-22 09:21:51,509 [salt.crypt                                    ][DEBUG   ][10676] Re-using SAuth for ('/etc/salt/pki/minion', 'stage-static01.idc1.fn', 'tcp://10.201.193.6:6054')

2016-01-22 09:22:08,523 [salt.minion                                   ][INFO    ][31344] User root Executing command test.ping with jid 20160122092206585666
2016-01-22 09:22:08,524 [salt.minion                                   ][DEBUG   ][31344] Command details {'tgt_type': 'glob', 'jid': '20160122092206585666', 'tgt': 'stage-static01.idc1.fn', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'test.ping'}
2016-01-22 09:22:08,533 [salt.minion                                   ][INFO    ][10739] Starting a new job with PID 10739
2016-01-22 09:22:08,580 [salt.utils.lazy                               ][DEBUG   ][10739] LazyLoaded test.ping
2016-01-22 09:22:08,581 [salt.minion                                   ][INFO    ][10739] Returning information for job: 20160122092206585666
2016-01-22 09:22:08,581 [salt.crypt                                    ][DEBUG   ][10739] Re-using SAuth for ('/etc/salt/pki/minion', 'stage-static01.idc1.fn', 'tcp://10.201.193.6:6054')
2016-01-22 09:22:25,632 [salt.minion                                   ][INFO    ][31344] User root Executing command test.ping with jid 20160122092225614351
2016-01-22 09:22:25,632 [salt.minion                                   ][DEBUG   ][31344] Command details {'tgt_type': 'glob', 'jid': '20160122092225614351', 'tgt': 'stage-static01.idc1.fn', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'test.ping'}
2016-01-22 09:22:25,642 [salt.minion                                   ][INFO    ][10770] Starting a new job with PID 10770
2016-01-22 09:22:25,690 [salt.utils.lazy                               ][DEBUG   ][10770] LazyLoaded test.ping
2016-01-22 09:22:25,691 [salt.minion                                   ][INFO    ][10770] Returning information for job: 20160122092225614351
2016-01-22 09:22:25,691 [salt.crypt                                    ][DEBUG   ][10770] Re-using SAuth for ('/etc/salt/pki/minion', 'stage-static01.idc1.fn', 'tcp://10.201.193.6:6054')
2016-01-22 09:22:39,122 [salt.config                                   ][DEBUG   ][10676] Reading configuration from /etc/salt/minion
2016-01-22 09:22:39,177 [salt.config                                   ][DEBUG   ][10676] Including configuration from '/etc/salt/minion.d/_schedule.conf'
2016-01-22 09:22:39,177 [salt.config                                   ][DEBUG   ][10676] Reading configuration from /etc/salt/minion.d/_schedule.conf
2016-01-22 09:22:39,544 [salt.crypt                                    ][DEBUG   ][10676] Re-using SAuth for ('/etc/salt/pki/minion', 'stage-static01.idc1.fn', 'tcp://10.201.193.6:6054')
2016-01-22 09:22:40,636 [salt.crypt                                    ][DEBUG   ][10676] Loaded minion key: /etc/salt/pki/minion/minion.pem
2016-01-22 09:22:40,679 [salt.state                                    ][INFO    ][10676] Loading fresh modules for state activity
2016-01-22 09:22:40,696 [salt.utils.lazy                               ][DEBUG   ][10676] LazyLoaded jinja.render
2016-01-22 09:22:40,697 [salt.utils.lazy                               ][DEBUG   ][10676] LazyLoaded yaml.render
2016-01-22 09:22:40,701 [salt.fileclient                               ][INFO    ][10676] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://webserver/static/rsync.sls'
2016-01-22 09:22:40,703 [salt.utils.lazy                               ][DEBUG   ][10676] LazyLoaded cmd.run
2016-01-22 09:22:40,703 [salt.utils.jinja                              ][DEBUG   ][10676] Jinja search path: ['/var/cache/salt/minion/files/base']
2016-01-22 09:22:40,711 [salt.template                                 ][DEBUG   ][10676] Rendered data from file: /var/cache/salt/minion/files/base/webserver/static/rsync.sls:

static_sync:
  module.run:
    - name: rsync.rsync
    - src: ftp.idc1.fn::static_preview
    - dst: /home/webdata/htdocs/static/

2016-01-22 09:22:40,714 [salt.utils.lazy                               ][DEBUG   ][10676] LazyLoaded config.get
2016-01-22 09:22:40,714 [salt.loaded.int.render.yaml                   ][DEBUG   ][10676] Results of YAML rendering: 
OrderedDict([('static_sync', OrderedDict([('module.run', [OrderedDict([('name', 'rsync.rsync')]), OrderedDict([('src', 'ftp.idc1.fn::static_preview')]), OrderedDict([('dst', '/home/webdata/htdocs/static/')])])]))])
2016-01-22 09:22:40,715 [salt.utils.lazy                               ][DEBUG   ][10676] LazyLoaded module.run
2016-01-22 09:22:40,715 [salt.state                                    ][INFO    ][10676] Running state [rsync.rsync] at time 09:22:40.715264
2016-01-22 09:22:40,716 [salt.state                                    ][INFO    ][10676] Executing state module.run for rsync.rsync
2016-01-22 09:22:40,716 [salt.utils.lazy                               ][DEBUG   ][10676] LazyLoaded rsync.rsync
2016-01-22 09:22:40,717 [salt.loaded.int.module.cmdmod                 ][INFO    ][10676] Executing command 'rsync -avz ftp.idc1.fn::static_preview /home/webdata/htdocs/static/' in directory '/root'
2016-01-22 09:22:41,627 [salt.loaded.int.module.cmdmod                 ][DEBUG   ][10676] stdout: receiving incremental file list

sent 341 bytes  received 42611 bytes  28634.67 bytes/sec
total size is 46640864  speedup is 1085.88
2016-01-22 09:22:41,627 [salt.state                                    ][INFO    ][10676] {'ret': {'pid': 10816, 'retcode': 0, 'stderr': '', 'stdout': 'receiving incremental file list\n\nsent 341 bytes  received 42611 bytes  28634.67 bytes/sec\ntotal size is 46640864  speedup is 1085.88'}}
2016-01-22 09:22:41,628 [salt.state                                    ][INFO    ][10676] Completed state [rsync.rsync] at time 09:22:41.627478
2016-01-22 09:22:41,628 [salt.state                                    ][DEBUG   ][10676] File /var/cache/salt/minion/accumulator/35674320 does not exist, no need to cleanup.
2016-01-22 09:22:41,629 [salt.minion                                   ][INFO    ][10676] Returning information for job: 20160122092149605459
2016-01-22 09:22:41,630 [salt.crypt                                    ][DEBUG   ][10676] Re-using SAuth for ('/etc/salt/pki/minion', 'stage-static01.idc1.fn', 'tcp://10.201.193.6:6054')
2016-01-22 09:22:42,777 [salt.minion                                   ][INFO    ][31344] User root Executing command test.ping with jid 20160122092242760246
2016-01-22 09:22:42,777 [salt.minion                                   ][DEBUG   ][31344] Command details {'tgt_type': 'glob',

master log:
2016-01-22 09:21:49,606 [salt.utils.event                         ][DEBUG   ][29382] Sending event - data = {'tgt_type': 'compound', 'jid': '20160122092149605459', 'tgt': '( L@stage-static01.idc1.fn )', '_stamp': '2016-01-22T01:21:49.605955', 'user': 'root', 'arg': ['webserver.static.rsync', 'pillar={"env":preview}', 'queue=true'], 'fun': 'state.sls', 'minions': ['stage-static01.idc1.fn']}

after about 40s , the master get this job results.

I am deploying coding by salt ,I require less time to complete the deploy job

Thanks.

freedba commented 8 years ago

@jfindlay I found the cause of the slow execute state.sls . There are two very large directorys (many files) in my file_roots . I moved that two directory, and execute state.sls is very quick. refer https://github.com/saltstack/salt/issues/11610 I've set fileserver_limit_traversal: True in /etc/salt/master and restart the master,but that config option doesn't seem to have any effect.

what other way can I do?

Thanks

jfindlay commented 8 years ago

@freedba, the fileserver_limit_traversal config limits searching of file_roots to to the specific saltev you're currently using. If the two directories with many files are also located within the same saltenv, fileserver_limit_traversal will not improve performance.

freedba commented 8 years ago

@jfindlay my file_roots config:

file_roots:
  base:
    - /usr/locar/src/salt
  online2:
    - /srv/fnenv/online2
  online:
    - /srv/fnenv/online
  preview:
    - /srv/fnenv/preview
    - /srv/fnenv/online

and my dir

# tree salt/
salt/
├── deploy
│   └── deployrollback.py
└── webserver
    └── static
        ├── deploy.sls
        ├── deploy.sls.bak
        └── rsync.sls

when I execute state.sls webserver.static.deploy , why salt search sls file from /srv/fnenv can salt only search sls file from /usr/local/src/salt ?

Thanks

jfindlay commented 8 years ago

@freedba, I'm unsure what you're asking. What specific error or problem are you getting?

freedba commented 8 years ago

@jfindlay

sorry, my english is no good:) excute state.sls need search file_roots sls, my file_roots include base online,online2,preview , there are many file in the online,online2,preview. this is cause execute state.sls is slow. I set fileserver_limit_traversal:True on the master config, execute state.sls is still slow. but when I set fileserver_limit_traversal:True on the minion config ,and excute state.sls is quick.

So the problem is resolved.

Thanks :)

jfindlay commented 8 years ago

@freedba, I am glad you fixed the problem and I am sorry I was not much help. Do you think this issue could be closed?

freedba commented 8 years ago

@jfindlay yes, I closed this issue

Thanks