From 26b1f6cd7d26bb8300ea6f82ff62adb7e2407ec8 Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 16:59:24 +0100 Subject: [PATCH 01/14] feat: add performance stats --- internal/command/updater.go | 12 ++ internal/command/updater_test.go | 78 ++++++++ internal/generator/factory.go | 176 ++++++++++++----- internal/generator/factory_test.go | 87 +++++++++ internal/timing/stats.go | 294 +++++++++++++++++++++++++++++ internal/timing/stats_test.go | 274 +++++++++++++++++++++++++++ 6 files changed, 878 insertions(+), 43 deletions(-) create mode 100644 internal/timing/stats.go create mode 100644 internal/timing/stats_test.go diff --git a/internal/command/updater.go b/internal/command/updater.go index 4333a7a79..596d21e1e 100644 --- a/internal/command/updater.go +++ b/internal/command/updater.go @@ -13,6 +13,7 @@ import ( "github.com/CustomResourceDefinition/catalog/internal/crd" "github.com/CustomResourceDefinition/catalog/internal/generator" "github.com/CustomResourceDefinition/catalog/internal/registry" + "github.com/CustomResourceDefinition/catalog/internal/timing" ) type Updater struct { @@ -68,6 +69,8 @@ func (cmd Updater) Run() error { } defer os.RemoveAll(tmpDir) + totalStats := timing.NewStats() + for _, config := range splitConfigurations(configurations) { runtime.GC() @@ -82,6 +85,13 @@ func (cmd Updater) Run() error { fmt.Fprintf(cmd.Logger, "::warning:: build of %s failed: %v\n", config.Name, err) continue } + + stats := build.Stats() + for _, cat := range []timing.Category{timing.CategoryHTTP, timing.CategoryGit, timing.CategoryHelm, timing.CategoryOCI, timing.CategoryGeneration, timing.CategoryMisc} { + for _, op := range stats.GetCategoryStats(cat) { + totalStats.Record(op.Category, op.Type, op.Name, op.Duration, op.Success) + } + } } if cmd.registry != nil && cmd.registryPath != "" { @@ -90,6 +100,8 @@ func (cmd Updater) Run() error { } } + totalStats.PrintSummary() + return merge(tmpDir, cmd.Schema) } diff --git a/internal/command/updater_test.go b/internal/command/updater_test.go index 5109b4766..d5766ead2 100644 --- a/internal/command/updater_test.go +++ b/internal/command/updater_test.go @@ -293,3 +293,81 @@ func TestCheckLocal(t *testing.T) { assert.Nil(t, err) assert.True(t, false, "this test should always be skipped and/or ignored") } + +func TestRunAggregatesStats(t *testing.T) { + b, err := os.ReadFile("testdata/updater/multiple.yaml") + assert.Nil(t, err) + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + w.Write(b) + })) + defer server.Close() + + template := ` +- apiGroups: + - chart.uri + crds: + - baseUri: {{ server }} + paths: + - chart-1.0.0.yaml + version: 1.0.0 + kind: http + name: http +` + tmpDir := t.TempDir() + + config := path.Join(tmpDir, "config.yaml") + os.WriteFile(config, []byte(strings.ReplaceAll(template, "{{ server }}", server.URL)), 0664) + + output := bytes.NewBuffer([]byte{}) + updater := NewUpdater(config, tmpDir, tmpDir, "", output, nil) + + err = updater.Run() + assert.Nil(t, err) + + outStr := output.String() + assert.NotEmpty(t, outStr) +} + +func TestRunWithMultipleConfigsAggregatesStats(t *testing.T) { + b, err := os.ReadFile("testdata/updater/multiple.yaml") + assert.Nil(t, err) + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + w.Write(b) + })) + defer server.Close() + + template := ` +- apiGroups: + - chart.uri + crds: + - baseUri: {{ server }} + paths: + - chart-1.0.0.yaml + version: 1.0.0 + kind: http + name: http1 +- apiGroups: + - chart.uri + crds: + - baseUri: {{ server }} + paths: + - chart-1.0.0.yaml + version: 1.0.0 + kind: http + name: http2 +` + tmpDir := t.TempDir() + + config := path.Join(tmpDir, "config.yaml") + os.WriteFile(config, []byte(strings.ReplaceAll(template, "{{ server }}", server.URL)), 0664) + + output := bytes.NewBuffer([]byte{}) + updater := NewUpdater(config, tmpDir, tmpDir, "", output, nil) + + err = updater.Run() + assert.Nil(t, err) +} diff --git a/internal/generator/factory.go b/internal/generator/factory.go index 06c7eeca6..6f1dae378 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -8,10 +8,12 @@ import ( "regexp" "runtime" "slices" + "time" "github.com/CustomResourceDefinition/catalog/internal/configuration" "github.com/CustomResourceDefinition/catalog/internal/crd" "github.com/CustomResourceDefinition/catalog/internal/registry" + "github.com/CustomResourceDefinition/catalog/internal/timing" ) type Builder struct { @@ -22,6 +24,7 @@ type Builder struct { config configuration.Configuration generator Generator registry *registry.SourceRegistry + stats *timing.Stats } func NewBuilder( @@ -44,6 +47,7 @@ func NewBuilder( generatedRepository: generatedRepository, definitionRepository: definitionRepository, registry: reg, + stats: timing.NewStats(), }, nil } @@ -62,13 +66,14 @@ func (builder Builder) Build() error { logger := builder.logger fmt.Fprintf(logger, "Producing for %s@%s:\n", builder.config.Name, builder.config.Kind) - defer fmt.Fprintf(logger, "End.\n") - if _, ok := builder.generator.(*PreparedGitGenerator); ok { fmt.Fprintf(logger, " - using prepared git generator\n") } + defer fmt.Fprintf(logger, "End.\n") + stop := builder.stats.RecordDuration(timing.CategoryMisc, timing.OperationTypeStatus, "registry_status") latestVersion, isUpdated, err := builder.registryStatus() + stop() if err != nil { return err } @@ -77,17 +82,13 @@ func (builder Builder) Build() error { return nil } - versions, err := builder.generator.Versions() + versions, err := builder.fetchVersions(logger) if err != nil { return err } - fmt.Fprintf(logger, " - found %d versions.\n", len(versions)) - slices.Reverse(versions) - fmt.Fprintf(logger, " - checking version %s for completeness.\n", latestVersion) - metadata, err := builder.generator.MetaData(latestVersion) + metadata, err := builder.fetchMetadata(logger, latestVersion) if err != nil { - fmt.Fprintf(logger, " ! failed: %s\n", err.Error()) return err } @@ -100,54 +101,143 @@ func (builder Builder) Build() error { } for _, version := range versions { + start := time.Now() runtime.GC() + builder.stats.Record(timing.CategoryMisc, timing.OperationTypeUpdate, "gc", time.Since(start), true) - fmt.Fprintf(logger, " - render version %s.\n", version) - crds, err := builder.generator.Crds(version) - if err != nil { - fmt.Fprintf(logger, " - - discarded due to error: %s.\n", err.Error()) + if err := builder.renderVersion(logger, version); err != nil { continue } + } - schemas := make([]crd.CrdSchema, 0) - valid := true - for _, c := range crds { - schema, err := c.Schema() - if err != nil { - fmt.Fprintf(logger, " - - discarding due to error: %s.\n", err.Error()) - valid = false - } - schemas = append(schemas, schema...) - } - if !valid { - fmt.Fprintf(logger, " - - discarded.\n") - continue + defer builder.stats.RecordDuration(timing.CategoryMisc, timing.OperationTypeUpdate, "update_registry")() + builder.updateRegistry(latestVersion) + + return nil +} + +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) + if err != nil { + return nil, err + } + fmt.Fprintf(logger, " - found %d versions.\n", len(versions)) + slices.Reverse(versions) + return versions, nil +} + +func (builder Builder) fetchMetadata(logger io.Writer, latestVersion string) ([]crd.CrdMetaSchema, error) { + 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) + if err != nil { + fmt.Fprintf(logger, " ! failed: %s\n", err.Error()) + return nil, err + } + return metadata, nil +} + +func (builder Builder) renderVersion(logger io.Writer, version string) error { + fmt.Fprintf(logger, " - render version %s.\n", version) + + crds, err := builder.generateCrds(logger, version) + if err != nil { + fmt.Fprintf(logger, " - - discarded due to error: %s.\n", err.Error()) + return err + } + + schemas := builder.extractSchemas(logger, crds) + + if len(crds) > 0 { + builder.writeDefinitions(crds) + } + + if len(schemas) > 0 { + builder.writeSchemas(schemas) + } + + return nil +} + +func (builder Builder) generateCrds(logger io.Writer, 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) + return crds, err +} + +func (builder Builder) extractSchemas(logger io.Writer, crds []crd.Crd) []crd.CrdSchema { + schemas := make([]crd.CrdSchema, 0) + valid := true + for _, c := range crds { + schema, err := c.Schema() + if err != nil { + fmt.Fprintf(logger, " - - discarding due to error: %s.\n", err.Error()) + valid = false } + schemas = append(schemas, schema...) + } + if !valid { + fmt.Fprintf(logger, " - - discarded.\n") + return nil + } + return schemas +} - fmt.Fprintf(logger, " - - rendered %d definitions.\n", len(crds)) - for _, crd := range crds { - file := path.Join(builder.definitionRepository, crd.Filepath()) - os.MkdirAll(path.Dir(file), 0755) - err := os.WriteFile(file, crd.Bytes, 0644) - if err != nil { - return err - } +func (builder Builder) writeDefinitions(crds []crd.Crd) { + fmt.Fprintf(builder.logger, " - - rendered %d definitions.\n", len(crds)) + var writeDuration time.Duration + for _, crd := range crds { + file := path.Join(builder.definitionRepository, crd.Filepath()) + os.MkdirAll(path.Dir(file), 0755) + if err := os.WriteFile(file, crd.Bytes, 0644); err != nil { + return } + writeDuration += time.Second + } + if len(crds) > 0 { + builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "definitions", writeDuration, true) + } +} - fmt.Fprintf(logger, " - - rendered %d schema.\n", len(schemas)) - for _, schema := range schemas { - file := path.Join(builder.generatedRepository, schema.Filepath()) - os.MkdirAll(path.Dir(file), 0755) - err := os.WriteFile(file, schema.Bytes, 0644) - if err != nil { - return err - } +func (builder Builder) writeSchemas(schemas []crd.CrdSchema) { + fmt.Fprintf(builder.logger, " - - rendered %d schema.\n", len(schemas)) + schemaWriteDuration := time.Duration(0) + for _, schema := range schemas { + file := path.Join(builder.generatedRepository, schema.Filepath()) + os.MkdirAll(path.Dir(file), 0755) + if err := os.WriteFile(file, schema.Bytes, 0644); err != nil { + return } + schemaWriteDuration += time.Second } + if len(schemas) > 0 { + builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "schemas", schemaWriteDuration, true) + } +} - builder.updateRegistry(latestVersion) +func (builder Builder) Stats() *timing.Stats { + return builder.stats +} - return nil +func (builder Builder) operationCategory() timing.Category { + switch builder.config.Kind { + case configuration.Git: + return timing.CategoryGit + case configuration.Http: + return timing.CategoryHTTP + case configuration.Helm: + return timing.CategoryHelm + case configuration.HelmOci: + return timing.CategoryOCI + } + return timing.CategoryMisc } // registryStatus reports on the state in registry based on the latest version diff --git a/internal/generator/factory_test.go b/internal/generator/factory_test.go index 6f03faccf..173b5935d 100644 --- a/internal/generator/factory_test.go +++ b/internal/generator/factory_test.go @@ -10,6 +10,7 @@ import ( "github.com/CustomResourceDefinition/catalog/internal/configuration" "github.com/CustomResourceDefinition/catalog/internal/crd" "github.com/CustomResourceDefinition/catalog/internal/registry" + "github.com/CustomResourceDefinition/catalog/internal/timing" "github.com/stretchr/testify/assert" ) @@ -381,3 +382,89 @@ func TestBuildRunsWhenChanged(t *testing.T) { assert.Equal(t, "http", entry.Kind) assert.Equal(t, "1.0.0", entry.Version) } + +func TestBuildRecordsStats(t *testing.T) { + b, err := os.ReadFile("testdata/test-crd.yaml") + assert.Nil(t, err) + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + w.Write(b) + })) + defer server.Close() + + config := configuration.Configuration{ + Kind: configuration.Http, + Name: "test", + ApiGroups: []string{"chart.uri"}, + Downloads: []configuration.ConfigurationDownload{ + { + BaseUri: server.URL, + Version: "1.0.0", + Paths: []string{"any"}, + }, + }, + } + + reader, err := crd.NewCrdReader(setupLogger()) + assert.Nil(t, err) + + tmpDir := t.TempDir() + + builder, err := NewBuilder(config, reader, tmpDir, tmpDir, tmpDir, setupLogger(), nil) + assert.Nil(t, err) + + assert.NotNil(t, builder.Stats()) + + err = builder.Build() + assert.Nil(t, err) + + stats := builder.Stats() + assert.Greater(t, stats.TotalOperations(), 0) + assert.Greater(t, int(stats.TotalTime()), 0) + + httpOps := stats.GetCategoryStats(timing.CategoryHTTP) + assert.NotNil(t, httpOps) + assert.NotEmpty(t, httpOps) + + genOps := stats.GetCategoryStats(timing.CategoryGeneration) + assert.NotNil(t, genOps) + assert.NotEmpty(t, genOps) +} + +func TestOperationCategory(t *testing.T) { + tests := []struct { + kind configuration.Kind + expected timing.Category + }{ + {kind: configuration.Git, expected: timing.CategoryGit}, + {kind: configuration.Http, expected: timing.CategoryHTTP}, + {kind: configuration.Helm, expected: timing.CategoryHelm}, + {kind: configuration.HelmOci, expected: timing.CategoryOCI}, + {kind: configuration.Kind("unknown"), expected: timing.CategoryMisc}, + } + + for _, tt := range tests { + config := configuration.Configuration{ + Kind: tt.kind, + Name: "test", + Downloads: []configuration.ConfigurationDownload{{Version: "1.0.0"}}, + } + + builder := &Builder{config: config} + result := builder.operationCategory() + assert.Equal(t, tt.expected, result, "kind: %s", tt.kind) + } +} + +func TestStatsInitialized(t *testing.T) { + config := configuration.Configuration{ + Kind: configuration.Http, + Name: "test", + Downloads: []configuration.ConfigurationDownload{{Version: "1.0.0"}}, + } + + builder, err := NewBuilder(config, nil, "-", "-", "-", nil, nil) + assert.Nil(t, err) + assert.NotNil(t, builder.stats) +} diff --git a/internal/timing/stats.go b/internal/timing/stats.go new file mode 100644 index 000000000..50a2f9ef3 --- /dev/null +++ b/internal/timing/stats.go @@ -0,0 +1,294 @@ +package timing + +import ( + "context" + "fmt" + "sort" + "strings" + "sync" + "time" +) + +type Category string + +const ( + CategoryHTTP Category = "http" + CategoryGit Category = "git" + CategoryHelm Category = "helm" + CategoryOCI Category = "oci" + CategoryGeneration Category = "generation" + CategoryMisc Category = "misc" +) + +type OperationType string + +const ( + OperationTypeFetch OperationType = "fetch" + OperationTypeGenerate OperationType = "generate" + OperationTypeDownload OperationType = "download" + OperationTypeRender OperationType = "render" + OperationTypeAPIFetch OperationType = "api_fetch" + OperationTypeClone OperationType = "clone" + OperationTypeCheckout OperationType = "checkout" + OperationTypeSubmodule OperationType = "submodule" + OperationTypeTags OperationType = "tags" + OperationTypeBranches OperationType = "branches" + OperationTypeWrite OperationType = "write" + OperationTypeStatus OperationType = "status" + OperationTypeUpdate OperationType = "update" + OperationTypePull OperationType = "pull" + OperationTypeAuth OperationType = "auth" + OperationTypeIndex OperationType = "index" +) + +type Operation struct { + Category Category + Type OperationType + Name string + Duration time.Duration + Success bool + StartTime time.Time +} + +type categoryStats struct { + operations []Operation + mu sync.RWMutex +} + +type Stats struct { + categories map[Category]*categoryStats + totalTime time.Duration + totalOps int + mu sync.RWMutex +} + +var contextKey = struct{}{} + +func NewStats() *Stats { + return &Stats{ + categories: make(map[Category]*categoryStats), + } +} + +func FromContext(ctx context.Context) (*Stats, bool) { + s, ok := ctx.Value(contextKey).(*Stats) + return s, ok +} + +func WithContext(ctx context.Context, stats *Stats) context.Context { + return context.WithValue(ctx, contextKey, stats) +} + +func (s *Stats) Record(category Category, opType OperationType, name string, duration time.Duration, success bool) { + s.mu.Lock() + defer s.mu.Unlock() + + s.totalTime += duration + s.totalOps++ + + cat, ok := s.categories[category] + if !ok { + cat = &categoryStats{} + s.categories[category] = cat + } + + cat.mu.Lock() + defer cat.mu.Unlock() + + cat.operations = append(cat.operations, Operation{ + Category: category, + Type: opType, + Name: name, + Duration: duration, + Success: success, + StartTime: time.Now().Add(-duration), + }) +} + +func (s *Stats) RecordFunc(category Category, opType OperationType, name string, success bool, fn func() error) error { + start := time.Now() + err := fn() + duration := time.Since(start) + s.Record(category, opType, name, duration, err == nil) + return err +} + +func (s *Stats) GetCategoryStats(category Category) []Operation { + s.mu.RLock() + defer s.mu.RUnlock() + + cat, ok := s.categories[category] + if !ok { + return nil + } + + cat.mu.RLock() + defer cat.mu.RUnlock() + + result := make([]Operation, len(cat.operations)) + copy(result, cat.operations) + return result +} + +func (s *Stats) TotalTime() time.Duration { + s.mu.RLock() + defer s.mu.RUnlock() + return s.totalTime +} + +func (s *Stats) TotalOperations() int { + s.mu.RLock() + defer s.mu.RUnlock() + return s.totalOps +} + +func (s *Stats) RecordDuration(category Category, opType OperationType, name string) func() { + start := time.Now() + return func() { + s.Record(category, opType, name, time.Since(start), true) + } +} + +func calculatePercentiles(durations []float64, ps []float64) map[float64]time.Duration { + if len(durations) == 0 { + return nil + } + + sorted := make([]float64, len(durations)) + copy(sorted, durations) + sort.Float64s(sorted) + + result := make(map[float64]time.Duration) + for _, p := range ps { + idx := int(float64(len(sorted)) * p) + if idx >= len(sorted) { + idx = len(sorted) - 1 + } + if idx < 0 { + idx = 0 + } + result[p] = time.Duration(sorted[idx] * float64(time.Second)) + } + return result +} + +func findWorst(durations []float64) (int, time.Duration) { + if len(durations) == 0 { + return -1, 0 + } + + maxIdx := 0 + maxVal := durations[0] + for i, v := range durations { + if v > maxVal { + maxVal = v + maxIdx = i + } + } + return maxIdx, time.Duration(maxVal * float64(time.Second)) +} + +func sanitizeName(name string) string { + name = strings.ReplaceAll(name, "/", "_") + name = strings.ReplaceAll(name, ":", "_") + name = strings.ReplaceAll(name, ".", "_") + name = strings.ReplaceAll(name, "-", "_") + name = strings.ReplaceAll(name, " ", "_") + return name +} + +func formatDuration(d time.Duration) string { + if d < time.Millisecond { + return fmt.Sprintf("%.0fµs", float64(d.Microseconds())) + } + if d < time.Second { + return fmt.Sprintf("%.0fms", float64(d.Milliseconds())) + } + if d < time.Minute { + return fmt.Sprintf("%.1fs", d.Seconds()) + } + if d < time.Hour { + m := d.Minutes() + if m < 10 { + return fmt.Sprintf("%.1fm", m) + } + return fmt.Sprintf("%.0fm", m) + } + h := d.Hours() + return fmt.Sprintf("%.1fh", h) +} + +func (s *Stats) PrintSummary() { + s.mu.RLock() + defer s.mu.RUnlock() + + fmt.Printf("\n=== Update Statistics ===\n\n") + fmt.Printf("Overall: %s (%d operations)\n\n", formatDuration(s.totalTime), s.totalOps) + + categoryOrder := []Category{CategoryHTTP, CategoryGit, CategoryHelm, CategoryOCI, CategoryGeneration, CategoryMisc} + + for _, cat := range categoryOrder { + catStats, ok := s.categories[cat] + if !ok { + continue + } + + catStats.mu.RLock() + ops := catStats.operations + catStats.mu.RUnlock() + + if len(ops) == 0 { + continue + } + + typeStats := make(map[OperationType][]time.Duration) + + for _, op := range ops { + typeStats[op.Type] = append(typeStats[op.Type], op.Duration) + } + + fmt.Printf("%s:\n", strings.ToUpper(string(cat)[:1])+string(cat)[1:]) + + for opType, durations := range typeStats { + if len(durations) == 0 { + continue + } + + var total time.Duration + durationsSecs := make([]float64, len(durations)) + for i, d := range durations { + total += d + durationsSecs[i] = d.Seconds() + } + + percs := calculatePercentiles(durationsSecs, []float64{0.75, 0.90, 0.95}) + + typeLabel := string(opType) + fmt.Printf(" %-10s %4d operations total: %s", + typeLabel+":", + len(durations), + formatDuration(total), + ) + + if len(percs) > 0 { + fmt.Printf(" p75: %s p90: %s p95: %s", + formatDuration(percs[0.75]), + formatDuration(percs[0.90]), + formatDuration(percs[0.95]), + ) + } + fmt.Println() + + worstIdx, worstDur := findWorst(durationsSecs) + if worstIdx >= 0 { + for _, op := range ops { + if op.Type == opType && op.Duration == worstDur { + fmt.Printf(" Worst: %s (%s)\n", op.Name, formatDuration(worstDur)) + break + } + } + } + } + fmt.Println() + } +} diff --git a/internal/timing/stats_test.go b/internal/timing/stats_test.go new file mode 100644 index 000000000..bd8cfc389 --- /dev/null +++ b/internal/timing/stats_test.go @@ -0,0 +1,274 @@ +package timing + +import ( + "context" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func TestNewStats(t *testing.T) { + s := NewStats() + assert.NotNil(t, s) + assert.Zero(t, s.TotalTime()) + assert.Zero(t, s.TotalOperations()) +} + +func TestRecord(t *testing.T) { + s := NewStats() + + s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true) + + 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, "test-op", ops[0].Name) + assert.Equal(t, 100*time.Millisecond, ops[0].Duration) + assert.True(t, ops[0].Success) +} + +func TestRecordMultipleCategories(t *testing.T) { + s := NewStats() + + s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 50*time.Millisecond, true) + s.Record(CategoryGit, OperationTypeClone, "git-op", 100*time.Millisecond, true) + s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 75*time.Millisecond, true) + + assert.Equal(t, 3, s.TotalOperations()) + assert.Equal(t, 225*time.Millisecond, s.TotalTime()) + + assert.Len(t, s.GetCategoryStats(CategoryHTTP), 1) + assert.Len(t, s.GetCategoryStats(CategoryGit), 1) + assert.Len(t, s.GetCategoryStats(CategoryHelm), 1) +} + +func TestRecordMultipleOperationsSameCategory(t *testing.T) { + s := NewStats() + + s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true) + s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true) + s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true) + + ops := s.GetCategoryStats(CategoryHTTP) + assert.Len(t, ops, 3) +} + +func TestRecordFailure(t *testing.T) { + s := NewStats() + + s.Record(CategoryHTTP, OperationTypeFetch, "failed-op", 100*time.Millisecond, false) + + ops := s.GetCategoryStats(CategoryHTTP) + assert.Len(t, ops, 1) + assert.False(t, ops[0].Success) +} + +func TestGetCategoryStatsEmpty(t *testing.T) { + s := NewStats() + + ops := s.GetCategoryStats(CategoryHTTP) + assert.Nil(t, ops) +} + +func TestGetCategoryStatsUnknownCategory(t *testing.T) { + s := NewStats() + s.Record(CategoryHTTP, OperationTypeFetch, "test", 100*time.Millisecond, true) + + ops := s.GetCategoryStats(CategoryOCI) + assert.Nil(t, ops) +} + +func TestFromContext(t *testing.T) { + s := NewStats() + ctx := WithContext(context.Background(), s) + + retrieved, ok := FromContext(ctx) + assert.True(t, ok) + assert.Equal(t, s, retrieved) +} + +func TestFromContextNotPresent(t *testing.T) { + ctx := context.Background() + + _, ok := FromContext(ctx) + assert.False(t, ok) +} + +func TestRecordFunc(t *testing.T) { + s := NewStats() + + err := s.RecordFunc(CategoryHTTP, OperationTypeFetch, "test-op", true, func() error { + time.Sleep(10 * time.Millisecond) + return nil + }) + + assert.NoError(t, err) + assert.Equal(t, 1, s.TotalOperations()) + assert.GreaterOrEqual(t, s.TotalTime(), 10*time.Millisecond) +} + +func TestRecordFuncWithError(t *testing.T) { + s := NewStats() + + err := s.RecordFunc(CategoryHTTP, OperationTypeFetch, "test-op", false, func() error { + time.Sleep(10 * time.Millisecond) + return assert.AnError + }) + + assert.Error(t, err) + + ops := s.GetCategoryStats(CategoryHTTP) + assert.Len(t, ops, 1) + assert.False(t, ops[0].Success) +} + +func TestCalculatePercentiles(t *testing.T) { + durations := []float64{10, 20, 30, 40, 50, 60, 70, 80, 90, 100} + + result := calculatePercentiles(durations, []float64{0.75, 0.90, 0.95}) + + assert.NotNil(t, result) + assert.Equal(t, 80*time.Second, result[0.75]) + assert.Equal(t, 100*time.Second, result[0.90]) + assert.Equal(t, 100*time.Second, result[0.95]) +} + +func TestCalculatePercentilesEmpty(t *testing.T) { + result := calculatePercentiles([]float64{}, []float64{0.75}) + assert.Nil(t, result) +} + +func TestCalculatePercentilesSingle(t *testing.T) { + result := calculatePercentiles([]float64{50}, []float64{0.75, 0.90, 0.95}) + + assert.NotNil(t, result) + assert.Equal(t, 50*time.Second, result[0.75]) + assert.Equal(t, 50*time.Second, result[0.90]) + assert.Equal(t, 50*time.Second, result[0.95]) +} + +func TestFindWorst(t *testing.T) { + durations := []float64{10, 20, 30, 40, 50} + + idx, dur := findWorst(durations) + + assert.Equal(t, 4, idx) + assert.Equal(t, 50*time.Second, dur) +} + +func TestFindWorstEmpty(t *testing.T) { + idx, dur := findWorst([]float64{}) + + assert.Equal(t, -1, idx) + assert.Zero(t, dur) +} + +func TestSanitizeName(t *testing.T) { + tests := []struct { + input string + expected string + }{ + {"simple", "simple"}, + {"with/slash", "with_slash"}, + {"with:colon", "with_colon"}, + {"with.dot", "with_dot"}, + {"with-dash", "with_dash"}, + {"with space", "with_space"}, + {"mixed/slash:colon.dash-dash", "mixed_slash_colon_dash_dash"}, + } + + for _, tt := range tests { + result := sanitizeName(tt.input) + assert.Equal(t, tt.expected, result, "input: %s", tt.input) + } +} + +func TestFormatDuration(t *testing.T) { + tests := []struct { + input time.Duration + expected string + }{ + {100 * time.Microsecond, "100µs"}, + {500 * time.Microsecond, "500µs"}, + {100 * time.Millisecond, "100ms"}, + {500 * time.Millisecond, "500ms"}, + {1500 * time.Millisecond, "1.5s"}, + {10 * time.Second, "10.0s"}, + {90 * time.Second, "1.5m"}, + {5 * time.Minute, "5.0m"}, + {10 * time.Minute, "10m"}, + {90 * time.Minute, "1.5h"}, + {2 * time.Hour, "2.0h"}, + } + + for _, tt := range tests { + result := formatDuration(tt.input) + assert.Equal(t, tt.expected, result, "input: %v", tt.input) + } +} + +func TestPrintSummaryEmpty(t *testing.T) { + s := NewStats() + + s.PrintSummary() +} + +func TestPrintSummaryWithData(t *testing.T) { + s := NewStats() + + s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true) + s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true) + s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true) + s.Record(CategoryGit, OperationTypeClone, "repo1", 100*time.Millisecond, true) + s.Record(CategoryGit, OperationTypeClone, "repo2", 200*time.Millisecond, true) + + s.PrintSummary() +} + +func TestPrintSummaryAllCategories(t *testing.T) { + s := NewStats() + + s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 10*time.Millisecond, true) + s.Record(CategoryGit, OperationTypeClone, "git-op", 20*time.Millisecond, true) + s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 30*time.Millisecond, true) + s.Record(CategoryOCI, OperationTypePull, "oci-op", 40*time.Millisecond, true) + s.Record(CategoryGeneration, OperationTypeWrite, "gen-op", 50*time.Millisecond, true) + s.Record(CategoryMisc, OperationTypeUpdate, "misc-op", 60*time.Millisecond, true) + + s.PrintSummary() +} + +func TestRecordDuration(t *testing.T) { + s := NewStats() + + stop := s.RecordDuration(CategoryHTTP, OperationTypeFetch, "test-op") + time.Sleep(10 * time.Millisecond) + stop() + + ops := s.GetCategoryStats(CategoryHTTP) + assert.Len(t, ops, 1) + assert.Equal(t, "test-op", ops[0].Name) + assert.GreaterOrEqual(t, ops[0].Duration, 10*time.Millisecond) +} + +func TestConcurrentRecording(t *testing.T) { + s := NewStats() + + var wg sync.WaitGroup + for i := 0; i < 100; i++ { + wg.Add(1) + go func(n int) { + defer wg.Done() + s.Record(CategoryHTTP, OperationTypeFetch, "op", time.Duration(n)*time.Millisecond, true) + }(i) + } + wg.Wait() + + assert.Equal(t, 100, s.TotalOperations()) + assert.Len(t, s.GetCategoryStats(CategoryHTTP), 100) +} From 85b94a91e2eac1dfc8a2e05da21f890c529f72ca Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 18:17:35 +0100 Subject: [PATCH 02/14] tmp --- internal/command/updater.go | 23 ++++--- internal/command/updater_test.go | 65 ++++++++++++++++--- internal/generator/factory.go | 14 +++-- internal/timing/stats.go | 92 ++++++++++++++------------- internal/timing/stats_test.go | 104 +++++++++++++++++++------------ main.go | 4 +- make.d/check.mk | 2 +- 7 files changed, 198 insertions(+), 106 deletions(-) diff --git a/internal/command/updater.go b/internal/command/updater.go index 596d21e1e..b4b1ff836 100644 --- a/internal/command/updater.go +++ b/internal/command/updater.go @@ -23,16 +23,18 @@ type Updater struct { reader crd.CrdReader registry *registry.SourceRegistry registryPath string + performanceLog string } -func NewUpdater(configuration, schema, definitions, registryPath string, logger io.Writer, flags *flag.FlagSet) Updater { +func NewUpdater(configuration, schema, definitions, registryPath, performancePath string, logger io.Writer, flags *flag.FlagSet) Updater { return Updater{ - flags: flags, - Configuration: configuration, - Schema: schema, - Definitions: definitions, - registryPath: registryPath, - Logger: logger, + flags: flags, + Configuration: configuration, + Schema: schema, + Definitions: definitions, + registryPath: registryPath, + Logger: logger, + performanceLog: performancePath, } } @@ -71,6 +73,11 @@ func (cmd Updater) Run() error { 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) { runtime.GC() @@ -100,7 +107,7 @@ func (cmd Updater) Run() error { } } - totalStats.PrintSummary() + totalStats.PrintSummary(cmd.Logger) return merge(tmpDir, cmd.Schema) } diff --git a/internal/command/updater_test.go b/internal/command/updater_test.go index d5766ead2..cccbedda1 100644 --- a/internal/command/updater_test.go +++ b/internal/command/updater_test.go @@ -17,7 +17,7 @@ func TestRun(t *testing.T) { server, config, tmpDir := setup(t) defer server.Close() - updater := NewUpdater(config, tmpDir, tmpDir, "", bytes.NewBuffer([]byte{}), nil) + updater := NewUpdater(config, tmpDir, tmpDir, "", "", bytes.NewBuffer([]byte{}), nil) err := updater.Run() assert.Nil(t, err) @@ -221,7 +221,7 @@ func TestRunWithRegistryLoadError(t *testing.T) { registryPath := path.Join(tmpDir, "registry.yaml") os.WriteFile(registryPath, []byte("invalid: yaml: content:"), 0644) - updater := NewUpdater(unused, tmpDir, tmpDir, registryPath, bytes.NewBuffer([]byte{}), nil) + updater := NewUpdater(unused, tmpDir, tmpDir, registryPath, "", bytes.NewBuffer([]byte{}), nil) err := updater.Run() assert.NotNil(t, err) @@ -236,7 +236,7 @@ func TestRunWithRegistrySavesUpdates(t *testing.T) { initialContent := "sources: {}\n" os.WriteFile(registryPath, []byte(initialContent), 0664) - updater := NewUpdater(config, tmpDir, tmpDir, registryPath, bytes.NewBuffer([]byte{}), nil) + updater := NewUpdater(config, tmpDir, tmpDir, registryPath, "", bytes.NewBuffer([]byte{}), nil) err := updater.Run() assert.Nil(t, err) @@ -269,7 +269,7 @@ func TestRunWithRegistryRemovesStaleEntries(t *testing.T) { ` os.WriteFile(registryPath, []byte(initialContent), 0664) - updater := NewUpdater(config, tmpDir, tmpDir, registryPath, bytes.NewBuffer([]byte{}), nil) + updater := NewUpdater(config, tmpDir, tmpDir, registryPath, "", bytes.NewBuffer([]byte{}), nil) err := updater.Run() assert.Nil(t, err) @@ -287,7 +287,7 @@ func TestRunWithRegistryRemovesStaleEntries(t *testing.T) { func TestCheckLocal(t *testing.T) { output := "../../build/ephemeral/schema" config := "../../build/configuration.yaml" - updater := NewUpdater(config, output, output, "", nil, nil) + updater := NewUpdater(config, output, output, "", "", nil, nil) err := updater.Run() assert.Nil(t, err) @@ -321,13 +321,17 @@ func TestRunAggregatesStats(t *testing.T) { os.WriteFile(config, []byte(strings.ReplaceAll(template, "{{ server }}", server.URL)), 0664) output := bytes.NewBuffer([]byte{}) - updater := NewUpdater(config, tmpDir, tmpDir, "", output, nil) + updater := NewUpdater(config, tmpDir, tmpDir, "", "", output, nil) err = updater.Run() assert.Nil(t, err) outStr := output.String() - assert.NotEmpty(t, outStr) + assert.Contains(t, outStr, "Update Statistics") + assert.Contains(t, outStr, "Overall:") + assert.Contains(t, outStr, "operations") + assert.Contains(t, outStr, "Http:") + assert.Contains(t, outStr, "api_fetch") } func TestRunWithMultipleConfigsAggregatesStats(t *testing.T) { @@ -366,8 +370,53 @@ func TestRunWithMultipleConfigsAggregatesStats(t *testing.T) { os.WriteFile(config, []byte(strings.ReplaceAll(template, "{{ server }}", server.URL)), 0664) output := bytes.NewBuffer([]byte{}) - updater := NewUpdater(config, tmpDir, tmpDir, "", output, nil) + updater := NewUpdater(config, tmpDir, tmpDir, "", "", output, nil) err = updater.Run() assert.Nil(t, err) + + outStr := output.String() + assert.Contains(t, outStr, "Overall:") + assert.Contains(t, outStr, "api_fetch") +} + +func TestRunWithPerformanceLog(t *testing.T) { + b, err := os.ReadFile("testdata/updater/multiple.yaml") + assert.Nil(t, err) + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + w.Write(b) + })) + defer server.Close() + + template := ` +- apiGroups: + - chart.uri + crds: + - baseUri: {{ server }} + paths: + - chart-1.0.0.yaml + version: 1.0.0 + kind: http + name: http +` + tmpDir := t.TempDir() + + config := path.Join(tmpDir, "config.yaml") + os.WriteFile(config, []byte(strings.ReplaceAll(template, "{{ server }}", server.URL)), 0664) + + logPath := path.Join(tmpDir, "perf.log") + + output := bytes.NewBuffer([]byte{}) + updater := NewUpdater(config, tmpDir, tmpDir, "", logPath, output, nil) + + err = updater.Run() + assert.Nil(t, err) + + perfContent, err := os.ReadFile(logPath) + assert.Nil(t, err) + assert.NotEmpty(t, string(perfContent)) + assert.Contains(t, string(perfContent), "http") + assert.Contains(t, string(perfContent), "api_fetch") } diff --git a/internal/generator/factory.go b/internal/generator/factory.go index 6f1dae378..b419953d2 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -192,33 +192,35 @@ func (builder Builder) extractSchemas(logger io.Writer, crds []crd.Crd) []crd.Cr func (builder Builder) writeDefinitions(crds []crd.Crd) { fmt.Fprintf(builder.logger, " - - rendered %d definitions.\n", len(crds)) - var writeDuration time.Duration + var duration time.Duration for _, crd := range crds { file := path.Join(builder.definitionRepository, crd.Filepath()) os.MkdirAll(path.Dir(file), 0755) + start := time.Now() if err := os.WriteFile(file, crd.Bytes, 0644); err != nil { return } - writeDuration += time.Second + duration += time.Since(start) } if len(crds) > 0 { - builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "definitions", writeDuration, true) + builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "definitions", duration, true) } } func (builder Builder) writeSchemas(schemas []crd.CrdSchema) { fmt.Fprintf(builder.logger, " - - rendered %d schema.\n", len(schemas)) - schemaWriteDuration := time.Duration(0) + var duration time.Duration for _, schema := range schemas { file := path.Join(builder.generatedRepository, schema.Filepath()) os.MkdirAll(path.Dir(file), 0755) + start := time.Now() if err := os.WriteFile(file, schema.Bytes, 0644); err != nil { return } - schemaWriteDuration += time.Second + duration += time.Since(start) } if len(schemas) > 0 { - builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "schemas", schemaWriteDuration, true) + builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "schemas", duration, true) } } diff --git a/internal/timing/stats.go b/internal/timing/stats.go index 50a2f9ef3..72a89a327 100644 --- a/internal/timing/stats.go +++ b/internal/timing/stats.go @@ -3,6 +3,8 @@ package timing import ( "context" "fmt" + "io" + "os" "sort" "strings" "sync" @@ -60,6 +62,8 @@ type Stats struct { totalTime time.Duration totalOps int mu sync.RWMutex + logFile *os.File + logMu sync.Mutex } var contextKey = struct{}{} @@ -79,6 +83,26 @@ func WithContext(ctx context.Context, stats *Stats) context.Context { return context.WithValue(ctx, contextKey, stats) } +func (s *Stats) OpenLogFile(path string) error { + if path == "" { + return nil + } + + f, err := os.Create(path) + if err != nil { + return err + } + s.logFile = f + return nil +} + +func (s *Stats) CloseLogFile() { + if s.logFile != nil { + s.logFile.Close() + s.logFile = nil + } +} + func (s *Stats) Record(category Category, opType OperationType, name string, duration time.Duration, success bool) { s.mu.Lock() defer s.mu.Unlock() @@ -103,6 +127,23 @@ func (s *Stats) Record(category Category, opType OperationType, name string, dur Success: success, StartTime: time.Now().Add(-duration), }) + + if s.logFile != nil { + successStr := "success" + if !success { + successStr = "failure" + } + s.logMu.Lock() + defer s.logMu.Unlock() + fmt.Fprintf(s.logFile, "%s %s %s %s %s (%s)\n", + time.Now().Format(time.RFC3339), + category, + opType, + name, + formatDuration(duration), + successStr, + ) + } } func (s *Stats) RecordFunc(category Category, opType OperationType, name string, success bool, fn func() error) error { @@ -172,31 +213,6 @@ func calculatePercentiles(durations []float64, ps []float64) map[float64]time.Du return result } -func findWorst(durations []float64) (int, time.Duration) { - if len(durations) == 0 { - return -1, 0 - } - - maxIdx := 0 - maxVal := durations[0] - for i, v := range durations { - if v > maxVal { - maxVal = v - maxIdx = i - } - } - return maxIdx, time.Duration(maxVal * float64(time.Second)) -} - -func sanitizeName(name string) string { - name = strings.ReplaceAll(name, "/", "_") - name = strings.ReplaceAll(name, ":", "_") - name = strings.ReplaceAll(name, ".", "_") - name = strings.ReplaceAll(name, "-", "_") - name = strings.ReplaceAll(name, " ", "_") - return name -} - func formatDuration(d time.Duration) string { if d < time.Millisecond { return fmt.Sprintf("%.0fµs", float64(d.Microseconds())) @@ -218,12 +234,12 @@ func formatDuration(d time.Duration) string { return fmt.Sprintf("%.1fh", h) } -func (s *Stats) PrintSummary() { +func (s *Stats) PrintSummary(writer io.Writer) { s.mu.RLock() defer s.mu.RUnlock() - fmt.Printf("\n=== Update Statistics ===\n\n") - fmt.Printf("Overall: %s (%d operations)\n\n", formatDuration(s.totalTime), s.totalOps) + fmt.Fprintf(writer, "\n=== Update 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} @@ -247,7 +263,7 @@ func (s *Stats) PrintSummary() { typeStats[op.Type] = append(typeStats[op.Type], op.Duration) } - fmt.Printf("%s:\n", strings.ToUpper(string(cat)[:1])+string(cat)[1:]) + fmt.Fprintf(writer, "%s:\n", strings.ToUpper(string(cat)[:1])+string(cat)[1:]) for opType, durations := range typeStats { if len(durations) == 0 { @@ -264,31 +280,21 @@ func (s *Stats) PrintSummary() { percs := calculatePercentiles(durationsSecs, []float64{0.75, 0.90, 0.95}) typeLabel := string(opType) - fmt.Printf(" %-10s %4d operations total: %s", + fmt.Fprintf(writer, " %-10s %4d operations total: %s", typeLabel+":", len(durations), formatDuration(total), ) if len(percs) > 0 { - fmt.Printf(" p75: %s p90: %s p95: %s", + fmt.Fprintf(writer, " p75: %s p90: %s p95: %s", formatDuration(percs[0.75]), formatDuration(percs[0.90]), formatDuration(percs[0.95]), ) } - fmt.Println() - - worstIdx, worstDur := findWorst(durationsSecs) - if worstIdx >= 0 { - for _, op := range ops { - if op.Type == opType && op.Duration == worstDur { - fmt.Printf(" Worst: %s (%s)\n", op.Name, formatDuration(worstDur)) - break - } - } - } + fmt.Fprintln(writer) } - fmt.Println() + fmt.Fprintln(writer) } } diff --git a/internal/timing/stats_test.go b/internal/timing/stats_test.go index bd8cfc389..60bfecd11 100644 --- a/internal/timing/stats_test.go +++ b/internal/timing/stats_test.go @@ -2,6 +2,9 @@ package timing import ( "context" + "io" + "os" + "strings" "sync" "testing" "time" @@ -152,42 +155,6 @@ func TestCalculatePercentilesSingle(t *testing.T) { assert.Equal(t, 50*time.Second, result[0.95]) } -func TestFindWorst(t *testing.T) { - durations := []float64{10, 20, 30, 40, 50} - - idx, dur := findWorst(durations) - - assert.Equal(t, 4, idx) - assert.Equal(t, 50*time.Second, dur) -} - -func TestFindWorstEmpty(t *testing.T) { - idx, dur := findWorst([]float64{}) - - assert.Equal(t, -1, idx) - assert.Zero(t, dur) -} - -func TestSanitizeName(t *testing.T) { - tests := []struct { - input string - expected string - }{ - {"simple", "simple"}, - {"with/slash", "with_slash"}, - {"with:colon", "with_colon"}, - {"with.dot", "with_dot"}, - {"with-dash", "with_dash"}, - {"with space", "with_space"}, - {"mixed/slash:colon.dash-dash", "mixed_slash_colon_dash_dash"}, - } - - for _, tt := range tests { - result := sanitizeName(tt.input) - assert.Equal(t, tt.expected, result, "input: %s", tt.input) - } -} - func TestFormatDuration(t *testing.T) { tests := []struct { input time.Duration @@ -215,7 +182,7 @@ func TestFormatDuration(t *testing.T) { func TestPrintSummaryEmpty(t *testing.T) { s := NewStats() - s.PrintSummary() + s.PrintSummary(io.Discard) } func TestPrintSummaryWithData(t *testing.T) { @@ -227,7 +194,7 @@ func TestPrintSummaryWithData(t *testing.T) { s.Record(CategoryGit, OperationTypeClone, "repo1", 100*time.Millisecond, true) s.Record(CategoryGit, OperationTypeClone, "repo2", 200*time.Millisecond, true) - s.PrintSummary() + s.PrintSummary(io.Discard) } func TestPrintSummaryAllCategories(t *testing.T) { @@ -240,7 +207,7 @@ func TestPrintSummaryAllCategories(t *testing.T) { s.Record(CategoryGeneration, OperationTypeWrite, "gen-op", 50*time.Millisecond, true) s.Record(CategoryMisc, OperationTypeUpdate, "misc-op", 60*time.Millisecond, true) - s.PrintSummary() + s.PrintSummary(io.Discard) } func TestRecordDuration(t *testing.T) { @@ -272,3 +239,62 @@ func TestConcurrentRecording(t *testing.T) { assert.Equal(t, 100, s.TotalOperations()) assert.Len(t, s.GetCategoryStats(CategoryHTTP), 100) } + +func TestOpenLogFileEmpty(t *testing.T) { + s := NewStats() + + err := s.OpenLogFile("") + assert.NoError(t, err) + assert.Nil(t, s.logFile) +} + +func TestOpenLogFile(t *testing.T) { + s := NewStats() + + tmpFile := t.TempDir() + "/perf.log" + err := s.OpenLogFile(tmpFile) + assert.NoError(t, err) + assert.NotNil(t, s.logFile) + + s.CloseLogFile() + + _, err = os.Stat(tmpFile) + assert.NoError(t, err) +} + +func TestOpenLogFileThenRecord(t *testing.T) { + s := NewStats() + + tmpFile := t.TempDir() + "/perf.log" + err := s.OpenLogFile(tmpFile) + assert.NoError(t, err) + + s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true) + s.CloseLogFile() + + content, err := os.ReadFile(tmpFile) + assert.NoError(t, err) + assert.Contains(t, string(content), "http") + assert.Contains(t, string(content), "fetch") + assert.Contains(t, string(content), "test-op") +} + +func TestOpenLogFileInvalidPath(t *testing.T) { + s := NewStats() + + err := s.OpenLogFile("/invalid/path/that/does/not/exist/perf.log") + assert.Error(t, err) +} + +func TestPrintSummaryWriter(t *testing.T) { + s := NewStats() + + s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true) + + var buf strings.Builder + s.PrintSummary(&buf) + + assert.Contains(t, buf.String(), "Update Statistics") + assert.Contains(t, buf.String(), "Overall:") + assert.Contains(t, buf.String(), "Http:") +} diff --git a/main.go b/main.go index 8ee6216e5..b54b00c7a 100644 --- a/main.go +++ b/main.go @@ -55,12 +55,14 @@ func parse(args []string, logger io.Writer) (command.Command, error) { schema := cmd.String("output", "", "Path of directory for openapi schema output files") definitions := cmd.String("definitions", "", "Path of directory for definition output files") registry := cmd.String("registry", "", "Path to registry file for tracking source versions") + performance := cmd.String("performance-log", "", "Path to performance log file") cmd.SetOutput(logger) err := cmd.Parse(args[2:]) if err != nil { return nil, err } - return command.NewUpdater(*configuration, *schema, *definitions, *registry, logger, cmd), nil + updater := command.NewUpdater(*configuration, *schema, *definitions, *registry, *performance, logger, cmd) + return updater, nil case commandVerify: cmd := flag.NewFlagSet(commandVerify, flag.ContinueOnError) schema := cmd.String("schema", "", "Path of jsonschema file to use") diff --git a/make.d/check.mk b/make.d/check.mk index d0328169a..b01280640 100644 --- a/make.d/check.mk +++ b/make.d/check.mk @@ -2,4 +2,4 @@ check: build/bin/catalog -find build/ephemeral -not -name ".gitignore" -and -not -name ".gitkeep" -type f -delete -find build/ephemeral -type d -empty -delete touch build/configuration.yaml - build/bin/catalog update --configuration build/configuration.yaml --output build/ephemeral/schema --definitions build/ephemeral/schema + build/bin/catalog update --configuration build/configuration.yaml --output build/ephemeral/schema --definitions build/ephemeral/schema --performance-log build/ephemeral/perf.log From 01909319598fd6150011e2e6c4b3448d729f4398 Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 20:40:12 +0100 Subject: [PATCH 03/14] tmp --- internal/command/updater.go | 8 +-- internal/generator/factory.go | 39 ++++++---- internal/timing/stats.go | 131 ++++++++++++++-------------------- internal/timing/stats_test.go | 104 ++++++--------------------- 4 files changed, 105 insertions(+), 177 deletions(-) diff --git a/internal/command/updater.go b/internal/command/updater.go index b4b1ff836..0e0423406 100644 --- a/internal/command/updater.go +++ b/internal/command/updater.go @@ -94,13 +94,13 @@ func (cmd Updater) Run() error { } stats := build.Stats() - for _, cat := range []timing.Category{timing.CategoryHTTP, timing.CategoryGit, timing.CategoryHelm, timing.CategoryOCI, timing.CategoryGeneration, timing.CategoryMisc} { - for _, op := range stats.GetCategoryStats(cat) { - totalStats.Record(op.Category, op.Type, op.Name, op.Duration, op.Success) - } + for _, op := range stats.GetAllStats() { + totalStats.Record(op.Category, op.Type, op.Name, op.Duration, op.Success, op.StartTime) } } + totalStats.Flush() + if cmd.registry != nil && cmd.registryPath != "" { if err := cmd.registry.Save(cmd.registryPath); err != nil { fmt.Fprintf(cmd.Logger, "::warning:: failed to save registry: %v\n", err) diff --git a/internal/generator/factory.go b/internal/generator/factory.go index b419953d2..9de79a3bc 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -71,9 +71,9 @@ func (builder Builder) Build() error { } defer fmt.Fprintf(logger, "End.\n") - stop := builder.stats.RecordDuration(timing.CategoryMisc, timing.OperationTypeStatus, "registry_status") + start := time.Now() latestVersion, isUpdated, err := builder.registryStatus() - stop() + builder.stats.Record(timing.CategoryMisc, timing.OperationTypeStatus, "registry_status", time.Since(start), err == nil, start) if err != nil { return err } @@ -103,15 +103,16 @@ func (builder Builder) Build() error { for _, version := range versions { start := time.Now() runtime.GC() - builder.stats.Record(timing.CategoryMisc, timing.OperationTypeUpdate, "gc", time.Since(start), true) + builder.stats.Record(timing.CategoryMisc, timing.OperationTypeUpdate, "gc", time.Since(start), true, start) if err := builder.renderVersion(logger, version); err != nil { continue } } - defer builder.stats.RecordDuration(timing.CategoryMisc, timing.OperationTypeUpdate, "update_registry")() + start = time.Now() builder.updateRegistry(latestVersion) + builder.stats.Record(timing.CategoryMisc, timing.OperationTypeUpdate, "update_registry", time.Since(start), true, start) return nil } @@ -120,7 +121,7 @@ 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) + builder.stats.Record(cat, timing.OperationTypeAPIFetch, "versions", time.Since(start), err == nil, start) if err != nil { return nil, err } @@ -134,7 +135,7 @@ func (builder Builder) fetchMetadata(logger io.Writer, latestVersion string) ([] start := time.Now() metadata, err := builder.generator.MetaData(latestVersion) cat := builder.operationCategory() - builder.stats.Record(cat, timing.OperationTypeAPIFetch, "metadata", time.Since(start), err == nil) + builder.stats.Record(cat, timing.OperationTypeAPIFetch, "metadata", time.Since(start), err == nil, start) if err != nil { fmt.Fprintf(logger, " ! failed: %s\n", err.Error()) return nil, err @@ -168,7 +169,7 @@ func (builder Builder) generateCrds(logger io.Writer, version string) ([]crd.Crd 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) + builder.stats.Record(cat, timing.OperationTypeGenerate, fmt.Sprintf("crds_%s", version), time.Since(start), err == nil, start) return crds, err } @@ -192,35 +193,43 @@ func (builder Builder) extractSchemas(logger io.Writer, crds []crd.Crd) []crd.Cr func (builder Builder) writeDefinitions(crds []crd.Crd) { fmt.Fprintf(builder.logger, " - - rendered %d definitions.\n", len(crds)) + var startTime time.Time var duration time.Duration - for _, crd := range crds { + for i, crd := range crds { file := path.Join(builder.definitionRepository, crd.Filepath()) os.MkdirAll(path.Dir(file), 0755) - start := time.Now() + loopStart := time.Now() + if i == 0 { + startTime = loopStart + } if err := os.WriteFile(file, crd.Bytes, 0644); err != nil { return } - duration += time.Since(start) + duration += time.Since(loopStart) } if len(crds) > 0 { - builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "definitions", duration, true) + builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "definitions", duration, true, startTime) } } func (builder Builder) writeSchemas(schemas []crd.CrdSchema) { fmt.Fprintf(builder.logger, " - - rendered %d schema.\n", len(schemas)) + var startTime time.Time var duration time.Duration - for _, schema := range schemas { + for i, schema := range schemas { file := path.Join(builder.generatedRepository, schema.Filepath()) os.MkdirAll(path.Dir(file), 0755) - start := time.Now() + loopStart := time.Now() + if i == 0 { + startTime = loopStart + } if err := os.WriteFile(file, schema.Bytes, 0644); err != nil { return } - duration += time.Since(start) + duration += time.Since(loopStart) } if len(schemas) > 0 { - builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "schemas", duration, true) + builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "schemas", duration, true, startTime) } } diff --git a/internal/timing/stats.go b/internal/timing/stats.go index 72a89a327..cada14ec9 100644 --- a/internal/timing/stats.go +++ b/internal/timing/stats.go @@ -1,7 +1,6 @@ package timing import ( - "context" "fmt" "io" "os" @@ -52,13 +51,8 @@ type Operation struct { StartTime time.Time } -type categoryStats struct { - operations []Operation - mu sync.RWMutex -} - type Stats struct { - categories map[Category]*categoryStats + categories map[Category][]Operation totalTime time.Duration totalOps int mu sync.RWMutex @@ -66,23 +60,12 @@ type Stats struct { logMu sync.Mutex } -var contextKey = struct{}{} - func NewStats() *Stats { return &Stats{ - categories: make(map[Category]*categoryStats), + categories: make(map[Category][]Operation), } } -func FromContext(ctx context.Context) (*Stats, bool) { - s, ok := ctx.Value(contextKey).(*Stats) - return s, ok -} - -func WithContext(ctx context.Context, stats *Stats) context.Context { - return context.WithValue(ctx, contextKey, stats) -} - func (s *Stats) OpenLogFile(path string) error { if path == "" { return nil @@ -97,80 +80,89 @@ func (s *Stats) OpenLogFile(path string) error { } func (s *Stats) CloseLogFile() { + s.Flush() if s.logFile != nil { s.logFile.Close() s.logFile = nil } } -func (s *Stats) Record(category Category, opType OperationType, name string, duration time.Duration, success bool) { - s.mu.Lock() - defer s.mu.Unlock() - - s.totalTime += duration - s.totalOps++ - - cat, ok := s.categories[category] - if !ok { - cat = &categoryStats{} - s.categories[category] = cat +func (s *Stats) Flush() { + if s.logFile == nil { + return } - cat.mu.Lock() - defer cat.mu.Unlock() + s.mu.RLock() + var allOps []Operation + for _, ops := range s.categories { + allOps = append(allOps, ops...) + } + s.mu.RUnlock() - cat.operations = append(cat.operations, Operation{ - Category: category, - Type: opType, - Name: name, - Duration: duration, - Success: success, - StartTime: time.Now().Add(-duration), + sort.Slice(allOps, func(i, j int) bool { + return allOps[i].StartTime.Before(allOps[j].StartTime) }) - if s.logFile != nil { + s.logMu.Lock() + defer s.logMu.Unlock() + for _, op := range allOps { successStr := "success" - if !success { + if !op.Success { successStr = "failure" } - s.logMu.Lock() - defer s.logMu.Unlock() fmt.Fprintf(s.logFile, "%s %s %s %s %s (%s)\n", - time.Now().Format(time.RFC3339), - category, - opType, - name, - formatDuration(duration), + op.StartTime.Format(time.RFC3339Nano), + op.Category, + op.Type, + op.Name, + formatDuration(op.Duration), successStr, ) } } -func (s *Stats) RecordFunc(category Category, opType OperationType, name string, success bool, fn func() error) error { - start := time.Now() - err := fn() - duration := time.Since(start) - s.Record(category, opType, name, duration, err == nil) - return err +func (s *Stats) Record(category Category, opType OperationType, name string, duration time.Duration, success bool, startTime time.Time) { + s.mu.Lock() + defer s.mu.Unlock() + + s.totalTime += duration + s.totalOps++ + + s.categories[category] = append(s.categories[category], Operation{ + Category: category, + Type: opType, + Name: name, + Duration: duration, + Success: success, + StartTime: startTime, + }) } func (s *Stats) GetCategoryStats(category Category) []Operation { s.mu.RLock() defer s.mu.RUnlock() - cat, ok := s.categories[category] + ops, ok := s.categories[category] if !ok { return nil } - cat.mu.RLock() - defer cat.mu.RUnlock() - - result := make([]Operation, len(cat.operations)) - copy(result, cat.operations) + result := make([]Operation, len(ops)) + copy(result, ops) return result } +func (s *Stats) GetAllStats() []Operation { + s.mu.RLock() + defer s.mu.RUnlock() + + var allOps []Operation + for _, ops := range s.categories { + allOps = append(allOps, ops...) + } + return allOps +} + func (s *Stats) TotalTime() time.Duration { s.mu.RLock() defer s.mu.RUnlock() @@ -183,13 +175,6 @@ func (s *Stats) TotalOperations() int { return s.totalOps } -func (s *Stats) RecordDuration(category Category, opType OperationType, name string) func() { - start := time.Now() - return func() { - s.Record(category, opType, name, time.Since(start), true) - } -} - func calculatePercentiles(durations []float64, ps []float64) map[float64]time.Duration { if len(durations) == 0 { return nil @@ -244,16 +229,8 @@ func (s *Stats) PrintSummary(writer io.Writer) { categoryOrder := []Category{CategoryHTTP, CategoryGit, CategoryHelm, CategoryOCI, CategoryGeneration, CategoryMisc} for _, cat := range categoryOrder { - catStats, ok := s.categories[cat] - if !ok { - continue - } - - catStats.mu.RLock() - ops := catStats.operations - catStats.mu.RUnlock() - - if len(ops) == 0 { + ops, ok := s.categories[cat] + if !ok || len(ops) == 0 { continue } diff --git a/internal/timing/stats_test.go b/internal/timing/stats_test.go index 60bfecd11..582eb00a3 100644 --- a/internal/timing/stats_test.go +++ b/internal/timing/stats_test.go @@ -1,7 +1,6 @@ package timing import ( - "context" "io" "os" "strings" @@ -22,7 +21,7 @@ func TestNewStats(t *testing.T) { func TestRecord(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true) + s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true, time.Now()) assert.Equal(t, 1, s.TotalOperations()) assert.Equal(t, 100*time.Millisecond, s.TotalTime()) @@ -38,9 +37,9 @@ func TestRecord(t *testing.T) { func TestRecordMultipleCategories(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 50*time.Millisecond, true) - s.Record(CategoryGit, OperationTypeClone, "git-op", 100*time.Millisecond, true) - s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 75*time.Millisecond, true) + 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()) assert.Equal(t, 3, s.TotalOperations()) assert.Equal(t, 225*time.Millisecond, s.TotalTime()) @@ -53,9 +52,9 @@ func TestRecordMultipleCategories(t *testing.T) { func TestRecordMultipleOperationsSameCategory(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true) - s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true) - s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true) + 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()) ops := s.GetCategoryStats(CategoryHTTP) assert.Len(t, ops, 3) @@ -64,7 +63,7 @@ func TestRecordMultipleOperationsSameCategory(t *testing.T) { func TestRecordFailure(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "failed-op", 100*time.Millisecond, false) + s.Record(CategoryHTTP, OperationTypeFetch, "failed-op", 100*time.Millisecond, false, time.Now()) ops := s.GetCategoryStats(CategoryHTTP) assert.Len(t, ops, 1) @@ -80,56 +79,12 @@ func TestGetCategoryStatsEmpty(t *testing.T) { func TestGetCategoryStatsUnknownCategory(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "test", 100*time.Millisecond, true) + s.Record(CategoryHTTP, OperationTypeFetch, "test", 100*time.Millisecond, true, time.Now()) ops := s.GetCategoryStats(CategoryOCI) assert.Nil(t, ops) } -func TestFromContext(t *testing.T) { - s := NewStats() - ctx := WithContext(context.Background(), s) - - retrieved, ok := FromContext(ctx) - assert.True(t, ok) - assert.Equal(t, s, retrieved) -} - -func TestFromContextNotPresent(t *testing.T) { - ctx := context.Background() - - _, ok := FromContext(ctx) - assert.False(t, ok) -} - -func TestRecordFunc(t *testing.T) { - s := NewStats() - - err := s.RecordFunc(CategoryHTTP, OperationTypeFetch, "test-op", true, func() error { - time.Sleep(10 * time.Millisecond) - return nil - }) - - assert.NoError(t, err) - assert.Equal(t, 1, s.TotalOperations()) - assert.GreaterOrEqual(t, s.TotalTime(), 10*time.Millisecond) -} - -func TestRecordFuncWithError(t *testing.T) { - s := NewStats() - - err := s.RecordFunc(CategoryHTTP, OperationTypeFetch, "test-op", false, func() error { - time.Sleep(10 * time.Millisecond) - return assert.AnError - }) - - assert.Error(t, err) - - ops := s.GetCategoryStats(CategoryHTTP) - assert.Len(t, ops, 1) - assert.False(t, ops[0].Success) -} - func TestCalculatePercentiles(t *testing.T) { durations := []float64{10, 20, 30, 40, 50, 60, 70, 80, 90, 100} @@ -188,11 +143,11 @@ func TestPrintSummaryEmpty(t *testing.T) { func TestPrintSummaryWithData(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true) - s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true) - s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true) - s.Record(CategoryGit, OperationTypeClone, "repo1", 100*time.Millisecond, true) - s.Record(CategoryGit, OperationTypeClone, "repo2", 200*time.Millisecond, true) + 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.PrintSummary(io.Discard) } @@ -200,29 +155,16 @@ func TestPrintSummaryWithData(t *testing.T) { func TestPrintSummaryAllCategories(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 10*time.Millisecond, true) - s.Record(CategoryGit, OperationTypeClone, "git-op", 20*time.Millisecond, true) - s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 30*time.Millisecond, true) - s.Record(CategoryOCI, OperationTypePull, "oci-op", 40*time.Millisecond, true) - s.Record(CategoryGeneration, OperationTypeWrite, "gen-op", 50*time.Millisecond, true) - s.Record(CategoryMisc, OperationTypeUpdate, "misc-op", 60*time.Millisecond, true) + 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(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) } -func TestRecordDuration(t *testing.T) { - s := NewStats() - - stop := s.RecordDuration(CategoryHTTP, OperationTypeFetch, "test-op") - time.Sleep(10 * time.Millisecond) - stop() - - ops := s.GetCategoryStats(CategoryHTTP) - assert.Len(t, ops, 1) - assert.Equal(t, "test-op", ops[0].Name) - assert.GreaterOrEqual(t, ops[0].Duration, 10*time.Millisecond) -} - func TestConcurrentRecording(t *testing.T) { s := NewStats() @@ -231,7 +173,7 @@ func TestConcurrentRecording(t *testing.T) { wg.Add(1) go func(n int) { defer wg.Done() - s.Record(CategoryHTTP, OperationTypeFetch, "op", time.Duration(n)*time.Millisecond, true) + s.Record(CategoryHTTP, OperationTypeFetch, "op", time.Duration(n)*time.Millisecond, true, time.Now()) }(i) } wg.Wait() @@ -269,7 +211,7 @@ func TestOpenLogFileThenRecord(t *testing.T) { err := s.OpenLogFile(tmpFile) assert.NoError(t, err) - s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true) + s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true, time.Now()) s.CloseLogFile() content, err := os.ReadFile(tmpFile) @@ -289,7 +231,7 @@ func TestOpenLogFileInvalidPath(t *testing.T) { func TestPrintSummaryWriter(t *testing.T) { s := NewStats() - s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true) + s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now()) var buf strings.Builder s.PrintSummary(&buf) From b54af3de564ad6c98ef42fed213b1a286bf96c1c Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 20:47:20 +0100 Subject: [PATCH 04/14] tmp --- internal/generator/factory.go | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/internal/generator/factory.go b/internal/generator/factory.go index 9de79a3bc..87a91ed3c 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -155,11 +155,15 @@ func (builder Builder) renderVersion(logger io.Writer, version string) error { schemas := builder.extractSchemas(logger, crds) if len(crds) > 0 { - builder.writeDefinitions(crds) + if err := builder.writeDefinitions(crds); err != nil { + return err + } } if len(schemas) > 0 { - builder.writeSchemas(schemas) + if err := builder.writeSchemas(schemas); err != nil { + return err + } } return nil @@ -191,7 +195,7 @@ func (builder Builder) extractSchemas(logger io.Writer, crds []crd.Crd) []crd.Cr return schemas } -func (builder Builder) writeDefinitions(crds []crd.Crd) { +func (builder Builder) writeDefinitions(crds []crd.Crd) error { fmt.Fprintf(builder.logger, " - - rendered %d definitions.\n", len(crds)) var startTime time.Time var duration time.Duration @@ -203,16 +207,17 @@ func (builder Builder) writeDefinitions(crds []crd.Crd) { startTime = loopStart } if err := os.WriteFile(file, crd.Bytes, 0644); err != nil { - return + return err } duration += time.Since(loopStart) } if len(crds) > 0 { builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "definitions", duration, true, startTime) } + return nil } -func (builder Builder) writeSchemas(schemas []crd.CrdSchema) { +func (builder Builder) writeSchemas(schemas []crd.CrdSchema) error { fmt.Fprintf(builder.logger, " - - rendered %d schema.\n", len(schemas)) var startTime time.Time var duration time.Duration @@ -224,13 +229,14 @@ func (builder Builder) writeSchemas(schemas []crd.CrdSchema) { startTime = loopStart } if err := os.WriteFile(file, schema.Bytes, 0644); err != nil { - return + return err } duration += time.Since(loopStart) } if len(schemas) > 0 { builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "schemas", duration, true, startTime) } + return nil } func (builder Builder) Stats() *timing.Stats { From 4d2dc6f4e87689b00f9450fc4296c97276102695 Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 21:04:10 +0100 Subject: [PATCH 05/14] tmp --- internal/generator/factory.go | 2 +- internal/timing/stats.go | 27 ++++++++++++++------------- 2 files changed, 15 insertions(+), 14 deletions(-) diff --git a/internal/generator/factory.go b/internal/generator/factory.go index 87a91ed3c..9dd95efce 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -103,7 +103,7 @@ func (builder Builder) Build() error { for _, version := range versions { start := time.Now() runtime.GC() - builder.stats.Record(timing.CategoryMisc, timing.OperationTypeUpdate, "gc", time.Since(start), true, start) + builder.stats.Record(timing.CategoryMisc, timing.OperationTypeGC, "gc", time.Since(start), true, start) if err := builder.renderVersion(logger, version); err != nil { continue diff --git a/internal/timing/stats.go b/internal/timing/stats.go index cada14ec9..0745cd77a 100644 --- a/internal/timing/stats.go +++ b/internal/timing/stats.go @@ -13,33 +13,34 @@ import ( type Category string const ( - CategoryHTTP Category = "http" + CategoryGeneration Category = "generation" CategoryGit Category = "git" CategoryHelm Category = "helm" - CategoryOCI Category = "oci" - CategoryGeneration Category = "generation" + CategoryHTTP Category = "http" CategoryMisc Category = "misc" + CategoryOCI Category = "oci" ) 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" - OperationTypeDownload OperationType = "download" + OperationTypeIndex OperationType = "index" + OperationTypePull OperationType = "pull" OperationTypeRender OperationType = "render" - OperationTypeAPIFetch OperationType = "api_fetch" - OperationTypeClone OperationType = "clone" - OperationTypeCheckout OperationType = "checkout" + OperationTypeStatus OperationType = "status" OperationTypeSubmodule OperationType = "submodule" OperationTypeTags OperationType = "tags" - OperationTypeBranches OperationType = "branches" - OperationTypeWrite OperationType = "write" - OperationTypeStatus OperationType = "status" OperationTypeUpdate OperationType = "update" - OperationTypePull OperationType = "pull" - OperationTypeAuth OperationType = "auth" - OperationTypeIndex OperationType = "index" + OperationTypeWrite OperationType = "write" ) type Operation struct { From edd1f26f38216f8de0350df9f6a87bc531a61079 Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 21:19:16 +0100 Subject: [PATCH 06/14] tmp --- internal/generator/factory.go | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/internal/generator/factory.go b/internal/generator/factory.go index 9dd95efce..211dae3b2 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -71,6 +71,18 @@ func (builder Builder) Build() error { } defer fmt.Fprintf(logger, "End.\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) From 3b00bafc0a2fa0581372172ebc697e492414ec02 Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 21:26:32 +0100 Subject: [PATCH 07/14] tmp --- internal/command/updater.go | 2 -- internal/timing/stats.go | 4 ++-- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/internal/command/updater.go b/internal/command/updater.go index 0e0423406..d46b56d1a 100644 --- a/internal/command/updater.go +++ b/internal/command/updater.go @@ -99,8 +99,6 @@ func (cmd Updater) Run() error { } } - totalStats.Flush() - if cmd.registry != nil && cmd.registryPath != "" { if err := cmd.registry.Save(cmd.registryPath); err != nil { fmt.Fprintf(cmd.Logger, "::warning:: failed to save registry: %v\n", err) diff --git a/internal/timing/stats.go b/internal/timing/stats.go index 0745cd77a..3a6a23f17 100644 --- a/internal/timing/stats.go +++ b/internal/timing/stats.go @@ -81,14 +81,14 @@ func (s *Stats) OpenLogFile(path string) error { } func (s *Stats) CloseLogFile() { - s.Flush() + s.flush() if s.logFile != nil { s.logFile.Close() s.logFile = nil } } -func (s *Stats) Flush() { +func (s *Stats) flush() { if s.logFile == nil { return } From bdeb9056335bacb7b9335d87d51d14140d70d161 Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 21:35:56 +0100 Subject: [PATCH 08/14] tmp --- .github/workflows/scheduled-jobs.yaml | 7 +++++++ make.d/check.mk | 6 +++++- make.d/comparison.mk | 6 +++++- make.d/update.mk | 7 ++++++- 4 files changed, 23 insertions(+), 3 deletions(-) diff --git a/.github/workflows/scheduled-jobs.yaml b/.github/workflows/scheduled-jobs.yaml index 45c5df85c..6107d2a89 100644 --- a/.github/workflows/scheduled-jobs.yaml +++ b/.github/workflows/scheduled-jobs.yaml @@ -64,6 +64,13 @@ jobs: env: GITHUB_TOKEN: ${{ steps.app-token.outputs.token }} + - name: Save performance log + uses: actions/upload-artifact@v4 + with: + name: performance.log + path: build/ephemeral/performance.log + retention-days: 14 + - uses: actions/checkout@v6 with: repository: datreeio/CRDs-catalog diff --git a/make.d/check.mk b/make.d/check.mk index b01280640..32ac6399c 100644 --- a/make.d/check.mk +++ b/make.d/check.mk @@ -2,4 +2,8 @@ check: build/bin/catalog -find build/ephemeral -not -name ".gitignore" -and -not -name ".gitkeep" -type f -delete -find build/ephemeral -type d -empty -delete touch build/configuration.yaml - build/bin/catalog update --configuration build/configuration.yaml --output build/ephemeral/schema --definitions build/ephemeral/schema --performance-log build/ephemeral/perf.log + build/bin/catalog update \ + --configuration build/configuration.yaml \ + --output build/ephemeral/schema \ + --definitions build/ephemeral/schema \ + --performance-log build/ephemeral/performance.log diff --git a/make.d/comparison.mk b/make.d/comparison.mk index bc9e0bf62..c1dc15fcf 100644 --- a/make.d/comparison.mk +++ b/make.d/comparison.mk @@ -1,2 +1,6 @@ comparison: build/bin/catalog - build/bin/catalog compare --current schema --ignore configuration-ignore.yaml --datreeio build/remote/datreeio --out docs/COMPARISON.md + build/bin/catalog compare \ + --current schema \ + --ignore configuration-ignore.yaml \ + --datreeio build/remote/datreeio \ + --out docs/COMPARISON.md diff --git a/make.d/update.mk b/make.d/update.mk index 11ae2bfa6..7189e2e60 100644 --- a/make.d/update.mk +++ b/make.d/update.mk @@ -1,2 +1,7 @@ update: build/bin/catalog - build/bin/catalog update --registry registry.yaml --configuration configuration.yaml --output schema --definitions definitions + build/bin/catalog update \ + --registry registry.yaml \ + --configuration configuration.yaml \ + --output schema \ + --definitions definitions \ + --performance-log build/ephemeral/performance.log From f2671bbed921bc9bd80de934749a0bd7a2ab33be Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 21:45:53 +0100 Subject: [PATCH 09/14] tmp --- internal/generator/factory.go | 22 ++++++---------------- 1 file changed, 6 insertions(+), 16 deletions(-) diff --git a/internal/generator/factory.go b/internal/generator/factory.go index 211dae3b2..829b5463c 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -209,20 +209,15 @@ func (builder Builder) extractSchemas(logger io.Writer, crds []crd.Crd) []crd.Cr func (builder Builder) writeDefinitions(crds []crd.Crd) error { fmt.Fprintf(builder.logger, " - - rendered %d definitions.\n", len(crds)) - var startTime time.Time - var duration time.Duration - for i, crd := range crds { + startTime := time.Now() + for _, crd := range crds { file := path.Join(builder.definitionRepository, crd.Filepath()) os.MkdirAll(path.Dir(file), 0755) - loopStart := time.Now() - if i == 0 { - startTime = loopStart - } if err := os.WriteFile(file, crd.Bytes, 0644); err != nil { return err } - duration += time.Since(loopStart) } + duration := time.Since(startTime) if len(crds) > 0 { builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "definitions", duration, true, startTime) } @@ -231,20 +226,15 @@ func (builder Builder) writeDefinitions(crds []crd.Crd) error { func (builder Builder) writeSchemas(schemas []crd.CrdSchema) error { fmt.Fprintf(builder.logger, " - - rendered %d schema.\n", len(schemas)) - var startTime time.Time - var duration time.Duration - for i, schema := range schemas { + startTime := time.Now() + for _, schema := range schemas { file := path.Join(builder.generatedRepository, schema.Filepath()) os.MkdirAll(path.Dir(file), 0755) - loopStart := time.Now() - if i == 0 { - startTime = loopStart - } if err := os.WriteFile(file, schema.Bytes, 0644); err != nil { return err } - duration += time.Since(loopStart) } + duration := time.Since(startTime) if len(schemas) > 0 { builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "schemas", duration, true, startTime) } From 4ef97955d176c8fadbcc42efbb2b075e087a5e6e Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 21:55:23 +0100 Subject: [PATCH 10/14] tmp --- internal/timing/stats.go | 23 +++++++++++++++++------ internal/timing/stats_test.go | 23 ++++++++++++++++++++--- 2 files changed, 37 insertions(+), 9 deletions(-) diff --git a/internal/timing/stats.go b/internal/timing/stats.go index 3a6a23f17..18097222d 100644 --- a/internal/timing/stats.go +++ b/internal/timing/stats.go @@ -3,6 +3,7 @@ package timing import ( "fmt" "io" + "math" "os" "sort" "strings" @@ -187,14 +188,24 @@ func calculatePercentiles(durations []float64, ps []float64) map[float64]time.Du result := make(map[float64]time.Duration) for _, p := range ps { - idx := int(float64(len(sorted)) * p) - if idx >= len(sorted) { - idx = len(sorted) - 1 + rank := p * float64(len(sorted)-1) + lower := int(math.Floor(rank)) + upper := int(math.Ceil(rank)) + + if lower >= len(sorted) { + lower = len(sorted) - 1 + } + if upper >= len(sorted) { + upper = len(sorted) - 1 } - if idx < 0 { - idx = 0 + + if lower == upper { + result[p] = time.Duration(sorted[lower] * float64(time.Second)) + } else { + fraction := rank - float64(lower) + interpolated := sorted[lower] + (sorted[upper]-sorted[lower])*fraction + result[p] = time.Duration(interpolated * float64(time.Second)) } - result[p] = time.Duration(sorted[idx] * float64(time.Second)) } return result } diff --git a/internal/timing/stats_test.go b/internal/timing/stats_test.go index 582eb00a3..8ec248de5 100644 --- a/internal/timing/stats_test.go +++ b/internal/timing/stats_test.go @@ -91,9 +91,9 @@ func TestCalculatePercentiles(t *testing.T) { result := calculatePercentiles(durations, []float64{0.75, 0.90, 0.95}) assert.NotNil(t, result) - assert.Equal(t, 80*time.Second, result[0.75]) - assert.Equal(t, 100*time.Second, result[0.90]) - assert.Equal(t, 100*time.Second, result[0.95]) + assert.Equal(t, time.Duration(77.5*float64(time.Second)), result[0.75]) + assert.Equal(t, time.Duration(91*float64(time.Second)), result[0.90]) + assert.Equal(t, time.Duration(95.5*float64(time.Second)), result[0.95]) } func TestCalculatePercentilesEmpty(t *testing.T) { @@ -110,6 +110,23 @@ func TestCalculatePercentilesSingle(t *testing.T) { assert.Equal(t, 50*time.Second, result[0.95]) } +func TestCalculatePercentilesComprehensive(t *testing.T) { + durations := make([]float64, 100) + for i := range 100 { + durations[i] = float64(i + 1) + } + + result := calculatePercentiles(durations, []float64{0.01, 0.25, 0.50, 0.75, 0.95, 0.99}) + + assert.NotNil(t, result) + assert.Equal(t, time.Duration(1.99*float64(time.Second)), result[0.01]) + assert.Equal(t, time.Duration(25.75*float64(time.Second)), result[0.25]) + assert.Equal(t, time.Duration(50.5*float64(time.Second)), result[0.50]) + assert.Equal(t, time.Duration(75.25*float64(time.Second)), result[0.75]) + assert.Equal(t, time.Duration(95.05*float64(time.Second)), result[0.95]) + assert.Equal(t, time.Duration(99.01*float64(time.Second)), result[0.99]) +} + func TestFormatDuration(t *testing.T) { tests := []struct { input time.Duration From 27019ca51e04c14a7acd44c998ec2c64e88b8537 Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 22:02:38 +0100 Subject: [PATCH 11/14] tmp --- internal/generator/factory.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/internal/generator/factory.go b/internal/generator/factory.go index 829b5463c..806569742 100644 --- a/internal/generator/factory.go +++ b/internal/generator/factory.go @@ -66,10 +66,11 @@ func (builder Builder) Build() error { logger := builder.logger fmt.Fprintf(logger, "Producing for %s@%s:\n", builder.config.Name, builder.config.Kind) + defer fmt.Fprintf(logger, "End.\n") + if _, ok := builder.generator.(*PreparedGitGenerator); ok { fmt.Fprintf(logger, " - using prepared git generator\n") } - defer fmt.Fprintf(logger, "End.\n") buildStart := time.Now() defer func() { From ac4a7ac0b7377b6a6e4f5f5b59901e1ebb4af2fd Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 22:13:28 +0100 Subject: [PATCH 12/14] tmp --- internal/timing/stats_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/timing/stats_test.go b/internal/timing/stats_test.go index 8ec248de5..eefe9a6f2 100644 --- a/internal/timing/stats_test.go +++ b/internal/timing/stats_test.go @@ -93,7 +93,7 @@ func TestCalculatePercentiles(t *testing.T) { assert.NotNil(t, result) assert.Equal(t, time.Duration(77.5*float64(time.Second)), result[0.75]) assert.Equal(t, time.Duration(91*float64(time.Second)), result[0.90]) - assert.Equal(t, time.Duration(95.5*float64(time.Second)), result[0.95]) + assert.InDelta(t, time.Duration(95.5*float64(time.Second)), result[0.95], 0.001) } func TestCalculatePercentilesEmpty(t *testing.T) { From d13b1c01c931b8817e92dcf0fa6c333a2ce7bdcf Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 22:16:13 +0100 Subject: [PATCH 13/14] tmp --- internal/timing/stats_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/timing/stats_test.go b/internal/timing/stats_test.go index eefe9a6f2..f93b0a404 100644 --- a/internal/timing/stats_test.go +++ b/internal/timing/stats_test.go @@ -93,7 +93,7 @@ func TestCalculatePercentiles(t *testing.T) { assert.NotNil(t, result) assert.Equal(t, time.Duration(77.5*float64(time.Second)), result[0.75]) assert.Equal(t, time.Duration(91*float64(time.Second)), result[0.90]) - assert.InDelta(t, time.Duration(95.5*float64(time.Second)), result[0.95], 0.001) + assert.InDelta(t, time.Duration(95.5*float64(time.Second)), result[0.95], 0.01) } func TestCalculatePercentilesEmpty(t *testing.T) { From 60c69baa163efa874089ffdcda6f839aafda3ebf Mon Sep 17 00:00:00 2001 From: Jakob Jensen Date: Sat, 28 Mar 2026 22:20:43 +0100 Subject: [PATCH 14/14] tmp --- internal/timing/stats_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/timing/stats_test.go b/internal/timing/stats_test.go index f93b0a404..898ed07db 100644 --- a/internal/timing/stats_test.go +++ b/internal/timing/stats_test.go @@ -93,7 +93,7 @@ func TestCalculatePercentiles(t *testing.T) { assert.NotNil(t, result) assert.Equal(t, time.Duration(77.5*float64(time.Second)), result[0.75]) assert.Equal(t, time.Duration(91*float64(time.Second)), result[0.90]) - assert.InDelta(t, time.Duration(95.5*float64(time.Second)), result[0.95], 0.01) + assert.InDelta(t, time.Duration(95.5*float64(time.Second)), result[0.95], float64(1*time.Millisecond)) } func TestCalculatePercentilesEmpty(t *testing.T) {