use time.Since instead of time.Now().Sub
count # of shell invocation.
$ repo/android.sh kati -c -kati_stats
...
*kati*: eval time: "59.179409898s"
*kati*: shell func time: "40.99470661s" 2896
...
note that # of unique shell command lines seems to be 2514.
from "$ repo/android.sh kati -c -kati_eval_stats"
grep shell: | wc -l
top $(shell ..); cumulative time > 1sec
from "$ repo/android.sh kati -c -kati_eval_stats"
count,longest(ns),total(ns),longest,total,name
...
1325,53941610,16717939038,53.94161ms,16.717939038s,func:$(shell if [ -d $1 ] ; then cd $1 ; find ./ -not -name '.*' -and -type f -and -not -type l ; fi)
...
922,37729941,13098517289,37.729941ms,13.098517289s,func:$(shell cd ${LOCAL_PATH} ; find -L $1 -name "*.java" -and -not -name ".*")
...
162,39814484,2716881896,39.814484ms,2.716881896s,func:$(shell cd ${TOP_DIR}${LOCAL_PATH}/${dir} && find . -type d -a -name ".svn" -prune -o -type f -a \! -name"*.java" -a \! -name "package.html" -a \! -name "overview.html" -a \! -name ".*.swp" -a \! -name ".DS_Store" -a \! -name "*~" -print )
...
174,34637725,2245014340,34.637725ms,2.24501434s,func:$(shell echo $1 | tr 'a-zA-Z' 'n-za-mN-ZA-M')
...
1,1633210877,1633210877,1.633210877s,1.633210877s,func:$(shell build/tools/findleaves.py --prune=${OUT_DIR} --prune=.repo --prune=.git . CleanSpec.mk)
...
note:
$ time find repo/android -ls > /dev/null
find repo/android -ls > /dev/null 2.33s user 2.04s system 100% cpu 4.366 total
diff --git a/func.go b/func.go
index 6de6118..855ced4 100644
--- a/func.go
+++ b/func.go
@@ -678,7 +678,10 @@
// http://www.gnu.org/software/make/manual/make.html#Shell-Function
type funcShell struct{ fclosure }
-var shellFuncTime time.Duration
+var (
+ shellFuncTime time.Duration
+ shellFuncCount int
+)
func (f *funcShell) Arity() int { return 1 }
@@ -704,10 +707,13 @@
abuf := newBuf()
f.args[1].Eval(abuf, ev)
if ev.avoidIO && !hasNoIoInShellScript(abuf.Bytes()) {
+ t := time.Now()
ev.hasIO = true
w.Write([]byte("$("))
w.Write(abuf.Bytes())
w.Write([]byte{')'})
+ addStats("shell", tmpval(abuf.Bytes()), t)
+ freeBuf(abuf)
return
}
arg := abuf.String()
@@ -722,12 +728,13 @@
}
t := time.Now()
out, err := cmd.Output()
- shellFuncTime += time.Now().Sub(t)
+ shellFuncTime += time.Since(t)
+ shellFuncCount++
if err != nil {
Logf("$(shell %q) failed: %q", arg, err)
}
-
w.Write(formatCommandOutput(out))
+ addStats("shell", literal(arg), t)
}
// https://www.gnu.org/software/make/manual/html_node/Call-Function.html#Call-Function
diff --git a/main.go b/main.go
index b4157cb..457c5ff 100644
--- a/main.go
+++ b/main.go
@@ -145,12 +145,12 @@
if loadGOB != "" {
g := LoadDepGraph(loadGOB)
- LogStats("deserialize time: %q", time.Now().Sub(startTime))
+ LogStats("deserialize time: %q", time.Since(startTime))
return g
}
if loadJSON != "" {
g := LoadDepGraphFromJSON(loadJSON)
- LogStats("deserialize time: %q", time.Now().Sub(startTime))
+ LogStats("deserialize time: %q", time.Since(startTime))
return g
}
@@ -215,19 +215,19 @@
vars.Merge(er.vars)
- LogStats("eval time: %q", time.Now().Sub(startTime))
- LogStats("shell func time: %q", shellFuncTime)
+ LogStats("eval time: %q", time.Since(startTime))
+ LogStats("shell func time: %q %d", shellFuncTime, shellFuncCount)
startTime = time.Now()
db := NewDepBuilder(er, vars)
- LogStats("dep build prepare time: %q", time.Now().Sub(startTime))
+ LogStats("dep build prepare time: %q", time.Since(startTime))
startTime = time.Now()
nodes, err2 := db.Eval(targets)
if err2 != nil {
panic(err2)
}
- LogStats("dep build time: %q", time.Now().Sub(startTime))
+ LogStats("dep build time: %q", time.Since(startTime))
var readMks []*ReadMakefile
// Always put the root Makefile as the first element.
readMks = append(readMks, &ReadMakefile{
@@ -300,30 +300,30 @@
if eagerCmdEvalFlag {
startTime := time.Now()
EvalCommands(nodes, vars)
- LogStats("eager eval command time: %q", time.Now().Sub(startTime))
+ LogStats("eager eval command time: %q", time.Since(startTime))
}
if saveGOB != "" {
startTime := time.Now()
DumpDepGraph(g, saveGOB, targets)
- LogStats("serialize time: %q", time.Now().Sub(startTime))
+ LogStats("serialize time: %q", time.Since(startTime))
}
if saveJSON != "" {
startTime := time.Now()
DumpDepGraphAsJSON(g, saveJSON, targets)
- LogStats("serialize time: %q", time.Now().Sub(startTime))
+ LogStats("serialize time: %q", time.Since(startTime))
}
if useCache && !g.isCached {
startTime := time.Now()
DumpDepGraphCache(g, targets)
- LogStats("serialize time: %q", time.Now().Sub(startTime))
+ LogStats("serialize time: %q", time.Since(startTime))
}
if generateNinja {
startTime := time.Now()
GenerateNinja(g)
- LogStats("generate ninja time: %q", time.Now().Sub(startTime))
+ LogStats("generate ninja time: %q", time.Since(startTime))
return
}
@@ -352,5 +352,5 @@
if err != nil {
panic(err)
}
- LogStats("exec time: %q", time.Now().Sub(startTime))
+ LogStats("exec time: %q", time.Since(startTime))
}
diff --git a/serialize.go b/serialize.go
index d9f2d94..46bbbf5 100644
--- a/serialize.go
+++ b/serialize.go
@@ -252,10 +252,10 @@
e := gob.NewEncoder(f)
startTime := time.Now()
sg := MakeSerializableGraph(g, roots)
- LogStats("serialize prepare time: %q", time.Now().Sub(startTime))
+ LogStats("serialize prepare time: %q", time.Since(startTime))
startTime = time.Now()
e.Encode(sg)
- LogStats("serialize output time: %q", time.Now().Sub(startTime))
+ LogStats("serialize output time: %q", time.Since(startTime))
err = f.Close()
if err != nil {
panic(err)
@@ -586,7 +586,7 @@
func LoadDepGraphCache(makefile string, roots []string) *DepGraph {
startTime := time.Now()
defer func() {
- LogStats("Cache lookup time: %q", time.Now().Sub(startTime))
+ LogStats("Cache lookup time: %q", time.Since(startTime))
}()
filename := GetCacheFilename(makefile, roots)
