Add discovery duration logging #1055

VillePihlava · 2023-02-10T13:00:24Z

This pull request adds logging of discovery durations. There are some optional things mentioned in #899 by @eero-t. I had a quick discussion with @marquiz and if I understood correctly something like what is implemented here could also be useful. Depending on what exactly is wanted, this could close #899. This is related to work done in #1050.

The logging output can look like this:

<output from other sources>
I0213 12:42:32.317317 2204667 nfd-worker.go:199] discovery duration for "system" source: 472.156µs
I0213 12:42:32.318310 2204667 usb.go:150] discovered usb features:
I0213 10:51:09.882921 2197292 usb.go:150] <many lines of output>
I0213 12:42:32.318726 2204667 nfd-worker.go:199] discovery duration for "usb" source: 1.397359ms
I0213 12:42:32.318736 2204667 nfd-worker.go:203] feature discovery for 9 sources lasted for: 6s
W0213 12:42:32.318745 2204667 nfd-worker.go:205] feature discovery sources took over half (6s) of sleep interval (10s)
I0213 12:42:32.318755 2204667 nfd-worker.go:561] starting feature discovery...

Fixes #899

netlify · 2023-02-10T13:00:29Z

✅ Deploy Preview for kubernetes-sigs-nfd ready!

Name	Link
🔨 Latest commit	`b1c6b22`
🔍 Latest deploy log	https://app.netlify.com/sites/kubernetes-sigs-nfd/deploys/63ea17be5be97a00096d114b
😎 Deploy Preview	https://deploy-preview-1055--kubernetes-sigs-nfd.netlify.app
📱 Preview on mobile	Toggle QR Code... Use your smartphone camera to open QR code link.

To edit notification comments on pull requests, go to your Netlify site settings.

k8s-ci-robot · 2023-02-10T13:00:34Z

Hi @VillePihlava. Thanks for your PR.

I'm waiting for a kubernetes-sigs 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.

marquiz

Thanks @VillePihlava, this is a nice improvement. The KlogDump prints sources in deterministic order which is nice.

What we'd like is to have similar information for hooks run in getFeaturesFromGooks( in source/loca/local.go) because those are the most likely source of "surprises" (even if they are deprecated). This can be addressed in a separate PR, though

eero-t · 2023-02-10T13:38:44Z

pkg/nfd-worker/nfd-worker.go

 	}
+	utils.KlogDump(3, "discovery durations for feature sources:", "  ", durations)


What's the advantage of using intermediate map & printing things only after whole loop, instead of just printing header before loop, moving Infof() printing after Discover(), and adding time to that log item?

Regarding the deterministic order comment by @marquiz, current Infof() printing within the loop has higher logging priority than this, so it will be printed always when this is, right? I think it will be confusing to have items printed twice, but in different order... IMHO it's better to join the messages.

Yeah, this is a good point 👍

I removed the Infof before Discover and added logging after which includes the duration.

eero-t · 2023-02-10T13:57:02Z

Depending on what exactly is wanted, this could close #899

@VillePihlava While this could be a step into direction requested in #899, it does not yet do any of the suggested 3 items.

#899 requires deducting from the sleep used between discovery rounds, the time already spent on that interval from core.sleepInterval value, so that discoveries actually happen on the specified interval (or using time ticker to handle that, as suggested by @marquiz in #899).

EDIT: I hadn't noticed 2101cb2 going in, which actually adds the ticker usage. That's the PR that should have closed #899, as extra warnings / better logging was optional part of that ticket.

eero-t · 2023-02-10T14:26:46Z

To finish #899 (now that 2101cb2 is merged), this should check (also) the total time used for a discovery round, and e.g. log an error for discovery rounds that exceed sleep interval, and/or a warning if total (+ any individual discoveries?) is (say) >50% of it.

