확인된 것
컨테이너에서 JVM이 G1이 아니라 Serial GC를 고른다. 아무도 그렇게 지정한 적이 없다.
[info][gc ] Using Serial
[info][gc,init] CPUs: 4 total, 1 available
[info][gc,init] Memory: 512M
왜 그런가
JVM은 실행 환경이 "server-class machine"인지 보고 컬렉터를 고른다. 조건은 CPU 2개 이상 그리고 메모리 1792MB 이상이고, 둘 다 만족해야 G1이 된다. 컨테이너의 메모리 제한이 512M이므로 이 조건에서 탈락한다.
이미지로 2×2를 직접 돌려 확인했다.
|
메모리 512M |
메모리 2G |
| CPU 무제한 |
Serial |
G1 |
| CPU 1.0 |
Serial |
Serial |
docker run --rm -m 512M --entrypoint sh <image> -c 'java -Xmx400M -Xlog:gc:stdout -version'
읽는 법:
- 메모리 512M만으로 이미 Serial이었다. CPU 상한을 넣기 전부터 그랬다
- CPU 상한(1.0)이 두 번째 독립 원인을 추가했다. 이제는 메모리를 2G로 올려도 Serial이다 — 즉 손잡이 하나가 가려졌다
지금 실제로 문제인가 — 색인 부하에서 재봤다
-Xlog:gc*,gc+heap=debug를 켜고 색인을 13분 돌린 결과다.
Young GC 132회 pause min 2.3ms / median 12.9ms / max 132.6ms
Full GC 8회 전부 (Metadata GC Threshold)
힙 점유 124M -> 55M (247M) 최대 400M 중 247M만 커밋
힙 자체는 넉넉하다. Full GC 8회가 전부 Metadata GC Threshold인데, 이것은 힙이 모자라서가 아니라 기동 중 클래스 로딩으로 메타스페이스가 늘 때 나는 것이다. 전부 기동 후 90초 안에 몰려 있고 그 뒤로는 없다. 즉 Allocation Failure로 인한 Full GC는 한 번도 없었다.
따라서 400M이 좁다는 근거는 지금 없다. 다만 그 400M이라는 값 자체에도 근거는 없다 — 컨테이너 제한과 같은 값(512M)이던 것을 여유를 두려고 내린 것이지 측정으로 고른 값이 아니다.
눈에 띄는 것은 Young pause 최댓값 132.6ms다. 중앙값 12.9ms에 비해 10배다. API 응답 경로에서 이 정도 정지는 사용자에게 보인다.
그래서 무엇을 할 것인가
당장 바꾸자는 제안이 아니다. 지금 확인된 것은 "의도하지 않은 컬렉터가 선택되어 있다"와 "그것이 문제라는 근거는 아직 없다" 둘이다.
정할 것은 이쪽이다.
| 선택지 |
내용 |
대가 |
| 그대로 둔다 |
힙 400M에서 Serial은 비상식적 선택이 아니다. 힙이 작으면 Serial이 오히려 단순하고 오버헤드가 적다 |
132ms pause를 받아들인다 |
| 명시한다 |
-XX:+UseSerialGC를 JAVA_OPTS에 적어 선택을 기록한다. 지금은 환경이 우연히 고른 값이라, 메모리 제한을 올리는 순간 조용히 G1로 바뀐다 |
없음. 권한다 |
| G1로 바꾼다 |
-XX:+UseG1GC를 강제하고 pause 분포를 다시 잰다 |
힙 400M에서 G1은 region 관리 오버헤드가 상대적으로 크다. 재보기 전에는 모른다 |
어느 쪽이든 "환경이 알아서 고르게 두는" 지금 상태가 가장 나쁘다. 컨테이너 메모리 제한을 바꾸는 것과 GC 컬렉터가 바뀌는 것이 연결되어 있다는 사실이 어디에도 적혀 있지 않다.
참고 — 이 측정이 가능해진 경위
JAVA_OPTS는 이 저장소에서 한 번도 읽힌 적이 없었다. Dockerfile의 ENTRYPOINT가 exec 형식이라 셸을 거치지 않아 변수가 확장되지 않았다. 그래서 GC 로그를 켤 방법 자체가 없었다. 그 수정 이후에야 이 이슈를 쓸 수 있었다.
관련
- 백로그 P2-10-1 (힙 상한 == 컨테이너 제한), P2-10-3 (CPU 상한)
compose.gc.yaml — 이 측정에 쓴 오버레이
확인된 것
컨테이너에서 JVM이 G1이 아니라 Serial GC를 고른다. 아무도 그렇게 지정한 적이 없다.
왜 그런가
JVM은 실행 환경이 "server-class machine"인지 보고 컬렉터를 고른다. 조건은 CPU 2개 이상 그리고 메모리 1792MB 이상이고, 둘 다 만족해야 G1이 된다. 컨테이너의 메모리 제한이 512M이므로 이 조건에서 탈락한다.
이미지로 2×2를 직접 돌려 확인했다.
읽는 법:
지금 실제로 문제인가 — 색인 부하에서 재봤다
-Xlog:gc*,gc+heap=debug를 켜고 색인을 13분 돌린 결과다.힙 자체는 넉넉하다. Full GC 8회가 전부
Metadata GC Threshold인데, 이것은 힙이 모자라서가 아니라 기동 중 클래스 로딩으로 메타스페이스가 늘 때 나는 것이다. 전부 기동 후 90초 안에 몰려 있고 그 뒤로는 없다. 즉Allocation Failure로 인한 Full GC는 한 번도 없었다.따라서 400M이 좁다는 근거는 지금 없다. 다만 그 400M이라는 값 자체에도 근거는 없다 — 컨테이너 제한과 같은 값(512M)이던 것을 여유를 두려고 내린 것이지 측정으로 고른 값이 아니다.
눈에 띄는 것은 Young pause 최댓값 132.6ms다. 중앙값 12.9ms에 비해 10배다. API 응답 경로에서 이 정도 정지는 사용자에게 보인다.
그래서 무엇을 할 것인가
당장 바꾸자는 제안이 아니다. 지금 확인된 것은 "의도하지 않은 컬렉터가 선택되어 있다"와 "그것이 문제라는 근거는 아직 없다" 둘이다.
정할 것은 이쪽이다.
-XX:+UseSerialGC를 JAVA_OPTS에 적어 선택을 기록한다. 지금은 환경이 우연히 고른 값이라, 메모리 제한을 올리는 순간 조용히 G1로 바뀐다-XX:+UseG1GC를 강제하고 pause 분포를 다시 잰다어느 쪽이든 "환경이 알아서 고르게 두는" 지금 상태가 가장 나쁘다. 컨테이너 메모리 제한을 바꾸는 것과 GC 컬렉터가 바뀌는 것이 연결되어 있다는 사실이 어디에도 적혀 있지 않다.
참고 — 이 측정이 가능해진 경위
JAVA_OPTS는 이 저장소에서 한 번도 읽힌 적이 없었다.Dockerfile의 ENTRYPOINT가 exec 형식이라 셸을 거치지 않아 변수가 확장되지 않았다. 그래서 GC 로그를 켤 방법 자체가 없었다. 그 수정 이후에야 이 이슈를 쓸 수 있었다.관련
compose.gc.yaml— 이 측정에 쓴 오버레이