TT Lab
Get started
Learn Learning paths Courses

The heap had room, but the service stopped

The heap had room, but the service stopped

Continue in TT Lab

Summary

If the heap and GC are fine but the service has stopped, threads are waiting somewhere. A thread dump (jcmd <pid> Thread.print) shows, at that moment, which line every thread is waiting on and for what, and it pairs the thread holding a lock with the threads queued behind it.

Why this was needed

This is the incident in the course title. On the monitoring screen: heap 40%, GC pause 5ms, CPU 3%. Yet health checks time out and users see "infinite loading." The server is alive — the port is open and the process exists. A restart brings it back. Then a few days later it stops again. The cause was that all 200 request-handling threads were standing in front of one lock, and the thread holding that lock was waiting indefinitely on an unresponsive external call. The heap shows no trace. The thread dump records it all.

How it works

The jcmd documentation describes Thread.print as "prints all threads with stack traces (impact: medium, proportional to the number of threads)," and says the -l option adds java.util.concurrent lock information. jstack <pid> gives you the same dump. A dump does not stop the JVM — it only waits briefly until threads reach a safepoint. So you can take one in production, and you should.

A fragment of a dump looks like this (JDK 21, measured).

"worker-2" #23 [213] prio=5 os_prio=0 cpu=11.78ms elapsed=1.45s tid=0x... nid=213 waiting for monitor entry
   java.lang.Thread.State: BLOCKED (on object monitor)
        at Stuck$Db.work(Stuck.java:41)
        - waiting to lock <0x000000008bb16390> (a Stuck$Db)
        at Stuck.lambda$main$3(Stuck.java:83)
"worker-1" #22 [212] ... waiting on condition
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(java.base@21/Native Method)
        at Stuck$Db.hold(Stuck.java:56)
        - locked <0x000000008bb16390> (a Stuck$Db)

The reading order is fixed. (1) Count by state — RUNNABLE means working, BLOCKED means waiting for a synchronized monitor, and WAITING/TIMED_WAITING means waiting via wait(), park(), or sleep(). If most request threads are BLOCKED, it is lock contention; if most are WAITING and the stack shows a socket read, it is waiting on an external call. (2) Collect the addresses in the waiting to lock <주소> lines (the placeholder stands for the lock address). If the same address appears dozens of times, that is the bottleneck. (3) Search for that address as - locked <주소> to find the thread holding the lock. The top of that thread's stack is the cause — in the example above it is Thread.sleep, and in reality it is usually a wait for an external response such as SocketInputStream.read.

If, rather than synchronized, you use the java.util.concurrent classes ReentrantLock and Semaphore, the state is not BLOCKED but WAITING (parking), and the line changes to - parking to wait for <주소> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) (again, the placeholder stands for the address). Only the wording differs by lock type; the way to read it is the same. The tryLock(timeout, unit) of ReentrantLock returns false if it cannot get the lock within the given time, so unlike synchronized, you can put an upper bound on the wait. Turning a request that waits forever into "try again shortly (503)" is this module's recovery.

Deadlock gets special treatment. If two threads wait on each other's locks, the JVM prints Found one Java-level deadlock: with the related threads and locks at the end of the dump, and finishes with Found 1 deadlock.. A deadlock does not resolve itself, so when you see this sentence the only answer is a restart, and the root fix is to unify the lock order.

Take several dumps. One dump is a moment. Take three at intervals of a few seconds; if the same thread stays in the same place, it really is stuck, and if it is in a different place each time, it is just busy. In jcmd output the first line is the pid and the second is the time, so the time lines of the three dumps must differ.

What it looks like in the field

The most common mistake is restarting first. A restart destroys the evidence. Taking three dumps at the moment the service is stuck takes 10 seconds — it is not too late to restart afterward. The second is running jcmd as a different user. As the documentation states, it only attaches as the same user that started the JVM. The third is counting BLOCKED threads without finding the thread holding the lock. The queued threads are victims, not the cause. The cause is at the top of the stack of the one thread that holds locked.

What you will do in the next lab

You start /opt/lab/fixtures/jvm/Stuck.java — a small HTTP service with 4 worker threads — take a dump in the normal state, then use /poison to make it hold the DB lock forever and take a dump in which the remaining requests pile up as BLOCKED. You read from the dump and write down the thread holding the lock and the number of queued threads, look at a deadlock dump with Deadlock.java, restart with -Ddb.lock.timeout.ms= to enable tryLock and confirm that the infinite wait turns into a 503, and finally save three dumps taken 2 seconds apart.