[GitHub] [kyuubi] lightning-L commented on issue #4876: [TEST] Flaky test BackendServiceMetricSuite

["lightning-L (via GitHub)" <gi...@apache.org>]

lightning-L commented on issue #4876:
URL: https://github.com/apache/kyuubi/issues/4876#issuecomment-1575608810

   The test failed at:
   ```
   assert(timer.get(BS_OPEN_SESSION).get("min").asInt() > 0)
   ```
   It seems that the value is 0. So test failed with message: `0 was not greater than 0`.
   
   Kyuubi server uses `io.dropwizard.metrics` to implement its metrics system. And in the test, we are getting values from `org.apache.kyuubi.metrics.JsonReporterService`.
   
   The timer data is updated as Nano seconds. (`org.apache.kyuubi.metrics.MetricsSystem`)
   ```
     def timerTracing[T](name: String)(f: => T): T = {
       val startTime = System.nanoTime()
       try {
         f
       } finally {
         tracing(_.updateTimer(name, System.nanoTime() - startTime, TimeUnit.NANOSECONDS))
       }
     }
   ```
   
   There is such code in `JsonReporterService`, so we know that the unit in the json metrics report is Milli seconds.
   ```
   private val jsonMapper = new ObjectMapper().registerModule(
       new MetricsModule(TimeUnit.SECONDS, TimeUnit.MILLISECONDS, false))
   ```
   
   So there must be a conversion logic to convert the duration from nano seconds to milli seconds. 
   After debugging into MetricsModule, I think I have found the root cause for the flaky test.
   
   Below is the logic for the time unit conversion:
   <img width="902" alt="image" src="https://github.com/apache/kyuubi/assets/21362040/5ce1d251-5d7c-4875-b488-82ea2024f4ad">
   ```
   json.writeNumberField("min", (double)snapshot.getMin() * this.durationFactor);
   ```
   First, it will get the original value, which is nano seconds.
   Then it will multiply a duration factor. For milli seconds, it will be `1/1000000`.
   <img width="761" alt="image" src="https://github.com/apache/kyuubi/assets/21362040/d95c8019-74e1-496d-843d-86316c48717b">
   
   For example, if the original time is 54788598(nano seconds), it will be converted to 54.
   I have tested in my local environment, the time for opening session varies, usually takes about 50,000,000 ~ 200,000,000 nano seconds.
   But there is possibility that it takes less than 1,000,000 nano seconds.
   Let's say the value is 500,000 nano seconds, so it will be converted to 0.5 in the metrics json.
   and `timer.get(BS_OPEN_SESSION).get("min").asInt()` will evaluates to 0.
   so `assert(timer.get(BS_OPEN_SESSION).get("min").asInt() > 0)` failes.
   
   
   


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: notifications-unsubscribe@kyuubi.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org


---------------------------------------------------------------------
To unsubscribe, e-mail: notifications-unsubscribe@kyuubi.apache.org
For additional commands, e-mail: notifications-help@kyuubi.apache.org