[
https://issues.apache.org/jira/browse/CASSANDRA-9862?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Mark Curtis updated CASSANDRA-9862:
-----------------------------------
Description:
The system will sometimes see a file not found exception in a given node’s
logs. This is seen after the same file appears in a compaction statement either
earlier on in the logs. I found the following events of potential interest:
I pulled out the missing files using this command:
{code}
grep "Caused by: java.io.FileNotFoundException:" * | awk '{print $4}' | sort -u
> files-to-search
{code}
Using the following file as an example: my_keyspace-my_table-jb-2085190-Data.db
File is created from a flush
system.log.10
{code}
7549 INFO [FlushWriter:1] 2015-06-03 12:25:31,857 Memtable.java (line 395)
Completed flushing
/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.d
7549 b (66804 bytes) for commitlog position
ReplayPosition(segmentId=1433333700832, position=2479196)
{code}
Next it appears in a compaction
system.log.10
{code}
8758 INFO [CompactionExecutor:5] 2015-06-03 12:25:37,209
CompactionTask.java (line 115) Compacting
[SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084993-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085164-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-...
...<truncated>...
{code}
The next time we see the file its in file not found exceptions
{code}
system.log.9
53811 java.lang.RuntimeException: java.io.FileNotFoundException:
/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.db
(No such file or directory)
{code}
So going back to compaction executor 5 in system.log.10
{code}
9102 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,684
ColumnFamilyStore.java (line 794) Enqueuing flush of
Memtable-compactions_in_progress@1431151640(0/0 serialized/live bytes, 1 ops)
...
9107 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,701
CompactionTask.java (line 287) Compacted 32 sstables to
[/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_my_table-jb-2085196,].
1,970,986 bytes to 1,880,866 (~95% of original) in 1,492ms = 1.202234MB/s.
13,576 total partitions merged to 11,243. Partition merge counts were {1:9379,
2:1474, 3:324, 4:54 9107 , 5:11, 6:1, }
9108 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,702
ColumnFamilyStore.java (line 794) Enqueuing flush of
Memtable-compactions_in_progress@493376470(357/3570 serialized/live bytes, 16
ops)
...
9111 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,717
CompactionTask.java (line 115) Compacting
[SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085182-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085192-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085175-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085196-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085194-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085191-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085193-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085195-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084985-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085114-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084901-Data.db')]
9112 ERROR [CompactionExecutor:5] 2015-06-03 12:25:38,718
CassandraDaemon.java (line 199) Exception in thread
Thread[CompactionExecutor:5,1,main]
9113 java.lang.RuntimeException: java.io.FileNotFoundException:
/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084901-Data.db
(No such file or directory)
{code}
So could it be that because the thread "CompactionExecutor:5" hit an exception
in line 9113 that the compaction in 8758 didn't complete?
was:
The system will sometimes see a file not found exception in a given node’s
logs. This is seen after the same file appears in a compaction statement either
earlier on in the logs. I found the following events of potential interest:
I pulled out the missing files using this command:
{code}
grep "Caused by: java.io.FileNotFoundException:" * | awk '{print $4}' | sort -u
> files-to-search
{code}
Using the following file as an example: my_keyspace-my_table-jb-2085190-Data.db
File is created from a flush
system.log.10
{code}
7549 INFO [FlushWriter:1] 2015-06-03 12:25:31,857 Memtable.java (line 395)
Completed flushing
/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.d
7549 b (66804 bytes) for commitlog position
ReplayPosition(segmentId=1433333700832, position=2479196)
{code}
Next it appears in a compaction
system.log.10
{code}
8758 INFO [CompactionExecutor:5] 2015-06-03 12:25:37,209
CompactionTask.java (line 115) Compacting
[SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_viewer
8758 _mapping-jb-2084993-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085164-Data.db'),
SSTableReader(path='/raid0/cassand
8758 ra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_viewer_m
...<truncated>...
{code}
The next time we see the file its in file not found exceptions
{code}
system.log.9
53811 java.lang.RuntimeException: java.io.FileNotFoundException:
/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.db
(No such file or directory)
{code}
So going back to compaction executor 5 in system.log.10
{code}
9102 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,684
ColumnFamilyStore.java (line 794) Enqueuing flush of
Memtable-compactions_in_progress@1431151640(0/0 serialized/live bytes, 1 ops)
...
9107 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,701
CompactionTask.java (line 287) Compacted 32 sstables to
[/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_viewer_mappi
9107 ng-jb-2085196,]. 1,970,986 bytes to 1,880,866 (~95% of original) in
1,492ms = 1.202234MB/s. 13,576 total partitions merged to 11,243. Partition
merge counts were {1:9379, 2:1474, 3:324, 4:54 9107 , 5:11, 6:1, }
9108 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,702
ColumnFamilyStore.java (line 794) Enqueuing flush of
Memtable-compactions_in_progress@493376470(357/3570 serialized/live bytes, 16
ops)
...
9111 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,717
CompactionTask.java (line 115) Compacting
[SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_viewer
9111 _mapping-jb-2085182-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085192-Data.db'),
SSTableReader(path='/raid0/cassand
9111
ra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085175-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_viewer_m
9111 apping-jb-2085196-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085194-Data.db'),
SSTableReader(path='/raid0/cassandra
9111 /data/my_keyspace/my_table/my_keyspace-my_table-jb-2085191-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_viewer_map
9111 ping-jb-2085193-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085195-Data.db'),
SSTableReader(path='/raid0/cassandra/d
9111 ata/my_keyspace/my_table/my_keyspace-my_table-jb-2084985-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_viewer_mappi
9111 ng-jb-2085114-Data.db'),
SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084901-Data.db')]
9112 ERROR [CompactionExecutor:5] 2015-06-03 12:25:38,718
CassandraDaemon.java (line 199) Exception in thread
Thread[CompactionExecutor:5,1,main]
9113 java.lang.RuntimeException: java.io.FileNotFoundException:
/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084901-Data.db
(No such file or directory)
{code}
So could it be that because the thread "CompactionExecutor:5" hit an exception
in line 9113 that the compaction in 8758 didn't complete?
> Missing sstable files seen some time after the same file is logged as being
> part of a compaction
> ------------------------------------------------------------------------------------------------
>
> Key: CASSANDRA-9862
> URL: https://issues.apache.org/jira/browse/CASSANDRA-9862
> Project: Cassandra
> Issue Type: Bug
> Reporter: Mark Curtis
> Assignee: Yuki Morishita
>
> The system will sometimes see a file not found exception in a given node’s
> logs. This is seen after the same file appears in a compaction statement
> either earlier on in the logs. I found the following events of potential
> interest:
> I pulled out the missing files using this command:
> {code}
> grep "Caused by: java.io.FileNotFoundException:" * | awk '{print $4}' | sort
> -u > files-to-search
> {code}
> Using the following file as an example:
> my_keyspace-my_table-jb-2085190-Data.db
> File is created from a flush
> system.log.10
> {code}
> 7549 INFO [FlushWriter:1] 2015-06-03 12:25:31,857 Memtable.java (line
> 395) Completed flushing
> /raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.d
> 7549 b (66804 bytes) for commitlog position
> ReplayPosition(segmentId=1433333700832, position=2479196)
> {code}
> Next it appears in a compaction
> system.log.10
> {code}
> 8758 INFO [CompactionExecutor:5] 2015-06-03 12:25:37,209
> CompactionTask.java (line 115) Compacting
> [SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084993-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085164-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-...
> ...<truncated>...
> {code}
> The next time we see the file its in file not found exceptions
> {code}
> system.log.9
> 53811 java.lang.RuntimeException: java.io.FileNotFoundException:
> /raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085190-Data.db
> (No such file or directory)
> {code}
> So going back to compaction executor 5 in system.log.10
> {code}
> 9102 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,684
> ColumnFamilyStore.java (line 794) Enqueuing flush of
> Memtable-compactions_in_progress@1431151640(0/0 serialized/live bytes, 1 ops)
> ...
> 9107 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,701
> CompactionTask.java (line 287) Compacted 32 sstables to
> [/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-data_my_table-jb-2085196,].
> 1,970,986 bytes to 1,880,866 (~95% of original) in 1,492ms = 1.202234MB/s.
> 13,576 total partitions merged to 11,243. Partition merge counts were
> {1:9379, 2:1474, 3:324, 4:54 9107 , 5:11, 6:1, }
> 9108 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,702
> ColumnFamilyStore.java (line 794) Enqueuing flush of
> Memtable-compactions_in_progress@493376470(357/3570 serialized/live bytes, 16
> ops)
> ...
> 9111 INFO [CompactionExecutor:5] 2015-06-03 12:25:38,717
> CompactionTask.java (line 115) Compacting
> [SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085182-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085192-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085175-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085196-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085194-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085191-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085193-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085195-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084985-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2085114-Data.db'),
>
> SSTableReader(path='/raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084901-Data.db')]
> 9112 ERROR [CompactionExecutor:5] 2015-06-03 12:25:38,718
> CassandraDaemon.java (line 199) Exception in thread
> Thread[CompactionExecutor:5,1,main]
> 9113 java.lang.RuntimeException: java.io.FileNotFoundException:
> /raid0/cassandra/data/my_keyspace/my_table/my_keyspace-my_table-jb-2084901-Data.db
> (No such file or directory)
> {code}
> So could it be that because the thread "CompactionExecutor:5" hit an
> exception in line 9113 that the compaction in 8758 didn't complete?
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
