내가 쓴 것은 SpringApplication.run(ExampleApplication.class, args) 한 줄뿐인데, 1.339초 뒤에 그 줄이 돌아온다. 그 한 줄 안에서 무슨 일이 어떤 순서로 벌어질까?
아래 재생기의 ▶를 누르면 한 스텝씩 진행된다. 금색 테두리가 지금 이야기하는 곳이고, 캡션이 무슨 일이 일어났는지 말해 준다. 굵게 밑줄 친 말은 누르면 뜻이 나온다. 빨간 딱지는 그때 벌어지는 일의 이름이고, 캡션 바로 위 회색 글자는 지금 스텝이 속한 묶음의 이름이다.
카드 아래 회색 줄은 그 일이 실제로 적혀 있는 소스의 파일 이름 : 줄 번호와 함수 이름이다. 글 안에 (:669)처럼 줄 번호만 적힌 것은 바로 앞에 적은 파일의 그 줄이라는 뜻이다. 캡션 한가운데 박힌 긴 영어 이름과 괄호 속 파일 · 줄 번호도 같다 — 건너뛰고 한글만 읽어도 뜻이 통하게 써 두었다.
장면 · 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 크고, 그래서 비율의 분모로 쓰지 않았다.
한 번의 실행에서 나온 값이다. 같은 컴퓨터에서도 돌릴 때마다 조금씩 다르므로 비율과 순서만 읽는다.