Getting connection from connection pool is too slow

[eltonlika]

When getting a connection from a OCI8::ConnectionPool there seems to be a hanging, resulting in waiting more than 40 seconds to get a connection.

From a rbtrace run I did, it seems to hang on the OCI8#server_attach method call. Below are some timings of different connection creations, for comparison, outputed by the attached script (test1.rb):

~/Desktop » ruby test1.rb
Creating direct connection
Direct connection got: 66ms

Creating connection pool
Connection pool created: 98ms

Getting connection from pool
Connection got from pool: 40174ms

test1.rb is as below:

require 'rbtrace'
require 'oci8'

puts "Creating direct connection"
tStart = Time.now.to_f
con1 = OCI8.new("hr","hr","(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = 192.168.0.115)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SID = XE)))")
tEnd = Time.now.to_f
puts "Direct connection got: " + ((tEnd - tStart) * 1000).to_i.to_s + "ms"
con1.logoff
puts

puts "Creating connection pool"
tStart = Time.now.to_f
cpool = OCI8::ConnectionPool.new(1,5,2,"hr","hr","(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = 192.168.0.115)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SID = XE)))")
tEnd = Time.now.to_f
puts "Connection pool created: " + ((tEnd - tStart) * 1000).to_i.to_s + "ms"

puts

puts "Getting connection from pool"
tStart = Time.now.to_f
con2 = OCI8.new("hr","hr", cpool)
tEnd = Time.now.to_f
puts "Connection got from pool: " + ((tEnd - tStart) * 1000).to_i.to_s + "ms"

con2.logoff
cpool.destroy

Oracle Instant Client version is 12.1.0 64-bit on Mint Linux 17.3. The problem is reproducible on Mac OS X 10.11.4 with instant client version 11.2. On both systems ruby 2.3.0 is installed.

The Oracle Database is Express Edition 11.2.0.2.0 on a Windows 7 Professional VMWare VM on the same machine with bridged networking.

rbtrace for the con2 = OCI8.new("hr","hr", cpool) line is:

~/Desktop » rbtrace --firehose --exec ruby test1.rb
...
Class#new
  OCI8#initialize
    Kernel#nil? <0.000101>
    OCI8.properties <0.000185>
    Hash#[]
      Hash#has_key? <0.000075>
      Hash#[] <0.000083>
    Hash#[] <0.000442>
    Kernel#is_a? <0.000059>
    OCI8::ConnectionPool#pool_name <0.000097>
    Fixnum#| <0.000087>
    OCI8#allocate_handles <0.014703>
    OCIHandle#attr_set_string <0.000090>
    OCIHandle#attr_set_string <0.000159>
    Comparable#>=
      OCI8::OracleVersion#<=>
        OCI8::OracleVersion#to_i <0.000052>
        Fixnum#<=> <0.000049>
      OCI8::OracleVersion#<=> <0.000249>
    Comparable#>= <0.000321>
    OCIHandle#attr_set_string <0.000080>
    **OCI8#server_attach <40.262195>**
    OCI8#session_begin <0.138027>
  OCI8#initialize <40.419448>
Class#new <40.419550>
...

[kubo]

Thank you for the report.

I could not reproduce it. I got the following result with the below script. Getting connection from connection pool is relatively slow. But not too slow.

Result:

Direct connection got: 119ms (stddev: 112.16)
Connection pool created: 121ms (stddev: 124.89)
Connection got from pool: 342ms (stddev: 139.98)

Script:

require 'oci8'

username = "ruby"
password = "oci8"
#database = "(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = 192.168.0.115)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SID = XE)))"
database = "//localhost/ora121"

connect_time = []
pool_time = []
pool_connect_time = []

100.times do |cnt|
  sleep 1
  puts
  puts "Iteration #{cnt + 1}"
  puts

  puts "Creating direct connection"
  tStart = Time.now.to_f
  con1 = OCI8.new(username, password, database)
  tEnd = Time.now.to_f
  msec = ((tEnd - tStart) * 1000).to_i
  puts "Direct connection got: #{msec}ms"
  con1.logoff
  puts
  connect_time << msec

  puts "Creating connection pool"
  tStart = Time.now.to_f
  cpool = OCI8::ConnectionPool.new(1,5,2,username, password, database)
  tEnd = Time.now.to_f
  msec = ((tEnd - tStart) * 1000).to_i
  puts "Connection pool created: #{msec}ms"
  puts
  pool_time << msec

  puts "Getting connection from pool"
  tStart = Time.now.to_f
  con2 = OCI8.new(username, password, cpool)
  tEnd = Time.now.to_f
  msec = ((tEnd - tStart) * 1000).to_i
  puts "Connection got from pool: #{msec}ms"
  pool_connect_time << msec

  con2.logoff
  cpool.destroy
end

def print_result(fmt, ary)
  sum = ary.inject(0) {|ac, n| ac + n}
  mean = sum / ary.size.to_f
  variance = ary.inject(0) {|ac, n| ac + (n - mean) ** 2} / (ary.size - 1).to_f
  stddev = Math.sqrt(variance)
  puts fmt % [mean, stddev]
end

puts '-----------------------------------------'
print_result("Direct connection got: %.fms (stddev: %.2f)", connect_time)
print_result("Connection pool created: %.fms (stddev: %.2f)", pool_time)
print_result("Connection got from pool: %.fms (stddev: %.2f)", pool_connect_time)

Both client and server is Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 on Linux. I'll test it with Oracle Express Edition on Windows later.

[kubo]

This isn't ruby-oci8 issue. This is an issue of Oracle database server on Windows. Could you ask to a DBA who can search Oracle support to know workaround?

[eltonlika]

I did reproduce the problem with an Oracle Express Edition 11g 64bit server instance hosted in Fedora 23 64-bit Linux, so could it be some networking issue?

[kubo]

I'm not sure what violates the agreement. You need to look at the Oracle support.

[kubo]

FYI. I updated document about connection pool because this is different with generally called connection pool. See http://www.rubydoc.info/github/kubo/ruby-oci8/OCI8/ConnectionPool

[serii833]

Have same issue. Getting connection from pool takes about 9 seconds ruby 2.3.0p0 (2015-12-25 revision 53290) [i386-mingw32] Oracle Instant Client 11.2.0.4 Oracle 11.2.0.3.0 Enterprise Edition on dedicated db server (Oracle Linux)

[serii833]

some more info. it works ok (~200ms to get connection) in such configuration ruby 2.3.1p112 (2016-04-26) [x86_64-linux-gnu] Oracle Instant Client 12.2.0.1.0 Oracle 11.2.0.1.0 Enterprise Edition host VM Windows 2003