TRACING

Enables or disables tracing for all CQL statements in the current CQL shell session.

Tracing can show tracing input from any or all nodes in the cluster. Use tracing to troubleshoot performance problems. Detailed transaction information related to internal operations is captured in the system_traces keyspace.

When a query runs in a tracing session, a session ID is shown in the query results. In addition, an entry with the high-level details, such as session ID, client, and session length, is written to the system_traces.session table. Details for each operation are written to the system_traces.events table.

You can use the session ID with the SHOW SESSION command to get detailed event information.

Tracing information is saved for 24 hours by default. To override this, set tracetype_query_ttl in cassandra.yaml, and then restart the node. The new TTL applies to trace data recorded after you restart the node. To preserve tracing data for longer than the TTL, copy the data to another location.

Synopsis

TRACING [ ON | OFF ]

ON: Enables tracing.
OFF: Disables tracing.

Trace a write request

The following example traces a write request on a keyspace with a replication factor of 3. For Astra DB, triple replication is enabled by default and cannot be changed.

To follow along with this example, create the following schema:

CREATE KEYSPACE IF NOT EXISTS cycling_alt
  WITH REPLICATION = {
    'class': 'SimpleStrategy',
    'replication_factor': 3
  };

CREATE TABLE IF NOT EXISTS cycling_alt.cyclist_name (
  id int PRIMARY KEY,
  lastname text,
  firstname text
);

Enable tracing:
```
TRACING ON
```

Insert a record into the cyclist_name table:

INSERT INTO cycling_alt.cyclist_name (
  id,
  lastname,
  firstname
) VALUES (
  e7ae5cf3-d358-4d99-b900-85902fda9bb0,
  'FRAME',
  'Alex'
);

The output shows the request details with information about each step required to complete the write operation. Specifically, the tracing shows that the coordinator node performs these actions:

Identifies the target nodes for replication of the row.
Writes the row to the commit log and memtable.
Confirms completion of the request.

Tracing session: 9b378c70-b114-11e6-89b5-b7fad52e1885

 activity                                                                                         | timestamp                  | source    | source_elapsed | client
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
                                                                               Execute CQL3 query | 2016-11-22 16:34:34.300000 | 127.0.0.1 |              0 | 127.0.0.1
 Parsing INSERT INTO cycling_alt.cyclist_name (id, lastname, firstname)
 VALUES (e7ae5cf3-d358-4d99-b900-85902fda9bb0, 'FRAME','Alex'); [Native-Transport-Requests-1]     | 2016-11-22 16:34:34.305000 | 127.0.0.1 |           5935 | 127.0.0.1
                                                Preparing statement [Native-Transport-Requests-1] | 2016-11-22 16:34:34.308000 | 127.0.0.1 |           9199 | 127.0.0.1
                                  Determining replicas for mutation [Native-Transport-Requests-1] | 2016-11-22 16:34:34.330000 | 127.0.0.1 |          30530 | 127.0.0.1
                                                         Appending to commitlog [MutationStage-3] | 2016-11-22 16:34:34.330000 | 127.0.0.1 |          30979 | 127.0.0.1
                                                Adding to cyclist_name memtable [MutationStage-3] | 2016-11-22 16:34:34.330000 | 127.0.0.1 |          31510 | 127.0.0.1
                                                                                 Request complete | 2016-11-22 16:34:34.333633 | 127.0.0.1 |          33633 | 127.0.0.1

The source_elapsed column value is the elapsed time of the event on the source node in microseconds.

Trace a sequential scan

This example demonstrates tracing when a single row is split across multiple SSTables. To read the complete row, the database must read from multiple SSTables, which can be observed in the tracing output.

To follow along with this example, create the following schema:

CREATE KEYSPACE IF NOT EXISTS cycling_alt
  WITH REPLICATION = {
    'class': 'SimpleStrategy',
    'replication_factor': 3
  };

CREATE TABLE IF NOT EXISTS cycling_alt.cyclist_name (
  id int PRIMARY KEY,
  lastname text,
  firstname text
);

Enable tracing:
```
TRACING ON
```

Query the table.

This example uses an unbounded SELECT statement because the dataset is small. For production databases, use a narrower query.

SELECT * FROM cycling_alt.cyclist_name;

The output includes the actual query results followed by the tracing details. To find SSTable reads, look for activities like Executing seq scan.

 id                                   | firstname | lastname
--------------------------------------+-----------+-----------------
 e7ae5cf3-d358-4d99-b900-85902fda9bb0 |      Alex |           FRAME
 fb372533-eb95-4bb4-8685-6ef61e994caa |   Michael |        MATTHEWS
 5b6962dd-3f90-4c93-8f61-eabfa4a803e2 |  Marianne |             VOS
 220844bf-4860-49d6-9a4b-6b5d3a79cbfb |     Paolo |       TIRALONGO
 6ab09bec-e68e-48d9-a5f8-97e6fb4c9b47 |    Steven |      KRUIKSWIJK
 e7cd5752-bc0d-4157-a80f-7523add8dbcd |      Anna | VAN DER BREGGEN

(6 rows)

