Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

cmd/vet: time.Since should not be used in defer statement #60048

Closed
devoxel opened this issue May 8, 2023 · 10 comments
Closed

cmd/vet: time.Since should not be used in defer statement #60048

devoxel opened this issue May 8, 2023 · 10 comments
Labels
Analysis Issues related to static analysis (vet, x/tools/go/analysis) FrozenDueToAge Proposal Proposal-Accepted
Milestone

Comments

@devoxel
Copy link
Contributor

devoxel commented May 8, 2023

Background

func main() {
	start := time.Now()
	defer fmt.Println(time.Since(start))
	time.Sleep(1 * time.Second)
}

People unfamiliar to the intricacies of the defer statement might expect that this code will print 1s, but it prints 0s. (See on go playground).

A correct version is:

func main() {
	start := time.Now()
	defer func() { fmt.Println(time.Since(start)) }()
	time.Sleep(1 * time.Second)
}

This is expected behaviour, but seems to be a somewhat common gotcha. I've made the mistake on a few occasions. I did a search with github codesearch and I found several instances where this is happening in public repositories, some examples:

Summary

I can't think of many use-cases where one calls defer f(time.Since(t)) and intends the behaviour to work as it does. I propose that a vet check is added to disallow this case.

I have implemented an analyser that does this already BTW but the guidelines indicate I should open an issue first for discussion.

@gopherbot gopherbot added this to the Proposal milestone May 8, 2023
@adonovan adonovan added the Analysis Issues related to static analysis (vet, x/tools/go/analysis) label May 8, 2023
@ianlancetaylor ianlancetaylor moved this to Incoming in Proposals May 9, 2023
@adonovan
Copy link
Member

