Collect more metrics for aquery handling

Test: go test soong tests
Test: m nothing & verify metrics
Change-Id: Id19e004d90dfbaa1b1706c607d5250bf845c0f3b
diff --git a/bazel/aquery.go b/bazel/aquery.go
index 80cf70a..6a5e054 100644
--- a/bazel/aquery.go
+++ b/bazel/aquery.go
@@ -23,9 +23,11 @@
 	"sort"
 	"strings"
 
+	analysis_v2_proto "prebuilts/bazel/common/proto/analysis_v2"
+
+	"github.com/google/blueprint/metrics"
 	"github.com/google/blueprint/proptools"
 	"google.golang.org/protobuf/proto"
-	analysis_v2_proto "prebuilts/bazel/common/proto/analysis_v2"
 )
 
 type artifactId int
@@ -313,7 +315,7 @@
 // action graph, as described by the given action graph json proto.
 // BuildStatements are one-to-one with actions in the given action graph, and AqueryDepsets
 // are one-to-one with Bazel's depSetOfFiles objects.
-func AqueryBuildStatements(aqueryJsonProto []byte) ([]BuildStatement, []AqueryDepset, error) {
+func AqueryBuildStatements(aqueryJsonProto []byte, eventHandler *metrics.EventHandler) ([]BuildStatement, []AqueryDepset, error) {
 	aqueryProto := &analysis_v2_proto.ActionGraphContainer{}
 	err := proto.Unmarshal(aqueryJsonProto, aqueryProto)
 	if err != nil {
@@ -387,74 +389,92 @@
 				ParentId: pathFragmentId(protoPathFragments.ParentId)})
 
 	}
-	aqueryHandler, err := newAqueryHandler(aqueryResult)
-	if err != nil {
-		return nil, nil, err
-	}
 
