diff --git a/modules/mesh-build-go/cmd/mesh-build-go/fetch.go b/modules/mesh-build-go/cmd/mesh-build-go/fetch.go index 6dc0e424..91fd3176 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/fetch.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/fetch.go @@ -49,6 +49,51 @@ type FetchResult struct { // Beside are the sibling repositories placed as plain directories under the workspace's beside directory, which // build_go_test hands to the tests as MESH_CHECK_BESIDE (ADR 0484 clause 4). Beside []Sibling `json:"beside,omitempty"` + // Took is how long each phase of the fetch ran, in seconds (issue 1921, the try speed-up's first measurement): what + // the checker reports as one "clone" time, split. + Took *FetchTook `json:"took,omitempty"` +} + +// FetchTook is the time of each phase of a fetch, in seconds; its phases add up to Total. Mirror is bringing the +// repository's mirror to the commit, Fetch the fetch and checkout into the tree, Merge the merge preview, Dissociate +// the repack that makes the tree independent of the mirror, Beside the placing of the siblings (their own mirror, +// fetch and repack), Other the narrowing and the listing of the go.mod directories, and Modules the download and +// verify of the Go modules. +type FetchTook struct { + Mirror float64 `json:"mirror"` + Fetch float64 `json:"fetch"` + Merge float64 `json:"preview"` // named for the merge preview, apart from the result's merge commit + Dissociate float64 `json:"dissociate"` + Beside float64 `json:"siblings"` + Other float64 `json:"other"` + Modules float64 `json:"modules"` + Total float64 `json:"total"` +} + +// phaseClock stamps the phases of a fetch: each lap is the time since the one before, so the laps add up to the total. +type phaseClock struct { + now func() time.Time + start, since time.Time +} + +func newPhaseClock(now func() time.Time) *phaseClock { + t := now() + return &phaseClock{now: now, start: t, since: t} +} + +// lap adds the time since the last lap to *into. +func (c *phaseClock) lap(into *float64) { + t := c.now() + *into += t.Sub(c.since).Seconds() + c.since = t +} + +func (c *phaseClock) total() float64 { return c.since.Sub(c.start).Seconds() } + +// String is the one log line a fetch says of its phases. +func (t FetchTook) String() string { + return fmt.Sprintf("mirror %.1fs, fetch %.1fs, merge %.1fs, dissociate %.1fs, beside %.1fs, other %.1fs, modules %.1fs, total %.1fs", + t.Mirror, t.Fetch, t.Merge, t.Dissociate, t.Beside, t.Other, t.Modules, t.Total) } // fetchTool is the fetch step tool. @@ -109,43 +154,71 @@ func (m *Module) fetch(ctx context.Context, args map[string]any) (res any, err e } func (m *Module) fetchInto(ctx context.Context, req buildstep.FetchRequest, id string, siblings []siblingArg) (any, error) { + res, err := m.fetchPhases(ctx, req, id, siblings) + if err != nil { + return nil, err + } + if m.Say != nil && res.Took != nil { + m.Say("the fetch of %s at %s took %s", req.Repository, short(req.Commit), res.Took) + } + return res, nil +} + +func short(commit string) string { + if len(commit) > 12 { + return commit[:12] + } + return commit +} + +func (m *Module) fetchPhases(ctx context.Context, req buildstep.FetchRequest, id string, siblings []siblingArg) (FetchResult, error) { repository, commit, ref, base := req.Repository, req.Commit, req.Ref, req.Base var err error + took := &FetchTook{} + clock := newPhaseClock(m.now) + defer func() { took.Total = clock.total() }() root := filepath.Join(m.Work, id) tree := filepath.Join(root, "tree") if err := os.MkdirAll(tree, 0o700); err != nil { - return nil, err + return FetchResult{}, err } remote := m.remote(repository) - if err := buildstep.FetchCommit(ctx, m.Run, tree, remote, commit, ref, m.fetchOptions(ctx, repository, commit, ref)...); err != nil { - return nil, err + opts := m.fetchOptions(ctx, repository, commit, ref) + clock.lap(&took.Mirror) + if err := buildstep.FetchCommit(ctx, m.Run, tree, remote, commit, ref, opts...); err != nil { + return FetchResult{}, err } - res := FetchResult{Workspace: id, Commit: commit} + clock.lap(&took.Fetch) + res := FetchResult{Workspace: id, Commit: commit, Took: took} if base != "" { if err := m.merge(ctx, &res, tree, remote, base, commit); err != nil { - return nil, err + return FetchResult{}, err } } + clock.lap(&took.Merge) if err := m.dissociate(ctx, tree); err != nil { - return nil, err + return FetchResult{}, err } + clock.lap(&took.Dissociate) if res.Beside, err = m.placeSiblings(ctx, root, siblings); err != nil { - return nil, err + return FetchResult{}, err } + clock.lap(&took.Beside) if (base == "" || res.Merge != "") && len(req.Paths) > 0 { if err := buildstep.Narrow(tree, req); err != nil { - return nil, err + return FetchResult{}, err } // Said beside the tree, so the steps that list the tree's go.mod files leave out those narrowed away. if err := os.WriteFile(filepath.Join(root, narrowedMark), nil, 0o600); err != nil { - return nil, err + return FetchResult{}, err } } dirs, err := m.goModDirs(ctx, tree) if err != nil { - return nil, err + return FetchResult{}, err } res.Modules = dirs + clock.lap(&took.Other) if base != "" && res.Merge == "" { return res, nil // a conflict: the tree is at the trunk, nothing of the head is built or tested } @@ -168,9 +241,10 @@ func (m *Module) fetchInto(ctx context.Context, req buildstep.FetchRequest, id s }() } wg.Wait() + clock.lap(&took.Modules) for _, err := range errs { if err != nil { - return nil, err + return FetchResult{}, err } } return res, nil diff --git a/modules/mesh-build-go/cmd/mesh-build-go/fetch_test.go b/modules/mesh-build-go/cmd/mesh-build-go/fetch_test.go index 04874659..a6734ac3 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/fetch_test.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/fetch_test.go @@ -3,6 +3,7 @@ package main import ( "context" "encoding/json" + "fmt" "os" "path/filepath" "strings" @@ -302,3 +303,60 @@ func TestWorkAndCacheAreTheDirectoriesTheManifestPlacesOutsideTheHome(t *testing } } } + +// 1921/S1: the fetch says how long each phase ran (mirror, fetch, merge, dissociate, beside, other, modules), and the +// phases add up to its total, so a try's "clone" time is split into its parts. +func TestTheFetchSaysTheTimeOfEachPhaseAndTheyAddUpToTheTotal(t *testing.T) { + var mu sync.Mutex + now := time.Date(2026, 10, 25, 9, 0, 0, 0, time.UTC) + advance := func(s int) { + mu.Lock() + now = now.Add(time.Duration(s) * time.Second) + mu.Unlock() + } + f := &fakeStep{gomods: "go.mod\n", files: map[string]string{"go.mod": "module x\n", "go.sum": ""}, rule: func(line string) (forgekey.Ran, bool) { + switch { + case strings.Contains(line, "/mirror/") && strings.Contains(line, " fetch "): + advance(1) + case strings.Contains(line, " fetch --no-tags --depth 1 "): + advance(2) + case strings.Contains(line, " merge --no-ff "): + advance(3) + case strings.Contains(line, " repack "): + advance(4) + case strings.HasSuffix(line, " mod download"): + advance(5) + } + return forgekey.Ran{}, false + }} + m, states := fetchModule(t, f) + said := []string{} + m.Say = func(format string, a ...any) { said = append(said, fmt.Sprintf(format, a...)) } + m.Now = func() time.Time { mu.Lock(); defer mu.Unlock(); return now } + args := map[string]any{"repository": "novox/mesh-sdk", "commit": commitSHA, "base": strings.Repeat("b", 40)} + if _, err := fetchTool(t, m)(args); err != nil { + t.Fatal(err) + } + st := states.waitEnd(t) + if st.State != delivery.StepPassed { + t.Fatalf("the step ended %s: %s", st.State, st.Reason) + } + var res FetchResult + if err := json.Unmarshal(st.Result, &res); err != nil { + t.Fatal(err) + } + if res.Took == nil { + t.Fatalf("the result says no phase times: %s", st.Result) + } + got := *res.Took + want := FetchTook{Mirror: 1, Fetch: 2, Merge: 3, Dissociate: 4, Modules: 5, Total: 15} + if got != want { + t.Errorf("phases = %+v, want %+v", got, want) + } + if sum := got.Mirror + got.Fetch + got.Merge + got.Dissociate + got.Beside + got.Other + got.Modules; sum != got.Total { + t.Errorf("the phases add up to %v, not the total %v", sum, got.Total) + } + if !strings.Contains(strings.Join(said, "\n"), "dissociate 4.0s") { + t.Errorf("no log line names the phases: %q", said) + } +}