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 /ui/tracer | |
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
Diffstat (limited to 'ui/tracer')
-rw-r--r-- | ui/tracer/Android.bp | 23 | ||||
-rw-r--r-- | ui/tracer/ninja.go | 130 | ||||
-rw-r--r-- | ui/tracer/tracer.go | 244 |
3 files changed, 397 insertions, 0 deletions
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), + }) +} |