Testing performance impact using tracing
Running and tracing queries that read data at different consistency levels.
Tracing records all activity related to a request. These steps use tracing to show queries on a keyspace with a replication factor of 3 using different consistency levels (CL):
- ONE processes responses from one of three replicas
- QUORUM from two of three replicas
- ALL from three of three replicas
Tip: For more information on tracing data, see
this post on the DataStax Support
Blog, which explains in detail how to locate data on disk.
Procedure
-
On the cqlsh command line, create a keyspace that specifies using three
replicas for data distribution in the cluster.
CREATE KEYSPACE cycling_alt WITH replication = {'class':'SimpleStrategy', 'replication_factor':3}; -
Create a table, and insert some values:
USE cycling_alt; CREATE TABLE cycling_alt.tester ( id int PRIMARY KEY, col1 int, col2 int ); INSERT INTO cycling_alt.tester (id, col1, col2) VALUES (0, 0, 0);
-
Turn on tracing and use the CONSISTENCY command to check that the
consistency level is ONE, the default.
TRACING on; CONSISTENCY;
The output should be:Current consistency level is 1. -
Query the table to read the value of the primary key.
SELECT * FROM cycling_alt.tester WHERE id = 0;
The output includes tracing information:id | col1 | col2 ----+------+------ 0 | 0 | 0 (1 rows) Tracing session: 983f3ae0-fdfe-11e6-8b40-23a5e4e49022 activity | timestamp | source | source_elapsed | client ------------------------------------------------------------------------------------------------------------------------------+----------------------------+----------------+----------------+----------- Execute CQL3 query | 2017-02-28 21:40:59.918000 | 10.200.176.228 | 0 | 127.0.0.1 Parsing SELECT * FROM cycling_alt.tester WHERE id = 0; [Native-Transport-Requests-1] | 2017-02-28 21:40:59.918000 | 10.200.176.228 | 248 | 127.0.0.1 Preparing statement [Native-Transport-Requests-1] | 2017-02-28 21:40:59.918000 | 10.200.176.228 | 473 | 127.0.0.1 speculating read retry on /10.200.176.229 [Native-Transport-Requests-1] | 2017-02-28 21:40:59.920000 | 10.200.176.228 | 2339 | 127.0.0.1 Sending READ message to /10.200.176.229 message size 134 bytes [MessagingService-Outgoing-/10.200.176.229-Small] | 2017-02-28 21:40:59.921000 | 10.200.176.228 | 2660 | 127.0.0.1 Executing single-partition query on tester [ReadStage-3] | 2017-02-28 21:40:59.923000 | 10.200.176.228 | 4706 | 127.0.0.1 Acquiring sstable references [ReadStage-3] | 2017-02-28 21:40:59.923000 | 10.200.176.228 | 4841 | 127.0.0.1 Merging memtable contents [ReadStage-3] | 2017-02-28 21:40:59.923000 | 10.200.176.228 | 4910 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-3] | 2017-02-28 21:40:59.923000 | 10.200.176.228 | 5192 | 127.0.0.1 REQUEST_RESPONSE message received from /10.200.176.229 [MessagingService-Incoming-/10.200.176.229] | 2017-02-28 21:40:59.924000 | 10.200.176.228 | 5644 | 127.0.0.1 Processing response from /10.200.176.229 [RequestResponseStage-3] | 2017-02-28 21:40:59.924000 | 10.200.176.228 | 6116 | 127.0.0.1 Initiating read-repair [RequestResponseStage-3] | 2017-02-28 21:40:59.924000 | 10.200.176.228 | 6256 | 127.0.0.1 READ message received from /10.200.176.228 [MessagingService-Incoming-/10.200.176.228] | 2017-02-28 21:40:59.968000 | 10.200.176.229 | 19 | 127.0.0.1 Executing single-partition query on tester [ReadStage-1] | 2017-02-28 21:40:59.969000 | 10.200.176.229 | 711 | 127.0.0.1 Acquiring sstable references [ReadStage-1] | 2017-02-28 21:40:59.969000 | 10.200.176.229 | 781 | 127.0.0.1 Merging memtable contents [ReadStage-1] | 2017-02-28 21:40:59.969000 | 10.200.176.229 | 824 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-1] | 2017-02-28 21:40:59.969000 | 10.200.176.229 | 1056 | 127.0.0.1 Enqueuing response to /10.200.176.228 [ReadStage-1] | 2017-02-28 21:40:59.969000 | 10.200.176.229 | 1118 | 127.0.0.1 Sending REQUEST_RESPONSE message to /10.200.176.228 message size 113 bytes [MessagingService-Outgoing-/10.200.176.228-Small] | 2017-02-28 21:40:59.970000 | 10.200.176.229 | 1704 | 127.0.0.1 Request complete | 2017-02-28 21:40:59.924664 | 10.200.176.228 | 6664 | 127.0.0.1The tracing results list all the actions taken to complete the
SELECTstatement. -
Change the consistency level to QUORUM to trace what happens during a read with
a QUORUM consistency level.
CONSISTENCY quorum; SELECT * FROM cycling_alt.tester WHERE id = 0;
id | col1 | col2 ----+------+------ 0 | 0 | 0 (1 rows) Tracing session: c96811a0-fdfe-11e6-8b40-23a5e4e49022 activity | timestamp | source | source_elapsed | client -----------------------------------------------------------------------------------------------------------------------------+----------------------------+----------------+----------------+----------- Execute CQL3 query | 2017-02-28 21:42:22.394000 | 10.200.176.228 | 0 | 127.0.0.1 READ message received from /10.200.176.228 [MessagingService-Incoming-/10.200.176.228] | 2017-02-28 21:42:22.369000 | 10.200.176.23 | 20 | 127.0.0.1 Executing single-partition query on tester [ReadStage-2] | 2017-02-28 21:42:22.370000 | 10.200.176.23 | 1119 | 127.0.0.1 Acquiring sstable references [ReadStage-2] | 2017-02-28 21:42:22.370000 | 10.200.176.23 | 1188 | 127.0.0.1 Merging memtable contents [ReadStage-2] | 2017-02-28 21:42:22.370000 | 10.200.176.23 | 1272 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-2] | 2017-02-28 21:42:22.371000 | 10.200.176.23 | 1895 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-2] | 2017-02-28 21:42:22.371000 | 10.200.176.23 | 2052 | 127.0.0.1 Enqueuing response to /10.200.176.228 [ReadStage-2] | 2017-02-28 21:42:22.371000 | 10.200.176.23 | 2095 | 127.0.0.1 Sending REQUEST_RESPONSE message to /10.200.176.228 message size 96 bytes [MessagingService-Outgoing-/10.200.176.228-Small] | 2017-02-28 21:42:22.372000 | 10.200.176.23 | 2413 | 127.0.0.1 Parsing SELECT * FROM cycling_alt.tester WHERE id = 0; [Native-Transport-Requests-1] | 2017-02-28 21:42:22.395000 | 10.200.176.228 | 421 | 127.0.0.1 Preparing statement [Native-Transport-Requests-1] | 2017-02-28 21:42:22.395000 | 10.200.176.228 | 656 | 127.0.0.1 Executing single-partition query on tester [ReadStage-2] | 2017-02-28 21:42:22.395000 | 10.200.176.228 | 1159 | 127.0.0.1 Acquiring sstable references [ReadStage-2] | 2017-02-28 21:42:22.395000 | 10.200.176.228 | 1288 | 127.0.0.1 Merging memtable contents [ReadStage-2] | 2017-02-28 21:42:22.395000 | 10.200.176.228 | 1344 | 127.0.0.1 reading digest from /10.200.176.23 [Native-Transport-Requests-1] | 2017-02-28 21:42:22.396000 | 10.200.176.228 | 1514 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-2] | 2017-02-28 21:42:22.396000 | 10.200.176.228 | 1584 | 127.0.0.1 speculating read retry on /10.200.176.229 [Native-Transport-Requests-1] | 2017-02-28 21:42:22.396000 | 10.200.176.228 | 1781 | 127.0.0.1 Sending READ message to /10.200.176.229 message size 135 bytes [MessagingService-Outgoing-/10.200.176.229-Small] | 2017-02-28 21:42:22.396000 | 10.200.176.228 | 1981 | 127.0.0.1 Sending READ message to /10.200.176.23 message size 135 bytes [MessagingService-Outgoing-/10.200.176.23-Small] | 2017-02-28 21:42:22.396000 | 10.200.176.228 | 2243 | 127.0.0.1 REQUEST_RESPONSE message received from /10.200.176.229 [MessagingService-Incoming-/10.200.176.229] | 2017-02-28 21:42:22.399000 | 10.200.176.228 | 4734 | 127.0.0.1 Processing response from /10.200.176.229 [RequestResponseStage-3] | 2017-02-28 21:42:22.399000 | 10.200.176.228 | 4869 | 127.0.0.1 REQUEST_RESPONSE message received from /10.200.176.23 [MessagingService-Incoming-/10.200.176.23] | 2017-02-28 21:42:22.404000 | 10.200.176.228 | 38 | 127.0.0.1 Processing response from /10.200.176.23 [RequestResponseStage-2] | 2017-02-28 21:42:22.405000 | 10.200.176.228 | 4559 | 127.0.0.1 Initiating read-repair [RequestResponseStage-2] | 2017-02-28 21:42:22.405000 | 10.200.176.228 | 4711 | 127.0.0.1 READ message received from /10.200.176.228 [MessagingService-Incoming-/10.200.176.228] | 2017-02-28 21:42:22.443000 | 10.200.176.229 | 19 | 127.0.0.1 Executing single-partition query on tester [ReadStage-1] | 2017-02-28 21:42:22.444000 | 10.200.176.229 | 346 | 127.0.0.1 Acquiring sstable references [ReadStage-1] | 2017-02-28 21:42:22.444000 | 10.200.176.229 | 418 | 127.0.0.1 Merging memtable contents [ReadStage-1] | 2017-02-28 21:42:22.444000 | 10.200.176.229 | 477 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-1] | 2017-02-28 21:42:22.444000 | 10.200.176.229 | 854 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-1] | 2017-02-28 21:42:22.444000 | 10.200.176.229 | 975 | 127.0.0.1 Enqueuing response to /10.200.176.228 [ReadStage-1] | 2017-02-28 21:42:22.444000 | 10.200.176.229 | 1039 | 127.0.0.1 Sending REQUEST_RESPONSE message to /10.200.176.228 message size 96 bytes [MessagingService-Outgoing-/10.200.176.228-Small] | 2017-02-28 21:42:22.445000 | 10.200.176.229 | 1617 | 127.0.0.1 Request complete | 2017-02-28 21:42:22.400017 | 10.200.176.228 | 6017 | 127.0.0.1 -
Change the consistency level to ALL and run the SELECT statement again.
CONSISTENCY ALL; SELECT * FROM cycling_alt.tester WHERE id = 0;
id | col1 | col2 ----+------+------ 0 | 0 | 0 (1 rows) Tracing session: ea9a9aa0-fdfe-11e6-8b40-23a5e4e49022 activity | timestamp | source | source_elapsed | client -----------------------------------------------------------------------------------------------------------------------------+----------------------------+----------------+----------------+----------- Execute CQL3 query | 2017-02-28 21:43:18.090000 | 10.200.176.228 | 0 | 127.0.0.1 READ message received from /10.200.176.228 [MessagingService-Incoming-/10.200.176.228] | 2017-02-28 21:43:18.065000 | 10.200.176.23 | 41 | 127.0.0.1 Executing single-partition query on tester [ReadStage-1] | 2017-02-28 21:43:18.065000 | 10.200.176.23 | 369 | 127.0.0.1 Acquiring sstable references [ReadStage-1] | 2017-02-28 21:43:18.065000 | 10.200.176.23 | 428 | 127.0.0.1 Merging memtable contents [ReadStage-1] | 2017-02-28 21:43:18.065000 | 10.200.176.23 | 518 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-1] | 2017-02-28 21:43:18.066000 | 10.200.176.23 | 771 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-1] | 2017-02-28 21:43:18.066000 | 10.200.176.23 | 852 | 127.0.0.1 Enqueuing response to /10.200.176.228 [ReadStage-1] | 2017-02-28 21:43:18.066000 | 10.200.176.23 | 893 | 127.0.0.1 Sending REQUEST_RESPONSE message to /10.200.176.228 message size 96 bytes [MessagingService-Outgoing-/10.200.176.228-Small] | 2017-02-28 21:43:18.066000 | 10.200.176.23 | 1344 | 127.0.0.1 Parsing SELECT * FROM cycling_alt.tester WHERE id = 0; [Native-Transport-Requests-1] | 2017-02-28 21:43:18.090000 | 10.200.176.228 | 451 | 127.0.0.1 Preparing statement [Native-Transport-Requests-1] | 2017-02-28 21:43:18.091000 | 10.200.176.228 | 774 | 127.0.0.1 reading digest from /10.200.176.23 [Native-Transport-Requests-1] | 2017-02-28 21:43:18.091000 | 10.200.176.228 | 1256 | 127.0.0.1 reading digest from /10.200.176.229 [Native-Transport-Requests-1] | 2017-02-28 21:43:18.092000 | 10.200.176.228 | 1562 | 127.0.0.1 Sending READ message to /10.200.176.23 message size 135 bytes [MessagingService-Outgoing-/10.200.176.23-Small] | 2017-02-28 21:43:18.092000 | 10.200.176.228 | 1941 | 127.0.0.1 Executing single-partition query on tester [ReadStage-3] | 2017-02-28 21:43:18.094000 | 10.200.176.228 | 4066 | 127.0.0.1 Acquiring sstable references [ReadStage-3] | 2017-02-28 21:43:18.094000 | 10.200.176.228 | 4213 | 127.0.0.1 Merging memtable contents [ReadStage-3] | 2017-02-28 21:43:18.094000 | 10.200.176.228 | 4323 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-3] | 2017-02-28 21:43:18.095000 | 10.200.176.228 | 4595 | 127.0.0.1 REQUEST_RESPONSE message received from /10.200.176.23 [MessagingService-Incoming-/10.200.176.23] | 2017-02-28 21:43:18.095000 | 10.200.176.228 | 5123 | 127.0.0.1 Processing response from /10.200.176.23 [RequestResponseStage-4] | 2017-02-28 21:43:18.096000 | 10.200.176.228 | 5730 | 127.0.0.1 Sending READ message to /10.200.176.229 message size 135 bytes [MessagingService-Outgoing-/10.200.176.229-Small] | 2017-02-28 21:43:18.096000 | 10.200.176.228 | 5916 | 127.0.0.1 REQUEST_RESPONSE message received from /10.200.176.229 [MessagingService-Incoming-/10.200.176.229] | 2017-02-28 21:43:18.099000 | 10.200.176.228 | 8493 | 127.0.0.1 Processing response from /10.200.176.229 [RequestResponseStage-3] | 2017-02-28 21:43:18.099000 | 10.200.176.228 | 9062 | 127.0.0.1 READ message received from /10.200.176.228 [MessagingService-Incoming-/10.200.176.228] | 2017-02-28 21:43:18.143000 | 10.200.176.229 | 19 | 127.0.0.1 Executing single-partition query on tester [ReadStage-2] | 2017-02-28 21:43:18.144000 | 10.200.176.229 | 689 | 127.0.0.1 Acquiring sstable references [ReadStage-2] | 2017-02-28 21:43:18.144000 | 10.200.176.229 | 862 | 127.0.0.1 Merging memtable contents [ReadStage-2] | 2017-02-28 21:43:18.144000 | 10.200.176.229 | 906 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-2] | 2017-02-28 21:43:18.144000 | 10.200.176.229 | 1182 | 127.0.0.1 Read 1 live and 0 tombstone cells [ReadStage-2] | 2017-02-28 21:43:18.144000 | 10.200.176.229 | 1280 | 127.0.0.1 Enqueuing response to /10.200.176.228 [ReadStage-2] | 2017-02-28 21:43:18.144000 | 10.200.176.229 | 1326 | 127.0.0.1 Sending REQUEST_RESPONSE message to /10.200.176.228 message size 96 bytes [MessagingService-Outgoing-/10.200.176.228-Small] | 2017-02-28 21:43:18.144001 | 10.200.176.229 | 1521 | 127.0.0.1 Request complete | 2017-02-28 21:43:18.100053 | 10.200.176.228 | 10053 | 127.0.0.1