題名の通り、独自エラーにスタックトレース情報をもたせ、
slogで構造化ログとして出力できるようにします
goでスタックトレースを取得するとパフォーマンスへの影響もあるとかないとか
詳しい説明はこちらの記事が大変わかりやすかったです
実装
スタックトレースの取得
エラーの生成とともにスタック情報を取得しています
type MyError struct {
Msg string
stack []uintptr
err error
}
func NewMyError(msg string) *MyError {
if !hasStack {
return &MyError{Msg: msg}
}
stack := make([]uintptr, maxDepth)
// skip 2 frames [NewMyError, runtime.Callers]
length := runtime.Callers(2, stack)
return &MyError{Msg: msg, stack: stack[:length]}
}
履歴（スタックトレース）を格納する箱を用意して、その箱に履歴（スタックトレース）を積むイメージです
runtime.Callers(2, stack)の第一引数は取得するスタックトレースの開始位置を指定しており、
この場合2なので、自分自身（runtime.Callers）と呼び出し関数（NewMyError）をスキップします
スタックトレースの出力
エラー発生時に取得したスタックトレースを出力します
slogで出力した際に以下のように出力したいので、スライスで返すようにします
{
"time": "2024-12-19T08:33:23.232035471Z",
"level": "ERROR",
"msg": "occured error",
"stackTrace": [
{
"file": "/workspaces/caller_sample/cmd/main.go",
"function": "main.f3",
"line": 40
},
{
"file": "/workspaces/caller_sample/cmd/main.go",
"function": "main.f2",
"line": 33
},
]
}
func (e *MyError) StackTrace() []map[string]interface{} {
if !hasStack {
return nil
}
if e.err != nil {
if myErr, ok := e.err.(*MyError); ok {
return myErr.StackTrace()
}
}
frames := runtime.CallersFrames(e.stack)
res := make([]map[string]interface{}, 0)
for {
frame, more := frames.Next()
res = append(res, map[string]interface{}{
"file": frame.File,
"line": frame.Line,
"function": frame.Function,
})
if !more {
break
}
}
return res
}
runtime.CallersFrames(e.stack)でスタックトレースを解析し、フレーム情報（関数名、ファイル名、行番号など）を出力する準備をしています
上記で取得できるフレーム情報をループで回し、各フレーム情報を取得しスライスに格納していきます
エラーがラップされている場合も考慮して、ラップされている場合は再起的に処理を繰り返します
コード全体
package main
import (
"fmt"
"log/slog"
"os"
"runtime"
)
const (
maxDepth = 50
)
var hasStack = true
type MyError struct {
Msg string
stack []uintptr
err error
}
func NewMyError(msg string) *MyError {
if !hasStack {
return &MyError{Msg: msg}
}
stack := make([]uintptr, maxDepth)
length := runtime.Callers(2, stack)
return &MyError{Msg: msg, stack: stack[:length]}
}
func (e *MyError) Error() string {
return e.Msg
}
func (e *MyError) Unwrap() error {
return e.err
}
func (e *MyError) Wrap(err error) {
e.err = err
}
func (e *MyError) StackTrace() []map[string]interface{} {
if !hasStack {
return nil
}
if e.err != nil {
if myErr, ok := e.err.(*MyError); ok {
return myErr.StackTrace()
}
}
frames := runtime.CallersFrames(e.stack)
res := make([]map[string]interface{}, 0)
for {
frame, more := frames.Next()
res = append(res, map[string]interface{}{
"file": frame.File,
"line": frame.Line,
"function": frame.Function,
})
if !more {
break
}
}
return res
}
使ってみる
func main() {
// slogの出力設定
logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
err := f1()
if myErr, ok := err.(*MyError); ok {
logger.Error("occured error", slog.Any("stackTrace", myErr.StackTrace()))
} else {
fmt.Println("error is not of type *MyError")
}
}
func f1() error {
return f2()
}
func f2() error {
err := f3()
newErr := NewMyError("this is f2 error")
// f3で起きたエラーをラップ
newErr.Wrap(err)
return newErr
}
func f3() error {
// エラー発生
err := NewMyError("this is f3 error")
return err
}
ログ
※JSONは整形しています
{
"time": "2009-11-10T23:00:00Z",
"level": "ERROR",
"msg": "occured error",
"stackTrace": [
{
"file": "/tmp/sandbox1721138770/prog.go",
"function": "main.f3",
"line": 40
},
{
"file": "/tmp/sandbox1721138770/prog.go",
"function": "main.f2",
"line": 33
},
{
"file": "/tmp/sandbox1721138770/prog.go",
"function": "main.f1",
"line": 29
},
{
"file": "/tmp/sandbox1721138770/prog.go",
"function": "main.main",
"line": 19
},
{
"file": "/usr/local/go-faketime/src/runtime/proc.go",
"function": "runtime.main",
"line": 272
},
{
"file": "/usr/local/go-faketime/src/runtime/asm_amd64.s",
"function": "runtime.goexit",
"line": 1700
}
]
}
ベンチマーク
パフォーマンスへの影響がどれほどあるのかも確認してみます
テスコード
func BenchmarkWithStackTrace(b *testing.B) {
hasStack = true
output, _ := os.Create("output_withstack.log")
logger := slog.New(slog.NewJSONHandler(output, nil))
b.ResetTimer()
for i := 0; i < b.N; i++ {
logger.Error("occured error", slog.Any("stackTrace", NewMyError("occured error").StackTrace()))
}
}
func BenchmarkWithoutStackTrace(b *testing.B) {
hasStack = false
output, _ := os.Create("output_withoutstack.log")
logger := slog.New(slog.NewJSONHandler(output, nil))
b.ResetTimer()
for i := 0; i < b.N; i++ {
logger.Error("occured error", slog.Any("stackTrace", NewMyError("occured error")))
}
}
結果
BenchmarkWithStackTrace-10 16770 70639 ns/op 3733 B/op 56 allocs/op
BenchmarkWithoutStackTrace-10 20995 49570 ns/op 112 B/op 2 allocs/op
- 実行時間: スタックトレースを含む場合、約1.43倍の時間がかかる
- メモリ使用量: スタックトレースを含む場合、約33.34倍のメモリを使用
- アロケーション数: スタックトレースを含む場合、28倍のアロケーションが発生
参考