add a metric that can be used to notice stuck worker threads

pkg/util/workqueue/prometheus/prometheus.go

@@ -71,6 +71,30 @@ func (prometheusMetricsProvider) NewWorkDurationMetric(name string) workqueue.Su
 	return workDuration
 }
 
+func (prometheusMetricsProvider) NewUnfinishedWorkSecondsMetric(name string) workqueue.SettableGaugeMetric {
+	unfinished := prometheus.NewGauge(prometheus.GaugeOpts{
+		Subsystem: name,
+		Name:      "unfinished_work_seconds",
+		Help: "How many seconds of work " + name + " has done that " +
+			"is in progress and hasn't been observed by work_duration. Large " +
+			"values indicate stuck threads. One can deduce the number of stuck " +
+			"threads by observing the rate at which this increases.",
+	})
+	prometheus.Register(unfinished)
+	return unfinished
+}
+
+func (prometheusMetricsProvider) NewLongestRunningProcessorMicrosecondsMetric(name string) workqueue.SettableGaugeMetric {
+	unfinished := prometheus.NewGauge(prometheus.GaugeOpts{
+		Subsystem: name,
+		Name:      "longest_running_procesor_microseconds",
+		Help: "How many microseconds has the longest running " +
+			"processor for " + name + " been running.",
+	})
+	prometheus.Register(unfinished)
+	return unfinished
+}
+
 func (prometheusMetricsProvider) NewRetriesMetric(name string) workqueue.CounterMetric {
 	retries := prometheus.NewCounter(prometheus.CounterOpts{
 		Subsystem: name,

staging/src/k8s.io/client-go/util/workqueue/BUILD

@@ -11,6 +11,7 @@ go_test(
     srcs = [
         "default_rate_limiters_test.go",
         "delaying_queue_test.go",
+        "metrics_test.go",
         "queue_test.go",
         "rate_limitting_queue_test.go",
     ],

staging/src/k8s.io/client-go/util/workqueue/metrics.go

@@ -19,6 +19,8 @@ package workqueue
 import (
 	"sync"
 	"time"
+
+	"k8s.io/apimachinery/pkg/util/clock"
 )
 
 // This file provides abstractions for setting the provider (e.g., prometheus)
@@ -28,6 +30,7 @@ type queueMetrics interface {
 	add(item t)
 	get(item t)
 	done(item t)
+	updateUnfinishedWork()
 }
 
 // GaugeMetric represents a single numerical value that can arbitrarily go up
@@ -37,6 +40,12 @@ type GaugeMetric interface {
 	Dec()
 }
 
+// SettableGaugeMetric represents a single numerical value that can arbitrarily go up
+// and down. (Separate from GaugeMetric to preserve backwards compatibility.)
+type SettableGaugeMetric interface {
+	Set(float64)
+}
+
 // CounterMetric represents a single numerical value that only ever
 // goes up.
 type CounterMetric interface {
@@ -52,9 +61,13 @@ type noopMetric struct{}
 
 func (noopMetric) Inc()            {}
 func (noopMetric) Dec()            {}
+func (noopMetric) Set(float64)     {}
 func (noopMetric) Observe(float64) {}
 
+// defaultQueueMetrics expects the caller to lock before setting any metrics.
 type defaultQueueMetrics struct {
+	clock clock.Clock
+
 	// current depth of a workqueue
 	depth GaugeMetric
 	// total number of adds handled by a workqueue
@@ -65,6 +78,10 @@ type defaultQueueMetrics struct {
 	workDuration         SummaryMetric
 	addTimes             map[t]time.Time
 	processingStartTimes map[t]time.Time
+
+	// how long have current threads been working?
+	unfinishedWorkSeconds   SettableGaugeMetric
+	longestRunningProcessor SettableGaugeMetric
 }
 
 func (m *defaultQueueMetrics) add(item t) {
@@ -75,7 +92,7 @@ func (m *defaultQueueMetrics) add(item t) {
 	m.adds.Inc()
 	m.depth.Inc()
 	if _, exists := m.addTimes[item]; !exists {
-		m.addTimes[item] = time.Now()
+		m.addTimes[item] = m.clock.Now()
 	}
 }
 
@@ -85,9 +102,9 @@ func (m *defaultQueueMetrics) get(item t) {
 	}
 
 	m.depth.Dec()
-	m.processingStartTimes[item] = time.Now()
+	m.processingStartTimes[item] = m.clock.Now()
 	if startTime, exists := m.addTimes[item]; exists {
-		m.latency.Observe(sinceInMicroseconds(startTime))
+		m.latency.Observe(m.sinceInMicroseconds(startTime))
 		delete(m.addTimes, item)
 	}
 }
@@ -98,14 +115,39 @@ func (m *defaultQueueMetrics) done(item t) {
 	}
 
 	if startTime, exists := m.processingStartTimes[item]; exists {
-		m.workDuration.Observe(sinceInMicroseconds(startTime))
+		m.workDuration.Observe(m.sinceInMicroseconds(startTime))
 		delete(m.processingStartTimes, item)
 	}
 }
 
+func (m *defaultQueueMetrics) updateUnfinishedWork() {
+	// Note that a summary metric would be better for this, but prometheus
+	// doesn't seem to have non-hacky ways to reset the summary metrics.
+	var total float64
+	var oldest float64
+	for _, t := range m.processingStartTimes {
+		age := m.sinceInMicroseconds(t)
+		total += age
+		if age > oldest {
+			oldest = age
+		}
+	}
+	// Convert to seconds; microseconds is unhelpfully granular for this.
+	total /= 1000000
+	m.unfinishedWorkSeconds.Set(total)
+	m.longestRunningProcessor.Set(oldest) // in microseconds.
+}
+
+type noMetrics struct{}
+
+func (noMetrics) add(item t)            {}
+func (noMetrics) get(item t)            {}
+func (noMetrics) done(item t)           {}
+func (noMetrics) updateUnfinishedWork() {}
+
 // Gets the time since the specified start in microseconds.
-func sinceInMicroseconds(start time.Time) float64 {
-	return float64(time.Since(start).Nanoseconds() / time.Microsecond.Nanoseconds())
+func (m *defaultQueueMetrics) sinceInMicroseconds(start time.Time) float64 {
+	return float64(m.clock.Since(start).Nanoseconds() / time.Microsecond.Nanoseconds())
 }
 
 type retryMetrics interface {
@@ -130,6 +172,8 @@ type MetricsProvider interface {
 	NewAddsMetric(name string) CounterMetric
 	NewLatencyMetric(name string) SummaryMetric
 	NewWorkDurationMetric(name string) SummaryMetric
+	NewUnfinishedWorkSecondsMetric(name string) SettableGaugeMetric
+	NewLongestRunningProcessorMicrosecondsMetric(name string) SettableGaugeMetric
 	NewRetriesMetric(name string) CounterMetric
 }
 
@@ -151,29 +195,49 @@ func (_ noopMetricsProvider) NewWorkDurationMetric(name string) SummaryMetric {
 	return noopMetric{}
 }
 
+func (_ noopMetricsProvider) NewUnfinishedWorkSecondsMetric(name string) SettableGaugeMetric {
+	return noopMetric{}
+}
+
+func (_ noopMetricsProvider) NewLongestRunningProcessorMicrosecondsMetric(name string) SettableGaugeMetric {
+	return noopMetric{}
+}
+
 func (_ noopMetricsProvider) NewRetriesMetric(name string) CounterMetric {
 	return noopMetric{}
 }
 
-var metricsFactory = struct {
-	metricsProvider MetricsProvider
-	setProviders    sync.Once
-}{
+var globalMetricsFactory = queueMetricsFactory{
 	metricsProvider: noopMetricsProvider{},
 }
 
-func newQueueMetrics(name string) queueMetrics {
-	var ret *defaultQueueMetrics
-	if len(name) == 0 {
-		return ret
+type queueMetricsFactory struct {
+	metricsProvider MetricsProvider
+
+	onlyOnce sync.Once
+}
+
+func (f *queueMetricsFactory) setProvider(mp MetricsProvider) {
+	f.onlyOnce.Do(func() {
+		f.metricsProvider = mp
+	})
+}
+
+func (f *queueMetricsFactory) newQueueMetrics(name string, clock clock.Clock) queueMetrics {
+	mp := f.metricsProvider
+	if len(name) == 0 || mp == (noopMetricsProvider{}) {
+		return noMetrics{}
 	}
 	return &defaultQueueMetrics{
-		depth:                metricsFactory.metricsProvider.NewDepthMetric(name),
-		adds:                 metricsFactory.metricsProvider.NewAddsMetric(name),
-		latency:              metricsFactory.metricsProvider.NewLatencyMetric(name),
-		workDuration:         metricsFactory.metricsProvider.NewWorkDurationMetric(name),
-		addTimes:             map[t]time.Time{},
-		processingStartTimes: map[t]time.Time{},
+		clock:                   clock,
+		depth:                   mp.NewDepthMetric(name),
+		adds:                    mp.NewAddsMetric(name),
+		latency:                 mp.NewLatencyMetric(name),
+		workDuration:            mp.NewWorkDurationMetric(name),
+		unfinishedWorkSeconds:   mp.NewUnfinishedWorkSecondsMetric(name),
+		longestRunningProcessor: mp.NewLongestRunningProcessorMicrosecondsMetric(name),
+		addTimes:                map[t]time.Time{},
+		processingStartTimes:    map[t]time.Time{},
 	}
 }
 
@@ -183,13 +247,12 @@ func newRetryMetrics(name string) retryMetrics {
 		return ret
 	}
 	return &defaultRetryMetrics{
-		retries: metricsFactory.metricsProvider.NewRetriesMetric(name),
+		retries: globalMetricsFactory.metricsProvider.NewRetriesMetric(name),
 	}
 }
 
-// SetProvider sets the metrics provider of the metricsFactory.
+// SetProvider sets the metrics provider for all subsequently created work
+// queues. Only the first call has an effect.
 func SetProvider(metricsProvider MetricsProvider) {
-	metricsFactory.setProviders.Do(func() {
-		metricsFactory.metricsProvider = metricsProvider
-	})
+	globalMetricsFactory.setProvider(metricsProvider)
 }