incubator-cassandra-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jeremy Hanna <jeremy.hanna1...@gmail.com>
Subject Re: SEVERE Data Corruption Problems
Date Thu, 17 Feb 2011 01:41:24 GMT
Dan,

Just wondered if you had a chance to try 0.7.1 or 0.7.2 out with your context/data.

Jeremy

On Feb 11, 2011, at 12:17 PM, Dan Hendry wrote:

> 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:aaron@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.junk@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:jbellis@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.junk@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
> 


Mime
View raw message