openlang

멈춘 테스트는 print보다 덤프로 읽는 게 낫다

예전에는 테스트가 멈추면 fmt.Println을 여기저기 넣고 다시 돌렸어요. 요즘은 다르게 해요. 타임아웃을 짧게 걸어 두면, 시간이 다 됐을 때 testing 패키지가 패닉을 내면서 모든 고루틴의 스택을 찍어 줘요.

package hang

import "testing"

func TestHandoff(t *testing.T) {
	results := make(chan int)
	go func() {
		results <- 42 // nobody reads this
	}()
	done := make(chan struct{})
	<-done
}

go test -timeout 3s를 돌리면 panic: test timed out after 3s, 실행 중인 테스트 목록, 그리고 고루틴이 하나씩 나와요. 고루틴마다 대괄호 안에 대기 이유가 있고, 지금 서 있는 줄이 나와요. 여기서는 중요한 두 개가 쉽게 보여요. 하나는 <-done 줄에서 [chan receive], 다른 하나는 results <- 42에서 [chan send]이고, 그 아래 created by 줄이 누가 띄웠는지 알려 줘요. 고루틴마다 얼마나 기다렸는지도 찍혀서 오래된 누수와 방금 생긴 걸 쉽게 구분할 수 있어요.

왜 그렇게 오래 print로 버텼는지 모르겠어요. 아마 기본 타임아웃이 10분이라 덤프를 볼 만큼 기다린 사람이 없어서였겠죠.

이어지는 대화 9

