Skip to content

[fix](file cache) keep the cache monitor off the LRU recorder lock - #67315

Merged
deardeng merged 1 commit into
apache:masterfrom
deardeng:codex/fc-fix-lru-log-lock-starvation
Sep 3, 2026
Merged

[fix](file cache) keep the cache monitor off the LRU recorder lock#67315
deardeng merged 1 commit into
apache:masterfrom
deardeng:codex/fc-fix-lru-log-lock-starvation

Conversation

@deardeng

Copy link
Copy Markdown
Contributor

run_background_monitor() ended its loop with
update_shadow_queue_element_count_metrics(), which takes _mutex_lru_log. The LRU log replay thread holds that lock for as long as it takes to drain the log queue, so a slow consumer froze the monitor with it: check_disk_resource_limit(), check_need_evict_cache_in_advance() and every gauge stopped running, and the disk resource limit mode stayed at whatever value it happened to hold. Gauges were observed frozen for up to 40 minutes in production.

The call was redundant from the start. #64798 added the shadow queue element count gauge and published it in two places: inside replay_queue_event(), under the same lock that mutates the shadow queue, and again from the monitor every file_cache_background_monitor_interval_ms as a periodic refresh. Nothing outside replay_queue_event() mutates a shadow queue, so that refresh could only rewrite a value that had just been published and could not have changed since. What it did add was a dependency from the disk protection loop onto a lock owned by a background consumer.

Drop the call, and update_shadow_queue_element_count_metrics() with it: it existed only for that refresh, and leaving a public method that takes _mutex_lru_log invites the next background loop to reintroduce the coupling. The gauge is still published by replay, now on the replay interval instead of the monitor interval. Its test is replaced by one asserting that replay publishes the gauge on its own.

How long replay holds the lock is a separate problem, addressed separately.

What problem does this PR solve?

Issue Number: close #xxx

Related PR: #xxx

Problem Summary:

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
  • 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

run_background_monitor() ended its loop with
update_shadow_queue_element_count_metrics(), which takes _mutex_lru_log. The
LRU log replay thread holds that lock for as long as it takes to drain the log
queue, so a slow consumer froze the monitor with it: check_disk_resource_limit(),
check_need_evict_cache_in_advance() and every gauge stopped running, and the
disk resource limit mode stayed at whatever value it happened to hold. Gauges
were observed frozen for up to 40 minutes in production.
The call was redundant from the start. apache#64798 added the shadow queue element
count gauge and published it in two places: inside replay_queue_event(), under
the same lock that mutates the shadow queue, and again from the monitor every
file_cache_background_monitor_interval_ms as a periodic refresh. Nothing outside
replay_queue_event() mutates a shadow queue, so that refresh could only rewrite
a value that had just been published and could not have changed since. What it
did add was a dependency from the disk protection loop onto a lock owned by a
background consumer.
Drop the call, and update_shadow_queue_element_count_metrics() with it: it
existed only for that refresh, and leaving a public method that takes
_mutex_lru_log invites the next background loop to reintroduce the coupling.
The gauge is still published by replay, now on the replay interval instead of
the monitor interval. Its test is replaced by one asserting that replay
publishes the gauge on its own.
How long replay holds the lock is a separate problem, addressed separately.
@deardeng

Copy link
Copy Markdown
ContributorAuthor

run buildall

@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?

@deardeng

Copy link
Copy Markdown
ContributorAuthor

/review

@github-actionsgithub-actionsBot 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.

Review conclusion: no blocking or actionable correctness issues found; submitting a summary-only review with no inline comments.

I reviewed the authoritative bundle for head 06d0134 against base c800f2a, including all four changed paths and the related cache lifecycle.

