-
Type:
Improvement
-
Resolution: Unresolved
-
Priority:
Minor - P4
-
None
-
Affects Version/s: 5.11.0
-
Component/s: None
-
None
-
None
-
Java Drivers
-
None
-
None
-
None
-
None
-
None
-
None
Hey!
I've noticed that command response times can be misleading when the thread pool is busy, for example, when running some CPU-bound code, just like serialization, whatever.
In the test case, I've created two user threads and 1 database thread.
The whole code is doing:
- wait 5 seconds for a response from the database
- by using the given command
def filter = Document.parse('{ $where: "sleep(5000) || true" }')
- after that, some CPU code is being executed for 5s
- by default, this is executed on the Mongo thread provided in TransportSettings
Current behaviour:
Metrics say that the second command finished after 10s. In reality, for 5s the thread was busy, and the task was just stuck in the Thread Pool Queue.
The full reproducible example is here
https://github.com/mongodb/mongo-java-driver/pull/2045
[mongo-thread-1] | 21:39:32 | stopped: mongodb.command in 5013.559833 ms [mongo-thread-1] | 21:39:32 | stopped: mongodb.operation in 5021.400041 ms [mongo-thread-1] | 21:39:37 | Runnable executed in: 5006 ms [mongo-thread-1] | 21:39:37 | Runnable waited: 5007 ms [mongo-thread-1] | 21:39:37 | stopped: mongodb.command in 10022.869917 ms [mongo-thread-1] | 21:39:37 | stopped: mongodb.operation in 10024.867416 ms
Why this matters:
- it may happen that the database metrics will tell, response time is 10ms
- On the other hand, client metrics will tell 100ms.
In theory:
- there was a network delay of 90ms
In practice:
- the task just waited in a thread pool queue
So what may help?
Adding a metric, like `mongo.threadpool.task.queue.wait.time`
I know it's possible to monitor the thread pool on its own, but it would be helpful to have this metric out of the box.
I/m open to any feedback or comments on that topic.