apache cassandra 1.0.8 IncompatibleClassChangeError vtable stub and AssertionError Added column does not sort as the last column

Today we will spend sometime to look into two errors and see if it is really something to concern about. The erros are thrown when apache cassandra version 1.0.8 is running. Okay, let's to the first error.

ERROR [ReadStage:1559] 2012-10-16 20:38:25,336 AbstractCassandraDaemon.java (line 139) Fatal exception in thread Thread[ReadStage:1559,5,main]
java.lang.IncompatibleClassChangeError: vtable stub
        at org.apache.cassandra.db.AbstractColumnContainer.getColumn(AbstractColumnContainer.java:134)
        at org.apache.cassandra.db.Memtable$6.computeNext(Memtable.java:402)
        at org.apache.cassandra.db.Memtable$6.computeNext(Memtable.java:384)
        at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:140)
        at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:135)
        at org.apache.cassandra.db.CollationController.collectTimeOrderedData(CollationController.java:93)
        at org.apache.cassandra.db.CollationController.getTopLevelColumns(CollationController.java:62)
        at org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:1298)
        at org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1184)
        at org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1151)
        at org.apache.cassandra.db.Table.getRow(Table.java:375)
        at org.apache.cassandra.db.SliceByNamesReadCommand.getRow(SliceByNamesReadCommand.java:58)
        at org.apache.cassandra.service.StorageProxy$LocalReadRunnable.runMayThrow(StorageProxy.java:765)
        at org.apache.cassandra.service.StorageProxy$DroppableRunnable.run(StorageProxy.java:1224)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)

I guess this is really some fatal errors encountered. Let's check out what is IncompatibleClassChangeError means. From IncompatibleClassChangeError javadoc

Thrown when an incompatible class change has occurred to some class definition. The definition of some class, on which the currently executing method depends, has since changed.

Honestly, this is really odd, this error thrown out of no where and the jvm stopped. I guess nobody change the compiled apache cassandra code during the node instance is running. It certainly sounds odd but I guess when the data hold per node is huge, then strange thing start to happened. Now, let's get into stack trace and follow stack trace path.

Bottom three stack traces are pretty obvious, a new thread was started and execute by the thread pool executor. Then we have class StorageProxy. Within this class, there is a static class LocalReadRunnable which implement the abstract method LocalReadRunnable. It seem like it is trying to read a local node table row. The table eventually make calls to the column family to retrieve column. Tracing even deeper, at line 134 of class AbstractColumnContainer,  reveal that no exception is thrown from here. This is like a mystery! :) The stack trace analysis and observed jvm stopped shown something is wrong. Though I am not sure what went wrong but if you have any idea, please discuss it as a comment below.

Next we look to another error.

ERROR [CompactionExecutor:4] 2014-10-22 06:13:00,884 AbstractCassandraDaemon.java (line 139) Fatal exception in thread Thread[CompactionExecutor:4,1,main]
java.lang.AssertionError: Added column does not sort as the last column
        at org.apache.cassandra.db.ArrayBackedSortedColumns.addColumn(ArrayBackedSortedColumns.java:126)
        at org.apache.cassandra.db.AbstractColumnContainer.addColumn(AbstractColumnContainer.java:129)
        at org.apache.cassandra.db.AbstractColumnContainer.addColumn(AbstractColumnContainer.java:124)
        at org.apache.cassandra.db.ColumnFamilySerializer.deserializeColumns(ColumnFamilySerializer.java:148)
        at org.apache.cassandra.io.sstable.SSTableIdentityIterator.getColumnFamilyWithColumns(SSTableIdentityIterator.java:232)
        at org.apache.cassandra.db.compaction.PrecompactedRow.merge(PrecompactedRow.java:110)
        at org.apache.cassandra.db.compaction.PrecompactedRow.<init>(PrecompactedRow.java:97)
        at org.apache.cassandra.db.compaction.CompactionController.getCompactedRow(CompactionController.java:137)
        at org.apache.cassandra.db.compaction.CompactionIterable$Reducer.getReduced(CompactionIterable.java:102)
        at org.apache.cassandra.db.compaction.CompactionIterable$Reducer.getReduced(CompactionIterable.java:87)
        at org.apache.cassandra.utils.MergeIterator$ManyToOne.consume(MergeIterator.java:118)
        at org.apache.cassandra.utils.MergeIterator$ManyToOne.computeNext(MergeIterator.java:101)
        at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:140)
        at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:135)
        at com.google.common.collect.Iterators$7.computeNext(Iterators.java:614)
        at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:140)
        at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:135)
        at org.apache.cassandra.db.compaction.CompactionTask.execute(CompactionTask.java:173)
        at org.apache.cassandra.db.compaction.CompactionManager$1.call(CompactionManager.java:135)
        at org.apache.cassandra.db.compaction.CompactionManager$1.call(CompactionManager.java:115)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)

