diff --git a/cmd/soong_ui/main.go b/cmd/soong_ui/main.go index 8c99988f2..661bd5d2e 100644 --- a/cmd/soong_ui/main.go +++ b/cmd/soong_ui/main.go @@ -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...) } } diff --git a/ui/build/upload.go b/ui/build/upload.go index 9f14bdd7c..9959e6f9c 100644 --- a/ui/build/upload.go +++ b/ui/build/upload.go @@ -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 { diff --git a/ui/build/upload_test.go b/ui/build/upload_test.go index 764a1e127..58d923702 100644 --- a/ui/build/upload_test.go +++ b/ui/build/upload_test.go @@ -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) + } +} diff --git a/ui/metrics/Android.bp b/ui/metrics/Android.bp index 2301c562f..bd1517cf4 100644 --- a/ui/metrics/Android.bp +++ b/ui/metrics/Android.bp @@ -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",