CQL for Cassandra 1.2

TRACING

Enables or disables request tracing.

Synopsis

 TRACING ( ON | OFF )

Synopsis Legend

  • Uppercase means literal
  • Lowercase means not literal
  • Italics mean optional
  • The pipe (|) symbol means OR or AND/OR
  • Ellipsis (...) means repeatable
  • Orange ( and ) means not literal, indicates scope

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.

Show/hide