I think I found a bug in coroutines... but I'm not sure if it is really a bug or a mistake I made: After the JVM is up for +- 3 days,

delay(...)

stops working, no matter what dispatcher I use (

Dispatchers.Default

,

<http://Dispatchers.IO|Dispatchers.IO>

, custom dispatcher from a custom executor, etc). It just hangs on the

delay

call and never continues. The dispatcher/thread pool isn't overloaded, because the application is still alive and processing every request without any delay... except when there is a

delay

call somewhere, then the code hangs) Restarting the JVM magically fixes the issue, until after a few days it stops working again. Using JVM 12, Kotlin 1.3.21 + Coroutines 1.2.1 (Yes, I know, it is outdated, I didn't update yet because I couldn't get Kotlin's script engine working on 1.3.31... if reeeally needed I can update, but I decided to ask here before I do it to figure out if anyone knows what could cause this issue (or if it was already fixed))

Something is bogging down the thread the does

delay

schedule. It is called “Default Executor”.

Yeah sure, let me upload it to gist

That should not affect

delay

in the way you describe.

Strange that everything works (calling

suspend

methods, etc), but not delay

Any chance you can attach a debugger this running JVM?

Yes, but that would require a JVM restart (and that would "fix" the issue until it breaks again, which looks like it takes about three/four days for some reason)

Can you get a memory dump with

jmap

?

Yeah, the only issue is the size of the memory dump, I don't think I would be able to open it because the app has 36GBs memory allocated, but I could try

Hm… I will not be able to open it…

I can try reproducing on a smaller instance (this happened before on one of my test instances) but the issue is waiting until the problem happens again 😛

Is the process remote or local? If it is local, then you can attach debugger from IDEA without restart

remote

Bad luck. I have an interesting theory, though.

Yes

Do you use something like

delay(Long.MAX_VALUE)

to wait forever?

No, I don't... but what about "very big values that aren't `Long.MAX_VALUE`"? (Because if a user says "hey, wait 100 years because idk" and the code waits for... well,

now - 100 years in milliseconds

)

Neither should be really a problem… I’m still puzzled how to explain it… Especially this “1 hour later wakeup”

Also, it isn't exactly 1 hour, it looks like it varies

That is extremely puzzling. It basically means that something got broken inside the delay’s binary heap data-structure, but I cannot figure out how this could happen — it is pretty robust data structure, simply synchronized and well covered with tests.

Here's a example: https://gist.github.com/MrPowerGamerBR/2e5aa548745e923074604da37197fc7e

What could break is a completely broken implementation of

System.nanoTime()

(and jumps back and forth and something like that), but that kind of broken nano-time would wreak a lot of havoc elsewhere. I doubt a running system can have a problem with it.

And here's the code itself: https://github.com/LorittaBot/Loritta/blob/master/loritta-core/src/main/java/com/mrpowergamerbr/loritta/modules/WelcomeModule.kt#L180

I cannot grasp a significance of “3 days” in this context….

Yes, they are sequentially numbered

Why don’t I see them in the thread-dump? What code creates them? Maybe it’s not the

delay

after all, but those threads were not available (missing) at the time?

This is the code that creates them:

Executors.newCachedThreadPool(ThreadFactoryBuilder().setNameFormat(name).build())

Only Kotlin Coroutines uses that executor, so it can't be something else. Also, wouldn't GC remove cached thread (that are unused) after 60s, causing them to create new threads (which will have a new ID assigined to them)? And if it was the dispatcher, wouldn't using a different dispatcher work? (like

Dispatchers.Default

or

<http://Dispatchers.IO|Dispatchers.IO>

)

Can it be some kind of contention in somewhere else? Can you try with unconfined dispatcher and with direct printing to console:

GlobalScope.launch(Dispatchers.Unconfined) { 
    println("(0) at ${Instant.now()}")
    delay(1)
    println("(1) at ${Instant.now()}")
}

Do you have console output of that process redirected somewhere?

I will try doing that asap, while I don't redirect the console output (except when logging with logback) I can see the console output.

It means that indeed something somehow got broken inside the DefaultExecutor’s queue that

delay

uses.

I hope updating everything + enabling debug will help trying to track down what is causing the issue 🙂

Thanks. Let us see how it goes. Ping me if it reproduces. In debugger I’ll be interested to examine the values of the fields of

DefaultExecutor

object instance.

I ended up taking out the debug flags, it was slowing everything down and causing issues on my production instance 😞 I will keep it enabled on my test instance (which I hope I can reproduce it there)

Yes. You can use “getDeclaredField” and “setAccesible(true)” to get hold on the private fields via reflection

Oh okay, that would be helpful, can you share what fields should be get from the DefaultExecutor object that would be helpful to debug the issue + how can I get a reference to the DefaultExecutor object? I tried searching around the internet and documentation about it but I couldn't find anything about it

Suspended where? In

delay()

? In theory it should not be a problem, since

delay

queue uses O(log n) algorithm.

@elizarov I'm trying to dump the variables from the

DefaultExecutor

, while most of them I was able to, getting the

_queue

and

_delayed

values from the

EventLoopImplBase

(which I guess are the ones that you will need) is kinda difficult, they don't show up on the

declaredMembers

list, only on the

declaredFields

list, which then returns a

AtomicReferenceFieldUpdater

on the

_queue$FU

field... but what are the variable's types? In Kotlin it is a

atomic<Any?>(null)

with AtomicFu, but what would that be in Java itself?

This type is

Object

in Java. Atomics are erased during compilation.

Yeah, but doesn't the

AtomicReferenceFieldUpdater

has two types?

<*, *>

... well, actually I don't need to know the two types because you can just cast it with

<*, *>

, however I wanted to know what value should be used on the

_queue.get(SomeObjectHere)

. I tried looking at the Kotlin Coroutines code but because it uses AtomicFu, it is just a

_queue.value

call

You don’t need field updater. What you see in code as

_queue.value

is actually stored in

_queue

field.

ooooh, sorry for my mistake! I was running my test code on a test project and there the

_delayed

and

_queue

fields were null, but that's because I never spawned any coroutine task. Anyway, here's some of the dumped variables from the

EventLoopImplBase

EventLoopImplBase:
_queue = kotlinx.coroutines.internal.LockFreeTaskQueueCore@44170e37
Size: 0
_queue$FU = java.util.concurrent.atomic.AtomicReferenceFieldUpdater$AtomicReferenceFieldUpdaterImpl@671fab50
_delayed = kotlinx.coroutines.internal.ThreadSafeHeap@3d30a5ae
Size: 3300
_delayed$FU = java.util.concurrent.atomic.AtomicReferenceFieldUpdater$AtomicReferenceFieldUpdaterImpl@3ad4a630
isCompleted = false

Can you do me a favor. There’s an array

a

inside

ThreadSafeHeap

instance. It contains instance of

DelayedTask

. Can you dump all of them? I’d need

index

and

nanoTime

for each one to see if it is consistent

Sure! I will do that asap

Thanks for additional info.