TRACING

トレーシングの要求を有効または無効にします。

構文 

TRACING(ON | OFF)

構文の凡例 

説明 

読み取り/書き込み要求のトレーシングをオンまたはオフにするには、TRACINGコマンドを使用します。トレーシングをオンにすると、データベース操作があると、Cassandraの内部動作の把握およびパフォーマンス問題のトラブルシュートに役立つ出力が生成されます。たとえば、トレーシング・チュートリアルを使用して、異なる整合性のレベルに応じた操作を確認できます。一部のトレーシング・メッセージはユーザーが理解できないデータベースの内部の仕組みについて記述していますが、トラブルシューティングに役立つ情報をCassandraチームに提供します。

Cassandraはトレーシング情報をsystem_tracesキースペースにあるセッションやイベント・テーブルに24時間保存して、確率的トレーシングを行う場合にクエリーの対象にできます。確率的トレーシングの詳細については、Cassandra 3.0ドキュメントまたはCassandra 2.2ドキュメントを参照してください。

$ CREATE TABLE sessions ( session_id uuid PRIMARY KEY, coordinator inet, duration int, parameters map<text, text>, request text, started_at timestamp ); CREATE TABLE events ( session_id uuid, event_id timeuuid, activity text, source inet, source_elapsed int, thread text, PRIMARY KEY (session_id, event_id) );

source_elapsedカラムには、ソース・ノードでイベントが発生するまでの経過時間がミリ秒単位で格納されます。

トレーシング情報を保持するには、セッションおよびイベント・テーブルのデータを他の場所にコピーします。または、トレーシング・セッションIDを指定して、SHOW SESSIONを使用してセッション情報を取得します。トレーシング・セッション情報は1日で有効期限が切れます。

書き込み要求のトレーシング 

この例では、ccmによってMac OSX上に作成された3ノード・クラスター上のトレーシング・アクティビティを示します。レプリケーション係数3を持つキースペースと、「複合プライマリ・キーの使用」のemployeeテーブルと同様のテーブルを使用して、トレーシングによって、coordinatorが以下のアクションを実行することを示します。

• 行のレプリケーション先となるノードを特定する。
• 行をcommitlogおよびmemtableに書き込む。
• 要求の完了を確認する。

TRACING ON INSERT INTO emp (empID, deptID, first_name, last_name) VALUES (104, 15, 'jane', 'smith');

Cassandraによって、要求を満たすための各ステップ、影響を受けるノードの名前、各ステップの時間、要求にかかる全時間の詳細が示されます。

Tracing session:740b9c10-3506-11e2-0000-fe8ebeead9ff activity | timestamp | source | source_elapsed -------------------------------------+--------------+-----------+---------------- execute_cql3_query | 16:41:00,754 | 127.0.0.1 | 0 Parsing statement | 16:41:00,754 | 127.0.0.1 | 48 Preparing statement | 16:41:00,755 | 127.0.0.1 | 658 Determining replicas for mutation | 16:41:00,755 | 127.0.0.1 | 979 Message received from /127.0.0.1 | 16:41:00,756 | 127.0.0.3 | 37 Acquiring switchLock read lock | 16:41:00,756 | 127.0.0.1 | 1848 Sending message to /127.0.0.3 | 16:41:00,756 | 127.0.0.1 | 1853 Appending to commitlog | 16:41:00,756 | 127.0.0.1 | 1891 Sending message to /127.0.0.2 | 16:41:00,756 | 127.0.0.1 | 1911 Adding to emp memtable | 16:41:00,756 | 127.0.0.1 | 1997 Acquiring switchLock read lock | 16:41:00,757 | 127.0.0.3 | 395 Message received from /127.0.0.1 | 16:41:00,757 | 127.0.0.2 | 42 Appending to commitlog | 16:41:00,757 | 127.0.0.3 | 432 Acquiring switchLock read lock | 16:41:00,757 | 127.0.0.2 | 168 Adding to emp memtable | 16:41:00,757 | 127.0.0.3 | 522 Appending to commitlog | 16:41:00,757 | 127.0.0.2 | 211 Adding to emp memtable | 16:41:00,757 | 127.0.0.2 | 359 Enqueuing response to /127.0.0.1 | 16:41:00,758 | 127.0.0.3 | 1282 Enqueuing response to /127.0.0.1 | 16:41:00,758 | 127.0.0.2 | 1024 Sending message to /127.0.0.1 | 16:41:00,758 | 127.0.0.3 | 1469 Sending message to /127.0.0.1 | 16:41:00,758 | 127.0.0.2 | 1179 Message received from /127.0.0.2 | 16:41:00,765 | 127.0.0.1 | 10966 Message received from /127.0.0.3 | 16:41:00,765 | 127.0.0.1 | 10966 Processing response from /127.0.0.2 | 16:41:00,765 | 127.0.0.1 | 11063 Processing response from /127.0.0.3 | 16:41:00,765 | 127.0.0.1 | 11066 Request complete | 16:41:00,765 | 127.0.0.1 | 11139

