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: "sweep increased allocation count" when using reflect.Call #21717

Closed
g7r opened this issue Aug 31, 2017 · 17 comments
Closed

runtime: "sweep increased allocation count" when using reflect.Call #21717

g7r opened this issue Aug 31, 2017 · 17 comments
Labels
CherryPickApproved Used during the release process for point releases FrozenDueToAge release-blocker
Milestone

Comments

@g7r
Copy link
Contributor

g7r commented Aug 31, 2017

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

go version go1.8.3 darwin/amd64, go version go1.9 darwin/amd64 and go version go1.8.3 linux/amd64 (i. e. all I've tried)

Does this issue reproduce with the latest release?

Yes

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/sz/src/gohome"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.9/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.9/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/9h/x_80x8ln3_g038_zj_t9tszw0000gn/T/go-build347957070=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"

What did you do?

package main

import "reflect"

func main() {
	fv := reflect.ValueOf(func(int) struct{} { return struct{}{} })
	args := []reflect.Value{reflect.ValueOf(0)}

	for {
		fv.Call(args)
	}
}

What did you expect to see?

Infinite loop

What did you see instead?

Crash with message fatal error: sweep increased allocation count within a second or less

runtime: nelems=512 nalloc=16 previous allocCount=15 nfreed=65535
fatal error: sweep increased allocation count

runtime stack:
runtime.throw(0x10a64a6, 0x20)
        /usr/local/Cellar/go/1.9/libexec/src/runtime/panic.go:605 +0x95
runtime.(*mspan).sweep(0x11be000, 0x11be001, 0x0)
        /usr/local/Cellar/go/1.9/libexec/src/runtime/mgcsweep.go:298 +0x911
runtime.(*mcentral).cacheSpan(0x1116af0, 0x110ed90)
        /usr/local/Cellar/go/1.9/libexec/src/runtime/mcentral.go:58 +0x2cd
runtime.(*mcache).refill(0x114d000, 0x102d405, 0xc420000a80)
        /usr/local/Cellar/go/1.9/libexec/src/runtime/mcache.go:123 +0xa4
runtime.(*mcache).nextFree.func1()
        /usr/local/Cellar/go/1.9/libexec/src/runtime/malloc.go:557 +0x32
runtime.systemstack(0xc420020000)
        /usr/local/Cellar/go/1.9/libexec/src/runtime/asm_amd64.s:344 +0x79
runtime.mstart()
        /usr/local/Cellar/go/1.9/libexec/src/runtime/proc.go:1125

goroutine 1 [running]:
runtime.systemstack_switch()
        /usr/local/Cellar/go/1.9/libexec/src/runtime/asm_amd64.s:298 fp=0xc420045a68 sp=0xc420045a60 pc=0x104bec0
runtime.(*mcache).nextFree(0x114d000, 0x5, 0xc420045b78, 0x100e5f0, 0xc4202f23a0)
        /usr/local/Cellar/go/1.9/libexec/src/runtime/malloc.go:556 +0xa9 fp=0xc420045ac0 sp=0xc420045a68 pc=0x100df19
runtime.mallocgc(0x8, 0xc42007a0f0, 0x100f401, 0xc42007a0f0)
        /usr/local/Cellar/go/1.9/libexec/src/runtime/malloc.go:687 +0x5c2 fp=0xc420045b68 sp=0xc420045ac0 pc=0x100e6b2
runtime.newobject(0xc42007a0f0, 0xc42000a080)
        /usr/local/Cellar/go/1.9/libexec/src/runtime/malloc.go:840 +0x38 fp=0xc420045b98 sp=0xc420045b68 pc=0x100eb28
reflect.unsafe_New(0xc42007a0f0, 0x0)
        /usr/local/Cellar/go/1.9/libexec/src/runtime/malloc.go:845 +0x2b fp=0xc420045bb8 sp=0xc420045b98 pc=0x100eb7b
reflect.Value.call(0x108bce0, 0x10a86a8, 0x13, 0x10a2ce7, 0x4, 0xc420045f58, 0x1, 0x1, 0xc4202f23a0, 0x1, ...)
        /usr/local/Cellar/go/1.9/libexec/src/reflect/value.go:408 +0xcbe fp=0xc420045e90 sp=0xc420045bb8 pc=0x1069a1e
reflect.Value.Call(0x108bce0, 0x10a86a8, 0x13, 0xc420045f58, 0x1, 0x1, 0xc4202f23a0, 0x1, 0x1)
        /usr/local/Cellar/go/1.9/libexec/src/reflect/value.go:302 +0xa4 fp=0xc420045ef8 sp=0xc420045e90 pc=0x1068c44
main.main()
        /Users/sz/src/gohome/src/github.com/joomcode/api/junk/sz/joom-go-sweep-treat/main.go:10 +0xd6 fp=0xc420045f80 sp=0xc420045ef8 pc=0x1078476
runtime.main()
        /usr/local/Cellar/go/1.9/libexec/src/runtime/proc.go:185 +0x20d fp=0xc420045fe0 sp=0xc420045f80 pc=0x1026ebd
runtime.goexit()
        /usr/local/Cellar/go/1.9/libexec/src/runtime/asm_amd64.s:2337 +0x1 fp=0xc420045fe8 sp=0xc420045fe0 pc=0x104e511
exit status 2
@aclements aclements added this to the Go1.9.1 milestone Aug 31, 2017
@aclements aclements changed the title "sweep increased allocation count" when using reflect.Call runtime: "sweep increased allocation count" when using reflect.Call Aug 31, 2017
@aclements
Copy link
Member

Thanks for the great, short reproducer!

I can confirm that I can reproduce locally with 1.9 on linux/amd64.

GODEBUG=gccheckmark=1 fails almost immediately from the write barrier in reflect.Value.call:

runtime: marking free object 0xc420436060 found at *(0x0+0x0)
base=0x0 is not in the Go heap
obj=0xc420436060 k=0x621021b s.base()=0xc420436000 s.limit=0xc420438000 s.spanclass=5 s.elemsize=16 s.state=_MSpanInUse
 *(obj+0) = 0x0
 *(obj+8) = 0x0
fatal error: marking free object

runtime stack:
runtime.throw(0x4a71c8, 0x13)
	/home/austin/.cache/gover/1.9/src/runtime/panic.go:605 +0x95 fp=0x7fff11ac4dc8 sp=0x7fff11ac4da8 pc=0x425e25
runtime.greyobject(0xc420436060, 0x0, 0x0, 0xc41ffde4fc, 0xc400000000, 0x7ff49ec74db8, 0xc42003d260, 0x6)
	/home/austin/.cache/gover/1.9/src/runtime/mgcmark.go:1251 +0x352 fp=0x7fff11ac4df8 sp=0x7fff11ac4dc8 pc=0x41b662
runtime.shade(0xc420436060)
	/home/austin/.cache/gover/1.9/src/runtime/mgcmark.go:1203 +0xc0 fp=0x7fff11ac4e50 sp=0x7fff11ac4df8 pc=0x41b2d0
runtime.gcmarkwb_m(0xc420435c68, 0xc420436060)
	/home/austin/.cache/gover/1.9/src/runtime/mbarrier.go:164 +0xbd fp=0x7fff11ac4e68 sp=0x7fff11ac4e50 pc=0x40f52d
runtime.writebarrierptr_prewrite1.func1()
	/home/austin/.cache/gover/1.9/src/runtime/mbarrier.go:193 +0x64 fp=0x7fff11ac4e88 sp=0x7fff11ac4e68 pc=0x44a774
runtime.systemstack(0x512300)
	/home/austin/.cache/gover/1.9/src/runtime/asm_amd64.s:344 +0x79 fp=0x7fff11ac4e90 sp=0x7fff11ac4e88 pc=0x44d009
runtime.mstart()
	/home/austin/.cache/gover/1.9/src/runtime/proc.go:1125 fp=0x7fff11ac4e98 sp=0x7fff11ac4e90 pc=0x42a5e0

goroutine 1 [running]:
runtime.systemstack_switch()
	/home/austin/.cache/gover/1.9/src/runtime/asm_amd64.s:298 fp=0xc42005bb40 sp=0xc42005bb38 pc=0x44cf80
runtime.writebarrierptr_prewrite1(0xc420435c68, 0xc420436060)
	/home/austin/.cache/gover/1.9/src/runtime/mbarrier.go:188 +0xb6 fp=0xc42005bb80 sp=0xc42005bb40 pc=0x40f606
runtime.writebarrierptr(0xc420435c68, 0xc420436060)
	/home/austin/.cache/gover/1.9/src/runtime/mbarrier.go:216 +0x4d fp=0xc42005bbb8 sp=0xc42005bb80 pc=0x40f69d
reflect.Value.call(0x48e280, 0x4ab380, 0x13, 0x4a58a7, 0x4, 0xc42005bf58, 0x1, 0x1, 0xc420435c40, 0x1, ...)
	/home/austin/.cache/gover/1.9/src/reflect/value.go:460 +0xb60 fp=0xc42005be90 sp=0xc42005bbb8 pc=0x46afb0
reflect.Value.Call(0x48e280, 0x4ab380, 0x13, 0xc42005bf58, 0x1, 0x1, 0xc420435c40, 0x1, 0x1)
	/home/austin/.cache/gover/1.9/src/reflect/value.go:302 +0xa4 fp=0xc42005bef8 sp=0xc42005be90 pc=0x46a334
main.main()
	/home/austin/go.dev/austin/21717/main.go:10 +0xd6 fp=0xc42005bf80 sp=0xc42005bef8 pc=0x479b66

/cc @RLH

@cherrymui
Copy link
Member

The faulty line in reflect.Value.call is

			ret[i] = Value{tv.common(), unsafe.Pointer(uintptr(args) + off), fl}

on the write barrier of storing the second field (unsafe.Pointer(uintptr(args) + off)).

I guess the problem is that, in this case, the return value is zero sized, so unsafe.Pointer(uintptr(args) + off) may be pointing at the next object in the heap, or something not allocated.

@cherrymui
Copy link
Member

As a quick hack, the patch below seems to fix it:

diff --git a/src/reflect/value.go b/src/reflect/value.go
index e67b3cdcff..51cdafb642 100644
--- a/src/reflect/value.go
+++ b/src/reflect/value.go
@@ -456,7 +456,11 @@ func (v Value) call(op string, in []Value) []Value {
                        a := uintptr(tv.Align())
                        off = (off + a - 1) &^ (a - 1)
                        fl := flagIndir | flag(tv.Kind())
-                       ret[i] = Value{tv.common(), unsafe.Pointer(uintptr(args) + off), fl}
+                       if tv.Size() != 0 {
+                               ret[i] = Value{tv.common(), unsafe.Pointer(uintptr(args) + off), fl}
+                       } else {
+                               ret[i] = Zero(tv)
+                       }
                        off += tv.Size()
                }
        }

