[
https://issues.apache.org/jira/browse/CASSANDRA-8669?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Yuki Morishita updated CASSANDRA-8669:
--------------------------------------
Attachment: debug-result.txt
8669-debug.txt
Here is what I found so far.
I added debug logging around snapshot (attached patch 8669-debug.txt) to the
latest cassandra-2.1, ran {{repair_test.py}}'s
{{simple_sequential_repair_test}} and found that when snapshot happens at
certain point of compaction, only tmplink file shows up as snapshot candidate.
And since [we are filtering open early
files|https://github.com/apache/cassandra/blob/cassandra-2.1.4/src/java/org/apache/cassandra/db/ColumnFamilyStore.java#L2223],
end up with empty snapshot directory.
Relevant debug log is (debug-result.txt):
{code}
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,469 CompactionManager.java:226
- Checking ks.cf
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,469
SizeTieredCompactionStrategy.java:88 - Compaction buckets are
[[SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-4-Data.db'),
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-3-Data.db'),
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-1-Data.db'),
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-2-Data.db')]]
INFO [CompactionExecutor:1] 2015-04-05 17:55:24,472 ColumnFamilyStore.java:882
- Enqueuing flush of compactions_in_progress: 1304 (0%) on-heap, 0 (0%) off-heap
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,472 ColumnFamilyStore.java:212
- scheduling flush in 3600000 ms
INFO [CompactionExecutor:1] 2015-04-05 17:55:24,477 CompactionTask.java:140 -
Compacting
[SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-1-Data.db'),
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-3-Data.db'),
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-2-Data.db'),
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-4-Data.db')]
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,477
ColumnFamilyStore.java:1287 - Checking for sstables overlapping
[SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-1-Data.db'),
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-3-Data.db'),
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-2-Data.db'),
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-4-Data.db')]
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,477
CompactionController.java:113 - Checking droppable sstables in
CFS(Keyspace='ks', ColumnFamily='cf')
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,482 CompactionTask.java:154 -
Expected bloom filter size : 2001
DEBUG [MemtablePostFlush:1] 2015-04-05 17:55:24,776 ColumnFamilyStore.java:921
- forceFlush requested but everything is clean in cf
DEBUG [AntiEntropyStage:1] 2015-04-05 17:55:24,776 ColumnFamilyStore.java:2231
- Snapshotting 1 sstables
DEBUG [AntiEntropyStage:1] 2015-04-05 17:55:24,776 ColumnFamilyStore.java:2236
- skipped snapshotting
SSTableReader(path='/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-tmplink-ka-5-Data.db')
(openReason EARLY)
DEBUG [AntiEntropyStage:1] 2015-04-05 17:55:24,776
RepairMessageVerbHandler.java:94 - Enqueuing response to snapshot request
d869f060-dbe6-11e4-9f47-51a3c6e97c77 to /127.0.0.1
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,780 FileUtils.java:161 -
Renaming
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-tmp-ka-5-Statistics.db
to
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-5-Statistics.db
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,780 FileUtils.java:161 -
Renaming
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-tmp-ka-5-TOC.txt
to
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-5-TOC.txt
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,780 FileUtils.java:161 -
Renaming
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-tmp-ka-5-Index.db
to
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-5-Index.db
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,781 FileUtils.java:161 -
Renaming
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-tmp-ka-5-Filter.db
to
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-5-Filter.db
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,781 FileUtils.java:161 -
Renaming
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-tmp-ka-5-CRC.db
to
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-5-CRC.db
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,781 FileUtils.java:161 -
Renaming
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-tmp-ka-5-Digest.sha1
to
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-5-Digest.sha1
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,781 FileUtils.java:161 -
Renaming
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-tmp-ka-5-Data.db
to
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-5-Data.db
INFO [CompactionExecutor:1] 2015-04-05 17:55:24,787 ColumnFamilyStore.java:882
- Enqueuing flush of compactions_in_progress: 164 (0%) on-heap, 0 (0%) off-heap
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,787 ColumnFamilyStore.java:212
- scheduling flush in 3600000 ms
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,794 DataTracker.java:460 -
removing
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-1
from list of files tracked for ks.cf
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,794 DataTracker.java:460 -
removing
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-3
from list of files tracked for ks.cf
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,794 DataTracker.java:460 -
removing
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-2
from list of files tracked for ks.cf
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,795 DataTracker.java:460 -
removing
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-4
from list of files tracked for ks.cf
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,795 SSTableReader.java:1695 -
Marking
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-1-Data.db
compacted
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,795 SSTableReader.java:1695 -
Marking
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-3-Data.db
compacted
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,795 SSTableReader.java:1695 -
Marking
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-2-Data.db
compacted
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,796 SSTableReader.java:1695 -
Marking
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-4-Data.db
compacted
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,797 DataTracker.java:445 -
adding
/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-5
to list of files tracked for ks.cf
INFO [CompactionExecutor:1] 2015-04-05 17:55:24,806 CompactionTask.java:270 -
Compacted 4 sstables to
[/tmp/dtest-9cJ7bi/test/node3/data/ks/cf-898085e0dbe611e4a66151a3c6e97c77/ks-cf-ka-5,].
145,470 bytes to 144,963 (~99% of original) in 320ms = 0.432023MB/s. 2,008
total partitions merged to 2,001. Partition merge counts were {1:1997, 2:1,
3:3, }
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,806 CompactionTask.java:272 -
CF Total Bytes Compacted: 161,938
DEBUG [CompactionExecutor:1] 2015-04-05 17:55:24,807 CompactionTask.java:273 -
Actual #keys: 2001, Estimated #keys:2001, Err%: 0.0
{code}
I tested against bisected commit (see above comment), and the result was
similar, I ended up with empty snapshot direcory. Only difference was I had 1
EARLY sstable and 4 METADATA_CHANGE sstables (that are compacting).
[~benedict], [~krummas], can you take a look?
> simple_repair test failing on 2.1
> ---------------------------------
>
> Key: CASSANDRA-8669
> URL: https://issues.apache.org/jira/browse/CASSANDRA-8669
> Project: Cassandra
> Issue Type: Bug
> Reporter: Philip Thompson
> Assignee: Yuki Morishita
> Fix For: 2.1.5
>
> Attachments: 8669-debug.txt, debug-result.txt
>
>
> The dtest simple_repair_test began failing on 12/22 on 2.1 and trunk. The
> test fails intermittently both locally and on cassci.
> The test is here:
> https://github.com/riptano/cassandra-dtest/blob/master/repair_test.py#L32
> The output is here:
> http://cassci.datastax.com/job/cassandra-2.1_dtest/661/testReport/repair_test/TestRepair/simple_repair_test/
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
