63154


cassandraで以下のような4台構成のクラスタを構成しました。  
10.17.38.204・・・seedノード  
10.17.38.210  
10.17.38.215  
10.17.38.218

整合性レベルQUORUMで書き込み、読み取りを行った際にクラスタ内の過半数のノードへ問合せを  
行っていることを確認したかったため以下の手順で動作確認を行いました。

１．書き込み操作時の詳細な動作を確認しようと10.17.38.204上で  
以下のコマンドを実行しました。

[code]

    > CREATE KEYSPACE test1 WITH REPLICATION = { 'class' : 'NetworkTopologyStrategy', 'dc1' : 1};
    > USE test1;
    > CREATE TABLE test_table ( id int PRIMARY KEY, col1 int, col2 int );
    > TRACING on;
    > CONSISTENCY quorum;
    > INSERT INTO test_table (id, col1, col2) VALUES (2, 2, 2);
    
[/code]

すると、書き込み操作に対するトレース結果が以下のように表示されました。

[code]

     activity                                                                                          | timestamp                  | source       | source_elapsed | client
    ---------------------------------------------------------------------------------------------------+----------------------------+--------------+----------------+----------
                                                                                    Execute CQL3 query | 2020-02-06 14:24:21.378000 | 10.17.38.204 |              0 | 127.0.0.1
       Parsing INSERT INTO test_table (id, col1, col2) VALUES (2, 2, 2); [Native-Transport-Requests-1] | 2020-02-06 14:24:21.380000 | 10.17.38.204 |           2299 | 127.0.0.1
                                                     Preparing statement [Native-Transport-Requests-1] | 2020-02-06 14:24:21.380000 | 10.17.38.204 |           2675 | 127.0.0.1
                                         reading data from /10.17.38.210 [Native-Transport-Requests-1] | 2020-02-06 14:24:21.389000 | 10.17.38.204 |          11254 | 127.0.0.1
                 Sending READ message to /10.17.38.210 [MessagingService-Outgoing-/10.17.38.210-Small] | 2020-02-06 14:24:21.389000 | 10.17.38.204 |          11938 | 127.0.0.1
                    READ message received from /10.17.38.204 [MessagingService-Incoming-/10.17.38.204] | 2020-02-06 14:24:21.392000 | 10.17.38.210 |            390 | 127.0.0.1
                                               Executing single-partition query on roles [ReadStage-1] | 2020-02-06 14:24:21.395000 | 10.17.38.210 |           3733 | 127.0.0.1
                                                            Acquiring sstable references [ReadStage-1] | 2020-02-06 14:24:21.395000 | 10.17.38.210 |           3885 | 127.0.0.1
               Skipped 0/1 non-slice-intersecting sstables, included 0 due to tombstones [ReadStage-1] | 2020-02-06 14:24:21.395000 | 10.17.38.210 |           4074 | 127.0.0.1
                                                             Key cache hit for sstable 2 [ReadStage-1] | 2020-02-06 14:24:21.395000 | 10.17.38.210 |           4239 | 127.0.0.1
                                               Merged data from memtables and 1 sstables [ReadStage-1] | 2020-02-06 14:24:21.397000 | 10.17.38.210 |           5524 | 127.0.0.1
                                                  Read 1 live rows and 0 tombstone cells [ReadStage-1] | 2020-02-06 14:24:21.397000 | 10.17.38.210 |           5683 | 127.0.0.1
                                                     Enqueuing response to /10.17.38.204 [ReadStage-1] | 2020-02-06 14:24:21.397000 | 10.17.38.210 |           5732 | 127.0.0.1
     Sending REQUEST_RESPONSE message to /10.17.38.204 [MessagingService-Outgoing-/10.17.38.204-Small] | 2020-02-06 14:24:21.397000 | 10.17.38.210 |           6012 | 127.0.0.1
        REQUEST_RESPONSE message received from /10.17.38.210 [MessagingService-Incoming-/10.17.38.210] | 2020-02-06 14:24:21.398000 | 10.17.38.204 |          20128 | 127.0.0.1
                                       Processing response from /10.17.38.210 [RequestResponseStage-3] | 2020-02-06 14:24:21.398000 | 10.17.38.204 |          20243 | 127.0.0.1
                                         reading data from /10.17.38.210 [Native-Transport-Requests-1] | 2020-02-06 14:24:21.401000 | 10.17.38.204 |          23720 | 127.0.0.1
                 Sending READ message to /10.17.38.210 [MessagingService-Outgoing-/10.17.38.210-Small] | 2020-02-06 14:24:21.402000 | 10.17.38.204 |          24477 | 127.0.0.1
                    READ message received from /10.17.38.204 [MessagingService-Incoming-/10.17.38.204] | 2020-02-06 14:24:21.406000 | 10.17.38.210 |             10 | 127.0.0.1
                                               Executing single-partition query on roles [ReadStage-2] | 2020-02-06 14:24:21.406000 | 10.17.38.210 |            385 | 127.0.0.1
                                                            Acquiring sstable references [ReadStage-2] | 2020-02-06 14:24:21.406000 | 10.17.38.210 |            479 | 127.0.0.1
               Skipped 0/1 non-slice-intersecting sstables, included 0 due to tombstones [ReadStage-2] | 2020-02-06 14:24:21.406000 | 10.17.38.210 |            566 | 127.0.0.1
        REQUEST_RESPONSE message received from /10.17.38.210 [MessagingService-Incoming-/10.17.38.210] | 2020-02-06 14:24:21.407000 | 10.17.38.204 |          29779 | 127.0.0.1
                                                             Key cache hit for sstable 2 [ReadStage-2] | 2020-02-06 14:24:21.407000 | 10.17.38.210 |            689 | 127.0.0.1
                                       Processing response from /10.17.38.210 [RequestResponseStage-2] | 2020-02-06 14:24:21.407000 | 10.17.38.204 |          29888 | 127.0.0.1
                                               Merged data from memtables and 1 sstables [ReadStage-2] | 2020-02-06 14:24:21.407000 | 10.17.38.210 |            904 | 127.0.0.1
                                                  Read 1 live rows and 0 tombstone cells [ReadStage-2] | 2020-02-06 14:24:21.407000 | 10.17.38.210 |            988 | 127.0.0.1
                                                     Enqueuing response to /10.17.38.204 [ReadStage-2] | 2020-02-06 14:24:21.407000 | 10.17.38.210 |           1026 | 127.0.0.1
     Sending REQUEST_RESPONSE message to /10.17.38.204 [MessagingService-Outgoing-/10.17.38.204-Small] | 2020-02-06 14:24:21.407000 | 10.17.38.210 |           1177 | 127.0.0.1
                                       Determining replicas for mutation [Native-Transport-Requests-1] | 2020-02-06 14:24:21.413000 | 10.17.38.204 |          35123 | 127.0.0.1
             Sending MUTATION message to /10.17.38.215 [MessagingService-Outgoing-/10.17.38.215-Small] | 2020-02-06 14:24:21.413000 | 10.17.38.204 |          35539 | 127.0.0.1
                MUTATION message received from /10.17.38.204 [MessagingService-Incoming-/10.17.38.204] | 2020-02-06 14:24:21.415000 | 10.17.38.215 |            432 | 127.0.0.1
                                                              Appending to commitlog [MutationStage-2] | 2020-02-06 14:24:21.416000 | 10.17.38.215 |           2101 | 127.0.0.1
                                                       Adding to test_table memtable [MutationStage-2] | 2020-02-06 14:24:21.417000 | 10.17.38.215 |           2301 | 127.0.0.1
                                                 Enqueuing response to /10.17.38.204 [MutationStage-2] | 2020-02-06 14:24:21.417000 | 10.17.38.215 |           2688 | 127.0.0.1
     Sending REQUEST_RESPONSE message to /10.17.38.204 [MessagingService-Outgoing-/10.17.38.204-Small] | 2020-02-06 14:24:21.417000 | 10.17.38.215 |           3013 | 127.0.0.1
        REQUEST_RESPONSE message received from /10.17.38.215 [MessagingService-Incoming-/10.17.38.215] | 2020-02-06 14:24:21.418000 | 10.17.38.204 |          40251 | 127.0.0.1
                                       Processing response from /10.17.38.215 [RequestResponseStage-3] | 2020-02-06 14:24:21.418000 | 10.17.38.204 |          40639 | 127.0.0.1
                                                                                      Request complete | 2020-02-06 14:24:21.418832 | 10.17.38.204 |          40832 | 127.0.0.1
    
