From 18ebb2318aeed61cd707332dd794c5edecc6e9d3 Mon Sep 17 00:00:00 2001 From: Chris Parsons Date: Fri, 25 Mar 2022 00:56:02 -0400 Subject: [PATCH] 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 | 1 + bootstrap/command.go | 6 +++ context.go | 19 ++++++- metrics/Android.bp | 27 ++++++++++ metrics/event_handler.go | 104 +++++++++++++++++++++++++++++++++++++++ 5 files changed, 156 insertions(+), 1 deletion(-) create mode 100644 metrics/Android.bp create mode 100644 metrics/event_handler.go diff --git a/Android.bp b/Android.bp index 74c1421..c84d04a 100644 --- a/Android.bp +++ b/Android.bp @@ -31,6 +31,7 @@ license { 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 @@ func RunBlueprint(args Args, stopBefore StopBefore, ctx *blueprint.Context, conf } else { fatalf("-l 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) diff --git a/context.go b/context.go index e50df90..33a7487 100644 --- a/context.go +++ b/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 { 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 +}