You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Dan Hendry (Created) (JIRA)" <ji...@apache.org> on 2011/11/10 22:05:53 UTC
[jira] [Created] (CASSANDRA-3482) Flush Assertion Error - CF size
changed during serialization
Flush Assertion Error - CF size changed during serialization
------------------------------------------------------------
Key: CASSANDRA-3482
URL: https://issues.apache.org/jira/browse/CASSANDRA-3482
Project: Cassandra
Issue Type: Bug
Components: Core
Affects Versions: 1.0.2
Environment: RHEL 6
java version "1.6.0_26"
6 node cluster
Reporter: Dan Hendry
I have seen the following assert in the logs - there are no other suspicious or unexpected log messages.
INFO [FlushWriter:9] 2011-11-10 13:08:58,882 Memtable.java (line 237) Writing Memtable-UserData@1388955390(25676955/430716097 serialized/live bytes, 478913 ops)
ERROR [FlushWriter:9] 2011-11-10 13:08:59,513 AbstractCassandraDaemon.java (line 133) Fatal exception in thread Thread[FlushWriter:9,5,main]
java.lang.AssertionError: CF size changed during serialization: was 4 initially but 3 written
at org.apache.cassandra.db.ColumnFamilySerializer.serializeForSSTable(ColumnFamilySerializer.java:94)
at org.apache.cassandra.db.ColumnFamilySerializer.serializeWithIndexes(ColumnFamilySerializer.java:112)
at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:177)
at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:264)
at org.apache.cassandra.db.Memtable.access$400(Memtable.java:47)
at org.apache.cassandra.db.Memtable$4.runMayThrow(Memtable.java:289)
at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Once the error occurs, further MemtablePostFlusher tasks are blocked:
nodetool tpstats:
Pool Name Active Pending Completed Blocked All time blocked
MemtablePostFlusher 1 18 16 0 0
It *seems* that all further flushed for the particular CF (in this case UserData) will also result in the same assertion error. Restarting the node fixes the problem.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (CASSANDRA-3482) Flush Assertion Error - CF size
changed during serialization
Posted by "Dan Hendry (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-3482?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13148013#comment-13148013 ]
Dan Hendry commented on CASSANDRA-3482:
---------------------------------------
I should also point out that the number of columns being logged in the error, 3/4, is MUCH smaller than the expected column count based on the flushed bytes.
Just based on the usage pattern for this CF and reading the description for CASSANDRA-2503, I suspect (without any real evidence) they may be related.
> Flush Assertion Error - CF size changed during serialization
> ------------------------------------------------------------
>
> Key: CASSANDRA-3482
> URL: https://issues.apache.org/jira/browse/CASSANDRA-3482
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Affects Versions: 1.0.2
> Environment: RHEL 6
> java version "1.6.0_26"
> 6 node cluster
> Reporter: Dan Hendry
>
> I have seen the following assert in the logs - there are no other suspicious or unexpected log messages.
> INFO [FlushWriter:9] 2011-11-10 13:08:58,882 Memtable.java (line 237) Writing Memtable-UserData@1388955390(25676955/430716097 serialized/live bytes, 478913 ops)
> ERROR [FlushWriter:9] 2011-11-10 13:08:59,513 AbstractCassandraDaemon.java (line 133) Fatal exception in thread Thread[FlushWriter:9,5,main]
> java.lang.AssertionError: CF size changed during serialization: was 4 initially but 3 written
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeForSSTable(ColumnFamilySerializer.java:94)
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeWithIndexes(ColumnFamilySerializer.java:112)
> at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:177)
> at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:264)
> at org.apache.cassandra.db.Memtable.access$400(Memtable.java:47)
> at org.apache.cassandra.db.Memtable$4.runMayThrow(Memtable.java:289)
> at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:662)
> Once the error occurs, further MemtablePostFlusher tasks are blocked:
> nodetool tpstats:
> Pool Name Active Pending Completed Blocked All time blocked
> MemtablePostFlusher 1 18 16 0 0
> It *seems* that all further flushed for the particular CF (in this case UserData) will also result in the same assertion error. Restarting the node fixes the problem.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (CASSANDRA-3482) Flush Assertion Error - CF size
changed during serialization
Posted by "Jonathan Ellis (Updated) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-3482?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jonathan Ellis updated CASSANDRA-3482:
--------------------------------------
Reviewer: slebresne
Priority: Critical (was: Major)
Fix Version/s: 1.0.3
Assignee: Jonathan Ellis
> Flush Assertion Error - CF size changed during serialization
> ------------------------------------------------------------
>
> Key: CASSANDRA-3482
> URL: https://issues.apache.org/jira/browse/CASSANDRA-3482
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Affects Versions: 1.0.2
> Environment: RHEL 6
> java version "1.6.0_26"
> 6 node cluster
> Reporter: Dan Hendry
> Assignee: Jonathan Ellis
> Priority: Critical
> Fix For: 1.0.3
>
> Attachments: 3482.txt
>
>
> I have seen the following assert in the logs - there are no other suspicious or unexpected log messages.
> INFO [FlushWriter:9] 2011-11-10 13:08:58,882 Memtable.java (line 237) Writing Memtable-UserData@1388955390(25676955/430716097 serialized/live bytes, 478913 ops)
> ERROR [FlushWriter:9] 2011-11-10 13:08:59,513 AbstractCassandraDaemon.java (line 133) Fatal exception in thread Thread[FlushWriter:9,5,main]
> java.lang.AssertionError: CF size changed during serialization: was 4 initially but 3 written
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeForSSTable(ColumnFamilySerializer.java:94)
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeWithIndexes(ColumnFamilySerializer.java:112)
> at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:177)
> at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:264)
> at org.apache.cassandra.db.Memtable.access$400(Memtable.java:47)
> at org.apache.cassandra.db.Memtable$4.runMayThrow(Memtable.java:289)
> at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:662)
> Once the error occurs, further MemtablePostFlusher tasks are blocked:
> nodetool tpstats:
> Pool Name Active Pending Completed Blocked All time blocked
> MemtablePostFlusher 1 18 16 0 0
> It *seems* that all further flushed for the particular CF (in this case UserData) will also result in the same assertion error. Restarting the node fixes the problem.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Resolved] (CASSANDRA-3482) Flush Assertion Error - CF size
changed during serialization
Posted by "Sylvain Lebresne (Resolved) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-3482?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Sylvain Lebresne resolved CASSANDRA-3482.
-----------------------------------------
Resolution: Fixed
+1, committed
> Flush Assertion Error - CF size changed during serialization
> ------------------------------------------------------------
>
> Key: CASSANDRA-3482
> URL: https://issues.apache.org/jira/browse/CASSANDRA-3482
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Affects Versions: 1.0.2
> Environment: RHEL 6
> java version "1.6.0_26"
> 6 node cluster
> Reporter: Dan Hendry
> Assignee: Jonathan Ellis
> Priority: Critical
> Fix For: 1.0.3
>
> Attachments: 3482.txt
>
>
> I have seen the following assert in the logs - there are no other suspicious or unexpected log messages.
> INFO [FlushWriter:9] 2011-11-10 13:08:58,882 Memtable.java (line 237) Writing Memtable-UserData@1388955390(25676955/430716097 serialized/live bytes, 478913 ops)
> ERROR [FlushWriter:9] 2011-11-10 13:08:59,513 AbstractCassandraDaemon.java (line 133) Fatal exception in thread Thread[FlushWriter:9,5,main]
> java.lang.AssertionError: CF size changed during serialization: was 4 initially but 3 written
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeForSSTable(ColumnFamilySerializer.java:94)
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeWithIndexes(ColumnFamilySerializer.java:112)
> at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:177)
> at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:264)
> at org.apache.cassandra.db.Memtable.access$400(Memtable.java:47)
> at org.apache.cassandra.db.Memtable$4.runMayThrow(Memtable.java:289)
> at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:662)
> Once the error occurs, further MemtablePostFlusher tasks are blocked:
> nodetool tpstats:
> Pool Name Active Pending Completed Blocked All time blocked
> MemtablePostFlusher 1 18 16 0 0
> It *seems* that all further flushed for the particular CF (in this case UserData) will also result in the same assertion error. Restarting the node fixes the problem.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (CASSANDRA-3482) Flush Assertion Error - CF size
changed during serialization
Posted by "Dan Hendry (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-3482?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13148020#comment-13148020 ]
Dan Hendry commented on CASSANDRA-3482:
---------------------------------------
Oh, and the problem crops up again with 1h of restarting the node so. "Restarting the node fixes the problem" isnt exactly true.
> Flush Assertion Error - CF size changed during serialization
> ------------------------------------------------------------
>
> Key: CASSANDRA-3482
> URL: https://issues.apache.org/jira/browse/CASSANDRA-3482
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Affects Versions: 1.0.2
> Environment: RHEL 6
> java version "1.6.0_26"
> 6 node cluster
> Reporter: Dan Hendry
>
> I have seen the following assert in the logs - there are no other suspicious or unexpected log messages.
> INFO [FlushWriter:9] 2011-11-10 13:08:58,882 Memtable.java (line 237) Writing Memtable-UserData@1388955390(25676955/430716097 serialized/live bytes, 478913 ops)
> ERROR [FlushWriter:9] 2011-11-10 13:08:59,513 AbstractCassandraDaemon.java (line 133) Fatal exception in thread Thread[FlushWriter:9,5,main]
> java.lang.AssertionError: CF size changed during serialization: was 4 initially but 3 written
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeForSSTable(ColumnFamilySerializer.java:94)
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeWithIndexes(ColumnFamilySerializer.java:112)
> at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:177)
> at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:264)
> at org.apache.cassandra.db.Memtable.access$400(Memtable.java:47)
> at org.apache.cassandra.db.Memtable$4.runMayThrow(Memtable.java:289)
> at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:662)
> Once the error occurs, further MemtablePostFlusher tasks are blocked:
> nodetool tpstats:
> Pool Name Active Pending Completed Blocked All time blocked
> MemtablePostFlusher 1 18 16 0 0
> It *seems* that all further flushed for the particular CF (in this case UserData) will also result in the same assertion error. Restarting the node fixes the problem.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (CASSANDRA-3482) Flush Assertion Error - CF size
changed during serialization
Posted by "Dan Hendry (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-3482?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13148540#comment-13148540 ]
Dan Hendry commented on CASSANDRA-3482:
---------------------------------------
Pretty sure CASSANDRA-2503 introduced this problem.
My experimental evidence at this point (since I have not traced through the code) is that 2 out of 2 times the node was started using 1.0.2 (release), the assert cropped up within 1 hour of going live (first time was after 59 mins, second was after 23 mins). I reverted the changes introduced in CASSANDRA-2503 (still running 1.0.2), and the node has now been up for 17 hours with no problems.
> Flush Assertion Error - CF size changed during serialization
> ------------------------------------------------------------
>
> Key: CASSANDRA-3482
> URL: https://issues.apache.org/jira/browse/CASSANDRA-3482
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Affects Versions: 1.0.2
> Environment: RHEL 6
> java version "1.6.0_26"
> 6 node cluster
> Reporter: Dan Hendry
>
> I have seen the following assert in the logs - there are no other suspicious or unexpected log messages.
> INFO [FlushWriter:9] 2011-11-10 13:08:58,882 Memtable.java (line 237) Writing Memtable-UserData@1388955390(25676955/430716097 serialized/live bytes, 478913 ops)
> ERROR [FlushWriter:9] 2011-11-10 13:08:59,513 AbstractCassandraDaemon.java (line 133) Fatal exception in thread Thread[FlushWriter:9,5,main]
> java.lang.AssertionError: CF size changed during serialization: was 4 initially but 3 written
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeForSSTable(ColumnFamilySerializer.java:94)
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeWithIndexes(ColumnFamilySerializer.java:112)
> at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:177)
> at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:264)
> at org.apache.cassandra.db.Memtable.access$400(Memtable.java:47)
> at org.apache.cassandra.db.Memtable$4.runMayThrow(Memtable.java:289)
> at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:662)
> Once the error occurs, further MemtablePostFlusher tasks are blocked:
> nodetool tpstats:
> Pool Name Active Pending Completed Blocked All time blocked
> MemtablePostFlusher 1 18 16 0 0
> It *seems* that all further flushed for the particular CF (in this case UserData) will also result in the same assertion error. Restarting the node fixes the problem.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (CASSANDRA-3482) Flush Assertion Error - CF size
changed during serialization
Posted by "Jonathan Ellis (Updated) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-3482?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jonathan Ellis updated CASSANDRA-3482:
--------------------------------------
Attachment: 3482.txt
I bet you're right. Patch attached to fix the race introduced by 2503.
> Flush Assertion Error - CF size changed during serialization
> ------------------------------------------------------------
>
> Key: CASSANDRA-3482
> URL: https://issues.apache.org/jira/browse/CASSANDRA-3482
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Affects Versions: 1.0.2
> Environment: RHEL 6
> java version "1.6.0_26"
> 6 node cluster
> Reporter: Dan Hendry
> Attachments: 3482.txt
>
>
> I have seen the following assert in the logs - there are no other suspicious or unexpected log messages.
> INFO [FlushWriter:9] 2011-11-10 13:08:58,882 Memtable.java (line 237) Writing Memtable-UserData@1388955390(25676955/430716097 serialized/live bytes, 478913 ops)
> ERROR [FlushWriter:9] 2011-11-10 13:08:59,513 AbstractCassandraDaemon.java (line 133) Fatal exception in thread Thread[FlushWriter:9,5,main]
> java.lang.AssertionError: CF size changed during serialization: was 4 initially but 3 written
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeForSSTable(ColumnFamilySerializer.java:94)
> at org.apache.cassandra.db.ColumnFamilySerializer.serializeWithIndexes(ColumnFamilySerializer.java:112)
> at org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:177)
> at org.apache.cassandra.db.Memtable.writeSortedContents(Memtable.java:264)
> at org.apache.cassandra.db.Memtable.access$400(Memtable.java:47)
> at org.apache.cassandra.db.Memtable$4.runMayThrow(Memtable.java:289)
> at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:662)
> Once the error occurs, further MemtablePostFlusher tasks are blocked:
> nodetool tpstats:
> Pool Name Active Pending Completed Blocked All time blocked
> MemtablePostFlusher 1 18 16 0 0
> It *seems* that all further flushed for the particular CF (in this case UserData) will also result in the same assertion error. Restarting the node fixes the problem.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira