Compute critical path when ninja finishes

Keep a running map of the critical path to each edge as it
finishes.  At the end of the build, find the edge with the
longest critical path and print the path to out/soong.log.

Test: critical_path_test.go
Change-Id: Ie01d26b068b768156b166bff00cdc3273e8124ca

5 files changed, 325 insertions, 0 deletions

diff --git a/ui/status/Android.bp b/ui/status/Android.bp
index 34241ee9..ec929b34 100644
--- a/ui/status/Android.bp
+++ b/ui/status/Android.bp
@@ -22,12 +22,14 @@ bootstrap_go_package {
         "soong-ui-status-build_error_proto",
     ],
     srcs: [
+        "critical_path.go",
         "kati.go",
         "log.go",
         "ninja.go",
         "status.go",
     ],
     testSrcs: [
+        "critical_path_test.go",
         "kati_test.go",
         "ninja_test.go",
         "status_test.go",
diff --git a/ui/status/critical_path.go b/ui/status/critical_path.go
new file mode 100644
index 00000000..444327ba
--- /dev/null
+++ b/ui/status/critical_path.go
@@ -0,0 +1,152 @@
+// Copyright 2019 Google Inc. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package status
+
+import (
+	"time"
+
+	"android/soong/ui/logger"
+)
+
+func NewCriticalPath(log logger.Logger) StatusOutput {
+	return &criticalPath{
+		log:     log,
+		running: make(map[*Action]time.Time),
+		nodes:   make(map[string]*node),
+		clock:   osClock{},
+	}
+}
+
+type criticalPath struct {
+	log logger.Logger
+
+	nodes   map[string]*node
+	running map[*Action]time.Time
+
+	start, end time.Time
+
+	clock clock
+}
+
+type clock interface {
+	Now() time.Time
+}
+
+type osClock struct{}
+
+func (osClock) Now() time.Time { return time.Now() }
+
+// A critical path node stores the critical path (the minimum time to build the node and all of its dependencies given
+// perfect parallelism) for an node.
+type node struct {
+	action             *Action
+	cumulativeDuration time.Duration
+	duration           time.Duration
+	input              *node
+}
+
+func (cp *criticalPath) StartAction(action *Action, counts Counts) {
+	start := cp.clock.Now()
+	if cp.start.IsZero() {
+		cp.start = start
+	}
+	cp.running[action] = start
+}
+
+func (cp *criticalPath) FinishAction(result ActionResult, counts Counts) {
+	if start, ok := cp.running[result.Action]; ok {
+		delete(cp.running, result.Action)
+
+		// Determine the input to this edge with the longest cumulative duration
+		var criticalPathInput *node
+		for _, input := range result.Action.Inputs {
+			if x := cp.nodes[input]; x != nil {
+				if criticalPathInput == nil || x.cumulativeDuration > criticalPathInput.cumulativeDuration {
+					criticalPathInput = x
+				}
+			}
+		}
+
+		end := cp.clock.Now()
+		duration := end.Sub(start)
+
+		cumulativeDuration := duration
+		if criticalPathInput != nil {
+			cumulativeDuration += criticalPathInput.cumulativeDuration
+		}
+
+		node := &node{
+			action:             result.Action,
+			cumulativeDuration: cumulativeDuration,
+			duration:           duration,
+			input:              criticalPathInput,
+		}
+
+		for _, output := range result.Action.Outputs {
+			cp.nodes[output] = node
+		}
+
+		cp.end = end
+	}
+}
+
+func (cp *criticalPath) Flush() {
+	criticalPath := cp.criticalPath()
+
+	if len(criticalPath) > 0 {
+		// Log the critical path to the verbose log
+		criticalTime := criticalPath[0].cumulativeDuration.Round(time.Second)
+		cp.log.Verbosef("critical path took %s", criticalTime.String())
+		if !cp.start.IsZero() {
+			elapsedTime := cp.end.Sub(cp.start).Round(time.Second)
+			cp.log.Verbosef("elapsed time %s", elapsedTime.String())
+			cp.log.Verbosef("perfect parallelism ratio %d%%",
+				int(float64(criticalTime)/float64(elapsedTime)*100))
+		}
+		cp.log.Verbose("critical path:")
+		for i := len(criticalPath) - 1; i >= 0; i-- {
+			duration := criticalPath[i].duration
+			duration = duration.Round(time.Second)
+			seconds := int(duration.Seconds())
+			cp.log.Verbosef("   %2d:%02d %s",
+				seconds/60, seconds%60, criticalPath[i].action.Description)
+		}
+	}
+}
+
+func (cp *criticalPath) Message(level MsgLevel, msg string) {}
+
+func (cp *criticalPath) Write(p []byte) (n int, err error) { return len(p), nil }
+
+func (cp *criticalPath) criticalPath() []*node {
+	var max *node
+
+	// Find the node with the longest critical path
+	for _, node := range cp.nodes {
+		if max == nil || node.cumulativeDuration > max.cumulativeDuration {
+			max = node
+		}
+	}
+
+	// Follow the critical path back to the leaf node
+	var criticalPath []*node
+	node := max
+	for node != nil {
+		criticalPath = append(criticalPath, node)
+		node = node.input
+	}
+
+	return criticalPath
+}
diff --git a/ui/status/critical_path_test.go b/ui/status/critical_path_test.go
new file mode 100644
index 00000000..965e0ad1
--- /dev/null
+++ b/ui/status/critical_path_test.go
@@ -0,0 +1,166 @@
+// Copyright 2019 Google Inc. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package status
+
+import (
+	"reflect"
+	"testing"
+	"time"
+)
+
+type testCriticalPath struct {
+	*criticalPath
+	Counts
+
+	actions map[int]*Action
+}
+
+type testClock time.Time
+
+func (t testClock) Now() time.Time { return time.Time(t) }
+
+func (t *testCriticalPath) start(id int, startTime time.Duration, outputs, inputs []string) {
+	t.clock = testClock(time.Unix(0, 0).Add(startTime))
+	action := &Action{
+		Description: outputs[0],
+		Outputs:     outputs,
+		Inputs:      inputs,
+	}
+
+	t.actions[id] = action
+	t.StartAction(action, t.Counts)
+}
+
+func (t *testCriticalPath) finish(id int, endTime time.Duration) {
+	t.clock = testClock(time.Unix(0, 0).Add(endTime))
+	t.FinishAction(ActionResult{
+		Action: t.actions[id],
+	}, t.Counts)
+}
+
+func TestCriticalPath(t *testing.T) {
+	tests := []struct {
+		name     string
+		msgs     func(*testCriticalPath)
+		want     []string
+		wantTime time.Duration
+	}{
+		{
+			name: "empty",
+			msgs: func(cp *testCriticalPath) {},
+		},
+		{
+			name: "duplicate",
+			msgs: func(cp *testCriticalPath) {
+				cp.start(0, 0, []string{"a"}, nil)
+				cp.start(1, 0, []string{"a"}, nil)
+				cp.finish(0, 1000)
+				cp.finish(0, 2000)
+			},
+			want:     []string{"a"},
+			wantTime: 1000,
+		},
+		{
+			name: "linear",
+			//  a
+			//  |
+			//  b
+			//  |
+			//  c
+			msgs: func(cp *testCriticalPath) {
+				cp.start(0, 0, []string{"a"}, nil)
+				cp.finish(0, 1000)
+				cp.start(1, 1000, []string{"b"}, []string{"a"})
+				cp.finish(1, 2000)
+				cp.start(2, 3000, []string{"c"}, []string{"b"})
+				cp.finish(2, 4000)
+			},
+			want:     []string{"c", "b", "a"},
+			wantTime: 3000,
+		},
+		{
+			name: "diamond",
+			//  a
+			//  |\
+			//  b c
+			//  |/
+			//  d
+			msgs: func(cp *testCriticalPath) {
+				cp.start(0, 0, []string{"a"}, nil)
+				cp.finish(0, 1000)
+				cp.start(1, 1000, []string{"b"}, []string{"a"})
+				cp.start(2, 1000, []string{"c"}, []string{"a"})
+				cp.finish(1, 2000)
+				cp.finish(2, 3000)
+				cp.start(3, 3000, []string{"d"}, []string{"b", "c"})
+				cp.finish(3, 4000)
+			},
+			want:     []string{"d", "c", "a"},
+			wantTime: 4000,
+		},
+		{
+			name: "multiple",
+			//  a d
+			//  | |
+			//  b e
+			//  |
+			//  c
+			msgs: func(cp *testCriticalPath) {
+				cp.start(0, 0, []string{"a"}, nil)
+				cp.start(3, 0, []string{"d"}, nil)
+				cp.finish(0, 1000)
+				cp.finish(3, 1000)
+				cp.start(1, 1000, []string{"b"}, []string{"a"})
+				cp.start(4, 1000, []string{"e"}, []string{"d"})
+				cp.finish(1, 2000)
+				cp.start(2, 2000, []string{"c"}, []string{"b"})
+				cp.finish(2, 3000)
+				cp.finish(4, 4000)
+
+			},
+			want:     []string{"e", "d"},
+			wantTime: 4000,
+		},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			cp := &testCriticalPath{
+				criticalPath: NewCriticalPath(nil).(*criticalPath),
+				actions:      make(map[int]*Action),
+			}
+
+			tt.msgs(cp)
+
+			criticalPath := cp.criticalPath.criticalPath()
+
+			var descs []string
+			for _, x := range criticalPath {
+				descs = append(descs, x.action.Description)
+			}
+
+			if !reflect.DeepEqual(descs, tt.want) {
+				t.Errorf("criticalPath.criticalPath() = %v, want %v", descs, tt.want)
+			}
+
+			var gotTime time.Duration
+			if len(criticalPath) > 0 {
+				gotTime = criticalPath[0].cumulativeDuration
+			}
+			if gotTime != tt.wantTime {
+				t.Errorf("cumulativeDuration[0].cumulativeDuration = %v, want %v", gotTime, tt.wantTime)
+			}
+		})
+	}
+}
diff --git a/ui/status/ninja.go b/ui/status/ninja.go
index ee2a2daa..9cf2f6a8 100644
--- a/ui/status/ninja.go
+++ b/ui/status/ninja.go
@@ -142,6 +142,7 @@ func (n *NinjaReader) run() {
 			action := &Action{
 				Description: msg.EdgeStarted.GetDesc(),
 				Outputs:     msg.EdgeStarted.Outputs,
+				Inputs:      msg.EdgeStarted.Inputs,
 				Command:     msg.EdgeStarted.GetCommand(),
 			}
 			n.status.StartAction(action)
diff --git a/ui/status/status.go b/ui/status/status.go
index 3d8cd7a2..df33baa8 100644
--- a/ui/status/status.go
+++ b/ui/status/status.go
@@ -32,6 +32,10 @@ type Action struct {
 	// but they can be any string.
 	Outputs []string
 
+	// Inputs is the (optional) list of inputs. Usually these are files,
+	// but they can be any string.
+	Inputs []string
+
 	// Command is the actual command line executed to perform the action.
 	// It's optional, but one of either Description or Command should be
 	// set.