novox/mesh-catalog
18
0
Fork 0
Code Issues Pull Requests 3 Actions Packages Projects Releases Wiki Activity

mesh-build-go: say how long each phase of a fetch ran, so a check's "clone" time splits into mirror, fetch, preview, repack, siblings and modules (issue 1921, try speed S1)

Browse Source
This commit is contained in:
jschoubben
2026-10-25 00:54:55 +02:00
parent 1968aba6e0
commit 4f074e87c7
2 changed files with 143 additions and 11 deletions
Download Patch File Download Diff File Expand all files Collapse all files
modules/mesh-build-go/cmd/mesh-build-go/fetch.go
+85 -11
View File
@@ -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
modules/mesh-build-go/cmd/mesh-build-go/fetch_test.go
+58
View File
@@ -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)
}
}