dump on timeout

Author: tangenta

pkg/testkit/testkit.go

@@ -19,6 +19,9 @@ package testkit
 import (
 	"context"
 	"fmt"
+	"log"
+	"os"
+	"runtime/pprof"
 	"strings"
 	"sync"
 	"testing"
@@ -684,3 +687,34 @@ func buildRowsRecordSet(ctx context.Context, rs sqlexec.RecordSet) sqlexec.Recor
 		idx:    0,
 	}
 }
+
+// DebugDumpOnTimeout will dump stack traces and possible blockers after given timeout.
+// wg is the WaitGroup to mark as done when finished (to avoid runaway goroutines)
+// c is the channel that will signal or close to cancel the timeout.
+func DebugDumpOnTimeout(wg *sync.WaitGroup, c chan struct{}, d time.Duration) {
+	select {
+	case <-time.After(d):
+		log.Print("Injected timeout, dumping all goroutines:")
+		_ = pprof.Lookup("goroutine").WriteTo(os.Stdout, 2)
+		log.Print("dumping all stack traces led to possible block:")
+		_ = pprof.Lookup("block").WriteTo(os.Stdout, 2)
+		log.Print("dumping all stack traces holding mutexes:")
+		_ = pprof.Lookup("mutex").WriteTo(os.Stdout, 2)
+		log.Print("dumping all stack traces led to creation of new OS threads:")
+		_ = pprof.Lookup("threadcreate").WriteTo(os.Stdout, 2)
+		log.Print("Waiting 2 seconds and to see if things changed...")
+		time.Sleep(2 * time.Second)
+		log.Print("Injected timeout, dumping all goroutines:")
+		_ = pprof.Lookup("goroutine").WriteTo(os.Stdout, 2)
+		log.Print("dumping all stack traces led to possible block:")
+		_ = pprof.Lookup("block").WriteTo(os.Stdout, 2)
+		log.Print("dumping all stack traces holding mutexes:")
+		_ = pprof.Lookup("mutex").WriteTo(os.Stdout, 2)
+		log.Print("dumping all stack traces led to creation of new OS threads:")
+		_ = pprof.Lookup("threadcreate").WriteTo(os.Stdout, 2)
+		panic("Injected timeout")
+	case <-c:
+		// Test finished
+	}
+	wg.Done()
+}

tests/realtikvtest/addindextest1/disttask_test.go

@@ -17,7 +17,9 @@ package addindextest
 import (
 	"context"
 	"fmt"
+	"sync"
 	"testing"
+	"time"
 
 	"github.com/pingcap/failpoint"
 	"github.com/pingcap/tidb/pkg/config"
@@ -46,6 +48,15 @@ func init() {
 }
 
 func TestAddIndexDistBasic(t *testing.T) {
+	var wg sync.WaitGroup
+	wg.Add(1)
+	dumpChan := make(chan struct{})
+	defer func() {
+		close(dumpChan)
+		wg.Wait()
+	}()
+	go testkit.DebugDumpOnTimeout(&wg, dumpChan, 7*time.Minute)
+
 	// mock that we only have 1 cpu, add-index task can be scheduled as usual
 	require.NoError(t, failpoint.Enable("github.com/pingcap/tidb/pkg/util/cpu/mockNumCpu", `return(1)`))
 	require.NoError(t, failpoint.Enable("github.com/pingcap/tidb/pkg/disttask/framework/storage/testSetLastTaskID", `return(true)`))