[SERVER-53014] Config server runs out of open files when dropping collection and inserting in a loop Created: 21/Nov/20  Updated: 06/Dec/22

Status: Backlog
Project: Core Server
Component/s: None
Affects Version/s: 4.4.0, 4.2.10
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Oleg Pudeyev (Inactive) Assignee: Backlog - Storage Execution Team
Resolution: Unresolved Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File cs-4.2.log     Text File cs-4.4-three.log     Text File cs-4.4.log    
Assigned Teams:
Storage Execution
Operating System: ALL
Participants:

 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.



 Comments   
Comment by Haley Connelly [ 07/Dec/20 ]

This sounds like something the execution could consider to limit outstanding resources on the system. I'm reassigning this ticket for them to comment on. 

Comment by Oleg Pudeyev (Inactive) [ 04/Dec/20 ]

I expected the server to limit how many background drops it allows to be outstanding, such that overall resource consumption is bounded.

Comment by Haley Connelly [ 04/Dec/20 ]

oleg.pudeyev, I believe this is works as expected. In the ruby driver, if the database isn’t specified, it defaults to the admin database. Since the admin database lives on the config server, and file descriptors are cleaned up lazily after the collection is dropped (here is more background on two phase drop), it’s not unexpected that the config server runs out of open files when it creates and drops the admin.db collection in a tight loop.

In the logs, it can be confirmed that the collection implicitly created and then dropped in a loop is on the admin database.

| 2020-11-20T22:44:56.172-05:00 I  STORAGE  20320   [conn8] “createCollection”,“attr”:{“namespace”:“admin.db1",“uuidDisposition”:“generated”,“uuid”:{“uuid”:{“$uuid”:“2a666d51-5acc-4c66-bc56-0be9ebf49d67"}},“options”:{}} 

In jsTests, we have waitForAllCollectionDropsToComplete(conn) to account for this.

Generated at Thu Feb 08 05:29:40 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.