Java Driver 1.0 for Apache Cassandra

Enabling tracing

To help you to understand how Cassandra functions when executing statements, you enable tracing.

Tracing is only enabled on a per-query basis. The sample client described here extends the SimpleClient class and then enables tracing on two queries: an INSERT of data and a SELECT that returns all the rows in a table.

Procedure

  1. Add a new class, TracingExample, to your simple-cassandra-client project. It should extend the SimpleClient class.
    package com.example.cassandra;
    
    public class TracingExample extends SimpleClient {
    }
    
  2. Add an instance method, traceInsert and implement it.
    1. Build an INSERT query and enable tracing on it.
            /* INSERT INTO simplex.songs
             *    (id, title, album, artist)
             *    VALUES (da7c6910-a6a4-11e2-96a9-4db56cdc5fe7,
             *            'Golden Brown', 'La Folie', 'The Stranglers'
             *    );
             */
            Query insert = QueryBuilder.insertInto("simplex", "songs")
                  .value("id", UUID.randomUUID())
                  .value("title", "Golden Brown")
                  .value("album", "La Folie")
                  .value("artist", "The Stranglers")
                  .setConsistencyLevel(ConsistencyLevel.ONE).enableTracing();
      
      The code illustrates using the QueryBuilder class and method chaining.
    2. Execute the INSERT query and retrieve the execution tracing information.
            ResultSet results = getSession().execute(insert);
            ExecutionInfo executionInfo = results.getExecutionInfo();
      
    3. Print out the information retrieved.
            System.out.printf( "Host (queried): %s\n", executionInfo.getQueriedHost().toString() );
            for (Host host : executionInfo.getTriedHosts()) {
               System.out.printf( "Host (tried): %s\n", host.toString() );
            }
            QueryTrace queryTrace = executionInfo.getQueryTrace();
            System.out.printf("Trace id: %s\n\n", queryTrace.getTraceId());
            System.out.println("---------------------------------------+--------------+------------+--------------");
            for (QueryTrace.Event event : queryTrace.getEvents()) {
               System.out.printf("%38s | %12s | %10s | %12s\n", event.getDescription(),
                     millis2Date(event.getTimestamp()), 
                     event.getSource(), event.getSourceElapsedMicros());
            }
      
      The code prints out information similar to that which cqlsh does when tracing has been enabled. The difference is that in cqlsh tracing is enabled and all subsequent queries prints out tracing information. In the Java driver, a session is basically stateless with respect to tracing which must be enabled on a per-query basis.
    4. Implement a private instance method to format the timestamp to be human-readable.
         private SimpleDateFormat format = new SimpleDateFormat("HH:mm:ss.SSS");
      
         private Object millis2Date(long timestamp) {
            return format.format(timestamp);
         }
      
  3. Add another instance method, traceSelect, and implement it.
       public void traceSelect() {
          Query scan = new SimpleStatement("SELECT * FROM simplex.songs;");
          ExecutionInfo executionInfo = getSession().execute(scan.enableTracing()).getExecutionInfo();
          System.out.printf( "Host (queried): %s\n", executionInfo.getQueriedHost().toString() );
          for (Host host : executionInfo.getTriedHosts()) {
             System.out.printf( "Host (tried): %s\n", host.toString() );
          }
          QueryTrace queryTrace = executionInfo.getQueryTrace();
          System.out.printf("Trace id: %s\n\n", queryTrace.getTraceId());
          System.out.printf("%-38s | %-12s | %-10s | %-12s\n", "activity", "timestamp", "source", "source_elapsed");
          System.out.println("---------------------------------------+--------------+------------+--------------");
          for (QueryTrace.Event event : queryTrace.getEvents()) {
             System.out.printf("%38s | %12s | %10s | %12s\n", event.getDescription(),
                   millis2Date(event.getTimestamp()), 
                   event.getSource(), event.getSourceElapsedMicros());
          }
          scan.disableTracing();
       }
    
    Instead of using QueryBuilder, this code uses SimpleStatement.
  4. Add a class method main and implement it.
       public static void main(String[] args) {
          TracingExample client = new TracingExample();
          client.connect("127.0.0.1");
          client.createSchema();
          client.traceInsert();
          client.traceSelect();
          client.resetSchema();
          client.close();
       }
    

