[JAVA-4811] 'maxIdleTimeMS' is not adhering to the Mongo Docs Created: 14/Nov/22  Updated: 27/Oct/23  Resolved: 14/Nov/22

Status: Closed
Project: Java Driver
Component/s: Connection Management
Affects Version/s: None
Fix Version/s: None

Type: Question Priority: Unknown
Reporter: Namila Bandara Assignee: Valentin Kavalenka
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File image-2022-11-14-09-04-03-011.png    
Issue Links:
Related

 Description   

Summary

Hi,

Currently, I'm working on a mongo java project (Spring boot) that enables the mongo connection pooling for mongo replicates (3 replications - 1 master and 2 replicates). Here I'm using the following mongo connection string variables;

&maxPoolSize=100&minPoolSize=1&waitQueueTimeoutMS=1000&maxIdleTimeMS=10000 

So according to this connection string, it should create a pool with min 1 connection for the replicates DB, hence the 3 connections from the application. And the definitions from Mongo Docs regarding the `maxIdleTimeMS` (Connection Pool Overview — MongoDB Manual){_}

Amount of time that a connection can be idle in the pool before closing. Idle connections close until the number of open connections equals minPoolSize.

Java driver doc;(Connection Options — Java (mongodb.com))

 


Specifies the maximum amount of time, in milliseconds, the Java driver will allow a pooled connection to idle before closing the connection. A value of 0 indicates that there is no upper bound on how long the driver can allow a pooled collection to be idle.

According to Mongo Docs, this means there should be a connection cleaning when there is only min connection opened or if there are more connections (>3) and idle for 10s, the driver should clear all the idle connections except the min pool. 

From what I observed in my project, the mongo driver is clearing all the connections (even the min pool connections) and creating it again after 10s, and repeating this again and again, which will use more resources for connection creation.

Please refer to the following sample logs I have collected from the application. connections 1,3,5 is the initial connections created to the replicate server. And those are killed and created again after 10s.

sample logs;

08:30:20.149 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:1, serverValue:1992301}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:30:20.176 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:3, serverValue:1992376}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:30:20.176 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:5, serverValue:2001746}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:30:22.627 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:7, serverValue:1992346}] to <REMOVED>.mongodb.net:27017 08:30:22.656 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:8, serverValue:2001795}] to <REMOVED>.mongodb.net:27017 08:30:22.666 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:9, serverValue:1992423}] to <REMOVED>.mongodb.net:27017 08:31:20.147 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:7, serverValue:1992346}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:31:20.177 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:9, serverValue:1992423}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:31:20.177 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:8, serverValue:2001795}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:31:22.656 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:11, serverValue:1992473}] to <REMOVED>.mongodb.net:27017 08:31:22.656 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:12, serverValue:2001841}] to <REMOVED>.mongodb.net:27017 08:31:22.656 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:10, serverValue:1992399}] to <REMOVED>.mongodb.net:27017 08:32:20.151 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:10, serverValue:1992399}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:32:20.181 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:11, serverValue:1992473}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:32:20.181 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:12, serverValue:2001841}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:32:22.615 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:14, serverValue:2001888}] to <REMOVED>.mongodb.net:27017 08:32:22.674 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:13, serverValue:1992442}] to <REMOVED>.mongodb.net:27017 08:32:22.674 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:15, serverValue:1992519}] to <REMOVED>.mongodb.net:27017 08:33:20.150 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:13, serverValue:1992442}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:33:20.180 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:14, serverValue:2001888}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:33:20.180 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:15, serverValue:1992519}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:33:22.574 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:16, serverValue:1992488}] to <REMOVED>.mongodb.net:27017 08:33:22.671 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:17, serverValue:1992562}] to <REMOVED>.mongodb.net:27017 08:33:22.672 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:18, serverValue:2001931}] to <REMOVED>.mongodb.net:27017 08:34:20.148 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:16, serverValue:1992488}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:34:20.178 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:18, serverValue:2001931}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:34:20.178 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:17, serverValue:1992562}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 08:34:22.611 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:19, serverValue:1992531}] to <REMOVED>.mongodb.net:27017 08:34:22.680 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:20, serverValue:1992608}] to <REMOVED>.mongodb.net:27017 08:34:22.680 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:21, serverValue:2001978}] to <REMOVED>.mongodb.net:27017 
 

