chore: adjust performance monitoring and tests

internal/command/updater.go

@@ -8,6 +8,7 @@ import (
 	"os"
 	"path"
 	"runtime"
+	"time"
 
 	"github.com/CustomResourceDefinition/catalog/internal/configuration"
 	"github.com/CustomResourceDefinition/catalog/internal/crd"
@@ -78,19 +79,25 @@ func (cmd Updater) Run() error {
 		return err
 	}
 
+	totalStats := timing.NewStats()
+
+	start := time.Now()
 	configurations, err := readConfiguration(cmd.Configuration)
 	if err != nil {
 		return err
 	}
+	totalStats.Record(timing.CategoryMisc, timing.OperationTypeConfiguration, "read", time.Since(start), true, start)
 
 	if cmd.registry != nil {
+		start = time.Now()
 		validKeys := validSourceKeys(configurations)
 		for key := range cmd.registry.Sources {
 			if !validKeys[key] {
 				delete(cmd.registry.Sources, key)
 				fmt.Fprintf(cmd.Logger, "Removing stale registry entry: %s\n", key)
 			}
 		}
+		totalStats.Record(timing.CategoryMisc, timing.OperationTypeConfiguration, "valid_keys", time.Since(start), true, start)
 	}
 
 	tmpDir, err := os.MkdirTemp("", "output")
@@ -99,14 +106,13 @@ func (cmd Updater) Run() error {
 	}
 	defer os.RemoveAll(tmpDir)
 
-	totalStats := timing.NewStats()
-
 	if err := totalStats.OpenLogFile(cmd.performanceLog); err != nil {
 		return fmt.Errorf("failed to open performance log: %w", err)
 	}
 	defer totalStats.CloseLogFile()
 
 	for _, config := range splitConfigurations(configurations) {
+		start = time.Now()
 		runtime.GC()
 
 		build, err := generator.NewBuilder(config, cmd.reader, tmpDir, cmd.Schema, cmd.Definitions, cmd.Logger, cmd.registry)
@@ -116,6 +122,7 @@ func (cmd Updater) Run() error {
 		}
 
 		err = build.Build()
+		totalStats.Record(timing.CategoryMisc, timing.OperationTypeBuild, config.Name, time.Since(start), true, start)
 		if err != nil {
 			fmt.Fprintf(cmd.Logger, "::warning:: build of %s failed: %v\n", config.Name, err)
 			continue
@@ -128,19 +135,28 @@ func (cmd Updater) Run() error {
 	}
 
 	if cmd.registry != nil && cmd.registryPath != "" {
+		start = time.Now()
 		if err := cmd.registry.Save(cmd.registryPath); err != nil {
 			fmt.Fprintf(cmd.Logger, "::warning:: failed to save registry: %v\n", err)
 		}
+		totalStats.Record(timing.CategoryMisc, timing.OperationTypeConfiguration, "save_registry", time.Since(start), true, start)
 	}
 
+	start = time.Now()
+	err = merge(tmpDir, cmd.Schema)
+	if err != nil {
+		return err
+	}
+	totalStats.Record(timing.CategoryMisc, timing.OperationTypeMerge, "files", time.Since(start), true, start)
+
 	writer, closer, err := cmd.createSummaryWriter()
 	if err != nil {
 		return err
 	}
 	defer closer()
 	totalStats.PrintSummary(writer)
 
-	return merge(tmpDir, cmd.Schema)
+	return nil
 }
 
 func (cmd Updater) validate() error {

internal/command/updater_test.go

@@ -329,7 +329,7 @@ func TestRunAggregatesStats(t *testing.T) {
 	assert.Nil(t, err)
 
 	outStr := output.String()
-	assert.Contains(t, outStr, "Update Statistics")
+	assert.Contains(t, outStr, "### Statistics")
 	assert.Contains(t, outStr, "**Overall:**")
 	assert.Contains(t, outStr, "operations")
 	assert.Contains(t, outStr, "#### Http")

internal/generator/factory.go

@@ -72,18 +72,6 @@ func (builder Builder) Build() error {
 		fmt.Fprintf(logger, " - using prepared git generator\n")
 	}
 
-	buildStart := time.Now()
-	defer func() {
-		builder.stats.Record(
-			timing.CategoryMisc,
-			timing.OperationTypeUpdate,
-			fmt.Sprintf("build_%s", builder.config.Name),
-			time.Since(buildStart),
-			true,
-			buildStart,
-		)
-	}()
-
 	start := time.Now()
 	latestVersion, isUpdated, err := builder.registryStatus()
 	builder.stats.Record(timing.CategoryMisc, timing.OperationTypeStatus, "registry_status", time.Since(start), err == nil, start)
@@ -114,9 +102,7 @@ func (builder Builder) Build() error {
 	}
 
 	for _, version := range versions {
-		start := time.Now()
 		runtime.GC()
-		builder.stats.Record(timing.CategoryMisc, timing.OperationTypeGC, "gc", time.Since(start), true, start)
 
 		if err := builder.renderVersion(logger, version); err != nil {
 			continue
@@ -133,8 +119,7 @@ func (builder Builder) Build() error {
 func (builder Builder) fetchVersions(logger io.Writer) ([]string, error) {
 	start := time.Now()
 	versions, err := builder.generator.Versions()
-	cat := builder.operationCategory()
-	builder.stats.Record(cat, timing.OperationTypeAPIFetch, "versions", time.Since(start), err == nil, start)
+	builder.stats.Record(builder.operationCategory(), timing.OperationTypeAPIFetch, "versions", time.Since(start), err == nil, start)
 	if err != nil {
 		return nil, err
 	}
@@ -147,8 +132,7 @@ func (builder Builder) fetchMetadata(logger io.Writer, latestVersion string) ([]
 	fmt.Fprintf(logger, " - checking version %s for completeness.\n", latestVersion)
 	start := time.Now()
 	metadata, err := builder.generator.MetaData(latestVersion)
-	cat := builder.operationCategory()
-	builder.stats.Record(cat, timing.OperationTypeAPIFetch, "metadata", time.Since(start), err == nil, start)
+	builder.stats.Record(builder.operationCategory(), timing.OperationTypeAPIFetch, "metadata", time.Since(start), err == nil, start)
 	if err != nil {
 		fmt.Fprintf(logger, " ! failed: %s\n", err.Error())
 		return nil, err
@@ -159,7 +143,7 @@ func (builder Builder) fetchMetadata(logger io.Writer, latestVersion string) ([]
 func (builder Builder) renderVersion(logger io.Writer, version string) error {
 	fmt.Fprintf(logger, " - render version %s.\n", version)
 
-	crds, err := builder.generateCrds(logger, version)
+	crds, err := builder.generateCrds(version)
 	if err != nil {
 		fmt.Fprintf(logger, " - - discarded due to error: %s.\n", err.Error())
 		return err
@@ -182,11 +166,10 @@ func (builder Builder) renderVersion(logger io.Writer, version string) error {
 	return nil
 }
 
-func (builder Builder) generateCrds(logger io.Writer, version string) ([]crd.Crd, error) {
+func (builder Builder) generateCrds(version string) ([]crd.Crd, error) {
 	start := time.Now()
 	crds, err := builder.generator.Crds(version)
-	cat := builder.operationCategory()
-	builder.stats.Record(cat, timing.OperationTypeGenerate, fmt.Sprintf("crds_%s", version), time.Since(start), err == nil, start)
+	builder.stats.Record(builder.operationCategory(), timing.OperationTypeGenerate, fmt.Sprintf("crds_%s", version), time.Since(start), err == nil, start)
 	return crds, err
 }
 

internal/timing/stats.go

@@ -25,23 +25,14 @@ const (
 type OperationType string
 
 const (
-	OperationTypeAPIFetch  OperationType = "api_fetch"
-	OperationTypeAuth      OperationType = "auth"
-	OperationTypeBranches  OperationType = "branches"
-	OperationTypeCheckout  OperationType = "checkout"
-	OperationTypeClone     OperationType = "clone"
-	OperationTypeDownload  OperationType = "download"
-	OperationTypeFetch     OperationType = "fetch"
-	OperationTypeGC        OperationType = "gc"
-	OperationTypeGenerate  OperationType = "generate"
-	OperationTypeIndex     OperationType = "index"
-	OperationTypePull      OperationType = "pull"
-	OperationTypeRender    OperationType = "render"
-	OperationTypeStatus    OperationType = "status"
-	OperationTypeSubmodule OperationType = "submodule"
-	OperationTypeTags      OperationType = "tags"
-	OperationTypeUpdate    OperationType = "update"
-	OperationTypeWrite     OperationType = "write"
+	OperationTypeAPIFetch      OperationType = "api_fetch"
+	OperationTypeBuild         OperationType = "build"
+	OperationTypeConfiguration OperationType = "configuration"
+	OperationTypeGenerate      OperationType = "generate"
+	OperationTypeMerge         OperationType = "merge"
+	OperationTypeStatus        OperationType = "status"
+	OperationTypeUpdate        OperationType = "update"
+	OperationTypeWrite         OperationType = "write"
 )
 
 type Operation struct {
@@ -235,7 +226,7 @@ func (s *Stats) PrintSummary(writer io.Writer) {
 	s.mu.RLock()
 	defer s.mu.RUnlock()
 
-	fmt.Fprintf(writer, "\n### Update Statistics\n\n")
+	fmt.Fprintf(writer, "\n### Statistics\n\n")
 	fmt.Fprintf(writer, "**Overall:** %s (%d operations)\n\n", formatDuration(s.totalTime), s.totalOps)
 
 	categoryOrder := []Category{CategoryHTTP, CategoryGit, CategoryHelm, CategoryOCI, CategoryGeneration, CategoryMisc}

internal/timing/stats_test.go

@@ -1,7 +1,6 @@
 package timing
 
 import (
-	"io"
 	"os"
 	"strings"
 	"sync"
@@ -21,14 +20,14 @@ func TestNewStats(t *testing.T) {
 func TestRecord(t *testing.T) {
 	s := NewStats()
 
-	s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "test-op", 100*time.Millisecond, true, time.Now())
 
 	assert.Equal(t, 1, s.TotalOperations())
 	assert.Equal(t, 100*time.Millisecond, s.TotalTime())
 
 	ops := s.GetCategoryStats(CategoryHTTP)
 	assert.Len(t, ops, 1)
-	assert.Equal(t, OperationTypeFetch, ops[0].Type)
+	assert.Equal(t, OperationTypeAPIFetch, ops[0].Type)
 	assert.Equal(t, "test-op", ops[0].Name)
 	assert.Equal(t, 100*time.Millisecond, ops[0].Duration)
 	assert.True(t, ops[0].Success)
@@ -37,9 +36,9 @@ func TestRecord(t *testing.T) {
 func TestRecordMultipleCategories(t *testing.T) {
 	s := NewStats()
 
-	s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 50*time.Millisecond, true, time.Now())
-	s.Record(CategoryGit, OperationTypeClone, "git-op", 100*time.Millisecond, true, time.Now())
-	s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 75*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "http-op", 50*time.Millisecond, true, time.Now())
+	s.Record(CategoryGit, OperationTypeWrite, "git-op", 100*time.Millisecond, true, time.Now())
+	s.Record(CategoryHelm, OperationTypeGenerate, "helm-op", 75*time.Millisecond, true, time.Now())
 
 	assert.Equal(t, 3, s.TotalOperations())
 	assert.Equal(t, 225*time.Millisecond, s.TotalTime())
@@ -52,9 +51,9 @@ func TestRecordMultipleCategories(t *testing.T) {
 func TestRecordMultipleOperationsSameCategory(t *testing.T) {
 	s := NewStats()
 
-	s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now())
-	s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true, time.Now())
-	s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "op1", 10*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "op2", 20*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "op3", 30*time.Millisecond, true, time.Now())
 
 	ops := s.GetCategoryStats(CategoryHTTP)
 	assert.Len(t, ops, 3)
@@ -63,7 +62,7 @@ func TestRecordMultipleOperationsSameCategory(t *testing.T) {
 func TestRecordFailure(t *testing.T) {
 	s := NewStats()
 
-	s.Record(CategoryHTTP, OperationTypeFetch, "failed-op", 100*time.Millisecond, false, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "failed-op", 100*time.Millisecond, false, time.Now())
 
 	ops := s.GetCategoryStats(CategoryHTTP)
 	assert.Len(t, ops, 1)
@@ -79,7 +78,7 @@ func TestGetCategoryStatsEmpty(t *testing.T) {
 
 func TestGetCategoryStatsUnknownCategory(t *testing.T) {
 	s := NewStats()
-	s.Record(CategoryHTTP, OperationTypeFetch, "test", 100*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "test", 100*time.Millisecond, true, time.Now())
 
 	ops := s.GetCategoryStats(CategoryOCI)
 	assert.Nil(t, ops)
@@ -154,43 +153,63 @@ func TestFormatDuration(t *testing.T) {
 func TestPrintSummaryEmpty(t *testing.T) {
 	s := NewStats()
 
-	s.PrintSummary(io.Discard)
+	var buf strings.Builder
+	s.PrintSummary(&buf)
+
+	assert.Contains(t, buf.String(), "### Statistics")
+	assert.Contains(t, buf.String(), "**Overall:** 0µs (0 operations)")
 }
 
 func TestPrintSummaryWithData(t *testing.T) {
 	s := NewStats()
 
-	s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now())
-	s.Record(CategoryHTTP, OperationTypeFetch, "op2", 20*time.Millisecond, true, time.Now())
-	s.Record(CategoryHTTP, OperationTypeFetch, "op3", 30*time.Millisecond, true, time.Now())
-	s.Record(CategoryGit, OperationTypeClone, "repo1", 100*time.Millisecond, true, time.Now())
-	s.Record(CategoryGit, OperationTypeClone, "repo2", 200*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "op1", 10*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "op2", 20*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "op3", 30*time.Millisecond, true, time.Now())
+	s.Record(CategoryGit, OperationTypeGenerate, "repo1", 100*time.Millisecond, true, time.Now())
+	s.Record(CategoryGit, OperationTypeGenerate, "repo2", 200*time.Millisecond, true, time.Now())
+
+	var buf strings.Builder
+	s.PrintSummary(&buf)
 
-	s.PrintSummary(io.Discard)
+	assert.Contains(t, buf.String(), "### Statistics")
+	assert.Contains(t, buf.String(), "**Overall:** 360ms (5 operations)")
+	assert.Contains(t, buf.String(), "#### Http")
+	assert.Contains(t, buf.String(), "#### Git")
 }
 
 func TestPrintSummaryAllCategories(t *testing.T) {
 	s := NewStats()
 
-	s.Record(CategoryHTTP, OperationTypeFetch, "http-op", 10*time.Millisecond, true, time.Now())
-	s.Record(CategoryGit, OperationTypeClone, "git-op", 20*time.Millisecond, true, time.Now())
-	s.Record(CategoryHelm, OperationTypeDownload, "helm-op", 30*time.Millisecond, true, time.Now())
-	s.Record(CategoryOCI, OperationTypePull, "oci-op", 40*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "http-op", 10*time.Millisecond, true, time.Now())
+	s.Record(CategoryGit, OperationTypeGenerate, "git-op", 20*time.Millisecond, true, time.Now())
+	s.Record(CategoryHelm, OperationTypeGenerate, "helm-op", 30*time.Millisecond, true, time.Now())
+	s.Record(CategoryOCI, OperationTypeGenerate, "oci-op", 40*time.Millisecond, true, time.Now())
 	s.Record(CategoryGeneration, OperationTypeWrite, "gen-op", 50*time.Millisecond, true, time.Now())
 	s.Record(CategoryMisc, OperationTypeUpdate, "misc-op", 60*time.Millisecond, true, time.Now())
 
-	s.PrintSummary(io.Discard)
+	var buf strings.Builder
+	s.PrintSummary(&buf)
+
+	assert.Contains(t, buf.String(), "### Statistics")
+	assert.Contains(t, buf.String(), "**Overall:** 210ms (6 operations)")
+	assert.Contains(t, buf.String(), "#### Http")
+	assert.Contains(t, buf.String(), "#### Git")
+	assert.Contains(t, buf.String(), "#### Helm")
+	assert.Contains(t, buf.String(), "#### Oci")
+	assert.Contains(t, buf.String(), "#### Generation")
+	assert.Contains(t, buf.String(), "#### Misc")
 }
 
 func TestConcurrentRecording(t *testing.T) {
 	s := NewStats()
 
 	var wg sync.WaitGroup
-	for i := 0; i < 100; i++ {
+	for i := range 100 {
 		wg.Add(1)
 		go func(n int) {
 			defer wg.Done()
-			s.Record(CategoryHTTP, OperationTypeFetch, "op", time.Duration(n)*time.Millisecond, true, time.Now())
+			s.Record(CategoryHTTP, OperationTypeAPIFetch, "op", time.Duration(n)*time.Millisecond, true, time.Now())
 		}(i)
 	}
 	wg.Wait()
@@ -228,7 +247,7 @@ func TestOpenLogFileThenRecord(t *testing.T) {
 	err := s.OpenLogFile(tmpFile)
 	assert.NoError(t, err)
 
-	s.Record(CategoryHTTP, OperationTypeFetch, "test-op", 100*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "test-op", 100*time.Millisecond, true, time.Now())
 	s.CloseLogFile()
 
 	content, err := os.ReadFile(tmpFile)
@@ -248,12 +267,12 @@ func TestOpenLogFileInvalidPath(t *testing.T) {
 func TestPrintSummaryWriter(t *testing.T) {
 	s := NewStats()
 
-	s.Record(CategoryHTTP, OperationTypeFetch, "op1", 10*time.Millisecond, true, time.Now())
+	s.Record(CategoryHTTP, OperationTypeAPIFetch, "op1", 10*time.Millisecond, true, time.Now())
 
 	var buf strings.Builder
 	s.PrintSummary(&buf)
 
-	assert.Contains(t, buf.String(), "Update Statistics")
+	assert.Contains(t, buf.String(), "### Statistics")
 	assert.Contains(t, buf.String(), "**Overall:**")
 	assert.Contains(t, buf.String(), "#### Http")
 }