pingcap / tidb

TiDB is an open-source, cloud-native, distributed, MySQL-Compatible database for elastic scale and real-time analytics. Try AI-powered Chat2Query free at : https://www.pingcap.com/tidb-serverless/
https://pingcap.com
Apache License 2.0
36.54k stars 5.75k forks source link

flaky test and data race in the TestOptimisticTxnRetryInPessimisticMode #40823

Open hawkingrei opened 1 year ago

hawkingrei commented 1 year ago

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

     stepped.go:140: 
            Error Trace:    /home/jenkins/.tidb/tmp/04446c229c5a73c16deb3edddcb4db34/sandbox/processwrapper-sandbox/5107/execroot/__main__/bazel-out/k8-fastbuild/bin/sessiontxn/sessiontxn_test_/sessiontxn_test.runfiles/__main__/sessiontxn/stepped.go:140
                                        /home/jenkins/.tidb/tmp/04446c229c5a73c16deb3edddcb4db34/sandbox/processwrapper-sandbox/5107/execroot/__main__/bazel-out/k8-fastbuild/bin/sessiontxn/sessiontxn_test_/sessiontxn_test.runfiles/__main__/sessiontxn/stepped.go:203
                                        /home/jenkins/.tidb/tmp/04446c229c5a73c16deb3edddcb4db34/sandbox/processwrapper-sandbox/5107/execroot/__main__/bazel-out/k8-fastbuild/bin/sessiontxn/sessiontxn_test_/sessiontxn_test.runfiles/__main__/sessiontxn/stepped.go:217
                                        /home/jenkins/.tidb/tmp/04446c229c5a73c16deb3edddcb4db34/sandbox/processwrapper-sandbox/5107/execroot/__main__/bazel-out/k8-fastbuild/bin/sessiontxn/sessiontxn_test_/sessiontxn_test.runfiles/__main__/sessiontxn/txn_context_test.go:835
                                        /home/jenkins/.tidb/tmp/04446c229c5a73c16deb3edddcb4db34/sandbox/processwrapper-sandbox/5107/execroot/__main__/bazel-out/k8-fastbuild/bin/sessiontxn/sessiontxn_test_/sessiontxn_test.runfiles/__main__/sessiontxn/fork.go:110
            Error:          Received unexpected error:
                            send msg timeout
                            github.com/pingcap/tidb/testkit.steppedTestKitMsgChan.recvMsg
                                testkit/stepped.go:65
                            github.com/pingcap/tidb/testkit.(*SteppedTestKit).handleCommandMsg
                                testkit/stepped.go:139
                            github.com/pingcap/tidb/testkit.(*SteppedTestKit).steppedCommand
                                testkit/stepped.go:203
                            github.com/pingcap/tidb/testkit.(*SteppedTestKit).SteppedMustExec
                                testkit/stepped.go:217
                            sessiontxn/sessiontxn_test_test.TestOptimisticTxnRetryInPessimisticMode.func1
                                sessiontxn/txn_context_test.go:835
                            github.com/pingcap/tidb/testkit/testfork.RunTest.func1.1
                                testkit/testfork/fork.go:110
                            testing.tRunner
                                GOROOT/src/testing/testing.go:1446
                            runtime.goexit
                                src/runtime/asm_amd64.s:1594
            Test:           TestOptimisticTxnRetryInPessimisticMode/#02
