Performance regression in mongo ruby driver 2.1.0.rc0 and/or bson 3

mongo1-8.rb

gem 'mongo', '=1.8.2'
# bson-1.8.2
# bson_ext-1.8.2

require 'mongo'
require 'benchmark/ips'

c = Mongo::MongoClient.new('localhost', 27017)['test']['hi']

Benchmark.ips do |x|
  x.config(:time => 20, :warmup => 2)

  # To reduce overhead, the number of iterations is passed in
  # and the block must run the code the specific number of times.
  # Used for when the workload is very small and any overhead
  # introduces incorrectable errors.
  x.report("mongo 1.8") do |times|
    i = 0
    while i < times
      c.find_one({_id: 1231231})
      i += 1
    end
  end
end

mongo2-1.rb

gem 'mongo', '=2.1.0.rc0'
# bson 3.2.4

require 'mongo'
require 'benchmark/ips'

c = Mongo::Client.new(['localhost:27017']).use(:test)['hi']
Mongo::Logger.logger.level = Logger::WARN

Benchmark.ips do |x|
  x.config(:time => 20, :warmup => 2)

  x.report("mongo 2.1") do |times|
    i = 0
    while i < times
      c.find({_id: 1231231}).first
      i += 1
    end
  end
  
  c = Mongo::Client.new(['localhost:27017'], monitoring: false).use(:test)['hi']
  x.report("mongo 2.1 (no monitor)") do |times|
  i = 0
  while i < times
    c.find({_id: 1231231}).first
    i += 1
  end
end


end

results-master.md

Testing at https://github.com/mongodb/mongo-ruby-driver/commit/7b2e165c837334ecbae8c160803a5ea3ad2dcee4.

Calculating -------------------------------------
           mongo 1.8   464.000  i/100ms
-------------------------------------------------
           mongo 1.8      4.649k (± 8.8%) i/s -     92.336k
Calculating -------------------------------------
           mongo @ master   243.000  i/100ms
-------------------------------------------------
           mongo @ master      2.566k (± 8.3%) i/s -     51.030k
Calculating -------------------------------------
mongo 2.1 @ master (no monitor)
                       284.000  i/100ms
-------------------------------------------------
mongo 2.1 @ master (no monitor)
                          2.862k (± 7.0%) i/s -     57.084k

results.md

Mongo server v2.4.12

$ ruby -v
ruby 2.1.5p273 (2014-11-13 revision 48405) [x86_64-darwin13.0]
$ ruby mongo1-8.rb && ruby mongo2-1.rb
Calculating -------------------------------------
           mongo 1.8   499.000  i/100ms
-------------------------------------------------
           mongo 1.8      4.555k (±15.5%) i/s -     88.822k
2.1.0.rc0
Calculating -------------------------------------
           mongo 2.1   255.000  i/100ms
-------------------------------------------------
           mongo 2.1      2.330k (±16.1%) i/s -     45.135k
Calculating -------------------------------------
mongo 2.1 (no monitor)
                       351.000  i/100ms
-------------------------------------------------
mongo 2.1 (no monitor)
                          3.435k (±11.2%) i/s -     67.392k

stackprof.md

2.1 @ master without monitoring

