diff --git a/.github/workflows/checks-codecov.yaml b/.github/workflows/checks-codecov.yaml index e69b83d2b..ef617652e 100644 --- a/.github/workflows/checks-codecov.yaml +++ b/.github/workflows/checks-codecov.yaml @@ -132,6 +132,19 @@ jobs: id: acceptance_test run: E2E_INSTRUMENTATION=true make acceptance + - name: Print profiling report + if: always() + run: cat /tmp/ec-profile/report.txt 2>/dev/null || echo "No profiling report found" + + - name: Upload profiling data + if: always() + uses: actions/upload-artifact@b7c566a772e6b6bfb58ed0dc250532a479d7789f # v6.0.0 + with: + name: acceptance-profiling + path: /tmp/ec-profile/ + retention-days: 7 + if-no-files-found: ignore + - name: Upload acceptance coverage artifact uses: actions/upload-artifact@b7c566a772e6b6bfb58ed0dc250532a479d7789f # v6.0.0 with: diff --git a/acceptance/acceptance_test.go b/acceptance/acceptance_test.go index 09fe40322..3a8fdd770 100644 --- a/acceptance/acceptance_test.go +++ b/acceptance/acceptance_test.go @@ -37,6 +37,7 @@ import ( "github.com/conforma/cli/acceptance/kubernetes" "github.com/conforma/cli/acceptance/log" "github.com/conforma/cli/acceptance/pipeline" + "github.com/conforma/cli/acceptance/profile" "github.com/conforma/cli/acceptance/registry" "github.com/conforma/cli/acceptance/rekor" "github.com/conforma/cli/acceptance/tekton" @@ -131,11 +132,13 @@ func initializeScenario(sc *godog.ScenarioContext) { sc.Before(func(ctx context.Context, sc *godog.Scenario) (context.Context, error) { logger, ctx := log.LoggerFor(ctx) logger.Name(sc.Name) + ctx = profile.ScenarioStart(ctx) return context.WithValue(ctx, testenv.Scenario, sc), nil }) sc.After(func(ctx context.Context, scenario *godog.Scenario, scenarioErr error) (context.Context, error) { + profile.ScenarioEnd(ctx, scenario.Name, scenario.Uri) // Log scenario end with status - write to /dev/tty to bypass capture if tty, err := os.OpenFile("/dev/tty", os.O_WRONLY, 0); err == nil { // Strip the working directory prefix to show relative paths @@ -196,6 +199,9 @@ func TestFeatures(t *testing.T) { ctx := setupContext(t) + profile.Init() + defer profile.Report() + opts := godog.Options{ Format: "pretty", Paths: []string{featuresDir}, @@ -221,6 +227,7 @@ func TestFeatures(t *testing.T) { if exitCode != 0 { // Exit directly without t.Fatal to avoid verbose Go test output + profile.Report() os.Exit(1) } } diff --git a/acceptance/git/git.go b/acceptance/git/git.go index bcc632849..c00d3dc95 100644 --- a/acceptance/git/git.go +++ b/acceptance/git/git.go @@ -47,6 +47,7 @@ import ( "github.com/testcontainers/testcontainers-go/wait" "github.com/conforma/cli/acceptance/log" + "github.com/conforma/cli/acceptance/profile" "github.com/conforma/cli/acceptance/testenv" ) @@ -179,16 +180,19 @@ func startStubGitServer(ctx context.Context) (context.Context, error) { logger, ctx := log.LoggerFor(ctx) + endContainer := profile.BeginContainer("git") git, err := testcontainers.GenericContainer(ctx, testcontainers.GenericContainerRequest{ ContainerRequest: req, Started: true, Logger: logger, }) if err != nil { + endContainer() return ctx, err } port, err := git.MappedPort(ctx, "443/tcp") + endContainer() if err != nil { return ctx, err } diff --git a/acceptance/kubernetes/kind/kind.go b/acceptance/kubernetes/kind/kind.go index abf104542..2ac9ac0c4 100644 --- a/acceptance/kubernetes/kind/kind.go +++ b/acceptance/kubernetes/kind/kind.go @@ -54,6 +54,7 @@ import ( "github.com/conforma/cli/acceptance/kubernetes/types" "github.com/conforma/cli/acceptance/kustomize" "github.com/conforma/cli/acceptance/log" + "github.com/conforma/cli/acceptance/profile" "github.com/conforma/cli/acceptance/registry" ) @@ -133,6 +134,8 @@ func Start(givenCtx context.Context) (ctx context.Context, kCluster types.Cluste create.Do(func() { logger.Log("Starting Kind cluster") + endKindTotal := profile.Begin("kind-cluster-total") + defer endKindTotal() var configDir string configDir, err = os.MkdirTemp("", "ec-acceptance.*") @@ -172,6 +175,7 @@ func Start(givenCtx context.Context) (ctx context.Context, kCluster types.Cluste kCluster.registryPort = int32(port) //nolint:gosec // G115 - ports shouldn't be larger than int32 } + endNodeCreate := profile.Begin("kind-node-create") if err = kCluster.provider.Create(kCluster.name, k.CreateWithV1Alpha4Config(&v1alpha4.Cluster{ TypeMeta: v1alpha4.TypeMeta{ @@ -197,9 +201,11 @@ func Start(givenCtx context.Context) (ctx context.Context, kCluster types.Cluste }, }), k.CreateWithKubeconfigPath(kCluster.kubeconfigPath)); err != nil { + endNodeCreate() logger.Errorf("Unable launch the Kind cluster: %v", err) return } + endNodeCreate() rules := clientcmd.NewDefaultClientConfigLoadingRules() rules.ExplicitPath = kCluster.kubeconfigPath @@ -231,30 +237,40 @@ func Start(givenCtx context.Context) (ctx context.Context, kCluster types.Cluste kCluster.mapper = restmapper.NewDiscoveryRESTMapper(resources) } + endApplyConfig := profile.Begin("kind-apply-config") var yaml []byte yaml, err = renderTestConfiguration(&kCluster) if err != nil { + endApplyConfig() logger.Errorf("Unable to kustomize test configuration: %v", err) return } err = applyConfiguration(ctx, &kCluster, yaml) if err != nil { + endApplyConfig() logger.Errorf("Unable apply cluster configuration: %v", err) return } + endApplyConfig() + endBuildCli := profile.Begin("kind-build-cli-image") err = kCluster.buildCliImage(ctx) if err != nil { + endBuildCli() logger.Errorf("Unable to build CLI image: %v", err) return } + endBuildCli() + endBuildBundle := profile.Begin("kind-build-task-bundle") err = kCluster.buildTaskBundleImage(ctx) if err != nil { + endBuildBundle() logger.Errorf("Unable to build Task image: %v", err) return } + endBuildBundle() globalCluster = &kCluster diff --git a/acceptance/profile/profile.go b/acceptance/profile/profile.go new file mode 100644 index 000000000..355f1efc6 --- /dev/null +++ b/acceptance/profile/profile.go @@ -0,0 +1,333 @@ +// Copyright The Conforma Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +// SPDX-License-Identifier: Apache-2.0 + +// Package profile provides runtime profiling for acceptance tests. +// Tracks per-scenario timing, container startup stats, and Kind cluster phases. +// Results are printed to stderr and written to /tmp/ec-profile/. +package profile + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "os" + "path/filepath" + "runtime" + "sort" + "sync" + "sync/atomic" + "time" +) + +var enabled = true + +type ctxKey int + +const scenarioStartKey ctxKey = 0 + +type phaseTiming struct { + Name string + Duration time.Duration +} + +type containerStats struct { + Count int + Total time.Duration + Min time.Duration + Max time.Duration +} + +type scenarioTiming struct { + Name string + Feature string + Duration time.Duration +} + +var ( + mu sync.Mutex + fileMu sync.Mutex + suiteStart time.Time + outputFile *os.File + outputDir string + reported sync.Once + + phases []phaseTiming + containerTypes map[string]*containerStats + scenarioList []scenarioTiming + + activeContainers atomic.Int64 + peakContainers int64 +) + +// Init initializes profiling. Call once at suite start. +func Init() { + if !enabled { + return + } + suiteStart = time.Now() + containerTypes = make(map[string]*containerStats) + + outputDir = "/tmp/ec-profile" + if d := os.Getenv("EC_PROFILE_DIR"); d != "" { + outputDir = d + } + os.MkdirAll(outputDir, 0755) + f, err := os.Create(filepath.Join(outputDir, "events.jsonl")) + if err == nil { + outputFile = f + } +} + +func logEvent(data map[string]any) { + if outputFile == nil { + return + } + b, _ := json.Marshal(data) + fileMu.Lock() + outputFile.Write(append(b, '\n')) + outputFile.Sync() + fileMu.Unlock() +} + +// Begin starts timing a named phase. Call the returned function to stop and record. +func Begin(name string) func() { + if !enabled { + return func() {} + } + start := time.Now() + return func() { + dur := time.Since(start) + mu.Lock() + phases = append(phases, phaseTiming{Name: name, Duration: dur}) + mu.Unlock() + logEvent(map[string]any{ + "event": "phase", "name": name, + "duration_ms": dur.Milliseconds(), "ts": time.Now().Format(time.RFC3339), + }) + } +} + +// BeginContainer starts timing a container creation. Call the returned function when ready. +func BeginContainer(containerType string) func() { + if !enabled { + return func() {} + } + start := time.Now() + return func() { + dur := time.Since(start) + mu.Lock() + stats, ok := containerTypes[containerType] + if !ok { + stats = &containerStats{Min: dur} + containerTypes[containerType] = stats + } + stats.Count++ + stats.Total += dur + if dur < stats.Min { + stats.Min = dur + } + if dur > stats.Max { + stats.Max = dur + } + mu.Unlock() + + current := activeContainers.Add(1) + mu.Lock() + if current > peakContainers { + peakContainers = current + } + mu.Unlock() + + logEvent(map[string]any{ + "event": "container", "type": containerType, + "duration_ms": dur.Milliseconds(), "ts": time.Now().Format(time.RFC3339), + }) + } +} + +// ScenarioStart marks the beginning of a scenario. Returns updated context. +func ScenarioStart(ctx context.Context) context.Context { + if !enabled { + return ctx + } + return context.WithValue(ctx, scenarioStartKey, time.Now()) +} + +// ScenarioEnd records the scenario duration. +func ScenarioEnd(ctx context.Context, name, feature string) { + if !enabled { + return + } + start, ok := ctx.Value(scenarioStartKey).(time.Time) + if !ok { + return + } + dur := time.Since(start) + mu.Lock() + scenarioList = append(scenarioList, scenarioTiming{Name: name, Feature: feature, Duration: dur}) + mu.Unlock() + + logEvent(map[string]any{ + "event": "scenario", "name": name, "feature": feature, + "duration_ms": dur.Milliseconds(), "ts": time.Now().Format(time.RFC3339), + }) +} + +// Report prints the profiling summary. Safe to call multiple times (runs once). +func Report() { + if !enabled { + return + } + reported.Do(doReport) +} + +func doReport() { + totalDur := time.Since(suiteStart) + + var buf bytes.Buffer + w := &buf + + fmt.Fprintf(w, "\n==========================================\n") + fmt.Fprintf(w, " ACCEPTANCE TEST PROFILING REPORT\n") + fmt.Fprintf(w, "==========================================\n") + fmt.Fprintf(w, "Total wall-clock time: %s\n", totalDur.Round(time.Millisecond)) + fmt.Fprintf(w, "Goroutine concurrency: %d (runtime.NumCPU)\n\n", runtime.NumCPU()) + + mu.Lock() + pCopy := make([]phaseTiming, len(phases)) + copy(pCopy, phases) + mu.Unlock() + + if len(pCopy) > 0 { + fmt.Fprintf(w, "--- One-off Phases ---\n") + for _, ph := range pCopy { + pct := float64(ph.Duration) / float64(totalDur) * 100 + fmt.Fprintf(w, " %-40s %10s (%5.1f%%)\n", + ph.Name, ph.Duration.Round(time.Millisecond), pct) + } + fmt.Fprintln(w) + } + + mu.Lock() + types := make([]string, 0, len(containerTypes)) + for t := range containerTypes { + types = append(types, t) + } + cCopy := make(map[string]containerStats) + for t, s := range containerTypes { + cCopy[t] = *s + } + peak := peakContainers + active := activeContainers.Load() + mu.Unlock() + sort.Strings(types) + + if len(types) > 0 { + fmt.Fprintf(w, "--- Container Startup Statistics ---\n") + fmt.Fprintf(w, " %-12s %5s %10s %10s %10s %10s\n", "TYPE", "COUNT", "TOTAL", "AVG", "MIN", "MAX") + totalCount := 0 + totalDurC := time.Duration(0) + for _, t := range types { + s := cCopy[t] + avg := s.Total / time.Duration(s.Count) + fmt.Fprintf(w, " %-12s %5d %10s %10s %10s %10s\n", + t, s.Count, + s.Total.Round(time.Millisecond), avg.Round(time.Millisecond), + s.Min.Round(time.Millisecond), s.Max.Round(time.Millisecond)) + totalCount += s.Count + totalDurC += s.Total + } + fmt.Fprintf(w, " %-12s %5d %10s\n", "TOTAL", totalCount, totalDurC.Round(time.Millisecond)) + fmt.Fprintf(w, "\n Peak concurrent containers: %d\n", peak) + fmt.Fprintf(w, " Final active containers: %d\n\n", active) + } + + mu.Lock() + sCopy := make([]scenarioTiming, len(scenarioList)) + copy(sCopy, scenarioList) + mu.Unlock() + + if len(sCopy) > 0 { + type featureAgg struct { + Count int + Total time.Duration + Max time.Duration + } + features := make(map[string]*featureAgg) + for _, s := range sCopy { + f := filepath.Base(s.Feature) + agg, ok := features[f] + if !ok { + agg = &featureAgg{} + features[f] = agg + } + agg.Count++ + agg.Total += s.Duration + if s.Duration > agg.Max { + agg.Max = s.Duration + } + } + + fNames := make([]string, 0, len(features)) + for f := range features { + fNames = append(fNames, f) + } + sort.Strings(fNames) + + fmt.Fprintf(w, "--- Per-Feature Aggregate ---\n") + fmt.Fprintf(w, " %-35s %5s %10s %10s %10s\n", "FEATURE", "COUNT", "TOTAL", "AVG", "MAX") + for _, f := range fNames { + agg := features[f] + avg := agg.Total / time.Duration(agg.Count) + fmt.Fprintf(w, " %-35s %5d %10s %10s %10s\n", + f, agg.Count, + agg.Total.Round(time.Millisecond), avg.Round(time.Millisecond), + agg.Max.Round(time.Millisecond)) + } + fmt.Fprintln(w) + + sort.Slice(sCopy, func(i, j int) bool { + return sCopy[i].Duration > sCopy[j].Duration + }) + limit := 20 + if len(sCopy) < limit { + limit = len(sCopy) + } + fmt.Fprintf(w, "--- Top %d Longest Scenarios ---\n", limit) + for i, s := range sCopy[:limit] { + name := s.Name + if len(name) > 55 { + name = name[:52] + "..." + } + fmt.Fprintf(w, " %2d. %-55s %10s (%s)\n", + i+1, name, s.Duration.Round(time.Millisecond), filepath.Base(s.Feature)) + } + fmt.Fprintln(w) + } + + fmt.Fprintf(w, "==========================================\n") + + report := buf.String() + fmt.Fprint(os.Stderr, report) + + if outputDir != "" { + os.WriteFile(filepath.Join(outputDir, "report.txt"), []byte(report), 0644) + } + if outputFile != nil { + outputFile.Close() + } +} diff --git a/acceptance/registry/registry.go b/acceptance/registry/registry.go index b8abdb9f2..2be1d324d 100644 --- a/acceptance/registry/registry.go +++ b/acceptance/registry/registry.go @@ -36,6 +36,7 @@ import ( "github.com/testcontainers/testcontainers-go/wait" "github.com/conforma/cli/acceptance/log" + "github.com/conforma/cli/acceptance/profile" "github.com/conforma/cli/acceptance/testenv" ) @@ -108,16 +109,19 @@ func startStubRegistry(ctx context.Context) (context.Context, error) { logger, ctx := log.LoggerFor(ctx) + endContainer := profile.BeginContainer("registry") registry, err := testcontainers.GenericContainer(ctx, testcontainers.GenericContainerRequest{ ContainerRequest: req, Started: true, Logger: logger, }) if err != nil { + endContainer() return ctx, err } port, err := registry.MappedPort(ctx, "5000/tcp") + endContainer() if err != nil { return ctx, err } diff --git a/acceptance/wiremock/wiremock.go b/acceptance/wiremock/wiremock.go index 08f7a94b2..f1b150b5d 100644 --- a/acceptance/wiremock/wiremock.go +++ b/acceptance/wiremock/wiremock.go @@ -36,6 +36,7 @@ import ( "github.com/wiremock/go-wiremock" "github.com/conforma/cli/acceptance/log" + "github.com/conforma/cli/acceptance/profile" "github.com/conforma/cli/acceptance/testenv" ) @@ -216,16 +217,20 @@ func StartWiremock(ctx context.Context) (context.Context, error) { }) logger, ctx := log.LoggerFor(ctx) + + endContainer := profile.BeginContainer("wiremock") w, err := testcontainers.GenericContainer(ctx, testcontainers.GenericContainerRequest{ ContainerRequest: req, Started: true, Logger: logger, }) if err != nil { + endContainer() return ctx, fmt.Errorf("unable to run GenericContainer: %v", err) } port, err := w.MappedPort(ctx, "8080/tcp") + endContainer() if err != nil { return ctx, err }