http: add opt-in slow query and request logging

Add two configuration knobs to help diagnose performance issues:

  [http]
  slow-request = "50ms"
  slow-query = "5ms"

When set, HTTP requests and SQL queries exceeding the threshold
are logged at WARN level with their duration. Both are disabled
by default (zero value).

Signed-off-by: Robin Jarry <robin@jarry.cc>

Author: rjarry

pkg/config/config.go

@@ -31,11 +31,13 @@ type IngressConfig struct {
 }
 
 type HttpConfig struct {
-	BaseURL    string `help:"Base URL of the patchwork instance."`
-	Listen     string `help:"HTTP listen address." default:"127.0.0.1:8080"`
-	CustomCSS  string `help:"Path to a custom CSS file served after the built-in stylesheet." type:"existingfile"`
-	NavHTML    string `help:"Path to an HTML file whose content is inserted in the navigation bar." type:"existingfile"`
-	FooterHTML string `help:"Path to an HTML file whose content is inserted in the footer." type:"existingfile"`
+	BaseURL     string   `help:"Base URL of the patchwork instance."`
+	Listen      string   `help:"HTTP listen address." default:"127.0.0.1:8080"`
+	SlowRequest Duration `help:"Log HTTP requests slower than this threshold."`
+	SlowQuery   Duration `help:"Log SQL queries slower than this threshold."`
+	CustomCSS   string   `help:"Path to a custom CSS file served after the built-in stylesheet." type:"existingfile"`
+	NavHTML     string   `help:"Path to an HTML file whose content is inserted in the navigation bar." type:"existingfile"`
+	FooterHTML  string   `help:"Path to an HTML file whose content is inserted in the footer." type:"existingfile"`
 }
 
 type SMTPConfig struct {

pkg/db/queryhook.go

@@ -0,0 +1,36 @@
+// Patchwork - automated patch tracking system
+// Copyright (C) The Patchwork Contributors (see CONTRIBUTORS)
+//
+// SPDX-License-Identifier: GPL-2.0-or-later
+
+package db
+
+import (
+	"context"
+	"time"
+
+	"github.com/uptrace/bun"
+
+	"github.com/getpatchwork/patchwork/pkg/log"
+)
+
+type slowQueryHook struct {
+	threshold time.Duration
+}
+
+type startTimeKey struct{}
+
+func NewSlowQueryHook(threshold time.Duration) bun.QueryHook {
+	return &slowQueryHook{threshold: threshold}
+}
+
+func (h *slowQueryHook) BeforeQuery(ctx context.Context, event *bun.QueryEvent) context.Context {
+	return context.WithValue(ctx, startTimeKey{}, time.Now())
+}
+
+func (h *slowQueryHook) AfterQuery(ctx context.Context, event *bun.QueryEvent) {
+	dur := time.Since(event.StartTime)
+	if dur >= h.threshold {
+		log.Warnf("slow query (%s): %s", dur.Round(time.Millisecond), event.Query)
+	}
+}

pkg/web/web.go

@@ -19,6 +19,7 @@ import (
 	"regexp"
 	"strconv"
 	"strings"
+	"time"
 
 	"github.com/go-chi/chi/v5"
 	"github.com/go-chi/chi/v5/middleware"
@@ -36,6 +37,12 @@ func NewRouter(cfg *config.Config, database *bun.DB, bus db.EventBus, version st
 	r := chi.NewRouter()
 	r.Use(middleware.Recoverer)
 	r.Use(middleware.StripSlashes)
+	if t := cfg.Http.SlowRequest.Duration(); t > 0 {
+		r.Use(slowRequestLogger(t))
+	}
+	if t := cfg.Http.SlowQuery.Duration(); t > 0 {
+		database.AddQueryHook(db.NewSlowQueryHook(t))
+	}
 	r.Use(db.Middleware(database, bus))
 
 	csrfKey := make([]byte, 32)
@@ -272,6 +279,20 @@ func isURL(s string) bool {
 	return strings.HasPrefix(s, "http://") || strings.HasPrefix(s, "https://")
 }
 
+func slowRequestLogger(threshold time.Duration) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			start := time.Now()
+			next.ServeHTTP(w, r)
+			dur := time.Since(start)
+			if dur >= threshold {
+				log.Warnf("slow request (%s): %s %s",
+					dur.Round(time.Millisecond), r.Method, r.URL.Path)
+			}
+		})
+	}
+}
+
 func readOptionalFile(path string) string {
 	if path == "" {
 		return ""