@g7r
Copy link
Contributor Author

g7r commented Aug 31, 2017

@cherrymui Please note that crash doesn't reproduce if I remove func argument or replace it with struct{}:

	fv := reflect.ValueOf(func() struct{} { return struct{}{} })
	args := []reflect.Value{}

and

	fv := reflect.ValueOf(func(struct{}) struct{} { return struct{}{} })
	args := []reflect.Value{reflect.ValueOf(struct{}{})}

@cherrymui
Copy link
Member

cherrymui commented Aug 31, 2017

@g7r If the arg size is also zero, I guess (without carefully read the code) that it works because the args variable in reflect.Value.call will be pointing to the dedicated zero-sized object, so it's fine.

@g7r
Copy link
Contributor Author

g7r commented Aug 31, 2017

This version also crashes:

package main

import "reflect"

func main() {
	for {
		reflect.ValueOf(func() (int, struct{}) { return 0, struct{}{} }).Call(nil)
	}
}

@gopherbot
Copy link

Change https://golang.org/cl/60811 mentions this issue: reflect: fix pointer pass-the-end in Call with zero-sized return value

@g7r
Copy link
Contributor Author

g7r commented Sep 1, 2017

If we consider sharing same reflect.Value.ptr for different values an error, here's one more case: https://play.golang.org/p/KnVsbcTgs7

