You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@ignite.apache.org by "Philipp Shergalis (Jira)" <ji...@apache.org> on 2024/10/21 08:41:00 UTC
[jira] [Comment Edited] (IGNITE-23325) Checkpoint read-lock timeout under high load
[ https://issues.apache.org/jira/browse/IGNITE-23325?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17891440#comment-17891440 ]
Philipp Shergalis edited comment on IGNITE-23325 at 10/21/24 8:40 AM:
----------------------------------------------------------------------
In CheckpointTimeoutLock.checkpointReadLock when new checkpoint is scheduled [we block until LOCK_RELEASED event|https://github.com/gridgain/apache-ignite-3/blob/main/modules/page-memory/src/main/java/org/apache/ignite/internal/pagememory/persistence/checkpoint/CheckpointTimeoutLock.java#L165] and fail on next loop iteration if timeout (10 seconds by default) passed. For this benchmark checkpoint time degrades to 10+ seconds, so we schedule a checkpoint, wait for 10+ seconds for last one to finish and new one to start and fail.
Discussed with [~ibessonov], throttling should fix that. Also discovered that sometimes we hold a read lock for 100-300 ms inserting 1 value, created ticket to investigate
Log example:
1) Checkpoint starts
{code:java}
[2024-10-18T07:32:20,622][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint started [checkpointId=368b18a1-e55b-475c-af30-29a042ed735b, checkpointBeforeWriteLockTime=1 1ms, checkpointWriteLockWait=1ms, checkpointListenersExecuteTime=0ms, checkpointWriteLockHoldTime=1ms, splitAndSortPagesDuration=144ms, pages=94368, reason='too many dirty pages']
{code}
2) Schedule a new one and wait for LOCK_RELEASED 6 seconds later
{code:java}
[2024-10-18T07:32:26,386][INFO ][org.apache.ignite.internal.benchmark.UpsertKvBenchmark.upsert-jmh-worker-14][CheckpointTimeoutLock] Waiting for LOCK_RELEASED{code}
3) 13 seconds later checkpoint finishes, new one starts, we get LOCK_RELEASED event and fail because timeout passed
{code:java}
[2024-10-18T07:32:39,216][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint finished [checkpointId=368b18a1-e55b-475c-af30-29a042ed735b, pages=94368, pagesWriteTime=47 27ms, fsyncTime=13863ms, totalTime=18752ms] {code}
{code:java}
[2024-10-18T07:32:39,227][INFO ][%node_3344%checkpoint-thread][CheckpointWorkflow] WRITE LOCK RELEASED AFTER 1
[2024-10-18T07:32:39,227][INFO ][%node_3344%JRaft-FSMCaller-Disruptor_stripe_43-0][CheckpointTimeoutLock] Didn't even try to lock{code}
[~ascherbakov], jfyi
was (Author: JIRAUSER303902):
In CheckpointTimeoutLock.checkpointReadLock when new checkpoint is scheduled [we block until LOCK_RELEASED event|https://github.com/gridgain/apache-ignite-3/blob/main/modules/page-memory/src/main/java/org/apache/ignite/internal/pagememory/persistence/checkpoint/CheckpointTimeoutLock.java#L165] and fail on next loop iteration if timeout (10 seconds by default) passed. For this benchmark checkpoint time degrades to 10+ seconds, so we schedule a checkpoint, wait for 10+ seconds for last one to finish and new one to start and fail.
Discussed with [~ibessonov], throttling should fix that. Also discovered that sometimes we hold a read lock for 100-300 ms inserting 1 value, created ticket to investigate
Log example:
1) Checkpoint starts
{code:java}
[2024-10-18T07:32:20,622][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint started [checkpointId=368b18a1-e55b-475c-af30-29a042ed735b, checkpointBeforeWriteLockTime=1 1ms, checkpointWriteLockWait=1ms, checkpointListenersExecuteTime=0ms, checkpointWriteLockHoldTime=1ms, splitAndSortPagesDuration=144ms, pages=94368, reason='too many dirty pages']
{code}
2) Schedule a new one and wait for LOCK_RELEASED 6 seconds later
{code:java}
[2024-10-18T07:32:26,386][INFO ][org.apache.ignite.internal.benchmark.UpsertKvBenchmark.upsert-jmh-worker-14][CheckpointTimeoutLock] Waiting for LOCK_RELEASED{code}
3) 13 seconds later checkpoint finishes, new one starts, we get LOCK_RELEASED event and fail because timeout passed
{code:java}
[2024-10-18T07:32:39,216][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint finished [checkpointId=368b18a1-e55b-475c-af30-29a042ed735b, pages=94368, pagesWriteTime=47 27ms, fsyncTime=13863ms, totalTime=18752ms] {code}
{code:java}
[2024-10-18T07:32:39,227][INFO ][%node_3344%checkpoint-thread][CheckpointWorkflow] WRITE LOCK RELEASED AFTER 1
[2024-10-18T07:32:39,227][INFO ][%node_3344%JRaft-FSMCaller-Disruptor_stripe_43-0][CheckpointTimeoutLock] Didn't even try to lock{code}
[~ascherbakov], jfyi
> Checkpoint read-lock timeout under high load
> --------------------------------------------
>
> Key: IGNITE-23325
> URL: https://issues.apache.org/jira/browse/IGNITE-23325
> Project: Ignite
> Issue Type: Bug
> Reporter: Ivan Bessonov
> Assignee: Philipp Shergalis
> Priority: Major
> Labels: ignite-3
>
> We encounter the following situation while having a very intensive load. It should not happen.
> Can be reproduced in {{ignite-22835-2}} on {{6bc1f97d0d2506b666975eea57b78ad8609b69d7}} commit.
> {noformat}
> [2024-09-25T11:03:12,180][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint started [checkpointId=db0f392d-7d71-4ef1-bb50-c17eb2d02d82, checkpointBeforeWriteLockTime=30ms, checkpointWriteLockWait=1ms, checkpointListenersExecuteTime=2ms, checkpointWriteLockHoldTime=4ms, splitAndSortPagesDuration=276ms, pages=80904, reason='too many dirty pages']
> 227808.089 ops/s
> [2024-09-25T11:03:13,438][WARN ][org.apache.ignite.internal.benchmark.UpsertKvBenchmark.upsert-jmh-worker-10][PersistentPageMemory] Page replacements started, pages will be rotated with disk, this will affect storage performance (consider increasing PageMemoryDataRegionConfiguration#setMaxSize for data region) [region=default]
> [2024-09-25T11:03:13,796][INFO ][checkpoint-runner-io0][CheckpointPagesWriter] Checkpoint pages were not written yet due to unsuccessful page write lock acquisition and will be retried [pageCount=1]
> [2024-09-25T11:03:14,071][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint finished [checkpointId=db0f392d-7d71-4ef1-bb50-c17eb2d02d82, pages=80904, pagesWriteTime=1614ms, fsyncTime=273ms, totalTime=2203ms]
> [2024-09-25T11:03:14,073][INFO ][%node_3344%compaction-thread][Compactor] Starting new compaction round [files=64]
> [2024-09-25T11:03:15,828][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint started [checkpointId=11157014-7a08-41e0-9e80-e26cf01656a8, checkpointBeforeWriteLockTime=21ms, checkpointWriteLockWait=0ms, checkpointListenersExecuteTime=6ms, checkpointWriteLockHoldTime=6ms, splitAndSortPagesDuration=205ms, pages=77234, reason='too many dirty pages']
> 231068.630 ops/s
> 271814.068 ops/s
> # Warmup Iteration 8: [2024-09-25T11:03:23,547][INFO ][%node_3344%compaction-thread][Compactor] Starting new compaction round [files=64]
> [2024-09-25T11:03:23,547][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint finished [checkpointId=11157014-7a08-41e0-9e80-e26cf01656a8, pages=77234, pagesWriteTime=2547ms, fsyncTime=5099ms, totalTime=7951ms]
> 26376.850 ops/s
> # Warmup Iteration 9: [2024-09-25T11:03:23,685][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint started [checkpointId=b1b2541a-e948-46cf-821b-412ea120146c, checkpointBeforeWriteLockTime=9ms, checkpointWriteLockWait=0ms, checkpointListenersExecuteTime=1ms, checkpointWriteLockHoldTime=1ms, splitAndSortPagesDuration=125ms, pages=95251, reason='too many dirty pages']
> [2024-09-25T11:03:34,706][INFO ][%node_3344%compaction-thread][Compactor] Compaction round finished [duration=11159ms]
> [2024-09-25T11:03:34,707][INFO ][%node_3344%compaction-thread][Compactor] Starting new compaction round [files=41]
> [2024-09-25T11:03:35,444][INFO ][%node_3344%lease-updater][LeaseUpdater] Leases updated (printed once per 10 iteration(s)): [inCurrentIteration=LeaseStats [leasesCreated=0, leasesPublished=0, leasesProlonged=64, leasesWithoutCandidates=0], active=64, currentAssignmentsSize=64].
> [2024-09-25T11:03:39,075][WARN ][%node_3344%meta-storage-safe-time-0][TrackableNetworkMessageHandler] Message handling has been too long [duration=11ms, message=class org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]
> [2024-09-25T11:03:40,287][INFO ][%node_3344%checkpoint-thread][Checkpointer] Checkpoint finished [checkpointId=b1b2541a-e948-46cf-821b-412ea120146c, pages=95251, pagesWriteTime=3098ms, fsyncTime=13146ms, totalTime=16740ms]
> [2024-09-25T11:03:40,307][WARN ][%node_3344%JRaft-FSMCaller-Disruptor_stripe_24-0][FailureProcessor] Possible failure suppressed according to a configured handler [hnd=NoOpFailureHandler [super=AbstractFailureHandler [ignoredFailureTypes=UnmodifiableSet [SYSTEM_WORKER_BLOCKED, SYSTEM_CRITICAL_OPERATION_TIMEOUT]]], failureCtx=SYSTEM_CRITICAL_OPERATION_TIMEOUT]
> org.apache.ignite.internal.lang.IgniteInternalException: Checkpoint read lock acquisition has been timed out.
> at org.apache.ignite.internal.pagememory.persistence.checkpoint.CheckpointTimeoutLock.failCheckpointReadLock(CheckpointTimeoutLock.java:242) ~[ignite-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.pagememory.persistence.checkpoint.CheckpointTimeoutLock.checkpointReadLock(CheckpointTimeoutLock.java:130) ~[ignite-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.storage.pagememory.mv.PersistentPageMemoryMvPartitionStorage.lambda$runConsistently$0(PersistentPageMemoryMvPartitionStorage.java:175) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.storage.pagememory.mv.AbstractPageMemoryMvPartitionStorage.busy(AbstractPageMemoryMvPartitionStorage.java:659) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.storage.pagememory.mv.PersistentPageMemoryMvPartitionStorage.runConsistently(PersistentPageMemoryMvPartitionStorage.java:170) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.raft.snapshot.outgoing.SnapshotAwarePartitionDataStorage.runConsistently(SnapshotAwarePartitionDataStorage.java:76) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.raft.PartitionListener.advanceLastAppliedIndexConsistently(PartitionListener.java:508) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.raft.PartitionListener.handleSafeTimeSyncCommand(PartitionListener.java:504) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.raft.PartitionListener.lambda$onWriteBusy$2(PartitionListener.java:250) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133) ~[?:?]
> at org.apache.ignite.internal.table.distributed.raft.PartitionListener.onWriteBusy(PartitionListener.java:199) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.raft.PartitionListener.onWrite(PartitionListener.java:192) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.raft.server.impl.JraftServerImpl$DelegatingStateMachine.onApply(JraftServerImpl.java:784) ~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.raft.jraft.core.FSMCallerImpl.doApplyTasks(FSMCallerImpl.java:686) ~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.raft.jraft.core.FSMCallerImpl.doCommitted(FSMCallerImpl.java:654) ~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.raft.jraft.core.FSMCallerImpl.runApplyTask(FSMCallerImpl.java:573) ~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.raft.jraft.core.FSMCallerImpl$ApplyTaskHandler.onEvent(FSMCallerImpl.java:246) ~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.raft.jraft.core.FSMCallerImpl$ApplyTaskHandler.onEvent(FSMCallerImpl.java:240) ~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.consumeBatch(StripedDisruptor.java:456) ~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:334) ~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.raft.jraft.disruptor.StripedDisruptor$StripeEntryHandler.onEvent(StripedDisruptor.java:272) ~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
> at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:167) ~[disruptor-4.0.0.jar:?]
> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:122) ~[disruptor-4.0.0.jar:?]
> at java.base/java.lang.Thread.run(Thread.java:1583) [?:?]
> [2024-09-25T11:03:40,321][WARN ][org.apache.ignite.internal.benchmark.UpsertKvBenchmark.upsert-jmh-worker-6][FailureProcessor] Possible failure suppressed according to a configured handler [hnd=NoOpFailureHandler [super=AbstractFailureHandler [ignoredFailureTypes=UnmodifiableSet [SYSTEM_WORKER_BLOCKED, SYSTEM_CRITICAL_OPERATION_TIMEOUT]]], failureCtx=SYSTEM_CRITICAL_OPERATION_TIMEOUT]
> org.apache.ignite.internal.lang.IgniteInternalException: Checkpoint read lock acquisition has been timed out.
> at org.apache.ignite.internal.pagememory.persistence.checkpoint.CheckpointTimeoutLock.failCheckpointReadLock(CheckpointTimeoutLock.java:242) ~[ignite-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.pagememory.persistence.checkpoint.CheckpointTimeoutLock.checkpointReadLock(CheckpointTimeoutLock.java:130) ~[ignite-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.storage.pagememory.mv.PersistentPageMemoryMvPartitionStorage.lambda$runConsistently$0(PersistentPageMemoryMvPartitionStorage.java:175) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.storage.pagememory.mv.AbstractPageMemoryMvPartitionStorage.busy(AbstractPageMemoryMvPartitionStorage.java:659) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.storage.pagememory.mv.PersistentPageMemoryMvPartitionStorage.runConsistently(PersistentPageMemoryMvPartitionStorage.java:170) ~[ignite-storage-page-memory-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.raft.snapshot.outgoing.SnapshotAwarePartitionDataStorage.runConsistently(SnapshotAwarePartitionDataStorage.java:76) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.StorageUpdateHandler.handleUpdate(StorageUpdateHandler.java:109) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$applyUpdateCommand$125(PartitionReplicaListener.java:2766) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.tracing.Instrumentation.measure(Instrumentation.java:217) ~[ignite-core-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$applyUpdateCommand$126(PartitionReplicaListener.java:2766) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?]
> at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2341) ~[?:?]
> at org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.applyUpdateCommand(PartitionReplicaListener.java:2754) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.applyUpdateCommand(PartitionReplicaListener.java:2805) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$processSingleEntryAction$147(PartitionReplicaListener.java:3053) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?]
> at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2341) ~[?:?]
> at org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$processSingleEntryAction$149(PartitionReplicaListener.java:3052) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]
> at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?]
> at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2341) ~[?:?]
> at org.apache.ignite.internal.table.distributed.replicator.PartitionReplicaListener.lambda$processSingleEntryAction$152(PartitionReplicaListener.java:3050) ~[ignite-table-3.0.0-SNAPSHOT.jar:?]{noformat}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)