From 49599e55caf178ff92b8ac6c34daf60f723ecf9b Mon Sep 17 00:00:00 2001 From: Fumitoshi Ukai Date: Fri, 26 Jun 2015 10:10:24 +0900 Subject: unexport LogStats --- cmd/kati/main.go | 18 ++----------- dep.go | 12 ++++----- depgraph.go | 12 ++++----- exec.go | 11 +++++--- log.go | 2 +- ninja.go | 3 +++ pathutil.go | 6 ++--- serialize.go | 77 +++++++++++++++++++++++++++++++++++++------------------- 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) -- cgit v1.2.3