메모리는 줄었는데, Go GC는 왜 더 자주 돌았을까?

메모리는 줄었는데 GC 그래프는 올라갔다

운영 중인 Go 서버에서 메모리가 줄었는데 GC는 오히려 늘었다. 메모리를 덜 쓰면 GC도 할 일이 줄어들 것 같은데, 그래프는 반대로 움직였다.

위는 Go 메모리 사용량, 아래는 GC 빈도의 추이다. 메모리가 내려가는 구간에서 GC 빈도는 올라간다. 그림은 며칠간의 흐름이고, 아래 표는 그중 전후 30분씩을 비교한 값이다. 그림의 Heap Total과 표의 생존 heap은 다른 지표다.

변화 전후 각각 30분의 Datadog 지표를 비교했다. (MiB는 메모리 크기 단위로, 1 MiB는 1,048,576바이트다.)

생존 heap은 약 35% 줄고 GC 빈도는 약 63% 늘었다. 반면 새 객체를 저장하기 위해 heap에 할당한 메모리는 초당 약 238 MiB에서 240 MiB로 거의 같았다. 표의 ‘평균 heap 할당률’이 이 값이다.

예를 들어 요청을 처리하며 JSON을 읽어 객체를 만들면, 그 객체를 저장할 공간이 필요하다. 할당률은 이렇게 새 객체에 할당한 공간을 초당 합산한 값이다. 금방 사용을 마친 객체도 포함하므로, 초당 240 MiB를 할당한다고 사용 중인 메모리가 매초 240 MiB씩 쌓이는 것은 아니다.

새 객체에 할당하는 메모리와 GC 후에도 사용 중인 메모리

heap은 프로그램에서 동적으로 할당한 객체를 두는 메모리 공간이다. 모든 Go 변수가 heap에 할당되는 것은 아니지만 여기서는 heap에 할당한 데이터와 캐시에 집중하자.

참조는 프로그램이 객체를 가리키는 연결을 의미하는데, GC는 이 연결을 따라가 도달할 수 있는 객체를 찾고 더 이상 도달할 수 없는 객체의 공간을 회수한다. 프로그램이 계속 붙잡고 있는 객체는 임의로 버리지는 않는다.

할당률은 새 객체에 초당 할당한 메모리 크기이고, live heap은 직전 GC에서 아직 참조 중이라고 판단한 객체들의 메모리 크기다. 임시 객체도 GC 시점에 참조 중이라면 live heap에 포함될 수 있다.

참고로 live heap이란, 가비지 컬렉션이 끝난 후에도 살아남은 실제 객체들의 메모리 크기로 만약 이 수치가 계속 증가하면 memory leak을 의심해 봐야 한다.

객체를 더 이상 사용하지 않아도 GC가 처리하기 전까지는 메모리 공간을 차지할 수 있다. GC 이후에는 해당 공간에 다른 객체를 저장할 수 있지만, Go Runtime이 이 빈 메모리 공간을 다음에 쓰려고 보관하기도 한다. 그렇기 때문에 GC가 끝났다고 운영체제에서 보는 메모리 사용량이 바로 줄어들진 않는다.이번 조사에서는 전체 Go 메모리 감소와 별개로, 생존 heap 자체가 줄어든 것을 확인했다.

대량 캐시 삭제가 있었다.

메모리 감소가 발생했던 날의 배포 이력을 살펴보니 광고 설정을 벌크로 수정하는 PR이 있었다. 팀원에게 확인해본 결과 실제로 대량의 광고 오프 작업이 수행됐고, 작업의 결과로 메모리 감소까지 이어진 걸 확인했다.

여기서 14만 건은 비활성화한 광고 항목 수로 로컬 캐시에서 삭제된 항목 수와 정확히 일치하는 것은 아니다.

그렇다면 광고 항목을 비활성화한 것이 서버 메모리 감소로 어떻게 이어졌을까? Pyroscope의 메모리 프로파일을 비교해, 어느 코드에서 할당한 메모리가 줄었는지 확인했다.

살아 있는 객체의 메모리를 보는 inuse_space에서 감소가 집중된 곳은 광고 JSON을 로컬 캐시에 넣는 지점이었다. 이곳의 표본 합은 약 72% 줄었고 나머지는 거의 같았다.

비활성화된 광고를 동기화할 때 Redis의 후보 목록과 JSON을 삭제했다. 이 변경이 로컬 캐시에 반영되는 흐름은 다음과 같다.

te
광고 항목 비활성화
  → 동기화 과정에서 Redis 후보·JSON 삭제
  → API 프로세스의 로컬 캐시 만료·정리
  → 더 이상 사용하지 않는 JSON의 참조 해제
  → GC가 공간 회수

