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
diff --git a/cmd/soong_ui/main.go b/cmd/soong_ui/main.go
index d3ef415..4d59a39 100644
--- a/cmd/soong_ui/main.go
+++ b/cmd/soong_ui/main.go
@@ -162,6 +162,7 @@
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"))
diff --git a/ui/status/Android.bp b/ui/status/Android.bp
index 34241ee..ec929b3 100644
--- a/ui/status/Android.bp
+++ b/ui/status/Android.bp
@@ -22,12 +22,14 @@
"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 0000000..444327b
--- /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 0000000..965e0ad
--- /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 ee2a2da..9cf2f6a 100644
--- a/ui/status/ninja.go
+++ b/ui/status/ninja.go
@@ -142,6 +142,7 @@
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 3d8cd7a..df33baa 100644
--- a/ui/status/status.go
+++ b/ui/status/status.go
@@ -32,6 +32,10 @@
// 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.