$ stackprof mongo2-1.dump
==================================
  Mode: cpu(1000)
  Samples: 11996 (0.00% miss rate)
  GC: 0 (0.00%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      4657  (38.8%)        4657  (38.8%)     block in Mongo::Socket#write
      3964  (33.0%)        3964  (33.0%)     Mongo::Socket#read_from_socket
      2025  (16.9%)         579   (4.8%)     #<Module:0x007fd3336bbcb0>.deserialize
       318   (2.7%)         318   (2.7%)     block in Mongo::Socket#readbyte
       212   (1.8%)         212   (1.8%)     #<Module:0x007fd3336bbad0>.serialize
       214   (1.8%)         186   (1.6%)     Mongo::Operation::ReadPreference#update_options
      4731  (39.4%)         171   (1.4%)     Mongo::ServerSelector::Selectable#select_server
       164   (1.4%)         164   (1.4%)     BSON::Integer#to_bson
       154   (1.3%)         154   (1.3%)     Mongo::Server#description
       143   (1.2%)         143   (1.2%)     Mongo::Server#pool
       135   (1.1%)         135   (1.1%)     Mongo::Collection::View::Readable#setup_selector
       214   (1.8%)         126   (1.1%)     Mongo::Server::ConnectionPool::Queue#dequeue_connection
       115   (1.0%)         115   (1.0%)     #<Module:0x007fd3336bbc10>.serialize
       109   (0.9%)          94   (0.8%)     Mongo::Collection::View::Readable#read
        93   (0.8%)          90   (0.8%)     Mongo::Protocol::Serializers::BitVector#serialize
        87   (0.7%)          87   (0.7%)     block in Mongo::Server::ConnectionPool::Queue#dequeue_connection
        74   (0.6%)          74   (0.6%)     block in Mongo::Collection::View::Readable#flags
       286   (2.4%)          72   (0.6%)     Mongo::Collection#find
        65   (0.5%)          65   (0.5%)     BSON::Document#initialize
       128   (1.1%)          53   (0.4%)     Mongo::Collection::View::Readable#query_options
        51   (0.4%)          51   (0.4%)     #<Module:0x007fd3336bbcb0>.serialize
       209   (1.7%)          51   (0.4%)     Mongo::Collection::View::Readable#query_spec
        38   (0.3%)          38   (0.3%)     Mongo::Protocol::Query#determine_limit
        28   (0.2%)          28   (0.2%)     Mongo::Database#cluster
        21   (0.2%)          21   (0.2%)     Mongo::Collection::View::Immutable#configure
        51   (0.4%)          20   (0.2%)     Mongo::Cluster::Topology::Single#servers
        19   (0.2%)          19   (0.2%)     block (2 levels) in Mongo::Cluster#servers_list
        19   (0.2%)          19   (0.2%)     block in Mongo::Socket#gets
        15   (0.1%)          15   (0.1%)     Mongo::Collection#read_preference
        14   (0.1%)          14   (0.1%)     BSON::String#to_utf8_binary

1.8.2

$ stackprof mongo1-8.dump
==================================
  Mode: cpu(1000)
  Samples: 7456 (0.00% miss rate)
  GC: 0 (0.00%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      3522  (47.2%)        3522  (47.2%)     Mongo::TCPSocket#read
      2434  (32.6%)        2434  (32.6%)     Mongo::TCPSocket#send
       455   (6.1%)         325   (4.4%)     Mongo::Cursor#initialize
       292   (3.9%)         292   (3.9%)     BSON::ByteBuffer#initialize
       202   (2.7%)         199   (2.7%)     BSON::ByteBuffer#put_num
       602   (8.1%)         147   (2.0%)     Mongo::Collection#find
       142   (1.9%)         142   (1.9%)     BSON::BSON_RUBY.to_utf8_binary
       128   (1.7%)         128   (1.7%)     Mongo::Cursor#convert_fields_for_query
      6821  (91.5%)          87   (1.2%)     Mongo::Logging#instrument
        35   (0.5%)          35   (0.5%)     BSON::ByteBuffer#prepend!
        27   (0.4%)          21   (0.3%)     Mongo::Pool#checkout
      7456 (100.0%)          21   (0.3%)     Mongo::Collection#find_one
        17   (0.2%)          17   (0.2%)     Mongo::Networking#new_binary_string
        39   (0.5%)          11   (0.1%)     Mongo::MongoClient#checkout_reader
         9   (0.1%)           9   (0.1%)     block in Mongo::Networking#get_request_id
      6833  (91.6%)           8   (0.1%)     Mongo::Cursor#next
        11   (0.1%)           6   (0.1%)     BSON::BSON_C.deserialize
      3569  (47.9%)           6   (0.1%)     Mongo::Networking#receive
      1613  (21.6%)           5   (0.1%)     Mongo::Networking#receive_header
         5   (0.1%)           5   (0.1%)     BSON::ByteBuffer#put_binary
       803  (10.8%)           4   (0.1%)     Mongo::Networking#receive_response_header
         4   (0.1%)           4   (0.1%)     Mongo::Cursor#instrument_payload
         4   (0.1%)           4   (0.1%)     Mongo::Cursor#close_cursor_if_query_complete
         3   (0.0%)           3   (0.0%)     Mongo::ThreadLocalVariableManager#thread_local
         3   (0.0%)           3   (0.0%)     Mongo::Networking#check_response_flags
         2   (0.0%)           2   (0.0%)     block in Mongo::Pool#checkin
         2   (0.0%)           2   (0.0%)     #<Module:0x007ff27beb93d8>.instrumenter
         2   (0.0%)           2   (0.0%)     BSON::ByteBuffer#to_s
         2   (0.0%)           2   (0.0%)     BSON::ByteBuffer#ensure_length
         2   (0.0%)           1   (0.0%)     Mongo::Pool#checkout_existing_socket