프로그램이 아니라 루프를 측정하기 — mere-ruby의 spec 스윕을 90분에서 11분으로

mere-ruby는 내가 만들고 있는 작은 ML 계열 언어 Mere로 작성한 Ruby 서브셋 인터프리터다. 적합성 기록은 저장소에 들어 있는 표로, ruby/spec의 모든 그룹을 진짜 ruby와 바이트 단위로 대조해 만든다. 만드는 데 한 시간 반이 걸렸다. 여러 작업이 착지하는 날에는 하루 여섯 번 스윕하는 것이 보통이므로, 작업일의 대부분이 스윕이었다.

느린 것은 인터프리터라고 넘겨짚고 있었다. 그 가정은 한 번도 측정된 적이 없었고, 기록해 둘 만한 방식으로 틀려 있었다.

첫 정직한 측정

spec 파일 하나를 하네스에 통과시키며 시계를 붙였다:

real 2.71   user 0.15   sys 1.89

user 0.15초. 두 인터프리터 — mere-ruby와 참조 ruby — 를 합쳐도 작은 파일이면 0.1초 남짓이다. 나머지는 전부 파일 시스템이었고, 그것은 하네스 자신이 한 일이었다. require_relative와 옆의 shared/, fixtures/가 풀리도록, spec 트리 (core, language, library, shared, fixtures)를 파일마다 임시 디렉터리로 복제하고 있었다.

파일 하나당 4,333개. 기록의 2,498개 파일에 대해 한 번의 스윕에 약 1,080만 번.

숫자를 보면 고치는 법은 자명하다. 트리를 한 번만 만들어 각 실행에 넘긴다. 90분이 30분이 되었다.

두 번째 대가는 안에서는 보이지 않았다. 그만큼 파일 시스템을 휘저으면 macOS의 fseventsd가 CPU 100% 이상, 수 기가바이트 상주 상태로 붙박이고, 스윕이 끝난 뒤에도 몇 시간 그대로다. 그래서 그 기계 위의 다른 모든 것이 — 다음 스윕을 포함해 — 최대 여덟 배 느려졌다. 그 느림을 인터프리터의 교착으로 읽느라 한 시간을 썼다. ps aux | sort -k3 -rn 한 줄이면 범인이 나왔다.

하네스가 답을 정하고 있었다

스윕이 세 배 빨라지면 다음 수는 자명하다. 그룹은 독립적이고 기계는 10코어다. 병렬로 돌렸다. 그리고 기록이 움직였다 — 인터프리터는 전혀 건드리지 않았는데, 두 번.

경계	기록이 말한 것
순차	core/dir 18 DIFF, 1 SLOW; 전체 CRASH 0
워커 6개, 같은 경계	core/dir 14 DIFF, 5 SLOW
워커 6개, 경계 둘 다 ×6	SLOW 13 → 4, 그리고 CRASH 0 → 4

같은 바이너리, 세 개의 다른 표. 격차는 DIFF와 SLOW와 CRASH 사이를, 어느 한계가 먼저 울리느냐에 따라 미끄러졌다 — 그리고 모든 한계가 벽시계였다. 혼자면 24초인 파일은 워커가 다섯 개 더 있으면 40초가 걸린다. 판정은 인터프리터에 대한 사실이 아니라 부하에 대한 사실이 되어 있었다.

그 표에는 교훈이 하나 더 묻혀 있다. 첫 수정은 바깥쪽 경계를 늘렸고 아무것도 바뀌지 않았다. 파일들이 넘고 있던 것은 다른, 안쪽 경계였기 때문이다. 하나의 질문에 두 개의 한계를 가진 하네스는, 그중 하나를 당신에게서 숨긴다.

정말로 뜻하는 양으로 묶기

“이것이 끝나는가”는 시계가 아니라 CPU에 대한 질문이다. 25 CPU초를 태우는 파일은 워커가 하나든 여섯이든 25초를 태운다. 그래서:

• SPEC_CPU (25초, RLIMIT_CPU)가 “끝나는가”에 답한다
• SPEC_WALL은 그것의 24배이고, 아예 돌고 있지 않은 프로세스만 잡는다. 비율로 쓰면 의도가 남는다 — 벽시계의 24분의 1도 CPU에 쓰지 않았다면 기다리는 중이다
• 바깥 경계는 SPEC_WALL에서 유도된다. 그래서 먼저 울릴 수가 없다
• 바이트가 세 번째 한계이고, 이제 스윕이 메모리 감시자를 스스로 띄운다. 사람이 기억해서 띄우던 그것은 반나절 죽어 있었다

이 모든 것을 계획한 전제가 틀렸고, 측정이 즉시 그렇게 말했다. 나는 “stdin에서 막히는 spec이 몇 개 있고 CPU를 쓰지 않으니 CPU 경계만으로는 안 된다”고 써 두었다. 측정해 보니 기록의 느린 파일 아홉 개는 전부 CPU 한계였다(84–99%). 나는 그 spec들이 무엇에 관한 것인지에 대한 기억으로 그 문장을 썼던 것이다.

