Add build tracing

This creates a rotating build.trace.gz in the out directory that can be
loaded with chrome://tracing. It'll include start and end timings for
make/soong/kati/ninja, and it will import and time-correct the ninja log
files.

Test: m -j; load out/build.trace.gz in chrome://tracing
Test: multiproduct_kati -keep; load out/multiproduct*/build.trace.gz
Change-Id: Ic060fa9515eb88d95dbe16712479dae9dffcf626

4 files changed, 32 insertions, 11 deletions

diff --git a/cmd/multiproduct_kati/Android.bp b/cmd/multiproduct_kati/Android.bp
index 8c1cd266..b264c354 100644
--- a/cmd/multiproduct_kati/Android.bp
+++ b/cmd/multiproduct_kati/Android.bp
@@ -17,6 +17,7 @@ blueprint_go_binary {
     deps: [
         "soong-ui-build",
         "soong-ui-logger",
+        "soong-ui-tracer",
     ],
     srcs: [
         "main.go",
diff --git a/cmd/multiproduct_kati/main.go b/cmd/multiproduct_kati/main.go
index 0570c17b..2ff19ce4 100644
--- a/cmd/multiproduct_kati/main.go
+++ b/cmd/multiproduct_kati/main.go
@@ -28,6 +28,7 @@ import (
 
 	"android/soong/ui/build"
 	"android/soong/ui/logger"
+	"android/soong/ui/tracer"
 )
 
 // We default to number of cpus / 4, which seems to be the sweet spot for my
@@ -64,13 +65,20 @@ func main() {
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
 
-	build.SetupSignals(log, cancel, log.Cleanup)
+	trace := tracer.New(log)
+	defer trace.Close()
 
-	buildCtx := &build.ContextImpl{
+	build.SetupSignals(log, cancel, func() {
+		trace.Close()
+		log.Cleanup()
+	})
+
+	buildCtx := build.Context{&build.ContextImpl{
 		Context:        ctx,
 		Logger:         log,
+		Tracer:         trace,
 		StdioInterface: build.StdioImpl{},
-	}
+	}}
 
 	failed := false
 
@@ -95,6 +103,7 @@ func main() {
 
 	build.SetupOutDir(buildCtx, config)
 	log.SetOutput(filepath.Join(config.OutDir(), "build.log"))
+	trace.SetOutput(filepath.Join(config.OutDir(), "build.trace"))
 
 	vars, err := build.DumpMakeVars(buildCtx, config, nil, nil, []string{"all_named_products"})
 	if err != nil {
@@ -130,11 +139,13 @@ func main() {
 			productLog := logger.New(&bytes.Buffer{})
 			productLog.SetOutput(filepath.Join(productOutDir, "build.log"))
 
-			productCtx := &build.ContextImpl{
+			productCtx := build.Context{&build.ContextImpl{
 				Context:        ctx,
 				Logger:         productLog,
+				Tracer:         trace,
 				StdioInterface: build.NewCustomStdio(nil, f, f),
-			}
+				Thread:         trace.NewThread(product),
+			}}
 
 			productConfig := build.NewConfig(productCtx)
 			productConfig.Environment().Set("OUT_DIR", productOutDir)
diff --git a/cmd/soong_ui/Android.bp b/cmd/soong_ui/Android.bp
index 6d6ef339..f09e42ed 100644
--- a/cmd/soong_ui/Android.bp
+++ b/cmd/soong_ui/Android.bp
@@ -17,6 +17,7 @@ blueprint_go_binary {
     deps: [
         "soong-ui-build",
         "soong-ui-logger",
+        "soong-ui-tracer",
     ],
     srcs: [
         "main.go",
diff --git a/cmd/soong_ui/main.go b/cmd/soong_ui/main.go
index 34739b75..de941f40 100644
--- a/cmd/soong_ui/main.go
+++ b/cmd/soong_ui/main.go
@@ -24,6 +24,7 @@ import (
 
 	"android/soong/ui/build"
 	"android/soong/ui/logger"
+	"android/soong/ui/tracer"
 )
 
 func indexList(s string, list []string) int {
@@ -51,26 +52,33 @@ func main() {
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
 
-	build.SetupSignals(log, cancel, log.Cleanup)
+	trace := tracer.New(log)
+	defer trace.Close()
 
-	buildCtx := &build.ContextImpl{
+	build.SetupSignals(log, cancel, func() {
+		trace.Close()
+		log.Cleanup()
+	})
+
+	buildCtx := build.Context{&build.ContextImpl{
 		Context:        ctx,
 		Logger:         log,
+		Tracer:         trace,
 		StdioInterface: build.StdioImpl{},
-	}
+	}}
 	config := build.NewConfig(buildCtx, os.Args[1:]...)
 
 	log.SetVerbose(config.IsVerbose())
-	if err := os.MkdirAll(config.OutDir(), 0777); err != nil {
-		log.Fatalf("Error creating out directory: %v", err)
-	}
+	build.SetupOutDir(buildCtx, config)
 	log.SetOutput(filepath.Join(config.OutDir(), "build.log"))
+	trace.SetOutput(filepath.Join(config.OutDir(), "build.trace"))
 
 	if start, ok := os.LookupEnv("TRACE_BEGIN_SOONG"); ok {
 		if !strings.HasSuffix(start, "N") {
 			if start_time, err := strconv.ParseUint(start, 10, 64); err == nil {
 				log.Verbosef("Took %dms to start up.",
 					time.Since(time.Unix(0, int64(start_time))).Nanoseconds()/time.Millisecond.Nanoseconds())
+				buildCtx.CompleteTrace("startup", start_time, uint64(time.Now().UnixNano()))
 			}
 		}
 	}