@cherrymui
Copy link
Member

@g7r this is not a bug. It is the same as normal Go does:

fmt.Printf("%p %p\n", &t.A, &t.B)

prints 0x10410020 0x10410020.

@bcmills
Copy link
Contributor

bcmills commented Sep 1, 2017

If we consider sharing same reflect.Value.ptr for different values an error

As I noted on the change review, ‘[t]he property we want is “the ptr fields are either nil or valid pointers”, which is strictly weaker than “the ptr fields are either nil or distinct pointers”.’

We do also want it to be the case that a pointer to a struct field resides within the struct that contains it, and that every pointer field in a struct contains a valid pointer, but in that example the pointer does reside within the struct, and because struct{} contains no fields at all it trivially cannot contain invalid pointer fields.

@aclements
Copy link
Member

Re-open for cherry-pick to Go 1.9.

@rsc
Copy link
Contributor

rsc commented Oct 13, 2017

CL 60811 OK for Go 1.9.2.

@rsc rsc added the CherryPickApproved Used during the release process for point releases label Oct 14, 2017
@gopherbot
Copy link

Change https://golang.org/cl/70971 mentions this issue: [release-branch.go1.9] reflect: fix pointer past-the-end in Call with zero-sized return value

gopherbot pushed a commit that referenced this issue Oct 25, 2017
… zero-sized return value