Code listing

Complete code listing which illustrates:
  • Enabling tracing on:
    • INSERT
    • SELECT
  • Retrieving execution information and printing it out.
package com.example.cassandra;

import java.text.SimpleDateFormat;
import java.util.UUID;

import com.datastax.driver.core.ConsistencyLevel;
import com.datastax.driver.core.ExecutionInfo;
import com.datastax.driver.core.Host;
import com.datastax.driver.core.Query;
import com.datastax.driver.core.QueryTrace;
import com.datastax.driver.core.ResultSet;
import com.datastax.driver.core.SimpleStatement;
import com.datastax.driver.core.querybuilder.QueryBuilder;

public class TracingExample extends SimpleClient {
   private SimpleDateFormat format = new SimpleDateFormat("HH:mm:ss.SSS");
   
   public TracingExample() {
   }
   
   public void traceInsert() {
         /* INSERT INTO simplex.songs
          *    (id, title, album, artist)
          *    VALUES (da7c6910-a6a4-11e2-96a9-4db56cdc5fe7,
          *            'Golden Brown', 'La Folie', 'The Stranglers'
          *    );
          */
      Query insert = QueryBuilder.insertInto("simplex", "songs")
            .value("id", UUID.randomUUID())
            .value("title", "Golden Brown")
            .value("album", "La Folie")
            .value("artist", "The Stranglers")
            .setConsistencyLevel(ConsistencyLevel.ONE).enableTracing();
      // 
      ResultSet results = getSession().execute(insert);
      ExecutionInfo executionInfo = results.getExecutionInfo();
      System.out.printf( "Host (queried): %s\n", executionInfo.getQueriedHost().toString() );
      for (Host host : executionInfo.getTriedHosts()) {
         System.out.printf( "Host (tried): %s\n", host.toString() );
      }
      QueryTrace queryTrace = executionInfo.getQueryTrace();
      System.out.printf("Trace id: %s\n\n", queryTrace.getTraceId());
      System.out.printf("%-38s | %-12s | %-10s | %-12s\n", "activity", "timestamp", "source", "source_elapsed");
      System.out.println("---------------------------------------+--------------+------------+--------------");
      for (QueryTrace.Event event : queryTrace.getEvents()) {
         System.out.printf("%38s | %12s | %10s | %12s\n", event.getDescription(),
               millis2Date(event.getTimestamp()), 
               event.getSource(), event.getSourceElapsedMicros());
      }
      insert.disableTracing();
   }
   
   public void traceSelect() {
      Query scan = new SimpleStatement("SELECT * FROM simplex.songs;");
      ExecutionInfo executionInfo = getSession().execute(scan.enableTracing()).getExecutionInfo();
      System.out.printf( "Host (queried): %s\n", executionInfo.getQueriedHost().toString() );
      for (Host host : executionInfo.getTriedHosts()) {
         System.out.printf( "Host (tried): %s\n", host.toString() );
      }
      QueryTrace queryTrace = executionInfo.getQueryTrace();
      System.out.printf("Trace id: %s\n\n", queryTrace.getTraceId());
      System.out.printf("%-38s | %-12s | %-10s | %-12s\n", "activity", "timestamp", "source", "source_elapsed");
      System.out.println("---------------------------------------+--------------+------------+--------------");
      for (QueryTrace.Event event : queryTrace.getEvents()) {
         System.out.printf("%38s | %12s | %10s | %12s\n", event.getDescription(),
               millis2Date(event.getTimestamp()), 
               event.getSource(), event.getSourceElapsedMicros());
      }
      scan.disableTracing();
   }

   private Object millis2Date(long timestamp) {
      return format.format(timestamp);
   }

