git bisect run을 사용하여 1,000개 커밋에서 버그 찾기: 10번의 테스트 실행과 3개의 오답

• git bisect run은 1,000개 커밋 중 심어둔 버그를 10번의 테스트 실행으로 찾아냈으며, 선형 검색(linear walk)으로는 389번이 필요했습니다.

• 새로운 커밋에서만 존재하는 테스트 파일 때문에 bisect blame은 613 대신 커밋 2를 지목했습니다.

• 종료 코드 125가 없었을 때, 41개의 빌드 실패(broken builds)는 커밋 560을 지목했지만, 종료 코드가 있을 때는 17번의 실행으로 커밋 613을 찾아냈습니다.

• 느려짐 현상을 한 번 측정하는 것이 30번의 bisect에서 26개의 다른 오답 원인을 제시했고, 중앙값(median)인 9회 실행으로는 절대 놓치지 않았습니다.

저는 1,000개 커밋으로 이루어진 리포지토리에 버그를 심고 git bisect run이 이를 추적하도록 했습니다. 이 도구는 10번의 테스트 실행과 반 시간이 채 걸리지 않는 시간 안에 올바른 커밋을 찾아냈는데, 이는 한 번에 커밋 하나씩 되돌아가며 찾는 방식(walking back one commit at a time)으로는 389번이 필요했습니다.

또한 총 3번이나 잘못된 커밋을 지목했는데, 이 모든 것은 확신을 가지고 이루어졌습니다. 제 테스트 스크립트가 원인이었고, 수정하는 데 걸리는 시간은 쉘(shell) 코드 두 줄을 넘지 않았습니다.

1,000개 커밋 중 심어둔 버그를 10번의 실행으로 찾기

이 리포지토리는 쉘 루프(shell loop)에서 생성되었습니다. 모든 커밋은 변경 로그(changelog)에 한 줄을 추가하고 작은 빌드 파일을 재작성하기 때문에, 어떤 두 커밋도 동일하지 않으며 몇몇 커밋에는 특정 변경 사항들이 심어져 있습니다. 여기서 가장 중요한 것은 커밋 613인데, 이 커밋이 가격 포매터(price formatter)를

직관적인 대안은 최상단 커밋부터 테스트가 통과할 때까지 체크아웃하는 것입니다. 이 방법은 389번의 실행과 17.8초가 소요되었으며, 체크아웃 및 Node 시작 시간으로 단계당 약 46ms입니다.

단계당 46ms는 간극이 거의 느껴지지 않기 때문에 실제 프로젝트에 규모를 키워 생각해 봅시다. 만약 각 단계마다 90초의 빌드가 필요하다면, 389단계는 10시간에 가깝고 10단계는 15분입니다. 이는 제가 계산한 단순 산술일 뿐이며 벤치마크는 아니지만, 이 때문에 저는 diff를 읽기 전에 bisect을 사용하게 됩니다.

버그가 프로덕션에서만 나타나고 로컬 테스트로는 재현할 수 없는 경우엔 적용되지 않습니다. 그럴 때는 Debugging a Production Bug I Cannot Reproduce Locally에서 설명하는 것처럼, 배포 로그를 통해 bisect합니다.

아직 존재하지 않았던 테스트 파일

일반적으로 버그를 발견한 후에 실패하는 테스트를 작성합니다. 제 레포지토리의 경우, 해당 테스트인 test.js는 613 커밋의 버그가 발생한 이후인 700 커밋에 위치합니다.

따라서 명백하게 node test.js라는 스크립트는 체크아웃할 때마다 바뀌는 작업 디렉토리 내에서 실행됩니다. 700보다 오래된 모든 커밋에서는 해당 파일이 존재하지 않습니다. Node는 코드 1로 종료되고, bisect은 종료 코드 1을