SIGKILL은 인터프리터가 죽은 것이 아니다

표에서 CRASH는 “ruby가 죽지 않는 곳에서 mere-ruby가 죽는다” — 인터프리터에 대한 주장으로 정의되어 있다. 메모리 감시자가 죽인 실행은 분류기에 “출력 없음”으로 도착하므로 거기에 기록되었다. 7GB를 원하지만 동작은 하는 파일에 대해, 기록은 “인터프리터가 죽었다”고 말하고 있었다.

이제 세 한계는 하나의 판정 — 하네스가 멈췄다 — 을 내고, 행이 어느 것인지 이름을 댄다. CRASH는 다시 한 가지만 뜻하게 되었다.

⚠ 이것은 CRASH 0을 되돌리지만 인터프리터가 그것을 얻어낸 것은 전혀 아니다. 다시 분류했을 뿐이므로, 그 아래의 사실 — ruby가 수 MB면 되는 곳에서 spec 두 개가 6GB를 넘는다 — 은 결함을 기록하는 문서에 적었다. 결함은 거기에 속한다.

그리고, 기록은 측정이 아니다

그 수정의 첫 판본은 행에 실측값을 적었다 — used 25.3s of 25s CPU, peaked 5.22 GB. 분류는 안정되었고, 기록은 나빠졌다. 재현되지 않는 행이 둘에서 일곱으로 늘었다. 5.22 GB와 5.01 GB는 같은 사실이고 다른 바이트이기 때문이다.

기록과 측정은 원하는 것이 반대다. 기록은 두 번 읽어 같아야 하고, 측정은 변하는 지점에 가치가 있다. 행에는 분류를, 숫자는 커밋하지 않는 실행별 로그로.

기록이 나를 붙잡았다

이 모든 것 뒤에 스윕은 MATCH 1758을 돌려주었다. 1764가 아니라. 여섯 파일, 전부 core/env, MATCH에서 DIFF로 떨어져 있었다.

환경 변수 하나. 벽시계 경계를 안쪽 셸에 넘기려고 하네스의 허용 목록에 더했는데, core/env는 ENV 키의 개수를 센다. 양쪽이 환경에 대한 시야를 각자 다르게 구성하므로, 양쪽 모두에 주어져도 여분의 키는 공짜가 아니다 — 그리고 그 허용 목록 위의 주석에는 바로 그 이야기가, 지난번에 그것 때문에 떨어진 다섯 파일의 이름과 함께 적혀 있다. 나는 그럼에도 변수를 더했다.

변수를 지워도 여전히 하나가 어긋났다. 셸 한 겹, 그것도 여분이었다. 셸은 통째로 없앴다. alarm 때문에 perl은 원래 사슬 안에 있었으므로, 이제 perl이 fork하고, 리다이렉트하고, 리스트로 exec하고(셸을 거치지 않는다), alarm에 자식을 죽인다. 환경에는 아무것도 더해지지 않는다.

읽어서는 찾지 못했을 하나

기록이 다시 재현되게 된 뒤에도, 워커 1개와 6개 사이에서 한 행이 움직였다 — core/exception/interrupt_spec. 순차에서는 완주해 DIFF가 된다. 워커 6개에서는 참조 ruby가 벽시계 10분, CPU 0.07초로 주저앉아 있다가 벽시계 경계에 걸렸다.

이 spec은 “자기 SIGINT로 죽어야 할 자식”을 기다린다.

셸은 백그라운드로 띄운 작업의 SIGINT와 SIGQUIT를 SIG_IGN으로 만든다. 그리고 SIG_IGN은 fork뿐 아니라 exec도 넘어 상속된다. 워커는 ( … ) &이다. 즉 워커 6개에서는 그 아래 모든 spec 프로세스가 SIGINT를 무시했고, 워커 1개(전경)에서는 아무도 무시하지 않았다.

같은 popen을	결과
전경에서	자식이 죽는다 (SIGINT (signal 2))
백그라운드 서브셸에서	자식이 죽지 않는다

병렬 스윕은 대상의 일정을 바꾸고 있었던 것이 아니라, 대상 자체를 바꾸고 있었다. exec 앞의 두 줄로 고쳐졌고, 병렬 실행마다 붙던 10분짜리 꼬리가 사라졌다.

나는 이 증상을 그날 이른 시간에 “연결되지 않은 두 사실 — 발견이 아니라 열린 질문” 으로 기록해 두었다. 그 위에는 더 말끔하지만 전부 틀린 설명이 셋 있었다. 명시적으로 미해결이라고 써 두었기에 나중에 찾을 수 있었다. 확신에 찬 한 문장을 썼더라면 질문은 닫혔을 것이다.