Again, this error pop out of nowhere, during node operation, this exception just thrown. So now, we will look into what happened using the stack trace given. Similar to the above, bottom three stack traces are pretty obvious, a new thread was started and execute by the thread pool executor. It is a compaction thread and when compacting sstable, things break. Then row get reduced and columns get deserialized. When columns are re-formation, it throw an exception as the column does not sort. This is another strange phenomenon. It should have been sort before anyway but it is not. The javdoc for this method addColumn

AddColumn throws an exception if the column added does not sort after the last column in the map. The reasoning is that this implementation can get slower if too much insertions are done in unsorted order and right now we only use it when *all* insertion (with this method) are done in sorted order. The assertion throwing is thus a protection against performance regression without knowing about (we can revisit that decision later if we have use cases where most insert are in sorted order but a few are not).

It seem that this is probably reproducible during development environment as a few are not.. I guess this is not as fatal as previous error. That's it for this analysis, please give your inputs or comments if you have workaround.

---

 

UPDATE:

It seem that the second error is fix in https://issues.apache.org/jira/browse/CASSANDRA-5856

Research into cassandra nodetool cfhistograms and interpret statistics

What is nodetool cfhistogram?

According to the official documentation definition: The nodetool cfhistograms command provides statistics about a table, including read/write latency, row size, column count, and number of SSTables.

If you noticed the picture output below, it is entirely different than the cfhistogram output in cassandra 2.0.6 . Apparently output of cfhistograms is simplified and improved! You can find more information about this improvement here. To get the existing way of output, give −−compact to the nodetool as a parameter.



Okay, let's start by issue command nodetool cfhistograms to our cluster.

jason@localhost:~$ nodetool -h localhost cfhistograms jw_schema1 users
jw_schema1/users histograms

SSTables per Read
1 sstables: 997

Write Latency (microseconds)
No Data

Read Latency (microseconds)
  103 us: 1
  124 us: 15
  149 us: 28
  179 us: 131
  215 us: 306
  258 us: 373
  310 us: 66
  372 us: 17
  446 us: 6
  535 us: 21
  642 us: 10
  770 us: 2
  924 us: 1
 1109 us: 3
 1331 us: 1
 1597 us: 1
 1916 us: 3
 2299 us: 0
 2759 us: 2
 3311 us: 1
 3973 us: 0
 4768 us: 0
 5722 us: 1
 6866 us: 0
 8239 us: 1
 9887 us: 4
11864 us: 1
14237 us: 1
17084 us: 1

Partition Size (bytes)
149 bytes: 3

Cell Count per Partition
5 cells: 3

The statistics is a bit difficult to understand if you do not know what does it mean. Let's begin by studying into the cfhistograms codes.