-	var buildStatements []BuildStatement
-	for _, actionEntry := range aqueryResult.Actions {
-		if shouldSkipAction(actionEntry) {
-			continue
-		}
-
-		var buildStatement BuildStatement
-		if actionEntry.isSymlinkAction() {
-			buildStatement, err = aqueryHandler.symlinkActionBuildStatement(actionEntry)
-		} else if actionEntry.isTemplateExpandAction() && len(actionEntry.Arguments) < 1 {
-			buildStatement, err = aqueryHandler.templateExpandActionBuildStatement(actionEntry)
-		} else if actionEntry.isFileWriteAction() {
-			buildStatement, err = aqueryHandler.fileWriteActionBuildStatement(actionEntry)
-		} else if actionEntry.isSymlinkTreeAction() {
-			buildStatement, err = aqueryHandler.symlinkTreeActionBuildStatement(actionEntry)
-		} else if len(actionEntry.Arguments) < 1 {
-			return nil, nil, fmt.Errorf("received action with no command: [%s]", actionEntry.Mnemonic)
-		} else {
-			buildStatement, err = aqueryHandler.normalActionBuildStatement(actionEntry)
-		}
-
+	var aqueryHandler *aqueryArtifactHandler
+	{
+		eventHandler.Begin("init_handler")
+		defer eventHandler.End("init_handler")
+		aqueryHandler, err = newAqueryHandler(aqueryResult)
 		if err != nil {
 			return nil, nil, err
 		}
-		buildStatements = append(buildStatements, buildStatement)
+	}
+
+	var buildStatements []BuildStatement
+	{
+		eventHandler.Begin("build_statements")
+		defer eventHandler.End("build_statements")
+		for _, actionEntry := range aqueryResult.Actions {
+			if shouldSkipAction(actionEntry) {
+				continue
+			}
+
+			var buildStatement BuildStatement
+			if actionEntry.isSymlinkAction() {
+				buildStatement, err = aqueryHandler.symlinkActionBuildStatement(actionEntry)
+			} else if actionEntry.isTemplateExpandAction() && len(actionEntry.Arguments) < 1 {
+				buildStatement, err = aqueryHandler.templateExpandActionBuildStatement(actionEntry)
+			} else if actionEntry.isFileWriteAction() {
+				buildStatement, err = aqueryHandler.fileWriteActionBuildStatement(actionEntry)
+			} else if actionEntry.isSymlinkTreeAction() {
+				buildStatement, err = aqueryHandler.symlinkTreeActionBuildStatement(actionEntry)
+			} else if len(actionEntry.Arguments) < 1 {
+				err = fmt.Errorf("received action with no command: [%s]", actionEntry.Mnemonic)
+			} else {
+				buildStatement, err = aqueryHandler.normalActionBuildStatement(actionEntry)
+			}
+
+			if err != nil {
+				return nil, nil, err
+			}
+			buildStatements = append(buildStatements, buildStatement)
+		}
 	}
 
 	depsetsByHash := map[string]AqueryDepset{}
 	var depsets []AqueryDepset
-	for _, aqueryDepset := range aqueryHandler.depsetIdToAqueryDepset {
-		if prevEntry, hasKey := depsetsByHash[aqueryDepset.ContentHash]; hasKey {
-			// Two depsets collide on hash. Ensure that their contents are identical.
-			if !reflect.DeepEqual(aqueryDepset, prevEntry) {
-				return nil, nil, fmt.Errorf("two different depsets have the same hash: %v, %v", prevEntry, aqueryDepset)
+	{
+		eventHandler.Begin("depsets")
+		defer eventHandler.End("depsets")
+		for _, aqueryDepset := range aqueryHandler.depsetIdToAqueryDepset {
+			if prevEntry, hasKey := depsetsByHash[aqueryDepset.ContentHash]; hasKey {
+				// Two depsets collide on hash. Ensure that their contents are identical.
+				if !reflect.DeepEqual(aqueryDepset, prevEntry) {
+					return nil, nil, fmt.Errorf("two different depsets have the same hash: %v, %v", prevEntry, aqueryDepset)
+				}
+			} else {
+				depsetsByHash[aqueryDepset.ContentHash] = aqueryDepset
+				depsets = append(depsets, aqueryDepset)
 			}
-		} else {
-			depsetsByHash[aqueryDepset.ContentHash] = aqueryDepset
-			depsets = append(depsets, aqueryDepset)
 		}
 	}
 
-	// Build Statements and depsets must be sorted by their content hash to
-	// preserve determinism between builds (this will result in consistent ninja file
-	// output). Note they are not sorted by their original IDs nor their Bazel ordering,
-	// as Bazel gives nondeterministic ordering / identifiers in aquery responses.
-	sort.Slice(buildStatements, func(i, j int) bool {
-		// For build statements, compare output lists. In Bazel, each output file
-		// may only have one action which generates it, so this will provide
-		// a deterministic ordering.
-		outputs_i := buildStatements[i].OutputPaths
-		outputs_j := buildStatements[j].OutputPaths
-		if len(outputs_i) != len(outputs_j) {
-			return len(outputs_i) < len(outputs_j)
-		}
-		if len(outputs_i) == 0 {
-			// No outputs for these actions, so compare commands.
-			return buildStatements[i].Command < buildStatements[j].Command
-		}
-		// There may be multiple outputs, but the output ordering is deterministic.
-		return outputs_i[0] < outputs_j[0]
+	eventHandler.Do("build_statement_sort", func() {
+		// Build Statements and depsets must be sorted by their content hash to
+		// preserve determinism between builds (this will result in consistent ninja file
+		// output). Note they are not sorted by their original IDs nor their Bazel ordering,
+		// as Bazel gives nondeterministic ordering / identifiers in aquery responses.
+		sort.Slice(buildStatements, func(i, j int) bool {
+			// For build statements, compare output lists. In Bazel, each output file
+			// may only have one action which generates it, so this will provide
+			// a deterministic ordering.
+			outputs_i := buildStatements[i].OutputPaths
+			outputs_j := buildStatements[j].OutputPaths
+			if len(outputs_i) != len(outputs_j) {
+				return len(outputs_i) < len(outputs_j)
+			}
+			if len(outputs_i) == 0 {
+				// No outputs for these actions, so compare commands.
+				return buildStatements[i].Command < buildStatements[j].Command
+			}
+			// There may be multiple outputs, but the output ordering is deterministic.
+			return outputs_i[0] < outputs_j[0]
+		})
 	})
-	sort.Slice(depsets, func(i, j int) bool {
-		return depsets[i].ContentHash < depsets[j].ContentHash
+	eventHandler.Do("depset_sort", func() {
+		sort.Slice(depsets, func(i, j int) bool {
+			return depsets[i].ContentHash < depsets[j].ContentHash
+		})
 	})
 	return buildStatements, depsets, nil
 }
diff --git a/bazel/aquery_test.go b/bazel/aquery_test.go
index 4d1503e..c6b139e 100644
--- a/bazel/aquery_test.go
+++ b/bazel/aquery_test.go
@@ -21,8 +21,10 @@
 	"sort"
 	"testing"
 
-	"google.golang.org/protobuf/proto"
 	analysis_v2_proto "prebuilts/bazel/common/proto/analysis_v2"
+
+	"github.com/google/blueprint/metrics"
+	"google.golang.org/protobuf/proto"
 )
 
 func TestAqueryMultiArchGenrule(t *testing.T) {
@@ -136,7 +138,7 @@
 		t.Error(err)
 		return
 	}
-	actualbuildStatements, actualDepsets, _ := AqueryBuildStatements(data)
+	actualbuildStatements, actualDepsets, _ := AqueryBuildStatements(data, &metrics.EventHandler{})
 	var expectedBuildStatements []BuildStatement
 	for _, arch := range []string{"arm", "arm64", "x86", "x86_64"} {
 		expectedBuildStatements = append(expectedBuildStatements,
@@ -195,7 +197,7 @@
 		t.Error(err)
 		return
 	}
-	_, _, err = AqueryBuildStatements(data)
+	_, _, err = AqueryBuildStatements(data, &metrics.EventHandler{})
 	assertError(t, err, "undefined outputId 3")
 }
 
@@ -226,7 +228,7 @@
 		t.Error(err)
 		return
 	}
-	_, _, err = AqueryBuildStatements(data)
+	_, _, err = AqueryBuildStatements(data, &metrics.EventHandler{})
 	assertError(t, err, "undefined (not even empty) input depsetId 2")
 }
 
@@ -257,7 +259,7 @@
 		t.Error(err)
 		return
 	}
-	_, _, err = AqueryBuildStatements(data)
+	_, _, err = AqueryBuildStatements(data, &metrics.EventHandler{})
 	assertError(t, err, "undefined input depsetId 42 (referenced by depsetId 1)")
 }
 
@@ -288,7 +290,7 @@
 		t.Error(err)
 		return
 	}
-	_, _, err = AqueryBuildStatements(data)
+	_, _, err = AqueryBuildStatements(data, &metrics.EventHandler{})
 	assertError(t, err, "undefined input artifactId 3")
 }
 