   public static void main(String[] args) {
      TracingExample client = new TracingExample();
      client.connect("127.0.0.1");
      client.createSchema();
      client.traceInsert();
      client.traceSelect();
      client.close();
   }
}

Output:

Connected to cluster: xerxes
Simplex keyspace and schema created.
Host (queried): /127.0.0.1
Host (tried): /127.0.0.1
Trace id: 96ac9400-a3a5-11e2-96a9-4db56cdc5fe7

activity                               | timestamp    | source     | source_elapsed
---------------------------------------+--------------+------------+--------------
                     Parsing statement | 12:17:16.736 | /127.0.0.1 |           28
                    Peparing statement | 12:17:16.736 | /127.0.0.1 |          199
     Determining replicas for mutation | 12:17:16.736 | /127.0.0.1 |          348
         Sending message to /127.0.0.3 | 12:17:16.736 | /127.0.0.1 |          788
         Sending message to /127.0.0.2 | 12:17:16.736 | /127.0.0.1 |          805
        Acquiring switchLock read lock | 12:17:16.736 | /127.0.0.1 |          828
                Appending to commitlog | 12:17:16.736 | /127.0.0.1 |          848
              Adding to songs memtable | 12:17:16.736 | /127.0.0.1 |          900
      Message received from /127.0.0.1 | 12:17:16.737 | /127.0.0.2 |           34
      Message received from /127.0.0.1 | 12:17:16.737 | /127.0.0.3 |           25
        Acquiring switchLock read lock | 12:17:16.737 | /127.0.0.2 |          672
        Acquiring switchLock read lock | 12:17:16.737 | /127.0.0.3 |          525
                Appending to commitlog | 12:17:16.737 | /127.0.0.2 |          692
                Appending to commitlog | 12:17:16.737 | /127.0.0.3 |          541
              Adding to songs memtable | 12:17:16.737 | /127.0.0.2 |          741
              Adding to songs memtable | 12:17:16.737 | /127.0.0.3 |          583
      Enqueuing response to /127.0.0.1 | 12:17:16.737 | /127.0.0.3 |          751
      Enqueuing response to /127.0.0.1 | 12:17:16.738 | /127.0.0.2 |          950
      Message received from /127.0.0.3 | 12:17:16.738 | /127.0.0.1 |          178
         Sending message to /127.0.0.1 | 12:17:16.738 | /127.0.0.2 |         1189
      Message received from /127.0.0.2 | 12:17:16.738 | /127.0.0.1 |          249
   Processing response from /127.0.0.3 | 12:17:16.738 | /127.0.0.1 |          345
   Processing response from /127.0.0.2 | 12:17:16.738 | /127.0.0.1 |          377
   
   
Connected to cluster: xerxes
Host (queried): /127.0.0.3
Host (tried): /127.0.0.3
Trace id: da7c6910-a6a4-11e2-96a9-4db56cdc5fe7

activity                               | timestamp    | source     | source_elapsed
---------------------------------------+--------------+------------+--------------
                     Parsing statement | 12:49:34.497 | /127.0.0.3 |           35
                    Peparing statement | 12:49:34.497 | /127.0.0.3 |          191
         Determining replicas to query | 12:49:34.497 | /127.0.0.3 |          342
         Sending message to /127.0.0.2 | 12:49:34.498 | /127.0.0.3 |         1561
      Message received from /127.0.0.3 | 12:49:34.499 | /127.0.0.2 |           37
      Message received from /127.0.0.2 | 12:49:34.499 | /127.0.0.3 |         2880
Executing seq scan across 0 sstables
  for [min(-9223372036854775808),
  min(-9223372036854775808)]           | 12:49:34.499 | /127.0.0.2 |          580
          Scanned 0 rows and matched 0 | 12:49:34.499 | /127.0.0.2 |          648
      Enqueuing response to /127.0.0.3 | 12:49:34.499 | /127.0.0.2 |          670
         Sending message to /127.0.0.3 | 12:49:34.499 | /127.0.0.2 |          767
   Processing response from /127.0.0.2 | 12:49:34.500 | /127.0.0.3 |         3237