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

runtime: document finalizer semantics for tiny objects (<16 bytes) #46827

Open
seebs opened this issue Jun 19, 2021 · 29 comments
Open

runtime: document finalizer semantics for tiny objects (<16 bytes) #46827

seebs opened this issue Jun 19, 2021 · 29 comments

Comments

@seebs
Copy link
Contributor

@seebs seebs commented Jun 19, 2021

What version of Go are you using (go version)?

playground (presumably 1.16ish?), also 1.16.5

Does this issue reproduce with the latest release?

I believe so.

What operating system and processor architecture are you using (go env)?

playground or amd64 linux

What did you do?

Original reproducer credit goes to BenLubar in libera.chat #go-nuts. Basically: Set finalizers on every object in a small program, then run runtime.GC several times.

https://play.golang.org/p/kdX7i36g8TD

Uncomment the creation of "x", and use it in some way, and suddenly all six finalizers run. I originally thought this was size-related, and depended on x being the same size as those objects, but it doesn't seem that's the case.

What did you expect to see?

All finalizers.

What did you see instead?

All finalizers but the first one.

Allocating anything else before this makes them all show up. I don't have the tooling handy to tell immediately whether the issue is that the first item isn't getting collected, or that the finalizer for it isn't running, but I'm pretty sure the finalizers should run.

Behavior not affected by moving the allocations into another function or other things like that.

@seankhliao seankhliao changed the title finalizer or GC appears to miss first allocated item or something? runtime: finalizer or GC appears to miss first allocated item Jun 19, 2021
@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jun 19, 2021

This seems like an issue with package log, not the compiler or runtime.

See this variation on your test program: https://play.golang.org/p/e0fNmJ5YOZ7

It uses println and fmt.Println to print the same message, but also has run-time disabled logic for calling log.Println. All of the objects are successfully garbage collected when println and fmt.Println are used, but they're retained when log.Println is also used.

It's also not an escape analysis issue, because we don't currently do any optimizations to detect global variables that are never reassigned.

I would check if package log has any slices where it buffers use data values, and maybe it needs to zero them out after use to avoid retaining objects.

@mdempsky mdempsky changed the title runtime: finalizer or GC appears to miss first allocated item log: printed arguments are sometimes retained and never finalized Jun 19, 2021
@mdempsky mdempsky changed the title log: printed arguments are sometimes retained and never finalized log: Print arguments are sometimes retained and never GC'd/finalized Jun 19, 2021
@andig
Copy link
Contributor

@andig andig commented Jun 19, 2021

It does retain a bytes.Buffer, see #46285

@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jun 19, 2021

@andig Sorry, I don't follow. Package log doesn't use bytes.Buffer, except in its unit tests.

@seankhliao
Copy link
Contributor

@seankhliao seankhliao commented Jun 19, 2021

running with just println and not log.Println or fmt.Println i still see the issue, though the reproducer isn't stable, run multiple times, sometimes it GCs everything and sometimes it misses one usually the first one

@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jun 19, 2021

@seankhliao Thanks, I see that too now. I forgot about the Go playground caching program output.

@mdempsky mdempsky changed the title log: Print arguments are sometimes retained and never GC'd/finalized runtime: finalizers not consistently run Jun 19, 2021
@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jun 19, 2021

Minimized test case: https://play.golang.org/p/SAXVXDVr-Ae

It fails often, but not 100% reliably.

However, it reliably passes if import _ "reflect" is removed or even replaced by blank imports of reflect's imported packages. So it seems like something in package reflect's package initialization is affecting finalization.

@mdempsky mdempsky changed the title runtime: finalizers not consistently run runtime: finalizers not consistently run when package reflect imported Jun 19, 2021
@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jun 19, 2021

This seems like a GC issue, though I can't explain the sensitivity to importing "reflect". /cc @mknyszek

@agnivade
Copy link
Contributor

@agnivade agnivade commented Jun 20, 2021

It fails often, but not 100% reliably.

FWIW, I tried it locally 50 times. It passed always. 🤷‍♂️

@andig
Copy link
Contributor

@andig andig commented Jun 20, 2021

@andig Sorry, I don't follow. Package log doesn't use bytes.Buffer, except in its unit tests.

Sorry for the confusion, replied to quickly. Log has byte slice for assembling log output that it reuses.

@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jun 20, 2021

FWIW, I tried it locally 50 times. It passed always.

Interesting. Can you share any more details about your test system? I just double checked again with my system Go version, and it failed 320 out of 1000 runs.

