Merge "Compute critical path when ninja finishes" (7c9b4cf1) · Commits · e / os / android_build_soong

cmd/soong_ui/main.go

+1 −0

Original line number	Diff line number	Diff line
		@@ -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

+2 −0

Original line number	Diff line number	Diff line
		@@ -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 → 100644

+152 −0

Original line number	Diff line number	Diff line
		// 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 → 100644

+166 −0

Original line number	Diff line number	Diff line
		// 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

+1 −0

Original line number	Diff line number	Diff line
		@@ -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)