You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Brandon Williams (Jira)" <ji...@apache.org> on 2021/04/15 14:26:00 UTC
[jira] [Updated] (CASSANDRA-16603) Sporadic CQL operation timeout
due to unconfigured table
[ https://issues.apache.org/jira/browse/CASSANDRA-16603?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Brandon Williams updated CASSANDRA-16603:
-----------------------------------------
Bug Category: Parent values: Availability(12983)
Complexity: Challenging
Discovered By: User Report
Severity: Normal
Status: Open (was: Triage Needed)
> Sporadic CQL operation timeout due to unconfigured table
> --------------------------------------------------------
>
> Key: CASSANDRA-16603
> URL: https://issues.apache.org/jira/browse/CASSANDRA-16603
> Project: Cassandra
> Issue Type: Bug
> Components: Local/Commit Log
> Reporter: Haoze Wu
> Priority: Normal
>
> We were doing some systematic testing in Cassandra stable release 3.11.10 and found the disk I/O delay may cause some issues.
> We start a Cassandra cluster of 3 nodes with the default configuration, in node 1, we open the cqlsh shell and type in:
> {code:java}
> create keyspace ycsb WITH REPLICATION = {'class' : 'SimpleStrategy', 'replication_factor': 3 };
> USE ycsb;
> create table usertable (
> y_id varchar primary key,
> field0 varchar,
> field1 varchar,
> field2 varchar,
> field3 varchar,
> field4 varchar,
> field5 varchar,
> field6 varchar,
> field7 varchar,
> field8 varchar,
> field9 varchar);
> {code}
> During this process, we inject a single disk I/O delay in node 2’s CommitLog#add method (e.g., in Mutation.serializer.serialize).
> {code:java}
> /**
> * Add a Mutation to the commit log. If CDC is enabled, this can fail.
> *
> * @param mutation the Mutation to add to the log
> * @throws WriteTimeoutException
> */
> public CommitLogPosition add(Mutation mutation) throws WriteTimeoutException
> {
> assert mutation != null;
> try (DataOutputBuffer dob = DataOutputBuffer.scratchBuffer.get())
> {
> Mutation.serializer.serialize(mutation, dob, MessagingService.current_version);
> int size = dob.getLength();
> int totalSize = size + ENTRY_OVERHEAD_SIZE;
> if (totalSize > MAX_MUTATION_SIZE)
> {
> throw new IllegalArgumentException(String.format("Mutation of %s is too large for the maximum size of %s",
> FBUtilities.prettyPrintMemory(totalSize),
> FBUtilities.prettyPrintMemory(MAX_MUTATION_SIZE)));
> }
> // ...
> }
> catch (IOException e)
> {
> throw new FSWriteError(e, segmentManager.allocatingFrom().getPath());
> }
> }
> {code}
> In the aforementioned cqlsh shell connected to node 1, when it runs the command of “create table usertable ...”, it costs more time than normal, and finally shows a warning message:
> {code:java}
> Warning: schema version mismatch detected; check the schema versions of your nodes in system.local and system.peers.
> {code}
> This behavior seems reasonable because our injection affects node 2.
> When we open another cqlsh shell connecting to node 2, intent to run some commands on the created table:
> {code:java}
> USE ycsb;
> {code}
> The cqlsh shell shows an error message:
> {code:java}
> InvalidRequest: Error from server: code=2200 [Invalid query] message="unconfigured table t"
> {code}
> It seems reasonable, too, because our injection affects node 2. However, when we run a cqlsh shell connecting to node 1 again, and try to run some commands like:
> {code:java}
> USE ycsb;
> SELECT * FROM usertable;
> {code}
> Most of the time, the result is shown immediately. However, sometimes it gets stuck for a few seconds, and shows the error message:
> {code:java}
> ReadTimeout: Error from server: code=1200 [Coordinator node timed out waiting for replica nodes' responses] message="Operation timed out - received only 0 responses." info={'received_responses': 0, 'required_responses': 1, 'consistency': 'ONE'}
> {code}
> A more reliable way to reproduce this failure is using our client based on datastax (see [https://github.com/functioner/datastax-cassandra-client]).
> We have dump the jstack for node 2 when the issue happens:
> {code:java}
> "MutationStage-1" #90 daemon prio=5 os_prio=0 tid=0x00007f858429c880 nid=0x6f23 waiting on condition [0x00007f856889e000]
> java.lang.Thread.State: TIMED_WAITING (sleeping)
> at java.lang.Thread.sleep(Native Method)
> at org.apache.cassandra.db.commitlog.CommitLog.add(CommitLog.java:246)
> at org.apache.cassandra.db.Keyspace.applyInternal(Keyspace.java:593)
> at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:470)
> at org.apache.cassandra.db.Mutation.apply(Mutation.java:250)
> at org.apache.cassandra.db.Mutation.apply(Mutation.java:255)
> at org.apache.cassandra.db.Mutation.apply(Mutation.java:264)
> at org.apache.cassandra.cql3.statements.ModificationStatement.executeInternalWithoutCondition(ModificationStatement.java:597)
> at org.apache.cassandra.cql3.statements.ModificationStatement.executeInternal(ModificationStatement.java:577)
> at org.apache.cassandra.cql3.QueryProcessor.executeInternal(QueryProcessor.java:315)
> at org.apache.cassandra.db.SystemKeyspace.lambda$updatePeerInfo$1(SystemKeyspace.java:757)
> at org.apache.cassandra.db.SystemKeyspace$$Lambda$286/119781138.run(Unknown Source)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at org.apache.cassandra.concurrent.AbstractLocalAwareExecutorService$FutureTask.run(AbstractLocalAwareExecutorService.java:162)
> at org.apache.cassandra.concurrent.SEPWorker.run(SEPWorker.java:113)
> at java.lang.Thread.run(Thread.java:748)
> "MigrationStage:1" #69 daemon prio=5 os_prio=0 tid=0x00007f857c6d1b20 nid=0x6ecd waiting on condition [0x00007f8568cef000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000005e5e7abd8> (a com.google.common.util.concurrent.ListenableFutureTask)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
> at java.util.concurrent.FutureTask.get(FutureTask.java:191)
> at org.apache.cassandra.utils.FBUtilities.waitOnFuture(FBUtilities.java:438)
> at org.apache.cassandra.schema.SchemaKeyspace.lambda$flush$1(SchemaKeyspace.java:310)
> at org.apache.cassandra.schema.SchemaKeyspace$$Lambda$263/1985363058.accept(Unknown Source)
> at java.lang.Iterable.forEach(Iterable.java:75)
> at org.apache.cassandra.schema.SchemaKeyspace.flush(SchemaKeyspace.java:310)
> at org.apache.cassandra.schema.SchemaKeyspace.mergeSchema(SchemaKeyspace.java:1398)
> - locked <0x0000000611bd39e0> (a java.lang.Class for org.apache.cassandra.schema.SchemaKeyspace)
> at org.apache.cassandra.schema.SchemaKeyspace.mergeSchemaAndAnnounceVersion(SchemaKeyspace.java:1380)
> - locked <0x0000000611bd39e0> (a java.lang.Class for org.apache.cassandra.schema.SchemaKeyspace)
> at org.apache.cassandra.db.DefinitionsUpdateVerbHandler$1.runMayThrow(DefinitionsUpdateVerbHandler.java:51)
> at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at org.apache.cassandra.concurrent.NamedThreadFactory.lambda$threadLocalDeallocator$0(NamedThreadFactory.java:84)
> at org.apache.cassandra.concurrent.NamedThreadFactory$$Lambda$6/1239807799.run(Unknown Source)
> at java.lang.Thread.run(Thread.java:748)
> "MemtablePostFlush:1" #22 daemon prio=5 os_prio=0 tid=0x00007f8598b018e0 nid=0x6e45 waiting on condition [0x00007f856e1ad000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000005e5e7abb8> (a java.util.concurrent.CountDownLatch$Sync)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
> at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
> at org.apache.cassandra.db.ColumnFamilyStore$PostFlush.call(ColumnFamilyStore.java:1019)
> at org.apache.cassandra.db.ColumnFamilyStore$PostFlush.call(ColumnFamilyStore.java:1002)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at org.apache.cassandra.concurrent.NamedThreadFactory.lambda$threadLocalDeallocator$0(NamedThreadFactory.java:84)
> at org.apache.cassandra.concurrent.NamedThreadFactory$$Lambda$6/1239807799.run(Unknown Source)
> at java.lang.Thread.run(Thread.java:748)
> "MemtableFlushWriter:2" #19 daemon prio=5 os_prio=0 tid=0x00007f8598af9da0 nid=0x6e42 waiting on condition [0x00007f856e270000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:304)
> at org.apache.cassandra.utils.concurrent.WaitQueue$AbstractSignal.awaitUninterruptibly(WaitQueue.java:280)
> at org.apache.cassandra.utils.concurrent.OpOrder$Group.await(OpOrder.java:264)
> at org.apache.cassandra.utils.concurrent.OpOrder$Barrier.await(OpOrder.java:431)
> at org.apache.cassandra.db.ColumnFamilyStore$Flush.run(ColumnFamilyStore.java:1114)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at org.apache.cassandra.concurrent.NamedThreadFactory.lambda$threadLocalDeallocator$0(NamedThreadFactory.java:84)
> at org.apache.cassandra.concurrent.NamedThreadFactory$$Lambda$6/1239807799.run(Unknown Source)
> {code}
> We found that the delay in CommitLog#add make another thread (DefinitionsUpdateVerbHandler$1.runMayThrow) stuck. In particular, `DefinitionsUpdateVerbHandler` is stuck in waiting for `SchemaKeyspace.flush`, which in turn waits for the `ColumnFamilyStore.waitForFlushes`.
> We are not sure what is the best place to mitigate the issue. One potential fix is to perhaps introduce a timeout limit (default no limit) in the add method, e.g., execute the I/O operations in a Future task and call waitOnFutures with a timeout in the end. If the timeout is exceeded, a WriteTimeoutException would be thrown.
> Any comments and suggestions would be appreciated.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@cassandra.apache.org
For additional commands, e-mail: commits-help@cassandra.apache.org