Skip to content

[test](fe) Stabilize async cache refresh test#65873

Draft
shuke987 wants to merge 2 commits into
apache:masterfrom
shuke987:codex/fix-cache-factory-async-refresh-flaky
Draft

[test](fe) Stabilize async cache refresh test#65873
shuke987 wants to merge 2 commits into
apache:masterfrom
shuke987:codex/fix-cache-factory-async-refresh-flaky

Conversation

@shuke987

Copy link
Copy Markdown
Contributor

What problem does this PR solve?

Issue Number: None

Related PR: None

Problem Summary:

CacheFactoryTest.testAsyncLoadingCacheWithExpireAfterWrite waited a fixed 2.5 seconds for an asynchronous refresh whose loader deliberately sleeps for 2 seconds. Executor scheduling, JVM pauses, or an oversleep of more than the remaining 500 ms can leave the legal background refresh in flight and make the counter assertion flaky.

Replace the wall-clock sleep with a bounded Awaitility wait for the existing counter == 2 semantic oracle. The assertions that refresh immediately returns the old cached value and that expiry performs a new load remain unchanged.

Release note

None

Check List (For Author)

  • Test
    • Regression test
    • Unit Test
    • Manual test (add detailed scripts or steps below)
    • No need to test or manual test. Explain why:
      • This is a refactor/code format and no logic has been changed.
      • Previous test can cover this change.
      • No code files have been changed.
      • Other reason

Validation:

  • ./run-fe-ut.sh --run org.apache.doris.common.CacheFactoryTest#testAsyncLoadingCacheWithExpireAfterWrite: passed

  • Exact method repeated 10 times: 10/10 passed

  • Full CacheFactoryTest repeated twice: 2/2 passed, 6 tests per round

  • Exact method after rebasing onto the latest master: passed

  • Behavior changed:

    • No.
    • Yes.
  • Does this need documentation?

    • No.
    • Yes.

Check List (For Reviewer who merge this PR)

  • Confirm the release note
  • Confirm test cases
  • Confirm document
  • Add branch pick label

### What problem does this PR solve?\n\nIssue Number: None\n\nThe test used a fixed 2.5 second sleep to wait for a two-second asynchronous refresh, which can observe a legal in-flight refresh under CI scheduling delay. Wait for the existing counter oracle with a bounded timeout instead.\n\n### Release note\n\nNone\n\n### Check List\n\n- [x] Test-only change\n- [x] Target test repeated 10 times\n- [x] Full CacheFactoryTest repeated twice
@hello-stephen

Copy link
Copy Markdown
Contributor

Thank you for your contribution to Apache Doris.
Don't know what should be done next? See How to process your PR.