Checkpoints:

  • Shadow-queue correctness/lifecycle: production shadow queues are mutated only by replay_queue_event(), which publishes the current gauge after dequeued events under _mutex_lru_log. Restore mutates real queues and enqueues replay records; disabled/full logging does not mutate shadow state.
  • Concurrency/locking: replay and LRU dump serialize shadow access with _mutex_lru_log, while the monitor no longer waits on that lock. Producers only enqueue lock-free log records, and stats read the bvar status value.
  • API/build hygiene: both removed methods have no remaining repository references; the remaining mutex/lock_guard interfaces and BE-UT unity requirements are intact.
  • Test coverage: the replacement unit test verifies replay-time gauge publication, while existing tests cover disabled backlog, queue caps, tail trimming, remove behavior, all queue types, restore/dump, and idle replay. I did not run builds or tests because this runner is restricted to review operations.

No additional user-provided review focus was supplied. Existing bundled and live review context contains no inline threads or replies requiring deduplication.

@hello-stephen

Copy link
Copy Markdown
Contributor

BE UT Coverage Report

Increment line coverage 🎉

Increment coverage report
Complete coverage report

CategoryCoverage
Function Coverage62.72% (29342/46779)
Line Coverage47.70% (306902/643431)
Region Coverage43.30% (247719/572141)
Branch Coverage44.88% (115371/257037)

@hello-stephen

Copy link
Copy Markdown
Contributor
TPC-H: Total hot run time: 16874 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit 06d0134cf22aca65549f09686980a2d59db55ac9, data reload: false
------ Round 1 ----------------------------------
============================================
q1	17586	3004	3012	3004
q2	2107	262	236	236
q3	10214	876	501	501
q4	4674	246	208	208
q5	7680	577	385	385
q6	138	115	93	93
q7	516	520	386	386
q8	9233	890	922	890
q9	3489	2430	2402	2402
q10	6506	888	726	726
q11	398	201	183	183
q12	620	264	202	202
q13	18127	1583	1146	1146
q14	170	157	141	141
q15	q16	443	397	365	365
q17	1327	817	802	802
q18	3149	2312	2352	2312
q19	1278	923	753	753
q20	394	292	197	197
q21	5581	1717	1900	1717
q22	334	269	225	225
Total cold run time: 93964 ms
Total hot run time: 16874 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1	3369	3297	3309	3297
q2	518	394	371	371
q3	2285	2610	2254	2254
q4	1204	1187	904	904
q5	2238	2154	2143	2143
q6	169	124	88	88
q7	1043	919	865	865
q8	1634	1421	1430	1421
q9	3262	3218	3236	3218
q10	1941	1849	1664	1664
q11	374	274	253	253
q12	462	433	356	356
q13	1494	1531	1156	1156
q14	172	180	158	158
q15	q16	398	403	361	361
q17	3766	3541	3366	3366
q18	4979	4589	5157	4589
q19	942	884	862	862
q20	1024	978	860	860
q21	3924	3224	3216	3216
q22	406	355	327	327
Total cold run time: 35604 ms
Total hot run time: 31729 ms

@hello-stephen

