feat: prewarm git repo from Bitrise Build Cache

gitclone/checkout_method_pr_auto_merge_branch.go

@@ -3,7 +3,8 @@ package gitclone
 import (
 	"fmt"
 	"strings"
-
+	"time"
+
 	"github.com/bitrise-io/go-utils/command/git"
 	"github.com/bitrise-io/go-utils/log"
 )
@@ -62,36 +63,46 @@ func (c checkoutPRMergeRef) performCheckout(gitCmd git.Git, fetchOpts fetchOptio
 	// This is caused by the remote merge and head branches being "force-pushed" by GitHub.
 	// To solve it we remove merge and head branch refs.
 	// $ git update-ref -d refs/remotes/pull/7/merge
+	tDelMerge := time.Now()
 	err := deleteRef(gitCmd, c.localMergeRef())
 	if err != nil {
 		return fmt.Errorf("failed to delete ref: %w", err)
 	}
+	log.Printf("[%s] PRMergeRef: delete-ref %s took %s", time.Now().Format("15:04:05.000"), c.localMergeRef(), time.Since(tDelMerge).Round(time.Millisecond))
 
 	// $ git update-ref -d refs/remotes/pull/7/head
 	// If the ref does not exist, the command still exits with 0 exit code.
+	tDelHead := time.Now()
 	err = deleteRef(gitCmd, c.localHeadRef())
 	if err != nil {
 		return fmt.Errorf("failed to delete ref: %w", err)
 	}
+	log.Printf("[%s] PRMergeRef: delete-ref %s took %s", time.Now().Format("15:04:05.000"), c.localHeadRef(), time.Since(tDelHead).Round(time.Millisecond))
 
 	//$ git fetch origin refs/remotes/pull/7/merge:refs/pull/7/merge
+	tFetchMerge := time.Now()
 	err = fetch(gitCmd, originRemoteName, refSpec, fetchOpts)
 	if err != nil {
 		return fmt.Errorf("failed to fetch merge ref: %w", err)
 	}
+	log.Printf("[%s] PRMergeRef: fetch merge ref %s took %s", time.Now().Format("15:04:05.000"), refSpec, time.Since(tFetchMerge).Round(time.Millisecond))
 
 	// Also fetch the PR head ref because the step exports outputs based on the PR head commit (see output.go)
 	// $ git fetch origin refs/remotes/pull/7/head:refs/pull/7/head
+	tFetchHead := time.Now()
 	err = c.fetchPRHeadRef(gitCmd, fetchOpts)
 	if err != nil {
 		return err
 	}
+	log.Printf("[%s] PRMergeRef: fetch head ref %s took %s", time.Now().Format("15:04:05.000"), c.remoteHeadRef(), time.Since(tFetchHead).Round(time.Millisecond))
 
 	// $ git checkout refs/remotes/pull/7/merge
+	tCheckout := time.Now()
 	err = checkoutWithCustomRetry(gitCmd, c.localMergeRef(), nil)
 	if err != nil {
 		return err
 	}
+	log.Printf("[%s] PRMergeRef: checkout %s took %s", time.Now().Format("15:04:05.000"), c.localMergeRef(), time.Since(tCheckout).Round(time.Millisecond))
 
 	return nil
 }

gitclone/gitclone.go

