Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-53014

Config server runs out of open files when dropping collection and inserting in a loop

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major - P3
    • Resolution: Unresolved
    • Affects Version/s: 4.2.10, 4.4.0
    • Fix Version/s: Backlog
    • Component/s: None
    • Labels:
      None
    • Operating System:
      ALL

      Description

      I made the following test program which repeatedly drops a collection and inserts a document into it:

      require 'mongo'
       
      Mongo::Logger.logger.level = 1
       
      client = Mongo::Client.new(['localhost:14440', 'localhost:14441'])
      db1 = client[:db1]
       
      loop do
        db1.drop
        db1.insert_one(a: 1)
        print('.')
      end
      

      I ran this against 4.2 and 4.4 sharded clusters launched as follows:

      serene% ./script/launch-4.2-sharded-multishard   
      Base port: 14240
      Running mlaunch --replicaset --nodes 2 --sharded 2 --name ruby-driver-rs --mongos 2 --dir /mnt/zram/mongodb/4.2-scm --setParameter diagnosticDataCollectionEnabled=false --wiredTigerCacheSizeGB 0.25 --setParameter honorSystemUmask=true --wiredTigerEngineConfigString 'log=(prealloc=false,file_max=20MB),cache_size=256M' --networkMessageCompressors zstd,snappy,zlib --setParameter enableTestCommands=1 --filePermissions 0666 --binarypath /usr/local/m/versions/4.2 --port 14240
      warning: ignoring unknown argument --wiredTigerEngineConfigString for /usr/local/m/versions/4.2/mongos
      launching: "/usr/local/m/versions/4.2/mongod" on port 14242
      launching: "/usr/local/m/versions/4.2/mongod" on port 14243
      launching: "/usr/local/m/versions/4.2/mongod" on port 14244
      launching: "/usr/local/m/versions/4.2/mongod" on port 14245
      launching: config server on port 14246
      replica set 'configRepl' initialized.
      replica set 'shard01' initialized.
      replica set 'shard02' initialized.
      launching: /usr/local/m/versions/4.2/mongos on port 14240
      launching: /usr/local/m/versions/4.2/mongos on port 14241
      adding shards. can take up to 30 seconds...
       
      serene% ./script/launch-4.4-sharded-multishard 
      Base port: 14440
      Running mlaunch --replicaset --nodes 2 --sharded 2 --name ruby-driver-rs --mongos 2 --dir /mnt/zram/mongodb/4.4-scm --setParameter diagnosticDataCollectionEnabled=false --wiredTigerCacheSizeGB 0.25 --setParameter honorSystemUmask=true --wiredTigerEngineConfigString 'log=(prealloc=false,file_max=20MB),cache_size=256M' --networkMessageCompressors zstd,snappy,zlib --setParameter enableTestCommands=1 --filePermissions 0666 --binarypath /usr/local/m/versions/4.4 --port 14440
      warning: ignoring unknown argument --wiredTigerEngineConfigString for /usr/local/m/versions/4.4/mongos
      launching: "/usr/local/m/versions/4.4/mongod" on port 14442
      launching: "/usr/local/m/versions/4.4/mongod" on port 14443
      launching: "/usr/local/m/versions/4.4/mongod" on port 14444
      launching: "/usr/local/m/versions/4.4/mongod" on port 14445
      launching: config server on port 14446
      replica set 'configRepl' initialized.
      replica set 'shard01' initialized.
      replica set 'shard02' initialized.
      launching: /usr/local/m/versions/4.4/mongos on port 14440
      launching: /usr/local/m/versions/4.4/mongos on port 14441
      adding shards. can take up to 30 seconds...
      

      In both cases, after some time, the config server runs out of open files.

      Program output:

      serene% ruby test.rb
      .........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................Traceback (most recent call last):
      	20: from test.rb:8:in `<main>'
      	19: from test.rb:8:in `loop'
      	18: from test.rb:10:in `block in <main>'
      	17: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/collection.rb:546:in `insert_one'
      	16: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/client.rb:1018:in `with_session'
      	15: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/collection.rb:552:in `block in insert_one'
      	14: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/retryable.rb:220:in `write_with_retry'
      	13: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/collection.rb:563:in `block (2 levels) in insert_one'
      	12: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/shared/write.rb:39:in `execute'
      	11: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/server.rb:425:in `with_connection'
      	10: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/server/connection_pool.rb:590:in `with_connection'
      	 9: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/shared/write.rb:50:in `block in execute'
      	 8: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/shared/response_handling.rb:26:in `validate_result'
      	 7: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/shared/response_handling.rb:82:in `unpin_maybe'
      	 6: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/shared/response_handling.rb:27:in `block in validate_result'
      	 5: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/shared/response_handling.rb:43:in `add_error_labels'
      	 4: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/shared/response_handling.rb:28:in `block (2 levels) in validate_result'
      	 3: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/shared/response_handling.rb:96:in `add_server_diagnostics'
      	 2: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/shared/response_handling.rb:29:in `block (3 levels) in validate_result'
      	 1: from /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/result.rb:289:in `validate!'
      /home/w/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.1/lib/mongo/operation/result.rb:321:in `raise_operation_failure': Connection closed by peer (6) (on localhost:14440, modern retry, attempt 1) (Mongo::Error::OperationFailure)
      

      Server logs attached for 4.2.10 and 4.4.0.

      Since I am operating on the same collection, I expect the server to be able to handle this workload without unbounded growth in open file count.

      This condition, once encountered, appears to be persistent. If I now restart the crashed config server, I get one of two behaviors:

      • The same failure happens much quicker (e.g. after ~15 iterations)
      • The server doesn't come up at all due to exceeding open file limit

      The second attached config server log file for 4.4 is with 3 attempts - one original as shown in the first file + two restarts.

        Attachments

        1. cs-4.2.log
          3.14 MB
        2. cs-4.4.log
          5.83 MB
        3. cs-4.4-three.log
          22.23 MB

          Activity

            People

            Assignee:
            backlog-server-execution Backlog - Storage Execution Team
            Reporter:
            oleg.pudeyev Oleg Pudeyev
            Participants:
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Dates

              Created:
              Updated: