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/internal/command/updater.go b/internal/command/updater.go index 4333a7a79..d46b56d1a 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 { @@ -22,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, } } @@ -68,6 +71,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) { runtime.GC() @@ -82,6 +92,11 @@ func (cmd Updater) Run() error { fmt.Fprintf(cmd.Logger, "::warning:: build of %s failed: %v\n", config.Name, err) continue } + + stats := build.Stats() + for _, op := range stats.GetAllStats() { + totalStats.Record(op.Category, op.Type, op.Name, op.Duration, op.Success, op.StartTime) + } } if cmd.registry != nil && cmd.registryPath != "" { @@ -90,6 +105,8 @@ func (cmd Updater) Run() error { } } + totalStats.PrintSummary(cmd.Logger) + return merge(tmpDir, cmd.Schema) } diff --git a/internal/command/updater_test.go b/internal/command/updater_test.go index 5109b4766..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,9 +287,136 @@ 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) 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.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) { + 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) + + 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 06c7eeca6..806569742 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 } @@ -68,7 +72,21 @@ 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) if err != nil { return err } @@ -77,17 +95,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,56 +114,152 @@ 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) - 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 + start = time.Now() + builder.updateRegistry(latestVersion) + builder.stats.Record(timing.CategoryMisc, timing.OperationTypeUpdate, "update_registry", time.Since(start), true, start) + + 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, start) + 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, start) + 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 { + if err := builder.writeDefinitions(crds); err != nil { + return err } + } - 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 - } + if len(schemas) > 0 { + if err := builder.writeSchemas(schemas); err != nil { + return err } + } + + return nil +} - 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) 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, start) + 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 +} - builder.updateRegistry(latestVersion) +func (builder Builder) writeDefinitions(crds []crd.Crd) error { + fmt.Fprintf(builder.logger, " - - rendered %d definitions.\n", len(crds)) + startTime := time.Now() + 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 err + } + } + duration := time.Since(startTime) + if len(crds) > 0 { + builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "definitions", duration, true, startTime) + } + return nil +} +func (builder Builder) writeSchemas(schemas []crd.CrdSchema) error { + fmt.Fprintf(builder.logger, " - - rendered %d schema.\n", len(schemas)) + startTime := time.Now() + 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 err + } + } + duration := time.Since(startTime) + if len(schemas) > 0 { + builder.stats.Record(timing.CategoryGeneration, timing.OperationTypeWrite, "schemas", duration, true, startTime) + } return nil } +func (builder Builder) Stats() *timing.Stats { + return builder.stats +} + +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 // available and only uses the decided interface method for latest version information func (builder Builder) registryStatus() (string, bool, error) { 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..18097222d --- /dev/null +++ b/internal/timing/stats.go @@ -0,0 +1,289 @@ +package timing + +import ( + "fmt" + "io" + "math" + "os" + "sort" + "strings" + "sync" + "time" +) + +type Category string + +const ( + CategoryGeneration Category = "generation" + CategoryGit Category = "git" + CategoryHelm Category = "helm" + 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" + OperationTypeIndex OperationType = "index" + OperationTypePull OperationType = "pull" + OperationTypeRender OperationType = "render" + OperationTypeStatus OperationType = "status" + OperationTypeSubmodule OperationType = "submodule" + OperationTypeTags OperationType = "tags" + OperationTypeUpdate OperationType = "update" + OperationTypeWrite OperationType = "write" +) + +type Operation struct { + Category Category + Type OperationType + Name string + Duration time.Duration + Success bool + StartTime time.Time +} + +type Stats struct { + categories map[Category][]Operation + totalTime time.Duration + totalOps int + mu sync.RWMutex + logFile *os.File + logMu sync.Mutex +} + +func NewStats() *Stats { + return &Stats{ + categories: make(map[Category][]Operation), + } +} + +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() { + s.flush() + if s.logFile != nil { + s.logFile.Close() + s.logFile = nil + } +} + +func (s *Stats) flush() { + if s.logFile == nil { + return + } + + s.mu.RLock() + var allOps []Operation + for _, ops := range s.categories { + allOps = append(allOps, ops...) + } + s.mu.RUnlock() + + sort.Slice(allOps, func(i, j int) bool { + return allOps[i].StartTime.Before(allOps[j].StartTime) + }) + + s.logMu.Lock() + defer s.logMu.Unlock() + for _, op := range allOps { + successStr := "success" + if !op.Success { + successStr = "failure" + } + fmt.Fprintf(s.logFile, "%s %s %s %s %s (%s)\n", + op.StartTime.Format(time.RFC3339Nano), + op.Category, + op.Type, + op.Name, + formatDuration(op.Duration), + successStr, + ) + } +} + +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() + + ops, ok := s.categories[category] + if !ok { + return nil + } + + 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() + return s.totalTime +} + +func (s *Stats) TotalOperations() int { + s.mu.RLock() + defer s.mu.RUnlock() + return s.totalOps +} + +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 { + 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 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)) + } + } + return result +} + +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(writer io.Writer) { + s.mu.RLock() + defer s.mu.RUnlock() + + 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} + + for _, cat := range categoryOrder { + ops, ok := s.categories[cat] + if !ok || len(ops) == 0 { + continue + } + + typeStats := make(map[OperationType][]time.Duration) + + for _, op := range ops { + typeStats[op.Type] = append(typeStats[op.Type], op.Duration) + } + + fmt.Fprintf(writer, "%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.Fprintf(writer, " %-10s %4d operations total: %s", + typeLabel+":", + len(durations), + formatDuration(total), + ) + + if len(percs) > 0 { + fmt.Fprintf(writer, " p75: %s p90: %s p95: %s", + formatDuration(percs[0.75]), + formatDuration(percs[0.90]), + formatDuration(percs[0.95]), + ) + } + fmt.Fprintln(writer) + } + fmt.Fprintln(writer) + } +} diff --git a/internal/timing/stats_test.go b/internal/timing/stats_test.go new file mode 100644 index 000000000..898ed07db --- /dev/null +++ b/internal/timing/stats_test.go @@ -0,0 +1,259 @@ +package timing + +import ( + "io" + "os" + "strings" + "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, 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, "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, 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()) + + 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, 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) +} + +func TestRecordFailure(t *testing.T) { + s := NewStats() + + s.Record(CategoryHTTP, OperationTypeFetch, "failed-op", 100*time.Millisecond, false, time.Now()) + + 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, time.Now()) + + ops := s.GetCategoryStats(CategoryOCI) + assert.Nil(t, ops) +} + +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, 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], float64(1*time.Millisecond)) +} + +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 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 + 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(io.Discard) +} + +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.PrintSummary(io.Discard) +} + +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(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 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, time.Now()) + }(i) + } + wg.Wait() + + 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, time.Now()) + 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, time.Now()) + + 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..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 + 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