Testing performance impact using tracing
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
|
For more information on tracing data, see this post on the DataStax Support Blog, which explains in detail how to locate data on disk. |
-
On the cqlsh command line, create a keyspace that specifies using three replicas for data distribution in the cluster.
CREATE KEYSPACE IF NOT EXISTS cycling_alt WITH REPLICATION = { 'class': 'SimpleStrategy', 'replication_factor': 3 }; -
Create a table and insert a row.
USE cycling_alt; CREATE TABLE IF NOT EXISTS cycling_alt.cyclist_name ( id int PRIMARY KEY, lastname text, firstname text ); INSERT INTO cycling_alt.cyclist_name ( id, lastname, firstname ) VALUES ( 1, 'HOSKINS', 'Melissa' ); -
Turn on tracing and use the CONSISTENCY command to ensure the consistency level is ONE, the default.
TRACING ON; CONSISTENCY;The output is:
Current consistency level is ONE. -
Query the table to read the row.
SELECT * FROM cycling_alt.cyclist_name WHERE id = 1;The output includes tracing information:
id | firstname | lastname ----+-----------+---------- 1 | Melissa | HOSKINS (1 rows) Tracing session: e8c661e0-185a-11ea-9875-4584590d1ec9 activity | timestamp | source | source_elapsed | client ---------------------------------------------------------------------------------------------------------------------+--------------------- -------+---------------+----------------+----------- Execute CQL3 query | 2019-12-06 19:02:11. 966000 | 10.101.33.107 | 0 | 127.0.0.1 READS.SINGLE_READ message received from /10.101.33.107 [MessagingService-Incoming-/10.101.33.107] | 2019-12-06 19:02:11. 966000 | 10.101.35.157 | -- | 127.0.0.1 READS.SINGLE_READ message received from /10.101.33.107 [MessagingService-Incoming-/10.101.33.107] | 2019-12-06 19:02:11. 966000 | 10.101.35.173 | 64 | 127.0.0.1 Parsing SELECT *\nFROM cycling_alt.cyclist_name \nWHERE id = 1; [CoreThread-0] | 2019-12-06 19:02:11. 966000 | 10.101.33.107 | 126 | 127.0.0.1 Executing single-partition query on cyclist_name [CoreThread-2] | 2019-12-06 19:02:11. 966000 | 10.101.35.157 | 428 | 127.0.0.1 Executing single-partition query on cyclist_name [CoreThread-0] | 2019-12-06 19:02:11. 966000 | 10.101.35.173 | 332 | 127.0.0.1 Preparing statement [CoreThread-0] | 2019-12-06 19:02:11. 966000 | 10.101.33.107 | 282 | 127.0.0.1 Acquiring sstable references [CoreThread-2] | 2019-12-06 19:02:11. 966000 | 10.101.35.157 | 490 | 127.0.0.1 Acquiring sstable references [CoreThread-0] | 2019-12-06 19:02:11. 966000 | 10.101.35.173 | 414 | 127.0.0.1 Merged data from memtables and 0 sstables [CoreThread-2] | 2019-12-06 19:02:11. 966000 | 10.101.35.157 | 676 | 127.0.0.1 Merged data from memtables and 0 sstables [CoreThread-0] | 2019-12-06 19:02:11. 966000 | 10.101.35.173 | 607 | 127.0.0.1 Reading data from [/10.101.33.107] [CoreThread-0] | 2019-12-06 19:02:11. 966000 | 10.101.33.107 | 420 | 127.0.0.1 Read 1 live rows and 0 tombstone cells [CoreThread-0] | 2019-12-06 19:02:11. 966000 | 10.101.35.173 | 672 | 127.0.0.1 Executing single-partition query on cyclist_name [CoreThread-0] | 2019-12-06 19:02:11. 966000 | 10.101.33.107 | 483 | 127.0.0.1 Enqueuing READS.SINGLE_READ response to /10.101.35.173 [CoreThread-0] | 2019-12-06 19:02:11. 966000 | 10.101.35.173 | 737 | 127.0.0.1 Acquiring sstable references [CoreThread-0] | 2019-12-06 19:02:11. 966001 | 10.101.33.107 | 483 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.33.107, size=43 bytes [MessagingService-Outgoing-/10.101.33.107-Small] | 2019-12-06 19:02:11. 966001 | 10.101.35.173 | 801 | 127.0.0.1 Merged data from memtables and 0 sstables [CoreThread-0] | 2019-12-06 19:02:11. 966001 | 10.101.33.107 | 608 | 127.0.0.1 Read 1 live rows and 0 tombstone cells [CoreThread-0] | 2019-12-06 19:02:11. 966001 | 10.101.33.107 | 682 | 127.0.0.1 Reading digests from [/10.101.35.173, /10.101.35.157] [CoreThread-0] | 2019-12-06 19:02:11. 966001 | 10.101.33.107 | 745 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.35.173, size=92 bytes [MessagingService-Outgoing-/10.101.35.173-Small] | 2019-12-06 19:02:11. 967000 | 10.101.33.107 | 871 | 127.0.0.1 Read 1 live rows and 0 tombstone cells [CoreThread-2] | 2019-12-06 19:02:11. 967000 | 10.101.35.157 | 737 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.35.157, size=92 bytes [MessagingService-Outgoing-/10.101.35.157-Small] | 2019-12-06 19:02:11. 967000 | 10.101.33.107 | 871 | 127.0.0.1 Enqueuing READS.SINGLE_READ response to /10.101.35.157 [CoreThread-2] | 2019-12-06 19:02:11. 967000 | 10.101.35.157 | 799 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.33.107, size=43 bytes [MessagingService-Outgoing-/10.101.33.107-Small] | 2019-12-06 19:02:11. 967000 | 10.101.35.157 | 1546 | 127.0.0.1 READS.SINGLE_READ message received from /10.101.35.173 [MessagingService-Incoming-/10.101.35.173] | 2019-12-06 19:02:11. 968000 | 10.101.33.107 | 2269 | 127.0.0.1 Processing response from /10.101.35.173 [CoreThread-0] | 2019-12-06 19:02:11. 968000 | 10.101.33.107 | 2470 | 127.0.0.1 READS.SINGLE_READ message received from /10.101.35.157 [MessagingService-Incoming-/10.101.35.157] | 2019-12-06 19:02:11. 969000 | 10.101.33.107 | 3125 | 127.0.0.1 Processing response from /10.101.35.157 [CoreThread-0] | 2019-12-06 19:02:11. 969000 | 10.101.33.107 | 3265 | 127.0.0.1 Request complete | 2019-12-06 19:02:11. 969499 | 10.101.33.107 | 3499 | 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.cyclist_name WHERE id = 1;id | firstname | lastname ----+-----------+---------- 1 | Melissa | HOSKINS (1 rows) Tracing session: e8caa7a0-185a-11ea-9875-4584590d1ec9 activity | timestamp | source | source_elapsed | client ---------------------------------------------------------------------------------------------------------------------+--------------------- -------+---------------+----------------+----------- Execute CQL3 query | 2019-12-06 19:02:11. 994000 | 10.101.33.107 | 0 | 127.0.0.1 READS.SINGLE_READ message received from /10.101.33.107 [MessagingService-Incoming-/10.101.33.107] | 2019-12-06 19:02:11. 994000 | 10.101.35.173 | 60 | 127.0.0.1 Parsing SELECT *\nFROM cycling_alt.cyclist_name \nWHERE id = 1; [CoreThread-0] | 2019-12-06 19:02:11. 994000 | 10.101.33.107 | 121 | 127.0.0.1 Preparing statement [CoreThread-0] | 2019-12-06 19:02:11. 994000 | 10.101.33.107 | 363 | 127.0.0.1 Reading data from [/10.101.33.107] [CoreThread-0] | 2019-12-06 19:02:11. 994000 | 10.101.33.107 | 500 | 127.0.0.1 Executing single-partition query on cyclist_name [CoreThread-0] | 2019-12-06 19:02:11. 994000 | 10.101.33.107 | 622 | 127.0.0.1 Acquiring sstable references [CoreThread-0] | 2019-12-06 19:02:11. 994001 | 10.101.33.107 | 622 | 127.0.0.1 Merged data from memtables and 0 sstables [CoreThread-0] | 2019-12-06 19:02:11. 994001 | 10.101.33.107 | 682 | 127.0.0.1 Read 1 live rows and 0 tombstone cells [CoreThread-0] | 2019-12-06 19:02:11. 994001 | 10.101.33.107 | 742 | 127.0.0.1 Reading digests from [/10.101.35.173] [CoreThread-0] | 2019-12-06 19:02:11. 994001 | 10.101.33.107 | 786 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.35.173, size=92 bytes [MessagingService-Outgoing-/10.101.35.173-Small] | 2019-12-06 19:02:11. 995000 | 10.101.33.107 | 908 | 127.0.0.1 Executing single-partition query on cyclist_name [CoreThread-2] | 2019-12-06 19:02:11. 995000 | 10.101.35.173 | 121 | 127.0.0.1 Acquiring sstable references [CoreThread-2] | 2019-12-06 19:02:11. 995000 | 10.101.35.173 | 121 | 127.0.0.1 Merged data from memtables and 0 sstables [CoreThread-2] | 2019-12-06 19:02:11. 995000 | 10.101.35.173 | 121 | 127.0.0.1 Read 1 live rows and 0 tombstone cells [CoreThread-2] | 2019-12-06 19:02:11. 995000 | 10.101.35.173 | 121 | 127.0.0.1 Enqueuing READS.SINGLE_READ response to /10.101.35.173 [CoreThread-2] | 2019-12-06 19:02:11. 995000 | 10.101.35.173 | 121 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.33.107, size=43 bytes [MessagingService-Outgoing-/10.101.33.107-Small] | 2019-12-06 19:02:11. 995000 | 10.101.35.173 | 461 | 127.0.0.1 READS.SINGLE_READ message received from /10.101.35.173 [MessagingService-Incoming-/10.101.35.173] | 2019-12-06 19:02:11. 996000 | 10.101.33.107 | 1916 | 127.0.0.1 Processing response from /10.101.35.173 [CoreThread-0] | 2019-12-06 19:02:11. 996000 | 10.101.33.107 | 2039 | 127.0.0.1 Request complete | 2019-12-06 19:02:11. 996230 | 10.101.33.107 | 2230 | 127.0.0.1 -
Change the consistency level to ALL and run the SELECT statement again.
CONSISTENCY ALL; SELECT * FROM cycling_alt.cyclist_name WHERE id = 1;id | firstname | lastname ----+-----------+---------- 1 | Melissa | HOSKINS (1 rows) Tracing session: e8cfb0b0-185a-11ea-9875-4584590d1ec9 activity | timestamp | source | source_elapsed | client ---------------------------------------------------------------------------------------------------------------------+--------------------- -------+---------------+----------------+----------- Execute CQL3 query | 2019-12-06 19:02:12. 027000 | 10.101.33.107 | 0 | 127.0.0.1 READS.SINGLE_READ message received from /10.101.33.107 [MessagingService-Incoming-/10.101.33.107] | 2019-12-06 19:02:12. 027000 | 10.101.35.157 | -- | 127.0.0.1 READS.SINGLE_READ message received from /10.101.33.107 [MessagingService-Incoming-/10.101.33.107] | 2019-12-06 19:02:12. 027000 | 10.101.35.173 | -- | 127.0.0.1 Parsing SELECT *\nFROM cycling_alt.cyclist_name \nWHERE id = 1; [CoreThread-0] | 2019-12-06 19:02:12. 027000 | 10.101.33.107 | 126 | 127.0.0.1 Executing single-partition query on cyclist_name [CoreThread-1] | 2019-12-06 19:02:12. 027000 | 10.101.35.173 | 193 | 127.0.0.1 Preparing statement [CoreThread-0] | 2019-12-06 19:02:12. 027000 | 10.101.33.107 | 249 | 127.0.0.1 Acquiring sstable references [CoreThread-1] | 2019-12-06 19:02:12. 027000 | 10.101.35.173 | 268 | 127.0.0.1 Merged data from memtables and 0 sstables [CoreThread-1] | 2019-12-06 19:02:12. 027000 | 10.101.35.173 | 404 | 127.0.0.1 Read-repair DC_LOCAL [CoreThread-0] | 2019-12-06 19:02:12. 027000 | 10.101.33.107 | 370 | 127.0.0.1 Read 1 live rows and 0 tombstone cells [CoreThread-1] | 2019-12-06 19:02:12. 027000 | 10.101.35.173 | 404 | 127.0.0.1 Reading data from [/10.101.33.107] [CoreThread-0] | 2019-12-06 19:02:12. 027000 | 10.101.33.107 | 431 | 127.0.0.1 Enqueuing READS.SINGLE_READ response to /10.101.35.173 [CoreThread-1] | 2019-12-06 19:02:12. 027000 | 10.101.35.173 | 468 | 127.0.0.1 Reading digests from [/10.101.35.173, /10.101.35.157] [CoreThread-0] | 2019-12-06 19:02:12. 027001 | 10.101.33.107 | 431 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.33.107, size=43 bytes [MessagingService-Outgoing-/10.101.33.107-Small] | 2019-12-06 19:02:12. 027001 | 10.101.35.173 | 797 | 127.0.0.1 Executing single-partition query on cyclist_name [CoreThread-1] | 2019-12-06 19:02:12. 027001 | 10.101.33.107 | 491 | 127.0.0.1 Acquiring sstable references [CoreThread-1] | 2019-12-06 19:02:12. 028000 | 10.101.33.107 | 563 | 127.0.0.1 Executing single-partition query on cyclist_name [CoreThread-2] | 2019-12-06 19:02:12. 028000 | 10.101.35.157 | 416 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.35.173, size=92 bytes [MessagingService-Outgoing-/10.101.35.173-Small] | 2019-12-06 19:02:12. 028000 | 10.101.33.107 | 563 | 127.0.0.1 Acquiring sstable references [CoreThread-2] | 2019-12-06 19:02:12. 028000 | 10.101.35.157 | 546 | 127.0.0.1 Merged data from memtables and 0 sstables [CoreThread-1] | 2019-12-06 19:02:12. 028000 | 10.101.33.107 | 563 | 127.0.0.1 Merged data from memtables and 0 sstables [CoreThread-2] | 2019-12-06 19:02:12. 028000 | 10.101.35.157 | 676 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.35.157, size=92 bytes [MessagingService-Outgoing-/10.101.35.157-Small] | 2019-12-06 19:02:12. 028000 | 10.101.33.107 | 563 | 127.0.0.1 Read 1 live rows and 0 tombstone cells [CoreThread-2] | 2019-12-06 19:02:12. 028000 | 10.101.35.157 | 740 | 127.0.0.1 Read 1 live rows and 0 tombstone cells [CoreThread-1] | 2019-12-06 19:02:12. 028000 | 10.101.33.107 | 563 | 127.0.0.1 Enqueuing READS.SINGLE_READ response to /10.101.35.157 [CoreThread-2] | 2019-12-06 19:02:12. 028000 | 10.101.35.157 | 805 | 127.0.0.1 READS.SINGLE_READ message received from /10.101.35.173 [MessagingService-Incoming-/10.101.35.173] | 2019-12-06 19:02:12. 029000 | 10.101.33.107 | 1857 | 127.0.0.1 Sending READS.SINGLE_READ message to /10.101.33.107, size=43 bytes [MessagingService-Outgoing-/10.101.33.107-Small] | 2019-12-06 19:02:12. 029000 | 10.101.35.157 | 1450 | 127.0.0.1 Processing response from /10.101.35.173 [CoreThread-0] | 2019-12-06 19:02:12. 029000 | 10.101.33.107 | 1918 | 127.0.0.1 READS.SINGLE_READ message received from /10.101.35.157 [MessagingService-Incoming-/10.101.35.157] | 2019-12-06 19:02:12. 029000 | 10.101.33.107 | 2549 | 127.0.0.1 Processing response from /10.101.35.157 [CoreThread-0] | 2019-12-06 19:02:12. 030000 | 10.101.33.107 | 2713 | 127.0.0.1 Request complete | 2019-12-06 19:02:12. 029911 | 10.101.33.107 | 2911 | 127.0.0.1