$ /usr/lib/google-golang/bin/go version
go version go1.16.3 linux/amd64
$ uname -a
Linux mdempsky 5.10.28-1rodete2-amd64 #1 SMP Debian 5.10.28-1rodete2 (2021-05-12) x86_64 GNU/Linux

Sorry for the confusion, replied to quickly. Log has byte slice for assembling log output that it reuses.

Byte slices don't have pointers. Something would have to be really, really broken for a byte slice to prevent other objects from being garbage collected.

Anyway, package log appears to have been a red herring. This issue can be reproduced without it.

@agnivade
Copy link
Contributor

@agnivade agnivade commented Jun 20, 2021

13:37:03-~/play$gotip version
go version devel go1.17-b73cc4b02b Sat Jun 19 00:46:21 2021 +0000 linux/amd64
13:37:07-~/play$uname -a
Linux agniva-x1 5.4.0-66-generic #74-Ubuntu SMP Wed Jan 27 22:54:38 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jun 20, 2021

@agnivade Thanks. I just tried with my Go 1.17 branch checkout, and it's reliably passing for me too. So maybe we independently fixed this issue for Go 1.17 already. (My Go 1.17 checkout was in the middle of a messy rebase earlier, so I didn't trust it for testing.)

If anyone has time/interest, it would great if someone could confirm that the test program fails for them with Go 1.16, and maybe do a bisect to identify what CL fixed it.

@zephyrtronium
Copy link
Contributor

@zephyrtronium zephyrtronium commented Jun 20, 2021

On 1.16.4 linux/amd64, I see ~30% failures with the original reproducer, but never with #46827 (comment):

zephyr@brandenbedoingthelinux:~$ cat ./finalizer.go 
package main

import (
	"runtime"

	_ "reflect"
)

func main() {
	done := make(chan struct{})

	var r int
	runtime.SetFinalizer(&r, func(*int) {
		close(done)
	})

	for try := 0; try < 10; try++ {
		select {
		case <-done:
			return
		default:
			runtime.GC()
		}
	}

	panic("did not finalize")
}

zephyr@brandenbedoingthelinux:~$ for i in {1..1000}; do go run ./finalizer.go; done
zephyr@brandenbedoingthelinux:~$ go version
go version go1.16.4 linux/amd64
zephyr@brandenbedoingthelinux:~$ uname -a
Linux brandenbedoingthelinux 5.11.0-7614-generic #15~1622578982~20.10~383c0a9-Ubuntu SMP Wed Jun 2 00:54:41 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jun 20, 2021

Hm, also interesting. Does it make a difference if you add the "log" import back (e.g., as _ "log")?

(Also, you might consider running go build finalizer.go once outside the loop, and then just running ./finalizer inside of it.)

@zephyrtronium
Copy link
Contributor

@zephyrtronium zephyrtronium commented Jun 20, 2021

It does not reproduce just with adding a blank import for log, but it sporadically does with a use of log: https://play.golang.org/p/TC4R7_VU6un

@zephyrtronium
Copy link
Contributor

@zephyrtronium zephyrtronium commented Jun 20, 2021

The reproducer that uses log also fails occasionally on tip:

zephyr@brandenbedoingthelinux:~$ go version ./finalizer
./finalizer: devel go1.17-b73cc4b02b Sat Jun 19 00:46:21 2021 +0000
zephyr@brandenbedoingthelinux:~$ ./finalizer 
zephyr@brandenbedoingthelinux:~$ ./finalizer 
zephyr@brandenbedoingthelinux:~$ ./finalizer 
panic: did not finalize

goroutine 1 [running]:
main.main()
	/home/zephyr/finalizer.go:31 +0x10e

@seankhliao
Copy link
Contributor

@seankhliao seankhliao commented Jun 20, 2021

I see it both with 1.16.5 and tip with #46827 (comment)

main » uname -a
Linux eevee 5.12.8-arch1-1 #1 SMP PREEMPT Fri, 28 May 2021 15:10:20 +0000 x86_64 GNU/Linux
main » go1.16.5 version
go version go1.16.5 linux/amd64

main » go1.16.5 build -a

main » ./testrepo-489

main » ./testrepo-489
panic: did not finalize

goroutine 1 [running]:
main.main()
	/home/arccy/tmp/testrepo-489/main.go:26 +0x130

main » gotip version
go version devel go1.17-b73cc4b Sat Jun 19 00:46:21 2021 +0000 linux/amd64

main » gotip build -a

main » ./testrepo-489
panic: did not finalize

