Add critical path infomation into metrics
To improve build efficiency, the metrics for critical path and
parallelism ratio is necessary. That information has been included in
soong.log, so added it into metrics as well.
Bug: 271526845
Test: build and check if metrics pb has critical path info
Change-Id: I14e1a78c13d400b792d3b05df18604da48759ade
diff --git a/ui/status/Android.bp b/ui/status/Android.bp
index a46a007..b724bc9 100644
--- a/ui/status/Android.bp
+++ b/ui/status/Android.bp
@@ -28,6 +28,7 @@
],
srcs: [
"critical_path.go",
+ "critical_path_logger.go",
"kati.go",
"log.go",
"ninja.go",
diff --git a/ui/status/critical_path.go b/ui/status/critical_path.go
index 8065c60..72914e7 100644
--- a/ui/status/critical_path.go
+++ b/ui/status/critical_path.go
@@ -15,23 +15,23 @@
package status
import (
+ "android/soong/ui/metrics"
+
+ soong_metrics_proto "android/soong/ui/metrics/metrics_proto"
"time"
- "android/soong/ui/logger"
+ "google.golang.org/protobuf/proto"
)
-func NewCriticalPath(log logger.Logger) StatusOutput {
- return &criticalPath{
- log: log,
+func NewCriticalPath() *CriticalPath {
+ return &CriticalPath{
running: make(map[*Action]time.Time),
nodes: make(map[string]*node),
clock: osClock{},
}
}
-type criticalPath struct {
- log logger.Logger
-
+type CriticalPath struct {
nodes map[string]*node
running map[*Action]time.Time
@@ -57,7 +57,7 @@
input *node
}
-func (cp *criticalPath) StartAction(action *Action, counts Counts) {
+func (cp *CriticalPath) StartAction(action *Action) {
start := cp.clock.Now()
if cp.start.IsZero() {
cp.start = start
@@ -65,13 +65,13 @@
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)
+func (cp *CriticalPath) FinishAction(action *Action) {
+ if start, ok := cp.running[action]; ok {
+ delete(cp.running, action)
// Determine the input to this edge with the longest cumulative duration
var criticalPathInput *node
- for _, input := range result.Action.Inputs {
+ for _, input := range action.Inputs {
if x := cp.nodes[input]; x != nil {
if criticalPathInput == nil || x.cumulativeDuration > criticalPathInput.cumulativeDuration {
criticalPathInput = x
@@ -88,13 +88,13 @@
}
node := &node{
- action: result.Action,
+ action: action,
cumulativeDuration: cumulativeDuration,
duration: duration,
input: criticalPathInput,
}
- for _, output := range result.Action.Outputs {
+ for _, output := range action.Outputs {
cp.nodes[output] = node
}
@@ -102,37 +102,7 @@
}
}
-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())
- if elapsedTime > 0 {
- 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 {
+func (cp *CriticalPath) criticalPath() (path []*node, elapsedTime time.Duration, criticalTime time.Duration) {
var max *node
// Find the node with the longest critical path
@@ -142,13 +112,31 @@
}
}
- // Follow the critical path back to the leaf node
- var criticalPath []*node
node := max
for node != nil {
- criticalPath = append(criticalPath, node)
+ path = append(path, node)
node = node.input
}
+ if len(path) > 0 {
+ // Log the critical path to the verbose log
+ criticalTime = path[0].cumulativeDuration
+ if !cp.start.IsZero() {
+ elapsedTime = cp.end.Sub(cp.start)
+ }
+ }
+ return
+}
- return criticalPath
+func (cp *CriticalPath) WriteToMetrics(met *metrics.Metrics) {
+ criticalPathInfo := soong_metrics_proto.CriticalPathInfo{}
+ path, elapsedTime, criticalTime := cp.criticalPath()
+ criticalPathInfo.ElapsedTime = proto.Uint64(uint64(elapsedTime.Microseconds()))
+ criticalPathInfo.CriticalPathTime = proto.Uint64(uint64(criticalTime.Microseconds()))
+ for _, job := range path {
+ jobInfo := soong_metrics_proto.JobInfo{}
+ jobInfo.ElapsedTime = proto.Uint64(uint64(job.duration.Microseconds()))
+ jobInfo.JobDescription = &job.action.Description
+ criticalPathInfo.CriticalPath = append(criticalPathInfo.CriticalPath, &jobInfo)
+ }
+ met.SetCriticalPathInfo(criticalPathInfo)
}
diff --git a/ui/status/critical_path_logger.go b/ui/status/critical_path_logger.go
new file mode 100644
index 0000000..f8b49d1
--- /dev/null
+++ b/ui/status/critical_path_logger.go
@@ -0,0 +1,73 @@
+// Copyright 2023 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"
+)
+
+// Create a new CriticalPathLogger. if criticalPath is nil, it creates a new criticalPath,
+// if not, it uses that.(its purpose is using a critical path outside logger)
+func NewCriticalPathLogger(log logger.Logger, criticalPath *CriticalPath) StatusOutput {
+ if criticalPath == nil {
+ criticalPath = NewCriticalPath()
+ }
+ return &criticalPathLogger{
+ log: log,
+ criticalPath: criticalPath,
+ }
+}
+
+type criticalPathLogger struct {
+ log logger.Logger
+ criticalPath *CriticalPath
+}
+
+func (cp *criticalPathLogger) StartAction(action *Action, counts Counts) {
+ cp.criticalPath.StartAction(action)
+}
+
+func (cp *criticalPathLogger) FinishAction(result ActionResult, counts Counts) {
+ cp.criticalPath.FinishAction(result.Action)
+}
+
+func (cp *criticalPathLogger) Flush() {
+ criticalPath, elapsedTime, criticalTime := cp.criticalPath.criticalPath()
+
+ if len(criticalPath) > 0 {
+ cp.log.Verbosef("critical path took %s", criticalTime.String())
+ if !cp.criticalPath.start.IsZero() {
+ cp.log.Verbosef("elapsed time %s", elapsedTime.String())
+ if elapsedTime > 0 {
+ 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 *criticalPathLogger) Message(level MsgLevel, msg string) {}
+
+func (cp *criticalPathLogger) Write(p []byte) (n int, err error) { return len(p), nil }
diff --git a/ui/status/critical_path_test.go b/ui/status/critical_path_test.go
index 965e0ad..369e805 100644
--- a/ui/status/critical_path_test.go
+++ b/ui/status/critical_path_test.go
@@ -21,7 +21,7 @@
)
type testCriticalPath struct {
- *criticalPath
+ *CriticalPath
Counts
actions map[int]*Action
@@ -40,14 +40,12 @@
}
t.actions[id] = action
- t.StartAction(action, t.Counts)
+ t.StartAction(action)
}
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)
+ t.FinishAction(t.actions[id])
}
func TestCriticalPath(t *testing.T) {
@@ -137,13 +135,13 @@
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
cp := &testCriticalPath{
- criticalPath: NewCriticalPath(nil).(*criticalPath),
+ CriticalPath: NewCriticalPath(),
actions: make(map[int]*Action),
}
tt.msgs(cp)
- criticalPath := cp.criticalPath.criticalPath()
+ criticalPath, _, _ := cp.CriticalPath.criticalPath()
var descs []string
for _, x := range criticalPath {