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.

It does retain a bytes.Buffer, see #46285

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

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

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

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.

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

It fails often, but not 100% reliably.

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

@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.

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 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.

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

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.)

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

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

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

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

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

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.

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.

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.

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.

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.

@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.

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.

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

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

[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.)

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