diff options
author | Dan Willemsen <dwillemsen@google.com> | 2017-07-13 14:27:31 -0700 |
---|---|---|
committer | Dan Willemsen <dwillemsen@google.com> | 2017-07-13 15:09:44 -0700 |
commit | cae59bc29de92e135ca53cfb1142d3524b62f846 (patch) | |
tree | 8a5c5c634c53b8941d6189d32b2d1b5975456e0d | |
parent | 1b822867360844bea1c30facb95492ff21eb4e6b (diff) | |
download | build_soong-cae59bc29de92e135ca53cfb1142d3524b62f846.tar.gz build_soong-cae59bc29de92e135ca53cfb1142d3524b62f846.tar.bz2 build_soong-cae59bc29de92e135ca53cfb1142d3524b62f846.zip |
Add microfactory tracing
Test: m clean; load out/build.trace.gz in chrome://tracing
Test: m -j nothing; load again
Change-Id: I67d4e006a4bdde593b54c20d6d93a48278fe696d
-rw-r--r-- | cmd/microfactory/microfactory.bash | 1 | ||||
-rw-r--r-- | cmd/microfactory/microfactory.go | 52 | ||||
-rw-r--r-- | cmd/soong_ui/main.go | 4 | ||||
-rw-r--r-- | ui/tracer/Android.bp | 1 | ||||
-rw-r--r-- | ui/tracer/microfactory.go | 63 | ||||
-rw-r--r-- | ui/tracer/ninja.go | 77 | ||||
-rw-r--r-- | ui/tracer/tracer.go | 1 |
7 files changed, 156 insertions, 43 deletions
diff --git a/cmd/microfactory/microfactory.bash b/cmd/microfactory/microfactory.bash index 6bd0f400..aae67408 100644 --- a/cmd/microfactory/microfactory.bash +++ b/cmd/microfactory/microfactory.bash @@ -81,6 +81,7 @@ function build_go mf_cmd="${mf_bin}" fi + rm -f "${out_dir}/.$1.trace" ${mf_cmd} -s "${mf_src}" -b "${mf_bin}" \ -pkg-path "android/soong=${TOP}/build/soong" -trimpath "${TOP}/build/soong" \ -o "${built_bin}" $2 diff --git a/cmd/microfactory/microfactory.go b/cmd/microfactory/microfactory.go index 6c062e27..18008da2 100644 --- a/cmd/microfactory/microfactory.go +++ b/cmd/microfactory/microfactory.go @@ -60,6 +60,7 @@ import ( "strings" "sync" "syscall" + "time" ) var ( @@ -132,6 +133,8 @@ func (s *linkedDepSet) ignore(name string) { // for import dependencies that exist in pkgMap, then recursively does the // same for all of those dependencies. func (p *GoPackage) FindDeps(path string, pkgMap *pkgPathMapping) error { + defer un(trace("findDeps")) + depSet := newDepSet() err := p.findDeps(path, pkgMap, depSet) if err != nil { @@ -259,6 +262,8 @@ func (p *GoPackage) Compile(outDir, trimPath string) error { } } + endTrace := trace("check compile %s", p.Name) + p.pkgDir = filepath.Join(outDir, p.Name) p.output = filepath.Join(p.pkgDir, p.Name) + ".a" shaFile := p.output + ".hash" @@ -317,9 +322,11 @@ func (p *GoPackage) Compile(outDir, trimPath string) error { } } + endTrace() if !rebuild { return nil } + defer un(trace("compile %s", p.Name)) err := os.RemoveAll(p.pkgDir) if err != nil { @@ -364,6 +371,7 @@ func (p *GoPackage) Link(out string) error { if p.Name != "main" { return fmt.Errorf("Can only link main package") } + endTrace := trace("check link %s", p.Name) shaFile := filepath.Join(filepath.Dir(out), "."+filepath.Base(out)+"_hash") @@ -376,9 +384,11 @@ func (p *GoPackage) Link(out string) error { p.rebuilt = !bytes.Equal(oldSha, p.hashResult) } } + endTrace() if !p.rebuilt { return nil } + defer un(trace("link %s", p.Name)) err := os.Remove(shaFile) if err != nil && !os.IsNotExist(err) { @@ -412,8 +422,9 @@ func (p *GoPackage) Link(out string) error { } // rebuildMicrofactory checks to see if microfactory itself needs to be rebuilt, -// and if does, it will launch a new copy instead of returning. -func rebuildMicrofactory(mybin, mysrc string, pkgMap *pkgPathMapping) { +// and if does, it will launch a new copy and return true. Otherwise it will return +// false to continue executing. +func rebuildMicrofactory(mybin, mysrc string, pkgMap *pkgPathMapping) bool { intermediates := filepath.Join(filepath.Dir(mybin), "."+filepath.Base(mybin)+"_intermediates") err := os.MkdirAll(intermediates, 0777) @@ -442,7 +453,7 @@ func rebuildMicrofactory(mybin, mysrc string, pkgMap *pkgPathMapping) { } if !pkg.rebuilt { - return + return false } cmd := exec.Command(mybin, os.Args[1:]...) @@ -450,11 +461,29 @@ func rebuildMicrofactory(mybin, mysrc string, pkgMap *pkgPathMapping) { cmd.Stdout = os.Stdout cmd.Stderr = os.Stderr if err := cmd.Run(); err == nil { - os.Exit(0) + return true } else if e, ok := err.(*exec.ExitError); ok { os.Exit(e.ProcessState.Sys().(syscall.WaitStatus).ExitStatus()) } os.Exit(1) + return true +} + +var traceFile *os.File + +func trace(format string, a ...interface{}) func() { + if traceFile == nil { + return func() {} + } + s := strings.TrimSpace(fmt.Sprintf(format, a...)) + fmt.Fprintf(traceFile, "%d B %s\n", time.Now().UnixNano()/1000, s) + return func() { + fmt.Fprintf(traceFile, "%d E %s\n", time.Now().UnixNano()/1000, s) + } +} + +func un(f func()) { + f() } func main() { @@ -477,8 +506,21 @@ func main() { os.Exit(1) } + tracePath := filepath.Join(filepath.Dir(output), "."+filepath.Base(output)+".trace") + traceFile, err = os.OpenFile(tracePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666) + if err != nil { + traceFile = nil + } + if executable, err := os.Executable(); err == nil { + defer un(trace("microfactory %s", executable)) + } else { + defer un(trace("microfactory <unknown>")) + } + if mybin != "" && mysrc != "" { - rebuildMicrofactory(mybin, mysrc, &pkgMap) + if rebuildMicrofactory(mybin, mysrc, &pkgMap) { + return + } } mainPackage := &GoPackage{ diff --git a/cmd/soong_ui/main.go b/cmd/soong_ui/main.go index 26887ae6..94d6d5c4 100644 --- a/cmd/soong_ui/main.go +++ b/cmd/soong_ui/main.go @@ -89,6 +89,10 @@ func main() { buildCtx.CompleteTrace("startup", start_time, uint64(time.Now().UnixNano())) } } + + if executable, err := os.Executable(); err == nil { + trace.ImportMicrofactoryLog(filepath.Join(filepath.Dir(executable), "."+filepath.Base(executable)+".trace")) + } } build.Build(buildCtx, config, build.BuildAll) diff --git a/ui/tracer/Android.bp b/ui/tracer/Android.bp index 89812a13..9729c7e5 100644 --- a/ui/tracer/Android.bp +++ b/ui/tracer/Android.bp @@ -17,6 +17,7 @@ bootstrap_go_package { pkgPath: "android/soong/ui/tracer", deps: ["soong-ui-logger"], srcs: [ + "microfactory.go", "ninja.go", "tracer.go", ], diff --git a/ui/tracer/microfactory.go b/ui/tracer/microfactory.go new file mode 100644 index 00000000..320d9d8e --- /dev/null +++ b/ui/tracer/microfactory.go @@ -0,0 +1,63 @@ +// 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. + +package tracer + +import ( + "bufio" + "os" + "strconv" + "strings" +) + +func (t *tracerImpl) ImportMicrofactoryLog(filename string) { + if _, err := os.Stat(filename); err != nil { + return + } + + f, err := os.Open(filename) + if err != nil { + t.log.Println("Error opening microfactory trace:", err) + return + } + defer f.Close() + + entries := []*eventEntry{} + begin := map[string][]uint64{} + s := bufio.NewScanner(f) + for s.Scan() { + fields := strings.SplitN(s.Text(), " ", 3) + if len(fields) != 3 { + t.log.Verboseln("Unknown line in microfactory trace:", s.Text()) + continue + } + timestamp, err := strconv.ParseUint(fields[0], 10, 64) + if err != nil { + t.log.Verboseln("Failed to parse timestamp in microfactory trace:", err) + } + + if fields[1] == "B" { + begin[fields[2]] = append(begin[fields[2]], timestamp) + } else if beginTimestamps, ok := begin[fields[2]]; ok { + entries = append(entries, &eventEntry{ + Name: fields[2], + Begin: beginTimestamps[len(beginTimestamps)-1], + End: timestamp, + }) + begin[fields[2]] = beginTimestamps[:len(beginTimestamps)-1] + } + } + + t.importEvents(entries) +} diff --git a/ui/tracer/ninja.go b/ui/tracer/ninja.go index da558f12..1980559c 100644 --- a/ui/tracer/ninja.go +++ b/ui/tracer/ninja.go @@ -23,16 +23,42 @@ import ( "time" ) -type ninjaLogEntry struct { +type eventEntry struct { Name string - Begin int - End int + Begin uint64 + End uint64 } -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] } +func (t *tracerImpl) importEvents(entries []*eventEntry) { + sort.Slice(entries, func(i, j int) bool { + return entries[i].Begin < entries[j].Begin + }) + + cpus := []uint64{} + 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: entry.Begin, + Dur: entry.End - entry.Begin, + Pid: 1, + Tid: uint64(tid), + }) + } +} // ImportNinjaLog reads a .ninja_log file from ninja and writes the events out // to the trace. @@ -61,8 +87,9 @@ func (t *tracerImpl) ImportNinjaLog(thread Thread, filename string, startOffset s := bufio.NewScanner(f) header := true - entries := ninjaLogEntries{} + entries := []*eventEntry{} prevEnd := 0 + offset := uint64(startOffset.UnixNano()) / 1000 for s.Scan() { if header { hdr := s.Text() @@ -89,10 +116,10 @@ func (t *tracerImpl) ImportNinjaLog(thread Thread, filename string, startOffset entries = nil } prevEnd = end - entries = append(entries, &ninjaLogEntry{ + entries = append(entries, &eventEntry{ Name: fields[3], - Begin: begin, - End: end, + Begin: offset + uint64(begin)*1000, + End: offset + uint64(end)*1000, }) } if err := s.Err(); err != nil { @@ -100,31 +127,5 @@ func (t *tracerImpl) ImportNinjaLog(thread Thread, filename string, startOffset 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), - }) - } + t.importEvents(entries) } diff --git a/ui/tracer/tracer.go b/ui/tracer/tracer.go index f19ac186..87050403 100644 --- a/ui/tracer/tracer.go +++ b/ui/tracer/tracer.go @@ -45,6 +45,7 @@ type Tracer interface { End(thread Thread) Complete(name string, thread Thread, begin, end uint64) + ImportMicrofactoryLog(filename string) ImportNinjaLog(thread Thread, filename string, startOffset time.Time) NewThread(name string) Thread |