Copy link
Copy Markdown
Contributor
TPC-DS: Total hot run time: 83207 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 06d0134cf22aca65549f09686980a2d59db55ac9, data reload: false
query5	4259	400	337	337
query6	396	139	126	126
query7	4956	397	234	234
query8	288	125	118	118
query9	8663	2893	2875	2875
query10	387	209	180	180
query11	5378	1046	917	917
query12	116	73	71	71
query13	1193	454	347	347
query14	6082	2245	2140	2140
query14_1	2027	2025	2030	2025
query15	172	128	116	116
query16	923	380	354	354
query17	797	478	373	373
query18	2330	369	229	229
query19	152	133	100	100
query20	71	68	69	68
query21	201	99	83	83
query22	5519	5462	5356	5356
query23	7036	6346	6144	6144
query23_1	6293	6265	6394	6265
query24	7304	1098	769	769
query24_1	768	766	753	753
query25	411	273	230	230
query26	1235	225	133	133
query27	2775	428	262	262
query28	4663	1508	1507	1507
query29	913	432	343	343
query30	245	154	135	135
query31	819	408	335	335
query32	133	85	74	74
query33	454	201	168	168
query34	979	845	482	482
query35	406	414	346	346
query36	562	576	530	530
query37	124	81	68	68
query38	1016	866	841	841
query39	511	490	486	486
query39_1	454	482	479	479
query40	205	89	74	74
query41	56	52	51	51
query42	73	71	71	71
query43	243	246	210	210
query44	1017	570	551	551
query45	109	112	95	95
query46	790	872	536	536
query47	776	766	711	711
query48	321	316	229	229
query49	533	241	210	210
query50	747	266	191	191
query51	8021	7874	8110	7874
query52	70	67	59	59
query53	197	214	161	161
query54	235	178	199	178
query55	70	59	54	54
query56	199	158	169	158
query57	692	680	668	668
query58	190	172	164	164
query59	1278	1263	1137	1137
query60	243	210	183	183
query61	156	140	148	140
query62	369	209	175	175
query63	176	148	148	148
query64	2897	806	691	691
query65	1662	1664	1647	1647
query66	1772	260	207	207
query67	10171	9980	9952	9952
query68	3035	1179	733	733
query69	347	222	190	190
query70	687	617	610	610
query71	258	181	159	159
query72	2378	1736	1565	1565
query73	680	635	322	322
query74	1995	1238	1155	1155
query75	1214	1126	986	986
query76	2381	723	552	552
query77	264	259	216	216
query78	3997	3725	3314	3314
query79	2753	836	611	611
query80	1621	320	268	268
query81	512	158	135	135
query82	618	127	100	100
query83	281	206	190	190
query84	296	111	93	93
query85	808	365	286	286
query86	476	173	173	173
query87	1034	982	915	915
query88	3159	2103	2129	2103
query89	295	198	178	178
query90	2186	135	131	131
query91	133	121	99	99
query92	97	70	63	63
query93	2349	1054	691	691
query94	647	220	219	219
query95	549	260	226	226
query96	789	553	278	278
query97	1062	1079	1063	1063
query98	180	137	131	131
query99	428	348	315	315
Total cold run time: 181204 ms
Total hot run time: 83207 ms

@hello-stephen

Copy link
Copy Markdown
Contributor

BE Regression && UT Coverage Report

Increment line coverage 100% (0/0) 🎉

Increment coverage report
Complete coverage report

CategoryCoverage
Function Coverage76.00% (34451/45333)
Line Coverage60.98% (388059/636397)
Region Coverage57.11% (325700/570302)
Branch Coverage57.94% (148587/256470)

@hello-stephen

Copy link
Copy Markdown
Contributor
ClickBench: Total hot run time: 14.64 s
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit 06d0134cf22aca65549f09686980a2d59db55ac9, data reload: false
query1	0.01	0.00	0.01
query2	0.07	0.03	0.04
query3	0.25	0.11	0.11
query4	1.61	0.11	0.10
query5	0.18	0.17	0.15
query6	1.26	0.69	0.68
query7	0.03	0.00	0.00
query8	0.04	0.03	0.03
query9	0.29	0.22	0.22
query10	0.35	0.36	0.33
query11	0.16	0.12	0.12
query12	0.14	0.12	0.12
query13	0.31	0.31	0.31
query14	0.46	0.45	0.46
query15	0.35	0.35	0.35
query16	0.22	0.21	0.23
query17	0.71	0.74	0.67
query18	0.18	0.16	0.17
query19	1.21	1.19	1.09
query20	0.01	0.01	0.01
query21	15.46	0.15	0.11
query22	5.08	0.04	0.04
query23	16.18	0.26	0.10
query24	3.03	0.33	0.27
query25	0.10	0.04	0.04
query26	0.78	0.16	0.12
query27	0.04	0.03	0.04
query28	3.69	0.54	0.29
query29	12.49	3.15	2.57
query30	0.25	0.10	0.11
query31	2.76	0.37	0.17
query32	3.52	0.32	0.23
query33	1.37	1.41	1.61
query34	15.39	2.15	1.79
query35	1.80	1.78	1.73
query36	0.47	0.29	0.27
query37	0.06	0.04	0.04
query38	0.04	0.03	0.03
query39	0.03	0.03	0.02
query40	0.12	0.08	0.08
query41	0.08	0.02	0.03
query42	0.03	0.02	0.02
query43	0.04	0.03	0.02
Total cold run time: 90.65 s
Total hot run time: 14.64 s

