@tiancaiamao I can't explain why TestSecurityEnhancedModeInfoschema was 82s for you. For me it's a quick test:
PASS: privileges_test.go:1446: testPrivilegeSuite.TestSecurityEnhancedModeInfoschema	0.017s
The test itself is also quite straight forward (no loops or anything complicated). The only thing I can think of is if reading from one of the tables such as CLUSTER_STATEMENTS_SUMMARY blocks while waiting for the resource to be ready.

@morgo Maybe I should assign this issue to @crazycs520

It turned out this is caused by the CLUSTER_STATEMENTS_SUMMARY table.
I follow the log and it looks like that:

[2021/07/27 10:28:58.956 +08:00] [WARN] [backoff.go:149] ["tikvRPC backoffer.maxSleep 40000ms is exceeded, errors:\nsend tikv request error: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp :10080: connect: connection refused\", ctx: region ID: 0, meta: <nil>, peer: <nil>, addr: :10080, idx: 0, reqStoreType: TiKvOnly, runStoreType: , try next peer later at 2021-07-27T10:28:56.141763315+08:00\nsend tikv request error: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp :10080: connect: connection refused\", ctx: region ID: 0, meta: <nil>, peer: <nil>, addr: :10080, idx: 0, reqStoreType: TiKvOnly, runStoreType: , try next peer later at 2021-07-27T10:28:57.216129782+08:00\nsend tikv request error: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp :10080: connect: connection refused\", ctx: region ID: 0, meta: <nil>, peer: <nil>, addr: :10080, idx: 0, reqStoreType: TiKvOnly, runStoreType: , try next peer later at 2021-07-27T10:28:58.956654122+08:00"]
[2021/07/27 10:28:58.956 +08:00] [WARN] [adapter.go:1022] ["# Txn_start_ts: 426600798200266752\n# User@Host: uroot1[uroot1] @ localhost [localhost]\n# Conn_ID: 1\n# Query_time: 40.548874325\n# Parse_time: 0.00003658\n# Compile_time: 0.000367923\n# Rewrite_time: 0.000246732\n# Optimize_time: 0.000078051\n# Wait_TS: 0.00000516\n# Cop_time: 40.548146679 Request_count: 1\n# Is_internal: false\n# Digest: 4875c8b3072035d3c5db0387429aa67e4ee8845c254349eb03fcf4ff62440a7a\n# Stats: CLUSTER_STATEMENTS_SUMMARY:pseudo\n# Num_cop_tasks: 1\n# Cop_proc_avg: 0 Cop_proc_addr: \n# Cop_wait_avg: 0 Cop_wait_addr: \n# Mem_max: 10641\n# Prepared: false\n# Plan_from_cache: false\n# Plan_from_binding: false\n# Has_more_results: false\n# KV_total: 0\n# PD_total: 0\n# Backoff_total: 0\n# Write_sql_response_total: 0\n# Succ: true\n# Plan: tidb_decode_plan('mQXwUjAJNl82CTAJMQlmdW5jczpjb3VudCgxKS0+Q29sdW1uIzkxCTEJdGltZTo0MC41cywgbG9vcHM6MiwgcGFydGlhbF93b3JrZXI6e3dhbGxfdGltCSrwSTQ4MjEyOTlzLCBjb25jdXJyZW5jeTo1LCB0YXNrX251bTowLCB0b3Rfd2FpdDozbTIyLjc0MDkwODYxcywgdG90X2V4ZWM6MHMsBQ0FWAAzESYoMTA4OHMsIG1heDoBljA0ODE4MzI2cywgcDk1MhIAGH0sIGZpbmFqpQAIODU0AUuqpQAQMTAxNjEBNAG+KGV4ZWM6Ny43McK1DbcuqgAQMTAyNjMhBBmqEDIxMTEzMqoACRLAfQkxMC4yIEtCCU4vQQoxCTMxXzEwCTAJODAwMAlkYXRhOlNlbGVjdGlvbl85CTAJdEKTASwxCTE2MSBCeXRlcwkBRCAyCTFfOQkxXzIJREBuZShsZW5ndGgoaW5mb3JtYQVLyHNjaGVtYS5jbHVzdGVyX3N0YXRlbWVudHNfc3VtbWFyeS5pbnN0YW5jZSksIDM2KQkwCQFdAQQYCjMJNDNfOAVi8FExMDAwMAl0YWJsZTpDTFVTVEVSX1NUQVRFTUVOVFNfU1VNTUFSWSwga2VlcCBvcmRlcjpmYWxzZSwgc3RhdHM6cHNldWRvCTAJCU4vQQlOL0EK')\n# Plan_digest: 0f93707ee58047f8de2034bb18a2fcac3bf7f99cea69a9da77bbeb94af568fb6\nSELECT COUNT(*) FROM information_schema.CLUSTER_STATEMENTS_SUMMARY WHERE length(instance) != 36;"]

If you have a TiDB listening on :10080, this test can finish soon.
Otherwise, query the CLUSTER_STATEMENTS_SUMMARY table will send distsql request to :10080 and fail, before that, it backoff 40s ... There are two such SQL statements, so this test takes 80s.

runtime/debug.Stack(0x0, 0x11, 0xc0052bf320)
	/snap/go/7954/src/runtime/debug/stack.go:24 +0x9f
