Net::SSH performance, why is it so slow?

Question

I have an automated test case in Ruby (using a framework I'm building see github), that is doing like around 15-20 SSH connections to servers under test collecting various data and logs.

Problem is that it takes quite a while until it is actually doing anything, meaning getting to the execution itself. I've enabled the require 'profile' profiler in attempt to find out what is it exactly doing. Here is the top of the list:

     time   seconds   seconds    calls  ms/call  ms/call  name
 18.84     8.37      8.37       82   102.10   102.10  OpenSSL::PKey::DH#generate_key!
  6.20    11.13      2.75    45978     0.06     0.26  Net::SSH::Transport::PacketStream#poll_next_packet
  3.93    12.87      1.75    83928     0.02     0.06  OpenSSL::PKey::DH#valid?
  2.64    14.05      1.17    27319     0.04     0.22  Wasabi::Parser#process_type
  2.57    15.19      1.14    13698     0.08     0.11  Net::SSH::Buffer#read
  1.94    16.05      0.86    24438     0.04     0.64  Net::SSH::Transport::PacketStream#next_packet
  1.83    16.87      0.81    47183     0.02     0.03  Net::SSH::Buffer#available
  1.66    17.61      0.74    47183     0.02     0.05  Net::SSH::BufferedIo#available
  1.58    18.31      0.70    46662     0.02     1.25  Net::SSH::Transport::Session#poll_message
  1.57    19.00      0.70    21819     0.03     2.07  Net::SSH::Transport::Session#wait
  1.48    19.66      0.66       84     7.83    34.37  Integer#times
  1.48    20.32      0.66    64205     0.01     0.01  Net::SSH::Buffer#length
  1.41    20.94      0.63    31212     0.02     0.77  Nokogiri::XML::NodeSet#each
  1.34    21.54      0.60      834     0.71    25.34  Kernel#gem_original_require
  1.15    22.05      0.51    26202     0.02     3.04  Array#each
  1.06    22.52      0.47    15127     0.03     0.04  Net::SSH::Transport::HMAC::Abstract.mac_length
  0.96    22.95      0.43     9520     0.04     0.14  Wasabi::Parser#input_output_for
  0.94    23.37      0.42    12291     0.03     0.07  Nokogiri::XML::Searchable#extract_params
  0.85    23.75      0.38    24438     0.02     2.26  Kernel#loop
  0.81    24.10      0.36    19890     0.02     0.02  #<OpenSSL::Cipher:0x58730a0>.xor!
  0.78    24.45      0.35     4346     0.08     0.35  Net::SSH::Buffer.from
  0.78    24.80      0.34    28736     0.01     0.03  Savon::Builder#namespace_by_uri
  0.73    25.12      0.33     4845     0.07     0.09  Net::SSH::Transport::State#update_next_iv
  0.68    25.42      0.30    10865     0.03     0.14  Net::SSH::Transport::PacketStream#enqueue_packet
  0.67    25.72      0.30       82     3.62     3.62  OpenSSL::PKey::DH#compute_key
  0.63    26.00      0.28    12819     0.02     0.51  Hash#each
  0.63    26.28      0.28    13003     0.02     4.07  Class#new
  0.63    26.57      0.28    38403     0.01     0.01  Nokogiri::XML::Node#attribute
  0.63    26.84      0.28    23036     0.01     0.02  Net::SSH::Compat.io_select
  0.56    27.09      0.25    84338     0.00     0.00  OpenSSL::PKey::DH#pub_key
  0.52    27.33      0.23     7893     0.03     0.10  Gem::BasicSpecification#have_file?
  0.50    27.55      0.22   102844     0.00     0.00  Fixnum#-
  0.49    27.77      0.22    22278     0.01     0.03  Net::SSH::Transport::PacketStream#available_for_read?
  0.49    27.98      0.22     4525     0.05     0.18  Net::SSH::Buffer#read_long
  0.49    28.20      0.22     4838     0.04     0.42  Net::SSH::KnownHosts#keys_for
  0.49    28.42      0.22     2025     0.11     0.14  Net::SSH::Transport::State#increment
  0.45    28.62      0.20   121786     0.00     0.00  Fixnum#+
  0.45    28.82      0.20     1966     0.10     0.39  Net::SSH::Transport::ServerVersion#negotiate!
  0.45    29.02      0.20    15117     0.01     0.06  

Did anyone experience something similar and maybe found the solution?

Here is my code:

    ##
    # generic SSH request
    # 
    # ==== Attributes
    # * +ssh_h+ - host
    # * +ssh_u+ - user
    # * +ssh_u+ - user
    # * +ssh_p+ - password
    # * +cmd+ - command
    # * +onlyOutput+ - if true, return only the result of the command, else, return the command itself as well
    # * +options+ - various options like custom port for ex
    # 
    def sshcmd(ssh_h, ssh_u, ssh_p, cmd, onlyOutput = false, options = {})
        ssh_port = options[:port] ? options[:port] : '22'
        logger.debug "SSH (#{ssh_u}@#{ssh_h}:#{ssh_port}): " + cmd
        Net::SSH.start(
            ssh_h,
            ssh_u,
            {:port => ssh_port,
            :password => ssh_p,
            # :verbose => :debug,
            :auth_methods => ['publickey','hostbased','password','keyboard-interactive'],
            :forward_agent => true}
        ) do|ssh| 
            out = ''
            if onlyOutput == true
                out = ssh.exec!(cmd)
            else
                out = cmd+"\n"+ssh.exec!(cmd)
            end
            logger.debug out
            return out
        end
end

Update: here is my current version, that works a little better. At least is connects only 3 times (1 connection per server) now:

##
# generic SSH request
# 
# ==== Attributes
# * +ssh_h+ - host
# * +ssh_u+ - user
# * +ssh_u+ - user
# * +ssh_p+ - password
# * +cmd+ - command
# * +onlyOutput+ - if true, return only the result of the command, else, return the command itself as well
# * +options+ - various options like custom port for ex
# 
def sshcmd(ssh_h, ssh_u, ssh_p, cmd, onlyOutput = false, options = {})
    ssh_port = options[:port] ? options[:port] : '22'
    logger.debug "SSH (#{ssh_u}@#{ssh_h}:#{ssh_port}): " + cmd
    logger.debug "SSH number of SSH connections in $sshConnnections pool: #{$sshConnnections.size}"
    Thread.current[:user_connections] ||= {}
    connectionName = ssh_h+"-"+ssh_port+"-"+ssh_u
    unless Thread.current[:user_connections].key?(connectionName)
        logger.debug "SSH Create new SSH connection (#{ssh_u}@#{ssh_h}:#{ssh_port}) for command: " + cmd + ""
        Thread.current[:user_connections][connectionName] = Net::SSH.start(
            ssh_h,
            ssh_u,
            {:port => ssh_port,
            :password => ssh_p,
            # :verbose => :debug,
            :max_pkt_size => 0x10000,
            :paranoid => false,
            :keepalive => true,
            :config => false,
            :compression => true,
            # :auth_methods => ['password','publickey','hostbased','keyboard-interactive'],
            :auth_methods => ['password'],
            :forward_agent => true}
        )
    else
        logger.debug "SSH Using existing SSH connection (#{ssh_u}@#{ssh_h}:#{ssh_port}) for command: " + cmd + ""
    end

    if onlyOutput == true
        out = Thread.current[:user_connections][connectionName].exec!(cmd)
    else
        out = cmd+"\n"+Thread.current[:user_connections][connectionName].exec!(cmd)
    end
    logger.debug out
    out
end

And the profiler shows:

 time   seconds   seconds    calls  ms/call  ms/call  name
 38.21     8.20      8.20        3  2734.33  2734.33  OpenSSL::PKey::DH#generate_key!
  5.25     9.33      1.13    27319     0.04     0.23  Wasabi::Parser#process_type
  3.13    10.00      0.67      843     0.80    23.56  Kernel#gem_original_require
  2.91    10.63      0.62    31212     0.02     0.78  Nokogiri::XML::NodeSet#each
  2.76    11.22      0.59    12291     0.05     0.09  Nokogiri::XML::Searchable#extract_params
  1.89    11.63      0.41    18391     0.02     2.42  Array#each
  1.80    12.01      0.39    28736     0.01     0.03  Savon::Builder#namespace_by_uri
  1.54    12.35      0.33    70350     0.00     0.00  Hash#[]
  1.47    12.66      0.31     9520     0.03     0.13  Wasabi::Parser#input_output_for
  1.23    12.92      0.26     4606     0.06     0.08  Net::SSH::Buffer#read
  1.16    13.17      0.25    38403     0.01     0.01  Nokogiri::XML::Node#attribute
  1.09    13.41      0.23    12468     0.02     0.12  Hash#each
  1.03    13.63      0.22    47225     0.00     0.01  Hash#[]=
  0.88    13.82      0.19     4097     0.05     0.16  Nokogiri::XML::Searchable#xpath_impl
  0.86    14.00      0.18     4097     0.05     0.21  Nokogiri::XML::Searchable#xpath_internal
  0.82    14.18      0.18     8361     0.02     0.09  Gem::BasicSpecification#have_file?
  0.82    14.35      0.17     7200     0.02     0.30  Savon::Builder#convert_type_namespaces_to_hash
  0.73    14.51      0.16     1623     0.10     0.15  Wasabi::CoreExt::String#snakecase
  0.72    14.66      0.15     8194     0.02     0.05  Nokogiri::XML::XPathContext#register_namespaces
  0.67    14.81      0.14     7446     0.02     0.03  Nokogiri::XML::Node#[]
  0.65    14.95      0.14    31841     0.00     0.00  Nokogiri::XML::Node#to_s
  0.58    15.07      0.12     1377     0.09     2.11  Wasabi::Parser#parse_operations
  0.52    15.18      0.11     2995     0.04     0.12  Net::SSH::Transport::PacketStream#enqueue_packet
  0.51    15.29      0.11    10303     0.01     0.01  Array#hash
  0.51    15.40      0.11     1238     0.09     0.86  Net::SSH::Transport::PacketStream#poll_next_packet
  0.50    15.51      0.11     5232     0.02     5.47  nil#
  0.44    15.60      0.09      912     0.10     0.41  Net::SSH::Buffer.from
  0.44    15.70      0.09     1699     0.06    11.36  Net::SSH::Transport::Session#poll_message
  0.44    15.79      0.09     9486     0.01     1.26  Integer#upto