Merge "Write bazel metrics file from soong." (3420d978) · Commits · e / os / android_build_soong

cmd/soong_ui/main.go

+6 −1

Original line number	Diff line number	Diff line
		@@ -199,11 +199,16 @@ func main() {
		soongMetricsFile := filepath.Join(logsDir, c.logsPrefix+"soong_metrics")
		rbeMetricsFile := filepath.Join(logsDir, c.logsPrefix+"rbe_metrics.pb")
		bp2buildMetricsFile := filepath.Join(logsDir, c.logsPrefix+"bp2build_metrics.pb")
		bazelMetricsFile := filepath.Join(logsDir, c.logsPrefix+"bazel_metrics.pb")

		//the profile file generated by Bazel"
		bazelProfileFile := filepath.Join(logsDir, c.logsPrefix+"analyzed_bazel_profile.txt")
		metricsFiles := []string{
		buildErrorFile, // build error strings
		rbeMetricsFile, // high level metrics related to remote build execution.
		bp2buildMetricsFile, // high level metrics related to bp2build.
		soongMetricsFile, // high level metrics related to this build system.
		bazelMetricsFile, // high level metrics related to bazel execution
		config.BazelMetricsDir(), // directory that contains a set of bazel metrics.
		}

		@@ -217,7 +222,7 @@ func main() {

		defer met.Dump(soongMetricsFile)
		if !config.SkipMetricsUpload() {
		defer build.UploadMetrics(buildCtx, config, c.simpleOutput, buildStarted, metricsFiles...)
		defer build.UploadMetrics(buildCtx, config, c.simpleOutput, buildStarted, bazelProfileFile, bazelMetricsFile, metricsFiles...)
		}

		}

ui/build/upload.go

+108 −1

Original line number	Diff line number	Diff line
		@@ -18,16 +18,21 @@ package build
		// another.

		import (
		"bufio"
		"fmt"
		"io/ioutil"
		"os"
		"path/filepath"
		"strconv"
		"strings"
		"time"

		"android/soong/shared"
		"android/soong/ui/metrics"

		"google.golang.org/protobuf/proto"

		bazel_metrics_proto "android/soong/ui/metrics/bazel_metrics_proto"
		upload_proto "android/soong/ui/metrics/upload_proto"
		)

		@@ -73,12 +78,113 @@ func pruneMetricsFiles(paths []string) []string {
		return metricsFiles
		}

		func parseTimingToNanos(str string) int64 {
		millisString := removeDecimalPoint(str)
		timingMillis, _ := strconv.ParseInt(millisString, 10, 64)
		return timingMillis * 1000000
		}

		func parsePercentageToTenThousandths(str string) int32 {
		percentageString := removeDecimalPoint(str)
		//remove the % at the end of the string
		percentage := strings.ReplaceAll(percentageString, "%", "")
		percentagePortion, _ := strconv.ParseInt(percentage, 10, 32)
		return int32(percentagePortion)
		}

		func removeDecimalPoint(numString string) string {
		// The format is always 0.425 or 10.425
		return strings.ReplaceAll(numString, ".", "")
		}

		func parseTotal(line string) int64 {
		words := strings.Fields(line)
		timing := words[3]
		return parseTimingToNanos(timing)
		}

		func parsePhaseTiming(line string) bazel_metrics_proto.PhaseTiming {
		words := strings.Fields(line)
		getPhaseNameAndTimingAndPercentage := func([]string) (string, int64, int32) {
		// Sample lines include:
		// Total launch phase time 0.011 s 2.59%
		// Total target pattern evaluation phase time 0.011 s 2.59%
		var beginning int
		var end int
		for ind, word := range words {
		if word == "Total" {
		beginning = ind + 1
		} else if beginning > 0 && word == "phase" {
		end = ind
		break
		}
		}
		phaseName := strings.Join(words[beginning:end], " ")

		// end is now "phase" - advance by 2 for timing and 4 for percentage
		percentageString := words[end+4]
		timingString := words[end+2]
		timing := parseTimingToNanos(timingString)
		percentagePortion := parsePercentageToTenThousandths(percentageString)
		return phaseName, timing, percentagePortion
		}

		phaseName, timing, portion := getPhaseNameAndTimingAndPercentage(words)
		phaseTiming := bazel_metrics_proto.PhaseTiming{}
		phaseTiming.DurationNanos = &timing
		phaseTiming.PortionOfBuildTime = &portion

		phaseTiming.PhaseName = &phaseName
		return phaseTiming
		}

		func processBazelMetrics(bazelProfileFile string, bazelMetricsFile string, ctx Context) {
		if bazelProfileFile == "" {
		return
		}

		readBazelProto := func(filepath string) bazel_metrics_proto.BazelMetrics {
		//serialize the proto, write it
		bazelMetrics := bazel_metrics_proto.BazelMetrics{}

		file, err := os.ReadFile(filepath)
		if err != nil {
		ctx.Fatalln("Error reading metrics file\n", err)
		}

		scanner := bufio.NewScanner(strings.NewReader(string(file)))
		scanner.Split(bufio.ScanLines)

		var phaseTimings []*bazel_metrics_proto.PhaseTiming
		for scanner.Scan() {
		line := scanner.Text()
		if strings.HasPrefix(line, "Total run time") {
		total := parseTotal(line)
		bazelMetrics.Total = &total
		} else if strings.HasPrefix(line, "Total") {
		phaseTiming := parsePhaseTiming(line)
		phaseTimings = append(phaseTimings, &phaseTiming)
		}
		}
		bazelMetrics.PhaseTimings = phaseTimings

		return bazelMetrics
		}

		if _, err := os.Stat(bazelProfileFile); err != nil {
		// We can assume bazel didn't run if the profile doesn't exist
		return
		}
		bazelProto := readBazelProto(bazelProfileFile)
		shared.Save(&bazelProto, bazelMetricsFile)
		}

		// UploadMetrics uploads a set of metrics files to a server for analysis.
		// The metrics files are first copied to a temporary directory
		// and the uploader is then executed in the background to allow the user/system
		// to continue working. Soong communicates to the uploader through the
		// upload_proto raw protobuf file.
		func UploadMetrics(ctx Context, config Config, simpleOutput bool, buildStarted time.Time, paths ...string) {
		func UploadMetrics(ctx Context, config Config, simpleOutput bool, buildStarted time.Time, bazelProfileFile string, bazelMetricsFile string, paths ...string) {
		ctx.BeginTrace(metrics.RunSetupTool, "upload_metrics")
		defer ctx.EndTrace()

		@@ -88,6 +194,7 @@ func UploadMetrics(ctx Context, config Config, simpleOutput bool, buildStarted t
		return
		}

		processBazelMetrics(bazelProfileFile, bazelMetricsFile, ctx)
		// Several of the files might be directories.
		metricsFiles := pruneMetricsFiles(paths)
		if len(metricsFiles) == 0 {

ui/build/upload_test.go

+102 −4

Original line number	Diff line number	Diff line
		@@ -29,6 +29,30 @@ import (
		"android/soong/ui/logger"
		)

		func writeBazelProfileFile(dir string) error {
		contents := `

		=== PHASE SUMMARY INFORMATION ===

		Total launch phase time 1.193 s 15.77%
		Total init phase time 1.092 s 14.44%
		Total target pattern evaluation phase time 0.580 s 7.67%
		Total interleaved loading-and-analysis phase time 3.646 s 48.21%
		Total preparation phase time 0.022 s 0.30%
		Total execution phase time 0.993 s 13.13%
		Total finish phase time 0.036 s 0.48%
		---------------------------------------------------------------------
		Total run time 7.563 s 100.00%

		Critical path (178 ms):
		Time Percentage Description
		178 ms 100.00% action 'BazelWorkspaceStatusAction stable-status.txt'

		`
		file := filepath.Join(dir, "bazel_metrics.txt")
		return os.WriteFile(file, []byte(contents), 0666)
		}

		func TestPruneMetricsFiles(t *testing.T) {
		rootDir := t.TempDir()

		@@ -84,12 +108,12 @@ func TestUploadMetrics(t *testing.T) {
		}, {
		description: "non-existent metrics files no upload",
		uploader: "echo",
		files: []string{"metrics_file_1", "metrics_file_2", "metrics_file_3"},
		files: []string{"metrics_file_1", "metrics_file_2", "metrics_file_3, bazel_metrics.pb"},
		}, {
		description: "trigger upload",
		uploader: "echo",
		createFiles: true,
		files: []string{"metrics_file_1", "metrics_file_2"},
		files: []string{"metrics_file_1", "metrics_file_2, bazel_metrics.pb"},
		}}

		for _, tt := range tests {
		@@ -130,6 +154,9 @@ func TestUploadMetrics(t *testing.T) {
		}
		}
		}
		if err := writeBazelProfileFile(outDir); err != nil {
		t.Fatalf("failed to create bazel profile file in dir: %v", outDir)
		}

		config := Config{&configImpl{
		environ: &Environment{
		@@ -139,7 +166,7 @@ func TestUploadMetrics(t *testing.T) {
		metricsUploader: tt.uploader,
		}}

		UploadMetrics(ctx, config, false, time.Now(), metricsFiles...)
		UploadMetrics(ctx, config, false, time.Now(), "out/bazel_metrics.txt", "out/bazel_metrics.pb", metricsFiles...)
		})
		}
		}
		@@ -194,8 +221,79 @@ func TestUploadMetricsErrors(t *testing.T) {
		metricsUploader: "echo",
		}}

		UploadMetrics(ctx, config, true, time.Now(), metricsFile)
		UploadMetrics(ctx, config, true, time.Now(), "", "", metricsFile)
		t.Errorf("got nil, expecting %q as a failure", tt.expectedErr)
		})
		}
		}

		func TestParsePercentageToTenThousandths(t *testing.T) {
		// 2.59% should be returned as 259 - representing 259/10000 of the build
		percentage := parsePercentageToTenThousandths("2.59%")
		if percentage != 259 {
		t.Errorf("Expected percentage to be returned as ten-thousandths. Expected 259, have %d\n", percentage)
		}

		// Test without a leading digit
		percentage = parsePercentageToTenThousandths(".52%")
		if percentage != 52 {
		t.Errorf("Expected percentage to be returned as ten-thousandths. Expected 52, have %d\n", percentage)
		}
		}

		func TestParseTimingToNanos(t *testing.T) {
		// This parses from seconds (with millis precision) and returns nanos
		timingNanos := parseTimingToNanos("0.111")
		if timingNanos != 111000000 {
		t.Errorf("Error parsing timing. Expected 111000, have %d\n", timingNanos)
		}

		// Test without a leading digit
		timingNanos = parseTimingToNanos(".112")
		if timingNanos != 112000000 {
		t.Errorf("Error parsing timing. Expected 112000, have %d\n", timingNanos)
		}
		}

		func TestParsePhaseTiming(t *testing.T) {
		// Sample lines include:
		// Total launch phase time 0.011 s 2.59%
		// Total target pattern evaluation phase time 0.012 s 4.59%

		line1 := "Total launch phase time 0.011 s 2.59%"
		timing := parsePhaseTiming(line1)

		if timing.GetPhaseName() != "launch" {
		t.Errorf("Failed to parse phase name. Expected launch, have %s\n", timing.GetPhaseName())
		} else if timing.GetDurationNanos() != 11000000 {
		t.Errorf("Failed to parse duration nanos. Expected 11000000, have %d\n", timing.GetDurationNanos())
		} else if timing.GetPortionOfBuildTime() != 259 {
		t.Errorf("Failed to parse portion of build time. Expected 259, have %d\n", timing.GetPortionOfBuildTime())
		}

		// Test with a multiword phase name
		line2 := "Total target pattern evaluation phase time 0.012 s 4.59%"

		timing = parsePhaseTiming(line2)
		if timing.GetPhaseName() != "target pattern evaluation" {
		t.Errorf("Failed to parse phase name. Expected target pattern evaluation, have %s\n", timing.GetPhaseName())
		} else if timing.GetDurationNanos() != 12000000 {
		t.Errorf("Failed to parse duration nanos. Expected 12000000, have %d\n", timing.GetDurationNanos())
		} else if timing.GetPortionOfBuildTime() != 459 {
		t.Errorf("Failed to parse portion of build time. Expected 459, have %d\n", timing.GetPortionOfBuildTime())
		}
		}

		func TestParseTotal(t *testing.T) {
		// Total line is in the form of:
		// Total run time 7.563 s 100.00%

		line := "Total run time 7.563 s 100.00%"

		total := parseTotal(line)

		// Only the seconds field is parsed, as nanos
		if total != 7563000000 {
		t.Errorf("Failed to parse total build time. Expected 7563000000, have %d\n", total)
		}
		}

ui/metrics/Android.bp

+13 −0

Original line number	Diff line number	Diff line
		@@ -22,6 +22,7 @@ bootstrap_go_package {
		deps: [
		"golang-protobuf-proto",
		"soong-ui-bp2build_metrics_proto",
		"soong-ui-bazel_metrics_proto",
		"soong-ui-metrics_upload_proto",
		"soong-ui-metrics_proto",
		"soong-ui-mk_metrics_proto",
		@@ -72,6 +73,18 @@ bootstrap_go_package {
		],
		}

		bootstrap_go_package {
		name: "soong-ui-bazel_metrics_proto",
		pkgPath: "android/soong/ui/metrics/bazel_metrics_proto",
		deps: [
		"golang-protobuf-reflect-protoreflect",
		"golang-protobuf-runtime-protoimpl",
		],
		srcs: [
		"bazel_metrics_proto/bazel_metrics.pb.go",
		],
		}

		bootstrap_go_package {
		name: "soong-ui-mk_metrics_proto",
		pkgPath: "android/soong/ui/metrics/mk_metrics_proto",