Here is my chronology: - I turned on my current cluster in early December, starting with about 0.7 RC2 or thereabouts. I ran into a number of problems but was able to get things more or less ironed out (upgrading to new versions pretty quickly). Once 0.7.0 was released, I had no problems for about 2 weeks. In that time (using 0.7.0), I ran frequent compactions but never a repair (not really needed with my workload: read repair works fine and I use expiring columns)
- Sometime mid-January (~21) I hit my first instance of sstable corruption. I was able to fix things by deleting EVERYTHING related to the problematic CF on the problematic node (sstables, hints column family, saved caches, the works). I then ran a repair which failed (http://www.mail-archive.com/user@cassandra.apache.org/msg09154.html) possibly due to CASSANDRA-1992 or some such. I was able to delete sstables, run cleanup and compaction, truncate unimportant CFs and get my service operating again - A week or two ago I created a new CF which turned out to be the most problematic in terms of SSTable corruption. Since creating this CF via CLI (again, all nodes running 0.7.0), there have been no repairs run and no ring changes (moving, bootstrapping or decommissioning). Unless I misunderstand CASSANDRA-1992, I don't think it is related. I have been seeing steadily increasing rates of Cassandra exceptions on multiple CFs, reads failing, compaction failing, hinted handoff failing, inability to export sstables2json, etc. Now I cant even understand how any of the RC bugs I hit back in the day are still around given I was running 0.7.0 for weeks and ran multiple full compactions without issue. Regardless, they could not have affected then new CF. I have seen no improvement for the one node I put on the 0.7 branch (r 1069600). I am seeing the same behaviour for multiple failed compactions (as per the bug I filed: https://issues.apache.org/jira/browse/CASSANDRA-2084) and am still investigating the read exceptions. Jonathan suggested a completely clean 0.7.1 install which would be a lot of work given I would have to migrate data at an application level but I would be willing to do so if I had any confidence it would help. Here is an example of one SSTable on the node running 0.7. Notice that a bunch of seemingly fine sstables (no problems reading from it that I could determine but my tests were not rigorous and this happened overnight), which had to either be created or compacted at least once (given -f-) on 0.7 (with, for example, the CASSANDRA-1992 and CASSANDRA-1999 fixes) gets compacted to a new SSTable that is completely f'ed. INFO [CompactionExecutor:1] 2011-02-10 20:25:42,200 CompactionManager.java (line 373) Compacting [org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data /kikmetrics/ProcessingBuckets-f-4311-Data.db'),org.apache.cassandra.io.sstab le.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/ProcessingBuckets- f-4312-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/li b/cassandra/data/kikmetrics/ProcessingBuckets-f-4313-Data.db'),org.apache.ca ssandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/Pr ocessingBuckets-f-4314-Data.db')] ... INFO [CompactionExecutor:1] 2011-02-10 20:25:49,908 CompactionIterator.java (line 135) Compacting large row 555345525f4556454e547c5345434f4e445f3130 (393599737 bytes) incrementally ... INFO [CompactionExecutor:1] 2011-02-10 20:26:42,989 CompactionManager.java (line 458) Compacted to /var/lib/cassandra/data/kikmetrics/ProcessingBuckets-tmp-f-4315-Data.db. 487,085,029 to 477,567,892 (~98% of original) bytes for 12 keys. Time: 60,788ms. ... ... this sstable does not appear in the logs unitll: ... INFO [CompactionExecutor:1] 2011-02-10 22:51:30,613 CompactionManager.java (line 373) Compacting [org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data /kikmetrics/ProcessingBuckets-e-4295-Data.db'),org.apache.cassandra.io.sstab le.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/ProcessingBuckets- f-4315-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/li b/cassandra/data/kikmetrics/ProcessingBuckets-f-4320-Data.db'),org.apache.ca ssandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/Pr ocessingBuckets-f-4327-Data.db')] ... ... Note the 'File :' output is a minor change I made (obviously) ... ERROR [CompactionExecutor:1] 2011-02-10 22:51:49,029 AbstractCassandraDaemon.java (line 114) Fatal exception in thread Thread[CompactionExecutor:1,1,main] java.io.IOError: java.io.IOException: File :/var/lib/cassandra/data/kikmetrics/ProcessingBuckets-f-4315-Data.db at org.apache.cassandra.io.sstable.SSTableIdentityIterator.<init>(SSTableIdenti tyIterator.java:85) at org.apache.cassandra.io.sstable.SSTableScanner$KeyScanningIterator.next(SSTa bleScanner.java:179) at org.apache.cassandra.io.sstable.SSTableScanner$KeyScanningIterator.next(SSTa bleScanner.java:144) at org.apache.cassandra.io.sstable.SSTableScanner.next(SSTableScanner.java:136) at org.apache.cassandra.io.sstable.SSTableScanner.next(SSTableScanner.java:39) at org.apache.commons.collections.iterators.CollatingIterator.set(CollatingIter ator.java:284) at org.apache.commons.collections.iterators.CollatingIterator.least(CollatingIt erator.java:326) at org.apache.commons.collections.iterators.CollatingIterator.next(CollatingIte rator.java:230) at org.apache.cassandra.utils.ReducingIterator.computeNext(ReducingIterator.jav a:68) at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator .java:136) at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:131 ) at org.apache.commons.collections.iterators.FilterIterator.setNextObject(Filter Iterator.java:183) at org.apache.commons.collections.iterators.FilterIterator.hasNext(FilterIterat or.java:94) at org.apache.cassandra.db.CompactionManager.doCompaction(CompactionManager.jav a:427) at org.apache.cassandra.db.CompactionManager$1.call(CompactionManager.java:123) at org.apache.cassandra.db.CompactionManager$1.call(CompactionManager.java:93) 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.ja va:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9 08) at java.lang.Thread.run(Thread.java:662) Caused by: java.io.IOException: File :/var/lib/cassandra/data/kikmetrics/ProcessingBuckets-f-4315-Data.db ... 21 more Caused by: java.io.EOFException: attempted to skip 67113066 bytes but only skipped 27852647 at org.apache.cassandra.io.sstable.IndexHelper.skipBloomFilter(IndexHelper.java :51) at org.apache.cassandra.io.sstable.SSTableIdentityIterator.<init>(SSTableIdenti tyIterator.java:69) ... 20 more INFO [CompactionExecutor:1] 2011-02-10 22:51:49,030 CompactionManager.java (line 373) Compacting [org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data /kikmetrics/ProcessingBuckets-e-4295-Data.db'),org.apache.cassandra.io.sstab le.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/ProcessingBuckets- f-4315-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/li b/cassandra/data/kikmetrics/ProcessingBuckets-f-4320-Data.db'),org.apache.ca ssandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/kikmetrics/Pr ocessingBuckets-f-4327-Data.db')] ... etc ... Now when trying to export ProcessingBuckets-f-4315-Data.db using sstable2json, I get the following: Exception in thread "main" java.io.IOError: java.io.EOFException at org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSortedMap. java:246) at org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:262) at org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:223) at java.util.concurrent.ConcurrentSkipListMap.buildFromSorted(ConcurrentSkipLis tMap.java:1493) at java.util.concurrent.ConcurrentSkipListMap.<init>(ConcurrentSkipListMap.java :1443) at org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:3 66) at org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:3 14) at org.apache.cassandra.db.columniterator.IndexedSliceReader$IndexedBlockFetche r.getNextBlock(IndexedSliceReader.java:181) at org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(Indexe dSliceReader.java:120) at org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(Indexe dSliceReader.java:48) at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator .java:136) at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:131 ) at org.apache.cassandra.db.columniterator.SSTableSliceIterator.hasNext(SSTableS liceIterator.java:108) at org.apache.cassandra.tools.SSTableExport.serializeRow(SSTableExport.java:178 ) at org.apache.cassandra.tools.SSTableExport.export(SSTableExport.java:353) at org.apache.cassandra.tools.SSTableExport.export(SSTableExport.java:375) at org.apache.cassandra.tools.SSTableExport.export(SSTableExport.java:388) at org.apache.cassandra.tools.SSTableExport.main(SSTableExport.java:446) Caused by: java.io.EOFException at java.io.RandomAccessFile.readByte(RandomAccessFile.java:591) at org.apache.cassandra.utils.ByteBufferUtil.readShortLength(ByteBufferUtil.jav a:287) at org.apache.cassandra.utils.ByteBufferUtil.readWithShortLength(ByteBufferUtil .java:298) at org.apache.cassandra.db.ColumnSerializer.deserialize(ColumnSerializer.java:6 6) at org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSortedMap. java:242) ... 17 more :( Dan From: Aaron Morton [mailto:aa...@thelastpickle.com] Sent: February-10-11 20:16 To: dev@cassandra.apache.org Subject: Re: RE: SEVERE Data Corruption Problems Looks like the bloom filter for the row is corrupted, does it happen for all reads or just for reads on one row ? After the upgrade to 0.7 (assuming an 0.7 nightly build) did you run anything like nodetool repair ? Have you tried asking on the #cassandra IRC room to see if their are any comitters around ? Aaron On 11 Feb, 2011,at 01:18 PM, Dan Hendry <dan.hendry.j...@gmail.com> wrote: Upgraded one node to 0.7. Its logging exceptions like mad (thousands per minute). All like below (which is fairly new to me): ERROR [ReadStage:721] 2011-02-10 18:13:56,190 AbstractCassandraDaemon.java (line 114) Fatal exception in thread Threa d[ReadStage:721,5,main] java.io.IOError: java.io.EOFException at org.apache.cassandra.db.columniterator.SSTableNamesIterator.<init>(SSTableNa mesIterator.java:75) at org.apache.cassandra.db.filter.NamesQueryFilter.getSSTableColumnIterator(Nam esQueryFilter.java:59) at org.apache.cassandra.db.filter.QueryFilter.getSSTableColumnIterator(QueryFil ter.java:80) at org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilySto re.java:1275) at org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore. java:1167) at org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore. java:1095) at org.apache.cassandra.db.Table.getRow(Table.java:384) at org.apache.cassandra.db.SliceByNamesReadCommand.getRow(SliceByNamesReadComma nd.java:60) at org.apache.cassandra.service.StorageProxy$LocalReadRunnable.runMayThrow(Stor ageProxy.java:473) at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja va:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9 08) at java.lang.Thread.run(Thread.java:662) Caused by: java.io.EOFException at java.io.DataInputStream.readInt(DataInputStream.java:375) at org.apache.cassandra.utils.BloomFilterSerializer.deserialize(BloomFilterSeri alizer.java:48) at org.apache.cassandra.utils.BloomFilterSerializer.deserialize(BloomFilterSeri alizer.java:30) at org.apache.cassandra.io.sstable.IndexHelper.defreezeBloomFilter(IndexHelper. java:108) at org.apache.cassandra.db.columniterator.SSTableNamesIterator.read(SSTableName sIterator.java:106) at org.apache.cassandra.db.columniterator.SSTableNamesIterator.<init>(SSTableNa mesIterator.java:71) ... 12 more Dan -----Original Message----- From: Jonathan Ellis [mailto:jbel...@gmail.com] Sent: February-09-11 18:14 To: dev Subject: Re: SEVERE Data Corruption Problems Hi Dan, it would be very useful to test with 0.7 branch instead of 0.7.0 so at least you're not chasing known and fixed bugs like CASSANDRA-1992. As you say, there's a lot of people who aren't seeing this, so it would also be useful if you can provide some kind of test harness where you can say "point this at a cluster and within a few hours On Wed, Feb 9, 2011 at 4:31 PM, Dan Hendry <dan.hendry.j...@gmail.com> wrote: > I have been having SEVERE data corruption issues with SSTables in my > cluster, for one CF it was happening almost daily (I have since shut down > the service using that CF as it was too much work to manage the Cassandra > errors). At this point, I can't see how it is anything but a Cassandra bug > yet it's somewhat strange and very scary that I am the only one who seems to > be having such serious issues. Most of my data is indexed in two ways so I > have been able to write a validator which goes through and back fills > missing data but it's kind of defeating the whole point of Cassandra. The > only way I have found to deal with issues when they crop up to prevent nodes > crashing from repeated failed compactions is delete the SSTable. My cluster > is running a slightly modified 0.7.0 version which logs what files errors > for so that I can stop the node and delete them. > > > > The problem: > > - Reads, compactions and hinted handoff fail with various > exceptions (samples shown at the end of this email) which seem to indicate > sstable corruption. > > - I have seen failed reads/compactions/hinted handoff on 4 out of 4 > nodes (RF=2) for 3 different super column families and 1 standard column > family (4 out of 11) and just now, the Hints system CF. (if it matters the > ring has not changed since one CF which has been giving me trouble was > created). I have check SMART disk info and run various diagnostics and there > does not seem to be any hardware issues, plus what are the chances of all > four nodes having the same hardware problems at the same time when for all > other purposes, they appear fine? > > - I have added logging which outputs what sstable are causing > exceptions to be thrown. The corrupt sstables have been both freshly flushed > memtables and the output of compaction (ie, 4 sstables which all seem to be > fine get compacted to 1 which is then corrupt). It seems that the majority > of corrupt sstables are post-compacted (vs post-memtable flush). > > - The one CF which was giving me the most problems was heavily > written to (1000-1500 writes/second continually across the cluster). For > that cf, was having to deleting 4-6 sstables a day across the cluster (and > the number was going up, even the number of problems for remaining CFs is > going up). The other CFs which have had corrupt sstables are also quite > heavily written to (generally a few hundred writes a second across the > cluster). > > - Most of the time (5/6 attempts) when this problem occurs, > sstable2json also fails. I have however, had one case where I was able to > export the sstable to json, then re-import it at which point I was no longer > seeing exceptions. > > - The cluster has been running for a little over 2 months now, > problem seems to have sprung up in the last 3-4 weeks and seems to be > steadily getting worse. > > > > Ultimately, I think I am hitting some subtle race condition somewhere. I > have been starting to dig into the Cassandra code but I barely know where to > start looking. I realize I have not provided nearly enough information to > easily debug the problem but PLEASE keep your eyes open for possibly racy or > buggy code which could cause these sorts of problems. I am willing to > provided full Cassandra logs and a corrupt SSTable on an individual basis: > please email me and let me know. > > > > Here is possibly relevant information and my theories on a possible root > cause. Again, I know little about the Cassandra code base and have only > moderate java experience so these theories may be way off base. > > - Strictly speaking, I probably don't have enough memory for my > workload. I see stop the world gc occurring ~30/day/node, often causing > Cassandra to hang for 30+ seconds (according to the gc logs). Could there be > some java bug where a full gc in the middle of writing or flushing > (compaction/memtable flush) or doing some other disk based activity causes > some sort of data corruption? > > - Writes are usually done at ConsistencyLevel ONE with additional > client side retry logic. Given that I often see consecutive nodes in the > ring down, could there be some edge condition where dying at just the right > time causes parts of mutations/messages to be lost? > > - All of the CFs which have been causing me problems have large > rows which are compacted incrementally. Could there be some problem with the > incremental compaction logic? > > - My cluster has a fairly heavy write load (again, the most > problematic CF is getting 1500 (w/s)/(RF=2) = 750 writes/second/node). > Furthermore, it is highly probable that there are timestamp collisions. > Could there be some issue with timestamp logic (ie, using > instead of >= or > some such) during flushes/compaction? > > - Once a node > > > > Cluster/system information: > > - 4 nodes with RF=2 > > - Nodes have 8 cores with 24 GB of RAM a piece. > > - 2 HDs, 1 for commit log/system, 1 for /var/lib/cassandra/data > > - OS is Ubuntu 10.04 (uname -r = 2.6.32-24-server) > > - Java: > > o java version "1.6.0_22" > > o Java(TM) SE Runtime Environment (build 1.6.0_22-b04) > > o Java HotSpot(TM) 64-Bit Server VM (build 17.1-b03, mixed mode) > > - Slightly modified (file information in exceptions) version of > 0.7.0 > > > > The following non-standard cassandra.yaml properties have been changed: > > - commitlog_sync_period_in_ms: 100 (with commitlog_sync: periodic) > > - disk_access_mode: mmap_index_only > > - concurrent_reads: 12 > > - concurrent_writes: 2 (was 32, but I dropped it to 2 to try and > eliminate any mutation race conditions - did not seem to help) > > - sliced_buffer_size_in_kb: 128 > > - in_memory_compaction_limit_in_mb: 50 > > - rpc_timeout_in_ms: 15000 > > > > Schema for most problematic CF: > > name: DeviceEventsByDevice > > column_type: Standard > > memtable_throughput_in_mb: 150 > > memtable_operations_in_millions: 1.5 > > gc_grace_seconds: 172800 > > keys_cached: 1000000 > > rows_cached: 0 > > > > Dan Hendry > > (403) 660-2297 > > -- Jonathan Ellis Project Chair, Apache Cassandra co-founder of DataStax, the source for professional Cassandra support http://www.datastax.com No virus found in this incoming message. Checked by AVG - www.avg.com <http://www.avgcom> Version: 9.0872 / Virus Database: 271.1.1/3432 - Release Date: 02/09/11 02:34:00 No virus found in this incoming message. Checked by AVG - www.avg.com Version: 9.0.872 / Virus Database: 271.1.1/3436 - Release Date: 02/11/11 02:34:00
