diff --git a/cmd/soong_ui/main.go b/cmd/soong_ui/main.go index d3ef415b5..4d59a3923 100644 --- a/cmd/soong_ui/main.go +++ b/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")) diff --git a/ui/status/Android.bp b/ui/status/Android.bp index 34241ee9a..ec929b342 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 000000000..444327ba4 --- /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 000000000..965e0ad13 --- /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 ee2a2daaa..9cf2f6a81 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 3d8cd7a2c..df33baa8b 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.