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

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

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)

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

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 {
+	build.SetupOutDir(buildCtx, config)
-		log.Fatalf("Error creating out directory: %v", err)
-	}
 	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()))
 			}
 		}
 	}

ui/build/Android.bp

@@ -17,6 +17,7 @@ bootstrap_go_package {
     pkgPath: "android/soong/ui/build",
     deps: [
         "soong-ui-logger",
+        "soong-ui-tracer",
     ],
     srcs: [
         "build.go",

ui/build/context.go

@@ -18,8 +18,10 @@ import (
 	"context"
 	"io"
 	"os"
+	"time"
 
 	"android/soong/ui/logger"
+	"android/soong/ui/tracer"
 )
 
 type StdioInterface interface {
@@ -55,10 +57,41 @@ var _ StdioInterface = customStdio{}
 // Context combines a context.Context, logger.Logger, and StdIO redirection.
 // These all are agnostic of the current build, and may be used for multiple
 // builds, while the Config objects contain per-build information.
-type Context *ContextImpl
+type Context struct{ *ContextImpl }
 type ContextImpl struct {
 	context.Context
 	logger.Logger
 
 	StdioInterface
+
+	Thread tracer.Thread
+	Tracer tracer.Tracer
+}
+
+// BeginTrace starts a new Duration Event.
+func (c ContextImpl) BeginTrace(name string) {
+	if c.Tracer != nil {
+		c.Tracer.Begin(name, c.Thread)
+	}
+}
+
+// EndTrace finishes the last Duration Event.
+func (c ContextImpl) EndTrace() {
+	if c.Tracer != nil {
+		c.Tracer.End(c.Thread)
+	}
+}
+
+// CompleteTrace writes a trace with a beginning and end times.
+func (c ContextImpl) CompleteTrace(name string, begin, end uint64) {
+	if c.Tracer != nil {
+		c.Tracer.Complete(name, c.Thread, begin, end)
+	}
+}
+
+// ImportNinjaLog imports a .ninja_log file into the tracer.
+func (c ContextImpl) ImportNinjaLog(filename string, startOffset time.Time) {
+	if c.Tracer != nil {
+		c.Tracer.ImportNinjaLog(c.Thread, filename, startOffset)
+	}
 }

ui/build/kati.go

@@ -57,6 +57,9 @@ func genKatiSuffix(ctx Context, config Config) {
 }
 
 func runKati(ctx Context, config Config) {
+	ctx.BeginTrace("kati")
+	defer ctx.EndTrace()
+
 	genKatiSuffix(ctx, config)
 
 	executable := "prebuilts/build-tools/" + config.HostPrebuiltTag() + "/bin/ckati"

ui/build/make.go

@@ -35,6 +35,9 @@ import (
 // vars is the list of variables to read. The values will be put in the
 // returned map.
 func DumpMakeVars(ctx Context, config Config, goals, extra_targets, vars []string) (map[string]string, error) {
+	ctx.BeginTrace("dumpvars")
+	defer ctx.EndTrace()
+
 	cmd := exec.CommandContext(ctx.Context,
 		"make",
 		"--no-print-directory",

ui/build/ninja.go

@@ -16,11 +16,16 @@ package build
 
 import (
 	"os/exec"
+	"path/filepath"
 	"strconv"
 	"strings"
+	"time"
 )
 
 func runNinja(ctx Context, config Config) {
+	ctx.BeginTrace("ninja")
+	defer ctx.EndTrace()
+
 	executable := "prebuilts/build-tools/" + config.HostPrebuiltTag() + "/bin/ninja"
 	args := []string{
 		"-d", "keepdepfile",
@@ -68,6 +73,8 @@ func runNinja(ctx Context, config Config) {
 	cmd.Stdout = ctx.Stdout()
 	cmd.Stderr = ctx.Stderr()
 	ctx.Verboseln(cmd.Path, cmd.Args)
+	startTime := time.Now()
+	defer ctx.ImportNinjaLog(filepath.Join(config.OutDir(), ".ninja_log"), startTime)
 	if err := cmd.Run(); err != nil {
 		if e, ok := err.(*exec.ExitError); ok {
 			ctx.Fatalln("ninja failed with:", e.ProcessState.String())

ui/build/soong.go

@@ -20,6 +20,9 @@ import (
 )
 
 func runSoongBootstrap(ctx Context, config Config) {
+	ctx.BeginTrace("bootstrap soong")
+	defer ctx.EndTrace()
+
 	cmd := exec.CommandContext(ctx.Context, "./bootstrap.bash")
 	env := config.Environment().Copy()
 	env.Set("BUILDDIR", config.SoongOutDir())
@@ -37,6 +40,9 @@ func runSoongBootstrap(ctx Context, config Config) {
 }
 
 func runSoong(ctx Context, config Config) {
+	ctx.BeginTrace("soong")
+	defer ctx.EndTrace()
+
 	cmd := exec.CommandContext(ctx.Context, filepath.Join(config.SoongOutDir(), "soong"), "-w", "dupbuild=err")
 	if config.IsVerbose() {
 		cmd.Args = append(cmd.Args, "-v")

ui/tracer/Android.bp

@@ -0,0 +1,23 @@
+// Copyright 2016 Google Inc. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+bootstrap_go_package {
+    name: "soong-ui-tracer",
+    pkgPath: "android/soong/ui/tracer",
+    deps: ["soong-ui-logger"],
+    srcs: [
+        "ninja.go",
+        "tracer.go",
+    ],
+}

ui/tracer/ninja.go

@@ -0,0 +1,130 @@
+// Copyright 2016 Google Inc. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package tracer
+
+import (
+	"bufio"
+	"os"
+	"sort"
+	"strconv"
+	"strings"
+	"time"
+)
+
+type ninjaLogEntry struct {
+	Name  string
+	Begin int
+	End   int
+}
+type ninjaLogEntries []*ninjaLogEntry
+
+func (n ninjaLogEntries) Len() int           { return len(n) }
+func (n ninjaLogEntries) Less(i, j int) bool { return n[i].Begin < n[j].Begin }
+func (n ninjaLogEntries) Swap(i, j int)      { n[i], n[j] = n[j], n[i] }
+
+// ImportNinjaLog reads a .ninja_log file from ninja and writes the events out
+// to the trace.
+//
+// startOffset is when the ninja process started, and is used to position the
+// relative times from the ninja log into the trace. It's also used to skip
+// reading the ninja log if nothing was run.
+func (t *tracerImpl) ImportNinjaLog(thread Thread, filename string, startOffset time.Time) {
+	t.Begin("ninja log import", thread)
+	defer t.End(thread)
+
+	if stat, err := os.Stat(filename); err != nil {
+		t.log.Println("Missing ninja log:", err)
+		return
+	} else if stat.ModTime().Before(startOffset) {
+		t.log.Verboseln("Ninja log not modified, not importing any entries.")
+		return
+	}
+
+	f, err := os.Open(filename)
+	if err != nil {
+		t.log.Println("Error opening ninja log:", err)
+		return
+	}
+	defer f.Close()
+
+	s := bufio.NewScanner(f)
+	header := true
+	entries := ninjaLogEntries{}
+	prevEnd := 0
+	for s.Scan() {
+		if header {
+			hdr := s.Text()
+			if hdr != "# ninja log v5" {
+				t.log.Printf("Unknown ninja log header: %q", hdr)
+				return
+			}
+			header = false
+			continue
+		}
+
+		fields := strings.Split(s.Text(), "\t")
+		begin, err := strconv.Atoi(fields[0])
+		if err != nil {
+			t.log.Printf("Unable to parse ninja entry %q: %v", s.Text(), err)
+			return
+		}
+		end, err := strconv.Atoi(fields[1])
+		if err != nil {
+			t.log.Printf("Unable to parse ninja entry %q: %v", s.Text(), err)
+			return
+		}
+		if end < prevEnd {
+			entries = nil
+		}
+		prevEnd = end
+		entries = append(entries, &ninjaLogEntry{
+			Name:  fields[3],
+			Begin: begin,
+			End:   end,
+		})
+	}
+	if err := s.Err(); err != nil {
+		t.log.Println("Unable to parse ninja log:", err)
+		return
+	}
+
+	sort.Sort(entries)
+
+	cpus := []int{}
+	offset := uint64(startOffset.UnixNano()) / 1000
+	for _, entry := range entries {
+		tid := -1
+		for cpu, endTime := range cpus {
+			if endTime <= entry.Begin {
+				tid = cpu
+				cpus[cpu] = entry.End
+				break
+			}
+		}
+		if tid == -1 {
+			tid = len(cpus)
+			cpus = append(cpus, entry.End)
+		}
+
+		t.writeEvent(&viewerEvent{
+			Name:  entry.Name,
+			Phase: "X",
+			Time:  offset + uint64(entry.Begin)*1000,
+			Dur:   uint64(entry.End-entry.Begin) * 1000,
+			Pid:   1,
+			Tid:   uint64(tid),
+		})
+	}
+}

ui/tracer/tracer.go

@@ -0,0 +1,244 @@
+// Copyright 2017 Google Inc. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// This package implements a trace file writer, whose files can be opened in
+// chrome://tracing.
+//
+// It implements the JSON Array Format defined here:
+// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit
+package tracer
+
+import (
+	"bytes"
+	"compress/gzip"
+	"encoding/json"
+	"fmt"
+	"io"
+	"os"
+	"strings"
+	"sync"
+	"time"
+
+	"android/soong/ui/logger"
+)
+
+type Thread uint64
+
+const (
+	MainThread     = Thread(iota)
+	MaxInitThreads = Thread(iota)
+)
+
+type Tracer interface {
+	Begin(name string, thread Thread)
+	End(thread Thread)
+	Complete(name string, thread Thread, begin, end uint64)
+
+	ImportNinjaLog(thread Thread, filename string, startOffset time.Time)
+}
+
+type tracerImpl struct {
+	lock sync.Mutex
+	log  logger.Logger
+
+	buf  bytes.Buffer
+	file *os.File
+	w    io.WriteCloser
+
+	firstEvent bool
+	nextTid    uint64
+}
+
+var _ Tracer = &tracerImpl{}
+
+type viewerEvent struct {
+	Name  string      `json:"name,omitempty"`
+	Phase string      `json:"ph"`
+	Scope string      `json:"s,omitempty"`
+	Time  uint64      `json:"ts"`
+	Dur   uint64      `json:"dur,omitempty"`
+	Pid   uint64      `json:"pid"`
+	Tid   uint64      `json:"tid"`
+	ID    uint64      `json:"id,omitempty"`
+	Arg   interface{} `json:"args,omitempty"`
+}
+
+type nameArg struct {
+	Name string `json:"name"`
+}
+
+type nopCloser struct{ io.Writer }
+
+func (nopCloser) Close() error { return nil }
+
+// New creates a new Tracer, storing log in order to log errors later.
+// Events are buffered in memory until SetOutput is called.
+func New(log logger.Logger) *tracerImpl {
+	ret := &tracerImpl{
+		log: log,
+
+		firstEvent: true,
+		nextTid:    uint64(MaxInitThreads),
+	}
+	ret.startBuffer()
+
+	return ret
+}
+
+func (t *tracerImpl) startBuffer() {
+	t.w = nopCloser{&t.buf}
+	fmt.Fprintln(t.w, "[")
+
+	t.defineThread(MainThread, "main")
+}
+
+func (t *tracerImpl) close() {
+	if t.file != nil {
+		fmt.Fprintln(t.w, "]")
+
+		if err := t.w.Close(); err != nil {
+			t.log.Println("Error closing trace writer:", err)
+		}
+
+		if err := t.file.Close(); err != nil {
+			t.log.Println("Error closing trace file:", err)
+		}
+		t.file = nil
+		t.startBuffer()
+	}
+}
+
+// SetOutput creates the output file (rotating old files).
+func (t *tracerImpl) SetOutput(filename string) {
+	t.lock.Lock()
+	defer t.lock.Unlock()
+
+	t.close()
+
+	// chrome://tracing requires that compressed trace files end in .gz
+	if !strings.HasSuffix(filename, ".gz") {
+		filename += ".gz"
+	}
+
+	f, err := logger.CreateFileWithRotation(filename, 5)
+	if err != nil {
+		t.log.Println("Failed to create trace file:", err)
+		return
+	}
+	// Save the file, since closing the gzip Writer doesn't close the
+	// underlying file.
+	t.file = f
+	t.w = gzip.NewWriter(f)
+
+	// Write out everything that happened since the start
+	if _, err := io.Copy(t.w, &t.buf); err != nil {
+		t.log.Println("Failed to write trace buffer to file:", err)
+	}
+	t.buf = bytes.Buffer{}
+}
+
+// Close closes the output file. Any future events will be buffered until the
+// next call to SetOutput.
+func (t *tracerImpl) Close() {
+	t.lock.Lock()
+	defer t.lock.Unlock()
+
+	t.close()
+}
+
+func (t *tracerImpl) writeEvent(event *viewerEvent) {
+	t.lock.Lock()
+	defer t.lock.Unlock()
+
+	t.writeEventLocked(event)
+}
+
+func (t *tracerImpl) writeEventLocked(event *viewerEvent) {
+	bytes, err := json.Marshal(event)
+	if err != nil {
+		t.log.Println("Failed to marshal event:", err)
+		t.log.Verbosef("Event: %#v", event)
+		return
+	}
+
+	if !t.firstEvent {
+		fmt.Fprintln(t.w, ",")
+	} else {
+		t.firstEvent = false
+	}
+
+	if _, err = t.w.Write(bytes); err != nil {
+		t.log.Println("Trace write error:", err)
+	}
+}
+
+func (t *tracerImpl) defineThread(thread Thread, name string) {
+	t.writeEventLocked(&viewerEvent{
+		Name:  "thread_name",
+		Phase: "M",
+		Pid:   0,
+		Tid:   uint64(thread),
+		Arg: &nameArg{
+			Name: name,
+		},
+	})
+}
+
+// NewThread returns a new Thread with an unused tid, writing the name out to
+// the trace file.
+func (t *tracerImpl) NewThread(name string) Thread {
+	t.lock.Lock()
+	defer t.lock.Unlock()
+
+	ret := Thread(t.nextTid)
+	t.nextTid += 1
+
+	t.defineThread(ret, name)
+	return ret
+}
+
+// Begin starts a new Duration Event. More than one Duration Event may be active
+// at a time on each Thread, but they're nested.
+func (t *tracerImpl) Begin(name string, thread Thread) {
+	t.writeEvent(&viewerEvent{
+		Name:  name,
+		Phase: "B",
+		Time:  uint64(time.Now().UnixNano()) / 1000,
+		Pid:   0,
+		Tid:   uint64(thread),
+	})
+}
+
+// End finishes the most recent active Duration Event on the thread.
+func (t *tracerImpl) End(thread Thread) {
+	t.writeEvent(&viewerEvent{
+		Phase: "E",
+		Time:  uint64(time.Now().UnixNano()) / 1000,
+		Pid:   0,
+		Tid:   uint64(thread),
+	})
+}
+
+// Complete writes a Complete Event, which are like Duration Events, but include
+// a begin and end timestamp in the same event.
+func (t *tracerImpl) Complete(name string, thread Thread, begin, end uint64) {
+	t.writeEvent(&viewerEvent{
+		Name:  name,
+		Phase: "X",
+		Time:  begin / 1000,
+		Dur:   (end - begin) / 1000,
+		Pid:   0,
+		Tid:   uint64(thread),
+	})
+}