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)")