TRACING
Enables or disables request tracing.
Enables or disables request tracing.
Synopsis
TRACING ON | OFF
A semicolon that terminates CQL statements is not included in the synopsis. |
Description
To turn tracing read/write requests on or off, use the TRACING command. After turning on tracing, database activity creates output that can help you understand Apache Cassandra™ internal operations and troubleshoot performance problems. For example, using the tracing tutorial you can see how different consistency levels affect operations. Some tracing messages refer to internals of the database that users cannot understand, but can provide to the Cassandra team for troubleshooting.
For 24 hours, Cassandra saves the tracing information in sessions and events tables in the system_traces keyspace, which you query when using probabilistic tracing. For information about probabilistic tracing, see Cassandra 2.1 documentation or Cassandra 2.0 documentation.
$ CREATE TABLE sessions (
session_id uuid PRIMARY KEY,
coordinator inet,
duration int,
parameters map<text, text>,
request text,
started_at timestamp
);
CREATE TABLE events (
session_id uuid,
event_id timeuuid,
activity text,
source inet,
source_elapsed int,
thread text,
PRIMARY KEY (session_id, event_id)
);The source_elapsed column stores the elapsed time in microseconds before the event occurred on the source node.
To keep tracing information, copy the data in sessions and event tables to another location. Alternatively, use the tracing session id to retrieve session information using SHOW SESSION. Tracing session information expires after one day.
Tracing a write request
This example shows tracing activity on a 3-node cluster created by ccm on Mac OSX. Using a keyspace that has a replication factor of 3 and an employee table similar to the one in "Using a compound primary key," the tracing shows that the coordinator performs the following actions:
- Identifies the target nodes for replication of the row.
- Writes the row to the commitlog and memtable.
- Confirms completion of the request.
TRACING ON
INSERT INTO emp (empID, deptID, first_name, last_name)
VALUES (104, 15, 'jane', 'smith');Cassandra provides a description of each step it takes to satisfy the request, the names of nodes that are affected, the time for each step, and the total time for the request.
Tracing session: 740b9c10-3506-11e2-0000-fe8ebeead9ff
activity | timestamp | source | source_elapsed
-------------------------------------+--------------+-----------+----------------
execute_cql3_query | 16:41:00,754 | 127.0.0.1 | 0
Parsing statement | 16:41:00,754 | 127.0.0.1 | 48
Preparing statement | 16:41:00,755 | 127.0.0.1 | 658
Determining replicas for mutation | 16:41:00,755 | 127.0.0.1 | 979
Message received from /127.0.0.1 | 16:41:00,756 | 127.0.0.3 | 37
Acquiring switchLock read lock | 16:41:00,756 | 127.0.0.1 | 1848
Sending message to /127.0.0.3 | 16:41:00,756 | 127.0.0.1 | 1853
Appending to commitlog | 16:41:00,756 | 127.0.0.1 | 1891
Sending message to /127.0.0.2 | 16:41:00,756 | 127.0.0.1 | 1911
Adding to emp memtable | 16:41:00,756 | 127.0.0.1 | 1997
Acquiring switchLock read lock | 16:41:00,757 | 127.0.0.3 | 395
Message received from /127.0.0.1 | 16:41:00,757 | 127.0.0.2 | 42
Appending to commitlog | 16:41:00,757 | 127.0.0.3 | 432
Acquiring switchLock read lock | 16:41:00,757 | 127.0.0.2 | 168
Adding to emp memtable | 16:41:00,757 | 127.0.0.3 | 522
Appending to commitlog | 16:41:00,757 | 127.0.0.2 | 211
Adding to emp memtable | 16:41:00,757 | 127.0.0.2 | 359
Enqueuing response to /127.0.0.1 | 16:41:00,758 | 127.0.0.3 | 1282
Enqueuing response to /127.0.0.1 | 16:41:00,758 | 127.0.0.2 | 1024
Sending message to /127.0.0.1 | 16:41:00,758 | 127.0.0.3 | 1469
Sending message to /127.0.0.1 | 16:41:00,758 | 127.0.0.2 | 1179
Message received from /127.0.0.2 | 16:41:00,765 | 127.0.0.1 | 10966
Message received from /127.0.0.3 | 16:41:00,765 | 127.0.0.1 | 10966
Processing response from /127.0.0.2 | 16:41:00,765 | 127.0.0.1 | 11063
Processing response from /127.0.0.3 | 16:41:00,765 | 127.0.0.1 | 11066
Request complete | 16:41:00,765 | 127.0.0.1 | 11139Tracing a sequential scan
Due to the log structured design of Cassandra, a single row is spread across multiple SSTables. Reading one row involves reading pieces from multiple SSTables, as shown by this trace of a request to read the employee table, which was pre-loaded with 10 rows of data.
SELECT * FROM emp;
empid | deptid | first_name | last_name
-------+--------+------------+-----------
110 | 16 | naoko | murai
105 | 15 | john | smith
111 | 15 | jane | thath
113 | 15 | lisa | amato
112 | 20 | mike | burns
107 | 15 | sukhit | ran
108 | 16 | tom | brown
109 | 18 | ann | green
104 | 15 | jane | smith
106 | 15 | bob | jonesThe tracing output of this read request looks something like this (a few rows have been truncated to fit on this page):
Tracing session: bf5163e0-350f-11e2-0000-fe8ebeead9ff
activity | timestamp | source | source_elapsed
-------------------------------------------------+--------------+-----------+----------------
execute_cql3_query | 17:47:32,511 | 127.0.0.1 | 0
Parsing statement | 17:47:32,511 | 127.0.0.1 | 47
Preparing statement | 17:47:32,511 | 127.0.0.1 | 249
Determining replicas to query | 17:47:32,511 | 127.0.0.1 | 383
Sending message to /127.0.0.2 | 17:47:32,512 | 127.0.0.1 | 883
Message received from /127.0.0.1 | 17:47:32,512 | 127.0.0.2 | 33
Executing seq scan across 0 sstables for . . . | 17:47:32,513 | 127.0.0.2 | 670
Read 1 live cells and 0 tombstoned | 17:47:32,513 | 127.0.0.2 | 964
Read 1 live cells and 0 tombstoned | 17:47:32,514 | 127.0.0.2 | 1268
Read 1 live cells and 0 tombstoned | 17:47:32,514 | 127.0.0.2 | 1502
Read 1 live cells and 0 tombstoned | 17:47:32,514 | 127.0.0.2 | 1673
Scanned 4 rows and matched 4 | 17:47:32,514 | 127.0.0.2 | 1721
Enqueuing response to /127.0.0.1 | 17:47:32,514 | 127.0.0.2 | 1742
Sending message to /127.0.0.1 | 17:47:32,514 | 127.0.0.2 | 1852
Message received from /127.0.0.2 | 17:47:32,515 | 127.0.0.1 | 3776
Processing response from /127.0.0.2 | 17:47:32,515 | 127.0.0.1 | 3900
Sending message to /127.0.0.2 | 17:47:32,665 | 127.0.0.1 | 153535
Message received from /127.0.0.1 | 17:47:32,665 | 127.0.0.2 | 44
Executing seq scan across 0 sstables for . . . | 17:47:32,666 | 127.0.0.2 | 1068
Read 1 live cells and 0 tombstoned | 17:47:32,667 | 127.0.0.2 | 1454
Read 1 live cells and 0 tombstoned | 17:47:32,667 | 127.0.0.2 | 1640
Scanned 2 rows and matched 2 | 17:47:32,667 | 127.0.0.2 | 1694
Enqueuing response to /127.0.0.1 | 17:47:32,667 | 127.0.0.2 | 1722
Sending message to /127.0.0.1 | 17:47:32,667 | 127.0.0.2 | 1825
Message received from /127.0.0.2 | 17:47:32,668 | 127.0.0.1 | 156454
Processing response from /127.0.0.2 | 17:47:32,668 | 127.0.0.1 | 156610
Executing seq scan across 0 sstables for . . . | 17:47:32,669 | 127.0.0.1 | 157387
Read 1 live cells and 0 tombstoned | 17:47:32,669 | 127.0.0.1 | 157729
Read 1 live cells and 0 tombstoned | 17:47:32,669 | 127.0.0.1 | 157904
Read 1 live cells and 0 tombstoned | 17:47:32,669 | 127.0.0.1 | 158054
Read 1 live cells and 0 tombstoned | 17:47:32,669 | 127.0.0.1 | 158217
Scanned 4 rows and matched 4 | 17:47:32,669 | 127.0.0.1 | 158270
Request complete | 17:47:32,670 | 127.0.0.1 | 159525The sequential scan across the cluster shows:
- The first scan found 4 rows on node 2.
- The second scan found 2 more rows found on node 2.
- The third scan found the 4 rows on node 1.