[
https://issues.apache.org/jira/browse/IGNITE-29192?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dmitry Werner updated IGNITE-29192:
-----------------------------------
Description:
[https://ci2.ignite.apache.org/test/1116565989146548944?currentProjectId=IgniteTests24Java8&branch=%3Cdefault%3E]
*Root cause*
The test runs in two phases on the same persistence directory. In phase 1 it
logs a CheckpointRecord, saves the returned WALPointer start (which lands in
WAL segment 0), writes 1000 pages across 20 simulated checkpoints with
AlwaysWriteFullPages=true and WalMode=LOG_ONLY, then stops the node. In phase 2
it restarts the node and calls wal.replay(start).
The test never sets maxWalArchiveSize, so the default DFLT_WAL_ARCHIVE_MAX_SIZE
of 1 GiB applies (DataStorageConfiguration.java:130) and the background
FileCleaner worker is active. Two facts make the failure possible:
1. The cleaner wakes up at half the limit, not at 1 GiB. FileCleaner blocks in
SegmentArchiveSizeStorage.awaitExceedMaxSize(minWalArchiveSize)
(FileWriteAheadLogManager.java:3304, SegmentArchiveSizeStorage.java:154), where
minWalArchiveSize = maxWalArchiveSize / 2 = 512 MB
(FileWriteAheadLogManager.java:3656-3663). During phase 1 the 8 update threads
write full-page snapshots non-stop, and the WAL grows past ~9 segments (~576
MB), so the cleaner becomes eligible.
2. Segment 0 loses its protection only at the end of the test. While
checkpoints are disabled, the stale lastCheckpointPtr (initially
WALPointer(0,0,0), FileWriteAheadLogManager.java:383) actually protects segment
0: the cleaner's gate fileDesc.idx >= lastCheckpointPtr.index() breaks the
scan, and doCheckpoint() is skipped entirely while disabled — even forced
checkpoints are merely rescheduled (Checkpointer.java:283-289). The protection
is lifted when the test re-enables checkpoints in the finally block
(dbMgr.enableCheckpoints(true) before stopAllGrids(false)): a real checkpoint
runs at the WAL tail (segment ~8), and CheckpointWorkflow.markCheckpointEnd
calls wal.notchLastCheckpointPtr(checkpointMark) (CheckpointWorkflow.java:571,
FileWriteAheadLogManager.java:1155), advancing lastCheckpointPtr to index ~8.
Segments 0..7 are now all "obsolete" from the cleaner's point of view, and its
scan always marks the oldest unprotected segment for deletion ("Ensure that
there will be exactly removed at least one segment",
FileWriteAheadLogManager.java:3315-3327). The test's start pointer is never
reserved, so segment 0 is deleted if the cleaner wins the race against node
shutdown.
On restart the archive starts at segment 1, so RecordsIterator.init() throws
IgniteCheckedException: WAL history is too short [descs[0].idx=1, start.idx=0]
(FileWriteAheadLogManager.java:2957), which is exactly the failure captured in
CI: testCheckpointSimulationMultiThreaded:192->verifyReads:674 with descs=idx
1..8, start=WALPointer [idx=0, fileOff=9791920, len=41].
This is a timing-dependent race between the FileCleaner's truncation and
stopAllGrids() in the window after checkpoints are re-enabled: if the cleaner
gets scheduled in that window the test fails, otherwise segment 0 survives and
the test passes. That explains the flakiness on fast CI agents.
*Fix*
One line in getConfiguration — disable WAL archive truncation so the
FileCleaner never starts and segment 0 is guaranteed to survive until phase 2:
setDataStorageConfiguration(
new DataStorageConfiguration()
.setCheckpointFrequency(500)
.setWalMode(WALMode.LOG_ONLY)
.setAlwaysWriteFullPages(true)
.setMaxWalArchiveSize(DataStorageConfiguration.UNLIMITED_WAL_ARCHIVE)
// add this
.setDefaultDataRegionConfiguration(...))
With UNLIMITED_WAL_ARCHIVE the manager is created in unlimited mode
(walArchiveUnlimited(), FileWriteAheadLogManager.java:3253), the FileCleaner
worker is never constructed or started (its constructor asserts
!walArchiveUnlimited(), :3295), so no deletion path exists at all and the fix
deterministically removes the race rather than just shrinking it.
This is the same pattern already used by sibling PDS tests that replay WAL
after a restart (IgnitePdsStartWIthEmptyArchive,
IgnitePdsReserveWalSegmentsTest, IgniteLocalWalSizeTest,
IgniteWalRebalanceLoggingTest). It is safe for all five tests in the class —
none depend on archive truncation, each runs in a clean persistence dir wiped
by beforeTest/afterTest, and the largest WAL footprint is ~9-10 segments × 64
MB ≈ a few hundred MiB.
was:
https://ci2.ignite.apache.org/test/1116565989146548944?currentProjectId=IgniteTests24Java8&branch=%3Cdefault%3E
*Root cause*
The test runs in two phases on the same persistence directory. In phase 1 it
logs a CheckpointRecord, saves the returned WALPointer start (which lands in
WAL segment 0), writes 1000 pages across 20 simulated checkpoints with
AlwaysWriteFullPages=true and WalMode=LOG_ONLY, then stops the node. In phase 2
it restarts the node and calls wal.replay(start).
The test never sets maxWalArchiveSize, so the default 1 GiB applies and the
background FileCleaner worker is active. Because real checkpoints are disabled
(dbMgr.enableCheckpoints(false)), the cleaner's lastCheckpointPtr lags behind,
and it legitimately deletes segment 0 (where start lives) as "obsolete" before
the node stops. On restart the archive starts at segment 1, so
RecordsIterator.init() throws IgniteCheckedException: WAL history is too short
[descs[0].idx=1, start.idx=0].
This is a timing-dependent race: on fast CI agents the cleaner wins the race
and the test fails; on slower runs segment 0 survives and the test passes.
*Fix*
One line in getConfiguration — disable WAL archive truncation so the cleaner
never starts and segment 0 is guaranteed to survive until phase 2:
.setDataStorageConfiguration(
new DataStorageConfiguration()
.setCheckpointFrequency(500)
.setWalMode(WALMode.LOG_ONLY)
.setAlwaysWriteFullPages(true)
.setMaxWalArchiveSize(DataStorageConfiguration.UNLIMITED_WAL_ARCHIVE)
// add this
.setDefaultDataRegionConfiguration(...))
This is the same pattern already used by sibling PDS tests that replay WAL
after a restart (IgnitePdsStartWIthEmptyArchive,
IgnitePdsReserveWalSegmentsTest, IgniteLocalWalSizeTest,
IgniteWalRebalanceLoggingTest). It is safe for all five tests in the class —
none depend on archive truncation, each runs in a clean persistence dir wiped
by afterTest, and the largest WAL footprint is a few hundred MiB.
> Fix flaky
> IgnitePdsCheckpointSimulationWithRealCpDisabledTest.testCheckpointSimulationMultiThreaded
> ---------------------------------------------------------------------------------------------------
>
> Key: IGNITE-29192
> URL: https://issues.apache.org/jira/browse/IGNITE-29192
> Project: Ignite
> Issue Type: Bug
> Reporter: Dmitry Werner
> Assignee: Dmitry Werner
> Priority: Minor
> Labels: MakeTeamcityGreenAgain
> Time Spent: 10m
> Remaining Estimate: 0h
>
> [https://ci2.ignite.apache.org/test/1116565989146548944?currentProjectId=IgniteTests24Java8&branch=%3Cdefault%3E]
> *Root cause*
> The test runs in two phases on the same persistence directory. In phase 1 it
> logs a CheckpointRecord, saves the returned WALPointer start (which lands in
> WAL segment 0), writes 1000 pages across 20 simulated checkpoints with
> AlwaysWriteFullPages=true and WalMode=LOG_ONLY, then stops the node. In phase
> 2 it restarts the node and calls wal.replay(start).
> The test never sets maxWalArchiveSize, so the default
> DFLT_WAL_ARCHIVE_MAX_SIZE of 1 GiB applies
> (DataStorageConfiguration.java:130) and the background FileCleaner worker is
> active. Two facts make the failure possible:
> 1. The cleaner wakes up at half the limit, not at 1 GiB. FileCleaner blocks
> in SegmentArchiveSizeStorage.awaitExceedMaxSize(minWalArchiveSize)
> (FileWriteAheadLogManager.java:3304, SegmentArchiveSizeStorage.java:154),
> where minWalArchiveSize = maxWalArchiveSize / 2 = 512 MB
> (FileWriteAheadLogManager.java:3656-3663). During phase 1 the 8 update
> threads write full-page snapshots non-stop, and the WAL grows past ~9
> segments (~576 MB), so the cleaner becomes eligible.
> 2. Segment 0 loses its protection only at the end of the test. While
> checkpoints are disabled, the stale lastCheckpointPtr (initially
> WALPointer(0,0,0), FileWriteAheadLogManager.java:383) actually protects
> segment 0: the cleaner's gate fileDesc.idx >= lastCheckpointPtr.index()
> breaks the scan, and doCheckpoint() is skipped entirely while disabled — even
> forced checkpoints are merely rescheduled (Checkpointer.java:283-289). The
> protection is lifted when the test re-enables checkpoints in the finally
> block (dbMgr.enableCheckpoints(true) before stopAllGrids(false)): a real
> checkpoint runs at the WAL tail (segment ~8), and
> CheckpointWorkflow.markCheckpointEnd calls
> wal.notchLastCheckpointPtr(checkpointMark) (CheckpointWorkflow.java:571,
> FileWriteAheadLogManager.java:1155), advancing lastCheckpointPtr to index ~8.
> Segments 0..7 are now all "obsolete" from the cleaner's point of view, and
> its scan always marks the oldest unprotected segment for deletion ("Ensure
> that there will be exactly removed at least one segment",
> FileWriteAheadLogManager.java:3315-3327). The test's start pointer is never
> reserved, so segment 0 is deleted if the cleaner wins the race against node
> shutdown.
> On restart the archive starts at segment 1, so RecordsIterator.init() throws
> IgniteCheckedException: WAL history is too short [descs[0].idx=1,
> start.idx=0] (FileWriteAheadLogManager.java:2957), which is exactly the
> failure captured in CI:
> testCheckpointSimulationMultiThreaded:192->verifyReads:674 with descs=idx
> 1..8, start=WALPointer [idx=0, fileOff=9791920, len=41].
> This is a timing-dependent race between the FileCleaner's truncation and
> stopAllGrids() in the window after checkpoints are re-enabled: if the cleaner
> gets scheduled in that window the test fails, otherwise segment 0 survives
> and the test passes. That explains the flakiness on fast CI agents.
> *Fix*
> One line in getConfiguration — disable WAL archive truncation so the
> FileCleaner never starts and segment 0 is guaranteed to survive until phase 2:
> setDataStorageConfiguration(
> new DataStorageConfiguration()
> .setCheckpointFrequency(500)
> .setWalMode(WALMode.LOG_ONLY)
> .setAlwaysWriteFullPages(true)
> .setMaxWalArchiveSize(DataStorageConfiguration.UNLIMITED_WAL_ARCHIVE)
> // add this
> .setDefaultDataRegionConfiguration(...))
> With UNLIMITED_WAL_ARCHIVE the manager is created in unlimited mode
> (walArchiveUnlimited(), FileWriteAheadLogManager.java:3253), the FileCleaner
> worker is never constructed or started (its constructor asserts
> !walArchiveUnlimited(), :3295), so no deletion path exists at all and the fix
> deterministically removes the race rather than just shrinking it.
> This is the same pattern already used by sibling PDS tests that replay WAL
> after a restart (IgnitePdsStartWIthEmptyArchive,
> IgnitePdsReserveWalSegmentsTest, IgniteLocalWalSizeTest,
> IgniteWalRebalanceLoggingTest). It is safe for all five tests in the class —
> none depend on archive truncation, each runs in a clean persistence dir wiped
> by beforeTest/afterTest, and the largest WAL footprint is ~9-10 segments × 64
> MB ≈ a few hundred MiB.
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
