pkg/injector: Add webhook time tracking facility #1852

eduser25 · 2020-10-15T20:00:04Z

Adding a small piece to help track time spent by individual routines
handling webhooks.

It parses the timeout value from the webhook call, and based on some
static thresholds will log differently depending on how much time is
taking vs. the timeout value given by the url.

Affected area:

Control Plane [X]
Performance [X]
Does this change contain code from or inspired by another project? If so, did you notify the maintainers and provide attribution?
No

pkg/injector/errors.go

eduser25 · 2020-10-15T20:04:01Z

log example:

{"level":"debug","component":"sidecar-injector","time":"2020-10-15T02:55:38Z","file":"webhook.go:166","message":"Mutate Webhook for pod server/server took 1.841792726s time to execute (0.06 of it's timeout, 30s)"}

codecov-io · 2020-10-15T20:08:32Z

Codecov Report

Merging #1852 into main will decrease coverage by 0.36%.
The diff coverage is 28.00%.

@@            Coverage Diff             @@
##             main    #1852      +/-   ##
==========================================
- Coverage   59.19%   58.83%   -0.37%     
==========================================
  Files         125      126       +1     
  Lines        5171     5196      +25     
==========================================
- Hits         3061     3057       -4     
- Misses       2107     2135      +28     
- Partials        3        4       +1

Impacted Files	Coverage Δ
pkg/injector/profiling.go	`20.00% <20.00%> (ø)`
pkg/injector/webhook.go	`73.11% <60.00%> (-0.37%)`	⬇️
...ertificate/providers/tresor/certificate_manager.go	`64.04% <0.00%> (-12.36%)`	⬇️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 622a23e...cedd099. Read the comment docs.

shashankram

Thanks for the change.

I'd like to see a more concrete description of the time tracking facility being introduced since its hard to reason from the code exactly what's going on.

pkg/injector/webhook.go

pkg/injector/webhook_test.go

pkg/injector/webhook.go

eduser25 · 2020-10-15T20:48:05Z

its hard to reason from the code exactly what's going on.

Let's see if I can help.

on mutate handler, we read timeout from the url.
if reading the url succeeded, we defer a time-tracking function that will run when mutateHandler is done and will print how much time we spent in the handler itself.

Most of the ... ugly code is getting the podname. We could obviate this part of the code and it'd look way cleaner, but the log message would be less relevant without knowing which resource came triggered the webhook.

pkg/injector/webhook.go

shashankram · 2020-10-15T21:01:33Z

pkg/injector/webhook.go

