Poisoned pod, extremely slow, weird thread counts

[KadekM]

Our pods (hosted in kubernetes) sometimes get poisoned and 100% of their requests become incredibly slow (think 5-25secs instead of <1s).
Response is slow even with zero traffic (essentially only test curl).
Non poisioned pod from same deployment works just fine (and has normal numbers in jmx etc).

interesting jmx of poisioned pod

ComputePoolSampler.ActiveThreadCount is 65534 
ComputePoolSampler.WorkerThreadCount is 2
ComputePoolSampler.SearchingThreadCount is 65535. 
ComputePoolSampler.BlockedWorkerThreadCount is 0

Weirdly threaddump shows < 100threads. threads_dump.txt

scala2.13.6
cats-effect: 3.6.2
doobie 1.0.0-RC9
sttp client with armeria backend 3.11.0
tapir + http4s 1.11.36

vm 17.0.15 eclipse adoptium (observed also on 21)

jvm options
 -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.local.only=false -Dcom.sun.management.jmxremote.port=1099 -Dcom.sun.management.jmxremote.rmi.port=1099 -Djava.rmi.server.hostname=127.0.0.1 -XX:+UseG1GC -XX:G1PeriodicGCInterval=30000 -XX:+PrintCommandLineFlags -Dsun.net.inetaddr.ttl=30 -Dpidfile.path=/dev/null -XX:+CrashOnOutOfMemoryError -XX:MaxMetaspaceSize=320m -XX:ReservedCodeCacheSize=64m -XX:CompressedClassSpaceSize=64m -XX:InitialHeapSize=519m -XX:MaxHeapSize=1038m
-XX:CompressedClassSpaceSize=67108864 -XX:ConcGCThreads=1 -XX:+CrashOnOutOfMemoryError -XX:G1ConcRefinementThreads=2 -XX:G1PeriodicGCInterval=30000 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=544210944 -XX:+ManagementServer -XX:MarkStackSize=4194304 -XX:MaxHeapSize=1088421888 -XX:MaxMetaspaceSize=335544320 -XX:MinHeapSize=6815736 -XX:+PrintCommandLineFlags -XX:ReservedCodeCacheSize=67108864 -XX:-THPStackMitigation -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC

If we kill the pod the new one works just fine, but roughly once a day we see this happen on eventually on multiple pods across multiple services, where only commonality is cats-effect 3.6.2, latest scala2, tapir and sttp client, doobie rc9 (though not necessarily the same client/server backends).

k8 instances

 limits:
            cpu: 1100m
            memory: 1200Mi
          requests:
            cpu: 600m
            memory: 1200Mi

Some pods never get poisoned, we haven't yet observed any pattern except that it happens semi-regularly, and once it's poisioned it doesn't recover.

[durban]

ComputePoolSampler.ActiveThreadCount is 65534
ComputePoolSampler.WorkerThreadCount is 2
ComputePoolSampler.SearchingThreadCount is 65535.
ComputePoolSampler.BlockedWorkerThreadCount is 0

Just to clarify: do you get these exact numbers with both 3.6.0 and 3.6.2?

[KadekM]

ComputePoolSampler.ActiveThreadCount is 65534
ComputePoolSampler.WorkerThreadCount is 2
ComputePoolSampler.SearchingThreadCount is 65535.
ComputePoolSampler.BlockedWorkerThreadCount is 0

Just to clarify: do you get these exact numbers with both 3.6.0 and 3.6.2?

Correct. I'm just looking at two pods from two different services, one is on 3.6.0 and other one 3.6.2, both with same problem
edit:see below

[KadekM]

it seems to jump to that value. Poisioned pod is the youngest one (6hours old, others are 8h and 2d)

[KadekM]

sidenote - I ran a stress test on the healthy pod (pushing it up to failure). hoping to see that maybe it might eventually enter into the poisoned state, but nope.

[djspiewak]

