add -kati_trace_event=<json filename>

if this option is given, it outputs trace json file
for chrome://tracing for makefile include traces.

5 files changed, 103 insertions, 23 deletions

diff --git a/eval.go b/eval.go
index fad679e..82742fd 100644
--- a/eval.go
+++ b/eval.go
@@ -21,7 +21,6 @@ import (
 	"io/ioutil"
 	"path/filepath"
 	"strings"
-	"time"
 )
 
 type FileState int
@@ -264,9 +263,9 @@ func (ev *Evaluator) EvaluateVar(name string) string {
 }
 
 func (ev *Evaluator) evalIncludeFile(fname string, c []byte) error {
-	t := time.Now()
+	te := traceEvent.begin("include", literal(fname))
 	defer func() {
-		addStats("include", literal(fname), t)
+		traceEvent.end(te)
 	}()
 	mk, ok, err := LookupMakefileCache(fname)
 	if !ok {
diff --git a/expr.go b/expr.go
index c76aed1..6af75f1 100644
--- a/expr.go
+++ b/expr.go
@@ -22,7 +22,6 @@ import (
 	"strconv"
 	"strings"
 	"sync"
-	"time"
 )
 
 var (
@@ -150,13 +149,13 @@ func (v varref) String() string {
 }
 
 func (v varref) Eval(w io.Writer, ev *Evaluator) {
-	t := time.Now()
+	te := traceEvent.begin("var", v)
 	buf := newBuf()
 	v.varname.Eval(buf, ev)
 	vv := ev.LookupVar(buf.String())
 	freeBuf(buf)
 	vv.Eval(w, ev)
-	addStats("var", v, t)
+	traceEvent.end(te)
 }
 
 func (v varref) Serialize() SerializableVar {
@@ -178,7 +177,7 @@ func (p paramref) String() string {
 }
 
 func (p paramref) Eval(w io.Writer, ev *Evaluator) {
-	t := time.Now()
+	te := traceEvent.begin("param", p)
 	n := int(p)
 	if n < len(ev.paramVars) {
 		ev.paramVars[n].Eval(w, ev)
@@ -186,7 +185,7 @@ func (p paramref) Eval(w io.Writer, ev *Evaluator) {
 		// out of range?
 		// panic(fmt.Sprintf("out of range %d: %d", n, len(ev.paramVars)))
 	}
-	addStats("param", p, t)
+	traceEvent.end(te)
 }
 
 func (p paramref) Serialize() SerializableVar {
@@ -210,7 +209,7 @@ func (v varsubst) String() string {
 }
 
 func (v varsubst) Eval(w io.Writer, ev *Evaluator) {
-	t := time.Now()
+	te := traceEvent.begin("varsubst", v)
 	buf := newBuf()
 	params := ev.args(buf, v.varname, v.pat, v.subst)
 	vname := string(params[0])
@@ -229,7 +228,7 @@ func (v varsubst) Eval(w io.Writer, ev *Evaluator) {
 		io.WriteString(w, substRef(pat, subst, val))
 		space = true
 	}
-	addStats("varsubst", v, t)
+	traceEvent.end(te)
 }
 
 func (v varsubst) Serialize() SerializableVar {
@@ -565,7 +564,7 @@ func parseFunc(f Func, in []byte, s int, term []byte, funcName string) (Value, i
 	if compactor, ok := f.(Compactor); ok {
 		fv = compactor.Compact()
 	}
-	if katiEvalStatsFlag {
+	if katiEvalStatsFlag || traceEvent.enabled() {
 		fv = funcstats{fv}
 	}
 	return fv, i, nil
@@ -580,8 +579,8 @@ type funcstats struct {
 }
 
 func (f funcstats) Eval(w io.Writer, ev *Evaluator) {
-	t := time.Now()
+	te := traceEvent.begin("func", f)
 	f.Value.Eval(w, ev)
 	// TODO(ukai): per functype?
-	addStats("func", f, t)
+	traceEvent.end(te)
 }
diff --git a/func.go b/func.go
index 3a944d5..0b6d16e 100644
--- a/func.go
+++ b/func.go
@@ -447,13 +447,13 @@ func (f *funcWildcard) Eval(w io.Writer, ev *Evaluator) {
 	assertArity("wildcard", 1, len(f.args))
 	abuf := newBuf()
 	f.args[1].Eval(abuf, ev)
-	t := time.Now()
+	te := traceEvent.begin("wildcard", tmpval(abuf.Bytes()))
 	if ev.avoidIO && !useWildcardCache {
 		ev.hasIO = true
 		w.Write([]byte("$(/bin/ls -d "))
 		w.Write(abuf.Bytes())
 		w.Write([]byte(" 2> /dev/null)"))
-		addStats("wildcard", tmpval(abuf.Bytes()), t)
+		traceEvent.end(te)
 		freeBuf(abuf)
 		return
 	}
@@ -463,7 +463,7 @@ func (f *funcWildcard) Eval(w io.Writer, ev *Evaluator) {
 		pat := string(ws.Bytes())
 		wildcard(&sw, pat)
 	}
-	addStats("wildcard", tmpval(abuf.Bytes()), t)
+	traceEvent.end(te)
 	freeBuf(abuf)
 }
 
@@ -721,12 +721,12 @@ func (f *funcShell) Eval(w io.Writer, ev *Evaluator) {
 	abuf := newBuf()
 	f.args[1].Eval(abuf, ev)
 	if ev.avoidIO && !hasNoIoInShellScript(abuf.Bytes()) {
-		t := time.Now()
+		te := traceEvent.begin("shell", tmpval(abuf.Bytes()))
 		ev.hasIO = true
 		w.Write([]byte("$("))
 		w.Write(abuf.Bytes())
 		w.Write([]byte{')'})
-		addStats("shell", tmpval(abuf.Bytes()), t)
+		traceEvent.end(te)
 		freeBuf(abuf)
 		return
 	}
@@ -740,15 +740,15 @@ func (f *funcShell) Eval(w io.Writer, ev *Evaluator) {
 		Args:   cmdline,
 		Stderr: os.Stderr,
 	}
-	t := time.Now()
+	te := traceEvent.begin("shell", literal(arg))
 	out, err := cmd.Output()
-	shellFuncTime += time.Since(t)
+	shellFuncTime += time.Since(te.t)
 	shellFuncCount++
 	if err != nil {
 		Logf("$(shell %q) failed: %q", arg, err)
 	}
 	w.Write(formatCommandOutput(out))
-	addStats("shell", literal(arg), t)
+	traceEvent.end(te)
 }
 
 func (f *funcShell) Compact() Value {
diff --git a/main.go b/main.go
index ad01f8a..f414a0b 100644
--- a/main.go
+++ b/main.go
@@ -37,6 +37,7 @@ var (
 	cpuprofile            string
 	heapprofile           string
 	memstats              string
+	traceEventFile        string
 	katiStatsFlag         bool
 	katiPeriodicStatsFlag bool
 	katiEvalStatsFlag     bool
@@ -84,6 +85,7 @@ func parseFlags() {
 	flag.StringVar(&cpuprofile, "kati_cpuprofile", "", "write cpu profile to `file`")
 	flag.StringVar(&heapprofile, "kati_heapprofile", "", "write heap profile to `file`")
 	flag.StringVar(&memstats, "kati_memstats", "", "Show memstats with given templates")
+	flag.StringVar(&traceEventFile, "kati_trace_event", "", "write trace event to `file`")
 	flag.BoolVar(&katiStatsFlag, "kati_stats", false, "Show a bunch of statistics")
 	flag.BoolVar(&katiPeriodicStatsFlag, "kati_periodic_stats", false, "Show a bunch of periodic statistics")
 	flag.BoolVar(&katiEvalStatsFlag, "kati_eval_stats", false, "Show eval statistics")
@@ -308,6 +310,14 @@ func main() {
 			fmt.Println(buf.String())
 		}()
 	}
+	if traceEventFile != "" {
+		f, err := os.Create(traceEventFile)
+		if err != nil {
+			panic(err)
+		}
+		traceEvent.start(f)
+		defer traceEvent.stop()
+	}
 
 	if findCachePrunes != "" {
 		useFindCache = true
diff --git a/stats.go b/stats.go
index 0193604..a85d194 100644
--- a/stats.go
+++ b/stats.go
@@ -16,10 +16,82 @@ package main
 
 import (
 	"fmt"
+	"io"
+	"os"
 	"sort"
 	"time"
 )
 
+type traceEventT struct {
+	f   io.WriteCloser
+	t0  time.Time
+	pid int
+}
+
+var traceEvent traceEventT
+
+func (t *traceEventT) start(f io.WriteCloser) {
+	t.f = f
+	t.t0 = time.Now()
+	fmt.Fprint(t.f, "[ ")
+}
+
+func (t *traceEventT) enabled() bool {
+	return t.f != nil
+}
+
+func (t *traceEventT) stop() {
+	fmt.Fprint(t.f, "\n]\n")
+	t.f.Close()
+}
+
+type event struct {
+	name, v string
+	t       time.Time
+}
+
+func (t *traceEventT) begin(name string, v Value) event {
+	var e event
+	e.t = time.Now()
+	if t.f != nil {
+		emit := name == "include"
+		if t.pid == 0 {
+			t.pid = os.Getpid()
+		} else if emit {
+			fmt.Fprint(t.f, ",\n")
+		}
+		e.name = name
+		e.v = v.String()
+		if emit {
+			ts := e.t.Sub(t.t0)
+			fmt.Fprintf(t.f, `{"pid":%d,"tid":1,"ts":%d,"ph":"B","cat":%q,"name":%q,"args":{}}`,
+				t.pid,
+				ts.Nanoseconds()/1e3,
+				e.name,
+				e.v,
+			)
+		}
+	}
+	return e
+}
+
+func (t *traceEventT) end(e event) {
+	if t.f != nil {
+		now := time.Now()
+		ts := now.Sub(t.t0)
+		if e.name == "include" {
+			fmt.Fprint(t.f, ",\n")
+			fmt.Fprintf(t.f, `{"pid":%d,"tid":1,"ts":%d,"ph":"E","cat":%q,"name":%q}`,
+				t.pid,
+				ts.Nanoseconds()/1e3,
+				e.name,
+				e.v,
+			)
+		}
+	}
+	addStats(e.name, e.v, e.t)
+}
+
 type statsData struct {
 	Name    string
 	Count   int
@@ -29,12 +101,12 @@ type statsData struct {
 
 var stats = map[string]statsData{}
 
-func addStats(name string, v Value, t time.Time) {
+func addStats(name, v string, t time.Time) {
 	if !katiEvalStatsFlag {
 		return
 	}
 	d := time.Since(t)
-	key := fmt.Sprintf("%s:%s", name, v.String())
+	key := fmt.Sprintf("%s:%s", name, v)
 	s := stats[key]
 	if d > s.Longest {
 		s.Longest = d