cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Yuki Morishita (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CASSANDRA-8669) simple_repair test failing on 2.1
Date Sun, 05 Apr 2015 23:40:09 GMT

     [ 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)

Mime
View raw message