lib: Added v.io/x/lib/timing package.

Adds the timing package, which provides utilities for collecting
trees of timing information and dumping it with a nice format.
An example of the output format:

00:00:01.000 root       98.000s       00:01:39.000
00:00:01.000    *           9.000s    00:00:10.000
00:00:10.000    foo        45.000s    00:00:55.000
00:00:10.000       *           5.000s 00:00:15.000
00:00:15.000       foo1       22.000s 00:00:37.000
00:00:37.000       foo2       18.000s 00:00:55.000
00:00:55.000    bar        25.000s    00:01:20.000
00:01:20.000    baz        19.000s    00:01:39.000

Also add this support to the cmdline package via the -time flag,
and add some preliminary timings for "jiri update".

MultiPart: 3/4

Change-Id: Ic22476e7b75ad31756eec8b6554991dd885b7632

Author: Todd Wang

Diff for: cmdline/.api

@@ -5,6 +5,8 @@ pkg cmdline, func HideGlobalFlagsExcept(...*regexp.Regexp)
 pkg cmdline, func Main(*Command)
 pkg cmdline, func Parse(*Command, *Env, []string) (Runner, []string, error)
 pkg cmdline, func ParseAndRun(*Command, *Env, []string) error
+pkg cmdline, method (*Env) TimerPop()
+pkg cmdline, method (*Env) TimerPush(string)
 pkg cmdline, method (*Env) UsageErrorf(string, ...interface{}) error
 pkg cmdline, method (ErrExitCode) Error() string
 pkg cmdline, method (RunnerFunc) Run(*Env, []string) error
@@ -23,6 +25,7 @@ pkg cmdline, type Env struct
 pkg cmdline, type Env struct, Stderr io.Writer
 pkg cmdline, type Env struct, Stdin io.Reader
 pkg cmdline, type Env struct, Stdout io.Writer
+pkg cmdline, type Env struct, Timer timing.Timer
 pkg cmdline, type Env struct, Usage func(*Env, io.Writer)
 pkg cmdline, type Env struct, Vars map[string]string
 pkg cmdline, type ErrExitCode int

Diff for: cmdline/cmdline.go

@@ -53,6 +53,7 @@ import (
 
 	"v.io/x/lib/envvar"
 	_ "v.io/x/lib/metadata" // for the -metadata flag
+	"v.io/x/lib/timing"
 )
 
 // Command represents a single command in a command-line program.  A program
