Misleading Response Times Metrics in case of Async

XMLWordPrintableJSON

    • 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.

       

       

            Assignee:
            Nabil Hachicha
            Reporter:
            Mateusz Nalepa (EXT)
            None
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated: