Add microfactory tracing

Test: m clean; load out/build.trace.gz in chrome://tracing
Test: m -j nothing; load again
Change-Id: I67d4e006a4bdde593b54c20d6d93a48278fe696d
This commit is contained in:
Dan Willemsen 2017-07-13 14:27:31 -07:00
parent 1b82286736
commit cae59bc29d
7 changed files with 156 additions and 43 deletions

View File

@ -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

View File

@ -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{

View File

@ -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)

View File

@ -17,6 +17,7 @@ bootstrap_go_package {
pkgPath: "android/soong/ui/tracer",
deps: ["soong-ui-logger"],
srcs: [
"microfactory.go",
"ninja.go",
"tracer.go",
],

63
ui/tracer/microfactory.go Normal file
View File

@ -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)
}

View File

@ -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)
}

View File

@ -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