Is okhttp3.EventListener reliable regarding time-measurements - how do you measure time correctly

I did a very interesting experience using EventListener with okhttp3 in an Android mobile project, where I want to do performance measurements regarding upload and download transfer rate by sending a http POST request without having the big time for SSL Handshake included

I therefor installed a derived class of EventListener which is overriding all http lifecycle-methods and measure the time by using System.currentTimeMillis() I'm measuring a roundtrip by sending 65kBytes in the body of the post request and the backend is returning 65kBytes in the response

Following typical lifecycle sequences are invoked:

*** callStart
*** resetMetricData
*** secureConnectStart
*** secureConnectEnd
*** connectionAcquired
*** requestHeadersStart
*** requestHeadersEnd
*** requestBodyStart
*** requestBodyEnd, requestBodyStartingTime: 1626892169366 , requestBodyTimeMS: 4 , requestBodyPayload: 65850
*** responseHeadersStart
*** responseBodyStart
*** responseBodyEnd responseBodyStartingTime: 1626892169564 , responseBodyTimeMS: 415 , responseBodyPayload: 65862

I'm taking the time in the requestBodyStart method, and 4 ms later the requestBodyEnd method is invoked showing that 65'850 Bytes have ben sent. I somehow do not trust this data, due similar case in the opposite way is showing 415 ms download the response body of 65'862 Bytes

If I show you the logs which containing the log-timestamp you can see, that the callbacks are really invoked on that time, ok there is a time of 5 ms between requestBodyStart and RequestBody end, but i still have the feeling this is not correct and in reality takes much longer than just 4 ms.

Here are the Logs:

[2021-07-21 20:29:29,084] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** callStart
[2021-07-21 20:29:29,085] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** resetMetricData
[2021-07-21 20:29:29,154] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** secureConnectStart
[2021-07-21 20:29:29,340] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** secureConnectEnd
[2021-07-21 20:29:29,346] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** connectionAcquired
[2021-07-21 20:29:29,359] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** requestHeadersStart
[2021-07-21 20:29:29,363] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** requestHeadersEnd
[2021-07-21 20:29:29,365] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** requestBodyStart
[2021-07-21 20:29:29,370] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** requestBodyEnd, requestBodyStartingTime: 1626892169366 , requestBodyTimeMS: 4 , requestBodyPayload: 65850
[2021-07-21 20:29:29,373] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** responseHeadersStart
[2021-07-21 20:29:29,559] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** responseBodyStart
[2021-07-21 20:29:29,979] RoundTripMeasurementService$RoundTripEventListener : [20521::pool-2-thread-1] INFO [RoundTrip] *** responseBodyEnd responseBodyStartingTime: 1626892169564 , responseBodyTimeMS: 415 , responseBodyPayload: 65862

Here is the class implementing the EventListener:

inner class RoundTripEventListener : EventListener(), Loggable {
        @Volatile var sslHandshakeStartTimestamp: Long? = null
        @Volatile var requestBodyStartingTime: Long? = null
        @Volatile var responseBodyStartingTime: Long? = null

        fun resetMetricData() {
            logi("[RoundTrip] *** resetMetricData")
            sslHandshakeStartTimestamp = null
            requestBodyStartingTime = null
            responseBodyStartingTime = null
            sslHandshakeTimeMS = 0 // resetting last ssl timestamp
            requestBodyTimeMS = 0
            requestBodyPayload = 0
            responseBodyTimeMS = 0
            responseBodyPayload = 0
        }

        override fun callStart(call: Call) {
            logi("[RoundTrip] *** callStart")
            resetMetricData()
        }

        override fun secureConnectStart(call: Call) {
            logi("[RoundTrip] *** secureConnectStart")
            sslHandshakeStartTimestamp = System.currentTimeMillis()
        }

        /**
         * this method will be invoked after a ssl-handshake has been finished
         */
        override fun secureConnectEnd(call: Call, handshake: Handshake?) {
            logi("[RoundTrip] *** secureConnectEnd")
            sslHandshakeStartTimestamp?.let {
                sslHandshakeTimeMS = System.currentTimeMillis() - it
            }
        }


        override fun connectionAcquired(call: Call, connection: Connection) {
            logi("[RoundTrip] *** connectionAcquired")
        }

        override fun requestHeadersStart(call: Call) {
            logi("[RoundTrip] *** requestHeadersStart")
        }

        override fun requestHeadersEnd(call: Call, request: Request) {
            logi("[RoundTrip] *** requestHeadersEnd")
        }

        override fun requestBodyStart(call: Call) {
            logi("[RoundTrip] *** requestBodyStart")
            // we need to take this time after the ssl handshake has finished, due this callback is invoked to late and then only 3 ms
            // are recorded for the request time ,which is not correct
            requestBodyStartingTime = System.currentTimeMillis()

        }

        override fun requestBodyEnd(call: Call, byteCount: Long) {
            requestBodyStartingTime?.let {
                requestBodyTimeMS = System.currentTimeMillis() - it
            }
            requestBodyPayload = byteCount
            logi("[RoundTrip] *** requestBodyEnd, requestBodyStartingTime: $requestBodyStartingTime , requestBodyTimeMS: $requestBodyTimeMS , requestBodyPayload: $requestBodyPayload")
        }

        override fun responseHeadersStart(call: Call) {
            logi("[RoundTrip] *** responseHeadersStart")
        }

        override fun responseBodyStart(call: Call) {
            logi("[RoundTrip] *** responseBodyStart")
            responseBodyStartingTime = System.currentTimeMillis()
        }

        override fun responseBodyEnd(call: Call, byteCount: Long) {
            responseBodyStartingTime?.let {
                responseBodyTimeMS = System.currentTimeMillis() - it
            }
            responseBodyPayload = byteCount
            logi("[RoundTrip] *** responseBodyEnd responseBodyStartingTime: $responseBodyStartingTime , responseBodyTimeMS: $responseBodyTimeMS , responseBodyPayload: $responseBodyPayload")
        }
    }

And here is the installation of the Listener:

 private val client = OkHttpClient.Builder().eventListener(RoundTripEventListener()).build()

and here is the post

val request: Request = Request.Builder()
                                .url(url)
                                .post(body) // 65KBytes
                                .header(AUTHORIZATION_HEADER, authorizationValue)
                                .build()


client.newCall(request).execute().use { // do some stuff with the Response}

So does anybody having some experience regarding using the EventLister with the okhttp3 client? The functionality of this class is great and it would make posible to measure pure up- and down-stream datatransfer without the time-consuming ssl handshake.

Thanks in advance for any proposal regarding that. Luke