From bfe67f6332de352b32a468b7ff21b721ba1ee3ad Mon Sep 17 00:00:00 2001 From: Peter Edge Date: Fri, 17 Feb 2017 15:15:48 +0100 Subject: [PATCH 1/6] Clean up stacktrace --- config_test.go | 2 +- field.go | 8 ++++++-- field_test.go | 2 +- stacktrace.go | 48 +++++++++++++++++++++++++++++++++------------- stacktrace_test.go | 23 ++++++++++++++-------- 5 files changed, 58 insertions(+), 25 deletions(-) diff --git a/config_test.go b/config_test.go index a4ad6229f..d77f8bc94 100644 --- a/config_test.go +++ b/config_test.go @@ -50,7 +50,7 @@ func TestConfig(t *testing.T) { expectRe: "DEBUG\t.*go.uber.org/zap/config_test.go:" + `\d+` + "\tdebug\t" + `{"k": "v", "z": "zz"}` + "\n" + "INFO\t.*go.uber.org/zap/config_test.go:" + `\d+` + "\tinfo\t" + `{"k": "v", "z": "zz"}` + "\n" + "WARN\t.*go.uber.org/zap/config_test.go:" + `\d+` + "\twarn\t" + `{"k": "v", "z": "zz"}` + "\n" + - `goroutine \d+ \[running\]:`, + `go.uber.org/zap.TestConfig.func1`, }, } diff --git a/field.go b/field.go index c8ff1372a..17d530657 100644 --- a/field.go +++ b/field.go @@ -195,14 +195,18 @@ func NamedError(key string, err error) zapcore.Field { // extremely expensive (relatively speaking); this function both makes an // allocation and takes ~10 microseconds. func Stack(key string) zapcore.Field { + return stack(key, 4) +} + +// needed for testing +func stack(key string, skip int) zapcore.Field { // Try to avoid allocating a buffer. buf := bufferpool.Get() - bs := buf.Bytes() // Returning the stacktrace as a string costs an allocation, but saves us // from expanding the zapcore.Field union struct to include a byte slice. Since // taking a stacktrace is already so expensive (~10us), the extra allocation // is okay. - field := String(key, takeStacktrace(bs[:cap(bs)], false)) + field := String(key, takeStacktrace(buf, skip)) bufferpool.Put(buf) return field } diff --git a/field_test.go b/field_test.go index 7c1a1295f..acd2742fd 100644 --- a/field_test.go +++ b/field_test.go @@ -164,7 +164,7 @@ func TestFieldConstructors(t *testing.T) { } func TestStackField(t *testing.T) { - f := Stack("stacktrace") + f := stack("stacktrace", 0) assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") assert.Contains(t, f.String, "zap.TestStackField", "Expected stacktrace to contain caller.") diff --git a/stacktrace.go b/stacktrace.go index 842145759..681905f54 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -20,23 +20,45 @@ package zap -import "runtime" +import ( + "runtime" + + "go.uber.org/zap/buffer" +) // takeStacktrace attempts to use the provided byte slice to take a stacktrace. // If the provided slice isn't large enough, takeStacktrace will allocate // successively larger slices until it can capture the whole stack. -func takeStacktrace(buf []byte, includeAllGoroutines bool) string { - if len(buf) == 0 { - // We may have been passed a nil byte slice. - buf = make([]byte, 1024) +func takeStacktrace(buffer *buffer.Buffer, skip int) string { + size := 16 + programCounters := make([]uintptr, size) + n := runtime.Callers(skip+2, programCounters) + for n >= size { + size *= 2 + programCounters = make([]uintptr, size) + n = runtime.Callers(skip+2, programCounters) } - n := runtime.Stack(buf, includeAllGoroutines) - for n >= len(buf) { - // Buffer wasn't large enough, allocate a larger one. No need to copy - // previous buffer's contents. - size := 2 * n - buf = make([]byte, size) - n = runtime.Stack(buf, includeAllGoroutines) + programCounters = programCounters[:n] + + for i, programCounter := range programCounters { + f := runtime.FuncForPC(programCounter) + name := f.Name() + // this strips everything below runtime.main + // TODO(pedge): we might want to do a better check than this + if name == "runtime.main" { + break + } + // heh + if i != 0 { + buffer.AppendByte('\n') + } + file, line := f.FileLine(programCounter - 1) + buffer.AppendString(f.Name()) + buffer.AppendByte('\n') + buffer.AppendByte('\t') + buffer.AppendString(file) + buffer.AppendByte(':') + buffer.AppendInt(int64(line)) } - return string(buf[:n]) + return buffer.String() } diff --git a/stacktrace_test.go b/stacktrace_test.go index 7de5cfafc..e9f98df49 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -22,19 +22,26 @@ package zap import ( "testing" + "unicode/utf8" + + "go.uber.org/zap/internal/bufferpool" "github.com/stretchr/testify/assert" ) func TestTakeStacktrace(t *testing.T) { - // Even if we pass a tiny buffer, takeStacktrace should allocate until it - // can capture the whole stacktrace. - traceNil := takeStacktrace(nil, false) - traceTiny := takeStacktrace(make([]byte, 1), false) - for _, trace := range []string{traceNil, traceTiny} { - // The top frame should be takeStacktrace. - assert.Contains(t, trace, "zap.takeStacktrace", "Stacktrace should contain the takeStacktrace function.") - // The stacktrace should also capture its immediate caller. + traceZero := takeStacktrace(bufferpool.Get(), 0) + for _, trace := range []string{traceZero} { + // The stacktrace should also its immediate caller. assert.Contains(t, trace, "TestTakeStacktrace", "Stacktrace should contain the test function.") } } + +func TestRunes(t *testing.T) { + // https://golang.org/src/bytes/buffer.go?s=8208:8261#L237 + // I think this test might not be needed, because this might be checked + // implicitly by the fact that we can pass these as bytes to AppendByte + assert.True(t, '\n' < utf8.RuneSelf, `You can't cast '\n' to a byte, stop being silly`) + assert.True(t, '\t' < utf8.RuneSelf, `You can't cast '\t' to a byte, stop being silly`) + assert.True(t, ':' < utf8.RuneSelf, `You can't cast ':' to a byte, stop being silly`) +} From d1eb37794f8debbeaf454874960d980c980836fb Mon Sep 17 00:00:00 2001 From: Peter Edge Date: Mon, 20 Feb 2017 13:42:25 +0100 Subject: [PATCH 2/6] Use strings.HasPrefix instead of skip callers for takeStacktrace --- field.go | 12 +--------- field_test.go | 2 +- stacktrace.go | 55 ++++++++++++++++++++++++++++++++++------------ stacktrace_test.go | 20 +++-------------- 4 files changed, 46 insertions(+), 43 deletions(-) diff --git a/field.go b/field.go index 17d530657..f04cb04de 100644 --- a/field.go +++ b/field.go @@ -25,7 +25,6 @@ import ( "math" "time" - "go.uber.org/zap/internal/bufferpool" "go.uber.org/zap/zapcore" ) @@ -195,20 +194,11 @@ func NamedError(key string, err error) zapcore.Field { // extremely expensive (relatively speaking); this function both makes an // allocation and takes ~10 microseconds. func Stack(key string) zapcore.Field { - return stack(key, 4) -} - -// needed for testing -func stack(key string, skip int) zapcore.Field { - // Try to avoid allocating a buffer. - buf := bufferpool.Get() // Returning the stacktrace as a string costs an allocation, but saves us // from expanding the zapcore.Field union struct to include a byte slice. Since // taking a stacktrace is already so expensive (~10us), the extra allocation // is okay. - field := String(key, takeStacktrace(buf, skip)) - bufferpool.Put(buf) - return field + return String(key, takeStacktrace()) } // Duration constructs a field with the given key and value. The encoder diff --git a/field_test.go b/field_test.go index acd2742fd..7c1a1295f 100644 --- a/field_test.go +++ b/field_test.go @@ -164,7 +164,7 @@ func TestFieldConstructors(t *testing.T) { } func TestStackField(t *testing.T) { - f := stack("stacktrace", 0) + f := Stack("stacktrace") assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") assert.Contains(t, f.String, "zap.TestStackField", "Expected stacktrace to contain caller.") diff --git a/stacktrace.go b/stacktrace.go index 681905f54..dda422524 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -22,43 +22,70 @@ package zap import ( "runtime" + "strings" + "sync" - "go.uber.org/zap/buffer" + "go.uber.org/zap/internal/bufferpool" +) + +var ( + defaultUintptrSliceSize = 128 + uintptrPool = sync.Pool{ + New: func() interface{} { + return make([]uintptr, defaultUintptrSliceSize) + }, + } ) // takeStacktrace attempts to use the provided byte slice to take a stacktrace. // If the provided slice isn't large enough, takeStacktrace will allocate // successively larger slices until it can capture the whole stack. -func takeStacktrace(buffer *buffer.Buffer, skip int) string { - size := 16 - programCounters := make([]uintptr, size) - n := runtime.Callers(skip+2, programCounters) +func takeStacktrace() string { + buffer := bufferpool.Get() + programCounters := getUintptrSlice() + n := runtime.Callers(0, programCounters) + size := defaultUintptrSliceSize for n >= size { size *= 2 + // Do not put programCounters back in pool, will put larger buffer in + // This is in case our size is always wrong, we optimize to pul + // correctly-sized buffers back in the pool programCounters = make([]uintptr, size) - n = runtime.Callers(skip+2, programCounters) + n = runtime.Callers(0, programCounters) } programCounters = programCounters[:n] - for i, programCounter := range programCounters { + i := 0 + for _, programCounter := range programCounters { f := runtime.FuncForPC(programCounter) name := f.Name() - // this strips everything below runtime.main - // TODO(pedge): we might want to do a better check than this - if name == "runtime.main" { - break + if strings.HasPrefix(name, "runtime.") || strings.HasPrefix(name, "go.uber.org/zap.") { + continue } - // heh if i != 0 { buffer.AppendByte('\n') } + i++ file, line := f.FileLine(programCounter - 1) - buffer.AppendString(f.Name()) + buffer.AppendString(name) buffer.AppendByte('\n') buffer.AppendByte('\t') buffer.AppendString(file) buffer.AppendByte(':') buffer.AppendInt(int64(line)) } - return buffer.String() + + s := buffer.String() + bufferpool.Put(buffer) + putUintptrSlice(programCounters) + return s +} + +func getUintptrSlice() []uintptr { + s := uintptrPool.Get().([]uintptr) + return s +} + +func putUintptrSlice(s []uintptr) { + uintptrPool.Put(s) } diff --git a/stacktrace_test.go b/stacktrace_test.go index e9f98df49..4af107d2c 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -22,26 +22,12 @@ package zap import ( "testing" - "unicode/utf8" - - "go.uber.org/zap/internal/bufferpool" "github.com/stretchr/testify/assert" ) func TestTakeStacktrace(t *testing.T) { - traceZero := takeStacktrace(bufferpool.Get(), 0) - for _, trace := range []string{traceZero} { - // The stacktrace should also its immediate caller. - assert.Contains(t, trace, "TestTakeStacktrace", "Stacktrace should contain the test function.") - } -} - -func TestRunes(t *testing.T) { - // https://golang.org/src/bytes/buffer.go?s=8208:8261#L237 - // I think this test might not be needed, because this might be checked - // implicitly by the fact that we can pass these as bytes to AppendByte - assert.True(t, '\n' < utf8.RuneSelf, `You can't cast '\n' to a byte, stop being silly`) - assert.True(t, '\t' < utf8.RuneSelf, `You can't cast '\t' to a byte, stop being silly`) - assert.True(t, ':' < utf8.RuneSelf, `You can't cast ':' to a byte, stop being silly`) + trace := takeStacktrace() + // The stacktrace should also its immediate caller. + assert.Contains(t, trace, "TestTakeStacktrace", "Stacktrace should contain the test function.") } From 7c29d8921dbc6e321367183db96ca4f6ad2e7666 Mon Sep 17 00:00:00 2001 From: Peter Edge Date: Wed, 22 Feb 2017 17:26:56 +0100 Subject: [PATCH 3/6] Update per comments --- config_test.go | 30 ++++++++++++++++------------ field_test.go | 12 +++++++----- logger_test.go | 31 +++++++++++++++-------------- stacktrace.go | 49 ++++++++++++++++++++++++---------------------- stacktrace_test.go | 43 ++++++++++++++++++++++++++++++++++++---- 5 files changed, 106 insertions(+), 59 deletions(-) diff --git a/config_test.go b/config_test.go index d77f8bc94..9b23b2dd0 100644 --- a/config_test.go +++ b/config_test.go @@ -50,7 +50,7 @@ func TestConfig(t *testing.T) { expectRe: "DEBUG\t.*go.uber.org/zap/config_test.go:" + `\d+` + "\tdebug\t" + `{"k": "v", "z": "zz"}` + "\n" + "INFO\t.*go.uber.org/zap/config_test.go:" + `\d+` + "\tinfo\t" + `{"k": "v", "z": "zz"}` + "\n" + "WARN\t.*go.uber.org/zap/config_test.go:" + `\d+` + "\twarn\t" + `{"k": "v", "z": "zz"}` + "\n" + - `go.uber.org/zap.TestConfig.func1`, + `go.uber.org/zap.Stack`, }, } @@ -68,19 +68,25 @@ func TestConfig(t *testing.T) { logger, err := tt.cfg.Build(Hooks(hook)) require.NoError(t, err, "Unexpected error constructing logger.") - logger.Debug("debug") - logger.Info("info") - logger.Warn("warn") + withStacktraceIgnorePrefixes([]string{}, func() { + logger.Debug("debug") + logger.Info("info") + logger.Warn("warn") - byteContents, err := ioutil.ReadAll(temp) - require.NoError(t, err, "Couldn't read log contents from temp file.") - logs := string(byteContents) - assert.Regexp(t, tt.expectRe, logs, "Unexpected log output.") + byteContents, err := ioutil.ReadAll(temp) + // not doing require so no problem with lock in withStacktraceIgnorePrefixes + assert.NoError(t, err, "Couldn't read log contents from temp file.") + if err != nil { + return + } + logs := string(byteContents) + assert.Regexp(t, tt.expectRe, logs, "Unexpected log output.") - for i := 0; i < 200; i++ { - logger.Info("sampling") - } - assert.Equal(t, tt.expectN, count.Load(), "Hook called an unexpected number of times.") + for i := 0; i < 200; i++ { + logger.Info("sampling") + } + assert.Equal(t, tt.expectN, count.Load(), "Hook called an unexpected number of times.") + }) }) } } diff --git a/field_test.go b/field_test.go index 7c1a1295f..2b0701e1e 100644 --- a/field_test.go +++ b/field_test.go @@ -164,9 +164,11 @@ func TestFieldConstructors(t *testing.T) { } func TestStackField(t *testing.T) { - f := Stack("stacktrace") - assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") - assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") - assert.Contains(t, f.String, "zap.TestStackField", "Expected stacktrace to contain caller.") - assertCanBeReused(t, f) + withStacktraceIgnorePrefixes([]string{}, func() { + f := Stack("stacktrace") + assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") + assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") + assert.Contains(t, f.String, "zap.TestStackField", "Expected stacktrace to contain caller.") + assertCanBeReused(t, f) + }) } diff --git a/logger_test.go b/logger_test.go index d6c832e88..cddb82e40 100644 --- a/logger_test.go +++ b/logger_test.go @@ -360,23 +360,24 @@ func TestLoggerAddCallerFail(t *testing.T) { } func TestLoggerAddStacktrace(t *testing.T) { - assertHasStack := func(t testing.TB, obs observer.LoggedEntry) { - assert.Contains(t, obs.Entry.Stack, "zap.TestLoggerAddStacktrace", "Expected to find test function in stacktrace.") - } - - withLogger(t, DebugLevel, opts(AddStacktrace(InfoLevel)), func(logger *Logger, logs *observer.ObservedLogs) { - logger.Debug("") - assert.Empty( - t, - logs.AllUntimed()[0].Entry.Stack, - "Unexpected stacktrack at DebugLevel.", - ) + withStacktraceIgnorePrefixes([]string{}, func() { + assertHasStack := func(t testing.TB, obs observer.LoggedEntry) { + assert.Contains(t, obs.Entry.Stack, "zap.TestLoggerAddStacktrace", "Expected to find test function in stacktrace.") + } + withLogger(t, DebugLevel, opts(AddStacktrace(InfoLevel)), func(logger *Logger, logs *observer.ObservedLogs) { + logger.Debug("") + assert.Empty( + t, + logs.AllUntimed()[0].Entry.Stack, + "Unexpected stacktrack at DebugLevel.", + ) - logger.Info("") - assertHasStack(t, logs.AllUntimed()[1]) + logger.Info("") + assertHasStack(t, logs.AllUntimed()[1]) - logger.Warn("") - assertHasStack(t, logs.AllUntimed()[2]) + logger.Warn("") + assertHasStack(t, logs.AllUntimed()[2]) + }) }) } diff --git a/stacktrace.go b/stacktrace.go index dda422524..b81d375c7 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -29,10 +29,13 @@ import ( ) var ( - defaultUintptrSliceSize = 128 - uintptrPool = sync.Pool{ + _stacktraceIgnorePrefixes = []string{ + "go.uber.org/zap", + "runtime.", + } + _stacktraceUintptrPool = sync.Pool{ New: func() interface{} { - return make([]uintptr, defaultUintptrSliceSize) + return make([]uintptr, 64) }, } ) @@ -42,24 +45,27 @@ var ( // successively larger slices until it can capture the whole stack. func takeStacktrace() string { buffer := bufferpool.Get() - programCounters := getUintptrSlice() - n := runtime.Callers(0, programCounters) - size := defaultUintptrSliceSize - for n >= size { - size *= 2 + programCounters := _stacktraceUintptrPool.Get().([]uintptr) + defer bufferpool.Put(buffer) + defer _stacktraceUintptrPool.Put(programCounters) + + for { + n := runtime.Callers(2, programCounters) + if n < len(programCounters) { + programCounters = programCounters[:n] + break + } // Do not put programCounters back in pool, will put larger buffer in // This is in case our size is always wrong, we optimize to pul // correctly-sized buffers back in the pool - programCounters = make([]uintptr, size) - n = runtime.Callers(0, programCounters) + programCounters = make([]uintptr, len(programCounters)*2) } - programCounters = programCounters[:n] i := 0 for _, programCounter := range programCounters { f := runtime.FuncForPC(programCounter) name := f.Name() - if strings.HasPrefix(name, "runtime.") || strings.HasPrefix(name, "go.uber.org/zap.") { + if shouldIgnoreStacktraceName(name) { continue } if i != 0 { @@ -75,17 +81,14 @@ func takeStacktrace() string { buffer.AppendInt(int64(line)) } - s := buffer.String() - bufferpool.Put(buffer) - putUintptrSlice(programCounters) - return s + return buffer.String() } -func getUintptrSlice() []uintptr { - s := uintptrPool.Get().([]uintptr) - return s -} - -func putUintptrSlice(s []uintptr) { - uintptrPool.Put(s) +func shouldIgnoreStacktraceName(name string) bool { + for _, prefix := range _stacktraceIgnorePrefixes { + if strings.HasPrefix(name, prefix) { + return true + } + } + return false } diff --git a/stacktrace_test.go b/stacktrace_test.go index 4af107d2c..d5264a7cd 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -21,13 +21,48 @@ package zap import ( + "strings" + "sync" "testing" "github.com/stretchr/testify/assert" ) -func TestTakeStacktrace(t *testing.T) { - trace := takeStacktrace() - // The stacktrace should also its immediate caller. - assert.Contains(t, trace, "TestTakeStacktrace", "Stacktrace should contain the test function.") +var ( + _stacktraceTestLock sync.Mutex +) + +func TestEmptyStacktrace(t *testing.T) { + withStacktraceIgnorePrefixes( + []string{ + "go.uber.org/zap", + "runtime.", + "testing.", + }, + func() { + assert.Empty(t, takeStacktrace(), "stacktrace should be empty if we ignore runtime, testing, and functions in this package") + }, + ) +} + +func TestAllStacktrace(t *testing.T) { + withStacktraceIgnorePrefixes( + []string{}, + func() { + stacktrace := takeStacktrace() + assert.True(t, strings.HasPrefix(stacktrace, "go.uber.org/zap.TestAllStacktrace"), + "stacktrace should start with TestAllStacktrace if no prefixes set, but is %s", stacktrace) + }, + ) +} + +// What happens with require functions? If they completely break out of the +// function, will this lock never get unlocked? +func withStacktraceIgnorePrefixes(prefixes []string, f func()) { + _stacktraceTestLock.Lock() + existing := _stacktraceIgnorePrefixes + _stacktraceIgnorePrefixes = prefixes + f() + _stacktraceIgnorePrefixes = existing + _stacktraceTestLock.Unlock() } From bf6975fffbd5e83980a9b5134cffc6256e3558de Mon Sep 17 00:00:00 2001 From: Peter Edge Date: Tue, 28 Feb 2017 11:15:22 +0100 Subject: [PATCH 4/6] Update after comments --- config_test.go | 8 ++------ field_test.go | 2 +- logger_test.go | 2 +- stacktrace.go | 31 +++++++++++++++++++++---------- stacktrace_test.go | 15 +++++++++------ 5 files changed, 34 insertions(+), 24 deletions(-) diff --git a/config_test.go b/config_test.go index 9b23b2dd0..1fcb4e0d7 100644 --- a/config_test.go +++ b/config_test.go @@ -68,17 +68,13 @@ func TestConfig(t *testing.T) { logger, err := tt.cfg.Build(Hooks(hook)) require.NoError(t, err, "Unexpected error constructing logger.") - withStacktraceIgnorePrefixes([]string{}, func() { + withNoStacktraceIgnorePrefixes(func() { logger.Debug("debug") logger.Info("info") logger.Warn("warn") byteContents, err := ioutil.ReadAll(temp) - // not doing require so no problem with lock in withStacktraceIgnorePrefixes - assert.NoError(t, err, "Couldn't read log contents from temp file.") - if err != nil { - return - } + require.NoError(t, err, "Couldn't read log contents from temp file.") logs := string(byteContents) assert.Regexp(t, tt.expectRe, logs, "Unexpected log output.") diff --git a/field_test.go b/field_test.go index 2b0701e1e..29567b868 100644 --- a/field_test.go +++ b/field_test.go @@ -164,7 +164,7 @@ func TestFieldConstructors(t *testing.T) { } func TestStackField(t *testing.T) { - withStacktraceIgnorePrefixes([]string{}, func() { + withNoStacktraceIgnorePrefixes(func() { f := Stack("stacktrace") assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") diff --git a/logger_test.go b/logger_test.go index cddb82e40..39ccc3858 100644 --- a/logger_test.go +++ b/logger_test.go @@ -360,7 +360,7 @@ func TestLoggerAddCallerFail(t *testing.T) { } func TestLoggerAddStacktrace(t *testing.T) { - withStacktraceIgnorePrefixes([]string{}, func() { + withNoStacktraceIgnorePrefixes(func() { assertHasStack := func(t testing.TB, obs observer.LoggedEntry) { assert.Contains(t, obs.Entry.Stack, "zap.TestLoggerAddStacktrace", "Expected to find test function in stacktrace.") } diff --git a/stacktrace.go b/stacktrace.go index b81d375c7..26b782b10 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -31,11 +31,12 @@ import ( var ( _stacktraceIgnorePrefixes = []string{ "go.uber.org/zap", - "runtime.", + "runtime.goexit", + "runtime.main", } - _stacktraceUintptrPool = sync.Pool{ + _stacktracePool = sync.Pool{ New: func() interface{} { - return make([]uintptr, 64) + return newProgramCounters(64) }, } ) @@ -45,24 +46,26 @@ var ( // successively larger slices until it can capture the whole stack. func takeStacktrace() string { buffer := bufferpool.Get() - programCounters := _stacktraceUintptrPool.Get().([]uintptr) defer bufferpool.Put(buffer) - defer _stacktraceUintptrPool.Put(programCounters) + programCounters := _stacktracePool.Get().(*programCounters) + defer _stacktracePool.Put(programCounters) for { - n := runtime.Callers(2, programCounters) - if n < len(programCounters) { - programCounters = programCounters[:n] + // skipping 2 skips the call to runtime.Counters and takeStacktrace + // so that the program counters start at the caller of takeStacktrace + n := runtime.Callers(2, programCounters.pcs) + if n < len(programCounters.pcs) { + programCounters.pcs = programCounters.pcs[:n] break } // Do not put programCounters back in pool, will put larger buffer in // This is in case our size is always wrong, we optimize to pul // correctly-sized buffers back in the pool - programCounters = make([]uintptr, len(programCounters)*2) + programCounters = newProgramCounters(len(programCounters.pcs) * 2) } i := 0 - for _, programCounter := range programCounters { + for _, programCounter := range programCounters.pcs { f := runtime.FuncForPC(programCounter) name := f.Name() if shouldIgnoreStacktraceName(name) { @@ -92,3 +95,11 @@ func shouldIgnoreStacktraceName(name string) bool { } return false } + +type programCounters struct { + pcs []uintptr +} + +func newProgramCounters(size int) *programCounters { + return &programCounters{make([]uintptr, size)} +} diff --git a/stacktrace_test.go b/stacktrace_test.go index d5264a7cd..38b03de93 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -46,8 +46,7 @@ func TestEmptyStacktrace(t *testing.T) { } func TestAllStacktrace(t *testing.T) { - withStacktraceIgnorePrefixes( - []string{}, + withNoStacktraceIgnorePrefixes( func() { stacktrace := takeStacktrace() assert.True(t, strings.HasPrefix(stacktrace, "go.uber.org/zap.TestAllStacktrace"), @@ -56,13 +55,17 @@ func TestAllStacktrace(t *testing.T) { ) } -// What happens with require functions? If they completely break out of the -// function, will this lock never get unlocked? +func withNoStacktraceIgnorePrefixes(f func()) { + withStacktraceIgnorePrefixes([]string{}, f) +} + func withStacktraceIgnorePrefixes(prefixes []string, f func()) { _stacktraceTestLock.Lock() + defer _stacktraceTestLock.Unlock() existing := _stacktraceIgnorePrefixes _stacktraceIgnorePrefixes = prefixes + defer func() { + _stacktraceIgnorePrefixes = existing + }() f() - _stacktraceIgnorePrefixes = existing - _stacktraceTestLock.Unlock() } From 311ad66bb14d26d329847b40186d8b7560107113 Mon Sep 17 00:00:00 2001 From: Peter Edge Date: Mon, 6 Mar 2017 13:47:14 -0500 Subject: [PATCH 5/6] Do not skip go.uber.org/zap calls when taking a stacktrace --- stacktrace.go | 1 - 1 file changed, 1 deletion(-) diff --git a/stacktrace.go b/stacktrace.go index 26b782b10..3b9552cd1 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -30,7 +30,6 @@ import ( var ( _stacktraceIgnorePrefixes = []string{ - "go.uber.org/zap", "runtime.goexit", "runtime.main", } From e48738f8985f3dbf15fda84da4bd1adda5d59919 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Tue, 7 Mar 2017 10:02:58 -0800 Subject: [PATCH 6/6] Remove some now-unnecessary changes --- config_test.go | 24 ++++++++++------------ field.go | 4 ++-- field_test.go | 12 +++++------ logger_test.go | 30 +++++++++++++--------------- options.go | 3 +-- stacktrace.go | 14 +++++-------- stacktrace_test.go | 50 ++++++++++------------------------------------ 7 files changed, 48 insertions(+), 89 deletions(-) diff --git a/config_test.go b/config_test.go index 1fcb4e0d7..293f87151 100644 --- a/config_test.go +++ b/config_test.go @@ -68,21 +68,19 @@ func TestConfig(t *testing.T) { logger, err := tt.cfg.Build(Hooks(hook)) require.NoError(t, err, "Unexpected error constructing logger.") - withNoStacktraceIgnorePrefixes(func() { - logger.Debug("debug") - logger.Info("info") - logger.Warn("warn") + logger.Debug("debug") + logger.Info("info") + logger.Warn("warn") - byteContents, err := ioutil.ReadAll(temp) - require.NoError(t, err, "Couldn't read log contents from temp file.") - logs := string(byteContents) - assert.Regexp(t, tt.expectRe, logs, "Unexpected log output.") + byteContents, err := ioutil.ReadAll(temp) + require.NoError(t, err, "Couldn't read log contents from temp file.") + logs := string(byteContents) + assert.Regexp(t, tt.expectRe, logs, "Unexpected log output.") - for i := 0; i < 200; i++ { - logger.Info("sampling") - } - assert.Equal(t, tt.expectN, count.Load(), "Hook called an unexpected number of times.") - }) + for i := 0; i < 200; i++ { + logger.Info("sampling") + } + assert.Equal(t, tt.expectN, count.Load(), "Hook called an unexpected number of times.") }) } } diff --git a/field.go b/field.go index f04cb04de..905defe87 100644 --- a/field.go +++ b/field.go @@ -191,8 +191,8 @@ func NamedError(key string, err error) zapcore.Field { // Stack constructs a field that stores a stacktrace of the current goroutine // under provided key. Keep in mind that taking a stacktrace is eager and -// extremely expensive (relatively speaking); this function both makes an -// allocation and takes ~10 microseconds. +// expensive (relatively speaking); this function both makes an allocation and +// takes about two microseconds. func Stack(key string) zapcore.Field { // Returning the stacktrace as a string costs an allocation, but saves us // from expanding the zapcore.Field union struct to include a byte slice. Since diff --git a/field_test.go b/field_test.go index 29567b868..7c1a1295f 100644 --- a/field_test.go +++ b/field_test.go @@ -164,11 +164,9 @@ func TestFieldConstructors(t *testing.T) { } func TestStackField(t *testing.T) { - withNoStacktraceIgnorePrefixes(func() { - f := Stack("stacktrace") - assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") - assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") - assert.Contains(t, f.String, "zap.TestStackField", "Expected stacktrace to contain caller.") - assertCanBeReused(t, f) - }) + f := Stack("stacktrace") + assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") + assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") + assert.Contains(t, f.String, "zap.TestStackField", "Expected stacktrace to contain caller.") + assertCanBeReused(t, f) } diff --git a/logger_test.go b/logger_test.go index 39ccc3858..1c220a2f5 100644 --- a/logger_test.go +++ b/logger_test.go @@ -360,24 +360,22 @@ func TestLoggerAddCallerFail(t *testing.T) { } func TestLoggerAddStacktrace(t *testing.T) { - withNoStacktraceIgnorePrefixes(func() { - assertHasStack := func(t testing.TB, obs observer.LoggedEntry) { - assert.Contains(t, obs.Entry.Stack, "zap.TestLoggerAddStacktrace", "Expected to find test function in stacktrace.") - } - withLogger(t, DebugLevel, opts(AddStacktrace(InfoLevel)), func(logger *Logger, logs *observer.ObservedLogs) { - logger.Debug("") - assert.Empty( - t, - logs.AllUntimed()[0].Entry.Stack, - "Unexpected stacktrack at DebugLevel.", - ) + assertHasStack := func(t testing.TB, obs observer.LoggedEntry) { + assert.Contains(t, obs.Entry.Stack, "zap.TestLoggerAddStacktrace", "Expected to find test function in stacktrace.") + } + withLogger(t, DebugLevel, opts(AddStacktrace(InfoLevel)), func(logger *Logger, logs *observer.ObservedLogs) { + logger.Debug("") + assert.Empty( + t, + logs.AllUntimed()[0].Entry.Stack, + "Unexpected stacktrack at DebugLevel.", + ) - logger.Info("") - assertHasStack(t, logs.AllUntimed()[1]) + logger.Info("") + assertHasStack(t, logs.AllUntimed()[1]) - logger.Warn("") - assertHasStack(t, logs.AllUntimed()[2]) - }) + logger.Warn("") + assertHasStack(t, logs.AllUntimed()[2]) }) } diff --git a/options.go b/options.go index 405a1b34c..29fdbf84e 100644 --- a/options.go +++ b/options.go @@ -92,8 +92,7 @@ func AddCallerSkip(skip int) Option { } // AddStacktrace configures the Logger to record a stack trace for all messages at -// or above a given level. Keep in mind that taking a stacktrace takes several -// microseconds; relative to the cost of logging, this is quite slow. +// or above a given level. func AddStacktrace(lvl zapcore.LevelEnabler) Option { return optionFunc(func(log *Logger) { log.addStack = lvl diff --git a/stacktrace.go b/stacktrace.go index 3b9552cd1..2726d84c7 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -40,9 +40,6 @@ var ( } ) -// takeStacktrace attempts to use the provided byte slice to take a stacktrace. -// If the provided slice isn't large enough, takeStacktrace will allocate -// successively larger slices until it can capture the whole stack. func takeStacktrace() string { buffer := bufferpool.Get() defer bufferpool.Put(buffer) @@ -50,16 +47,15 @@ func takeStacktrace() string { defer _stacktracePool.Put(programCounters) for { - // skipping 2 skips the call to runtime.Counters and takeStacktrace - // so that the program counters start at the caller of takeStacktrace + // Skip the call to runtime.Counters and takeStacktrace so that the + // program counters start at the caller of takeStacktrace. n := runtime.Callers(2, programCounters.pcs) - if n < len(programCounters.pcs) { + if n < cap(programCounters.pcs) { programCounters.pcs = programCounters.pcs[:n] break } - // Do not put programCounters back in pool, will put larger buffer in - // This is in case our size is always wrong, we optimize to pul - // correctly-sized buffers back in the pool + // Don't put the too-short counter slice back into the pool; this lets + // the pool adjust if we consistently take deep stacktraces. programCounters = newProgramCounters(len(programCounters.pcs) * 2) } diff --git a/stacktrace_test.go b/stacktrace_test.go index 38b03de93..1d5357637 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -22,50 +22,20 @@ package zap import ( "strings" - "sync" "testing" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) -var ( - _stacktraceTestLock sync.Mutex -) - -func TestEmptyStacktrace(t *testing.T) { - withStacktraceIgnorePrefixes( - []string{ - "go.uber.org/zap", - "runtime.", - "testing.", - }, - func() { - assert.Empty(t, takeStacktrace(), "stacktrace should be empty if we ignore runtime, testing, and functions in this package") - }, - ) -} - -func TestAllStacktrace(t *testing.T) { - withNoStacktraceIgnorePrefixes( - func() { - stacktrace := takeStacktrace() - assert.True(t, strings.HasPrefix(stacktrace, "go.uber.org/zap.TestAllStacktrace"), - "stacktrace should start with TestAllStacktrace if no prefixes set, but is %s", stacktrace) - }, +func TestTakeStacktrace(t *testing.T) { + trace := takeStacktrace() + lines := strings.Split(trace, "\n") + require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.") + assert.Contains( + t, + lines[0], + "TestTakeStacktrace", + "Expected stacktrace to start with this test function, but top frame is %s.", lines[0], ) } - -func withNoStacktraceIgnorePrefixes(f func()) { - withStacktraceIgnorePrefixes([]string{}, f) -} - -func withStacktraceIgnorePrefixes(prefixes []string, f func()) { - _stacktraceTestLock.Lock() - defer _stacktraceTestLock.Unlock() - existing := _stacktraceIgnorePrefixes - _stacktraceIgnorePrefixes = prefixes - defer func() { - _stacktraceIgnorePrefixes = existing - }() - f() -}