[
https://issues.apache.org/jira/browse/CASSANDRA-3712?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13203676#comment-13203676
]
Yuki Morishita edited comment on CASSANDRA-3712 at 2/8/12 4:23 PM:
-------------------------------------------------------------------
When updating/deleting CFS backed secondary index, currently it doesn't acquire
Memtable lock. So when flush and cleanup occurred at the same time on indexed
column family, there is a chance of getting this AssertionError.
Test case attached to reproduce the same error. Note that test does not fail
always, so you may run several times to see the error.
To fix this, I added CFS#applyDirect method which just acquire and release lock
before/after CFS update, and call it from KeysIndex.
Both patches are for 1.0 branch.
was (Author: yukim):
When updating/deleting CFS backed secondary index, currently it doesn't
acquire Memtable lock. So when flush and cleanup occurred at the same time on
indexed column family, there is a chance of getting this AssertionError.
Test case attached to reproduce the same error. Note that test does not fail
always, so you may run several times to see the error.
To fix this, I added CFS#applyDirect method which just acquire and release lock
before/after CFS update, and call it from KeysIndex.
> Can't cleanup after I moved a token.
> ------------------------------------
>
> Key: CASSANDRA-3712
> URL: https://issues.apache.org/jira/browse/CASSANDRA-3712
> Project: Cassandra
> Issue Type: Bug
> Affects Versions: 1.0.6
> Environment: java version "1.6.0_26"
> Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
> Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
> Ubuntu 10.04.2 LTS 64-Bit
> RAM: 2GB / 1GB free
> Data partition: 80% free on the most used server.
> Reporter: Herve Nicol
> Assignee: Yuki Morishita
> Attachments: 0001-Add-flush-and-cleanup-race-test.patch,
> 0002-Acquire-lock-when-updating-index.patch
>
>
> Before cleanup failed, I moved one node's token.
> My cluster had 10GB data on 2 nodes. Data repartition was bad, tokens were
> 165[...] and 155[...].
> I moved 155 to 075[...], then adjusted to 076[...]. The moves were correctly
> processed, with no exception.
> But then, when I wanted to cleanup, it failed and keeps failing, on both
> nodes.
> Other maintenance procedures like repair, compact or scrub work.
> All the data is in the URLs CF.
> Example session log:
> nodetool cleanup fails:
> $ ./nodetool --host cnode1 cleanup
> Error occured during cleanup
> java.util.concurrent.ExecutionException: java.lang.AssertionError
> at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:222)
> at java.util.concurrent.FutureTask.get(FutureTask.java:83)
> at
> org.apache.cassandra.db.compaction.CompactionManager.performAllSSTableOperation(CompactionManager.java:203)
> at
> org.apache.cassandra.db.compaction.CompactionManager.performCleanup(CompactionManager.java:237)
> at
> org.apache.cassandra.db.ColumnFamilyStore.forceCleanup(ColumnFamilyStore.java:958)
> at
> org.apache.cassandra.service.StorageService.forceTableCleanup(StorageService.java:1604)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at
> com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:93)
> at
> com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:27)
> at
> com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:208)
> at com.sun.jmx.mbeanserver.PerInterface.invoke(PerInterface.java:120)
> at com.sun.jmx.mbeanserver.MBeanSupport.invoke(MBeanSupport.java:262)
> at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:836)
> at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:761)
> at
> javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1427)
> at
> javax.management.remote.rmi.RMIConnectionImpl.access$200(RMIConnectionImpl.java:72)
> at
> javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1265)
> at
> javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1360)
> at
> javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:788)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
> at sun.rmi.transport.Transport$1.run(Transport.java:159)
> at java.security.AccessController.doPrivileged(Native Method)
> at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
> at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
> at
> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
> at
> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
> 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)
> Caused by: java.lang.AssertionError
> at org.apache.cassandra.db.Memtable.put(Memtable.java:136)
> at
> org.apache.cassandra.db.ColumnFamilyStore.apply(ColumnFamilyStore.java:780)
> at
> org.apache.cassandra.db.index.keys.KeysIndex.deleteColumn(KeysIndex.java:82)
> at
> org.apache.cassandra.db.index.SecondaryIndexManager.deleteFromIndexes(SecondaryIndexManager.java:438)
> at
> org.apache.cassandra.db.compaction.CompactionManager.doCleanupCompaction(CompactionManager.java:754)
> at
> org.apache.cassandra.db.compaction.CompactionManager.access$300(CompactionManager.java:63)
> at
> org.apache.cassandra.db.compaction.CompactionManager$5.perform(CompactionManager.java:241)
> at
> org.apache.cassandra.db.compaction.CompactionManager$2.call(CompactionManager.java:182)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
> ... 3 more
> The server log looks like this:
> INFO [CompactionExecutor:260] 2012-01-09 14:08:41,716 CompactionManager.java
> (line 702) Cleaning up
> SSTableReader(path='/ke/cassandra/data/kev3/URLs-hc-457-Data.db')
> INFO [OptionalTasks:1] 2012-01-09 14:08:47,220 MeteredFlusher.java (line 62)
> flushing high-traffic column family CFS(Keyspace='kev3', ColumnFamily='URLs')
> (estimated 156787206 bytes)
> INFO [OptionalTasks:1] 2012-01-09 14:08:47,226 ColumnFamilyStore.java (line
> 692) Enqueuing flush of
> Memtable-URLs.URLs_1_idx@1347180703(16324791/156973287 serialized/live bytes,
> 173288 ops)
> INFO [FlushWriter:23] 2012-01-09 14:08:47,236 Memtable.java (line 240)
> Writing Memtable-URLs.URLs_1_idx@1347180703(16324791/156973287
> serialized/live bytes, 173288 ops)
> INFO [pool-1-thread-1] 2012-01-09 14:08:51,003 Memtable.java (line 180)
> CFS(Keyspace='kev3', ColumnFamily='URLs.URLs_1_idx') liveRatio is
> 7.692510757866615 (just-counted was 4.512127842861816). calculation took
> 8648ms for 97329 columns
> INFO [FlushWriter:23] 2012-01-09 14:08:54,360 Memtable.java (line 277)
> Completed flushing /ke/cassandra/data/kev3/URLs.URLs_1_idx-hc-143-Data.db
> (26375495 bytes)
> INFO [ScheduledTasks:1] 2012-01-09 14:08:55,566 GCInspector.java (line 123)
> GC for ParNew: 206 ms for 1 collections, 934108624 used; max is 2034237440
> INFO [OptionalTasks:1] 2012-01-09 14:08:57,289 MeteredFlusher.java (line 62)
> flushing high-traffic column family CFS(Keyspace='kev3', ColumnFamily='URLs')
> (estimated 188842513 bytes)
> INFO [OptionalTasks:1] 2012-01-09 14:08:57,297 ColumnFamilyStore.java (line
> 692) Enqueuing flush of Memtable-URLs.URLs_1_idx@164871630(19662738/189069779
> serialized/live bytes, 208494 ops)
> INFO [FlushWriter:23] 2012-01-09 14:08:57,297 Memtable.java (line 240)
> Writing Memtable-URLs.URLs_1_idx@164871630(19662738/189069779 serialized/live
> bytes, 208494 ops)
> INFO [ScheduledTasks:1] 2012-01-09 14:08:57,619 GCInspector.java (line 123)
> GC for ParNew: 402 ms for 2 collections, 981893424 used; max is 2034237440
> INFO [FlushWriter:23] 2012-01-09 14:09:05,944 Memtable.java (line 277)
> Completed flushing /ke/cassandra/data/kev3/URLs.URLs_1_idx-hc-144-Data.db
> (31755390 bytes)
> INFO [OptionalTasks:1] 2012-01-09 14:09:06,447 MeteredFlusher.java (line 62)
> flushing high-traffic column family CFS(Keyspace='kev3', ColumnFamily='URLs')
> (estimated 174605041 bytes)
> INFO [OptionalTasks:1] 2012-01-09 14:09:06,447 ColumnFamilyStore.java (line
> 692) Enqueuing flush of Memtable-URLs.URLs_1_idx@284469330(18158445/174605041
> serialized/live bytes, 192702 ops)
> INFO [FlushWriter:23] 2012-01-09 14:09:06,447 Memtable.java (line 240)
> Writing Memtable-URLs.URLs_1_idx@284469330(18158445/174605041 serialized/live
> bytes, 192702 ops)
> ERROR [CompactionExecutor:260] 2012-01-09 14:09:06,448
> AbstractCassandraDaemon.java (line 133) Fatal exception in thread
> Thread[CompactionExecutor:260,1,RMI Runtime]
> java.lang.AssertionError
> at org.apache.cassandra.db.Memtable.put(Memtable.java:136)
> at
> org.apache.cassandra.db.ColumnFamilyStore.apply(ColumnFamilyStore.java:780)
> at
> org.apache.cassandra.db.index.keys.KeysIndex.deleteColumn(KeysIndex.java:82)
> at
> org.apache.cassandra.db.index.SecondaryIndexManager.deleteFromIndexes(SecondaryIndexManager.java:438)
> at
> org.apache.cassandra.db.compaction.CompactionManager.doCleanupCompaction(CompactionManager.java:754)
> at
> org.apache.cassandra.db.compaction.CompactionManager.access$300(CompactionManager.java:63)
> at
> org.apache.cassandra.db.compaction.CompactionManager$5.perform(CompactionManager.java:241)
> at
> org.apache.cassandra.db.compaction.CompactionManager$2.call(CompactionManager.java:182)
> 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.java:886)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:662)
--
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