Please clearly describe your PR:

  1. What problem was fixed (it's best to include specific error reporting information). How it was fixed.
  2. Which behaviors were modified. What was the previous behavior, what is it now, why was it modified, and what possible impacts might there be.
  3. What features were added. Why was this function added?
  4. Which code was refactored and why was this part of the code refactored?
  5. Which functions were optimized and what is the difference before and after the optimization?

@shuke987

Copy link
Copy Markdown
Contributor Author

/review

@shuke987

Copy link
Copy Markdown
Contributor Author

run buildall

@github-actions github-actions Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Automated review: request changes

I found one P2 test-correctness issue. The new wait observes loader-side progress before the asynchronous refresh is cache-visible, so a legal executor schedule can still make the later expiry assertion flaky. See the inline comment for the concrete execution and fix direction.

Critical checkpoint conclusions:

  • Goal and proof: The PR is narrowly intended to stabilize testAsyncLoadingCacheWithExpireAfterWrite, but counter == 2 does not prove future completion or cache publication, so the stated goal is not fully achieved. The author-reported repeated passes are useful sampling but cannot exclude this ordering.
  • Scope and clarity: The diff is small and focused: one test import and one wait replacement. Awaitility is already declared and used in FE-core.
  • Concurrency and lifecycle: The relevant actors are the test/Awaitility thread, the daemon executor worker, and Caffeine's completion/publication action. AtomicLong safely exposes the increment but cannot order actions that occur after it. No locks, static initialization, production lifecycle, or production shared state are changed; the daemon executor's non-shutdown behavior predates this PR.
  • Configuration, compatibility, persistence, and data paths: No configuration, API/symbol, serialization, FE-BE variable, rolling-upgrade, transaction, persistence, data-write, or cloud/shared-nothing behavior changes.
  • Parallel paths and coverage: The unchanged synchronous-cache sleeps are outside this PR's specifically async scope. Exact equality cannot skip 2 before the later expiry access, the fresh executor has capacity, and the 10-second timeout introduces no separate supported defect. No generated result file applies.
  • Performance and observability: The polling wait has no production impact and can reduce test duration; production observability is not applicable.

Validation and completion: I reviewed the authoritative one-file diff and relevant loader/cache/executor paths, deduplicated against both the supplied and live GitHub review state, and completed three review rounds. The final full-review and risk-focused agents both returned NO_NEW_VALUABLE_FINDINGS against this exact comment set. Per the runner contract, I did not run builds or tests; git diff --check is clean, CheckStyle passed, and FE UT/compile were still pending at submission time. No additional user focus was provided. The review itself is complete with one inline issue and no unresolved candidate points.

// sleep longer to wait for refresh
Thread.sleep(2500);
// Wait for the refresh triggered above instead of relying on executor scheduling time.
Awaitility.await().atMost(10, TimeUnit.SECONDS).until(() -> counter.get() == 2);

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[P2] Wait for the refresh publication, not just the counter

createValue increments counter before returning, so this predicate can succeed before BasicAsyncCacheLoader completes the reload future and before Caffeine replaces the old cached future. If the loader is descheduled after the increment, line 243 still reads the old completed future; the test can then advance the FakeTicker by 61 seconds, and if the refresh publishes at the advanced fake time, line 249 sees a fresh completed entry and assertFalse(futureValue.isDone()) still flakes. The get() at line 243 does not wait for the refresh because Caffeine returns the old value during refresh. Please wait for cache-visible publication (for example, retain the pre-refresh cached future and await until the cache holds a different future), then assert the counter before advancing fake time.

### What problem does this PR solve?\n\nIssue Number: None\n\nThe review identified that the loader counter can advance before the refreshed future is published to Caffeine. Wait until the cache exposes a different completed future before advancing fake time.\n\n### Release note\n\nNone\n\n### Check List\n\n- [x] Target test repeated 10 times\n- [x] Full CacheFactoryTest repeated twice
@hello-stephen

Copy link
Copy Markdown
Contributor
TPC-H: Total hot run time: 29396 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit ea1f6808cc3bbe45bc1ed1de50bf074a2905eb08, data reload: false

------ Round 1 ----------------------------------
============================================
q1	17653	4100	4113	4100
q2	2061	317	201	201
q3	10282	1359	775	775
q4	4676	469	342	342
q5	7501	853	556	556
q6	187	175	140	140
q7	734	817	609	609
q8	9773	1462	1549	1462
q9	6105	4350	4309	4309
q10	6817	1746	1451	1451
q11	512	345	326	326
q12	783	572	466	466
q13	18092	3260	2683	2683
q14	264	255	245	245
q15	q16	784	775	706	706
q17	972	979	1065	979
q18	7062	5650	5580	5580
q19	1211	1307	1095	1095
q20	815	664	566	566
q21	5649	2623	2505	2505
q22	419	358	300	300
Total cold run time: 102352 ms
Total hot run time: 29396 ms

----- Round 2, with runtime_filter_mode=off -----
============================================
q1	4426	4331	4401	4331
q2	306	325	216	216
q3	4589	4976	4423	4423
q4	2060	2153	1366	1366
q5	4437	4288	4318	4288
q6	231	173	130	130
q7	1744	2000	1769	1769
q8	2490	2255	2204	2204
q9	7834	7858	7765	7765
q10	4664	4621	4222	4222
q11	584	433	397	397
q12	740	746	623	623
q13	3305	3611	2966	2966
q14	298	321	308	308
q15	q16	714	734	652	652
q17	1407	1379	1424	1379
q18	8007	7533	7003	7003
q19	1102	1176	1069	1069
q20	2229	2215	1960	1960
q21	5275	4620	4484	4484
q22	549	462	441	441
Total cold run time: 56991 ms
Total hot run time: 51996 ms

@hello-stephen

Copy link
Copy Markdown
Contributor
TPC-DS: Total hot run time: 177200 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit ea1f6808cc3bbe45bc1ed1de50bf074a2905eb08, data reload: false

query5	4325	628	482	482
query6	475	218	203	203
query7	4844	613	342	342
query8	343	192	167	167
query9	8772	4068	4073	4068
query10	475	352	332	332
query11	5923	2340	2167	2167
query12	180	103	102	102
query13	1282	618	441	441
query14	6248	5208	4827	4827
query14_1	4263	4211	4208	4208
query15	228	205	180	180
query16	1043	484	442	442
query17	1127	737	583	583
query18	2632	479	347	347
query19	218	200	157	157
query20	113	119	104	104
query21	245	161	137	137
query22	13509	13564	13417	13417
query23	17283	16347	16021	16021
query23_1	16122	16280	16108	16108
query24	7490	1766	1276	1276
query24_1	1299	1288	1264	1264
query25	565	463	382	382
query26	1342	354	221	221
query27	2524	610	369	369
query28	4450	2036	1992	1992
query29	1078	617	481	481
query30	346	264	228	228
query31	1128	1109	992	992
query32	152	67	63	63
query33	516	309	245	245
query34	1156	1176	684	684
query35	773	793	671	671
query36	1210	1221	1097	1097
query37	153	109	101	101
query38	1900	1685	1649	1649
query39	889	873	842	842
query39_1	833	832	840	832
query40	255	158	142	142
query41	67	64	64	64
query42	92	88	90	88
query43	323	324	279	279
query44	1416	755	765	755
query45	197	180	176	176
query46	1083	1147	716	716
query47	2093	2143	2012	2012
query48	385	408	291	291
query49	593	438	303	303
query50	1046	432	329	329
query51	10476	10472	10426	10426
query52	86	89	78	78
query53	253	277	196	196
query54	273	234	230	230
query55	73	69	64	64
query56	298	293	302	293
query57	1338	1308	1199	1199
query58	282	268	260	260
query59	1620	1627	1481	1481
query60	297	270	257	257
query61	154	143	149	143
query62	552	495	442	442
query63	237	197	204	197
query64	2811	1030	858	858
query65	4706	4641	4617	4617
query66	1798	512	369	369
query67	29198	29176	28930	28930
query68	3162	1582	993	993
query69	408	292	274	274
query70	1057	949	964	949
query71	374	336	373	336
query72	3083	2685	2361	2361
query73	863	769	444	444
query74	5088	4916	4706	4706
query75	2536	2512	2139	2139
query76	2338	1168	769	769
query77	357	368	280	280
query78	11941	11803	11342	11342
query79	1383	1116	724	724
query80	1312	553	472	472
query81	518	332	289	289
query82	620	156	120	120
query83	362	324	301	301
query84	276	161	129	129
query85	976	610	529	529
query86	426	306	281	281
query87	1848	1829	1756	1756
query88	3689	2781	2748	2748
query89	444	373	334	334
query90	1916	197	192	192
query91	202	188	156	156
query92	63	57	55	55
query93	1611	1480	965	965
query94	736	370	326	326
query95	763	499	458	458
query96	1052	770	340	340
query97	2613	2621	2510	2510
query98	219	207	201	201
query99	1095	1118	987	987
Total cold run time: 263054 ms
Total hot run time: 177200 ms

@hello-stephen

Copy link
Copy Markdown
Contributor
ClickBench: Total hot run time: 25.06 s
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit ea1f6808cc3bbe45bc1ed1de50bf074a2905eb08, data reload: false

query1	0.01	0.01	0.01
query2	0.10	0.05	0.05
query3	0.25	0.14	0.13
query4	1.61	0.15	0.14
query5	0.25	0.22	0.22
query6	1.25	1.06	1.06
query7	0.04	0.01	0.00
query8	0.06	0.04	0.04
query9	0.40	0.32	0.32
query10	0.55	0.56	0.57
query11	0.18	0.13	0.14
query12	0.18	0.14	0.13
query13	0.47	0.47	0.46
query14	1.01	1.00	1.01
query15	0.61	0.59	0.60
query16	0.31	0.32	0.31
query17	1.13	1.12	1.06
query18	0.24	0.21	0.21
query19	2.05	1.96	1.95
query20	0.02	0.01	0.01
query21	15.42	0.20	0.14
query22	4.90	0.05	0.05
query23	16.13	0.30	0.13
query24	2.96	0.40	0.32
query25	0.10	0.07	0.05
query26	0.76	0.20	0.15
query27	0.05	0.04	0.04
query28	3.54	0.90	0.53
query29	12.47	4.15	3.28
query30	0.29	0.17	0.16
query31	2.77	0.61	0.31
query32	3.24	0.59	0.51
query33	3.20	3.19	3.17
query34	15.50	4.22	3.53
query35	3.53	3.52	3.55
query36	0.56	0.46	0.42
query37	0.09	0.06	0.06
query38	0.05	0.04	0.03
query39	0.04	0.03	0.03
query40	0.19	0.16	0.16
query41	0.08	0.03	0.03
query42	0.04	0.03	0.03
query43	0.04	0.04	0.03
Total cold run time: 96.67 s
Total hot run time: 25.06 s

@shuke987

Copy link
Copy Markdown
Contributor Author

/review

@github-actions github-actions Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Automated review summary

No new inline issues were found on head 25e9e9a117be2cfdc254bcec754209c7d51c5374. The existing P2 publication-order concern is addressed: the test retains the pre-refresh cached future and waits until the cache exposes a different completed future before advancing FakeTicker, so loader-side progress alone cannot satisfy the wait.

Critical checkpoint conclusions:

  • Goal and proof: The patch accomplishes its stated one-test goal by replacing a fixed 2.5-second scheduling assumption with a bounded cache-visible condition while preserving assertions for stale-value refresh, exactly one refresh load, and expiry-triggered reload. The PR reports targeted and repeated unit-test passes; those tests were not rerun in this review-only runner.
  • Scope and clarity: The source change is small, focused, and uses the existing Awaitility test dependency. The predicate and comment explain the required publication boundary. Non-blocking metadata note: the PR description still describes the superseded counter == 2 predicate and could be updated to match the current head.
  • Concurrency: The relevant actors are the test/Awaitility polling thread and the configured executor's cache-loader thread. BasicAsyncCacheLoader returns a distinct future, and Caffeine retains the old mapping while refresh is in flight; repeated polls neither publish early nor start another refresh. No project lock or shared non-atomic mutable state is added.
  • Lifecycle and static initialization: No production resource ownership, shutdown order, static initialization, or cross-TU lifecycle is changed. The pre-existing daemon executor lifecycle is unchanged.
  • Parallel paths and special conditions: The two older synchronous LoadingCache tests still contain fixed waits, but those waits are unchanged, outside the authoritative diff, and outside the PR's explicit single-method goal; they are a separate cleanup opportunity rather than a regression in this patch. The new identity-plus-completion condition fails with a bounded timeout if publication never occurs.
  • Tests and expected results: No generated result files are involved. The changed test continues to cover the old value during refresh, refresh completion/counter behavior, and expiry after publication. GitHub CheckStyle is green at this head. The external check_coverage_fe (Coverage) status currently reports a TeamCity failure without public diagnostic detail and remains subject to the normal merge gate.
  • Configuration, compatibility, persistence, transactions/data writes, FE-BE variables, and observability: Not applicable; this is test-only and changes no runtime configuration, format/protocol, persisted state, data path, logging, or metrics.
  • Performance and memory: The bounded polling performs a single cache lookup per interval only in this unit test; there is no production hot-path or memory-accounting impact.
  • User focus: No additional user-provided focus was supplied.

The full-review and timing-focused passes converged with NO_NEW_VALUABLE_FINDINGS; all suspicious points have evidence-based conclusions, the prior thread is not duplicated, and the final inline-comment set is empty.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants