Merge pull request #320 from rtay1188/timing

add time metrics

admiral/pkg/clusters/configwriter.go

@@ -5,9 +5,11 @@ import (
 	"sort"
 	"strconv"
 	"strings"
+	"time"
 
 	"github.com/istio-ecosystem/admiral/admiral/pkg/controller/admiral"
 	"github.com/istio-ecosystem/admiral/admiral/pkg/controller/common"
+	"github.com/istio-ecosystem/admiral/admiral/pkg/controller/util"
 	"github.com/istio-ecosystem/admiral/admiral/pkg/registry"
 	"github.com/sirupsen/logrus"
 	networkingV1Alpha3 "istio.io/api/networking/v1alpha3"
@@ -35,15 +37,20 @@ func (b *ServiceEntryBuilder) BuildServiceEntriesFromIdentityConfig(ctxLogger *l
 		identity       = identityConfig.IdentityName
 		seMap          = map[string]*networkingV1Alpha3.ServiceEntry{}
 		serviceEntries = []*networkingV1Alpha3.ServiceEntry{}
+		start          = time.Now()
 		err            error
 	)
-	ctxLogger.Infof(common.CtxLogFormat, "buildServiceEntry", identity, common.GetSyncNamespace(), b.ClientCluster, "Beginning to build the SE spec")
+	defer util.LogElapsedTime("BuildServiceEntriesFromIdentityConfig", identity, common.GetOperatorSyncNamespace(), b.ClientCluster)
+	ctxLogger.Infof(common.CtxLogFormat, "BuildServiceEntriesFromIdentityConfig", identity, common.GetOperatorSyncNamespace(), b.ClientCluster, "Beginning to build the SE spec")
 	ingressEndpoints, err := getIngressEndpoints(identityConfig.Clusters)
+	util.LogElapsedTimeSince("getIngressEndpoints", identity, "", b.ClientCluster, start)
 	if err != nil || len(ingressEndpoints) == 0 {
 		return serviceEntries, err
 	}
+	start = time.Now()
 	_, isServerOnClientCluster := ingressEndpoints[b.ClientCluster]
 	dependentNamespaces, err := getExportTo(ctxLogger, b.RemoteRegistry.RegistryClient, b.ClientCluster, isServerOnClientCluster, identityConfig.ClientAssets)
+	util.LogElapsedTimeSince("getExportTo", identity, "", b.ClientCluster, start)
 	if err != nil {
 		return serviceEntries, err
 	}
@@ -52,7 +59,9 @@ func (b *ServiceEntryBuilder) BuildServiceEntriesFromIdentityConfig(ctxLogger *l
 		for _, identityConfigEnvironment := range identityConfigCluster.Environment {
 			env := identityConfigEnvironment.Name
 			var tmpSe *networkingV1Alpha3.ServiceEntry
+			start = time.Now()
 			ep, err := getServiceEntryEndpoint(ctxLogger, b.ClientCluster, serverCluster, ingressEndpoints, identityConfigEnvironment)
+			util.LogElapsedTimeSince("getServiceEntryEndpoint", identity, env, b.ClientCluster, start)
 			if err != nil {
 				return serviceEntries, err
 			}

admiral/pkg/clusters/serviceentry.go

@@ -1074,6 +1074,7 @@ func modifySidecarForLocalClusterCommunication(
 	if rc == nil {
 		return fmt.Errorf("skipped modifying sidecar resource as remoteController object is nil")
 	}
+	defer util.LogElapsedTime("modifySidecarForLocalClusterCommunication", sourceIdentity, sidecarNamespace, rc.ClusterID)
 	//get existing sidecar from the cluster
 	sidecarConfig := rc.SidecarController
 	sidecarEgressMap.Range(func(k string, v map[string]common.SidecarEgress) {

admiral/pkg/clusters/shard_handler.go

@@ -3,8 +3,10 @@ package clusters
 import (
 	"context"
 	"fmt"
+	"github.com/istio-ecosystem/admiral/admiral/pkg/controller/util"
 	"strings"
 	"sync"
+	"time"
 
 	admiralapiv1 "github.com/istio-ecosystem/admiral-api/pkg/apis/admiral/v1"
 	"github.com/istio-ecosystem/admiral/admiral/pkg/registry"
@@ -82,8 +84,10 @@ func HandleEventForShard(ctx context.Context, event admiral.EventType, obj *admi
 // of the assets on the shard, and puts those into configWriterData which go into the job channel
 func ProduceIdentityConfigsFromShard(ctxLogger *log.Entry, shard admiralapiv1.Shard, configWriterData chan<- *ConfigWriterData, rr *RemoteRegistry, producerWG *sync.WaitGroup) {
 	cnames := make(map[string]string)
+	defer util.LogElapsedTime("ProduceIdentityConfigsFromShard", shard.Name, shard.Namespace, "")
 	for _, clusterShard := range shard.Spec.Clusters {
 		for _, identityItem := range clusterShard.Identities {
+			start := time.Now()
 			identityConfig, err := rr.RegistryClient.GetIdentityConfigByIdentityName(identityItem.Name, ctxLogger)
 			if err != nil {
 				ctxLogger.Warnf(common.CtxLogFormat, "ProduceIdentityConfig", identityItem.Name, shard.Namespace, clusterShard.Name, err)
@@ -125,6 +129,7 @@ func ProduceIdentityConfigsFromShard(ctxLogger *log.Entry, shard admiralapiv1.Sh
 				ClusterName:    clusterShard.Name,
 				Error:          err,
 			}
+			util.LogElapsedTimeSince("ProduceIdentityConfigsFillCaches", identityItem.Name, "", clusterShard.Name, start)
 		}
 	}
 	producerWG.Done()
@@ -140,6 +145,7 @@ func ConsumeIdentityConfigs(ctxLogger *log.Entry, ctx context.Context, configWri
 		assetName := identityConfig.IdentityName
 		clientCluster := data.ClusterName
 		ctxLogger.Infof(common.CtxLogFormat, "ConsumeIdentityConfig", assetName, "", clientCluster, "starting to consume identityConfig")
+		start := time.Now()
 		serviceEntryBuilder := ServiceEntryBuilder{ClientCluster: clientCluster, RemoteRegistry: rr}
 		serviceEntries, err := serviceEntryBuilder.BuildServiceEntriesFromIdentityConfig(ctxLogger, *identityConfig)
 		if err != nil {
@@ -201,6 +207,7 @@ func ConsumeIdentityConfigs(ctxLogger *log.Entry, ctx context.Context, configWri
 			}
 		}
 		configWriterDataResults <- data
+		util.LogElapsedTimeSince("ConsumeIdentityConfigs", assetName, "", clientCluster, start)
 	}
 }
 

admiral/pkg/registry/registry.go

@@ -3,10 +3,10 @@ package registry
 import (
 	"encoding/json"
 	"os"
-
 	"strings"
 
 	"github.com/istio-ecosystem/admiral/admiral/pkg/controller/common"
+	"github.com/istio-ecosystem/admiral/admiral/pkg/controller/util"
 	log "github.com/sirupsen/logrus"
 )
 
@@ -41,6 +41,7 @@ func WithRegistryEndpoint(registryEndpoint string) func(*registryClient) {
 // the given identityAlias
 func (c *registryClient) GetIdentityConfigByIdentityName(identityAlias string, ctxLogger *log.Entry) (IdentityConfig, error) {
 	//TODO: Use real result from registry and remove string splitting to match test file names
+	defer util.LogElapsedTime("GetIdentityConfigByIdentityName", identityAlias, "", "")
 	byteValue, err := readIdentityConfigFromFile(strings.Split(identityAlias, "."))
 	if err != nil {
 		ctxLogger.Infof(common.CtxLogFormat, "GetByIdentityName", identityAlias, "", "", err)
@@ -64,6 +65,7 @@ func readIdentityConfigFromFile(shortAlias []string) ([]byte, error) {
 // GetIdentityConfigByClusterName calls the registry API to fetch the IdentityConfigs for
 // every identity on the cluster.
 func (c *registryClient) GetIdentityConfigByClusterName(clusterName string, ctxLogger *log.Entry) ([]IdentityConfig, error) {
+	defer util.LogElapsedTime("GetIdentityConfigByClusterName", "", "", clusterName)
 	//TODO: need to call this function once during startup time to warm the cache
 	//jsonResult = os.request(/cluster/{cluster_id}/configurations
 	ctxLogger.Infof(common.CtxLogFormat, "GetByClusterName", "", "", clusterName, "")