A quick search for defer\ [^{]*time.Since in Google's corpus turned up about 70 hits nearly all of which look wrong. Typically something like:

  defer recordLatency(time.Since(start))

@rsc
Copy link
Contributor

rsc commented May 24, 2023

I looked into this in the public corpus and found tons of hits for time.Since called as an argument to a deferred call; all of them seemed wrong. Are there other such functions that are worth checking and commonly misused?

@rsc
Copy link
Contributor

rsc commented May 24, 2023

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

@rsc rsc moved this from Incoming to Active in Proposals May 24, 2023
@rsc rsc moved this from Active to Likely Accept in Proposals May 31, 2023
@rsc
Copy link
Contributor

rsc commented May 31, 2023

Based on the discussion above, this proposal seems like a likely accept.
— rsc for the proposal review group

@gopherbot
Copy link
Contributor

Change https://go.dev/cl/499875 mentions this issue: go/analysis/passes/defermistake: add analyser for defer mistake

rski pushed a commit to rski/tools that referenced this issue Jun 5, 2023
This is adding an analysis pass to catch defer statements where people
intend to invoke a defer arguments when the defer is ran; not when it is
first invoked.

In order to acheive this, the current analyasis implementation first uses
the inspect.Preorder tool to look for defer nodes. It then walks the
defer node expression tree. This solution means that we don't catch
function literals, and maybe it's slightly unoptimized because it
doesn't use the Inspect fast node filtering once we find the defer
nodes.

Updates golang/go#60048.

Change-Id: I50ec60c7fc4a5ced858f42cb8db8e9ea37a7038f
@rsc rsc moved this from Likely Accept to Accepted in Proposals Jun 7, 2023
@rsc
Copy link
Contributor

rsc commented Jun 7, 2023

No change in consensus, so accepted. 🎉
This issue now tracks the work of implementing the proposal.
— rsc for the proposal review group

@rsc rsc changed the title proposal: cmd/vet: time.Since should not be used in defer statement cmd/vet: time.Since should not be used in defer statement Jun 7, 2023
@rsc rsc modified the milestones: Proposal, Backlog Jun 7, 2023
gopherbot pushed a commit to golang/tools that referenced this issue Jun 13, 2023
This is adding an analysis pass to catch defer statements where people
intend to invoke a defer arguments when the defer is ran; not when it is
first invoked.

In order to achieve this, the current analyasis implementation first uses
the inspect.Preorder tool to look for defer nodes. It then walks the
defer node expression tree. This solution means that we don't catch
function literals, and maybe it's slightly unoptimized because it
doesn't use the Inspect fast node filtering once we find the defer
nodes.

Updates golang/go#60048.

Change-Id: I50ec60c7fc4a5ced858f42cb8db8e9ea37a7038f
Reviewed-on: https://go-review.googlesource.com/c/tools/+/499875
TryBot-Bypass: Alan Donovan <adonovan@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
Reviewed-by: Robert Findley <rfindley@google.com>
Auto-Submit: Alan Donovan <adonovan@google.com>
gopls-CI: kokoro <noreply+kokoro@google.com>
Run-TryBot: Alan Donovan <adonovan@google.com>
@gopherbot
Copy link
Contributor

Change https://go.dev/cl/502975 mentions this issue: gopls/internal/lsp/source: enable new defers analyzer

gopherbot pushed a commit to golang/tools that referenced this issue Aug 7, 2023
This change enables the new defers analyzer in gopls.
It also adds it to the vet compatibility test.
A follow-up change will add it to vet itself.

Also, remove stray backquote in doc comment.

Updates golang/go#60048

Change-Id: I42f09bb79fcbe4e48593dd32fd066ddd39b9626f
Reviewed-on: https://go-review.googlesource.com/c/tools/+/502975
Run-TryBot: Alan Donovan <adonovan@google.com>
Auto-Submit: Alan Donovan <adonovan@google.com>
Reviewed-by: Robert Findley <rfindley@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
@devoxel
Copy link
Contributor Author

devoxel commented Sep 7, 2023

Hey this is has been in gopls for a month now, @alandonovan should I open a change adding this to vet?

@adonovan
Copy link
Member

adonovan commented Sep 7, 2023

Hey this is has been in gopls for a month now, @alandonovan should I open a change adding this to vet?

Yes, that would be great. Thanks!

@gopherbot
Copy link
Contributor

Change https://go.dev/cl/527095 mentions this issue: cmd/vet: add defers analysis pass

sluongng added a commit to buildbuddy-io/buildbuddy that referenced this issue Mar 22, 2024
Remove usage of `vet = True` in nogo definition. It's simply a shortcut
attribute to appends some additional analyzers to the nogo binary.

Instead, run `go tool vet help` and copy all listed analyzers in the doc
to our analyzer. This list is more up-to-date than the one in current
rules_go.

Fix 2 vet issues found with new analyzers added:

- Misuse of unbuffered os.Signal channel as argument to signal.Notify
  The channel should be buffered with minimal size of 1.

- time.Since should not be used in defer statement
  See golang/go#60048 for more information
swetharepakula added a commit to swetharepakula/ingress-gce that referenced this issue Jun 26, 2024
 * Fix how time.Since should be used with defer as described in
   golang/go#60048
 * Previously time.Since(start) is evaluated immediately when the defer
   is defined which means the latency recorded is always 0 seconds. By
   moving the time.Since into a function, it does not get evaluated
   until the function is called which properly times the processing
   latency.
swetharepakula added a commit to swetharepakula/ingress-gce that referenced this issue Jun 26, 2024
 * Fix how time.Since should be used with defer as described in
   golang/go#60048
 * Previously time.Since(start) is evaluated immediately when the defer
   is defined which means the latency recorded is always 0 seconds. By
   moving the time.Since into a function, it does not get evaluated
   until the function is called which properly times the processing
   latency.
druzn3k added a commit to druzn3k/immudb that referenced this issue Aug 20, 2024
This commit fixes the complaining from `go vet` about the deferring of
`time.Since`. This can cause wrong time evaluation of the elapsed time.
This impact only the debug level, but still it should be addressed.

ref: golang/go#60048
druzn3k added a commit to druzn3k/immudb that referenced this issue Aug 20, 2024
This commit fixes the complaining from `go vet` about the deferring of
`time.Since`. This can cause wrong time evaluation of the elapsed time.
This impact only the debug level, but still it should be addressed.

ref: golang/go#60048

Signed-off-by: Maurizio Del Corno <druznek@gmail.com>
druzn3k added a commit to druzn3k/immudb that referenced this issue Aug 21, 2024
This commit fixes the complaining from `go vet` about the deferring of
`time.Since`. This can cause wrong time evaluation of the elapsed time.
This impact only the debug level, but still it should be addressed.

To make the code a little bit more readable, I wrote a method on the
`immuClient` instance with the signature `debugElapsedTime(method
string, start time.Time)`.

ref: golang/go#60048

Signed-off-by: Maurizio Del Corno <druznek@gmail.com>
druzn3k added a commit to druzn3k/immudb that referenced this issue Aug 21, 2024
This commit fixes the complaining from `go vet` about the deferring of
`time.Since`. This can cause wrong time evaluation of the elapsed time.
This impact only the debug level, but still it should be addressed.

To make the code a little bit more readable, I wrote a method on the
`immuClient` instance with the signature `debugElapsedTime(method
string, start time.Time)`.

ref: golang/go#60048

Signed-off-by: Maurizio Del Corno <druznek@gmail.com>
ostafen pushed a commit to codenotary/immudb that referenced this issue Aug 21, 2024
This commit fixes the complaining from `go vet` about the deferring of
`time.Since`. This can cause wrong time evaluation of the elapsed time.
This impact only the debug level, but still it should be addressed.

To make the code a little bit more readable, I wrote a method on the
`immuClient` instance with the signature `debugElapsedTime(method
string, start time.Time)`.

ref: golang/go#60048

Signed-off-by: Maurizio Del Corno <druznek@gmail.com>
@golang golang locked and limited conversation to collaborators Sep 24, 2024
@aclements aclements removed this from Proposals Sep 25, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Analysis Issues related to static analysis (vet, x/tools/go/analysis) FrozenDueToAge Proposal Proposal-Accepted
Projects
None yet
Development

No branches or pull requests

4 participants