@@ -121,9 +122,16 @@ type Topic struct {
 func Main(root *Command) {
 	env := EnvFromOS()
 	err := ParseAndRun(root, env, os.Args[1:])
-	os.Exit(ExitCode(err, env.Stderr))
+	code := ExitCode(err, env.Stderr)
+	if *flagTime && env.Timer != nil {
+		env.Timer.Finish()
+		timing.IntervalPrinter{}.Print(env.Stderr, env.Timer.Root())
+	}
+	os.Exit(code)
 }
 
+var flagTime = flag.Bool("time", false, "Dump timing information to stderr before exiting the program.")
+
 // Parse parses args against the command tree rooted at root down to a leaf
 // command.  A single path through the command tree is traversed, based on the
 // sub-commands specified in args.  Global and command-specific flags are parsed
@@ -156,6 +164,8 @@ func Main(root *Command) {
 // Parse merges root flags into flag.CommandLine and sets ContinueOnError, so
 // that subsequent calls to flag.Parsed return true.
 func Parse(root *Command, env *Env, args []string) (Runner, []string, error) {
+	env.TimerPush("cmdline parse")
+	defer env.TimerPop()
 	if globalFlags == nil {
 		// Initialize our global flags to a cleaned copy.  We don't want the merging
 		// in parseFlags to contaminate the global flags, even if Parse is called
@@ -203,6 +213,8 @@ func ParseAndRun(root *Command, env *Env, args []string) error {
 	if err != nil {
 		return err
 	}
+	env.TimerPush("cmdline run")
+	defer env.TimerPop()
 	return runner.Run(env, args)
 }
 
@@ -337,7 +349,7 @@ func (cmd *Command) parse(path []*Command, env *Env, args []string) (Runner, []s
 	if cmd.LookPath {
 		// Look for a matching executable in PATH.
 		subCmd := cmd.Name + "-" + subName
-		if lookPath(subCmd, env.pathDirs()) {
+		if lookPath(env, subCmd) {
 			return binaryRunner{subCmd, cmdPath}, subArgs, nil
 		}
 	}
@@ -464,6 +476,8 @@ type binaryRunner struct {
 }
 
 func (b binaryRunner) Run(env *Env, args []string) error {
+	env.TimerPush("run " + b.subCmd)
+	defer env.TimerPop()
 	vars := envvar.CopyMap(env.Vars)
 	vars["CMDLINE_PREFIX"] = b.cmdPath
 	cmd := exec.Command(b.subCmd, args...)
@@ -481,10 +495,12 @@ func (b binaryRunner) Run(env *Env, args []string) error {
 	return err
 }
 
-// lookPath returns a boolean that indicates whether executable <name>
-// can be found in any of the given directories.
-func lookPath(name string, dirs []string) bool {
-	for _, dir := range dirs {
+// lookPath returns true iff an executable with the given name can be found in
+// any of the PATH directories.
+func lookPath(env *Env, name string) bool {
+	env.TimerPush("lookpath " + name)
+	defer env.TimerPop()
+	for _, dir := range env.pathDirs() {
 		fileInfos, err := ioutil.ReadDir(dir)
 		if err != nil {
 			continue
@@ -501,11 +517,13 @@ func lookPath(name string, dirs []string) bool {
 	return false
 }
 
-// lookPathAll returns a deduped list of all executables found in the given
-// directories whose name starts with "<name>-", and where the name doesn't
-// match the given seen set.  The seen set may be mutated by this function.
-func lookPathAll(name string, dirs []string, seen map[string]bool) (result []string) {
-	for _, dir := range dirs {
+// lookPathAll returns a deduped list of all executables found in the PATH
+// directories whose name starts with "name-", and where the name doesn't match
+// the given seen set.  The seen set may be mutated by this function.
+func lookPathAll(env *Env, name string, seen map[string]bool) (result []string) {
+	env.TimerPush("lookpathall " + name)
+	defer env.TimerPop()
+	for _, dir := range env.pathDirs() {
 		fileInfos, err := ioutil.ReadDir(dir)
 		if err != nil {
 			continue

Diff for: cmdline/cmdline_test.go

@@ -2770,6 +2770,8 @@ Usage:
 The global flags are:
  -metadata=<just specify -metadata to activate>
    Displays metadata for the program and exits.
+ -time=false
+   Dump timing information to stderr before exiting the program.
 `,
 		},
 		{
@@ -2788,6 +2790,8 @@ Usage:
 The global flags are:
  -metadata=<just specify -metadata to activate>
    Displays metadata for the program and exits.
+ -time=false
+   Dump timing information to stderr before exiting the program.
 `,
 		},
 		{

Diff for: cmdline/env.go

@@ -13,6 +13,7 @@ import (
 
 	"v.io/x/lib/envvar"
 	"v.io/x/lib/textutil"
+	"v.io/x/lib/timing"
 )
 
 // EnvFromOS returns a new environment based on the operating system.
@@ -22,6 +23,7 @@ func EnvFromOS() *Env {
 		Stdout: os.Stdout,
 		Stderr: os.Stderr,
 		Vars:   envvar.SliceToMap(os.Environ()),
+		Timer:  timing.NewFullTimer("root"),
 	}
 }
 
@@ -33,6 +35,7 @@ type Env struct {
 	Stdout io.Writer
 	Stderr io.Writer
 	Vars   map[string]string // Environment variables
+	Timer  timing.Timer
 
 	// Usage is a function that prints usage information to w.  Typically set by
 	// calls to Main or Parse to print usage of the leaf command.
@@ -46,14 +49,28 @@ func (e *Env) UsageErrorf(format string, args ...interface{}) error {
 	return usageErrorf(e, e.Usage, format, args...)
 }
 
-// Clone creates a deep copy of Env.
+// TimerPush calls e.Timer.Push(name), only if the Timer is non-nil.
+func (e *Env) TimerPush(name string) {
+	if e.Timer != nil {
+		e.Timer.Push(name)
+	}
+}
+
+// TimerPop calls e.Timer.Pop(), only if the Timer is non-nil.
+func (e *Env) TimerPop() {
+	if e.Timer != nil {
+		e.Timer.Pop()
+	}
+}
+
 func (e *Env) clone() *Env {
 	return &Env{
 		Stdin:  e.Stdin,
 		Stdout: e.Stdout,
 		Stderr: e.Stderr,
 		Vars:   envvar.CopyMap(e.Vars),
 		Usage:  e.Usage,
+		Timer:  e.Timer, // use the same timer for all operations
 	}
 }
 

Diff for: cmdline/help.go

@@ -126,7 +126,7 @@ func runHelp(w *textutil.LineWriter, env *Env, args []string, path []*Command, c
 	if cmd.LookPath {
 		// Look for a matching executable in PATH.
 		extName := cmd.Name + "-" + subName
-		if lookPath(extName, env.pathDirs()) {
+		if lookPath(env, extName) {
 			runner := binaryRunner{extName, cmdPath}
 			envCopy := env.clone()
 			envCopy.Vars["CMDLINE_STYLE"] = config.style.String()
@@ -225,7 +225,7 @@ func usageAll(w *textutil.LineWriter, env *Env, path []*Command, config *helpCon
 		usageAll(w, env, append(path, help), config, false)
 	}
 	if cmd.LookPath {
-		extNames := lookPathAll(cmd.Name, env.pathDirs(), cmd.subNames())
+		extNames := lookPathAll(env, cmd.Name, cmd.subNames())
 		for _, extName := range extNames {
 			runner := binaryRunner{extName, cmdPath}
 			var buffer bytes.Buffer
@@ -277,6 +277,8 @@ func usageAll(w *textutil.LineWriter, env *Env, path []*Command, config *helpCon
 // avoid printing redundant information (e.g. help command, global flags).
 func usage(w *textutil.LineWriter, env *Env, path []*Command, config *helpConfig, firstCall bool) {
 	cmd, cmdPath := path[len(path)-1], pathName(config.prefix, path)
+	env.TimerPush("usage " + cmdPath)
+	defer env.TimerPop()
 	if config.style == styleShort {
 		fmt.Fprintln(w, cmd.Short)
 		return
@@ -305,7 +307,7 @@ func usage(w *textutil.LineWriter, env *Env, path []*Command, config *helpConfig
 	}
 	var extChildren []string
 	if cmd.LookPath {
-		extChildren = lookPathAll(cmd.Name, env.pathDirs(), cmd.subNames())
+		extChildren = lookPathAll(env, cmd.Name, cmd.subNames())
 	}
 	hasSubcommands := len(cmd.Children) > 0 || len(extChildren) > 0
 	if hasSubcommands {

Diff for: timing/.api

@@ -0,0 +1,45 @@
+pkg timing, func IntervalDuration(Interval, time.Time) time.Duration
+pkg timing, func NewCompactTimer(string) *CompactTimer
+pkg timing, func NewFullTimer(string) *FullTimer
+pkg timing, method (*CompactTimer) Finish()
+pkg timing, method (*CompactTimer) Pop()
+pkg timing, method (*CompactTimer) Push(string)
+pkg timing, method (*CompactTimer) Root() Interval
+pkg timing, method (*CompactTimer) String() string
+pkg timing, method (*FullTimer) Finish()
+pkg timing, method (*FullTimer) Pop()
+pkg timing, method (*FullTimer) Push(string)
+pkg timing, method (*FullTimer) Root() Interval
+pkg timing, method (*FullTimer) String() string
+pkg timing, method (FullInterval) Child(int) Interval
+pkg timing, method (FullInterval) End() time.Time
+pkg timing, method (FullInterval) Name() string
+pkg timing, method (FullInterval) NumChild() int
+pkg timing, method (FullInterval) Start() time.Time
+pkg timing, method (FullInterval) String() string
+pkg timing, method (IntervalPrinter) Print(io.Writer, Interval) error
+pkg timing, type CompactTimer struct
+pkg timing, type FullInterval struct
+pkg timing, type FullInterval struct, Children []FullInterval
+pkg timing, type FullInterval struct, EndTime time.Time
+pkg timing, type FullInterval struct, Label string
+pkg timing, type FullInterval struct, StartTime time.Time
+pkg timing, type FullTimer struct
+pkg timing, type FullTimer struct, FullRoot FullInterval
+pkg timing, type Interval interface { Child, End, Name, NumChild, Start, String }
+pkg timing, type Interval interface, Child(int) Interval
+pkg timing, type Interval interface, End() time.Time
+pkg timing, type Interval interface, Name() string
+pkg timing, type Interval interface, NumChild() int
+pkg timing, type Interval interface, Start() time.Time
+pkg timing, type Interval interface, String() string
+pkg timing, type IntervalPrinter struct
+pkg timing, type IntervalPrinter struct, Indent int
+pkg timing, type IntervalPrinter struct, MinGap time.Duration
+pkg timing, type IntervalPrinter struct, TimeFormat string
+pkg timing, type Timer interface { Finish, Pop, Push, Root, String }
+pkg timing, type Timer interface, Finish()
+pkg timing, type Timer interface, Pop()
+pkg timing, type Timer interface, Push(string)
+pkg timing, type Timer interface, Root() Interval
+pkg timing, type Timer interface, String() string