측정해서 버린 여섯 개의 아이디어

폐기 목록은 이 기록에서 가장 많이 재사용되리라 생각하는 부분이다. 같은 숫자를 본 다음 사람은 같은 아이디어를 떠올릴 테니까.

아이디어	측정	판정
참조 출력을 스윕 간에 캐시	30분 중 약 2분	트리 수정 전이었다면 열 배의 값어치
peak RSS로 판정	모호한 두 파일은 두 경계 모두를 넘는다	답이 없는 것은 풀 수 없다
실측값을 행에 적기	불일치 행이 2 → 7	위와 같음
큰 그룹부터 분배	719.9s 대 기준선 646–662s	더 느림
워커 6개 대신 10개	736.7s, CPU는 +50s	더 느림. 병목은 공유된 직렬 자원
corpus 프로세스마다 고유한 /tmp	한 프로그램이 File.basename(__FILE__)을 출력한다	양쪽은 별개 프로세스. 바이트 일치가 깨진다

마지막 둘은 한 문장씩 값어치가 있다. 워커 10개가 같은 결과에 더 많은 CPU를 쓴 것은 경합이고, 남은 병목이 공유된 직렬 자원이라고 말해 준다 — 스윕 CPU의 절반이 시스템 시간이니, 파일 시스템이다. 정렬로도 개수로도 그것은 움직이지 않는다.

결과

	전	후
빌드 + 게이트	약 6분	약 4분
전체 기록 스윕	90분, 이후 30분	11분
여덟 개의 소스 게이트	약 29s	4.95s
그중 하나 dead_defs_check	22.99s	0.64s
bracket_depth	75.04s	11.97s
corpus, 두 모드	111.65s	70.0s
CI	11분 04초	8분 34초

dead_defs_check가 가장 소박하다. 정의마다 awk를 하나씩 띄우고, 각각이 사용처 표 전체를 훑고 있었다 — 2,575개 프로세스로 7,577개 식별자, 1,950만 줄 스캔. 두 표를 하나의 awk에 읽히면 같은 질문에 답할 수 있다.

기록 자체는 움직이지 않았다: 103그룹, 2,498파일, MATCH 1764, CRASH 0. 이제 워커 1개와 6개에서 바이트 단위로 같아졌고, 그것이 본래의 주장이며 속도는 그 귀결일 뿐이다.

측정에 대해 내가 틀린 부분

스케줄링 아이디어 둘을 시험했더니 둘 다 느리게 나왔다. 그때 macOS의 스토리지 색인이 CPU의 150%를 먹고 있었다. 측정 불가로 둘 다 철회했다 — 몇 시간 떨어진 세 번의 스윕은 비교가 아니다.

그러고 나서 대조를 돌렸다. 손대지 않은 하네스를, 같은 부하 아래에서. 646초. 일곱 시간에 걸친 기준선과 일치한다. 부하는 높았지만 일정했다 — 교란이 아니라 상수였고, 두 변경은 그 바깥에 충분히 떨어져 있었다. 철회 쪽이 오류였고, 그것을 찾아낸 것은 대조였다.

⚠ 불편한 쪽 절반. 그 색인은 오전부터 보였고 나는 그때 기록까지 해 두었다. 그것이 “교란”으로 승격된 것은 숫자가 시험 중인 변경에 불리하게 나온 뒤였다. 큰 그룹부터 분배해서 10% 빨랐다면, 대조 없이 커밋했을 것이다.

그러니 규칙은 “뜻밖의 결과를 의심하라”가 아니다. 전후는 같은 창 안에서 짝지을 것. 그리고 의심할지 말지는 어떻게 측정했는지로 정할 것 — 어느 쪽으로 나왔는지로 정하지 말 것.

덧붙임 — 문서도 같은 병을 앓고 있었다

이게 전부 정리되어 있느냐는 질문에 나는 그렇다고 답했다. 그러고 나서 확인했다.

루프 문서는 추가 전용이고, 세 번의 편집이 살아 있는 질문에 이미 참이 아니게 된 방식으로 답하는 절을 세 개 남겨 두었다. 독자가 먼저 만나는 것은 가장 오래된 것이다. 다른 절은 나중의 측정이 부정한 주장을 여전히 내걸고 있었다. 173줄이 본문과 모순되고 있었다.

나는 그날 내내 “기록이 내 실수를 잡았다”고 쓰면서, 기록 자체는 아무도 검사하지 않는 상태로 두었던 것이다. 커밋된 기록에서 기계 경로를 거부하는 게이트는 이제 같은 제목의 절을 두 개 가진 문서도 거부한다 — 한 사본을 교체하고 다른 사본을 지우지 못한 편집의 서명이다.

추적 중인 모든 문서에서 오탐 0을 확인했고, 하나를 더해 독을 먹여 보았다.