From 33ffee658c305e1a92093e8e977393d3c6fb8e7e Mon Sep 17 00:00:00 2001 From: pk910 Date: Sun, 1 Sep 2024 00:17:15 +0200 Subject: [PATCH] fix callstack extraction for timed out page calls --- go.mod | 1 + go.sum | 2 ++ services/frontendcache.go | 33 +++++++++++++++++++-------------- utils/debug.go | 32 -------------------------------- 4 files changed, 22 insertions(+), 46 deletions(-) delete mode 100644 utils/debug.go diff --git a/go.mod b/go.mod index 597092c4..dcf043f5 100644 --- a/go.mod +++ b/go.mod @@ -29,6 +29,7 @@ require ( github.com/sirupsen/logrus v1.9.3 github.com/stdatiks/jdenticon-go v0.1.0 github.com/tdewolff/minify v2.3.6+incompatible + github.com/timandy/routine v1.1.4 github.com/urfave/negroni v1.0.0 golang.org/x/crypto v0.26.0 golang.org/x/exp v0.0.0-20240613232115-7f521ea00fb8 diff --git a/go.sum b/go.sum index 55406583..092e8c74 100644 --- a/go.sum +++ b/go.sum @@ -412,6 +412,8 @@ github.com/tdewolff/parse v2.3.4+incompatible h1:x05/cnGwIMf4ceLuDMBOdQ1qGniMoxp github.com/tdewolff/parse v2.3.4+incompatible/go.mod h1:8oBwCsVmUkgHO8M5iCzSIDtpzXOT0WXX9cWhz+bIzJQ= github.com/tdewolff/test v1.0.9 h1:SswqJCmeN4B+9gEAi/5uqT0qpi1y2/2O47V/1hhGZT0= github.com/tdewolff/test v1.0.9/go.mod h1:6DAvZliBAAnD7rhVgwaM7DE5/d9NMOAJ09SqYqeK4QE= +github.com/timandy/routine v1.1.4 h1:L9eAli/ROJcW6LhmwZcusYQcdAqxAXGOQhEXLQSNWOA= +github.com/timandy/routine v1.1.4/go.mod h1:siBcl8iIsGmhLCajRGRcy7Y7FVcicNXkr97JODdt9fc= github.com/tklauser/go-sysconf v0.3.14 h1:g5vzr9iPFFz24v2KZXs/pvpvh8/V9Fw6vQK5ZZb78yU= github.com/tklauser/go-sysconf v0.3.14/go.mod h1:1ym4lWMLUOhuBOPGtRcJm7tEGX4SCYNEEEtghGG/8uY= github.com/tklauser/numcpus v0.8.0 h1:Mx4Wwe/FjZLeQsK/6kt2EOepwwSl7SmJrK5bV/dXYgY= diff --git a/services/frontendcache.go b/services/frontendcache.go index f2367091..428823f9 100644 --- a/services/frontendcache.go +++ b/services/frontendcache.go @@ -14,6 +14,7 @@ import ( "github.com/ethpandaops/dora/cache" "github.com/ethpandaops/dora/utils" "github.com/sirupsen/logrus" + "github.com/timandy/routine" ) type FrontendCacheService struct { @@ -119,6 +120,8 @@ func (fc *FrontendCacheService) processPageCall(pageKey string, caching bool, pa callIdx := fc.pageCallCounter fc.pageCallCounterMutex.Unlock() + callGoId := int64(0) + go func(callIdx uint64) { defer func() { if err := recover(); err != nil { @@ -130,6 +133,8 @@ func (fc *FrontendCacheService) processPageCall(pageKey string, caching bool, pa } }() + callGoId = routine.Goid() + // check cache if !utils.Config.Frontend.Debug && caching && fc.getFrontendCache(pageKey, pageData) == nil { logrus.Debugf("page served from cache: %v", pageKey) @@ -169,7 +174,7 @@ func (fc *FrontendCacheService) processPageCall(pageKey string, caching bool, pa return nil, &FrontendCachePageError{ name: "page timeout", err: fmt.Errorf("page call %v timeout", callIdx), - stack: fc.extractPageCallStack(callIdx), + stack: fc.extractPageCallStack(callGoId), } } } @@ -190,7 +195,7 @@ func (fc *FrontendCacheService) completePageLoad(pageKey string, processingPage fc.processingMutex.Unlock() } -func (fc *FrontendCacheService) extractPageCallStack(callIdx uint64) string { +func (fc *FrontendCacheService) extractPageCallStack(callGoid int64) string { if fc.callStackMutex.TryLock() { runtime.Stack(fc.callStackBuffer, true) fc.callStackMutex.Unlock() @@ -198,27 +203,27 @@ func (fc *FrontendCacheService) extractPageCallStack(callIdx uint64) string { fc.callStackMutex.RLock() defer fc.callStackMutex.RUnlock() - callFnName := fmt.Sprintf("processPageCall.func1(0x%x)", callIdx) scanner := bufio.NewScanner(bytes.NewReader(fc.callStackBuffer)) - lastBlock := []string{} - isPageCall := false + stackTrace := []string{} + isRelevantCall := false for scanner.Scan() { line := scanner.Text() if strings.HasPrefix(line, "goroutine ") { - if isPageCall { + if isRelevantCall { break } - lastBlock = []string{} - } else { - lastBlock = append(lastBlock, line) - if strings.Contains(line, callFnName) { - isPageCall = true - } + isRelevantCall = strings.HasPrefix(line, fmt.Sprintf("goroutine %v ", callGoid)) + } + + if isRelevantCall { + stackTrace = append(stackTrace, line) } } - if !isPageCall { + + if !isRelevantCall { return "call stack not found" } - return strings.Join(lastBlock, "\n") + + return strings.Join(stackTrace, "\n") } diff --git a/utils/debug.go b/utils/debug.go deleted file mode 100644 index ddd63228..00000000 --- a/utils/debug.go +++ /dev/null @@ -1,32 +0,0 @@ -package utils - -import ( - "bytes" - "runtime" - "strconv" -) - -var ( - goroutinePrefix = []byte("goroutine ") -) - -// This is terrible, slow, and should never be used. -func Goid() int { - buf := make([]byte, 32) - n := runtime.Stack(buf, false) - buf = buf[:n] - // goroutine 1 [running]: ... - - buf, ok := bytes.CutPrefix(buf, goroutinePrefix) - if !ok { - return 0 - } - - i := bytes.IndexByte(buf, ' ') - if i < 0 { - return 0 - } - - res, _ := strconv.Atoi(string(buf[:i])) - return res -}