diff --git a/.agents/skills/tidb-test-guidelines/references/server-case-map.md b/.agents/skills/tidb-test-guidelines/references/server-case-map.md index 1e25fce64a5aa..1c7dbca835215 100644 --- a/.agents/skills/tidb-test-guidelines/references/server-case-map.md +++ b/.agents/skills/tidb-test-guidelines/references/server-case-map.md @@ -38,8 +38,8 @@ ### Tests - `pkg/server/handler/tests/dxf_test.go` - server/handler: Tests DXF API. -- `pkg/server/handler/tests/http_handler_serial_test.go` - server/handler: Tests post settings. -- `pkg/server/handler/tests/http_handler_test.go` - server/handler: Tests region index range. +- `pkg/server/handler/tests/http_handler_serial_test.go` - server/handler: Tests serial HTTP handlers, including pprof request logging. +- `pkg/server/handler/tests/http_handler_test.go` - server/handler: Tests HTTP handlers, including `/debug/zip` request logging. - `pkg/server/handler/tests/main_test.go` - Configures default goleak settings and registers testdata. ## pkg/server/handler/tikvhandler diff --git a/.agents/skills/tidb-test-guidelines/references/util-case-map.md b/.agents/skills/tidb-test-guidelines/references/util-case-map.md index 95410e5b6185f..dd6d6338bc561 100644 --- a/.agents/skills/tidb-test-guidelines/references/util-case-map.md +++ b/.agents/skills/tidb-test-guidelines/references/util-case-map.md @@ -397,7 +397,7 @@ ### Tests - `pkg/util/profile/flamegraph_test.go` - util/profile: Tests profile to datum. - `pkg/util/profile/main_test.go` - Configures default goleak settings and registers testdata. -- `pkg/util/profile/profile_test.go` - util/profile: Tests profiles. +- `pkg/util/profile/profile_test.go` - util/profile: Tests profile tables and profiling logs. ### Testdata - `pkg/util/profile/testdata/test.pprof` diff --git a/pkg/bindinfo/tests/BUILD.bazel b/pkg/bindinfo/tests/BUILD.bazel index 732e64505debd..a1a162f48d39b 100644 --- a/pkg/bindinfo/tests/BUILD.bazel +++ b/pkg/bindinfo/tests/BUILD.bazel @@ -11,7 +11,7 @@ go_test( ], flaky = True, race = "on", - shard_count = 25, + shard_count = 26, deps = [ "//pkg/bindinfo", "//pkg/domain", diff --git a/pkg/infoschema/perfschema/BUILD.bazel b/pkg/infoschema/perfschema/BUILD.bazel index 171a2f44b1585..d2383fa960799 100644 --- a/pkg/infoschema/perfschema/BUILD.bazel +++ b/pkg/infoschema/perfschema/BUILD.bazel @@ -27,11 +27,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 d032bdd20cae5..bbc55bb8eb7dd 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 ( @@ -237,19 +239,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 ebbcc53af66d7..39a8cf36f306d 100644 --- a/pkg/server/handler/tests/BUILD.bazel +++ b/pkg/server/handler/tests/BUILD.bazel @@ -78,5 +78,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 43d0f47704237..11ae57a9adf86 100644 --- a/pkg/server/handler/tests/http_handler_serial_test.go +++ b/pkg/server/handler/tests/http_handler_serial_test.go @@ -52,6 +52,7 @@ import ( "github.com/stretchr/testify/require" "github.com/tikv/pd/client/clients/gc" "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" ) func dummyRecord() *deadlockhistory.DeadlockRecord { @@ -444,6 +445,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/", @@ -462,12 +469,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 TestAutoIDOwnerRouteRegistration(t *testing.T) { diff --git a/pkg/server/handler/tests/http_handler_test.go b/pkg/server/handler/tests/http_handler_test.go index c83eb753b543a..a7b86f93c3c26 100644 --- a/pkg/server/handler/tests/http_handler_test.go +++ b/pkg/server/handler/tests/http_handler_test.go @@ -85,6 +85,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 { @@ -1245,6 +1246,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) @@ -1252,6 +1260,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 6b7b95f5fa947..4d1f7ac970de7 100644 --- a/pkg/server/http_status.go +++ b/pkg/server/http_status.go @@ -214,6 +214,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() @@ -343,12 +361,12 @@ func (s *Server) startHTTPServer() { router.PathPrefix(path).Handler(handler) } - 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)) router.HandleFunc("/debug/traceevent", traceeventHandler) router.HandleFunc("/covdata", func(writer http.ResponseWriter, _ *http.Request) { @@ -443,7 +461,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 @@ -525,7 +543,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) + } }