「bcrypt 때문」이라고 말하고 나서 쟀다 — 3분 6초가 7.5초, 가드는 깨뜨려 봐야 가드였다

「테스트가 너무 오래 돕니다.」 사내 제안서 지식검색 도구의 업무 화면 쪽 백엔드에서 들은 말입니다. 테스트 823개가 한 바퀴에 3분 6초 걸렸습니다. 그 자리에서 제가 먼저 한 말은 「bcrypt 때문일 겁니다」였습니다.

근거는 있었습니다. 사용자를 만들고 로그인하는 헬퍼가 테스트마다 도는 구조를 알고 있었습니다. bcrypt 가 일부러 느리게 만든 해시라는 것도 알고 있었습니다. 그런데 잰 적은 없었습니다.

이틀 전 같은 프로젝트에서 「내가 안 쟀다」를 「아무도 안 쟀다」로 옮겨 적은 일이 있었습니다. 그래서 이번에는 말하고 나서 바로 재기부터 했습니다.

가장 느린 15개를 더해도 18초였습니다

먼저 전체 시간을 쟀습니다. 186.85초였습니다. 다음으로 느린 순서대로 상위 15개를 뽑았습니다. 15개의 합이 18초였습니다. 전체의 10%가 안 됩니다. 한두 개가 병목인 모양이 아니었습니다. 823개가 전부 조금씩 느린 분포였습니다.

그래서 한 건의 비용을 따로 쟀습니다. bcrypt 의 기본 작업계수는 12입니다. 이 값으로 해시 한 번이 175ms, 검증 한 번이 174ms 였습니다.

의심했던 다른 후보는 무시할 수준이었습니다. sqlite 스키마 생성이 1.8ms, 앱 import 가 280ms 였습니다. 823개에 고르게 깔린 175ms 짜리 호출이 답이었습니다.

프로파일러의 「가장 느린 N개」는 병목이 몇 개일 때만 답을 줍니다. 상위 15개의 합이 전체의 10%면 병목은 없고 바닥이 높은 것입니다. 이 모양에서는 느린 테스트 몇 개를 고쳐도 전체 시간이 거의 안 줄어듭니다. 바닥을 낮춰야 했습니다.

빠르게 만드는 방법은 셋인데, 둘은 검사를 줄입니다

해시를 안 부르거나 싸게 부르는 방법을 세 가지 놓고 봤습니다.

A 와 B 는 테스트 개수가 그대로입니다. 823 passed 라는 초록불도 그대로 뜹니다. 그런데 그 초록불 가운데 일부는 로그인 검증을 한 번도 안 지나간 초록불입니다. 속도를 얻는 자리에서 검사가 조용히 빠지는 형태가 이것입니다.

C 를 골랐습니다. bcrypt 의 작업계수는 반복 횟수를 정하는 값이라, 낮춰도 여전히 진짜 bcrypt 해시입니다.

비밀번호 검증 함수도 그대로 검증합니다. 해시 문자열 안에 작업계수가 들어가므로 검증도 같이 빨라집니다. 파라미터 하나만 낮추면 해시 형식·검증 경로·헬퍼 호출이 전부 그대로입니다.

테스트에서만 4로 내리고, 운영의 12는 가드가 봅니다

인증 모듈에 작업계수를 상수로 뒀습니다. 운영 값은 12 그대로입니다. 테스트 공통 설정(conftest)의 autouse 픽스처가 매 테스트 앞에서 이 값을 4로 바꿉니다. 테스트 밖에서는 아무것도 안 바뀝니다.

결과는 186.85초에서 7.54초입니다. 약 25배입니다. 823 passed / 3 skipped 로 개수는 같습니다. 해시 한 번이 175ms 에서 0.7ms 가 됐습니다.

테스트에 고정 해시가 박혀 있으면 작업계수를 바꾸는 순간 검증이 깨집니다. grep 으로 그런 해시가 없는 것을 확인했습니다. 이 확인이 빠지면 같은 처방이 다른 레포에서 깨집니다.

그런데 「테스트에서만 4」는 「운영은 12」를 전제로 합니다. 그 전제를 보는 사람이 없으면 누군가 운영 상수를 낮춰도 테스트는 조용히 통과합니다. 테스트가 어차피 4로 덮어쓰니 운영 값이 얼마든 상관없습니다. 테스트에서 편하자고 넣은 값이 운영을 안 보게 만드는 구조입니다.