Redis에서 지웠다고 모든 API 프로세스의 로컬 캐시가 즉시 사라지진 않고, GC를 거치며 더 이상 조회되지 않는 데이터의 참조가 끊어진다. 물론 캐시가 여전히 참조하는 객체는 GC가 자주 돈다고 제거되지 않는다.

GC 빈도가 늘어난 이유

Go는 GOGC 설정으로 live heap에 비례하여 메모리의 추가 할당 여유를 정한다. 당시 서버의 GOGC=100이었고, GOMEMLIMIT은 별도 설정값이 없었다. GOGC=100은 직전 GC가 끝난 시점의 라이브 힙 크기가 100MB일때, 그 크기의 100%에 해당하는 100MB가 더 늘어나 총 200MB가 되는 시점에 가비지 컬렉션이 트리거된다는 의미다. 만약 GOGC=50이라면 GC가 자주 일어나 메모리 사용량은 줄어들고 CPU 부담은 늘어난다고 이해할 수 있다.

쉽게 설명하면 live heap의 양 만큼 메모리에 더 할당할 여유를 둔다는 의미다. 아래 예시에선 두 경우 모두 할당률은 100 MiB/s로 같다고 가정한다.

Go 공식 GC 가이드의 목표식은 생존 heap + (생존 heap + GC roots) × GOGC / 100이다. 실제로는 목표에 맞춰 수집을 마치도록 GC를 미리 시작하므로 heap 목표를 정확한 GC 시작선으로 읽으면 안 된다. 표의 주기도 원리를 이해하기 위한 근사치다. GC 횟수가 늘어난만큼 CPU 비용도 늘었다고 단정할 수는 없는데, 한 번의 CG에서 처리하는 양과 객체 참조 구조에 따라 비용도 달라지기 때문이다.

GC 관련 CPU 비율도 높아졌다. 누적 영역의 전체 높이는 패널 구성요소의 합이며, GC 정지 시간을 나타내는 그래프는 아니다.

앞서 비교한 두 30분 구간에서 GC CPU 값은 6.87%에서 9.21%로 증가했다. 다만 여기에는 유휴 CPU를 사용하는 idle mark와 메모리를 운영체제에 돌려주는 scavenging도 포함되고, 전체 서버의 CPU와는 별개로 해석한다.

p95 latency 개선

신기하게 p95 레이턴시도 줄었다.

앞쪽에서는 400~500ms 부근까지 반복해서 올라가다 300ms 안팎으로 낮아진다.

평균은 거의 같고 p95가 줄었으므로 모든 api 요청이 일률적으로 빨라졌다고 보기는 어렵다. 광고 타게팅을 체크하는 경로의 누적 CPU 표본 시간은 약 56% 줄었는데, 앞서 진행된 대량 광고 목록 비활성화의 (postive) 사이드 이펙트 일수도 있겠다는 추론을 했다.

text
광고 14만 건 비활성화
  ├─ 더 이상 조회하지 않는 광고 데이터가 캐시에서 사라짐
  │    → 로컬 메모리 감소
  │
  └─ 요청에서 검사하거나 선택하는 광고 후보가 달라짐
       → 일부 요청의 처리량·처리 경로가 달라질 가능성
       → p95 개선에 기여했을 가능성

광고 대량 비활성화는 캐시에 보관할 데이터뿐 아니라 요청에서 검사할 후보도 바꾼다. 실제로 캐시 메모리와 타게팅 체크 함수의 CPU 표본 시간이 함께 감소했다. 비활성화가 p95 개선에도 기여했을 가능성은 있지만, 캐시 메모리 감소 자체가 응답시간을 줄였다고 단정할 수는 없다. 예를 들어 타게팅 체크에 시간이 많이 걸리는 광고 후보가 메모리에서 제거됐다면 해당 광고를 체크하던 요청은 빨라질 수 있는 셈이다. (물론 뇌피셜이지만 지금으로선 이게 합리적 의심이긴 함)

또한 Go GC는 대부분 애플리케이션과 동시에 실행된다. 짧은 정지나 CPU 경쟁은 있지만 GC 빈도가 request의 정지 시간과 일대일로 대응하지는 않는다. GC가 잦더라도 다른 처리나 대기시간이 줄면 응답시간은 개선될 수 있다.

광고 비활성화가 검사 비용 감소의 유력한 원인이긴 하지만, p95 개선에 얼마나 기여했는지는 미확정으로 남겼다.

마무리

서버 지표를 모니터링하다가 급격하게 줄어든 메모리 usage 그래프를 보고 이번 조사(?)를 시작하게 됐다. 대량 광고 오프라는 명확한 액션이 있었기에 추론에 오래걸리지는 않았다. 메모리 사용과 GC 실행 빈도, GC CPU 등의 지표에 상관관계에 대해 알아 볼 수 있는 시간이었다.