Cassandraログ

Cassandraは、ロギングを豊富にサポートしており、オペレーターにデータベースを最大限に理解させると同時に、ログへのノイズを制限しようとします。

共通ログファイル

Cassandraには、一般的なログメッセージ、デバッグログメッセージ、Javaガbageコレクションログをそれぞれ保持する、system.log、debug.log、gc.logの3つの主要なログがあります。

これらのログはデフォルトでは${CASSANDRA_HOME}/logsにありますが、ほとんどのLinuxディストリビューションではログが/var/log/cassandraに再配置されます。オペレーターは、提供されているlogback.xmlファイルを使用して、この場所とログに記録されるレベルを調整できます。

`system.log`

このログはデフォルトのCassandraログであり、調査を開始するのに適した場所です。このログに記録されるアクティビティの例を次に示します。

キャッチされない例外。これらは、エラーのデバッグに非常に役立ちます。
ガbageコレクターの長い一時停止を示すGCInspectorメッセージ。長い一時停止が発生すると、Cassandraは一時停止の長さとその一時停止時のシステムの状態（スレッド状態）を出力します。これは、容量の問題（ヒープが足りないか、CPUの空き容量が足りないか）を絞り込むのに役立ちます。
ノードのクラスタへの参加と脱退、およびトークンメタデータ（データ所有権）の変更に関する情報。これは、ネットワークパーティション、データの移動などのデバッグに役立ちます。
キースペース/テーブルの作成、変更、削除。
Cassandraを実行するためのオペレーティングシステムの最適な構成を保証するStartupChecks
一部のバックグラウンド操作タスク（例：インデックス再配布）に関する情報。

他のアプリケーションと同様に、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のディスクへのフラッシュに関する情報。発生時刻、フラッシュのサイズ、フラッシュが影響を与えたコミットログセグメントなど。

このログは非常にノイズが多い可能性があるため、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

これにより、アプリケーションが一時停止された時間（たとえば、33ミリ秒の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-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に56ミリ秒のレイテンシが発生していました。

GC一時停止は、ガbageコレクション_のみではないことに注意してください。ただし、一般的に、高速なセーフポイントを伴う高い一時停止は、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.741: 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などのツールを使用して視覚化できます。このツールは、Cassandra GCログを入力として受け取り、ガbageコレクションのパフォーマンスに関する詳細な視覚情報を表示します。これには、一時停止分析とスループット情報が含まれます。安定したCassandra JVMの場合、おそらく200ミリ秒未満の一時停止と99％を超えるGCスループットを目指したいと思うでしょう。

Java GC一時停止は、Cassandraのテールレイテンシの主な原因の1つ（ドライブレイテンシと 함께）であるため、この情報はテールレイテンシの問題をデバッグする際に非常に重要になる場合があります。

詳細情報の取得

デフォルトのロギングレベルが足りない場合は、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などの他のライブキャプチャオプションが利用可能です。

Cassandraドキュメント

バージョン