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

1 files changed, 3 insertions, 3 deletions

diff --git a/serialize.go b/serialize.go
index d9f2d94..46bbbf5 100644
--- a/serialize.go
+++ b/serialize.go
@@ -252,10 +252,10 @@ func DumpDepGraph(g *DepGraph, filename string, roots []string) {
 	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 LoadDepGraph(filename string) *DepGraph {
 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)