Add microfactory tracing
Test: m clean; load out/build.trace.gz in chrome://tracing
Test: m -j nothing; load again
Change-Id: I67d4e006a4bdde593b54c20d6d93a48278fe696d
diff --git a/cmd/microfactory/microfactory.bash b/cmd/microfactory/microfactory.bash
index 6bd0f40..aae6740 100644
--- a/cmd/microfactory/microfactory.bash
+++ b/cmd/microfactory/microfactory.bash
@@ -81,6 +81,7 @@
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 6c062e2..18008da 100644
--- a/cmd/microfactory/microfactory.go
+++ b/cmd/microfactory/microfactory.go
@@ -60,6 +60,7 @@
"strings"
"sync"
"syscall"
+ "time"
)
var (
@@ -132,6 +133,8 @@
// 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 @@
}
}
+ 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 @@
}
}
+ endTrace()
if !rebuild {
return nil
}
+ defer un(trace("compile %s", p.Name))
err := os.RemoveAll(p.pkgDir)
if err != nil {
@@ -364,6 +371,7 @@
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 @@
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 @@
}
// 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 @@
}
if !pkg.rebuilt {
- return
+ return false
}
cmd := exec.Command(mybin, os.Args[1:]...)
@@ -450,11 +461,29 @@
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 @@
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 26887ae..94d6d5c 100644
--- a/cmd/soong_ui/main.go
+++ b/cmd/soong_ui/main.go
@@ -89,6 +89,10 @@
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 89812a1..9729c7e 100644
--- a/ui/tracer/Android.bp
+++ b/ui/tracer/Android.bp
@@ -17,6 +17,7 @@
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 0000000..320d9d8
--- /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 da558f1..1980559 100644
--- a/ui/tracer/ninja.go
+++ b/ui/tracer/ninja.go
@@ -23,16 +23,42 @@
"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 @@
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 @@
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 @@
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 f19ac18..8705040 100644
--- a/ui/tracer/tracer.go
+++ b/ui/tracer/tracer.go
@@ -45,6 +45,7 @@
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