goroutine 1 [running]:
main.main()
	/home/arccy/tmp/testrepo-489/main.go:26 +0xd8

main » ./testrepo-489

@cuonglm
Copy link
Member

@cuonglm cuonglm commented Jun 20, 2021

Seems specific to Linux, as I can't reproduce this on Apple M1, both with go1.16 and gotip.

@josharian
Copy link
Contributor

@josharian josharian commented Jun 20, 2021

Running with allocfreetrace and comparing a few good/bad runs might help identify the culprit.

@CAFxX
Copy link
Contributor

@CAFxX CAFxX commented Jun 21, 2021

type ref uint64

Aren't objects smaller than maxTinySize (16 bytes) (update: that do not contain pointers) still using block allocations, preventing individual objects from being immediately collected (and therefore finalized) until all objects in the block become unreachable? If so, imports and arch/OS differences are probably just red herrings.

@mknyszek
Copy link
Contributor

@mknyszek mknyszek commented Jun 21, 2021

I haven't had a chance to look too closely, but as @CAFxX points out, any object not containing pointers that is < 16 bytes in size has its lifetime potentially shared with other allocations (they are allocated in a 16 byte block). Which allocations end up in the same block depends on so many factors (allocation order, which depends on goroutine scheduling, OS scheduling, the whims of hardware, etc.) that I wouldn't be surprised if an import causes some init function to run, which creates some tiny allocation that never dies, and now the finalized object is bound to it.

To the letter, I think this behavior still agrees with SetFinalizer's documentation, but it's subtle. If you just had a finalizer on something that was just a file handle (a uint32 or something) then this could be problematic. The workaround here is to add padding to your type so that it gets its own object slot, but that's kind of annoying. I wonder if there's anything we can do to help with this without losing the memory use/performance benefits of grouping tiny objects in this way.

@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jun 21, 2021

Oof, right, I forgot about the tiny allocator. I agree that seems to explain everything seen, and the suggestion of bumping up the allocation size to at least 16 bytes should address the issue by bypassing the tiny allocator.

@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jul 2, 2021

Closing the issue because it seems like things are working as intended, and there's no obvious action to take.

But if anyone thinks there's something concrete to do here within the runtime, speak up and/or reopen the issue. Thanks.

@mdempsky mdempsky closed this Jul 2, 2021
@seebs
Copy link
Contributor Author

@seebs seebs commented Jul 2, 2021

I feel like there might be a doc bug here but I also feel like it's pretty clearly established that there's no general guarantee that a finalizer is ever reached. It seems like a sort of weird special case that tiny objects would be more vulnerable to this, and I'm sure someone could make it behave badly, but... there's pretty decent warnings already.

Sorry for the belated response, I apparently missed any earlier notifications, but I'm fine with this being closed as-is.

@mdempsky
Copy link
Member

@mdempsky mdempsky commented Jul 2, 2021

@seebs I think a paragraph warning about SetFinalizer's semantics on objects allocated with the tiny allocator seems reasonable. If someone wants to send a CL for that, that would be great. Please send to me, @mknyszek, and @ianlancetaylor. Thanks.

@seebs
Copy link
Contributor Author

@seebs seebs commented Jul 6, 2021

I just thought of a messy special case for this; imagine for some reason a pair of objects, both small enough to get into tiny allocator blocks, such that one of them controls (but doesn't just contain) a reference to the other, so when the first one is finalized, it eliminates the sole reference to the other. As long as the allocations are separate, the GC will eventually free them, but if they end up in the same tiny allocator block, you actually just get stuck forever; the finalizer won't ever run, because the finalizer is what would have removed the reference to the other thing in that block. I wonder whether this could actually happen, but my intuition would be that "object and the small thing it's referring to get allocated right next to each other" might be common.

@seebs
Copy link
Contributor Author

@seebs seebs commented Jul 6, 2021

https://play.golang.org/p/1qSh5EY_mzU

In which _ [0]int in a struct changes whether or not a finalizer runs (???!)

@randall77
Copy link
Contributor

@randall77 randall77 commented Jul 6, 2021

[0]int at the end of a struct makes it one byte bigger. (So a pointer to that field does not point to the next object in memory.)

@mdempsky mdempsky changed the title runtime: finalizers not consistently run when package reflect imported runtime: document finalizer semantics for tiny objects (<16 bytes) Jul 7, 2021
@gopherbot
Copy link

@gopherbot gopherbot commented Jul 26, 2021

Change https://golang.org/cl/337391 mentions this issue: runtime: clarify finalizer semantics for tiny objects

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet