kevin.cianfarini
10/21/2023, 9:37 AMDispatchers.Default
on a linux machine, I'm seeing delays resumed before I'm expecting them to very frequently. The following code:
public suspend fun Clock.delayUntil(instant: Instant) {
val expectedDuration = instant - now()
val actualDuration = measureTime { delay(duration = expectedDuration) }
if (actualDuration < expectedDuration) {
println("Supposed to delay for $expectedDuration, delayed for $actualDuration.")
}
}
Produces the following logs when run iteratively over ~1 minutes, so this is a common occurrence.
Supposed to delay for 998.612601ms, delayed for 998.557767ms.
Supposed to delay for 998.891639ms, delayed for 998.538202ms.
Supposed to delay for 998.744499ms, delayed for 998.735252ms.
Supposed to delay for 998.929048ms, delayed for 998.500404ms.
Supposed to delay for 998.832210ms, delayed for 998.619967ms.
Supposed to delay for 998.589884ms, delayed for 998.523756ms.
Supposed to delay for 998.921973ms, delayed for 998.628101ms.
Supposed to delay for 998.890982ms, delayed for 998.699278ms.
Supposed to delay for 998.776822ms, delayed for 998.580276ms.
Supposed to delay for 998.765377ms, delayed for 998.495635ms.
Supposed to delay for 998.642242ms, delayed for 998.615320ms.
Supposed to delay for 998.962181ms, delayed for 998.829443ms.
Supposed to delay for 998.788745ms, delayed for 998.536458ms.
I am personally surprised by this. I would have expected delays to always suspend for an amount of time equal to or greater than the passed in duration, but never less than. Is that an unreasonable expectation?cron
-like API to schedule jobs.linuxX64
K/N seems even less accurate.
Supposed to delay for 998.913685ms, delayed for 998.282396ms, difference of 631.289us.
Supposed to delay for 999.682193ms, delayed for 999.291051ms, difference of 391.142us.
Supposed to delay for 998.704951ms, delayed for 998.309983ms, difference of 394.968us.
Supposed to delay for 998.844689ms, delayed for 998.286725ms, difference of 557.964us.
Supposed to delay for 998.911791ms, delayed for 998.283234ms, difference of 628.557us.
Is potentially resuming a delay for upwards of half a ms before intended considered expected behavior?runBlocking
event loop seems to suffer from the same problem on the JVM.
Supposed to delay for 997.837087ms, delayed for 997.760069ms, difference of 77.018us.
Supposed to delay for 998.845540ms, delayed for 998.381947ms, difference of 463.593us.
Supposed to delay for 998.618864ms, delayed for 998.390328ms, difference of 228.536us.
Supposed to delay for 998.847573ms, delayed for 998.409186ms, difference of 438.387us.
Sam
10/21/2023, 10:15 AMInstant.now()
only has millisecond precision on the JVM I'm looking at right now.kevin.cianfarini
10/21/2023, 10:17 AMdelay(Long)
to narrow it downInstant
. Seems the bug is mine after all 😄@Test fun foo() = runTest(timeout = 1.days) {
withContext(Dispatchers.Default) {
while (true) {
val expectedDuration = 998.milliseconds + 902752.nanoseconds
val actualDuration = measureTime { delay(expectedDuration) }
val difference = actualDuration - expectedDuration
println("Supposed to delay for $expectedDuration, delayed for $actualDuration, difference of $difference.")
}
}
}
Sometimes does not delay for the required duration. Here are the following logs for JVM on my Linux box.
Supposed to delay for 998.902752ms, delayed for 1.000313484s, difference of 1.410732ms.
Supposed to delay for 998.902752ms, delayed for 998.778686ms, difference of -124.066us.
Supposed to delay for 998.902752ms, delayed for 999.019637ms, difference of 116.885us.
Supposed to delay for 998.902752ms, delayed for 998.660794ms, difference of -241.958us.
Supposed to delay for 998.902752ms, delayed for 998.949447ms, difference of 46.695us.
Supposed to delay for 998.902752ms, delayed for 998.573213ms, difference of -329.539us.
Supposed to delay for 998.902752ms, delayed for 998.600730ms, difference of -302.022us.
Supposed to delay for 998.902752ms, delayed for 999.076977ms, difference of 174.225us.
Supposed to delay for 998.902752ms, delayed for 998.584946ms, difference of -317.806us.
Anything negative resumes prior to when it's expected.Supposed to delay for 998.902752ms, delayed for 998.751622ms, difference of -151.13us.
Supposed to delay for 998.902752ms, delayed for 998.394454ms, difference of -508.298us.
Supposed to delay for 998.902752ms, delayed for 998.351222ms, difference of -551.53us.
Supposed to delay for 998.902752ms, delayed for 998.766148ms, difference of -136.604us.
Supposed to delay for 998.902752ms, delayed for 998.434123ms, difference of -468.629us.
Supposed to delay for 998.902752ms, delayed for 998.680873ms, difference of -221.879us.
Supposed to delay for 998.902752ms, delayed for 998.431539ms, difference of -471.213us.
Supposed to delay for 998.902752ms, delayed for 998.816225ms, difference of -86.527us.
delay(Duration)
the value is converted to milliseconds and delegated to delay(Long)
. This loses the nanosecond granularity because the only coercion done is to ensure that Duration.inWholeMilliseconds
doesn't produce a zero value.
internal fun Duration.toDelayMillis(): Long =
if (this > Duration.ZERO) inWholeMilliseconds.coerceAtLeast(1) else 0
I think what this should really be doing is rounding nanoseconds up to the nearest millisecond so as to not lose nanoseconds which are important. Logs which show this:
Supposed to delay for 992.759049ms, delayed for 992.691033ms, difference of 68.016us.
now: 2023-10-21T15:31:06.007240951Z
delayUntil: 2023-10-21T15:31:07Z
delayMillis: 992
private fun Duration.myToMillis(): Long {
val millis = inWholeMilliseconds
return if (millis * 1_000_000 < inWholeNanoseconds) millis + 1 else millis
}
Which rounds up the nanosecond, everything works as expected.