Allow debugging kubelet image pull times

[alvaroaleman]

This PR adds additional buckets of 60, 300, 600, 900 and 1200 seconds
to the kubelet_runtime_operations_duration_seconds metrics in order to
allow debugging image pull times. Right now the biggest bucket is 10
seconds, which is an ordinary time frame to pull an image, making the
metric useless for the aforementioned usecase.

I wrote this PR while waiting 10 minutes for a 90 MB image to get pulled and I'd like to be able to find out if pulls are always this slow or if there are other factors that impact pull time (time of day, different nodes, ...)

The kubelet_runtime_operations_duration_seconds metric buckets were set to 0.005 0.0125 0.03125 0.078125 0.1953125 0.48828125 1.220703125 3.0517578125 7.62939453125 19.073486328125 47.6837158203125 119.20928955078125 298.0232238769531 and 745.0580596923828 seconds

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

[alvaroaleman]

Test failure is unlikely to be related:
ERROR: An error occurred during the fetch of repository 'debian-iptables-amd64':

/retest

[mrunalp]

We could define a variable for this custom bucket.

[alvaroaleman]

Sure. Where would that variable live, here or in the metrics package?

[tangenti]

The metric is also used for other runtime ops. Would this change add too much cardinality to kubelet_runtime_operations_duration_seconds?

[ruiwen-zhao]

Would it be clearer (and look less arbitrary) if we just use exponential buckets here? i.e.

...
Buckets : metrics.ExponentialBuckets(.005, 2, 18),
...

to make a list of .005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10, 20, 40, 80, 160, 320, 640, 1280

[alvaroaleman]

Yeah, works for me, too, I don't have a very strong opinion on the exact bucket sizes, I only want a set of bigger buckets to exist

[rphillips]

@alvaroaleman: +1 to changing this PR to metrics.ExponentialBuckets(.005, 2, 18)

[alvaroaleman]

updated, ptal

[dashpole]

/assign
/triage accepted

[alvaroaleman]

/retest

[rphillips]

/kind feature
/lgtm

[dashpole]

I think this should produce buckets of

.005, .01, .02, .04, .08, .16, .32, .64, 1.28, 2.56, 5.12, 10.24, 20.48, 40.96, 81.92, 163.84, 327.68, 655.36

not what is listed above. Is that still large enough for your use-case? If you are changing bucket boundaries anyways, should we make the growth factor larger so we don't need to add as many streams?

[alvaroaleman]

not what is listed above. Is that still large enough for your use-case?

Thanks for pointing that out, its not, the issue we are seeing is that this takes more than 15 minutes.

If you are changing bucket boundaries anyways, should we make the growth factor larger so we don't need to add as many streams?

TBH I would actually prefer having it smaller in the upper end (that's why the PR initially proposed 600, 900, 1200). The underlying problem is that this metric is used for both operations that are very quick and some like the pulling that are very slow. WDYT about what I initially proposed, still visible above this comment?

[dashpole]

I suspect you are interested in buckets clustered around ~15 minutes because that is about what your image takes to pull. I prefer exponential buckets because they are equally good for debugging X% deviations from expectation, regardless of what the expected value is.

It's unfortunate that image pulls are included with the other metrics, otherwise i'd say we should remove many of the smaller buckets. Looking at some data I have, it is unusual for image pull to take less than a second. time docker pull busybox takes ~1.3 seconds.

It does look like it is common for stopping a container or sandbox to take longer than 10 seconds. That might just be because some containers don't respond to sig-term... But still, it means additional buckets would likely be useful for other operations.

[alvaroaleman]

I suspect you are interested in buckets clustered around ~15 minutes because that is about what your image takes to pull. I prefer exponential buckets because they are equally good for debugging X% deviations from expectation, regardless of what the expected value is.

hm yeah, to be fair the expectation for pretty much all pulls is low single digit minutes at most so it probably doesn't matter much.
I've updated the PR to use metrics.ExponentialBuckets(.005, 2, 20), is that ok for you?

[alvaroaleman]

The test failures seem to be due to kubernetes/test-infra#19910

[dashpole]

ack
/retest

[alvaroaleman]

merge: 04e3aaea31fc9805aae21daa1b81fad85d3067de - not something we can merge

I have that commit locally and the UI also referenced it: 04e3aae

Rebased in the hope that it will make a difference

[dashpole]

Doubling the number of buckets feels like a lot of additional streams. Does something like (.005, 2.5, 14) seems like a reasonable compromise? That puts the top buckets at ~2, ~5, ~12, ~30 minutes.

[alvaroaleman]

Doubling the number of buckets feels like a lot of additional streams. Does something like (.005, 2.5, 14) seems like a reasonable compromise? That puts the top buckets at ~2, ~5, ~12, ~30 minutes.

sgtm, updated

[dashpole]

/lgtm
/approve

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: alvaroaleman, dashpole, ruiwen-zhao

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• pkg/kubelet/metrics/OWNERS [dashpole]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[alvaroaleman]

Same merge: 04e3aaea31fc9805aae21daa1b81fad85d3067de - not something we can merge issue, could you re-add the lgtm? I just did a no-op ammend to work around it

[dashpole]

/lgtm

[alvaroaleman]

/retest