Opening and closing 16000 Mongo DB instances in PHP

Question

I am currently working on some personal tests and benchmarks to compare the workflow and efficiency between using MongoDB and MySQL with real world example data.

To setup my data in each database I am doing several thousand loops and randomly creating data objects to insert into the database.

However I am having some issues using the Mongo class in PHP which I cannot solve. The problem is like so:

I have a loop which creates a new Mongo instance and connection, inserts a small array into a collection and then closes the connection. This loop should run 20000 times. However it is always failing around the 16300nd loop (with a min of 16200 and max of 16350 I'd say after a few runs) when it attempts to create the instance/make a connection.

The code in the loop is below:

$data = get_random_user_data();

$mongo = new Mongo('mongodb://admin:password@localhost:27017/test');

    if ($mongo->test->users->insert($data)) {
        $users[] = array('id' => $data['_id'], 'name' => $data['username']);
    echo $i." - Added user: ".$data['username'].'<br/>';
    }

$mongo->close();

get_random_user_data() just returns a simple associative array.

The error I get is:

Fatal error: Uncaught exception 'MongoConnectionException' with message 'Unknown error'

On the line:

$mongo = new Mongo('mongodb://admin:password@localhost:27017/test');

Any ideas? Is there something fundamental I am missing like some security or spam-prevention?

Thanks in advance.

Extra info:

The script dies at about 114.9797 seconds. It's not a PHP memory or time based issue as all the limits are raised and I ran my MySQL benchmarks yesterday inserting 120000 rows (with the same method of looping open connection, insert, close connection) over about an hour with no problems.

Running PHP Version 5.3.5

phpinfo Mongo info:

MongoDB Support enabled
Version 1.2.0-
Directive   Local Value Master Value
mongo.allow_empty_keys  0   0
mongo.allow_persistent  1   1
mongo.auto_reconnect    1   1
mongo.chunk_size    262144  262144
mongo.cmd   $   $
mongo.default_host  localhost   localhost
mongo.default_port  27017   27017
mongo.long_as_object    0   0
mongo.native_long   0   0
mongo.no_id 0   0
mongo.utf8  1   1

Answer 1

Your operating system has a limited number of sockets it's willing to open. When you open a socket and then close it, the OS doesn't immediately put it back in the "available" pool, it hangs out for a while in "time wait" state, that Nat mentions in his answer.

You can increase the number of sockets your OS will open, see http://www.mongodb.org/display/DOCS/Too+Many+Open+Files (each socket is an open "file").

Also, you're using a pretty old version of the driver, you might want to consider upgrading.

Answer 2

I confirm that this is the same behavior from ruby driver too. I replicated similar case with ruby mongo, which inserts 20000 records by opening/closing mongo instance each time. And it keep on failing between 14110 to 14200.

This is the error message

 uncaught throw #<Mongo::ConnectionFailure: Failed to connect to host localhost and port 27017: Cannot assign requested address - connect(2)>

this is the complete stack trace

Failed to connect to host localhost and port 27017: Cannot assign requested address - connect(2)
["/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/util/pool.rb:171:in `rescue in checkout_new_socket'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/util/pool.rb:166:in `checkout_new_socket'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/util/pool.rb:267:in `block (2 levels) in checkout'", "<internal:prelude>:10:in `synchronize'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/util/pool.rb:259:in `block in checkout'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/util/pool.rb:252:in `loop'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/util/pool.rb:252:in `checkout'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/connection.rb:496:in `checkout_writer'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/networking.rb:34:in `send_message'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/collection.rb:948:in `block in insert_documents'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/util/logging.rb:28:in `instrument'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/collection.rb:944:in `insert_documents'", "/home/ramesh/.rvm/gems/ruby-1.9.2-p290/gems/mongo-1.5.2/lib/mongo/collection.rb:343:in `insert'", "/home/ramesh/Desktop/load_test.rb:15:in `block in load_test'", "/home/ramesh/Desktop/load_test.rb:6:in `times'", "/home/ramesh/Desktop/load_test.rb:6:in `load_test'", "(irb):2:in `irb_binding'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb/workspace.rb:80:in `eval'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb/workspace.rb:80:in `evaluate'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb/context.rb:254:in `evaluate'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb.rb:159:in `block (2 levels) in eval_input'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb.rb:273:in `signal_status'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb.rb:156:in `block in eval_input'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb/ruby-lex.rb:243:in `block (2 levels) in each_top_level_statement'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb/ruby-lex.rb:229:in `loop'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb/ruby-lex.rb:229:in `block in each_top_level_statement'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb/ruby-lex.rb:228:in `catch'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb/ruby-lex.rb:228:in `each_top_level_statement'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb.rb:155:in `eval_input'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb.rb:70:in `block in start'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb.rb:69:in `catch'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/irb.rb:69:in `start'", "/home/ramesh/.rvm/rubies/ruby-1.9.2-p290/bin/irb:16:in `<main>'"]
ArgumentError: uncaught throw #<Mongo::ConnectionFailure: Failed to connect to host localhost and port 27017: Cannot assign requested address - connect(2)>
    from /home/ramesh/Desktop/load_test.rb:21:in `throw'
    from /home/ramesh/Desktop/load_test.rb:21:in `rescue in block in load_test'
    from /home/ramesh/Desktop/load_test.rb:7:in `block in load_test'
    from /home/ramesh/Desktop/load_test.rb:6:in `times'
    from /home/ramesh/Desktop/load_test.rb:6:in `load_test'

Also as @Chrisui said, i am also not experiencing any memory drops.

This is the script i have tried

require 'mongo'

def load_test
    start = Time.now
    puts 'starting at :' + start.to_s 
    20000.times do |i|    
            begin
                puts i      
            doc = {"name" => "MongoDB", "type" => "database", "count" => 1,"info" => {"x" => 203, "y" => '102'}}
            con = Mongo::Connection.new("localhost")
            db   = con['bulktest']
            coll = db['test']
            coll.insert(doc)
            con.close
                con,db,coll=nil,nil,nil
        rescue Exception => e  
            puts e.message  
            puts e.backtrace.inspect  
            throw e 
        end

    end
    stop = Time.now
    puts 'stoping at :' + stop.to_s 
    puts 'elapsed time is ' + (stop-start).to_s + ' seconds'
end

Answer 3

Your benchmark doesn't make sense. Don't keep open/close connection. You should reuse persisted connection instead of opening/closing every time. If you open and close socket quickly, you will have too many sockets in timed-wait state which still use file descriptors