Cassandra 로그
Cassandra 로그 (Cassandra Logs)
Cassandra는 로깅 지원이 풍부하며, 운영자에게 데이터베이스에 대한 최대한의 통찰을 주면서도 동시에 로그의 노이즈를 최소화하려고 합니다. 문제 해결을 시작할 때 로그를 제대로 읽고 활용하는 것은 매우 중요해요.
본문
일반적인 로그 파일
Cassandra에는 세 가지 주요 로그가 있습니다. system.log, debug.log, gc.log로, 각각 일반 로깅 메시지, 디버깅 로깅 메시지, 그리고 Java 가비지 컬렉션(garbage collection) 로그를 담당해요.
이 로그들은 기본적으로 ${CASSANDRA_HOME}/logs에 위치하지만, 대부분의 Linux 배포판은 로그를 /var/log/cassandra로 옮겨 놓습니다. 운영자는 제공된 logback.xml 파일로 이 위치와 로그 레벨을 조정할 수 있습니다.
system.log
이 로그는 Cassandra의 기본 로그로, 어떤 조사든 이 로그에서 시작하는 것이 좋아요. 이 로그에 기록되는 활동의 예는 다음과 같습니다.
- 잡히지 않은 예외(uncaught exceptions). 오류 디버깅에 매우 유용할 수 있어요.
- 긴 가비지 컬렉터 일시 정지(pause)를 알리는
GCInspector메시지. 긴 일시 정지가 발생하면 Cassandra는 정지 시간이 얼마나 길었는지, 그리고 그 시점의 시스템 상태(스레드 상태)가 어땠는지 출력합니다. 이는 용량 문제(힙 부족 또는 여유 CPU 부족)를 좁히는 데 도움이 됩니다. - 클러스터에 노드가 합류하고 떠나는 정보, 그리고 토큰 메타데이터(데이터 소유권) 변경 정보. 네트워크 파티션, 데이터 이동 등을 디버깅하는 데 유용해요.
- 키스페이스/테이블 생성, 수정, 삭제.
- Cassandra 실행을 위한 운영체제 최적 설정을 보장하는
StartupChecks. - 일부 백그라운드 운영 작업(예: Index Redistribution)에 대한 정보.
다른 애플리케이션처럼 ERROR나 WARN 줄을 찾는 것이 훌륭한 첫 단계가 될 수 있어요.
$ # Search for warnings or errors in the latest system.log
$ grep 'WARN\|ERROR' system.log | tail
...
$ # Search for warnings or errors in all rotated system.log
$ zgrep 'WARN\|ERROR' system.log.* | less
...
debug.log
이 로그는 문제 해결 시 유용할 수 있는 추가 디버깅 정보를 담고 있지만, 일반적인 system.log보다 훨씬 시끄러울 수 있어요. 이 로그에 기록되는 활동의 예는 다음과 같습니다.
- 컴팩션에 대한 정보 — 언제 시작하는지, 어떤 sstable을 포함하는지, 언제 끝나는지.
- 디스크로의 멤테이블(memtable) 플러시 정보 — 언제 발생했는지, 플러시 크기, 플러시가 어떤 commitlog 세그먼트에 영향을 주었는지.
이 로그는 매우 시끄러울 수 있으므로, grep과 그 외 로그 분석 도구를 사용해 깊이 파고드는 것이 강력히 권장됩니다. 예를 들어:
# Search for messages involving a CompactionTask with 5 lines of context
$ grep CompactionTask debug.log -C 5
# Look at the distribution of flush tasks per keyspace
$ grep "Enqueuing flush" debug.log | cut -f 10 -d ' ' | sort | uniq -c
6 compaction_history:
1 test_keyspace:
2 local:
17 size_estimates:
17 sstable_activity:
gc.log
gc 로그는 표준 Java GC 로그입니다. 기본 jvm.options 설정으로 이 로그에서 애플리케이션 일시 정지 시간, 일시 정지가 발생한 이유 등 많은 유용한 정보를 얻을 수 있어요. 이는 처리량이나 지연 문제를 잘못 튜닝된 JVM 때문이라고 좁히는 데 도움이 됩니다. 예를 들어 마지막 몇 번의 일시 정지를 확인할 수 있습니다.
$ grep stopped gc.log.0.current | tail
2018-08-29T00:19:39.522+0000: 3022663.591: Total time for which application threads were stopped: 0.0332813 seconds, Stopping threads took: 0.0008189 seconds
2018-08-29T00:19:44.369+0000: 3022668.438: Total time for which application threads were stopped: 0.0312507 seconds, Stopping threads took: 0.0007025 seconds
2018-08-29T00:19:49.796+0000: 3022673.865: Total time for which application threads were stopped: 0.0307071 seconds, Stopping threads took: 0.0006662 seconds
2018-08-29T00:19:55.452+0000: 3022679.521: Total time for which application threads were stopped: 0.0309578 seconds, Stopping threads took: 0.0006832 seconds
2018-08-29T00:20:00.127+0000: 3022684.197: Total time for which application threads were stopped: 0.0310082 seconds, Stopping threads took: 0.0007090 seconds
2018-08-29T00:20:06.583+0000: 3022690.653: Total time for which application threads were stopped: 0.0317346 seconds, Stopping threads took: 0.0007106 seconds
2018-08-29T00:20:10.079+0000: 3022694.148: Total time for which application threads were stopped: 0.0299036 seconds, Stopping threads took: 0.0006889 seconds
2018-08-29T00:20:15.739+0000: 3022699.809: Total time for which application threads were stopped: 0.0078283 seconds, Stopping threads took: 0.0006012 seconds
2018-08-29T00:20:15.770+0000: 3022699.839: Total time for which application threads were stopped: 0.0301285 seconds, Stopping threads took: 0.0003789 seconds
2018-08-29T00:20:15.798+0000: 3022699.867: Total time for which application threads were stopped: 0.0279407 seconds, Stopping threads took: 0.0003627 seconds
이 출력은 애플리케이션이 얼마나 오래 일시 정지되었는지(즉, 예를 들어 33ms 동안 JVM 일시 정지 중 사용자 쿼리가 전혀 처리되지 않았는지)와 세이프포인트(safepoint) 진입에 걸린 시간 등 유용한 정보를 많이 보여줍니다. 이 원시 데이터로 예를 들어 가장 긴 일시 정지를 얻을 수 있습니다.
$ grep stopped gc.log.0.current | cut -f 11 -d ' ' | sort -n | tail | xargs -IX grep X gc.log.0.current | sort -k 1
2018-08-28T17:13:40.520-0700: 1.193: Total time for which application threads were stopped: 0.0157914 seconds, Stopping threads took: 0.0000355 seconds
2018-08-28T17:13:41.206-0700: 1.879: Total time for which application threads were stopped: 0.0249811 seconds, Stopping threads took: 0.0000318 seconds
2018-08-28T17:13:41.638-0700: 2.311: Total time for which application threads were stopped: 0.0561130 seconds, Stopping threads took: 0.0000328 seconds
2018-08-28T17:13:41.677-0700: 2.350: Total time for which application threads were stopped: 0.0362129 seconds, Stopping threads took: 0.0000597 seconds
2018-08-28T17:13:41.781-0700: 2.454: Total time for which application threads were stopped: 0.0442846 seconds, Stopping threads took: 0.0000238 seconds
2018-08-28T17:13:41.976-0700: 2.649: Total time for which application threads were stopped: 0.0377115 seconds, Stopping threads took: 0.0000250 seconds
2018-08-28T17:13:42.172-0700: 2.845: Total time for which application threads were stopped: 0.0475415 seconds, Stopping threads took: 0.0001018 seconds
2018-08-28T17:13:42.825-0700: 3.498: Total time for which application threads were stopped: 0.0379155 seconds, Stopping threads took: 0.0000571 seconds
2018-08-28T17:13:43.574-0700: 4.247: Total time for which application threads were stopped: 0.0323812 seconds, Stopping threads took: 0.0000574 seconds
2018-08-28T17:13:44.602-0700: 5.275: Total time for which application threads were stopped: 0.0238975 seconds, Stopping threads took: 0.0000788 seconds
이 경우 쿼리를 기다리던 클라이언트는 17:13:41에 56ms의 지연을 경험했을 것입니다.
참고로 GC 일시 정지는 가비지 컬렉션_만_은 아닙니다. 일반적으로 빠른 세이프포인트와 함께 높은 일시 정지가 나타나면 JVM 힙 부족이나 잘못 튜닝된 JVM GC 알고리즘을 의미해요. 느린 세이프포인트와 함께 높은 일시 정지가 나타나면 보통 JVM이 세이프포인트 진입에 어려움을 겪고 있다는 뜻이며, 이는 대개 느린 디스크 드라이브를 의미합니다(Cassandra는 메모리 매핑 읽기를 많이 사용하는데, JVM은 그것에 디스크 지연이 있을 수 있음을 알지 못하므로, JVM 세이프포인트 로직은 블로킹 메모리 매핑 읽기를 특히 잘 처리하지 못합니다).
이 로그들을 사용하면 histogram.py 같은 도구로 일시 정지 분포도 얻을 수 있어요.
$ grep stopped gc.log.0.current | cut -f 11 -d ' ' | sort -n | histogram.py
# NumSamples = 410293; Min = 0.00; Max = 11.49
# Mean = 0.035346; Variance = 0.002216; SD = 0.047078; Median 0.036498
# each ∎ represents a count of 5470
0.0001 - 1.1496 [410255]: ∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
1.1496 - 2.2991 [ 15]:
2.2991 - 3.4486 [ 5]:
3.4486 - 4.5981 [ 1]:
4.5981 - 5.7475 [ 5]:
5.7475 - 6.8970 [ 9]:
6.8970 - 8.0465 [ 1]:
8.0465 - 9.1960 [ 0]:
9.1960 - 10.3455 [ 0]:
10.3455 - 11.4949 [ 2]:
이 경우 평균 성능은 아주 좋지만, 어떤 것이 수 초에 달하는 JVM 일시 정지를 일으키고 있음을 알 수 있어요. 이 예시에서는 대부분 느린 디스크로 인한 세이프포인트 일시 정지였습니다.
$ grep stopped gc.log.0.current | cut -f 11 -d ' ' | sort -n | tail | xargs -IX grep X gc.log.0.current| sort -k 1
2018-07-27T04:52:27.413+0000: 187831.482: Total time for which application threads were stopped: 6.5037022 seconds, Stopping threads took: 0.0005212 seconds
2018-07-30T23:38:18.354+0000: 514582.423: Total time for which application threads were stopped: 6.3262938 seconds, Stopping threads took: 0.0004882 seconds
2018-08-01T02:37:48.380+0000: 611752.450: Total time for which application threads were stopped: 10.3879659 seconds, Stopping threads took: 0.0004475 seconds
2018-08-06T22:04:14.990+0000: 1113739.059: Total time for which application threads were stopped: 6.0917409 seconds, Stopping threads took: 0.0005553 seconds
2018-08-14T00:04:06.091+0000: 1725730.160: Total time for which application threads were stopped: 6.0141054 seconds, Stopping threads took: 0.0004976 seconds
2018-08-17T06:23:06.755+0000: 2007670.824: Total time for which application threads were stopped: 6.0133694 seconds, Stopping threads took: 0.0006011 seconds
2018-08-23T06:35:46.068+0000: 2526830.137: Total time for which application threads were stopped: 6.4767751 seconds, Stopping threads took: 6.4426849 seconds
2018-08-23T06:36:29.018+0000: 2526873.087: Total time for which application threads were stopped: 11.4949489 seconds, Stopping threads took: 11.4638297 seconds
2018-08-23T06:37:12.671+0000: 2526916.725: Total time for which application threads were stopped: 6.3867003 seconds, Stopping threads took: 6.3507166 seconds
2018-08-23T06:37:47.156+0000: 2526951.225: Total time for which application threads were stopped: 7.9528200 seconds, Stopping threads took: 7.9197756 seconds
때로는 Java GC 로그를 읽고 이해하기 어렵지만, 원시 GC 파일을 가져와 GCViewer 같은 도구로 시각화할 수 있어요. GCViewer는 Cassandra GC 로그를 입력으로 받아 가비지 컬렉션 성능에 대한 상세한 시각 정보를 보여줍니다. 일시 정지 분석뿐 아니라 처리량 정보도 포함합니다. 안정적인 Cassandra JVM을 위해서는 일시 정지가 200ms 미만이고, GC 처리량이 99%보다 커야 합니다.
Java GC 일시 정지는 (드라이브 지연과 함께) Cassandra에서 꼬리 지연(tail latency)의 주요 원인 중 하나이므로, 꼬리 지연 문제를 디버깅할 때 이 정보가 결정적인 역할을 할 수 있어요.
더 많은 정보 얻기
기본 로깅 레벨로 부족하다면, nodetool의 nodetool setlogginglevel 명령으로 다양한 패키지와 클래스의 로깅 레벨을 높이거나 낮출 수 있어요. 먼저 현재 레벨을 확인해 보세요.
$ nodetool getlogginglevels
Logger Name Log Level
ROOT INFO
org.apache.cassandra DEBUG
아마 Gossiper가 문제를 일으키고 있어서, 더 많은 통찰을 위해 TRACE 레벨로 켜고 싶을 수 있어요.
$ nodetool setlogginglevel org.apache.cassandra.gms.Gossiper TRACE
$ nodetool getlogginglevels
Logger Name Log Level
ROOT INFO
org.apache.cassandra DEBUG
org.apache.cassandra.gms.Gossiper TRACE
$ grep TRACE debug.log | tail -2
TRACE [GossipStage:1] 2018-07-04 17:07:47,879 Gossiper.java:1234 - Updating
heartbeat state version to 2344 from 2343 for 127.0.0.2:7000 ...
TRACE [GossipStage:1] 2018-07-04 17:07:47,879 Gossiper.java:923 - local
heartbeat version 2341 greater than 2340 for 127.0.0.1:7000
이런 방식으로 변경한 내용은 다음 Cassandra 프로세스 재시작 시 되돌아갑니다. 변경을 영구적으로 만들려면 logback.xml에 적절한 규칙을 추가하세요.
diff --git a/conf/logback.xml b/conf/logback.xml
index b2c5b10..71b0a49 100644
--- a/conf/logback.xml
+++ b/conf/logback.xml
@@ -98,4 +98,5 @@ appender reference in the root level section below.
</root>
<logger name="org.apache.cassandra" level="DEBUG"/>
+ <logger name="org.apache.cassandra.gms.Gossiper" level="TRACE"/>
</configuration>
이 도구가 제공하는 것보다 더 많은 정보가 필요하다면, packet-capture 같은 다른 라이브 캡처 옵션도 있습니다.