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
diff --git a/cmd/multiproduct_kati/Android.bp b/cmd/multiproduct_kati/Android.bp
index 8c1cd26..b264c35 100644
--- a/cmd/multiproduct_kati/Android.bp
+++ b/cmd/multiproduct_kati/Android.bp
@@ -17,6 +17,7 @@
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 0570c17..2ff19ce 100644
--- a/cmd/multiproduct_kati/main.go
+++ b/cmd/multiproduct_kati/main.go
@@ -28,6 +28,7 @@
"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 @@
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 @@
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 @@
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 6d6ef33..f09e42e 100644
--- a/cmd/soong_ui/Android.bp
+++ b/cmd/soong_ui/Android.bp
@@ -17,6 +17,7 @@
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 34739b7..de941f4 100644
--- a/cmd/soong_ui/main.go
+++ b/cmd/soong_ui/main.go
@@ -24,6 +24,7 @@
"android/soong/ui/build"
"android/soong/ui/logger"
+ "android/soong/ui/tracer"
)
func indexList(s string, list []string) int {
@@ -51,26 +52,33 @@
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()))
}
}
}
diff --git a/ui/build/Android.bp b/ui/build/Android.bp
index d6da950..e4044e1 100644
--- a/ui/build/Android.bp
+++ b/ui/build/Android.bp
@@ -17,6 +17,7 @@
pkgPath: "android/soong/ui/build",
deps: [
"soong-ui-logger",
+ "soong-ui-tracer",
],
srcs: [
"build.go",
diff --git a/ui/build/context.go b/ui/build/context.go
index 59474f5..8144e58 100644
--- a/ui/build/context.go
+++ b/ui/build/context.go
@@ -18,8 +18,10 @@
"context"
"io"
"os"
+ "time"
"android/soong/ui/logger"
+ "android/soong/ui/tracer"
)
type StdioInterface interface {
@@ -55,10 +57,41 @@
// 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)
+ }
}
diff --git a/ui/build/kati.go b/ui/build/kati.go
index 6997fbe..423bcbc 100644
--- a/ui/build/kati.go
+++ b/ui/build/kati.go
@@ -57,6 +57,9 @@
}
func runKati(ctx Context, config Config) {
+ ctx.BeginTrace("kati")
+ defer ctx.EndTrace()
+
genKatiSuffix(ctx, config)
executable := "prebuilts/build-tools/" + config.HostPrebuiltTag() + "/bin/ckati"
diff --git a/ui/build/make.go b/ui/build/make.go
index 5880509..89e03f7 100644
--- a/ui/build/make.go
+++ b/ui/build/make.go
@@ -35,6 +35,9 @@
// 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",
diff --git a/ui/build/ninja.go b/ui/build/ninja.go
index 13e1834..33f9a07 100644
--- a/ui/build/ninja.go
+++ b/ui/build/ninja.go
@@ -16,11 +16,16 @@
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 @@
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())
diff --git a/ui/build/soong.go b/ui/build/soong.go
index 88e4161..d017e70 100644
--- a/ui/build/soong.go
+++ b/ui/build/soong.go
@@ -20,6 +20,9 @@
)
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 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")
diff --git a/ui/tracer/Android.bp b/ui/tracer/Android.bp
new file mode 100644
index 0000000..89812a1
--- /dev/null
+++ b/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",
+ ],
+}
diff --git a/ui/tracer/ninja.go b/ui/tracer/ninja.go
new file mode 100644
index 0000000..da558f1
--- /dev/null
+++ b/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),
+ })
+ }
+}
diff --git a/ui/tracer/tracer.go b/ui/tracer/tracer.go
new file mode 100644
index 0000000..b372885
--- /dev/null
+++ b/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),
+ })
+}