Understand cassandra write path by tracing in CQL

In this article, we will learn the write path for cassandra 2.0.7. Since cql is the way moving forward, we will start learning write path by focusing on cqlsh. Let's turn on the tracing, consistency to all and insert one row of data. Read output below:

cqlsh:jw_schema1> tracing on;
Now tracing requests.
cqlsh:jw_schema1> consistency all;
Consistency level set to ALL.

cqlsh:jw_schema1> insert into users (user_id, age, first, last, middle) values ('1', 10, 'john30003', 'smith', 'junior');

Tracing session: 03477650-d43f-11e3-bd26-a322c40b8b81

 activity                                                                                                        | timestamp    | source        | source_elapsed
-----------------------------------------------------------------------------------------------------------------+--------------+---------------+----------------
                                                                                              execute_cql3_query | 18:21:25,430 |  <node1_ip> |              0
                                                                             Message received from /<node1_ip>   | 18:21:23,795 |  <node2_ip> |             52
                                                                                  Acquiring switchLock read lock | 18:21:23,795 |  <node2_ip> |            455
                                                                                          Appending to commitlog | 18:21:23,795 |  <node2_ip> |            497
                                                                                        Adding to users memtable | 18:21:23,795 |  <node2_ip> |            613
                                                                             Enqueuing response to /<node1_ip>   | 18:21:23,800 |  <node2_ip> |           5520
                                                                                Sending message to /<node1_ip>   | 18:21:23,801 |  <node2_ip> |           6359
                                                                             Message received from /<node1_ip>   | 18:21:25,121 |  <node3_ip> |             84
                                                                                  Acquiring switchLock read lock | 18:21:25,123 |  <node3_ip> |           1777
                                                                                          Appending to commitlog | 18:21:25,123 |  <node3_ip> |           1826
                                                                                        Adding to users memtable | 18:21:25,123 |  <node3_ip> |           2121
                                                                             Enqueuing response to /<node1_ip>   | 18:21:25,129 |  <node3_ip> |           8278
                                                                                Sending message to /<node1_ip>   | 18:21:25,129 |  <node3_ip> |           8563
 Parsing insert into users (user_id, age, first, last, middle) values ('1', 10, 'john30003', 'smith', 'junior'); | 18:21:25,430 |  <node1_ip> |             93
                                                                                             Preparing statement | 18:21:25,430 |  <node1_ip> |            227
                                                                               Determining replicas for mutation | 18:21:25,433 |  <node1_ip> |           2721
                                                                                Sending message to /<node2_ip>   | 18:21:25,433 |  <node1_ip> |           3525
                                                                               Sending message to /<node3_ip>    | 18:21:25,434 |  <node1_ip> |           3751
                                                                                  Acquiring switchLock read lock | 18:21:25,434 |  <node1_ip> |           3963
                                                                                          Appending to commitlog | 18:21:25,434 |  <node1_ip> |           3992
                                                                                        Adding to users memtable | 18:21:25,434 |  <node1_ip> |           4067
                                                                            Message received from /<node3_ip>    | 18:21:25,730 |  <node1_ip> |         300016
                                                                         Processing response from /<node3_ip>    | 18:21:25,730 |  <node1_ip> |         300178
                                                                             Message received from /<node2_ip>   | 18:21:25,738 |  <node1_ip> |         308225
                                                                          Processing response from /<node2_ip>   | 18:21:25,738 |  <node1_ip> |         308676
                                                                                                Request complete | 18:21:25,738 |  <node1_ip> |         308825

TRACE [Thrift:186] 2014-05-05 18:24:33,825 QueryProcessor.java (line 153) Process org.apache.cassandra.cql3.statements.UpdateStatement@17d2390 @CL.ALL
DEBUG [Thrift:186] 2014-05-05 18:24:34,621 CassandraServer.java (line 1955) execute_cql3_query
TRACE [Thrift:186] 2014-05-05 18:24:34,622 QueryProcessor.java (line 153) Process org.apache.cassandra.cql3.statements.SelectStatement@159d495 @CL.ONE
DEBUG [Thrift:186] 2014-05-05 18:24:34,623 Tracing.java (line 159) request complete
DEBUG [Thrift:186] 2014-05-05 18:24:34,626 CassandraServer.java (line 1955) execute_cql3_query
TRACE [Thrift:186] 2014-05-05 18:24:34,626 QueryProcessor.java (line 153) Process org.apache.cassandra.cql3.statements.SelectStatement@75219b @CL.ONE
DEBUG [Thrift:186] 2014-05-05 18:24:34,629 Tracing.java (line 159) request complete

If you noticed, the entry path will be execute_cql3_query no matter write or read. If you trace the code down, it will be too much to even start the discussion. I summarize the points below in tandem with the output of cqlsh tracing and system.log where applicable. Thus it may not be complete but I will give you the link to the code as narration goes so that you can study yourself in detail.

It started at CassandraServer.execute_cql3_query(...)  as indicated in cqlsh tracing output. So basically the work done can be summarize by this line:

cState.getCQLQueryHandler().process(queryString, cState.getQueryState(), new QueryOptions(ThriftConversion.fromThrift(cLevel), Collections.<ByteBuffer>emptyList())).toThriftResult();

If you step into the line above, QueryProcessor.process(...) which implement the interface QueryHandler which get a valid CQLStatement. The execution continue by calling method QueryProcessor.processStatement(...). Notice that the logger in this method is shown in cassandra system.log (of cause you need to enable tracing for this class in log4j.properties in order for this line to log successfully). So access checking and validation are perform here. When checking and validation were done, then CQLStatement.execute(...) is executed. Because we are adding a new row by inserting a new row of data, the correspond class that implement interface CQLStatement is ModificationStatement.  Extract from ModificationStatement.execute(...)

public ResultMessage execute(QueryState queryState, QueryOptions options)
throws RequestExecutionException, RequestValidationException
{
    if (options.getConsistency() == null)
        throw new InvalidRequestException("Invalid empty consistency level");

    if (hasConditions() && options.getProtocolVersion() == 1)
        throw new InvalidRequestException("Conditional updates are not supported by the protocol version in use. You need to upgrade to a driver using the native protocol v2.");

    return hasConditions()
         ? executeWithCondition(queryState, options)
         : executeWithoutCondition(queryState, options);
}

The execution continue to the method ModificationStatement.executeWithoutCondition(...)  as our insert statement does not contain if not exists. Method getMutations(...) return a collection of mutations to be perform.

The collections of mutation is pass to StorageProxy.mutateWithTriggers(...) for further processing. This column family does not have trigger, so the execution continue to method StorageProxy.mutate() . The description of this method is informative, it write:

Use this method to have these Mutations applied across all replicas. This method will take care of the possibility of a replica being down and hint the data across to some other replica.

So this method basically does saving of data by applying to all replicas. If you trace along this path, you should notice the cqlsh tracing debug output appear along the way.

That's it for this article, for my next article, we will trace for cassandra read path. Thank you.