I'm not sure which one is more important; an error telling that discoveries, or discovery interval, is not working, or an early warning of approaching the limit. Because that is easy to fix just by increasing core.sleepInterval, I do not think these messages would need rate-limiting.

VillePihlava · 2023-02-10T14:59:00Z

To finish #899 (now that 2101cb2 is merged), this should check (also) the total time used for a discovery round, and e.g. log an error for discovery rounds that exceed sleep interval, and/or a warning if total (+ any individual discoveries?) is (say) >50% of it.

I'm not sure which one is more important; an error telling that discoveries, or discovery interval, is not working, or an early warning of approaching the limit. Because that is easy to fix just by increasing core.sleepInterval, I do not think these messages would need rate-limiting.

I'll look into this. Also added a link to the other pull request to avoid confusion in the original message.

marquiz · 2023-02-10T15:55:46Z

To finish #899 (now that 2101cb2 is merged), this should check (also) the total time used for a discovery round, and e.g. log an error for discovery rounds that exceed sleep interval, and/or a warning if total (+ any individual discoveries?) is (say) >50% of it.

We could log a warning. I wouldn't tie this to the sleep interval but put some reasonable hard limit, e.g. the discovery really shouldn't take more than 1 or 2 seconds in any scenario, I think. If you put sleep interval to 1 hour and the discovery takes 20 minutes something is really badly wrong (IMHO)

eero-t · 2023-02-10T16:11:58Z

If you put sleep interval to 1 hour and the discovery takes 20 minutes something is really badly wrong (IMHO)

Why? That would be a deliberate user decision. It could just be something naturally slow, but not very taxing on resources (maybe not RFC 2549, but something).

ArangoGutierrez · 2023-02-10T16:32:50Z

If you put sleep interval to 1 hour and the discovery takes 20 minutes something is really badly wrong (IMHO)

Why? That would be a deliberate user decision. It could just be something naturally slow, but not very taxing on resources (maybe not RFC 2549, but something).

I agree with @marquiz , discovery usually takes seconds, we should aim for lowering the foot print of NFD, allowing minutes won't move us in that direction

Aside from that, this PR looks good to me

eero-t · 2023-02-10T16:39:48Z

I agree with @marquiz , discovery usually takes seconds, we should aim for lowering the foot print of NFD, allowing minutes won't move us in that direction

I think short enough default sleepInterval, and giving the warning much earlier (e.g. 10% of interval), would work better than using a fixed time limit for when warning is given.

If user increases the interval from default, he's likely to have a good reason for it.

ArangoGutierrez · 2023-02-10T16:47:17Z

I agree with @marquiz , discovery usually takes seconds, we should aim for lowering the foot print of NFD, allowing minutes won't move us in that direction

I think short enough default sleepInterval, and giving the warning much earlier (e.g. 10% of interval), would work better than using a fixed time limit for when warning is given.

If user increases the interval from default, he's likely to have a good reason for it.

Umm Maybe for custom Hooks, but we are deprecating hooks, if user wants to discover something that they know takes time, is better for them to use a side car that publishes to the NodeFeature CR, than to increasing the discovery time toleration on NFD core

marquiz · 2023-02-10T17:47:46Z

If user increases the interval from default, he's likely to have a good reason for it.

I think the usual reason is something else than preparing for that the nfd-worker is churning feature discovery for ages. As @ArangoGutierrez noted hooks are being deprecated anyway so I wouldn't spend too much time on this. The built-in discovery should be in the order of milliseconds (sub-second anyway) so anything longer than a few seconds is raising concnerns

marquiz

Thanks @VillePihlava, looks good to me.

ping @eero-t

VillePihlava · 2023-02-13T09:03:19Z

The warning is displayed if the duration for all sources exceeds 5 seconds. I updated the initial comment for an example of the output.

ArangoGutierrez

/lgtm
Unhold at will @marquiz
/hold

k8s-ci-robot · 2023-02-13T09:22:56Z

LGTM label has been added.