If a function with nonzero frame but zero-sized return value is
Call'd, we may write a past-the-end pointer in preparing the
return Values. Fix by return the zero value for zero-sized
return value.

Fixes #21717.

Change-Id: I5351cd86d898467170a888b4c3fc9392f0e7aa3b
Reviewed-on: https://go-review.googlesource.com/60811
Run-TryBot: Cherry Zhang <cherryyz@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Austin Clements <austin@google.com>
Reviewed-on: https://go-review.googlesource.com/70971
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Cherry Zhang <cherryyz@google.com>
@rsc
Copy link
Contributor

rsc commented Oct 26, 2017

go1.9.2 has been packaged and includes:

The release is posted at golang.org/dl.

— golang.org/x/build/cmd/releasebot, Oct 26 21:09:12 UTC

@rsc rsc closed this as completed Oct 26, 2017
@quasilyte
Copy link
Contributor

Running test with -count=2 causes it to fail.

bin/go test -v -run 'TestCallReturnsEmpty' -count=2 reflect
=== RUN   TestCallReturnsEmpty
--- PASS: TestCallReturnsEmpty (0.01s)
=== RUN   TestCallReturnsEmpty
--- FAIL: TestCallReturnsEmpty (5.00s)
	all_test.go:1698: finalizer did not run
FAIL
FAIL	reflect	5.008s

Does this deserve an investigation?

Either TestCallReturnsEmpty is not idempotent or this issue was only partially solved.

@ianlancetaylor
Copy link
Contributor

@quasilyte This issue is closed and we believe the problem is fixed in the upcoming 1.10 release. I see no particular reason to think that the problem you are seeing is related to the problem that was fixed here. If you are seeing a repeatable problem with the development version, please open a new issue. Thanks.

@gopherbot
Copy link

Change https://golang.org/cl/128475 mentions this issue: reflect: use a bigger object when we need a finalizer to run

gopherbot pushed a commit that referenced this issue Aug 24, 2018
If an object is allocated as part of a tinyalloc, then other live
objects in the same tinyalloc chunk keep the finalizer from being run,
even if the object that has the finalizer is dead.

Make sure the object we're setting the finalizer on is big enough
to not trigger tinyalloc allocation.

Fixes #26857
Update #21717

Change-Id: I56ad8679426283237ebff20a0da6c9cf64eb1c27
Reviewed-on: https://go-review.googlesource.com/128475
Run-TryBot: Keith Randall <khr@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Austin Clements <austin@google.com>
Reviewed-by: Cherry Zhang <cherryyz@google.com>
bastianccm added a commit to i-love-flamingo/flamingo that referenced this issue Apr 2, 2019
a bug in reflect.Value leads to issues during garbage collection
(suspiciously dangling heap-pointers and mark+sweep issues)

This should be fixed in go 1.9.2, so for now we force a
garbage collection before every rendering, hopefully tackling
this issue.

golang/go#21717

targetprocess #147131
bastianccm added a commit to i-love-flamingo/flamingo that referenced this issue Apr 2, 2019
a bug in reflect.Value leads to issues during garbage collection
(suspiciously dangling heap-pointers and mark+sweep issues)

This should be fixed in go 1.9.2, so for now we force a
garbage collection before every rendering, hopefully tackling
this issue.

golang/go#21717

targetprocess #147131
bastianccm added a commit to i-love-flamingo/pugtemplate that referenced this issue Apr 2, 2019
a bug in reflect.Value leads to issues during garbage collection
(suspiciously dangling heap-pointers and mark+sweep issues)

This should be fixed in go 1.9.2, so for now we force a
garbage collection before every rendering, hopefully tackling
this issue.

golang/go#21717

targetprocess #147131
@golang golang locked and limited conversation to collaborators Aug 8, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
CherryPickApproved Used during the release process for point releases FrozenDueToAge release-blocker
Projects
None yet
Development

No branches or pull requests

8 participants