[2023/01/29 15:51:47.121 +08:00] [INFO] [coprocessor.go:1205] ["[TIME_COP_PROCESS] resp_time:38.456281248s txnStartTS:439085606952763392 region_id:2 store_addr:store1 kv_process_ms:38455 kv_wait_ms:0 kv_read_ms:0"]
[2023/01/29 15:52:07.204 +08:00] [INFO] [coprocessor.go:1205] ["[TIME_COP_WAIT] resp_time:51.635934012s txnStartTS:439085609928097792 region_id:2 store_addr:store1 kv_process_ms:0 kv_wait_ms:0 kv_read_ms:0"]
[2023/01/29 15:52:07.216 +08:00] [WARN] [adapter.go:1621] ["# Txn_start_ts: 439085609928097792\n# Query_time: 54.568269609\n# Parse_time: 0\n# Compile_time: 2.931214495\n# Rewrite_time: 0.000172564\n# Optimize_time: 2.930534933\n# Wait_TS: 0.000055985\n# Cop_time: 51.636181293 Request_count: 1\n# Is_internal: true\n# Digest: 9d5a0f1a8c1c0e1fd5f0955da80b305eae920a2ab897319c6d2d8de5d890bedc\n# Stats: tidb_mdl_info:pseudo\n# Num_cop_tasks: 1\n# Cop_proc_avg: 0 Cop_proc_addr: store1\n# Cop_wait_avg: 0 Cop_wait_addr: store1\n# Mem_max: 171\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.000005692\n# Backoff_total: 0\n# Write_sql_response_total: 0\n# Result_rows: 0\n# Succ: true\n# IsExplicitTxn: false\n# IsSyncStatsFailed: false\n# Plan: tidb_decode_plan('mwPwUjAJMzFfNwkwCTMzMjMuMzMJZGF0YTpTZWxlY3Rpb25fNgkwCXRpbWU6NTEuNnMsIGxvb3BzOjEsIGNvcF90YXNrOiB7bnVtOiAxLCBtYXg6IDUxBShEcHJvY19rZXlzOiAwLCBycGNfESYBDAB0AVIRK/BMY29wcl9jYWNoZV9oaXRfcmF0aW86IDAuMDAsIGRpc3RzcWxfY29uY3VycmVuY3k6IDE1fQkxNzEgQnl0ZXMJTi9BCjEJMV82CTFfMAkRx6hsZShteXNxbC50aWRiX21kbF9pbmZvLnZlcnNpb24sIDQ2KQkwCXRpa3ZfBcYEe3QBkxg4NzkuNsK1FegUMH0JTi9BAQRcCjIJNDNfNQkxXzAJMTAwMDAJdGFibGU6Ml8AfCwga2VlcCBvcmRlcjpmYWxzZSwgc3RhdHM6cHNldWRvtnIA')\n# Plan_digest: c68b37cb6ba3074a6ee32e9b33a56d8b18aea208db31fb6e13471a1db7195d65\n# Binary_plan: tidb_decode_binary_plan('ggSYCv0DCg1UYWJsZVJlYWRlcl83EqACCgtTZWxlY3Rpb25fNhKbAQoPBSJMRnVsbFNjYW5fNSEAAAAAIGUhQSkBCfBxAIjDQDgCQAJKGAoWCgVteXNxbBINdGlkYl9tZGxfaW5mb1Iea2VlcCBvcmRlcjpmYWxzZSwgc3RhdHM6cHNldWRvaiJ0aWt2X3Rhc2s6e3RpbWU6ODc5LjbCtXMsIGxvb3BzOjB9cP///////////wF4CQgM////AQWKLIBPIkEpq6qqqqr2qQWKEFIjbGUoBYkALjKIADgudmVyc2lvbiwgNDYpaiLidQABbAzqc+ZAGXUkAUABUhBkYXRhOj07CFoTdAHMEDUxLjZzEckcMWJ+Y29wX3QB6zgge251bTogMSwgbWF4OiANKERwcm9jX2tleXM6IDAsIHJwY18RJgEMBVIRK/BDY29wcl9jYWNoZV9oaXRfcmF0aW86IDAuMDAsIGRpc3RzcWxfY29uY3VycmVuY3k6IDE1fXCrAXj///////////8BGAE=')\nselect job_id, version, table_ids from mysql.tidb_mdl_info where version <= 46;"]
==================
WARNING: DATA RACE
Write at 0x00c00bf3f580 by goroutine 216448:
  github.com/pingcap/tidb/sessionctx/variable.(*SessionVars).SetAlloc()
      sessionctx/variable/session.go:1400 +0x324
  github.com/pingcap/tidb/testkit.(*TestKit).ExecWithContext()
      testkit/testkit.go:313 +0x25e
  github.com/pingcap/tidb/testkit.(*TestKit).MustExecWithContext()
      testkit/testkit.go:130 +0xb7
  github.com/pingcap/tidb/testkit.(*TestKit).MustExec()
      testkit/testkit.go:125 +0xf7
  github.com/pingcap/tidb/testkit.(*SteppedTestKit).MustExec()
      testkit/stepped.go:233 +0x148
  sessiontxn/sessiontxn_test_test.TestOptimisticTxnRetryInPessimisticMode.func1.1()
      sessiontxn/txn_context_test.go:810 +0x4c
  runtime.deferCallSave()
      GOROOT/src/runtime/panic.go:796 +0x87
  github.com/pingcap/tidb/testkit/testfork.(*T).FailNow()
      <autogenerated>:1 +0x46
  github.com/stretchr/testify/require.NoError()
      external/com_github_stretchr_testify/require/require.go:1264 +0xc7
  github.com/pingcap/tidb/testkit.(*SteppedTestKit).handleCommandMsg()
      testkit/stepped.go:140 +0xc9
  github.com/pingcap/tidb/testkit.(*SteppedTestKit).steppedCommand()
      testkit/stepped.go:203 +0x1d1
  github.com/pingcap/tidb/testkit.(*SteppedTestKit).SteppedMustExec()
      testkit/stepped.go:217 +0x144
  sessiontxn/sessiontxn_test_test.TestOptimisticTxnRetryInPessimisticMode.func1()
      sessiontxn/txn_context_test.go:835 +0x5af
  github.com/pingcap/tidb/testkit/testfork.RunTest.func1.1()
      testkit/testfork/fork.go:110 +0xc1
  testing.tRunner()
      GOROOT/src/testing/testing.go:1446 +0x216
  testing.(*T).Run.func1()
      GOROOT/src/testing/testing.go:1493 +0x47