private void printCfHistograms(String keySpace, String columnFamily, PrintStream output, boolean compactFormat)
{
   ColumnFamilyStoreMBean store = this.probe.getCfsProxy(keySpace, columnFamily);

   // default is 90 offsets
   long[] offsets = new EstimatedHistogram().getBucketOffsets();

   long[] rrlh = store.getRecentReadLatencyHistogramMicros();
   long[] rwlh = store.getRecentWriteLatencyHistogramMicros();
   long[] sprh = store.getRecentSSTablesPerReadHistogram();
   long[] ersh = store.getEstimatedRowSizeHistogram();
   long[] ecch = store.getEstimatedColumnCountHistogram();

   output.println(String.format("%s/%s histograms", keySpace, columnFamily));
   output.println("");

   if (compactFormat)
   {
      output.println(String.format("%-10s%10s%18s%18s%18s%18s",
               "Offset", "SSTables", "Write Latency", "Read Latency", "Partition Size", "Cell Count"));
      output.println(String.format("%-10s%10s%18s%18s%18s%18s",
               "", "", "(micros)", "(micros)", "(bytes)", ""));

      for (int i = 0; i < offsets.length; i++)
      {
         output.println(String.format("%-10d%10s%18s%18s%18s%18s",
            offsets[i],
               (i < sprh.length ? sprh[i] : "0"),
               (i < rwlh.length ? rwlh[i] : "0"),
               (i < rrlh.length ? rrlh[i] : "0"),
               (i < ersh.length ? ersh[i] : "0"),
               (i < ecch.length ? ecch[i] : "0")));
      }
   }
   else
   {
       output.println("SSTables per Read");
       printHistogram(sprh, offsets, "sstables", output);

       output.println("Write Latency (microseconds)");
       printHistogram(rwlh, offsets, "us", output);

       output.println("Read Latency (microseconds)");
       printHistogram(rrlh, offsets, "us", output);

       output.println("Partition Size (bytes)");
       printHistogram(ersh, offsets, "bytes", output);

       output.println("Cell Count per Partition");
       printHistogram(ecch, offsets, "cells", output);
   }
}

