major ssh slowdown after 1.3.4

Archives Ansible Project
1

Hi,

today I upgraded from Ansible 1.3.4 to 1.4.4 and noticed a major slowdown in my playbooks using ssh between virtual machines on the same VirtualBox host.

Here’s a simple test with ping showing what I mean:

root@ansible:~/test/deploy# ansible --version
ansible 1.3.4

root@ansible:~/test/deploy# time ansible -i test -m ping test-host-2 -c ssh -vvvv
ESTABLISH CONNECTION FOR USER: root
EXEC [‘ssh’, ‘-tt’, ‘-vvv’, ‘-o’, ‘ControlMaster=auto’, ‘-o’, ‘ControlPersist=60s’, ‘-o’, ‘ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r’, ‘-o’, ‘Port=40033’, ‘-o’, ‘KbdInteractiveAuthentication=no’, ‘-o’, ‘PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey’, ‘-o’, ‘PasswordAuthentication=no’, ‘-o’, ‘ConnectTimeout=10’, ‘test-host-2’, “/bin/sh -c ‘mkdir -p $HOME/.ansible/tmp/ansible-1391890971.81-192496444342081 && echo $HOME/.ansible/tmp/ansible-1391890971.81-192496444342081’”]
REMOTE_MODULE ping
PUT /tmp/tmpDzkccX TO /root/.ansible/tmp/ansible-1391890971.81-192496444342081/ping
EXEC [‘ssh’, ‘-tt’, ‘-vvv’, ‘-o’, ‘ControlMaster=auto’, ‘-o’, ‘ControlPersist=60s’, ‘-o’, ‘ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r’, ‘-o’, ‘Port=40033’, ‘-o’, ‘KbdInteractiveAuthentication=no’, ‘-o’, ‘PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey’, ‘-o’, ‘PasswordAuthentication=no’, ‘-o’, ‘ConnectTimeout=10’, ‘test-host-2’, “/bin/sh -c ‘/usr/bin/python /root/.ansible/tmp/ansible-1391890971.81-192496444342081/ping; rm -rf /root/.ansible/tmp/ansible-1391890971.81-192496444342081/ >/dev/null 2>&1’”]
test-host-2 | success >> {
“changed”: false,
“ping”: “pong”
}

real 0m0.392s
user 0m0.124s
sys 0m0.032s

root@ansible:~/test/deploy# ansible --version
ansible 1.4.4

root@ansible:~/test/deploy# time ansible -i test -m ping test-host-2 -c ssh -vvvv
ESTABLISH CONNECTION FOR USER: root
EXEC [‘ssh’, ‘-tt’, ‘-vvv’, ‘-o’, ‘ControlMaster=auto’, ‘-o’, ‘ControlPersist=60s’, ‘-o’, ‘ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r’, ‘-o’, ‘Port=40033’, ‘-o’, ‘KbdInteractiveAuthentication=no’, ‘-o’, ‘PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey’, ‘-o’, ‘PasswordAuthentication=no’, ‘-o’, ‘ConnectTimeout=10’, ‘test-host-2’, “/bin/sh -c ‘mkdir -p $HOME/.ansible/tmp/ansible-1391890986.05-221773170470374 && echo $HOME/.ansible/tmp/ansible-1391890986.05-221773170470374’”]
REMOTE_MODULE ping
PUT /tmp/tmptXIMKK TO /root/.ansible/tmp/ansible-1391890986.05-221773170470374/ping
PUT /tmp/tmpjViJP5 TO /root/.ansible/tmp/ansible-1391890986.05-221773170470374/arguments
EXEC [‘ssh’, ‘-tt’, ‘-vvv’, ‘-o’, ‘ControlMaster=auto’, ‘-o’, ‘ControlPersist=60s’, ‘-o’, ‘ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r’, ‘-o’, ‘Port=40033’, ‘-o’, ‘KbdInteractiveAuthentication=no’, ‘-o’, ‘PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey’, ‘-o’, ‘PasswordAuthentication=no’, ‘-o’, ‘ConnectTimeout=10’, ‘test-host-2’, “/bin/sh -c ‘/usr/bin/python /root/.ansible/tmp/ansible-1391890986.05-221773170470374/ping /root/.ansible/tmp/ansible-1391890986.05-221773170470374/arguments; rm -rf /root/.ansible/tmp/ansible-1391890986.05-221773170470374/ >/dev/null 2>&1’”]
test-host-2 | success >> {
“changed”: false,
“ping”: “pong”
}

real 0m2.412s
user 0m0.148s
sys 0m0.036s

I tried the same test with the current github HEAD and in the best case it’s still much slower than 1.3.4:

root@ansible:~/test/deploy# ansible --version
ansible 1.5 (devel 2267503c53) last updated 2014/02/04 14:20:20 (GMT +200)

new SSH plugin