Previous read at 0x00c00bf3f580 by goroutine 217396:
  github.com/pingcap/tidb/executor.newBaseExecutor()
      executor/executor.go:271 +0x1e6
  github.com/pingcap/tidb/executor.(*executorBuilder).buildPointGet()
      executor/point_get.go:59 +0x278
  github.com/pingcap/tidb/executor.(*executorBuilder).build()
      executor/builder.go:195 +0x1b84
  github.com/pingcap/tidb/executor.(*executorBuilder).buildSelection()
      executor/builder.go:1676 +0xc4
  github.com/pingcap/tidb/executor.(*executorBuilder).build()
      executor/builder.go:263 +0x18e4
  github.com/pingcap/tidb/executor.(*executorBuilder).buildUpdate()
      executor/builder.go:2289 +0x1f0
  github.com/pingcap/tidb/executor.(*executorBuilder).build()
      executor/builder.go:249 +0x1b1d
  github.com/pingcap/tidb/executor.(*ExecStmt).buildExecutor()
      executor/adapter.go:1154 +0x3a7
  github.com/pingcap/tidb/executor.(*ExecStmt).Exec()
      executor/adapter.go:516 +0x9f7
  github.com/pingcap/tidb/session.runStmt()
      session/session.go:2351 +0x761
  github.com/pingcap/tidb/session.(*session).ExecuteStmt()
      session/session.go:2215 +0xfa5
  github.com/pingcap/tidb/testkit.(*TestKit).ExecWithContext()
      testkit/testkit.go:321 +0x96e
  github.com/pingcap/tidb/testkit.(*TestKit).MustExecWithContext()
      testkit/testkit.go:130 +0xb7
  github.com/pingcap/tidb/testkit.(*TestKit).MustExec()
      testkit/testkit.go:125 +0xf7
  github.com/pingcap/tidb/testkit.(*SteppedTestKit).MustExec()
      testkit/stepped.go:233 +0x148
  github.com/pingcap/tidb/testkit.(*SteppedTestKit).SteppedMustExec.func1()
      testkit/stepped.go:218 +0x7a
  github.com/pingcap/tidb/testkit.(*SteppedTestKit).steppedCommand.func1()
      testkit/stepped.go:199 +0x3c3
Goroutine 216448 (running) created at:
  testing.(*T).Run()
      GOROOT/src/testing/testing.go:1493 +0x75d
  github.com/pingcap/tidb/testkit/testfork.RunTest()
      testkit/testfork/fork.go:114 +0x158
  sessiontxn/sessiontxn_test_test.TestOptimisticTxnRetryInPessimisticMode()
      sessiontxn/txn_context_test.go:804 +0x25a
  github.com/pingcap/tidb/domain.(*Domain).LoadSysVarCacheLoop()
      domain/domain.go:1384 +0xa8
  github.com/pingcap/tidb/session.BootstrapSession()
      session/session.go:3337 +0x693
  github.com/pingcap/tidb/domain.(*Domain).GetSessionCache()
      domain/sysvar_cache.go:62 +0x59
  github.com/pingcap/tidb/session.(*session).loadCommonGlobalVariablesIfNeeded()
      session/session.go:3656 +0x104
  github.com/pingcap/tidb/session.(*session).ExecuteStmt()
      session/session.go:2134 +0x2a5
  github.com/pingcap/tidb/session.(*session).ExecuteInternal()
      session/session.go:1668 +0x471
  github.com/pingcap/tidb/domain.(*Domain).LoadPrivilegeLoop()
      domain/domain.go:1328 +0x130
  github.com/pingcap/tidb/session.BootstrapSession()
      session/session.go:3330 +0x644
  github.com/pingcap/tidb/testkit.bootstrap()
      testkit/mockstore.go:85 +0xac
  github.com/pingcap/tidb/testkit.CreateMockStoreAndDomain()
      testkit/mockstore.go:70 +0xe9
  sessiontxn/sessiontxn_test_test.setupTxnContextTest()
      sessiontxn/txn_context_test.go:61 +0x28d
  sessiontxn/sessiontxn_test_test.TestOptimisticTxnRetryInPessimisticMode()
      sessiontxn/txn_context_test.go:794 +0x30
  testing.tRunner()
      GOROOT/src/testing/testing.go:1446 +0x216
  testing.(*T).Run.func1()
      GOROOT/src/testing/testing.go:1493 +0x47
Goroutine 217396 (running) created at:
  github.com/pingcap/tidb/testkit.(*SteppedTestKit).steppedCommand()
      testkit/stepped.go:165 +0x1c4
  github.com/pingcap/tidb/testkit.(*SteppedTestKit).SteppedMustExec()
      testkit/stepped.go:217 +0x144
  sessiontxn/sessiontxn_test_test.TestOptimisticTxnRetryInPessimisticMode.func1()
      sessiontxn/txn_context_test.go:835 +0x5af
  github.com/pingcap/tidb/testkit/testfork.RunTest.func1.1()
      testkit/testfork/fork.go:110 +0xc1
  testing.tRunner()
      GOROOT/src/testing/testing.go:1446 +0x216
  testing.(*T).Run.func1()
      GOROOT/src/testing/testing.go:1493 +0x47
================== 

2. What did you expect to see? (Required)

3. What did you see instead (Required)

4. What is your TiDB version? (Required)

hawkingrei commented 1 year ago

https://prow.pingcap.net/view/gs/pingcapprow/logs/tidb_race/1619596852770902016