Study · Spring Boot · STEP 8 / 8 · 요청마다
첫 요청만 29ms가 걸리고, 일을 끝낸 스레드는 죽지 않고 풀로 돌아간다
같은 서버에 요청을 열 번 보냈더니 첫 번째만 29ms였고 나머지는 2–18ms였다. 코드는 하나도 안 바뀌었는데 왜 첫 번째만 느릴까? 그리고 일을 끝낸 스레드는 어디로 갈까?
아래 재생기의 ▶를 누르면 한 스텝씩 진행된다. 금색 테두리가 방금 바뀐 곳이고, 캡션이 무슨 일이 일어났는지 말해 준다. 굵게 밑줄 친 말은 누르면 뜻이 나온다.
포트는 열렸고 아직 아무 요청도 보내지 않았다. ▶를 누르면 요청 열 개를 차례로 보내며 걸린 시간을 막대로 쌓고, 그 사이 로그가 무엇을 말하는지 본다.
키보드 · ← → 한 스텝 · Space 재생/멈춤 · Home 처음
첫 요청이 느린 이유는 그 요청이 모든 단계를 그 실행에서 처음 지나가기 때문이다. 29ms를 쪼개 보면 접수→메서드 결정 3ms, 형식 고르기 10ms, 내보내기 15ms로 흩어져 있고, 두 번째 요청에서 같은 구간은 0 · 5 · 0ms다. 한 곳이 아니라 골고루 느렸다. DispatcherServlet 초기화도 이 요청 위에서 일어나기는 했지만 1ms였고 29ms를 재기 시작하는 지점보다 앞이라, 29ms 안에는 들어 있지 않다. 그리고 10분을 쉬고 다시 보낸 요청들이 exec-3 · 1 · 9 · 8 을 그대로 다시 썼다 — 스레드가 죽지 않고 풀로 돌아왔다는 증거다. 5단계의 maxThreads 200 은 더 정확히 말하면 「동시에 일을 맡은 채 반납되지 않고 있을 수 있는 스레드의 최대」다. 스레드가 DB 응답을 기다리며 아무 일도 안 하는 동안에도 그 자리를 차지하므로, 응답이 빨리 나가 반납이 빨리 되는 것이 곧 처리량이 된다.
어떻게 확인했나
- 요청 10개의 시간은 로그의 요청 접수 줄과 Completed 줄의 시각 차다. 밀리초 단위까지만 찍히므로 1ms 안팎의 오차가 있다.
- 스레드 이름도 같은 로그 줄에서 읽었다. 1차 다섯 개가 exec-2 · 3 · 1 · 9 · 8 이고, 10분 뒤 2차 다섯 개가 exec-10 · 3 · 1 · 9 · 8 이다.
- 나간 JSON 의 실제 글자는 로그에 없다. 로그에 찍히는 것은 자바 Map 을 그대로 찍은 모양이라, 장면의 JSON 줄은 같은 주소로 요청해 받은 응답 본문이다.
- 한 번의 실행에서 나온 값이다. 시간은 컴퓨터와 그때 상황에 따라 달라지므로 순서와 차이만 읽는다.