Tracing session: 117c1440-b116-11e6-89b5-b7fad52e1885

 activity                                                                                                                      | timestamp                  | source    | source_elapsed | client
-------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
                                                                                                            Execute CQL3 query | 2016-11-22 16:45:02.212000 | 127.0.0.1 |              0 | 127.0.0.1
                                                Parsing SELECT * FROM cycling_alt.cyclist_name ; [Native-Transport-Requests-1] | 2016-11-22 16:45:02.212000 | 127.0.0.1 |            372 | 127.0.0.1
                                                                             Preparing statement [Native-Transport-Requests-1] | 2016-11-22 16:45:02.212000 | 127.0.0.1 |            541 | 127.0.0.1
                                                                       Computing ranges to query [Native-Transport-Requests-1] | 2016-11-22 16:45:02.213000 | 127.0.0.1 |            807 | 127.0.0.1
 Submitting range requests on 257 ranges with a concurrency of 257 (0.3 rows per range expected) [Native-Transport-Requests-1] | 2016-11-22 16:45:02.213000 | 127.0.0.1 |           1632 | 127.0.0.1
                                                           Submitted 1 concurrent range requests [Native-Transport-Requests-1] | 2016-11-22 16:45:02.215000 | 127.0.0.1 |           3002 | 127.0.0.1
                 Executing seq scan across 1 sstables for (min(-9223372036854775808), min(-9223372036854775808)] [ReadStage-2] | 2016-11-22 16:45:02.215000 | 127.0.0.1 |           3130 | 127.0.0.1
                                                                               Read 6 live and 0 tombstone cells [ReadStage-2] | 2016-11-22 16:45:02.216000 | 127.0.0.1 |           3928 | 127.0.0.1
                                                                                                              Request complete | 2016-11-22 16:45:02.216252 | 127.0.0.1 |           4252 | 127.0.0.1

Use tracing to test consistency level performance

In a distributed database, it can take time to propagate mutations to all replicas. Client applications cannot predict which node has the most recent data. Instead, client applications set consistency levels (CLs) for read and write requests to balance response time and data accuracy.

For example, consistency level ONE is fastest but the least accurate because it gets a response from only one replica, and doesn’t compare that replica to any other replica. In contrast, consistency level ALL is slowest but most accurate because it waits for a unified response from all replicas. Other consistency levels between ONE and ALL, such as QUORUM, provide a balance between response time and data accuracy. For more information, see Consistency levels.

You can use TRACING to monitor read performance at different consistency levels and determine which consistency level is best for your use case. TRACING records all activity related to a request, including the time taken for each step and the nodes involved.

The following example traces queries on a keyspace with a replication factor of 3 using different consistency levels. For Astra DB, triple replication is enabled by default and cannot be changed. In this example, read latency progressively degrades as the consistency level changes from ONE to QUORUM to ALL. This is the typical expectation for these consistency levels because each level requires more responses than the previous level. Your results will be unique to your environment, data model, cluster configuration, and network conditions.

To follow along with this example, create the following schema, and then insert some rows into the table:

CREATE KEYSPACE IF NOT EXISTS cycling_alt
  WITH REPLICATION = {
    'class': 'SimpleStrategy',
    'replication_factor': 3
  };

CREATE TABLE IF NOT EXISTS cycling_alt.cyclist_name (
  id int PRIMARY KEY,
  lastname text,
  firstname text
);

Enable tracing:
```
TRACING ON;
```
Use the CONSISTENCY command to verify that the consistency level is ONE, which is the default:
```
CONSISTENCY;
```
```
Current consistency level is ONE.
```
If the consistency level isn’t ONE, run CONSISTENCY ONE.

Query the table to read a row and trace read activity at consistency level ONE.

You must run the same query at each consistency level to compare the performance.

SELECT * FROM cycling_alt.cyclist_name WHERE id = 1;

The output includes the tracing details, including all the actions taken to complete the SELECT statement.

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

Change the consistency level to QUORUM:
```
CONSISTENCY QUORUM;
```
Run the same query that you used for ONE to trace read activity at QUORUM.

Consistency level of QUORUM waits for responses from a majority of the replicas. With a replication factor of 3, it waits for responses from two replicas. If QUORUM inadvertently selects a slow node as part of the quorum, it can take longer to process the request.
Change the consistency level to ALL:
```
CONSISTENCY ALL;
```
Run the same query to trace read activity at ALL.

Consistency level of ALL waits for responses from all replicas. A single slow node can delay the entire response significantly. In the absence of node outages or network issues, ALL is expected to be much slower than QUORUM in production databases where datasets are much larger and clusters might have more replicas.

ALL is typically reserved for situation where accuracy is much more important than speed, and users of such applications are likely conditioned to longer response times (if the difference in latency is even perceived by the user). ALL is also used when a write must be propagated to all replicas faster than eventual consistency and repairs would allow.
Compare the output of the three queries to understand how different consistency levels affect read performance and latency.

TRACING

Synopsis

Trace a write request

Trace a sequential scan

Use tracing to test consistency level performance

Was this helpful?

Give Feedback