Add event handling to blueprint for metrics
In conjunction with soong/build changes, this materialized runtime
metrics for various soong_build events.
Test: Manually verified materialized protos for bp2build, mixed builds,
and legacy build.
Change-Id: Ia92403605e3063028dbf6a1ded8449c190b9e63e
diff --git a/Android.bp b/Android.bp
index 74c1421..c84d04a 100644
--- a/Android.bp
+++ b/Android.bp
@@ -31,6 +31,7 @@
bootstrap_go_package {
name: "blueprint",
deps: [
+ "blueprint-metrics",
"blueprint-parser",
"blueprint-pathtools",
"blueprint-proptools",
diff --git a/bootstrap/command.go b/bootstrap/command.go
index e475709..8c045b4 100644
--- a/bootstrap/command.go
+++ b/bootstrap/command.go
@@ -81,7 +81,9 @@
} else {
fatalf("-l <moduleListFile> is required and must be nonempty")
}
+ ctx.BeginEvent("list_modules")
filesToParse, err := ctx.ListModulePaths(srcDir)
+ ctx.EndEvent("list_modules")
if err != nil {
fatalf("could not enumerate files: %v\n", err.Error())
}
@@ -91,10 +93,12 @@
ctx.RegisterModuleType("blueprint_go_binary", newGoBinaryModuleFactory())
ctx.RegisterSingletonType("bootstrap", newSingletonFactory())
+ ctx.BeginEvent("parse_bp")
blueprintFiles, errs := ctx.ParseFileList(".", filesToParse, config)
if len(errs) > 0 {
fatalErrors(errs)
}
+ ctx.EndEvent("parse_bp")
// Add extra ninja file dependencies
ninjaDeps = append(ninjaDeps, blueprintFiles...)
@@ -124,6 +128,8 @@
var f *os.File
var buf *bufio.Writer
+ ctx.BeginEvent("write_files")
+ defer ctx.EndEvent("write_files")
if args.EmptyNinjaFile {
if err := ioutil.WriteFile(joinPath(ctx.SrcDir(), args.OutFile), []byte(nil), outFilePermissions); err != nil {
fatalf("error writing empty Ninja file: %s", err)
diff --git a/context.go b/context.go
index e50df90..33a7487 100644
--- a/context.go
+++ b/context.go
@@ -34,6 +34,7 @@
"text/scanner"
"text/template"
+ "github.com/google/blueprint/metrics"
"github.com/google/blueprint/parser"
"github.com/google/blueprint/pathtools"
"github.com/google/blueprint/proptools"
@@ -71,7 +72,9 @@
type Context struct {
context.Context
- // set at instantiation
+ // Used for metrics-related event logging.
+ EventHandler *metrics.EventHandler
+
moduleFactories map[string]ModuleFactory
nameInterface NameInterface
moduleGroups []*moduleGroup
@@ -380,8 +383,10 @@
}
func newContext() *Context {
+ eventHandler := metrics.EventHandler{}
return &Context{
Context: context.Background(),
+ EventHandler: &eventHandler,
moduleFactories: make(map[string]ModuleFactory),
nameInterface: NewSimpleNameInterface(),
moduleInfo: make(map[Module]*moduleInfo),
@@ -1538,6 +1543,8 @@
// the modules depended upon are defined and that no circular dependencies
// exist.
func (c *Context) ResolveDependencies(config interface{}) (deps []string, errs []error) {
+ c.BeginEvent("resolve_deps")
+ defer c.EndEvent("resolve_deps")
return c.resolveDependencies(c.Context, config)
}
@@ -2404,6 +2411,8 @@
// methods.
func (c *Context) PrepareBuildActions(config interface{}) (deps []string, errs []error) {
+ c.BeginEvent("prepare_build_actions")
+ defer c.EndEvent("prepare_build_actions")
pprof.Do(c.Context, pprof.Labels("blueprint", "PrepareBuildActions"), func(ctx context.Context) {
c.buildActionsReady = false
@@ -4106,6 +4115,14 @@
return nil
}
+func (c *Context) BeginEvent(name string) {
+ c.EventHandler.Begin(name)
+}
+
+func (c *Context) EndEvent(name string) {
+ c.EventHandler.End(name)
+}
+
func (c *Context) writeLocalBuildActions(nw *ninjaWriter,
defs *localBuildActions) error {
diff --git a/metrics/Android.bp b/metrics/Android.bp
new file mode 100644
index 0000000..3668668
--- /dev/null
+++ b/metrics/Android.bp
@@ -0,0 +1,27 @@
+//
+// Copyright (C) 2022 The Android Open Source Project
+//
+// 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 {
+ default_applicable_licenses: ["build_blueprint_license"],
+}
+
+bootstrap_go_package {
+ name: "blueprint-metrics",
+ pkgPath: "github.com/google/blueprint/metrics",
+ srcs: [
+ "event_handler.go",
+ ],
+}
diff --git a/metrics/event_handler.go b/metrics/event_handler.go
new file mode 100644
index 0000000..c19d039
--- /dev/null
+++ b/metrics/event_handler.go
@@ -0,0 +1,104 @@
+// Copyright 2022 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 metrics
+
+import (
+ "fmt"
+ "strings"
+ "time"
+)
+
+// EventHandler tracks nested events and their start/stop times in a single
+// thread.
+type EventHandler struct {
+ completedEvents []Event
+
+ // These fields handle event scoping. When starting a new event, a new entry
+ // is pushed onto these fields. When ending an event, these fields are popped.
+ scopeIds []string
+ scopeStartTimes []time.Time
+}
+
+// _now wraps the time.Now() function. _now is declared for unit testing purpose.
+var _now = func() time.Time {
+ return time.Now()
+}
+
+// Event holds the performance metrics data of a single build event.
+type Event struct {
+ // A unique human-readable identifier / "name" for the build event. Event
+ // names use period-delimited scoping. For example, if an event alpha starts,
+ // then an event bravo starts, then an event charlie starts and ends, the
+ // unique identifier for charlie will be 'alpha.bravo.charlie'.
+ Id string
+
+ Start time.Time
+ end time.Time
+}
+
+// RuntimeNanoseconds returns the number of nanoseconds between the start
+// and end times of the event.
+func (e Event) RuntimeNanoseconds() uint64 {
+ return uint64(e.end.Sub(e.Start).Nanoseconds())
+}
+
+// Begin logs the start of an event. This must be followed by a corresponding
+// call to End (though other events may begin and end before this event ends).
+// Events within the same scope must have unique names.
+func (h *EventHandler) Begin(name string) {
+ h.scopeIds = append(h.scopeIds, name)
+ h.scopeStartTimes = append(h.scopeStartTimes, _now())
+}
+
+// End logs the end of an event. All events nested within this event must have
+// themselves been marked completed.
+func (h *EventHandler) End(name string) {
+ if len(h.scopeIds) == 0 || name != h.scopeIds[len(h.scopeIds)-1] {
+ panic(fmt.Errorf("Unexpected scope end '%s'. Current scope: (%s)",
+ name, h.scopeIds))
+ }
+ event := Event{
+ // The event Id is formed from the period-delimited scope names of all
+ // active events (e.g. `alpha.beta.charlie`). See Event.Id documentation
+ // for more detail.
+ Id: strings.Join(h.scopeIds, "."),
+ Start: h.scopeStartTimes[len(h.scopeStartTimes)-1],
+ end: _now(),
+ }
+ h.completedEvents = append(h.completedEvents, event)
+ h.scopeIds = h.scopeIds[:len(h.scopeIds)-1]
+ h.scopeStartTimes = h.scopeStartTimes[:len(h.scopeStartTimes)-1]
+}
+
+// CompletedEvents returns all events which have been completed, after
+// validation.
+// It is an error to call this method if there are still ongoing events, or
+// if two events were completed with the same scope and name.
+func (h *EventHandler) CompletedEvents() []Event {
+ if len(h.scopeIds) > 0 {
+ panic(fmt.Errorf(
+ "Retrieving events before all events have been closed. Current scope: (%s)",
+ h.scopeIds))
+ }
+ // Validate no two events have the same full id.
+ ids := map[string]bool{}
+ for _, event := range h.completedEvents {
+ if _, containsId := ids[event.Id]; containsId {
+ panic(fmt.Errorf("Duplicate event registered: %s", event.Id))
+ }
+ ids[event.Id] = true
+ }
+ return h.completedEvents
+}