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.

  1. 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
    };
  2. 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'
    );
  3. 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.
  4. 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.1

    The tracing results list all the actions taken to complete the SELECT statement.

  5. 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
  6. 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

Was this helpful?

Give Feedback

How can we improve the documentation?

© 2024 DataStax | Privacy policy | Terms of use

Apache, Apache Cassandra, Cassandra, Apache Tomcat, Tomcat, Apache Lucene, Apache Solr, Apache Hadoop, Hadoop, Apache Pulsar, Pulsar, Apache Spark, Spark, Apache TinkerPop, TinkerPop, Apache Kafka and Kafka are either registered trademarks or trademarks of the Apache Software Foundation or its subsidiaries in Canada, the United States and/or other countries. Kubernetes is the registered trademark of the Linux Foundation.

General Inquiries: +1 (650) 389-6000, info@datastax.com