runtime/debug.PrintStack()
	/snap/go/7954/src/runtime/debug/stack.go:16 +0x25
github.com/pingcap/tidb/executor.(*executorBuilder).buildMemTable(0xc005fc89a0, 0xc005f91c20, 0xc005b1ec60, 0x10ab425)
	/home/genius/project/src/github.com/pingcap/tidb/executor/builder.go:1602 +0x1d85
github.com/pingcap/tidb/executor.(*executorBuilder).build(0xc005fc89a0, 0x3b7ad78, 0xc005f91c20, 0x3b7ad78, 0xc005f91c20)
	/home/genius/project/src/github.com/pingcap/tidb/executor/builder.go:222 +0x6c5
github.com/pingcap/tidb/executor.(*executorBuilder).buildSelection(0xc005fc89a0, 0xc005fca0a0, 0xc005b1edf0, 0x10ab425)
	/home/genius/project/src/github.com/pingcap/tidb/executor/builder.go:1375 +0x91
github.com/pingcap/tidb/executor.(*executorBuilder).build(0xc005fc89a0, 0x3b7aec8, 0xc005fca0a0, 0x3b7aec8, 0xc005fca0a0)
	/home/genius/project/src/github.com/pingcap/tidb/executor/builder.go:214 +0x1045
github.com/pingcap/tidb/executor.(*executorBuilder).buildHashAgg(0xc005fc89a0, 0xc0052ad500, 0xc005b1f040, 0x10addf8)
	/home/genius/project/src/github.com/pingcap/tidb/executor/builder.go:1267 +0x91
github.com/pingcap/tidb/executor.(*executorBuilder).build(0xc005fc89a0, 0x3b7a838, 0xc0052ad500, 0xc0052ad500, 0x0)
	/home/genius/project/src/github.com/pingcap/tidb/executor/builder.go:216 +0x1545
github.com/pingcap/tidb/executor.(*ExecStmt).buildExecutor(0xc005f86820, 0xc0053adc00, 0x32d3240, 0x54eff50, 0x31fb5a0)
	/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:800 +0x1c5
github.com/pingcap/tidb/executor.(*ExecStmt).Exec(0xc005f86820, 0x3b50798, 0xc005fb7200, 0x0, 0x0, 0x0, 0x0)
	/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:381 +0x1f7
github.com/pingcap/tidb/session.runStmt(0x3b50728, 0xc000122010, 0xc004c64c00, 0x3b66340, 0xc005f86820, 0x0, 0x0, 0x0, 0x0)
	/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1755 +0x37f
github.com/pingcap/tidb/session.(*session).ExecuteStmt(0xc004c64c00, 0x3b50728, 0xc000122010, 0x3b6aad8, 0xc005be6f00, 0x0, 0x0, 0x0, 0x0)
	/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1650 +0xab1
github.com/pingcap/tidb/util/testkit.(*TestKit).Exec(0xc005b1fb50, 0x374e734, 0x4a, 0x0, 0x0, 0x0, 0x0, 0xc005941a0a, 0x6, 0xc005941902)
	/home/genius/project/src/github.com/pingcap/tidb/util/testkit/testkit.go:170 +0x21c
github.com/pingcap/tidb/util/testkit.(*TestKit).MustQuery(0xc005b1fb50, 0x374e734, 0x4a, 0x0, 0x0, 0x0, 0x0)
	/home/genius/project/src/github.com/pingcap/tidb/util/testkit/testkit.go:324 +0x193
github.com/pingcap/tidb/privilege/privileges_test.(*testPrivilegeSuite).TestSecurityEnhancedModeInfoschema(0xc0002a80d0, 0xc00510a1e0)
	/home/genius/project/src/github.com/pingcap/tidb/privilege/privileges/privileges_test.go:1474 +0x53e
reflect.Value.call(0x36697a0, 0xc0002a80d0, 0x8613, 0x369449a, 0x4, 0xc000ce1ef0, 0x1, 0x1, 0x54f4520, 0xc000095e28, ...)
	/snap/go/7954/src/reflect/value.go:476 +0x8e7
reflect.Value.Call(0x36697a0, 0xc0002a80d0, 0x8613, 0xc000095ef0, 0x1, 0x1, 0xc00510a2d0, 0xc00491ecc0, 0x1)
	/snap/go/7954/src/reflect/value.go:337 +0xb9
github.com/pingcap/check.(*suiteRunner).forkTest.func1(0xc00510a1e0)
	/home/genius/go/pkg/mod/github.com/pingcap/check@v0.0.0-20200212061837-5e12011dc712/check.go:850 +0x6b5
github.com/pingcap/check.(*suiteRunner).forkCall.func1(0xc0002b7680, 0xc00510a1e0, 0xc00501bf60)
	/home/genius/go/pkg/mod/github.com/pingcap/check@v0.0.0-20200212061837-5e12011dc712/check.go:739 +0xbf
created by github.com/pingcap/check.(*suiteRunner).forkCall
	/home/genius/go/pkg/mod/github.com/pingcap/check@v0.0.0-20200212061837-5e12011dc712/check.go:734 +0x233
goroutine 479 [running]:

PASS: privileges_test.go:1446: testPrivilegeSuite.TestSecurityEnhancedModeInfoschema 82.565s @morgo #26587

Description

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions