loading up the forgejo repo on tangled to test page performance
feat: add limited execution tracing support
- For every process that is spawned (every new non-trivial goroutine
such as http requests, queues or tasks) start a [execution
tracer](https://pkg.go.dev/runtime/trace). This allows very precise
diagnosis of how each individual process over a time period.
- It's safe and [fast](https://go.dev/blog/execution-traces-2024#low-overhead-tracing) to
be run in production, hence no setting to disable this. There's only
noticable overhead when tracing is actually performed and not continuous.
- Proper tracing support would mean the codebase would be full of
`trace.WithRegion` and `trace.Log`, which feels premature for this patch
as there's no real-world usage yet to indicate which places would need
this the most. So far only Git commands and SQL queries receive somewhat
proper tracing support given that these are used throughout the codebase.
- Make git commands a new process type.
- Add tracing to diagnosis zip file.
+75
-17
+22
models/db/engine.go
+22
models/db/engine.go
···
11
11
"fmt"
12
12
"io"
13
13
"reflect"
14
+
"runtime/trace"
14
15
"strings"
15
16
"time"
16
17
···
162
163
xormEngine.AddHook(&ErrorQueryHook{
163
164
Logger: errorLogger,
164
165
})
166
+
167
+
xormEngine.AddHook(&TracingHook{})
165
168
166
169
SetDefaultEngine(ctx, xormEngine)
167
170
return nil
···
316
319
} else if sess, ok := e.(*xorm.Session); ok {
317
320
sess.Engine().ShowSQL(on)
318
321
}
322
+
}
323
+
324
+
type TracingHook struct{}
325
+
326
+
var _ contexts.Hook = &TracingHook{}
327
+
328
+
type sqlTask struct{}
329
+
330
+
func (TracingHook) BeforeProcess(c *contexts.ContextHook) (context.Context, error) {
331
+
ctx, task := trace.NewTask(c.Ctx, "sql")
332
+
ctx = context.WithValue(ctx, sqlTask{}, task)
333
+
trace.Log(ctx, "query", c.SQL)
334
+
trace.Logf(ctx, "args", "%v", c.Args)
335
+
return ctx, nil
336
+
}
337
+
338
+
func (TracingHook) AfterProcess(c *contexts.ContextHook) error {
339
+
c.Ctx.Value(sqlTask{}).(*trace.Task).End()
340
+
return nil
319
341
}
320
342
321
343
type SlowQueryHook struct {
+4
-2
modules/git/command.go
+4
-2
modules/git/command.go
···
13
13
"os"
14
14
"os/exec"
15
15
"runtime"
16
+
"runtime/trace"
16
17
"strings"
17
18
"time"
18
19
···
317
318
var finished context.CancelFunc
318
319
319
320
if opts.UseContextTimeout {
320
-
ctx, cancel, finished = process.GetManager().AddContext(c.parentContext, desc)
321
+
ctx, cancel, finished = process.GetManager().AddTypedContext(c.parentContext, desc, process.GitProcessType, true)
321
322
} else {
322
-
ctx, cancel, finished = process.GetManager().AddContextTimeout(c.parentContext, timeout, desc)
323
+
ctx, cancel, finished = process.GetManager().AddTypedContextTimeout(c.parentContext, timeout, desc, process.GitProcessType, true)
323
324
}
324
325
defer finished()
325
326
327
+
trace.Log(ctx, "command", desc)
326
328
startTime := time.Now()
327
329
328
330
cmd := exec.CommandContext(ctx, c.prog, c.args...)
+20
-3
modules/process/manager.go
+20
-3
modules/process/manager.go
···
7
7
import (
8
8
"context"
9
9
"runtime/pprof"
10
+
"runtime/trace"
10
11
"strconv"
11
12
"sync"
12
13
"sync/atomic"
···
126
127
return ctx, cancel, finished
127
128
}
128
129
129
-
// AddContextTimeout creates a new context and add it as a process. Once the process is finished, finished must be called
130
+
// AddTypedContextTimeout creates a new context and adds it as a process. Once the process is finished, finished must be called
130
131
// to remove the process from the process table. It should not be called until the process is finished but must always be called.
131
132
//
132
133
// cancel should be used to cancel the returned context, however it will not remove the process from the process table.
···
134
135
//
135
136
// Most processes will not need to use the cancel function but there will be cases whereby you want to cancel the process but not immediately remove it from the
136
137
// process table.
137
-
func (pm *Manager) AddContextTimeout(parent context.Context, timeout time.Duration, description string) (ctx context.Context, cancel context.CancelFunc, finished FinishedFunc) {
138
+
func (pm *Manager) AddTypedContextTimeout(parent context.Context, timeout time.Duration, description, processType string, currentlyRunning bool) (ctx context.Context, cancel context.CancelFunc, finished FinishedFunc) {
138
139
if timeout <= 0 {
139
140
// it's meaningless to use timeout <= 0, and it must be a bug! so we must panic here to tell developers to make the timeout correct
140
141
panic("the timeout must be greater than zero, otherwise the context will be cancelled immediately")
···
142
143
143
144
ctx, cancel = context.WithTimeout(parent, timeout)
144
145
145
-
ctx, _, finished = pm.Add(ctx, description, cancel, NormalProcessType, true)
146
+
ctx, _, finished = pm.Add(ctx, description, cancel, processType, currentlyRunning)
146
147
147
148
return ctx, cancel, finished
148
149
}
149
150
151
+
// AddContextTimeout creates a new context and add it as a process. Once the process is finished, finished must be called
152
+
// to remove the process from the process table. It should not be called until the process is finished but must always be called.
153
+
//
154
+
// cancel should be used to cancel the returned context, however it will not remove the process from the process table.
155
+
// finished will cancel the returned context and remove it from the process table.
156
+
//
157
+
// Most processes will not need to use the cancel function but there will be cases whereby you want to cancel the process but not immediately remove it from the
158
+
// process table.
159
+
func (pm *Manager) AddContextTimeout(parent context.Context, timeout time.Duration, description string) (ctx context.Context, cancel context.CancelFunc, finished FinishedFunc) {
160
+
return pm.AddTypedContextTimeout(parent, timeout, description, NormalProcessType, true)
161
+
}
162
+
150
163
// Add create a new process
151
164
func (pm *Manager) Add(ctx context.Context, description string, cancel context.CancelFunc, processType string, currentlyRunning bool) (context.Context, IDType, FinishedFunc) {
152
165
parentPID := GetParentPID(ctx)
···
159
172
parentPID = ""
160
173
}
161
174
175
+
ctx, traceTask := trace.NewTask(ctx, processType)
176
+
162
177
process := &process{
163
178
PID: pid,
164
179
ParentPID: parentPID,
···
166
181
Start: start,
167
182
Cancel: cancel,
168
183
Type: processType,
184
+
TraceTrask: traceTask,
169
185
}
170
186
171
187
var finished FinishedFunc
···
218
234
}
219
235
220
236
func (pm *Manager) remove(process *process) {
237
+
process.TraceTrask.End()
221
238
deleted := false
222
239
223
240
pm.mutex.Lock()
+3
modules/process/process.go
+3
modules/process/process.go
···
5
5
6
6
import (
7
7
"context"
8
+
"runtime/trace"
8
9
"time"
9
10
)
10
11
11
12
var (
12
13
SystemProcessType = "system"
13
14
RequestProcessType = "request"
15
+
GitProcessType = "git"
14
16
NormalProcessType = "normal"
15
17
NoneProcessType = "none"
16
18
)
···
23
25
Start time.Time
24
26
Cancel context.CancelFunc
25
27
Type string
28
+
TraceTrask *trace.Task
26
29
}
27
30
28
31
// ToProcess converts a process to a externally usable Process
+3
routers/common/middleware.go
+3
routers/common/middleware.go
···
6
6
import (
7
7
"fmt"
8
8
"net/http"
9
+
"runtime/trace"
9
10
"strings"
10
11
11
12
"code.gitea.io/gitea/modules/cache"
···
43
44
return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
44
45
ctx, _, finished := process.GetManager().AddTypedContext(req.Context(), fmt.Sprintf("%s: %s", req.Method, req.RequestURI), process.RequestProcessType, true)
45
46
defer finished()
47
+
trace.Log(ctx, "method", req.Method)
48
+
trace.Log(ctx, "url", req.RequestURI)
46
49
next.ServeHTTP(context.WrapResponseWriter(resp), req.WithContext(cache.WithCacheContext(ctx)))
47
50
})
48
51
})
+21
-12
routers/web/admin/diagnosis.go
+21
-12
routers/web/admin/diagnosis.go
···
7
7
"archive/zip"
8
8
"fmt"
9
9
"runtime/pprof"
10
+
"runtime/trace"
10
11
"time"
11
12
12
13
"code.gitea.io/gitea/modules/httplib"
···
15
16
16
17
func MonitorDiagnosis(ctx *context.Context) {
17
18
seconds := ctx.FormInt64("seconds")
18
-
if seconds <= 5 {
19
-
seconds = 5
20
-
}
21
-
if seconds > 300 {
22
-
seconds = 300
23
-
}
19
+
seconds = max(5, min(300, seconds))
24
20
25
21
httplib.ServeSetHeaders(ctx.Resp, &httplib.ServeHeaderOptions{
26
22
ContentType: "application/zip",
27
23
Disposition: "attachment",
28
-
Filename: fmt.Sprintf("gitea-diagnosis-%s.zip", time.Now().Format("20060102-150405")),
24
+
Filename: fmt.Sprintf("forgejo-diagnosis-%s.zip", time.Now().Format("20060102-150405")),
29
25
})
30
26
31
27
zipWriter := zip.NewWriter(ctx.Resp)
···
44
40
return
45
41
}
46
42
47
-
err = pprof.StartCPUProfile(f)
48
-
if err == nil {
49
-
time.Sleep(time.Duration(seconds) * time.Second)
50
-
pprof.StopCPUProfile()
51
-
} else {
43
+
if err := pprof.StartCPUProfile(f); err != nil {
44
+
_, _ = f.Write([]byte(err.Error()))
45
+
}
46
+
47
+
f, err = zipWriter.CreateHeader(&zip.FileHeader{Name: "trace.dat", Method: zip.Deflate, Modified: time.Now()})
48
+
if err != nil {
49
+
ctx.ServerError("Failed to create zip file", err)
50
+
return
51
+
}
52
+
53
+
if err := trace.Start(f); err != nil {
52
54
_, _ = f.Write([]byte(err.Error()))
53
55
}
56
+
57
+
select {
58
+
case <-time.After(time.Duration(seconds) * time.Second):
59
+
case <-ctx.Done():
60
+
}
61
+
pprof.StopCPUProfile()
62
+
trace.Stop()
54
63
55
64
f, err = zipWriter.CreateHeader(&zip.FileHeader{Name: "goroutine-after.txt", Method: zip.Deflate, Modified: time.Now()})
56
65
if err != nil {