1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
|
# Trace Logging Performance Impact in Turbo Mode
## Summary
The `dlog.Server.Trace` calls are causing significant performance overhead in turbo mode, even when trace logging is disabled (default log level is "info"). The overhead comes primarily from `runtime.Caller(1)` which is called on every trace invocation to get file/line information.
## Key Findings
### 1. Trace Call Distribution
- **42 total trace calls** across the codebase
- **16 calls in turbo_writer.go** - the hot path for turbo mode
- **8 trace calls in WriteLineData** - called for every line processed
### 2. Performance Measurements
#### Per-Call Overhead
- **497 nanoseconds per trace call** when logging is disabled
- Almost all overhead (>99%) comes from `runtime.Caller(1)`
- The log level check itself has negligible overhead
#### Real-World Impact
Testing with a 100,000 line file showed:
- **With trace calls**: 240ms (416K lines/sec)
- **Without trace calls**: 19ms (5.36M lines/sec)
- **Performance degradation**: 1,188% slower (12x slower!)
- **Throughput loss**: 4.9 million lines/sec
#### Extrapolated Impact on Large Files
- 1M lines: 2.2 seconds overhead
- 10M lines: 22 seconds overhead
- 100M lines: 3 minutes 41 seconds overhead
### 3. Hot Path Analysis
The most impactful trace calls are in `WriteLineData`:
1. Entry trace with line number and content length
2. Stats trace with lines/bytes written
3. Channel operation traces (3-4 calls)
4. Success/retry traces
For a 1M line file, this results in 8M trace calls, adding ~4 seconds of overhead.
## Root Cause
Even when trace logging is disabled, each `dlog.Server.Trace` call:
1. Calls `runtime.Caller(1)` to get file/line info (expensive!)
2. Allocates memory for the args slice
3. Formats the file/line string
4. Only then checks if trace level is enabled
The current implementation in `dlog.go`:
```go
func (d *DLog) Trace(args ...interface{}) string {
_, file, line, _ := runtime.Caller(1) // Always executed!
args = append(args, fmt.Sprintf("at %s:%d", file, line))
return d.log(Trace, args) // Level check happens inside here
}
```
## Recommendations
### 1. Immediate Fix - Add Early Level Check
```go
func (d *DLog) Trace(args ...interface{}) string {
if d.maxLevel < Trace {
return "" // Skip runtime.Caller when trace is disabled
}
_, file, line, _ := runtime.Caller(1)
args = append(args, fmt.Sprintf("at %s:%d", file, line))
return d.log(Trace, args)
}
```
### 2. Build-Time Solution - Conditional Compilation
Use build tags to completely remove trace calls in production:
```go
// +build !debug
func (d *DLog) Trace(args ...interface{}) string {
return "" // No-op in production builds
}
```
### 3. Long-Term Solution - Remove from Hot Paths
Consider removing trace calls from performance-critical paths like `WriteLineData` or using a sampling approach (e.g., trace every 1000th line).
## Conclusion
The trace logging overhead is severe enough to negate much of the performance benefit of turbo mode. With the simple fix of checking the log level before calling `runtime.Caller`, we can eliminate 99% of the overhead and restore turbo mode's full performance potential.
|