@@ -74,6 +74,12 @@ type CheckoutStateResult struct {
 func (g GitCloner) CheckoutState(cfg Config) (CheckoutStateResult, error) {
 	defer g.tracker.Wait()
 
+	checkoutStateStart := time.Now()
+	g.logger.TInfof("CheckoutState: starting git checkout flow")
+
+	setupStart := time.Now()
+	g.logger.TInfof("CheckoutState: phase=setup (origin check, init, remote add, gc config)")
+
 	gitCmd, err := git.New(cfg.CloneIntoDir)
 	if err != nil {
 		return CheckoutStateResult{}, newStepError(
@@ -93,13 +99,16 @@ func (g GitCloner) CheckoutState(cfg Config) (CheckoutStateResult, error) {
 	}
 
 	if originPresent && cfg.ResetRepository {
+		resetStart := time.Now()
+		g.logger.TInfof("CheckoutState: phase=reset-repo (origin present and reset_repository=true)")
 		if err := resetRepo(gitCmd); err != nil {
 			return CheckoutStateResult{}, newStepError(
 				"reset_repository_failed",
 				fmt.Errorf("reset repository failed: %v", err),
 				"Resetting repository failed",
 			)
 		}
+		g.logger.TInfof("CheckoutState: reset-repo took %s", time.Since(resetStart).Round(time.Millisecond))
 	}
 	if err := runner.Run(gitCmd.Init()); err != nil {
 		return CheckoutStateResult{}, newStepError(
@@ -129,11 +138,19 @@ func (g GitCloner) CheckoutState(cfg Config) (CheckoutStateResult, error) {
 			"Failed to disable git garbage collection",
 		)
 	}
+	g.logger.TInfof("CheckoutState: setup took %s", time.Since(setupStart).Round(time.Millisecond))
 
-	if err := setupSparseCheckout(gitCmd, cfg.SparseDirectories); err != nil {
-		return CheckoutStateResult{}, err
+	if len(cfg.SparseDirectories) > 0 {
+		sparseStart := time.Now()
+		g.logger.TInfof("CheckoutState: phase=sparse-checkout (configuring %d directories)", len(cfg.SparseDirectories))
+		if err := setupSparseCheckout(gitCmd, cfg.SparseDirectories); err != nil {
+			return CheckoutStateResult{}, err
+		}
+		g.logger.TInfof("CheckoutState: sparse-checkout took %s", time.Since(sparseStart).Round(time.Millisecond))
 	}
 
+	cleanCheckStart := time.Now()
+	g.logger.TInfof("CheckoutState: phase=working-tree-clean-check")
 	clean, err := isWorkingTreeClean(gitCmd)
 	if err != nil {
 		g.logger.Warnf("Failed to check if working tree is clean: %s", err)
@@ -152,23 +169,28 @@ func (g GitCloner) CheckoutState(cfg Config) (CheckoutStateResult, error) {
 			g.logger.Warnf("Failed to reset repository: %s", err)
 		}
 	}
+	g.logger.TInfof("CheckoutState: working-tree-clean-check took %s (was clean=%t)", time.Since(cleanCheckStart).Round(time.Millisecond), clean)
 
+	g.logger.TInfof("CheckoutState: phase=fetch-and-checkout")
 	checkoutStrategy, isPR, err := g.checkoutState(gitCmd, cfg)
 	if err != nil {
 		return CheckoutStateResult{}, err
 	}
 
 	if cfg.UpdateSubmodules {
 		startTime := time.Now()
+		g.logger.TInfof("CheckoutState: phase=submodule-update")
 		if err := updateSubmodules(gitCmd, cfg); err != nil {
 			return CheckoutStateResult{}, err
 		}
 		updateTime := time.Since(startTime).Round(time.Second)
 		g.logger.Println()
-		g.logger.Infof("Updating submodules took %s", updateTime)
+		g.logger.TInfof("CheckoutState: submodule-update took %s", updateTime)
 		g.tracker.LogSubmoduleUpdate(updateTime)
 	}
 
+	g.logger.Donef("CheckoutState: total took %s", time.Since(checkoutStateStart).Round(time.Millisecond))
+
 	return CheckoutStateResult{
 		gitRef: checkoutStrategy.getBuildTriggerRef(),
 		isPR:   isPR,
@@ -195,10 +217,10 @@ func (g GitCloner) checkoutState(gitCmd git.Git, cfg Config) (strategy checkoutS
 		return nil, false, err
 	}
 
-	checkoutDuration := time.Since(checkoutStartTime).Round(time.Second)
+	checkoutDuration := time.Since(checkoutStartTime).Round(time.Millisecond)
 	g.logger.Println()
-	g.logger.Infof("Fetch and checkout took %s", checkoutDuration)
-	g.tracker.LogCheckout(checkoutDuration, checkoutMethod.String(), cfg.RepositoryURL)
+	g.logger.TInfof("Fetch and checkout took %s", checkoutDuration)
+	g.tracker.LogCheckout(checkoutDuration.Round(time.Second), checkoutMethod.String(), cfg.RepositoryURL)
 
 	return checkoutStrategy, isPRCheckout(checkoutMethod), nil
 }

go.mod

@@ -1,8 +1,9 @@
 module github.com/bitrise-steplib/steps-git-clone
 
-go 1.22.0
+go 1.24.0
 
 require (
+	github.com/bitrise-io/bitrise-build-cache-cli/v2 v2.6.1-0.20260507075805-6857170497fa
 	github.com/bitrise-io/bitrise-init v0.0.0-20250909114624-fbfc915502b7
 	github.com/bitrise-io/envman v0.0.0-20210517135508-b2b4fe89eac5
 	github.com/bitrise-io/go-steputils v1.0.6
@@ -15,16 +16,31 @@ require (
 )
 
 require (
+	cloud.google.com/go/longrunning v0.6.0 // indirect
+	github.com/bazelbuild/remote-apis v0.0.0-20240703191324-0d21f29acdb9 // indirect
 	github.com/bitrise-io/goinp v0.0.0-20240103152431-054ed78518ef // indirect
-	github.com/davecgh/go-spew v1.1.1 // indirect
+	github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc // indirect
+	github.com/dustin/go-humanize v1.0.1 // indirect
 	github.com/gofrs/uuid/v5 v5.2.0 // indirect
+	github.com/google/uuid v1.6.0 // indirect
 	github.com/hashicorp/go-cleanhttp v0.5.2 // indirect
+	github.com/klauspost/cpuid/v2 v2.0.12 // indirect
+	github.com/kr/text v0.2.0 // indirect
 	github.com/mitchellh/mapstructure v1.5.0 // indirect
-	github.com/pmezard/go-difflib v1.0.0 // indirect
+	github.com/pkg/xattr v0.4.10 // indirect
+	github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 // indirect
 	github.com/stretchr/objx v0.5.2 // indirect
-	golang.org/x/crypto v0.32.0 // indirect
-	golang.org/x/sys v0.29.0 // indirect
-	golang.org/x/term v0.28.0 // indirect
+	github.com/zeebo/blake3 v0.2.4 // indirect
+	golang.org/x/crypto v0.48.0 // indirect
+	golang.org/x/net v0.50.0 // indirect
+	golang.org/x/sys v0.41.0 // indirect
+	golang.org/x/term v0.40.0 // indirect
+	golang.org/x/text v0.34.0 // indirect
+	google.golang.org/genproto/googleapis/api v0.0.0-20251202230838-ff82c1b0f217 // indirect
+	google.golang.org/genproto/googleapis/bytestream v0.0.0-20240822170219-fc7c04adadcd // indirect
+	google.golang.org/genproto/googleapis/rpc v0.0.0-20251202230838-ff82c1b0f217 // indirect
+	google.golang.org/grpc v1.79.3 // indirect
+	google.golang.org/protobuf v1.36.10 // indirect
 	gopkg.in/yaml.v2 v2.4.0 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )