Merge "Compute critical path when ninja finishes"

cmd/soong_ui/main.go

@@ -162,6 +162,7 @@ func main() {
 	stat.AddOutput(status.NewVerboseLog(log, filepath.Join(logsDir, "verbose.log")))
 	stat.AddOutput(status.NewErrorLog(log, filepath.Join(logsDir, "error.log")))
 	stat.AddOutput(status.NewProtoErrorLog(log, filepath.Join(logsDir, "build_error")))
+	stat.AddOutput(status.NewCriticalPath(log))
 
 	defer met.Dump(filepath.Join(logsDir, "soong_metrics"))
 

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",

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
+}

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)
+			}
+		})
+	}
+}

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)

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.