[/code]

REQUEST_RESPONSE message received from・・・  
というメッセージが表示されたのでクラスタ内の別のノードからも書き込み操作が完了したという  
メッセージが10.17.38.204に返されたのだと判断しました。

２．続いてそのまま読み取り操作に対するトレース結果を確認しようと以下のコマンドを実行しました。

[code]

    > SELECT * FROM test_table;
    
[/code]

すると書き込み操作時とは違い、トレース結果が3000行以上にわたって表示されました。  
書き込み時と読み取り時で結果がかなり異なるのですがcassandraとして正常な動作でしょうか。  
それとも設定や確認の手順を間違えているのでしょうか。


CC BY-SA 4.0
2020-02-18T01:55:37.310
63135
2020-02-18T12:09:09.100
37872
question
cassandra
CassandraのTRACINGコマンドの結果について


上記のトレース結果は、読み取りと書き込みの両方が混ざって表示されているようです。  
通常は書き込みなら、書き込みのトレースのみが表示されるはずです。system_trace.eventsから直接取り出したのでしょうか。

書き込みに関する部分を抜き出すと

[code]

                                       Determining replicas for mutation [Native-Transport-Requests-1] | 2020-02-06 14:24:21.413000 | 10.17.38.204 |          35123 | 127.0.0.1
             Sending MUTATION message to /10.17.38.215 [MessagingService-Outgoing-/10.17.38.215-Small] | 2020-02-06 14:24:21.413000 | 10.17.38.204 |          35539 | 127.0.0.1
                MUTATION message received from /10.17.38.204 [MessagingService-Incoming-/10.17.38.204] | 2020-02-06 14:24:21.415000 | 10.17.38.215 |            432 | 127.0.0.1
                                                              Appending to commitlog [MutationStage-2] | 2020-02-06 14:24:21.416000 | 10.17.38.215 |           2101 | 127.0.0.1
                                                       Adding to test_table memtable [MutationStage-2] | 2020-02-06 14:24:21.417000 | 10.17.38.215 |           2301 | 127.0.0.1
                                                 Enqueuing response to /10.17.38.204 [MutationStage-2] | 2020-02-06 14:24:21.417000 | 10.17.38.215 |           2688 | 127.0.0.1
     Sending REQUEST_RESPONSE message to /10.17.38.204 [MessagingService-Outgoing-/10.17.38.204-Small] | 2020-02-06 14:24:21.417000 | 10.17.38.215 |           3013 | 127.0.0.1
        REQUEST_RESPONSE message received from /10.17.38.215 [MessagingService-Incoming-/10.17.38.215] | 2020-02-06 14:24:21.418000 | 10.17.38.204 |          40251 | 127.0.0.1
                                       Processing response from /10.17.38.215 [RequestResponseStage-3] | 2020-02-06 14:24:21.418000 | 10.17.38.204 |          40639 | 127.0.0.1
                                                                                      Request complete | 2020-02-06 14:24:21.418832 | 10.17.38.204 |          40832 | 127.0.0.1
    
