내가 쓴 것은 SpringApplication.run(ExampleApplication.class, args) 한 줄뿐인데, 1.339초 뒤에 그 줄이 돌아온다. 그 한 줄 안에서 무슨 일이 어떤 순서로 벌어질까?
아래 재생기의 ▶를 누르면 한 스텝씩 진행된다. 금색 테두리가 방금 바뀐 곳이고, 캡션이 무슨 일이 일어났는지 말해 준다. 굵게 밑줄 친 말은 누르면 뜻이 나온다.
장면 · main() 한 줄이 무엇을 시작하나0 / 12
run() 본문은 일곱 걸음이다 — ① 설정을 읽고 ② 배너를 찍고 ③ 빈 통을 만들고 ④ 내 클래스를 등록하고 ⑤ 통을 채우고 ⑥ 다 됐다고 알리고 ⑦ 내 러너를 부른다. ▶를 누르면 이 걸음들을 12스텝으로 따라간다. 스텝이 더 많은 것은 ⑤ 한 걸음 안에서 벌어지는 일을 네 스텝으로 펼쳐 보기 때문이다(배너 찍기는 화면에서 건너뛴다).
키보드 · ← → 한 스텝 · Space 재생/멈춤 · Home 처음
run()이 하는 일은 일곱 걸음이지만 시간은 고르게 쓰이지 않는다. 로그로 볼 수 있는 구간은 첫 줄 24.681부터 마지막 줄 25.767까지 1,086ms인데, refreshContext 한 걸음이 그중 1,058ms(24.709→25.767)로 97%를 쓴다. 그 앞의 세 걸음은 다 합쳐 28ms(24.681→24.709)다. 2 · 3 · 4 · 5단계에서 볼 일이 전부 그 한 줄 안에서 벌어진다.
어떻게 확인했나
일곱 걸음의 이름과 순서는 스프링 부트 4.0.6 의 SpringApplication.run 안에 적힌 호출 순서를 그대로 옮겼다.
시각(24.681 · 24.709 · 25.247 · 25.466 · 25.755 · 25.767)과 1.339초는 --debug 를 붙여 한 번 돌린 기동 로그에서 읽었다. 계산은 이렇다 — 로그 폭 25.767 − 24.681 = 1,086ms, refreshContext 25.767 − 24.709 = 1,058ms, 앞의 세 걸음 24.709 − 24.681 = 28ms, 1,058 ÷ 1,086 = 97%. 1.339초는 로그가 찍히기 전부터 재기 시작한 값이라 1,086ms 보다 253ms 크고, 그래서 비율의 분모로 쓰지 않았다.
한 번의 실행에서 나온 값이다. 같은 컴퓨터에서도 돌릴 때마다 조금씩 다르므로 비율과 순서만 읽는다.