logging: better timestamp precision / log when CNI request finishes processing #381
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
The old format - RFC3339 - does not have enough precision - we need to see milliseconds (at least) to understand how long does it take for a CNI ADD / DEL to be processed in the IPAM stage to understand how long does it take for a CNI ADD / DEL to be processed in the IPAM stage. Signed-off-by: Miguel Duarte Barroso <mdbarroso@redhat.com>
We were missing a clear log indicating the IPAM CNI process is finishing. Now, it should be possible to understand how long a request takes from the logs. Signed-off-by: Miguel Duarte Barroso <mdbarroso@redhat.com>
maiqueb
changed the title
oshoval
reviewed
Aug 17, 2023
| defer func() { safeCloseKubernetesBackendConnection(ipam) }() | ||
| defer func() { | ||
| safeCloseKubernetesBackendConnection(ipam) | ||
| logging.Debugf("DEL - IPAM plugin finished. Took: %q Config: %+v", time.Since(startTime).String(), *ipamConf) |
There was a problem hiding this comment.
maybe in case of a failure better to change to finished (failed)
so we can filter the failure lines easily when benchmarking ?
unless it is not important because when benchmarking we dont run failures cases
but it is more accurate this way, because it is not finished, but finished with failure
if it is - then also on ADD please
There was a problem hiding this comment.
Yes, there's no point bench marking failed results.
BUT it makes sense to log the result (or a simplified version of it).
I'll act on this.
Comment on lines
+36
to
+39
| defer func() { | ||
| safeCloseKubernetesBackendConnection(ipam) | ||
| logging.Debugf("ADD - IPAM plugin finished. Took: %q Config: %+v", time.Since(startTime).String(), *ipamConf) | ||
| }() |
There was a problem hiding this comment.
Please consider using a function that gets a string, startTime and is reused in both places
as beside ADD / DEL string it is the same
dougbtv
approved these changes
Aug 17, 2023
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
What this PR does / why we need it:
The old format - RFC3339 - does not have enough precision - we need to see milliseconds (at least) to understand how long does it take for a CNI ADD / DEL to be processed in the IPAM stage to understand how long does it take for a CNI ADD / DEL to be processed in the IPAM stage.
A new log in added when the CNI request ( ADD or DELETE) finishes processing. It prints how long it took to process the request.
Which issue(s) this PR fixes (optional, in
fixes #<issue number>(, fixes #<issue_number>, ...)format, will close the issue(s) when PR gets merged):Fixes #
Special notes for your reviewer (optional):
Old format:
New format: