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 Cassandra internal operations and troubleshoot performance problems.
For 24 hours, Cassandra saves the tracing information in the tables, which are in the system_traces keyspace:
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.
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 Creating a table, the tracing shows:
- The coordinator 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 | 11139
Tracing 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;
Output is:
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 | jones
The 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 | 159525
The 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.
For examples of tracing indexed queries and diagnosing performance problems using tracing, see Request tracing in Cassandra 1.2.