feat(librarian): write a timing log at the end of update-image (#2771)

This writes a file rather than logging the timing of each library to
avoid cluttering up the logs, and to make it easier to look at just
timing.

At the moment this only writes a timing log for update-image, but the
writeTiming function is designed to make it easy to call from any other
comamnd (e.g. release init or generate) if we want.

Author: jskeet

internal/librarian/command.go

@@ -15,6 +15,7 @@
 package librarian
 
 import (
+	"cmp"
 	"context"
 	"errors"
 	"fmt"
@@ -39,6 +40,7 @@ import (
 const (
 	defaultAPISourceBranch  = "master"
 	prBodyFile              = "pr-body.txt"
+	timingFile              = "timing.txt"
 	failedGenerationComment = `One or more libraries have failed to generate, please review PR description for a list of failed libraries.
 For each failed library, open a ticket in that library’s repository and then you may resolve this comment and merge.
 `
@@ -756,3 +758,54 @@ func isURL(s string) bool {
 
 	return true
 }
+
+// writeTiming creates a file in the work root with diagnostic information
+// about the time taken to process each library. A summary line states
+// the number of individual measurements represented, as well as the total
+// and the average, then the time taken for each library is recorded
+// in descending order of time, to make it easier to figure out what to
+// focus on. All times are rounded to the nearest millisecond.
+func writeTiming(workRoot string, timeByLibrary map[string]time.Duration) error {
+	if len(timeByLibrary) == 0 {
+		slog.Info("no libraries processed; skipping timing statistics")
+		return nil
+	}
+
+	// Work out the total and average times, and create a slice of timing
+	// by library, sorted in descending order of duration.
+	var total time.Duration
+	for _, duration := range timeByLibrary {
+		total += duration
+	}
+	average := time.Duration(int64(total) / int64(len(timeByLibrary)))
+
+	type timing struct {
+		LibraryID string
+		Duration  time.Duration
+	}
+
+	var timingStructs []timing
+	for id, duration := range timeByLibrary {
+		timingStructs = append(timingStructs, timing{id, duration})
+	}
+
+	slices.SortFunc(timingStructs, func(a, b timing) int {
+		return -cmp.Compare(a.Duration, b.Duration)
+	})
+
+	// Create the timing log in memory: one summary line, then one line per library.
+	var sb strings.Builder
+	sb.WriteString(fmt.Sprintf("Processed %d libraries in %s; average=%s\n", len(timeByLibrary), total.Round(time.Millisecond), average.Round(time.Millisecond)))
+
+	for _, ts := range timingStructs {
+		sb.WriteString(fmt.Sprintf("%s: %s\n", ts.LibraryID, ts.Duration.Round(time.Millisecond)))
+	}
+
+	// Write it out to disk.
+	fullPath := filepath.Join(workRoot, timingFile)
+	if err := os.WriteFile(fullPath, []byte(sb.String()), 0644); err != nil {
+		return err
+	}
+	slog.Info("wrote timing statistics", "file", fullPath)
+	return nil
+}

internal/librarian/command_test.go

@@ -24,6 +24,7 @@ import (
 	"sort"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/google/go-cmp/cmp"
 	"github.com/googleapis/librarian/internal/config"
@@ -2296,3 +2297,49 @@ func TestCopyGlobalAllowlist(t *testing.T) {
 		})
 	}
 }
+
+func TestWriteTiming_BadWorkRoot(t *testing.T) {
+	badWorkRoot := filepath.Join(t.TempDir(), "missing-directory")
+	timeByLibrary := map[string]time.Duration{
+		"a": time.Second,
+	}
+	if err := writeTiming(badWorkRoot, timeByLibrary); err == nil {
+		t.Fatal("writeTiming() expected to return error")
+	}
+}
+
+func TestWriteTiming_EmptyMap(t *testing.T) {
+	workRoot := filepath.Join(t.TempDir())
+	timeByLibrary := map[string]time.Duration{}
+	if err := writeTiming(workRoot, timeByLibrary); err != nil {
+		t.Fatal("writeTiming() failed", err)
+	}
+	if _, err := os.Stat(filepath.Join(workRoot, timingFile)); !os.IsNotExist(err) {
+		t.Error("writeTiming() should not have created a file")
+	}
+}
+
+func TestWriteTiming(t *testing.T) {
+	workRoot := t.TempDir()
+	timeByLibrary := map[string]time.Duration{
+		"a": time.Second,
+		"b": 5 * time.Second,
+		"c": 3 * time.Second,
+	}
+	if err := writeTiming(workRoot, timeByLibrary); err != nil {
+		t.Fatal("writeTiming() failed", err)
+	}
+	want := `Processed 3 libraries in 9s; average=3s
+b: 5s
+c: 3s
+a: 1s
+`
+	bytes, err := os.ReadFile(filepath.Join(workRoot, timingFile))
+	if err != nil {
+		t.Fatal("unable to read timing log", err)
+	}
+	got := string(bytes)
+	if diff := cmp.Diff(want, got); diff != "" {
+		t.Errorf("writeTiming() mismatch (-want +got):%s", diff)
+	}
+}

internal/librarian/update_image.go

@@ -22,6 +22,7 @@ import (
 	"log/slog"
 	"path/filepath"
 	"strings"
+	"time"
 
 	"github.com/googleapis/librarian/internal/config"
 	"github.com/googleapis/librarian/internal/gitrepo"
@@ -118,7 +119,9 @@ func (r *updateImageRunner) run(ctx context.Context) error {
 		return err
 	}
 	outputDir := filepath.Join(r.workRoot, "output")
+	timings := map[string]time.Duration{}
 	for _, libraryState := range r.state.Libraries {
+		startTime := time.Now()
 		err := r.regenerateSingleLibrary(ctx, libraryState, outputDir)
 		if err != nil {
 			slog.Error(err.Error(), "library", libraryState.ID, "commit", libraryState.LastGeneratedCommit)
@@ -127,11 +130,15 @@ func (r *updateImageRunner) run(ctx context.Context) error {
 		} else {
 			successfulGenerations = append(successfulGenerations, libraryState)
 		}
+		timings[libraryState.ID] = time.Since(startTime)
 	}
 	if len(failedGenerations) > 0 {
 		slog.Warn("failed generations", slog.Int("num", len(failedGenerations)))
 	}
 	slog.Info("successful generations", slog.Int("num", len(successfulGenerations)))
+	if err := writeTiming(r.workRoot, timings); err != nil {
+		return err
+	}
 
 	prBodyBuilder := func() (string, error) {
 		return formatUpdateImagePRBody(r.image, failedGenerations)