Please provide the version of the driver. If applicable, please provide the MongoDB server version and topology (standalone, replica set, or sharded cluster).

current mongo drivers: 

Mongo Server: Replica (1 master and 2 replicates)

How to Reproduce

Create a spring-boot project with the above mongo replicate connection with the above string parameters

Additional Background

 



 Comments   
Comment by Namila Bandara [ 16/Nov/22 ]

Hi Valentin, thanks for clarifying the issue.

Comment by Valentin Kavalenka [ 14/Nov/22 ]

Hi namila007@gmail.com,

The MongoDB manual you are referring to is not fully correct in its description of the maxIdleTimeMS connection option, while being correct in a different place. You may also see that neither the driver connection guide nor the driver API restrict the effect of this option with minPoolSize. The behavior you are observing is intended, but we need to change the description of this connection option in the MongoDB manual (I filed an internal ticket for that).

While the obvious use of this option is to deflate a pool, as less obvious use is to work around the behavior of some intermediary software/hardware that may detect idle TCP connections and terminate them. By setting this option to a value smaller than that used by an intermediary, a user may ensure that a pool terminates idle connections before an intermediary would have done that. If as a result of such termination the pool size drops below minPoolSize, then the pool establishes a connection replacing the terminated one (often, ASAP). This is better than a situation when an intermediary terminates a connection, as that will only be detected when trying to use the connection to execute a user operation based on the failure of the attempt.

Comment by Namila Bandara [ 14/Nov/22 ]

logs:

08:30:20.149 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:1, serverValue:1992301}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:30:20.176 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:3, serverValue:1992376}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:30:20.176 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:5, serverValue:2001746}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:30:22.627 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:7, serverValue:1992346}] to <REMOVED>.mongodb.net:27017 
08:30:22.656 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:8, serverValue:2001795}] to <REMOVED>.mongodb.net:27017 
08:30:22.666 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:9, serverValue:1992423}] to <REMOVED>.mongodb.net:27017 
08:31:20.147 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:7, serverValue:1992346}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:31:20.177 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:9, serverValue:1992423}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:31:20.177 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:8, serverValue:2001795}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:31:22.656 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:11, serverValue:1992473}] to <REMOVED>.mongodb.net:27017 
08:31:22.656 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:12, serverValue:2001841}] to <REMOVED>.mongodb.net:27017 
08:31:22.656 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:10, serverValue:1992399}] to <REMOVED>.mongodb.net:27017 
08:32:20.151 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:10, serverValue:1992399}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:32:20.181 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:11, serverValue:1992473}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:32:20.181 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:12, serverValue:2001841}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:32:22.615 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:14, serverValue:2001888}] to <REMOVED>.mongodb.net:27017 
08:32:22.674 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:13, serverValue:1992442}] to <REMOVED>.mongodb.net:27017 
08:32:22.674 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:15, serverValue:1992519}] to <REMOVED>.mongodb.net:27017 
08:33:20.150 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:13, serverValue:1992442}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:33:20.180 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:14, serverValue:2001888}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:33:20.180 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:15, serverValue:1992519}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:33:22.574 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:16, serverValue:1992488}] to <REMOVED>.mongodb.net:27017 
08:33:22.671 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:17, serverValue:1992562}] to <REMOVED>.mongodb.net:27017 
08:33:22.672 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:18, serverValue:2001931}] to <REMOVED>.mongodb.net:27017 
08:34:20.148 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:16, serverValue:1992488}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:34:20.178 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:18, serverValue:2001931}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:34:20.178 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Closed connection [connectionId{localValue:17, serverValue:1992562}] to <REMOVED>.mongodb.net:27017 because it is past its maximum allowed idle time. 
08:34:22.611 - [MaintenanceTimer-1-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:19, serverValue:1992531}] to <REMOVED>.mongodb.net:27017 
08:34:22.680 - [MaintenanceTimer-2-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:20, serverValue:1992608}] to <REMOVED>.mongodb.net:27017 
08:34:22.680 - [MaintenanceTimer-3-thread-1] INFO  org.mongodb.driver.connection -  - Opened connection [connectionId{localValue:21, serverValue:2001978}] to <REMOVED>.mongodb.net:27017 
 
 

Generated at Thu Feb 08 09:03:01 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.