DagExplainer now publish the whole EXPLAIN in a single log

CHANGES.MD

@@ -25,6 +25,8 @@ Bump to 0.1.0 to mark the move to JDK 25 (still 0.x — Adhoc is not yet API-sta
 - `RoutingMeasure` (`engine/recipes`): `ICombinator`-style measure dispatching each `CubeQueryStep` to one of several underlying measures via a `Function<CubeQueryStep, String>`. Callers must ensure queries do not straddle the routing boundary. Not Jackson-serializable — register programmatically.
 
 ### Changed
+- `DagExplainer` now emits a SINGLE `AdhocLogEvent` carrying the whole tree (one row per step, joined by EOL) instead of one event per step. Posting per-step events let the SLF4J sink interleave rows from concurrent explains on the same logger, scrambling the ASCII-art DAG. The downstream `AdhocEventsFromGuavaEventBusToSfl4j` listener already splits multi-line EXPLAIN messages back into one log line per row, so the final SLF4J output is unchanged. The `printStepAndUnderlyings` method now takes a `StringBuilder lines` parameter — subclasses overriding it must propagate the buffer (only `DagExplainerForPerfs` is affected and is updated in place since it overrides `additionalInfo`, not the recursion).
+- `TableQueryEngine.reportOnTableQuery` now emits a SINGLE `AdhocLogEvent` for the `/-- N inducers from ...` header plus its per-step `|\- step ...` / `\-- step ...` rows (joined by EOL), instead of one event per row. Same rationale as `DagExplainer`: concurrent table-query reports on the same eventBus would interleave in the SLF4J output. The per-step `QueryStepIsCompleted` instrumentation event is unaffected — it is a distinct event type, not part of the EXPLAIN ASCII block.
 - `JooqTableQueryFactory.prepareSliceQuery(TableQueryV4)` now emits a SQL UNION ALL across `TableQueryV4#streamV3()` branches when `isPerfectV3()` is false, instead of inflating to a covering single GROUPING-SETS query via the deleted `TableQueryV4.asCoveringV3()`. The DB only computes the `(groupBy, aggregator)` pairs each branch actually requires. When `isPerfectV3()` is true, the path routes through the new `TableQueryV4.toV3()` helper (perfect-match-required, throws otherwise) — same single GROUPING-SET SQL as before. DRILLTHROUGH (`ColumnsManager.openStreamInternal`) also uses `toV3()` (single-groupBy guarantees perfect match).
 - `CompositeCubesTableWrapper#getCoordinates(Map, int)`: override now fans out one bulk call per sub-cube (with the columns it actually carries) instead of falling back to `ITableWrapper`'s default per-column loop. Preserves the `JooqTableWrapper` bulk-SQL optimization end-to-end through a composite — a Pivotable navbar search across N columns now issues one SQL round-trip per Jooq-backed sub-cube rather than N. The `optCubeSlicer` virtual column is synthesised locally; merged samples union coordinates (truncated to `limit`) and sum estimated cardinalities.
 - `CubeQueryEngine` no longer owns the plan registry — `StandardQueryPreparator` does. The preparator carries `queryPlanRegistry` (default `NoopQueryPlanRegistry.INSTANCE`) and writes it into the `QueryPod`; the engine no longer rebuilds the pod. `AdhocSchema` threads it through `makeQueryPreparator()`. Tests overriding `engine()` to wire a registry now override `queryPreparator()`.

engine/cube/src/test/java/eu/solven/adhoc/engine/cache/TestDagCubeQuery_QueryStepCache.java

@@ -139,7 +139,7 @@ public void testGrandTotal_transformator() {
 			});
 		}
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								\\-- #1 m=k1PlusK2AsExpr(Combinator[EXPRESSION]) filter=matchAll groupBy=grandTotal
@@ -188,7 +188,7 @@ public void testGrandTotal_aggregatorThenTransformator() {
 			});
 		}
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								\\-- #1 m=k1PlusK2AsExpr(Combinator[EXPRESSION]) filter=matchAll groupBy=grandTotal
@@ -199,7 +199,9 @@ public void testGrandTotal_aggregatorThenTransformator() {
 								/-- #0 t=inMemory id=00000000-0000-0000-0000-000000000001 (parentId=00000000-0000-0000-0000-000000000000)
 								\\-- #1 m=k2(SUM) filter=matchAll groupBy=grandTotal""");
 
-		Assertions.assertThat(messages).hasSize(4 + 2 + 2);
+		// 1 event for the cube DagExplainer tree, 1 for the table-query "inducers from" + "step" report
+		// from TableQueryEngine (header + steps collapsed into a single event), 1 for the table DagExplainer tree.
+		Assertions.assertThat(messages).hasSize(1 + 1 + 1);
 	}
 
 }

engine/cube/src/test/java/eu/solven/adhoc/query/foreignexchange/TestDagCubeQueryFx.java