root@ansible:~/test/deploy# time ansible -i test -m ping test-host-2 -c ssh -vvvv
ESTABLISH CONNECTION FOR USER: root
REMOTE_MODULE ping
EXEC [‘ssh’, ‘-C’, ‘-tt’, ‘-vvv’, ‘-o’, ‘ControlMaster=auto’, ‘-o’, ‘ControlPersist=60s’, ‘-o’, ‘ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r’, ‘-o’, ‘Port=40033’, ‘-o’, ‘KbdInteractiveAuthentication=no’, ‘-o’, ‘PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey’, ‘-o’, ‘PasswordAuthentication=no’, ‘-o’, ‘ConnectTimeout=10’, ‘test-host-2’, “/bin/sh -c ‘mkdir -p $HOME/.ansible/tmp/ansible-tmp-1391891219.83-137866337554858 && echo $HOME/.ansible/tmp/ansible-tmp-1391891219.83-137866337554858’”]
PUT /tmp/tmpu_xAge TO /root/.ansible/tmp/ansible-tmp-1391891219.83-137866337554858/ping
EXEC [‘ssh’, ‘-C’, ‘-tt’, ‘-vvv’, ‘-o’, ‘ControlMaster=auto’, ‘-o’, ‘ControlPersist=60s’, ‘-o’, ‘ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r’, ‘-o’, ‘Port=40033’, ‘-o’, ‘KbdInteractiveAuthentication=no’, ‘-o’, ‘PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey’, ‘-o’, ‘PasswordAuthentication=no’, ‘-o’, ‘ConnectTimeout=10’, ‘test-host-2’, “/bin/sh -c ‘/usr/bin/python /root/.ansible/tmp/ansible-tmp-1391891219.83-137866337554858/ping; rm -rf /root/.ansible/tmp/ansible-tmp-1391891219.83-137866337554858/ >/dev/null 2>&1’”]
test-host-2 | success >> {
“changed”: false,
“ping”: “pong”
}

real 0m2.556s
user 0m0.160s
sys 0m0.048s

old SSH plugin

root@ansible:~/test/deploy# time ansible -i test -m ping test-host-2 -c ssh_old -vvvv
ESTABLISH CONNECTION FOR USER: root
REMOTE_MODULE ping
EXEC [‘ssh’, ‘-tt’, ‘-vvv’, ‘-o’, ‘ControlMaster=auto’, ‘-o’, ‘ControlPersist=60s’, ‘-o’, ‘ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r’, ‘-o’, ‘Port=40033’, ‘-o’, ‘KbdInteractiveAuthentication=no’, ‘-o’, ‘PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey’, ‘-o’, ‘PasswordAuthentication=no’, ‘-o’, ‘ConnectTimeout=10’, ‘test-host-2’, “/bin/sh -c ‘mkdir -p $HOME/.ansible/tmp/ansible-tmp-1391891284.37-266812075342423 && echo $HOME/.ansible/tmp/ansible-tmp-1391891284.37-266812075342423’”]
PUT /tmp/tmpAmk9Z_ TO /root/.ansible/tmp/ansible-tmp-1391891284.37-266812075342423/ping
EXEC [‘ssh’, ‘-tt’, ‘-vvv’, ‘-o’, ‘ControlMaster=auto’, ‘-o’, ‘ControlPersist=60s’, ‘-o’, ‘ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r’, ‘-o’, ‘Port=40033’, ‘-o’, ‘KbdInteractiveAuthentication=no’, ‘-o’, ‘PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey’, ‘-o’, ‘PasswordAuthentication=no’, ‘-o’, ‘ConnectTimeout=10’, ‘test-host-2’, “/bin/sh -c ‘/usr/bin/python /root/.ansible/tmp/ansible-tmp-1391891284.37-266812075342423/ping; rm -rf /root/.ansible/tmp/ansible-tmp-1391891284.37-266812075342423/ >/dev/null 2>&1’”]
test-host-2 | success >> {
“changed”: false,
“ping”: “pong”
}

real 0m2.386s
user 0m0.152s
sys 0m0.020s

new SSH plugin with pipelining=True

root@ansible:~/test/deploy# time ansible -i test -m ping test-host-2 -c ssh -vvvv
ESTABLISH CONNECTION FOR USER: root
REMOTE_MODULE ping
EXEC [‘ssh’, ‘-C’, ‘-vvv’, ‘-o’, ‘ControlMaster=auto’, ‘-o’, ‘ControlPersist=60s’, ‘-o’, ‘ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r’, ‘-o’, ‘Port=40033’, ‘-o’, ‘KbdInteractiveAuthentication=no’, ‘-o’, ‘PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey’, ‘-o’, ‘PasswordAuthentication=no’, ‘-o’, ‘ConnectTimeout=10’, ‘test-host-2’, ‘/bin/sh -c /usr/bin/python’]
test-host-2 | success >> {
“changed”: false,
“ping”: “pong”
}

real 0m1.412s
user 0m0.132s
sys 0m0.044s

Is this major slowdown after 1.3.4 expected?

thanks ciao
ste

2

Sorry to reply to myself but in case anyone is interested I just noticed that the ssh slowdown has been fixed on the day after my mail by a commit very appropriately commented as “Fix slow ssh”:

https://github.com/ansible/ansible/commit/75b7a1d9c7f088a9ec5a43e618139f6276cf6a4a

Unfortunately the commit hasn’t made it to any released version yet.

Thanks lberruti for the fix, it does solve the issue here.

ciao
ste

3

1.5 releases in a few weeks.

Strangely this doesn’t slow everyone down and it’s very curious you’d see this, but you don’t have to wait long.