From ee7a30e2f641fee883b8350921d4c6d77e861f3a Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Fri, 20 Dec 2024 18:15:35 +0800 Subject: [PATCH 01/12] fix --- models/db/engine_hook.go | 20 +++-- models/db/engine_init.go | 2 +- modules/git/command.go | 12 ++- modules/git/command_test.go | 2 +- modules/gtprof/trace.go | 119 ++++++++++++++++++++++++++++ modules/gtprof/trace_builtin.go | 66 +++++++++++++++ modules/gtprof/trace_const.go | 19 +++++ modules/tailmsg/taillog.go | 73 +++++++++++++++++ options/locale/locale_en-US.ini | 3 +- routers/common/middleware.go | 17 +++- routers/web/admin/admin.go | 1 + routers/web/admin/perftrace.go | 19 +++++ routers/web/admin/stacktrace.go | 2 +- routers/web/web.go | 1 + templates/admin/navbar.tmpl | 6 +- templates/admin/perftrace.tmpl | 13 +++ templates/admin/stacktrace-row.tmpl | 5 +- templates/admin/stacktrace.tmpl | 28 +------ templates/admin/trace_tabs.tmpl | 17 ++++ 19 files changed, 378 insertions(+), 47 deletions(-) create mode 100644 modules/gtprof/trace.go create mode 100644 modules/gtprof/trace_builtin.go create mode 100644 modules/gtprof/trace_const.go create mode 100644 modules/tailmsg/taillog.go create mode 100644 routers/web/admin/perftrace.go create mode 100644 templates/admin/perftrace.tmpl create mode 100644 templates/admin/trace_tabs.tmpl diff --git a/models/db/engine_hook.go b/models/db/engine_hook.go index b4c543c3dd824..d2655b3eeae6f 100644 --- a/models/db/engine_hook.go +++ b/models/db/engine_hook.go @@ -7,23 +7,33 @@ import ( "context" "time" + "code.gitea.io/gitea/modules/gtprof" "code.gitea.io/gitea/modules/log" + "code.gitea.io/gitea/modules/setting" "xorm.io/xorm/contexts" ) -type SlowQueryHook struct { +type EngineHook struct { Threshold time.Duration Logger log.Logger } -var _ contexts.Hook = (*SlowQueryHook)(nil) +var _ contexts.Hook = (*EngineHook)(nil) -func (*SlowQueryHook) BeforeProcess(c *contexts.ContextHook) (context.Context, error) { - return c.Ctx, nil +func (*EngineHook) BeforeProcess(c *contexts.ContextHook) (context.Context, error) { + ctx, _ := gtprof.GetTracer().Start(c.Ctx, gtprof.TraceSpanDatabase) + return ctx, nil } -func (h *SlowQueryHook) AfterProcess(c *contexts.ContextHook) error { +func (h *EngineHook) AfterProcess(c *contexts.ContextHook) error { + span := gtprof.GetContextSpan(c.Ctx) + if span != nil { + span.SetAttributeString(gtprof.TraceAttrDbSQL, c.SQL) + span.End() + } else { + setting.PanicInDevOrTesting("span in database engine hook is nil") + } if c.ExecuteTime >= h.Threshold { // 8 is the amount of skips passed to runtime.Caller, so that in the log the correct function // is being displayed (the function that ultimately wants to execute the query in the code) diff --git a/models/db/engine_init.go b/models/db/engine_init.go index da85018957b8b..edca6979342df 100644 --- a/models/db/engine_init.go +++ b/models/db/engine_init.go @@ -72,7 +72,7 @@ func InitEngine(ctx context.Context) error { xe.SetDefaultContext(ctx) if setting.Database.SlowQueryThreshold > 0 { - xe.AddHook(&SlowQueryHook{ + xe.AddHook(&EngineHook{ Threshold: setting.Database.SlowQueryThreshold, Logger: log.GetLogger("xorm"), }) diff --git a/modules/git/command.go b/modules/git/command.go index 2584e3cc57c45..602d00f027104 100644 --- a/modules/git/command.go +++ b/modules/git/command.go @@ -18,6 +18,7 @@ import ( "time" "code.gitea.io/gitea/modules/git/internal" //nolint:depguard // only this file can use the internal type CmdArg, other files and packages should use AddXxx functions + "code.gitea.io/gitea/modules/gtprof" "code.gitea.io/gitea/modules/log" "code.gitea.io/gitea/modules/process" "code.gitea.io/gitea/modules/util" @@ -54,7 +55,7 @@ func logArgSanitize(arg string) string { } else if filepath.IsAbs(arg) { base := filepath.Base(arg) dir := filepath.Dir(arg) - return filepath.Join(filepath.Base(dir), base) + return ".../" + filepath.Join(filepath.Base(dir), base) } return arg } @@ -295,15 +296,20 @@ func (c *Command) run(skip int, opts *RunOpts) error { timeout = defaultCommandExecutionTimeout } - var desc string + cmdLogString := c.LogString() callerInfo := util.CallerFuncName(1 /* util */ + 1 /* this */ + skip /* parent */) if pos := strings.LastIndex(callerInfo, "/"); pos >= 0 { callerInfo = callerInfo[pos+1:] } // these logs are for debugging purposes only, so no guarantee of correctness or stability - desc = fmt.Sprintf("git.Run(by:%s, repo:%s): %s", callerInfo, logArgSanitize(opts.Dir), c.LogString()) + desc := fmt.Sprintf("git.Run(by:%s, repo:%s): %s", callerInfo, logArgSanitize(opts.Dir), cmdLogString) log.Debug("git.Command: %s", desc) + _, span := gtprof.GetTracer().Start(c.parentContext, gtprof.TraceSpanGitRun) + defer span.End() + span.SetAttributeString(gtprof.TraceAttrFuncCaller, callerInfo) + span.SetAttributeString(gtprof.TraceAttrGitCommand, cmdLogString) + var ctx context.Context var cancel context.CancelFunc var finished context.CancelFunc diff --git a/modules/git/command_test.go b/modules/git/command_test.go index 0823afd7f76a9..e988714db7fb6 100644 --- a/modules/git/command_test.go +++ b/modules/git/command_test.go @@ -58,5 +58,5 @@ func TestCommandString(t *testing.T) { assert.EqualValues(t, cmd.prog+` a "-m msg" "it's a test" "say \"hello\""`, cmd.LogString()) cmd = NewCommandContextNoGlobals(context.Background(), "url: https://a:b@c/", "/root/dir-a/dir-b") - assert.EqualValues(t, cmd.prog+` "url: https://sanitized-credential@c/" dir-a/dir-b`, cmd.LogString()) + assert.EqualValues(t, cmd.prog+` "url: https://sanitized-credential@c/" .../dir-a/dir-b`, cmd.LogString()) } diff --git a/modules/gtprof/trace.go b/modules/gtprof/trace.go new file mode 100644 index 0000000000000..994b4c262dbcc --- /dev/null +++ b/modules/gtprof/trace.go @@ -0,0 +1,119 @@ +// Copyright 2024 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package gtprof + +import ( + "context" + "fmt" + "sync" + "time" + + "code.gitea.io/gitea/modules/util" +) + +type contextKey struct { + name string +} + +var ContextKeySpan = &contextKey{"span"} + +type traceStarter interface { + start(ctx context.Context, traceSpan *TraceSpan, internalSpanIdx int) (context.Context, traceSpanInternal) +} + +type traceSpanInternal interface { + end() +} + +type TraceSpan struct { + // immutable + parent *TraceSpan + internalSpans []traceSpanInternal + + // mutable, must be protected by mutex + mu sync.RWMutex + name string + startTime time.Time + endTime time.Time + attributes []TraceAttribute + children []*TraceSpan +} + +type TraceAttribute struct { + Key string + Value TraceValue +} + +type TraceValue struct { + v any +} + +func (t *TraceValue) AsString() string { + return fmt.Sprint(t.v) +} + +func (t *TraceValue) AsInt64() int64 { + v, _ := util.ToInt64(t.v) + return v +} + +func (t *TraceValue) AsFloat64() float64 { + v, _ := util.ToFloat64(t.v) + return v +} + +var globalTraceStarters []traceStarter + +type Tracer struct { + starters []traceStarter +} + +func (s *TraceSpan) SetAttributeString(key, value string) *TraceSpan { + s.mu.Lock() + defer s.mu.Unlock() + + s.attributes = append(s.attributes, TraceAttribute{Key: key, Value: TraceValue{v: value}}) + return s +} + +func (t *Tracer) Start(ctx context.Context, spanName string) (context.Context, *TraceSpan) { + starters := t.starters + if starters == nil { + starters = globalTraceStarters + } + ts := &TraceSpan{name: spanName, startTime: time.Now()} + existingCtxSpan, _ := ctx.Value(ContextKeySpan).(*TraceSpan) + if existingCtxSpan != nil { + existingCtxSpan.mu.Lock() + existingCtxSpan.children = append(existingCtxSpan.children, ts) + existingCtxSpan.mu.Unlock() + ts.parent = existingCtxSpan + } + for internalSpanIdx, tsp := range starters { + var internalSpan traceSpanInternal + ctx, internalSpan = tsp.start(ctx, ts, internalSpanIdx) + ts.internalSpans = append(ts.internalSpans, internalSpan) + } + ctx = context.WithValue(ctx, ContextKeySpan, ts) + return ctx, ts +} + +func (s *TraceSpan) End() { + s.mu.Lock() + s.endTime = time.Now() + s.mu.Unlock() + + for _, tsp := range s.internalSpans { + tsp.end() + } +} + +func GetTracer() *Tracer { + return &Tracer{} +} + +func GetContextSpan(ctx context.Context) *TraceSpan { + ts, _ := ctx.Value(ContextKeySpan).(*TraceSpan) + return ts +} diff --git a/modules/gtprof/trace_builtin.go b/modules/gtprof/trace_builtin.go new file mode 100644 index 0000000000000..c9be98713e5eb --- /dev/null +++ b/modules/gtprof/trace_builtin.go @@ -0,0 +1,66 @@ +// Copyright 2024 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package gtprof + +import ( + "context" + "fmt" + "strings" + "time" + + "code.gitea.io/gitea/modules/tailmsg" +) + +type traceBuiltinStarter struct{} + +type traceBuiltinSpan struct { + ts *TraceSpan + + internalSpanIdx int +} + +func (t *traceBuiltinSpan) toString(out *strings.Builder, indent int) { + t.ts.mu.RLock() + defer t.ts.mu.RUnlock() + + out.WriteString(strings.Repeat(" ", indent)) + out.WriteString(t.ts.name) + if t.ts.endTime.IsZero() { + out.WriteString(" duration: (not ended)") + } else { + out.WriteString(fmt.Sprintf(" duration: %.4fs", t.ts.endTime.Sub(t.ts.startTime).Seconds())) + } + out.WriteString("\n") + for _, a := range t.ts.attributes { + out.WriteString(strings.Repeat(" ", indent+2)) + out.WriteString(a.Key) + out.WriteString(": ") + out.WriteString(a.Value.AsString()) + out.WriteString("\n") + } + for _, c := range t.ts.children { + span := c.internalSpans[t.internalSpanIdx].(*traceBuiltinSpan) + span.toString(out, indent+2) + } +} + +func (t *traceBuiltinSpan) end() { + if t.ts.parent == nil { + // FIXME: debug purpose only + // FIXME: it should distinguish between http response network lag and actual processing time + if len(t.ts.children) > 3 || t.ts.endTime.Sub(t.ts.startTime) > 100*time.Millisecond { + sb := &strings.Builder{} + t.toString(sb, 0) + tailmsg.GetManager().GetTraceRecorder().Record(sb.String()) + } + } +} + +func (t *traceBuiltinStarter) start(ctx context.Context, traceSpan *TraceSpan, internalSpanIdx int) (context.Context, traceSpanInternal) { + return ctx, &traceBuiltinSpan{ts: traceSpan, internalSpanIdx: internalSpanIdx} +} + +func init() { + globalTraceStarters = append(globalTraceStarters, &traceBuiltinStarter{}) +} diff --git a/modules/gtprof/trace_const.go b/modules/gtprof/trace_const.go new file mode 100644 index 0000000000000..96a0b885c81ef --- /dev/null +++ b/modules/gtprof/trace_const.go @@ -0,0 +1,19 @@ +// Copyright 2024 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package gtprof + +// Some interesting names could be found in https://github.com/open-telemetry/opentelemetry-go/tree/main/semconv + +const ( + TraceSpanHTTP = "http" + TraceSpanGitRun = "git-run" + TraceSpanDatabase = "database" +) + +const ( + TraceAttrFuncCaller = "func.caller" + TraceAttrDbSQL = "db.sql" + TraceAttrGitCommand = "git.command" + TraceAttrHTTPRoute = "http.route" +) diff --git a/modules/tailmsg/taillog.go b/modules/tailmsg/taillog.go new file mode 100644 index 0000000000000..5d3e6fefd1403 --- /dev/null +++ b/modules/tailmsg/taillog.go @@ -0,0 +1,73 @@ +// Copyright 2024 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package tailmsg + +import ( + "sync" + "time" +) + +type MsgRecord struct { + Time time.Time + Content string +} + +type MsgRecorder interface { + Record(content string) + GetRecords() []*MsgRecord +} + +type memoryMsgRecorder struct { + mu sync.RWMutex + msgs []*MsgRecord + limit int +} + +// TODO: use redis for a clustered environment + +func (m *memoryMsgRecorder) Record(content string) { + m.mu.Lock() + defer m.mu.Unlock() + m.msgs = append(m.msgs, &MsgRecord{ + Time: time.Now(), + Content: content, + }) + if len(m.msgs) > m.limit { + m.msgs = m.msgs[len(m.msgs)-m.limit:] + } +} + +func (m *memoryMsgRecorder) GetRecords() []*MsgRecord { + m.mu.RLock() + defer m.mu.RUnlock() + ret := make([]*MsgRecord, len(m.msgs)) + copy(ret, m.msgs) + return ret +} + +func NewMsgRecorder(limit int) MsgRecorder { + return &memoryMsgRecorder{ + limit: limit, + } +} + +type Manager struct { + traceRecorder MsgRecorder + logRecorder MsgRecorder +} + +func (m *Manager) GetTraceRecorder() MsgRecorder { + return m.traceRecorder +} + +func (m *Manager) GetLogRecorder() MsgRecorder { + return m.logRecorder +} + +var GetManager = sync.OnceValue(func() *Manager { + return &Manager{ + traceRecorder: NewMsgRecorder(100), + logRecorder: NewMsgRecorder(1000), + } +}) diff --git a/options/locale/locale_en-US.ini b/options/locale/locale_en-US.ini index 6029d49ade0bc..a7249e6eb6a5c 100644 --- a/options/locale/locale_en-US.ini +++ b/options/locale/locale_en-US.ini @@ -3363,6 +3363,8 @@ monitor.previous = Previous Time monitor.execute_times = Executions monitor.process = Running Processes monitor.stacktrace = Stacktrace +monitor.trace = Trace +monitor.performance_logs = Performance Logs monitor.processes_count = %d Processes monitor.download_diagnosis_report = Download diagnosis report monitor.desc = Description @@ -3371,7 +3373,6 @@ monitor.execute_time = Execution Time monitor.last_execution_result = Result monitor.process.cancel = Cancel process monitor.process.cancel_desc = Cancelling a process may cause data loss -monitor.process.cancel_notices = Cancel: %s? monitor.process.children = Children monitor.queues = Queues diff --git a/routers/common/middleware.go b/routers/common/middleware.go index 12b0c67b01823..f08577f37d2dc 100644 --- a/routers/common/middleware.go +++ b/routers/common/middleware.go @@ -9,6 +9,7 @@ import ( "strings" "code.gitea.io/gitea/modules/cache" + "code.gitea.io/gitea/modules/gtprof" "code.gitea.io/gitea/modules/httplib" "code.gitea.io/gitea/modules/reqctx" "code.gitea.io/gitea/modules/setting" @@ -44,10 +45,18 @@ func ProtocolMiddlewares() (handlers []any) { func RequestContextHandler() func(h http.Handler) http.Handler { return func(next http.Handler) http.Handler { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { - profDesc := fmt.Sprintf("%s: %s", req.Method, req.RequestURI) + profDesc := fmt.Sprintf("HTTP: %s %s", req.Method, req.RequestURI) ctx, finished := reqctx.NewRequestContext(req.Context(), profDesc) defer finished() + ctx, span := gtprof.GetTracer().Start(ctx, gtprof.TraceSpanHTTP) + req = req.WithContext(ctx) + defer func() { + chiCtx := chi.RouteContext(req.Context()) + span.SetAttributeString(gtprof.TraceAttrHTTPRoute, chiCtx.RoutePattern()) + span.End() + }() + defer func() { if err := recover(); err != nil { RenderPanicErrorPage(resp, req, err) // it should never panic @@ -71,11 +80,11 @@ func ChiRoutePathHandler() func(h http.Handler) http.Handler { // make sure chi uses EscapedPath(RawPath) as RoutePath, then "%2f" could be handled correctly return func(next http.Handler) http.Handler { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { - ctx := chi.RouteContext(req.Context()) + chiCtx := chi.RouteContext(req.Context()) if req.URL.RawPath == "" { - ctx.RoutePath = req.URL.EscapedPath() + chiCtx.RoutePath = req.URL.EscapedPath() } else { - ctx.RoutePath = req.URL.RawPath + chiCtx.RoutePath = req.URL.RawPath } next.ServeHTTP(resp, req) }) diff --git a/routers/web/admin/admin.go b/routers/web/admin/admin.go index 3902a1efb1474..0cd13acf6012b 100644 --- a/routers/web/admin/admin.go +++ b/routers/web/admin/admin.go @@ -37,6 +37,7 @@ const ( tplSelfCheck templates.TplName = "admin/self_check" tplCron templates.TplName = "admin/cron" tplQueue templates.TplName = "admin/queue" + tplPerfTrace templates.TplName = "admin/perftrace" tplStacktrace templates.TplName = "admin/stacktrace" tplQueueManage templates.TplName = "admin/queue_manage" tplStats templates.TplName = "admin/stats" diff --git a/routers/web/admin/perftrace.go b/routers/web/admin/perftrace.go new file mode 100644 index 0000000000000..cb0ac2bbe8589 --- /dev/null +++ b/routers/web/admin/perftrace.go @@ -0,0 +1,19 @@ +// Copyright 2024 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package admin + +import ( + "net/http" + + "code.gitea.io/gitea/modules/tailmsg" + "code.gitea.io/gitea/services/context" +) + +func PerfTrace(ctx *context.Context) { + ctx.Data["Title"] = ctx.Tr("admin.monitor") + ctx.Data["PageIsAdminMonitorTrace"] = true + ctx.Data["PageIsAdminMonitorPerfTrace"] = true + ctx.Data["PerfTraceRecords"] = tailmsg.GetManager().GetTraceRecorder().GetRecords() + ctx.HTML(http.StatusOK, tplPerfTrace) +} diff --git a/routers/web/admin/stacktrace.go b/routers/web/admin/stacktrace.go index ff751be621701..456118110e4f4 100644 --- a/routers/web/admin/stacktrace.go +++ b/routers/web/admin/stacktrace.go @@ -15,7 +15,7 @@ import ( // Stacktrace show admin monitor goroutines page func Stacktrace(ctx *context.Context) { ctx.Data["Title"] = ctx.Tr("admin.monitor") - ctx.Data["PageIsAdminMonitorStacktrace"] = true + ctx.Data["PageIsAdminMonitorTrace"] = true ctx.Data["GoroutineCount"] = runtime.NumGoroutine() diff --git a/routers/web/web.go b/routers/web/web.go index 5e0995545e814..8e4c190d57772 100644 --- a/routers/web/web.go +++ b/routers/web/web.go @@ -719,6 +719,7 @@ func registerRoutes(m *web.Router) { m.Group("/monitor", func() { m.Get("/stats", admin.MonitorStats) m.Get("/cron", admin.CronTasks) + m.Get("/perftrace", admin.PerfTrace) m.Get("/stacktrace", admin.Stacktrace) m.Post("/stacktrace/cancel/{pid}", admin.StacktraceCancel) m.Get("/queue", admin.Queues) diff --git a/templates/admin/navbar.tmpl b/templates/admin/navbar.tmpl index 4116357d1d235..72584ec799cc3 100644 --- a/templates/admin/navbar.tmpl +++ b/templates/admin/navbar.tmpl @@ -95,7 +95,7 @@ {{ctx.Locale.Tr "admin.notices"}} -
+
{{ctx.Locale.Tr "admin.monitor"}}
@@ -107,8 +107,8 @@ {{ctx.Locale.Tr "admin.monitor.queues"}} - - {{ctx.Locale.Tr "admin.monitor.stacktrace"}} + + {{ctx.Locale.Tr "admin.monitor.trace"}}
diff --git a/templates/admin/perftrace.tmpl b/templates/admin/perftrace.tmpl new file mode 100644 index 0000000000000..1cd4a41593f9c --- /dev/null +++ b/templates/admin/perftrace.tmpl @@ -0,0 +1,13 @@ +{{template "admin/layout_head" (dict "ctxData" . "pageClass" "admin monitor")}} + +
+ {{template "admin/trace_tabs" .}} + + {{range $record := .PerfTraceRecords}} +
+ 
{{$record.Content}}
+
+ {{end}} +
+ +{{template "admin/layout_footer" .}} diff --git a/templates/admin/stacktrace-row.tmpl b/templates/admin/stacktrace-row.tmpl index 97c361ff902e5..db7ed81c79370 100644 --- a/templates/admin/stacktrace-row.tmpl +++ b/templates/admin/stacktrace-row.tmpl @@ -17,7 +17,10 @@
{{if or (eq .Process.Type "request") (eq .Process.Type "normal")}} - {{svg "octicon-trash" 16 "text-red"}} + {{svg "octicon-trash" 16 "text-red"}} {{end}}
diff --git a/templates/admin/stacktrace.tmpl b/templates/admin/stacktrace.tmpl index ce03d80555732..c5dde6b30c108 100644 --- a/templates/admin/stacktrace.tmpl +++ b/templates/admin/stacktrace.tmpl @@ -1,22 +1,7 @@ {{template "admin/layout_head" (dict "ctxData" . "pageClass" "admin monitor")}}
-
-
-
- {{ctx.Locale.Tr "admin.monitor.process"}} - {{ctx.Locale.Tr "admin.monitor.stacktrace"}} -
-
-
-
- - {{ctx.Locale.Tr "tool.raw_seconds"}} -
-
-
- -
+ {{template "admin/trace_tabs" .}}

{{printf "%d Goroutines" .GoroutineCount}}{{/* Goroutine is non-translatable*/}} @@ -34,15 +19,4 @@ {{end}}

-
-
- {{ctx.Locale.Tr "admin.monitor.process.cancel"}} -
-
-

{{ctx.Locale.Tr "admin.monitor.process.cancel_notices" (``|SafeHTML)}}

-

{{ctx.Locale.Tr "admin.monitor.process.cancel_desc"}}

-
- {{template "base/modal_actions_confirm" .}} -
- {{template "admin/layout_footer" .}} diff --git a/templates/admin/trace_tabs.tmpl b/templates/admin/trace_tabs.tmpl new file mode 100644 index 0000000000000..4b7bedcededfc --- /dev/null +++ b/templates/admin/trace_tabs.tmpl @@ -0,0 +1,17 @@ +
+
+
+ {{ctx.Locale.Tr "admin.monitor.performance_logs"}} + {{ctx.Locale.Tr "admin.monitor.process"}} + {{ctx.Locale.Tr "admin.monitor.stacktrace"}} +
+
+
+
+ + {{ctx.Locale.Tr "tool.raw_seconds"}} +
+
+
+ +
From 94816bf306bdeae3d0cf877332f1db655b3330b4 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Wed, 15 Jan 2025 23:03:35 +0800 Subject: [PATCH 02/12] trace web functions --- modules/gtprof/trace.go | 2 +- modules/web/handler.go | 4 ++-- modules/web/routing/context.go | 33 +++++++++++++++++++++++++-------- routers/init.go | 2 +- routers/web/base.go | 4 ++-- routers/web/web.go | 2 +- services/context/base.go | 24 +++++++++++------------- 7 files changed, 43 insertions(+), 28 deletions(-) diff --git a/modules/gtprof/trace.go b/modules/gtprof/trace.go index 994b4c262dbcc..1a06a9c828b94 100644 --- a/modules/gtprof/trace.go +++ b/modules/gtprof/trace.go @@ -83,7 +83,7 @@ func (t *Tracer) Start(ctx context.Context, spanName string) (context.Context, * starters = globalTraceStarters } ts := &TraceSpan{name: spanName, startTime: time.Now()} - existingCtxSpan, _ := ctx.Value(ContextKeySpan).(*TraceSpan) + existingCtxSpan := GetContextSpan(ctx) if existingCtxSpan != nil { existingCtxSpan.mu.Lock() existingCtxSpan.children = append(existingCtxSpan.children, ts) diff --git a/modules/web/handler.go b/modules/web/handler.go index 9a3e4a7f17660..42a649714d9df 100644 --- a/modules/web/handler.go +++ b/modules/web/handler.go @@ -121,7 +121,7 @@ func wrapHandlerProvider[T http.Handler](hp func(next http.Handler) T, funcInfo return func(next http.Handler) http.Handler { h := hp(next) // this handle could be dynamically generated, so we can't use it for debug info return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { - routing.UpdateFuncInfo(req.Context(), funcInfo) + defer routing.RecordFuncInfo(req.Context(), funcInfo)() h.ServeHTTP(resp, req) }) } @@ -157,7 +157,7 @@ func toHandlerProvider(handler any) func(next http.Handler) http.Handler { return // it's doing pre-check, just return } - routing.UpdateFuncInfo(req.Context(), funcInfo) + defer routing.RecordFuncInfo(req.Context(), funcInfo)() ret := fn.Call(argsIn) // handle the return value (no-op at the moment) diff --git a/modules/web/routing/context.go b/modules/web/routing/context.go index c5e85a415b1eb..6a6aba4747929 100644 --- a/modules/web/routing/context.go +++ b/modules/web/routing/context.go @@ -6,22 +6,39 @@ package routing import ( "context" "net/http" + + "code.gitea.io/gitea/modules/gtprof" + "code.gitea.io/gitea/modules/reqctx" ) type contextKeyType struct{} var contextKey contextKeyType -// UpdateFuncInfo updates a context's func info -func UpdateFuncInfo(ctx context.Context, funcInfo *FuncInfo) { - record, ok := ctx.Value(contextKey).(*requestRecord) - if !ok { - return +func StartContextSpan(ctx reqctx.RequestContext, spanName string) (*gtprof.TraceSpan, func()) { + curTraceSpan := gtprof.GetContextSpan(ctx) + _, newTraceSpan := gtprof.GetTracer().Start(ctx, spanName) + ctx.SetContextValue(gtprof.ContextKeySpan, newTraceSpan) + return newTraceSpan, func() { + newTraceSpan.End() + ctx.SetContextValue(gtprof.ContextKeySpan, curTraceSpan) } +} - record.lock.Lock() - record.funcInfo = funcInfo - record.lock.Unlock() +// RecordFuncInfo records a func info into context +func RecordFuncInfo(ctx context.Context, funcInfo *FuncInfo) (end func()) { + end = func() {} + if reqCtx := reqctx.FromContext(ctx); reqCtx != nil { + var traceSpan *gtprof.TraceSpan + traceSpan, end = StartContextSpan(reqCtx, "http.func") + traceSpan.SetAttributeString("func", funcInfo.shortName) + } + if record, ok := ctx.Value(contextKey).(*requestRecord); ok { + record.lock.Lock() + record.funcInfo = funcInfo + record.lock.Unlock() + } + return end } // MarkLongPolling marks the request is a long-polling request, and the logger may output different message for it diff --git a/routers/init.go b/routers/init.go index e7aa765bf03c9..744feee2f0db0 100644 --- a/routers/init.go +++ b/routers/init.go @@ -213,7 +213,7 @@ func NormalRoutes() *web.Router { } r.NotFound(func(w http.ResponseWriter, req *http.Request) { - routing.UpdateFuncInfo(req.Context(), routing.GetFuncInfo(http.NotFound, "GlobalNotFound")) + defer routing.RecordFuncInfo(req.Context(), routing.GetFuncInfo(http.NotFound, "GlobalNotFound"))() http.NotFound(w, req) }) return r diff --git a/routers/web/base.go b/routers/web/base.go index aa0b43c16a1f0..abe11593f756e 100644 --- a/routers/web/base.go +++ b/routers/web/base.go @@ -34,7 +34,7 @@ func storageHandler(storageSetting *setting.Storage, prefix string, objStore sto http.Error(w, http.StatusText(http.StatusNotFound), http.StatusNotFound) return } - routing.UpdateFuncInfo(req.Context(), funcInfo) + defer routing.RecordFuncInfo(req.Context(), funcInfo)() rPath := strings.TrimPrefix(req.URL.Path, "/"+prefix+"/") rPath = util.PathJoinRelX(rPath) @@ -65,7 +65,7 @@ func storageHandler(storageSetting *setting.Storage, prefix string, objStore sto http.Error(w, http.StatusText(http.StatusNotFound), http.StatusNotFound) return } - routing.UpdateFuncInfo(req.Context(), funcInfo) + defer routing.RecordFuncInfo(req.Context(), funcInfo)() rPath := strings.TrimPrefix(req.URL.Path, "/"+prefix+"/") rPath = util.PathJoinRelX(rPath) diff --git a/routers/web/web.go b/routers/web/web.go index bb83815146fbe..d469018f8fb2a 100644 --- a/routers/web/web.go +++ b/routers/web/web.go @@ -1623,7 +1623,7 @@ func registerRoutes(m *web.Router) { m.NotFound(func(w http.ResponseWriter, req *http.Request) { ctx := context.GetWebContext(req) - routing.UpdateFuncInfo(ctx, routing.GetFuncInfo(ctx.NotFound, "WebNotFound")) + defer routing.RecordFuncInfo(ctx, routing.GetFuncInfo(ctx.NotFound, "WebNotFound"))() ctx.NotFound("", nil) }) } diff --git a/services/context/base.go b/services/context/base.go index 7a39353e09e5d..5db84f42a55f0 100644 --- a/services/context/base.go +++ b/services/context/base.go @@ -4,7 +4,6 @@ package context import ( - "context" "fmt" "html/template" "io" @@ -25,8 +24,7 @@ type BaseContextKeyType struct{} var BaseContextKey BaseContextKeyType type Base struct { - context.Context - reqctx.RequestDataStore + reqctx.RequestContext Resp ResponseWriter Req *http.Request @@ -172,19 +170,19 @@ func (b *Base) TrN(cnt any, key1, keyN string, args ...any) template.HTML { } func NewBaseContext(resp http.ResponseWriter, req *http.Request) *Base { - ds := reqctx.GetRequestDataStore(req.Context()) + reqCtx := reqctx.FromContext(req.Context()) b := &Base{ - Context: req.Context(), - RequestDataStore: ds, - Req: req, - Resp: WrapResponseWriter(resp), - Locale: middleware.Locale(resp, req), - Data: ds.GetData(), + RequestContext: reqCtx, + + Req: req, + Resp: WrapResponseWriter(resp), + Locale: middleware.Locale(resp, req), + Data: reqCtx.GetData(), } b.Req = b.Req.WithContext(b) - ds.SetContextValue(BaseContextKey, b) - ds.SetContextValue(translation.ContextKey, b.Locale) - ds.SetContextValue(httplib.RequestContextKey, b.Req) + reqCtx.SetContextValue(BaseContextKey, b) + reqCtx.SetContextValue(translation.ContextKey, b.Locale) + reqCtx.SetContextValue(httplib.RequestContextKey, b.Req) return b } From 5572bbe8f84c5f1b36119dbaa0100ec0ca790a54 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Thu, 16 Jan 2025 21:01:06 +0800 Subject: [PATCH 03/12] improve --- cmd/web.go | 4 ++++ modules/gtprof/trace_builtin.go | 38 +++++++++++++++++++++++++-------- routers/web/admin/diagnosis.go | 18 ++++++++++++++-- routers/web/admin/perftrace.go | 3 +-- routers/web/admin/stacktrace.go | 11 ++++++++-- templates/admin/perftrace.tmpl | 4 ++-- templates/admin/trace_tabs.tmpl | 6 ++++-- 7 files changed, 65 insertions(+), 19 deletions(-) diff --git a/cmd/web.go b/cmd/web.go index f8217758e559e..dc5c6de48a309 100644 --- a/cmd/web.go +++ b/cmd/web.go @@ -18,10 +18,12 @@ import ( "code.gitea.io/gitea/modules/container" "code.gitea.io/gitea/modules/graceful" + "code.gitea.io/gitea/modules/gtprof" "code.gitea.io/gitea/modules/log" "code.gitea.io/gitea/modules/process" "code.gitea.io/gitea/modules/public" "code.gitea.io/gitea/modules/setting" + "code.gitea.io/gitea/modules/util" "code.gitea.io/gitea/routers" "code.gitea.io/gitea/routers/install" @@ -218,6 +220,8 @@ func serveInstalled(ctx *cli.Context) error { } } + gtprof.EnableBuiltinTracer(util.Iif(setting.IsProd, 2000*time.Millisecond, 100*time.Millisecond)) + // Set up Chi routes webRoutes := routers.NormalRoutes() err := listen(webRoutes, true) diff --git a/modules/gtprof/trace_builtin.go b/modules/gtprof/trace_builtin.go index c9be98713e5eb..d6f5146e3371e 100644 --- a/modules/gtprof/trace_builtin.go +++ b/modules/gtprof/trace_builtin.go @@ -7,6 +7,7 @@ import ( "context" "fmt" "strings" + "sync/atomic" "time" "code.gitea.io/gitea/modules/tailmsg" @@ -29,16 +30,28 @@ func (t *traceBuiltinSpan) toString(out *strings.Builder, indent int) { if t.ts.endTime.IsZero() { out.WriteString(" duration: (not ended)") } else { - out.WriteString(fmt.Sprintf(" duration: %.4fs", t.ts.endTime.Sub(t.ts.startTime).Seconds())) + out.WriteString(fmt.Sprintf(" duration=%.4fs", t.ts.endTime.Sub(t.ts.startTime).Seconds())) } - out.WriteString("\n") for _, a := range t.ts.attributes { - out.WriteString(strings.Repeat(" ", indent+2)) + out.WriteString(" ") out.WriteString(a.Key) - out.WriteString(": ") - out.WriteString(a.Value.AsString()) - out.WriteString("\n") + out.WriteString("=") + value := a.Value.AsString() + if strings.ContainsAny(value, " \t\r\n") { + quoted := false + for _, c := range "\"'`" { + if quoted = !strings.Contains(value, string(c)); quoted { + value = string(c) + value + string(c) + break + } + } + if !quoted { + value = fmt.Sprintf("%q", value) + } + } + out.WriteString(value) } + out.WriteString("\n") for _, c := range t.ts.children { span := c.internalSpans[t.internalSpanIdx].(*traceBuiltinSpan) span.toString(out, indent+2) @@ -47,9 +60,10 @@ func (t *traceBuiltinSpan) toString(out *strings.Builder, indent int) { func (t *traceBuiltinSpan) end() { if t.ts.parent == nil { - // FIXME: debug purpose only - // FIXME: it should distinguish between http response network lag and actual processing time - if len(t.ts.children) > 3 || t.ts.endTime.Sub(t.ts.startTime) > 100*time.Millisecond { + // TODO: debug purpose only + // TODO: it should distinguish between http response network lag and actual processing time + threshold := time.Duration(traceBuiltinThreshold.Load()) + if threshold != 0 && t.ts.endTime.Sub(t.ts.startTime) > threshold { sb := &strings.Builder{} t.toString(sb, 0) tailmsg.GetManager().GetTraceRecorder().Record(sb.String()) @@ -64,3 +78,9 @@ func (t *traceBuiltinStarter) start(ctx context.Context, traceSpan *TraceSpan, i func init() { globalTraceStarters = append(globalTraceStarters, &traceBuiltinStarter{}) } + +var traceBuiltinThreshold atomic.Int64 + +func EnableBuiltinTracer(threshold time.Duration) { + traceBuiltinThreshold.Store(int64(threshold)) +} diff --git a/routers/web/admin/diagnosis.go b/routers/web/admin/diagnosis.go index 020554a35a4f3..d040dbe0ba364 100644 --- a/routers/web/admin/diagnosis.go +++ b/routers/web/admin/diagnosis.go @@ -10,13 +10,15 @@ import ( "time" "code.gitea.io/gitea/modules/httplib" + "code.gitea.io/gitea/modules/tailmsg" + "code.gitea.io/gitea/modules/util" "code.gitea.io/gitea/services/context" ) func MonitorDiagnosis(ctx *context.Context) { seconds := ctx.FormInt64("seconds") - if seconds <= 5 { - seconds = 5 + if seconds <= 1 { + seconds = 1 } if seconds > 300 { seconds = 300 @@ -65,4 +67,16 @@ func MonitorDiagnosis(ctx *context.Context) { return } _ = pprof.Lookup("heap").WriteTo(f, 0) + + f, err = zipWriter.CreateHeader(&zip.FileHeader{Name: "perftrace.txt", Method: zip.Deflate, Modified: time.Now()}) + if err != nil { + ctx.ServerError("Failed to create zip file", err) + return + } + for _, record := range tailmsg.GetManager().GetTraceRecorder().GetRecords() { + _, _ = f.Write(util.UnsafeStringToBytes(record.Time.Format(time.RFC3339))) + _, _ = f.Write([]byte(" ")) + _, _ = f.Write(util.UnsafeStringToBytes((record.Content))) + _, _ = f.Write([]byte("\n\n")) + } } diff --git a/routers/web/admin/perftrace.go b/routers/web/admin/perftrace.go index cb0ac2bbe8589..5c5a359505286 100644 --- a/routers/web/admin/perftrace.go +++ b/routers/web/admin/perftrace.go @@ -11,8 +11,7 @@ import ( ) func PerfTrace(ctx *context.Context) { - ctx.Data["Title"] = ctx.Tr("admin.monitor") - ctx.Data["PageIsAdminMonitorTrace"] = true + monitorTraceCommon(ctx) ctx.Data["PageIsAdminMonitorPerfTrace"] = true ctx.Data["PerfTraceRecords"] = tailmsg.GetManager().GetTraceRecorder().GetRecords() ctx.HTML(http.StatusOK, tplPerfTrace) diff --git a/routers/web/admin/stacktrace.go b/routers/web/admin/stacktrace.go index 456118110e4f4..2b8c2fb4afb65 100644 --- a/routers/web/admin/stacktrace.go +++ b/routers/web/admin/stacktrace.go @@ -12,10 +12,17 @@ import ( "code.gitea.io/gitea/services/context" ) -// Stacktrace show admin monitor goroutines page -func Stacktrace(ctx *context.Context) { +func monitorTraceCommon(ctx *context.Context) { ctx.Data["Title"] = ctx.Tr("admin.monitor") ctx.Data["PageIsAdminMonitorTrace"] = true + // Hide the performance trace tab in production, because it shows a lot of SQLs and is not that useful for end users. + // To avoid confusing end users, do not let them know this tab. End users should "download diagnosis report" instead. + ctx.Data["ShowAdminPerformanceTraceTab"] = !setting.IsProd +} + +// Stacktrace show admin monitor goroutines page +func Stacktrace(ctx *context.Context) { + monitorTraceCommon(ctx) ctx.Data["GoroutineCount"] = runtime.NumGoroutine() diff --git a/templates/admin/perftrace.tmpl b/templates/admin/perftrace.tmpl index 1cd4a41593f9c..8e9ee71e894e4 100644 --- a/templates/admin/perftrace.tmpl +++ b/templates/admin/perftrace.tmpl @@ -4,8 +4,8 @@ {{template "admin/trace_tabs" .}} {{range $record := .PerfTraceRecords}} -
- 
{{$record.Content}}
+
+ 
{{$record.Content}}
{{end}}
diff --git a/templates/admin/trace_tabs.tmpl b/templates/admin/trace_tabs.tmpl index 4b7bedcededfc..5066c9c41b9fa 100644 --- a/templates/admin/trace_tabs.tmpl +++ b/templates/admin/trace_tabs.tmpl @@ -1,9 +1,11 @@
+ {{if .ShowAdminPerformanceTraceTab}} {{ctx.Locale.Tr "admin.monitor.performance_logs"}} - {{ctx.Locale.Tr "admin.monitor.process"}} - {{ctx.Locale.Tr "admin.monitor.stacktrace"}} + {{end}} + {{ctx.Locale.Tr "admin.monitor.process"}} + {{ctx.Locale.Tr "admin.monitor.stacktrace"}}
From 76c1e134be045cd4155c980b5569cad094c082ba Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Fri, 17 Jan 2025 11:37:20 +0800 Subject: [PATCH 04/12] add tests --- modules/gtprof/trace.go | 27 ++++++---- modules/gtprof/trace_builtin.go | 2 +- modules/gtprof/trace_const.go | 2 +- modules/gtprof/trace_test.go | 89 +++++++++++++++++++++++++++++++++ 4 files changed, 108 insertions(+), 12 deletions(-) create mode 100644 modules/gtprof/trace_test.go diff --git a/modules/gtprof/trace.go b/modules/gtprof/trace.go index 1a06a9c828b94..4ea164e2c6c9d 100644 --- a/modules/gtprof/trace.go +++ b/modules/gtprof/trace.go @@ -1,4 +1,4 @@ -// Copyright 2024 The Gitea Authors. All rights reserved. +// Copyright 2025 The Gitea Authors. All rights reserved. // SPDX-License-Identifier: MIT package gtprof @@ -28,8 +28,9 @@ type traceSpanInternal interface { type TraceSpan struct { // immutable - parent *TraceSpan - internalSpans []traceSpanInternal + parent *TraceSpan + internalSpans []traceSpanInternal + internalContexts []context.Context // mutable, must be protected by mutex mu sync.RWMutex @@ -83,16 +84,22 @@ func (t *Tracer) Start(ctx context.Context, spanName string) (context.Context, * starters = globalTraceStarters } ts := &TraceSpan{name: spanName, startTime: time.Now()} - existingCtxSpan := GetContextSpan(ctx) - if existingCtxSpan != nil { - existingCtxSpan.mu.Lock() - existingCtxSpan.children = append(existingCtxSpan.children, ts) - existingCtxSpan.mu.Unlock() - ts.parent = existingCtxSpan + parentSpan := GetContextSpan(ctx) + if parentSpan != nil { + parentSpan.mu.Lock() + parentSpan.children = append(parentSpan.children, ts) + parentSpan.mu.Unlock() + ts.parent = parentSpan } + + parentCtx := ctx for internalSpanIdx, tsp := range starters { var internalSpan traceSpanInternal - ctx, internalSpan = tsp.start(ctx, ts, internalSpanIdx) + if parentSpan != nil { + parentCtx = parentSpan.internalContexts[internalSpanIdx] + } + ctx, internalSpan = tsp.start(parentCtx, ts, internalSpanIdx) + ts.internalContexts = append(ts.internalContexts, ctx) ts.internalSpans = append(ts.internalSpans, internalSpan) } ctx = context.WithValue(ctx, ContextKeySpan, ts) diff --git a/modules/gtprof/trace_builtin.go b/modules/gtprof/trace_builtin.go index d6f5146e3371e..b1d1e07b3177e 100644 --- a/modules/gtprof/trace_builtin.go +++ b/modules/gtprof/trace_builtin.go @@ -1,4 +1,4 @@ -// Copyright 2024 The Gitea Authors. All rights reserved. +// Copyright 2025 The Gitea Authors. All rights reserved. // SPDX-License-Identifier: MIT package gtprof diff --git a/modules/gtprof/trace_const.go b/modules/gtprof/trace_const.go index 96a0b885c81ef..af9ce9223fd36 100644 --- a/modules/gtprof/trace_const.go +++ b/modules/gtprof/trace_const.go @@ -1,4 +1,4 @@ -// Copyright 2024 The Gitea Authors. All rights reserved. +// Copyright 2025 The Gitea Authors. All rights reserved. // SPDX-License-Identifier: MIT package gtprof diff --git a/modules/gtprof/trace_test.go b/modules/gtprof/trace_test.go new file mode 100644 index 0000000000000..2c9042a9e7de5 --- /dev/null +++ b/modules/gtprof/trace_test.go @@ -0,0 +1,89 @@ +// Copyright 2025 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package gtprof + +import ( + "context" + "testing" + + "github.com/stretchr/testify/assert" +) + +// "vendor span" is a simple demo for a span from a vendor library + +var vendorContextKey any = "vendorContextKey" + +type vendorSpan struct { + name string + children []*vendorSpan +} + +func vendorTraceStart(ctx context.Context, name string) (context.Context, *vendorSpan) { + span := &vendorSpan{name: name} + parentSpan, ok := ctx.Value(vendorContextKey).(*vendorSpan) + if ok { + parentSpan.children = append(parentSpan.children, span) + } + ctx = context.WithValue(ctx, vendorContextKey, span) + return ctx, span +} + +// below "testTrace*" integrate the vendor span into our trace system + +type testTraceSpan struct { + vendorSpan *vendorSpan +} + +func (t *testTraceSpan) end() {} + +type testTraceStarter struct{} + +func (t *testTraceStarter) start(ctx context.Context, traceSpan *TraceSpan, internalSpanIdx int) (context.Context, traceSpanInternal) { + ctx, span := vendorTraceStart(ctx, traceSpan.name) + return ctx, &testTraceSpan{span} +} + +func TestTraceStarter(t *testing.T) { + globalTraceStarters = []traceStarter{&testTraceStarter{}} + + ctx := context.Background() + ctx, span := GetTracer().Start(ctx, "root") + defer span.End() + + func(ctx context.Context) { + ctx, span := GetTracer().Start(ctx, "span1") + defer span.End() + func(ctx context.Context) { + ctx, span := GetTracer().Start(ctx, "spanA") + defer span.End() + }(ctx) + func(ctx context.Context) { + ctx, span := GetTracer().Start(ctx, "spanB") + defer span.End() + }(ctx) + }(ctx) + + func(ctx context.Context) { + ctx, span := GetTracer().Start(ctx, "span2") + defer span.End() + }(ctx) + + var spanFullNames []string + var collectSpanNames func(parentFullName string, s *vendorSpan) + collectSpanNames = func(parentFullName string, s *vendorSpan) { + fullName := parentFullName + "/" + s.name + spanFullNames = append(spanFullNames, fullName) + for _, c := range s.children { + collectSpanNames(fullName, c) + } + } + collectSpanNames("", span.internalSpans[0].(*testTraceSpan).vendorSpan) + assert.Equal(t, []string([]string{ + "/root", + "/root/span1", + "/root/span1/spanA", + "/root/span1/spanB", + "/root/span2", + }), spanFullNames) +} From 8e5a0ff735c85d11b86a6db6beccf78592428bce Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Fri, 17 Jan 2025 11:47:50 +0800 Subject: [PATCH 05/12] add comments --- modules/gtprof/trace_test.go | 10 +++++----- modules/web/routing/context.go | 3 +++ 2 files changed, 8 insertions(+), 5 deletions(-) diff --git a/modules/gtprof/trace_test.go b/modules/gtprof/trace_test.go index 2c9042a9e7de5..c67ff2aa3a466 100644 --- a/modules/gtprof/trace_test.go +++ b/modules/gtprof/trace_test.go @@ -55,17 +55,17 @@ func TestTraceStarter(t *testing.T) { ctx, span := GetTracer().Start(ctx, "span1") defer span.End() func(ctx context.Context) { - ctx, span := GetTracer().Start(ctx, "spanA") + _, span := GetTracer().Start(ctx, "spanA") defer span.End() }(ctx) func(ctx context.Context) { - ctx, span := GetTracer().Start(ctx, "spanB") + _, span := GetTracer().Start(ctx, "spanB") defer span.End() }(ctx) }(ctx) func(ctx context.Context) { - ctx, span := GetTracer().Start(ctx, "span2") + _, span := GetTracer().Start(ctx, "span2") defer span.End() }(ctx) @@ -79,11 +79,11 @@ func TestTraceStarter(t *testing.T) { } } collectSpanNames("", span.internalSpans[0].(*testTraceSpan).vendorSpan) - assert.Equal(t, []string([]string{ + assert.Equal(t, []string{ "/root", "/root/span1", "/root/span1/spanA", "/root/span1/spanB", "/root/span2", - }), spanFullNames) + }, spanFullNames) } diff --git a/modules/web/routing/context.go b/modules/web/routing/context.go index 6a6aba4747929..d2e385e2fa0e8 100644 --- a/modules/web/routing/context.go +++ b/modules/web/routing/context.go @@ -15,6 +15,9 @@ type contextKeyType struct{} var contextKey contextKeyType +// StartContextSpan starts a trace span in Gitea's web request context +// Due to the design limitation of Gitea's web framework, it can't use `context.WithValue` to bind a new span into a new context. +// So here we use our "reqctx" framework to achieve the same result: web request context could always see the latest "span". func StartContextSpan(ctx reqctx.RequestContext, spanName string) (*gtprof.TraceSpan, func()) { curTraceSpan := gtprof.GetContextSpan(ctx) _, newTraceSpan := gtprof.GetTracer().Start(ctx, spanName) From 44aec4096a1bf7488958cdf9dd063849b125cc93 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sat, 18 Jan 2025 17:46:57 +0800 Subject: [PATCH 06/12] move scrollbar to parent --- templates/admin/perftrace.tmpl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/templates/admin/perftrace.tmpl b/templates/admin/perftrace.tmpl index 8e9ee71e894e4..51f6676b78236 100644 --- a/templates/admin/perftrace.tmpl +++ b/templates/admin/perftrace.tmpl @@ -4,8 +4,8 @@ {{template "admin/trace_tabs" .}} {{range $record := .PerfTraceRecords}} -
- 
{{$record.Content}}
+
+ 
{{$record.Content}}
{{end}}
From ea8dcfc031e3c675043ecd94a5c267cd79b92a4a Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sat, 18 Jan 2025 17:48:41 +0800 Subject: [PATCH 07/12] add comment for sql --- models/db/engine_hook.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/models/db/engine_hook.go b/models/db/engine_hook.go index d2655b3eeae6f..2c9fc09c99da7 100644 --- a/models/db/engine_hook.go +++ b/models/db/engine_hook.go @@ -29,6 +29,9 @@ func (*EngineHook) BeforeProcess(c *contexts.ContextHook) (context.Context, erro func (h *EngineHook) AfterProcess(c *contexts.ContextHook) error { span := gtprof.GetContextSpan(c.Ctx) if span != nil { + // Do not record SQL parameters here: + // * It shouldn't expose the parameters because they contain sensitive information, end users need to report the trace details safely. + // * Some parameters contain quite long texts, waste memory and are difficult to display. span.SetAttributeString(gtprof.TraceAttrDbSQL, c.SQL) span.End() } else { From 392f349f3a20d70bfc109cb368ec4345c140ecbd Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sat, 18 Jan 2025 20:29:07 +0800 Subject: [PATCH 08/12] improve shim layer, add event support --- modules/gtprof/event.go | 32 ++++++++++++++++++++++++++++++++ modules/gtprof/trace.go | 28 ++++++++++++++++++++++++++-- modules/gtprof/trace_builtin.go | 10 ++++++++++ modules/gtprof/trace_test.go | 4 ++++ 4 files changed, 72 insertions(+), 2 deletions(-) create mode 100644 modules/gtprof/event.go diff --git a/modules/gtprof/event.go b/modules/gtprof/event.go new file mode 100644 index 0000000000000..da4a0faff934a --- /dev/null +++ b/modules/gtprof/event.go @@ -0,0 +1,32 @@ +// Copyright 2025 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package gtprof + +type EventConfig struct { + attributes []*TraceAttribute +} + +type EventOption interface { + applyEvent(*EventConfig) +} + +type applyEventFunc func(*EventConfig) + +func (f applyEventFunc) applyEvent(cfg *EventConfig) { + f(cfg) +} + +func WithAttributes(attrs ...*TraceAttribute) EventOption { + return applyEventFunc(func(cfg *EventConfig) { + cfg.attributes = append(cfg.attributes, attrs...) + }) +} + +func eventConfigFromOptions(options ...EventOption) *EventConfig { + cfg := &EventConfig{} + for _, opt := range options { + opt.applyEvent(cfg) + } + return cfg +} diff --git a/modules/gtprof/trace.go b/modules/gtprof/trace.go index 4ea164e2c6c9d..c7edf06e055dc 100644 --- a/modules/gtprof/trace.go +++ b/modules/gtprof/trace.go @@ -23,6 +23,8 @@ type traceStarter interface { } type traceSpanInternal interface { + addEvent(name string, cfg *EventConfig) + recordError(err error, cfg *EventConfig) end() } @@ -35,9 +37,11 @@ type TraceSpan struct { // mutable, must be protected by mutex mu sync.RWMutex name string + statusCode uint32 + statusDesc string startTime time.Time endTime time.Time - attributes []TraceAttribute + attributes []*TraceAttribute children []*TraceSpan } @@ -70,11 +74,31 @@ type Tracer struct { starters []traceStarter } +func (s *TraceSpan) SetStatus(code uint32, desc string) { + s.mu.Lock() + defer s.mu.Unlock() + s.statusCode, s.statusDesc = code, desc +} + +func (s *TraceSpan) AddEvent(name string, options ...EventOption) { + cfg := eventConfigFromOptions(options...) + for _, tsp := range s.internalSpans { + tsp.addEvent(name, cfg) + } +} + +func (s *TraceSpan) RecordError(err error, options ...EventOption) { + cfg := eventConfigFromOptions(options...) + for _, tsp := range s.internalSpans { + tsp.recordError(err, cfg) + } +} + func (s *TraceSpan) SetAttributeString(key, value string) *TraceSpan { s.mu.Lock() defer s.mu.Unlock() - s.attributes = append(s.attributes, TraceAttribute{Key: key, Value: TraceValue{v: value}}) + s.attributes = append(s.attributes, &TraceAttribute{Key: key, Value: TraceValue{v: value}}) return s } diff --git a/modules/gtprof/trace_builtin.go b/modules/gtprof/trace_builtin.go index b1d1e07b3177e..41743a25e4d8a 100644 --- a/modules/gtprof/trace_builtin.go +++ b/modules/gtprof/trace_builtin.go @@ -21,6 +21,16 @@ type traceBuiltinSpan struct { internalSpanIdx int } +func (t *traceBuiltinSpan) addEvent(name string, cfg *EventConfig) { + // No-op because builtin tracer doesn't need it. + // In the future we might use it to mark the time point between backend logic and network response. +} + +func (t *traceBuiltinSpan) recordError(err error, cfg *EventConfig) { + // No-op because builtin tracer doesn't need it. + // Actually Gitea doesn't handle err this way in most cases +} + func (t *traceBuiltinSpan) toString(out *strings.Builder, indent int) { t.ts.mu.RLock() defer t.ts.mu.RUnlock() diff --git a/modules/gtprof/trace_test.go b/modules/gtprof/trace_test.go index c67ff2aa3a466..7e1743c88d4f1 100644 --- a/modules/gtprof/trace_test.go +++ b/modules/gtprof/trace_test.go @@ -35,6 +35,10 @@ type testTraceSpan struct { vendorSpan *vendorSpan } +func (t *testTraceSpan) addEvent(name string, cfg *EventConfig) {} + +func (t *testTraceSpan) recordError(err error, cfg *EventConfig) {} + func (t *testTraceSpan) end() {} type testTraceStarter struct{} From 7f9f30940be8f6a9b7c8babe6eb50c4213ebb712 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sat, 18 Jan 2025 20:45:34 +0800 Subject: [PATCH 09/12] add SetName --- modules/gtprof/trace.go | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/modules/gtprof/trace.go b/modules/gtprof/trace.go index c7edf06e055dc..c4eabd6239e7e 100644 --- a/modules/gtprof/trace.go +++ b/modules/gtprof/trace.go @@ -74,6 +74,12 @@ type Tracer struct { starters []traceStarter } +func (s *TraceSpan) SetName(name string) { + s.mu.Lock() + defer s.mu.Unlock() + s.name = name +} + func (s *TraceSpan) SetStatus(code uint32, desc string) { s.mu.Lock() defer s.mu.Unlock() From b8f78d25b33473bbbddc6b8c6837a800e96a344b Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sat, 18 Jan 2025 21:03:32 +0800 Subject: [PATCH 10/12] hide context details, callers do not need to know how the low-level framework works --- modules/gtprof/trace.go | 25 ++++++++++++++++++++++--- modules/web/routing/context.go | 15 +-------------- 2 files changed, 23 insertions(+), 17 deletions(-) diff --git a/modules/gtprof/trace.go b/modules/gtprof/trace.go index c4eabd6239e7e..ad67c226dcee4 100644 --- a/modules/gtprof/trace.go +++ b/modules/gtprof/trace.go @@ -16,7 +16,7 @@ type contextKey struct { name string } -var ContextKeySpan = &contextKey{"span"} +var contextKeySpan = &contextKey{"span"} type traceStarter interface { start(ctx context.Context, traceSpan *TraceSpan, internalSpanIdx int) (context.Context, traceSpanInternal) @@ -132,10 +132,29 @@ func (t *Tracer) Start(ctx context.Context, spanName string) (context.Context, * ts.internalContexts = append(ts.internalContexts, ctx) ts.internalSpans = append(ts.internalSpans, internalSpan) } - ctx = context.WithValue(ctx, ContextKeySpan, ts) + ctx = context.WithValue(ctx, contextKeySpan, ts) return ctx, ts } +type mutableContext interface { + context.Context + SetContextValue(key, value any) + GetContextValue(key any) any +} + +// StartInContext starts a trace span in Gitea's mutable context (usually the web request context). +// Due to the design limitation of Gitea's web framework, it can't use `context.WithValue` to bind a new span into a new context. +// So here we use our "reqctx" framework to achieve the same result: web request context could always see the latest "span". +func (t *Tracer) StartInContext(ctx mutableContext, spanName string) (*TraceSpan, func()) { + curTraceSpan := GetContextSpan(ctx) + _, newTraceSpan := GetTracer().Start(ctx, spanName) + ctx.SetContextValue(contextKeySpan, newTraceSpan) + return newTraceSpan, func() { + newTraceSpan.End() + ctx.SetContextValue(contextKeySpan, curTraceSpan) + } +} + func (s *TraceSpan) End() { s.mu.Lock() s.endTime = time.Now() @@ -151,6 +170,6 @@ func GetTracer() *Tracer { } func GetContextSpan(ctx context.Context) *TraceSpan { - ts, _ := ctx.Value(ContextKeySpan).(*TraceSpan) + ts, _ := ctx.Value(contextKeySpan).(*TraceSpan) return ts } diff --git a/modules/web/routing/context.go b/modules/web/routing/context.go index d2e385e2fa0e8..d3eb98f83db70 100644 --- a/modules/web/routing/context.go +++ b/modules/web/routing/context.go @@ -15,25 +15,12 @@ type contextKeyType struct{} var contextKey contextKeyType -// StartContextSpan starts a trace span in Gitea's web request context -// Due to the design limitation of Gitea's web framework, it can't use `context.WithValue` to bind a new span into a new context. -// So here we use our "reqctx" framework to achieve the same result: web request context could always see the latest "span". -func StartContextSpan(ctx reqctx.RequestContext, spanName string) (*gtprof.TraceSpan, func()) { - curTraceSpan := gtprof.GetContextSpan(ctx) - _, newTraceSpan := gtprof.GetTracer().Start(ctx, spanName) - ctx.SetContextValue(gtprof.ContextKeySpan, newTraceSpan) - return newTraceSpan, func() { - newTraceSpan.End() - ctx.SetContextValue(gtprof.ContextKeySpan, curTraceSpan) - } -} - // RecordFuncInfo records a func info into context func RecordFuncInfo(ctx context.Context, funcInfo *FuncInfo) (end func()) { end = func() {} if reqCtx := reqctx.FromContext(ctx); reqCtx != nil { var traceSpan *gtprof.TraceSpan - traceSpan, end = StartContextSpan(reqCtx, "http.func") + traceSpan, end = gtprof.GetTracer().StartInContext(reqCtx, "http.func") traceSpan.SetAttributeString("func", funcInfo.shortName) } if record, ok := ctx.Value(contextKey).(*requestRecord); ok { From 9a57ac76a4dde8a883c655cc23702ec8e67bd88e Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sun, 19 Jan 2025 00:06:27 +0800 Subject: [PATCH 11/12] rename --- modules/tailmsg/{taillog.go => talimsg.go} | 2 +- routers/web/admin/perftrace.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) rename modules/tailmsg/{taillog.go => talimsg.go} (95%) diff --git a/modules/tailmsg/taillog.go b/modules/tailmsg/talimsg.go similarity index 95% rename from modules/tailmsg/taillog.go rename to modules/tailmsg/talimsg.go index 5d3e6fefd1403..aafc98e2d2d06 100644 --- a/modules/tailmsg/taillog.go +++ b/modules/tailmsg/talimsg.go @@ -1,4 +1,4 @@ -// Copyright 2024 The Gitea Authors. All rights reserved. +// Copyright 2025 The Gitea Authors. All rights reserved. // SPDX-License-Identifier: MIT package tailmsg diff --git a/routers/web/admin/perftrace.go b/routers/web/admin/perftrace.go index 5c5a359505286..51ee57da10f74 100644 --- a/routers/web/admin/perftrace.go +++ b/routers/web/admin/perftrace.go @@ -1,4 +1,4 @@ -// Copyright 2024 The Gitea Authors. All rights reserved. +// Copyright 2025 The Gitea Authors. All rights reserved. // SPDX-License-Identifier: MIT package admin From 8fdccb071ba62574dd21e4c00d93dbfa4aa9e37d Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sun, 19 Jan 2025 17:48:24 +0800 Subject: [PATCH 12/12] Update templates/admin/perftrace.tmpl Co-authored-by: silverwind --- templates/admin/perftrace.tmpl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/templates/admin/perftrace.tmpl b/templates/admin/perftrace.tmpl index 51f6676b78236..2e09f14e46da4 100644 --- a/templates/admin/perftrace.tmpl +++ b/templates/admin/perftrace.tmpl @@ -4,7 +4,7 @@ {{template "admin/trace_tabs" .}} {{range $record := .PerfTraceRecords}} -
+ 
{{$record.Content}}
{{end}}