Essentially a proxy ColumnFamilyStoreMBean is made through jmx ($ jconsole service:jmx:rmi:///jndi/rmi://192.168.0.2:7199/jmxrmi also see picture below) based on the previous keyspace and column family specified in the nodetool parameter. The default bucket offset will always be 90. Thus if you carefully analyzed the row output of the compact statistics, you will noticed exactly 90 rows each time nodetool cfhistogram command is triggered.



You would ask, why would 90 bucket offsets? Well according to the codes documentation:

The series of values to which the counts in `buckets` correspond:
1, 2, 3, 4, 5, 6, 7, 8, 10, 12, 14, 17, 20, etc.
Thus, a `buckets` of [0, 0, 1, 10] would mean we had seen one value of 3 and 10 values of 4.

The series starts at 1 and grows by 1.2 each time (rounding and removing duplicates). It goes from 1
to around 36M by default (creating 90+1 buckets), which will give us timing resolution from microseconds to
36 seconds, with less precision as the numbers get larger.

Each bucket represents values from (previous bucket offset, current offset].

Depending if parameter compact is specified, the output will be different. There are six metrics exposed. We will take a closer look.

• offset | the bucket offset

Bucket offset from 149 (exclusive) to 179 (inclusive). Essentially this bucket offset contain latency from 149 microseconds until 179 microseconds.

• SSTables | recent SSTables per read

With each read, total of sstables accessed accountable for. Note that for each nodetool cfhistograms trigger for this keyspace and column family, this metric will be reset.

This metric will increase if there is any call to CollationController.java or CacheService.java

• Write Latency (micros) | recent write latency histogram in microseconds.

An array representing the latency histogram for write in microseconds. Note that for each nodetool cfhistograms trigger for this keyspace and column family, this metric will be reset.

This metric will increase if there is any call to ColumnFamilyStore.java, StorageProxy.java or WeightedQueue.java .

• Read Latency (micros) | recent read latency histogram in Microseconds.

An array representing the latency histogram for read in microseconds. Note that for each nodetool cfhistograms trigger for this keyspace and column family, this metric will be reset.

• Partition Size (bytes ) | estimated row size histogram

As estimation of row size in bytes. Note that for each nodetool cfhistograms trigger for this keyspace and column family, this metric will NOT reset.

The metric is collected by iterating over the sstables, and get the estimated row size in bytes.

• Cell Count | estimated column count histogram

Estimated number of columns. Note that for each nodetool cfhistograms trigger for this keyspace and column family, this metric will NOT reset.

The metric is collected by iterating over the sstables, and get the estimated column count.

So with these interpretation from the codes, let's take another compact form cfhistogram to interpret the metrics. First, we will make start by make some statistics:

cqlsh:jw_schema1> select * from users where age > 5 and age < 50 and last = 'smith' allow filtering;

jason@localhost:~$ nodetool -h localhost cfhistograms jw_schema1 users  -c
jw_schema1/users histograms

Offset      SSTables     Write Latency      Read Latency    Partition Size        Cell Count
                              (micros)          (micros)           (bytes)
1                997                 0                 0                 0                 0
2                  0                 0                 0                 0                 0
3                  0                 0                 0                 0                 0
4                  0                 0                 0                 0                 0
5                  0                 0                 0                 0              1000
6                  0                 0                 0                 0                 0
7                  0                 0                 0                 0                 0
8                  0                 0                 0                 0                 0
10                 0                 0                 0                 0                 0
12                 0                 0                 0                 0                 0
14                 0                 0                 0                 0                 0
17                 0                 0                 0                 0                 0
20                 0                 0                 0                 0                 0
24                 0                 0                 0                 0                 0
29                 0                 0                 0                 0                 0
35                 0                 0                 0                 0                 0
42                 0                 0                 0                 0                 0
50                 0                 0                 0                 0                 0
60                 0                 0                 0                 0                 0
72                 0                 0                 0                 0                 0
86                 0                 0                 0                 0                 0
103                0                 0                 0                 0                 0
124                0                 0                 0                 0                 0
149                0                 0                 0               999                 0
179                0                 0                 0                 1                 0
215                0                 0                 0                 0                 0
258                0                 0                 0                 0                 0
310                0                 0                 0                 0                 0
372                0                 0                 0                 0                 0
446                0                 0                 0                 0                 0
535                0                 0                 0                 0                 0
642                0                 0                 0                 0                 0
770                0                 0                 0                 0                 0
924                0                 0                 0                 0                 0
1109               0                 0                 0                 0                 0
1331               0                 0                51                 0                 0
1597               0                 0               491                 0                 0
1916               0                 0                95                 0                 0
2299               0                 0                53                 0                 0
2759               0                 0                84                 0                 0
3311               0                 0                95                 0                 0
3973               0                 0                41                 0                 0
4768               0                 0                32                 0                 0
5722               0                 0                25                 0                 0
6866               0                 0                 9                 0                 0
8239               0                 0                 7                 0                 0
9887               0                 0                 6                 0                 0
11864              0                 0                 4                 0                 0
14237              0                 0                 0                 0                 0
17084              0                 0                 2                 0                 0
20501              0                 0                 0                 0                 0
24601              0                 0                 0                 0                 0
29521              0                 0                 0                 0                 0
35425              0                 0                 0                 0                 0
42510              0                 0                 1                 0                 0
51012              0                 0                 0                 0                 0
61214              0                 0                 0                 0                 0
73457              0                 0                 0                 0                 0
88148              0                 0                 0                 0                 0
105778             0                 0                 1                 0                 0
126934             0                 0                 0                 0                 0
152321             0                 0                 0                 0                 0
182785             0                 0                 0                 0                 0
219342             0                 0                 0                 0                 0
263210             0                 0                 0                 0                 0
315852             0                 0                 0                 0                 0
379022             0                 0                 0                 0                 0
454826             0                 0                 0                 0                 0
545791             0                 0                 0                 0                 0
654949             0                 0                 0                 0                 0
785939             0                 0                 0                 0                 0
943127             0                 0                 0                 0                 0
1131752            0                 0                 0                 0                 0
1358102            0                 0                 0                 0                 0
1629722            0                 0                 0                 0                 0
1955666            0                 0                 0                 0                 0
2346799            0                 0                 0                 0                 0
2816159            0                 0                 0                 0                 0
3379391            0                 0                 0                 0                 0
4055269            0                 0                 0                 0                 0
4866323            0                 0                 0                 0                 0
5839588            0                 0                 0                 0                 0
7007506            0                 0                 0                 0                 0
8409007            0                 0                 0                 0                 0
10090808           0                 0                 0                 0                 0
12108970           0                 0                 0                 0                 0
14530764           0                 0                 0                 0                 0
17436917           0                 0                 0                 0                 0
20924300           0                 0                 0                 0                 0
25109160           0                 0                 0                 0                 0

• There are 51 read requests spend time from 1109 microsecond to 1331 microsecond.


• 997 sstables were read and spent time 1 microsecond.


• Because this is a read operation, (cql select statement), there is no write latency involved.


• The mean size for 999 partition is 149 bytes and another one is 179 bytes.


• There are 1000 partition with 5 cells.

These metric is good for monitoring if you can poll periodically and plot them into graphs. Note that, those methods covered above, many had been deprecated in this cassandra version and probably in the coming cassandra, it will be removed and that they will have better way of depicting the metric. If you started on older cassandra version for example, pre-cassandra 1.1, the cell is correspond to column whilst partition is correspond to row.

Thank you.