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

Android.bp

@@ -31,6 +31,7 @@ license {
 bootstrap_go_package {
     name: "blueprint",
     deps: [
+        "blueprint-metrics",
         "blueprint-parser",
         "blueprint-pathtools",
         "blueprint-proptools",

bootstrap/command.go

@@ -81,7 +81,9 @@ func RunBlueprint(args Args, stopBefore StopBefore, ctx *blueprint.Context, conf
 	} 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 @@ func RunBlueprint(args Args, stopBefore StopBefore, ctx *blueprint.Context, conf
 	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 @@ func RunBlueprint(args Args, stopBefore StopBefore, ctx *blueprint.Context, conf
 	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)

context.go

@@ -34,6 +34,7 @@ import (
 	"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 @@ const MockModuleListFile = "bplist"
 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 @@ type mutatorInfo struct {
 }
 
 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 @@ func (c *Context) addModule(module *moduleInfo) []error {
 // 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 @@ func writeJson(w io.Writer, modules []*JsonModule) {
 // 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 @@ func (c *Context) writeAllSingletonActions(nw *ninjaWriter) error {
 	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 {
 

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",
+    ],
+}

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
+}