@@ -319,7 +321,7 @@
 		t.Error(err)
 		return
 	}
-	_, _, err = AqueryBuildStatements(data)
+	_, _, err = AqueryBuildStatements(data, &metrics.EventHandler{})
 	assertError(t, err, "undefined path fragment id 3")
 }
 
@@ -352,7 +354,7 @@
 		t.Error(err)
 		return
 	}
-	actual, _, err := AqueryBuildStatements(data)
+	actual, _, err := AqueryBuildStatements(data, &metrics.EventHandler{})
 	if err != nil {
 		t.Errorf("Unexpected error %q", err)
 	}
@@ -402,7 +404,7 @@
 		t.Error(err)
 		return
 	}
-	_, _, err = AqueryBuildStatements(data)
+	_, _, err = AqueryBuildStatements(data, &metrics.EventHandler{})
 	assertError(t, err, `found multiple potential depfiles "two.d", "other.d"`)
 }
 
@@ -483,7 +485,7 @@
 		t.Error(err)
 		return
 	}
-	actualbuildStatements, actualDepsets, _ := AqueryBuildStatements(data)
+	actualbuildStatements, actualDepsets, _ := AqueryBuildStatements(data, &metrics.EventHandler{})
 
 	expectedBuildStatements := []BuildStatement{
 		{
@@ -538,7 +540,7 @@
 		t.Error(err)
 		return
 	}
-	actual, _, err := AqueryBuildStatements(data)
+	actual, _, err := AqueryBuildStatements(data, &metrics.EventHandler{})
 	if err != nil {
 		t.Errorf("Unexpected error %q", err)
 	}
@@ -594,7 +596,7 @@
 		t.Error(err)
 		return
 	}
