From dbee4e4c5ce73cbab5bf660d677cccda3bd645c3 Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sun, 29 Mar 2026 15:55:24 +0200 Subject: [PATCH 1/2] chore: adjust performance monitoring and tests --- internal/command/updater.go | 22 ++++++++-- internal/generator/factory.go | 15 +++---- internal/timing/stats.go | 27 +++++-------- internal/timing/stats_test.go | 75 ++++++++++++++++++++++------------- 4 files changed, 80 insertions(+), 59 deletions(-) diff --git a/internal/command/updater.go b/internal/command/updater.go index 6dd049459..d1447f324 100644 --- a/internal/command/updater.go +++ b/internal/command/updater.go @@ -8,6 +8,7 @@ import ( "os" "path" "runtime" + "time" "github.com/CustomResourceDefinition/catalog/internal/configuration" "github.com/CustomResourceDefinition/catalog/internal/crd" @@ -78,12 +79,17 @@ func (cmd Updater) Run() error { return err } + totalStats := timing.NewStats() + + start := time.Now() configurations, err := readConfiguration(cmd.Configuration) if err != nil { return err } + totalStats.Record(timing.CategoryMisc, timing.OperationTypeConfiguration, "read", time.Since(start), true, start) if cmd.registry != nil { + start = time.Now() validKeys := validSourceKeys(configurations) for key := range cmd.registry.Sources { if !validKeys[key] { @@ -91,6 +97,7 @@ func (cmd Updater) Run() error { fmt.Fprintf(cmd.Logger, "Removing stale registry entry: %s\n", key) } } + totalStats.Record(timing.CategoryMisc, timing.OperationTypeConfiguration, "valid_keys", time.Since(start), true, start) } tmpDir, err := os.MkdirTemp("", "output") @@ -99,14 +106,13 @@ func (cmd Updater) Run() error { } defer os.RemoveAll(tmpDir) - totalStats := timing.NewStats() - if err := totalStats.OpenLogFile(cmd.performanceLog); err != nil { return fmt.Errorf("failed to open performance log: %w", err) } defer totalStats.CloseLogFile() for _, config := range splitConfigurations(configurations) { + start = time.Now() runtime.GC() build, err := generator.NewBuilder(config, cmd.reader, tmpDir, cmd.Schema, cmd.Definitions, cmd.Logger, cmd.registry) @@ -116,6 +122,7 @@ func (cmd Updater) Run() error { } err = build.Build() + totalStats.Record(timing.CategoryMisc, timing.OperationTypeBuild, config.Name, time.Since(start), true, start) if err != nil { fmt.Fprintf(cmd.Logger, "::warning:: build of %s failed: %v\n", config.Name, err) continue @@ -128,11 +135,20 @@ func (cmd Updater) Run() error { } if cmd.registry != nil && cmd.registryPath != "" { + start = time.Now() if err := cmd.registry.Save(cmd.registryPath); err != nil { fmt.Fprintf(cmd.Logger, "::warning:: failed to save registry: %v\n", err) } + totalStats.Record(timing.CategoryMisc, timing.OperationTypeConfiguration, "save_registry", time.Since(start), true, start) } + start = time.Now() + err = merge(tmpDir, cmd.Schema) + if err != nil { + return err + } + totalStats.Record(timing.CategoryMisc, timing.OperationTypeMerge, "files", time.Since(start), true, start) + writer, closer, err := cmd.createSummaryWriter() if err != nil { return err @@ -140,7 +156,7 @@ func (cmd Updater) Run() error { defer closer() totalStats.PrintSummary(writer) - return merge(tmpDir, cmd.Schema) + return nil } func (cmd Updater) validate() error { diff --git a/internal/generator/factory.go b/internal/generator/factory.go index 806569742..c874253dc 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -114,9 +114,7 @@ func (builder Builder) Build() error { } for _, version := range versions { - start := time.Now() runtime.GC() - builder.stats.Record(timing.CategoryMisc, timing.OperationTypeGC, "gc", time.Since(start), true, start) if err := builder.renderVersion(logger, version); err != nil { continue @@ -133,8 +131,7 @@ func (builder Builder) Build() error { func (builder Builder) fetchVersions(logger io.Writer) ([]string, error) { start := time.Now() versions, err := builder.generator.Versions() - cat := builder.operationCategory() - builder.stats.Record(cat, timing.OperationTypeAPIFetch, "versions", time.Since(start), err == nil, start) + builder.stats.Record(builder.operationCategory(), timing.OperationTypeAPIFetch, "versions", time.Since(start), err == nil, start) if err != nil { return nil, err } @@ -147,8 +144,7 @@ func (builder Builder) fetchMetadata(logger io.Writer, latestVersion string) ([] fmt.Fprintf(logger, " - checking version %s for completeness.\n", latestVersion) start := time.Now() metadata, err := builder.generator.MetaData(latestVersion) - cat := builder.operationCategory() - builder.stats.Record(cat, timing.OperationTypeAPIFetch, "metadata", time.Since(start), err == nil, start) + builder.stats.Record(builder.operationCategory(), timing.OperationTypeAPIFetch, "metadata", time.Since(start), err == nil, start) if err != nil { fmt.Fprintf(logger, " ! failed: %s\n", err.Error()) return nil, err @@ -159,7 +155,7 @@ func (builder Builder) fetchMetadata(logger io.Writer, latestVersion string) ([] func (builder Builder) renderVersion(logger io.Writer, version string) error { fmt.Fprintf(logger, " - render version %s.\n", version) - crds, err := builder.generateCrds(logger, version) + crds, err := builder.generateCrds(version) if err != nil { fmt.Fprintf(logger, " - - discarded due to error: %s.\n", err.Error()) return err @@ -182,11 +178,10 @@ func (builder Builder) renderVersion(logger io.Writer, version string) error { return nil } -func (builder Builder) generateCrds(logger io.Writer, version string) ([]crd.Crd, error) { +func (builder Builder) generateCrds(version string) ([]crd.Crd, error) { start := time.Now() crds, err := builder.generator.Crds(version) - cat := builder.operationCategory() - builder.stats.Record(cat, timing.OperationTypeGenerate, fmt.Sprintf("crds_%s", version), time.Since(start), err == nil, start) + builder.stats.Record(builder.operationCategory(), timing.OperationTypeGenerate, fmt.Sprintf("crds_%s", version), time.Since(start), err == nil, start) return crds, err } diff --git a/internal/timing/stats.go b/internal/timing/stats.go index 7524469dc..4024b8df7 100644 --- a/internal/timing/stats.go +++ b/internal/timing/stats.go @@ -25,23 +25,14 @@ const ( type OperationType string const ( - OperationTypeAPIFetch OperationType = "api_fetch" - OperationTypeAuth OperationType = "auth" - OperationTypeBranches OperationType = "branches" - OperationTypeCheckout OperationType = "checkout" - OperationTypeClone OperationType = "clone" - OperationTypeDownload OperationType = "download" - OperationTypeFetch OperationType = "fetch" - OperationTypeGC OperationType = "gc" - OperationTypeGenerate OperationType = "generate" - OperationTypeIndex OperationType = "index" - OperationTypePull OperationType = "pull" - OperationTypeRender OperationType = "render" - OperationTypeStatus OperationType = "status" - OperationTypeSubmodule OperationType = "submodule" - OperationTypeTags OperationType = "tags" - OperationTypeUpdate OperationType = "update" - OperationTypeWrite OperationType = "write" + OperationTypeAPIFetch OperationType = "api_fetch" + OperationTypeBuild OperationType = "build" + OperationTypeConfiguration OperationType = "configuration" + OperationTypeGenerate OperationType = "generate" + OperationTypeMerge OperationType = "merge" + OperationTypeStatus OperationType = "status" + OperationTypeUpdate OperationType = "update" + OperationTypeWrite OperationType = "write" ) type Operation struct { @@ -235,7 +226,7 @@ func (s *Stats) PrintSummary(writer io.Writer) { s.mu.RLock() defer s.mu.RUnlock() - fmt.Fprintf(writer, "\n### Update Statistics\n\n") + fmt.Fprintf(writer, "\n### Statistics\n\n") fmt.Fprintf(writer, "**Overall:** %s (%d operations)\n\n", formatDuration(s.totalTime), s.totalOps) categoryOrder := []Category{CategoryHTTP, CategoryGit, CategoryHelm, CategoryOCI, CategoryGeneration, CategoryMisc} diff --git a/internal/timing/stats_test.go b/internal/timing/stats_test.go index 8ba7dc121..0532d9795 100644 --- a/internal/timing/stats_test.go +++ b/internal/timing/stats_test.go @@ -1,7 +1,6 @@ package timing import ( - "io" "os" "strings" "sync" @@ -21,14 +20,14 @@ func TestNewStats(t *testing.T) { func TestRecord(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "test-op", 100*time.Millisecond, true, time.Now()) assert.Equal(t, 1, s.TotalOperations()) assert.Equal(t, 100*time.Millisecond, s.TotalTime()) ops := s.GetCategoryStats(CategoryHTTP) assert.Len(t, ops, 1) - assert.Equal(t, OperationTypeFetch, ops[0].Type) + assert.Equal(t, OperationTypeAPIFetch, ops[0].Type) assert.Equal(t, "test-op", ops[0].Name) assert.Equal(t, 100*time.Millisecond, ops[0].Duration) assert.True(t, ops[0].Success) @@ -37,9 +36,9 @@ func TestRecord(t *testing.T) { func TestRecordMultipleCategories(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 50*time.Millisecond, true, time.Now()) - s.Record(CategoryGit, OperationTypeClone, "git-op", 100*time.Millisecond, true, time.Now()) - s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 75*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "http-op", 50*time.Millisecond, true, time.Now()) + s.Record(CategoryGit, OperationTypeWrite, "git-op", 100*time.Millisecond, true, time.Now()) + s.Record(CategoryHelm, OperationTypeGenerate, "helm-op", 75*time.Millisecond, true, time.Now()) assert.Equal(t, 3, s.TotalOperations()) assert.Equal(t, 225*time.Millisecond, s.TotalTime()) @@ -52,9 +51,9 @@ func TestRecordMultipleCategories(t *testing.T) { func TestRecordMultipleOperationsSameCategory(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now()) - s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true, time.Now()) - s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "op1", 10*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "op2", 20*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "op3", 30*time.Millisecond, true, time.Now()) ops := s.GetCategoryStats(CategoryHTTP) assert.Len(t, ops, 3) @@ -63,7 +62,7 @@ func TestRecordMultipleOperationsSameCategory(t *testing.T) { func TestRecordFailure(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "failed-op", 100*time.Millisecond, false, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "failed-op", 100*time.Millisecond, false, time.Now()) ops := s.GetCategoryStats(CategoryHTTP) assert.Len(t, ops, 1) @@ -79,7 +78,7 @@ func TestGetCategoryStatsEmpty(t *testing.T) { func TestGetCategoryStatsUnknownCategory(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "test", 100*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "test", 100*time.Millisecond, true, time.Now()) ops := s.GetCategoryStats(CategoryOCI) assert.Nil(t, ops) @@ -154,43 +153,63 @@ func TestFormatDuration(t *testing.T) { func TestPrintSummaryEmpty(t *testing.T) { s := NewStats() - s.PrintSummary(io.Discard) + var buf strings.Builder + s.PrintSummary(&buf) + + assert.Contains(t, buf.String(), "### Statistics") + assert.Contains(t, buf.String(), "**Overall:** 0µs (0 operations)") } func TestPrintSummaryWithData(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now()) - s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true, time.Now()) - s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true, time.Now()) - s.Record(CategoryGit, OperationTypeClone, "repo1", 100*time.Millisecond, true, time.Now()) - s.Record(CategoryGit, OperationTypeClone, "repo2", 200*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "op1", 10*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "op2", 20*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "op3", 30*time.Millisecond, true, time.Now()) + s.Record(CategoryGit, OperationTypeGenerate, "repo1", 100*time.Millisecond, true, time.Now()) + s.Record(CategoryGit, OperationTypeGenerate, "repo2", 200*time.Millisecond, true, time.Now()) + + var buf strings.Builder + s.PrintSummary(&buf) - s.PrintSummary(io.Discard) + assert.Contains(t, buf.String(), "### Statistics") + assert.Contains(t, buf.String(), "**Overall:** 360ms (5 operations)") + assert.Contains(t, buf.String(), "#### Http") + assert.Contains(t, buf.String(), "#### Git") } func TestPrintSummaryAllCategories(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 10*time.Millisecond, true, time.Now()) - s.Record(CategoryGit, OperationTypeClone, "git-op", 20*time.Millisecond, true, time.Now()) - s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 30*time.Millisecond, true, time.Now()) - s.Record(CategoryOCI, OperationTypePull, "oci-op", 40*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "http-op", 10*time.Millisecond, true, time.Now()) + s.Record(CategoryGit, OperationTypeGenerate, "git-op", 20*time.Millisecond, true, time.Now()) + s.Record(CategoryHelm, OperationTypeGenerate, "helm-op", 30*time.Millisecond, true, time.Now()) + s.Record(CategoryOCI, OperationTypeGenerate, "oci-op", 40*time.Millisecond, true, time.Now()) s.Record(CategoryGeneration, OperationTypeWrite, "gen-op", 50*time.Millisecond, true, time.Now()) s.Record(CategoryMisc, OperationTypeUpdate, "misc-op", 60*time.Millisecond, true, time.Now()) - s.PrintSummary(io.Discard) + var buf strings.Builder + s.PrintSummary(&buf) + + assert.Contains(t, buf.String(), "### Statistics") + assert.Contains(t, buf.String(), "**Overall:** 210ms (6 operations)") + assert.Contains(t, buf.String(), "#### Http") + assert.Contains(t, buf.String(), "#### Git") + assert.Contains(t, buf.String(), "#### Helm") + assert.Contains(t, buf.String(), "#### Oci") + assert.Contains(t, buf.String(), "#### Generation") + assert.Contains(t, buf.String(), "#### Misc") } func TestConcurrentRecording(t *testing.T) { s := NewStats() var wg sync.WaitGroup - for i := 0; i < 100; i++ { + for i := range 100 { wg.Add(1) go func(n int) { defer wg.Done() - s.Record(CategoryHTTP, OperationTypeFetch, "op", time.Duration(n)*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "op", time.Duration(n)*time.Millisecond, true, time.Now()) }(i) } wg.Wait() @@ -228,7 +247,7 @@ func TestOpenLogFileThenRecord(t *testing.T) { err := s.OpenLogFile(tmpFile) assert.NoError(t, err) - s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "test-op", 100*time.Millisecond, true, time.Now()) s.CloseLogFile() content, err := os.ReadFile(tmpFile) @@ -248,12 +267,12 @@ func TestOpenLogFileInvalidPath(t *testing.T) { func TestPrintSummaryWriter(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now()) + s.Record(CategoryHTTP, OperationTypeAPIFetch, "op1", 10*time.Millisecond, true, time.Now()) var buf strings.Builder s.PrintSummary(&buf) - assert.Contains(t, buf.String(), "Update Statistics") + assert.Contains(t, buf.String(), "### Statistics") assert.Contains(t, buf.String(), "**Overall:**") assert.Contains(t, buf.String(), "#### Http") } From 2a64c6861b497e827d4e9a409efd2dc246d6abee Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sun, 29 Mar 2026 16:02:39 +0200 Subject: [PATCH 2/2] tmp --- internal/command/updater_test.go | 2 +- internal/generator/factory.go | 12 ------------ 2 files changed, 1 insertion(+), 13 deletions(-) diff --git a/internal/command/updater_test.go b/internal/command/updater_test.go index e99903ea4..36f50c407 100644 --- a/internal/command/updater_test.go +++ b/internal/command/updater_test.go @@ -329,7 +329,7 @@ func TestRunAggregatesStats(t *testing.T) { assert.Nil(t, err) outStr := output.String() - assert.Contains(t, outStr, "Update Statistics") + assert.Contains(t, outStr, "### Statistics") assert.Contains(t, outStr, "**Overall:**") assert.Contains(t, outStr, "operations") assert.Contains(t, outStr, "#### Http") diff --git a/internal/generator/factory.go b/internal/generator/factory.go index c874253dc..95b8cbe3d 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -72,18 +72,6 @@ func (builder Builder) Build() error { fmt.Fprintf(logger, " - using prepared git generator\n") } - buildStart := time.Now() - defer func() { - builder.stats.Record( - timing.CategoryMisc, - timing.OperationTypeUpdate, - fmt.Sprintf("build_%s", builder.config.Name), - time.Since(buildStart), - true, - buildStart, - ) - }() - start := time.Now() latestVersion, isUpdated, err := builder.registryStatus() builder.stats.Record(timing.CategoryMisc, timing.OperationTypeStatus, "registry_status", time.Since(start), err == nil, start)