Git tree hash: 35e9e6348bf33928f53c48a24144b74bb9499179

VillePihlava · 2023-02-13T09:29:58Z

Noticed that the log levels were different, I changed both to 2 now

eero-t · 2023-02-13T09:34:00Z

As @ArangoGutierrez noted hooks are being deprecated anyway so I wouldn't spend too much time on this. The built-in discovery should be in the order of milliseconds (sub-second anyway) so anything longer than a few seconds is raising concnerns

@marquiz unfortunately you both missed the point. If interval is 1 second, doing warning only when discovery actually takes >2 seconds is not really useful. Warning should be logged before the whole interval is used.

eero-t · 2023-02-13T10:01:17Z

pkg/nfd-worker/nfd-worker.go

+	if discoveryDuration > 5*time.Second {
+		klog.Warningf("feature discovery for sources lasted for more than 5s (%v)", discoveryDuration)


Warning at 5s is not useful when the discovery interval is smaller. I would go for something like this (untested!):

Suggested change

if discoveryDuration > 5*time.Second {

klog.Warningf("feature discovery for sources lasted for more than 5s (%v)", discoveryDuration)

if discoveryDuration > core.sleepInterval/2 {

klog.Warningf("Feature discovery sources took over half (%v) of sleep interval (%v)", discoveryDuration, core.sleepInterval)

(Other alternative would be having measurement and warning like this where the sleep is done instead.)

PS. commit message is missing "Fixes:" tag for #899.

@VillePihlava please address, I agree with @eero-t

@eero-t PTAL

This is now changed. A fixes tag is not allowed in the commit message in this repository apparently, the original comment has it

Also added a check to see if the duration is positive (negative durations should not cause a warning)

Good point, looks fine now!

eero-t · 2023-02-13T10:01:43Z

pkg/nfd-worker/nfd-worker.go

+	}
+
+	discoveryDuration := time.Since(discoveryStart)
+	klog.V(2).Infof("feature discovery for sources lasted for: %v", discoveryDuration)


For improved log output amount control, per-source logging could be V(3), and this V(2), with count included to it:

Suggested change

klog.V(2).Infof("feature discovery for sources lasted for: %v", discoveryDuration)

klog.V(2).Infof("feature discovery for %d sources lasted for: %v", len(w.featureSources), discoveryDuration)

(Just a suggestion, feel free to ignore.)

@VillePihlava please address, I agree with @eero-t

@eero-t PTAL

This has now been changed

@eero-t PTAL

Looks fine now!

eero-t · 2023-02-13T11:40:08Z

/lgtm

k8s-ci-robot · 2023-02-13T11:40:11Z

@eero-t: changing LGTM is restricted to collaborators

In response to this:

/lgtm

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.

ArangoGutierrez

/lgtm

k8s-ci-robot · 2023-02-13T11:40:50Z

LGTM label has been added.

Git tree hash: 29770799c7e6c844416c4b5ff46965da637981e0

k8s-ci-robot · 2023-02-13T11:40:51Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: ArangoGutierrez, marquiz, VillePihlava

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:

~~OWNERS~~ [marquiz]

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

marquiz · 2023-02-13T14:14:35Z

Looks like everybody consent on merging
/unhold
/ok-to-test

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Feb 10, 2023

k8s-ci-robot requested review from ArangoGutierrez and kad February 10, 2023 13:00

k8s-ci-robot added the size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. label Feb 10, 2023

marquiz approved these changes Feb 10, 2023

View reviewed changes

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Feb 10, 2023

eero-t reviewed Feb 10, 2023

View reviewed changes

VillePihlava force-pushed the discovery-duration-logging branch from 3d0fc26 to 0019029 Compare February 13, 2023 08:44

k8s-ci-robot added size/S Denotes a PR that changes 10-29 lines, ignoring generated files. and removed size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels Feb 13, 2023

VillePihlava force-pushed the discovery-duration-logging branch from 0019029 to 5d24ecc Compare February 13, 2023 08:50

marquiz approved these changes Feb 13, 2023

View reviewed changes

ArangoGutierrez approved these changes Feb 13, 2023

View reviewed changes

k8s-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Feb 13, 2023

k8s-ci-robot assigned ArangoGutierrez Feb 13, 2023

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Feb 13, 2023

VillePihlava force-pushed the discovery-duration-logging branch from 5d24ecc to e558c89 Compare February 13, 2023 09:28

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Feb 13, 2023

k8s-ci-robot requested a review from ArangoGutierrez February 13, 2023 09:29

eero-t reviewed Feb 13, 2023

View reviewed changes

VillePihlava force-pushed the discovery-duration-logging branch 2 times, most recently from 9e5479b to 714d3d6 Compare February 13, 2023 10:48

k8s-ci-robot added the do-not-merge/invalid-commit-message Indicates that a PR should not merge because it has an invalid commit message. label Feb 13, 2023

VillePihlava force-pushed the discovery-duration-logging branch from 714d3d6 to 52813e9 Compare February 13, 2023 10:49

k8s-ci-robot removed the do-not-merge/invalid-commit-message Indicates that a PR should not merge because it has an invalid commit message. label Feb 13, 2023

Add discovery duration logging.

b1c6b22

VillePihlava force-pushed the discovery-duration-logging branch from 52813e9 to b1c6b22 Compare February 13, 2023 10:58

ArangoGutierrez approved these changes Feb 13, 2023

View reviewed changes

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Feb 13, 2023

k8s-ci-robot merged commit f4c6d59 into kubernetes-sigs:master Feb 13, 2023

marquiz mentioned this pull request Apr 12, 2023

Release v0.13.0 #1068

Closed

24 tasks

		}
		utils.KlogDump(3, "discovery durations for feature sources:", " ", durations)

		if discoveryDuration > 5*time.Second {
		klog.Warningf("feature discovery for sources lasted for more than 5s (%v)", discoveryDuration)

	klog.V(2).Infof("feature discovery for sources lasted for: %v", discoveryDuration)
	klog.V(2).Infof("feature discovery for %d sources lasted for: %v", len(w.featureSources), discoveryDuration)

Add discovery duration logging #1055

Add discovery duration logging #1055

Conversation

VillePihlava commented Feb 10, 2023 • edited Loading

netlify bot commented Feb 10, 2023 • edited Loading

✅ Deploy Preview for kubernetes-sigs-nfd ready!

k8s-ci-robot commented Feb 10, 2023

marquiz left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

eero-t Feb 10, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

eero-t commented Feb 10, 2023 • edited Loading

eero-t commented Feb 10, 2023

VillePihlava commented Feb 10, 2023

marquiz commented Feb 10, 2023

eero-t commented Feb 10, 2023

ArangoGutierrez commented Feb 10, 2023

eero-t commented Feb 10, 2023

ArangoGutierrez commented Feb 10, 2023

marquiz commented Feb 10, 2023

marquiz left a comment

Choose a reason for hiding this comment

VillePihlava commented Feb 13, 2023

ArangoGutierrez left a comment

Choose a reason for hiding this comment

k8s-ci-robot commented Feb 13, 2023

VillePihlava commented Feb 13, 2023

eero-t commented Feb 13, 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

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

eero-t commented Feb 13, 2023

k8s-ci-robot commented Feb 13, 2023

ArangoGutierrez left a comment

Choose a reason for hiding this comment

k8s-ci-robot commented Feb 13, 2023

k8s-ci-robot commented Feb 13, 2023

marquiz commented Feb 13, 2023

VillePihlava commented Feb 10, 2023 •

edited

Loading

netlify bot commented Feb 10, 2023 •

edited

Loading

eero-t Feb 10, 2023 •

edited

Loading

eero-t commented Feb 10, 2023 •

edited

Loading