서로의 근거를 따라
  1. 고유 링크

    로그를 넣기 전에 스레드 덤프부터 읽던 습관의 Go 판이네요. 이렇게 정리된 글이 있어서 반가워요. 저는 이런 덤프를 읽을 때 created by 줄이 제일 도움이 됐어요. testing 패키지의 고루틴도 같이 나오는데, chan receive에 앉아 있는 testing.(*T).Run 같은 것들이 vadimk 님 고루틴과 똑같이 멈춰 보여요. 자기 테스트 함수가 만들었고 아래에 자기 파일 이름이 찍힌 고루틴부터 보면 돼요.

  2. 고유 링크

    네, 그리고 1.23에서는 created by 줄이 어느 고루틴에서 띄웠는지도 알려 줘요. created by hang.TestHandoff in goroutine 19 이런 식으로요. 고루틴이 다른 고루틴을 띄우는 구조라면 그 번호를 따라 테스트까지 거슬러 올라갈 수 있어요.

  3. 고유 링크

    대기 이유는 각 고루틴이 어디에 있는지를 알려 주며, 왜 그런지에 대한 가설을 세우기 전에 먼저 읽을 가치가 있습니다. 이 테스트의 덤프에서는 두 가지를 관찰할 수 있습니다. 테스트 고루틴은 아무도 보내지 않을 수신을 기다리고, 다른 고루틴은 아무도 받지 않을 송신을 기다립니다. 어느 하나만으로도 테스트가 멈춘 것을 설명할 수 있으므로, 덤프는 열두 줄짜리 테스트 안의 결함 하나와 그 증상이 아니라 서로 독립된 결함 두 개를 보여 줍니다.

  4. 고유 링크

    여기서는 순서가 중요합니다. 먼저 덤프입니다. 비용이 들지 않고 한순간의 모든 고루틴을 보여 줍니다. 그다음, 테스트 밖에서 멈췄다면 살아 있는 프로세스에서 net/http/pprof의 /debug/pprof/goroutine?debug=2로 같은 그림을 얻습니다. 죽어 가는 프로그램이 찍는 것과 같은 형식으로 스택을 보여 줍니다. 실행 트레이서는 그 뒤에야 열 가치가 있습니다. 멈춤을 트레이서로 시작하면 그냥 주차해 있는 고루틴의 타임라인을 읽게 됩니다.

  5. 고유 링크

    루트 글에서 한 문장이 틀렸어요. 대괄호 안의 대기 시간은 항상 나오지 않아요. 분 단위 정수로 찍혀서 1분 미만은 아예 안 보이고, 런타임은 가비지 컬렉션 패스 중에만 고루틴이 기다리기 시작한 시점을 기록해요. vadimk 님 테스트를 -timeout 75s로 돌려도 그냥 [chan send]만 나왔어요. 테스트 안에서 몇 초마다 runtime.GC()를 부르고 -timeout 70s로 돌리니까 같은 고루틴이 [chan send, 1 minutes]로 나왔어요. 그러니까 3초 타임아웃으로는 절대 못 보고, 조용한 테스트에서는 아예 못 볼 수도 있어요.

  6. 고유 링크

    테스트라면 읽기 전에 단계를 하나 더 넣겠어요. 고루틴이 수천 개면 덤프를 위에서부터 읽는 사람은 없으니까 먼저 대기 이유별로 세요.

    go test -timeout 5s 2>&1 | grep -oE '^goroutine [0-9]+ \[[^],]+' \
      | cut -d'[' -f2 | sort | uniq -c | sort -rn

    900개가 chan send에 있고 하나가 chan receive에 있다면, 그 하나와 나머지 900개를 대신 읽어 줘야 했던 쪽을 보면 돼요.

  7. 고유 링크

    덤프가 동사로 말한다는 점이 좋아요. "chan send"는 고루틴이 하려는 일이라서 누구를 기다리는지 이미 힌트를 주는데, "멈췄다"는 그런 걸 하나도 안 알려 줘요.

  8. 고유 링크

    덤프는 어디서 멈췄는지 알려 줄 뿐이다. 다음 멈춤을 싸게 만들어 주지는 않는다. 그 테스트의 송신에는 빠져나갈 길이 있어야 한다. ctx.Done()에 대한 select든 결과 수만큼 버퍼를 둔 채널이든 말이다. 그리고 테스트는 타임아웃 패닉에 기대지 말고 스스로 메시지를 남기며 실패해야 한다. 그 패닉은 테스트 바이너리 전체를 죽이기 때문에 패키지에서 멈춘 테스트 뒤의 테스트는 하나도 돌지 않는다. 송신부터 고치고 그다음에 타임아웃을 줄여라.

  9. 고유 링크

    그래도 타임아웃은 마지막 안전망으로 남겨 두고 싶어요. 스스로 실패하는 테스트는 누군가 예상한 멈춤만 잡아요. 아무도 예상하지 못한 멈춤에는 여전히 패닉과 덤프가 필요하니까, 둘 중 하나를 고르기보다 패키지의 -timeout을 줄이고 송신도 고치는 쪽이 좋겠어요.

같은 질문의 다른 갈래

  1. init의 setq가 fill-column을 버퍼 하나에서만 바꿨다

    init에 (setq fill-column 72)를 오래전부터 넣어 뒀는데, 새 버퍼에서 M-q를 누르면 여전히 70에서 줄이 바뀐다는 걸 이제야 알았어요. (*scratch*에서는 72에서 바뀌어서 그동안 스스로를 속였어요…

  2. SilentlyContinue는 철자만 나아진 On Error Resume Next

    물려받은 워크북에서 물려받은 PowerShell 스크립트로 넘어왔더니 옛 친구가 새 옷을 입고 있네요. cmdlet 호출 절반에는 -ErrorAction SilentlyContinue, 나머지에는 2>$null이 붙어 있어요…

  3. 업그레이드 가능하다는 건 스토리지 레이아웃이 영원하다는 뜻이다

    프록시 패턴이라는 말을 들으면 불변성 문제가 사라졌다고 생각하는 사람이 많습니다. 사라진 게 아니라 옮겨 갔습니다. 프록시가 상태를 들고 delegatecall로 호출을 넘기므로 구현 쪽 코드는 프록시의 스토리지 위에서 돕니…