@deardeng
deardeng merged commit 182022b into apache:masterSep 3, 2026
34 checks passed
github-actionsBot pushed a commit that referenced this pull request Sep 3, 2026
…67315)
run_background_monitor() ended its loop with
update_shadow_queue_element_count_metrics(), which takes _mutex_lru_log.
The LRU log replay thread holds that lock for as long as it takes to
drain the log queue, so a slow consumer froze the monitor with it:
check_disk_resource_limit(), check_need_evict_cache_in_advance() and
every gauge stopped running, and the disk resource limit mode stayed at
whatever value it happened to hold. Gauges were observed frozen for up
to 40 minutes in production.
The call was redundant from the start. #64798 added the shadow queue
element count gauge and published it in two places: inside
replay_queue_event(), under the same lock that mutates the shadow queue,
and again from the monitor every
file_cache_background_monitor_interval_ms as a periodic refresh. Nothing
outside replay_queue_event() mutates a shadow queue, so that refresh
could only rewrite a value that had just been published and could not
have changed since. What it did add was a dependency from the disk
protection loop onto a lock owned by a background consumer.
Drop the call, and update_shadow_queue_element_count_metrics() with it:
it existed only for that refresh, and leaving a public method that takes
_mutex_lru_log invites the next background loop to reintroduce the
coupling. The gauge is still published by replay, now on the replay
interval instead of the monitor interval. Its test is replaced by one
asserting that replay publishes the gauge on its own.
How long replay holds the lock is a separate problem, addressed
separately.
yiguolei pushed a commit that referenced this pull request Sep 5, 2026
…67315)
run_background_monitor() ended its loop with
update_shadow_queue_element_count_metrics(), which takes _mutex_lru_log.
The LRU log replay thread holds that lock for as long as it takes to
drain the log queue, so a slow consumer froze the monitor with it:
check_disk_resource_limit(), check_need_evict_cache_in_advance() and
every gauge stopped running, and the disk resource limit mode stayed at
whatever value it happened to hold. Gauges were observed frozen for up
to 40 minutes in production.
The call was redundant from the start. #64798 added the shadow queue
element count gauge and published it in two places: inside
replay_queue_event(), under the same lock that mutates the shadow queue,
and again from the monitor every
file_cache_background_monitor_interval_ms as a periodic refresh. Nothing
outside replay_queue_event() mutates a shadow queue, so that refresh
could only rewrite a value that had just been published and could not
have changed since. What it did add was a dependency from the disk
protection loop onto a lock owned by a background consumer.
Drop the call, and update_shadow_queue_element_count_metrics() with it:
it existed only for that refresh, and leaving a public method that takes
_mutex_lru_log invites the next background loop to reintroduce the
coupling. The gauge is still published by replay, now on the replay
interval instead of the monitor interval. Its test is replaced by one
asserting that replay publishes the gauge on its own.
How long replay holds the lock is a separate problem, addressed
separately.
yiguolei pushed a commit that referenced this pull request Sep 6, 2026
…rder lock #67315 (#67495)
Cherry-picked from #67315
Co-authored-by: deardeng <dengxin@selectdb.com>
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants

@deardeng@hello-stephen@gavinchou@yiguolei