-	actualBuildStatements, actualDepsets, _ := AqueryBuildStatements(data)
+	actualBuildStatements, actualDepsets, _ := AqueryBuildStatements(data, &metrics.EventHandler{})
 	if len(actualDepsets) != 1 {
 		t.Errorf("expected 1 depset but found %#v", actualDepsets)
 		return
@@ -681,7 +683,7 @@
 		t.Error(err)
 		return
 	}
-	actualBuildStatements, actualDepsets, _ := AqueryBuildStatements(data)
+	actualBuildStatements, actualDepsets, _ := AqueryBuildStatements(data, &metrics.EventHandler{})
 	if len(actualDepsets) != 0 {
 		t.Errorf("expected 0 depsets but found %#v", actualDepsets)
 		return
@@ -748,7 +750,7 @@
 		t.Error(err)
 		return
 	}
-	actualBuildStatements, actualDepsets, err := AqueryBuildStatements(data)
+	actualBuildStatements, actualDepsets, err := AqueryBuildStatements(data, &metrics.EventHandler{})
 	if err != nil {
 		t.Errorf("Unexpected error %q", err)
 	}
@@ -845,7 +847,7 @@
 		t.Error(err)
 		return
 	}
-	actual, _, err := AqueryBuildStatements(data)
+	actual, _, err := AqueryBuildStatements(data, &metrics.EventHandler{})
 
 	if err != nil {
 		t.Errorf("Unexpected error %q", err)
@@ -894,7 +896,7 @@
 		t.Error(err)
 		return
 	}
-	actual, _, err := AqueryBuildStatements(data)
+	actual, _, err := AqueryBuildStatements(data, &metrics.EventHandler{})
 	if err != nil {
 		t.Errorf("Unexpected error %q", err)
 	}
@@ -940,7 +942,7 @@
 		t.Error(err)
 		return
 	}
-	_, _, err = AqueryBuildStatements(data)
+	_, _, err = AqueryBuildStatements(data, &metrics.EventHandler{})
 	assertError(t, err, `Expect 1 input and 1 output to symlink action, got: input ["file" "other_file"], output ["symlink"]`)
 }
 
@@ -971,7 +973,7 @@
 		t.Error(err)
 		return
 	}
-	_, _, err = AqueryBuildStatements(data)
+	_, _, err = AqueryBuildStatements(data, &metrics.EventHandler{})
 	assertError(t, err, "undefined outputId 2")
 }
 
@@ -1004,7 +1006,7 @@
 		t.Error(err)
 		return
 	}
-	actual, _, err := AqueryBuildStatements(data)
+	actual, _, err := AqueryBuildStatements(data, &metrics.EventHandler{})
 	if err != nil {
 		t.Errorf("Unexpected error %q", err)
 	}
@@ -1046,7 +1048,7 @@
 		t.Error(err)
 		return
 	}
-	_, _, err = AqueryBuildStatements(data)
+	_, _, err = AqueryBuildStatements(data, &metrics.EventHandler{})
 	assertError(t, err, `Expect 1 output to template expand action, got: output []`)
 }
 
@@ -1074,7 +1076,7 @@
 		t.Error(err)
 		return
 	}
-	actual, _, err := AqueryBuildStatements(data)
+	actual, _, err := AqueryBuildStatements(data, &metrics.EventHandler{})
 	if err != nil {
 		t.Errorf("Unexpected error %q", err)
 	}
@@ -1111,7 +1113,7 @@
 		t.Error(err)
 		return
 	}
-	actual, _, err := AqueryBuildStatements(data)
+	actual, _, err := AqueryBuildStatements(data, &metrics.EventHandler{})
 	if err != nil {
 		t.Errorf("Unexpected error %q", err)
 	}