+	timeoutValue, err := readTimeout(req)
+	if err != nil {
+		log.Error().Msgf("Could not read timeout from request url: %v", err)


Under what circumstances will this error occur? Is there a scenario where the request will not have a timeout?

This one I do not know. I'm being cautions and just avoiding the call If it can't read it.

pkg/injector/webhook.go

shashankram · 2020-10-15T21:06:45Z

pkg/injector/webhook.go

+		// Error logging when going beyond timeout value to process a webhook
+		logEv = log.Error()
+	}
+	logEv.Msgf("Mutate Webhook for %s took %v to execute (%.2f of it's timeout, %v)",


Why are these custom logs necessary? K8s events should be logging timeouts anyway.

synced offlined. We agreed timeout messaging/events are going to be seen in K8s events to begin with, so arguably we do not need to strictly log error on those from this side of the fence.
We however might want to keep at least debug log for this messages to debug/profile timings without requiring to plug in pprof in the picture.

pkg/injector/webhook.go

shashankram · 2020-10-15T21:09:27Z

its hard to reason from the code exactly what's going on.

Let's see if I can help.

on mutate handler, we read timeout from the url.

if reading the url succeeded, we defer a time-tracking function that will run when mutateHandler is done and will print how much time we spent in the handler itself.

Most of the ... ugly code is getting the podname. We could obviate this part of the code and it'd look way cleaner, but the log message would be less relevant without knowing which resource came triggered the webhook.

I am wondering why this tracking facility is even required. The PR does not describe why this functionality is required.
When the webhook experiences a timeout, k8s API server will log an event regarding the timeout, so why is this even needed.

draychev

This seems very useful!

shashankram · 2020-10-22T18:06:07Z

@eduser25 are you planning to iterate on the changes we discussed and agreed upon or do you prefer to merge this as is?

#1852 (comment)

pkg/injector/profiling.go

Adding a small piece to help track time spent by individual routines handling webhooks. It parses the timeout value from the webhook call, and based on some static thresholds will log differently depending on how much time is taking vs. the timeout value given by the url.

* pkg/injector: Add webhook time tracking facility Adding a small piece to help track time spent by individual routines handling webhooks. It parses the timeout value from the webhook call, and based on some static thresholds will log differently depending on how much time is taking vs. the timeout value given by the url. * Update pkg/injector/errors.go * Addressing CR * Simplifying code * Simplifying code * Fix webhookTimeoutStr * Add tests for TimeoutParser and WebhokLogging

eduser25 requested a review from a team as a code owner October 15, 2020 20:00

eduser25 commented Oct 15, 2020

View reviewed changes

pkg/injector/errors.go Outdated Show resolved Hide resolved

shashankram previously requested changes Oct 15, 2020

View reviewed changes

shashankram reviewed Oct 15, 2020

View reviewed changes

eduser25 force-pushed the webhook-time branch from e88518e to 165b878 Compare October 15, 2020 21:49

draychev previously approved these changes Oct 22, 2020

View reviewed changes

shashankram self-requested a review October 22, 2020 18:31

shashankram previously approved these changes Oct 22, 2020

View reviewed changes

shashankram reviewed Oct 22, 2020

View reviewed changes

pkg/injector/profiling.go Show resolved Hide resolved

eduser25 added 7 commits October 22, 2020 15:12

Update pkg/injector/errors.go

84c8175

Addressing CR

32f430d

Simplifying code

551794a

Simplifying code

edfeefd

Fix webhookTimeoutStr

5cddf41

Add tests for TimeoutParser and WebhokLogging

2bf7427

eduser25 dismissed stale reviews from shashankram and draychev via 2bf7427 October 23, 2020 00:58

eduser25 force-pushed the webhook-time branch from d00c37c to 2bf7427 Compare October 23, 2020 00:58

shashankram approved these changes Oct 23, 2020

View reviewed changes

snehachhabria approved these changes Oct 23, 2020

View reviewed changes

eduser25 merged commit d3ade1e into openservicemesh:main Oct 23, 2020

eduser25 deleted the webhook-time branch October 23, 2020 19:43

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

pkg/injector: Add webhook time tracking facility #1852

pkg/injector: Add webhook time tracking facility #1852

eduser25 commented Oct 15, 2020

eduser25 commented Oct 15, 2020

codecov-io commented Oct 15, 2020 •

edited

Loading

shashankram left a comment

eduser25 commented Oct 15, 2020 •

edited

Loading

shashankram Oct 15, 2020

eduser25 Oct 15, 2020

shashankram Oct 15, 2020

eduser25 Oct 15, 2020

shashankram commented Oct 15, 2020

draychev left a comment

shashankram commented Oct 22, 2020

pkg/injector: Add webhook time tracking facility #1852

pkg/injector: Add webhook time tracking facility #1852

Conversation

eduser25 commented Oct 15, 2020

eduser25 commented Oct 15, 2020

codecov-io commented Oct 15, 2020 • edited Loading

Codecov Report

shashankram left a comment

Choose a reason for hiding this comment

eduser25 commented Oct 15, 2020 • edited Loading

shashankram Oct 15, 2020

Choose a reason for hiding this comment

eduser25 Oct 15, 2020

Choose a reason for hiding this comment

shashankram Oct 15, 2020

Choose a reason for hiding this comment

eduser25 Oct 15, 2020

Choose a reason for hiding this comment

shashankram commented Oct 15, 2020

draychev left a comment

Choose a reason for hiding this comment

shashankram commented Oct 22, 2020

codecov-io commented Oct 15, 2020 •

edited

Loading

eduser25 commented Oct 15, 2020 •

edited

Loading