kvcache-ai/Mooncake

Fork 0

mirror of https://github.com/kvcache-ai/Mooncake.git synced 2026-11-05 01:17:55 +00:00

[GH-ISSUE #3245] [Store][Test] PutStartExpiringTest can race with asynchronous eviction under coverage #831

New issue

Closed

opened 2026-10-29 21:19:59 +00:00 by bsakaguchi · 1 comment

bsakaguchi commented

2026-10-29 21:19:59 +00:00

Owner

Originally created by @Icedcoco on GitHub (Aug 3, 2026).
Original GitHub issue: https://github.com/kvcache-ai/Mooncake/issues/3245

Bug Report

Summary

MasterServiceTest.PutStartExpiringTest failed in PR #3201 because the test retries PutStart() after a fixed 50 ms sleep, while the memory eviction that releases expired/discarded replicas runs asynchronously.

In the failed CI run, the eviction cycle took approximately 59 ms. The retry therefore happened before eviction completed and before capacity became available.

This appears to be a pre-existing timing-sensitive test rather than a functional regression introduced by PR #3201.

Observed failure

Failed CI job:

https://github.com/kvcache-ai/Mooncake/actions/runs/30544794003/job/90903216242

Environment:

GitHub Actions Ubuntu 22.04 runner
Python 3.12 build job
Coverage instrumentation enabled through --coverage
109 CTest targets executed
108 passed
Only master_service_test failed
Inside that binary, 145 of 146 tests passed

Failure:

[ RUN      ] MasterServiceTest.PutStartExpiringTest

/home/runner/work/Mooncake/Mooncake/mooncake-store/tests/master_service_test.cpp:5472: Failure
Value of: put_start_result.has_value()
  Actual: false
Expected: true

unknown file: Failure
C++ exception with description "Bad expected access" thrown in the test body.

The Bad expected access exception is secondary. The test uses a non-fatal
EXPECT_TRUE() and then immediately calls .value() on the failed result.

Test scenario

PutStartExpiringTest configures:

put_start_discard_timeout_sec = 3
put_start_release_timeout_sec = 5
Three memory segments of 16 MiB each
Object size of 6 MiB
Three replicas per object

After the replicas of key_2 become eligible for discard/release, the test:

Calls PutStart(key_2) and expects NO_AVAILABLE_HANDLE.
This failed allocation triggers asynchronous memory eviction.
Sleeps for a fixed 50 ms.
Calls PutStart(key_2) again and expects success.

Relevant test code is around:

mooncake-store/tests/master_service_test.cpp:5460-5473

CI timing evidence

The failed job contains the following sequence:

15:49:21.504084 [EVICT-TRIGGER] memory_ratio=0.75 ... need_mem_eviction=1
15:49:21.563361 [EVICT-RESULT] evicted_count=0 ...
15:49:21.563400 [EVICT-DONE] BatchEvict execution completed.

The eviction cycle took approximately 59.3 ms from trigger to completion.
This already exceeds the test's fixed 50 ms wait.

The assertion failed before the EVICT-RESULT and EVICT-DONE messages were
emitted, which is consistent with the second PutStart() running before
discarded replicas had been released.

The test does not print the error returned by the second PutStart().
NO_AVAILABLE_HANDLE is the most likely result based on the allocation path,
but this should be confirmed by improving the assertion diagnostics.

Relevant implementation path

When allocation cannot find enough memory replicas,
AllocateAndInsertMetadata():

Sets need_mem_eviction_ = true.
Returns ErrorCode::NO_AVAILABLE_HANDLE.

The background eviction thread checks this flag asynchronously. It sleeps for
up to 10 ms between checks and then calls BatchEvict().

BatchEvict() scans all 1024 metadata shards, using up to 16 worker threads,
joins those workers, and only later calls
ReleaseExpiredDiscardedReplicas(now).

There is no synchronization between the test and completion of this eviction
cycle. The test therefore assumes that thread wake-up, shard scanning, and
discarded-replica release will all finish within 50 ms.

Coverage instrumentation and CI load make that assumption unreliable.

The evicted_count=0 log line does not show whether discarded replicas were
released. That count is separate from the discarded-replica release count, so
it should not be interpreted as evidence that no memory was released.

Relationship to PR #3201

PR #3201 changes only the oplog batch storage, codec, and snapshot tests:

oplog_batch_storage.h/.cpp
oplog_batch_types.h
oplog_batch_codec.cpp
Oplog batch storage/codec tests
snapshot_child_process_test.cpp

It does not modify:

master_service.cpp
master_service.h
master_service_test.cpp
The allocation or eviction implementation

Other relevant tests, including master_service_ha_test and all modified
oplog batch tests, passed in the same CI job.

Therefore, the available evidence indicates that PR #3201 exposed an existing
timing-sensitive test rather than introducing the failure directly.

Local result

The test passed five consecutive iterations in a local non-coverage build:

LSAN_OPTIONS=detect_leaks=0 \
./build/mooncake-store/tests/master_service_test \
  --gtest_filter=MasterServiceTest.PutStartExpiringTest \
  --gtest_repeat=5 \
  --gtest_break_on_failure=0

Local eviction cycles completed in approximately 6-14 ms, so the fixed 50 ms
sleep happened to be sufficient. This difference further supports a
load-sensitive race rather than a deterministic functional failure.

Suggested fix

Replace the fixed 50 ms sleep with a bounded condition-based retry:

Reuse the existing MasterServiceTest::WaitUntil() helper.
Retry PutStart() until it succeeds or the timeout expires.
Treat NO_AVAILABLE_HANDLE as the expected transient result.
Fail immediately on any unexpected error.
Preserve the successful result instead of calling PutStart() again.
Use ASSERT_TRUE() before accessing .value().
Include the returned error code in failure diagnostics.

Increasing the sleep to another fixed value would only reduce the probability
of failure and would keep the test timing-dependent.

A production change to reorder work inside BatchEvict() may be worth
evaluating separately, but it is not required to make this test deterministic.

Acceptance criteria

PutStartExpiringTest waits for observable eviction completion instead of a
fixed delay.
A failed retry reports the actual returned error.
The test never calls .value() after a non-fatal failed assertion.
The test passes repeatedly with coverage instrumentation and under CI load.
No production eviction behavior is changed solely to accommodate the test.

Before submitting...

Ensure you searched for relevant issues and read the [documentation]

Originally created by @Icedcoco on GitHub (Aug 3, 2026). Original GitHub issue: https://github.com/kvcache-ai/Mooncake/issues/3245 ### Bug Report ## Summary `MasterServiceTest.PutStartExpiringTest` failed in PR #3201 because the test retries `PutStart()` after a fixed 50 ms sleep, while the memory eviction that releases expired/discarded replicas runs asynchronously. In the failed CI run, the eviction cycle took approximately 59 ms. The retry therefore happened before eviction completed and before capacity became available. This appears to be a pre-existing timing-sensitive test rather than a functional regression introduced by PR #3201. ## Observed failure Related PR: https://github.com/kvcache-ai/Mooncake/pull/3201 Failed CI job: https://github.com/kvcache-ai/Mooncake/actions/runs/30544794003/job/90903216242 Environment: - GitHub Actions Ubuntu 22.04 runner - Python 3.12 build job - Coverage instrumentation enabled through `--coverage` - 109 CTest targets executed - 108 passed - Only `master_service_test` failed - Inside that binary, 145 of 146 tests passed Failure: ```text [ RUN ] MasterServiceTest.PutStartExpiringTest /home/runner/work/Mooncake/Mooncake/mooncake-store/tests/master_service_test.cpp:5472: Failure Value of: put_start_result.has_value() Actual: false Expected: true unknown file: Failure C++ exception with description "Bad expected access" thrown in the test body. ``` The `Bad expected access` exception is secondary. The test uses a non-fatal `EXPECT_TRUE()` and then immediately calls `.value()` on the failed result. ## Test scenario `PutStartExpiringTest` configures: - `put_start_discard_timeout_sec = 3` - `put_start_release_timeout_sec = 5` - Three memory segments of 16 MiB each - Object size of 6 MiB - Three replicas per object After the replicas of `key_2` become eligible for discard/release, the test: 1. Calls `PutStart(key_2)` and expects `NO_AVAILABLE_HANDLE`. 2. This failed allocation triggers asynchronous memory eviction. 3. Sleeps for a fixed 50 ms. 4. Calls `PutStart(key_2)` again and expects success. Relevant test code is around: `mooncake-store/tests/master_service_test.cpp:5460-5473` ## CI timing evidence The failed job contains the following sequence: ```text 15:49:21.504084 [EVICT-TRIGGER] memory_ratio=0.75 ... need_mem_eviction=1 15:49:21.563361 [EVICT-RESULT] evicted_count=0 ... 15:49:21.563400 [EVICT-DONE] BatchEvict execution completed. ``` The eviction cycle took approximately 59.3 ms from trigger to completion. This already exceeds the test's fixed 50 ms wait. The assertion failed before the `EVICT-RESULT` and `EVICT-DONE` messages were emitted, which is consistent with the second `PutStart()` running before discarded replicas had been released. The test does not print the error returned by the second `PutStart()`. `NO_AVAILABLE_HANDLE` is the most likely result based on the allocation path, but this should be confirmed by improving the assertion diagnostics. ## Relevant implementation path When allocation cannot find enough memory replicas, `AllocateAndInsertMetadata()`: 1. Sets `need_mem_eviction_ = true`. 2. Returns `ErrorCode::NO_AVAILABLE_HANDLE`. The background eviction thread checks this flag asynchronously. It sleeps for up to 10 ms between checks and then calls `BatchEvict()`. `BatchEvict()` scans all 1024 metadata shards, using up to 16 worker threads, joins those workers, and only later calls `ReleaseExpiredDiscardedReplicas(now)`. There is no synchronization between the test and completion of this eviction cycle. The test therefore assumes that thread wake-up, shard scanning, and discarded-replica release will all finish within 50 ms. Coverage instrumentation and CI load make that assumption unreliable. The `evicted_count=0` log line does not show whether discarded replicas were released. That count is separate from the discarded-replica release count, so it should not be interpreted as evidence that no memory was released. ## Relationship to PR #3201 PR #3201 changes only the oplog batch storage, codec, and snapshot tests: - `oplog_batch_storage.h/.cpp` - `oplog_batch_types.h` - `oplog_batch_codec.cpp` - Oplog batch storage/codec tests - `snapshot_child_process_test.cpp` It does not modify: - `master_service.cpp` - `master_service.h` - `master_service_test.cpp` - The allocation or eviction implementation Other relevant tests, including `master_service_ha_test` and all modified oplog batch tests, passed in the same CI job. Therefore, the available evidence indicates that PR #3201 exposed an existing timing-sensitive test rather than introducing the failure directly. ## Local result The test passed five consecutive iterations in a local non-coverage build: ```bash LSAN_OPTIONS=detect_leaks=0 \ ./build/mooncake-store/tests/master_service_test \ --gtest_filter=MasterServiceTest.PutStartExpiringTest \ --gtest_repeat=5 \ --gtest_break_on_failure=0 ``` Local eviction cycles completed in approximately 6-14 ms, so the fixed 50 ms sleep happened to be sufficient. This difference further supports a load-sensitive race rather than a deterministic functional failure. ## Suggested fix Replace the fixed 50 ms sleep with a bounded condition-based retry: - Reuse the existing `MasterServiceTest::WaitUntil()` helper. - Retry `PutStart()` until it succeeds or the timeout expires. - Treat `NO_AVAILABLE_HANDLE` as the expected transient result. - Fail immediately on any unexpected error. - Preserve the successful result instead of calling `PutStart()` again. - Use `ASSERT_TRUE()` before accessing `.value()`. - Include the returned error code in failure diagnostics. Increasing the sleep to another fixed value would only reduce the probability of failure and would keep the test timing-dependent. A production change to reorder work inside `BatchEvict()` may be worth evaluating separately, but it is not required to make this test deterministic. ## Acceptance criteria - `PutStartExpiringTest` waits for observable eviction completion instead of a fixed delay. - A failed retry reports the actual returned error. - The test never calls `.value()` after a non-fatal failed assertion. - The test passes repeatedly with coverage instrumentation and under CI load. - No production eviction behavior is changed solely to accommodate the test. ### Before submitting... - [ ] Ensure you searched for relevant issues and read the [documentation]

bsakaguchi

2026-10-29 21:19:59 +00:00

closed this issue
added the
Tests
label

bsakaguchi commented

2026-10-29 21:20:00 +00:00

Author

Owner

@github-actions[bot] commented on GitHub (Aug 3, 2026):

Thanks for opening this issue, @Icedcoco!

Field	Value
Issue	#3245
GitHub user ID	`102317026`
Reporter	@Icedcoco

A maintainer will triage this when possible. To help us respond faster, please include:

Mooncake version or commit SHA
Environment (OS, CUDA/driver, RDMA stack if relevant)
Steps to reproduce and expected vs. actual behavior

Useful links: Documentation · Contributing guide

This message was posted automatically by the issue bot.

@github-actions[bot] commented on GitHub (Aug 3, 2026): Thanks for opening this issue, @Icedcoco! | Field | Value | |-------|-------| | **Issue** | #3245 | | **GitHub user ID** | `102317026` | | **Reporter** | @Icedcoco | A maintainer will triage this when possible. To help us respond faster, please include: - Mooncake version or commit SHA - Environment (OS, CUDA/driver, RDMA stack if relevant) - Steps to reproduce and expected vs. actual behavior Useful links: [Documentation](https://kvcache-ai.github.io/Mooncake/) · [Contributing guide](https://github.com/kvcache-ai/Mooncake/blob/main/CONTRIBUTING.md) > This message was posted automatically by the issue bot.

bsakaguchi referenced this issue

2026-10-29 21:30:53 +00:00

[PR #831] [MERGED] [Transfer Engine] Post notify if all transfer tasks are completed #1855