You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@doris.apache.org by "wenzhenghu (via GitHub)" <gi...@apache.org> on 2026/10/04 13:11:13 UTC
[PR] [improvement](fe) Add bounded query planning diagnostics [doris]
wenzhenghu opened a new pull request, #68727:
URL: https://github.com/apache/doris/pull/68727
### What problem does this PR solve?
Issue Number: N/A
Related PR: #68694
Problem Summary:
A query that stalls or fails during FE planning can leave little evidence about its active phase, optimizer job, lock wait, or external metadata operation. This PR adds bounded Nereids planning diagnostics and numeric audit/Profile timing details, allowing operators to identify where planning time is spent, including before a query reaches BE execution.
#### Planning progress and failure diagnostics
- A scoped context records each `planWithLock` pass and restores the outer diagnostic context on normal returns, failures, cache paths, EXPLAIN, and nested planning. Internal MV planning can inherit the outer query identity and summary ownership across different `ConnectContext` instances.
- The existing connection timeout checker emits rate-limited WARN events for registered queries that are still planning. Events identify the active nested pass, phase, optimizer job, operation/target, elapsed time, timeout budgets, and held locks. `root_pass_id` and `root_elapsed_ms` retain the outer pass's identity and elapsed time. The checker reads published diagnostic state without acquiring the planner's table-lock monitor; no additional monitoring thread is created.
- Slow or failed passes emit a completion summary with phase status, elapsed time, and the failed step. Fast successful passes produce no diagnostic log events.
- Read-lock wait and hold times are tracked separately. Table resolution, schema, snapshot, and partition metadata operations include qualified targets. Targets are resolved only during an active diagnostic scope, once on the planning thread, and captured for background checks.
- Completed operation events are deferred until the outermost planning resources are released. Each pass buffers at most 16 events; child events are merged into the bounded parent buffer, with omitted events counted. Nested passes share the running-report rate limit and the outer elapsed-time threshold.
Each diagnostic JSON event carries an explicit `query_id` and excludes raw SQL. Event emission temporarily binds that identity in Log4j MDC and restores the caller's previous value, so an existing MDC-aware layout cannot attribute the event to another query. This PR is independently based on master: it does not depend on the `QueryLogContext` class or `sys_log_enable_query_id` from #68694, and it changes no BE code or common log-prefix configuration. The two PRs touch `NereidsPlanner` and `ConnectContext`; when merging both, retain the planner diagnostic scope together with the query-log scope and preserve both timeout-checker hooks.
The following FE settings are dynamically configurable:
| Configuration | Default | Behavior |
| --- | ---: | --- |
| `nereids_planning_log_threshold_ms` | `5000` | Slow-pass threshold; non-positive values disable slow-pass reports. |
| `nereids_planning_operation_log_threshold_ms` | `1000` | Slow lock/metadata operation threshold; non-positive values disable slow-operation reports. |
| `nereids_planning_log_interval_ms` | `30000` | Minimum interval between running reports; nested passes share it, and values below 1000 use 1000 ms. |
Failed passes and failed operations remain eligible for reporting when slow thresholds are disabled; the event-buffer limit still applies. Running reports follow the existing connection-checker cadence. Metadata instrumentation covers the common FE entry points rather than every connector-internal operation. Existing lock ordering, lock timeouts, and exception propagation are preserved.
#### Audit and Profile details
- Audit `plan_times_ms` adds `preload_external_metadata`, `pre_rewrite_mv`, and flattened numeric `planning_*` entries for phases, pass counts, and failures. Its type remains `MAP<STRING, INT>`; new phase totals use `-1` when not run, preserve elapsed time on failure, and saturate at the INT limit.
- Profile adds `Nereids Planning Details`, accumulating repeated CTAS/retry/nested passes and recording the last pass's `completed`, `failed`, or `not_run` phase states. Audit timing collection also works with query Profile disabled.
- Existing timing fields keep their meaning, including the broad legacy `translate` field. Nested phase/pass timings are inclusive and must not be added as disjoint wall-clock durations.
### Release note
FE reports slow or failed Nereids planning and slow lock/metadata operations, with bounded deferred events and configurable thresholds. Audit `plan_times_ms` gains numeric planning keys, and Profile gains accumulated planning details. The audit map type remains unchanged. Disabling slow-report thresholds does not suppress failure diagnostics.
### Check List (For Author)
- Test:
- Post-split FE validation: **103/103 tests across 10 classes passed**, with no failures/errors/skips, through `./run-fe-ut.sh --run ...`. Includes all 27 migrated diagnostic tests plus 2 new identity cases, as well as SummaryProfile, StatementContext/MVCC, NereidsPlanner, external schema/row-count, and nested MV suites.
- FE common/core class outputs were removed before compilation. The branch builds and tests without the query-prefix implementation or its configuration from #68694.
- FE Checkstyle (0 violations), source whitespace checks, and static cross-review passed. The BE diff is empty. The generated audit result retains its original trailing separator line.
- The audit regression suite and its runner-generated expected output are unchanged from the previously validated combined branch (#68694, `a07bed545df`). They cover successful/failed audit records with Profile disabled. This regression and live-instance checks were not rerun after the split; the current split was validated with the targeted FE suites above.
- Full suites, refreshed community coverage, multi-node fault injection, and production performance benchmarks were not run locally.
- Behavior changed:
- [x] Yes. FE adds slow/failure planning events and audit/Profile planning fields. All three diagnostic settings are dynamic.
- Does this need documentation?
- [x] Yes. Planning events, thresholds, audit/Profile fields, and inclusive timing semantics; documentation PR pending.
### Check List (For Reviewer who merge this PR)
- [ ] Confirm the release note
- [ ] Confirm test cases
- [ ] Confirm document
- [ ] Add branch pick label
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6124920569
# FE UT Coverage Report
Increment line coverage ` 96.94% (348/359)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_4abbea0ad82bbc4dd47631e3833a9774e030dc93/fe_increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_4abbea0ad82bbc4dd47631e3833a9774e030dc93/fe_report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6126007129
run buildall
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6314684623
# FE UT Coverage Report
Increment line coverage ` 96.06% (414/431)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_37ba8ccf456eddc1ab0946c37ce556f534d1fbad/fe_increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_37ba8ccf456eddc1ab0946c37ce556f534d1fbad/fe_report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6352335771
# FE Regression Coverage Report
Increment line coverage ` 87.24% (376/431)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e_merge_fe/increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e_merge_fe/report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6128090380
<details>
<summary>ClickBench: <b>Total hot run time: 24.79 s</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit 21b3cc226fee907a1280f5e2fc0f740e146a86bb, data reload: false
query1 0.00 0.00 0.01
query2 0.10 0.05 0.04
query3 0.26 0.11 0.12
query4 1.61 0.12 0.12
query5 0.28 0.25 0.26
query6 1.17 0.69 0.69
query7 0.04 0.01 0.01
query8 0.06 0.04 0.04
query9 0.43 0.36 0.35
query10 0.57 0.59 0.60
query11 0.21 0.15 0.14
query12 0.18 0.14 0.14
query13 0.48 0.50 0.49
query14 0.99 0.98 0.95
query15 0.63 0.61 0.61
query16 0.34 0.35 0.35
query17 1.14 1.16 1.16
query18 0.23 0.21 0.22
query19 2.14 1.99 1.94
query20 0.02 0.02 0.01
query21 15.51 0.27 0.15
query22 4.43 0.06 0.05
query23 16.26 0.32 0.12
query24 2.96 0.56 0.53
query25 0.12 0.06 0.06
query26 1.57 0.25 0.16
query27 0.05 0.04 0.03
query28 2.48 0.58 0.43
query29 12.50 4.13 3.31
query30 0.29 0.15 0.13
query31 2.80 0.59 0.34
query32 3.23 0.61 0.54
query33 3.30 3.27 3.25
query34 15.40 4.04 3.39
query35 3.36 3.35 3.33
query36 0.55 0.42 0.43
query37 0.10 0.06 0.06
query38 0.05 0.04 0.04
query39 0.03 0.04 0.03
query40 0.18 0.16 0.14
query41 0.09 0.04 0.03
query42 0.04 0.02 0.03
query43 0.04 0.04 0.03
Total cold run time: 96.22 s
Total hot run time: 24.79 s
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6129337665
<details>
<summary>TPC-H: <b>Total hot run time: 29171 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit 21b3cc226fee907a1280f5e2fc0f740e146a86bb, data reload: false
------ Round 1 ----------------------------------
============================================
q1 17596 5637 5542 5542
q2 2147 325 262 262
q3 10193 1369 828 828
q4 4674 479 350 350
q5 7433 789 542 542
q6 186 187 155 155
q7 771 811 615 615
q8 9247 1363 1068 1068
q9 5679 4465 4447 4447
q10 6811 1292 1031 1031
q11 442 257 237 237
q12 626 400 291 291
q13 18054 3067 2403 2403
q14 269 274 246 246
q15 q16 740 726 677 677
q17 1163 741 590 590
q18 7012 6205 6194 6194
q19 1114 946 588 588
q20 379 331 224 224
q21 5663 2582 2593 2582
q22 367 325 299 299
Total cold run time: 100566 ms
Total hot run time: 29171 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1 6490 6381 6585 6381
q2 737 593 565 565
q3 5670 5707 5225 5225
q4 2347 2168 1566 1566
q5 5881 5592 5595 5592
q6 248 209 159 159
q7 2249 2108 1848 1848
q8 3135 2814 2767 2767
q9 8250 7962 7709 7709
q10 3667 3590 3224 3224
q11 606 406 376 376
q12 668 705 508 508
q13 2764 3106 2415 2415
q14 280 285 278 278
q15 q16 679 693 628 628
q17 7864 7039 6834 6834
q18 13188 12264 13031 12264
q19 921 783 790 783
q20 2207 2186 1941 1941
q21 5916 4691 4830 4691
q22 512 452 418 418
Total cold run time: 74279 ms
Total hot run time: 66172 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on code in PR #68727:
URL: https://github.com/apache/doris/pull/68727#discussion_r4267302700
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/PlanningDiagnostics.java:
##########
@@ -0,0 +1,437 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.common.Config;
+import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.thrift.TUniqueId;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.gson.JsonObject;
+import org.apache.logging.log4j.CloseableThreadContext;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+import java.util.ArrayList;
+import java.util.EnumMap;
+import java.util.List;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.function.LongSupplier;
+import java.util.function.Supplier;
+
+/**
+ * One planning pass. The planning thread owns timers and the bounded slow-operation buffer.
+ * The connection checker reads only immutable, volatile-published steps, never planner/table locks.
+ * Timings are inclusive: nested phases and operations must not be added to their enclosing phase.
+ */
+public final class PlanningDiagnostics {
+ private static final Logger LOG = LogManager.getLogger(PlanningDiagnostics.class);
+ private static final int MAX_SLOW_OPERATIONS = 16;
+ // Internal MV planning can replace ConnectContext while the calling planner still holds table locks.
+ private static final ThreadLocal<PlanningDiagnostics> ACTIVE = new ThreadLocal<>();
+
+ public enum Phase {
+ PREPROCESS, COLLECT_TABLES, PRELOAD_METADATA, WAIT_CHANGE_VISIBLE, LOCK_TABLES,
+ ANALYZE, REWRITE, PRE_REWRITE_MV, OPTIMIZE, CHOOSE_PLAN, POST_PROCESS,
+ TRANSLATE, DISTRIBUTE, RELEASE_RESOURCES;
+
+ public String key() {
+ return name().toLowerCase(Locale.ROOT);
+ }
+ }
+
+ private final ConnectContext context;
+ private final SummaryProfile summary;
+ private final long passId;
+ private final PlanningDiagnostics parent;
+ private final PlanningDiagnostics root;
+ private final boolean inheritsQueryIdentity;
+ private final TUniqueId queryId;
+ private final long statementId;
+ private final String threadName;
+ private volatile long timeoutMs;
+ private final LongSupplier clock;
+ private final long started;
+ private final EnumMap<Phase, Timing> timings = new EnumMap<>(Phase.class);
+ private final List<Event> slowOperations = new ArrayList<>();
+ private final AtomicLong lastReport;
+ private volatile Step current;
+ private volatile Class<?> currentJob;
+ private volatile HeldLocks heldLocks = new HeldLocks(0, 0, "");
+ private volatile boolean finished;
+ // Only the root publishes this pointer, so its registered connection can inspect an internal pass.
+ private volatile PlanningDiagnostics activePass;
+ private String failedStep = "";
+ private Throwable stepFailure;
+ private long omittedOperations;
+
+ private PlanningDiagnostics(ConnectContext context) {
+ this(context, System::nanoTime);
+ }
+
+ @VisibleForTesting
+ PlanningDiagnostics(ConnectContext context, LongSupplier clock) {
+ this.context = context;
+ this.parent = ACTIVE.get();
+ this.root = parent == null ? this : parent.root;
+ this.lastReport = parent == null ? new AtomicLong(Long.MIN_VALUE) : parent.lastReport;
+ SummaryProfile contextSummary = SummaryProfile.getSummaryProfile(context);
+ this.summary = contextSummary != null ? contextSummary : parent == null ? null : parent.summary;
+ this.passId = summary == null ? 0 : summary.nextPlanningPassId();
+ TUniqueId contextQueryId = context.queryId();
+ this.inheritsQueryIdentity = contextQueryId == null && parent != null;
+ this.queryId = inheritsQueryIdentity ? parent.queryId
+ : contextQueryId == null ? null : contextQueryId.deepCopy();
+ this.statementId = inheritsQueryIdentity ? parent.statementId : context.getStmtId();
+ this.threadName = Thread.currentThread().getName();
+ this.timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ this.clock = clock;
+ this.started = clock.getAsLong();
+ }
+
+ /** Includes cleanup and restores an outer pass even when internal planning uses another connection. */
+ public static <T> T plan(ConnectContext context, Supplier<T> action) {
+ return execute(new PlanningDiagnostics(context), action);
+ }
+
+ @VisibleForTesting
+ static <T> T execute(PlanningDiagnostics diagnostics, Supplier<T> action) {
+ ConnectContext context = diagnostics.context;
+ PlanningDiagnostics previous = context.getPlanningDiagnostics();
+ ACTIVE.set(diagnostics);
+ context.setPlanningDiagnostics(diagnostics);
+ diagnostics.root.activePass = diagnostics;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ if (diagnostics.stepFailure != failure) {
+ diagnostics.failedStep = "between_phases";
+ }
+ throw failure;
+ } finally {
+ diagnostics.finished = true;
+ context.setPlanningDiagnostics(previous);
+ diagnostics.root.activePass = diagnostics.parent;
+ if (diagnostics.parent == null) {
+ ACTIVE.remove();
+ } else {
+ ACTIVE.set(diagnostics.parent);
+ }
+ diagnostics.finish(success);
+ }
+ }
+
+ public static void runPhase(ConnectContext context, Phase phase, Runnable action) {
+ phase(context, phase, () -> {
+ action.run();
+ return null;
+ });
+ }
+
+ public static <T> T phase(ConnectContext context, Phase phase, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ return diagnostics == null ? action.get() : diagnostics.measure(phase, "", "", -1, action);
+ }
+
+ /** A negative operation budget means that timeout handling belongs to the connector. */
+ public static <T> T operation(ConnectContext context, String operation, String target,
+ long budgetMs, Supplier<T> action) {
+ return operation(context, operation, () -> target, budgetMs, action);
+ }
+
+ /** Resolve the target only for an active planning pass, on the calling thread. */
+ public static <T> T operation(ConnectContext context, String operation, Supplier<String> target,
+ long budgetMs, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ if (diagnostics == null) {
+ return action.get();
+ }
+ Step step = diagnostics.current;
+ return diagnostics.measure(step == null ? Phase.PREPROCESS : step.phase,
+ operation, target.get(), budgetMs, action);
+ }
+
+ public static PlanningDiagnostics current(ConnectContext context) {
+ return context == null ? null : context.getPlanningDiagnostics();
+ }
+
+ private <T> T measure(Phase phase, String operation, String target, long budgetMs, Supplier<T> action) {
+ Step previous = current;
+ Step step = new Step(phase, operation, target, budgetMs, clock.getAsLong(),
+ operation.isEmpty() || previous == null ? -1 : previous.phaseStarted);
+ current = step;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ // Preserve the innermost failing step of this exception, not an earlier recovered MV failure.
+ if (stepFailure != failure) {
+ stepFailure = failure;
+ failedStep = phase.key() + (operation.isEmpty() ? "" : "/" + operation);
+ }
+ throw failure;
+ } finally {
+ long elapsed = clock.getAsLong() - step.started;
+ if (operation.isEmpty()) {
+ Timing timing = timings.computeIfAbsent(phase, key -> new Timing());
+ timing.nanos += elapsed;
+ timing.calls++;
+ timing.failures += success ? 0 : 1;
+ if (phase == Phase.PREPROCESS && success) {
+ // SET_VAR hints are applied by preprocessing, after this pass was created.
+ timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ }
+ } else {
+ recordOperation(step, elapsed, success);
+ }
+ current = previous;
+ }
+ }
+
+ /** Avoid allocating task descriptions for every optimizer job; format the class only on a slow report. */
+ public Class<?> setCurrentJob(Class<?> job) {
+ Class<?> previous = currentJob;
+ currentJob = job;
+ return previous;
+ }
+
+ public LockHold acquiredLock(String table) {
+ long now = clock.getAsLong();
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count + 1, previous.count == 0 ? now : previous.started,
+ previous.count == 0 ? table : previous.oldestTable);
+ return new LockHold(table, now);
+ }
+
+ /** Closed after unlocking; planner resources release in reverse acquisition order. */
+ public final class LockHold implements AutoCloseable {
+ private final String table;
+ private final long acquired;
+
+ private LockHold(String table, long acquired) {
+ this.table = table;
+ this.acquired = acquired;
+ }
+
+ @Override
+ public void close() {
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count - 1, previous.started, previous.oldestTable);
+ recordOperation(new Step(Phase.RELEASE_RESOURCES, "read_lock_hold", table, -1, acquired, -1),
+ clock.getAsLong() - acquired, true);
+ }
+ }
+
+ private void recordOperation(Step step, long nanos, boolean success) {
+ long threshold = Config.nereids_planning_operation_log_threshold_ms;
+ if (success && (threshold <= 0 || millis(nanos) < threshold)) {
+ return;
+ }
+ if (slowOperations.size() == MAX_SLOW_OPERATIONS) {
+ omittedOperations++;
+ return;
+ }
+ JsonObject event = step.toJson();
+ event.addProperty("elapsed_ms", millis(nanos));
+ event.addProperty("status", success ? "completed" : "failed");
+ slowOperations.add(new Event(this, "Planning operation", event));
+ }
+
+ /** Invoked by the existing connection timeout checker, including while a planner job is blocked. */
+ public void reportIfSlow() {
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ PlanningDiagnostics active = root.activePass;
+ if (root.finished || active == null || threshold <= 0) {
+ return;
+ }
+ // Snapshot published starts before reading the clock. A newer step/lock sampled after the clock
+ // could otherwise appear to have started in the future when the checker was descheduled.
+ Step step = active.current;
+ Class<?> job = active.currentJob;
+ HeldLocks oldest = active.heldLocks;
+ int lockCount = oldest.count;
+ for (PlanningDiagnostics outer = active.parent; outer != null; outer = outer.parent) {
+ HeldLocks locks = outer.heldLocks;
+ lockCount += locks.count;
+ if (locks.count > 0 && (oldest.count == 0 || locks.started < oldest.started)) {
+ oldest = locks;
+ }
+ }
+ long now = root.clock.getAsLong();
+ if (millis(now - root.started) < threshold) {
+ return;
+ }
+ long previous = root.lastReport.get();
+ // A minimum interval protects the checker from an accidentally zero/negative dynamic setting.
+ long interval = Math.max(1000, Config.nereids_planning_log_interval_ms);
+ if ((previous != Long.MIN_VALUE && millis(now - previous) < interval)
+ || !root.lastReport.compareAndSet(previous, now)) {
+ return;
+ }
+ JsonObject event = step == null ? new JsonObject() : step.toJson();
+ event.addProperty("status", "running");
+ event.addProperty("elapsed_ms", millis(now - active.started));
+ event.addProperty("root_pass_id", root.passId);
+ event.addProperty("root_elapsed_ms", millis(now - root.started));
+ event.addProperty("phase_elapsed_ms", step == null ? 0 : millis(now - step.phaseStarted));
+ event.addProperty("operation_elapsed_ms", step == null || step.operation.isEmpty()
+ ? 0 : millis(now - step.started));
+ event.addProperty("job", job == null ? "" : job.getSimpleName());
+ event.addProperty("held_locks", lockCount);
+ event.addProperty("oldest_lock", lockCount == 0 ? "" : bounded(oldest.oldestTable));
+ event.addProperty("oldest_lock_hold_ms", lockCount == 0 ? 0 : millis(now - oldest.started));
+ active.log("Slow planning", event);
+ }
+
+ private void finish(boolean success) {
+ JsonObject result = new JsonObject();
+ result.addProperty("pass_id", passId);
+ result.addProperty("status", success ? "completed" : "failed");
+ result.addProperty("elapsed_ms", millis(clock.getAsLong() - started));
+ result.addProperty("failed_step", success ? "" : failedStep);
+ JsonObject phases = new JsonObject();
+ for (Phase phase : Phase.values()) {
+ Timing timing = timings.get(phase);
+ JsonObject value = new JsonObject();
+ value.addProperty("status", timing == null ? "not_run" : timing.failures > 0 ? "failed" : "completed");
+ value.addProperty("elapsed_ms", timing == null ? 0 : millis(timing.nanos));
+ value.addProperty("calls", timing == null ? 0 : timing.calls);
+ phases.add(phase.key(), value);
+ }
+ result.add("phases", phases);
+ result.addProperty("omitted_operations", omittedOperations);
+ if (summary != null) {
+ summary.addPlanningPass(result);
+ }
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ boolean report = !success || !slowOperations.isEmpty()
+ || (threshold > 0 && result.get("elapsed_ms").getAsLong() >= threshold);
+ // An enclosing MV planning pass may still hold locks. Defer its children's logs as well.
+ if (parent != null) {
+ for (Event event : slowOperations) {
+ parent.defer(event);
+ }
+ parent.omittedOperations += omittedOperations;
+ if (report) {
+ parent.defer(new Event(this, "Planning finished", result));
+ }
+ } else {
+ for (Event event : slowOperations) {
+ event.owner.log(event.message, event.json);
+ }
+ if (report) {
+ log("Planning finished", result);
+ }
+ }
+ }
+
+ private void defer(Event event) {
+ if (slowOperations.size() == MAX_SLOW_OPERATIONS) {
+ omittedOperations++;
+ } else {
+ slowOperations.add(event);
+ }
+ }
+
+ private void log(String message, JsonObject event) {
+ String formattedId = queryId == null || (queryId.hi == 0 && queryId.lo == 0)
+ ? "" : DebugUtil.printId(queryId);
+ event.addProperty("query_id", formattedId);
+ event.addProperty("pass_id", passId);
+ event.addProperty("statement_id", statementId);
+ event.addProperty("planner_thread", threadName);
+ event.addProperty("query_timeout_ms", timeoutMs);
+ // Bind only this event; the checker or a deferred event may run under another query's context.
+ try (CloseableThreadContext.Instance ignored = CloseableThreadContext.put("query_id", formattedId)) {
Review Comment:
The standalone PR intentionally retains self-contained `query_id` in each diagnostic JSON event and restores its temporary MDC binding after emission. It does not depend on the runtime-prefix switch from the query-logging PR; disabling a prefix must not remove the diagnostic event's own identity.
The intended landing order is query logging first, diagnostics second. The second landing adaptation should reuse `QueryLogContext` for the shared key/binding/inheritance and reconcile the planner/checker wrappers. The temporary combination was tested with the log scope outside the diagnostics scope. These standalone branches still need that landing adaptation; I am not claiming the textual conflicts or duplicated helper logic are already removed.
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java:
##########
@@ -1593,24 +1611,81 @@ public void setAssignedWeightPerBackend(Map<Backend, Long> assignedWeightPerBack
this.assignedWeightPerBackend = assignedWeightPerBackend;
}
+ public synchronized long nextPlanningPassId() {
+ return ++planningPassSequence;
+ }
+
+ /** Bounded across retries, CTAS passes and nested MV planning; existing timing fields keep their meaning. */
+ public synchronized void addPlanningPass(JsonObject pass) {
+ planningPassCount++;
+ planningFailedPassCount += "failed".equals(pass.get("status").getAsString()) ? 1 : 0;
+ planningElapsedMs += pass.get("elapsed_ms").getAsLong();
+ lastPlanningPass = pass.deepCopy();
+ for (Phase phase : Phase.values()) {
+ String key = phase.key();
+ long total = planningPhaseTotals.has(key) ? planningPhaseTotals.get(key).getAsLong() : 0;
+ JsonObject phaseResult = pass.getAsJsonObject("phases").getAsJsonObject(key);
+ if (!"not_run".equals(phaseResult.get("status").getAsString())) {
+ planningPhaseTotals.addProperty(key, total + phaseResult.get("elapsed_ms").getAsLong());
+ }
+ if ("failed".equals(phaseResult.get("status").getAsString())) {
+ long failures = planningPhaseFailures.has(key) ? planningPhaseFailures.get(key).getAsLong() : 0;
+ planningPhaseFailures.addProperty(key, failures + 1);
+ }
+ }
+ }
+
+ public synchronized JsonObject getPlanningDetails() {
+ JsonObject result = new JsonObject();
+ result.addProperty("passes", planningPassCount);
+ result.addProperty("failed_passes", planningFailedPassCount);
+ result.addProperty("elapsed_ms", planningElapsedMs);
+ result.add("phase_time_ms", planningPhaseTotals.deepCopy());
+ result.add("last_pass", lastPlanningPass.deepCopy());
+ return result;
+ }
+
+ /** plan_times_ms is MAP<STRING, INT>. Never add strings or nested objects to this audit field. */
+ private synchronized void addPlanningAuditTimes(JsonObject result) {
Review Comment:
Addressed in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a). `addPlanningAuditTimes()` now returns without adding any `planning_*` keys when no root pass has completed. Therefore a timeout raised during the first active pass does not add the old zero/`-1` block.
After completion, only the three numeric summary keys are exposed; full phase detail remains in Profile.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-5980398238
run buildall
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6121617122
run buildall
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6124636164
# FE Regression Coverage Report
Increment line coverage ` 92.48% (332/359)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_4abbea0ad82bbc4dd47631e3833a9774e030dc93_merge_fe/increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_4abbea0ad82bbc4dd47631e3833a9774e030dc93_merge_fe/report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6162501936
<details>
<summary>TPC-H: <b>Total hot run time: 28924 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit 4f6bc8489d16a9280805ddab30df234390ea60b1, data reload: false
------ Round 1 ----------------------------------
============================================
q1 17607 5750 5638 5638
q2 2124 318 264 264
q3 10208 1397 849 849
q4 4678 479 346 346
q5 7435 803 560 560
q6 189 188 155 155
q7 774 788 595 595
q8 9260 1346 1123 1123
q9 5732 4460 4444 4444
q10 6810 1296 1032 1032
q11 424 258 234 234
q12 634 402 288 288
q13 18039 3043 2375 2375
q14 273 271 250 250
q15 q16 730 730 656 656
q17 1193 747 573 573
q18 7057 6222 6168 6168
q19 1111 964 612 612
q20 386 334 231 231
q21 5004 2268 2367 2268
q22 365 315 263 263
Total cold run time: 100033 ms
Total hot run time: 28924 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1 6151 6113 6145 6113
q2 689 582 548 548
q3 5269 5378 4914 4914
q4 1997 2112 1552 1552
q5 5281 5181 6043 5181
q6 264 200 159 159
q7 2371 2093 1919 1919
q8 3209 2853 2961 2853
q9 8438 8350 8289 8289
q10 3764 3684 3384 3384
q11 625 424 406 406
q12 693 740 547 547
q13 2867 3212 2590 2590
q14 300 310 274 274
q15 q16 697 755 640 640
q17 8522 7494 7383 7383
q18 13045 12256 13037 12256
q19 961 819 829 819
q20 2220 2244 1990 1990
q21 6045 4694 4811 4694
q22 526 454 407 407
Total cold run time: 73934 ms
Total hot run time: 66918 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6162706508
<details>
<summary>ClickBench: <b>Total hot run time: 24.32 s</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit 4f6bc8489d16a9280805ddab30df234390ea60b1, data reload: false
query1 0.01 0.01 0.00
query2 0.11 0.06 0.05
query3 0.27 0.13 0.12
query4 1.62 0.12 0.12
query5 0.28 0.25 0.25
query6 1.18 0.69 0.68
query7 0.04 0.01 0.01
query8 0.06 0.04 0.04
query9 0.42 0.34 0.35
query10 0.58 0.57 0.62
query11 0.20 0.13 0.15
query12 0.19 0.15 0.14
query13 0.48 0.49 0.52
query14 0.97 0.97 0.97
query15 0.63 0.61 0.61
query16 0.35 0.34 0.35
query17 1.09 1.12 1.17
query18 0.22 0.20 0.20
query19 2.04 1.99 1.89
query20 0.02 0.01 0.01
query21 15.55 0.27 0.14
query22 4.43 0.05 0.06
query23 16.22 0.33 0.12
query24 3.09 0.72 0.38
query25 0.11 0.06 0.04
query26 1.53 0.26 0.15
query27 0.05 0.03 0.05
query28 2.01 0.59 0.40
query29 12.53 4.16 3.27
query30 0.29 0.14 0.13
query31 2.77 0.59 0.35
query32 3.22 0.63 0.52
query33 3.22 3.20 3.29
query34 15.44 3.97 3.39
query35 3.36 3.33 3.37
query36 0.56 0.44 0.40
query37 0.10 0.07 0.06
query38 0.05 0.04 0.03
query39 0.04 0.03 0.03
query40 0.17 0.15 0.14
query41 0.09 0.03 0.03
query42 0.03 0.02 0.02
query43 0.05 0.03 0.04
Total cold run time: 95.67 s
Total hot run time: 24.32 s
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6162049097
Review follow-up for [the inline review](https://github.com/apache/doris/pull/68727#pullrequestreview-5497879038): all 12 discussions have individual replies and resolution dispositions.
The update separates root/nested accounting, limits Audit to three summary keys, defers JSON construction, caches per-pass target names, puts cancellation before reporting, compacts fast-failure logs, registers the Profile key, and removes common-pool/1-second test dependence. The three dynamic settings deliberately retain `volatile` for visibility and their original defaults. Cross-PR landing adaptation and the separate configuration-reference documentation PR remain follow-ups.
Running reports require a connection registered with the existing checker; unregistered forwarded/MTMV/stream-load contexts can emit eligible completion/operation events, but do not receive periodic running reports from that checker. Optimizer job identity remains the job class, not an individual rule.
Validation of the review-fix code included 105 independent FE tests and two successful Audit regression runs (runner-generated expected output, then verification) with Profile disabled. Those tests preceded the later master merge; I refreshed the merged-head source for these replies and did not rerun the complete tests after that merge. Production overhead and real external-catalog/nested-MV end-to-end coverage remain unmeasured.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6350778467
<details>
<summary>TPC-DS: <b>Total hot run time: 152676 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit b8c3b95b338135c2d75aaea83d0c60bc1baef90e, data reload: false
query5 4335 599 447 447
query6 424 210 189 189
query7 4794 470 243 243
query8 320 178 151 151
query9 8768 3117 3131 3117
query10 479 310 259 259
query11 6038 3940 3611 3611
query12 148 91 86 86
query13 1238 435 332 332
query14 6160 4074 3782 3782
query14_1 3530 3505 3613 3505
query15 216 208 182 182
query16 940 444 379 379
query17 908 643 528 528
query18 2407 419 303 303
query19 193 157 132 132
query20 87 87 82 82
query21 213 139 107 107
query22 12903 13051 12970 12970
query23 13575 12853 12382 12382
query23_1 12546 12517 12602 12517
query24 7385 836 473 473
query24_1 463 465 463 463
query25 523 396 346 346
query26 1257 253 140 140
query27 2773 447 268 268
query28 4653 1951 1918 1918
query29 1538 577 436 436
query30 300 224 193 193
query31 1011 947 827 827
query32 133 92 103 92
query33 505 286 237 237
query34 951 857 498 498
query35 756 745 642 642
query36 795 801 739 739
query37 128 101 90 90
query38 1841 1798 1691 1691
query39 806 807 769 769
query39_1 735 737 759 737
query40 224 116 98 98
query41 75 74 70 70
query42 87 89 83 83
query43 361 380 327 327
query44 1322 684 695 684
query45 186 185 172 172
query46 841 987 574 574
query47 2900 2979 2830 2830
query48 303 315 223 223
query49 585 420 301 301
query50 678 291 231 231
query51 10670 10637 10341 10341
query52 83 86 73 73
query53 191 211 156 156
query54 242 217 201 201
query55 83 70 63 63
query56 250 241 238 238
query57 1668 1656 1582 1582
query58 311 290 277 277
query59 2165 2123 1967 1967
query60 316 256 240 240
query61 167 164 165 164
query62 400 338 288 288
query63 198 160 164 160
query64 2875 1051 860 860
query65 3478 3364 3401 3364
query66 1782 427 300 300
query67 20596 20540 20468 20468
query68 2989 984 610 610
query69 402 278 245 245
query70 853 764 782 764
query71 332 234 209 209
query72 2747 2593 2301 2301
query73 504 540 311 311
query74 4678 4510 4344 4344
query75 2411 2305 1913 1913
query76 2303 1016 589 589
query77 351 389 269 269
query78 10258 10104 9551 9551
query79 955 894 513 513
query80 542 410 347 347
query81 540 336 296 296
query82 580 137 116 116
query83 301 196 205 196
query84 313 121 104 104
query85 865 420 368 368
query86 317 238 230 230
query87 2038 1990 1840 1840
query88 3611 2643 2639 2639
query89 338 287 255 255
query90 1855 178 169 169
query91 163 150 126 126
query92 101 94 95 94
query93 1034 985 569 569
query94 450 290 277 277
query95 582 333 358 333
query96 657 479 240 240
query97 2429 2430 2328 2328
query98 162 154 152 152
query99 758 752 639 639
Total cold run time: 236025 ms
Total hot run time: 152676 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on code in PR #68727:
URL: https://github.com/apache/doris/pull/68727#discussion_r4267307918
##########
fe/fe-common/src/main/java/org/apache/doris/common/Config.java:
##########
@@ -104,6 +104,21 @@ public class Config extends ConfigBase {
@ConfField(mutable = true, description = "The threshold of slow query, in milliseconds. If the response time of a "
+ "query exceeds this threshold, it will be recorded in audit log.")
public static long qe_slow_log_ms = 5000;
+
+ @ConfField(mutable = true, description = "Log slow Nereids planning passes after this many milliseconds. "
+ + "Non-positive values disable slow-pass logs; failed passes are still reported.")
+ public static volatile long nereids_planning_log_threshold_ms = 5000;
Review Comment:
I kept `volatile` deliberately for these three dynamically updated settings. They are read by planning threads and the background connection checker without a shared lock with the configuration writer; `volatile` supplies the visibility contract for those reads. Matching the plain-field style would remove that guarantee, so I did not adopt that stylistic change.
Defaults remain `5000 / 1000 / 30000` ms. The PR description and field descriptions explain the triggers, disabling semantics, and tuning guidance; a separate configuration-reference documentation PR is still pending.
##########
fe/fe-core/src/test/java/org/apache/doris/common/profile/PlanningDiagnosticsTest.java:
##########
@@ -0,0 +1,988 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.catalog.Column;
+import org.apache.doris.catalog.TableIf;
+import org.apache.doris.common.Config;
+import org.apache.doris.common.FeConstants;
+import org.apache.doris.common.jmockit.Deencapsulation;
+import org.apache.doris.common.profile.PlanningDiagnostics.Phase;
+import org.apache.doris.datasource.ExternalCatalog;
+import org.apache.doris.datasource.ExternalDatabase;
+import org.apache.doris.datasource.ExternalTable;
+import org.apache.doris.datasource.SchemaCacheValue;
+import org.apache.doris.datasource.mvcc.MvccSnapshot;
+import org.apache.doris.datasource.mvcc.PluginDrivenMvccExternalTable;
+import org.apache.doris.mysql.authenticate.TestLogAppender;
+import org.apache.doris.nereids.NereidsPlanner;
+import org.apache.doris.nereids.StatementContext;
+import org.apache.doris.nereids.trees.plans.commands.ExplainCommand.ExplainLevel;
+import org.apache.doris.nereids.trees.plans.logical.LogicalFileScan.SelectedPartitions;
+import org.apache.doris.nereids.trees.plans.logical.LogicalPlan;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.qe.OriginStatement;
+import org.apache.doris.qe.StmtExecutor;
+
+import com.google.common.collect.ImmutableList;
+import com.google.gson.JsonObject;
+import com.google.gson.JsonParser;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.ThreadContext;
+import org.apache.logging.log4j.core.LogEvent;
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.Assertions;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.mockito.Mockito;
+
+import java.util.Collections;
+import java.util.List;
+import java.util.Optional;
+import java.util.concurrent.CompletableFuture;
+import java.util.concurrent.CountDownLatch;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.Executors;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.concurrent.atomic.AtomicReference;
+import java.util.function.Supplier;
+
+public class PlanningDiagnosticsTest {
+ private static final String QUERY_ID_KEY = "query_id";
+ private final AtomicLong clock = new AtomicLong(TimeUnit.SECONDS.toNanos(1));
+ private ConnectContext context;
+ private ConnectContext previousContext;
+ private SummaryProfile summary;
+ private long savedThreshold;
+ private long savedOperationThreshold;
+ private long savedInterval;
+ private boolean savedUnitTest;
+ private String savedQueryId;
+
+ @BeforeEach
+ public void setUp() {
+ savedThreshold = Config.nereids_planning_log_threshold_ms;
+ savedOperationThreshold = Config.nereids_planning_operation_log_threshold_ms;
+ savedInterval = Config.nereids_planning_log_interval_ms;
+ savedUnitTest = FeConstants.runningUnitTest;
+ previousContext = ConnectContext.get();
+ savedQueryId = ThreadContext.get(QUERY_ID_KEY);
+ Config.nereids_planning_log_threshold_ms = 5000;
+ Config.nereids_planning_operation_log_threshold_ms = 1000;
+ Config.nereids_planning_log_interval_ms = 30000;
+ FeConstants.runningUnitTest = true;
+ context = new ConnectContext();
+ context.setQueryId(new org.apache.doris.thrift.TUniqueId(1, 2));
+ context.setStmtId(7);
+ context.setThreadLocalInfo();
+ summary = new SummaryProfile();
+ StmtExecutor executor = Mockito.mock(StmtExecutor.class);
+ Mockito.when(executor.getSummaryProfile()).thenReturn(summary);
+ context.setExecutor(executor);
+ }
+
+ @AfterEach
+ public void tearDown() {
+ ConnectContext.remove();
+ if (previousContext != null) {
+ previousContext.setThreadLocalInfo();
+ }
+ if (savedQueryId == null) {
+ ThreadContext.remove(QUERY_ID_KEY);
+ } else {
+ ThreadContext.put(QUERY_ID_KEY, savedQueryId);
+ }
+ Config.nereids_planning_log_threshold_ms = savedThreshold;
+ Config.nereids_planning_operation_log_threshold_ms = savedOperationThreshold;
+ Config.nereids_planning_log_interval_ms = savedInterval;
+ FeConstants.runningUnitTest = savedUnitTest;
+ }
+
+ @Test
+ public void testFastPassIsQuietAndAuditContainsTimingsWithoutProfile() {
+ context.getSessionVariable().enableProfile = false;
+ summary.addNereidsPreloadExternalMetadataTime(12);
+ summary.setNereidsCollectTablePartitionFinishTime(100);
+ summary.setNereidsPreRewriteByMvFinishTime(108);
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> {
+ PlanningDiagnostics.runPhase(context, Phase.CHOOSE_PLAN, () -> advance(7));
+ PlanningDiagnostics.runPhase(context, Phase.POST_PROCESS, () -> advance(11));
+ });
+ Assertions.assertTrue(events(appender).isEmpty());
+ }
+ JsonObject audit = JsonParser.parseString(summary.getPlanTime()).getAsJsonObject();
+ Assertions.assertEquals(12, audit.get("preload_external_metadata").getAsLong());
+ Assertions.assertEquals(8, audit.get("pre_rewrite_mv").getAsLong());
+ Assertions.assertEquals(7, audit.get("planning_choose_plan").getAsLong());
+ Assertions.assertEquals(-1, audit.get("planning_analyze").getAsLong());
+ audit.entrySet().forEach(entry -> {
+ Assertions.assertTrue(entry.getValue().isJsonPrimitive());
+ Assertions.assertTrue(entry.getValue().getAsJsonPrimitive().isNumber());
+ Assertions.assertEquals(entry.getValue().getAsLong(), entry.getValue().getAsInt());
+ });
+ Assertions.assertEquals(11, phase("post_process").get("elapsed_ms").getAsLong());
+ Assertions.assertEquals("not_run", phase("analyze").get("status").getAsString());
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ }
+
+ @Test
+ public void testRunningReportRateLimitIdentityAndContextRestoration() {
+ PlanningDiagnostics diagnostics = new PlanningDiagnostics(context, clock::get);
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ PlanningDiagnostics.execute(diagnostics, () -> {
+ PlanningDiagnostics.runPhase(context, Phase.OPTIMIZE, () -> {
+ diagnostics.setCurrentJob(PlanningDiagnosticsTest.class);
+ advance(5000);
+ context.queryId().setLo(99);
+ ThreadContext.put(QUERY_ID_KEY, "checker");
+ context.checkTimeout(0);
+ Assertions.assertEquals("checker", ThreadContext.get(QUERY_ID_KEY));
+ context.checkTimeout(0);
+ Assertions.assertEquals(1, events(appender).size());
+ advance(30000);
+ context.checkTimeout(0);
+ Assertions.assertEquals(2, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(0), "1-2");
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"job\":\"PlanningDiagnosticsTest\""));
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"phase\":\"optimize\""));
+ });
+ return null;
+ });
+ int count = events(appender).size();
+ diagnostics.reportIfSlow();
+ Assertions.assertEquals(count, events(appender).size());
+ }
+ }
+
+ @Test
+ public void testMissingAndZeroQueryIdsClearEventIdentityAndRestoreCaller() {
+ for (org.apache.doris.thrift.TUniqueId queryId : new org.apache.doris.thrift.TUniqueId[] {
+ null, new org.apache.doris.thrift.TUniqueId(0, 0)}) {
+ context.setQueryId(queryId);
+ ThreadContext.put(QUERY_ID_KEY, "caller");
+ IllegalStateException failure = new IllegalStateException("planning failure without query identity");
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ Assertions.assertSame(failure, Assertions.assertThrows(IllegalStateException.class, () -> run(() -> {
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ throw failure;
+ })));
+ Assertions.assertEquals(1, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(0), "");
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ }
+ }
+ }
+
+ @Test
+ public void testNestedPassWithOwnIdKeepsSnapshotForCheckerAndDeferredEvents() {
+ ConnectContext child = new ConnectContext();
+ child.setQueryId(new org.apache.doris.thrift.TUniqueId(3, 4));
+ ThreadContext.put(QUERY_ID_KEY, "caller");
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ PlanningDiagnostics parent = context.getPlanningDiagnostics();
+ PlanningDiagnostics.execute(new PlanningDiagnostics(child, clock::get), () -> {
+ PlanningDiagnostics.runPhase(child, Phase.OPTIMIZE, () -> {
+ child.queryId().setLo(99);
+ advance(5000);
+ context.checkTimeout(0);
+ Assertions.assertEquals(1, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(0), "3-4");
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ });
+ return null;
+ });
+ Assertions.assertSame(parent, context.getPlanningDiagnostics());
+ Assertions.assertNull(child.getPlanningDiagnostics());
+ Assertions.assertEquals(1, events(appender).size(), "The child completion remains deferred");
+ advance(30000);
+ context.checkTimeout(0);
+ Assertions.assertEquals(2, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(1), "1-2");
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ }));
+ Assertions.assertEquals(4, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(2), "3-4");
+ assertDiagnosticIdentity(events(appender).get(3), "1-2");
+ Assertions.assertEquals(2, summary.getPlanningDetails().get("passes").getAsInt());
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ }
+ }
+
+ @Test
+ public void testDynamicDisableAndMinimumInterval() {
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.ANALYZE, () -> {
+ advance(5000);
+ Config.nereids_planning_log_threshold_ms = 0;
+ context.checkTimeout(0);
+ Assertions.assertTrue(events(appender).isEmpty());
+ Config.nereids_planning_log_threshold_ms = 1;
+ Config.nereids_planning_log_interval_ms = 0;
+ context.checkTimeout(0);
+ advance(999);
+ context.checkTimeout(0);
+ Assertions.assertEquals(1, events(appender).size());
+ advance(1);
+ context.checkTimeout(0);
+ Assertions.assertEquals(2, events(appender).size());
+ }));
+ }
+ }
+
+ @Test
+ public void testFailurePreservesElapsedAndSkipsLaterStages() {
+ IllegalStateException expected = new IllegalStateException("original failure");
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ Assertions.assertSame(expected, Assertions.assertThrows(IllegalStateException.class,
+ () -> run(() -> PlanningDiagnostics.runPhase(context, Phase.ANALYZE, () -> {
+ advance(3);
+ throw expected;
+ }))));
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"failed_step\":\"analyze\""));
+ }
+ Assertions.assertEquals(3, phase("analyze").get("elapsed_ms").getAsLong());
+ Assertions.assertEquals("failed", phase("analyze").get("status").getAsString());
+ Assertions.assertEquals("not_run", phase("optimize").get("status").getAsString());
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ }
+
+ @Test
+ public void testNestedAndRepeatedPlanningRestoreParentAndAccumulate() {
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ PlanningDiagnostics parent = context.getPlanningDiagnostics();
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.CHOOSE_PLAN, () -> advance(5)));
+ Assertions.assertSame(parent, context.getPlanningDiagnostics());
+ advance(2);
+ }));
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.CHOOSE_PLAN, () -> advance(8)));
+ Assertions.assertEquals(3, summary.getPlanningDetails().get("passes").getAsInt());
+ Assertions.assertEquals(13, summary.getPlanningDetails().getAsJsonObject("phase_time_ms")
+ .get("choose_plan").getAsLong());
+ Assertions.assertEquals("not_run", phase("rewrite").get("status").getAsString());
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ }
+
+ @Test
+ public void testNestedSlowOperationsAreDeferredUntilOuterPassEnds() {
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> {
+ PlanningDiagnostics.LockHold hold = context.getPlanningDiagnostics().acquiredLock("catalog.db.outer");
+ run(() -> PlanningDiagnostics.operation(context, "load_schema", "catalog.db.inner", -1, () -> {
+ advance(1000);
+ return null;
+ }));
+ Assertions.assertTrue(events(appender).isEmpty());
+ hold.close();
+ });
+ Assertions.assertTrue(appender.contains(Level.WARN, "catalog.db.inner"));
+ Assertions.assertTrue(appender.contains(Level.WARN, "catalog.db.outer"));
+ }
+ }
+
+ @Test
+ public void testInternalConnectionPlanningDefersLogsAndKeepsQueryIdentity() {
+ StatementContext outerStatement = new StatementContext(context, new OriginStatement("select 1", 0));
+ TableIf table = table(1, "catalog.db.outer");
+ outerStatement.getTables().put(ImmutableList.of("outer"), table);
+ Mockito.when(table.tryReadLock(1, TimeUnit.MINUTES)).thenReturn(true);
+ // MV cache construction installs a separate connection without an executor or query ID.
+ ConnectContext internal = new ConnectContext();
+ StatementContext internalStatement = new StatementContext(internal, new OriginStatement("select 1", 0));
+ NereidsPlanner planner = new NereidsPlanner(internalStatement) {
+ @Override
+ protected LogicalPlan preprocess(LogicalPlan plan) {
+ throw new IllegalArgumentException("internal planning failure");
+ }
+ };
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ PlanningDiagnostics.plan(context, () -> {
+ outerStatement.lock();
+ try {
+ internal.setThreadLocalInfo();
+ Assertions.assertThrows(IllegalArgumentException.class, () -> planner.planWithLock(
+ Mockito.mock(LogicalPlan.class), org.apache.doris.nereids.properties.PhysicalProperties.ANY,
+ ExplainLevel.NONE, false));
+ Assertions.assertTrue(events(appender).isEmpty(), "Outer table locks are still held");
+ Assertions.assertNull(internal.getPlanningDiagnostics());
+ } finally {
+ context.setThreadLocalInfo();
+ outerStatement.releasePlannerResources();
+ }
+ return null;
+ });
+ Mockito.verify(table).readUnlock();
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"failed_step\":\"preprocess\""));
+ Assertions.assertEquals(2, summary.getPlanningDetails().get("passes").getAsInt());
+ Assertions.assertEquals(1, summary.getPlanningDetails().get("failed_passes").getAsInt());
+ events(appender).forEach(event -> assertDiagnosticIdentity(event, "1-2"));
+ }
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ // Reusing the same planner thread must not retain the preceding root or its summary/ID.
+ internal.setThreadLocalInfo();
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ Assertions.assertThrows(IllegalArgumentException.class, () -> PlanningDiagnostics.plan(internal, () -> {
+ throw new IllegalArgumentException("independent planning failure");
+ }));
+ Assertions.assertEquals(1, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(0), "");
+ }
+ Assertions.assertEquals(2, summary.getPlanningDetails().get("passes").getAsInt());
+ }
+
+ @Test
+ public void testRunningReportFollowsInternalPassAndSharesRootRateLimit() {
+ ConnectContext internal = new ConnectContext();
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ PlanningDiagnostics.LockHold hold = context.getPlanningDiagnostics().acquiredLock("catalog.db.outer");
+ try {
+ advance(5000);
+ for (int i = 0; i < 2; i++) {
+ PlanningDiagnostics.execute(new PlanningDiagnostics(internal, clock::get), () ->
+ PlanningDiagnostics.operation(internal, "load_schema", "catalog.db.inner", -1, () -> {
+ advance(1);
+ context.checkTimeout(0);
+ return null;
+ }));
+ }
+ Assertions.assertEquals(1, events(appender).size(), "Nested passes share the root interval");
+ JsonObject event = JsonParser.parseString(events(appender).get(0).getMessage().getFormattedMessage()
+ .split(": ", 2)[1]).getAsJsonObject();
+ Assertions.assertEquals("catalog.db.inner", event.get("target").getAsString());
+ Assertions.assertEquals(1, event.get("held_locks").getAsInt());
+ Assertions.assertEquals("catalog.db.outer", event.get("oldest_lock").getAsString());
+ Assertions.assertEquals(5001, event.get("root_elapsed_ms").getAsLong());
+ Assertions.assertEquals(1, event.get("operation_elapsed_ms").getAsLong());
+ advance(30000);
+ context.checkTimeout(0);
+ Assertions.assertEquals(2, events(appender).size());
+ } finally {
+ hold.close();
+ }
+ }));
+ }
+ }
+
+ @Test
+ public void testRunningReportDoesNotUseStartsPublishedAfterItsTimestamp() throws Exception {
+ Thread plannerThread = Thread.currentThread();
+ CountDownLatch clockRead = new CountDownLatch(1);
+ CountDownLatch resumeChecker = new CountDownLatch(1);
+ PlanningDiagnostics diagnostics = new PlanningDiagnostics(context, () -> {
+ long now = clock.get();
+ if (Thread.currentThread() != plannerThread) {
+ clockRead.countDown();
+ try {
+ Assertions.assertTrue(resumeChecker.await(10, TimeUnit.SECONDS));
+ } catch (InterruptedException e) {
+ Thread.currentThread().interrupt();
+ throw new AssertionError(e);
+ }
+ }
+ return now;
+ });
+ ExecutorService checker = Executors.newSingleThreadExecutor();
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ PlanningDiagnostics.execute(diagnostics, () -> {
+ advance(5000);
+ PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ CompletableFuture<Void> report = CompletableFuture.runAsync(diagnostics::reportIfSlow, checker);
+ try {
+ Assertions.assertTrue(clockRead.await(10, TimeUnit.SECONDS));
+ advance(10);
+ PlanningDiagnostics.operation(context, "load_schema", "catalog.db.next", -1, () -> {
+ PlanningDiagnostics.LockHold hold = diagnostics.acquiredLock("catalog.db.next");
+ try {
+ resumeChecker.countDown();
+ report.get(10, TimeUnit.SECONDS);
+ JsonObject event = JsonParser.parseString(events(appender).get(0).getMessage()
+ .getFormattedMessage().split(": ", 2)[1]).getAsJsonObject();
+ for (String key : new String[] {"phase_elapsed_ms", "operation_elapsed_ms",
+ "oldest_lock_hold_ms"}) {
+ Assertions.assertTrue(event.get(key).getAsLong() >= 0, key);
+ }
+ } catch (Exception e) {
+ throw new AssertionError(e);
+ } finally {
+ hold.close();
+ }
+ return null;
+ });
+ } catch (InterruptedException e) {
+ Thread.currentThread().interrupt();
+ throw new AssertionError(e);
+ } finally {
+ resumeChecker.countDown();
+ }
+ });
+ return null;
+ });
+ } finally {
+ resumeChecker.countDown();
+ checker.shutdownNow();
+ Assertions.assertTrue(checker.awaitTermination(10, TimeUnit.SECONDS));
+ }
+ }
+
+ @Test
+ public void testRecoveredOperationDoesNotReplaceLaterFailure() {
+ Assertions.assertThrows(IllegalStateException.class, () -> run(() -> {
+ try {
+ PlanningDiagnostics.operation(context, "load_schema", "catalog.db.table", -1, () -> {
+ throw new IllegalArgumentException("recovered");
+ });
+ } catch (IllegalArgumentException expected) {
+ // Materialized-view alternatives can fail while planning continues.
+ }
+ PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ throw new IllegalStateException("actual failure");
+ });
+ }));
+ Assertions.assertEquals("rewrite", summary.getPlanningDetails().getAsJsonObject("last_pass")
+ .get("failed_step").getAsString());
+ }
+
+ @Test
+ public void testOperationsAreBoundedDeferredAndCarryQueryIdentity() {
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> {
+ for (int i = 0; i < 20; i++) {
+ PlanningDiagnostics.operation(context, "load_schema", "catalog.db.table", -1, () -> {
+ advance(1000);
+ return null;
+ });
+ }
+ Assertions.assertTrue(events(appender).isEmpty());
+ });
+ Assertions.assertEquals(17, events(appender).size());
+ events(appender).forEach(event -> assertDiagnosticIdentity(event, "1-2"));
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"omitted_operations\":4"));
+ }
+ }
+
+ @Test
+ public void testCheckerDoesNotWaitForStatementMonitorAndShowsHeldLock() throws Exception {
+ StatementContext statement = new StatementContext(context, new OriginStatement("select 1", 0));
+ TableIf first = table(1, "catalog.db.first");
+ TableIf second = table(2, "catalog.db.second");
+ statement.getTables().put(ImmutableList.of("first"), first);
+ statement.getTables().put(ImmutableList.of("second"), second);
+ CountDownLatch waiting = new CountDownLatch(1);
+ CountDownLatch release = new CountDownLatch(1);
+ Mockito.when(first.tryReadLock(1, TimeUnit.MINUTES)).thenReturn(true);
+ Mockito.when(second.tryReadLock(1, TimeUnit.MINUTES)).thenAnswer(invocation -> {
+ waiting.countDown();
+ Assertions.assertTrue(release.await(10, TimeUnit.SECONDS));
+ return true;
+ });
+ ExecutorService worker = Executors.newSingleThreadExecutor();
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ CompletableFuture<Void> planning = CompletableFuture.runAsync(() -> run(() -> {
+ try {
+ PlanningDiagnostics.runPhase(context, Phase.LOCK_TABLES, statement::lock);
+ advance(2000);
+ } finally {
+ statement.releasePlannerResources();
+ }
+ }), worker);
+ try {
+ Assertions.assertTrue(waiting.await(10, TimeUnit.SECONDS));
+ advance(5000);
+ CompletableFuture.runAsync(() -> context.checkTimeout(0)).get(1, TimeUnit.SECONDS);
Review Comment:
Addressed in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a). The lock/checker test now uses a dedicated single-thread checker executor, latch coordination, a 10-second wait, and executor cleanup rather than the common pool with a 1-second bound.
The latch still ensures the planner holds the statement monitor while the checker must complete independently. The diagnostic test class passed all 33 cases in the independent FE run.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6162637945
<details>
<summary>TPC-DS: <b>Total hot run time: 152400 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit 4f6bc8489d16a9280805ddab30df234390ea60b1, data reload: false
query5 4316 575 457 457
query6 429 210 192 192
query7 4815 450 237 237
query8 319 182 164 164
query9 8770 3999 4026 3999
query10 470 317 269 269
query11 5995 3427 3204 3204
query12 147 87 85 85
query13 1245 434 337 337
query14 6564 4782 4462 4462
query14_1 4256 4245 4278 4245
query15 207 197 185 185
query16 932 459 443 443
query17 859 710 536 536
query18 2403 415 302 302
query19 193 181 129 129
query20 78 76 77 76
query21 208 132 116 116
query22 13073 13115 12807 12807
query23 13025 12472 12123 12123
query23_1 12208 12106 12143 12106
query24 7076 821 457 457
query24_1 461 471 473 471
query25 515 396 343 343
query26 1254 259 136 136
query27 2756 437 280 280
query28 4604 1959 1964 1959
query29 1545 581 434 434
query30 296 219 186 186
query31 881 768 646 646
query32 144 88 92 88
query33 502 302 253 253
query34 920 858 495 495
query35 742 762 639 639
query36 820 834 739 739
query37 131 106 90 90
query38 1799 1755 1693 1693
query39 725 710 676 676
query39_1 681 690 685 685
query40 216 119 95 95
query41 100 68 64 64
query42 85 81 88 81
query43 364 381 318 318
query44 1300 707 713 707
query45 177 179 159 159
query46 851 951 575 575
query47 3035 2728 2944 2728
query48 295 298 210 210
query49 574 392 291 291
query50 675 271 221 221
query51 10566 10557 10694 10557
query52 78 77 73 73
query53 188 211 154 154
query54 246 193 175 175
query55 71 74 65 65
query56 220 216 200 200
query57 1615 1598 1588 1588
query58 286 254 261 254
query59 2363 2369 2109 2109
query60 291 234 217 217
query61 151 149 143 143
query62 394 338 280 280
query63 203 167 167 167
query64 2722 921 894 894
query65 3417 3370 3400 3370
query66 1802 436 316 316
query67 20266 20256 20006 20006
query68 2976 1002 621 621
query69 386 314 262 262
query70 935 853 828 828
query71 297 248 210 210
query72 2898 2763 2454 2454
query73 536 535 299 299
query74 4589 4481 4347 4347
query75 2341 2264 2008 2008
query76 2312 1019 618 618
query77 347 404 305 305
query78 8997 8969 8417 8417
query79 981 906 533 533
query80 537 413 360 360
query81 533 322 273 273
query82 576 131 106 106
query83 307 203 190 190
query84 321 122 95 95
query85 819 432 368 368
query86 310 235 235 235
query87 2047 1970 1860 1860
query88 3609 2679 2694 2679
query89 350 297 254 254
query90 1887 187 175 175
query91 164 149 125 125
query92 101 89 88 88
query93 987 996 568 568
query94 443 307 273 273
query95 585 400 324 324
query96 675 521 243 243
query97 2451 2397 2354 2354
query98 155 145 145 145
query99 775 766 648 648
Total cold run time: 233888 ms
Total hot run time: 152400 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6161745852
run buildall
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6127849953
<details>
<summary>TPC-H: <b>Total hot run time: 28740 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit 21b3cc226fee907a1280f5e2fc0f740e146a86bb, data reload: false
------ Round 1 ----------------------------------
============================================
q1 17597 5618 5556 5556
q2 2102 309 256 256
q3 10254 1401 829 829
q4 4675 475 355 355
q5 7418 788 532 532
q6 188 189 155 155
q7 755 798 611 611
q8 9249 1345 1152 1152
q9 5657 4426 4425 4425
q10 6813 1296 1027 1027
q11 435 250 236 236
q12 627 405 284 284
q13 18061 3046 2350 2350
q14 264 266 238 238
q15 q16 733 724 681 681
q17 1156 734 571 571
q18 7039 6196 6158 6158
q19 1089 958 591 591
q20 373 323 225 225
q21 4536 2240 2386 2240
q22 360 311 268 268
Total cold run time: 99381 ms
Total hot run time: 28740 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1 6160 6126 6138 6126
q2 674 581 527 527
q3 5210 5392 4952 4952
q4 2011 2109 1522 1522
q5 5269 5162 5916 5162
q6 260 196 152 152
q7 2331 2051 1845 1845
q8 3156 2784 2794 2784
q9 8271 8152 8074 8074
q10 3718 3982 3364 3364
q11 655 444 430 430
q12 683 729 514 514
q13 2904 3275 2496 2496
q14 299 301 282 282
q15 q16 734 719 658 658
q17 8421 7551 7508 7508
q18 13179 12266 13081 12266
q19 914 789 780 780
q20 2170 2172 1945 1945
q21 5744 4646 4765 4646
q22 497 458 387 387
Total cold run time: 73260 ms
Total hot run time: 66420 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6130468340
# FE Regression Coverage Report
Increment line coverage ` 92.76% (333/359)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_21b3cc226fee907a1280f5e2fc0f740e146a86bb_merge_fe/increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_21b3cc226fee907a1280f5e2fc0f740e146a86bb_merge_fe/report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6211175175
<details>
<summary>TPC-DS: <b>Total hot run time: 152437 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit cb9776041ee588919431e071140c849545b626ac, data reload: false
query5 4313 566 460 460
query6 427 209 193 193
query7 4793 457 234 234
query8 320 175 161 161
query9 8782 3936 3944 3936
query10 454 314 264 264
query11 6026 3816 3506 3506
query12 140 91 87 87
query13 1259 478 326 326
query14 6161 4008 3772 3772
query14_1 3566 3513 3532 3513
query15 210 212 200 200
query16 969 436 419 419
query17 854 656 530 530
query18 2441 437 310 310
query19 201 163 136 136
query20 86 84 84 84
query21 215 133 109 109
query22 12963 12982 12778 12778
query23 13545 12957 12638 12638
query23_1 12694 12591 12521 12521
query24 7130 843 471 471
query24_1 490 476 479 476
query25 544 425 365 365
query26 1278 259 143 143
query27 2763 441 271 271
query28 4596 1968 1966 1966
query29 1565 612 473 473
query30 298 231 185 185
query31 1002 921 812 812
query32 163 97 89 89
query33 518 306 246 246
query34 876 851 491 491
query35 754 761 648 648
query36 851 801 779 779
query37 132 102 92 92
query38 1794 1762 1692 1692
query39 795 796 746 746
query39_1 746 753 754 753
query40 217 117 99 99
query41 73 71 71 71
query42 90 84 83 83
query43 365 379 334 334
query44 1313 703 735 703
query45 174 176 165 165
query46 856 968 557 557
query47 2935 2903 2934 2903
query48 293 302 215 215
query49 571 397 293 293
query50 668 278 215 215
query51 10583 11305 10494 10494
query52 79 83 70 70
query53 186 202 148 148
query54 239 192 188 188
query55 72 71 62 62
query56 216 210 218 210
query57 1607 1582 1545 1545
query58 282 263 251 251
query59 2084 2138 1976 1976
query60 296 241 231 231
query61 149 148 150 148
query62 400 337 284 284
query63 194 164 162 162
query64 2722 957 787 787
query65 3302 3219 3214 3214
query66 1784 426 297 297
query67 20063 19987 20095 19987
query68 2934 1013 605 605
query69 399 286 254 254
query70 859 783 815 783
query71 310 237 205 205
query72 2690 2569 2275 2275
query73 522 521 295 295
query74 4591 4478 4306 4306
query75 2336 2294 1955 1955
query76 2298 1010 648 648
query77 339 374 280 280
query78 9978 9813 9158 9158
query79 994 846 514 514
query80 890 419 372 372
query81 580 321 275 275
query82 743 136 108 108
query83 308 192 179 179
query84 312 130 101 101
query85 860 429 370 370
query86 373 239 227 227
query87 2029 1938 1825 1825
query88 3603 2699 2688 2688
query89 337 286 251 251
query90 1788 178 176 176
query91 177 151 126 126
query92 95 89 99 89
query93 1002 987 579 579
query94 557 314 271 271
query95 582 335 389 335
query96 670 524 236 236
query97 2441 2473 2330 2330
query98 162 158 150 150
query99 787 760 652 652
Total cold run time: 234836 ms
Total hot run time: 152437 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-5980768713
<details>
<summary>TPC-H: <b>Total hot run time: 27651 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit ea2fd4223405ec0811ffbfa237302d540127d19e, data reload: false
------ Round 1 ----------------------------------
============================================
q1 17624 3894 3881 3881
q2 2147 358 309 309
q3 10118 1346 792 792
q4 4681 467 343 343
q5 7500 803 534 534
q6 178 172 133 133
q7 729 770 598 598
q8 9322 1481 1487 1481
q9 5412 4147 4138 4138
q10 6816 1320 1006 1006
q11 436 264 242 242
q12 630 421 301 301
q13 18051 2596 1995 1995
q14 259 262 235 235
q15 q16 736 719 671 671
q17 1678 1144 967 967
q18 6409 5560 5547 5547
q19 1166 1230 1047 1047
q20 486 404 255 255
q21 5403 3025 2868 2868
q22 441 360 308 308
Total cold run time: 100222 ms
Total hot run time: 27651 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1 4606 4436 4561 4436
q2 727 541 516 516
q3 4738 5222 4585 4585
q4 2183 2289 1455 1455
q5 4512 4480 4409 4409
q6 237 171 127 127
q7 1806 1745 1549 1549
q8 2258 2016 1975 1975
q9 7509 7128 6765 6765
q10 3647 3540 3065 3065
q11 502 374 340 340
q12 705 697 497 497
q13 2261 2588 1979 1979
q14 264 269 248 248
q15 q16 651 678 601 601
q17 7253 6674 6580 6580
q18 11839 11053 11632 11053
q19 1174 1010 1039 1010
q20 2184 2166 1891 1891
q21 4893 4032 4196 4032
q22 491 444 397 397
Total cold run time: 64440 ms
Total hot run time: 57510 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6123213514
<details>
<summary>TPC-H: <b>Total hot run time: 28662 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit 4abbea0ad82bbc4dd47631e3833a9774e030dc93, data reload: false
------ Round 1 ----------------------------------
============================================
q1 17598 5581 5511 5511
q2 2245 305 268 268
q3 10095 1388 831 831
q4 4680 466 348 348
q5 7423 785 532 532
q6 181 192 154 154
q7 785 787 604 604
q8 9244 1335 1052 1052
q9 5650 4424 4393 4393
q10 6809 1287 1023 1023
q11 427 253 232 232
q12 631 396 288 288
q13 18083 3040 2378 2378
q14 274 268 241 241
q15 q16 728 721 671 671
q17 1167 739 571 571
q18 7121 6224 6162 6162
q19 1101 946 596 596
q20 378 321 223 223
q21 5141 2321 2375 2321
q22 357 308 263 263
Total cold run time: 100118 ms
Total hot run time: 28662 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1 6147 6107 6116 6107
q2 692 560 563 560
q3 5205 5420 5005 5005
q4 2017 2140 1546 1546
q5 5278 5183 5994 5183
q6 276 201 159 159
q7 2337 1975 1794 1794
q8 3159 2785 2831 2785
q9 8301 8155 8133 8133
q10 4007 3704 3375 3375
q11 637 429 400 400
q12 685 757 521 521
q13 2933 3253 2525 2525
q14 330 325 304 304
q15 q16 698 711 682 682
q17 8365 7472 7600 7472
q18 13171 12336 12967 12336
q19 914 762 775 762
q20 2201 2172 1957 1957
q21 5817 4716 4771 4716
q22 497 485 413 413
Total cold run time: 73667 ms
Total hot run time: 66735 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6343346248
<details>
<summary>TPC-H: <b>Total hot run time: 28159 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit b8c3b95b338135c2d75aaea83d0c60bc1baef90e, data reload: false
------ Round 1 ----------------------------------
============================================
q1 17600 5156 5041 5041
q2 2149 349 241 241
q3 10190 1353 820 820
q4 4675 452 341 341
q5 7414 794 524 524
q6 178 184 152 152
q7 745 794 604 604
q8 9244 1271 1007 1007
q9 5488 4180 4165 4165
q10 6834 1269 1020 1020
q11 439 241 233 233
q12 643 389 277 277
q13 18102 3508 3008 3008
q14 272 270 251 251
q15 q16 721 704 660 660
q17 1185 745 573 573
q18 7037 6180 6100 6100
q19 1096 940 573 573
q20 375 322 226 226
q21 4950 2092 2240 2092
q22 334 287 251 251
Total cold run time: 99671 ms
Total hot run time: 28159 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1 5576 5574 5568 5568
q2 668 565 521 521
q3 5192 5393 4954 4954
q4 2003 2109 1525 1525
q5 5376 5234 5596 5234
q6 276 209 160 160
q7 2347 1973 1831 1831
q8 2984 2748 2619 2619
q9 8294 8141 8182 8141
q10 3745 3668 3267 3267
q11 722 461 421 421
q12 687 689 538 538
q13 3761 3963 3185 3185
q14 304 310 297 297
q15 q16 709 714 662 662
q17 8314 7525 6842 6842
q18 12957 12166 12838 12166
q19 874 756 752 752
q20 2134 2145 1917 1917
q21 5531 4606 4671 4606
q22 517 426 422 422
Total cold run time: 72971 ms
Total hot run time: 65628 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6315096639
<details>
<summary>TPC-H: <b>Total hot run time: 29341 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit 37ba8ccf456eddc1ab0946c37ce556f534d1fbad, data reload: false
------ Round 1 ----------------------------------
============================================
q1 17588 5501 5364 5364
q2 2140 353 271 271
q3 10178 1508 883 883
q4 4679 513 347 347
q5 7447 827 531 531
q6 204 205 163 163
q7 800 828 611 611
q8 9277 1537 1159 1159
q9 5631 4449 4411 4411
q10 6960 1367 1012 1012
q11 453 256 229 229
q12 629 454 293 293
q13 18080 4126 3061 3061
q14 288 286 254 254
q15 q16 760 742 674 674
q17 1367 767 591 591
q18 7052 6171 6137 6137
q19 1108 1108 623 623
q20 392 347 228 228
q21 5456 2239 2518 2239
q22 373 318 260 260
Total cold run time: 100862 ms
Total hot run time: 29341 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1 5964 5923 5914 5914
q2 745 633 593 593
q3 5237 5420 4957 4957
q4 2243 2396 1715 1715
q5 5306 5714 5711 5711
q6 293 216 163 163
q7 2441 2162 2083 2083
q8 3134 2810 2725 2725
q9 7985 7911 8085 7911
q10 4035 3896 3451 3451
q11 676 496 447 447
q12 757 786 561 561
q13 3774 4195 3223 3223
q14 313 320 297 297
q15 q16 722 744 716 716
q17 8408 7634 7551 7551
q18 13058 12187 13005 12187
q19 1036 838 828 828
q20 2191 2185 1972 1972
q21 6091 5098 5197 5098
q22 538 479 425 425
Total cold run time: 74947 ms
Total hot run time: 68528 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6315362500
<details>
<summary>ClickBench: <b>Total hot run time: 24.44 s</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit 37ba8ccf456eddc1ab0946c37ce556f534d1fbad, data reload: false
query1 0.01 0.01 0.01
query2 0.09 0.05 0.05
query3 0.27 0.09 0.08
query4 1.61 0.10 0.11
query5 0.24 0.24 0.24
query6 1.17 0.70 0.66
query7 0.04 0.01 0.01
query8 0.06 0.04 0.04
query9 0.40 0.34 0.35
query10 0.57 0.56 0.62
query11 0.20 0.15 0.15
query12 0.18 0.15 0.15
query13 0.48 0.50 0.49
query14 1.04 1.04 1.00
query15 0.67 0.62 0.64
query16 0.36 0.34 0.34
query17 1.10 1.12 1.13
query18 0.21 0.20 0.18
query19 2.05 2.02 1.95
query20 0.02 0.01 0.01
query21 15.52 0.19 0.13
query22 4.95 0.06 0.06
query23 16.26 0.33 0.13
query24 3.32 0.56 0.45
query25 0.12 0.10 0.04
query26 0.97 0.21 0.15
query27 0.05 0.06 0.08
query28 3.38 0.74 0.38
query29 12.52 4.05 3.26
query30 0.27 0.15 0.11
query31 2.77 0.55 0.32
query32 3.22 0.59 0.52
query33 3.20 3.17 3.20
query34 15.44 4.02 3.39
query35 3.39 3.38 3.39
query36 0.56 0.46 0.43
query37 0.10 0.07 0.06
query38 0.05 0.04 0.03
query39 0.04 0.03 0.04
query40 0.17 0.16 0.15
query41 0.09 0.04 0.03
query42 0.04 0.03 0.03
query43 0.04 0.03 0.04
Total cold run time: 97.24 s
Total hot run time: 24.44 s
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6350589762
<details>
<summary>TPC-H: <b>Total hot run time: 28677 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit b8c3b95b338135c2d75aaea83d0c60bc1baef90e, data reload: false
------ Round 1 ----------------------------------
============================================
q1 17587 5096 5021 5021
q2 2106 332 264 264
q3 10213 1388 830 830
q4 4682 472 331 331
q5 7423 782 545 545
q6 179 183 165 165
q7 735 802 596 596
q8 9237 1305 1099 1099
q9 5482 4181 4170 4170
q10 6822 1281 1028 1028
q11 440 243 230 230
q12 653 393 275 275
q13 18114 3557 3013 3013
q14 268 257 236 236
q15 q16 716 719 672 672
q17 1189 756 573 573
q18 6952 6163 6130 6130
q19 1114 967 580 580
q20 387 333 228 228
q21 5230 2399 2425 2399
q22 371 352 292 292
Total cold run time: 99900 ms
Total hot run time: 28677 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1 5944 5943 6066 5943
q2 722 586 571 571
q3 5564 5771 5304 5304
q4 1989 2177 1529 1529
q5 5762 5784 5617 5617
q6 240 189 139 139
q7 2185 1998 1741 1741
q8 3086 2673 2597 2597
q9 7851 7921 7586 7586
q10 3626 3542 3134 3134
q11 575 404 373 373
q12 651 667 497 497
q13 3298 3514 3009 3009
q14 300 284 263 263
q15 q16 667 695 605 605
q17 7692 6995 6860 6860
q18 12996 12160 12884 12160
q19 888 758 772 758
q20 2128 2134 1929 1929
q21 5550 4566 4641 4566
q22 495 443 445 443
Total cold run time: 72209 ms
Total hot run time: 65624 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-5980859275
<details>
<summary>TPC-DS: <b>Total hot run time: 152261 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit ea2fd4223405ec0811ffbfa237302d540127d19e, data reload: false
query5 4332 597 468 468
query6 432 208 190 190
query7 4814 559 290 290
query8 330 176 184 176
query9 8809 3975 3959 3959
query10 471 309 264 264
query11 5833 3546 3231 3231
query12 142 89 85 85
query13 1264 623 421 421
query14 6525 4526 4257 4257
query14_1 3968 3960 3924 3924
query15 205 199 180 180
query16 1001 465 426 426
query17 902 658 556 556
query18 2446 459 341 341
query19 209 185 140 140
query20 88 83 80 80
query21 221 134 115 115
query22 13017 13014 12764 12764
query23 13941 12961 12435 12435
query23_1 12583 12433 12462 12433
query24 7203 1147 640 640
query24_1 721 710 695 695
query25 559 430 372 372
query26 1256 313 170 170
query27 2692 551 344 344
query28 4585 1928 1951 1928
query29 1704 736 547 547
query30 298 221 186 186
query31 882 759 654 654
query32 154 104 100 100
query33 559 306 254 254
query34 1187 1101 628 628
query35 718 745 630 630
query36 773 775 711 711
query37 143 107 95 95
query38 1825 1769 1714 1714
query39 689 718 677 677
query39_1 638 638 647 638
query40 225 126 106 106
query41 73 68 67 67
query42 98 94 92 92
query43 332 345 298 298
query44 1431 715 702 702
query45 183 185 163 163
query46 1092 1215 723 723
query47 1508 1482 1406 1406
query48 378 448 282 282
query49 581 396 287 287
query50 994 354 260 260
query51 10516 10236 10175 10175
query52 87 89 79 79
query53 242 257 183 183
query54 246 198 182 182
query55 79 75 67 67
query56 217 230 223 223
query57 1529 1395 1358 1358
query58 289 254 248 248
query59 1956 2067 1836 1836
query60 282 239 213 213
query61 149 141 143 141
query62 393 318 268 268
query63 219 171 177 171
query64 2818 1036 809 809
query65 3475 3413 3411 3411
query66 1827 427 302 302
query67 20004 19857 19853 19853
query68 3248 1510 841 841
query69 406 295 254 254
query70 906 837 785 785
query71 286 232 210 210
query72 2592 2519 2265 2265
query73 862 789 394 394
query74 4587 4556 4331 4331
query75 2350 2317 1968 1968
query76 2316 1148 809 809
query77 363 401 309 309
query78 9340 9215 8645 8645
query79 1409 1219 754 754
query80 1236 492 382 382
query81 592 323 293 293
query82 632 169 129 129
query83 318 223 197 197
query84 309 143 109 109
query85 875 467 386 386
query86 409 237 219 219
query87 1968 1947 1822 1822
query88 3666 2691 2703 2691
query89 356 290 248 248
query90 1912 177 176 176
query91 166 153 123 123
query92 104 87 91 87
query93 1434 1454 822 822
query94 730 338 300 300
query95 641 365 412 365
query96 998 777 364 364
query97 2460 2422 2320 2320
query98 159 146 142 142
query99 714 725 619 619
Total cold run time: 237336 ms
Total hot run time: 152261 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-5982224611
# FE Regression Coverage Report
Increment line coverage ` 91.92% (330/359)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_ea2fd4223405ec0811ffbfa237302d540127d19e_merge_fe/increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_ea2fd4223405ec0811ffbfa237302d540127d19e_merge_fe/report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6123360781
<details>
<summary>TPC-DS: <b>Total hot run time: 151639 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit 4abbea0ad82bbc4dd47631e3833a9774e030dc93, data reload: false
query5 4329 602 470 470
query6 427 206 190 190
query7 4804 443 225 225
query8 312 176 164 164
query9 8758 3949 3915 3915
query10 473 298 256 256
query11 5882 3389 3183 3183
query12 146 89 85 85
query13 1246 434 315 315
query14 6524 4707 4485 4485
query14_1 4248 4275 4207 4207
query15 202 193 180 180
query16 947 449 432 432
query17 856 651 542 542
query18 2419 415 319 319
query19 196 187 143 143
query20 83 78 80 78
query21 207 132 114 114
query22 12937 12990 12807 12807
query23 13100 12610 12211 12211
query23_1 12379 12334 12285 12285
query24 7095 823 485 485
query24_1 481 478 482 478
query25 536 421 385 385
query26 1297 249 139 139
query27 2773 433 265 265
query28 4631 1989 1960 1960
query29 1546 586 430 430
query30 299 221 180 180
query31 874 767 654 654
query32 134 93 88 88
query33 508 295 239 239
query34 875 835 485 485
query35 732 745 638 638
query36 782 827 742 742
query37 124 103 90 90
query38 1800 1725 1700 1700
query39 719 717 683 683
query39_1 659 658 666 658
query40 220 116 93 93
query41 65 64 60 60
query42 81 84 83 83
query43 357 371 323 323
query44 1281 705 709 705
query45 173 182 163 163
query46 856 950 564 564
query47 3005 2874 2824 2824
query48 291 299 213 213
query49 570 439 294 294
query50 668 267 214 214
query51 10203 10358 10046 10046
query52 81 79 71 71
query53 183 210 150 150
query54 233 205 181 181
query55 71 65 61 61
query56 245 221 213 213
query57 1591 1598 1548 1548
query58 274 256 246 246
query59 2364 2372 2120 2120
query60 294 248 222 222
query61 144 147 145 145
query62 389 342 286 286
query63 195 166 166 166
query64 2743 928 800 800
query65 3397 3347 3371 3347
query66 1782 411 297 297
query67 20144 20297 19857 19857
query68 2993 1011 614 614
query69 379 278 248 248
query70 906 864 818 818
query71 302 224 210 210
query72 2639 2650 2383 2383
query73 517 524 295 295
query74 4588 4479 4315 4315
query75 2330 2293 1934 1934
query76 2304 1015 616 616
query77 371 411 311 311
query78 9068 8978 8476 8476
query79 1007 901 515 515
query80 552 442 404 404
query81 526 320 280 280
query82 580 136 113 113
query83 302 192 183 183
query84 307 131 94 94
query85 846 420 362 362
query86 317 250 224 224
query87 1985 1946 1855 1855
query88 3584 2683 2689 2683
query89 341 295 253 253
query90 1854 182 177 177
query91 163 146 122 122
query92 92 86 86 86
query93 1009 989 584 584
query94 454 281 267 267
query95 587 338 389 338
query96 671 526 235 235
query97 2489 2434 2329 2329
query98 157 145 150 145
query99 771 783 657 657
Total cold run time: 232950 ms
Total hot run time: 151639 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6125999997
run buildall
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on code in PR #68727:
URL: https://github.com/apache/doris/pull/68727#discussion_r4267301123
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/PlanningDiagnostics.java:
##########
@@ -0,0 +1,437 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.common.Config;
+import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.thrift.TUniqueId;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.gson.JsonObject;
+import org.apache.logging.log4j.CloseableThreadContext;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+import java.util.ArrayList;
+import java.util.EnumMap;
+import java.util.List;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.function.LongSupplier;
+import java.util.function.Supplier;
+
+/**
+ * One planning pass. The planning thread owns timers and the bounded slow-operation buffer.
+ * The connection checker reads only immutable, volatile-published steps, never planner/table locks.
+ * Timings are inclusive: nested phases and operations must not be added to their enclosing phase.
+ */
+public final class PlanningDiagnostics {
+ private static final Logger LOG = LogManager.getLogger(PlanningDiagnostics.class);
+ private static final int MAX_SLOW_OPERATIONS = 16;
+ // Internal MV planning can replace ConnectContext while the calling planner still holds table locks.
+ private static final ThreadLocal<PlanningDiagnostics> ACTIVE = new ThreadLocal<>();
+
+ public enum Phase {
+ PREPROCESS, COLLECT_TABLES, PRELOAD_METADATA, WAIT_CHANGE_VISIBLE, LOCK_TABLES,
+ ANALYZE, REWRITE, PRE_REWRITE_MV, OPTIMIZE, CHOOSE_PLAN, POST_PROCESS,
+ TRANSLATE, DISTRIBUTE, RELEASE_RESOURCES;
+
+ public String key() {
+ return name().toLowerCase(Locale.ROOT);
+ }
+ }
+
+ private final ConnectContext context;
+ private final SummaryProfile summary;
+ private final long passId;
+ private final PlanningDiagnostics parent;
+ private final PlanningDiagnostics root;
+ private final boolean inheritsQueryIdentity;
+ private final TUniqueId queryId;
+ private final long statementId;
+ private final String threadName;
+ private volatile long timeoutMs;
+ private final LongSupplier clock;
+ private final long started;
+ private final EnumMap<Phase, Timing> timings = new EnumMap<>(Phase.class);
+ private final List<Event> slowOperations = new ArrayList<>();
+ private final AtomicLong lastReport;
+ private volatile Step current;
+ private volatile Class<?> currentJob;
+ private volatile HeldLocks heldLocks = new HeldLocks(0, 0, "");
+ private volatile boolean finished;
+ // Only the root publishes this pointer, so its registered connection can inspect an internal pass.
+ private volatile PlanningDiagnostics activePass;
+ private String failedStep = "";
+ private Throwable stepFailure;
+ private long omittedOperations;
+
+ private PlanningDiagnostics(ConnectContext context) {
+ this(context, System::nanoTime);
+ }
+
+ @VisibleForTesting
+ PlanningDiagnostics(ConnectContext context, LongSupplier clock) {
+ this.context = context;
+ this.parent = ACTIVE.get();
+ this.root = parent == null ? this : parent.root;
+ this.lastReport = parent == null ? new AtomicLong(Long.MIN_VALUE) : parent.lastReport;
+ SummaryProfile contextSummary = SummaryProfile.getSummaryProfile(context);
+ this.summary = contextSummary != null ? contextSummary : parent == null ? null : parent.summary;
+ this.passId = summary == null ? 0 : summary.nextPlanningPassId();
+ TUniqueId contextQueryId = context.queryId();
+ this.inheritsQueryIdentity = contextQueryId == null && parent != null;
+ this.queryId = inheritsQueryIdentity ? parent.queryId
+ : contextQueryId == null ? null : contextQueryId.deepCopy();
+ this.statementId = inheritsQueryIdentity ? parent.statementId : context.getStmtId();
+ this.threadName = Thread.currentThread().getName();
+ this.timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ this.clock = clock;
+ this.started = clock.getAsLong();
+ }
+
+ /** Includes cleanup and restores an outer pass even when internal planning uses another connection. */
+ public static <T> T plan(ConnectContext context, Supplier<T> action) {
+ return execute(new PlanningDiagnostics(context), action);
+ }
+
+ @VisibleForTesting
+ static <T> T execute(PlanningDiagnostics diagnostics, Supplier<T> action) {
+ ConnectContext context = diagnostics.context;
+ PlanningDiagnostics previous = context.getPlanningDiagnostics();
+ ACTIVE.set(diagnostics);
+ context.setPlanningDiagnostics(diagnostics);
+ diagnostics.root.activePass = diagnostics;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ if (diagnostics.stepFailure != failure) {
+ diagnostics.failedStep = "between_phases";
+ }
+ throw failure;
+ } finally {
+ diagnostics.finished = true;
+ context.setPlanningDiagnostics(previous);
+ diagnostics.root.activePass = diagnostics.parent;
+ if (diagnostics.parent == null) {
+ ACTIVE.remove();
+ } else {
+ ACTIVE.set(diagnostics.parent);
+ }
+ diagnostics.finish(success);
+ }
+ }
+
+ public static void runPhase(ConnectContext context, Phase phase, Runnable action) {
+ phase(context, phase, () -> {
+ action.run();
+ return null;
+ });
+ }
+
+ public static <T> T phase(ConnectContext context, Phase phase, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ return diagnostics == null ? action.get() : diagnostics.measure(phase, "", "", -1, action);
+ }
+
+ /** A negative operation budget means that timeout handling belongs to the connector. */
+ public static <T> T operation(ConnectContext context, String operation, String target,
+ long budgetMs, Supplier<T> action) {
+ return operation(context, operation, () -> target, budgetMs, action);
+ }
+
+ /** Resolve the target only for an active planning pass, on the calling thread. */
+ public static <T> T operation(ConnectContext context, String operation, Supplier<String> target,
+ long budgetMs, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ if (diagnostics == null) {
+ return action.get();
+ }
+ Step step = diagnostics.current;
+ return diagnostics.measure(step == null ? Phase.PREPROCESS : step.phase,
+ operation, target.get(), budgetMs, action);
+ }
+
+ public static PlanningDiagnostics current(ConnectContext context) {
+ return context == null ? null : context.getPlanningDiagnostics();
+ }
+
+ private <T> T measure(Phase phase, String operation, String target, long budgetMs, Supplier<T> action) {
+ Step previous = current;
+ Step step = new Step(phase, operation, target, budgetMs, clock.getAsLong(),
+ operation.isEmpty() || previous == null ? -1 : previous.phaseStarted);
+ current = step;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ // Preserve the innermost failing step of this exception, not an earlier recovered MV failure.
+ if (stepFailure != failure) {
+ stepFailure = failure;
+ failedStep = phase.key() + (operation.isEmpty() ? "" : "/" + operation);
+ }
+ throw failure;
+ } finally {
+ long elapsed = clock.getAsLong() - step.started;
+ if (operation.isEmpty()) {
+ Timing timing = timings.computeIfAbsent(phase, key -> new Timing());
+ timing.nanos += elapsed;
+ timing.calls++;
+ timing.failures += success ? 0 : 1;
+ if (phase == Phase.PREPROCESS && success) {
+ // SET_VAR hints are applied by preprocessing, after this pass was created.
+ timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ }
+ } else {
+ recordOperation(step, elapsed, success);
+ }
+ current = previous;
+ }
+ }
+
+ /** Avoid allocating task descriptions for every optimizer job; format the class only on a slow report. */
+ public Class<?> setCurrentJob(Class<?> job) {
+ Class<?> previous = currentJob;
+ currentJob = job;
+ return previous;
+ }
+
+ public LockHold acquiredLock(String table) {
+ long now = clock.getAsLong();
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count + 1, previous.count == 0 ? now : previous.started,
+ previous.count == 0 ? table : previous.oldestTable);
+ return new LockHold(table, now);
+ }
+
+ /** Closed after unlocking; planner resources release in reverse acquisition order. */
+ public final class LockHold implements AutoCloseable {
+ private final String table;
+ private final long acquired;
+
+ private LockHold(String table, long acquired) {
+ this.table = table;
+ this.acquired = acquired;
+ }
+
+ @Override
+ public void close() {
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count - 1, previous.started, previous.oldestTable);
+ recordOperation(new Step(Phase.RELEASE_RESOURCES, "read_lock_hold", table, -1, acquired, -1),
+ clock.getAsLong() - acquired, true);
+ }
+ }
+
+ private void recordOperation(Step step, long nanos, boolean success) {
+ long threshold = Config.nereids_planning_operation_log_threshold_ms;
+ if (success && (threshold <= 0 || millis(nanos) < threshold)) {
+ return;
+ }
+ if (slowOperations.size() == MAX_SLOW_OPERATIONS) {
+ omittedOperations++;
+ return;
+ }
+ JsonObject event = step.toJson();
+ event.addProperty("elapsed_ms", millis(nanos));
+ event.addProperty("status", success ? "completed" : "failed");
+ slowOperations.add(new Event(this, "Planning operation", event));
+ }
+
+ /** Invoked by the existing connection timeout checker, including while a planner job is blocked. */
+ public void reportIfSlow() {
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ PlanningDiagnostics active = root.activePass;
+ if (root.finished || active == null || threshold <= 0) {
+ return;
+ }
+ // Snapshot published starts before reading the clock. A newer step/lock sampled after the clock
+ // could otherwise appear to have started in the future when the checker was descheduled.
+ Step step = active.current;
+ Class<?> job = active.currentJob;
+ HeldLocks oldest = active.heldLocks;
+ int lockCount = oldest.count;
+ for (PlanningDiagnostics outer = active.parent; outer != null; outer = outer.parent) {
+ HeldLocks locks = outer.heldLocks;
+ lockCount += locks.count;
+ if (locks.count > 0 && (oldest.count == 0 || locks.started < oldest.started)) {
+ oldest = locks;
+ }
+ }
+ long now = root.clock.getAsLong();
+ if (millis(now - root.started) < threshold) {
+ return;
+ }
+ long previous = root.lastReport.get();
+ // A minimum interval protects the checker from an accidentally zero/negative dynamic setting.
+ long interval = Math.max(1000, Config.nereids_planning_log_interval_ms);
+ if ((previous != Long.MIN_VALUE && millis(now - previous) < interval)
+ || !root.lastReport.compareAndSet(previous, now)) {
+ return;
+ }
+ JsonObject event = step == null ? new JsonObject() : step.toJson();
+ event.addProperty("status", "running");
+ event.addProperty("elapsed_ms", millis(now - active.started));
+ event.addProperty("root_pass_id", root.passId);
+ event.addProperty("root_elapsed_ms", millis(now - root.started));
+ event.addProperty("phase_elapsed_ms", step == null ? 0 : millis(now - step.phaseStarted));
+ event.addProperty("operation_elapsed_ms", step == null || step.operation.isEmpty()
+ ? 0 : millis(now - step.started));
+ event.addProperty("job", job == null ? "" : job.getSimpleName());
+ event.addProperty("held_locks", lockCount);
+ event.addProperty("oldest_lock", lockCount == 0 ? "" : bounded(oldest.oldestTable));
+ event.addProperty("oldest_lock_hold_ms", lockCount == 0 ? 0 : millis(now - oldest.started));
+ active.log("Slow planning", event);
+ }
+
+ private void finish(boolean success) {
Review Comment:
Addressed in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a). Completed passes retain a lightweight `PassSnapshot`; phase aggregates use primitive counters. Fast successful completion does not construct the full phase JSON or deep-copy it. JSON is produced for emitted events and Profile rendering/serialization.
The adapters preserve the earlier object-shaped persisted Profile format, including empty legacy last-pass values. Legacy-read and snapshot-independence tests passed. I have not measured production allocation/CPU savings, so no quantitative performance claim is made.
##########
fe/fe-core/src/main/java/org/apache/doris/datasource/ExternalTable.java:
##########
@@ -182,17 +184,17 @@ public List<Column> getFullSchema() {
// NOT getFullSchema(Optional.empty()): an empty snapshot means "this reference has no pin" (=>
// latest), whereas the no-arg form means "I have no reference, resolve from the ambient context".
// Collapsing the two would strip the ambient resolution from every statement-global caller.
- Optional<SchemaCacheValue> schemaCacheValue = getSchemaCacheValue();
- return schemaCacheValue.map(SchemaCacheValue::getSchema).orElse(null);
+ return PlanningDiagnostics.operation(ConnectContext.get(), "load_schema", this::getNameWithFullQualifiers, -1,
Review Comment:
Addressed in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a) by caching the qualified target name within each active pass, keyed by table identity. Repeated schema/partition instrumentation reuses that name. Without active diagnostics, it does not resolve the target.
The underlying schema/partition calls remain inside their diagnostic scopes; this change caches the display name rather than skipping observation of those operations. Tests cover target capture/cache behavior and no-diagnostics resolution.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6211266036
<details>
<summary>ClickBench: <b>Total hot run time: 24.94 s</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit cb9776041ee588919431e071140c849545b626ac, data reload: false
query1 0.01 0.01 0.00
query2 0.10 0.06 0.05
query3 0.27 0.13 0.12
query4 1.62 0.12 0.12
query5 0.26 0.25 0.24
query6 1.17 0.69 0.67
query7 0.04 0.01 0.00
query8 0.06 0.04 0.04
query9 0.41 0.34 0.35
query10 0.62 0.57 0.62
query11 0.20 0.14 0.14
query12 0.19 0.15 0.15
query13 0.49 0.49 0.48
query14 1.02 1.01 1.00
query15 0.63 0.63 0.62
query16 0.31 0.34 0.33
query17 1.19 1.15 1.16
query18 0.22 0.21 0.21
query19 2.11 2.06 2.05
query20 0.02 0.01 0.02
query21 15.49 0.28 0.14
query22 4.60 0.06 0.05
query23 16.28 0.31 0.12
query24 2.85 0.81 0.76
query25 0.10 0.04 0.03
query26 1.84 0.24 0.15
query27 0.06 0.03 0.03
query28 2.12 0.59 0.38
query29 12.53 4.16 3.33
query30 0.29 0.15 0.14
query31 2.76 0.58 0.34
query32 3.22 0.62 0.52
query33 3.12 3.14 3.26
query34 15.56 3.99 3.40
query35 3.34 3.34 3.34
query36 0.58 0.50 0.43
query37 0.11 0.07 0.06
query38 0.06 0.04 0.04
query39 0.04 0.03 0.02
query40 0.18 0.15 0.14
query41 0.08 0.04 0.03
query42 0.04 0.03 0.03
query43 0.04 0.04 0.03
Total cold run time: 96.23 s
Total hot run time: 24.94 s
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6212335203
# FE UT Coverage Report
Increment line coverage ` 96.06% (414/431)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_cb9776041ee588919431e071140c849545b626ac/fe_increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_cb9776041ee588919431e071140c849545b626ac/fe_report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6211014869
<details>
<summary>TPC-H: <b>Total hot run time: 29528 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit cb9776041ee588919431e071140c849545b626ac, data reload: false
------ Round 1 ----------------------------------
============================================
q1 17609 5655 5539 5539
q2 2093 314 266 266
q3 10253 1458 837 837
q4 4678 466 343 343
q5 7429 789 536 536
q6 183 183 155 155
q7 755 786 604 604
q8 9255 1323 1076 1076
q9 5532 4263 4231 4231
q10 6810 1289 1030 1030
q11 430 247 232 232
q12 636 392 285 285
q13 18119 3573 2970 2970
q14 267 262 246 246
q15 q16 734 725 675 675
q17 1195 768 585 585
q18 7108 6239 6207 6207
q19 1118 957 587 587
q20 387 329 218 218
q21 5653 2609 2660 2609
q22 398 367 297 297
Total cold run time: 100642 ms
Total hot run time: 29528 ms
----- Round 2, with runtime_filter_mode=off -----
============================================
q1 6679 6648 6709 6648
q2 772 630 569 569
q3 5614 5708 5387 5387
q4 2071 2218 1592 1592
q5 5754 5615 5857 5615
q6 244 187 143 143
q7 2257 2029 1848 1848
q8 3128 2690 2790 2690
q9 8236 8055 7840 7840
q10 3634 3602 3269 3269
q11 584 398 383 383
q12 648 679 491 491
q13 3241 3522 2985 2985
q14 287 283 260 260
q15 q16 650 678 620 620
q17 7848 7026 6860 6860
q18 13133 12245 13132 12245
q19 907 802 783 783
q20 2187 2176 1937 1937
q21 5788 4710 4818 4710
q22 502 476 399 399
Total cold run time: 74164 ms
Total hot run time: 67274 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-5982168968
# FE UT Coverage Report
Increment line coverage ` 96.94% (348/359)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_ea2fd4223405ec0811ffbfa237302d540127d19e/fe_increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_ea2fd4223405ec0811ffbfa237302d540127d19e/fe_report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6336061824
run buildall
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6350870732
<details>
<summary>ClickBench: <b>Total hot run time: 24.05 s</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit b8c3b95b338135c2d75aaea83d0c60bc1baef90e, data reload: false
query1 0.01 0.00 0.01
query2 0.09 0.06 0.05
query3 0.26 0.08 0.08
query4 1.62 0.09 0.10
query5 0.26 0.24 0.23
query6 1.17 0.68 0.68
query7 0.04 0.00 0.00
query8 0.06 0.03 0.04
query9 0.39 0.36 0.35
query10 0.57 0.57 0.58
query11 0.20 0.14 0.13
query12 0.18 0.14 0.14
query13 0.49 0.50 0.49
query14 1.01 1.01 1.02
query15 0.61 0.60 0.60
query16 0.35 0.31 0.34
query17 1.14 1.17 1.14
query18 0.22 0.19 0.18
query19 2.10 2.04 2.00
query20 0.02 0.02 0.01
query21 15.49 0.19 0.14
query22 4.98 0.05 0.05
query23 16.30 0.33 0.12
query24 3.04 0.61 0.30
query25 0.10 0.08 0.06
query26 1.17 0.22 0.15
query27 0.07 0.04 0.03
query28 3.76 0.84 0.35
query29 12.47 4.10 3.22
query30 0.29 0.13 0.10
query31 2.77 0.56 0.32
query32 3.22 0.60 0.50
query33 3.19 3.19 3.17
query34 15.36 3.95 3.36
query35 3.35 3.32 3.32
query36 0.54 0.43 0.42
query37 0.09 0.07 0.07
query38 0.05 0.04 0.04
query39 0.04 0.03 0.03
query40 0.17 0.15 0.14
query41 0.08 0.03 0.02
query42 0.03 0.02 0.02
query43 0.04 0.03 0.04
Total cold run time: 97.39 s
Total hot run time: 24.05 s
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6350881457
# FE Regression Coverage Report
Increment line coverage ` 87.24% (376/431)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e_merge_fe/increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e_merge_fe/report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6129565957
<details>
<summary>ClickBench: <b>Total hot run time: 24.61 s</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit 21b3cc226fee907a1280f5e2fc0f740e146a86bb, data reload: false
query1 0.00 0.00 0.01
query2 0.10 0.05 0.06
query3 0.27 0.12 0.11
query4 1.61 0.13 0.13
query5 0.28 0.26 0.26
query6 1.17 0.69 0.69
query7 0.04 0.00 0.01
query8 0.05 0.04 0.04
query9 0.43 0.35 0.37
query10 0.60 0.56 0.58
query11 0.21 0.15 0.14
query12 0.19 0.15 0.15
query13 0.50 0.50 0.50
query14 0.98 0.98 0.97
query15 0.65 0.61 0.62
query16 0.32 0.35 0.32
query17 1.14 1.17 1.17
query18 0.22 0.20 0.20
query19 2.04 1.94 1.95
query20 0.02 0.02 0.01
query21 15.48 0.29 0.16
query22 4.54 0.06 0.05
query23 16.22 0.33 0.12
query24 2.93 0.73 0.39
query25 0.10 0.05 0.05
query26 1.49 0.24 0.15
query27 0.04 0.04 0.03
query28 2.16 0.66 0.42
query29 12.53 4.14 3.30
query30 0.29 0.14 0.14
query31 2.76 0.57 0.34
query32 3.22 0.62 0.51
query33 3.28 3.26 3.22
query34 15.60 3.98 3.38
query35 3.37 3.35 3.34
query36 0.55 0.45 0.46
query37 0.10 0.07 0.06
query38 0.05 0.04 0.04
query39 0.04 0.03 0.03
query40 0.17 0.15 0.14
query41 0.09 0.03 0.03
query42 0.04 0.03 0.03
query43 0.04 0.04 0.03
Total cold run time: 95.91 s
Total hot run time: 24.61 s
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-5980897487
<details>
<summary>ClickBench: <b>Total hot run time: 23.98 s</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit ea2fd4223405ec0811ffbfa237302d540127d19e, data reload: false
query1 0.01 0.01 0.01
query2 0.09 0.04 0.04
query3 0.26 0.15 0.13
query4 1.61 0.14 0.14
query5 0.24 0.21 0.23
query6 1.16 0.92 0.93
query7 0.03 0.01 0.00
query8 0.06 0.04 0.03
query9 0.38 0.32 0.33
query10 0.54 0.55 0.55
query11 0.20 0.14 0.14
query12 0.19 0.15 0.14
query13 0.46 0.46 0.45
query14 0.94 0.96 0.95
query15 0.59 0.58 0.57
query16 0.30 0.32 0.33
query17 1.05 1.05 1.14
query18 0.21 0.19 0.20
query19 2.00 1.94 1.96
query20 0.02 0.01 0.01
query21 15.48 0.22 0.15
query22 4.89 0.06 0.06
query23 16.14 0.31 0.13
query24 2.99 0.42 0.31
query25 0.10 0.05 0.05
query26 0.75 0.21 0.16
query27 0.05 0.03 0.04
query28 3.49 0.76 0.34
query29 12.50 4.07 3.25
query30 0.27 0.16 0.15
query31 2.77 0.55 0.30
query32 3.22 0.58 0.48
query33 3.15 3.20 3.21
query34 15.57 3.93 3.28
query35 3.19 3.21 3.26
query36 0.55 0.45 0.43
query37 0.10 0.06 0.06
query38 0.05 0.04 0.03
query39 0.04 0.03 0.02
query40 0.17 0.16 0.14
query41 0.09 0.03 0.03
query42 0.03 0.03 0.03
query43 0.04 0.04 0.03
Total cold run time: 95.97 s
Total hot run time: 23.98 s
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on code in PR #68727:
URL: https://github.com/apache/doris/pull/68727#discussion_r4267299273
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/PlanningDiagnostics.java:
##########
@@ -0,0 +1,437 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.common.Config;
+import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.thrift.TUniqueId;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.gson.JsonObject;
+import org.apache.logging.log4j.CloseableThreadContext;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+import java.util.ArrayList;
+import java.util.EnumMap;
+import java.util.List;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.function.LongSupplier;
+import java.util.function.Supplier;
+
+/**
+ * One planning pass. The planning thread owns timers and the bounded slow-operation buffer.
+ * The connection checker reads only immutable, volatile-published steps, never planner/table locks.
+ * Timings are inclusive: nested phases and operations must not be added to their enclosing phase.
+ */
+public final class PlanningDiagnostics {
+ private static final Logger LOG = LogManager.getLogger(PlanningDiagnostics.class);
+ private static final int MAX_SLOW_OPERATIONS = 16;
+ // Internal MV planning can replace ConnectContext while the calling planner still holds table locks.
+ private static final ThreadLocal<PlanningDiagnostics> ACTIVE = new ThreadLocal<>();
+
+ public enum Phase {
+ PREPROCESS, COLLECT_TABLES, PRELOAD_METADATA, WAIT_CHANGE_VISIBLE, LOCK_TABLES,
+ ANALYZE, REWRITE, PRE_REWRITE_MV, OPTIMIZE, CHOOSE_PLAN, POST_PROCESS,
+ TRANSLATE, DISTRIBUTE, RELEASE_RESOURCES;
+
+ public String key() {
+ return name().toLowerCase(Locale.ROOT);
+ }
+ }
+
+ private final ConnectContext context;
+ private final SummaryProfile summary;
+ private final long passId;
+ private final PlanningDiagnostics parent;
+ private final PlanningDiagnostics root;
+ private final boolean inheritsQueryIdentity;
+ private final TUniqueId queryId;
+ private final long statementId;
+ private final String threadName;
+ private volatile long timeoutMs;
+ private final LongSupplier clock;
+ private final long started;
+ private final EnumMap<Phase, Timing> timings = new EnumMap<>(Phase.class);
+ private final List<Event> slowOperations = new ArrayList<>();
+ private final AtomicLong lastReport;
+ private volatile Step current;
+ private volatile Class<?> currentJob;
+ private volatile HeldLocks heldLocks = new HeldLocks(0, 0, "");
+ private volatile boolean finished;
+ // Only the root publishes this pointer, so its registered connection can inspect an internal pass.
+ private volatile PlanningDiagnostics activePass;
+ private String failedStep = "";
+ private Throwable stepFailure;
+ private long omittedOperations;
+
+ private PlanningDiagnostics(ConnectContext context) {
+ this(context, System::nanoTime);
+ }
+
+ @VisibleForTesting
+ PlanningDiagnostics(ConnectContext context, LongSupplier clock) {
+ this.context = context;
+ this.parent = ACTIVE.get();
+ this.root = parent == null ? this : parent.root;
+ this.lastReport = parent == null ? new AtomicLong(Long.MIN_VALUE) : parent.lastReport;
+ SummaryProfile contextSummary = SummaryProfile.getSummaryProfile(context);
+ this.summary = contextSummary != null ? contextSummary : parent == null ? null : parent.summary;
Review Comment:
Addressed in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a). A nested pass sharing its parent's SummaryProfile now updates separate nested-pass counts and the last nested breakdown, without adding its time/count to root totals. Root attempts still accumulate across retries/CTAS.
`testNestedRewriteDoesNotInflateRootTotals` verifies one root pass and a rewrite total that includes the nested work only once. Nested-failure counts and independent nested Profile details are also covered.
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java:
##########
@@ -582,6 +584,21 @@ public boolean isWarmup() {
@ResetOnRetry(ResetScope.PLAN)
private long waitChangeVisibleEndTime = -1L;
+ @SerializedName("planningPassCount")
+ private long planningPassCount;
Review Comment:
Adopted the smaller Audit surface in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a): only `planning_passes`, `planning_failed_passes`, and `planning_last_failed` are added, after a root pass completes. Per-phase totals/failures remain in Profile.
The code and PR description explicitly distinguish cumulative root-attempt summaries from legacy last-attempt timing keys. A retry test covers accumulation, and the real Audit regression with Profile disabled verified exactly three `planning_*` keys for successful and failed queries. Its `.out` was runner-generated and then verified in a second run.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on code in PR #68727:
URL: https://github.com/apache/doris/pull/68727#discussion_r4267304461
##########
fe/fe-core/src/main/java/org/apache/doris/nereids/jobs/scheduler/SimpleJobScheduler.java:
##########
@@ -48,7 +49,15 @@ public void executeJobPool(ScheduleContext scheduleContext) {
}
}
Job job = pool.pop();
- job.execute();
+ PlanningDiagnostics diagnostics = PlanningDiagnostics.current(context.getConnectContext());
Review Comment:
Hoisted `PlanningDiagnostics.current(context)` above the optimizer job loop in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a). The loop now only updates the current job on that captured diagnostics instance. The scheduler's cancellation and exception paths are unchanged.
##########
fe/fe-core/src/main/java/org/apache/doris/qe/ConnectContext.java:
##########
@@ -1326,7 +1327,22 @@ public void cancelQuery(Status cancelReason) {
}
}
+ // Published independently of StatementContext's monitor, which is held during table-lock acquisition.
+ private volatile PlanningDiagnostics planningDiagnostics;
+
+ public PlanningDiagnostics getPlanningDiagnostics() {
+ return planningDiagnostics;
+ }
+
+ public void setPlanningDiagnostics(PlanningDiagnostics diagnostics) {
+ planningDiagnostics = diagnostics;
+ }
+
public void checkTimeout(long now) {
+ PlanningDiagnostics diagnostics = planningDiagnostics;
+ if (diagnostics != null) {
+ diagnostics.reportIfSlow();
Review Comment:
Addressed in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a). The existing timeout/kill logic now runs first, and `reportIfSlow()` runs afterward in `finally`. Diagnostic formatting/logging can no longer prevent reaching the timeout decision for that round.
The diagnostic reference is captured before handling, so cancellation can clear the connection state without losing the diagnostic snapshot.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6310590629
run buildall
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6336069035
run buildall
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6210000672
run buildall
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-5980306197
Thank you for your contribution to Apache Doris.
Don't know what should be done next? See [How to process your PR](https://doris.apache.org/community/how-to-contribute/review-and-ci).
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?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6129491101
<details>
<summary>TPC-DS: <b>Total hot run time: 151939 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit 21b3cc226fee907a1280f5e2fc0f740e146a86bb, data reload: false
query5 4307 571 456 456
query6 418 210 210 210
query7 4829 465 228 228
query8 323 186 175 175
query9 8796 4110 4063 4063
query10 489 320 265 265
query11 6006 3423 3194 3194
query12 146 100 86 86
query13 1258 453 329 329
query14 6578 4803 4455 4455
query14_1 4275 4274 4207 4207
query15 207 210 185 185
query16 945 445 441 441
query17 861 661 550 550
query18 2420 424 331 331
query19 201 172 136 136
query20 82 79 80 79
query21 215 134 114 114
query22 13054 13158 12805 12805
query23 13093 12536 12038 12038
query23_1 12193 12142 12183 12142
query24 7111 828 460 460
query24_1 472 477 466 466
query25 548 427 368 368
query26 1251 270 141 141
query27 2762 444 275 275
query28 4623 1998 1985 1985
query29 1572 601 457 457
query30 300 215 188 188
query31 903 772 650 650
query32 156 90 92 90
query33 520 311 245 245
query34 919 857 497 497
query35 759 781 650 650
query36 816 802 750 750
query37 128 107 94 94
query38 1805 1763 1724 1724
query39 716 734 694 694
query39_1 687 695 691 691
query40 221 118 102 102
query41 71 68 71 68
query42 102 91 84 84
query43 369 374 332 332
query44 1351 708 703 703
query45 182 176 161 161
query46 869 957 567 567
query47 3027 3003 2782 2782
query48 302 304 219 219
query49 576 392 291 291
query50 678 272 221 221
query51 10366 10203 10225 10203
query52 79 82 71 71
query53 184 205 154 154
query54 249 193 178 178
query55 81 66 67 66
query56 223 242 200 200
query57 1607 1600 1554 1554
query58 293 266 274 266
query59 2350 2396 2157 2157
query60 280 242 220 220
query61 149 148 144 144
query62 423 345 288 288
query63 201 156 165 156
query64 2727 903 783 783
query65 3448 3390 3363 3363
query66 1760 411 326 326
query67 19979 20024 19936 19936
query68 3025 1005 616 616
query69 389 286 243 243
query70 927 824 860 824
query71 298 239 218 218
query72 2677 2571 2321 2321
query73 526 527 298 298
query74 4632 4481 4330 4330
query75 2330 2315 1983 1983
query76 2296 1038 631 631
query77 364 378 301 301
query78 8943 8947 8526 8526
query79 974 887 531 531
query80 682 440 336 336
query81 570 327 278 278
query82 577 138 114 114
query83 263 193 177 177
query84 310 126 108 108
query85 891 419 365 365
query86 336 242 229 229
query87 2034 2023 1812 1812
query88 3623 2715 2699 2699
query89 341 303 265 265
query90 1815 179 188 179
query91 167 157 123 123
query92 102 76 77 76
query93 1044 993 576 576
query94 468 303 271 271
query95 589 408 318 318
query96 678 533 231 231
query97 2450 2417 2314 2314
query98 164 163 154 154
query99 783 771 651 651
Total cold run time: 233885 ms
Total hot run time: 151939 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "Ryan19929 (via GitHub)" <gi...@apache.org>.
Ryan19929 commented on code in PR #68727:
URL: https://github.com/apache/doris/pull/68727#discussion_r4253916246
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/PlanningDiagnostics.java:
##########
@@ -0,0 +1,437 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.common.Config;
+import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.thrift.TUniqueId;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.gson.JsonObject;
+import org.apache.logging.log4j.CloseableThreadContext;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+import java.util.ArrayList;
+import java.util.EnumMap;
+import java.util.List;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.function.LongSupplier;
+import java.util.function.Supplier;
+
+/**
+ * One planning pass. The planning thread owns timers and the bounded slow-operation buffer.
+ * The connection checker reads only immutable, volatile-published steps, never planner/table locks.
+ * Timings are inclusive: nested phases and operations must not be added to their enclosing phase.
+ */
+public final class PlanningDiagnostics {
+ private static final Logger LOG = LogManager.getLogger(PlanningDiagnostics.class);
+ private static final int MAX_SLOW_OPERATIONS = 16;
+ // Internal MV planning can replace ConnectContext while the calling planner still holds table locks.
+ private static final ThreadLocal<PlanningDiagnostics> ACTIVE = new ThreadLocal<>();
+
+ public enum Phase {
+ PREPROCESS, COLLECT_TABLES, PRELOAD_METADATA, WAIT_CHANGE_VISIBLE, LOCK_TABLES,
+ ANALYZE, REWRITE, PRE_REWRITE_MV, OPTIMIZE, CHOOSE_PLAN, POST_PROCESS,
+ TRANSLATE, DISTRIBUTE, RELEASE_RESOURCES;
+
+ public String key() {
+ return name().toLowerCase(Locale.ROOT);
+ }
+ }
+
+ private final ConnectContext context;
+ private final SummaryProfile summary;
+ private final long passId;
+ private final PlanningDiagnostics parent;
+ private final PlanningDiagnostics root;
+ private final boolean inheritsQueryIdentity;
+ private final TUniqueId queryId;
+ private final long statementId;
+ private final String threadName;
+ private volatile long timeoutMs;
+ private final LongSupplier clock;
+ private final long started;
+ private final EnumMap<Phase, Timing> timings = new EnumMap<>(Phase.class);
+ private final List<Event> slowOperations = new ArrayList<>();
+ private final AtomicLong lastReport;
+ private volatile Step current;
+ private volatile Class<?> currentJob;
+ private volatile HeldLocks heldLocks = new HeldLocks(0, 0, "");
+ private volatile boolean finished;
+ // Only the root publishes this pointer, so its registered connection can inspect an internal pass.
+ private volatile PlanningDiagnostics activePass;
+ private String failedStep = "";
+ private Throwable stepFailure;
+ private long omittedOperations;
+
+ private PlanningDiagnostics(ConnectContext context) {
+ this(context, System::nanoTime);
+ }
+
+ @VisibleForTesting
+ PlanningDiagnostics(ConnectContext context, LongSupplier clock) {
+ this.context = context;
+ this.parent = ACTIVE.get();
+ this.root = parent == null ? this : parent.root;
+ this.lastReport = parent == null ? new AtomicLong(Long.MIN_VALUE) : parent.lastReport;
+ SummaryProfile contextSummary = SummaryProfile.getSummaryProfile(context);
+ this.summary = contextSummary != null ? contextSummary : parent == null ? null : parent.summary;
Review Comment:
[P2] Nested MV planning passes are double-counted in the `planning_*` audit totals
When MV rewrite plans an MV definition in-line, `InitMaterializationContextHook` (around :283-291) calls `MTMVPlanUtil.createBasicMvContext(...)` → `MTMVCache.from(...)` → `planWithLock(...)`. That context has no `SummaryProfile`, so the inner pass falls back to `parent.summary` here, and its `finish()` adds the inner phase times to the same totals through `SummaryProfile.addPlanningPass`.
The outer pass's rewrite phase already includes all of the inner planning. As a result:
- `planning_rewrite` counts the inner rewrite twice;
- `planning_analyze` / `planning_optimize` include time spent planning the MV-definition SQL;
- `planning_passes` becomes `K + 1` for `K` such MVs.
`testNestedAndRepeatedPlanningRestoreParentAndAccumulate` encodes this behavior, which contradicts the "nested phases must not be added to their enclosing phase" note. Consider aggregating only root passes into the audit totals and keeping the nested breakdown in the Profile, or define the per-key semantics explicitly.
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java:
##########
@@ -582,6 +584,21 @@ public boolean isWarmup() {
@ResetOnRetry(ResetScope.PLAN)
private long waitChangeVisibleEndTime = -1L;
+ @SerializedName("planningPassCount")
+ private long planningPassCount;
Review Comment:
[P2] Retry semantics are mixed in one map, and the audit field roughly doubles
These new fields have no `@ResetOnRetry`. After a retry, the legacy `plan_times_ms` keys (`analyze`, `rewrite`, ...) describe only the last attempt, while the `planning_*` keys sum all attempts, so the same map carries two meanings. Either reset them with `ResetScope.PLAN`, or document that they are cumulative.
Size: every audited statement gains about 19 keys, six of which overlap existing ones (`analyze`, `rewrite`, `optimize`, `lock_tables`, `translate`, `distribute`). That grows every row in `fe.audit.log` and `__internal_schema.audit_log`. Consider limiting the audit field to two or three summary keys (passes / failed passes / last failed) and keeping the per-phase detail in the Profile.
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/PlanningDiagnostics.java:
##########
@@ -0,0 +1,437 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.common.Config;
+import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.thrift.TUniqueId;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.gson.JsonObject;
+import org.apache.logging.log4j.CloseableThreadContext;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+import java.util.ArrayList;
+import java.util.EnumMap;
+import java.util.List;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.function.LongSupplier;
+import java.util.function.Supplier;
+
+/**
+ * One planning pass. The planning thread owns timers and the bounded slow-operation buffer.
+ * The connection checker reads only immutable, volatile-published steps, never planner/table locks.
+ * Timings are inclusive: nested phases and operations must not be added to their enclosing phase.
+ */
+public final class PlanningDiagnostics {
+ private static final Logger LOG = LogManager.getLogger(PlanningDiagnostics.class);
+ private static final int MAX_SLOW_OPERATIONS = 16;
+ // Internal MV planning can replace ConnectContext while the calling planner still holds table locks.
+ private static final ThreadLocal<PlanningDiagnostics> ACTIVE = new ThreadLocal<>();
+
+ public enum Phase {
+ PREPROCESS, COLLECT_TABLES, PRELOAD_METADATA, WAIT_CHANGE_VISIBLE, LOCK_TABLES,
+ ANALYZE, REWRITE, PRE_REWRITE_MV, OPTIMIZE, CHOOSE_PLAN, POST_PROCESS,
+ TRANSLATE, DISTRIBUTE, RELEASE_RESOURCES;
+
+ public String key() {
+ return name().toLowerCase(Locale.ROOT);
+ }
+ }
+
+ private final ConnectContext context;
+ private final SummaryProfile summary;
+ private final long passId;
+ private final PlanningDiagnostics parent;
+ private final PlanningDiagnostics root;
+ private final boolean inheritsQueryIdentity;
+ private final TUniqueId queryId;
+ private final long statementId;
+ private final String threadName;
+ private volatile long timeoutMs;
+ private final LongSupplier clock;
+ private final long started;
+ private final EnumMap<Phase, Timing> timings = new EnumMap<>(Phase.class);
+ private final List<Event> slowOperations = new ArrayList<>();
+ private final AtomicLong lastReport;
+ private volatile Step current;
+ private volatile Class<?> currentJob;
+ private volatile HeldLocks heldLocks = new HeldLocks(0, 0, "");
+ private volatile boolean finished;
+ // Only the root publishes this pointer, so its registered connection can inspect an internal pass.
+ private volatile PlanningDiagnostics activePass;
+ private String failedStep = "";
+ private Throwable stepFailure;
+ private long omittedOperations;
+
+ private PlanningDiagnostics(ConnectContext context) {
+ this(context, System::nanoTime);
+ }
+
+ @VisibleForTesting
+ PlanningDiagnostics(ConnectContext context, LongSupplier clock) {
+ this.context = context;
+ this.parent = ACTIVE.get();
+ this.root = parent == null ? this : parent.root;
+ this.lastReport = parent == null ? new AtomicLong(Long.MIN_VALUE) : parent.lastReport;
+ SummaryProfile contextSummary = SummaryProfile.getSummaryProfile(context);
+ this.summary = contextSummary != null ? contextSummary : parent == null ? null : parent.summary;
+ this.passId = summary == null ? 0 : summary.nextPlanningPassId();
+ TUniqueId contextQueryId = context.queryId();
+ this.inheritsQueryIdentity = contextQueryId == null && parent != null;
+ this.queryId = inheritsQueryIdentity ? parent.queryId
+ : contextQueryId == null ? null : contextQueryId.deepCopy();
+ this.statementId = inheritsQueryIdentity ? parent.statementId : context.getStmtId();
+ this.threadName = Thread.currentThread().getName();
+ this.timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ this.clock = clock;
+ this.started = clock.getAsLong();
+ }
+
+ /** Includes cleanup and restores an outer pass even when internal planning uses another connection. */
+ public static <T> T plan(ConnectContext context, Supplier<T> action) {
+ return execute(new PlanningDiagnostics(context), action);
+ }
+
+ @VisibleForTesting
+ static <T> T execute(PlanningDiagnostics diagnostics, Supplier<T> action) {
+ ConnectContext context = diagnostics.context;
+ PlanningDiagnostics previous = context.getPlanningDiagnostics();
+ ACTIVE.set(diagnostics);
+ context.setPlanningDiagnostics(diagnostics);
+ diagnostics.root.activePass = diagnostics;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ if (diagnostics.stepFailure != failure) {
+ diagnostics.failedStep = "between_phases";
+ }
+ throw failure;
+ } finally {
+ diagnostics.finished = true;
+ context.setPlanningDiagnostics(previous);
+ diagnostics.root.activePass = diagnostics.parent;
+ if (diagnostics.parent == null) {
+ ACTIVE.remove();
+ } else {
+ ACTIVE.set(diagnostics.parent);
+ }
+ diagnostics.finish(success);
+ }
+ }
+
+ public static void runPhase(ConnectContext context, Phase phase, Runnable action) {
+ phase(context, phase, () -> {
+ action.run();
+ return null;
+ });
+ }
+
+ public static <T> T phase(ConnectContext context, Phase phase, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ return diagnostics == null ? action.get() : diagnostics.measure(phase, "", "", -1, action);
+ }
+
+ /** A negative operation budget means that timeout handling belongs to the connector. */
+ public static <T> T operation(ConnectContext context, String operation, String target,
+ long budgetMs, Supplier<T> action) {
+ return operation(context, operation, () -> target, budgetMs, action);
+ }
+
+ /** Resolve the target only for an active planning pass, on the calling thread. */
+ public static <T> T operation(ConnectContext context, String operation, Supplier<String> target,
+ long budgetMs, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ if (diagnostics == null) {
+ return action.get();
+ }
+ Step step = diagnostics.current;
+ return diagnostics.measure(step == null ? Phase.PREPROCESS : step.phase,
+ operation, target.get(), budgetMs, action);
+ }
+
+ public static PlanningDiagnostics current(ConnectContext context) {
+ return context == null ? null : context.getPlanningDiagnostics();
+ }
+
+ private <T> T measure(Phase phase, String operation, String target, long budgetMs, Supplier<T> action) {
+ Step previous = current;
+ Step step = new Step(phase, operation, target, budgetMs, clock.getAsLong(),
+ operation.isEmpty() || previous == null ? -1 : previous.phaseStarted);
+ current = step;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ // Preserve the innermost failing step of this exception, not an earlier recovered MV failure.
+ if (stepFailure != failure) {
+ stepFailure = failure;
+ failedStep = phase.key() + (operation.isEmpty() ? "" : "/" + operation);
+ }
+ throw failure;
+ } finally {
+ long elapsed = clock.getAsLong() - step.started;
+ if (operation.isEmpty()) {
+ Timing timing = timings.computeIfAbsent(phase, key -> new Timing());
+ timing.nanos += elapsed;
+ timing.calls++;
+ timing.failures += success ? 0 : 1;
+ if (phase == Phase.PREPROCESS && success) {
+ // SET_VAR hints are applied by preprocessing, after this pass was created.
+ timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ }
+ } else {
+ recordOperation(step, elapsed, success);
+ }
+ current = previous;
+ }
+ }
+
+ /** Avoid allocating task descriptions for every optimizer job; format the class only on a slow report. */
+ public Class<?> setCurrentJob(Class<?> job) {
+ Class<?> previous = currentJob;
+ currentJob = job;
+ return previous;
+ }
+
+ public LockHold acquiredLock(String table) {
+ long now = clock.getAsLong();
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count + 1, previous.count == 0 ? now : previous.started,
+ previous.count == 0 ? table : previous.oldestTable);
+ return new LockHold(table, now);
+ }
+
+ /** Closed after unlocking; planner resources release in reverse acquisition order. */
+ public final class LockHold implements AutoCloseable {
+ private final String table;
+ private final long acquired;
+
+ private LockHold(String table, long acquired) {
+ this.table = table;
+ this.acquired = acquired;
+ }
+
+ @Override
+ public void close() {
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count - 1, previous.started, previous.oldestTable);
+ recordOperation(new Step(Phase.RELEASE_RESOURCES, "read_lock_hold", table, -1, acquired, -1),
+ clock.getAsLong() - acquired, true);
+ }
+ }
+
+ private void recordOperation(Step step, long nanos, boolean success) {
+ long threshold = Config.nereids_planning_operation_log_threshold_ms;
+ if (success && (threshold <= 0 || millis(nanos) < threshold)) {
+ return;
+ }
+ if (slowOperations.size() == MAX_SLOW_OPERATIONS) {
+ omittedOperations++;
+ return;
+ }
+ JsonObject event = step.toJson();
+ event.addProperty("elapsed_ms", millis(nanos));
+ event.addProperty("status", success ? "completed" : "failed");
+ slowOperations.add(new Event(this, "Planning operation", event));
+ }
+
+ /** Invoked by the existing connection timeout checker, including while a planner job is blocked. */
+ public void reportIfSlow() {
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ PlanningDiagnostics active = root.activePass;
+ if (root.finished || active == null || threshold <= 0) {
+ return;
+ }
+ // Snapshot published starts before reading the clock. A newer step/lock sampled after the clock
+ // could otherwise appear to have started in the future when the checker was descheduled.
+ Step step = active.current;
+ Class<?> job = active.currentJob;
+ HeldLocks oldest = active.heldLocks;
+ int lockCount = oldest.count;
+ for (PlanningDiagnostics outer = active.parent; outer != null; outer = outer.parent) {
+ HeldLocks locks = outer.heldLocks;
+ lockCount += locks.count;
+ if (locks.count > 0 && (oldest.count == 0 || locks.started < oldest.started)) {
+ oldest = locks;
+ }
+ }
+ long now = root.clock.getAsLong();
+ if (millis(now - root.started) < threshold) {
+ return;
+ }
+ long previous = root.lastReport.get();
+ // A minimum interval protects the checker from an accidentally zero/negative dynamic setting.
+ long interval = Math.max(1000, Config.nereids_planning_log_interval_ms);
+ if ((previous != Long.MIN_VALUE && millis(now - previous) < interval)
+ || !root.lastReport.compareAndSet(previous, now)) {
+ return;
+ }
+ JsonObject event = step == null ? new JsonObject() : step.toJson();
+ event.addProperty("status", "running");
+ event.addProperty("elapsed_ms", millis(now - active.started));
+ event.addProperty("root_pass_id", root.passId);
+ event.addProperty("root_elapsed_ms", millis(now - root.started));
+ event.addProperty("phase_elapsed_ms", step == null ? 0 : millis(now - step.phaseStarted));
+ event.addProperty("operation_elapsed_ms", step == null || step.operation.isEmpty()
+ ? 0 : millis(now - step.started));
+ event.addProperty("job", job == null ? "" : job.getSimpleName());
+ event.addProperty("held_locks", lockCount);
+ event.addProperty("oldest_lock", lockCount == 0 ? "" : bounded(oldest.oldestTable));
+ event.addProperty("oldest_lock_hold_ms", lockCount == 0 ? 0 : millis(now - oldest.started));
+ active.log("Slow planning", event);
+ }
+
+ private void finish(boolean success) {
+ JsonObject result = new JsonObject();
+ result.addProperty("pass_id", passId);
+ result.addProperty("status", success ? "completed" : "failed");
+ result.addProperty("elapsed_ms", millis(clock.getAsLong() - started));
+ result.addProperty("failed_step", success ? "" : failedStep);
+ JsonObject phases = new JsonObject();
+ for (Phase phase : Phase.values()) {
+ Timing timing = timings.get(phase);
+ JsonObject value = new JsonObject();
+ value.addProperty("status", timing == null ? "not_run" : timing.failures > 0 ? "failed" : "completed");
+ value.addProperty("elapsed_ms", timing == null ? 0 : millis(timing.nanos));
+ value.addProperty("calls", timing == null ? 0 : timing.calls);
+ phases.add(phase.key(), value);
+ }
+ result.add("phases", phases);
+ result.addProperty("omitted_operations", omittedOperations);
+ if (summary != null) {
+ summary.addPlanningPass(result);
+ }
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ boolean report = !success || !slowOperations.isEmpty()
+ || (threshold > 0 && result.get("elapsed_ms").getAsLong() >= threshold);
+ // An enclosing MV planning pass may still hold locks. Defer its children's logs as well.
+ if (parent != null) {
+ for (Event event : slowOperations) {
+ parent.defer(event);
+ }
+ parent.omittedOperations += omittedOperations;
+ if (report) {
+ parent.defer(new Event(this, "Planning finished", result));
+ }
+ } else {
+ for (Event event : slowOperations) {
+ event.owner.log(event.message, event.json);
+ }
+ if (report) {
+ log("Planning finished", result);
+ }
+ }
+ }
+
+ private void defer(Event event) {
+ if (slowOperations.size() == MAX_SLOW_OPERATIONS) {
+ omittedOperations++;
+ } else {
+ slowOperations.add(event);
+ }
+ }
+
+ private void log(String message, JsonObject event) {
+ String formattedId = queryId == null || (queryId.hi == 0 && queryId.lo == 0)
+ ? "" : DebugUtil.printId(queryId);
+ event.addProperty("query_id", formattedId);
+ event.addProperty("pass_id", passId);
+ event.addProperty("statement_id", statementId);
+ event.addProperty("planner_thread", threadName);
+ event.addProperty("query_timeout_ms", timeoutMs);
+ // Bind only this event; the checker or a deferred event may run under another query's context.
+ try (CloseableThreadContext.Instance ignored = CloseableThreadContext.put("query_id", formattedId)) {
Review Comment:
[P2] Coordinate the MDC binding and nested-identity logic with #68694
Problems with the binding here:
- The key `"query_id"` is hardcoded.
- An empty string is written when there is no id; #68694's `QueryLogContext` removes the key instead.
- The `sys_log_enable_query_id` switch introduced by #68694 is not honored.
On master no log pattern contains `%X{query_id}`, so if this PR lands alone the binding has no effect. With both PRs merged, the id is printed twice: in the log prefix and in the JSON `query_id` field.
Both PRs also implement "nested planning inherits the outer query id" independently (`inheritsQueryIdentity` here, `QueryLogContext.PLANNING_QUERY_ID` there). A `git merge-tree` trial merge shows textual conflicts in `NereidsPlanner.java` (both split `planWithLock` into `planWithLockInternal`) and in `ConnectContext.checkTimeout`.
Suggest agreeing on a merge order; whichever PR lands second should reuse `QueryLogContext`'s key and inheritance logic.
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/PlanningDiagnostics.java:
##########
@@ -0,0 +1,437 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.common.Config;
+import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.thrift.TUniqueId;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.gson.JsonObject;
+import org.apache.logging.log4j.CloseableThreadContext;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+import java.util.ArrayList;
+import java.util.EnumMap;
+import java.util.List;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.function.LongSupplier;
+import java.util.function.Supplier;
+
+/**
+ * One planning pass. The planning thread owns timers and the bounded slow-operation buffer.
+ * The connection checker reads only immutable, volatile-published steps, never planner/table locks.
+ * Timings are inclusive: nested phases and operations must not be added to their enclosing phase.
+ */
+public final class PlanningDiagnostics {
+ private static final Logger LOG = LogManager.getLogger(PlanningDiagnostics.class);
+ private static final int MAX_SLOW_OPERATIONS = 16;
+ // Internal MV planning can replace ConnectContext while the calling planner still holds table locks.
+ private static final ThreadLocal<PlanningDiagnostics> ACTIVE = new ThreadLocal<>();
+
+ public enum Phase {
+ PREPROCESS, COLLECT_TABLES, PRELOAD_METADATA, WAIT_CHANGE_VISIBLE, LOCK_TABLES,
+ ANALYZE, REWRITE, PRE_REWRITE_MV, OPTIMIZE, CHOOSE_PLAN, POST_PROCESS,
+ TRANSLATE, DISTRIBUTE, RELEASE_RESOURCES;
+
+ public String key() {
+ return name().toLowerCase(Locale.ROOT);
+ }
+ }
+
+ private final ConnectContext context;
+ private final SummaryProfile summary;
+ private final long passId;
+ private final PlanningDiagnostics parent;
+ private final PlanningDiagnostics root;
+ private final boolean inheritsQueryIdentity;
+ private final TUniqueId queryId;
+ private final long statementId;
+ private final String threadName;
+ private volatile long timeoutMs;
+ private final LongSupplier clock;
+ private final long started;
+ private final EnumMap<Phase, Timing> timings = new EnumMap<>(Phase.class);
+ private final List<Event> slowOperations = new ArrayList<>();
+ private final AtomicLong lastReport;
+ private volatile Step current;
+ private volatile Class<?> currentJob;
+ private volatile HeldLocks heldLocks = new HeldLocks(0, 0, "");
+ private volatile boolean finished;
+ // Only the root publishes this pointer, so its registered connection can inspect an internal pass.
+ private volatile PlanningDiagnostics activePass;
+ private String failedStep = "";
+ private Throwable stepFailure;
+ private long omittedOperations;
+
+ private PlanningDiagnostics(ConnectContext context) {
+ this(context, System::nanoTime);
+ }
+
+ @VisibleForTesting
+ PlanningDiagnostics(ConnectContext context, LongSupplier clock) {
+ this.context = context;
+ this.parent = ACTIVE.get();
+ this.root = parent == null ? this : parent.root;
+ this.lastReport = parent == null ? new AtomicLong(Long.MIN_VALUE) : parent.lastReport;
+ SummaryProfile contextSummary = SummaryProfile.getSummaryProfile(context);
+ this.summary = contextSummary != null ? contextSummary : parent == null ? null : parent.summary;
+ this.passId = summary == null ? 0 : summary.nextPlanningPassId();
+ TUniqueId contextQueryId = context.queryId();
+ this.inheritsQueryIdentity = contextQueryId == null && parent != null;
+ this.queryId = inheritsQueryIdentity ? parent.queryId
+ : contextQueryId == null ? null : contextQueryId.deepCopy();
+ this.statementId = inheritsQueryIdentity ? parent.statementId : context.getStmtId();
+ this.threadName = Thread.currentThread().getName();
+ this.timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ this.clock = clock;
+ this.started = clock.getAsLong();
+ }
+
+ /** Includes cleanup and restores an outer pass even when internal planning uses another connection. */
+ public static <T> T plan(ConnectContext context, Supplier<T> action) {
+ return execute(new PlanningDiagnostics(context), action);
+ }
+
+ @VisibleForTesting
+ static <T> T execute(PlanningDiagnostics diagnostics, Supplier<T> action) {
+ ConnectContext context = diagnostics.context;
+ PlanningDiagnostics previous = context.getPlanningDiagnostics();
+ ACTIVE.set(diagnostics);
+ context.setPlanningDiagnostics(diagnostics);
+ diagnostics.root.activePass = diagnostics;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ if (diagnostics.stepFailure != failure) {
+ diagnostics.failedStep = "between_phases";
+ }
+ throw failure;
+ } finally {
+ diagnostics.finished = true;
+ context.setPlanningDiagnostics(previous);
+ diagnostics.root.activePass = diagnostics.parent;
+ if (diagnostics.parent == null) {
+ ACTIVE.remove();
+ } else {
+ ACTIVE.set(diagnostics.parent);
+ }
+ diagnostics.finish(success);
+ }
+ }
+
+ public static void runPhase(ConnectContext context, Phase phase, Runnable action) {
+ phase(context, phase, () -> {
+ action.run();
+ return null;
+ });
+ }
+
+ public static <T> T phase(ConnectContext context, Phase phase, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ return diagnostics == null ? action.get() : diagnostics.measure(phase, "", "", -1, action);
+ }
+
+ /** A negative operation budget means that timeout handling belongs to the connector. */
+ public static <T> T operation(ConnectContext context, String operation, String target,
+ long budgetMs, Supplier<T> action) {
+ return operation(context, operation, () -> target, budgetMs, action);
+ }
+
+ /** Resolve the target only for an active planning pass, on the calling thread. */
+ public static <T> T operation(ConnectContext context, String operation, Supplier<String> target,
+ long budgetMs, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ if (diagnostics == null) {
+ return action.get();
+ }
+ Step step = diagnostics.current;
+ return diagnostics.measure(step == null ? Phase.PREPROCESS : step.phase,
+ operation, target.get(), budgetMs, action);
+ }
+
+ public static PlanningDiagnostics current(ConnectContext context) {
+ return context == null ? null : context.getPlanningDiagnostics();
+ }
+
+ private <T> T measure(Phase phase, String operation, String target, long budgetMs, Supplier<T> action) {
+ Step previous = current;
+ Step step = new Step(phase, operation, target, budgetMs, clock.getAsLong(),
+ operation.isEmpty() || previous == null ? -1 : previous.phaseStarted);
+ current = step;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ // Preserve the innermost failing step of this exception, not an earlier recovered MV failure.
+ if (stepFailure != failure) {
+ stepFailure = failure;
+ failedStep = phase.key() + (operation.isEmpty() ? "" : "/" + operation);
+ }
+ throw failure;
+ } finally {
+ long elapsed = clock.getAsLong() - step.started;
+ if (operation.isEmpty()) {
+ Timing timing = timings.computeIfAbsent(phase, key -> new Timing());
+ timing.nanos += elapsed;
+ timing.calls++;
+ timing.failures += success ? 0 : 1;
+ if (phase == Phase.PREPROCESS && success) {
+ // SET_VAR hints are applied by preprocessing, after this pass was created.
+ timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ }
+ } else {
+ recordOperation(step, elapsed, success);
+ }
+ current = previous;
+ }
+ }
+
+ /** Avoid allocating task descriptions for every optimizer job; format the class only on a slow report. */
+ public Class<?> setCurrentJob(Class<?> job) {
+ Class<?> previous = currentJob;
+ currentJob = job;
+ return previous;
+ }
+
+ public LockHold acquiredLock(String table) {
+ long now = clock.getAsLong();
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count + 1, previous.count == 0 ? now : previous.started,
+ previous.count == 0 ? table : previous.oldestTable);
+ return new LockHold(table, now);
+ }
+
+ /** Closed after unlocking; planner resources release in reverse acquisition order. */
+ public final class LockHold implements AutoCloseable {
+ private final String table;
+ private final long acquired;
+
+ private LockHold(String table, long acquired) {
+ this.table = table;
+ this.acquired = acquired;
+ }
+
+ @Override
+ public void close() {
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count - 1, previous.started, previous.oldestTable);
+ recordOperation(new Step(Phase.RELEASE_RESOURCES, "read_lock_hold", table, -1, acquired, -1),
+ clock.getAsLong() - acquired, true);
+ }
+ }
+
+ private void recordOperation(Step step, long nanos, boolean success) {
+ long threshold = Config.nereids_planning_operation_log_threshold_ms;
+ if (success && (threshold <= 0 || millis(nanos) < threshold)) {
+ return;
+ }
+ if (slowOperations.size() == MAX_SLOW_OPERATIONS) {
+ omittedOperations++;
+ return;
+ }
+ JsonObject event = step.toJson();
+ event.addProperty("elapsed_ms", millis(nanos));
+ event.addProperty("status", success ? "completed" : "failed");
+ slowOperations.add(new Event(this, "Planning operation", event));
+ }
+
+ /** Invoked by the existing connection timeout checker, including while a planner job is blocked. */
+ public void reportIfSlow() {
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ PlanningDiagnostics active = root.activePass;
+ if (root.finished || active == null || threshold <= 0) {
+ return;
+ }
+ // Snapshot published starts before reading the clock. A newer step/lock sampled after the clock
+ // could otherwise appear to have started in the future when the checker was descheduled.
+ Step step = active.current;
+ Class<?> job = active.currentJob;
+ HeldLocks oldest = active.heldLocks;
+ int lockCount = oldest.count;
+ for (PlanningDiagnostics outer = active.parent; outer != null; outer = outer.parent) {
+ HeldLocks locks = outer.heldLocks;
+ lockCount += locks.count;
+ if (locks.count > 0 && (oldest.count == 0 || locks.started < oldest.started)) {
+ oldest = locks;
+ }
+ }
+ long now = root.clock.getAsLong();
+ if (millis(now - root.started) < threshold) {
+ return;
+ }
+ long previous = root.lastReport.get();
+ // A minimum interval protects the checker from an accidentally zero/negative dynamic setting.
+ long interval = Math.max(1000, Config.nereids_planning_log_interval_ms);
+ if ((previous != Long.MIN_VALUE && millis(now - previous) < interval)
+ || !root.lastReport.compareAndSet(previous, now)) {
+ return;
+ }
+ JsonObject event = step == null ? new JsonObject() : step.toJson();
+ event.addProperty("status", "running");
+ event.addProperty("elapsed_ms", millis(now - active.started));
+ event.addProperty("root_pass_id", root.passId);
+ event.addProperty("root_elapsed_ms", millis(now - root.started));
+ event.addProperty("phase_elapsed_ms", step == null ? 0 : millis(now - step.phaseStarted));
+ event.addProperty("operation_elapsed_ms", step == null || step.operation.isEmpty()
+ ? 0 : millis(now - step.started));
+ event.addProperty("job", job == null ? "" : job.getSimpleName());
+ event.addProperty("held_locks", lockCount);
+ event.addProperty("oldest_lock", lockCount == 0 ? "" : bounded(oldest.oldestTable));
+ event.addProperty("oldest_lock_hold_ms", lockCount == 0 ? 0 : millis(now - oldest.started));
+ active.log("Slow planning", event);
+ }
+
+ private void finish(boolean success) {
Review Comment:
[P2] Per-pass JSON construction is paid on every query
`finish()` builds about 16 `JsonObject`s for every pass, and `addPlanningPass()` then `deepCopy()`s the result. This happens on every query, even with Profile disabled and nothing to log. With `K + 1` passes per query when MV rewrite plans MV definitions, and with high-QPS `INSERT ... VALUES`, this is avoidable. Consider accumulating per-`Phase` counters in primitive arrays and serializing to JSON only when a report is emitted or the Profile is rendered.
##########
fe/fe-core/src/main/java/org/apache/doris/nereids/jobs/scheduler/SimpleJobScheduler.java:
##########
@@ -48,7 +49,15 @@ public void executeJobPool(ScheduleContext scheduleContext) {
}
}
Job job = pool.pop();
- job.execute();
+ PlanningDiagnostics diagnostics = PlanningDiagnostics.current(context.getConnectContext());
Review Comment:
[P3] Hoist the loop-invariant diagnostics lookup
`PlanningDiagnostics.current(...)` does not change inside this loop, which is the optimizer's hottest loop. It can be read once above the `while`.
##########
fe/fe-core/src/main/java/org/apache/doris/datasource/ExternalTable.java:
##########
@@ -182,17 +184,17 @@ public List<Column> getFullSchema() {
// NOT getFullSchema(Optional.empty()): an empty snapshot means "this reference has no pin" (=>
// latest), whereas the no-arg form means "I have no reference, resolve from the ambient context".
// Collapsing the two would strip the ambient resolution from every statement-global caller.
- Optional<SchemaCacheValue> schemaCacheValue = getSchemaCacheValue();
- return schemaCacheValue.map(SchemaCacheValue::getSchema).orElse(null);
+ return PlanningDiagnostics.operation(ConnectContext.get(), "load_schema", this::getNameWithFullQualifiers, -1,
Review Comment:
[P2] The qualified target name is built on every schema access, not once
`getFullSchema()` (and the overload at :196, plus `initSelectedPartitions` at :493) is called many times per query, both directly and through `getColumn(name)` / `getBaseSchema()`. Inside an active pass, every call builds `getNameWithFullQualifiers()`, allocates a `Step`, and reads `nanoTime` twice. The description says targets are resolved once; in practice they are resolved once per call. Consider caching the qualified name or instrumenting at a coarser level, e.g. only the schema-cache load path.
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java:
##########
@@ -1593,24 +1611,81 @@ public void setAssignedWeightPerBackend(Map<Backend, Long> assignedWeightPerBack
this.assignedWeightPerBackend = assignedWeightPerBackend;
}
+ public synchronized long nextPlanningPassId() {
+ return ++planningPassSequence;
+ }
+
+ /** Bounded across retries, CTAS passes and nested MV planning; existing timing fields keep their meaning. */
+ public synchronized void addPlanningPass(JsonObject pass) {
+ planningPassCount++;
+ planningFailedPassCount += "failed".equals(pass.get("status").getAsString()) ? 1 : 0;
+ planningElapsedMs += pass.get("elapsed_ms").getAsLong();
+ lastPlanningPass = pass.deepCopy();
+ for (Phase phase : Phase.values()) {
+ String key = phase.key();
+ long total = planningPhaseTotals.has(key) ? planningPhaseTotals.get(key).getAsLong() : 0;
+ JsonObject phaseResult = pass.getAsJsonObject("phases").getAsJsonObject(key);
+ if (!"not_run".equals(phaseResult.get("status").getAsString())) {
+ planningPhaseTotals.addProperty(key, total + phaseResult.get("elapsed_ms").getAsLong());
+ }
+ if ("failed".equals(phaseResult.get("status").getAsString())) {
+ long failures = planningPhaseFailures.has(key) ? planningPhaseFailures.get(key).getAsLong() : 0;
+ planningPhaseFailures.addProperty(key, failures + 1);
+ }
+ }
+ }
+
+ public synchronized JsonObject getPlanningDetails() {
+ JsonObject result = new JsonObject();
+ result.addProperty("passes", planningPassCount);
+ result.addProperty("failed_passes", planningFailedPassCount);
+ result.addProperty("elapsed_ms", planningElapsedMs);
+ result.add("phase_time_ms", planningPhaseTotals.deepCopy());
+ result.add("last_pass", lastPlanningPass.deepCopy());
+ return result;
+ }
+
+ /** plan_times_ms is MAP<STRING, INT>. Never add strings or nested objects to this audit field. */
+ private synchronized void addPlanningAuditTimes(JsonObject result) {
Review Comment:
[P3] The plan-timeout error now carries a block of `-1` entries
`SimpleJobScheduler` throws `QueryPlanningErrors.planTimeoutError()` while the current pass is still running, and that calls `getPlanTime()`. Because no pass has finished yet, the user-visible "Nereids cost too much time" message gains `planning_passes:0`, `planning_last_failed:-1` and about a dozen `planning_*:-1` entries, which is noise there. Consider omitting the planning keys when `planningPassCount == 0`.
##########
fe/fe-core/src/main/java/org/apache/doris/qe/ConnectContext.java:
##########
@@ -1326,7 +1327,22 @@ public void cancelQuery(Status cancelReason) {
}
}
+ // Published independently of StatementContext's monitor, which is held during table-lock acquisition.
+ private volatile PlanningDiagnostics planningDiagnostics;
+
+ public PlanningDiagnostics getPlanningDiagnostics() {
+ return planningDiagnostics;
+ }
+
+ public void setPlanningDiagnostics(PlanningDiagnostics diagnostics) {
+ planningDiagnostics = diagnostics;
+ }
+
public void checkTimeout(long now) {
+ PlanningDiagnostics diagnostics = planningDiagnostics;
+ if (diagnostics != null) {
+ diagnostics.reportIfSlow();
Review Comment:
[P3] `reportIfSlow()` runs before the timeout/kill decision
I don't see a throwing path today. If one appears later, `ConnectPoolMgr` catches the exception per connection, and that connection's timeout kill is skipped for the round. Moving the call after the kill logic removes the coupling.
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/PlanningDiagnostics.java:
##########
@@ -0,0 +1,437 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.common.Config;
+import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.thrift.TUniqueId;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.gson.JsonObject;
+import org.apache.logging.log4j.CloseableThreadContext;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+import java.util.ArrayList;
+import java.util.EnumMap;
+import java.util.List;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.function.LongSupplier;
+import java.util.function.Supplier;
+
+/**
+ * One planning pass. The planning thread owns timers and the bounded slow-operation buffer.
+ * The connection checker reads only immutable, volatile-published steps, never planner/table locks.
+ * Timings are inclusive: nested phases and operations must not be added to their enclosing phase.
+ */
+public final class PlanningDiagnostics {
+ private static final Logger LOG = LogManager.getLogger(PlanningDiagnostics.class);
+ private static final int MAX_SLOW_OPERATIONS = 16;
+ // Internal MV planning can replace ConnectContext while the calling planner still holds table locks.
+ private static final ThreadLocal<PlanningDiagnostics> ACTIVE = new ThreadLocal<>();
+
+ public enum Phase {
+ PREPROCESS, COLLECT_TABLES, PRELOAD_METADATA, WAIT_CHANGE_VISIBLE, LOCK_TABLES,
+ ANALYZE, REWRITE, PRE_REWRITE_MV, OPTIMIZE, CHOOSE_PLAN, POST_PROCESS,
+ TRANSLATE, DISTRIBUTE, RELEASE_RESOURCES;
+
+ public String key() {
+ return name().toLowerCase(Locale.ROOT);
+ }
+ }
+
+ private final ConnectContext context;
+ private final SummaryProfile summary;
+ private final long passId;
+ private final PlanningDiagnostics parent;
+ private final PlanningDiagnostics root;
+ private final boolean inheritsQueryIdentity;
+ private final TUniqueId queryId;
+ private final long statementId;
+ private final String threadName;
+ private volatile long timeoutMs;
+ private final LongSupplier clock;
+ private final long started;
+ private final EnumMap<Phase, Timing> timings = new EnumMap<>(Phase.class);
+ private final List<Event> slowOperations = new ArrayList<>();
+ private final AtomicLong lastReport;
+ private volatile Step current;
+ private volatile Class<?> currentJob;
+ private volatile HeldLocks heldLocks = new HeldLocks(0, 0, "");
+ private volatile boolean finished;
+ // Only the root publishes this pointer, so its registered connection can inspect an internal pass.
+ private volatile PlanningDiagnostics activePass;
+ private String failedStep = "";
+ private Throwable stepFailure;
+ private long omittedOperations;
+
+ private PlanningDiagnostics(ConnectContext context) {
+ this(context, System::nanoTime);
+ }
+
+ @VisibleForTesting
+ PlanningDiagnostics(ConnectContext context, LongSupplier clock) {
+ this.context = context;
+ this.parent = ACTIVE.get();
+ this.root = parent == null ? this : parent.root;
+ this.lastReport = parent == null ? new AtomicLong(Long.MIN_VALUE) : parent.lastReport;
+ SummaryProfile contextSummary = SummaryProfile.getSummaryProfile(context);
+ this.summary = contextSummary != null ? contextSummary : parent == null ? null : parent.summary;
+ this.passId = summary == null ? 0 : summary.nextPlanningPassId();
+ TUniqueId contextQueryId = context.queryId();
+ this.inheritsQueryIdentity = contextQueryId == null && parent != null;
+ this.queryId = inheritsQueryIdentity ? parent.queryId
+ : contextQueryId == null ? null : contextQueryId.deepCopy();
+ this.statementId = inheritsQueryIdentity ? parent.statementId : context.getStmtId();
+ this.threadName = Thread.currentThread().getName();
+ this.timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ this.clock = clock;
+ this.started = clock.getAsLong();
+ }
+
+ /** Includes cleanup and restores an outer pass even when internal planning uses another connection. */
+ public static <T> T plan(ConnectContext context, Supplier<T> action) {
+ return execute(new PlanningDiagnostics(context), action);
+ }
+
+ @VisibleForTesting
+ static <T> T execute(PlanningDiagnostics diagnostics, Supplier<T> action) {
+ ConnectContext context = diagnostics.context;
+ PlanningDiagnostics previous = context.getPlanningDiagnostics();
+ ACTIVE.set(diagnostics);
+ context.setPlanningDiagnostics(diagnostics);
+ diagnostics.root.activePass = diagnostics;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ if (diagnostics.stepFailure != failure) {
+ diagnostics.failedStep = "between_phases";
+ }
+ throw failure;
+ } finally {
+ diagnostics.finished = true;
+ context.setPlanningDiagnostics(previous);
+ diagnostics.root.activePass = diagnostics.parent;
+ if (diagnostics.parent == null) {
+ ACTIVE.remove();
+ } else {
+ ACTIVE.set(diagnostics.parent);
+ }
+ diagnostics.finish(success);
+ }
+ }
+
+ public static void runPhase(ConnectContext context, Phase phase, Runnable action) {
+ phase(context, phase, () -> {
+ action.run();
+ return null;
+ });
+ }
+
+ public static <T> T phase(ConnectContext context, Phase phase, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ return diagnostics == null ? action.get() : diagnostics.measure(phase, "", "", -1, action);
+ }
+
+ /** A negative operation budget means that timeout handling belongs to the connector. */
+ public static <T> T operation(ConnectContext context, String operation, String target,
+ long budgetMs, Supplier<T> action) {
+ return operation(context, operation, () -> target, budgetMs, action);
+ }
+
+ /** Resolve the target only for an active planning pass, on the calling thread. */
+ public static <T> T operation(ConnectContext context, String operation, Supplier<String> target,
+ long budgetMs, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ if (diagnostics == null) {
+ return action.get();
+ }
+ Step step = diagnostics.current;
+ return diagnostics.measure(step == null ? Phase.PREPROCESS : step.phase,
+ operation, target.get(), budgetMs, action);
+ }
+
+ public static PlanningDiagnostics current(ConnectContext context) {
+ return context == null ? null : context.getPlanningDiagnostics();
+ }
+
+ private <T> T measure(Phase phase, String operation, String target, long budgetMs, Supplier<T> action) {
+ Step previous = current;
+ Step step = new Step(phase, operation, target, budgetMs, clock.getAsLong(),
+ operation.isEmpty() || previous == null ? -1 : previous.phaseStarted);
+ current = step;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ // Preserve the innermost failing step of this exception, not an earlier recovered MV failure.
+ if (stepFailure != failure) {
+ stepFailure = failure;
+ failedStep = phase.key() + (operation.isEmpty() ? "" : "/" + operation);
+ }
+ throw failure;
+ } finally {
+ long elapsed = clock.getAsLong() - step.started;
+ if (operation.isEmpty()) {
+ Timing timing = timings.computeIfAbsent(phase, key -> new Timing());
+ timing.nanos += elapsed;
+ timing.calls++;
+ timing.failures += success ? 0 : 1;
+ if (phase == Phase.PREPROCESS && success) {
+ // SET_VAR hints are applied by preprocessing, after this pass was created.
+ timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ }
+ } else {
+ recordOperation(step, elapsed, success);
+ }
+ current = previous;
+ }
+ }
+
+ /** Avoid allocating task descriptions for every optimizer job; format the class only on a slow report. */
+ public Class<?> setCurrentJob(Class<?> job) {
+ Class<?> previous = currentJob;
+ currentJob = job;
+ return previous;
+ }
+
+ public LockHold acquiredLock(String table) {
+ long now = clock.getAsLong();
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count + 1, previous.count == 0 ? now : previous.started,
+ previous.count == 0 ? table : previous.oldestTable);
+ return new LockHold(table, now);
+ }
+
+ /** Closed after unlocking; planner resources release in reverse acquisition order. */
+ public final class LockHold implements AutoCloseable {
+ private final String table;
+ private final long acquired;
+
+ private LockHold(String table, long acquired) {
+ this.table = table;
+ this.acquired = acquired;
+ }
+
+ @Override
+ public void close() {
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count - 1, previous.started, previous.oldestTable);
+ recordOperation(new Step(Phase.RELEASE_RESOURCES, "read_lock_hold", table, -1, acquired, -1),
+ clock.getAsLong() - acquired, true);
+ }
+ }
+
+ private void recordOperation(Step step, long nanos, boolean success) {
+ long threshold = Config.nereids_planning_operation_log_threshold_ms;
+ if (success && (threshold <= 0 || millis(nanos) < threshold)) {
+ return;
+ }
+ if (slowOperations.size() == MAX_SLOW_OPERATIONS) {
+ omittedOperations++;
+ return;
+ }
+ JsonObject event = step.toJson();
+ event.addProperty("elapsed_ms", millis(nanos));
+ event.addProperty("status", success ? "completed" : "failed");
+ slowOperations.add(new Event(this, "Planning operation", event));
+ }
+
+ /** Invoked by the existing connection timeout checker, including while a planner job is blocked. */
+ public void reportIfSlow() {
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ PlanningDiagnostics active = root.activePass;
+ if (root.finished || active == null || threshold <= 0) {
+ return;
+ }
+ // Snapshot published starts before reading the clock. A newer step/lock sampled after the clock
+ // could otherwise appear to have started in the future when the checker was descheduled.
+ Step step = active.current;
+ Class<?> job = active.currentJob;
+ HeldLocks oldest = active.heldLocks;
+ int lockCount = oldest.count;
+ for (PlanningDiagnostics outer = active.parent; outer != null; outer = outer.parent) {
+ HeldLocks locks = outer.heldLocks;
+ lockCount += locks.count;
+ if (locks.count > 0 && (oldest.count == 0 || locks.started < oldest.started)) {
+ oldest = locks;
+ }
+ }
+ long now = root.clock.getAsLong();
+ if (millis(now - root.started) < threshold) {
+ return;
+ }
+ long previous = root.lastReport.get();
+ // A minimum interval protects the checker from an accidentally zero/negative dynamic setting.
+ long interval = Math.max(1000, Config.nereids_planning_log_interval_ms);
+ if ((previous != Long.MIN_VALUE && millis(now - previous) < interval)
+ || !root.lastReport.compareAndSet(previous, now)) {
+ return;
+ }
+ JsonObject event = step == null ? new JsonObject() : step.toJson();
+ event.addProperty("status", "running");
+ event.addProperty("elapsed_ms", millis(now - active.started));
+ event.addProperty("root_pass_id", root.passId);
+ event.addProperty("root_elapsed_ms", millis(now - root.started));
+ event.addProperty("phase_elapsed_ms", step == null ? 0 : millis(now - step.phaseStarted));
+ event.addProperty("operation_elapsed_ms", step == null || step.operation.isEmpty()
+ ? 0 : millis(now - step.started));
+ event.addProperty("job", job == null ? "" : job.getSimpleName());
+ event.addProperty("held_locks", lockCount);
+ event.addProperty("oldest_lock", lockCount == 0 ? "" : bounded(oldest.oldestTable));
+ event.addProperty("oldest_lock_hold_ms", lockCount == 0 ? 0 : millis(now - oldest.started));
+ active.log("Slow planning", event);
+ }
+
+ private void finish(boolean success) {
+ JsonObject result = new JsonObject();
+ result.addProperty("pass_id", passId);
+ result.addProperty("status", success ? "completed" : "failed");
+ result.addProperty("elapsed_ms", millis(clock.getAsLong() - started));
+ result.addProperty("failed_step", success ? "" : failedStep);
+ JsonObject phases = new JsonObject();
+ for (Phase phase : Phase.values()) {
+ Timing timing = timings.get(phase);
+ JsonObject value = new JsonObject();
+ value.addProperty("status", timing == null ? "not_run" : timing.failures > 0 ? "failed" : "completed");
+ value.addProperty("elapsed_ms", timing == null ? 0 : millis(timing.nanos));
+ value.addProperty("calls", timing == null ? 0 : timing.calls);
+ phases.add(phase.key(), value);
+ }
+ result.add("phases", phases);
+ result.addProperty("omitted_operations", omittedOperations);
+ if (summary != null) {
+ summary.addPlanningPass(result);
+ }
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ boolean report = !success || !slowOperations.isEmpty()
+ || (threshold > 0 && result.get("elapsed_ms").getAsLong() >= threshold);
+ // An enclosing MV planning pass may still hold locks. Defer its children's logs as well.
+ if (parent != null) {
+ for (Event event : slowOperations) {
+ parent.defer(event);
+ }
+ parent.omittedOperations += omittedOperations;
+ if (report) {
+ parent.defer(new Event(this, "Planning finished", result));
+ }
+ } else {
+ for (Event event : slowOperations) {
+ event.owner.log(event.message, event.json);
+ }
+ if (report) {
+ log("Planning finished", result);
Review Comment:
[P3] The failed-pass summary WARN cannot be disabled and duplicates an existing WARN
A failed pass always emits "Planning finished" with a full JSON summary, independent of the thresholds. `StmtExecutor` already logs "Nereids plan query failed" for the same failure, so frequent user errors such as "Unknown column" add another sizeable WARN line each time. Consider gating it behind the threshold, or logging only the failed step.
##########
fe/fe-common/src/main/java/org/apache/doris/common/Config.java:
##########
@@ -104,6 +104,21 @@ public class Config extends ConfigBase {
@ConfField(mutable = true, description = "The threshold of slow query, in milliseconds. If the response time of a "
+ "query exceeds this threshold, it will be recorded in audit log.")
public static long qe_slow_log_ms = 5000;
+
+ @ConfField(mutable = true, description = "Log slow Nereids planning passes after this many milliseconds. "
+ + "Non-positive values disable slow-pass logs; failed passes are still reported.")
+ public static volatile long nereids_planning_log_threshold_ms = 5000;
Review Comment:
[P3] `volatile` is unusual for `Config` fields
Other mutable configs in this file are plain `public static` fields. Please keep the new ones consistent, and add a docs PR for the three settings.
##########
fe/fe-core/src/test/java/org/apache/doris/common/profile/PlanningDiagnosticsTest.java:
##########
@@ -0,0 +1,988 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.catalog.Column;
+import org.apache.doris.catalog.TableIf;
+import org.apache.doris.common.Config;
+import org.apache.doris.common.FeConstants;
+import org.apache.doris.common.jmockit.Deencapsulation;
+import org.apache.doris.common.profile.PlanningDiagnostics.Phase;
+import org.apache.doris.datasource.ExternalCatalog;
+import org.apache.doris.datasource.ExternalDatabase;
+import org.apache.doris.datasource.ExternalTable;
+import org.apache.doris.datasource.SchemaCacheValue;
+import org.apache.doris.datasource.mvcc.MvccSnapshot;
+import org.apache.doris.datasource.mvcc.PluginDrivenMvccExternalTable;
+import org.apache.doris.mysql.authenticate.TestLogAppender;
+import org.apache.doris.nereids.NereidsPlanner;
+import org.apache.doris.nereids.StatementContext;
+import org.apache.doris.nereids.trees.plans.commands.ExplainCommand.ExplainLevel;
+import org.apache.doris.nereids.trees.plans.logical.LogicalFileScan.SelectedPartitions;
+import org.apache.doris.nereids.trees.plans.logical.LogicalPlan;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.qe.OriginStatement;
+import org.apache.doris.qe.StmtExecutor;
+
+import com.google.common.collect.ImmutableList;
+import com.google.gson.JsonObject;
+import com.google.gson.JsonParser;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.ThreadContext;
+import org.apache.logging.log4j.core.LogEvent;
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.Assertions;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.mockito.Mockito;
+
+import java.util.Collections;
+import java.util.List;
+import java.util.Optional;
+import java.util.concurrent.CompletableFuture;
+import java.util.concurrent.CountDownLatch;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.Executors;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.concurrent.atomic.AtomicReference;
+import java.util.function.Supplier;
+
+public class PlanningDiagnosticsTest {
+ private static final String QUERY_ID_KEY = "query_id";
+ private final AtomicLong clock = new AtomicLong(TimeUnit.SECONDS.toNanos(1));
+ private ConnectContext context;
+ private ConnectContext previousContext;
+ private SummaryProfile summary;
+ private long savedThreshold;
+ private long savedOperationThreshold;
+ private long savedInterval;
+ private boolean savedUnitTest;
+ private String savedQueryId;
+
+ @BeforeEach
+ public void setUp() {
+ savedThreshold = Config.nereids_planning_log_threshold_ms;
+ savedOperationThreshold = Config.nereids_planning_operation_log_threshold_ms;
+ savedInterval = Config.nereids_planning_log_interval_ms;
+ savedUnitTest = FeConstants.runningUnitTest;
+ previousContext = ConnectContext.get();
+ savedQueryId = ThreadContext.get(QUERY_ID_KEY);
+ Config.nereids_planning_log_threshold_ms = 5000;
+ Config.nereids_planning_operation_log_threshold_ms = 1000;
+ Config.nereids_planning_log_interval_ms = 30000;
+ FeConstants.runningUnitTest = true;
+ context = new ConnectContext();
+ context.setQueryId(new org.apache.doris.thrift.TUniqueId(1, 2));
+ context.setStmtId(7);
+ context.setThreadLocalInfo();
+ summary = new SummaryProfile();
+ StmtExecutor executor = Mockito.mock(StmtExecutor.class);
+ Mockito.when(executor.getSummaryProfile()).thenReturn(summary);
+ context.setExecutor(executor);
+ }
+
+ @AfterEach
+ public void tearDown() {
+ ConnectContext.remove();
+ if (previousContext != null) {
+ previousContext.setThreadLocalInfo();
+ }
+ if (savedQueryId == null) {
+ ThreadContext.remove(QUERY_ID_KEY);
+ } else {
+ ThreadContext.put(QUERY_ID_KEY, savedQueryId);
+ }
+ Config.nereids_planning_log_threshold_ms = savedThreshold;
+ Config.nereids_planning_operation_log_threshold_ms = savedOperationThreshold;
+ Config.nereids_planning_log_interval_ms = savedInterval;
+ FeConstants.runningUnitTest = savedUnitTest;
+ }
+
+ @Test
+ public void testFastPassIsQuietAndAuditContainsTimingsWithoutProfile() {
+ context.getSessionVariable().enableProfile = false;
+ summary.addNereidsPreloadExternalMetadataTime(12);
+ summary.setNereidsCollectTablePartitionFinishTime(100);
+ summary.setNereidsPreRewriteByMvFinishTime(108);
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> {
+ PlanningDiagnostics.runPhase(context, Phase.CHOOSE_PLAN, () -> advance(7));
+ PlanningDiagnostics.runPhase(context, Phase.POST_PROCESS, () -> advance(11));
+ });
+ Assertions.assertTrue(events(appender).isEmpty());
+ }
+ JsonObject audit = JsonParser.parseString(summary.getPlanTime()).getAsJsonObject();
+ Assertions.assertEquals(12, audit.get("preload_external_metadata").getAsLong());
+ Assertions.assertEquals(8, audit.get("pre_rewrite_mv").getAsLong());
+ Assertions.assertEquals(7, audit.get("planning_choose_plan").getAsLong());
+ Assertions.assertEquals(-1, audit.get("planning_analyze").getAsLong());
+ audit.entrySet().forEach(entry -> {
+ Assertions.assertTrue(entry.getValue().isJsonPrimitive());
+ Assertions.assertTrue(entry.getValue().getAsJsonPrimitive().isNumber());
+ Assertions.assertEquals(entry.getValue().getAsLong(), entry.getValue().getAsInt());
+ });
+ Assertions.assertEquals(11, phase("post_process").get("elapsed_ms").getAsLong());
+ Assertions.assertEquals("not_run", phase("analyze").get("status").getAsString());
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ }
+
+ @Test
+ public void testRunningReportRateLimitIdentityAndContextRestoration() {
+ PlanningDiagnostics diagnostics = new PlanningDiagnostics(context, clock::get);
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ PlanningDiagnostics.execute(diagnostics, () -> {
+ PlanningDiagnostics.runPhase(context, Phase.OPTIMIZE, () -> {
+ diagnostics.setCurrentJob(PlanningDiagnosticsTest.class);
+ advance(5000);
+ context.queryId().setLo(99);
+ ThreadContext.put(QUERY_ID_KEY, "checker");
+ context.checkTimeout(0);
+ Assertions.assertEquals("checker", ThreadContext.get(QUERY_ID_KEY));
+ context.checkTimeout(0);
+ Assertions.assertEquals(1, events(appender).size());
+ advance(30000);
+ context.checkTimeout(0);
+ Assertions.assertEquals(2, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(0), "1-2");
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"job\":\"PlanningDiagnosticsTest\""));
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"phase\":\"optimize\""));
+ });
+ return null;
+ });
+ int count = events(appender).size();
+ diagnostics.reportIfSlow();
+ Assertions.assertEquals(count, events(appender).size());
+ }
+ }
+
+ @Test
+ public void testMissingAndZeroQueryIdsClearEventIdentityAndRestoreCaller() {
+ for (org.apache.doris.thrift.TUniqueId queryId : new org.apache.doris.thrift.TUniqueId[] {
+ null, new org.apache.doris.thrift.TUniqueId(0, 0)}) {
+ context.setQueryId(queryId);
+ ThreadContext.put(QUERY_ID_KEY, "caller");
+ IllegalStateException failure = new IllegalStateException("planning failure without query identity");
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ Assertions.assertSame(failure, Assertions.assertThrows(IllegalStateException.class, () -> run(() -> {
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ throw failure;
+ })));
+ Assertions.assertEquals(1, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(0), "");
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ }
+ }
+ }
+
+ @Test
+ public void testNestedPassWithOwnIdKeepsSnapshotForCheckerAndDeferredEvents() {
+ ConnectContext child = new ConnectContext();
+ child.setQueryId(new org.apache.doris.thrift.TUniqueId(3, 4));
+ ThreadContext.put(QUERY_ID_KEY, "caller");
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ PlanningDiagnostics parent = context.getPlanningDiagnostics();
+ PlanningDiagnostics.execute(new PlanningDiagnostics(child, clock::get), () -> {
+ PlanningDiagnostics.runPhase(child, Phase.OPTIMIZE, () -> {
+ child.queryId().setLo(99);
+ advance(5000);
+ context.checkTimeout(0);
+ Assertions.assertEquals(1, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(0), "3-4");
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ });
+ return null;
+ });
+ Assertions.assertSame(parent, context.getPlanningDiagnostics());
+ Assertions.assertNull(child.getPlanningDiagnostics());
+ Assertions.assertEquals(1, events(appender).size(), "The child completion remains deferred");
+ advance(30000);
+ context.checkTimeout(0);
+ Assertions.assertEquals(2, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(1), "1-2");
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ }));
+ Assertions.assertEquals(4, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(2), "3-4");
+ assertDiagnosticIdentity(events(appender).get(3), "1-2");
+ Assertions.assertEquals(2, summary.getPlanningDetails().get("passes").getAsInt());
+ Assertions.assertEquals("caller", ThreadContext.get(QUERY_ID_KEY));
+ }
+ }
+
+ @Test
+ public void testDynamicDisableAndMinimumInterval() {
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.ANALYZE, () -> {
+ advance(5000);
+ Config.nereids_planning_log_threshold_ms = 0;
+ context.checkTimeout(0);
+ Assertions.assertTrue(events(appender).isEmpty());
+ Config.nereids_planning_log_threshold_ms = 1;
+ Config.nereids_planning_log_interval_ms = 0;
+ context.checkTimeout(0);
+ advance(999);
+ context.checkTimeout(0);
+ Assertions.assertEquals(1, events(appender).size());
+ advance(1);
+ context.checkTimeout(0);
+ Assertions.assertEquals(2, events(appender).size());
+ }));
+ }
+ }
+
+ @Test
+ public void testFailurePreservesElapsedAndSkipsLaterStages() {
+ IllegalStateException expected = new IllegalStateException("original failure");
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ Assertions.assertSame(expected, Assertions.assertThrows(IllegalStateException.class,
+ () -> run(() -> PlanningDiagnostics.runPhase(context, Phase.ANALYZE, () -> {
+ advance(3);
+ throw expected;
+ }))));
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"failed_step\":\"analyze\""));
+ }
+ Assertions.assertEquals(3, phase("analyze").get("elapsed_ms").getAsLong());
+ Assertions.assertEquals("failed", phase("analyze").get("status").getAsString());
+ Assertions.assertEquals("not_run", phase("optimize").get("status").getAsString());
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ }
+
+ @Test
+ public void testNestedAndRepeatedPlanningRestoreParentAndAccumulate() {
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ PlanningDiagnostics parent = context.getPlanningDiagnostics();
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.CHOOSE_PLAN, () -> advance(5)));
+ Assertions.assertSame(parent, context.getPlanningDiagnostics());
+ advance(2);
+ }));
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.CHOOSE_PLAN, () -> advance(8)));
+ Assertions.assertEquals(3, summary.getPlanningDetails().get("passes").getAsInt());
+ Assertions.assertEquals(13, summary.getPlanningDetails().getAsJsonObject("phase_time_ms")
+ .get("choose_plan").getAsLong());
+ Assertions.assertEquals("not_run", phase("rewrite").get("status").getAsString());
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ }
+
+ @Test
+ public void testNestedSlowOperationsAreDeferredUntilOuterPassEnds() {
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> {
+ PlanningDiagnostics.LockHold hold = context.getPlanningDiagnostics().acquiredLock("catalog.db.outer");
+ run(() -> PlanningDiagnostics.operation(context, "load_schema", "catalog.db.inner", -1, () -> {
+ advance(1000);
+ return null;
+ }));
+ Assertions.assertTrue(events(appender).isEmpty());
+ hold.close();
+ });
+ Assertions.assertTrue(appender.contains(Level.WARN, "catalog.db.inner"));
+ Assertions.assertTrue(appender.contains(Level.WARN, "catalog.db.outer"));
+ }
+ }
+
+ @Test
+ public void testInternalConnectionPlanningDefersLogsAndKeepsQueryIdentity() {
+ StatementContext outerStatement = new StatementContext(context, new OriginStatement("select 1", 0));
+ TableIf table = table(1, "catalog.db.outer");
+ outerStatement.getTables().put(ImmutableList.of("outer"), table);
+ Mockito.when(table.tryReadLock(1, TimeUnit.MINUTES)).thenReturn(true);
+ // MV cache construction installs a separate connection without an executor or query ID.
+ ConnectContext internal = new ConnectContext();
+ StatementContext internalStatement = new StatementContext(internal, new OriginStatement("select 1", 0));
+ NereidsPlanner planner = new NereidsPlanner(internalStatement) {
+ @Override
+ protected LogicalPlan preprocess(LogicalPlan plan) {
+ throw new IllegalArgumentException("internal planning failure");
+ }
+ };
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ PlanningDiagnostics.plan(context, () -> {
+ outerStatement.lock();
+ try {
+ internal.setThreadLocalInfo();
+ Assertions.assertThrows(IllegalArgumentException.class, () -> planner.planWithLock(
+ Mockito.mock(LogicalPlan.class), org.apache.doris.nereids.properties.PhysicalProperties.ANY,
+ ExplainLevel.NONE, false));
+ Assertions.assertTrue(events(appender).isEmpty(), "Outer table locks are still held");
+ Assertions.assertNull(internal.getPlanningDiagnostics());
+ } finally {
+ context.setThreadLocalInfo();
+ outerStatement.releasePlannerResources();
+ }
+ return null;
+ });
+ Mockito.verify(table).readUnlock();
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"failed_step\":\"preprocess\""));
+ Assertions.assertEquals(2, summary.getPlanningDetails().get("passes").getAsInt());
+ Assertions.assertEquals(1, summary.getPlanningDetails().get("failed_passes").getAsInt());
+ events(appender).forEach(event -> assertDiagnosticIdentity(event, "1-2"));
+ }
+ Assertions.assertNull(context.getPlanningDiagnostics());
+ // Reusing the same planner thread must not retain the preceding root or its summary/ID.
+ internal.setThreadLocalInfo();
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ Assertions.assertThrows(IllegalArgumentException.class, () -> PlanningDiagnostics.plan(internal, () -> {
+ throw new IllegalArgumentException("independent planning failure");
+ }));
+ Assertions.assertEquals(1, events(appender).size());
+ assertDiagnosticIdentity(events(appender).get(0), "");
+ }
+ Assertions.assertEquals(2, summary.getPlanningDetails().get("passes").getAsInt());
+ }
+
+ @Test
+ public void testRunningReportFollowsInternalPassAndSharesRootRateLimit() {
+ ConnectContext internal = new ConnectContext();
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ PlanningDiagnostics.LockHold hold = context.getPlanningDiagnostics().acquiredLock("catalog.db.outer");
+ try {
+ advance(5000);
+ for (int i = 0; i < 2; i++) {
+ PlanningDiagnostics.execute(new PlanningDiagnostics(internal, clock::get), () ->
+ PlanningDiagnostics.operation(internal, "load_schema", "catalog.db.inner", -1, () -> {
+ advance(1);
+ context.checkTimeout(0);
+ return null;
+ }));
+ }
+ Assertions.assertEquals(1, events(appender).size(), "Nested passes share the root interval");
+ JsonObject event = JsonParser.parseString(events(appender).get(0).getMessage().getFormattedMessage()
+ .split(": ", 2)[1]).getAsJsonObject();
+ Assertions.assertEquals("catalog.db.inner", event.get("target").getAsString());
+ Assertions.assertEquals(1, event.get("held_locks").getAsInt());
+ Assertions.assertEquals("catalog.db.outer", event.get("oldest_lock").getAsString());
+ Assertions.assertEquals(5001, event.get("root_elapsed_ms").getAsLong());
+ Assertions.assertEquals(1, event.get("operation_elapsed_ms").getAsLong());
+ advance(30000);
+ context.checkTimeout(0);
+ Assertions.assertEquals(2, events(appender).size());
+ } finally {
+ hold.close();
+ }
+ }));
+ }
+ }
+
+ @Test
+ public void testRunningReportDoesNotUseStartsPublishedAfterItsTimestamp() throws Exception {
+ Thread plannerThread = Thread.currentThread();
+ CountDownLatch clockRead = new CountDownLatch(1);
+ CountDownLatch resumeChecker = new CountDownLatch(1);
+ PlanningDiagnostics diagnostics = new PlanningDiagnostics(context, () -> {
+ long now = clock.get();
+ if (Thread.currentThread() != plannerThread) {
+ clockRead.countDown();
+ try {
+ Assertions.assertTrue(resumeChecker.await(10, TimeUnit.SECONDS));
+ } catch (InterruptedException e) {
+ Thread.currentThread().interrupt();
+ throw new AssertionError(e);
+ }
+ }
+ return now;
+ });
+ ExecutorService checker = Executors.newSingleThreadExecutor();
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ PlanningDiagnostics.execute(diagnostics, () -> {
+ advance(5000);
+ PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ CompletableFuture<Void> report = CompletableFuture.runAsync(diagnostics::reportIfSlow, checker);
+ try {
+ Assertions.assertTrue(clockRead.await(10, TimeUnit.SECONDS));
+ advance(10);
+ PlanningDiagnostics.operation(context, "load_schema", "catalog.db.next", -1, () -> {
+ PlanningDiagnostics.LockHold hold = diagnostics.acquiredLock("catalog.db.next");
+ try {
+ resumeChecker.countDown();
+ report.get(10, TimeUnit.SECONDS);
+ JsonObject event = JsonParser.parseString(events(appender).get(0).getMessage()
+ .getFormattedMessage().split(": ", 2)[1]).getAsJsonObject();
+ for (String key : new String[] {"phase_elapsed_ms", "operation_elapsed_ms",
+ "oldest_lock_hold_ms"}) {
+ Assertions.assertTrue(event.get(key).getAsLong() >= 0, key);
+ }
+ } catch (Exception e) {
+ throw new AssertionError(e);
+ } finally {
+ hold.close();
+ }
+ return null;
+ });
+ } catch (InterruptedException e) {
+ Thread.currentThread().interrupt();
+ throw new AssertionError(e);
+ } finally {
+ resumeChecker.countDown();
+ }
+ });
+ return null;
+ });
+ } finally {
+ resumeChecker.countDown();
+ checker.shutdownNow();
+ Assertions.assertTrue(checker.awaitTermination(10, TimeUnit.SECONDS));
+ }
+ }
+
+ @Test
+ public void testRecoveredOperationDoesNotReplaceLaterFailure() {
+ Assertions.assertThrows(IllegalStateException.class, () -> run(() -> {
+ try {
+ PlanningDiagnostics.operation(context, "load_schema", "catalog.db.table", -1, () -> {
+ throw new IllegalArgumentException("recovered");
+ });
+ } catch (IllegalArgumentException expected) {
+ // Materialized-view alternatives can fail while planning continues.
+ }
+ PlanningDiagnostics.runPhase(context, Phase.REWRITE, () -> {
+ throw new IllegalStateException("actual failure");
+ });
+ }));
+ Assertions.assertEquals("rewrite", summary.getPlanningDetails().getAsJsonObject("last_pass")
+ .get("failed_step").getAsString());
+ }
+
+ @Test
+ public void testOperationsAreBoundedDeferredAndCarryQueryIdentity() {
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ run(() -> {
+ for (int i = 0; i < 20; i++) {
+ PlanningDiagnostics.operation(context, "load_schema", "catalog.db.table", -1, () -> {
+ advance(1000);
+ return null;
+ });
+ }
+ Assertions.assertTrue(events(appender).isEmpty());
+ });
+ Assertions.assertEquals(17, events(appender).size());
+ events(appender).forEach(event -> assertDiagnosticIdentity(event, "1-2"));
+ Assertions.assertTrue(appender.contains(Level.WARN, "\"omitted_operations\":4"));
+ }
+ }
+
+ @Test
+ public void testCheckerDoesNotWaitForStatementMonitorAndShowsHeldLock() throws Exception {
+ StatementContext statement = new StatementContext(context, new OriginStatement("select 1", 0));
+ TableIf first = table(1, "catalog.db.first");
+ TableIf second = table(2, "catalog.db.second");
+ statement.getTables().put(ImmutableList.of("first"), first);
+ statement.getTables().put(ImmutableList.of("second"), second);
+ CountDownLatch waiting = new CountDownLatch(1);
+ CountDownLatch release = new CountDownLatch(1);
+ Mockito.when(first.tryReadLock(1, TimeUnit.MINUTES)).thenReturn(true);
+ Mockito.when(second.tryReadLock(1, TimeUnit.MINUTES)).thenAnswer(invocation -> {
+ waiting.countDown();
+ Assertions.assertTrue(release.await(10, TimeUnit.SECONDS));
+ return true;
+ });
+ ExecutorService worker = Executors.newSingleThreadExecutor();
+ try (TestLogAppender appender = TestLogAppender.attach(PlanningDiagnostics.class, Level.WARN)) {
+ CompletableFuture<Void> planning = CompletableFuture.runAsync(() -> run(() -> {
+ try {
+ PlanningDiagnostics.runPhase(context, Phase.LOCK_TABLES, statement::lock);
+ advance(2000);
+ } finally {
+ statement.releasePlannerResources();
+ }
+ }), worker);
+ try {
+ Assertions.assertTrue(waiting.await(10, TimeUnit.SECONDS));
+ advance(5000);
+ CompletableFuture.runAsync(() -> context.checkTimeout(0)).get(1, TimeUnit.SECONDS);
Review Comment:
[P3] Test depends on the common pool and a 1 s timeout
`CompletableFuture.runAsync(...)` on the common pool with `.get(1, TimeUnit.SECONDS)` can time out on a loaded CI machine. The other cases use an injected clock/executor and latches; this one could follow the same pattern.
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java:
##########
@@ -818,6 +835,7 @@ private void updateExecutionSummaryProfile() {
executionSummaryProfile.addInfoString(NEREIDS_PRE_REWRITE_BY_MV_TIME, getPrettyNereidsPreRewriteByMvTime());
executionSummaryProfile.addInfoString(NEREIDS_OPTIMIZE_TIME, getPrettyNereidsOptimizeTime());
executionSummaryProfile.addInfoString(NEREIDS_TRANSLATE_TIME, getPrettyNereidsTranslateTime());
+ executionSummaryProfile.addInfoString("Nereids Planning Details", getPlanningDetails().toString());
Review Comment:
[P3] Register the new Profile key like the other Nereids entries
`"Nereids Planning Details"` is a string literal and is not in `EXECUTION_SUMMARY_KEYS` or the indentation map, so it renders at the end of the execution summary without indentation. Please follow the existing `NEREIDS_*` constant pattern.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6343557635
<details>
<summary>TPC-DS: <b>Total hot run time: 150624 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit b8c3b95b338135c2d75aaea83d0c60bc1baef90e, data reload: false
query5 4309 571 437 437
query6 428 208 189 189
query7 4817 448 218 218
query8 312 166 152 152
query9 8768 3097 3088 3088
query10 485 301 248 248
query11 6027 3844 3585 3585
query12 152 93 86 86
query13 1245 433 310 310
query14 6127 3924 3643 3643
query14_1 3426 3433 3366 3366
query15 206 201 186 186
query16 950 429 397 397
query17 867 664 532 532
query18 2424 431 314 314
query19 200 160 139 139
query20 84 86 82 82
query21 211 130 107 107
query22 13015 12892 12779 12779
query23 13526 12762 12453 12453
query23_1 12523 12515 12490 12490
query24 7368 806 467 467
query24_1 472 474 475 474
query25 537 427 369 369
query26 1287 257 145 145
query27 2768 440 282 282
query28 4604 1954 1950 1950
query29 1585 609 453 453
query30 300 215 188 188
query31 1008 929 820 820
query32 146 93 88 88
query33 541 301 251 251
query34 881 841 503 503
query35 728 750 642 642
query36 820 821 703 703
query37 120 98 95 95
query38 1778 1770 1686 1686
query39 790 798 748 748
query39_1 732 720 740 720
query40 217 117 102 102
query41 72 68 68 68
query42 84 86 84 84
query43 342 369 307 307
query44 1295 684 686 684
query45 186 183 172 172
query46 872 970 564 564
query47 2961 2961 2991 2961
query48 299 322 260 260
query49 574 411 287 287
query50 655 276 209 209
query51 10484 10277 10370 10277
query52 76 83 70 70
query53 188 206 154 154
query54 231 193 206 193
query55 72 63 61 61
query56 246 227 206 206
query57 1659 1645 1574 1574
query58 285 257 253 253
query59 2137 2203 1937 1937
query60 292 238 223 223
query61 144 140 140 140
query62 384 327 284 284
query63 184 157 160 157
query64 2721 942 750 750
query65 3321 3267 3252 3252
query66 1781 423 292 292
query67 20360 20068 20065 20065
query68 2934 987 609 609
query69 376 302 234 234
query70 842 755 752 752
query71 297 232 220 220
query72 2644 2535 2291 2291
query73 513 523 289 289
query74 4624 4427 4323 4323
query75 2314 2285 1894 1894
query76 2313 991 568 568
query77 341 363 273 273
query78 9813 9667 9164 9164
query79 990 844 520 520
query80 1189 430 346 346
query81 578 322 272 272
query82 577 133 102 102
query83 303 189 176 176
query84 312 122 98 98
query85 860 410 365 365
query86 395 237 227 227
query87 2031 1955 1823 1823
query88 3615 2657 2626 2626
query89 332 277 243 243
query90 1933 173 156 156
query91 158 150 123 123
query92 102 91 87 87
query93 987 971 571 571
query94 611 310 240 240
query95 585 396 305 305
query96 652 475 231 231
query97 2432 2450 2322 2322
query98 161 149 153 149
query99 765 767 650 650
Total cold run time: 235161 ms
Total hot run time: 150624 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6344827745
# FE UT Coverage Report
Increment line coverage ` 96.06% (414/431)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e/fe_increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e/fe_report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6350819655
# FE UT Coverage Report
Increment line coverage ` 96.06% (414/431)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e/fe_increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e/fe_report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "wenzhenghu (via GitHub)" <gi...@apache.org>.
wenzhenghu commented on code in PR #68727:
URL: https://github.com/apache/doris/pull/68727#discussion_r4267306149
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/PlanningDiagnostics.java:
##########
@@ -0,0 +1,437 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import org.apache.doris.common.Config;
+import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.qe.ConnectContext;
+import org.apache.doris.thrift.TUniqueId;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.gson.JsonObject;
+import org.apache.logging.log4j.CloseableThreadContext;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+import java.util.ArrayList;
+import java.util.EnumMap;
+import java.util.List;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.function.LongSupplier;
+import java.util.function.Supplier;
+
+/**
+ * One planning pass. The planning thread owns timers and the bounded slow-operation buffer.
+ * The connection checker reads only immutable, volatile-published steps, never planner/table locks.
+ * Timings are inclusive: nested phases and operations must not be added to their enclosing phase.
+ */
+public final class PlanningDiagnostics {
+ private static final Logger LOG = LogManager.getLogger(PlanningDiagnostics.class);
+ private static final int MAX_SLOW_OPERATIONS = 16;
+ // Internal MV planning can replace ConnectContext while the calling planner still holds table locks.
+ private static final ThreadLocal<PlanningDiagnostics> ACTIVE = new ThreadLocal<>();
+
+ public enum Phase {
+ PREPROCESS, COLLECT_TABLES, PRELOAD_METADATA, WAIT_CHANGE_VISIBLE, LOCK_TABLES,
+ ANALYZE, REWRITE, PRE_REWRITE_MV, OPTIMIZE, CHOOSE_PLAN, POST_PROCESS,
+ TRANSLATE, DISTRIBUTE, RELEASE_RESOURCES;
+
+ public String key() {
+ return name().toLowerCase(Locale.ROOT);
+ }
+ }
+
+ private final ConnectContext context;
+ private final SummaryProfile summary;
+ private final long passId;
+ private final PlanningDiagnostics parent;
+ private final PlanningDiagnostics root;
+ private final boolean inheritsQueryIdentity;
+ private final TUniqueId queryId;
+ private final long statementId;
+ private final String threadName;
+ private volatile long timeoutMs;
+ private final LongSupplier clock;
+ private final long started;
+ private final EnumMap<Phase, Timing> timings = new EnumMap<>(Phase.class);
+ private final List<Event> slowOperations = new ArrayList<>();
+ private final AtomicLong lastReport;
+ private volatile Step current;
+ private volatile Class<?> currentJob;
+ private volatile HeldLocks heldLocks = new HeldLocks(0, 0, "");
+ private volatile boolean finished;
+ // Only the root publishes this pointer, so its registered connection can inspect an internal pass.
+ private volatile PlanningDiagnostics activePass;
+ private String failedStep = "";
+ private Throwable stepFailure;
+ private long omittedOperations;
+
+ private PlanningDiagnostics(ConnectContext context) {
+ this(context, System::nanoTime);
+ }
+
+ @VisibleForTesting
+ PlanningDiagnostics(ConnectContext context, LongSupplier clock) {
+ this.context = context;
+ this.parent = ACTIVE.get();
+ this.root = parent == null ? this : parent.root;
+ this.lastReport = parent == null ? new AtomicLong(Long.MIN_VALUE) : parent.lastReport;
+ SummaryProfile contextSummary = SummaryProfile.getSummaryProfile(context);
+ this.summary = contextSummary != null ? contextSummary : parent == null ? null : parent.summary;
+ this.passId = summary == null ? 0 : summary.nextPlanningPassId();
+ TUniqueId contextQueryId = context.queryId();
+ this.inheritsQueryIdentity = contextQueryId == null && parent != null;
+ this.queryId = inheritsQueryIdentity ? parent.queryId
+ : contextQueryId == null ? null : contextQueryId.deepCopy();
+ this.statementId = inheritsQueryIdentity ? parent.statementId : context.getStmtId();
+ this.threadName = Thread.currentThread().getName();
+ this.timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ this.clock = clock;
+ this.started = clock.getAsLong();
+ }
+
+ /** Includes cleanup and restores an outer pass even when internal planning uses another connection. */
+ public static <T> T plan(ConnectContext context, Supplier<T> action) {
+ return execute(new PlanningDiagnostics(context), action);
+ }
+
+ @VisibleForTesting
+ static <T> T execute(PlanningDiagnostics diagnostics, Supplier<T> action) {
+ ConnectContext context = diagnostics.context;
+ PlanningDiagnostics previous = context.getPlanningDiagnostics();
+ ACTIVE.set(diagnostics);
+ context.setPlanningDiagnostics(diagnostics);
+ diagnostics.root.activePass = diagnostics;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ if (diagnostics.stepFailure != failure) {
+ diagnostics.failedStep = "between_phases";
+ }
+ throw failure;
+ } finally {
+ diagnostics.finished = true;
+ context.setPlanningDiagnostics(previous);
+ diagnostics.root.activePass = diagnostics.parent;
+ if (diagnostics.parent == null) {
+ ACTIVE.remove();
+ } else {
+ ACTIVE.set(diagnostics.parent);
+ }
+ diagnostics.finish(success);
+ }
+ }
+
+ public static void runPhase(ConnectContext context, Phase phase, Runnable action) {
+ phase(context, phase, () -> {
+ action.run();
+ return null;
+ });
+ }
+
+ public static <T> T phase(ConnectContext context, Phase phase, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ return diagnostics == null ? action.get() : diagnostics.measure(phase, "", "", -1, action);
+ }
+
+ /** A negative operation budget means that timeout handling belongs to the connector. */
+ public static <T> T operation(ConnectContext context, String operation, String target,
+ long budgetMs, Supplier<T> action) {
+ return operation(context, operation, () -> target, budgetMs, action);
+ }
+
+ /** Resolve the target only for an active planning pass, on the calling thread. */
+ public static <T> T operation(ConnectContext context, String operation, Supplier<String> target,
+ long budgetMs, Supplier<T> action) {
+ PlanningDiagnostics diagnostics = current(context);
+ if (diagnostics == null) {
+ return action.get();
+ }
+ Step step = diagnostics.current;
+ return diagnostics.measure(step == null ? Phase.PREPROCESS : step.phase,
+ operation, target.get(), budgetMs, action);
+ }
+
+ public static PlanningDiagnostics current(ConnectContext context) {
+ return context == null ? null : context.getPlanningDiagnostics();
+ }
+
+ private <T> T measure(Phase phase, String operation, String target, long budgetMs, Supplier<T> action) {
+ Step previous = current;
+ Step step = new Step(phase, operation, target, budgetMs, clock.getAsLong(),
+ operation.isEmpty() || previous == null ? -1 : previous.phaseStarted);
+ current = step;
+ boolean success = false;
+ try {
+ T result = action.get();
+ success = true;
+ return result;
+ } catch (RuntimeException | Error failure) {
+ // Preserve the innermost failing step of this exception, not an earlier recovered MV failure.
+ if (stepFailure != failure) {
+ stepFailure = failure;
+ failedStep = phase.key() + (operation.isEmpty() ? "" : "/" + operation);
+ }
+ throw failure;
+ } finally {
+ long elapsed = clock.getAsLong() - step.started;
+ if (operation.isEmpty()) {
+ Timing timing = timings.computeIfAbsent(phase, key -> new Timing());
+ timing.nanos += elapsed;
+ timing.calls++;
+ timing.failures += success ? 0 : 1;
+ if (phase == Phase.PREPROCESS && success) {
+ // SET_VAR hints are applied by preprocessing, after this pass was created.
+ timeoutMs = inheritsQueryIdentity ? parent.timeoutMs : context.getExecTimeoutS() * 1000L;
+ }
+ } else {
+ recordOperation(step, elapsed, success);
+ }
+ current = previous;
+ }
+ }
+
+ /** Avoid allocating task descriptions for every optimizer job; format the class only on a slow report. */
+ public Class<?> setCurrentJob(Class<?> job) {
+ Class<?> previous = currentJob;
+ currentJob = job;
+ return previous;
+ }
+
+ public LockHold acquiredLock(String table) {
+ long now = clock.getAsLong();
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count + 1, previous.count == 0 ? now : previous.started,
+ previous.count == 0 ? table : previous.oldestTable);
+ return new LockHold(table, now);
+ }
+
+ /** Closed after unlocking; planner resources release in reverse acquisition order. */
+ public final class LockHold implements AutoCloseable {
+ private final String table;
+ private final long acquired;
+
+ private LockHold(String table, long acquired) {
+ this.table = table;
+ this.acquired = acquired;
+ }
+
+ @Override
+ public void close() {
+ HeldLocks previous = heldLocks;
+ heldLocks = new HeldLocks(previous.count - 1, previous.started, previous.oldestTable);
+ recordOperation(new Step(Phase.RELEASE_RESOURCES, "read_lock_hold", table, -1, acquired, -1),
+ clock.getAsLong() - acquired, true);
+ }
+ }
+
+ private void recordOperation(Step step, long nanos, boolean success) {
+ long threshold = Config.nereids_planning_operation_log_threshold_ms;
+ if (success && (threshold <= 0 || millis(nanos) < threshold)) {
+ return;
+ }
+ if (slowOperations.size() == MAX_SLOW_OPERATIONS) {
+ omittedOperations++;
+ return;
+ }
+ JsonObject event = step.toJson();
+ event.addProperty("elapsed_ms", millis(nanos));
+ event.addProperty("status", success ? "completed" : "failed");
+ slowOperations.add(new Event(this, "Planning operation", event));
+ }
+
+ /** Invoked by the existing connection timeout checker, including while a planner job is blocked. */
+ public void reportIfSlow() {
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ PlanningDiagnostics active = root.activePass;
+ if (root.finished || active == null || threshold <= 0) {
+ return;
+ }
+ // Snapshot published starts before reading the clock. A newer step/lock sampled after the clock
+ // could otherwise appear to have started in the future when the checker was descheduled.
+ Step step = active.current;
+ Class<?> job = active.currentJob;
+ HeldLocks oldest = active.heldLocks;
+ int lockCount = oldest.count;
+ for (PlanningDiagnostics outer = active.parent; outer != null; outer = outer.parent) {
+ HeldLocks locks = outer.heldLocks;
+ lockCount += locks.count;
+ if (locks.count > 0 && (oldest.count == 0 || locks.started < oldest.started)) {
+ oldest = locks;
+ }
+ }
+ long now = root.clock.getAsLong();
+ if (millis(now - root.started) < threshold) {
+ return;
+ }
+ long previous = root.lastReport.get();
+ // A minimum interval protects the checker from an accidentally zero/negative dynamic setting.
+ long interval = Math.max(1000, Config.nereids_planning_log_interval_ms);
+ if ((previous != Long.MIN_VALUE && millis(now - previous) < interval)
+ || !root.lastReport.compareAndSet(previous, now)) {
+ return;
+ }
+ JsonObject event = step == null ? new JsonObject() : step.toJson();
+ event.addProperty("status", "running");
+ event.addProperty("elapsed_ms", millis(now - active.started));
+ event.addProperty("root_pass_id", root.passId);
+ event.addProperty("root_elapsed_ms", millis(now - root.started));
+ event.addProperty("phase_elapsed_ms", step == null ? 0 : millis(now - step.phaseStarted));
+ event.addProperty("operation_elapsed_ms", step == null || step.operation.isEmpty()
+ ? 0 : millis(now - step.started));
+ event.addProperty("job", job == null ? "" : job.getSimpleName());
+ event.addProperty("held_locks", lockCount);
+ event.addProperty("oldest_lock", lockCount == 0 ? "" : bounded(oldest.oldestTable));
+ event.addProperty("oldest_lock_hold_ms", lockCount == 0 ? 0 : millis(now - oldest.started));
+ active.log("Slow planning", event);
+ }
+
+ private void finish(boolean success) {
+ JsonObject result = new JsonObject();
+ result.addProperty("pass_id", passId);
+ result.addProperty("status", success ? "completed" : "failed");
+ result.addProperty("elapsed_ms", millis(clock.getAsLong() - started));
+ result.addProperty("failed_step", success ? "" : failedStep);
+ JsonObject phases = new JsonObject();
+ for (Phase phase : Phase.values()) {
+ Timing timing = timings.get(phase);
+ JsonObject value = new JsonObject();
+ value.addProperty("status", timing == null ? "not_run" : timing.failures > 0 ? "failed" : "completed");
+ value.addProperty("elapsed_ms", timing == null ? 0 : millis(timing.nanos));
+ value.addProperty("calls", timing == null ? 0 : timing.calls);
+ phases.add(phase.key(), value);
+ }
+ result.add("phases", phases);
+ result.addProperty("omitted_operations", omittedOperations);
+ if (summary != null) {
+ summary.addPlanningPass(result);
+ }
+ long threshold = Config.nereids_planning_log_threshold_ms;
+ boolean report = !success || !slowOperations.isEmpty()
+ || (threshold > 0 && result.get("elapsed_ms").getAsLong() >= threshold);
+ // An enclosing MV planning pass may still hold locks. Defer its children's logs as well.
+ if (parent != null) {
+ for (Event event : slowOperations) {
+ parent.defer(event);
+ }
+ parent.omittedOperations += omittedOperations;
+ if (report) {
+ parent.defer(new Event(this, "Planning finished", result));
+ }
+ } else {
+ for (Event event : slowOperations) {
+ event.owner.log(event.message, event.json);
+ }
+ if (report) {
+ log("Planning finished", result);
Review Comment:
Adopted the compact-failure option in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a). A fast failed pass now logs attribution, elapsed time, and `failed_step` without the full phase tree. Detailed phase status remains in Profile; failed metadata-operation events still retain their own target/error attribution.
`testFastFailureEmitsCompactAttribution` covers both an ordinary phase failure and a fast metadata failure. Failure reporting remains intentional even when slow thresholds are disabled, as documented; its volume was reduced rather than disabling failure evidence.
##########
fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java:
##########
@@ -818,6 +835,7 @@ private void updateExecutionSummaryProfile() {
executionSummaryProfile.addInfoString(NEREIDS_PRE_REWRITE_BY_MV_TIME, getPrettyNereidsPreRewriteByMvTime());
executionSummaryProfile.addInfoString(NEREIDS_OPTIMIZE_TIME, getPrettyNereidsOptimizeTime());
executionSummaryProfile.addInfoString(NEREIDS_TRANSLATE_TIME, getPrettyNereidsTranslateTime());
+ executionSummaryProfile.addInfoString("Nereids Planning Details", getPlanningDetails().toString());
Review Comment:
Addressed in [5d0a0779ce8d](https://github.com/apache/doris/commit/5d0a0779ce8db4a5f372cff13e1e07ba0d7b530a): introduced `NEREIDS_PLANNING_DETAILS`, registered it in `EXECUTION_SUMMARY_KEYS` and the indentation map, and used the constant when rendering the execution summary. It now follows the existing Nereids entries' ordering/indentation pattern.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6123436548
<details>
<summary>ClickBench: <b>Total hot run time: 24.63 s</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit 4abbea0ad82bbc4dd47631e3833a9774e030dc93, data reload: false
query1 0.01 0.00 0.01
query2 0.11 0.04 0.05
query3 0.27 0.12 0.12
query4 1.61 0.12 0.12
query5 0.24 0.25 0.24
query6 1.17 0.67 0.69
query7 0.03 0.01 0.00
query8 0.06 0.04 0.03
query9 0.41 0.35 0.35
query10 0.56 0.58 0.59
query11 0.20 0.14 0.14
query12 0.19 0.14 0.15
query13 0.48 0.49 0.50
query14 0.97 0.97 0.97
query15 0.62 0.61 0.61
query16 0.36 0.34 0.36
query17 1.16 1.19 1.16
query18 0.23 0.21 0.21
query19 2.13 2.00 1.98
query20 0.02 0.01 0.01
query21 15.52 0.25 0.14
query22 4.44 0.05 0.05
query23 16.26 0.32 0.13
query24 2.90 0.58 0.48
query25 0.14 0.06 0.06
query26 1.82 0.26 0.15
query27 0.05 0.04 0.05
query28 2.32 0.62 0.41
query29 12.50 4.18 3.32
query30 0.29 0.14 0.13
query31 2.77 0.57 0.33
query32 3.22 0.63 0.52
query33 3.16 3.20 3.23
query34 15.61 3.96 3.37
query35 3.37 3.34 3.37
query36 0.54 0.47 0.41
query37 0.10 0.07 0.06
query38 0.05 0.04 0.04
query39 0.04 0.03 0.03
query40 0.17 0.15 0.14
query41 0.09 0.03 0.03
query42 0.04 0.02 0.02
query43 0.05 0.03 0.03
Total cold run time: 96.28 s
Total hot run time: 24.63 s
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6128008642
<details>
<summary>TPC-DS: <b>Total hot run time: 151854 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit 21b3cc226fee907a1280f5e2fc0f740e146a86bb, data reload: false
query5 4318 573 447 447
query6 427 207 190 190
query7 4804 440 226 226
query8 318 186 173 173
query9 8780 3927 3915 3915
query10 456 312 262 262
query11 5990 3427 3188 3188
query12 148 87 82 82
query13 1255 447 324 324
query14 6571 4720 4539 4539
query14_1 4291 4240 4274 4240
query15 206 196 189 189
query16 949 452 420 420
query17 861 660 561 561
query18 2411 431 322 322
query19 217 170 139 139
query20 85 80 80 80
query21 223 141 110 110
query22 13037 12974 12783 12783
query23 13069 12526 12107 12107
query23_1 12283 12186 12128 12128
query24 7101 830 465 465
query24_1 468 467 473 467
query25 538 473 327 327
query26 1255 257 133 133
query27 2786 442 270 270
query28 4646 1960 1978 1960
query29 1522 570 431 431
query30 287 217 188 188
query31 887 761 641 641
query32 140 86 85 85
query33 502 300 232 232
query34 996 846 482 482
query35 743 775 644 644
query36 828 799 735 735
query37 138 99 84 84
query38 1786 1760 1675 1675
query39 705 716 690 690
query39_1 673 655 679 655
query40 220 116 95 95
query41 69 67 63 63
query42 82 79 82 79
query43 371 374 327 327
query44 1286 699 698 698
query45 175 180 165 165
query46 815 953 566 566
query47 2800 2974 2909 2909
query48 301 306 225 225
query49 566 394 281 281
query50 664 278 217 217
query51 10531 10455 10214 10214
query52 74 85 74 74
query53 187 205 153 153
query54 228 199 194 194
query55 76 74 63 63
query56 232 228 210 210
query57 1605 1579 1564 1564
query58 277 262 254 254
query59 2351 2394 2138 2138
query60 295 234 222 222
query61 136 139 146 139
query62 398 338 290 290
query63 198 163 169 163
query64 2745 992 899 899
query65 3432 3387 3413 3387
query66 1782 438 364 364
query67 20130 20286 20172 20172
query68 2943 1049 631 631
query69 410 291 263 263
query70 977 842 842 842
query71 301 222 204 204
query72 2784 2591 2251 2251
query73 535 515 300 300
query74 4569 4467 4300 4300
query75 2354 2284 1933 1933
query76 2287 1015 620 620
query77 354 383 318 318
query78 8999 8996 8425 8425
query79 1044 855 511 511
query80 551 425 330 330
query81 550 322 274 274
query82 584 138 125 125
query83 317 198 177 177
query84 315 124 98 98
query85 812 415 361 361
query86 315 245 235 235
query87 2001 1945 1808 1808
query88 3572 2679 2655 2655
query89 337 296 265 265
query90 1908 178 181 178
query91 161 147 121 121
query92 89 88 89 88
query93 1011 985 588 588
query94 448 291 265 265
query95 567 339 320 320
query96 656 527 237 237
query97 2455 2403 2284 2284
query98 156 149 143 143
query99 769 771 657 657
Total cold run time: 233617 ms
Total hot run time: 151854 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6343662763
<details>
<summary>ClickBench: <b>Total hot run time: 24.36 s</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit b8c3b95b338135c2d75aaea83d0c60bc1baef90e, data reload: false
query1 0.00 0.00 0.00
query2 0.10 0.05 0.04
query3 0.28 0.09 0.09
query4 1.61 0.09 0.10
query5 0.23 0.24 0.24
query6 1.18 0.69 0.68
query7 0.04 0.01 0.01
query8 0.05 0.04 0.03
query9 0.40 0.36 0.33
query10 0.58 0.57 0.57
query11 0.20 0.14 0.14
query12 0.18 0.16 0.14
query13 0.50 0.50 0.48
query14 1.02 1.01 1.00
query15 0.65 0.60 0.60
query16 0.34 0.35 0.35
query17 1.12 1.11 1.19
query18 0.21 0.19 0.19
query19 2.12 2.01 1.94
query20 0.02 0.01 0.02
query21 15.48 0.19 0.14
query22 4.93 0.07 0.06
query23 16.25 0.30 0.12
query24 3.02 0.62 0.47
query25 0.11 0.07 0.06
query26 1.60 0.21 0.15
query27 0.06 0.03 0.04
query28 3.50 0.76 0.36
query29 12.48 4.12 3.24
query30 0.28 0.14 0.10
query31 2.77 0.56 0.32
query32 3.21 0.59 0.53
query33 3.11 3.30 3.28
query34 15.45 3.96 3.39
query35 3.33 3.33 3.30
query36 0.56 0.43 0.45
query37 0.09 0.06 0.07
query38 0.04 0.04 0.03
query39 0.04 0.03 0.03
query40 0.17 0.15 0.14
query41 0.09 0.03 0.03
query42 0.04 0.02 0.03
query43 0.05 0.04 0.03
Total cold run time: 97.49 s
Total hot run time: 24.36 s
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6350673701
# FE Regression Coverage Report
Increment line coverage ` 87.24% (376/431)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e_merge_fe/increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e_merge_fe/report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6351072045
# FE Regression Coverage Report
Increment line coverage ` 87.24% (376/431)` :tada:
[Increment coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e_merge_fe/increment_report/index.html)
[Complete coverage report](http://coverage.selectdb-in.cc/coverage/68727_b8c3b95b338135c2d75aaea83d0c60bc1baef90e_merge_fe/report/index.html)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org
Re: [PR] [improvement](fe) Add bounded query planning diagnostics [doris]
Posted by "hello-stephen (via GitHub)" <gi...@apache.org>.
hello-stephen commented on PR #68727:
URL: https://github.com/apache/doris/pull/68727#issuecomment-6315276763
<details>
<summary>TPC-DS: <b>Total hot run time: 151163 ms</b></summary>
```
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit 37ba8ccf456eddc1ab0946c37ce556f534d1fbad, data reload: false
query5 4310 582 476 476
query6 442 206 188 188
query7 4810 442 218 218
query8 334 163 151 151
query9 8794 3091 3117 3091
query10 471 312 259 259
query11 6020 3919 3614 3614
query12 152 102 87 87
query13 1269 443 334 334
query14 6117 3927 3626 3626
query14_1 3459 3480 3404 3404
query15 207 196 182 182
query16 972 470 453 453
query17 884 678 565 565
query18 2439 438 312 312
query19 207 164 137 137
query20 88 86 82 82
query21 212 129 110 110
query22 13056 12899 12831 12831
query23 13530 12913 12329 12329
query23_1 12574 12575 12580 12575
query24 7400 837 477 477
query24_1 463 472 485 472
query25 546 431 358 358
query26 1267 263 145 145
query27 2762 441 274 274
query28 4635 1951 1925 1925
query29 1566 602 455 455
query30 306 227 194 194
query31 1017 944 817 817
query32 182 98 88 88
query33 542 301 253 253
query34 936 856 502 502
query35 750 749 665 665
query36 856 795 713 713
query37 127 104 92 92
query38 1783 1719 1675 1675
query39 790 823 757 757
query39_1 732 733 744 733
query40 221 120 101 101
query41 74 69 68 68
query42 90 84 85 84
query43 345 368 322 322
query44 1342 685 687 685
query45 181 175 164 164
query46 862 981 582 582
query47 3025 2875 2674 2674
query48 288 314 220 220
query49 567 415 287 287
query50 707 282 210 210
query51 10349 10516 10458 10458
query52 84 79 69 69
query53 185 204 148 148
query54 231 199 183 183
query55 72 72 72 72
query56 253 211 216 211
query57 1636 1612 1546 1546
query58 280 264 277 264
query59 2027 2106 1938 1938
query60 285 240 227 227
query61 147 140 136 136
query62 385 324 279 279
query63 203 152 155 152
query64 2779 938 744 744
query65 3339 3292 3287 3287
query66 1791 419 318 318
query67 20290 20157 20195 20157
query68 3257 1030 595 595
query69 387 296 254 254
query70 828 768 773 768
query71 310 240 204 204
query72 2887 2708 2272 2272
query73 534 541 294 294
query74 4650 4510 4373 4373
query75 2346 2302 1905 1905
query76 2397 1017 592 592
query77 353 380 275 275
query78 9992 9840 9238 9238
query79 1019 863 534 534
query80 1370 429 337 337
query81 597 325 276 276
query82 828 137 108 108
query83 281 209 173 173
query84 316 116 101 101
query85 1091 441 375 375
query86 398 233 232 232
query87 2017 1934 1841 1841
query88 3701 2660 2650 2650
query89 327 280 238 238
query90 1814 176 170 170
query91 162 151 131 131
query92 99 90 93 90
query93 1055 1019 573 573
query94 636 292 263 263
query95 571 340 306 306
query96 669 486 230 230
query97 2443 2432 2333 2333
query98 167 153 151 151
query99 769 765 647 647
Total cold run time: 237061 ms
Total hot run time: 151163 ms
```
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org