unexport LogStats

8 files changed, 79 insertions, 62 deletions

diff --git a/cmd/kati/main.go b/cmd/kati/main.go
index 1edf311..f45dd28 100644
--- a/cmd/kati/main.go
+++ b/cmd/kati/main.go
@@ -136,31 +136,22 @@ func findPara() string {
 }
 
 func load(req kati.LoadReq) (*kati.DepGraph, error) {
-	startTime := time.Now()
-
 	if loadGOB != "" {
-		g, err := kati.GOB.Load(loadGOB)
-		kati.LogStats("deserialize time: %q", time.Since(startTime))
-		return g, err
+		return kati.GOB.Load(loadGOB)
 	}
 	if loadJSON != "" {
-		g, err := kati.JSON.Load(loadJSON)
-		kati.LogStats("deserialize time: %q", time.Since(startTime))
-		return g, err
+		return kati.JSON.Load(loadJSON)
 	}
 	return kati.Load(req)
 }
 
 func save(g *kati.DepGraph, targets []string) error {
 	var err error
-	startTime := time.Now()
 	if saveGOB != "" {
 		err = kati.GOB.Save(g, saveGOB, targets)
-		kati.LogStats("serialize time: %q", time.Since(startTime))
 	}
 	if saveJSON != "" {
 		serr := kati.JSON.Save(g, saveJSON, targets)
-		kati.LogStats("serialize time: %q", time.Since(startTime))
 		if err == nil {
 			err = serr
 		}
@@ -245,9 +236,7 @@ func main() {
 	}
 
 	if generateNinja {
-		startTime := time.Now()
 		kati.GenerateNinja(g, gomaDir)
-		kati.LogStats("generate ninja time: %q", time.Since(startTime))
 		return
 	}
 
@@ -270,7 +259,6 @@ func main() {
 		}
 	}
 
-	startTime := time.Now()
 	execOpt := &kati.ExecutorOpt{
 		NumJobs: jobsFlag,
 	}
@@ -282,6 +270,4 @@ func main() {
 	if err != nil {
 		panic(err)
 	}
-	kati.LogStats("exec time: %q", time.Since(startTime))
-
 }
diff --git a/dep.go b/dep.go
index 6d3eb26..9fb7775 100644
--- a/dep.go
+++ b/dep.go
@@ -493,10 +493,10 @@ func (db *depBuilder) reportStats() {
 		return
 	}
 
-	LogStats("node=%d explicit=%d implicit=%d suffix=%d explicitWOCmd=%d",
+	logStats("node=%d explicit=%d implicit=%d suffix=%d explicitWOCmd=%d",
 		db.nodeCnt, db.pickExplicitRuleCnt, db.pickImplicitRuleCnt, db.pickSuffixRuleCnt, db.pickExplicitRuleWithoutCmdCnt)
 	if len(db.trace) > 1 {
-		LogStats("trace=%q", db.trace)
+		logStats("trace=%q", db.trace)
 	}
 }
 
@@ -528,10 +528,10 @@ func (db *depBuilder) Eval(targets []string) ([]*DepNode, error) {
 		targets = append(targets, db.firstRule.outputs[0])
 	}
 
-	LogStats("%d variables", len(db.vars))
-	LogStats("%d explicit rules", len(db.rules))
-	LogStats("%d implicit rules", len(db.implicitRules))
-	LogStats("%d suffix rules", len(db.suffixRules))
+	logStats("%d variables", len(db.vars))
+	logStats("%d explicit rules", len(db.rules))
+	logStats("%d implicit rules", len(db.implicitRules))
+	logStats("%d suffix rules", len(db.suffixRules))
 
 	var nodes []*DepNode
 	for _, target := range targets {
diff --git a/depgraph.go b/depgraph.go
index 31006ba..2f243e4 100644
--- a/depgraph.go
+++ b/depgraph.go
@@ -121,19 +121,19 @@ func Load(req LoadReq) (*DepGraph, error) {
 	}
 	vars.Merge(er.vars)
 
-	LogStats("eval time: %q", time.Since(startTime))
-	LogStats("shell func time: %q %d", shellStats.Duration(), shellStats.Count())
+	logStats("eval time: %q", time.Since(startTime))
+	logStats("shell func time: %q %d", shellStats.Duration(), shellStats.Count())
 
 	startTime = time.Now()
 	db := newDepBuilder(er, vars)
-	LogStats("dep build prepare time: %q", time.Since(startTime))
+	logStats("dep build prepare time: %q", time.Since(startTime))
 
 	startTime = time.Now()
 	nodes, err := db.Eval(req.Targets)
 	if err != nil {
 		return nil, err
 	}
-	LogStats("dep build time: %q", time.Since(startTime))
+	logStats("dep build time: %q", time.Since(startTime))
 	var accessedMks []*accessedMakefile
 	// Always put the root Makefile as the first element.
 	accessedMks = append(accessedMks, &accessedMakefile{
@@ -151,12 +151,12 @@ func Load(req LoadReq) (*DepGraph, error) {
 	if req.EagerEvalCommand {
 		startTime := time.Now()
 		evalCommands(nodes, vars)
-		LogStats("eager eval command time: %q", time.Since(startTime))
+		logStats("eager eval command time: %q", time.Since(startTime))
 	}
 	if req.UseCache {
 		startTime := time.Now()
 		saveCache(gd, req.Targets)
-		LogStats("serialize time: %q", time.Since(startTime))
+		logStats("serialize time: %q", time.Since(startTime))
 	}
 	return gd, nil
 }
diff --git a/exec.go b/exec.go
index bd22f03..160c0b7 100644
--- a/exec.go
+++ b/exec.go
@@ -21,6 +21,7 @@ import (
 	"path/filepath"
 	"strings"
 	"sync"
+	"time"
 )
 
 type Executor struct {
@@ -211,10 +212,10 @@ func (ex *Executor) reportStats() {
 		return
 	}
 
-	LogStats("build=%d alreadyDone=%d noRule=%d, upToDate=%d runCommand=%d",
+	logStats("build=%d alreadyDone=%d noRule=%d, upToDate=%d runCommand=%d",
 		ex.buildCnt, ex.alreadyDoneCnt, ex.noRuleCnt, ex.upToDateCnt, ex.runCommandCnt)
 	if len(ex.trace) > 1 {
-		LogStats("trace=%q", ex.trace)
+		logStats("trace=%q", ex.trace)
 	}
 }
 
@@ -256,10 +257,12 @@ func NewExecutor(vars Vars, opt *ExecutorOpt) *Executor {
 }
 
 func (ex *Executor) Exec(roots []*DepNode) error {
+	startTime := time.Now()
 	for _, root := range roots {
 		ex.makeJobs(root, nil)
 	}
 	ex.wm.Wait()
+	logStats("exec time: %q", time.Since(startTime))
 	return nil
 }
 
@@ -314,7 +317,7 @@ func evalCommands(nodes []*DepNode, vars Vars) {
 		if hasIO {
 			ioCnt++
 			if ioCnt%100 == 0 {
-				LogStats("%d/%d rules have IO", ioCnt, i+1)
+				logStats("%d/%d rules have IO", ioCnt, i+1)
 			}
 			continue
 		}
@@ -334,5 +337,5 @@ func evalCommands(nodes []*DepNode, vars Vars) {
 		}
 	}
 
-	LogStats("%d/%d rules have IO", ioCnt, len(nodes))
+	logStats("%d/%d rules have IO", ioCnt, len(nodes))
 }
diff --git a/log.go b/log.go
index 1138b30..811792d 100644
--- a/log.go
+++ b/log.go
@@ -33,7 +33,7 @@ func logAlways(f string, a ...interface{}) {
 	logMu.Unlock()
 }
 
-func LogStats(f string, a ...interface{}) {
+func logStats(f string, a ...interface{}) {
 	if !LogFlag && !StatsFlag {
 		return
 	}
diff --git a/ninja.go b/ninja.go
index ad71d2c..5f6c648 100644
--- a/ninja.go
+++ b/ninja.go
@@ -22,6 +22,7 @@ import (
 	"regexp"
 	"runtime"
 	"strings"
+	"time"
 )
 
 type ninjaGenerator struct {
@@ -333,7 +334,9 @@ func (n *ninjaGenerator) generateNinja() {
 }
 
 func GenerateNinja(g *DepGraph, gomaDir string) {
+	startTime := time.Now()
 	n := newNinjaGenerator(g, gomaDir)
 	n.generateShell()
 	n.generateNinja()
+	logStats("generate ninja time: %q", time.Since(startTime))
 }
diff --git a/pathutil.go b/pathutil.go
index 3d4f6bc..cb5eea9 100644
--- a/pathutil.go
+++ b/pathutil.go
@@ -181,7 +181,7 @@ func (c *androidFindCacheT) start(prunes, leafNames []string) {
 	defer func() {
 		traceEvent.end(te)
 		c.scanTime = time.Since(te.t)
-		LogStats("android find cache scan: %v", c.scanTime)
+		logStats("android find cache scan: %v", c.scanTime)
 	}()
 
 	dirs := make(chan string, 32)
@@ -251,7 +251,7 @@ func (c *androidFindCacheT) start(prunes, leafNames []string) {
 		sort.Sort(fileInfoByLeaf(leaves))
 		c.leavesch <- leaves
 		traceEvent.end(leavesTe)
-		LogStats("%d leaves %d dirs in find cache", nfiles, len(dirs))
+		logStats("%d leaves %d dirs in find cache", nfiles, len(dirs))
 		for i, leaf := range leaves {
 			logf("android findleaves cache: %d: %s %v", i, leaf.path, leaf.mode)
 		}
@@ -266,7 +266,7 @@ func (c *androidFindCacheT) start(prunes, leafNames []string) {
 		sort.Sort(fileInfoByName(files))
 		c.filesch <- files
 		traceEvent.end(filesTe)
-		LogStats("%d files in find cache", len(files))
+		logStats("%d files in find cache", len(files))
 		for i, fi := range files {
 			logf("android find cache: %d: %s %v", i, fi.path, fi.mode)
 		}
diff --git a/serialize.go b/serialize.go
index 0d33ac7..aadad3f 100644
--- a/serialize.go
+++ b/serialize.go
@@ -252,6 +252,7 @@ func makeSerializableGraph(g *DepGraph, roots []string) serializableGraph {
 }
 
 func (jsonLoadSaver) Save(g *DepGraph, filename string, roots []string) error {
+	startTime := time.Now()
 	sg := makeSerializableGraph(g, roots)
 	o, err := json.MarshalIndent(sg, " ", " ")
 	if err != nil {
@@ -261,23 +262,43 @@ func (jsonLoadSaver) Save(g *DepGraph, filename string, roots []string) error {
 	if err != nil {
 		return err
 	}
-	f.Write(o)
-	return f.Close()
+	_, err = f.Write(o)
+	if err != nil {
+		f.Close()
+		return err
+	}
+	err = f.Close()
+	if err != nil {
+		return err
+	}
+	logStats("json serialize time: %q", time.Since(startTime))
+	return nil
 }
 
 func (gobLoadSaver) Save(g *DepGraph, filename string, roots []string) error {
+	startTime := time.Now()
 	f, err := os.Create(filename)
 	if err != nil {
 		return err
 	}
 	e := gob.NewEncoder(f)
-	startTime := time.Now()
-	sg := makeSerializableGraph(g, roots)
-	LogStats("serialize prepare time: %q", time.Since(startTime))
-	startTime = time.Now()
-	e.Encode(sg)
-	LogStats("serialize output time: %q", time.Since(startTime))
-	return f.Close()
+	var sg serializableGraph
+	{
+		startTime := time.Now()
+		sg = makeSerializableGraph(g, roots)
+		logStats("gob serialize prepare time: %q", time.Since(startTime))
+	}
+	{
+		startTime := time.Now()
+		e.Encode(sg)
+		logStats("gob serialize output time: %q", time.Since(startTime))
+	}
+	err = f.Close()
+	if err != nil {
+		return err
+	}
+	logStats("gob serialize time: %q", time.Since(startTime))
+	return nil
 }
 
 func cacheFilename(mk string, roots []string) string {
@@ -484,14 +505,14 @@ func showSerializedNodesStats(nodes []*serializableDepNode) {
 		linenoSize += 4
 	}
 	size := outputSize + cmdSize + depsSize + actualInputSize + tsvSize + filenameSize + linenoSize
-	LogStats("%d nodes %s", len(nodes), human(size))
-	LogStats(" output %s", human(outputSize))
-	LogStats(" command %s", human(cmdSize))
-	LogStats(" deps %s", human(depsSize))
-	LogStats(" inputs %s", human(actualInputSize))
-	LogStats(" tsv %s", human(tsvSize))
-	LogStats(" filename %s", human(filenameSize))
-	LogStats(" lineno %s", human(linenoSize))
+	logStats("%d nodes %s", len(nodes), human(size))
+	logStats(" output %s", human(outputSize))
+	logStats(" command %s", human(cmdSize))
+	logStats(" deps %s", human(depsSize))
+	logStats(" inputs %s", human(actualInputSize))
+	logStats(" tsv %s", human(tsvSize))
+	logStats(" filename %s", human(filenameSize))
+	logStats(" lineno %s", human(linenoSize))
 }
 
 func (v serializableVar) size() int {
@@ -513,9 +534,9 @@ func showSerializedVarsStats(vars map[string]serializableVar) {
 		valueSize += v.size()
 	}
 	size := nameSize + valueSize
-	LogStats("%d vars %s", len(vars), human(size))
-	LogStats(" name %s", human(nameSize))
-	LogStats(" value %s", human(valueSize))
+	logStats("%d vars %s", len(vars), human(size))
+	logStats(" name %s", human(nameSize))
+	logStats(" value %s", human(valueSize))
 }
 
 func showSerializedTsvsStats(vars []serializableTargetSpecificVar) {
@@ -526,9 +547,9 @@ func showSerializedTsvsStats(vars []serializableTargetSpecificVar) {
 		valueSize += v.Value.size()
 	}
 	size := nameSize + valueSize
-	LogStats("%d tsvs %s", len(vars), human(size))
-	LogStats(" name %s", human(nameSize))
-	LogStats(" value %s", human(valueSize))
+	logStats("%d tsvs %s", len(vars), human(size))
+	logStats(" name %s", human(nameSize))
+	logStats(" value %s", human(valueSize))
 }
 
 func showSerializedTargetsStats(targets []string) {
@@ -536,7 +557,7 @@ func showSerializedTargetsStats(targets []string) {
 	for _, t := range targets {
 		size += len(t)
 	}
-	LogStats("%d targets %s", len(targets), human(size))
+	logStats("%d targets %s", len(targets), human(size))
 }
 
 func showSerializedAccessedMksStats(accessedMks []*accessedMakefile) {
@@ -544,7 +565,7 @@ func showSerializedAccessedMksStats(accessedMks []*accessedMakefile) {
 	for _, rm := range accessedMks {
 		size += len(rm.Filename) + len(rm.Hash) + 4
 	}
-	LogStats("%d makefiles %s", len(accessedMks), human(size))
+	logStats("%d makefiles %s", len(accessedMks), human(size))
 }
 
 func showSerializedGraphStats(g serializableGraph) {
@@ -570,6 +591,7 @@ func deserializeGraph(g serializableGraph) *DepGraph {
 }
 
 func (jsonLoadSaver) Load(filename string) (*DepGraph, error) {
+	startTime := time.Now()
 	f, err := os.Open(filename)
 	if err != nil {
 		return nil, err
@@ -583,10 +605,12 @@ func (jsonLoadSaver) Load(filename string) (*DepGraph, error) {
 		return nil, err
 	}
 	dg := deserializeGraph(g)
+	logStats("gob deserialize time: %q", time.Since(startTime))
 	return dg, nil
 }
 
 func (gobLoadSaver) Load(filename string) (*DepGraph, error) {
+	startTime := time.Now()
 	f, err := os.Open(filename)
 	if err != nil {
 		return nil, err
@@ -600,13 +624,14 @@ func (gobLoadSaver) Load(filename string) (*DepGraph, error) {
 		return nil, err
 	}
 	dg := deserializeGraph(g)
+	logStats("json deserialize time: %q", time.Since(startTime))
 	return dg, nil
 }
 
 func loadCache(makefile string, roots []string) *DepGraph {
 	startTime := time.Now()
 	defer func() {
-		LogStats("Cache lookup time: %q", time.Since(startTime))
+		logStats("Cache lookup time: %q", time.Since(startTime))
 	}()
 
 	filename := cacheFilename(makefile, roots)