From 9e8b600238e641da4901f5734ff0997d61990e89 Mon Sep 17 00:00:00 2001 From: DemchaAV Date: Fri, 10 Jul 2026 14:11:19 +0100 Subject: [PATCH] feat(benchmarks): opt-in benchmark logging flag Benchmark runs are quiet by default so GraphCompose, PDFBox, and FontBox DEBUG lifecycle logs don't distort the measured numbers or bury the metrics. Opt back into those logs when debugging a run: `-EnableBenchmarkLogs` on run-benchmarks.ps1, or `-Dgraphcompose.benchmark.logging=debug` on a direct Java entry point. BenchmarkSupport reads graphcompose.benchmark.logging (default quiet; debug/verbose/true/on enable logs): quiet installs logback-benchmark.xml (ERROR-only), otherwise logging stays at the default. This adds the logback-benchmark.xml resource that BenchmarkSupport already referenced but that was missing from the tree, so quiet mode now actually applies. The script threads the property through every benchmark step; BenchmarkSupportTest covers the default-quiet and opt-out paths. --- README.md | 2 +- .../com/demcha/compose/BenchmarkSupport.java | 13 ++++ .../src/main/resources/logback-benchmark.xml | 7 ++ .../demcha/compose/BenchmarkSupportTest.java | 75 +++++++++++++++++++ docs/operations/benchmarks.md | 16 ++++ scripts/run-benchmarks.ps1 | 26 +++++-- 6 files changed, 131 insertions(+), 8 deletions(-) create mode 100644 benchmarks/src/main/resources/logback-benchmark.xml create mode 100644 benchmarks/src/test/java/com/demcha/compose/BenchmarkSupportTest.java diff --git a/README.md b/README.md index ae95c0ede..c8e6bcbea 100644 --- a/README.md +++ b/README.md @@ -310,7 +310,7 @@ Full detail: [architecture overview](./docs/architecture/overview.md) · [ - [Which template system?](./docs/templates/which-template-system.md) — the template naming history and the migration map for callers arriving from a pre-2.0 surface (classic presets, built-in `*Template` classes, the legacy PDF API). The retired classic docs are archived at [v1-classic](./docs/templates/v1-classic/README.md). ### Architecture & operations -- [Architecture overview](./docs/architecture/overview.md) · [Lifecycle](./docs/architecture/lifecycle.md) · [Production rendering](./docs/operations/production-rendering.md) · [Layout snapshot testing](./docs/operations/layout-snapshot-testing.md) · [Troubleshooting](./docs/troubleshooting.md) +- [Architecture overview](./docs/architecture/overview.md) · [Lifecycle](./docs/architecture/lifecycle.md) · [Production rendering](./docs/operations/production-rendering.md) · [Benchmarks](./docs/operations/benchmarks.md) · [Layout snapshot testing](./docs/operations/layout-snapshot-testing.md) · [Troubleshooting](./docs/troubleshooting.md) ### Recipes & examples - [Recipes index](./docs/recipes.md) — [shape-as-container](./docs/recipes/shape-as-container.md) · [shapes](./docs/recipes/shapes.md) · [transforms](./docs/recipes/transforms.md) · [page-backgrounds](./docs/recipes/page-backgrounds.md) · [layered-page-design](./docs/recipes/layered-page-design.md) · [absolute-placement](./docs/recipes/absolute-placement.md) · [tables](./docs/recipes/tables.md) · [themes](./docs/recipes/themes.md) · [streaming](./docs/recipes/streaming.md) · [extending](./docs/recipes/extending.md) · [font-coverage](./docs/font-coverage.md) diff --git a/benchmarks/src/main/java/com/demcha/compose/BenchmarkSupport.java b/benchmarks/src/main/java/com/demcha/compose/BenchmarkSupport.java index 989214ff4..4a280a2ba 100644 --- a/benchmarks/src/main/java/com/demcha/compose/BenchmarkSupport.java +++ b/benchmarks/src/main/java/com/demcha/compose/BenchmarkSupport.java @@ -1,9 +1,11 @@ package com.demcha.compose; import java.net.URL; +import java.util.Locale; final class BenchmarkSupport { + private static final String BENCHMARK_LOGGING_PROPERTY = "graphcompose.benchmark.logging"; private static final String LOGBACK_CONFIG_PROPERTY = "logback.configurationFile"; private static final String LOGBACK_STATUS_LISTENER_PROPERTY = "logback.statusListenerClass"; private static final String NOP_STATUS_LISTENER = "ch.qos.logback.core.status.NopStatusListener"; @@ -19,6 +21,10 @@ static void configureQuietLogging() { System.setProperty(LOGBACK_STATUS_LISTENER_PROPERTY, NOP_STATUS_LISTENER); } + if (benchmarkLoggingEnabled()) { + return; + } + if (System.getProperty(LOGBACK_CONFIG_PROPERTY) != null) { return; } @@ -28,4 +34,11 @@ static void configureQuietLogging() { System.setProperty(LOGBACK_CONFIG_PROPERTY, config.toExternalForm()); } } + + private static boolean benchmarkLoggingEnabled() { + String mode = System.getProperty(BENCHMARK_LOGGING_PROPERTY, "quiet") + .trim() + .toLowerCase(Locale.ROOT); + return mode.equals("debug") || mode.equals("verbose") || mode.equals("true") || mode.equals("on"); + } } diff --git a/benchmarks/src/main/resources/logback-benchmark.xml b/benchmarks/src/main/resources/logback-benchmark.xml new file mode 100644 index 000000000..60919a318 --- /dev/null +++ b/benchmarks/src/main/resources/logback-benchmark.xml @@ -0,0 +1,7 @@ + + + + + + + diff --git a/benchmarks/src/test/java/com/demcha/compose/BenchmarkSupportTest.java b/benchmarks/src/test/java/com/demcha/compose/BenchmarkSupportTest.java new file mode 100644 index 000000000..a121a694c --- /dev/null +++ b/benchmarks/src/test/java/com/demcha/compose/BenchmarkSupportTest.java @@ -0,0 +1,75 @@ +package com.demcha.compose; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +class BenchmarkSupportTest { + + private static final String BENCHMARK_LOGGING_PROPERTY = "graphcompose.benchmark.logging"; + private static final String LOGBACK_CONFIG_PROPERTY = "logback.configurationFile"; + private static final String LOGBACK_STATUS_LISTENER_PROPERTY = "logback.statusListenerClass"; + private static final String NOP_STATUS_LISTENER = "ch.qos.logback.core.status.NopStatusListener"; + + private String originalBenchmarkLogging; + private String originalLogbackConfig; + private String originalStatusListener; + + @BeforeEach + void captureProperties() { + originalBenchmarkLogging = System.getProperty(BENCHMARK_LOGGING_PROPERTY); + originalLogbackConfig = System.getProperty(LOGBACK_CONFIG_PROPERTY); + originalStatusListener = System.getProperty(LOGBACK_STATUS_LISTENER_PROPERTY); + + System.clearProperty(BENCHMARK_LOGGING_PROPERTY); + System.clearProperty(LOGBACK_CONFIG_PROPERTY); + System.clearProperty(LOGBACK_STATUS_LISTENER_PROPERTY); + } + + @AfterEach + void restoreProperties() { + restore(BENCHMARK_LOGGING_PROPERTY, originalBenchmarkLogging); + restore(LOGBACK_CONFIG_PROPERTY, originalLogbackConfig); + restore(LOGBACK_STATUS_LISTENER_PROPERTY, originalStatusListener); + } + + @Test + void configuresQuietLogbackByDefault() { + BenchmarkSupport.configureQuietLogging(); + + assertThat(System.getProperty(LOGBACK_CONFIG_PROPERTY)) + .contains("logback-benchmark.xml"); + assertThat(System.getProperty(LOGBACK_STATUS_LISTENER_PROPERTY)) + .isEqualTo(NOP_STATUS_LISTENER); + } + + @Test + void leavesLogbackConfigurationUnsetWhenBenchmarkLoggingIsDebug() { + System.setProperty(BENCHMARK_LOGGING_PROPERTY, "debug"); + + BenchmarkSupport.configureQuietLogging(); + + assertThat(System.getProperty(LOGBACK_CONFIG_PROPERTY)).isNull(); + assertThat(System.getProperty(LOGBACK_STATUS_LISTENER_PROPERTY)) + .isEqualTo(NOP_STATUS_LISTENER); + } + + @Test + void leavesLogbackConfigurationUnsetWhenBenchmarkLoggingIsTrue() { + System.setProperty(BENCHMARK_LOGGING_PROPERTY, "true"); + + BenchmarkSupport.configureQuietLogging(); + + assertThat(System.getProperty(LOGBACK_CONFIG_PROPERTY)).isNull(); + } + + private static void restore(String name, String value) { + if (value == null) { + System.clearProperty(name); + } else { + System.setProperty(name, value); + } + } +} diff --git a/docs/operations/benchmarks.md b/docs/operations/benchmarks.md index 1c6bd6d75..20e183677 100644 --- a/docs/operations/benchmarks.md +++ b/docs/operations/benchmarks.md @@ -105,6 +105,22 @@ powershell -ExecutionPolicy Bypass -File .\scripts\run-benchmarks.ps1 -CurrentSp powershell -ExecutionPolicy Bypass -File .\scripts\run-benchmarks.ps1 -CurrentSpeedProfile full ``` +### Benchmark logging + +Benchmark runs are quiet by default so GraphCompose, PDFBox, and FontBox +DEBUG lifecycle logs do not dominate the step logs or console mirror. +When debugging benchmark internals, opt into those logs explicitly: + +```powershell +powershell -ExecutionPolicy Bypass -File .\scripts\run-benchmarks.ps1 -CurrentSpeedProfile smoke -EnableBenchmarkLogs +``` + +Direct Java entry points accept the same switch as a JVM property: + +```powershell +java -Dgraphcompose.benchmark.logging=debug -cp "benchmarks\target\test-classes;benchmarks\target\classes;$cp" com.demcha.compose.CurrentSpeedBenchmark +``` + ## Diff selection rules ### Current-speed diffs diff --git a/scripts/run-benchmarks.ps1 b/scripts/run-benchmarks.ps1 index a0dd2c777..734f887e6 100644 --- a/scripts/run-benchmarks.ps1 +++ b/scripts/run-benchmarks.ps1 @@ -21,12 +21,16 @@ Step 11 (`11-verdict-current-speed`) compares the current-speed result against the committed baseline (`baselines/current-speed-.json`) and fails the run when a canonical scenario regresses beyond the noise band. Use `-SkipVerdict` to skip that gate while exploring. See `docs/operations/perf-change-workflow.md`. + +Benchmark logging is quiet by default. Use `-EnableBenchmarkLogs` when debugging +GraphCompose/PDFBox lifecycle logs during a benchmark run. #> param( [switch]$IncludeEndurance, [switch]$OpenResults, [switch]$SkipDiff, [switch]$SkipVerdict, + [switch]$EnableBenchmarkLogs, [ValidateSet("full", "smoke")] [string]$CurrentSpeedProfile = "full", [ValidateRange(1, 10)] @@ -254,6 +258,7 @@ function Invoke-MedianAggregation { [string]$SuiteName, [string]$AggregateSuiteName, [string]$Classpath, + [string[]]$SystemProperties = @(), [string[]]$InputPaths ) @@ -263,7 +268,7 @@ function Invoke-MedianAggregation { $beforeRuns = @(Get-RunFiles -SuiteName $AggregateSuiteName) $arguments = @($SuiteName) + $InputPaths - Invoke-JavaMain -Name $Name -Classpath $Classpath -MainClass "com.demcha.compose.BenchmarkMedianTool" -Arguments $arguments | Out-Null + Invoke-JavaMain -Name $Name -Classpath $Classpath -MainClass "com.demcha.compose.BenchmarkMedianTool" -SystemProperties $SystemProperties -Arguments $arguments | Out-Null $afterRuns = @(Get-RunFiles -SuiteName $AggregateSuiteName) $newRuns = @($afterRuns | Where-Object { $_ -notin $beforeRuns }) @@ -287,6 +292,9 @@ function Get-IfExists { return $null } +$benchmarkLoggingMode = if ($EnableBenchmarkLogs) { "debug" } else { "quiet" } +$benchmarkLoggingProperties = @("-Dgraphcompose.benchmark.logging=$benchmarkLoggingMode") + Add-Content -Path $summaryPath -Value @( "# Benchmark Run", "", @@ -295,6 +303,7 @@ Add-Content -Path $summaryPath -Value @( ("- Include endurance: ``{0}``" -f $IncludeEndurance), ("- Skip diff: ``{0}``" -f $SkipDiff), ("- Current speed profile: ``{0}``" -f $CurrentSpeedProfile), + ("- Benchmark logging: ``{0}``" -f $benchmarkLoggingMode), ("- Repeat current-speed/comparative: ``{0}``" -f $Repeat), ("- Logs folder: ``{0}``" -f $logRoot), "" @@ -322,7 +331,7 @@ try { $dependencyClasspath = (Get-Content $resolvedClasspathFile -Raw).Trim() $javaClasspath = "benchmarks\target\test-classes;benchmarks\target\classes;$dependencyClasspath" - $currentSpeedProperties = @() + $currentSpeedProperties = @() + $benchmarkLoggingProperties $currentSpeedProperties += "-Dgraphcompose.benchmark.profile=$CurrentSpeedProfile" if ($Warmup -gt 0) { $currentSpeedProperties += "-Dgraphcompose.benchmark.warmup=$Warmup" @@ -351,6 +360,7 @@ try { -SuiteName "current-speed" ` -AggregateSuiteName $currentSpeedAggregateSuite ` -Classpath $javaClasspath ` + -SystemProperties $benchmarkLoggingProperties ` -InputPaths $currentSpeedRuns | Out-Null } @@ -359,6 +369,7 @@ try { -SuiteName "comparative" ` -Classpath $javaClasspath ` -MainClass "com.demcha.compose.ComparativeBenchmark" ` + -SystemProperties $benchmarkLoggingProperties ` -RepeatCount $Repeat $comparativeAggregateSuite = "aggregates/comparative" if ($Repeat -gt 1) { @@ -367,13 +378,14 @@ try { -SuiteName "comparative" ` -AggregateSuiteName $comparativeAggregateSuite ` -Classpath $javaClasspath ` + -SystemProperties $benchmarkLoggingProperties ` -InputPaths $comparativeRuns | Out-Null } - Invoke-JavaMain -Name "07-stress" -Classpath $javaClasspath -MainClass "com.demcha.compose.GraphComposeStressTest" + Invoke-JavaMain -Name "07-stress" -Classpath $javaClasspath -MainClass "com.demcha.compose.GraphComposeStressTest" -SystemProperties $benchmarkLoggingProperties if ($IncludeEndurance) { - Invoke-JavaMain -Name "08-endurance" -Classpath $javaClasspath -MainClass "com.demcha.compose.EnduranceTest" -JavaOptions @("-Xmx$EnduranceHeap") + Invoke-JavaMain -Name "08-endurance" -Classpath $javaClasspath -MainClass "com.demcha.compose.EnduranceTest" -SystemProperties $benchmarkLoggingProperties -JavaOptions @("-Xmx$EnduranceHeap") } else { Add-SummaryLine("- ``08-endurance``: skipped") Add-SummaryLine(" - Reason: use ``-IncludeEndurance`` to enable the 100,000 document soak run") @@ -390,7 +402,7 @@ try { if ($null -ne $currentSpeedDiffPair) { $currentSpeedDiffName = if ($Repeat -gt 1) { "09-diff-current-speed-median" } else { "09-diff-current-speed" } - Invoke-JavaMain -Name $currentSpeedDiffName -Classpath $javaClasspath -MainClass "com.demcha.compose.BenchmarkDiffTool" -Arguments $currentSpeedDiffPair + Invoke-JavaMain -Name $currentSpeedDiffName -Classpath $javaClasspath -MainClass "com.demcha.compose.BenchmarkDiffTool" -SystemProperties $benchmarkLoggingProperties -Arguments $currentSpeedDiffPair } else { Add-SummaryLine("- ``09-diff-current-speed``: skipped") if ($Repeat -gt 1) { @@ -408,7 +420,7 @@ try { if ($null -ne $comparativeDiffPair) { $comparativeDiffName = if ($Repeat -gt 1) { "10-diff-comparative-median" } else { "10-diff-comparative" } - Invoke-JavaMain -Name $comparativeDiffName -Classpath $javaClasspath -MainClass "com.demcha.compose.BenchmarkDiffTool" -Arguments $comparativeDiffPair + Invoke-JavaMain -Name $comparativeDiffName -Classpath $javaClasspath -MainClass "com.demcha.compose.BenchmarkDiffTool" -SystemProperties $benchmarkLoggingProperties -Arguments $comparativeDiffPair } else { Add-SummaryLine("- ``10-diff-comparative``: skipped") if ($Repeat -gt 1) { @@ -475,7 +487,7 @@ try { # average latency; peakHeapMb is advisory inside the tool. When the # gate is on, BenchmarkVerdictTool exits non-zero on a regression, # which makes Invoke-LoggedCommand throw and fail the whole run. - $verdictProperties = @() + $verdictProperties = @() + $benchmarkLoggingProperties if ($Repeat -le 1) { $verdictProperties += "-Dgraphcompose.benchmark.verdict.gate=false" Add-SummaryLine("- ``11-verdict-current-speed``: advisory (single run; use -Repeat 5 for the hard gate)")