Validating performance expectations: 10x overhead on ssh?

[Chris West]

Our "go off and do everything" playbook is now taking an uncomfortable number of minutes to run against a single host, even when there are no changes. This feels like a lot to me.

I have pipelining and ControlPersist enabled, and I'm pretty sure they're working. The hosts are about 10ms away, according to ping, and high spec (lots of idle cpu and ram and ssds).

For an example, I was playing with the file module, just checking the same directory exists over and over again. A lot of our plays do this; copy directories or files one by one (but also loads of other things). Maybe with_items: would be faster.

In ssh:

% time (for i in {1..20}; do ssh -o ControlPath=/home/faux/.ansible/cp/%h-%r -o ControlMaster=auto -o ControlPersist=180s xmas mkdir -p /tmp/ansible/foo; done) 0.65s user 0.06s system 47% cpu 1.490 total

In ansible:

% ansible-playbook -vvvv -i short-hosts.lst perf-playbook.yml 4.73s user 1.65s system 45% cpu 13.953 total

Nearly ten times slower? Does this match other people's expectations?

--

Exact setup:

# ansible.cfg: [defaults] pipelining=True forks=50 [ssh_connection] ssh_args = -o ControlMaster=auto -o ControlPersist=180s control_path = %(directory)s/%%h-%%r ## playbook - hosts: - all gather_facts: False tasks: - name: create directory 1 file: name=/tmp/ansible/foo state=directory - name: create directory 2 file: name=/tmp/ansible/foo state=directory - name: create directory 3 file: name=/tmp/ansible/foo state=directory - name: create directory 4 file: name=/tmp/ansible/foo state=directory - name: create directory 5 file: name=/tmp/ansible/foo state=directory - name: create directory 6 file: name=/tmp/ansible/foo state=directory - name: create directory 7 file: name=/tmp/ansible/foo state=directory - name: create directory 8 file: name=/tmp/ansible/foo state=directory - name: create directory 9 file: name=/tmp/ansible/foo state=directory - name: create directory 10 file: name=/tmp/ansible/foo state=directory - name: create directory 11 file: name=/tmp/ansible/foo state=directory - name: create directory 12 file: name=/tmp/ansible/foo state=directory - name: create directory 13 file: name=/tmp/ansible/foo state=directory - name: create directory 14 file: name=/tmp/ansible/foo state=directory - name: create directory 15 file: name=/tmp/ansible/foo state=directory - name: create directory 16 file: name=/tmp/ansible/foo state=directory - name: create directory 17 file: name=/tmp/ansible/foo state=directory - name: create directory 18 file: name=/tmp/ansible/foo state=directory - name: create directory 19 file: name=/tmp/ansible/foo state=directory - name: create directory 20 file: name=/tmp/ansible/foo state=directory ## a step, with timings (| ts '[%Y-%m-%d %H:%M:%.S]'): [2016-08-30 13:29:17.970906] TASK [create directory 20] ***************************************************** [2016-08-30 13:29:17.970941] task path: /home/faux/code/glue/infrastructure/ansible/perf-playbook.yml:43 [2016-08-30 13:29:18.016202] <xmas> ESTABLISH SSH CONNECTION FOR USER: None [2016-08-30 13:29:18.016544] <xmas> SSH: EXEC ssh -C -vvv -o ControlMaster=auto -o ControlPersist=180s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o ControlPath=/home/faux/.ansible/cp/%h-%r xmas '/bin/sh -c '"'"'( umask 77 && mkdir -p "` echo $HOME/.ansible/tmp/ansible-tmp-1472560158.02-23318569809518 `" && echo ansible-tmp-1472560158.02-23318569809518="` echo $HOME/.ansible/tmp/ansible-tmp-1472560158.02-23318569809518 `" ) && sleep 0'"'"'' [2016-08-30 13:29:18.066649] <xmas> PUT /tmp/tmptEKKtW TO /home/faux/.ansible/tmp/ansible-tmp-1472560158.02-23318569809518/file [2016-08-30 13:29:18.071041] <xmas> SSH: EXEC sftp -b - -C -vvv -o ControlMaster=auto -o ControlPersist=180s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o ControlPath=/home/faux/.ansible/cp/%h-%r '[xmas]' [2016-08-30 13:29:18.247611] <xmas> ESTABLISH SSH CONNECTION FOR USER: None [2016-08-30 13:29:18.248089] <xmas> SSH: EXEC ssh -C -vvv -o ControlMaster=auto -o ControlPersist=180s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o ControlPath=/home/faux/.ansible/cp/%h-%r -tt xmas '/bin/sh -c '"'"'LANG=en_GB.UTF-8 LC_ALL=en_GB.UTF-8 LC_MESSAGES=en_GB.UTF-8 /usr/bin/python /home/faux/.ansible/tmp/ansible-tmp-1472560158.02-23318569809518/file; rm -rf "/home/faux/.ansible/tmp/ansible-tmp-1472560158.02-23318569809518/" > /dev/null 2>&1 && sleep 0'"'"'' [2016-08-30 13:29:18.532505] ok: [xmas] => {"changed": false, "diff": {"after": {"path": "/tmp/ansible/foo"}, "before": {"path": "/tmp/ansible/foo"}}, "gid": 1005, "group": "faux", "invocation": {"module_args": {"backup": null, "content": null, "delimiter": null, "diff_peek": null, "directory_mode": null, "follow": false, "force": false, "group": null, "mode": null, "name": "/tmp/ansible/foo", "original_basename": null, "owner": null, "path": "/tmp/ansible/foo", "recurse": false, "regexp": null, "remote_src": null, "selevel": null, "serole": null, "setype": null, "seuser": null, "src": null, "state": "directory", "validate": null}, "module_name": "file"}, "mode": "0775", "owner": "faux", "path": "/tmp/ansible/foo", "size": 4096, "state": "directory", "uid": 1004} ## ping: rtt min/avg/max/mdev = 9.707/9.857/9.954/0.091 ms