Improve observability of node authorizer:

* Adding some metrics to the graph
* Adding log message when node authorizer has synced

Change-Id: I3447d6bc389a0b82ded1db2a7a4ae41d79486c2b

pkg/kubeapiserver/authorizer/config.go

@@ -82,6 +82,7 @@ func (config Config) New() (authorizer.Authorizer, authorizer.RuleResolver, erro
 		// Keep cases in sync with constant list in k8s.io/kubernetes/pkg/kubeapiserver/authorizer/modes/modes.go.
 		switch authorizationMode {
 		case modes.ModeNode:
+			node.RegisterMetrics()
 			graph := node.NewGraph()
 			node.AddGraphEventHandlers(
 				graph,

plugin/pkg/auth/authorizer/node/BUILD

@@ -36,6 +36,7 @@ go_library(
         "graph.go",
         "graph_populator.go",
         "intset.go",
+        "metrics.go",
         "node_authorizer.go",
     ],
     importpath = "k8s.io/kubernetes/plugin/pkg/auth/authorizer/node",
@@ -52,6 +53,7 @@ go_library(
         "//staging/src/k8s.io/api/rbac/v1:go_default_library",
         "//staging/src/k8s.io/api/storage/v1:go_default_library",
         "//staging/src/k8s.io/apimachinery/pkg/runtime/schema:go_default_library",
+        "//staging/src/k8s.io/apimachinery/pkg/util/wait:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/authentication/user:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/authorization/authorizer:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/util/feature:go_default_library",
@@ -59,6 +61,8 @@ go_library(
         "//staging/src/k8s.io/client-go/informers/storage/v1:go_default_library",
         "//staging/src/k8s.io/client-go/tools/cache:go_default_library",
         "//staging/src/k8s.io/component-base/featuregate:go_default_library",
+        "//staging/src/k8s.io/component-base/metrics:go_default_library",
+        "//staging/src/k8s.io/component-base/metrics/legacyregistry:go_default_library",
         "//third_party/forked/gonum/graph:go_default_library",
         "//third_party/forked/gonum/graph/simple:go_default_library",
         "//third_party/forked/gonum/graph/traverse:go_default_library",

plugin/pkg/auth/authorizer/node/graph.go

@@ -18,6 +18,7 @@ package node
 
 import (
 	"sync"
+	"time"
 
 	corev1 "k8s.io/api/core/v1"
 	utilfeature "k8s.io/apiserver/pkg/util/feature"
@@ -334,6 +335,10 @@ func (g *Graph) recomputeDestinationIndex_locked(n graph.Node) {
 //   pvc       -> pod
 //   svcacct   -> pod
 func (g *Graph) AddPod(pod *corev1.Pod) {
+	start := time.Now()
+	defer func() {
+		graphActionsDuration.WithLabelValues("AddPod").Observe(time.Since(start).Seconds())
+	}()
 	g.lock.Lock()
 	defer g.lock.Unlock()
 
@@ -392,6 +397,10 @@ func (g *Graph) AddPod(pod *corev1.Pod) {
 	}
 }
 func (g *Graph) DeletePod(name, namespace string) {
+	start := time.Now()
+	defer func() {
+		graphActionsDuration.WithLabelValues("DeletePod").Observe(time.Since(start).Seconds())
+	}()
 	g.lock.Lock()
 	defer g.lock.Unlock()
 	g.deleteVertex_locked(podVertexType, namespace, name)
@@ -403,6 +412,10 @@ func (g *Graph) DeletePod(name, namespace string) {
 //
 //   pv -> pvc
 func (g *Graph) AddPV(pv *corev1.PersistentVolume) {
+	start := time.Now()
+	defer func() {
+		graphActionsDuration.WithLabelValues("AddPV").Observe(time.Since(start).Seconds())
+	}()
 	g.lock.Lock()
 	defer g.lock.Unlock()
 
@@ -425,6 +438,10 @@ func (g *Graph) AddPV(pv *corev1.PersistentVolume) {
 	}
 }
 func (g *Graph) DeletePV(name string) {
+	start := time.Now()
+	defer func() {
+		graphActionsDuration.WithLabelValues("DeletePV").Observe(time.Since(start).Seconds())
+	}()
 	g.lock.Lock()
 	defer g.lock.Unlock()
 	g.deleteVertex_locked(pvVertexType, "", name)
@@ -434,6 +451,10 @@ func (g *Graph) DeletePV(name string) {
 //
 //   volume attachment -> node
 func (g *Graph) AddVolumeAttachment(attachmentName, nodeName string) {
+	start := time.Now()
+	defer func() {
+		graphActionsDuration.WithLabelValues("AddVolumeAttachment").Observe(time.Since(start).Seconds())
+	}()
 	g.lock.Lock()
 	defer g.lock.Unlock()
 
@@ -448,6 +469,10 @@ func (g *Graph) AddVolumeAttachment(attachmentName, nodeName string) {
 	}
 }
 func (g *Graph) DeleteVolumeAttachment(name string) {
+	start := time.Now()
+	defer func() {
+		graphActionsDuration.WithLabelValues("DeleteVolumeAttachment").Observe(time.Since(start).Seconds())
+	}()
 	g.lock.Lock()
 	defer g.lock.Unlock()
 	g.deleteVertex_locked(vaVertexType, "", name)
@@ -457,6 +482,10 @@ func (g *Graph) DeleteVolumeAttachment(name string) {
 //
 // configmap -> node
 func (g *Graph) SetNodeConfigMap(nodeName, configMapName, configMapNamespace string) {
+	start := time.Now()
+	defer func() {
+		graphActionsDuration.WithLabelValues("SetNodeConfigMap").Observe(time.Since(start).Seconds())
+	}()
 	g.lock.Lock()
 	defer g.lock.Unlock()
 

plugin/pkg/auth/authorizer/node/graph_populator.go

@@ -18,10 +18,12 @@ package node
 
 import (
 	"fmt"
+
 	"k8s.io/klog/v2"
 
 	corev1 "k8s.io/api/core/v1"
 	storagev1 "k8s.io/api/storage/v1"
+	"k8s.io/apimachinery/pkg/util/wait"
 	utilfeature "k8s.io/apiserver/pkg/util/feature"
 	corev1informers "k8s.io/client-go/informers/core/v1"
 	storageinformers "k8s.io/client-go/informers/storage/v1"
@@ -44,12 +46,15 @@ func AddGraphEventHandlers(
 		graph: graph,
 	}
 
+	var hasSynced []cache.InformerSynced
+
 	if utilfeature.DefaultFeatureGate.Enabled(features.DynamicKubeletConfig) {
 		nodes.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{
 			AddFunc:    g.addNode,
 			UpdateFunc: g.updateNode,
 			DeleteFunc: g.deleteNode,
 		})
+		hasSynced = append(hasSynced, nodes.Informer().HasSynced)
 	}
 
 	pods.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{
@@ -57,18 +62,23 @@ func AddGraphEventHandlers(
 		UpdateFunc: g.updatePod,
 		DeleteFunc: g.deletePod,
 	})
+	hasSynced = append(hasSynced, pods.Informer().HasSynced)
 
 	pvs.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{
 		AddFunc:    g.addPV,
 		UpdateFunc: g.updatePV,
 		DeleteFunc: g.deletePV,
 	})
+	hasSynced = append(hasSynced, pvs.Informer().HasSynced)
 
 	attachments.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{
 		AddFunc:    g.addVolumeAttachment,
 		UpdateFunc: g.updateVolumeAttachment,
 		DeleteFunc: g.deleteVolumeAttachment,
 	})
+	hasSynced = append(hasSynced, attachments.Informer().HasSynced)
+
+	go cache.WaitForNamedCacheSync("node_authorizer", wait.NeverStop, hasSynced...)
 }
 
 func (g *graphPopulator) addNode(obj interface{}) {

plugin/pkg/auth/authorizer/node/metrics.go

@@ -0,0 +1,49 @@
+/*
+Copyright 2020 The Kubernetes Authors.
+
+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 node
+
+import (
+	"sync"
+
+	"k8s.io/component-base/metrics"
+	"k8s.io/component-base/metrics/legacyregistry"
+)
+
+const nodeAuthorizerSubsystem = "node_authorizer"
+
+var (
+	graphActionsDuration = metrics.NewHistogramVec(
+		&metrics.HistogramOpts{
+			Subsystem:      nodeAuthorizerSubsystem,
+			Name:           "graph_actions_duration_seconds",
+			Help:           "Histogram of duration of graph actions in node authorizer.",
+			StabilityLevel: metrics.ALPHA,
+			// Start with 0.1ms with the last bucket being [~200ms, Inf)
+			Buckets: metrics.ExponentialBuckets(0.0001, 2, 12),
+		},
+		[]string{"operation"},
+	)
+)
+
+var registerMetrics sync.Once
+
+// RegisterMetrics registers metrics for node package.
+func RegisterMetrics() {
+	registerMetrics.Do(func() {
+		legacyregistry.MustRegister(graphActionsDuration)
+	})
+}