@@ -19,21 +19,27 @@ import (
1919 "fmt"
2020 "math"
2121 "os"
22+ "strings"
2223 "testing"
2324 "time"
2425
26+ "github.com/pingcap/failpoint"
27+ "github.com/pingcap/kvproto/pkg/coprocessor"
28+ "github.com/pingcap/kvproto/pkg/kvrpcpb"
2529 "github.com/pingcap/tidb/pkg/config"
2630 "github.com/pingcap/tidb/pkg/executor"
2731 "github.com/pingcap/tidb/pkg/meta/model"
2832 "github.com/pingcap/tidb/pkg/parser/ast"
2933 "github.com/pingcap/tidb/pkg/parser/auth"
3034 "github.com/pingcap/tidb/pkg/store/mockstore"
35+ "github.com/pingcap/tidb/pkg/store/mockstore/unistore"
3136 "github.com/pingcap/tidb/pkg/testkit"
3237 "github.com/pingcap/tidb/pkg/testkit/external"
3338 "github.com/pingcap/tidb/pkg/testkit/testdata"
3439 "github.com/pingcap/tidb/pkg/testkit/testutil"
3540 "github.com/pingcap/tidb/pkg/util/logutil"
3641 "github.com/stretchr/testify/require"
42+ "github.com/tikv/client-go/v2/tikvrpc"
3743)
3844
3945func TestSlowQueryWithoutSlowLog (t * testing.T ) {
@@ -553,6 +559,143 @@ func TestStorageEnginesInSlowQuery(t *testing.T) {
553559 checkStorageEngines (t , tk , "query like 'select%tablesample%;'" , "1 0" )
554560}
555561
562+ func TestReadPoolTaskDetailsInDiagnostics (t * testing.T ) {
563+ originCfg := config .GetGlobalConfig ()
564+ newCfg := * originCfg
565+ f , err := os .CreateTemp ("" , "tidb-slow-*.log" )
566+ require .NoError (t , err )
567+ newCfg .Log .SlowQueryFile = f .Name ()
568+ config .StoreGlobalConfig (& newCfg )
569+ t .Cleanup (func () {
570+ if t .Failed () {
571+ if data , err := os .ReadFile (f .Name ()); err == nil {
572+ t .Logf ("slow log contents (%d bytes):\n %s" , len (data ), data )
573+ }
574+ }
575+ config .StoreGlobalConfig (originCfg )
576+ require .NoError (t , f .Close ())
577+ require .NoError (t , os .Remove (f .Name ()))
578+ })
579+ require .NoError (t , logutil .InitLogger (newCfg .Log .ToLogConfig ()))
580+
581+ store := testkit .CreateMockStore (t )
582+ tk := testkit .NewTestKit (t , store )
583+ tk .MustExec ("use test" )
584+ tk .MustExec (fmt .Sprintf ("set @@tidb_slow_query_file='%v'" , f .Name ()))
585+ tk .MustExec ("set tidb_slow_log_threshold=0" )
586+ tk .MustExec ("set tidb_enable_paging=0" )
587+ t .Cleanup (func () {
588+ tk .MustExec ("set tidb_slow_log_threshold=300" )
589+ })
590+
591+ tk .MustExec ("create table t_read_pool_details (id int primary key, v int)" )
592+ tk .MustExec ("insert into t_read_pool_details values (1, 10), (2, 20), (3, 30)" )
593+
594+ responseHook := func (_ * tikvrpc.Request , resp * tikvrpc.Response ) {
595+ newExecDetails := func () * kvrpcpb.ExecDetailsV2 {
596+ return & kvrpcpb.ExecDetailsV2 {
597+ ReadPoolTaskDetails : & kvrpcpb.PoolTaskDetails {
598+ PollCount : 4 ,
599+ DispatchCount : 2 ,
600+ TotalWallNanos : uint64 ((20 * time .Millisecond ).Nanoseconds ()),
601+ TotalQueueWaitNanos : uint64 ((6 * time .Millisecond ).Nanoseconds ()),
602+ MaxQueueWaitNanos : uint64 ((4 * time .Millisecond ).Nanoseconds ()),
603+ MinQueueWaitNanos : uint64 ((2 * time .Millisecond ).Nanoseconds ()),
604+ TotalWakeWaitNanos : uint64 ((4 * time .Millisecond ).Nanoseconds ()),
605+ MaxWakeWaitNanos : uint64 ((4 * time .Millisecond ).Nanoseconds ()),
606+ MinWakeWaitNanos : uint64 ((4 * time .Millisecond ).Nanoseconds ()),
607+ FairQueueEnabled : true ,
608+ TotalFairQueueWaitedTaskSlices : 6 ,
609+ MaxFairQueueWaitedTaskSlices : 4 ,
610+ MinFairQueueWaitedTaskSlices : 2 ,
611+ PollCpuNanos : uint64 ((8 * time .Millisecond ).Nanoseconds ()),
612+ MaxPollCpuNanos : uint64 ((3 * time .Millisecond ).Nanoseconds ()),
613+ MinPollCpuNanos : uint64 ((1 * time .Millisecond ).Nanoseconds ()),
614+ PollWallNanos : uint64 ((12 * time .Millisecond ).Nanoseconds ()),
615+ MaxPollWallNanos : uint64 ((5 * time .Millisecond ).Nanoseconds ()),
616+ MinPollWallNanos : uint64 ((2 * time .Millisecond ).Nanoseconds ()),
617+ },
618+ }
619+ }
620+
621+ switch typedResp := resp .Resp .(type ) {
622+ case * kvrpcpb.GetResponse :
623+ typedResp .ExecDetailsV2 = newExecDetails ()
624+ case * kvrpcpb.BatchGetResponse :
625+ typedResp .ExecDetailsV2 = newExecDetails ()
626+ case * coprocessor.Response :
627+ typedResp .ExecDetailsV2 = newExecDetails ()
628+ }
629+ }
630+ unistore .UnistoreRPCClientResponseHook .Store (& responseHook )
631+ require .NoError (t , failpoint .Enable (
632+ "github.com/pingcap/tidb/pkg/store/mockstore/unistore/unistoreRPCClientResponseHook" ,
633+ "return(true)" ,
634+ ))
635+ t .Cleanup (func () {
636+ unistore .UnistoreRPCClientResponseHook .Store (nil )
637+ require .NoError (t , failpoint .Disable (
638+ "github.com/pingcap/tidb/pkg/store/mockstore/unistore/unistoreRPCClientResponseHook" ,
639+ ))
640+ })
641+
642+ const expectedDetails = "{tasks:1, poll_count:{total:4, avg:4, max:4, min:4}, " +
643+ "dispatch_count:{total:2, max:2, min:2}, " +
644+ "task_wall_time:{total:20ms, avg:20ms, max:20ms, min:20ms}, " +
645+ "queue_wait:{total:6ms, avg:3ms, max:4ms, min:2ms}, " +
646+ "wake_wait:{total:4ms, avg:4ms, max:4ms, min:4ms}, " +
647+ "fair_queue:{enabled:true, waited_task_slices:{total:6, avg:3, max:4, min:2}}, " +
648+ "poll_cpu:{total:8ms, avg:2ms, max:3ms, min:1ms}, " +
649+ "poll_wall:{total:12ms, avg:3ms, max:5ms, min:2ms}}"
650+ cases := []struct {
651+ name string
652+ plan string
653+ sql string
654+ }{
655+ {
656+ name : "point get" ,
657+ plan : "Point_Get" ,
658+ sql : "select /* read_pool_point_get */ * from t_read_pool_details where id = 1" ,
659+ },
660+ {
661+ name : "batch point get" ,
662+ plan : "Batch_Point_Get" ,
663+ sql : "select /* read_pool_batch_point_get */ * from t_read_pool_details where id in (1, 2)" ,
664+ },
665+ {
666+ name : "cop task" ,
667+ plan : "TableReader" ,
668+ sql : "select /* read_pool_cop */ * from t_read_pool_details where v >= 10" ,
669+ },
670+ }
671+
672+ for _ , testCase := range cases {
673+ t .Run (testCase .name , func (t * testing.T ) {
674+ tk .MustHavePlan (testCase .sql , testCase .plan )
675+ tk .MustQuery (testCase .sql )
676+ tk .EventuallyMustQueryAndCheck (
677+ "select read_pool_task_details from information_schema.slow_query " +
678+ "where query = '" + testCase .sql + ";' " +
679+ "order by time desc limit 1" ,
680+ nil ,
681+ testkit .Rows (expectedDetails ),
682+ 2 * time .Second ,
683+ 50 * time .Millisecond ,
684+ )
685+
686+ rows := tk .MustQuery ("explain analyze " + testCase .sql ).Rows ()
687+ foundDetails := false
688+ for _ , row := range rows {
689+ if strings .Contains (fmt .Sprint (row [5 ]), "read_pool:" + expectedDetails ) {
690+ foundDetails = true
691+ break
692+ }
693+ }
694+ require .True (t , foundDetails , "read-pool task details not found in EXPLAIN ANALYZE output: %v" , rows )
695+ })
696+ }
697+ }
698+
556699func TestSessionConnectAttrsInSlowQuery (t * testing.T ) {
557700 originCfg := config .GetGlobalConfig ()
558701 newCfg := * originCfg
0 commit comments