저는 두 개의 경계 케이스를 시도해 보았습니다. Ctrl-C가 주는 종료 코드(130)로 종료되는 스크립트는 exit code 130 ... is < 0 or >= 128 메시지와 함께 실행을 중단시켰습니다. 스크립트 경로의 오타로 인해 발생하는 종료 코드 127은 천 개의 커밋 중 아무것도 나쁘다고 표시하지 않았습니다. Git 2.54는 error: bogus exit code 127 for good revision 메시지와 함께 중단되었습니다. 이것이 안전한 결과이지만, 여전히 아무것도 찾지 못하는 상황에 이르게 됩니다.

빌드 실패 커밋에는 종료 코드 125가 필요합니다

실제 히스토리에는 빌드가 되지 않는 커밋들이 있습니다. 제 두 번째 저장소에는 그러한 커밋이 41개 있으며, 커밋 560부터 600까지는 헬퍼 파일에 닫는 중괄호(closing brace)가 누락되어 있습니다. 이 커밋들에서 테스트를 실행하면 구문 오류로 인해 종료 코드 1과 함께 충돌합니다.

위에서 설명한 저장소 외부 스크립트를 사용했을 때, bisect는 해당 범위에 도달했고, 이 충돌을 버그로 간주하여 커밋 560을 비난했습니다. 또다시 틀렸고, 출력 결과는 실제 정답과 똑같이 보였습니다.

종료 코드 125는 bisect에게 "이 커밋은 테스트할 수 없으니, 다른 것을 골라줘"라고 알려줍니다. 그래서 스크립트는 무언가를 테스트하기 전에 코드가 로드되는지 확인합니다:

#!/bin/sh
node -e 'require("./price")' 2>/dev/null || exit 125
...

이 실행은 테스트를 17번 수행하고 1.27초가 걸렸으며 커밋 613을 찾았습니다. 41개의 빌드 실패 커밋 때문에 추가로 7번의 실행이 소요되었습니다.

만약 히스토리가 어디서 깨졌는지 이미 알고 있다면, bisect가 시작하기 전에 알려줄 수 있습니다. git bisect skip c559..c600은 41개를 모두 테스트 불가능한 것으로 미리 표시했고, 125 라인이 없는 일반 스크립트는 그 후 9번의 실행 만에 613을 찾았습니다. 저는 여전히 125 라인을 유지하는데, 이는 여러분이 알고 있는 빌드 실패 커밋들이 전부가 아닐 가능성이 높기 때문입니다.

알아두면 좋은 한계점도 있습니다. 건너뛴(skipped) 커밋이 문제의 커밋 바로 옆에 위치할 경우, Git은 어느 것이 먼저 왔는지 알 수 없습니다. 저는 612와 613을 건너뛰면서 이 상황을 강제했고, 하나의 답변 대신 The first bad commit could be any of: 아래에 세 개의 해시 값을 출력했습니다. 여전히 짧은 목록을 받지만, 단일 커밋은 아닙니다.

저는 이제 테스트 자체보다 먼저 125줄을 작성합니다. 모든 커밋이 빌드된다고 생각할 때조차도 말이죠. 컴파일된 프로젝트의 경우, 검사는 빌드 명령어입니다. 웹 앱의 경우 npm run build나 타입 체크가 될 수 있으며, '테스트 불가'와 '테스트 및 실패'를 구분하는 것이라면 무엇이든 상관없습니다.

깨진 커밋이 적다는 것은 건너뛰는(skip) 것도 적다는 뜻입니다. 타입 체크를 실행하는 pre-commit hook은 애초에 대부분의 문제를 히스토리에서 제외시키며, 이는 내가 모든 새 리포지토리에 복사하는 6가지 Git Hook 중 하나입니다.

버그 대신 속도 저하를 이분 탐색(Bisecting a Slowdown Instead of a Bug)

커밋 777에는 아무것도 깨진 것이 없습니다. 단지 Set을 indexOf로 대체했을 뿐입니다:

// 커밋 776
return [...new Set(list)];
...

