You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Dmitry Konstantinov <ne...@gmail.com> on 2025/02/03 16:26:52 UTC
Re: Unexplained stuck memtable flush
The issue is fixed now
On Fri, 15 Nov 2024 at 12:09, Dmitry Konstantinov <ne...@gmail.com>
wrote:
> Thank you!
> A ticket for the issue:
> https://issues.apache.org/jira/browse/CASSANDRA-20084
> <https://issues.apache.org/jira/browse/CASSANDRA-20084>
>
> Regards,
> Dmitry
>
> On Thu, 14 Nov 2024 at 10:33, Bowen Song via user <
> user@cassandra.apache.org> wrote:
>
>> Impressive! It all makes sense now.
>>
>> I believe this bug was accidentally introduced back in 2021 as a part of
>> CASSANDRA-16924 <https://issues.apache.org/jira/browse/CASSANDRA-16924>,
>> commit e5b92e1
>> <https://github.com/apache/cassandra/commit/e5b92e108851d2be81c43cbf982564f92d28aa6b#diff-a8247a86ff78ae4f477adbc7f9e93c6375e7d689a1265f26470fb9c42af74995>,
>> which removed the awaitUninterruptibly() method from the
>> WaitQueue$AbstractSignal in favour of the newly introduced
>> org.apache.cassandra.utils.concurrent.Awaitable class and split the code
>> below into two places.
>>
>> public void awaitUninterruptibly()
>> {
>> boolean interrupted = false;
>> while (!isSignalled())
>> {
>> if (Thread.interrupted())
>> interrupted = true;
>> LockSupport.park();
>> }
>> if (interrupted)
>> Thread.currentThread().interrupt();
>> checkAndClear();
>> }
>>
>> It's not impossible that someone runs into the same issue twice in a row
>> in a short window of time, but I wouldn't expect this to occur frequently
>> enough to catch most people's attentions. Because it rarely occurs and can
>> be "fixed" by simply restarting Cassandra, it has stayed in the codebase
>> for years without being discovered. I'm glad that we took the opportunity
>> to deep dive into this and found the root cause.
>>
>> Good job, Dmitry, and thank you for helping me on this.
>>
>>
>> On 13/11/2024 23:48, Dmitry Konstantinov wrote:
>>
>> Thank you. I think I have got the cause, it is a non-trivial puzzle which
>> took a few hours :-).
>>
>> So, we have the following stacktrace for "read-hotness-tracker:1" thread
>>
>> "read-hotness-tracker:1" daemon prio=5 tid=93 WAITING
>> at jdk.internal.misc.Unsafe.park(Native Method)
>> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:323)
>> at
>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$AbstractSignal.await(WaitQueue.java:289)
>> local variable:
>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$SignalWithListener#2086139
>> at
>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$AbstractSignal.await(WaitQueue.java:282)
>> local variable:
>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$SignalWithListener#2086139
>> at
>> org.apache.cassandra.utils.concurrent.Awaitable$Defaults.awaitUninterruptibly(Awaitable.java:186)
>> local variable:
>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$SignalWithListener#2086139
>> at
>> org.apache.cassandra.utils.concurrent.Awaitable$AbstractAwaitable.awaitUninterruptibly(Awaitable.java:259)
>> at
>> org.apache.cassandra.db.commitlog.AbstractCommitLogService.awaitSyncAt(AbstractCommitLogService.java:324)
>> local variable:
>> org.apache.cassandra.db.commitlog.PeriodicCommitLogService#1
>> local variable: com.codahale.metrics.Timer$Context#2086795
>> at
>> org.apache.cassandra.db.commitlog.PeriodicCommitLogService.maybeWaitForSync(PeriodicCommitLogService.java:42)
>> local variable:
>> org.apache.cassandra.db.commitlog.PeriodicCommitLogService#1
>> at
>> org.apache.cassandra.db.commitlog.AbstractCommitLogService.finishWriteFor(AbstractCommitLogService.java:284)
>> local variable:
>> org.apache.cassandra.db.commitlog.PeriodicCommitLogService#1
>> at org.apache.cassandra.db.commitlog.CommitLog.add(CommitLog.java:307)
>> local variable: org.apache.cassandra.db.commitlog.CommitLog#1
>> local variable:
>> org.apache.cassandra.io.util.DataOutputBuffer$1$1#61
>> local variable:
>> org.apache.cassandra.db.commitlog.CommitLogSegment$Allocation#1
>> at
>> org.apache.cassandra.db.CassandraKeyspaceWriteHandler.addToCommitLog(CassandraKeyspaceWriteHandler.java:100)
>> at
>> org.apache.cassandra.db.CassandraKeyspaceWriteHandler.beginWrite(CassandraKeyspaceWriteHandler.java:54)
>> local variable:
>> org.apache.cassandra.utils.concurrent.OpOrder$Group#8162
>> at org.apache.cassandra.db.Keyspace.applyInternal(Keyspace.java:628)
>> local variable: org.apache.cassandra.db.Keyspace#8
>> local variable: org.apache.cassandra.db.Mutation#54491
>> at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:512)
>> at org.apache.cassandra.db.Mutation.apply(Mutation.java:228)
>> at org.apache.cassandra.db.Mutation.apply(Mutation.java:248)
>> at
>> org.apache.cassandra.cql3.statements.ModificationStatement.executeInternalWithoutCondition(ModificationStatement.java:675)
>> at
>> org.apache.cassandra.cql3.statements.ModificationStatement.executeLocally(ModificationStatement.java:666)
>> at
>> org.apache.cassandra.cql3.QueryProcessor.executeInternal(QueryProcessor.java:447)
>> at
>> org.apache.cassandra.db.SystemKeyspace.persistSSTableReadMeter(SystemKeyspace.java:1488)
>> local variable: java.lang.String#42806
>> local variable: java.lang.String#47659
>> local variable:
>> org.apache.cassandra.io.sstable.UUIDBasedSSTableId#1389
>> local variable: org.apache.cassandra.metrics.RestorableMeter#752
>> at
>> org.apache.cassandra.io.sstable.format.SSTableReader$GlobalTidy$1.run(SSTableReader.java:2170)
>>
>> where we are waiting in the await() method of
>> WaitQueue$Standard$SignalWithListener#2086139 object.
>>
>> another input: WaitQueue$Standard$SignalWithListener#2086139 has the
>> following field values based on the screenshots:
>> state = *-1* (it means CANCELLED:
>> org.apache.cassandra.utils.concurrent.WaitQueue.Standard#CANCELLED = -1)
>> thread = null
>>
>> According to the code in WaitQueue.java such combination of values only
>> possible if we invoked cancel() on this SignalWithListener object but we
>> didn't do it in our code, it is in another branch of
>> AbstractCommitLogService.awaitSyncAt
>>
>> but let's check the await() logic more carefully:
>> public Signal await() throws InterruptedException
>> {
>> while (!isSignalled())
>> {
>> checkInterrupted();
>> LockSupport.park(); <--- we are here
>> }
>> checkAndClear();
>> return this;
>> }
>> and inspect unassuming checkInterrupted() method
>> private void checkInterrupted() throws InterruptedException
>> {
>> if (Thread.interrupted())
>> {
>> *cancel();*
>> throw new InterruptedException();
>> }
>> }
>> here we see that if the currently awaiting thread is interrupted then
>> SignalWithListener cancels itself.
>> but we throw new InterruptedException() here, so the execution should
>> fail with it.
>> Checking the thread stack trace and see that AbstractSignal.await() is
>> invoked from
>> org.apache.cassandra.utils.concurrent.Awaitable$AbstractAwaitable.awaitUninterruptibly(Awaitable.java:259)
>>
>> how it looks inside:
>> public static <A extends Awaitable> A awaitUninterruptibly(A await)
>> {
>> boolean interrupted = false;
>> while (true)
>> {
>> try
>> {
>> await.await();
>> break;
>> }
>> catch (InterruptedException e)
>> {
>> interrupted = true;
>> }
>> }
>> if (interrupted)
>> Thread.currentThread().interrupt();
>> return await;
>> }
>> Here we have a loop, if the current thread is interrupted - we have
>> InterruptedException thrown by await.await(), we catch it here and try
>> await.await() again. But in the previous invocation of await.await() we
>> have cancelled our Signal object, so the condition inside await() method:
>> isSignalled(): state == SIGNALLED is always false now plus if another
>> thread will invoke notifyAll - nothing will happen, because as a part of
>> cancellation our Signal object unregister itself from the queue and the
>> notifying thread will not able to find it to notify.
>> I have reproduced the case with a simple unit test.
>>
>> The last element of the puzzle - why is the thread interrupted? To
>> understand it - let's check there "read-hotness-tracker:1" thread execution
>> started. It is a background periodical runnable in
>> org.apache.cassandra.io.sstable.format.SSTableReader.GlobalTidy
>> readMeterSyncFuture = new
>> WeakReference<>(syncExecutor.scheduleAtFixedRate(new Runnable()
>> {
>> public void run()
>> {
>> if (obsoletion == null)
>> {
>> meterSyncThrottle.acquire();
>> SystemKeyspace.persistSSTableReadMeter(desc.ksname,
>> desc.cfname, desc.id, readMeter);
>> }
>> }
>> }, 1, 5, TimeUnit.MINUTES));
>>
>> let's check how we deal with readMeterSyncFuture ref and we see our
>> interruption:
>> private void stopReadMeterPersistence()
>> {
>> ScheduledFuture<?> readMeterSyncFutureLocal =
>> readMeterSyncFuture.get();
>> if (readMeterSyncFutureLocal != null)
>> {
>> * readMeterSyncFutureLocal.cancel(true); *<========= here we can
>> interrupt the thread
>> readMeterSyncFuture = NULL;
>> }
>> }
>>
>> stopReadMeterPersistence() is invoked by one of the following branches of
>> logic when an SSTable is not in use anymore:
>> org.apache.cassandra.io.sstable.format.SSTableReader#markObsolete
>> org.apache.cassandra.db.lifecycle.Helpers#markObsolete
>> org.apache.cassandra.db.lifecycle.Tracker#dropSSTables(...)
>> org.apache.cassandra.db.lifecycle.LifecycleTransaction#doCommit
>> org.apache.cassandra.db.lifecycle.LifecycleTransaction#doAbort
>>
>> So,the issue is caused by a combination of events with a right timing:
>> - an SSTable which was become obsolete at the middle of
>> persistSSTableReadMeter background job execution for this SSTable, so we
>> interrupted the job
>> - persistSSTableReadMeter was at that moment in the middle of write
>> operation, at commit log append step
>> - and the commit log append step was stuck due to a delay in commit log
>> sync (lastSyncedAt < syncTime condition in AbstractCommitLogService), so we
>> started to wait for it using await
>>
>>
>> The last observation - timing.
>> We have
>> org.apache.cassandra.db.commitlog.AbstractCommitLogService
>> lastSyncedAt = 1573038452910796
>>
>> com.codahale.metrics.Timer$Context#2086795 (created when the write
>> operation started to wait for commit log sync)
>> startTime = 1410129608743025
>>
>> both are from System.nanoTime()
>>
>> so, 1573038452910796 - 1410129608743025 = 162 908 844 167 771 ns = 162
>> 908 sec ~ 45 hours; the cause happened about that time ago.
>>
>> I will create a ticket for this issue to fix it.
>>
>> Regards,
>> Dmitry
>>
>>
>>
>> On Wed, 13 Nov 2024 at 22:11, Bowen Song via user <
>> user@cassandra.apache.org> wrote:
>>
>>> Please see the screenshots below.
>>>
>>> Unfortunately that the WaitQueue$Standard$SignalWithListener#2086139
>>> object is the GC root, and there's no references to it.
>>>
>>> I hope this helps.
>>>
>>>
>>>
>>>
>>> On 13/11/2024 21:33, Dmitry Konstantinov wrote:
>>>
>>> Hi Bowen, thank you for the details.
>>> Could you please also share a screenshot (Visual VM should be ok) for "read-hotness-tracker:1"
>>> thread with expanded local variable elements for the following lines:
>>> 1) at
>>> org.apache.cassandra.db.commitlog.AbstractCommitLogService.awaitSyncAt(AbstractCommitLogService.java:324),
>>> particularly com.codahale.metrics.Timer$Context#2086795 internals such
>>> as startTime
>>> 2) at
>>> org.apache.cassandra.utils.concurrent.Awaitable$Defaults.awaitUninterruptibly(Awaitable.java:186),
>>> particularly WaitQueue$Standard$SignalWithListener#2086139 internals
>>> such as thread, state
>>>
>>> Also, could you please render all GC paths to root for WaitQueue$Standard$SignalWithListener#2086139
>>> object and share the correspondent tree view?
>>>
>>> Regards,
>>> Dmitry
>>>
>>>
>>> On Tue, 12 Nov 2024 at 11:40, Bowen Song via user <
>>> user@cassandra.apache.org> wrote:
>>>
>>>> Just tried Eclipse Memory Analyzer, it shows the exact same local
>>>> variables as VisualVM, so there is no difference here.
>>>>
>>>> However, Eclipse Memory Analyzer is significantly slower (lagging) to
>>>> operate via X window forwarding or VNC (possibly due to the GUI decorations
>>>> and animations) and some features rely on a built-in web browser which I
>>>> can't get it to work on a headless server. I'm doing the analysis on a
>>>> headless server because my PC doesn't have enough RAM to load the large
>>>> heap dump file.
>>>>
>>>> See screenshot below for a comparison between Eclipse Memory Analyzer
>>>> and VisualVM on the variables referenced by the PERIODIC-COMMIT-LOG-SYNCER
>>>> thread.
>>>>
>>>> Eclipse Memory Analyzer
>>>>
>>>> VisualVM
>>>>
>>>>
>>>> On 11/11/2024 20:48, Dmitry Konstantinov wrote:
>>>>
>>>> >> If Eclipse Memory Analyzer also can't find the mysterious item, how
>>>> do I proceed from there? What else can I do?
>>>> We can analyze other variables from the heap dump, read code and
>>>> repeat, until we find a clue :-). As of now I do not see a much better
>>>> option. If the issue reproduces regularly - a custom build with extra logs
>>>> can be done to add more diagnostic info printing.
>>>> It is actually lucky that you have a heap dump, it can give a lot of
>>>> info, unfortunately only in a moment of time (so we cannot see from the
>>>> issue in dynamic).
>>>>
>>>> >> This has happened twice in the last 10 days, to two different nodes
>>>> in the same cluster.
>>>> Do you have heap dumps for the other failures?
>>>> How much time did you have between a node startup and the failure?
>>>>
>>>> Can you share field values
>>>> for org.apache.cassandra.db.commitlog.PeriodicCommitLogService and
>>>> org.apache.cassandra.db.commitlog.AbstractCommitLogService$SyncRunnable objects
>>>> using Eclipse Memory Analyzer
>>>> from the following thread?:
>>>> "PERIODIC-COMMIT-LOG-SYNCER" prio=5 tid=42 TIMED_WAITING
>>>> at jdk.internal.misc.Unsafe.park(Native Method)
>>>> at
>>>> java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
>>>> local variable: io.netty.util.concurrent.FastThreadLocalThread#5
>>>> at
>>>> java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1079)
>>>> local variable: java.util.concurrent.Semaphore$NonfairSync#1
>>>> local variable:
>>>> java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#157
>>>> at
>>>> java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1369)
>>>> at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:592)
>>>> at
>>>> org.apache.cassandra.utils.concurrent.Semaphore$Standard.tryAcquireUntil(Semaphore.java:142)
>>>> at
>>>> org.apache.cassandra.db.commitlog.AbstractCommitLogService$SyncRunnable.run(AbstractCommitLogService.java:216)
>>>>
>>>> It should looks like this:
>>>>
>>>> [image: image.png]
>>>>
>>>> [image: image.png]
>>>>
>>>> Regards,
>>>> Dmitry
>>>>
>>>>
>>>> On Fri, 8 Nov 2024 at 19:01, Bowen Song via user <
>>>> user@cassandra.apache.org> wrote:
>>>>
>>>>> Hi Dmitry,
>>>>>
>>>>> It indeed is very strange, either the tool I'm using is wrong, or
>>>>> there's something causing the item to evaporate from the queue mysteriously
>>>>> or never got into the queue.
>>>>>
>>>>> I've been using VisualVM to inspect the heap dump file and using OQL
>>>>> to find and explore the objects in it.
>>>>>
>>>>> VisualVM does show some local variables, but not all of them. This
>>>>> isn't an issue for types with little number of instances, because I can
>>>>> search objects by type to find them. But it can be troublesome when an
>>>>> object is a very common type.
>>>>>
>>>>> I will try Eclipse Memory Analyzer next week to see if it can find the
>>>>> missing item, but I have my doubts.
>>>>>
>>>>> I've read the code of WaitQueue and the
>>>>> AbstractCommitLogService.awaitSyncAt() method, and they both look correct
>>>>> to me. If Eclipse Memory Analyzer also can't find the mysterious item, how
>>>>> do I proceed from there? What else can I do?
>>>>>
>>>>> Cheers,
>>>>> Bowen
>>>>> On 08/11/2024 17:22, Dmitry Konstantinov wrote:
>>>>>
>>>>> Hi Bowen,
>>>>>
>>>>> >> protected volatile long lastSyncedAt = currentTimeMillis();". It
>>>>> looks like the code is inconsistent on whether lastSyncedAt is a relative
>>>>> monotonic clock or absolute epoch time.
>>>>> Yes, I think so, I am going to create a defect regarding it.
>>>>>
>>>>> >> I've also attempted to search for all RegisteredSignal objects in
>>>>> the heap, and found 15 of them, but none of them is related to the
>>>>> read-hotness-tracker:1 thread.
>>>>> It is very strange because the stack trace for this thread waits
>>>>> within the object and read-hotness-tracker:1 thread has active
>>>>> "WaitQueue.Signal signal" local variable..
>>>>> What tool do you use for the heap dump inspection? I use Eclipse
>>>>> Memory Analyzer. It has "threads_overview" view and you can check the
>>>>> values for local variables within a thread stack.
>>>>> Like this:
>>>>> [image: image.png]
>>>>>
>>>>> Regards,
>>>>> Dmitry
>>>>>
>>>>>
>>>>>
>>>>> On Fri, 8 Nov 2024 at 11:01, Bowen Song via user <
>>>>> user@cassandra.apache.org> wrote:
>>>>>
>>>>>> Hi Dmitry,
>>>>>>
>>>>>> Thank you for helping me.
>>>>>>
>>>>>> You are right, that's a monotonic clock. I was definitely wrongly
>>>>>> interpreting its value. I got misled by this line of code
>>>>>> <https://github.com/apache/cassandra/blob/8d91b469afd3fcafef7ef85c10c8acc11703ba2d/src/java/org/apache/cassandra/db/commitlog/AbstractCommitLogService.java#L63>:
>>>>>> "protected volatile long lastSyncedAt = currentTimeMillis();". It looks
>>>>>> like the code is inconsistent on whether lastSyncedAt is a relative
>>>>>> monotonic clock or absolute epoch time.
>>>>>>
>>>>>> Please see the attached cassandra.yaml with sensitive information
>>>>>> masked out with asterisks.
>>>>>>
>>>>>> There's no ERROR level log in the system.log other than some
>>>>>> guardrail violations (items_per_collection, if it matters) and random and
>>>>>> rare network issues such as connection timeout in the few days run up to
>>>>>> and during the event.
>>>>>>
>>>>>> We have the stdout and stderr captured in the systemd journal, and
>>>>>> they have been quiet in during that period as well, not a single line got
>>>>>> logged.
>>>>>>
>>>>>> There's 196 CommitLogSegment (more specifically, MemoryMappedSegment)
>>>>>> objects in the heap dump. Of these, 194 has cdcState = CONTAINS
>>>>>> lastSyncedOffset = 33554432 lastMarkerOffset = 33554432. The other two has
>>>>>> cdcState = CONTAINS lastSyncedOffset = 27007818 lastMarkerOffset = 27007818
>>>>>> and cdcState = PERMITTED lastSyncedOffset = 20 lastMarkerOffset = 20
>>>>>> respectively.
>>>>>>
>>>>>> The CDC index files have been deleted by the CDC consumer, and we
>>>>>> don't keep a copy of these files elsewhere, so I cannot check the offsets
>>>>>> in them unfortunately.
>>>>>>
>>>>>> Regarding the WaitQueue, I found the queue to be empty in the heap
>>>>>> dump, which means there's no RegisteredSignal objects in the queue at all.
>>>>>> The queue is a ConcurrentLinkedQueue object, which has a head and a tail.
>>>>>> The head has item=null and next=null, and the tail has item=null and
>>>>>> next=head. I've also attempted to search for all RegisteredSignal objects
>>>>>> in the heap, and found 15 of them, but none of them is related to the
>>>>>> read-hotness-tracker:1 thread. They are for the following threads:
>>>>>>
>>>>>> - MemtablePostFlush:1
>>>>>> - AntiEntropyStage:1
>>>>>> - MemtableFlushWriter:910
>>>>>> - COMMIT-LOG-ALLOCATOR
>>>>>> - NativePoolCleaner
>>>>>> - MemtableFlushWriter:911
>>>>>> - Native-Transport-Requests-135
>>>>>> - Native-Transport-Requests-139
>>>>>> - Native-Transport-Requests-132
>>>>>> - Native-Transport-Requests-143
>>>>>> - Native-Transport-Requests-129
>>>>>> - Native-Transport-Requests-140
>>>>>> - Native-Transport-Requests-153
>>>>>> - Native-Transport-Requests-141
>>>>>> - Native-Transport-Requests-137
>>>>>>
>>>>>> This looks rather suspicious to me, as the read-hotness-tracker:1
>>>>>> thread is blocked and waiting for a non-existence registered signal.
>>>>>>
>>>>>> Cheers,
>>>>>> Bowen
>>>>>> On 07/11/2024 21:30, Dmitry Konstantinov wrote:
>>>>>>
>>>>>> Hi Bowen,
>>>>>>
>>>>>> lastSyncedAt is updated by taking pollStarted: lastSyncedAt =
>>>>>> pollStarted;
>>>>>> where long pollStarted = clock.now();
>>>>>> the logic uses clock from: SyncRunnable sync = new
>>>>>> SyncRunnable(preciseTime)
>>>>>> preciseTime by default is SystemClock
>>>>>> clock.now() -> org.apache.cassandra.utils.Clock.Default#nanoTime ->
>>>>>> System.nanoTime()
>>>>>> so, the field is populated from System.nanoTime() which returns a
>>>>>> relative timestamp, which cannot be treated as an absolute time like
>>>>>> linux epoch (it is calculated like this:
>>>>>> https://github.com/openjdk/jdk/blob/jdk-11%2B20/src/hotspot/os/linux/os_linux.cpp#L1301
>>>>>> )
>>>>>>
>>>>>> Can you share your cassandra.yaml file? (with removed IPs, paths and
>>>>>> other security sensitive things, of course)
>>>>>> Do you have any exceptions in your system.log related to commit log?
>>>>>> Do you have JVM stdout/stderr captured to a file? Does it have any
>>>>>> exceptions? (which can be present there if Cassandra does not catch them
>>>>>> properly by itself)
>>>>>>
>>>>>> ---
>>>>>> How many CommitLogSegment objects do you have in your heap dump?
>>>>>> What are values for the following fields of CommitLogSegment objects?
>>>>>> lastSyncedOffset
>>>>>> lastMarkerOffset
>>>>>> cdcState
>>>>>>
>>>>>> Do you have CDC index files written by
>>>>>> org.apache.cassandra.db.commitlog.CommitLogSegment#writeCDCIndexFile ?
>>>>>> If you have them - what are the last offsets written there?
>>>>>>
>>>>>> Regards,
>>>>>> Dmitry
>>>>>>
>>>>>> On Thu, 7 Nov 2024 at 16:56, Bowen Song via user <
>>>>>> user@cassandra.apache.org> wrote:
>>>>>>
>>>>>>> The syncComplete is an instance of WaitQueue, and the
>>>>>>> syncComplete.queue is an instance of ConcurrentLinkedQueue. Surprisingly,
>>>>>>> the queue is empty. There is no item in the queue's linked list, only the
>>>>>>> head and tail nodes, each has item=null.
>>>>>>>
>>>>>>> The usage of the WaitQueue within the AbstractCommitLogService looks
>>>>>>> correct to me:
>>>>>>>
>>>>>>> do
>>>>>>> {
>>>>>>> WaitQueue.Signal signal = context != null ?
>>>>>>> syncComplete.register(context, Context::stop) : syncComplete.register();
>>>>>>> if (lastSyncedAt < syncTime)
>>>>>>> signal.awaitUninterruptibly();
>>>>>>> else
>>>>>>> signal.cancel();
>>>>>>> }
>>>>>>> while (lastSyncedAt < syncTime);
>>>>>>>
>>>>>>> This matches the example given in the WaitQueue's documentation
>>>>>>> (which is definitely missing a pair of curly brackets and has bad
>>>>>>> indentation):
>>>>>>>
>>>>>>> while (!conditionMet())
>>>>>>> Signal s = q.register();
>>>>>>> if (!conditionMet()) // or, perhaps more correctly,
>>>>>>> !conditionChanged()
>>>>>>> s.await();
>>>>>>> else
>>>>>>> s.cancel();
>>>>>>>
>>>>>>> So, why is the queue empty while the thread is blocked on waiting
>>>>>>> for the signal?
>>>>>>>
>>>>>>> Further digging showed that PeriodicCommitLogService.lastSyncedAt =
>>>>>>> 1573038452910796, which translates to 6 November 2019 11:07:32.910796,
>>>>>>> about 5 years ago.
>>>>>>>
>>>>>>> Is this suppose to be a wall clock time in milliseconds since 1
>>>>>>> January 1970 00:00? Or is it a monotonic clock time that has no meaning out
>>>>>>> of the context, and I'm just wrongly interpreting its value as a wall clock
>>>>>>> time?
>>>>>>>
>>>>>>>
>>>>>>> I've found that the syncComplete.queue is empty, meaning the
>>>>>>> WaitQueue object believes that there's nothing waiting for the signal, yet
>>>>>>> the "read-hotness-tracker:1" thread is clearly waiting for it.
>>>>>>> On 06/11/2024 13:49, Bowen Song via user wrote:
>>>>>>>
>>>>>>> I think I'm getting really close now. This seems to have something
>>>>>>> to do with the "read-hotness-tracker:1" thread. The thread dump is:
>>>>>>>
>>>>>>> "read-hotness-tracker:1" daemon prio=5 tid=93 WAITING
>>>>>>> at jdk.internal.misc.Unsafe.park(Native Method)
>>>>>>> at
>>>>>>> java.util.concurrent.locks.LockSupport.park(LockSupport.java:323)
>>>>>>> at
>>>>>>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$AbstractSignal.await(WaitQueue.java:289)
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$SignalWithListener#2086139
>>>>>>> at
>>>>>>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$AbstractSignal.await(WaitQueue.java:282)
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$SignalWithListener#2086139
>>>>>>> at
>>>>>>> org.apache.cassandra.utils.concurrent.Awaitable$Defaults.awaitUninterruptibly(Awaitable.java:186)
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.utils.concurrent.WaitQueue$Standard$SignalWithListener#2086139
>>>>>>> at
>>>>>>> org.apache.cassandra.utils.concurrent.Awaitable$AbstractAwaitable.awaitUninterruptibly(Awaitable.java:259)
>>>>>>> at
>>>>>>> org.apache.cassandra.db.commitlog.AbstractCommitLogService.awaitSyncAt(AbstractCommitLogService.java:324)
>>>>>>> <------ here
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.db.commitlog.PeriodicCommitLogService#1
>>>>>>> local variable: com.codahale.metrics.Timer$Context#2086795
>>>>>>> at
>>>>>>> org.apache.cassandra.db.commitlog.PeriodicCommitLogService.maybeWaitForSync(PeriodicCommitLogService.java:42)
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.db.commitlog.PeriodicCommitLogService#1
>>>>>>> at
>>>>>>> org.apache.cassandra.db.commitlog.AbstractCommitLogService.finishWriteFor(AbstractCommitLogService.java:284)
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.db.commitlog.PeriodicCommitLogService#1
>>>>>>> at
>>>>>>> org.apache.cassandra.db.commitlog.CommitLog.add(CommitLog.java:307)
>>>>>>> local variable: org.apache.cassandra.db.commitlog.CommitLog#1
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.io.util.DataOutputBuffer$1$1#61
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.db.commitlog.CommitLogSegment$Allocation#1
>>>>>>> at
>>>>>>> org.apache.cassandra.db.CassandraKeyspaceWriteHandler.addToCommitLog(CassandraKeyspaceWriteHandler.java:100)
>>>>>>> at
>>>>>>> org.apache.cassandra.db.CassandraKeyspaceWriteHandler.beginWrite(CassandraKeyspaceWriteHandler.java:54)
>>>>>>> <------ and here
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.utils.concurrent.OpOrder$Group#8162
>>>>>>> at
>>>>>>> org.apache.cassandra.db.Keyspace.applyInternal(Keyspace.java:628)
>>>>>>> local variable: org.apache.cassandra.db.Keyspace#8
>>>>>>> local variable: org.apache.cassandra.db.Mutation#54491
>>>>>>> at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:512)
>>>>>>> at org.apache.cassandra.db.Mutation.apply(Mutation.java:228)
>>>>>>> at org.apache.cassandra.db.Mutation.apply(Mutation.java:248)
>>>>>>> at
>>>>>>> org.apache.cassandra.cql3.statements.ModificationStatement.executeInternalWithoutCondition(ModificationStatement.java:675)
>>>>>>> at
>>>>>>> org.apache.cassandra.cql3.statements.ModificationStatement.executeLocally(ModificationStatement.java:666)
>>>>>>> at
>>>>>>> org.apache.cassandra.cql3.QueryProcessor.executeInternal(QueryProcessor.java:447)
>>>>>>> at
>>>>>>> org.apache.cassandra.db.SystemKeyspace.persistSSTableReadMeter(SystemKeyspace.java:1488)
>>>>>>> local variable: java.lang.String#42806
>>>>>>> local variable: java.lang.String#47659
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.io.sstable.UUIDBasedSSTableId#1389
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.metrics.RestorableMeter#752
>>>>>>> at
>>>>>>> org.apache.cassandra.io.sstable.format.SSTableReader$GlobalTidy$1.run(SSTableReader.java:2170)
>>>>>>> at
>>>>>>> org.apache.cassandra.concurrent.ExecutionFailure$1.run(ExecutionFailure.java:124)
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.concurrent.ExecutionFailure$1#122029
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.utils.WithResources$None$$Lambda$223#1
>>>>>>> at
>>>>>>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
>>>>>>> local variable:
>>>>>>> java.util.concurrent.Executors$RunnableAdapter#934
>>>>>>> at
>>>>>>> java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
>>>>>>> local variable:
>>>>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask#931
>>>>>>> at
>>>>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
>>>>>>> local variable:
>>>>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask#931
>>>>>>> at
>>>>>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
>>>>>>> local variable:
>>>>>>> org.apache.cassandra.concurrent.ScheduledThreadPoolExecutorPlus#6
>>>>>>> local variable:
>>>>>>> java.util.concurrent.ThreadPoolExecutor$Worker#7
>>>>>>> local variable:
>>>>>>> io.netty.util.concurrent.FastThreadLocalThread#7
>>>>>>> local variable:
>>>>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask#931
>>>>>>> at
>>>>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
>>>>>>> local variable:
>>>>>>> java.util.concurrent.ThreadPoolExecutor$Worker#7
>>>>>>> at
>>>>>>> io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
>>>>>>> local variable:
>>>>>>> io.netty.util.concurrent.FastThreadLocalRunnable#7
>>>>>>> at java.lang.Thread.run(Thread.java:829)
>>>>>>> local variable:
>>>>>>> io.netty.util.concurrent.FastThreadLocalThread#7
>>>>>>>
>>>>>>>
>>>>>>> In the CassandraKeyspaceWriteHandler.beginWrite() method:
>>>>>>>
>>>>>>> public WriteContext beginWrite(Mutation mutation, boolean
>>>>>>> makeDurable) throws RequestExecutionException
>>>>>>> {
>>>>>>> OpOrder.Group group = null;
>>>>>>> try
>>>>>>> {
>>>>>>> group = Keyspace.writeOrder.start(); // <--- here
>>>>>>>
>>>>>>> // write the mutation to the commitlog and memtables
>>>>>>> CommitLogPosition position = null;
>>>>>>> if (makeDurable)
>>>>>>> {
>>>>>>> position = addToCommitLog(mutation); // <--- and here
>>>>>>> }
>>>>>>> return new CassandraWriteContext(group, position);
>>>>>>> }
>>>>>>> catch (Throwable t)
>>>>>>> {
>>>>>>> if (group != null)
>>>>>>> {
>>>>>>> group.close();
>>>>>>> }
>>>>>>> throw t;
>>>>>>> }
>>>>>>> }
>>>>>>>
>>>>>>> The Keyspace.writeOrder.start() method call blocks the
>>>>>>> MemtableFlushWriter thread, and then it calls addToCommitLog(mutation)
>>>>>>> which indirectly calls AbstractCommitLogService.awaitSyncAt()
>>>>>>>
>>>>>>> void awaitSyncAt(long syncTime, Context context)
>>>>>>> {
>>>>>>> do
>>>>>>> {
>>>>>>> WaitQueue.Signal signal = context != null ?
>>>>>>> syncComplete.register(context, Context::stop) : syncComplete.register();
>>>>>>> if (lastSyncedAt < syncTime)
>>>>>>> signal.awaitUninterruptibly(); // <--- here
>>>>>>> else
>>>>>>> signal.cancel();
>>>>>>> }
>>>>>>> while (lastSyncedAt < syncTime);
>>>>>>> }
>>>>>>>
>>>>>>> This then got stuck on the signal.awaitUninterruptibly()
>>>>>>>
>>>>>>> Now I know what is blocking the memtable flushing, but I haven't
>>>>>>> been able to figure out is why it got stuck on waiting for that signal.
>>>>>>>
>>>>>>> I would appreciate it if anyone can offer some insight here.
>>>>>>>
>>>>>>>
>>>>>>> On 05/11/2024 17:48, Bowen Song via user wrote:
>>>>>>>
>>>>>>> I will give it a try and see what I can find. I plan to go down the
>>>>>>> rabbit hole tomorrow. Will keep you updated.
>>>>>>> On 05/11/2024 17:34, Jeff Jirsa wrote:
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On Nov 5, 2024, at 4:12 AM, Bowen Song via user
>>>>>>> <us...@cassandra.apache.org> <us...@cassandra.apache.org> wrote:
>>>>>>>
>>>>>>> Writes on this node starts to timeout and fail. But if left
>>>>>>> untouched, it's only gonna get worse, and eventually lead to JVM OOM and
>>>>>>> crash.
>>>>>>>
>>>>>>> By inspecting the heap dump created at OOM, we can see that both of
>>>>>>> the MemtableFlushWriter threads are stuck on line 1190
>>>>>>> <https://github.com/apache/cassandra/blob/8d91b469afd3fcafef7ef85c10c8acc11703ba2d/src/java/org/apache/cassandra/db/ColumnFamilyStore.java#L1190>
>>>>>>> in the ColumnFamilyStore.java:
>>>>>>>
>>>>>>> // mark writes older than the barrier as blocking
>>>>>>> progress, permitting them to exceed our memory limit
>>>>>>> // if they are stuck waiting on it, then wait for them
>>>>>>> all to complete
>>>>>>> writeBarrier.markBlocking();
>>>>>>> writeBarrier.await(); // <----------- stuck here
>>>>>>>
>>>>>>> And the MemtablePostFlush thread is stuck on line 1094
>>>>>>> <https://github.com/apache/cassandra/blob/8d91b469afd3fcafef7ef85c10c8acc11703ba2d/src/java/org/apache/cassandra/db/ColumnFamilyStore.java#L1094>
>>>>>>> in the same file.
>>>>>>>
>>>>>>> try
>>>>>>> {
>>>>>>> // we wait on the latch for the commitLogUpperBound
>>>>>>> to be set, and so that waiters
>>>>>>> // on this task can rely on all prior flushes being
>>>>>>> complete
>>>>>>> latch.await(); // <----------- stuck here
>>>>>>> }
>>>>>>> Our top suspect is CDC interacting with repair, since this started
>>>>>>> to happen shortly after we enabled CDC on the nodes, and each time repair
>>>>>>> was running. But we have not been able to reproduce this in a testing
>>>>>>> cluster, and don't know what's the next step to troubleshoot this issue. So
>>>>>>> I'm posting it in the mailing lists and hoping someone may know something
>>>>>>> about it or point me to the right direction.
>>>>>>>
>>>>>>>
>>>>>>> Wouldn’t be completely surprised if CDC or repair somehow has a
>>>>>>> barrier, I’ve also seen similar behavior pre-3.0 with “very long running
>>>>>>> read commands” that have a barrier on the memtable that prevent release.
>>>>>>>
>>>>>>> You’ve got the heap (great, way better than most people debugging),
>>>>>>> are you able to navigate through it and look for references to that
>>>>>>> memtable or other things holding a barrier?
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>> --
>>>>>> Dmitry Konstantinov
>>>>>>
>>>>>>
>>>>>
>>>>> --
>>>>> Dmitry Konstantinov
>>>>>
>>>>>
>>>>
>>>> --
>>>> Dmitry Konstantinov
>>>>
>>>>
>>>
>>> --
>>> Dmitry Konstantinov
>>>
>>>
>>
>> --
>> Dmitry Konstantinov
>>
>>
>
> --
> Dmitry Konstantinov
>
--
Dmitry Konstantinov