루프가 멈춘 시간을 재는 자를 만든다

목표

이벤트 루프가 얼마나 오래 멈춰 있었는지를 재는 자를 직접 만들고, 동기 작업 한 번이 그 프로세스의 모든 요청을 어떻게 함께 늦추는지 숫자로 확인합니다.

왜 중요한가

"API 가 느려요" 라는 신고가 들어오면 대개 그 API 의 코드를 먼저 봅니다. 그런데 Node 에서는 범인이 다른 곳에 있는 경우가 잦습니다. 자바스크립트를 실행하는 줄은 하나뿐이라, 어떤 요청 하나가 그 줄을 300ms 붙잡으면 그 시간 동안 도착한 모든 요청이 함께 300ms 늦습니다. 느려진 API 의 코드에는 아무 문제가 없습니다.

그래서 이 코스의 첫 도구는 프로파일러가 아니라 자 입니다. 일정한 간격으로 울리게 해 둔 타이머가 얼마나 늦게 울렸는지를 보면, 그 사이에 루프가 남의 일에 붙잡혀 있던 시간이 나옵니다. 평균은 거의 움직이지 않고 꼬리만 움직인다는 것이 이 분포의 핵심이고, 평균만 보는 대시보드가 이 사고를 못 잡는 이유입니다.

단계

/root/work/loop/lag.mjs 에 pct(samples, p) 를 만듭니다.
같은 파일에 sample({durationMs, intervalMs}) 를 만듭니다.
아무 일도 시키지 않고 재어 /root/work/loop/report.json 의 runs.idle 에 적습니다.
blockFor(ms) 를 만들고, 재는 도중에 한 번 막아 runs.blocked 에 적습니다.
100ms 를 넘긴 표본의 개수와 비율, 그리고 평균을 runs.blocked 에 더합니다.
queue({n, serviceMs, blockAt, blockMs}) 로 요청 여럿을 한꺼번에 처리해 runs.queue 에 적습니다.
verdict(run, budgetMs) 로 예산을 넘긴 표본을 세는 규칙을 만듭니다.

참고

백분위는 가장 가까운 순위(nearest-rank) 로 셉니다. 오름차순으로 정렬한 뒤 ceil(p/100 * n) - 1 번째 값이고, 범위를 벗어나면 양 끝으로 맞춥니다. 채점기가 같은 규칙으로 다시 계산해 대조합니다.
지연은 잰 간격을 뺀 나머지 입니다. 경과 시간을 그대로 담으면 조용한 상태에서도 중앙값이 간격만큼 나옵니다.
report.json 에는 node 필드로 이 파드의 판(process.version)을 적습니다.
흔한 실수: 막는 동안에도 표본이 쌓일 것이라고 생각하는 것. 루프가 멈추면 타이머도 멈추므로 그 구간은 표본 하나의 큰 값으로 나타납니다.

백분위부터 못 박는다

/root/work/loop/lag.mjs 에 pct(samples, p) 를 export 하세요. 가장 가까운 순위 규칙을 쓰고, 넘겨받은 배열을 정렬해 바꾸면 안 됩니다.

정렬은 사본에 합니다. [...samples].sort((a, b) => a - b) 로 시작하세요.

순위는 Math.ceil(p / 100 * n) - 1 이고, 0 보다 작거나 n 을 넘으면 양 끝으로 맞춥니다. p99 가 최댓값과 같아지는 작은 표본이 정상입니다.

타이머가 늦은 만큼이 루프가 멈춘 시간이다

같은 파일에 sample({durationMs, intervalMs}) 를 export 하세요. {intervalMs, durationMs, samples} 를 담은 프로미스를 돌려주고, samples 에는 간격을 뺀 늦은 시간을 ms 로 담습니다.

setInterval 로 intervalMs 마다 깨어나서, 지난번에 깨어난 시각과의 차이에서 intervalMs 를 뺍니다. 음수는 0 으로 맞춥니다.

durationMs 가 지나면 clearInterval 하고 결과를 돌려줍니다. 채점기가 이 자를 들고 스스로 루프를 막아 보므로, 실제 시각을 재야 합니다.

아무 일도 없을 때의 기준선

아무 일도 시키지 않고 1초 넘게 재어 /root/work/loop/report.json 에 node 와 runs.idle 을 적으세요. runs.idle 에는 intervalMs·durationMs·samples·p50·p99·max 를 담습니다.

기준선이 없으면 나중에 잰 숫자가 큰지 작은지 말할 수 없습니다.

p50·p99·max 는 직접 만든 pct 로 계산해 적습니다. 채점기가 samples 에서 다시 계산해 대조하므로 손으로 고치면 떨어집니다.

한 번 막고 다시 잰다

blockFor(ms) 를 export 하고(그 시간 동안 실제로 붙잡아야 합니다), 재는 도중에 blockFor(300) 을 한 번만 넣어 runs.blocked 에 적으세요. blockMs 도 함께 담습니다.

setTimeout(() => blockFor(300), 300) 처럼 재기 시작한 뒤에 한 번만 막습니다.

await new Promise(r => setTimeout(r, ms)) 는 막는 것이 아닙니다 — 기다리는 동안 루프는 자유롭습니다. 여기서는 CPU 를 붙잡고 있는 쪽이 필요합니다.

평균은 왜 아무 말도 하지 않는가

runs.blocked 에 over100(100ms 를 넘긴 표본 수), over100Ratio(소수점 넷째 자리까지), mean(평균)을 더하세요.

300ms 를 한 번 막았을 때 100ms 를 넘긴 표본이 몇 개인지 세어 보세요.

그 하나 때문에 어떤 요청은 통째로 멈췄는데 평균은 거의 그대로입니다. 평균만 보는 대시보드가 이 사고를 못 잡는 이유가 이 두 숫자에 있습니다.

느려진 것은 한 요청이 아니었다

queue({n, serviceMs, blockAt, blockMs}) 를 export 하세요. 요청 n 건을 한꺼번에 시작해 각각 serviceMs 를 기다리고, blockAt 번째만 blockFor(blockMs) 로 막은 뒤, 요청별 지연(ms) 배열을 돌려줍니다. n=10 · serviceMs=20 · blockAt=2 · blockMs=300 으로 재어 runs.queue 에 latencies·p50·p99·victims 를 적으세요.

victims 는 막은 요청을 빼고 지연이 blockMs * 0.8 이상인 요청의 수입니다.

한꺼번에 시작한다는 것은 프로미스를 모두 만들어 놓고 Promise.all 로 기다린다는 뜻입니다. for 안에서 await 하면 한 건씩 차례로 처리한 것이 되고, 그러면 이 실습이 보여 주려는 것이 사라집니다.

잰 것을 판단으로 바꾼다

verdict(run, budgetMs) 를 export 하세요. run.samples 에서 예산을 넘긴(같은 값은 넘긴 것이 아닙니다) 표본을 세어 {ok, worst, breaches} 를 돌려줍니다. 표본이 없으면 worst 는 0 입니다.

경계값을 어느 쪽에 넣을지 정해 두지 않으면 사람마다 다른 답을 냅니다. 여기서는 > budgetMs 만 위반입니다.

이 함수가 있으면 "지연이 좀 있네요" 대신 "예산 100ms 를 3번 넘겼고 최악은 310ms" 라고 말할 수 있습니다. 경보의 조건은 이런 문장에서 나옵니다.