diff --git a/pkg/infoschema/perfschema/BUILD.bazel b/pkg/infoschema/perfschema/BUILD.bazel index 70f51f697ace1..09f7060dce8d8 100644 --- a/pkg/infoschema/perfschema/BUILD.bazel +++ b/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", ], ) diff --git a/pkg/infoschema/perfschema/tables.go b/pkg/infoschema/perfschema/tables.go index fe78207b658d6..7b2139d28c89a 100644 --- a/pkg/infoschema/perfschema/tables.go +++ b/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) diff --git a/pkg/server/handler/tests/BUILD.bazel b/pkg/server/handler/tests/BUILD.bazel index a1ccf363c4409..db53fe9f5f6a3 100644 --- a/pkg/server/handler/tests/BUILD.bazel +++ b/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", ], ) diff --git a/pkg/server/handler/tests/http_handler_serial_test.go b/pkg/server/handler/tests/http_handler_serial_test.go index 5bddbd81c1600..3d71d89905a29 100644 --- a/pkg/server/handler/tests/http_handler_serial_test.go +++ b/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) { diff --git a/pkg/server/handler/tests/http_handler_test.go b/pkg/server/handler/tests/http_handler_test.go index 550d01d5e1e62..12b9c22f967be 100644 --- a/pkg/server/handler/tests/http_handler_test.go +++ b/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,6 +1084,13 @@ 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) @@ -1090,6 +1098,14 @@ func TestDebugZip(t *testing.T) { 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) { diff --git a/pkg/server/http_status.go b/pkg/server/http_status.go index 35c8eaf0a7422..ab71333ce7d69 100644 --- a/pkg/server/http_status.go +++ b/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() { diff --git a/pkg/util/profile/BUILD.bazel b/pkg/util/profile/BUILD.bazel index 6c1c440989851..37ec7a716a1f3 100644 --- a/pkg/util/profile/BUILD.bazel +++ b/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", ], ) diff --git a/pkg/util/profile/profile_test.go b/pkg/util/profile/profile_test.go index 6d8550f33e658..fce92f3ac6720 100644 --- a/pkg/util/profile/profile_test.go +++ b/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) + } }