Add microfactory tracing

Test: m clean; load out/build.trace.gz in chrome://tracing
Test: m -j nothing; load again
Change-Id: I67d4e006a4bdde593b54c20d6d93a48278fe696d

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

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{

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)

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",
     ],

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

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

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