Apache Cassandra 1.2 Documentation
TRACING¶
Enables or disables request tracing.
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)
);
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
Peparing 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.