50개의 고유 값에 대해 20,000개 태그가 있는 경우, 다섯 번 호출의 중앙값은 약 0.21ms에서 약 1.06ms로 증가했습니다. 이는 한 줄 변경으로 읽히는 정리 작업임에도 불구하고 5배 느려진 것입니다.

속도에 대해서는 '좋음(Good)'과 '나쁨(Bad)'이라는 용어가 어색하게 느껴지므로, bisect를 사용해 이 이름을 바꿀 수 있습니다:

git bisect start --term-old=fast --term-new=slow c1000 c1
git bisect run ~/bisect/check-speed.sh
...

그러면 출력 결과가 is the first slow commit이라고 나옵니다. 이 검사는 함수 시간을 측정하고 0.5ms를 기준으로 종료되는데, 이는 두 개의 따뜻한(warm) 숫자 사이에 있는 값입니다:

const { uniqueTags } = require(process.cwd() + "/tags");
const list = Array.from({ length: 20000 }, (_, i) => "tag-" + ((i * 7919) % 50));
...

저는 이 설정을 가지고 전체 bisect를 30번 실행했습니다. 한 번 측정했을 때, 30회 중 0번이 커밋 777을 찾았고, 그 결과는 26개의 다른 오답으로 돌아왔습니다. 5개 중앙값으로는 30회 중 29번(놓친 경우: 776)이었고, 9개 중앙값으로는 30회 모두 777을 찾아냈습니다.

단일 실행이 실패한 이유는 신규 프로세스에서 첫 호출이 느리기 때문입니다. 12번의 차가운(cold) 실행 동안 빠른 버전은 0.47ms에서 0.56ms 사이였는데, 이는 제 0.5 라인 바로 위에 위치했고, 반면 따뜻한 중앙값은 0.21 근처에 머물렀습니다. 제 추측으로는 JIT 워밍업(JIT warm-up) 때문이지만, 수정 사항이 원인에 의존하지는 않습니다. 여러 번 측정하고 중앙값을 사용하면 됩니다.

그리고 비섹트(bisect)를 시작하기 전에 양쪽 끝에서 체크를 실행하세요. 커밋 776에 대한 이 12번의 단일 실행만으로도, 그중 절반이 기준선 위에 위치했기 때문에 문제를 몇 초 만에 확인할 수 있었을 것입니다.

핵심 요약 (Bottom Line)

git bisect run은 스크립트가 좋은 것과 나쁜 것을 구분할 수 있을 때 제가 아는 가장 빠른 디버깅 도구입니다. 1,000개 커밋에 대한 10번의 실행은 쉬운 부분입니다. 문제가 생기는 곳은 스크립트이며, 이 문제는 조용히 발생합니다. 올바를 때 출력하는 것과 동일한 "첫 번째 나쁜 커밋(first bad commit)" 메시지와 함께 말이죠.

그래서 저는 git bisect start를 입력하기 전에 스크립트를 작성합니다. 이 스크립트는 리포지토리 외부에 존재하며, 코드가 빌드되지 않을 때 125를 반환하고 종료됩니다. 만약 시간을 측정한다면, 중앙값(median)을 사용하고 첫 번째 실행을 절대 신뢰하지 않습니다. 비섹트에 넘기기 전에 알려진 좋은 커밋(known-good commit)과 알려진 나쁜 커밋(known-bad commit)에 대해 각각 한 번씩 수동으로 실행하여 종료 코드가 0과 1인지 확인합니다.

만약 세션이 중간에 잘못된다면, git bisect log가 지금까지 기록된 모든 것을 출력합니다. 그것을 파일로 저장하고 잘못된 줄을 삭제하세요. git bisect reset 후, 해당 파일을 사용하여 git bisect replay를 실행하면 실수를 제외한 원래 위치로 돌아갑니다.

그 후에 비섹트가 검색을 수행하므로, 여러분은 단 하나의 diff만 읽으면 됩니다.

오늘 밤에 백로그(backlog)의 어떤 버그를 5줄짜리 체크 스크립트로 설명할 수 있나요?