Merge pull request #343 from bnema/perf/startup-first-presentation
perf(startup): trace first GTK presentation
19 files · +1208 -184
M cmd/dumber/main.go +6 -1
| @@ -141,6 +141,11 @@ func configureBrowserLaunchRelay(cfg *config.Config) { | |||
| 141 | 141 | } | |
| 142 | 142 | ||
| 143 | 143 | func main() { | |
| 144 | + | // This is intentionally before subprocess detection: each process records | |
| 145 | + | // its own first observable main event before CEF can take over execution. | |
| 146 | + | logging.InitStartupTrace("") | |
| 147 | + | logging.Trace().Mark("process_entry") | |
| 148 | + | ||
| 144 | 149 | // CEF subprocess handling: when CEF re-launches this binary with | |
| 145 | 150 | // --type=renderer/gpu/etc, we must call ExecuteProcess before anything | |
| 146 | 151 | // else (Cobra, config, arg stripping). We only treat a leading Chromium | |
| @@ -218,6 +223,7 @@ func runGUI(cfg *config.Config) int { | |||
| 218 | 223 | cfg = initConfig() | |
| 219 | 224 | configureBrowserLaunchRelay(cfg) | |
| 220 | 225 | } | |
| 226 | + | logging.Trace().Mark("config_complete") | |
| 221 | 227 | timer.Mark("config") | |
| 222 | 228 | ||
| 223 | 229 | ctx := initStartupContextWithTrace(cfg) | |
| @@ -414,7 +420,6 @@ func resolveCurrentExecutable(executable func() (string, error)) (string, error) | |||
| 414 | 420 | ||
| 415 | 421 | func initStartupContextWithTrace(cfg *config.Config) context.Context { | |
| 416 | 422 | logging.InitStartupTrace(cfg.Logging.Level) | |
| 417 | - | logging.Trace().Mark("config_loaded") | |
| 418 | 423 | ||
| 419 | 424 | ctx := initStartupContext(cfg) | |
| 420 | 425 | bootstrapLog := logging.FromContext(ctx) | |
| @@ -141,6 +141,11 @@ func configureBrowserLaunchRelay(cfg *config.Config) { | |||||
| 141 | } | 141 | } | ||
| 142 | 142 | ||||
| 143 | func main() { | 143 | func main() { | ||
| 144 | + | // This is intentionally before subprocess detection: each process records | |||
| 145 | + | // its own first observable main event before CEF can take over execution. | |||
| 146 | + | logging.InitStartupTrace("") | |||
| 147 | + | logging.Trace().Mark("process_entry") | |||
| 148 | + | ||||
| 144 | // CEF subprocess handling: when CEF re-launches this binary with | 149 | // CEF subprocess handling: when CEF re-launches this binary with | ||
| 145 | // --type=renderer/gpu/etc, we must call ExecuteProcess before anything | 150 | // --type=renderer/gpu/etc, we must call ExecuteProcess before anything | ||
| 146 | // else (Cobra, config, arg stripping). We only treat a leading Chromium | 151 | // else (Cobra, config, arg stripping). We only treat a leading Chromium | ||
| @@ -218,6 +223,7 @@ func runGUI(cfg *config.Config) int { | |||||
| 218 | cfg = initConfig() | 223 | cfg = initConfig() | ||
| 219 | configureBrowserLaunchRelay(cfg) | 224 | configureBrowserLaunchRelay(cfg) | ||
| 220 | } | 225 | } | ||
| 226 | + | logging.Trace().Mark("config_complete") | |||
| 221 | timer.Mark("config") | 227 | timer.Mark("config") | ||
| 222 | 228 | ||||
| 223 | ctx := initStartupContextWithTrace(cfg) | 229 | ctx := initStartupContextWithTrace(cfg) | ||
| @@ -414,7 +420,6 @@ func resolveCurrentExecutable(executable func() (string, error)) (string, error) | |||||
| 414 | 420 | ||||
| 415 | func initStartupContextWithTrace(cfg *config.Config) context.Context { | 421 | func initStartupContextWithTrace(cfg *config.Config) context.Context { | ||
| 416 | logging.InitStartupTrace(cfg.Logging.Level) | 422 | logging.InitStartupTrace(cfg.Logging.Level) | ||
| 417 | - | logging.Trace().Mark("config_loaded") | |||
| 418 | 423 | ||||
| 419 | ctx := initStartupContext(cfg) | 424 | ctx := initStartupContext(cfg) | ||
| 420 | bootstrapLog := logging.FromContext(ctx) | 425 | bootstrapLog := logging.FromContext(ctx) | ||
A docs/first-presentation.md +50 -0
| @@ -0,0 +1,50 @@ | |||
| 1 | + | # First presentation startup trace | |
| 2 | + | ||
| 3 | + | Dumber records one cold-start timeline for each GUI process. The trace begins | |
| 4 | + | at `process_entry`, before CEF subprocess handling, and accepts these one-shot | |
| 5 | + | milestones only in order: | |
| 6 | + | ||
| 7 | + | 1. `process_entry` | |
| 8 | + | 2. `config_complete` | |
| 9 | + | 3. `cef_library_load_begin` (immediately before `InitWithApp`) | |
| 10 | + | 4. `cef_initialized` | |
| 11 | + | 5. `browser_create_requested` | |
| 12 | + | 6. `first_accelerated_paint_received` | |
| 13 | + | 7. `first_dmabuf_texture_swap` (after `GtkPicture.SetPaintable` succeeds) | |
| 14 | + | 8. `first_gtk_presentation` (the subsequent GTK frame-clock after-paint) | |
| 15 | + | ||
| 16 | + | CEF library-load completion is intentionally not recorded: `InitWithApp` is an | |
| 17 | + | opaque operation. Duplicate, unknown, and out-of-order transitions are | |
| 18 | + | rejected. At the last milestone Dumber emits exactly one normal-level JSON | |
| 19 | + | summary (`startup_trace: first presentation`) with the selected `backend`, an | |
| 20 | + | `incomplete_reason`, total milliseconds, and monotonic milestones. | |
| 21 | + | ||
| 22 | + | ## Reproducible collection | |
| 23 | + | ||
| 24 | + | Build the candidate, then run: | |
| 25 | + | ||
| 26 | + | ```bash | |
| 27 | + | DUMBER_FIRST_PRESENTATION_BIN="$PWD/dist/dumber" \ | |
| 28 | + | DUMBER_MACHINE_GPU_PROFILE=integrated-gpu \ | |
| 29 | + | scripts/collect_first_presentation.sh | |
| 30 | + | ``` | |
| 31 | + | ||
| 32 | + | By default each collection is a fresh directory below | |
| 33 | + | `$XDG_STATE_HOME/dumber/roadmap-evidence` (or | |
| 34 | + | `$HOME/.local/state/dumber/roadmap-evidence` when `XDG_STATE_HOME` is unset), | |
| 35 | + | not in the repository. `DUMBER_FIRST_PRESENTATION_OUTPUT` may override it only | |
| 36 | + | with a new absolute directory below an existing non-symlink parent. The | |
| 37 | + | collector never clears or reuses a caller-supplied path. | |
| 38 | + | ||
| 39 | + | The script requires the current display and the CEF 147 runtime at | |
| 40 | + | `~/.local/share/cef-147-runtime` (override with `DUMBER_CEF_DIR`). It performs | |
| 41 | + | exactly five bounded launches with fresh XDG homes and CEF root cache, fixes the | |
| 42 | + | DMABUF/Vulkan renderer, and writes exactly `metadata.json`, `run-01.json` | |
| 43 | + | through `run-05.json`, and `baseline.json`. Metadata includes only coarse, | |
| 44 | + | comparison-safe OS/architecture, display protocol, and machine/GPU profile | |
| 45 | + | labels. Set `DUMBER_MACHINE_GPU_PROFILE` to one of `generic-gpu`, | |
| 46 | + | `integrated-gpu`, `discrete-gpu`, `hybrid-gpu`, `virtual-gpu`, or `unknown-gpu`; | |
| 47 | + | do not use a device model or other identifier. Publish only the seven reviewed | |
| 48 | + | JSON files to an external Gist. Raw logs and temporary XDG homes are removed and | |
| 49 | + | must not be published. A missing or incomplete timeline, non-DMABUF backend, or | |
| 50 | + | invalid run fails collection. | |
| @@ -0,0 +1,50 @@ | |||||
| 1 | + | # First presentation startup trace | |||
| 2 | + | ||||
| 3 | + | Dumber records one cold-start timeline for each GUI process. The trace begins | |||
| 4 | + | at `process_entry`, before CEF subprocess handling, and accepts these one-shot | |||
| 5 | + | milestones only in order: | |||
| 6 | + | ||||
| 7 | + | 1. `process_entry` | |||
| 8 | + | 2. `config_complete` | |||
| 9 | + | 3. `cef_library_load_begin` (immediately before `InitWithApp`) | |||
| 10 | + | 4. `cef_initialized` | |||
| 11 | + | 5. `browser_create_requested` | |||
| 12 | + | 6. `first_accelerated_paint_received` | |||
| 13 | + | 7. `first_dmabuf_texture_swap` (after `GtkPicture.SetPaintable` succeeds) | |||
| 14 | + | 8. `first_gtk_presentation` (the subsequent GTK frame-clock after-paint) | |||
| 15 | + | ||||
| 16 | + | CEF library-load completion is intentionally not recorded: `InitWithApp` is an | |||
| 17 | + | opaque operation. Duplicate, unknown, and out-of-order transitions are | |||
| 18 | + | rejected. At the last milestone Dumber emits exactly one normal-level JSON | |||
| 19 | + | summary (`startup_trace: first presentation`) with the selected `backend`, an | |||
| 20 | + | `incomplete_reason`, total milliseconds, and monotonic milestones. | |||
| 21 | + | ||||
| 22 | + | ## Reproducible collection | |||
| 23 | + | ||||
| 24 | + | Build the candidate, then run: | |||
| 25 | + | ||||
| 26 | + | ```bash | |||
| 27 | + | DUMBER_FIRST_PRESENTATION_BIN="$PWD/dist/dumber" \ | |||
| 28 | + | DUMBER_MACHINE_GPU_PROFILE=integrated-gpu \ | |||
| 29 | + | scripts/collect_first_presentation.sh | |||
| 30 | + | ``` | |||
| 31 | + | ||||
| 32 | + | By default each collection is a fresh directory below | |||
| 33 | + | `$XDG_STATE_HOME/dumber/roadmap-evidence` (or | |||
| 34 | + | `$HOME/.local/state/dumber/roadmap-evidence` when `XDG_STATE_HOME` is unset), | |||
| 35 | + | not in the repository. `DUMBER_FIRST_PRESENTATION_OUTPUT` may override it only | |||
| 36 | + | with a new absolute directory below an existing non-symlink parent. The | |||
| 37 | + | collector never clears or reuses a caller-supplied path. | |||
| 38 | + | ||||
| 39 | + | The script requires the current display and the CEF 147 runtime at | |||
| 40 | + | `~/.local/share/cef-147-runtime` (override with `DUMBER_CEF_DIR`). It performs | |||
| 41 | + | exactly five bounded launches with fresh XDG homes and CEF root cache, fixes the | |||
| 42 | + | DMABUF/Vulkan renderer, and writes exactly `metadata.json`, `run-01.json` | |||
| 43 | + | through `run-05.json`, and `baseline.json`. Metadata includes only coarse, | |||
| 44 | + | comparison-safe OS/architecture, display protocol, and machine/GPU profile | |||
| 45 | + | labels. Set `DUMBER_MACHINE_GPU_PROFILE` to one of `generic-gpu`, | |||
| 46 | + | `integrated-gpu`, `discrete-gpu`, `hybrid-gpu`, `virtual-gpu`, or `unknown-gpu`; | |||
| 47 | + | do not use a device model or other identifier. Publish only the seven reviewed | |||
| 48 | + | JSON files to an external Gist. Raw logs and temporary XDG homes are removed and | |||
| 49 | + | must not be published. A missing or incomplete timeline, non-DMABUF backend, or | |||
| 50 | + | invalid run fails collection. | |||
M go.mod +1 -1
| @@ -7,7 +7,7 @@ require ( | |||
| 7 | 7 | github.com/andybalholm/brotli v1.2.2 | |
| 8 | 8 | github.com/bnema/purego v0.11.0-bnema.4 | |
| 9 | 9 | github.com/bnema/purego-cef v0.13.3 | |
| 10 | - | github.com/bnema/purego-cef2gtk v0.8.2 | |
| 10 | + | github.com/bnema/purego-cef2gtk v0.8.4 | |
| 11 | 11 | github.com/bnema/purego-pipewire v0.1.4 | |
| 12 | 12 | github.com/bnema/purego-sqlite v0.1.3 | |
| 13 | 13 | github.com/bnema/puregotk v0.7.0 | |
| @@ -7,7 +7,7 @@ require ( | |||||
| 7 | github.com/andybalholm/brotli v1.2.2 | 7 | github.com/andybalholm/brotli v1.2.2 | ||
| 8 | github.com/bnema/purego v0.11.0-bnema.4 | 8 | github.com/bnema/purego v0.11.0-bnema.4 | ||
| 9 | github.com/bnema/purego-cef v0.13.3 | 9 | github.com/bnema/purego-cef v0.13.3 | ||
| 10 | - | github.com/bnema/purego-cef2gtk v0.8.2 | 10 | + | github.com/bnema/purego-cef2gtk v0.8.4 |
| 11 | github.com/bnema/purego-pipewire v0.1.4 | 11 | github.com/bnema/purego-pipewire v0.1.4 | ||
| 12 | github.com/bnema/purego-sqlite v0.1.3 | 12 | github.com/bnema/purego-sqlite v0.1.3 | ||
| 13 | github.com/bnema/puregotk v0.7.0 | 13 | github.com/bnema/puregotk v0.7.0 | ||
M go.sum +8 -0 generated file: collapsed
M internal/infrastructure/cef/engine_init.go +24 -3
| @@ -56,6 +56,7 @@ func NewEngine( | |||
| 56 | 56 | return nil, err | |
| 57 | 57 | } | |
| 58 | 58 | cef2gtk.ConfigureRenderStackEnvironment(renderStackPlan) | |
| 59 | + | logging.Trace().SetBackend(renderStackPlan.Backend.String()) | |
| 59 | 60 | ||
| 60 | 61 | settings, err := prepareCEFSettings(opts, paths, cfg, logger) | |
| 61 | 62 | if err != nil { | |
| @@ -146,6 +147,24 @@ func resolvedStateRoot(defaultStateRoot string, opts port.EngineOptions) string | |||
| 146 | 147 | return defaultStateRoot | |
| 147 | 148 | } | |
| 148 | 149 | ||
| 150 | + | // configureCEFSubprocessRuntime chooses the CEF runtime used by both the | |
| 151 | + | // browser and CEF helper processes. CEF re-execs this binary for helpers before | |
| 152 | + | // Dumber can load configuration, so the selected configured runtime must be in | |
| 153 | + | // its inherited environment before InitWithApp launches any child. A caller's | |
| 154 | + | // explicit CEF_DIR remains the override for both process types. | |
| 155 | + | func configureCEFSubprocessRuntime(configured string) string { | |
| 156 | + | if explicit := os.Getenv("CEF_DIR"); explicit != "" { | |
| 157 | + | return explicit | |
| 158 | + | } | |
| 159 | + | if configured == "" { | |
| 160 | + | return "" | |
| 161 | + | } | |
| 162 | + | if err := os.Setenv("CEF_DIR", configured); err != nil { | |
| 163 | + | return configured | |
| 164 | + | } | |
| 165 | + | return configured | |
| 166 | + | } | |
| 167 | + | ||
| 149 | 168 | // prepareCEFSettings builds purecef.Settings from the engine config. | |
| 150 | 169 | func prepareCEFSettings( | |
| 151 | 170 | opts port.EngineOptions, | |
| @@ -169,9 +188,7 @@ func prepareCEFSettings( | |||
| 169 | 188 | settings.MultiThreadedMessageLoop = true | |
| 170 | 189 | settings.ExternalMessagePump = false | |
| 171 | 190 | settings.RootCachePath = resolvedStateRoot(paths.StateRoot, opts) | |
| 172 | - | if cfg.CEFDir != "" { | |
| 173 | - | settings.CEFDir = cfg.CEFDir | |
| 174 | - | } | |
| 191 | + | settings.CEFDir = configureCEFSubprocessRuntime(cfg.CEFDir) | |
| 175 | 192 | if runtimeLogFile, err := prepareCEFLogFile(paths.LogFile, cfg.LogFile); err != nil { | |
| 176 | 193 | logger.Warn().Err(err).Msg("cef: failed to prepare runtime log file") | |
| 177 | 194 | } else { | |
| @@ -199,9 +216,13 @@ func initializeCEF(eng *Engine, settings purecef.Settings, logger *zerolog.Logge | |||
| 199 | 216 | Str("env_cef_dir", os.Getenv("CEF_DIR")). | |
| 200 | 217 | Msg("cef: runtime selection") | |
| 201 | 218 | logger.Debug().Msg("cef: calling InitWithApp") | |
| 219 | + | // InitWithApp encapsulates loading libcef, so only the begin boundary is | |
| 220 | + | // observable here; do not invent a separate library-load completion event. | |
| 221 | + | logging.Trace().Mark("cef_library_load_begin") | |
| 202 | 222 | if err := purecef.InitWithApp(settings, app); err != nil { | |
| 203 | 223 | return fmt.Errorf("cef.InitWithApp: %w", err) | |
| 204 | 224 | } | |
| 225 | + | logging.Trace().Mark("cef_initialized") | |
| 205 | 226 | if libcefPath := loadedLibCEFPath(); libcefPath != "" { | |
| 206 | 227 | logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded") | |
| 207 | 228 | } else { | |
| @@ -56,6 +56,7 @@ func NewEngine( | |||||
| 56 | return nil, err | 56 | return nil, err | ||
| 57 | } | 57 | } | ||
| 58 | cef2gtk.ConfigureRenderStackEnvironment(renderStackPlan) | 58 | cef2gtk.ConfigureRenderStackEnvironment(renderStackPlan) | ||
| 59 | + | logging.Trace().SetBackend(renderStackPlan.Backend.String()) | |||
| 59 | 60 | ||||
| 60 | settings, err := prepareCEFSettings(opts, paths, cfg, logger) | 61 | settings, err := prepareCEFSettings(opts, paths, cfg, logger) | ||
| 61 | if err != nil { | 62 | if err != nil { | ||
| @@ -146,6 +147,24 @@ func resolvedStateRoot(defaultStateRoot string, opts port.EngineOptions) string | |||||
| 146 | return defaultStateRoot | 147 | return defaultStateRoot | ||
| 147 | } | 148 | } | ||
| 148 | 149 | ||||
| 150 | + | // configureCEFSubprocessRuntime chooses the CEF runtime used by both the | |||
| 151 | + | // browser and CEF helper processes. CEF re-execs this binary for helpers before | |||
| 152 | + | // Dumber can load configuration, so the selected configured runtime must be in | |||
| 153 | + | // its inherited environment before InitWithApp launches any child. A caller's | |||
| 154 | + | // explicit CEF_DIR remains the override for both process types. | |||
| 155 | + | func configureCEFSubprocessRuntime(configured string) string { | |||
| 156 | + | if explicit := os.Getenv("CEF_DIR"); explicit != "" { | |||
| 157 | + | return explicit | |||
| 158 | + | } | |||
| 159 | + | if configured == "" { | |||
| 160 | + | return "" | |||
| 161 | + | } | |||
| 162 | + | if err := os.Setenv("CEF_DIR", configured); err != nil { | |||
| 163 | + | return configured | |||
| 164 | + | } | |||
| 165 | + | return configured | |||
| 166 | + | } | |||
| 167 | + | ||||
| 149 | // prepareCEFSettings builds purecef.Settings from the engine config. | 168 | // prepareCEFSettings builds purecef.Settings from the engine config. | ||
| 150 | func prepareCEFSettings( | 169 | func prepareCEFSettings( | ||
| 151 | opts port.EngineOptions, | 170 | opts port.EngineOptions, | ||
| @@ -169,9 +188,7 @@ func prepareCEFSettings( | |||||
| 169 | settings.MultiThreadedMessageLoop = true | 188 | settings.MultiThreadedMessageLoop = true | ||
| 170 | settings.ExternalMessagePump = false | 189 | settings.ExternalMessagePump = false | ||
| 171 | settings.RootCachePath = resolvedStateRoot(paths.StateRoot, opts) | 190 | settings.RootCachePath = resolvedStateRoot(paths.StateRoot, opts) | ||
| 172 | - | if cfg.CEFDir != "" { | 191 | + | settings.CEFDir = configureCEFSubprocessRuntime(cfg.CEFDir) |
| 173 | - | settings.CEFDir = cfg.CEFDir | |||
| 174 | - | } | |||
| 175 | if runtimeLogFile, err := prepareCEFLogFile(paths.LogFile, cfg.LogFile); err != nil { | 192 | if runtimeLogFile, err := prepareCEFLogFile(paths.LogFile, cfg.LogFile); err != nil { | ||
| 176 | logger.Warn().Err(err).Msg("cef: failed to prepare runtime log file") | 193 | logger.Warn().Err(err).Msg("cef: failed to prepare runtime log file") | ||
| 177 | } else { | 194 | } else { | ||
| @@ -199,9 +216,13 @@ func initializeCEF(eng *Engine, settings purecef.Settings, logger *zerolog.Logge | |||||
| 199 | Str("env_cef_dir", os.Getenv("CEF_DIR")). | 216 | Str("env_cef_dir", os.Getenv("CEF_DIR")). | ||
| 200 | Msg("cef: runtime selection") | 217 | Msg("cef: runtime selection") | ||
| 201 | logger.Debug().Msg("cef: calling InitWithApp") | 218 | logger.Debug().Msg("cef: calling InitWithApp") | ||
| 219 | + | // InitWithApp encapsulates loading libcef, so only the begin boundary is | |||
| 220 | + | // observable here; do not invent a separate library-load completion event. | |||
| 221 | + | logging.Trace().Mark("cef_library_load_begin") | |||
| 202 | if err := purecef.InitWithApp(settings, app); err != nil { | 222 | if err := purecef.InitWithApp(settings, app); err != nil { | ||
| 203 | return fmt.Errorf("cef.InitWithApp: %w", err) | 223 | return fmt.Errorf("cef.InitWithApp: %w", err) | ||
| 204 | } | 224 | } | ||
| 225 | + | logging.Trace().Mark("cef_initialized") | |||
| 205 | if libcefPath := loadedLibCEFPath(); libcefPath != "" { | 226 | if libcefPath := loadedLibCEFPath(); libcefPath != "" { | ||
| 206 | logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded") | 227 | logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded") | ||
| 207 | } else { | 228 | } else { | ||
M internal/infrastructure/cef/engine_init_test.go +16 -0
| @@ -36,6 +36,22 @@ func TestResolvedStateRoot_UsesProfileDefault(t *testing.T) { | |||
| 36 | 36 | require.Equal(t, profile.CEFUserDataDir(), root) | |
| 37 | 37 | } | |
| 38 | 38 | ||
| 39 | + | func TestConfigureCEFSubprocessRuntime_PropagatesConfiguredRuntimeBeforeInit(t *testing.T) { | |
| 40 | + | t.Setenv("CEF_DIR", "") | |
| 41 | + | ||
| 42 | + | runtime := filepath.Join(t.TempDir(), "cef-147") | |
| 43 | + | require.Equal(t, runtime, configureCEFSubprocessRuntime(runtime)) | |
| 44 | + | require.Equal(t, runtime, os.Getenv("CEF_DIR")) | |
| 45 | + | } | |
| 46 | + | ||
| 47 | + | func TestConfigureCEFSubprocessRuntime_PreservesExplicitEnvironmentOverride(t *testing.T) { | |
| 48 | + | explicitRuntime := filepath.Join(t.TempDir(), "cef-env") | |
| 49 | + | t.Setenv("CEF_DIR", explicitRuntime) | |
| 50 | + | ||
| 51 | + | require.Equal(t, explicitRuntime, configureCEFSubprocessRuntime(filepath.Join(t.TempDir(), "cef-config"))) | |
| 52 | + | require.Equal(t, explicitRuntime, os.Getenv("CEF_DIR")) | |
| 53 | + | } | |
| 54 | + | ||
| 39 | 55 | func TestPrepareCEFSettings_UsesResolvedProfilePaths(t *testing.T) { | |
| 40 | 56 | logger := zerolog.Nop() | |
| 41 | 57 | profile := testCEFDevProfile(t) | |
| @@ -36,6 +36,22 @@ func TestResolvedStateRoot_UsesProfileDefault(t *testing.T) { | |||||
| 36 | require.Equal(t, profile.CEFUserDataDir(), root) | 36 | require.Equal(t, profile.CEFUserDataDir(), root) | ||
| 37 | } | 37 | } | ||
| 38 | 38 | ||||
| 39 | + | func TestConfigureCEFSubprocessRuntime_PropagatesConfiguredRuntimeBeforeInit(t *testing.T) { | |||
| 40 | + | t.Setenv("CEF_DIR", "") | |||
| 41 | + | ||||
| 42 | + | runtime := filepath.Join(t.TempDir(), "cef-147") | |||
| 43 | + | require.Equal(t, runtime, configureCEFSubprocessRuntime(runtime)) | |||
| 44 | + | require.Equal(t, runtime, os.Getenv("CEF_DIR")) | |||
| 45 | + | } | |||
| 46 | + | ||||
| 47 | + | func TestConfigureCEFSubprocessRuntime_PreservesExplicitEnvironmentOverride(t *testing.T) { | |||
| 48 | + | explicitRuntime := filepath.Join(t.TempDir(), "cef-env") | |||
| 49 | + | t.Setenv("CEF_DIR", explicitRuntime) | |||
| 50 | + | ||||
| 51 | + | require.Equal(t, explicitRuntime, configureCEFSubprocessRuntime(filepath.Join(t.TempDir(), "cef-config"))) | |||
| 52 | + | require.Equal(t, explicitRuntime, os.Getenv("CEF_DIR")) | |||
| 53 | + | } | |||
| 54 | + | ||||
| 39 | func TestPrepareCEFSettings_UsesResolvedProfilePaths(t *testing.T) { | 55 | func TestPrepareCEFSettings_UsesResolvedProfilePaths(t *testing.T) { | ||
| 40 | logger := zerolog.Nop() | 56 | logger := zerolog.Nop() | ||
| 41 | profile := testCEFDevProfile(t) | 57 | profile := testCEFDevProfile(t) | ||
M internal/infrastructure/cef/factory.go +2 -0
| @@ -278,6 +278,8 @@ func (f *WebViewFactory) postPendingBrowserCreate(ctx context.Context, wv *WebVi | |||
| 278 | 278 | // renderer without an initial paint. We replay pending navigation from | |
| 279 | 279 | // OnAfterCreated once the host is fully wired. | |
| 280 | 280 | initialURL := "about:blank" | |
| 281 | + | // This is the request boundary, not the later OnAfterCreated callback. | |
| 282 | + | logging.Trace().Mark("browser_create_requested") | |
| 281 | 283 | result := cefBrowserHostCreateBrowser( | |
| 282 | 284 | pc.windowInfo, | |
| 283 | 285 | pc.client, | |
| @@ -278,6 +278,8 @@ func (f *WebViewFactory) postPendingBrowserCreate(ctx context.Context, wv *WebVi | |||||
| 278 | // renderer without an initial paint. We replay pending navigation from | 278 | // renderer without an initial paint. We replay pending navigation from | ||
| 279 | // OnAfterCreated once the host is fully wired. | 279 | // OnAfterCreated once the host is fully wired. | ||
| 280 | initialURL := "about:blank" | 280 | initialURL := "about:blank" | ||
| 281 | + | // This is the request boundary, not the later OnAfterCreated callback. | |||
| 282 | + | logging.Trace().Mark("browser_create_requested") | |||
| 281 | result := cefBrowserHostCreateBrowser( | 283 | result := cefBrowserHostCreateBrowser( | ||
| 282 | pc.windowInfo, | 284 | pc.windowInfo, | ||
| 283 | pc.client, | 285 | pc.client, | ||
M internal/infrastructure/cef/render_handler_adapter.go +35 -15
| @@ -23,6 +23,26 @@ type dumberRenderHandler struct { | |||
| 23 | 23 | ||
| 24 | 24 | var _ purecef.RenderHandler = (*dumberRenderHandler)(nil) | |
| 25 | 25 | ||
| 26 | + | // startupPresentationHooks consumes the one-shot facts emitted by | |
| 27 | + | // purego-cef2gtk. The bridge owns the native DMABUF and frame-clock boundaries; | |
| 28 | + | // Dumber only records their ordered application-level timeline. | |
| 29 | + | func startupPresentationHooks() cef2gtk.Hooks { | |
| 30 | + | return cef2gtk.Hooks{ | |
| 31 | + | OnFirstAcceleratedPaint: func() { | |
| 32 | + | logging.Trace().Mark("first_accelerated_paint_received") | |
| 33 | + | }, | |
| 34 | + | OnFirstDMABUFTextureSwap: func() { | |
| 35 | + | logging.Trace().Mark("first_dmabuf_texture_swap") | |
| 36 | + | }, | |
| 37 | + | OnFirstPresentation: func() { | |
| 38 | + | logging.Trace().MarkGTKAfterPaint() | |
| 39 | + | }, | |
| 40 | + | OnDMABUFUnsupported: func() { | |
| 41 | + | logging.Trace().SetIncompleteReason("dmabuf_texture_swap_unavailable") | |
| 42 | + | }, | |
| 43 | + | } | |
| 44 | + | } | |
| 45 | + | ||
| 26 | 46 | func newDumberRenderHandler(wv *WebView) purecef.RenderHandler { | |
| 27 | 47 | if wv == nil || wv.viewBridge == nil { | |
| 28 | 48 | return nil | |
| @@ -30,23 +50,23 @@ func newDumberRenderHandler(wv *WebView) purecef.RenderHandler { | |||
| 30 | 50 | h := &dumberRenderHandler{wv: wv} | |
| 31 | 51 | ||
| 32 | 52 | var unsupportedPaintOnce sync.Once | |
| 33 | - | h.main = wv.viewBridge.RenderHandler(cef2gtk.Hooks{ | |
| 34 | - | OnUnsupportedPaint: func() { | |
| 35 | - | unsupportedPaintOnce.Do(func() { | |
| 36 | - | if wv.ctx != nil { | |
| 37 | - | logging.FromContext(wv.ctx).Warn().Msg("cef: unsupported CPU paint from accelerated bridge") | |
| 38 | - | } | |
| 39 | - | }) | |
| 40 | - | }, | |
| 41 | - | OnError: func(err error) { | |
| 53 | + | hooks := startupPresentationHooks() | |
| 54 | + | hooks.OnUnsupportedPaint = func() { | |
| 55 | + | unsupportedPaintOnce.Do(func() { | |
| 42 | 56 | if wv.ctx != nil { | |
| 43 | - | logging.FromContext(wv.ctx).Warn().Err(err).Msg("cef: accelerated render bridge error") | |
| 57 | + | logging.FromContext(wv.ctx).Warn().Msg("cef: unsupported CPU paint from accelerated bridge") | |
| 44 | 58 | } | |
| 45 | - | }, | |
| 46 | - | OnTextSelectionChanged: func(selectedText string, _ *purecef.Range) { | |
| 47 | - | handleRenderTextSelectionChanged(wv, selectedText) | |
| 48 | - | }, | |
| 49 | - | }) | |
| 59 | + | }) | |
| 60 | + | } | |
| 61 | + | hooks.OnError = func(err error) { | |
| 62 | + | if wv.ctx != nil { | |
| 63 | + | logging.FromContext(wv.ctx).Warn().Err(err).Msg("cef: accelerated render bridge error") | |
| 64 | + | } | |
| 65 | + | } | |
| 66 | + | hooks.OnTextSelectionChanged = func(selectedText string, _ *purecef.Range) { | |
| 67 | + | handleRenderTextSelectionChanged(wv, selectedText) | |
| 68 | + | } | |
| 69 | + | h.main = wv.viewBridge.RenderHandler(hooks) | |
| 50 | 70 | ||
| 51 | 71 | if wv.popupSurface != nil { | |
| 52 | 72 | var popupUnsupportedPaintOnce sync.Once | |
| @@ -23,6 +23,26 @@ type dumberRenderHandler struct { | |||||
| 23 | 23 | ||||
| 24 | var _ purecef.RenderHandler = (*dumberRenderHandler)(nil) | 24 | var _ purecef.RenderHandler = (*dumberRenderHandler)(nil) | ||
| 25 | 25 | ||||
| 26 | + | // startupPresentationHooks consumes the one-shot facts emitted by | |||
| 27 | + | // purego-cef2gtk. The bridge owns the native DMABUF and frame-clock boundaries; | |||
| 28 | + | // Dumber only records their ordered application-level timeline. | |||
| 29 | + | func startupPresentationHooks() cef2gtk.Hooks { | |||
| 30 | + | return cef2gtk.Hooks{ | |||
| 31 | + | OnFirstAcceleratedPaint: func() { | |||
| 32 | + | logging.Trace().Mark("first_accelerated_paint_received") | |||
| 33 | + | }, | |||
| 34 | + | OnFirstDMABUFTextureSwap: func() { | |||
| 35 | + | logging.Trace().Mark("first_dmabuf_texture_swap") | |||
| 36 | + | }, | |||
| 37 | + | OnFirstPresentation: func() { | |||
| 38 | + | logging.Trace().MarkGTKAfterPaint() | |||
| 39 | + | }, | |||
| 40 | + | OnDMABUFUnsupported: func() { | |||
| 41 | + | logging.Trace().SetIncompleteReason("dmabuf_texture_swap_unavailable") | |||
| 42 | + | }, | |||
| 43 | + | } | |||
| 44 | + | } | |||
| 45 | + | ||||
| 26 | func newDumberRenderHandler(wv *WebView) purecef.RenderHandler { | 46 | func newDumberRenderHandler(wv *WebView) purecef.RenderHandler { | ||
| 27 | if wv == nil || wv.viewBridge == nil { | 47 | if wv == nil || wv.viewBridge == nil { | ||
| 28 | return nil | 48 | return nil | ||
| @@ -30,23 +50,23 @@ func newDumberRenderHandler(wv *WebView) purecef.RenderHandler { | |||||
| 30 | h := &dumberRenderHandler{wv: wv} | 50 | h := &dumberRenderHandler{wv: wv} | ||
| 31 | 51 | ||||
| 32 | var unsupportedPaintOnce sync.Once | 52 | var unsupportedPaintOnce sync.Once | ||
| 33 | - | h.main = wv.viewBridge.RenderHandler(cef2gtk.Hooks{ | 53 | + | hooks := startupPresentationHooks() |
| 34 | - | OnUnsupportedPaint: func() { | 54 | + | hooks.OnUnsupportedPaint = func() { |
| 35 | - | unsupportedPaintOnce.Do(func() { | 55 | + | unsupportedPaintOnce.Do(func() { |
| 36 | - | if wv.ctx != nil { | |||
| 37 | - | logging.FromContext(wv.ctx).Warn().Msg("cef: unsupported CPU paint from accelerated bridge") | |||
| 38 | - | } | |||
| 39 | - | }) | |||
| 40 | - | }, | |||
| 41 | - | OnError: func(err error) { | |||
| 42 | if wv.ctx != nil { | 56 | if wv.ctx != nil { | ||
| 43 | - | logging.FromContext(wv.ctx).Warn().Err(err).Msg("cef: accelerated render bridge error") | 57 | + | logging.FromContext(wv.ctx).Warn().Msg("cef: unsupported CPU paint from accelerated bridge") |
| 44 | } | 58 | } | ||
| 45 | - | }, | 59 | + | }) |
| 46 | - | OnTextSelectionChanged: func(selectedText string, _ *purecef.Range) { | 60 | + | } |
| 47 | - | handleRenderTextSelectionChanged(wv, selectedText) | 61 | + | hooks.OnError = func(err error) { |
| 48 | - | }, | 62 | + | if wv.ctx != nil { |
| 49 | - | }) | 63 | + | logging.FromContext(wv.ctx).Warn().Err(err).Msg("cef: accelerated render bridge error") |
| 64 | + | } | |||
| 65 | + | } | |||
| 66 | + | hooks.OnTextSelectionChanged = func(selectedText string, _ *purecef.Range) { | |||
| 67 | + | handleRenderTextSelectionChanged(wv, selectedText) | |||
| 68 | + | } | |||
| 69 | + | h.main = wv.viewBridge.RenderHandler(hooks) | |||
| 50 | 70 | ||||
| 51 | if wv.popupSurface != nil { | 71 | if wv.popupSurface != nil { | ||
| 52 | var popupUnsupportedPaintOnce sync.Once | 72 | var popupUnsupportedPaintOnce sync.Once | ||
A internal/infrastructure/cef/startup_presentation_hooks_test.go +16 -0
| @@ -0,0 +1,16 @@ | |||
| 1 | + | package cef | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "testing" | |
| 5 | + | ||
| 6 | + | "github.com/stretchr/testify/require" | |
| 7 | + | ) | |
| 8 | + | ||
| 9 | + | func TestStartupPresentationHooksWireEveryUpstreamFirstPresentationCallback(t *testing.T) { | |
| 10 | + | hooks := startupPresentationHooks() | |
| 11 | + | ||
| 12 | + | require.NotNil(t, hooks.OnFirstAcceleratedPaint) | |
| 13 | + | require.NotNil(t, hooks.OnFirstDMABUFTextureSwap) | |
| 14 | + | require.NotNil(t, hooks.OnFirstPresentation) | |
| 15 | + | require.NotNil(t, hooks.OnDMABUFUnsupported) | |
| 16 | + | } | |
| @@ -0,0 +1,16 @@ | |||||
| 1 | + | package cef | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "testing" | |||
| 5 | + | ||||
| 6 | + | "github.com/stretchr/testify/require" | |||
| 7 | + | ) | |||
| 8 | + | ||||
| 9 | + | func TestStartupPresentationHooksWireEveryUpstreamFirstPresentationCallback(t *testing.T) { | |||
| 10 | + | hooks := startupPresentationHooks() | |||
| 11 | + | ||||
| 12 | + | require.NotNil(t, hooks.OnFirstAcceleratedPaint) | |||
| 13 | + | require.NotNil(t, hooks.OnFirstDMABUFTextureSwap) | |||
| 14 | + | require.NotNil(t, hooks.OnFirstPresentation) | |||
| 15 | + | require.NotNil(t, hooks.OnDMABUFUnsupported) | |||
| 16 | + | } | |||
A internal/logging/first_presentation_collector_test.go +301 -0
| @@ -0,0 +1,301 @@ | |||
| 1 | + | package logging | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "encoding/json" | |
| 5 | + | "os" | |
| 6 | + | "os/exec" | |
| 7 | + | "path/filepath" | |
| 8 | + | "strings" | |
| 9 | + | "testing" | |
| 10 | + | ||
| 11 | + | "github.com/stretchr/testify/require" | |
| 12 | + | ) | |
| 13 | + | ||
| 14 | + | const validFirstPresentationLog = `{"message":"startup_trace: milestone","milestone":"process_entry","t_ms":0,"delta_ms":0,"time":"2026-07-14T09:00:00+02:00","machine_path":"/home/alice/private"} | |
| 15 | + | {"message":"startup_trace: milestone","milestone":"config_complete","t_ms":1,"delta_ms":1} | |
| 16 | + | {"message":"startup_trace: milestone","milestone":"cef_library_load_begin","t_ms":2,"delta_ms":1} | |
| 17 | + | {"message":"startup_trace: milestone","milestone":"cef_initialized","t_ms":3,"delta_ms":1} | |
| 18 | + | {"message":"startup_trace: milestone","milestone":"browser_create_requested","t_ms":4,"delta_ms":1} | |
| 19 | + | {"message":"startup_trace: milestone","milestone":"first_accelerated_paint_received","t_ms":5,"delta_ms":1} | |
| 20 | + | {"message":"startup_trace: milestone","milestone":"first_dmabuf_texture_swap","t_ms":6,"delta_ms":1} | |
| 21 | + | {"message":"startup_trace: milestone","milestone":"first_gtk_presentation","t_ms":7,"delta_ms":1} | |
| 22 | + | {"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}` | |
| 23 | + | ||
| 24 | + | func TestFirstPresentationCollectorNeverRecursivelyDeletesCallerOutput(t *testing.T) { | |
| 25 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |
| 26 | + | require.NoError(t, err) | |
| 27 | + | script, err := os.ReadFile(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |
| 28 | + | require.NoError(t, err) | |
| 29 | + | require.NotContains(t, string(script), "rm -rf \"$output\"") | |
| 30 | + | require.NotContains(t, string(script), "rm -rf -- \"$output\"") | |
| 31 | + | } | |
| 32 | + | ||
| 33 | + | func TestFirstPresentationCollectorRejectsUnsafeOutputPaths(t *testing.T) { | |
| 34 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |
| 35 | + | require.NoError(t, err) | |
| 36 | + | temp := t.TempDir() | |
| 37 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |
| 38 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |
| 39 | + | binary := filepath.Join(temp, "dumber") | |
| 40 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755)) | |
| 41 | + | home := filepath.Join(temp, "home") | |
| 42 | + | require.NoError(t, os.Mkdir(home, 0o755)) | |
| 43 | + | ||
| 44 | + | unrelated := filepath.Join(temp, "unrelated") | |
| 45 | + | require.NoError(t, os.Mkdir(unrelated, 0o755)) | |
| 46 | + | unrelatedSentinel := filepath.Join(unrelated, "keep") | |
| 47 | + | require.NoError(t, os.WriteFile(unrelatedSentinel, []byte("do not delete"), 0o600)) | |
| 48 | + | ||
| 49 | + | safeParent := filepath.Join(temp, "safe") | |
| 50 | + | require.NoError(t, os.Mkdir(safeParent, 0o755)) | |
| 51 | + | parentSentinel := filepath.Join(safeParent, "keep") | |
| 52 | + | require.NoError(t, os.WriteFile(parentSentinel, []byte("do not delete"), 0o600)) | |
| 53 | + | ||
| 54 | + | external := filepath.Join(temp, "external") | |
| 55 | + | require.NoError(t, os.Mkdir(external, 0o755)) | |
| 56 | + | externalSentinel := filepath.Join(external, "keep") | |
| 57 | + | require.NoError(t, os.WriteFile(externalSentinel, []byte("do not delete"), 0o600)) | |
| 58 | + | link := filepath.Join(temp, "link") | |
| 59 | + | require.NoError(t, os.Symlink(external, link)) | |
| 60 | + | ||
| 61 | + | for _, test := range []struct { | |
| 62 | + | name string | |
| 63 | + | output string | |
| 64 | + | verify func(t *testing.T) | |
| 65 | + | }{ | |
| 66 | + | {name: "empty", output: ""}, | |
| 67 | + | {name: "root", output: "/"}, | |
| 68 | + | {name: "home", output: home}, | |
| 69 | + | {name: "existing unrelated directory", output: unrelated, verify: func(t *testing.T) { | |
| 70 | + | requireFileContents(t, unrelatedSentinel, "do not delete") | |
| 71 | + | }}, | |
| 72 | + | {name: "parent traversal", output: safeParent + "/../escaped", verify: func(t *testing.T) { | |
| 73 | + | requireFileContents(t, parentSentinel, "do not delete") | |
| 74 | + | require.NoFileExists(t, filepath.Join(temp, "escaped")) | |
| 75 | + | }}, | |
| 76 | + | {name: "symlink escape", output: filepath.Join(link, "escaped"), verify: func(t *testing.T) { | |
| 77 | + | requireFileContents(t, externalSentinel, "do not delete") | |
| 78 | + | require.NoFileExists(t, filepath.Join(external, "escaped")) | |
| 79 | + | }}, | |
| 80 | + | } { | |
| 81 | + | t.Run(test.name, func(t *testing.T) { | |
| 82 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |
| 83 | + | // An isolated directory prevents a regression from reaching the tracked | |
| 84 | + | // default artifact path while this test proves output validation is first. | |
| 85 | + | cmd.Dir = temp | |
| 86 | + | cmd.Env = append(os.Environ(), | |
| 87 | + | "HOME="+home, | |
| 88 | + | "DISPLAY=:test", | |
| 89 | + | "DUMBER_CEF_DIR="+runtime, | |
| 90 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |
| 91 | + | "DUMBER_FIRST_PRESENTATION_OUTPUT="+test.output, | |
| 92 | + | ) | |
| 93 | + | result, err := cmd.CombinedOutput() | |
| 94 | + | require.Errorf(t, err, "collector accepted unsafe output %q: %s", test.output, result) | |
| 95 | + | require.Contains(t, string(result), "unsafe output path") | |
| 96 | + | if test.verify != nil { | |
| 97 | + | test.verify(t) | |
| 98 | + | } | |
| 99 | + | }) | |
| 100 | + | } | |
| 101 | + | } | |
| 102 | + | ||
| 103 | + | func requireFileContents(t *testing.T, path, want string) { | |
| 104 | + | t.Helper() | |
| 105 | + | contents, err := os.ReadFile(path) | |
| 106 | + | require.NoError(t, err) | |
| 107 | + | require.Equal(t, want, string(contents)) | |
| 108 | + | } | |
| 109 | + | ||
| 110 | + | func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) { | |
| 111 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |
| 112 | + | require.NoError(t, err) | |
| 113 | + | temp := t.TempDir() | |
| 114 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |
| 115 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |
| 116 | + | ||
| 117 | + | binary := filepath.Join(temp, "dumber") | |
| 118 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755)) | |
| 119 | + | ||
| 120 | + | output := filepath.Join(temp, "artifacts") | |
| 121 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |
| 122 | + | cmd.Dir = repoRoot | |
| 123 | + | cmd.Env = append(os.Environ(), | |
| 124 | + | "DISPLAY=:test", | |
| 125 | + | "WAYLAND_DISPLAY=", | |
| 126 | + | "DUMBER_CEF_DIR="+runtime, | |
| 127 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |
| 128 | + | "DUMBER_FIRST_PRESENTATION_OUTPUT="+output, | |
| 129 | + | "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1", | |
| 130 | + | "DUMBER_MACHINE_GPU_PROFILE=integrated-gpu", | |
| 131 | + | ) | |
| 132 | + | result, err := cmd.CombinedOutput() | |
| 133 | + | require.NoErrorf(t, err, "collector failed: %s", result) | |
| 134 | + | ||
| 135 | + | var artifacts strings.Builder | |
| 136 | + | for _, name := range append([]string{"metadata.json", "baseline.json"}, runArtifactNames()...) { | |
| 137 | + | artifactContents, readErr := os.ReadFile(filepath.Join(output, name)) | |
| 138 | + | require.NoError(t, readErr) | |
| 139 | + | artifacts.Write(artifactContents) | |
| 140 | + | } | |
| 141 | + | for _, forbidden := range []string{"/home/", temp, "alice", "machine_path", `"time"`} { | |
| 142 | + | require.NotContainsf(t, artifacts.String(), forbidden, "committed artifact leaked %q", forbidden) | |
| 143 | + | } | |
| 144 | + | for _, required := range []string{ | |
| 145 | + | `"measured_source_revision"`, | |
| 146 | + | `"tag": "v0.8.4"`, | |
| 147 | + | `"revision": "f217ece342dea3ef2a3f98671fcd16a39ad0037d"`, | |
| 148 | + | } { | |
| 149 | + | require.Contains(t, artifacts.String(), required) | |
| 150 | + | } | |
| 151 | + | ||
| 152 | + | var metadata struct { | |
| 153 | + | Comparison struct { | |
| 154 | + | OS string `json:"os"` | |
| 155 | + | Architecture string `json:"architecture"` | |
| 156 | + | DisplayProtocol string `json:"display_protocol"` | |
| 157 | + | MachineGPUProfile string `json:"machine_gpu_profile"` | |
| 158 | + | } `json:"comparison"` | |
| 159 | + | } | |
| 160 | + | contents, err := os.ReadFile(filepath.Join(output, "metadata.json")) | |
| 161 | + | require.NoError(t, err) | |
| 162 | + | require.NoError(t, json.Unmarshal(contents, &metadata)) | |
| 163 | + | require.NotEmpty(t, metadata.Comparison.OS) | |
| 164 | + | require.NotEmpty(t, metadata.Comparison.Architecture) | |
| 165 | + | require.Equal(t, "x11", metadata.Comparison.DisplayProtocol) | |
| 166 | + | require.Equal(t, "integrated-gpu", metadata.Comparison.MachineGPUProfile) | |
| 167 | + | } | |
| 168 | + | ||
| 169 | + | func TestFirstPresentationCollectorDefaultsToXDGStateEvidenceDirectory(t *testing.T) { | |
| 170 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |
| 171 | + | require.NoError(t, err) | |
| 172 | + | temp := t.TempDir() | |
| 173 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |
| 174 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |
| 175 | + | binary := filepath.Join(temp, "dumber") | |
| 176 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755)) | |
| 177 | + | stateHome := filepath.Join(temp, "state") | |
| 178 | + | ||
| 179 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |
| 180 | + | cmd.Dir = repoRoot | |
| 181 | + | cmd.Env = append(envWithout("DUMBER_FIRST_PRESENTATION_OUTPUT"), | |
| 182 | + | "DISPLAY=:test", | |
| 183 | + | "WAYLAND_DISPLAY=", | |
| 184 | + | "DUMBER_CEF_DIR="+runtime, | |
| 185 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |
| 186 | + | "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1", | |
| 187 | + | "DUMBER_MACHINE_GPU_PROFILE=integrated-gpu", | |
| 188 | + | "XDG_STATE_HOME="+stateHome, | |
| 189 | + | ) | |
| 190 | + | result, err := cmd.CombinedOutput() | |
| 191 | + | require.NoErrorf(t, err, "collector failed: %s", result) | |
| 192 | + | ||
| 193 | + | evidenceRoot := filepath.Join(stateHome, "dumber", "roadmap-evidence") | |
| 194 | + | entries, err := os.ReadDir(evidenceRoot) | |
| 195 | + | require.NoError(t, err) | |
| 196 | + | require.Len(t, entries, 1) | |
| 197 | + | require.True(t, entries[0].IsDir()) | |
| 198 | + | require.FileExists(t, filepath.Join(evidenceRoot, entries[0].Name(), "metadata.json")) | |
| 199 | + | require.NotContains(t, string(result), filepath.Join(repoRoot, "phase1")) | |
| 200 | + | } | |
| 201 | + | ||
| 202 | + | func envWithout(name string) []string { | |
| 203 | + | prefix := name + "=" | |
| 204 | + | var environment []string | |
| 205 | + | for _, entry := range os.Environ() { | |
| 206 | + | if !strings.HasPrefix(entry, prefix) { | |
| 207 | + | environment = append(environment, entry) | |
| 208 | + | } | |
| 209 | + | } | |
| 210 | + | return environment | |
| 211 | + | } | |
| 212 | + | ||
| 213 | + | func TestFirstPresentationCollectorReadsProvenanceWithScopedGitSafeDirectory(t *testing.T) { | |
| 214 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |
| 215 | + | require.NoError(t, err) | |
| 216 | + | temp := t.TempDir() | |
| 217 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |
| 218 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |
| 219 | + | binary := filepath.Join(temp, "dumber") | |
| 220 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755)) | |
| 221 | + | gitDir := filepath.Join(temp, "bin") | |
| 222 | + | require.NoError(t, os.Mkdir(gitDir, 0o755)) | |
| 223 | + | git := filepath.Join(gitDir, "git") | |
| 224 | + | require.NoError(t, os.WriteFile(git, []byte(`#!/bin/sh | |
| 225 | + | if [ "$1" = "-c" ] && [ "$2" = "safe.directory=$EXPECTED_SAFE_DIRECTORY" ] && [ "$3" = "rev-parse" ] && [ "$4" = "HEAD" ]; then | |
| 226 | + | echo 0123456789abcdef0123456789abcdef01234567 | |
| 227 | + | exit 0 | |
| 228 | + | fi | |
| 229 | + | echo "fatal: detected dubious ownership in repository" >&2 | |
| 230 | + | exit 128 | |
| 231 | + | `), 0o755)) | |
| 232 | + | ||
| 233 | + | output := filepath.Join(temp, "artifacts") | |
| 234 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |
| 235 | + | cmd.Dir = repoRoot | |
| 236 | + | cmd.Env = append(os.Environ(), | |
| 237 | + | "DISPLAY=:test", | |
| 238 | + | "DUMBER_CEF_DIR="+runtime, | |
| 239 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |
| 240 | + | "DUMBER_FIRST_PRESENTATION_OUTPUT="+output, | |
| 241 | + | "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1", | |
| 242 | + | "EXPECTED_SAFE_DIRECTORY="+repoRoot, | |
| 243 | + | "PATH="+gitDir+":"+os.Getenv("PATH"), | |
| 244 | + | ) | |
| 245 | + | result, err := cmd.CombinedOutput() | |
| 246 | + | require.NoErrorf(t, err, "collector failed: %s", result) | |
| 247 | + | ||
| 248 | + | var metadata struct { | |
| 249 | + | MeasuredSourceRevision string `json:"measured_source_revision"` | |
| 250 | + | } | |
| 251 | + | contents, err := os.ReadFile(filepath.Join(output, "metadata.json")) | |
| 252 | + | require.NoError(t, err) | |
| 253 | + | require.NoError(t, json.Unmarshal(contents, &metadata)) | |
| 254 | + | require.Equal(t, "0123456789abcdef0123456789abcdef01234567", metadata.MeasuredSourceRevision) | |
| 255 | + | } | |
| 256 | + | ||
| 257 | + | func TestFirstPresentationCollectorRejectsInconsistentTiming(t *testing.T) { | |
| 258 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |
| 259 | + | require.NoError(t, err) | |
| 260 | + | ||
| 261 | + | for _, test := range []struct { | |
| 262 | + | name string | |
| 263 | + | old string | |
| 264 | + | new string | |
| 265 | + | }{ | |
| 266 | + | {name: "non-integer delta", old: `"delta_ms":1}`, new: `"delta_ms":"1"}`}, | |
| 267 | + | {name: "incorrect delta", old: `"delta_ms":1}`, new: `"delta_ms":2}`}, | |
| 268 | + | {name: "non-integer summary total", old: `"total_ms":7`, new: `"total_ms":7.5`}, | |
| 269 | + | {name: "incorrect summary total", old: `"total_ms":7`, new: `"total_ms":8`}, | |
| 270 | + | } { | |
| 271 | + | t.Run(test.name, func(t *testing.T) { | |
| 272 | + | temp := t.TempDir() | |
| 273 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |
| 274 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |
| 275 | + | binary := filepath.Join(temp, "dumber") | |
| 276 | + | log := strings.Replace(validFirstPresentationLog, test.old, test.new, 1) | |
| 277 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(log), 0o755)) | |
| 278 | + | ||
| 279 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |
| 280 | + | cmd.Dir = repoRoot | |
| 281 | + | cmd.Env = append(os.Environ(), | |
| 282 | + | "DISPLAY=:test", | |
| 283 | + | "DUMBER_CEF_DIR="+runtime, | |
| 284 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |
| 285 | + | "DUMBER_FIRST_PRESENTATION_OUTPUT="+filepath.Join(temp, "artifacts"), | |
| 286 | + | "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1", | |
| 287 | + | ) | |
| 288 | + | result, err := cmd.CombinedOutput() | |
| 289 | + | require.Errorf(t, err, "collector accepted malformed timing artifact: %s", result) | |
| 290 | + | require.Contains(t, string(result), "invalid or incomplete non-DMABUF timeline") | |
| 291 | + | }) | |
| 292 | + | } | |
| 293 | + | } | |
| 294 | + | ||
| 295 | + | func collectorTestBinary(log string) []byte { | |
| 296 | + | return []byte("#!/bin/sh\ncat <<'EOF'\n" + log + "\nEOF\nexit 139\n") | |
| 297 | + | } | |
| 298 | + | ||
| 299 | + | func runArtifactNames() []string { | |
| 300 | + | return []string{"run-01.json", "run-02.json", "run-03.json", "run-04.json", "run-05.json"} | |
| 301 | + | } | |
| @@ -0,0 +1,301 @@ | |||||
| 1 | + | package logging | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "encoding/json" | |||
| 5 | + | "os" | |||
| 6 | + | "os/exec" | |||
| 7 | + | "path/filepath" | |||
| 8 | + | "strings" | |||
| 9 | + | "testing" | |||
| 10 | + | ||||
| 11 | + | "github.com/stretchr/testify/require" | |||
| 12 | + | ) | |||
| 13 | + | ||||
| 14 | + | const validFirstPresentationLog = `{"message":"startup_trace: milestone","milestone":"process_entry","t_ms":0,"delta_ms":0,"time":"2026-07-14T09:00:00+02:00","machine_path":"/home/alice/private"} | |||
| 15 | + | {"message":"startup_trace: milestone","milestone":"config_complete","t_ms":1,"delta_ms":1} | |||
| 16 | + | {"message":"startup_trace: milestone","milestone":"cef_library_load_begin","t_ms":2,"delta_ms":1} | |||
| 17 | + | {"message":"startup_trace: milestone","milestone":"cef_initialized","t_ms":3,"delta_ms":1} | |||
| 18 | + | {"message":"startup_trace: milestone","milestone":"browser_create_requested","t_ms":4,"delta_ms":1} | |||
| 19 | + | {"message":"startup_trace: milestone","milestone":"first_accelerated_paint_received","t_ms":5,"delta_ms":1} | |||
| 20 | + | {"message":"startup_trace: milestone","milestone":"first_dmabuf_texture_swap","t_ms":6,"delta_ms":1} | |||
| 21 | + | {"message":"startup_trace: milestone","milestone":"first_gtk_presentation","t_ms":7,"delta_ms":1} | |||
| 22 | + | {"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}` | |||
| 23 | + | ||||
| 24 | + | func TestFirstPresentationCollectorNeverRecursivelyDeletesCallerOutput(t *testing.T) { | |||
| 25 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |||
| 26 | + | require.NoError(t, err) | |||
| 27 | + | script, err := os.ReadFile(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |||
| 28 | + | require.NoError(t, err) | |||
| 29 | + | require.NotContains(t, string(script), "rm -rf \"$output\"") | |||
| 30 | + | require.NotContains(t, string(script), "rm -rf -- \"$output\"") | |||
| 31 | + | } | |||
| 32 | + | ||||
| 33 | + | func TestFirstPresentationCollectorRejectsUnsafeOutputPaths(t *testing.T) { | |||
| 34 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |||
| 35 | + | require.NoError(t, err) | |||
| 36 | + | temp := t.TempDir() | |||
| 37 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |||
| 38 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |||
| 39 | + | binary := filepath.Join(temp, "dumber") | |||
| 40 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755)) | |||
| 41 | + | home := filepath.Join(temp, "home") | |||
| 42 | + | require.NoError(t, os.Mkdir(home, 0o755)) | |||
| 43 | + | ||||
| 44 | + | unrelated := filepath.Join(temp, "unrelated") | |||
| 45 | + | require.NoError(t, os.Mkdir(unrelated, 0o755)) | |||
| 46 | + | unrelatedSentinel := filepath.Join(unrelated, "keep") | |||
| 47 | + | require.NoError(t, os.WriteFile(unrelatedSentinel, []byte("do not delete"), 0o600)) | |||
| 48 | + | ||||
| 49 | + | safeParent := filepath.Join(temp, "safe") | |||
| 50 | + | require.NoError(t, os.Mkdir(safeParent, 0o755)) | |||
| 51 | + | parentSentinel := filepath.Join(safeParent, "keep") | |||
| 52 | + | require.NoError(t, os.WriteFile(parentSentinel, []byte("do not delete"), 0o600)) | |||
| 53 | + | ||||
| 54 | + | external := filepath.Join(temp, "external") | |||
| 55 | + | require.NoError(t, os.Mkdir(external, 0o755)) | |||
| 56 | + | externalSentinel := filepath.Join(external, "keep") | |||
| 57 | + | require.NoError(t, os.WriteFile(externalSentinel, []byte("do not delete"), 0o600)) | |||
| 58 | + | link := filepath.Join(temp, "link") | |||
| 59 | + | require.NoError(t, os.Symlink(external, link)) | |||
| 60 | + | ||||
| 61 | + | for _, test := range []struct { | |||
| 62 | + | name string | |||
| 63 | + | output string | |||
| 64 | + | verify func(t *testing.T) | |||
| 65 | + | }{ | |||
| 66 | + | {name: "empty", output: ""}, | |||
| 67 | + | {name: "root", output: "/"}, | |||
| 68 | + | {name: "home", output: home}, | |||
| 69 | + | {name: "existing unrelated directory", output: unrelated, verify: func(t *testing.T) { | |||
| 70 | + | requireFileContents(t, unrelatedSentinel, "do not delete") | |||
| 71 | + | }}, | |||
| 72 | + | {name: "parent traversal", output: safeParent + "/../escaped", verify: func(t *testing.T) { | |||
| 73 | + | requireFileContents(t, parentSentinel, "do not delete") | |||
| 74 | + | require.NoFileExists(t, filepath.Join(temp, "escaped")) | |||
| 75 | + | }}, | |||
| 76 | + | {name: "symlink escape", output: filepath.Join(link, "escaped"), verify: func(t *testing.T) { | |||
| 77 | + | requireFileContents(t, externalSentinel, "do not delete") | |||
| 78 | + | require.NoFileExists(t, filepath.Join(external, "escaped")) | |||
| 79 | + | }}, | |||
| 80 | + | } { | |||
| 81 | + | t.Run(test.name, func(t *testing.T) { | |||
| 82 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |||
| 83 | + | // An isolated directory prevents a regression from reaching the tracked | |||
| 84 | + | // default artifact path while this test proves output validation is first. | |||
| 85 | + | cmd.Dir = temp | |||
| 86 | + | cmd.Env = append(os.Environ(), | |||
| 87 | + | "HOME="+home, | |||
| 88 | + | "DISPLAY=:test", | |||
| 89 | + | "DUMBER_CEF_DIR="+runtime, | |||
| 90 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |||
| 91 | + | "DUMBER_FIRST_PRESENTATION_OUTPUT="+test.output, | |||
| 92 | + | ) | |||
| 93 | + | result, err := cmd.CombinedOutput() | |||
| 94 | + | require.Errorf(t, err, "collector accepted unsafe output %q: %s", test.output, result) | |||
| 95 | + | require.Contains(t, string(result), "unsafe output path") | |||
| 96 | + | if test.verify != nil { | |||
| 97 | + | test.verify(t) | |||
| 98 | + | } | |||
| 99 | + | }) | |||
| 100 | + | } | |||
| 101 | + | } | |||
| 102 | + | ||||
| 103 | + | func requireFileContents(t *testing.T, path, want string) { | |||
| 104 | + | t.Helper() | |||
| 105 | + | contents, err := os.ReadFile(path) | |||
| 106 | + | require.NoError(t, err) | |||
| 107 | + | require.Equal(t, want, string(contents)) | |||
| 108 | + | } | |||
| 109 | + | ||||
| 110 | + | func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) { | |||
| 111 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |||
| 112 | + | require.NoError(t, err) | |||
| 113 | + | temp := t.TempDir() | |||
| 114 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |||
| 115 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |||
| 116 | + | ||||
| 117 | + | binary := filepath.Join(temp, "dumber") | |||
| 118 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755)) | |||
| 119 | + | ||||
| 120 | + | output := filepath.Join(temp, "artifacts") | |||
| 121 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |||
| 122 | + | cmd.Dir = repoRoot | |||
| 123 | + | cmd.Env = append(os.Environ(), | |||
| 124 | + | "DISPLAY=:test", | |||
| 125 | + | "WAYLAND_DISPLAY=", | |||
| 126 | + | "DUMBER_CEF_DIR="+runtime, | |||
| 127 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |||
| 128 | + | "DUMBER_FIRST_PRESENTATION_OUTPUT="+output, | |||
| 129 | + | "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1", | |||
| 130 | + | "DUMBER_MACHINE_GPU_PROFILE=integrated-gpu", | |||
| 131 | + | ) | |||
| 132 | + | result, err := cmd.CombinedOutput() | |||
| 133 | + | require.NoErrorf(t, err, "collector failed: %s", result) | |||
| 134 | + | ||||
| 135 | + | var artifacts strings.Builder | |||
| 136 | + | for _, name := range append([]string{"metadata.json", "baseline.json"}, runArtifactNames()...) { | |||
| 137 | + | artifactContents, readErr := os.ReadFile(filepath.Join(output, name)) | |||
| 138 | + | require.NoError(t, readErr) | |||
| 139 | + | artifacts.Write(artifactContents) | |||
| 140 | + | } | |||
| 141 | + | for _, forbidden := range []string{"/home/", temp, "alice", "machine_path", `"time"`} { | |||
| 142 | + | require.NotContainsf(t, artifacts.String(), forbidden, "committed artifact leaked %q", forbidden) | |||
| 143 | + | } | |||
| 144 | + | for _, required := range []string{ | |||
| 145 | + | `"measured_source_revision"`, | |||
| 146 | + | `"tag": "v0.8.4"`, | |||
| 147 | + | `"revision": "f217ece342dea3ef2a3f98671fcd16a39ad0037d"`, | |||
| 148 | + | } { | |||
| 149 | + | require.Contains(t, artifacts.String(), required) | |||
| 150 | + | } | |||
| 151 | + | ||||
| 152 | + | var metadata struct { | |||
| 153 | + | Comparison struct { | |||
| 154 | + | OS string `json:"os"` | |||
| 155 | + | Architecture string `json:"architecture"` | |||
| 156 | + | DisplayProtocol string `json:"display_protocol"` | |||
| 157 | + | MachineGPUProfile string `json:"machine_gpu_profile"` | |||
| 158 | + | } `json:"comparison"` | |||
| 159 | + | } | |||
| 160 | + | contents, err := os.ReadFile(filepath.Join(output, "metadata.json")) | |||
| 161 | + | require.NoError(t, err) | |||
| 162 | + | require.NoError(t, json.Unmarshal(contents, &metadata)) | |||
| 163 | + | require.NotEmpty(t, metadata.Comparison.OS) | |||
| 164 | + | require.NotEmpty(t, metadata.Comparison.Architecture) | |||
| 165 | + | require.Equal(t, "x11", metadata.Comparison.DisplayProtocol) | |||
| 166 | + | require.Equal(t, "integrated-gpu", metadata.Comparison.MachineGPUProfile) | |||
| 167 | + | } | |||
| 168 | + | ||||
| 169 | + | func TestFirstPresentationCollectorDefaultsToXDGStateEvidenceDirectory(t *testing.T) { | |||
| 170 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |||
| 171 | + | require.NoError(t, err) | |||
| 172 | + | temp := t.TempDir() | |||
| 173 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |||
| 174 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |||
| 175 | + | binary := filepath.Join(temp, "dumber") | |||
| 176 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755)) | |||
| 177 | + | stateHome := filepath.Join(temp, "state") | |||
| 178 | + | ||||
| 179 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |||
| 180 | + | cmd.Dir = repoRoot | |||
| 181 | + | cmd.Env = append(envWithout("DUMBER_FIRST_PRESENTATION_OUTPUT"), | |||
| 182 | + | "DISPLAY=:test", | |||
| 183 | + | "WAYLAND_DISPLAY=", | |||
| 184 | + | "DUMBER_CEF_DIR="+runtime, | |||
| 185 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |||
| 186 | + | "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1", | |||
| 187 | + | "DUMBER_MACHINE_GPU_PROFILE=integrated-gpu", | |||
| 188 | + | "XDG_STATE_HOME="+stateHome, | |||
| 189 | + | ) | |||
| 190 | + | result, err := cmd.CombinedOutput() | |||
| 191 | + | require.NoErrorf(t, err, "collector failed: %s", result) | |||
| 192 | + | ||||
| 193 | + | evidenceRoot := filepath.Join(stateHome, "dumber", "roadmap-evidence") | |||
| 194 | + | entries, err := os.ReadDir(evidenceRoot) | |||
| 195 | + | require.NoError(t, err) | |||
| 196 | + | require.Len(t, entries, 1) | |||
| 197 | + | require.True(t, entries[0].IsDir()) | |||
| 198 | + | require.FileExists(t, filepath.Join(evidenceRoot, entries[0].Name(), "metadata.json")) | |||
| 199 | + | require.NotContains(t, string(result), filepath.Join(repoRoot, "phase1")) | |||
| 200 | + | } | |||
| 201 | + | ||||
| 202 | + | func envWithout(name string) []string { | |||
| 203 | + | prefix := name + "=" | |||
| 204 | + | var environment []string | |||
| 205 | + | for _, entry := range os.Environ() { | |||
| 206 | + | if !strings.HasPrefix(entry, prefix) { | |||
| 207 | + | environment = append(environment, entry) | |||
| 208 | + | } | |||
| 209 | + | } | |||
| 210 | + | return environment | |||
| 211 | + | } | |||
| 212 | + | ||||
| 213 | + | func TestFirstPresentationCollectorReadsProvenanceWithScopedGitSafeDirectory(t *testing.T) { | |||
| 214 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |||
| 215 | + | require.NoError(t, err) | |||
| 216 | + | temp := t.TempDir() | |||
| 217 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |||
| 218 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |||
| 219 | + | binary := filepath.Join(temp, "dumber") | |||
| 220 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(validFirstPresentationLog), 0o755)) | |||
| 221 | + | gitDir := filepath.Join(temp, "bin") | |||
| 222 | + | require.NoError(t, os.Mkdir(gitDir, 0o755)) | |||
| 223 | + | git := filepath.Join(gitDir, "git") | |||
| 224 | + | require.NoError(t, os.WriteFile(git, []byte(`#!/bin/sh | |||
| 225 | + | if [ "$1" = "-c" ] && [ "$2" = "safe.directory=$EXPECTED_SAFE_DIRECTORY" ] && [ "$3" = "rev-parse" ] && [ "$4" = "HEAD" ]; then | |||
| 226 | + | echo 0123456789abcdef0123456789abcdef01234567 | |||
| 227 | + | exit 0 | |||
| 228 | + | fi | |||
| 229 | + | echo "fatal: detected dubious ownership in repository" >&2 | |||
| 230 | + | exit 128 | |||
| 231 | + | `), 0o755)) | |||
| 232 | + | ||||
| 233 | + | output := filepath.Join(temp, "artifacts") | |||
| 234 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |||
| 235 | + | cmd.Dir = repoRoot | |||
| 236 | + | cmd.Env = append(os.Environ(), | |||
| 237 | + | "DISPLAY=:test", | |||
| 238 | + | "DUMBER_CEF_DIR="+runtime, | |||
| 239 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |||
| 240 | + | "DUMBER_FIRST_PRESENTATION_OUTPUT="+output, | |||
| 241 | + | "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1", | |||
| 242 | + | "EXPECTED_SAFE_DIRECTORY="+repoRoot, | |||
| 243 | + | "PATH="+gitDir+":"+os.Getenv("PATH"), | |||
| 244 | + | ) | |||
| 245 | + | result, err := cmd.CombinedOutput() | |||
| 246 | + | require.NoErrorf(t, err, "collector failed: %s", result) | |||
| 247 | + | ||||
| 248 | + | var metadata struct { | |||
| 249 | + | MeasuredSourceRevision string `json:"measured_source_revision"` | |||
| 250 | + | } | |||
| 251 | + | contents, err := os.ReadFile(filepath.Join(output, "metadata.json")) | |||
| 252 | + | require.NoError(t, err) | |||
| 253 | + | require.NoError(t, json.Unmarshal(contents, &metadata)) | |||
| 254 | + | require.Equal(t, "0123456789abcdef0123456789abcdef01234567", metadata.MeasuredSourceRevision) | |||
| 255 | + | } | |||
| 256 | + | ||||
| 257 | + | func TestFirstPresentationCollectorRejectsInconsistentTiming(t *testing.T) { | |||
| 258 | + | repoRoot, err := filepath.Abs(filepath.Join("..", "..")) | |||
| 259 | + | require.NoError(t, err) | |||
| 260 | + | ||||
| 261 | + | for _, test := range []struct { | |||
| 262 | + | name string | |||
| 263 | + | old string | |||
| 264 | + | new string | |||
| 265 | + | }{ | |||
| 266 | + | {name: "non-integer delta", old: `"delta_ms":1}`, new: `"delta_ms":"1"}`}, | |||
| 267 | + | {name: "incorrect delta", old: `"delta_ms":1}`, new: `"delta_ms":2}`}, | |||
| 268 | + | {name: "non-integer summary total", old: `"total_ms":7`, new: `"total_ms":7.5`}, | |||
| 269 | + | {name: "incorrect summary total", old: `"total_ms":7`, new: `"total_ms":8`}, | |||
| 270 | + | } { | |||
| 271 | + | t.Run(test.name, func(t *testing.T) { | |||
| 272 | + | temp := t.TempDir() | |||
| 273 | + | runtime := filepath.Join(temp, "cef-147-runtime") | |||
| 274 | + | require.NoError(t, os.Mkdir(runtime, 0o755)) | |||
| 275 | + | binary := filepath.Join(temp, "dumber") | |||
| 276 | + | log := strings.Replace(validFirstPresentationLog, test.old, test.new, 1) | |||
| 277 | + | require.NoError(t, os.WriteFile(binary, collectorTestBinary(log), 0o755)) | |||
| 278 | + | ||||
| 279 | + | cmd := exec.Command(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) | |||
| 280 | + | cmd.Dir = repoRoot | |||
| 281 | + | cmd.Env = append(os.Environ(), | |||
| 282 | + | "DISPLAY=:test", | |||
| 283 | + | "DUMBER_CEF_DIR="+runtime, | |||
| 284 | + | "DUMBER_FIRST_PRESENTATION_BIN="+binary, | |||
| 285 | + | "DUMBER_FIRST_PRESENTATION_OUTPUT="+filepath.Join(temp, "artifacts"), | |||
| 286 | + | "DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS=1", | |||
| 287 | + | ) | |||
| 288 | + | result, err := cmd.CombinedOutput() | |||
| 289 | + | require.Errorf(t, err, "collector accepted malformed timing artifact: %s", result) | |||
| 290 | + | require.Contains(t, string(result), "invalid or incomplete non-DMABUF timeline") | |||
| 291 | + | }) | |||
| 292 | + | } | |||
| 293 | + | } | |||
| 294 | + | ||||
| 295 | + | func collectorTestBinary(log string) []byte { | |||
| 296 | + | return []byte("#!/bin/sh\ncat <<'EOF'\n" + log + "\nEOF\nexit 139\n") | |||
| 297 | + | } | |||
| 298 | + | ||||
| 299 | + | func runArtifactNames() []string { | |||
| 300 | + | return []string{"run-01.json", "run-02.json", "run-03.json", "run-04.json", "run-05.json"} | |||
| 301 | + | } | |||
M internal/logging/startup_trace.go +122 -134
| @@ -1,32 +1,44 @@ | |||
| 1 | 1 | package logging | |
| 2 | 2 | ||
| 3 | 3 | import ( | |
| 4 | - | "fmt" | |
| 5 | - | "strings" | |
| 6 | 4 | "sync" | |
| 7 | 5 | "time" | |
| 8 | 6 | ||
| 9 | 7 | "github.com/rs/zerolog" | |
| 10 | 8 | ) | |
| 11 | 9 | ||
| 12 | - | // StartupTrace tracks cold start milestones from process launch to first paint. | |
| 13 | - | // Thread-safe for use across goroutines. | |
| 14 | - | // Enabled only when log level is debug or trace. | |
| 10 | + | // StartupTrace records the single truthful path from process entry to the first | |
| 11 | + | // GTK presentation. It deliberately rejects unknown, duplicate, and out of | |
| 12 | + | // order milestones: accepting a convenient timestamp would make the result | |
| 13 | + | // unsuitable for cold-start measurement. | |
| 15 | 14 | type StartupTrace struct { | |
| 16 | - | mu sync.Mutex | |
| 17 | - | t0 time.Time | |
| 18 | - | milestones []Milestone | |
| 19 | - | enabled bool | |
| 20 | - | logger *zerolog.Logger | |
| 21 | - | buffered []Milestone // milestones recorded before logger is set | |
| 22 | - | finished bool | |
| 15 | + | mu sync.Mutex | |
| 16 | + | now func() time.Time | |
| 17 | + | t0 time.Time | |
| 18 | + | milestones []Milestone | |
| 19 | + | logger *zerolog.Logger | |
| 20 | + | buffered []Milestone | |
| 21 | + | backend string | |
| 22 | + | incompleteReason string | |
| 23 | + | summaryEmitted bool | |
| 23 | 24 | } | |
| 24 | 25 | ||
| 25 | - | // Milestone represents a timing checkpoint during startup. | |
| 26 | + | // Milestone represents a timing checkpoint measured from process entry. | |
| 26 | 27 | type Milestone struct { | |
| 27 | 28 | Name string | |
| 28 | - | Elapsed time.Duration // time since t0 | |
| 29 | - | Delta time.Duration // time since previous milestone | |
| 29 | + | Elapsed time.Duration | |
| 30 | + | Delta time.Duration | |
| 31 | + | } | |
| 32 | + | ||
| 33 | + | var startupMilestoneOrder = []string{ | |
| 34 | + | "process_entry", | |
| 35 | + | "config_complete", | |
| 36 | + | "cef_library_load_begin", | |
| 37 | + | "cef_initialized", | |
| 38 | + | "browser_create_requested", | |
| 39 | + | "first_accelerated_paint_received", | |
| 40 | + | "first_dmabuf_texture_swap", | |
| 41 | + | "first_gtk_presentation", | |
| 30 | 42 | } | |
| 31 | 43 | ||
| 32 | 44 | var ( | |
| @@ -35,186 +47,162 @@ var ( | |||
| 35 | 47 | globalTraceOnce sync.Once | |
| 36 | 48 | ) | |
| 37 | 49 | ||
| 38 | - | // InitStartupTrace initializes the global startup trace. | |
| 39 | - | // Call this as early as possible in main() to capture T0. | |
| 40 | - | // The trace is enabled only if the given log level is debug or trace. | |
| 41 | - | func InitStartupTrace(logLevel string) { | |
| 50 | + | func newStartupTrace(now func() time.Time) *StartupTrace { | |
| 51 | + | start := now() | |
| 52 | + | return &StartupTrace{ | |
| 53 | + | now: now, | |
| 54 | + | t0: start, | |
| 55 | + | milestones: make([]Milestone, 0, len(startupMilestoneOrder)), | |
| 56 | + | buffered: make([]Milestone, 0, len(startupMilestoneOrder)), | |
| 57 | + | } | |
| 58 | + | } | |
| 59 | + | ||
| 60 | + | // InitStartupTrace must be called at the first instruction in main. logLevel is | |
| 61 | + | // retained for source compatibility; this measurement is always collected so | |
| 62 | + | // its final structured summary is available at normal log level. | |
| 63 | + | func InitStartupTrace(_ string) { | |
| 42 | 64 | globalTraceOnce.Do(func() { | |
| 43 | - | enabled := logLevel == "debug" || logLevel == "trace" | |
| 65 | + | trace := newStartupTrace(time.Now) | |
| 44 | 66 | globalTraceMu.Lock() | |
| 45 | - | globalTrace = &StartupTrace{ | |
| 46 | - | t0: time.Now(), | |
| 47 | - | milestones: make([]Milestone, 0, 32), | |
| 48 | - | enabled: enabled, | |
| 49 | - | buffered: make([]Milestone, 0, 8), | |
| 50 | - | } | |
| 67 | + | globalTrace = trace | |
| 51 | 68 | globalTraceMu.Unlock() | |
| 52 | - | ||
| 53 | - | if enabled { | |
| 54 | - | // Record process_start as first milestone | |
| 55 | - | globalTrace.Mark("process_start") | |
| 56 | - | } | |
| 57 | 69 | }) | |
| 58 | 70 | } | |
| 59 | 71 | ||
| 60 | - | // Trace returns the global startup trace instance. | |
| 61 | - | // Returns a no-op trace if not initialized or disabled. | |
| 72 | + | // Trace returns the process startup trace. Callers before initialization get a | |
| 73 | + | // harmless trace which rejects all transitions. | |
| 62 | 74 | func Trace() *StartupTrace { | |
| 63 | 75 | globalTraceMu.Lock() | |
| 64 | 76 | defer globalTraceMu.Unlock() | |
| 65 | 77 | if globalTrace == nil { | |
| 66 | - | // Return a disabled no-op trace | |
| 67 | - | return &StartupTrace{enabled: false} | |
| 78 | + | return &StartupTrace{} | |
| 68 | 79 | } | |
| 69 | 80 | return globalTrace | |
| 70 | 81 | } | |
| 71 | 82 | ||
| 72 | - | // SetLogger sets the logger for emitting milestone logs. | |
| 73 | - | // Flushes any buffered milestones that were recorded before the logger was set. | |
| 83 | + | // SetLogger makes buffered milestones available to the process logger. | |
| 74 | 84 | func (st *StartupTrace) SetLogger(logger *zerolog.Logger) { | |
| 75 | - | if st == nil || !st.enabled { | |
| 85 | + | if st == nil || logger == nil { | |
| 76 | 86 | return | |
| 77 | 87 | } | |
| 78 | - | ||
| 79 | 88 | st.mu.Lock() | |
| 80 | 89 | defer st.mu.Unlock() | |
| 81 | - | ||
| 82 | 90 | st.logger = logger | |
| 83 | - | ||
| 84 | - | // Flush buffered milestones | |
| 85 | - | for _, m := range st.buffered { | |
| 86 | - | st.emitMilestone(m) | |
| 91 | + | for _, milestone := range st.buffered { | |
| 92 | + | st.emitMilestone(milestone) | |
| 87 | 93 | } | |
| 88 | 94 | st.buffered = nil | |
| 95 | + | st.emitSummaryLocked() | |
| 89 | 96 | } | |
| 90 | 97 | ||
| 91 | - | // UpdateLogger updates the logger and re-emits all milestones to the new logger. | |
| 92 | - | // Call this after the session file logger is available to capture milestones in the log file. | |
| 93 | - | func (st *StartupTrace) UpdateLogger(logger *zerolog.Logger) { | |
| 94 | - | if st == nil || !st.enabled { | |
| 98 | + | // UpdateLogger switches the destination without replaying events. Replaying | |
| 99 | + | // would violate the one-shot property in session logs. | |
| 100 | + | func (st *StartupTrace) UpdateLogger(logger *zerolog.Logger) { st.SetLogger(logger) } | |
| 101 | + | ||
| 102 | + | // SetBackend records the selected presentation backend for the final summary. | |
| 103 | + | func (st *StartupTrace) SetBackend(backend string) { | |
| 104 | + | if st == nil { | |
| 95 | 105 | return | |
| 96 | 106 | } | |
| 97 | - | ||
| 98 | 107 | st.mu.Lock() | |
| 99 | 108 | defer st.mu.Unlock() | |
| 100 | - | ||
| 101 | - | st.logger = logger | |
| 102 | - | ||
| 103 | - | // Re-emit all milestones to the new logger | |
| 104 | - | for _, m := range st.milestones { | |
| 105 | - | st.emitMilestone(m) | |
| 106 | - | } | |
| 109 | + | st.backend = backend | |
| 107 | 110 | } | |
| 108 | 111 | ||
| 109 | - | // Mark records a milestone with the given name. | |
| 110 | - | // Emits a debug log line showing elapsed time and delta from previous milestone. | |
| 111 | - | func (st *StartupTrace) Mark(name string) { | |
| 112 | - | if st == nil || !st.enabled { | |
| 112 | + | // SetIncompleteReason records why a trace cannot reach a valid DMABUF result. | |
| 113 | + | func (st *StartupTrace) SetIncompleteReason(reason string) { | |
| 114 | + | if st == nil { | |
| 113 | 115 | return | |
| 114 | 116 | } | |
| 115 | - | ||
| 116 | 117 | st.mu.Lock() | |
| 117 | 118 | defer st.mu.Unlock() | |
| 119 | + | if st.incompleteReason == "" { | |
| 120 | + | st.incompleteReason = reason | |
| 121 | + | } | |
| 122 | + | } | |
| 118 | 123 | ||
| 119 | - | if st.finished { | |
| 120 | - | return | |
| 124 | + | // Mark accepts exactly the next non-presentation startup milestone and returns | |
| 125 | + | // whether it was recorded. first_gtk_presentation is reserved for the GTK | |
| 126 | + | // frame-clock after-paint hook through MarkGTKAfterPaint. | |
| 127 | + | func (st *StartupTrace) Mark(name string) bool { | |
| 128 | + | if name == "first_gtk_presentation" { | |
| 129 | + | return false | |
| 121 | 130 | } | |
| 131 | + | return st.mark(name) | |
| 132 | + | } | |
| 122 | 133 | ||
| 123 | - | now := time.Now() | |
| 124 | - | elapsed := now.Sub(st.t0) | |
| 134 | + | // MarkGTKAfterPaint records the final milestone. It is called only from the | |
| 135 | + | // upstream CEF-to-GTK bridge's first frame-clock after-paint callback. | |
| 136 | + | func (st *StartupTrace) MarkGTKAfterPaint() bool { | |
| 137 | + | return st.mark("first_gtk_presentation") | |
| 138 | + | } | |
| 125 | 139 | ||
| 126 | - | var delta time.Duration | |
| 127 | - | if len(st.milestones) > 0 { | |
| 128 | - | delta = elapsed - st.milestones[len(st.milestones)-1].Elapsed | |
| 140 | + | // mark accepts the next milestone and is safe for callbacks from CEF and GTK | |
| 141 | + | // threads. | |
| 142 | + | func (st *StartupTrace) mark(name string) bool { | |
| 143 | + | if st == nil || st.now == nil { | |
| 144 | + | return false | |
| 129 | 145 | } | |
| 130 | - | ||
| 131 | - | m := Milestone{ | |
| 132 | - | Name: name, | |
| 133 | - | Elapsed: elapsed, | |
| 134 | - | Delta: delta, | |
| 146 | + | st.mu.Lock() | |
| 147 | + | defer st.mu.Unlock() | |
| 148 | + | if len(st.milestones) >= len(startupMilestoneOrder) || name != startupMilestoneOrder[len(st.milestones)] { | |
| 149 | + | return false | |
| 135 | 150 | } | |
| 136 | - | st.milestones = append(st.milestones, m) | |
| 137 | 151 | ||
| 138 | - | if st.logger != nil { | |
| 139 | - | st.emitMilestone(m) | |
| 152 | + | now := st.now() | |
| 153 | + | milestone := Milestone{Name: name, Elapsed: now.Sub(st.t0)} | |
| 154 | + | // Published fields are integer milliseconds. Compute delta on that same | |
| 155 | + | // scale so delta_ms always exactly reconstructs t_ms in collected evidence. | |
| 156 | + | previousMilliseconds := int64(0) | |
| 157 | + | if len(st.milestones) > 0 { | |
| 158 | + | previousMilliseconds = st.milestones[len(st.milestones)-1].Elapsed.Milliseconds() | |
| 159 | + | } | |
| 160 | + | milestone.Delta = time.Duration(milestone.Elapsed.Milliseconds()-previousMilliseconds) * time.Millisecond | |
| 161 | + | st.milestones = append(st.milestones, milestone) | |
| 162 | + | if st.logger == nil { | |
| 163 | + | st.buffered = append(st.buffered, milestone) | |
| 140 | 164 | } else { | |
| 141 | - | // Buffer until logger is set | |
| 142 | - | st.buffered = append(st.buffered, m) | |
| 165 | + | st.emitMilestone(milestone) | |
| 143 | 166 | } | |
| 167 | + | st.emitSummaryLocked() | |
| 168 | + | return true | |
| 144 | 169 | } | |
| 145 | 170 | ||
| 146 | - | // emitMilestone logs a single milestone. Caller must hold mutex. | |
| 147 | 171 | func (st *StartupTrace) emitMilestone(m Milestone) { | |
| 148 | 172 | if st.logger == nil { | |
| 149 | 173 | return | |
| 150 | 174 | } | |
| 151 | - | ||
| 152 | - | elapsedMs := m.Elapsed.Milliseconds() | |
| 153 | - | ||
| 154 | - | event := st.logger.Debug(). | |
| 175 | + | st.logger.Debug(). | |
| 155 | 176 | Str("milestone", m.Name). | |
| 156 | - | Int64("t_ms", elapsedMs) | |
| 157 | - | ||
| 158 | - | if m.Delta > 0 { | |
| 159 | - | event = event.Int64("delta_ms", m.Delta.Milliseconds()) | |
| 160 | - | } | |
| 161 | - | ||
| 162 | - | // Format: startup_trace: milestone_name (T+123ms, +45ms) | |
| 163 | - | if m.Delta > 0 { | |
| 164 | - | event.Msgf("startup_trace: %s (T+%dms, +%dms)", m.Name, elapsedMs, m.Delta.Milliseconds()) | |
| 165 | - | } else { | |
| 166 | - | event.Msgf("startup_trace: %s (T+%dms)", m.Name, elapsedMs) | |
| 167 | - | } | |
| 177 | + | Int64("t_ms", m.Elapsed.Milliseconds()). | |
| 178 | + | Int64("delta_ms", m.Delta.Milliseconds()). | |
| 179 | + | Msg("startup_trace: milestone") | |
| 168 | 180 | } | |
| 169 | 181 | ||
| 170 | - | // Finish marks the startup trace as complete and emits a summary. | |
| 171 | - | // Called on first_paint milestone. | |
| 172 | - | func (st *StartupTrace) Finish() { | |
| 173 | - | if st == nil || !st.enabled { | |
| 182 | + | func (st *StartupTrace) emitSummaryLocked() { | |
| 183 | + | if st.summaryEmitted || st.logger == nil || len(st.milestones) != len(startupMilestoneOrder) { | |
| 174 | 184 | return | |
| 175 | 185 | } | |
| 176 | - | ||
| 177 | - | st.mu.Lock() | |
| 178 | - | defer st.mu.Unlock() | |
| 179 | - | ||
| 180 | - | if st.finished { | |
| 181 | - | return | |
| 182 | - | } | |
| 183 | - | st.finished = true | |
| 184 | - | ||
| 185 | - | if st.logger == nil { | |
| 186 | - | return | |
| 187 | - | } | |
| 188 | - | ||
| 189 | - | // Build summary string | |
| 190 | - | total := time.Since(st.t0) | |
| 191 | - | var parts []string | |
| 192 | - | for _, m := range st.milestones { | |
| 193 | - | parts = append(parts, fmt.Sprintf("%s:%d", m.Name, m.Elapsed.Milliseconds())) | |
| 194 | - | } | |
| 195 | - | summary := strings.Join(parts, ",") | |
| 196 | - | ||
| 186 | + | st.summaryEmitted = true | |
| 197 | 187 | st.logger.Info(). | |
| 198 | - | Int64("total_ms", total.Milliseconds()). | |
| 199 | - | Str("milestones", summary). | |
| 200 | - | Msg("startup_trace: cold start complete") | |
| 188 | + | Str("backend", st.backend). | |
| 189 | + | Str("incomplete_reason", st.incompleteReason). | |
| 190 | + | Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()). | |
| 191 | + | Interface("milestones", st.milestones). | |
| 192 | + | Msg("startup_trace: first presentation") | |
| 201 | 193 | } | |
| 202 | 194 | ||
| 203 | - | // Enabled returns whether the trace is active. | |
| 204 | - | func (st *StartupTrace) Enabled() bool { | |
| 205 | - | if st == nil { | |
| 206 | - | return false | |
| 207 | - | } | |
| 208 | - | return st.enabled | |
| 209 | - | } | |
| 195 | + | // Finish is retained as a harmless compatibility no-op. The only valid source | |
| 196 | + | // for first_gtk_presentation is the upstream GTK frame-clock after-paint hook. | |
| 197 | + | func (*StartupTrace) Finish() {} | |
| 198 | + | ||
| 199 | + | func (st *StartupTrace) Enabled() bool { return st != nil && st.now != nil } | |
| 210 | 200 | ||
| 211 | - | // TotalElapsed returns the total time since T0. | |
| 212 | 201 | func (st *StartupTrace) TotalElapsed() time.Duration { | |
| 213 | - | if st == nil || !st.enabled { | |
| 202 | + | if st == nil || st.now == nil { | |
| 214 | 203 | return 0 | |
| 215 | 204 | } | |
| 216 | - | ||
| 217 | 205 | st.mu.Lock() | |
| 218 | 206 | defer st.mu.Unlock() | |
| 219 | - | return time.Since(st.t0) | |
| 207 | + | return st.now().Sub(st.t0) | |
| 220 | 208 | } | |
| @@ -1,32 +1,44 @@ | |||||
| 1 | package logging | 1 | package logging | ||
| 2 | 2 | ||||
| 3 | import ( | 3 | import ( | ||
| 4 | - | "fmt" | |||
| 5 | - | "strings" | |||
| 6 | "sync" | 4 | "sync" | ||
| 7 | "time" | 5 | "time" | ||
| 8 | 6 | ||||
| 9 | "github.com/rs/zerolog" | 7 | "github.com/rs/zerolog" | ||
| 10 | ) | 8 | ) | ||
| 11 | 9 | ||||
| 12 | - | // StartupTrace tracks cold start milestones from process launch to first paint. | 10 | + | // StartupTrace records the single truthful path from process entry to the first |
| 13 | - | // Thread-safe for use across goroutines. | 11 | + | // GTK presentation. It deliberately rejects unknown, duplicate, and out of |
| 14 | - | // Enabled only when log level is debug or trace. | 12 | + | // order milestones: accepting a convenient timestamp would make the result |
| 13 | + | // unsuitable for cold-start measurement. | |||
| 15 | type StartupTrace struct { | 14 | type StartupTrace struct { | ||
| 16 | - | mu sync.Mutex | 15 | + | mu sync.Mutex |
| 17 | - | t0 time.Time | 16 | + | now func() time.Time |
| 18 | - | milestones []Milestone | 17 | + | t0 time.Time |
| 19 | - | enabled bool | 18 | + | milestones []Milestone |
| 20 | - | logger *zerolog.Logger | 19 | + | logger *zerolog.Logger |
| 21 | - | buffered []Milestone // milestones recorded before logger is set | 20 | + | buffered []Milestone |
| 22 | - | finished bool | 21 | + | backend string |
| 22 | + | incompleteReason string | |||
| 23 | + | summaryEmitted bool | |||
| 23 | } | 24 | } | ||
| 24 | 25 | ||||
| 25 | - | // Milestone represents a timing checkpoint during startup. | 26 | + | // Milestone represents a timing checkpoint measured from process entry. |
| 26 | type Milestone struct { | 27 | type Milestone struct { | ||
| 27 | Name string | 28 | Name string | ||
| 28 | - | Elapsed time.Duration // time since t0 | 29 | + | Elapsed time.Duration |
| 29 | - | Delta time.Duration // time since previous milestone | 30 | + | Delta time.Duration |
| 31 | + | } | |||
| 32 | + | ||||
| 33 | + | var startupMilestoneOrder = []string{ | |||
| 34 | + | "process_entry", | |||
| 35 | + | "config_complete", | |||
| 36 | + | "cef_library_load_begin", | |||
| 37 | + | "cef_initialized", | |||
| 38 | + | "browser_create_requested", | |||
| 39 | + | "first_accelerated_paint_received", | |||
| 40 | + | "first_dmabuf_texture_swap", | |||
| 41 | + | "first_gtk_presentation", | |||
| 30 | } | 42 | } | ||
| 31 | 43 | ||||
| 32 | var ( | 44 | var ( | ||
| @@ -35,186 +47,162 @@ var ( | |||||
| 35 | globalTraceOnce sync.Once | 47 | globalTraceOnce sync.Once | ||
| 36 | ) | 48 | ) | ||
| 37 | 49 | ||||
| 38 | - | // InitStartupTrace initializes the global startup trace. | 50 | + | func newStartupTrace(now func() time.Time) *StartupTrace { |
| 39 | - | // Call this as early as possible in main() to capture T0. | 51 | + | start := now() |
| 40 | - | // The trace is enabled only if the given log level is debug or trace. | 52 | + | return &StartupTrace{ |
| 41 | - | func InitStartupTrace(logLevel string) { | 53 | + | now: now, |
| 54 | + | t0: start, | |||
| 55 | + | milestones: make([]Milestone, 0, len(startupMilestoneOrder)), | |||
| 56 | + | buffered: make([]Milestone, 0, len(startupMilestoneOrder)), | |||
| 57 | + | } | |||
| 58 | + | } | |||
| 59 | + | ||||
| 60 | + | // InitStartupTrace must be called at the first instruction in main. logLevel is | |||
| 61 | + | // retained for source compatibility; this measurement is always collected so | |||
| 62 | + | // its final structured summary is available at normal log level. | |||
| 63 | + | func InitStartupTrace(_ string) { | |||
| 42 | globalTraceOnce.Do(func() { | 64 | globalTraceOnce.Do(func() { | ||
| 43 | - | enabled := logLevel == "debug" || logLevel == "trace" | 65 | + | trace := newStartupTrace(time.Now) |
| 44 | globalTraceMu.Lock() | 66 | globalTraceMu.Lock() | ||
| 45 | - | globalTrace = &StartupTrace{ | 67 | + | globalTrace = trace |
| 46 | - | t0: time.Now(), | |||
| 47 | - | milestones: make([]Milestone, 0, 32), | |||
| 48 | - | enabled: enabled, | |||
| 49 | - | buffered: make([]Milestone, 0, 8), | |||
| 50 | - | } | |||
| 51 | globalTraceMu.Unlock() | 68 | globalTraceMu.Unlock() | ||
| 52 | - | ||||
| 53 | - | if enabled { | |||
| 54 | - | // Record process_start as first milestone | |||
| 55 | - | globalTrace.Mark("process_start") | |||
| 56 | - | } | |||
| 57 | }) | 69 | }) | ||
| 58 | } | 70 | } | ||
| 59 | 71 | ||||
| 60 | - | // Trace returns the global startup trace instance. | 72 | + | // Trace returns the process startup trace. Callers before initialization get a |
| 61 | - | // Returns a no-op trace if not initialized or disabled. | 73 | + | // harmless trace which rejects all transitions. |
| 62 | func Trace() *StartupTrace { | 74 | func Trace() *StartupTrace { | ||
| 63 | globalTraceMu.Lock() | 75 | globalTraceMu.Lock() | ||
| 64 | defer globalTraceMu.Unlock() | 76 | defer globalTraceMu.Unlock() | ||
| 65 | if globalTrace == nil { | 77 | if globalTrace == nil { | ||
| 66 | - | // Return a disabled no-op trace | 78 | + | return &StartupTrace{} |
| 67 | - | return &StartupTrace{enabled: false} | |||
| 68 | } | 79 | } | ||
| 69 | return globalTrace | 80 | return globalTrace | ||
| 70 | } | 81 | } | ||
| 71 | 82 | ||||
| 72 | - | // SetLogger sets the logger for emitting milestone logs. | 83 | + | // SetLogger makes buffered milestones available to the process logger. |
| 73 | - | // Flushes any buffered milestones that were recorded before the logger was set. | |||
| 74 | func (st *StartupTrace) SetLogger(logger *zerolog.Logger) { | 84 | func (st *StartupTrace) SetLogger(logger *zerolog.Logger) { | ||
| 75 | - | if st == nil || !st.enabled { | 85 | + | if st == nil || logger == nil { |
| 76 | return | 86 | return | ||
| 77 | } | 87 | } | ||
| 78 | - | ||||
| 79 | st.mu.Lock() | 88 | st.mu.Lock() | ||
| 80 | defer st.mu.Unlock() | 89 | defer st.mu.Unlock() | ||
| 81 | - | ||||
| 82 | st.logger = logger | 90 | st.logger = logger | ||
| 83 | - | 91 | + | for _, milestone := range st.buffered { | |
| 84 | - | // Flush buffered milestones | 92 | + | st.emitMilestone(milestone) |
| 85 | - | for _, m := range st.buffered { | |||
| 86 | - | st.emitMilestone(m) | |||
| 87 | } | 93 | } | ||
| 88 | st.buffered = nil | 94 | st.buffered = nil | ||
| 95 | + | st.emitSummaryLocked() | |||
| 89 | } | 96 | } | ||
| 90 | 97 | ||||
| 91 | - | // UpdateLogger updates the logger and re-emits all milestones to the new logger. | 98 | + | // UpdateLogger switches the destination without replaying events. Replaying |
| 92 | - | // Call this after the session file logger is available to capture milestones in the log file. | 99 | + | // would violate the one-shot property in session logs. |
| 93 | - | func (st *StartupTrace) UpdateLogger(logger *zerolog.Logger) { | 100 | + | func (st *StartupTrace) UpdateLogger(logger *zerolog.Logger) { st.SetLogger(logger) } |
| 94 | - | if st == nil || !st.enabled { | 101 | + | |
| 102 | + | // SetBackend records the selected presentation backend for the final summary. | |||
| 103 | + | func (st *StartupTrace) SetBackend(backend string) { | |||
| 104 | + | if st == nil { | |||
| 95 | return | 105 | return | ||
| 96 | } | 106 | } | ||
| 97 | - | ||||
| 98 | st.mu.Lock() | 107 | st.mu.Lock() | ||
| 99 | defer st.mu.Unlock() | 108 | defer st.mu.Unlock() | ||
| 100 | - | 109 | + | st.backend = backend | |
| 101 | - | st.logger = logger | |||
| 102 | - | ||||
| 103 | - | // Re-emit all milestones to the new logger | |||
| 104 | - | for _, m := range st.milestones { | |||
| 105 | - | st.emitMilestone(m) | |||
| 106 | - | } | |||
| 107 | } | 110 | } | ||
| 108 | 111 | ||||
| 109 | - | // Mark records a milestone with the given name. | 112 | + | // SetIncompleteReason records why a trace cannot reach a valid DMABUF result. |
| 110 | - | // Emits a debug log line showing elapsed time and delta from previous milestone. | 113 | + | func (st *StartupTrace) SetIncompleteReason(reason string) { |
| 111 | - | func (st *StartupTrace) Mark(name string) { | 114 | + | if st == nil { |
| 112 | - | if st == nil || !st.enabled { | |||
| 113 | return | 115 | return | ||
| 114 | } | 116 | } | ||
| 115 | - | ||||
| 116 | st.mu.Lock() | 117 | st.mu.Lock() | ||
| 117 | defer st.mu.Unlock() | 118 | defer st.mu.Unlock() | ||
| 119 | + | if st.incompleteReason == "" { | |||
| 120 | + | st.incompleteReason = reason | |||
| 121 | + | } | |||
| 122 | + | } | |||
| 118 | 123 | ||||
| 119 | - | if st.finished { | 124 | + | // Mark accepts exactly the next non-presentation startup milestone and returns |
| 120 | - | return | 125 | + | // whether it was recorded. first_gtk_presentation is reserved for the GTK |
| 126 | + | // frame-clock after-paint hook through MarkGTKAfterPaint. | |||
| 127 | + | func (st *StartupTrace) Mark(name string) bool { | |||
| 128 | + | if name == "first_gtk_presentation" { | |||
| 129 | + | return false | |||
| 121 | } | 130 | } | ||
| 131 | + | return st.mark(name) | |||
| 132 | + | } | |||
| 122 | 133 | ||||
| 123 | - | now := time.Now() | 134 | + | // MarkGTKAfterPaint records the final milestone. It is called only from the |
| 124 | - | elapsed := now.Sub(st.t0) | 135 | + | // upstream CEF-to-GTK bridge's first frame-clock after-paint callback. |
| 136 | + | func (st *StartupTrace) MarkGTKAfterPaint() bool { | |||
| 137 | + | return st.mark("first_gtk_presentation") | |||
| 138 | + | } | |||
| 125 | 139 | ||||
| 126 | - | var delta time.Duration | 140 | + | // mark accepts the next milestone and is safe for callbacks from CEF and GTK |
| 127 | - | if len(st.milestones) > 0 { | 141 | + | // threads. |
| 128 | - | delta = elapsed - st.milestones[len(st.milestones)-1].Elapsed | 142 | + | func (st *StartupTrace) mark(name string) bool { |
| 143 | + | if st == nil || st.now == nil { | |||
| 144 | + | return false | |||
| 129 | } | 145 | } | ||
| 130 | - | 146 | + | st.mu.Lock() | |
| 131 | - | m := Milestone{ | 147 | + | defer st.mu.Unlock() |
| 132 | - | Name: name, | 148 | + | if len(st.milestones) >= len(startupMilestoneOrder) || name != startupMilestoneOrder[len(st.milestones)] { |
| 133 | - | Elapsed: elapsed, | 149 | + | return false |
| 134 | - | Delta: delta, | |||
| 135 | } | 150 | } | ||
| 136 | - | st.milestones = append(st.milestones, m) | |||
| 137 | 151 | ||||
| 138 | - | if st.logger != nil { | 152 | + | now := st.now() |
| 139 | - | st.emitMilestone(m) | 153 | + | milestone := Milestone{Name: name, Elapsed: now.Sub(st.t0)} |
| 154 | + | // Published fields are integer milliseconds. Compute delta on that same | |||
| 155 | + | // scale so delta_ms always exactly reconstructs t_ms in collected evidence. | |||
| 156 | + | previousMilliseconds := int64(0) | |||
| 157 | + | if len(st.milestones) > 0 { | |||
| 158 | + | previousMilliseconds = st.milestones[len(st.milestones)-1].Elapsed.Milliseconds() | |||
| 159 | + | } | |||
| 160 | + | milestone.Delta = time.Duration(milestone.Elapsed.Milliseconds()-previousMilliseconds) * time.Millisecond | |||
| 161 | + | st.milestones = append(st.milestones, milestone) | |||
| 162 | + | if st.logger == nil { | |||
| 163 | + | st.buffered = append(st.buffered, milestone) | |||
| 140 | } else { | 164 | } else { | ||
| 141 | - | // Buffer until logger is set | 165 | + | st.emitMilestone(milestone) |
| 142 | - | st.buffered = append(st.buffered, m) | |||
| 143 | } | 166 | } | ||
| 167 | + | st.emitSummaryLocked() | |||
| 168 | + | return true | |||
| 144 | } | 169 | } | ||
| 145 | 170 | ||||
| 146 | - | // emitMilestone logs a single milestone. Caller must hold mutex. | |||
| 147 | func (st *StartupTrace) emitMilestone(m Milestone) { | 171 | func (st *StartupTrace) emitMilestone(m Milestone) { | ||
| 148 | if st.logger == nil { | 172 | if st.logger == nil { | ||
| 149 | return | 173 | return | ||
| 150 | } | 174 | } | ||
| 151 | - | 175 | + | st.logger.Debug(). | |
| 152 | - | elapsedMs := m.Elapsed.Milliseconds() | |||
| 153 | - | ||||
| 154 | - | event := st.logger.Debug(). | |||
| 155 | Str("milestone", m.Name). | 176 | Str("milestone", m.Name). | ||
| 156 | - | Int64("t_ms", elapsedMs) | 177 | + | Int64("t_ms", m.Elapsed.Milliseconds()). |
| 157 | - | 178 | + | Int64("delta_ms", m.Delta.Milliseconds()). | |
| 158 | - | if m.Delta > 0 { | 179 | + | Msg("startup_trace: milestone") |
| 159 | - | event = event.Int64("delta_ms", m.Delta.Milliseconds()) | |||
| 160 | - | } | |||
| 161 | - | ||||
| 162 | - | // Format: startup_trace: milestone_name (T+123ms, +45ms) | |||
| 163 | - | if m.Delta > 0 { | |||
| 164 | - | event.Msgf("startup_trace: %s (T+%dms, +%dms)", m.Name, elapsedMs, m.Delta.Milliseconds()) | |||
| 165 | - | } else { | |||
| 166 | - | event.Msgf("startup_trace: %s (T+%dms)", m.Name, elapsedMs) | |||
| 167 | - | } | |||
| 168 | } | 180 | } | ||
| 169 | 181 | ||||
| 170 | - | // Finish marks the startup trace as complete and emits a summary. | 182 | + | func (st *StartupTrace) emitSummaryLocked() { |
| 171 | - | // Called on first_paint milestone. | 183 | + | if st.summaryEmitted || st.logger == nil || len(st.milestones) != len(startupMilestoneOrder) { |
| 172 | - | func (st *StartupTrace) Finish() { | |||
| 173 | - | if st == nil || !st.enabled { | |||
| 174 | return | 184 | return | ||
| 175 | } | 185 | } | ||
| 176 | - | 186 | + | st.summaryEmitted = true | |
| 177 | - | st.mu.Lock() | |||
| 178 | - | defer st.mu.Unlock() | |||
| 179 | - | ||||
| 180 | - | if st.finished { | |||
| 181 | - | return | |||
| 182 | - | } | |||
| 183 | - | st.finished = true | |||
| 184 | - | ||||
| 185 | - | if st.logger == nil { | |||
| 186 | - | return | |||
| 187 | - | } | |||
| 188 | - | ||||
| 189 | - | // Build summary string | |||
| 190 | - | total := time.Since(st.t0) | |||
| 191 | - | var parts []string | |||
| 192 | - | for _, m := range st.milestones { | |||
| 193 | - | parts = append(parts, fmt.Sprintf("%s:%d", m.Name, m.Elapsed.Milliseconds())) | |||
| 194 | - | } | |||
| 195 | - | summary := strings.Join(parts, ",") | |||
| 196 | - | ||||
| 197 | st.logger.Info(). | 187 | st.logger.Info(). | ||
| 198 | - | Int64("total_ms", total.Milliseconds()). | 188 | + | Str("backend", st.backend). |
| 199 | - | Str("milestones", summary). | 189 | + | Str("incomplete_reason", st.incompleteReason). |
| 200 | - | Msg("startup_trace: cold start complete") | 190 | + | Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()). |
| 191 | + | Interface("milestones", st.milestones). | |||
| 192 | + | Msg("startup_trace: first presentation") | |||
| 201 | } | 193 | } | ||
| 202 | 194 | ||||
| 203 | - | // Enabled returns whether the trace is active. | 195 | + | // Finish is retained as a harmless compatibility no-op. The only valid source |
| 204 | - | func (st *StartupTrace) Enabled() bool { | 196 | + | // for first_gtk_presentation is the upstream GTK frame-clock after-paint hook. |
| 205 | - | if st == nil { | 197 | + | func (*StartupTrace) Finish() {} |
| 206 | - | return false | 198 | + | |
| 207 | - | } | 199 | + | func (st *StartupTrace) Enabled() bool { return st != nil && st.now != nil } |
| 208 | - | return st.enabled | |||
| 209 | - | } | |||
| 210 | 200 | ||||
| 211 | - | // TotalElapsed returns the total time since T0. | |||
| 212 | func (st *StartupTrace) TotalElapsed() time.Duration { | 201 | func (st *StartupTrace) TotalElapsed() time.Duration { | ||
| 213 | - | if st == nil || !st.enabled { | 202 | + | if st == nil || st.now == nil { |
| 214 | return 0 | 203 | return 0 | ||
| 215 | } | 204 | } | ||
| 216 | - | ||||
| 217 | st.mu.Lock() | 205 | st.mu.Lock() | ||
| 218 | defer st.mu.Unlock() | 206 | defer st.mu.Unlock() | ||
| 219 | - | return time.Since(st.t0) | 207 | + | return st.now().Sub(st.t0) |
| 220 | } | 208 | } | ||
A internal/logging/startup_trace_test.go +89 -0
| @@ -0,0 +1,89 @@ | |||
| 1 | + | package logging | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "bytes" | |
| 5 | + | "testing" | |
| 6 | + | "time" | |
| 7 | + | ||
| 8 | + | "github.com/rs/zerolog" | |
| 9 | + | "github.com/stretchr/testify/require" | |
| 10 | + | ) | |
| 11 | + | ||
| 12 | + | func TestStartupTraceAcceptsOnlyOrderedOneShotMilestones(t *testing.T) { | |
| 13 | + | now := time.Unix(100, 0) | |
| 14 | + | trace := newStartupTrace(func() time.Time { return now }) | |
| 15 | + | ||
| 16 | + | require.True(t, trace.Mark("process_entry")) | |
| 17 | + | require.False(t, trace.Mark("cef_initialized"), "out-of-order transition must be rejected") | |
| 18 | + | require.False(t, trace.Mark("process_entry"), "duplicate transition must be rejected") | |
| 19 | + | ||
| 20 | + | for _, name := range []string{ | |
| 21 | + | "config_complete", | |
| 22 | + | "cef_library_load_begin", | |
| 23 | + | "cef_initialized", | |
| 24 | + | "browser_create_requested", | |
| 25 | + | "first_accelerated_paint_received", | |
| 26 | + | "first_dmabuf_texture_swap", | |
| 27 | + | "first_gtk_presentation", | |
| 28 | + | } { | |
| 29 | + | now = now.Add(time.Millisecond) | |
| 30 | + | if name == "first_gtk_presentation" { | |
| 31 | + | require.Truef(t, trace.MarkGTKAfterPaint(), "milestone %s should be accepted", name) | |
| 32 | + | } else { | |
| 33 | + | require.Truef(t, trace.Mark(name), "milestone %s should be accepted", name) | |
| 34 | + | } | |
| 35 | + | } | |
| 36 | + | require.False(t, trace.Mark("first_gtk_presentation")) | |
| 37 | + | } | |
| 38 | + | ||
| 39 | + | func TestStartupTraceQuantizesDeltaToPublishedMilliseconds(t *testing.T) { | |
| 40 | + | now := time.Unix(100, 0) | |
| 41 | + | trace := newStartupTrace(func() time.Time { return now }) | |
| 42 | + | ||
| 43 | + | now = now.Add(1500 * time.Microsecond) | |
| 44 | + | require.True(t, trace.Mark("process_entry")) | |
| 45 | + | now = now.Add(900 * time.Microsecond) | |
| 46 | + | require.True(t, trace.Mark("config_complete")) | |
| 47 | + | ||
| 48 | + | require.Equal(t, int64(1), trace.milestones[0].Elapsed.Milliseconds()) | |
| 49 | + | require.Equal(t, int64(1), trace.milestones[0].Delta.Milliseconds()) | |
| 50 | + | require.Equal(t, int64(2), trace.milestones[1].Elapsed.Milliseconds()) | |
| 51 | + | require.Equal(t, int64(1), trace.milestones[1].Delta.Milliseconds()) | |
| 52 | + | } | |
| 53 | + | ||
| 54 | + | func TestStartupTraceFinishCannotFabricateFirstGTKPresentation(t *testing.T) { | |
| 55 | + | now := time.Unix(100, 0) | |
| 56 | + | trace := newStartupTrace(func() time.Time { return now }) | |
| 57 | + | ||
| 58 | + | for _, name := range startupMilestoneOrder[:len(startupMilestoneOrder)-1] { | |
| 59 | + | now = now.Add(time.Millisecond) | |
| 60 | + | require.True(t, trace.Mark(name)) | |
| 61 | + | } | |
| 62 | + | ||
| 63 | + | trace.Finish() // Legacy callers do not observe the upstream GTK after-paint. | |
| 64 | + | require.Len(t, trace.milestones, len(startupMilestoneOrder)-1) | |
| 65 | + | require.False(t, trace.Mark("first_gtk_presentation"), "generic callers cannot record the reserved milestone") | |
| 66 | + | require.False(t, trace.summaryEmitted) | |
| 67 | + | require.True(t, trace.MarkGTKAfterPaint(), "only the after-paint hook may record this milestone") | |
| 68 | + | } | |
| 69 | + | ||
| 70 | + | func TestStartupTraceEmitsOneNormalSummaryAtFirstPresentation(t *testing.T) { | |
| 71 | + | var output bytes.Buffer | |
| 72 | + | logger := zerolog.New(&output) | |
| 73 | + | now := time.Unix(100, 0) | |
| 74 | + | trace := newStartupTrace(func() time.Time { return now }) | |
| 75 | + | trace.SetBackend("gdk-dmabuf") | |
| 76 | + | trace.SetLogger(&logger) | |
| 77 | + | ||
| 78 | + | for _, name := range startupMilestoneOrder[:len(startupMilestoneOrder)-1] { | |
| 79 | + | now = now.Add(time.Millisecond) | |
| 80 | + | require.True(t, trace.Mark(name)) | |
| 81 | + | } | |
| 82 | + | now = now.Add(time.Millisecond) | |
| 83 | + | require.True(t, trace.MarkGTKAfterPaint()) | |
| 84 | + | trace.MarkGTKAfterPaint() | |
| 85 | + | ||
| 86 | + | require.Contains(t, output.String(), `"message":"startup_trace: first presentation"`) | |
| 87 | + | require.Contains(t, output.String(), `"backend":"gdk-dmabuf"`) | |
| 88 | + | require.Equal(t, 1, bytes.Count(output.Bytes(), []byte(`"message":"startup_trace: first presentation"`))) | |
| 89 | + | } | |
| @@ -0,0 +1,89 @@ | |||||
| 1 | + | package logging | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "bytes" | |||
| 5 | + | "testing" | |||
| 6 | + | "time" | |||
| 7 | + | ||||
| 8 | + | "github.com/rs/zerolog" | |||
| 9 | + | "github.com/stretchr/testify/require" | |||
| 10 | + | ) | |||
| 11 | + | ||||
| 12 | + | func TestStartupTraceAcceptsOnlyOrderedOneShotMilestones(t *testing.T) { | |||
| 13 | + | now := time.Unix(100, 0) | |||
| 14 | + | trace := newStartupTrace(func() time.Time { return now }) | |||
| 15 | + | ||||
| 16 | + | require.True(t, trace.Mark("process_entry")) | |||
| 17 | + | require.False(t, trace.Mark("cef_initialized"), "out-of-order transition must be rejected") | |||
| 18 | + | require.False(t, trace.Mark("process_entry"), "duplicate transition must be rejected") | |||
| 19 | + | ||||
| 20 | + | for _, name := range []string{ | |||
| 21 | + | "config_complete", | |||
| 22 | + | "cef_library_load_begin", | |||
| 23 | + | "cef_initialized", | |||
| 24 | + | "browser_create_requested", | |||
| 25 | + | "first_accelerated_paint_received", | |||
| 26 | + | "first_dmabuf_texture_swap", | |||
| 27 | + | "first_gtk_presentation", | |||
| 28 | + | } { | |||
| 29 | + | now = now.Add(time.Millisecond) | |||
| 30 | + | if name == "first_gtk_presentation" { | |||
| 31 | + | require.Truef(t, trace.MarkGTKAfterPaint(), "milestone %s should be accepted", name) | |||
| 32 | + | } else { | |||
| 33 | + | require.Truef(t, trace.Mark(name), "milestone %s should be accepted", name) | |||
| 34 | + | } | |||
| 35 | + | } | |||
| 36 | + | require.False(t, trace.Mark("first_gtk_presentation")) | |||
| 37 | + | } | |||
| 38 | + | ||||
| 39 | + | func TestStartupTraceQuantizesDeltaToPublishedMilliseconds(t *testing.T) { | |||
| 40 | + | now := time.Unix(100, 0) | |||
| 41 | + | trace := newStartupTrace(func() time.Time { return now }) | |||
| 42 | + | ||||
| 43 | + | now = now.Add(1500 * time.Microsecond) | |||
| 44 | + | require.True(t, trace.Mark("process_entry")) | |||
| 45 | + | now = now.Add(900 * time.Microsecond) | |||
| 46 | + | require.True(t, trace.Mark("config_complete")) | |||
| 47 | + | ||||
| 48 | + | require.Equal(t, int64(1), trace.milestones[0].Elapsed.Milliseconds()) | |||
| 49 | + | require.Equal(t, int64(1), trace.milestones[0].Delta.Milliseconds()) | |||
| 50 | + | require.Equal(t, int64(2), trace.milestones[1].Elapsed.Milliseconds()) | |||
| 51 | + | require.Equal(t, int64(1), trace.milestones[1].Delta.Milliseconds()) | |||
| 52 | + | } | |||
| 53 | + | ||||
| 54 | + | func TestStartupTraceFinishCannotFabricateFirstGTKPresentation(t *testing.T) { | |||
| 55 | + | now := time.Unix(100, 0) | |||
| 56 | + | trace := newStartupTrace(func() time.Time { return now }) | |||
| 57 | + | ||||
| 58 | + | for _, name := range startupMilestoneOrder[:len(startupMilestoneOrder)-1] { | |||
| 59 | + | now = now.Add(time.Millisecond) | |||
| 60 | + | require.True(t, trace.Mark(name)) | |||
| 61 | + | } | |||
| 62 | + | ||||
| 63 | + | trace.Finish() // Legacy callers do not observe the upstream GTK after-paint. | |||
| 64 | + | require.Len(t, trace.milestones, len(startupMilestoneOrder)-1) | |||
| 65 | + | require.False(t, trace.Mark("first_gtk_presentation"), "generic callers cannot record the reserved milestone") | |||
| 66 | + | require.False(t, trace.summaryEmitted) | |||
| 67 | + | require.True(t, trace.MarkGTKAfterPaint(), "only the after-paint hook may record this milestone") | |||
| 68 | + | } | |||
| 69 | + | ||||
| 70 | + | func TestStartupTraceEmitsOneNormalSummaryAtFirstPresentation(t *testing.T) { | |||
| 71 | + | var output bytes.Buffer | |||
| 72 | + | logger := zerolog.New(&output) | |||
| 73 | + | now := time.Unix(100, 0) | |||
| 74 | + | trace := newStartupTrace(func() time.Time { return now }) | |||
| 75 | + | trace.SetBackend("gdk-dmabuf") | |||
| 76 | + | trace.SetLogger(&logger) | |||
| 77 | + | ||||
| 78 | + | for _, name := range startupMilestoneOrder[:len(startupMilestoneOrder)-1] { | |||
| 79 | + | now = now.Add(time.Millisecond) | |||
| 80 | + | require.True(t, trace.Mark(name)) | |||
| 81 | + | } | |||
| 82 | + | now = now.Add(time.Millisecond) | |||
| 83 | + | require.True(t, trace.MarkGTKAfterPaint()) | |||
| 84 | + | trace.MarkGTKAfterPaint() | |||
| 85 | + | ||||
| 86 | + | require.Contains(t, output.String(), `"message":"startup_trace: first presentation"`) | |||
| 87 | + | require.Contains(t, output.String(), `"backend":"gdk-dmabuf"`) | |||
| 88 | + | require.Equal(t, 1, bytes.Count(output.Bytes(), []byte(`"message":"startup_trace: first presentation"`))) | |||
| 89 | + | } | |||
M internal/ui/coordinator/content/navigation.go +0 -4
| @@ -288,10 +288,6 @@ func (c *Coordinator) revealIfPending(ctx context.Context, paneID entity.PaneID, | |||
| 288 | 288 | } | |
| 289 | 289 | } | |
| 290 | 290 | ||
| 291 | - | // Mark first_paint and finish startup trace | |
| 292 | - | logging.Trace().Mark("first_paint") | |
| 293 | - | logging.Trace().Finish() | |
| 294 | - | ||
| 295 | 291 | if c.onWebViewShown != nil { | |
| 296 | 292 | c.onWebViewShown(paneID) | |
| 297 | 293 | } | |
| @@ -288,10 +288,6 @@ func (c *Coordinator) revealIfPending(ctx context.Context, paneID entity.PaneID, | |||||
| 288 | } | 288 | } | ||
| 289 | } | 289 | } | ||
| 290 | 290 | ||||
| 291 | - | // Mark first_paint and finish startup trace | |||
| 292 | - | logging.Trace().Mark("first_paint") | |||
| 293 | - | logging.Trace().Finish() | |||
| 294 | - | ||||
| 295 | if c.onWebViewShown != nil { | 291 | if c.onWebViewShown != nil { | ||
| 296 | c.onWebViewShown(paneID) | 292 | c.onWebViewShown(paneID) | ||
| 297 | } | 293 | } | ||
A scripts/collect_first_presentation.sh +176 -0
| @@ -0,0 +1,176 @@ | |||
| 1 | + | #!/usr/bin/env bash | |
| 2 | + | # Collect exactly five isolated CEF/DMABUF cold starts. The application is | |
| 3 | + | # deliberately terminated after the bounded observation window; a completed | |
| 4 | + | # first-presentation summary, rather than process exit, is the success signal. | |
| 5 | + | set -euo pipefail | |
| 6 | + | ||
| 7 | + | readonly runs=5 | |
| 8 | + | readonly timeout_seconds="${DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS:-45}" | |
| 9 | + | readonly runtime="${DUMBER_CEF_DIR:-$HOME/.local/share/cef-147-runtime}" | |
| 10 | + | readonly binary="${DUMBER_FIRST_PRESENTATION_BIN:-$PWD/dist/dumber}" | |
| 11 | + | ||
| 12 | + | fail_unsafe_output() { | |
| 13 | + | echo "first-presentation: unsafe output path: $1" >&2 | |
| 14 | + | exit 2 | |
| 15 | + | } | |
| 16 | + | ||
| 17 | + | if [[ -v DUMBER_FIRST_PRESENTATION_OUTPUT ]]; then | |
| 18 | + | output="$DUMBER_FIRST_PRESENTATION_OUTPUT" | |
| 19 | + | else | |
| 20 | + | # Evidence is state, not source: keep the default outside the checkout and | |
| 21 | + | # make every invocation a fresh child of the external evidence directory. | |
| 22 | + | readonly state_home="${XDG_STATE_HOME:-$HOME/.local/state}" | |
| 23 | + | [[ "$state_home" == /* ]] || fail_unsafe_output "XDG_STATE_HOME must be absolute" | |
| 24 | + | readonly evidence_root="$state_home/dumber/roadmap-evidence" | |
| 25 | + | mkdir -p -- "$evidence_root" || fail_unsafe_output "could not create XDG state directory" | |
| 26 | + | canonical_evidence_root="$(realpath -e -- "$evidence_root")" || \ | |
| 27 | + | fail_unsafe_output "XDG state directory cannot be canonicalized" | |
| 28 | + | [[ "$canonical_evidence_root" == "$evidence_root" && ! -L "$evidence_root" ]] || \ | |
| 29 | + | fail_unsafe_output "XDG state directory must not contain symbolic links" | |
| 30 | + | output="$evidence_root/first-presentation-$(date -u +%Y%m%dT%H%M%S)-$$" | |
| 31 | + | fi | |
| 32 | + | readonly output | |
| 33 | + | readonly upstream_module="github.com/bnema/purego-cef2gtk" | |
| 34 | + | readonly upstream_tag="v0.8.4" | |
| 35 | + | readonly upstream_revision="f217ece342dea3ef2a3f98671fcd16a39ad0037d" | |
| 36 | + | ||
| 37 | + | # The artifact destination is caller-controlled. Never empty or recursively | |
| 38 | + | # clear it: collection only writes to a newly-created directory whose parent is | |
| 39 | + | # already canonical and contains no symbolic-link hop. | |
| 40 | + | prepare_output() { | |
| 41 | + | local parent name canonical_parent canonical_output | |
| 42 | + | ||
| 43 | + | [[ -n "$output" ]] || fail_unsafe_output "path must not be empty" | |
| 44 | + | [[ "$output" == /* ]] || fail_unsafe_output "path must be absolute" | |
| 45 | + | [[ "$output" != "/" ]] || fail_unsafe_output "path must not be /" | |
| 46 | + | [[ "${output%/}" != "${HOME%/}" ]] || fail_unsafe_output "path must not be HOME" | |
| 47 | + | [[ "$output" != .. && "$output" != ../* && "$output" != */.. && "$output" != */../* ]] || \ | |
| 48 | + | fail_unsafe_output "path must not contain parent traversal" | |
| 49 | + | [[ ! -e "$output" && ! -L "$output" ]] || fail_unsafe_output "path must be a fresh directory" | |
| 50 | + | ||
| 51 | + | parent="$(dirname -- "$output")" | |
| 52 | + | name="$(basename -- "$output")" | |
| 53 | + | [[ -n "$name" && "$name" != "." && "$name" != ".." ]] || fail_unsafe_output "invalid directory name" | |
| 54 | + | [[ -d "$parent" && ! -L "$parent" ]] || fail_unsafe_output "parent must be an existing directory" | |
| 55 | + | canonical_parent="$(realpath -e -- "$parent")" || fail_unsafe_output "parent cannot be canonicalized" | |
| 56 | + | [[ "$parent" == "$canonical_parent" ]] || fail_unsafe_output "parent must not contain symbolic links" | |
| 57 | + | ||
| 58 | + | mkdir -- "$output" || fail_unsafe_output "could not create fresh directory" | |
| 59 | + | canonical_output="$(realpath -e -- "$output")" || fail_unsafe_output "created directory cannot be canonicalized" | |
| 60 | + | [[ -d "$output" && ! -L "$output" && "$canonical_output" == "$canonical_parent/$name" ]] || \ | |
| 61 | + | fail_unsafe_output "created directory changed unexpectedly" | |
| 62 | + | } | |
| 63 | + | ||
| 64 | + | prepare_output | |
| 65 | + | ||
| 66 | + | [[ -x "$binary" ]] || { echo "first-presentation: executable not found: $binary" >&2; exit 2; } | |
| 67 | + | [[ -d "$runtime" ]] || { echo "first-presentation: CEF runtime not found: $runtime" >&2; exit 2; } | |
| 68 | + | [[ -n "${WAYLAND_DISPLAY:-}${DISPLAY:-}" ]] || { echo "first-presentation: a current Wayland/X11 display is required" >&2; exit 2; } | |
| 69 | + | [[ "$(go list -m -f '{{.Version}}' "$upstream_module")" == "$upstream_tag" ]] || { | |
| 70 | + | echo "first-presentation: expected $upstream_module@$upstream_tag" >&2 | |
| 71 | + | exit 2 | |
| 72 | + | } | |
| 73 | + | ||
| 74 | + | # Raw logs and temporary XDG homes may contain machine-local paths. Keep them | |
| 75 | + | # outside the committed artifact directory and always remove them. | |
| 76 | + | work_root="$(mktemp -d "${TMPDIR:-/tmp}/dumber-first-presentation.XXXXXX")" | |
| 77 | + | readonly work_root | |
| 78 | + | cleanup_work_root() { | |
| 79 | + | [[ -n "${work_root:-}" && -d "$work_root" && ! -L "$work_root" ]] || return | |
| 80 | + | rm -rf -- "$work_root" | |
| 81 | + | } | |
| 82 | + | trap cleanup_work_root EXIT | |
| 83 | + | python3 - "$output/metadata.json" "$binary" "$timeout_seconds" "$upstream_module" "$upstream_tag" "$upstream_revision" <<'PY' | |
| 84 | + | import hashlib, json, os, platform, subprocess, sys | |
| 85 | + | path, binary, timeout, upstream_module, upstream_tag, upstream_revision = sys.argv[1:] | |
| 86 | + | with open(binary, "rb") as candidate: | |
| 87 | + | binary_sha256 = hashlib.file_digest(candidate, "sha256").hexdigest() | |
| 88 | + | ||
| 89 | + | # These deliberately coarse labels support comparison without exposing a host, | |
| 90 | + | # device name, driver version, path, or environment dump. | |
| 91 | + | architecture = {"x86_64": "amd64", "amd64": "amd64", "aarch64": "arm64", "arm64": "arm64"}.get(platform.machine().lower(), "other") | |
| 92 | + | os_label = {"linux": "linux", "darwin": "darwin", "windows": "windows"}.get(platform.system().lower(), "other") | |
| 93 | + | display_protocol = "wayland" if os.environ.get("WAYLAND_DISPLAY") else "x11" | |
| 94 | + | gpu_profile = os.environ.get("DUMBER_MACHINE_GPU_PROFILE", "generic-gpu") | |
| 95 | + | allowed_gpu_profiles = {"generic-gpu", "integrated-gpu", "discrete-gpu", "hybrid-gpu", "virtual-gpu", "unknown-gpu"} | |
| 96 | + | if gpu_profile not in allowed_gpu_profiles: | |
| 97 | + | raise SystemExit("DUMBER_MACHINE_GPU_PROFILE must be a non-identifying profile label") | |
| 98 | + | ||
| 99 | + | json.dump({ | |
| 100 | + | "runs": 5, | |
| 101 | + | "runtime": {"label": "cef", "version": "147"}, | |
| 102 | + | "binary": {"label": "dumber", "sha256": binary_sha256}, | |
| 103 | + | "timeout_seconds": int(timeout), | |
| 104 | + | "measured_source_revision": subprocess.check_output(["git", "-c", f"safe.directory={os.getcwd()}", "rev-parse", "HEAD"], text=True).strip(), | |
| 105 | + | "upstream": {"module": upstream_module, "tag": upstream_tag, "revision": upstream_revision}, | |
| 106 | + | "comparison": {"os": os_label, "architecture": architecture, "display_protocol": display_protocol, "machine_gpu_profile": gpu_profile}, | |
| 107 | + | "render_configuration": {"backend": "gdk-dmabuf", "buffer_sharing": "dmabuf", "renderer": "vulkan"} | |
| 108 | + | }, open(path, "w"), indent=2, sort_keys=True) | |
| 109 | + | PY | |
| 110 | + | ||
| 111 | + | for number in $(seq 1 "$runs"); do | |
| 112 | + | run="$(printf 'run-%02d' "$number")" | |
| 113 | + | root="$work_root/$run" | |
| 114 | + | mkdir -p "$root"/{config,data,state,cache} | |
| 115 | + | mkdir -p "$root/config/dumber" | |
| 116 | + | cat >"$root/config/dumber/config.toml" <<EOF | |
| 117 | + | [logging] | |
| 118 | + | level = "debug" | |
| 119 | + | format = "json" | |
| 120 | + | enable_file_log = false | |
| 121 | + | ||
| 122 | + | [engine.cef] | |
| 123 | + | cef_dir = "$runtime" | |
| 124 | + | EOF | |
| 125 | + | # Every directory below is newly created for this one launch. Do not inherit | |
| 126 | + | # a profile, shader cache, CEF root cache, or mutable app configuration. | |
| 127 | + | set +e | |
| 128 | + | env -i \ | |
| 129 | + | HOME="$HOME" PATH="$PATH" LANG="${LANG:-C.UTF-8}" \ | |
| 130 | + | WAYLAND_DISPLAY="${WAYLAND_DISPLAY:-}" DISPLAY="${DISPLAY:-}" XDG_RUNTIME_DIR="${XDG_RUNTIME_DIR:-}" \ | |
| 131 | + | DBUS_SESSION_BUS_ADDRESS="${DBUS_SESSION_BUS_ADDRESS:-}" XAUTHORITY="${XAUTHORITY:-}" \ | |
| 132 | + | XDG_CONFIG_HOME="$root/config" XDG_DATA_HOME="$root/data" XDG_STATE_HOME="$root/state" XDG_CACHE_HOME="$root/cache" \ | |
| 133 | + | DUMBER_CEF_ROOT_CACHE_PATH="$root/cef-root-cache" DUMBER_RENDER_STACK="vulkan-dmabuf" \ | |
| 134 | + | PUREGO_CEF2GTK_BACKEND="gdk-dmabuf" PUREGO_CEF2GTK_ANGLE_BACKEND="vulkan" GSK_RENDERER="vulkan" \ | |
| 135 | + | timeout --signal=TERM --kill-after=5s "${timeout_seconds}s" "$binary" browse about:blank >"$root/process.log" 2>&1 | |
| 136 | + | set -e | |
| 137 | + | # A completed, valid first-presentation summary is the observation success | |
| 138 | + | # signal. The GUI may later be stopped by timeout or terminate independently. | |
| 139 | + | python3 - "$root/process.log" "$output/$run.json" "$run" <<'PY' | |
| 140 | + | import json, sys | |
| 141 | + | log, destination, run = sys.argv[1:] | |
| 142 | + | order = ["process_entry", "config_complete", "cef_library_load_begin", "cef_initialized", "browser_create_requested", "first_accelerated_paint_received", "first_dmabuf_texture_swap", "first_gtk_presentation"] | |
| 143 | + | records, summary = [], None | |
| 144 | + | for line in open(log, errors="replace"): | |
| 145 | + | try: event = json.loads(line) | |
| 146 | + | except json.JSONDecodeError: continue | |
| 147 | + | if event.get("message") == "startup_trace: milestone": | |
| 148 | + | records.append({key: event.get(key) for key in ("milestone", "t_ms", "delta_ms")}) | |
| 149 | + | if event.get("message") == "startup_trace: first presentation": | |
| 150 | + | summary = {key: event.get(key) for key in ("backend", "incomplete_reason", "total_ms")} | |
| 151 | + | names = [event.get("milestone") for event in records] | |
| 152 | + | times = [event.get("t_ms") for event in records] | |
| 153 | + | deltas = [event.get("delta_ms") for event in records] | |
| 154 | + | valid = names == order and all(type(t) is int for t in times) and times == sorted(times) | |
| 155 | + | valid = valid and all(type(delta) is int for delta in deltas) | |
| 156 | + | valid = valid and all(delta == current - previous for previous, current, delta in zip([0] + times, times, deltas)) | |
| 157 | + | valid = valid and summary is not None and summary.get("backend") == "gdk-dmabuf" and not summary.get("incomplete_reason") | |
| 158 | + | valid = valid and type(summary.get("total_ms")) is int and summary["total_ms"] == times[-1] | |
| 159 | + | result = {"run": run, "valid": valid, "milestones": records, "summary": summary} | |
| 160 | + | json.dump(result, open(destination, "w"), indent=2) | |
| 161 | + | if not valid: | |
| 162 | + | raise SystemExit(f"{run}: invalid or incomplete non-DMABUF timeline") | |
| 163 | + | PY | |
| 164 | + | done | |
| 165 | + | ||
| 166 | + | python3 - "$output" <<'PY' | |
| 167 | + | import json, math, statistics, sys | |
| 168 | + | root = sys.argv[1] | |
| 169 | + | runs = [json.load(open(f"{root}/run-{n:02d}.json")) for n in range(1, 6)] | |
| 170 | + | if len(runs) != 5 or not all(run["valid"] for run in runs): raise SystemExit("expected exactly five valid runs") | |
| 171 | + | totals = sorted(run["summary"]["total_ms"] for run in runs) | |
| 172 | + | p95 = totals[max(0, math.ceil(.95 * len(totals)) - 1)] | |
| 173 | + | json.dump({"runs": 5, "total_ms": {"min": totals[0], "median": statistics.median(totals), "max": totals[-1], "p95": p95}}, open(f"{root}/baseline.json", "w"), indent=2) | |
| 174 | + | PY | |
| 175 | + | ||
| 176 | + | echo "first-presentation artifacts: $output" | |
| @@ -0,0 +1,176 @@ | |||||
| 1 | + | #!/usr/bin/env bash | |||
| 2 | + | # Collect exactly five isolated CEF/DMABUF cold starts. The application is | |||
| 3 | + | # deliberately terminated after the bounded observation window; a completed | |||
| 4 | + | # first-presentation summary, rather than process exit, is the success signal. | |||
| 5 | + | set -euo pipefail | |||
| 6 | + | ||||
| 7 | + | readonly runs=5 | |||
| 8 | + | readonly timeout_seconds="${DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS:-45}" | |||
| 9 | + | readonly runtime="${DUMBER_CEF_DIR:-$HOME/.local/share/cef-147-runtime}" | |||
| 10 | + | readonly binary="${DUMBER_FIRST_PRESENTATION_BIN:-$PWD/dist/dumber}" | |||
| 11 | + | ||||
| 12 | + | fail_unsafe_output() { | |||
| 13 | + | echo "first-presentation: unsafe output path: $1" >&2 | |||
| 14 | + | exit 2 | |||
| 15 | + | } | |||
| 16 | + | ||||
| 17 | + | if [[ -v DUMBER_FIRST_PRESENTATION_OUTPUT ]]; then | |||
| 18 | + | output="$DUMBER_FIRST_PRESENTATION_OUTPUT" | |||
| 19 | + | else | |||
| 20 | + | # Evidence is state, not source: keep the default outside the checkout and | |||
| 21 | + | # make every invocation a fresh child of the external evidence directory. | |||
| 22 | + | readonly state_home="${XDG_STATE_HOME:-$HOME/.local/state}" | |||
| 23 | + | [[ "$state_home" == /* ]] || fail_unsafe_output "XDG_STATE_HOME must be absolute" | |||
| 24 | + | readonly evidence_root="$state_home/dumber/roadmap-evidence" | |||
| 25 | + | mkdir -p -- "$evidence_root" || fail_unsafe_output "could not create XDG state directory" | |||
| 26 | + | canonical_evidence_root="$(realpath -e -- "$evidence_root")" || \ | |||
| 27 | + | fail_unsafe_output "XDG state directory cannot be canonicalized" | |||
| 28 | + | [[ "$canonical_evidence_root" == "$evidence_root" && ! -L "$evidence_root" ]] || \ | |||
| 29 | + | fail_unsafe_output "XDG state directory must not contain symbolic links" | |||
| 30 | + | output="$evidence_root/first-presentation-$(date -u +%Y%m%dT%H%M%S)-$$" | |||
| 31 | + | fi | |||
| 32 | + | readonly output | |||
| 33 | + | readonly upstream_module="github.com/bnema/purego-cef2gtk" | |||
| 34 | + | readonly upstream_tag="v0.8.4" | |||
| 35 | + | readonly upstream_revision="f217ece342dea3ef2a3f98671fcd16a39ad0037d" | |||
| 36 | + | ||||
| 37 | + | # The artifact destination is caller-controlled. Never empty or recursively | |||
| 38 | + | # clear it: collection only writes to a newly-created directory whose parent is | |||
| 39 | + | # already canonical and contains no symbolic-link hop. | |||
| 40 | + | prepare_output() { | |||
| 41 | + | local parent name canonical_parent canonical_output | |||
| 42 | + | ||||
| 43 | + | [[ -n "$output" ]] || fail_unsafe_output "path must not be empty" | |||
| 44 | + | [[ "$output" == /* ]] || fail_unsafe_output "path must be absolute" | |||
| 45 | + | [[ "$output" != "/" ]] || fail_unsafe_output "path must not be /" | |||
| 46 | + | [[ "${output%/}" != "${HOME%/}" ]] || fail_unsafe_output "path must not be HOME" | |||
| 47 | + | [[ "$output" != .. && "$output" != ../* && "$output" != */.. && "$output" != */../* ]] || \ | |||
| 48 | + | fail_unsafe_output "path must not contain parent traversal" | |||
| 49 | + | [[ ! -e "$output" && ! -L "$output" ]] || fail_unsafe_output "path must be a fresh directory" | |||
| 50 | + | ||||
| 51 | + | parent="$(dirname -- "$output")" | |||
| 52 | + | name="$(basename -- "$output")" | |||
| 53 | + | [[ -n "$name" && "$name" != "." && "$name" != ".." ]] || fail_unsafe_output "invalid directory name" | |||
| 54 | + | [[ -d "$parent" && ! -L "$parent" ]] || fail_unsafe_output "parent must be an existing directory" | |||
| 55 | + | canonical_parent="$(realpath -e -- "$parent")" || fail_unsafe_output "parent cannot be canonicalized" | |||
| 56 | + | [[ "$parent" == "$canonical_parent" ]] || fail_unsafe_output "parent must not contain symbolic links" | |||
| 57 | + | ||||
| 58 | + | mkdir -- "$output" || fail_unsafe_output "could not create fresh directory" | |||
| 59 | + | canonical_output="$(realpath -e -- "$output")" || fail_unsafe_output "created directory cannot be canonicalized" | |||
| 60 | + | [[ -d "$output" && ! -L "$output" && "$canonical_output" == "$canonical_parent/$name" ]] || \ | |||
| 61 | + | fail_unsafe_output "created directory changed unexpectedly" | |||
| 62 | + | } | |||
| 63 | + | ||||
| 64 | + | prepare_output | |||
| 65 | + | ||||
| 66 | + | [[ -x "$binary" ]] || { echo "first-presentation: executable not found: $binary" >&2; exit 2; } | |||
| 67 | + | [[ -d "$runtime" ]] || { echo "first-presentation: CEF runtime not found: $runtime" >&2; exit 2; } | |||
| 68 | + | [[ -n "${WAYLAND_DISPLAY:-}${DISPLAY:-}" ]] || { echo "first-presentation: a current Wayland/X11 display is required" >&2; exit 2; } | |||
| 69 | + | [[ "$(go list -m -f '{{.Version}}' "$upstream_module")" == "$upstream_tag" ]] || { | |||
| 70 | + | echo "first-presentation: expected $upstream_module@$upstream_tag" >&2 | |||
| 71 | + | exit 2 | |||
| 72 | + | } | |||
| 73 | + | ||||
| 74 | + | # Raw logs and temporary XDG homes may contain machine-local paths. Keep them | |||
| 75 | + | # outside the committed artifact directory and always remove them. | |||
| 76 | + | work_root="$(mktemp -d "${TMPDIR:-/tmp}/dumber-first-presentation.XXXXXX")" | |||
| 77 | + | readonly work_root | |||
| 78 | + | cleanup_work_root() { | |||
| 79 | + | [[ -n "${work_root:-}" && -d "$work_root" && ! -L "$work_root" ]] || return | |||
| 80 | + | rm -rf -- "$work_root" | |||
| 81 | + | } | |||
| 82 | + | trap cleanup_work_root EXIT | |||
| 83 | + | python3 - "$output/metadata.json" "$binary" "$timeout_seconds" "$upstream_module" "$upstream_tag" "$upstream_revision" <<'PY' | |||
| 84 | + | import hashlib, json, os, platform, subprocess, sys | |||
| 85 | + | path, binary, timeout, upstream_module, upstream_tag, upstream_revision = sys.argv[1:] | |||
| 86 | + | with open(binary, "rb") as candidate: | |||
| 87 | + | binary_sha256 = hashlib.file_digest(candidate, "sha256").hexdigest() | |||
| 88 | + | ||||
| 89 | + | # These deliberately coarse labels support comparison without exposing a host, | |||
| 90 | + | # device name, driver version, path, or environment dump. | |||
| 91 | + | architecture = {"x86_64": "amd64", "amd64": "amd64", "aarch64": "arm64", "arm64": "arm64"}.get(platform.machine().lower(), "other") | |||
| 92 | + | os_label = {"linux": "linux", "darwin": "darwin", "windows": "windows"}.get(platform.system().lower(), "other") | |||
| 93 | + | display_protocol = "wayland" if os.environ.get("WAYLAND_DISPLAY") else "x11" | |||
| 94 | + | gpu_profile = os.environ.get("DUMBER_MACHINE_GPU_PROFILE", "generic-gpu") | |||
| 95 | + | allowed_gpu_profiles = {"generic-gpu", "integrated-gpu", "discrete-gpu", "hybrid-gpu", "virtual-gpu", "unknown-gpu"} | |||
| 96 | + | if gpu_profile not in allowed_gpu_profiles: | |||
| 97 | + | raise SystemExit("DUMBER_MACHINE_GPU_PROFILE must be a non-identifying profile label") | |||
| 98 | + | ||||
| 99 | + | json.dump({ | |||
| 100 | + | "runs": 5, | |||
| 101 | + | "runtime": {"label": "cef", "version": "147"}, | |||
| 102 | + | "binary": {"label": "dumber", "sha256": binary_sha256}, | |||
| 103 | + | "timeout_seconds": int(timeout), | |||
| 104 | + | "measured_source_revision": subprocess.check_output(["git", "-c", f"safe.directory={os.getcwd()}", "rev-parse", "HEAD"], text=True).strip(), | |||
| 105 | + | "upstream": {"module": upstream_module, "tag": upstream_tag, "revision": upstream_revision}, | |||
| 106 | + | "comparison": {"os": os_label, "architecture": architecture, "display_protocol": display_protocol, "machine_gpu_profile": gpu_profile}, | |||
| 107 | + | "render_configuration": {"backend": "gdk-dmabuf", "buffer_sharing": "dmabuf", "renderer": "vulkan"} | |||
| 108 | + | }, open(path, "w"), indent=2, sort_keys=True) | |||
| 109 | + | PY | |||
| 110 | + | ||||
| 111 | + | for number in $(seq 1 "$runs"); do | |||
| 112 | + | run="$(printf 'run-%02d' "$number")" | |||
| 113 | + | root="$work_root/$run" | |||
| 114 | + | mkdir -p "$root"/{config,data,state,cache} | |||
| 115 | + | mkdir -p "$root/config/dumber" | |||
| 116 | + | cat >"$root/config/dumber/config.toml" <<EOF | |||
| 117 | + | [logging] | |||
| 118 | + | level = "debug" | |||
| 119 | + | format = "json" | |||
| 120 | + | enable_file_log = false | |||
| 121 | + | ||||
| 122 | + | [engine.cef] | |||
| 123 | + | cef_dir = "$runtime" | |||
| 124 | + | EOF | |||
| 125 | + | # Every directory below is newly created for this one launch. Do not inherit | |||
| 126 | + | # a profile, shader cache, CEF root cache, or mutable app configuration. | |||
| 127 | + | set +e | |||
| 128 | + | env -i \ | |||
| 129 | + | HOME="$HOME" PATH="$PATH" LANG="${LANG:-C.UTF-8}" \ | |||
| 130 | + | WAYLAND_DISPLAY="${WAYLAND_DISPLAY:-}" DISPLAY="${DISPLAY:-}" XDG_RUNTIME_DIR="${XDG_RUNTIME_DIR:-}" \ | |||
| 131 | + | DBUS_SESSION_BUS_ADDRESS="${DBUS_SESSION_BUS_ADDRESS:-}" XAUTHORITY="${XAUTHORITY:-}" \ | |||
| 132 | + | XDG_CONFIG_HOME="$root/config" XDG_DATA_HOME="$root/data" XDG_STATE_HOME="$root/state" XDG_CACHE_HOME="$root/cache" \ | |||
| 133 | + | DUMBER_CEF_ROOT_CACHE_PATH="$root/cef-root-cache" DUMBER_RENDER_STACK="vulkan-dmabuf" \ | |||
| 134 | + | PUREGO_CEF2GTK_BACKEND="gdk-dmabuf" PUREGO_CEF2GTK_ANGLE_BACKEND="vulkan" GSK_RENDERER="vulkan" \ | |||
| 135 | + | timeout --signal=TERM --kill-after=5s "${timeout_seconds}s" "$binary" browse about:blank >"$root/process.log" 2>&1 | |||
| 136 | + | set -e | |||
| 137 | + | # A completed, valid first-presentation summary is the observation success | |||
| 138 | + | # signal. The GUI may later be stopped by timeout or terminate independently. | |||
| 139 | + | python3 - "$root/process.log" "$output/$run.json" "$run" <<'PY' | |||
| 140 | + | import json, sys | |||
| 141 | + | log, destination, run = sys.argv[1:] | |||
| 142 | + | order = ["process_entry", "config_complete", "cef_library_load_begin", "cef_initialized", "browser_create_requested", "first_accelerated_paint_received", "first_dmabuf_texture_swap", "first_gtk_presentation"] | |||
| 143 | + | records, summary = [], None | |||
| 144 | + | for line in open(log, errors="replace"): | |||
| 145 | + | try: event = json.loads(line) | |||
| 146 | + | except json.JSONDecodeError: continue | |||
| 147 | + | if event.get("message") == "startup_trace: milestone": | |||
| 148 | + | records.append({key: event.get(key) for key in ("milestone", "t_ms", "delta_ms")}) | |||
| 149 | + | if event.get("message") == "startup_trace: first presentation": | |||
| 150 | + | summary = {key: event.get(key) for key in ("backend", "incomplete_reason", "total_ms")} | |||
| 151 | + | names = [event.get("milestone") for event in records] | |||
| 152 | + | times = [event.get("t_ms") for event in records] | |||
| 153 | + | deltas = [event.get("delta_ms") for event in records] | |||
| 154 | + | valid = names == order and all(type(t) is int for t in times) and times == sorted(times) | |||
| 155 | + | valid = valid and all(type(delta) is int for delta in deltas) | |||
| 156 | + | valid = valid and all(delta == current - previous for previous, current, delta in zip([0] + times, times, deltas)) | |||
| 157 | + | valid = valid and summary is not None and summary.get("backend") == "gdk-dmabuf" and not summary.get("incomplete_reason") | |||
| 158 | + | valid = valid and type(summary.get("total_ms")) is int and summary["total_ms"] == times[-1] | |||
| 159 | + | result = {"run": run, "valid": valid, "milestones": records, "summary": summary} | |||
| 160 | + | json.dump(result, open(destination, "w"), indent=2) | |||
| 161 | + | if not valid: | |||
| 162 | + | raise SystemExit(f"{run}: invalid or incomplete non-DMABUF timeline") | |||
| 163 | + | PY | |||
| 164 | + | done | |||
| 165 | + | ||||
| 166 | + | python3 - "$output" <<'PY' | |||
| 167 | + | import json, math, statistics, sys | |||
| 168 | + | root = sys.argv[1] | |||
| 169 | + | runs = [json.load(open(f"{root}/run-{n:02d}.json")) for n in range(1, 6)] | |||
| 170 | + | if len(runs) != 5 or not all(run["valid"] for run in runs): raise SystemExit("expected exactly five valid runs") | |||
| 171 | + | totals = sorted(run["summary"]["total_ms"] for run in runs) | |||
| 172 | + | p95 = totals[max(0, math.ceil(.95 * len(totals)) - 1)] | |||
| 173 | + | json.dump({"runs": 5, "total_ms": {"min": totals[0], "median": statistics.median(totals), "max": totals[-1], "p95": p95}}, open(f"{root}/baseline.json", "w"), indent=2) | |||
| 174 | + | PY | |||
| 175 | + | ||||
| 176 | + | echo "first-presentation artifacts: $output" | |||