Skip to content

Commit 75b8c94

Browse files
committed
add profiling thats reusable
1 parent 1c1061c commit 75b8c94

File tree

5 files changed

+458
-4
lines changed

5 files changed

+458
-4
lines changed

pkg/buffer/buffer.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@ import (
77
"strings"
88
)
99

10-
func ProcessAsRingBufferToEnd(httpResp *http.Response, maxJobLogLines int) (string, int, *http.Response, error) {
10+
func ProcessResponseAsRingBufferToEnd(httpResp *http.Response, maxJobLogLines int) (string, int, *http.Response, error) {
1111
lines := make([]string, maxJobLogLines)
1212
validLines := make([]bool, maxJobLogLines)
1313
totalLines := 0

pkg/github/actions.go

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@ import (
1010

1111
buffer "github.com/github/github-mcp-server/pkg/buffer"
1212
ghErrors "github.com/github/github-mcp-server/pkg/errors"
13+
"github.com/github/github-mcp-server/pkg/profiler"
1314
"github.com/github/github-mcp-server/pkg/translations"
1415
"github.com/google/go-github/v74/github"
1516
"github.com/mark3labs/mcp-go/mcp"
@@ -722,7 +723,7 @@ func getJobLogData(ctx context.Context, client *github.Client, owner, repo strin
722723

723724
if returnContent {
724725
// Download and return the actual log content
725-
content, originalLength, httpResp, err := downloadLogContent(url.String(), tailLines) //nolint:bodyclose // Response body is closed in downloadLogContent, but we need to return httpResp
726+
content, originalLength, httpResp, err := downloadLogContent(ctx, url.String(), tailLines) //nolint:bodyclose // Response body is closed in downloadLogContent, but we need to return httpResp
726727
if err != nil {
727728
// To keep the return value consistent wrap the response as a GitHub Response
728729
ghRes := &github.Response{
@@ -743,7 +744,10 @@ func getJobLogData(ctx context.Context, client *github.Client, owner, repo strin
743744
return result, resp, nil
744745
}
745746

746-
func downloadLogContent(logURL string, tailLines int) (string, int, *http.Response, error) {
747+
func downloadLogContent(ctx context.Context, logURL string, tailLines int) (string, int, *http.Response, error) {
748+
prof := profiler.New(nil, profiler.IsProfilingEnabled())
749+
finish := prof.Start(ctx, "log_buffer_processing")
750+
747751
httpResp, err := http.Get(logURL) //nolint:gosec
748752
if err != nil {
749753
return "", 0, httpResp, fmt.Errorf("failed to download logs: %w", err)
@@ -763,7 +767,7 @@ func downloadLogContent(logURL string, tailLines int) (string, int, *http.Respon
763767
bufferSize = maxJobLogLines
764768
}
765769

766-
processedInput, totalLines, httpResp, err := buffer.ProcessAsRingBufferToEnd(httpResp, bufferSize)
770+
processedInput, totalLines, httpResp, err := buffer.ProcessResponseAsRingBufferToEnd(httpResp, bufferSize)
767771
if err != nil {
768772
return "", 0, httpResp, fmt.Errorf("failed to process log content: %w", err)
769773
}
@@ -774,6 +778,8 @@ func downloadLogContent(logURL string, tailLines int) (string, int, *http.Respon
774778
}
775779
finalResult := strings.Join(lines, "\n")
776780

781+
_ = finish(len(lines), int64(len(finalResult)))
782+
777783
return finalResult, totalLines, httpResp, nil
778784
}
779785

pkg/github/actions_test.go

Lines changed: 70 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,10 +3,17 @@ package github
33
import (
44
"context"
55
"encoding/json"
6+
"io"
67
"net/http"
78
"net/http/httptest"
9+
"os"
10+
"runtime"
11+
"runtime/debug"
12+
"strings"
813
"testing"
914

15+
buffer "github.com/github/github-mcp-server/pkg/buffer"
16+
"github.com/github/github-mcp-server/pkg/profiler"
1017
"github.com/github/github-mcp-server/pkg/translations"
1118
"github.com/google/go-github/v74/github"
1219
"github.com/migueleliasweb/go-github-mock/src/mock"
@@ -1214,3 +1221,66 @@ func Test_GetJobLogs_WithContentReturnAndLargeTailLines(t *testing.T) {
12141221
assert.Equal(t, "Job logs content retrieved successfully", response["message"])
12151222
assert.NotContains(t, response, "logs_url")
12161223
}
1224+
1225+
func Test_MemoryUsage_SlidingWindow_vs_NoWindow(t *testing.T) {
1226+
if testing.Short() {
1227+
t.Skip("Skipping memory profiling test in short mode")
1228+
}
1229+
1230+
const logLines = 100000
1231+
const bufferSize = 1000
1232+
largeLogContent := strings.Repeat("log line with some content\n", logLines)
1233+
1234+
testServer := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
1235+
w.WriteHeader(http.StatusOK)
1236+
_, _ = w.Write([]byte(largeLogContent))
1237+
}))
1238+
defer testServer.Close()
1239+
1240+
os.Setenv("GITHUB_MCP_PROFILING_ENABLED", "true")
1241+
defer os.Unsetenv("GITHUB_MCP_PROFILING_ENABLED")
1242+
1243+
// Initialize the global profiler
1244+
profiler.InitFromEnv(nil)
1245+
1246+
ctx := context.Background()
1247+
1248+
debug.SetGCPercent(-1)
1249+
profile1, err1 := profiler.ProfileFuncWithMetrics(ctx, "sliding_window", func() (int, int64, error) {
1250+
resp1, err := http.Get(testServer.URL)
1251+
if err != nil {
1252+
return 0, 0, err
1253+
}
1254+
defer resp1.Body.Close()
1255+
content, totalLines, _, err := buffer.ProcessResponseAsRingBufferToEnd(resp1, bufferSize)
1256+
return totalLines, int64(len(content)), err
1257+
})
1258+
require.NoError(t, err1)
1259+
1260+
runtime.GC()
1261+
profile2, err2 := profiler.ProfileFuncWithMetrics(ctx, "no_window", func() (int, int64, error) {
1262+
resp2, err := http.Get(testServer.URL)
1263+
if err != nil {
1264+
return 0, 0, err
1265+
}
1266+
defer resp2.Body.Close()
1267+
content, err := io.ReadAll(resp2.Body)
1268+
if err != nil {
1269+
return 0, 0, err
1270+
}
1271+
lines := strings.Split(string(content), "\n")
1272+
if len(lines) > bufferSize {
1273+
lines = lines[len(lines)-bufferSize:]
1274+
}
1275+
result := strings.Join(lines, "\n")
1276+
return len(strings.Split(string(content), "\n")), int64(len(result)), nil
1277+
})
1278+
require.NoError(t, err2)
1279+
debug.SetGCPercent(100)
1280+
1281+
assert.Greater(t, profile2.MemoryDelta, profile1.MemoryDelta,
1282+
"Sliding window should use less memory than reading all into memory")
1283+
1284+
t.Logf("Sliding window: %s", profile1.String())
1285+
t.Logf("No window: %s", profile2.String())
1286+
}

pkg/profiler/profiler.go

Lines changed: 195 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,195 @@
1+
package profiler
2+
3+
import (
4+
"context"
5+
"fmt"
6+
"os"
7+
"runtime"
8+
"strconv"
9+
"time"
10+
11+
"log/slog"
12+
)
13+
14+
// Profile represents performance metrics for an operation
15+
type Profile struct {
16+
Operation string `json:"operation"`
17+
Duration time.Duration `json:"duration_ns"`
18+
MemoryBefore uint64 `json:"memory_before_bytes"`
19+
MemoryAfter uint64 `json:"memory_after_bytes"`
20+
MemoryDelta int64 `json:"memory_delta_bytes"`
21+
LinesCount int `json:"lines_count,omitempty"`
22+
BytesCount int64 `json:"bytes_count,omitempty"`
23+
Timestamp time.Time `json:"timestamp"`
24+
}
25+
26+
// String returns a human-readable representation of the profile
27+
func (p *Profile) String() string {
28+
return fmt.Sprintf("[%s] %s: duration=%v, memory_delta=%+dB, lines=%d, bytes=%d",
29+
p.Timestamp.Format("15:04:05.000"),
30+
p.Operation,
31+
p.Duration,
32+
p.MemoryDelta,
33+
p.LinesCount,
34+
p.BytesCount,
35+
)
36+
}
37+
38+
// Profiler provides minimal performance profiling capabilities
39+
type Profiler struct {
40+
logger *slog.Logger
41+
enabled bool
42+
}
43+
44+
// New creates a new Profiler instance
45+
func New(logger *slog.Logger, enabled bool) *Profiler {
46+
return &Profiler{
47+
logger: logger,
48+
enabled: enabled,
49+
}
50+
}
51+
52+
// ProfileFunc profiles a function execution
53+
func (p *Profiler) ProfileFunc(ctx context.Context, operation string, fn func() error) (*Profile, error) {
54+
if !p.enabled {
55+
return nil, fn()
56+
}
57+
58+
profile := &Profile{
59+
Operation: operation,
60+
Timestamp: time.Now(),
61+
}
62+
63+
var memBefore runtime.MemStats
64+
runtime.ReadMemStats(&memBefore)
65+
profile.MemoryBefore = memBefore.Alloc
66+
67+
start := time.Now()
68+
err := fn()
69+
profile.Duration = time.Since(start)
70+
71+
var memAfter runtime.MemStats
72+
runtime.ReadMemStats(&memAfter)
73+
profile.MemoryAfter = memAfter.Alloc
74+
profile.MemoryDelta = int64(memAfter.Alloc) - int64(memBefore.Alloc)
75+
76+
if p.logger != nil {
77+
p.logger.InfoContext(ctx, "Performance profile", "profile", profile.String())
78+
}
79+
80+
return profile, err
81+
}
82+
83+
// ProfileFuncWithMetrics profiles a function execution and captures additional metrics
84+
func (p *Profiler) ProfileFuncWithMetrics(ctx context.Context, operation string, fn func() (int, int64, error)) (*Profile, error) {
85+
if !p.enabled {
86+
_, _, err := fn()
87+
return nil, err
88+
}
89+
90+
profile := &Profile{
91+
Operation: operation,
92+
Timestamp: time.Now(),
93+
}
94+
95+
var memBefore runtime.MemStats
96+
runtime.ReadMemStats(&memBefore)
97+
profile.MemoryBefore = memBefore.Alloc
98+
99+
start := time.Now()
100+
lines, bytes, err := fn()
101+
profile.Duration = time.Since(start)
102+
profile.LinesCount = lines
103+
profile.BytesCount = bytes
104+
105+
var memAfter runtime.MemStats
106+
runtime.ReadMemStats(&memAfter)
107+
profile.MemoryAfter = memAfter.Alloc
108+
profile.MemoryDelta = int64(memAfter.Alloc) - int64(memBefore.Alloc)
109+
110+
if p.logger != nil {
111+
p.logger.InfoContext(ctx, "Performance profile", "profile", profile.String())
112+
}
113+
114+
return profile, err
115+
}
116+
117+
// Start begins timing an operation and returns a function to complete the profiling
118+
func (p *Profiler) Start(ctx context.Context, operation string) func(lines int, bytes int64) *Profile {
119+
if !p.enabled {
120+
return func(int, int64) *Profile { return nil }
121+
}
122+
123+
profile := &Profile{
124+
Operation: operation,
125+
Timestamp: time.Now(),
126+
}
127+
128+
var memBefore runtime.MemStats
129+
runtime.ReadMemStats(&memBefore)
130+
profile.MemoryBefore = memBefore.Alloc
131+
132+
start := time.Now()
133+
134+
return func(lines int, bytes int64) *Profile {
135+
profile.Duration = time.Since(start)
136+
profile.LinesCount = lines
137+
profile.BytesCount = bytes
138+
139+
var memAfter runtime.MemStats
140+
runtime.ReadMemStats(&memAfter)
141+
profile.MemoryAfter = memAfter.Alloc
142+
profile.MemoryDelta = int64(memAfter.Alloc) - int64(memBefore.Alloc)
143+
144+
if p.logger != nil {
145+
p.logger.InfoContext(ctx, "Performance profile", "profile", profile.String())
146+
}
147+
148+
return profile
149+
}
150+
}
151+
152+
var globalProfiler *Profiler
153+
154+
// IsProfilingEnabled checks if profiling is enabled via environment variables
155+
func IsProfilingEnabled() bool {
156+
if enabled, err := strconv.ParseBool(os.Getenv("GITHUB_MCP_PROFILING_ENABLED")); err == nil {
157+
return enabled
158+
}
159+
return false
160+
}
161+
162+
// Init initializes the global profiler
163+
func Init(logger *slog.Logger, enabled bool) {
164+
globalProfiler = New(logger, enabled)
165+
}
166+
167+
// InitFromEnv initializes the global profiler using environment variables
168+
func InitFromEnv(logger *slog.Logger) {
169+
globalProfiler = New(logger, IsProfilingEnabled())
170+
}
171+
172+
// ProfileFunc profiles a function using the global profiler
173+
func ProfileFunc(ctx context.Context, operation string, fn func() error) (*Profile, error) {
174+
if globalProfiler == nil {
175+
return nil, fn()
176+
}
177+
return globalProfiler.ProfileFunc(ctx, operation, fn)
178+
}
179+
180+
// ProfileFuncWithMetrics profiles a function with metrics using the global profiler
181+
func ProfileFuncWithMetrics(ctx context.Context, operation string, fn func() (int, int64, error)) (*Profile, error) {
182+
if globalProfiler == nil {
183+
_, _, err := fn()
184+
return nil, err
185+
}
186+
return globalProfiler.ProfileFuncWithMetrics(ctx, operation, fn)
187+
}
188+
189+
// Start begins timing using the global profiler
190+
func Start(ctx context.Context, operation string) func(int, int64) *Profile {
191+
if globalProfiler == nil {
192+
return func(int, int64) *Profile { return nil }
193+
}
194+
return globalProfiler.Start(ctx, operation)
195+
}

0 commit comments

Comments
 (0)