add profiling thats reusable

mattdholloway · Aug 19, 2025 · Aug 12, 2025 · Aug 12, 2025 · Aug 12, 2025 · Aug 12, 2025
commit 75b8c94bf6ba6c1e839f33258e3f0ee1201a5355
@@ -7,7 +7,7 @@ import (
 	"strings"
 )
 
-func ProcessAsRingBufferToEnd(httpResp *http.Response, maxJobLogLines int) (string, int, *http.Response, error) {
+func ProcessResponseAsRingBufferToEnd(httpResp *http.Response, maxJobLogLines int) (string, int, *http.Response, error) {
 	lines := make([]string, maxJobLogLines)
 	validLines := make([]bool, maxJobLogLines)
 	totalLines := 0

@@ -10,6 +10,7 @@ import (
 
 	buffer "github.com/github/github-mcp-server/pkg/buffer"
 	ghErrors "github.com/github/github-mcp-server/pkg/errors"
+	"github.com/github/github-mcp-server/pkg/profiler"
 	"github.com/github/github-mcp-server/pkg/translations"
 	"github.com/google/go-github/v74/github"
 	"github.com/mark3labs/mcp-go/mcp"
@@ -722,7 +723,7 @@ func getJobLogData(ctx context.Context, client *github.Client, owner, repo strin
 
 	if returnContent {
 		// Download and return the actual log content
-		content, originalLength, httpResp, err := downloadLogContent(url.String(), tailLines) //nolint:bodyclose // Response body is closed in downloadLogContent, but we need to return httpResp
+		content, originalLength, httpResp, err := downloadLogContent(ctx, url.String(), tailLines) //nolint:bodyclose // Response body is closed in downloadLogContent, but we need to return httpResp
 		if err != nil {
 			// To keep the return value consistent wrap the response as a GitHub Response
 			ghRes := &github.Response{
@@ -743,7 +744,10 @@ func getJobLogData(ctx context.Context, client *github.Client, owner, repo strin
 	return result, resp, nil
 }
 
-func downloadLogContent(logURL string, tailLines int) (string, int, *http.Response, error) {
+func downloadLogContent(ctx context.Context, logURL string, tailLines int) (string, int, *http.Response, error) {
+	prof := profiler.New(nil, profiler.IsProfilingEnabled())
+	finish := prof.Start(ctx, "log_buffer_processing")
-	finish := prof.Start(ctx, "log_buffer_processing")
+	finish := globalProfiler.Start(ctx, "log_buffer_processing")
-	finish := prof.Start(ctx, "log_buffer_processing")
+	finish := globalProfiler.Start(ctx, "log_buffer_processing")
+
 	httpResp, err := http.Get(logURL) //nolint:gosec
 	if err != nil {
 		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
 		bufferSize = maxJobLogLines
 	}
 
-	processedInput, totalLines, httpResp, err := buffer.ProcessAsRingBufferToEnd(httpResp, bufferSize)
+	processedInput, totalLines, httpResp, err := buffer.ProcessResponseAsRingBufferToEnd(httpResp, bufferSize)
 	if err != nil {
 		return "", 0, httpResp, fmt.Errorf("failed to process log content: %w", err)
 	}
@@ -774,6 +778,8 @@ func downloadLogContent(logURL string, tailLines int) (string, int, *http.Respon
 	}
 	finalResult := strings.Join(lines, "\n")
 
+	_ = finish(len(lines), int64(len(finalResult)))
+
 	return finalResult, totalLines, httpResp, nil
 }
 

@@ -3,10 +3,17 @@ package github
 import (
 	"context"
 	"encoding/json"
+	"io"
 	"net/http"
 	"net/http/httptest"
+	"os"
+	"runtime"
+	"runtime/debug"
+	"strings"
 	"testing"
 
+	buffer "github.com/github/github-mcp-server/pkg/buffer"
+	"github.com/github/github-mcp-server/pkg/profiler"
 	"github.com/github/github-mcp-server/pkg/translations"
 	"github.com/google/go-github/v74/github"
 	"github.com/migueleliasweb/go-github-mock/src/mock"
@@ -1214,3 +1221,66 @@ func Test_GetJobLogs_WithContentReturnAndLargeTailLines(t *testing.T) {
 	assert.Equal(t, "Job logs content retrieved successfully", response["message"])
 	assert.NotContains(t, response, "logs_url")
 }
+
+func Test_MemoryUsage_SlidingWindow_vs_NoWindow(t *testing.T) {
+	if testing.Short() {
+		t.Skip("Skipping memory profiling test in short mode")
+	}
+
+	const logLines = 100000
+	const bufferSize = 1000
+	largeLogContent := strings.Repeat("log line with some content\n", logLines)
+
+	testServer := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+		w.WriteHeader(http.StatusOK)
+		_, _ = w.Write([]byte(largeLogContent))
+	}))
+	defer testServer.Close()
+
+	os.Setenv("GITHUB_MCP_PROFILING_ENABLED", "true")
+	defer os.Unsetenv("GITHUB_MCP_PROFILING_ENABLED")
+
+	// Initialize the global profiler
+	profiler.InitFromEnv(nil)
+
+	ctx := context.Background()
+
+	debug.SetGCPercent(-1)
+	profile1, err1 := profiler.ProfileFuncWithMetrics(ctx, "sliding_window", func() (int, int64, error) {
+		resp1, err := http.Get(testServer.URL)
+		if err != nil {
+			return 0, 0, err
+		}
+		defer resp1.Body.Close()
+		content, totalLines, _, err := buffer.ProcessResponseAsRingBufferToEnd(resp1, bufferSize)
+		return totalLines, int64(len(content)), err
+	})
+	require.NoError(t, err1)
+
+	runtime.GC()
+	profile2, err2 := profiler.ProfileFuncWithMetrics(ctx, "no_window", func() (int, int64, error) {
+		resp2, err := http.Get(testServer.URL)
+		if err != nil {
+			return 0, 0, err
+		}
+		defer resp2.Body.Close()
+		content, err := io.ReadAll(resp2.Body)
+		if err != nil {
+			return 0, 0, err
+		}
+		lines := strings.Split(string(content), "\n")
+		if len(lines) > bufferSize {
+			lines = lines[len(lines)-bufferSize:]
+		}
+		result := strings.Join(lines, "\n")
+		return len(strings.Split(string(content), "\n")), int64(len(result)), nil
+	})
+	require.NoError(t, err2)
+	debug.SetGCPercent(100)
+
+	assert.Greater(t, profile2.MemoryDelta, profile1.MemoryDelta,
+		"Sliding window should use less memory than reading all into memory")
+
+	t.Logf("Sliding window: %s", profile1.String())
+	t.Logf("No window: %s", profile2.String())
+}
diff --git a/pkg/profiler/profiler.go b/pkg/profiler/profiler.go
@@ -0,0 +1,195 @@
+package profiler
+
+import (
+	"context"
+	"fmt"
+	"os"
+	"runtime"
+	"strconv"
+	"time"
+
+	"log/slog"
+)
+
+// Profile represents performance metrics for an operation
+type Profile struct {
+	Operation    string        `json:"operation"`
+	Duration     time.Duration `json:"duration_ns"`
+	MemoryBefore uint64        `json:"memory_before_bytes"`
+	MemoryAfter  uint64        `json:"memory_after_bytes"`
+	MemoryDelta  int64         `json:"memory_delta_bytes"`
+	LinesCount   int           `json:"lines_count,omitempty"`
+	BytesCount   int64         `json:"bytes_count,omitempty"`
+	Timestamp    time.Time     `json:"timestamp"`
+}
+
+// String returns a human-readable representation of the profile
+func (p *Profile) String() string {
+	return fmt.Sprintf("[%s] %s: duration=%v, memory_delta=%+dB, lines=%d, bytes=%d",
+		p.Timestamp.Format("15:04:05.000"),
+		p.Operation,
+		p.Duration,
+		p.MemoryDelta,
+		p.LinesCount,
+		p.BytesCount,
+	)
+}
+
+// Profiler provides minimal performance profiling capabilities
+type Profiler struct {
+	logger  *slog.Logger
+	enabled bool
+}
+
+// New creates a new Profiler instance
+func New(logger *slog.Logger, enabled bool) *Profiler {
+	return &Profiler{
+		logger:  logger,
+		enabled: enabled,
+	}
+}
+
+// ProfileFunc profiles a function execution
+func (p *Profiler) ProfileFunc(ctx context.Context, operation string, fn func() error) (*Profile, error) {
+	if !p.enabled {
+		return nil, fn()
+	}
+
+	profile := &Profile{
+		Operation: operation,
+		Timestamp: time.Now(),
+	}
+
+	var memBefore runtime.MemStats
+	runtime.ReadMemStats(&memBefore)
+	profile.MemoryBefore = memBefore.Alloc
+
+	start := time.Now()
+	err := fn()
+	profile.Duration = time.Since(start)
+
+	var memAfter runtime.MemStats
+	runtime.ReadMemStats(&memAfter)
+	profile.MemoryAfter = memAfter.Alloc
+	profile.MemoryDelta = int64(memAfter.Alloc) - int64(memBefore.Alloc)
+
+	if p.logger != nil {
+		p.logger.InfoContext(ctx, "Performance profile", "profile", profile.String())
+	}
+
+	return profile, err
+}
+
+// ProfileFuncWithMetrics profiles a function execution and captures additional metrics
+func (p *Profiler) ProfileFuncWithMetrics(ctx context.Context, operation string, fn func() (int, int64, error)) (*Profile, error) {
+	if !p.enabled {
+		_, _, err := fn()
+		return nil, err
+	}
+
+	profile := &Profile{
+		Operation: operation,
+		Timestamp: time.Now(),
+	}
+
+	var memBefore runtime.MemStats
+	runtime.ReadMemStats(&memBefore)
+	profile.MemoryBefore = memBefore.Alloc
+
+	start := time.Now()
+	lines, bytes, err := fn()
+	profile.Duration = time.Since(start)
+	profile.LinesCount = lines
+	profile.BytesCount = bytes
+
+	var memAfter runtime.MemStats
+	runtime.ReadMemStats(&memAfter)
+	profile.MemoryAfter = memAfter.Alloc
+	profile.MemoryDelta = int64(memAfter.Alloc) - int64(memBefore.Alloc)
+
+	if p.logger != nil {
+		p.logger.InfoContext(ctx, "Performance profile", "profile", profile.String())
+	}
+
+	return profile, err
+}
+
+// Start begins timing an operation and returns a function to complete the profiling
+func (p *Profiler) Start(ctx context.Context, operation string) func(lines int, bytes int64) *Profile {
+	if !p.enabled {
+		return func(int, int64) *Profile { return nil }
+	}
+
+	profile := &Profile{
+		Operation: operation,
+		Timestamp: time.Now(),
+	}
+
+	var memBefore runtime.MemStats
+	runtime.ReadMemStats(&memBefore)
+	profile.MemoryBefore = memBefore.Alloc
+
+	start := time.Now()
+
+	return func(lines int, bytes int64) *Profile {
+		profile.Duration = time.Since(start)
+		profile.LinesCount = lines
+		profile.BytesCount = bytes
+
+		var memAfter runtime.MemStats
+		runtime.ReadMemStats(&memAfter)
+		profile.MemoryAfter = memAfter.Alloc
+		profile.MemoryDelta = int64(memAfter.Alloc) - int64(memBefore.Alloc)
+
+		if p.logger != nil {
+			p.logger.InfoContext(ctx, "Performance profile", "profile", profile.String())
+		}
+
+		return profile
+	}
+}
+
+var globalProfiler *Profiler
+
+// IsProfilingEnabled checks if profiling is enabled via environment variables
+func IsProfilingEnabled() bool {
+	if enabled, err := strconv.ParseBool(os.Getenv("GITHUB_MCP_PROFILING_ENABLED")); err == nil {
+		return enabled
+	}
+	return false
+}
+
+// Init initializes the global profiler
+func Init(logger *slog.Logger, enabled bool) {
+	globalProfiler = New(logger, enabled)
+}
+
+// InitFromEnv initializes the global profiler using environment variables
+func InitFromEnv(logger *slog.Logger) {
+	globalProfiler = New(logger, IsProfilingEnabled())
+}
+
+// ProfileFunc profiles a function using the global profiler
+func ProfileFunc(ctx context.Context, operation string, fn func() error) (*Profile, error) {
+	if globalProfiler == nil {
+		return nil, fn()
+	}
+	return globalProfiler.ProfileFunc(ctx, operation, fn)
+}
+
+// ProfileFuncWithMetrics profiles a function with metrics using the global profiler
+func ProfileFuncWithMetrics(ctx context.Context, operation string, fn func() (int, int64, error)) (*Profile, error) {
+	if globalProfiler == nil {
+		_, _, err := fn()
+		return nil, err
+	}
+	return globalProfiler.ProfileFuncWithMetrics(ctx, operation, fn)
+}
+
+// Start begins timing using the global profiler
+func Start(ctx context.Context, operation string) func(int, int64) *Profile {
+	if globalProfiler == nil {
+		return func(int, int64) *Profile { return nil }
+	}
+	return globalProfiler.Start(ctx, operation)
+}