major ssh slowdown after 1.3.4

[Stefano Debenedetti]

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
<test-host-2> ESTABLISH CONNECTION FOR USER: root
<test-host-2> 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'"]
<test-host-2> REMOTE_MODULE ping
<test-host-2> PUT /tmp/tmpDzkccX TO /root/.ansible/tmp/ansible-1391890971.81-192496444342081/ping
<test-host-2> 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
<test-host-2> ESTABLISH CONNECTION FOR USER: root
<test-host-2> 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'"]
<test-host-2> REMOTE_MODULE ping
<test-host-2> PUT /tmp/tmptXIMKK TO /root/.ansible/tmp/ansible-1391890986.05-221773170470374/ping
<test-host-2> PUT /tmp/tmpjViJP5 TO /root/.ansible/tmp/ansible-1391890986.05-221773170470374/arguments
<test-host-2> 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
<test-host-2> ESTABLISH CONNECTION FOR USER: root
<test-host-2> REMOTE_MODULE ping
<test-host-2> 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'"]                                                                                                                                            
<test-host-2> PUT /tmp/tmpu_xAge TO /root/.ansible/tmp/ansible-tmp-1391891219.83-137866337554858/ping
<test-host-2> 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
<test-host-2> ESTABLISH CONNECTION FOR USER: root
<test-host-2> REMOTE_MODULE ping
<test-host-2> 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'"]
<test-host-2> PUT /tmp/tmpAmk9Z_ TO /root/.ansible/tmp/ansible-tmp-1391891284.37-266812075342423/ping
<test-host-2> 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
<test-host-2> ESTABLISH CONNECTION FOR USER: root
<test-host-2> REMOTE_MODULE ping
<test-host-2> 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

[Stefano Debenedetti]

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

[Michael DeHaan]

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.

--
You received this message because you are subscribed to the Google Groups "Ansible Project" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ansible-proje...@googlegroups.com.
To post to this group, send email to ansible...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/ansible-project/a59fb565-c273-4c19-a080-96aea93bd59d%40googlegroups.com.

For more options, visit https://groups.google.com/groups/opt_out.