Write bazel metrics file from soong.

Test: b build libcore:all
Change-Id: I372d48a9c7132bc57ecc1a8ba06eb098d28cbad7
This commit is contained in:
MarkDacek 2023-01-06 22:15:24 +00:00
parent 41f9b734bb
commit 00e3152aca
4 changed files with 229 additions and 6 deletions

View file

@ -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...)
}
}

View file

@ -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 {

View file

@ -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)
}
}

View file

@ -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",