테스트용 설정이 운영에 닿으면 어떻게 되는지는 다른 사고에서 이미 겪었습니다. 그래서 autouse 픽스처에 한 줄을 더 넣었습니다. 4로 바꾸기 전에 원본 상수가 12인지 확인합니다. 아니면 그 자리에서 실패합니다. 누가 운영 상수를 낮추면 823개가 전부 섭니다.

가드를 일부러 깨뜨려 봤습니다

여기서 멈추면 「가드가 있다」는 말만 남습니다. 가드가 실제로 막는지는 모릅니다. 옛 판에서도 통과하는 검사는 아무것도 증명하지 않습니다. 이 가드도 깨뜨려 보기 전에는 아무것도 안 막는 검사와 겉모습이 같습니다. 둘 다 초록입니다.

그래서 운영 상수를 10으로 낮추고 다시 돌렸습니다. 823개가 전부 섰습니다. 그걸 보고 나서야 「막는다」고 적었습니다. 걸린 시간은 테스트 한 바퀴입니다.

첫 추정은 맞았고, 둘째 추정은 틀렸습니다

「bcrypt 때문」은 맞았습니다. 그 자리에서 하나를 더 추정했습니다. 헬퍼가 불리는 횟수를 grep 으로 세어 「해시가 전체 시간의 66%」라고 했습니다. 실측은 96%였습니다. 헬퍼가 한 테스트 안에서 여러 번 불리는 것을 못 셌습니다.

첫 추정이 맞은 안도감이 둘째 추정을 안 재게 만듭니다. 이번에 추정이 맞았다는 것은 「다음엔 안 재도 된다」의 근거가 아닙니다. 같은 자리에서 낸 바로 다음 추정이 틀렸으니 규칙은 그대로입니다. 「X 때문」은 재고 나서 말합니다.

옆 레포는 손대지 않았고, 푸시도 안 했습니다

같은 도구의 문서 엔진 레포는 796개에 22초입니다. 이쪽에 같은 처방을 들고 갈 수도 있었습니다. 그런데 원인이 다릅니다. bcrypt 를 안 씁니다.

느린 것들은 그래프 DB·LLM·파일 제공자를 실제로 향해 도는 통합 테스트라 느린 것이 의도입니다. 자격증명이 없는 환경에서는 애초에 건너뜁니다. 같은 증상에 같은 처방을 들고 가지 않았습니다.

이번 커밋은 인증 모듈을 지나갑니다. 이 레포는 푸시가 곧 배포입니다. 「테스트 속도 개선」이라는 이름의 변경이 운영 인증 경로를 건드리므로 커밋만 하고 푸시는 미뤘습니다. 테스트 쪽 작업이 운영에 닿는 길은 설정값 하나만이 아닙니다.

테스트 속도를 손대기 전에 보는 것

상위 N개의 합이 전체의 몇 %인지 먼저 봅니다. 10% 근처면 병목이 아니라 분포입니다

빨라진 뒤 통과 개수만 비교하지 않습니다. 검증 경로가 전과 같이 도는지 확인합니다

테스트에서만 낮추는 값이 있으면 운영 값을 보는 가드를 같이 둡니다

그 가드는 운영 값을 일부러 바꿔 서는 것을 본 뒤에 「막는다」고 적습니다

느린 원인이 다른 레포에 같은 처방을 들고 가지 않습니다

가드가 아무것도 안 막았다면 무엇이 달라 보였을까

이 가드가 아무것도 안 막았다면 무엇이 달라 보였을지 되짚어 봤습니다. 아무것도 다르지 않았을 겁니다. 운영 상수를 10으로 내려도 823개가 초록이었을 겁니다.

823 passed 라는 화면은 가드가 있을 때와 없을 때가 똑같습니다. 가드가 있는 판과 없는 판을 가르는 것은 하나뿐입니다. 운영 값을 일부러 낮췄을 때 테스트가 서는가입니다.

그래서 검사 기준은 한 줄입니다. 그 검사가 서는 것을 한 번이라도 본 적이 있는가. 서는 것을 본 적이 없는 검사는 통과한 것인지 아무것도 검사하지 않은 것인지 구분해 주지 못합니다. 저는 이제 가드를 넣으면 그 자리에서 한 번 깨뜨려 봅니다.

연작 「실패할 수 없는 검사」

이 글은 다섯 편 중 5편입니다. 초록불·성공 표시·통과한 테스트가 실은 아무것도 검사하지 않던 사례를 이어서 다룹니다.