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 b231c3beea012..8592748b071cd 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 } @@ -289,15 +290,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..c12c9b9bec3c2 --- /dev/null +++ b/modules/gtprof/trace.go @@ -0,0 +1,116 @@ +// 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()} + ts.parent, _ = ctx.Value(ContextKeySpan).(*TraceSpan) + if ts.parent != nil { + ts.parent.children = append(ts.parent.children, ts) + } + for i, tsp := range starters { + var internalSpan traceSpanInternal + ctx, internalSpan = tsp.start(ctx, ts, i) + 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 ea4d36fb1ca7d..357ae0f259340 100644 --- a/options/locale/locale_en-US.ini +++ b/options/locale/locale_en-US.ini @@ -3355,6 +3355,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 @@ -3363,7 +3365,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"}} +
+
+
+ +