@@ -209,7 +209,7 @@ public void testExplain_grandTotal() {
 		cube().execute(CubeQuery.builder().measure(mName).customMarker(Optional.of("JPY")).explain(true).build());
 
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								\\-- #1 m=k1.CCY(Partitionor[FX][eu.solven.adhoc.measure.sum.SumElseSetAggregation]) filter=matchAll groupBy=grandTotal customMarker=JPY
@@ -237,7 +237,7 @@ public void testExplain_filter() {
 				.build());
 
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								\\-- #1 m=k1.CCY(Partitionor[FX][eu.solven.adhoc.measure.sum.SumElseSetAggregation]) filter=color==red groupBy=(letter) customMarker=JPY

engine/cube/src/test/java/eu/solven/adhoc/query/many_to_many/TestDagCubeQuery_ManyToMany.java

@@ -349,7 +349,7 @@ public void testExplain_groupByGroups() {
 		}
 
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								\\-- #1 m=k1.dispatched(Dispatchor[eu.solven.adhoc.measure.decomposition.many2many.ManyToMany1DDecomposition][SUM]) filter=matchAll groupBy=(country_groups)

engine/cube/src/test/java/eu/solven/adhoc/table/composite/TestDagTableQuery_DuckDb_CompositeCube.java

@@ -319,7 +319,7 @@ public void testQueryCube1Plus2_filterUnshared() {
 				.hasSize(1);
 
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=composite id=00000000-0000-0000-0000-000000000000
 								\\-- #1 m=k1PlusK2AsExpr(Combinator[EXPRESSION]) filter=b==b1 groupBy=grandTotal

engine/recipes/src/test/java/eu/solven/adhoc/measure/ratio/TestDagAggregations_RatioByCombinator.java

@@ -178,7 +178,7 @@ public void testExplain_groupByGroups() {
 		}
 
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								|\\- #1 m=FRoverUS(RatioByCombinator[DIVIDE]) filter=country==US groupBy=grandTotal

engine/recipes/src/test/java/eu/solven/adhoc/measure/ratio/TestDagAggregations_RatioCurrentCountry.java

@@ -161,7 +161,7 @@ public void testExplain_filterUs() {
 		}
 
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								\\-- #1 m=d_country=current_ratio(Columnator[SUM]) filter=country==US groupBy=grandTotal
@@ -175,7 +175,9 @@ public void testExplain_filterUs() {
 								/-- #0 t=inMemory id=00000000-0000-0000-0000-000000000001 (parentId=00000000-0000-0000-0000-000000000000)
 								\\-- #1 m=d(SUM) filter=country==US groupBy=(country)""");
 
-		Assertions.assertThat(messages).hasSize(7 + 2 + 2);
+		// 1 event for the cube DagExplainer tree, 1 for the table-query "inducers from" + "step" report
+		// from TableQueryEngine (header + steps collapsed into a single event), 1 for the table DagExplainer tree.
+		Assertions.assertThat(messages).hasSize(1 + 1 + 1);
 	}
 
 	@Test
@@ -193,7 +195,7 @@ public void testExplain_filterUs_andWhole() {
 		}
 
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								|\\- #1 m=d(SUM) filter=country==US groupBy=grandTotal
@@ -210,6 +212,8 @@ public void testExplain_filterUs_andWhole() {
 								|   \\-- #2 m=d(SUM) filter=country==US groupBy=(country)
 								\\-- !2""");
 
-		Assertions.assertThat(messages).hasSize(8 + 2 + 4);
+		// 1 event for the cube DagExplainer tree, 1 for the table-query "inducers from" + "step" report
+		// from TableQueryEngine (header + steps collapsed into a single event), 1 for the table DagExplainer tree.
+		Assertions.assertThat(messages).hasSize(1 + 1 + 1);
 	}
 }

engine/recipes/src/test/java/eu/solven/adhoc/measure/ratio/TestDagAggregations_RatioPairOfCountry.java

@@ -178,7 +178,7 @@ public void testExplain_filterOtherColumn() {
 		}
 
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								\\-- #1 m=FRoverUS(Combinator[DIVIDE]) filter=matchAll groupBy=grandTotal

engine/recipes/src/test/java/eu/solven/adhoc/measure/ratio/TestDagAggregations_RatioSpecificCountry.java

@@ -129,7 +129,7 @@ public void testExplain_filterOtherColumn() {
 		}
 
 		Assertions.assertThat(String.join("\n", messages))
-				.isEqualTo(
+				.isEqualToNormalizingNewlines(
 						"""
 								/-- #0 c=inMemory id=00000000-0000-0000-0000-000000000000
 								\\-- #1 m=d_country=FR_ratio(Combinator[DIVIDE]) filter=color==blue groupBy=grandTotal

engine/table/src/main/java/eu/solven/adhoc/engine/observability/DagExplainer.java

@@ -39,6 +39,7 @@
 import eu.solven.adhoc.engine.step.ICubeQuery;
 import eu.solven.adhoc.engine.step.ICubeQueryStep;
 import eu.solven.adhoc.engine.tabular.optimizer.IHasDagFromInducedToInducer;
+import eu.solven.adhoc.eventbus.AdhocEventsFromGuavaEventBusToSfl4j;
 import eu.solven.adhoc.eventbus.AdhocLogEvent;
 import eu.solven.adhoc.eventbus.AdhocLogEvent.AdhocLogEventBuilder;
 import eu.solven.adhoc.eventbus.IAdhocEventBus;
@@ -132,7 +133,15 @@
 
 		DagExplainerState state = newDagExplainerState(queryId, dag);
 
-		printStepAndUnderlyings(state, FAKE_ROOT, Optional.empty(), true);
+		// Atomic emission: every step is appended to a single buffer, then the whole tree is posted
+		// as ONE AdhocLogEvent. Posting per-step events lets the slf4j sink interleave rows from
+		// concurrent explains on the same logger, scrambling the ASCII-art DAG. The downstream
+		// listener (`AdhocEventsFromGuavaEventBusToSfl4j.printLogEvent`) already splits multi-line
+		// EXPLAIN messages back into one log line per row, so the final SLF4J output is unchanged.
+		StringBuilder lines = new StringBuilder();
+		printStepAndUnderlyings(state, FAKE_ROOT, Optional.empty(), true, lines);
+
+		eventBus.post(openEventBuilder().message(lines.toString()).build());
 	}
 
 	protected void shortExplain(AdhocQueryId queryId, IHasDagFromInducedToInducer dag) {
@@ -163,18 +172,26 @@
 	}
 
 	/**
-	 * 
+	 * Appends one row per step to {@code lines} (depth-first), with ASCII-art indentation. The caller (see
+	 * {@link #explain}) wraps the accumulated buffer into a single {@link AdhocLogEvent}.
+	 *
 	 * @param dagState
+	 *            mutable indentation/reference state shared across the recursion
 	 * @param step
-	 *            currently show queryStep
+	 *            currently shown queryStep
 	 * @param optParent
+	 *            parent step in the recursion (empty for {@link #FAKE_ROOT})
 	 * @param isLast
-	 *            true if this step is the last amongst its siblings.
+	 *            true if this step is the last amongst its siblings
+	 * @param lines
+	 *            output buffer; one row is appended per visited step, separated by
+	 *            {@link AdhocEventsFromGuavaEventBusToSfl4j#EOL}
 	 */
 	protected void printStepAndUnderlyings(DagExplainerState dagState,
 			ICubeQueryStep step,
 			Optional<ICubeQueryStep> optParent,
-			boolean isLast) {
+			boolean isLast,
+			StringBuilder lines) {
 		boolean isReferenced;
 		{
 			String indentation;
@@ -205,8 +222,10 @@
 
 			String additionalStepInfo = additionalInfo(dagState, step, indentation, isLast, isReferenced);
 
-			eventBus.post(openEventBuilder().message("%s%s%s".formatted(indentation, stepAsString, additionalStepInfo))
-					.build());
+			if (lines.length() > 0) {
+				lines.append(AdhocEventsFromGuavaEventBusToSfl4j.EOL);
+			}
+			lines.append(indentation).append(stepAsString).append(additionalStepInfo);
 		}
 
 		if (!isReferenced) {
@@ -216,7 +235,7 @@
 				ICubeQueryStep underlyingStep = underlyings.get(i);
 
 				boolean isLastUnderlying = i == underlyings.size() - 1;
-				printStepAndUnderlyings(dagState, underlyingStep, Optional.of(step), isLastUnderlying);
+				printStepAndUnderlyings(dagState, underlyingStep, Optional.of(step), isLastUnderlying, lines);
 			}
 		}
 	}

engine/table/src/main/java/eu/solven/adhoc/engine/observability/TableDagExplainer.java

@@ -0,0 +1,74 @@
+/**
+ * The MIT License
+ * Copyright (c) 2026 Benoit Chatain Lacelle - SOLVEN
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in
+ * all copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+ * THE SOFTWARE.
+ */
+package eu.solven.adhoc.engine.observability;
+
+import java.util.Map;
+import java.util.concurrent.atomic.AtomicInteger;
+
+import eu.solven.adhoc.cuboid.ICuboid;
+import eu.solven.adhoc.engine.step.TableQueryStep;
+import eu.solven.adhoc.eventbus.AdhocEventsFromGuavaEventBusToSfl4j;
+import lombok.Builder;
+import lombok.Builder.Default;
+
+/**
+ * 
+ * Atomic EXPLAIN emission: the header ("/-- N inducers from ...") and the per-step rows are collected into a single
+ * buffer and posted as ONE AdhocLogEvent. Posting per-step events would let the SLF4J sink interleave rows from
+ * concurrent table queries, scrambling the ASCII-art block. Same rationale and downstream contract as DagExplainer.
+ * 
+ * @author Benoit Lacelle
+ */
+@Builder
+public class TableDagExplainer {
+	final Map<TableQueryStep, ICuboid> oneQueryStepToValues;
+
+	@Default
+	final String eol = AdhocEventsFromGuavaEventBusToSfl4j.EOL;
+
+	@SuppressWarnings("PMD.AvoidStringBufferField")
+	final StringBuilder explainLines = new StringBuilder();
+	final AtomicInteger queryStepIndex = new AtomicInteger();
+
+	public void header(String perfLog) {
+		explainLines.append("/-- ").append(oneQueryStepToValues.size()).append(" inducers from ").append(perfLog);
+	}
+
+	public void step(String stepAsString) {
+		int lastStepIndex = oneQueryStepToValues.size() - 1;
+
+		boolean isLast = queryStepIndex.getAndIncrement() == lastStepIndex;
+		String template;
+		if (isLast) {
+			template = "\\-- step %s";
+		} else {
+			template = "|\\- step %s";
+		}
+		explainLines.append(eol).append(template.formatted(stepAsString));
+	}
+
+	@Override
+	public String toString() {
+		return explainLines.toString();
+	}
+}

engine/table/src/main/java/eu/solven/adhoc/engine/tabular/TableQueryEngine.java

@@ -34,7 +34,6 @@
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.ConcurrentMap;
-import java.util.concurrent.atomic.AtomicInteger;
 import java.util.function.Function;
 import java.util.function.Supplier;
 import java.util.stream.Collectors;
@@ -74,6 +73,7 @@
 import eu.solven.adhoc.engine.observability.DagExplainer;
 import eu.solven.adhoc.engine.observability.DagExplainerForPerfs;
 import eu.solven.adhoc.engine.observability.SizeAndDuration;
+import eu.solven.adhoc.engine.observability.TableDagExplainer;
 import eu.solven.adhoc.engine.observability.plan.IQueryPlanRegistry;
 import eu.solven.adhoc.engine.observability.plan.NodeOperator;
 import eu.solven.adhoc.engine.observability.plan.NodeState;
@@ -782,19 +782,16 @@ protected void reportOnTableQuery(TableQueryV4 tableQuery,
 			Map<TableQueryStep, ICuboid> oneQueryStepToValues) {
 		boolean isExplain = queryPod.isDebugOrExplain();
 
+		TableDagExplainer dagExplainer = TableDagExplainer.builder().oneQueryStepToValues(oneQueryStepToValues).build();
+
 		if (isExplain) {
-			eventBus.post(AdhocLogEvent.builder()
-					.debug(queryPod.isDebug())
-					.explain(queryPod.isExplain())
-					.message("/-- %s inducers from %s".formatted(oneQueryStepToValues.size(), toPerfLog(tableQuery)))
-					.source(this)
-					.build());
+			dagExplainer.header(toPerfLog(tableQuery));
 		}
 
-		int lastStepIndex = oneQueryStepToValues.size() - 1;
-		AtomicInteger queryStepIndex = new AtomicInteger();
+		for (Map.Entry<TableQueryStep, ICuboid> entry : oneQueryStepToValues.entrySet()) {
+			TableQueryStep queryStep = entry.getKey();
+			ICuboid column = entry.getValue();
 
-		oneQueryStepToValues.forEach((queryStep, column) -> {
 			eventBus.post(QueryStepIsCompleted.builder()
 					.querystep(queryStep)
 					.nbCells(column.size())
@@ -807,22 +804,18 @@ protected void reportOnTableQuery(TableQueryV4 tableQuery,
 					SizeAndDuration.builder().size(column.size()).duration(elapsed).build());
 
 			if (isExplain) {
-				boolean isLast = queryStepIndex.getAndIncrement() == lastStepIndex;
-
-				String template;
-				if (isLast) {
-					template = "\\-- step %s";
-				} else {
-					template = "|\\- step %s";
-				}
-				eventBus.post(AdhocLogEvent.builder()
-						.debug(queryPod.isDebug())
-						.explain(queryPod.isExplain())
-						.message(template.formatted(toPerfLog(queryStep)))
-						.source(this)
-						.build());
+				dagExplainer.step(toPerfLog(queryStep));
 			}
-		});
+		}
+
+		if (isExplain) {
+			eventBus.post(AdhocLogEvent.builder()
+					.debug(queryPod.isDebug())
+					.explain(queryPod.isExplain())
+					.message(dagExplainer.toString())
+					.source(this)
+					.build());
+		}
 	}
 
 	/**