Threads, Async & Event LoopsIntermediate

Timers fire late, health checks fail, one core at 100%

Symptoms

  • The Node.js API intermittently fails its health check although the process is up.
  • setTimeout(fn, 100) callbacks fire 2–3 seconds late during the episodes.
  • One core is at 100% during an episode; the other seven are idle.
  • Episodes coincide with customers requesting large CSV exports.
$ top -H -b -n1 -p 4242 | head -5              # Linux, per-thread
  PID USER  PR NI  VIRT  RES  S %CPU %MEM  TIME+   COMMAND
 4242 svc   20  0 1.2g 480m  R 99.7  3.0  18:22.1 node          # the main (event loop) thread
 4243 svc   20  0 1.2g 480m  S  0.0  3.0   0:02.4 node          # libuv pool threads
 4244 svc   20  0 1.2g 480m  S  0.0  3.0   0:02.1 node

# perf_hooks.monitorEventLoopDelay(), during an episode
event loop delay  p50: 1.1 ms   p99: 2,410 ms   max: 2,930 ms

$ strace -c -p 4242   (10 s during an episode)
% time  seconds  usecs/call  calls  syscall
 61.0   0.0061        3       2019  epoll_wait
 22.4   0.0022        1       1802  write
                                # ~0.006 s in syscalls out of 10 s: the thread is not waiting on the kernel

# node --cpu-prof, top self-time
 61.3%  JSON.stringify                 export.js:88
 22.1%  Array.prototype.sort           export.js:71
  6.2%  (garbage collector)

Investigate

Inspect areas in any order (0/6 inspected). When you think you know the root cause, commit to it.

Grow the libuv thread pool
The kernel and the scheduler
Garbage collection
CPU profile
The `async` handler
The load balancer