連続スキャンのトレーシング 

Cassandraのログ構造のため、1つの行が複数のSSTableに分散されることがあります。10行のデータをあらかじめ読み込んでおいたemployeeテーブルを対象とした読み取り要求のトレースに示すように、1つの行を読み取るのに複数のSSTableからそれぞれ一部を読み取ることになります。

SELECT * FROM emp;

empid | deptid | first_name | last_name -------+--------+------------+----------- 110 | 16 | naoko | murai 105 | 15 | john | smith 111 | 15 | jane | thath 113 | 15 | lisa | amato 112 | 20 | mike | burns 107 | 15 | sukhit | ran 108 | 16 | tom | brown 109 | 18 | ann | green 104 | 15 | jane | smith 106 | 15 | bob | jones

この読み込み要求のトレーシング出力は、以下のようになります（ページに収めるため、数行を省略しました）。

Tracing session:bf5163e0-350f-11e2-0000-fe8ebeead9ff activity | timestamp | source | source_elapsed -------------------------------------------------+--------------+-----------+---------------- execute_cql3_query | 17:47:32,511 | 127.0.0.1 | 0 Parsing statement | 17:47:32,511 | 127.0.0.1 | 47 Preparing statement | 17:47:32,511 | 127.0.0.1 | 249 Determining replicas to query | 17:47:32,511 | 127.0.0.1 | 383 Sending message to /127.0.0.2 | 17:47:32,512 | 127.0.0.1 | 883 Message received from /127.0.0.1 | 17:47:32,512 | 127.0.0.2 | 33 Executing seq scan across 0 sstables for .. . | 17:47:32,513 | 127.0.0.2 | 670 Read 1 live cells and 0 tombstoned | 17:47:32,513 | 127.0.0.2 | 964 Read 1 live cells and 0 tombstoned | 17:47:32,514 | 127.0.0.2 | 1268 Read 1 live cells and 0 tombstoned | 17:47:32,514 | 127.0.0.2 | 1502 Read 1 live cells and 0 tombstoned | 17:47:32,514 | 127.0.0.2 | 1673 Scanned 4 rows and matched 4 | 17:47:32,514 | 127.0.0.2 | 1721 Enqueuing response to /127.0.0.1 | 17:47:32,514 | 127.0.0.2 | 1742 Sending message to /127.0.0.1 | 17:47:32,514 | 127.0.0.2 | 1852 Message received from /127.0.0.2 | 17:47:32,515 | 127.0.0.1 | 3776 Processing response from /127.0.0.2 | 17:47:32,515 | 127.0.0.1 | 3900 Sending message to /127.0.0.2 | 17:47:32,665 | 127.0.0.1 | 153535 Message received from /127.0.0.1 | 17:47:32,665 | 127.0.0.2 | 44 Executing seq scan across 0 sstables for .. . | 17:47:32,666 | 127.0.0.2 | 1068 Read 1 live cells and 0 tombstoned | 17:47:32,667 | 127.0.0.2 | 1454 Read 1 live cells and 0 tombstoned | 17:47:32,667 | 127.0.0.2 | 1640 Scanned 2 rows and matched 2 | 17:47:32,667 | 127.0.0.2 | 1694 Enqueuing response to /127.0.0.1 | 17:47:32,667 | 127.0.0.2 | 1722 Sending message to /127.0.0.1 | 17:47:32,667 | 127.0.0.2 | 1825 Message received from /127.0.0.2 | 17:47:32,668 | 127.0.0.1 | 156454 Processing response from /127.0.0.2 | 17:47:32,668 | 127.0.0.1 | 156610 Executing seq scan across 0 sstables for .. . | 17:47:32,669 | 127.0.0.1 | 157387 Read 1 live cells and 0 tombstoned | 17:47:32,669 | 127.0.0.1 | 157729 Read 1 live cells and 0 tombstoned | 17:47:32,669 | 127.0.0.1 | 157904 Read 1 live cells and 0 tombstoned | 17:47:32,669 | 127.0.0.1 | 158054 Read 1 live cells and 0 tombstoned | 17:47:32,669 | 127.0.0.1 | 158217 Scanned 4 rows and matched 4 | 17:47:32,669 | 127.0.0.1 | 158270 Request complete | 17:47:32,670 | 127.0.0.1 | 159525

クラスター全体の連続スキャンから、以下のことがわかります。

• 1回目のスキャンでは、ノード2で4行が検出された。
• 2回目のスキャンでは、ノード2でさらに2行が検出された。
• 3回目のスキャンでは、ノード1で4行が検出された。