[/code]

`Mutation` (変更)が書き込みを表します。  
このトレースにあるように、Cassandraでの書き込みは

  * Commitlogへの追加 (`Appending to commitlog`)
  * Memtableへのデータ追加 (`Adding to test_table memtable`)

で完了します。

なお、Keyspace の設定を見るとレプリケーションファクターが1なので、データのコピーは一つ(10.17.38.215)にしか書きこまれません。  
(`CREATE KEYSPACE test1 WITH REPLICATION = { 'class' :
'NetworkTopologyStrategy', 'dc1' : 1};`)  
また、レプリケーションファクター1の場合、QUORUM(過半数)は1のため、QUORUMでの挙動を検証したい場合はレプリケーションファクターを3にする必要があります。

一方読み込みは

[code]

                                         reading data from /10.17.38.210 [Native-Transport-Requests-1] | 2020-02-06 14:24:21.389000 | 10.17.38.204 |          11254 | 127.0.0.1
                 Sending READ message to /10.17.38.210 [MessagingService-Outgoing-/10.17.38.210-Small] | 2020-02-06 14:24:21.389000 | 10.17.38.204 |          11938 | 127.0.0.1
                    READ message received from /10.17.38.204 [MessagingService-Incoming-/10.17.38.204] | 2020-02-06 14:24:21.392000 | 10.17.38.210 |            390 | 127.0.0.1
                                               Executing single-partition query on roles [ReadStage-1] | 2020-02-06 14:24:21.395000 | 10.17.38.210 |           3733 | 127.0.0.1
                                                            Acquiring sstable references [ReadStage-1] | 2020-02-06 14:24:21.395000 | 10.17.38.210 |           3885 | 127.0.0.1
               Skipped 0/1 non-slice-intersecting sstables, included 0 due to tombstones [ReadStage-1] | 2020-02-06 14:24:21.395000 | 10.17.38.210 |           4074 | 127.0.0.1
                                                             Key cache hit for sstable 2 [ReadStage-1] | 2020-02-06 14:24:21.395000 | 10.17.38.210 |           4239 | 127.0.0.1
                                               Merged data from memtables and 1 sstables [ReadStage-1] | 2020-02-06 14:24:21.397000 | 10.17.38.210 |           5524 | 127.0.0.1
                                                  Read 1 live rows and 0 tombstone cells [ReadStage-1] | 2020-02-06 14:24:21.397000 | 10.17.38.210 |           5683 | 127.0.0.1
                                                     Enqueuing response to /10.17.38.204 [ReadStage-1] | 2020-02-06 14:24:21.397000 | 10.17.38.210 |           5732 | 127.0.0.1
     Sending REQUEST_RESPONSE message to /10.17.38.204 [MessagingService-Outgoing-/10.17.38.204-Small] | 2020-02-06 14:24:21.397000 | 10.17.38.210 |           6012 | 127.0.0.1
        REQUEST_RESPONSE message received from /10.17.38.210 [MessagingService-Incoming-/10.17.38.210] | 2020-02-06 14:24:21.398000 | 10.17.38.204 |          20128 | 127.0.0.1
                                       Processing response from /10.17.38.210 [RequestResponseStage-3] | 2020-02-06 14:24:21.398000 | 10.17.38.204 |          20243 | 127.0.0.1
    
[/code]

です。  
読み込みはメモリー上のデータ(Memtable)とディスク上のデータ(SSTable)をマージして結果を返します。  
データに紐づくタイムスタンプが新しいものが正しいデータとして返却されます。  
(`Merged data from memtables and 1 sstables`)  
ディスク上のデータを素早く読み込むためにいろいろな工夫があり、キーキャッシュもその一つです。(`Key cache hit for sstable 2`)

この例では読み込むSSTableの数は一つですが、通常複数のSSTableから読み込みます。  
そのため、書き込みよりも読み込みのほうがステップが多くなります。(それに伴いレイテンシーも読み込みのほうが時間がかかる傾向があります。)


CC BY-SA 4.0
2020-02-18T12:09:09.100
63154
2020-02-18T12:09:09.100
4157
63135
answer