From e97209515ad8c4042f5a3ef32068200366892fc2 Mon Sep 17 00:00:00 2001 From: Austin Clements Date: Mon, 12 Jun 2017 11:12:12 -0400 Subject: runtime: hide methods from call stack The compiler generates wrapper methods to forward interface method calls (which are always pointer-based) to value methods. These wrappers appear in the call stack even though they are an implementation detail. This leaves ugly "" functions in stack traces and can throw off skip counts for stack traces. Fix this by considering these runtime frames in printed stack traces so they will only be printed if runtime frames are being printed, and by eliding them from the call stack expansion used by CallersFrames and Caller. This removes the test for issue 4388 since that was checking that "" appeared in the stack trace instead of something even weirder. We replace it with various runtime package tests. Fixes #16723. Change-Id: Ice3f118c66f254bb71478a664d62ab3fc7125819 Reviewed-on: https://go-review.googlesource.com/45412 Run-TryBot: Austin Clements TryBot-Result: Gobot Gobot Reviewed-by: Ian Lance Taylor --- src/runtime/stack_test.go | 58 +++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 58 insertions(+) (limited to 'src/runtime/stack_test.go') diff --git a/src/runtime/stack_test.go b/src/runtime/stack_test.go index 25e8f77da4..c9b84be066 100644 --- a/src/runtime/stack_test.go +++ b/src/runtime/stack_test.go @@ -5,6 +5,7 @@ package runtime_test import ( + "fmt" . "runtime" "strings" "sync" @@ -627,3 +628,60 @@ func count23(n int) int { } return 1 + count1(n-1) } + +type structWithMethod struct{} + +func (s structWithMethod) caller() string { + _, file, line, ok := Caller(1) + if !ok { + panic("Caller failed") + } + return fmt.Sprintf("%s:%d", file, line) +} + +func (s structWithMethod) callers() []uintptr { + pc := make([]uintptr, 16) + return pc[:Callers(0, pc)] +} + +func (s structWithMethod) stack() string { + buf := make([]byte, 4<<10) + return string(buf[:Stack(buf, false)]) +} + +func TestStackWrapperCaller(t *testing.T) { + var d structWithMethod + // Force the compiler to construct a wrapper method. + wrapper := (*structWithMethod).caller + // Check that the wrapper doesn't affect the stack trace. + if dc, ic := d.caller(), wrapper(&d); dc != ic { + t.Fatalf("direct caller %q != indirect caller %q", dc, ic) + } +} + +func TestStackWrapperCallers(t *testing.T) { + var d structWithMethod + wrapper := (*structWithMethod).callers + // Check that doesn't appear in the stack trace. + pcs := wrapper(&d) + frames := CallersFrames(pcs) + for { + fr, more := frames.Next() + if fr.File == "" { + t.Fatalf(" appears in stack trace: %+v", fr) + } + if !more { + break + } + } +} + +func TestStackWrapperStack(t *testing.T) { + var d structWithMethod + wrapper := (*structWithMethod).stack + // Check that doesn't appear in the stack trace. + stk := wrapper(&d) + if strings.Contains(stk, "") { + t.Fatalf(" appears in stack trace:\n%s", stk) + } +} -- cgit v1.3 From 15d6ab69fbd8c84cde109def59c7e002296c19e8 Mon Sep 17 00:00:00 2001 From: Austin Clements Date: Fri, 27 Oct 2017 15:20:21 -0400 Subject: runtime: make systemstack tail call if already switched Currently systemstack always calls its argument, even if we're already on the system stack. Unfortunately, traceback with _TraceJump stops at the first systemstack it sees, which often cuts off runtime stacks early in profiles. Fix this by performing a tail call if we're already on the system stack. This eliminates it from the traceback entirely, so it won't stop prematurely (or all get mushed into a single node in the profile graph). Change-Id: Ibc69e8765e899f8d3806078517b8c7314da196f4 Reviewed-on: https://go-review.googlesource.com/74050 Reviewed-by: Cherry Zhang Reviewed-by: Keith Randall --- src/runtime/asm_386.s | 7 ++++--- src/runtime/asm_amd64.s | 7 ++++--- src/runtime/asm_amd64p32.s | 5 +++-- src/runtime/asm_arm.s | 6 ++++-- src/runtime/asm_arm64.s | 6 ++++-- src/runtime/asm_mips64x.s | 7 +++++-- src/runtime/asm_mipsx.s | 7 +++++-- src/runtime/asm_ppc64x.s | 3 +++ src/runtime/asm_s390x.s | 7 +++++-- src/runtime/export_test.go | 13 +++++++++++++ src/runtime/stack_test.go | 33 +++++++++++++++++++++++++++++++++ 11 files changed, 83 insertions(+), 18 deletions(-) (limited to 'src/runtime/stack_test.go') diff --git a/src/runtime/asm_386.s b/src/runtime/asm_386.s index 15d9ce9fdf..80a145187c 100644 --- a/src/runtime/asm_386.s +++ b/src/runtime/asm_386.s @@ -474,11 +474,12 @@ switch: RET noswitch: - // already on system stack, just call directly + // already on system stack; tail call the function + // Using a tail call here cleans up tracebacks since we won't stop + // at an intermediate systemstack. MOVL DI, DX MOVL 0(DI), DI - CALL DI - RET + JMP DI /* * support for morestack diff --git a/src/runtime/asm_amd64.s b/src/runtime/asm_amd64.s index 2ac879c31d..01a1710046 100644 --- a/src/runtime/asm_amd64.s +++ b/src/runtime/asm_amd64.s @@ -419,11 +419,12 @@ switch: RET noswitch: - // already on m stack, just call directly + // already on m stack; tail call the function + // Using a tail call here cleans up tracebacks since we won't stop + // at an intermediate systemstack. MOVQ DI, DX MOVQ 0(DI), DI - CALL DI - RET + JMP DI /* * support for morestack diff --git a/src/runtime/asm_amd64p32.s b/src/runtime/asm_amd64p32.s index b7fcf2376e..7fee79aefb 100644 --- a/src/runtime/asm_amd64p32.s +++ b/src/runtime/asm_amd64p32.s @@ -306,10 +306,11 @@ switch: noswitch: // already on m stack, just call directly + // Using a tail call here cleans up tracebacks since we won't stop + // at an intermediate systemstack. MOVL DI, DX MOVL 0(DI), DI - CALL DI - RET + JMP DI /* * support for morestack diff --git a/src/runtime/asm_arm.s b/src/runtime/asm_arm.s index caa96cc4b3..306984e8f7 100644 --- a/src/runtime/asm_arm.s +++ b/src/runtime/asm_arm.s @@ -358,10 +358,12 @@ switch: RET noswitch: + // Using a tail call here cleans up tracebacks since we won't stop + // at an intermediate systemstack. MOVW R0, R7 MOVW 0(R0), R0 - BL (R0) - RET + MOVW.P 4(R13), R14 // restore LR + B (R0) /* * support for morestack diff --git a/src/runtime/asm_arm64.s b/src/runtime/asm_arm64.s index b2aff1aab7..5e202e7a87 100644 --- a/src/runtime/asm_arm64.s +++ b/src/runtime/asm_arm64.s @@ -239,9 +239,11 @@ switch: noswitch: // already on m stack, just call directly + // Using a tail call here cleans up tracebacks since we won't stop + // at an intermediate systemstack. MOVD 0(R26), R3 // code pointer - BL (R3) - RET + MOVD.P 16(RSP), R30 // restore LR + B (R3) /* * support for morestack diff --git a/src/runtime/asm_mips64x.s b/src/runtime/asm_mips64x.s index 3510853804..12cea00adc 100644 --- a/src/runtime/asm_mips64x.s +++ b/src/runtime/asm_mips64x.s @@ -214,9 +214,12 @@ switch: noswitch: // already on m stack, just call directly + // Using a tail call here cleans up tracebacks since we won't stop + // at an intermediate systemstack. MOVV 0(REGCTXT), R4 // code pointer - JAL (R4) - RET + MOVV 0(R29), R31 // restore LR + ADDV $8, R29 + JMP (R4) /* * support for morestack diff --git a/src/runtime/asm_mipsx.s b/src/runtime/asm_mipsx.s index 334f259186..bba6a9501d 100644 --- a/src/runtime/asm_mipsx.s +++ b/src/runtime/asm_mipsx.s @@ -215,9 +215,12 @@ switch: noswitch: // already on m stack, just call directly + // Using a tail call here cleans up tracebacks since we won't stop + // at an intermediate systemstack. MOVW 0(REGCTXT), R4 // code pointer - JAL (R4) - RET + MOVW 0(R29), R31 // restore LR + ADD $4, R29 + JMP (R4) /* * support for morestack diff --git a/src/runtime/asm_ppc64x.s b/src/runtime/asm_ppc64x.s index 2f2a4a7b04..487187f4d8 100644 --- a/src/runtime/asm_ppc64x.s +++ b/src/runtime/asm_ppc64x.s @@ -265,6 +265,9 @@ switch: noswitch: // already on m stack, just call directly + // On other arches we do a tail call here, but it appears to be + // impossible to tail call a function pointer in shared mode on + // ppc64 because the caller is responsible for restoring the TOC. MOVD 0(R11), R12 // code pointer MOVD R12, CTR BL (CTR) diff --git a/src/runtime/asm_s390x.s b/src/runtime/asm_s390x.s index 524b866b21..42b9326607 100644 --- a/src/runtime/asm_s390x.s +++ b/src/runtime/asm_s390x.s @@ -224,9 +224,12 @@ switch: noswitch: // already on m stack, just call directly + // Using a tail call here cleans up tracebacks since we won't stop + // at an intermediate systemstack. MOVD 0(R12), R3 // code pointer - BL (R3) - RET + MOVD 0(R15), LR // restore LR + ADD $8, R15 + BR (R3) /* * support for morestack diff --git a/src/runtime/export_test.go b/src/runtime/export_test.go index 9b269d9659..599ac2d84a 100644 --- a/src/runtime/export_test.go +++ b/src/runtime/export_test.go @@ -395,3 +395,16 @@ func LockOSCounts() (external, internal uint32) { } return g.m.lockedExt, g.m.lockedInt } + +//go:noinline +func TracebackSystemstack(stk []uintptr, i int) int { + if i == 0 { + pc, sp := getcallerpc(), getcallersp(unsafe.Pointer(&stk)) + return gentraceback(pc, sp, 0, getg(), 0, &stk[0], len(stk), nil, nil, _TraceJumpStack) + } + n := 0 + systemstack(func() { + n = TracebackSystemstack(stk, i-1) + }) + return n +} diff --git a/src/runtime/stack_test.go b/src/runtime/stack_test.go index c9b84be066..8e7c7d47a8 100644 --- a/src/runtime/stack_test.go +++ b/src/runtime/stack_test.go @@ -5,6 +5,7 @@ package runtime_test import ( + "bytes" "fmt" . "runtime" "strings" @@ -685,3 +686,35 @@ func TestStackWrapperStack(t *testing.T) { t.Fatalf(" appears in stack trace:\n%s", stk) } } + +func TestTracebackSystemstack(t *testing.T) { + if GOARCH == "ppc64" || GOARCH == "ppc64le" { + t.Skip("systemstack tail call not implemented on ppc64x") + } + + // Test that profiles correctly jump over systemstack, + // including nested systemstack calls. + pcs := make([]uintptr, 20) + pcs = pcs[:TracebackSystemstack(pcs, 5)] + // Check that runtime.TracebackSystemstack appears five times + // and that we see TestTracebackSystemstack. + countIn, countOut := 0, 0 + frames := CallersFrames(pcs) + var tb bytes.Buffer + for { + frame, more := frames.Next() + fmt.Fprintf(&tb, "\n%s+0x%x %s:%d", frame.Function, frame.PC-frame.Entry, frame.File, frame.Line) + switch frame.Function { + case "runtime.TracebackSystemstack": + countIn++ + case "runtime_test.TestTracebackSystemstack": + countOut++ + } + if !more { + break + } + } + if countIn != 5 || countOut != 1 { + t.Fatalf("expected 5 calls to TracebackSystemstack and 1 call to TestTracebackSystemstack, got:%s", tb.String()) + } +} -- cgit v1.3 From 032678e0fb0a5e0471a6555b758ca4d960249013 Mon Sep 17 00:00:00 2001 From: Austin Clements Date: Thu, 9 Nov 2017 17:55:45 -0500 Subject: runtime: don't elide wrapper functions that call panic or at TOS CL 45412 started hiding autogenerated wrapper functions from call stacks so that call stack semantics better matched language semantics. This is based on the theory that the wrapper function will call the "real" function and all the programmer knows about is the real function. However, this theory breaks down in two cases: 1. If the wrapper is at the top of the stack, then it didn't call anything. This can happen, for example, if the "stack" was actually synthesized by the user. 2. If the wrapper panics, for example by calling panicwrap or by dereferencing a nil pointer, then it didn't call the wrapped function and the user needs to see what panicked, even if we can't attribute it nicely. This commit modifies the traceback logic to include the wrapper function in both of these cases. Fixes #22231. Change-Id: I6e4339a652f73038bd8331884320f0b8edd86eb1 Reviewed-on: https://go-review.googlesource.com/76770 Run-TryBot: Austin Clements TryBot-Result: Gobot Gobot Reviewed-by: Keith Randall --- src/runtime/extern.go | 4 +-- src/runtime/stack_test.go | 78 +++++++++++++++++++++++++++++++++++++++++++++++ src/runtime/symtab.go | 12 ++++++-- src/runtime/traceback.go | 40 +++++++++++++++++++----- 4 files changed, 122 insertions(+), 12 deletions(-) (limited to 'src/runtime/stack_test.go') diff --git a/src/runtime/extern.go b/src/runtime/extern.go index 66b9527802..2c20e0d8af 100644 --- a/src/runtime/extern.go +++ b/src/runtime/extern.go @@ -178,11 +178,11 @@ func Caller(skip int) (pc uintptr, file string, line int, ok bool) { // We asked for one extra, so skip that one. If this is sigpanic, // stepping over this frame will set up state in Frames so the // next frame is correct. - callers, _, ok = stackExpander.next(callers) + callers, _, ok = stackExpander.next(callers, true) if !ok { return } - _, frame, _ := stackExpander.next(callers) + _, frame, _ := stackExpander.next(callers, true) pc = frame.PC file = frame.File line = frame.Line diff --git a/src/runtime/stack_test.go b/src/runtime/stack_test.go index 8e7c7d47a8..cb0e08256b 100644 --- a/src/runtime/stack_test.go +++ b/src/runtime/stack_test.go @@ -7,6 +7,7 @@ package runtime_test import ( "bytes" "fmt" + "reflect" . "runtime" "strings" "sync" @@ -650,6 +651,8 @@ func (s structWithMethod) stack() string { return string(buf[:Stack(buf, false)]) } +func (s structWithMethod) nop() {} + func TestStackWrapperCaller(t *testing.T) { var d structWithMethod // Force the compiler to construct a wrapper method. @@ -687,6 +690,81 @@ func TestStackWrapperStack(t *testing.T) { } } +type I interface { + M() +} + +func TestStackWrapperStackPanic(t *testing.T) { + t.Run("sigpanic", func(t *testing.T) { + // nil calls to interface methods cause a sigpanic. + testStackWrapperPanic(t, func() { I.M(nil) }, "runtime_test.I.M") + }) + t.Run("panicwrap", func(t *testing.T) { + // Nil calls to value method wrappers call panicwrap. + wrapper := (*structWithMethod).nop + testStackWrapperPanic(t, func() { wrapper(nil) }, "runtime_test.(*structWithMethod).nop") + }) +} + +func testStackWrapperPanic(t *testing.T, cb func(), expect string) { + // Test that the stack trace from a panicking wrapper includes + // the wrapper, even though elide these when they don't panic. + t.Run("CallersFrames", func(t *testing.T) { + defer func() { + err := recover() + if err == nil { + t.Fatalf("expected panic") + } + pcs := make([]uintptr, 10) + n := Callers(0, pcs) + frames := CallersFrames(pcs[:n]) + for { + frame, more := frames.Next() + t.Log(frame.Function) + if frame.Function == expect { + return + } + if !more { + break + } + } + t.Fatalf("panicking wrapper %s missing from stack trace", expect) + }() + cb() + }) + t.Run("Stack", func(t *testing.T) { + defer func() { + err := recover() + if err == nil { + t.Fatalf("expected panic") + } + buf := make([]byte, 4<<10) + stk := string(buf[:Stack(buf, false)]) + if !strings.Contains(stk, "\n"+expect) { + t.Fatalf("panicking wrapper %s missing from stack trace:\n%s", expect, stk) + } + }() + cb() + }) +} + +func TestCallersFromWrapper(t *testing.T) { + // Test that invoking CallersFrames on a stack where the first + // PC is an autogenerated wrapper keeps the wrapper in the + // trace. Normally we elide these, assuming that the wrapper + // calls the thing you actually wanted to see, but in this + // case we need to keep it. + pc := reflect.ValueOf(I.M).Pointer() + frames := CallersFrames([]uintptr{pc}) + frame, more := frames.Next() + if frame.Function != "runtime_test.I.M" { + t.Fatalf("want function %s, got %s", "runtime_test.I.M", frame.Function) + } + if more { + t.Fatalf("want 1 frame, got > 1") + } +} + func TestTracebackSystemstack(t *testing.T) { if GOARCH == "ppc64" || GOARCH == "ppc64le" { t.Skip("systemstack tail call not implemented on ppc64x") diff --git a/src/runtime/symtab.go b/src/runtime/symtab.go index 135fc1a7ad..c6c2b89f69 100644 --- a/src/runtime/symtab.go +++ b/src/runtime/symtab.go @@ -19,6 +19,11 @@ type Frames struct { // stackExpander expands callers into a sequence of Frames, // tracking the necessary state across PCs. stackExpander stackExpander + + // elideWrapper indicates that, if the next frame is an + // autogenerated wrapper function, it should be elided from + // the stack. + elideWrapper bool } // Frame is the information returned by Frames for each call frame. @@ -112,11 +117,12 @@ func (se *stackExpander) init(callers []uintptr) []uintptr { // Next returns frame information for the next caller. // If more is false, there are no more callers (the Frame value is valid). func (ci *Frames) Next() (frame Frame, more bool) { - ci.callers, frame, more = ci.stackExpander.next(ci.callers) + ci.callers, frame, more = ci.stackExpander.next(ci.callers, ci.elideWrapper) + ci.elideWrapper = elideWrapperCalling(frame.Function) return } -func (se *stackExpander) next(callers []uintptr) (ncallers []uintptr, frame Frame, more bool) { +func (se *stackExpander) next(callers []uintptr, elideWrapper bool) (ncallers []uintptr, frame Frame, more bool) { ncallers = callers again: if !se.pcExpander.more { @@ -145,7 +151,7 @@ again: } frame = se.pcExpander.next() - if frame.File == "" { + if elideWrapper && frame.File == "" { // Ignore autogenerated functions such as pointer // method forwarding functions. These are an // implementation detail that doesn't reflect the diff --git a/src/runtime/traceback.go b/src/runtime/traceback.go index 2282b2d5c0..501ecb0411 100644 --- a/src/runtime/traceback.go +++ b/src/runtime/traceback.go @@ -184,6 +184,7 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in cgoCtxt := gp.cgoCtxt printing := pcbuf == nil && callback == nil _defer := gp._defer + elideWrapper := false for _defer != nil && _defer.sp == _NoArgs { _defer = _defer.link @@ -386,8 +387,15 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in } if printing { - // assume skip=0 for printing - if (flags&_TraceRuntimeFrames) != 0 || showframe(f, gp, nprint == 0) { + // assume skip=0 for printing. + // + // Never elide wrappers if we haven't printed + // any frames. And don't elide wrappers that + // called panic rather than the wrapped + // function. Otherwise, leave them out. + name := funcname(f) + nextElideWrapper := elideWrapperCalling(name) + if (flags&_TraceRuntimeFrames) != 0 || showframe(f, gp, nprint == 0, elideWrapper && nprint != 0) { // Print during crash. // main(0x1, 0x2, 0x3) // /home/rsc/go/src/runtime/x.go:23 +0xf @@ -411,7 +419,6 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in ix = inltree[ix].parent } } - name := funcname(f) if name == "runtime.gopanic" { name = "panic" } @@ -438,6 +445,7 @@ func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max in print("\n") nprint++ } + elideWrapper = nextElideWrapper } n++ @@ -647,7 +655,7 @@ func printcreatedby(gp *g) { // Show what created goroutine, except main goroutine (goid 1). pc := gp.gopc f := findfunc(pc) - if f.valid() && showframe(f, gp, false) && gp.goid != 1 { + if f.valid() && showframe(f, gp, false, false) && gp.goid != 1 { print("created by ", funcname(f), "\n") tracepc := pc // back up to CALL instruction for funcline. if pc > f.entry { @@ -727,7 +735,7 @@ func gcallers(gp *g, skip int, pcbuf []uintptr) int { return gentraceback(^uintptr(0), ^uintptr(0), 0, gp, skip, &pcbuf[0], len(pcbuf), nil, nil, 0) } -func showframe(f funcInfo, gp *g, firstFrame bool) bool { +func showframe(f funcInfo, gp *g, firstFrame, elideWrapper bool) bool { g := getg() if g.m.throwing > 0 && gp != nil && (gp == g.m.curg || gp == g.m.caughtsig.ptr()) { return true @@ -738,8 +746,18 @@ func showframe(f funcInfo, gp *g, firstFrame bool) bool { return true } + if !f.valid() { + return false + } + + if elideWrapper { + file, _ := funcline(f, f.entry) + if file == "" { + return false + } + } + name := funcname(f) - file, _ := funcline(f, f.entry) // Special case: always show runtime.gopanic frame // in the middle of a stack trace, so that we can @@ -750,7 +768,7 @@ func showframe(f funcInfo, gp *g, firstFrame bool) bool { return true } - return f.valid() && contains(name, ".") && (!hasprefix(name, "runtime.") || isExportedRuntime(name)) && file != "" + return contains(name, ".") && (!hasprefix(name, "runtime.") || isExportedRuntime(name)) } // isExportedRuntime reports whether name is an exported runtime function. @@ -760,6 +778,14 @@ func isExportedRuntime(name string) bool { return len(name) > n && name[:n] == "runtime." && 'A' <= name[n] && name[n] <= 'Z' } +// elideWrapperCalling returns whether a wrapper function that called +// function "name" should be elided from stack traces. +func elideWrapperCalling(name string) bool { + // If the wrapper called a panic function instead of the + // wrapped function, we want to include it in stacks. + return !(name == "runtime.gopanic" || name == "runtime.sigpanic" || name == "runtime.panicwrap") +} + var gStatusStrings = [...]string{ _Gidle: "idle", _Grunnable: "runnable", -- cgit v1.3 From 2e5011d8029e29f37bae359f2b1d398212a961ee Mon Sep 17 00:00:00 2001 From: Austin Clements Date: Fri, 1 Dec 2017 15:15:42 -0500 Subject: runtime: even more TestStackGrowth timeout debugging This adds logging for the expected duration of a growStack, plus progress information on the growStack that timed out. Updates #19381. Change-Id: Ic358f8350f499ff22dd213b658aece7d1aa62675 Reviewed-on: https://go-review.googlesource.com/81556 Run-TryBot: Austin Clements TryBot-Result: Gobot Gobot Reviewed-by: Brad Fitzpatrick --- src/runtime/stack_test.go | 23 +++++++++++++++++------ 1 file changed, 17 insertions(+), 6 deletions(-) (limited to 'src/runtime/stack_test.go') diff --git a/src/runtime/stack_test.go b/src/runtime/stack_test.go index cb0e08256b..0fed241704 100644 --- a/src/runtime/stack_test.go +++ b/src/runtime/stack_test.go @@ -81,10 +81,13 @@ func TestStackGrowth(t *testing.T) { var wg sync.WaitGroup // in a normal goroutine + var growDuration time.Duration // For debugging failures wg.Add(1) go func() { defer wg.Done() - growStack() + start := time.Now() + growStack(nil) + growDuration = time.Since(start) }() wg.Wait() @@ -93,7 +96,7 @@ func TestStackGrowth(t *testing.T) { go func() { defer wg.Done() LockOSThread() - growStack() + growStack(nil) UnlockOSThread() }() wg.Wait() @@ -103,12 +106,14 @@ func TestStackGrowth(t *testing.T) { go func() { defer wg.Done() done := make(chan bool) - var started uint32 + var startTime time.Time + var started, progress uint32 go func() { s := new(string) SetFinalizer(s, func(ss *string) { + startTime = time.Now() atomic.StoreUint32(&started, 1) - growStack() + growStack(&progress) done <- true }) s = nil @@ -121,7 +126,10 @@ func TestStackGrowth(t *testing.T) { case <-time.After(20 * time.Second): if atomic.LoadUint32(&started) == 0 { t.Log("finalizer did not start") + } else { + t.Logf("finalizer started %s ago and finished %d iterations", time.Since(startTime), atomic.LoadUint32(&progress)) } + t.Log("first growStack took", growDuration) t.Error("finalizer did not run") return } @@ -134,7 +142,7 @@ func TestStackGrowth(t *testing.T) { // growStack() //} -func growStack() { +func growStack(progress *uint32) { n := 1 << 10 if testing.Short() { n = 1 << 8 @@ -145,6 +153,9 @@ func growStack() { if x != i+1 { panic("stack is corrupted") } + if progress != nil { + atomic.StoreUint32(progress, uint32(i)) + } } GC() } @@ -234,7 +245,7 @@ func TestDeferPtrs(t *testing.T) { } }() defer set(&y, 42) - growStack() + growStack(nil) } type bigBuf [4 * 1024]byte -- cgit v1.3