Queue metrics #45734

ra-grover · 2023-06-29T16:24:50Z

Please provide a description of this PR:
The PR adds metrics to the K8s worker queue. The metrics really helped to discover a lock contention issue mentioned in #44985.

The metrics are kept behind the flag, so that they can be enabled explicitly as adding them does result in impacted benchmarks.

istio-policy-bot · 2023-06-29T16:24:53Z

😊 Welcome @ra-grover! This is either your first contribution to the Istio istio repo, or it's been
awhile since you've been here.

You can learn more about the Istio working groups, code of conduct, and contributing guidelines
by referring to Contributing to Istio.

Thanks for contributing!

Courtesy of your friendly welcome wagon.

linux-foundation-easycla · 2023-06-29T16:24:54Z

The committers listed above are authorized under a signed CLA.

✅ login: ra-grover / name: Raghav Grover (aeb7e34, d4f2ca7, 37709e1, d90c137, 5a3df4f, dfee4d7, 4c38572, a0d95cd, 12c4a68, 0f9c5e4, 1797f84, e2e05d4, 39c1d3f, 2d5717e, bdc472c)
✅ login: tehlers320 / name: Timothy Ehlers (728964a)

istio-testing · 2023-06-29T16:25:00Z

Hi @ra-grover. Thanks for your PR.

I'm waiting for a istio member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

howardjohn · 2023-06-29T17:30:42Z

/ok-to-test

howardjohn

Few minor nits

WDYT @ramaraochavali ?

howardjohn · 2023-06-29T17:31:04Z

pkg/queue/instance.go

