server: add logging for profiling requests (#69897)

pkg/infoschema/perfschema/BUILD.bazel

@@ -26,11 +26,13 @@ go_library(
         "//pkg/table/tables",
         "//pkg/types",
         "//pkg/util",
+        "//pkg/util/logutil",
         "//pkg/util/profile",
         "@com_github_ngaut_pools//:pools",
         "@com_github_pingcap_errors//:errors",
         "@com_github_pingcap_failpoint//:failpoint",
         "@com_github_tikv_pd_client//http",
+        "@org_uber_go_zap//:zap",
     ],
 )
 

pkg/infoschema/perfschema/tables.go

@@ -37,8 +37,10 @@ import (
 	"github.com/pingcap/tidb/pkg/table/tables"
 	"github.com/pingcap/tidb/pkg/types"
 	"github.com/pingcap/tidb/pkg/util"
+	"github.com/pingcap/tidb/pkg/util/logutil"
 	"github.com/pingcap/tidb/pkg/util/profile"
 	pd "github.com/tikv/pd/client/http"
+	"go.uber.org/zap"
 )
 
 const (
@@ -233,19 +235,40 @@ func initTableIndices(t *perfSchemaTable) error {
 	return nil
 }
 
+func logTiDBProfileRequest(sctx sessionctx.Context, tableName string) {
+	vars := sctx.GetSessionVars()
+	fields := []zap.Field{
+		zap.String("table", "performance_schema."+tableName),
+		zap.Uint64("conn", vars.ConnectionID),
+	}
+	if vars.User != nil {
+		fields = append(fields, zap.String("user", vars.User.LoginString()))
+	}
+	if vars.ConnectionInfo != nil {
+		fields = append(fields, zap.String("client-ip", vars.ConnectionInfo.ClientIP))
+	}
+	logutil.BgLogger().Info("profiling request received", fields...)
+}
+
 func (vt *perfSchemaTable) getRows(ctx context.Context, sctx sessionctx.Context, cols []*table.Column) (fullRows [][]types.Datum, err error) {
 	switch vt.meta.Name.O {
 	case tableNameTiDBProfileCPU:
+		logTiDBProfileRequest(sctx, tableNameTiDBProfileCPU)
 		fullRows, err = (&profile.Collector{}).ProfileGraph("cpu")
 	case tableNameTiDBProfileMemory:
+		logTiDBProfileRequest(sctx, tableNameTiDBProfileMemory)
 		fullRows, err = (&profile.Collector{}).ProfileGraph("heap")
 	case tableNameTiDBProfileMutex:
+		logTiDBProfileRequest(sctx, tableNameTiDBProfileMutex)
 		fullRows, err = (&profile.Collector{}).ProfileGraph("mutex")
 	case tableNameTiDBProfileAllocs:
+		logTiDBProfileRequest(sctx, tableNameTiDBProfileAllocs)
 		fullRows, err = (&profile.Collector{}).ProfileGraph("allocs")
 	case tableNameTiDBProfileBlock:
+		logTiDBProfileRequest(sctx, tableNameTiDBProfileBlock)
 		fullRows, err = (&profile.Collector{}).ProfileGraph("block")
 	case tableNameTiDBProfileGoroutines:
+		logTiDBProfileRequest(sctx, tableNameTiDBProfileGoroutines)
 		fullRows, err = (&profile.Collector{}).ProfileGraph("goroutine")
 	case tableNameTiKVProfileCPU:
 		interval := fmt.Sprintf("%d", profile.CPUProfileInterval/time.Second)

pkg/server/handler/tests/BUILD.bazel

@@ -59,5 +59,6 @@ go_test(
         "@io_etcd_go_etcd_tests_v3//integration",
         "@org_uber_go_goleak//:goleak",
         "@org_uber_go_zap//:zap",
+        "@org_uber_go_zap//zaptest/observer",
     ],
 )

pkg/server/handler/tests/http_handler_serial_test.go

@@ -48,6 +48,7 @@ import (
 	"github.com/pingcap/tidb/pkg/util/versioninfo"
 	"github.com/stretchr/testify/require"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest/observer"
 )
 
 func dummyRecord() *deadlockhistory.DeadlockRecord {
@@ -445,6 +446,12 @@ func TestDebugRoutes(t *testing.T) {
 	ts := createBasicHTTPHandlerTestSuite()
 	ts.startServer(t)
 	defer ts.stopServer(t)
+	core, recorded := observer.New(zap.InfoLevel)
+	restore := log.ReplaceGlobals(zap.New(core), &log.ZapProperties{
+		Core:  core,
+		Level: zap.NewAtomicLevelAt(zap.InfoLevel),
+	})
+	defer restore()
 
 	debugRoutes := []string{
 		"/debug/pprof/",
@@ -463,12 +470,29 @@ func TestDebugRoutes(t *testing.T) {
 		// "/debug/zip", // this creates unexpected goroutines which will make goleak complain, so we skip it for now
 		"/debug/ballast-object-sz",
 	}
+	expectedProfilingLogs := 0
 	for _, route := range debugRoutes {
+		if strings.HasPrefix(route, "/debug/pprof/") {
+			expectedProfilingLogs++
+		}
 		resp, err := ts.FetchStatus(route)
 		require.NoError(t, err, fmt.Sprintf("GET route %s failed", route))
 		require.Equal(t, http.StatusOK, resp.StatusCode, fmt.Sprintf("GET route %s failed", route))
 		require.NoError(t, resp.Body.Close())
 	}
+
+	profilingLogs := recorded.FilterMessage("profiling request received")
+	require.Len(t, profilingLogs.All(), expectedProfilingLogs)
+	require.Len(t, profilingLogs.FilterField(zap.String("path", "/debug/pprof/goroutine")).
+		FilterField(zap.String("debug", "2")).All(), 1)
+	require.Len(t, profilingLogs.FilterField(zap.String("path", "/debug/pprof/profile")).
+		FilterField(zap.String("seconds", "5")).All(), 1)
+	for _, entry := range profilingLogs.All() {
+		fields := entry.ContextMap()
+		require.Equal(t, http.MethodGet, fields["method"])
+		require.NotEmpty(t, fields["path"])
+		require.NotEmpty(t, fields["remote-addr"])
+	}
 }
 
 func TestFailpointHandler(t *testing.T) {

pkg/server/handler/tests/http_handler_test.go

@@ -75,6 +75,7 @@ import (
 	"github.com/tikv/client-go/v2/tikv"
 	"go.etcd.io/etcd/tests/v3/integration"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest/observer"
 )
 
 type basicHTTPHandlerTestSuite struct {
@@ -1083,13 +1084,28 @@ func TestDebugZip(t *testing.T) {
 	ts := createBasicHTTPHandlerTestSuite()
 	ts.startServer(t)
 	defer ts.stopServer(t)
+	core, recorded := observer.New(zap.InfoLevel)
+	restore := log.ReplaceGlobals(zap.New(core), &log.ZapProperties{
+		Core:  core,
+		Level: zap.NewAtomicLevelAt(zap.InfoLevel),
+	})
+	defer restore()
+
 	resp, err := ts.FetchStatus("/debug/zip?seconds=1")
 	require.NoError(t, err)
 	require.Equal(t, http.StatusOK, resp.StatusCode)
 	b, err := httputil.DumpResponse(resp, true)
 	require.NoError(t, err)
 	require.Greater(t, len(b), 0)
 	require.NoError(t, resp.Body.Close())
+
+	profilingLogs := recorded.FilterMessage("profiling request received").
+		FilterField(zap.String("path", "/debug/zip")).
+		FilterField(zap.String("seconds", "1"))
+	require.Len(t, profilingLogs.All(), 1)
+	fields := profilingLogs.All()[0].ContextMap()
+	require.Equal(t, http.MethodGet, fields["method"])
+	require.NotEmpty(t, fields["remote-addr"])
 }
 
 func TestCheckCN(t *testing.T) {

pkg/server/http_status.go

@@ -207,6 +207,24 @@ func (b *Ballast) GenHTTPHandler() func(w http.ResponseWriter, r *http.Request)
 	}
 }
 
+func withProfilingRequestLog(next http.HandlerFunc) http.HandlerFunc {
+	return func(w http.ResponseWriter, r *http.Request) {
+		fields := []zap.Field{
+			zap.String("method", r.Method),
+			zap.String("path", r.URL.Path),
+			zap.String("remote-addr", r.RemoteAddr),
+		}
+		query := r.URL.Query()
+		for _, key := range []string{"seconds", "debug", "gc"} {
+			if value := query.Get(key); value != "" {
+				fields = append(fields, zap.String(key, value))
+			}
+		}
+		logutil.BgLogger().Info("profiling request received", fields...)
+		next(w, r)
+	}
+}
+
 func (s *Server) startHTTPServer() {
 	router := mux.NewRouter()
 
@@ -308,12 +326,12 @@ func (s *Server) startHTTPServer() {
 		router.PathPrefix("/static/").Handler(http.StripPrefix("/static", http.FileServer(static.Data)))
 	}
 
-	router.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
-	router.HandleFunc("/debug/pprof/profile", cpuprofile.ProfileHTTPHandler)
-	router.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
-	router.HandleFunc("/debug/pprof/trace", pprof.Trace)
+	router.HandleFunc("/debug/pprof/cmdline", withProfilingRequestLog(pprof.Cmdline))
+	router.HandleFunc("/debug/pprof/profile", withProfilingRequestLog(cpuprofile.ProfileHTTPHandler))
+	router.HandleFunc("/debug/pprof/symbol", withProfilingRequestLog(pprof.Symbol))
+	router.HandleFunc("/debug/pprof/trace", withProfilingRequestLog(pprof.Trace))
 	// Other /debug/pprof paths not covered above are redirected to pprof.Index.
-	router.PathPrefix("/debug/pprof/").HandlerFunc(pprof.Index)
+	router.PathPrefix("/debug/pprof/").HandlerFunc(withProfilingRequestLog(pprof.Index))
 
 	ballast := newBallast(s.cfg.MaxBallastObjectSize)
 	{
@@ -349,7 +367,7 @@ func (s *Server) startHTTPServer() {
 		}
 	})
 
-	router.HandleFunc("/debug/zip", func(w http.ResponseWriter, r *http.Request) {
+	router.HandleFunc("/debug/zip", withProfilingRequestLog(func(w http.ResponseWriter, r *http.Request) {
 		w.Header().Set("Content-Disposition", `attachment; filename="tidb_debug"`+time.Now().Format("20060102150405")+".zip")
 
 		// dump goroutine/heap/mutex
@@ -431,7 +449,7 @@ func (s *Server) startHTTPServer() {
 
 		err = zw.Close()
 		terror.Log(err)
-	})
+	}))
 
 	// failpoint is enabled only for tests so we can add some http APIs here for tests.
 	failpoint.Inject("enableTestAPI", func() {

pkg/util/profile/BUILD.bazel

@@ -37,9 +37,13 @@ go_test(
         "//pkg/testkit/testsetup",
         "//pkg/types",
         "//pkg/util/collate",
+        "//pkg/util/cpuprofile",
+        "@com_github_pingcap_log//:log",
         "@com_github_stretchr_testify//assert",
         "@com_github_stretchr_testify//require",
         "@io_opencensus_go//stats/view",
         "@org_uber_go_goleak//:goleak",
+        "@org_uber_go_zap//:zap",
+        "@org_uber_go_zap//zaptest/observer",
     ],
 )

pkg/util/profile/profile_test.go

@@ -18,14 +18,18 @@ import (
 	"testing"
 	"time"
 
+	"github.com/pingcap/log"
 	"github.com/pingcap/tidb/pkg/domain"
 	"github.com/pingcap/tidb/pkg/kv"
 	"github.com/pingcap/tidb/pkg/session"
 	"github.com/pingcap/tidb/pkg/store/mockstore"
 	"github.com/pingcap/tidb/pkg/testkit"
+	"github.com/pingcap/tidb/pkg/util/cpuprofile"
 	"github.com/pingcap/tidb/pkg/util/profile"
 	"github.com/stretchr/testify/require"
 	"go.opencensus.io/stats/view"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest/observer"
 )
 
 func TestProfiles(t *testing.T) {
@@ -51,12 +55,28 @@ func TestProfiles(t *testing.T) {
 	defer func() {
 		profile.CPUProfileInterval = oldValue
 	}()
+	require.NoError(t, cpuprofile.StartCPUProfiler())
+	defer cpuprofile.StopCPUProfiler()
 
 	tk := testkit.NewTestKit(t, store)
-	tk.MustExec("select * from performance_schema.tidb_profile_cpu")
-	tk.MustExec("select * from performance_schema.tidb_profile_memory")
-	tk.MustExec("select * from performance_schema.tidb_profile_allocs")
-	tk.MustExec("select * from performance_schema.tidb_profile_mutex")
-	tk.MustExec("select * from performance_schema.tidb_profile_block")
-	tk.MustExec("select * from performance_schema.tidb_profile_goroutines")
+	core, recorded := observer.New(zap.InfoLevel)
+	restore := log.ReplaceGlobals(zap.New(core), &log.ZapProperties{
+		Core:  core,
+		Level: zap.NewAtomicLevelAt(zap.InfoLevel),
+	})
+	defer restore()
+
+	profileTables := []string{
+		"tidb_profile_cpu",
+		"tidb_profile_memory",
+		"tidb_profile_allocs",
+		"tidb_profile_mutex",
+		"tidb_profile_block",
+		"tidb_profile_goroutines",
+	}
+	for _, tableName := range profileTables {
+		tk.MustQuery("select * from performance_schema." + tableName)
+		require.Len(t, recorded.FilterMessage("profiling request received").
+			FilterField(zap.String("table", "performance_schema."+tableName)).All(), 1)
+	}
 }