I'm pretty sure this is a real bug with state management. The searching and active counts come directly from masking and shifting the state. Also they're Ints so we're not looking at any sort of weird overflow. These states are semantically significant though; we're not just looking at harmless metrics here. So I think the pool is in a borked state.

[KadekM]

Yea, we can observe the pod with those numbers is very slow perf wise.
Is there anything I can do to help with identifying/replicating the issue?

[djspiewak]

Is there anything I can do to help with identifying/replicating the issue?

Maybe? Not sure yet. Do you have any blocking or interruptible usage? I see in your thread dump that you have a ton of other non-CE thread pools (which btw are seriously starving the CE compute work, so you definitely have performance issues even outside of the poisoning). Are most of your work units coming in via http4s or via kafka?

I'm almost positive that there's some sort of race condition going on here within the WorkerThread state machine which is causing the state to get decremented all the way to -1. This almost certainly means that transitionWorkerFromSearching is being called twice on a thread when it should have been called once. It seems possible that this may happen more frequently when low thread counts. @armanbilge

As a possible workaround, @KadekM, you could try overriding the thread count in your IOApp to be double or quadrouple the default. It's going to create a lot of kernel scheduler thrashing, but you already have a fair amount of that going on so it won't be that much worse.

[djspiewak]

Compounding the mystery here… I thought for a bit it might have something to do with Arman's fancy new state machine, but that doesn't exist in 3.6. Then I thought it could be a bug I introduced with the conditional polling, but if you're seeing the issue on 3.6.0 that can't be it either. This is profoundly strange. A lot of the code we're talking about here hasn't changed meaningfully in quite a long time. Did you ever run this application on 3.5.x?

[KadekM]

Do you have any blocking or interruptible usage?

interruptible almost none, blocking from internal deps from contextual logging (over Slf4jLogger) and config loading (one-off) and then perhaps if sttp-backends or other deps needs it

Are most of your work units coming in via http4s or via kafka?

it varies between services, but I've seen this poison in both pure event processors and regular http crud service

Did you ever run this application on 3.5.x?

Yes, but to make it more strange we've been starting to get these issues only ~2 weeks ago (I also see it in Grafana), so we've been running 3.6.x series since April with no issues until recent - unfortunately I can't speak of this in high confidence - because we might have not noticed this as we're gradually adding cats effect metrics etc. But it does affect very low single digit % of all the cats-effect pods we run for sure. To rephrase it, it seems we've been successfully running 3.5.x and 3.6.x with no observed issues until recently.

[lenguyenthanh]

We have a slightly different symptom (so this can be a totally different issue). Since updated to CE 3.6.2 (transitively via otel4s 0.13.1) our process's requests responses just went significant higher (10-20 times) then normal after 12-14 hours. Not all instances started to act up at the same times, but eventually all of them are acting up.

After it went up, it's never back down, and it happen at the same time with starvation warning.

We did try (but didn't help):

• switch from Blaze to Emeber
• override pollingSystem with SleepSystem

It works fine CE 3.6.1 version. So, I'm suspect #4377 is the cupid but totally guessing here.

[KadekM]

@djspiewak @durban I misled you - sorry. Our services were on cats-effect 3.6.2. We're downgrading to 3.6.0 at this moment (and actually double checking now we haven't pulled in transitively 3.6.2).
Will keep monitoring 3.6.0. So for us it's only on 3.6.2 confirmed so far.

[iRevive]

I noticed the same issue at $work - p95 latency jumped from 10 ms to 200 ms 😕.
ActiveThreadCount is 65534 and SearchingThreadCount is 65535.

I will be sure to provide more details today.

[durban]

So, the exact version is important here, because #4377 is only in 3.6.2, and that PR touches the WorkerThread state machine, the same state machine which is doing something very weird if state is (65534, 65535) or (65535, 65535). If the bug is not in 3.6.0, that's important information. (For example, so far I've looked at the 3.6.0 code... which is of course futile, if the bug is in #4377 :-)