@@ -46,14 +47,16 @@ type Instance interface {

 type queueImpl struct {
 	delay     time.Duration
-	tasks     []Task
+	tasks     []*Task


Do we need a pointer to the Task? Task is already a function which is basically a pointer

I was not able to use Task as a key to a map, keys have to be comparable. That map is being used to maintain the add times and processing times. Thats why I used a pointer to it.

I think this can be simplified by not storing a map at all. Or maybe getting rid of metrics entirely. Something like this:

diff --git a/pkg/queue/instance.go b/pkg/queue/instance.go index ea29930966..10854e6824 100644 --- a/pkg/queue/instance.go +++ b/pkg/queue/instance.go @@ -47,7 +47,7 @@ type Instance interface { type queueImpl struct { delay time.Duration - tasks []*Task + tasks []queueTask cond *sync.Cond closing bool closed chan struct{} @@ -70,7 +70,7 @@ func NewQueueWithID(errorDelay time.Duration, name string) Instance { } return &queueImpl{ delay: errorDelay, - tasks: make([]*Task, 0), + tasks: make([]queueTask, 0), closing: false, closed: make(chan struct{}), closeOnce: &sync.Once{}, @@ -81,11 +81,17 @@ func NewQueueWithID(errorDelay time.Duration, name string) Instance { } } +type queueTask struct { + task Task + enqueueTime time.Time + startTime time.Time +} + func (q *queueImpl) Push(item Task) { q.cond.L.Lock() defer q.cond.L.Unlock() if !q.closing { - q.tasks = append(q.tasks, &item) + q.tasks = append(q.tasks, queueTask{task: item, enqueueTime: time.Now()}) if q.metrics != nil { q.metrics.add(&item) } @@ -100,7 +106,7 @@ func (q *queueImpl) Closed() <-chan struct{} { // get blocks until it can return a task to be processed. If shutdown = true, // the processing go routine should stop. -func (q *queueImpl) get() (task *Task, shutdown bool) { +func (q *queueImpl) get() (task queueTask, shutdown bool) { q.cond.L.Lock() defer q.cond.L.Unlock() // wait for closing to be set, or a task to be pushed @@ -110,15 +116,15 @@ func (q *queueImpl) get() (task *Task, shutdown bool) { if q.closing && len(q.tasks) == 0 { // We must be shutting down. - return nil, true + return queueTask{}, true } task = q.tasks[0] + task.startTime = time.Now() // Slicing will not free the underlying elements of the array, so explicitly clear them out here - q.tasks[0] = nil + q.tasks[0] = queueTask{} q.tasks = q.tasks[1:] - if q.metrics != nil { - q.metrics.get(task) - } + + q.metrics.depth.RecordInt(int64(len(q.tasks))) return task, false } @@ -131,16 +137,14 @@ func (q *queueImpl) processNextItem() bool { } // Run the task. - if err := (*task)(); err != nil { + if err := task.task(); err != nil { delay := q.delay log.Infof("Work item handle failed (%v), retry after delay %v", err, delay) time.AfterFunc(delay, func() { - q.Push(*task) + q.Push(task.task) }) } - if q.metrics != nil { - q.metrics.done(task) - } + q.metrics.workDuration.Record(time.Since(task.startTime).Seconds()) return true }

With metrics we are basically keeping all the same info twice. This may be higher cost and easy to make mistakes where they fall out of sync. Instead we can just pass around the timings? WDYT?

Ive been following along on this a bit. I made a PR for some benchmarks. Basically the existing benchmark doesn't work well anymore with this change because of the way its setup.

It makes a new queue over and over again which isnt really what we want to test

for n := 0; n < b.N; n++ { q := NewQueue(1 * time.Microsecond)

ra-grover#1

go test -bench=. -count 1 -benchmem 2023-07-06T21:53:46.190758Z info Work item handle failed (fake error), retry after delay 1µs goos: darwin goarch: arm64 pkg: istio.io/istio/pkg/queue BenchmarkQueue-10 766 1366433 ns/op 630649 B/op 18114 allocs/op BenchmarkMetricsQueue-10 685503 1694 ns/op 560 B/op 19 allocs/op BenchmarkMetricsQueueDisabled-10 2983182 405.9 ns/op 48 B/op 4 allocs/op BenchmarkMetricsQueueAdd-10 4464358 267.9 ns/op 106 B/op 3 allocs/op BenchmarkMetricsQueueInc-10 4663022 257.1 ns/op 74 B/op 2 allocs/op BenchmarkMetricsQueueRec-10 4460540 268.8 ns/op 106 B/op 3 allocs/op BenchmarkMetricsQueueSinceInSeconds-10 36536446 32.18 ns/op 0 B/op 0 allocs/op BenchmarkMetricsQueueGet-10 1609574 753.7 ns/op 320 B/op 11 allocs/op PASS ok istio.io/istio/pkg/queue 12.103s

I'm not sure how much value the others are but these 2 show the real impact of this change and would love to see how much impact taking the mapping out has.

BenchmarkMetricsQueue-10 685503 1694 ns/op 560 B/op 19 allocs/op BenchmarkMetricsQueueDisabled-10 2983182 405.9 ns/op 48 B/op 4 allocs/op

pkg/queue/instance.go

pilot/pkg/features/pilot.go

ra-grover · 2023-06-30T14:05:51Z

/test lint

ramaraochavali · 2023-07-01T08:51:09Z

Sure makes sense

howardjohn · 2023-07-06T00:10:43Z

pkg/queue/instance.go

 		})
 	}
+	if q.metrics != nil {
+		q.metrics.done(task)


we probably should do this even in event of an error

Sure, I can do that.

Sorry, if I am missing something, but if there is an error it will be recorded in the same flow as there is no early return in case of error and time.AfterFunc is non-blocking.

howardjohn · 2023-07-06T00:12:20Z

pkg/queue/instance.go

@@ -46,14 +47,16 @@ type Instance interface {

 type queueImpl struct {
 	delay     time.Duration
-	tasks     []Task
+	tasks     []*Task


I think this can be simplified by not storing a map at all. Or maybe getting rid of metrics entirely. Something like this:

diff --git a/pkg/queue/instance.go b/pkg/queue/instance.go index ea29930966..10854e6824 100644 --- a/pkg/queue/instance.go +++ b/pkg/queue/instance.go @@ -47,7 +47,7 @@ type Instance interface { type queueImpl struct { delay time.Duration - tasks []*Task + tasks []queueTask cond *sync.Cond closing bool closed chan struct{} @@ -70,7 +70,7 @@ func NewQueueWithID(errorDelay time.Duration, name string) Instance { } return &queueImpl{ delay: errorDelay, - tasks: make([]*Task, 0), + tasks: make([]queueTask, 0), closing: false, closed: make(chan struct{}), closeOnce: &sync.Once{}, @@ -81,11 +81,17 @@ func NewQueueWithID(errorDelay time.Duration, name string) Instance { } } +type queueTask struct { + task Task + enqueueTime time.Time + startTime time.Time +} + func (q *queueImpl) Push(item Task) { q.cond.L.Lock() defer q.cond.L.Unlock() if !q.closing { - q.tasks = append(q.tasks, &item) + q.tasks = append(q.tasks, queueTask{task: item, enqueueTime: time.Now()}) if q.metrics != nil { q.metrics.add(&item) } @@ -100,7 +106,7 @@ func (q *queueImpl) Closed() <-chan struct{} { // get blocks until it can return a task to be processed. If shutdown = true, // the processing go routine should stop. -func (q *queueImpl) get() (task *Task, shutdown bool) { +func (q *queueImpl) get() (task queueTask, shutdown bool) { q.cond.L.Lock() defer q.cond.L.Unlock() // wait for closing to be set, or a task to be pushed @@ -110,15 +116,15 @@ func (q *queueImpl) get() (task *Task, shutdown bool) { if q.closing && len(q.tasks) == 0 { // We must be shutting down. - return nil, true + return queueTask{}, true } task = q.tasks[0] + task.startTime = time.Now() // Slicing will not free the underlying elements of the array, so explicitly clear them out here - q.tasks[0] = nil + q.tasks[0] = queueTask{} q.tasks = q.tasks[1:] - if q.metrics != nil { - q.metrics.get(task) - } + + q.metrics.depth.RecordInt(int64(len(q.tasks))) return task, false } @@ -131,16 +137,14 @@ func (q *queueImpl) processNextItem() bool { } // Run the task. - if err := (*task)(); err != nil { + if err := task.task(); err != nil { delay := q.delay log.Infof("Work item handle failed (%v), retry after delay %v", err, delay) time.AfterFunc(delay, func() { - q.Push(*task) + q.Push(task.task) }) } - if q.metrics != nil { - q.metrics.done(task) - } + q.metrics.workDuration.Record(time.Since(task.startTime).Seconds()) return true }

With metrics we are basically keeping all the same info twice. This may be higher cost and easy to make mistakes where they fall out of sync. Instead we can just pass around the timings? WDYT?

ra-grover · 2023-07-06T17:02:22Z

This may be higher cost and easy to make mistakes where they fall out of sync. Instead we can just pass around the timings? WDYT?

Thanks for suggesting, We are doing almost similar at Expedia, but we have modified the interface to supply the startTime and the type of the event from the source. The type being the endpoint, pods, service etc, so that we can add labels to metrics.
But yeah I like it, let me check if it gives better benchmarks, then we should be good to go with this approach.

tehlers320 · 2023-07-07T19:49:31Z

This may be higher cost and easy to make mistakes where they fall out of sync. Instead we can just pass around the timings? WDYT?

Thanks for suggesting, We are doing almost similar at Expedia, but we have modified the interface to supply the startTime and the type of the event from the source. The type being the endpoint, pods, service etc, so that we can add labels to metrics. But yeah I like it, let me check if it gives better benchmarks, then we should be good to go with this approach.

I tried the proposed change from @howardjohn

as-is

BenchmarkMetricsQueue-10                  	  685503	      1694 ns/op	     560 B/op	      19 allocs/op
BenchmarkMetricsQueueDisabled-10          	 2983182	       405.9 ns/op	      48 B/op	       4 allocs/op

proposed (ignore Disabled, this this change this is just always on and that code needs removal):

BenchmarkMetricsQueue-10                  	  860461	      1437 ns/op	     224 B/op	       7 allocs/op
BenchmarkMetricsQueueDisabled-10          	  833280	      1429 ns/op	     224 B/op	       7 allocs/op

it is better by 12 allocs ~200ns.

Is this what maintainers want, enabled permanently or was the code example just an example and the if blocks were removed just to highlight the idea?

Keeping just this

	if q.metrics != nil {
		q.metrics.workDuration.Record(time.Since(task.startTime).Seconds())
	}

would allow unchanged behavior from today (though i don't know how much 1000ns matters here).

BenchmarkMetricsQueue-10                  	  840907	      1240 ns/op	     224 B/op	       7 allocs/op
BenchmarkMetricsQueueDisabled-10          	 2406261	       492.9 ns/op	      96 B/op	       3 allocs/op

howardjohn · 2023-07-07T20:44:57Z

My diff wasn't meant to be complete just a step in the direction, I think it can be optimized to be zero cost if metrics are disabled still (as you mentioned)

hzxuzhonghu · 2023-07-14T09:43:52Z

pkg/queue/instance.go

 	// Slicing will not free the underlying elements of the array, so explicitly clear them out here
-	q.tasks[0] = nil
+	q.tasks[0] = queueTask{}


It is still holding memory allocated to empty queueTask.

The smooth change would be making use of queueTask pointer type

I thought the same, when was writing. I will convert it to a pointer queue. Thanks for the suggestion!

FWIW this line is still important since it frees the func in the task which may be a closure over some large variables. But a pointer would be 8bytes and queueTask is 56

howardjohn · 2023-07-14T14:55:21Z

pkg/queue/metrics.go

+}
+
+func init() {
+	monitoring.MustRegister(depth, latency, workDuration)


can use monitoring.RegisterIf, this is how we handle other conditional-enabled metrics. It makes the metrics recording ~free.

Then we do not need to handle if metrics != nil everywhere

Sure, I will check

howardjohn · 2023-07-14T14:56:10Z

pkg/queue/instance.go

 	// Slicing will not free the underlying elements of the array, so explicitly clear them out here
-	q.tasks[0] = nil
+	q.tasks[0] = queueTask{}


FWIW this line is still important since it frees the func in the task which may be a closure over some large variables. But a pointer would be 8bytes and queueTask is 56

hzxuzhonghu

LGTM, defer to @howardjohn to take a look at the metric issue

ra-grover · 2023-07-19T16:40:59Z

Apologies, I fixed it on my local and thought I pushed. I will resolve conflicts and make changes as pointed by you to make it pointer queue and monitoring.RegisterIf, today,

ra-grover · 2023-07-20T16:04:35Z

The benchmarks are now comparable for both the scenarios after the improvement in monitoring package (#45341)

BenchmarkMetricsQueue-10                  	 2054424	       582.8 ns/op	     104 B/op	       4 allocs/op
BenchmarkMetricsQueueDisabled-10          	 2063526	       583.8 ns/op	     104 B/op	       4 allocs/op

Let me know if the flag is still needed.

howardjohn · 2023-07-21T15:30:41Z

/retest

ra-grover requested a review from a team as a code owner June 29, 2023 16:24

istio-testing added the size/L Denotes a PR that changes 100-499 lines, ignoring generated files. label Jun 29, 2023

istio-testing added the needs-ok-to-test label Jun 29, 2023

istio-testing added ok-to-test Set this label allow normal testing to take place for a PR not submitted by an Istio org member. and removed needs-ok-to-test labels Jun 29, 2023

howardjohn reviewed Jun 29, 2023

View reviewed changes

howardjohn reviewed Jul 6, 2023

View reviewed changes

zirain mentioned this pull request Jul 6, 2023

Feature: Expose client_go metrics #45845

Closed

hzxuzhonghu reviewed Jul 14, 2023

View reviewed changes

howardjohn reviewed Jul 14, 2023

View reviewed changes

istio-testing added needs-rebase Indicates a PR needs to be rebased before being merged labels Jul 18, 2023

hzxuzhonghu reviewed Jul 19, 2023

View reviewed changes

ra-grover added 7 commits July 20, 2023 11:58

Added metrics to worker queue

aeb7e34

Enable metrics only behind a flag

d4f2ca7

Metrics behind a flag

37709e1

Disabling a test log statement

d90c137

Use .with while initialising

5a3df4f

Review comments and lint fix

dfee4d7

Tests fix, some lint

4c38572

ra-grover and others added 9 commits July 20, 2023 11:58

Lint fix

a0d95cd

Lint fix

12c4a68

Add releaseNotes

0f9c5e4

add benchmarks

728964a

Changed approach to maintain timestamps with objects

1797f84

Lint fix

e2e05d4

Review comments: turned to pointer queue

39c1d3f

Added monitoring.RegisterIf

2d5717e

Optional registration of metrics, new way

bdc472c

ra-grover force-pushed the queue_metrics branch from 89b65a4 to bdc472c Compare July 20, 2023 15:58

istio-testing removed the needs-rebase Indicates a PR needs to be rebased before being merged label Jul 20, 2023

howardjohn approved these changes Jul 20, 2023

View reviewed changes

hzxuzhonghu approved these changes Jul 21, 2023

View reviewed changes

istio-testing merged commit f371c65 into istio:master Jul 21, 2023
26 of 27 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Queue metrics #45734

Queue metrics #45734

ra-grover commented Jun 29, 2023 •

edited by istio-policy-bot

istio-policy-bot commented Jun 29, 2023

linux-foundation-easycla bot commented Jun 29, 2023 •

edited

istio-testing commented Jun 29, 2023

howardjohn commented Jun 29, 2023

howardjohn left a comment

howardjohn Jun 29, 2023

ra-grover Jun 29, 2023 •

edited

howardjohn Jul 6, 2023

tehlers320 Jul 6, 2023

ra-grover commented Jun 30, 2023

ramaraochavali commented Jul 1, 2023

howardjohn Jul 6, 2023

ra-grover Jul 6, 2023

ra-grover Jul 13, 2023 •

edited

howardjohn Jul 6, 2023

ra-grover commented Jul 6, 2023

tehlers320 commented Jul 7, 2023 •

edited

howardjohn commented Jul 7, 2023

hzxuzhonghu Jul 14, 2023

ra-grover Jul 14, 2023

howardjohn Jul 14, 2023

howardjohn Jul 14, 2023

ra-grover Jul 14, 2023

howardjohn Jul 14, 2023

hzxuzhonghu left a comment

ra-grover commented Jul 19, 2023

ra-grover commented Jul 20, 2023

howardjohn commented Jul 21, 2023

Queue metrics #45734

Queue metrics #45734

Conversation

ra-grover commented Jun 29, 2023 • edited by istio-policy-bot

istio-policy-bot commented Jun 29, 2023

linux-foundation-easycla bot commented Jun 29, 2023 • edited

istio-testing commented Jun 29, 2023

howardjohn commented Jun 29, 2023

howardjohn left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ra-grover Jun 29, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ra-grover commented Jun 30, 2023

ramaraochavali commented Jul 1, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ra-grover Jul 13, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ra-grover commented Jul 6, 2023

tehlers320 commented Jul 7, 2023 • edited

howardjohn commented Jul 7, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hzxuzhonghu left a comment

Choose a reason for hiding this comment

ra-grover commented Jul 19, 2023

ra-grover commented Jul 20, 2023

howardjohn commented Jul 21, 2023

ra-grover commented Jun 29, 2023 •

edited by istio-policy-bot

linux-foundation-easycla bot commented Jun 29, 2023 •

edited

ra-grover Jun 29, 2023 •

edited

ra-grover Jul 13, 2023 •

edited

tehlers320 commented Jul 7, 2023 •

edited