diff options
author | Dan Willemsen <dwillemsen@google.com> | 2016-08-21 15:17:17 -0700 |
---|---|---|
committer | Dan Willemsen <dwillemsen@google.com> | 2017-02-06 14:05:07 -0800 |
commit | d9f6fa28d681de1051adcddb5aef293e02bcc60e (patch) | |
tree | fee99e8cb9cc21243379fccb471902f3519080b6 | |
parent | c2af0bedc1701ee043f61d95d6b7b160f388a3cb (diff) | |
download | build_soong-d9f6fa28d681de1051adcddb5aef293e02bcc60e.tar.gz build_soong-d9f6fa28d681de1051adcddb5aef293e02bcc60e.tar.bz2 build_soong-d9f6fa28d681de1051adcddb5aef293e02bcc60e.zip |
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
-rw-r--r-- | cmd/multiproduct_kati/Android.bp | 1 | ||||
-rw-r--r-- | cmd/multiproduct_kati/main.go | 21 | ||||
-rw-r--r-- | cmd/soong_ui/Android.bp | 1 | ||||
-rw-r--r-- | cmd/soong_ui/main.go | 20 | ||||
-rw-r--r-- | ui/build/Android.bp | 1 | ||||
-rw-r--r-- | ui/build/context.go | 35 | ||||
-rw-r--r-- | ui/build/kati.go | 3 | ||||
-rw-r--r-- | ui/build/make.go | 3 | ||||
-rw-r--r-- | ui/build/ninja.go | 7 | ||||
-rw-r--r-- | ui/build/soong.go | 6 | ||||
-rw-r--r-- | ui/tracer/Android.bp | 23 | ||||
-rw-r--r-- | ui/tracer/ninja.go | 130 | ||||
-rw-r--r-- | ui/tracer/tracer.go | 244 |
13 files changed, 483 insertions, 12 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())) } } } diff --git a/ui/build/Android.bp b/ui/build/Android.bp index d6da9507..e4044e18 100644 --- a/ui/build/Android.bp +++ b/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", diff --git a/ui/build/context.go b/ui/build/context.go index 59474f53..8144e586 100644 --- a/ui/build/context.go +++ b/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) + } } diff --git a/ui/build/kati.go b/ui/build/kati.go index 6997fbec..423bcbc9 100644 --- a/ui/build/kati.go +++ b/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" diff --git a/ui/build/make.go b/ui/build/make.go index 58805095..89e03f74 100644 --- a/ui/build/make.go +++ b/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", diff --git a/ui/build/ninja.go b/ui/build/ninja.go index 13e1834c..33f9a07b 100644 --- a/ui/build/ninja.go +++ b/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()) diff --git a/ui/build/soong.go b/ui/build/soong.go index 88e4161c..d017e700 100644 --- a/ui/build/soong.go +++ b/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") diff --git a/ui/tracer/Android.bp b/ui/tracer/Android.bp new file mode 100644 index 00000000..89812a13 --- /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 00000000..da558f12 --- /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 00000000..b3728856 --- /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), + }) +} |