worker aggressively output error log

[july2993]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. What did you do? If possible, provide a recipe for reproducing the error.
   start 3master & 3worker and a task:
   work normally works at first try
   stop downstream and after some time worker output unnormal log.

2. What did you expect to see?
   more friendly log(and seems work can't work anymore)

3. What did you see instead?
   worker aggressively output the log(cpu take near 200%)

[2020/07/08 15:52:19.416 +08:00] [ERROR] [ddl.go:523] ["[ddl] get history DDL job failed, check again"] [error="tikv aborts txn: leveldb: closed"] [errorVerbose="tikv aborts txn: leveldb: closed\ngithub.com/pingcap/tidb/store/tikv.extractKeyErr\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:442\ngithub.com/pingcap/tidb/store/tikv.extractLockFromKeyErr\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:423\ngithub.com/pingcap/tidb/store/tikv.(*tikvSnapshot).get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:368\ngithub.com/pingcap/tidb/store/tikv.(*tikvSnapshot).Get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:298\ngithub.com/pingcap/tidb/kv.(*unionStore).Get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/kv/union_store.go:113\ngithub.com/pingcap/tidb/store/tikv.(*tikvTxn).Get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/txn.go:142\ngithub.com/pingcap/tidb/structure.(*TxStructure).HGet\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/structure/hash.go:59\ngithub.com/pingcap/tidb/meta.(*Meta).getHistoryDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/meta/meta.go:743\ngithub.com/pingcap/tidb/meta.(*Meta).GetHistoryDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/meta/meta.go:756\ngithub.com/pingcap/tidb/ddl.(*ddl).getHistoryDDLJob.func1\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_worker.go:263\ngithub.com/pingcap/tidb/kv.RunInNewTxn\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/kv/txn.go:47\ngithub.com/pingcap/tidb/ddl.(*ddl).getHistoryDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_worker.go:260\ngithub.com/pingcap/tidb/ddl.(*ddl).doDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl.go:521\ngithub.com/pingcap/tidb/ddl.(*ddl).DropTable\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_api.go:3689\ngithub.com/pingcap/dm/pkg/schema.(*Tracker).DropTable\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/pkg/schema/tracker.go:140\ngithub.com/pingcap/dm/syncer.(*RemoteCheckPoint).Rollback\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/checkpoint.go:559\ngithub.com/pingcap/dm/syncer.(*Syncer).Process\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/syncer.go:545\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373"] [stack="github.com/pingcap/tidb/ddl.(*ddl).doDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl.go:523\ngithub.com/pingcap/tidb/ddl.(*ddl).DropTable\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_api.go:3689\ngithub.com/pingcap/dm/pkg/schema.(*Tracker).DropTable\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/pkg/schema/tracker.go:140\ngithub.com/pingcap/dm/syncer.(*RemoteCheckPoint).Rollback\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/checkpoint.go:559\ngithub.com/pingcap/dm/syncer.(*Syncer).Process\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/syncer.go:545"]
[2020/07/08 15:52:19.516 +08:00] [WARN] [snapshot.go:443] ["2PC failed"] [error="tikv aborts txn: leveldb: closed"] [errorVerbose="tikv aborts txn: leveldb: closed\ngithub.com/pingcap/tidb/store/tikv.extractKeyErr\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:442\ngithub.com/pingcap/tidb/store/tikv.extractLockFromKeyErr\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:423\ngithub.com/pingcap/tidb/store/tikv.(*tikvSnapshot).get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:368\ngithub.com/pingcap/tidb/store/tikv.(*tikvSnapshot).Get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:298\ngithub.com/pingcap/tidb/kv.(*unionStore).Get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/kv/union_store.go:113\ngithub.com/pingcap/tidb/store/tikv.(*tikvTxn).Get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/txn.go:142\ngithub.com/pingcap/tidb/structure.(*TxStructure).HGet\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/structure/hash.go:59\ngithub.com/pingcap/tidb/meta.(*Meta).getHistoryDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/meta/meta.go:743\ngithub.com/pingcap/tidb/meta.(*Meta).GetHistoryDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/meta/meta.go:756\ngithub.com/pingcap/tidb/ddl.(*ddl).getHistoryDDLJob.func1\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_worker.go:263\ngithub.com/pingcap/tidb/kv.RunInNewTxn\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/kv/txn.go:47\ngithub.com/pingcap/tidb/ddl.(*ddl).getHistoryDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_worker.go:260\ngithub.com/pingcap/tidb/ddl.(*ddl).doDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl.go:521\ngithub.com/pingcap/tidb/ddl.(*ddl).DropTable\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_api.go:3689\ngithub.com/pingcap/dm/pkg/schema.(*Tracker).DropTable\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/pkg/schema/tracker.go:140\ngithub.com/pingcap/dm/syncer.(*RemoteCheckPoint).Rollback\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/checkpoint.go:559\ngithub.com/pingcap/dm/syncer.(*Syncer).Process\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/syncer.go:545\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373"]
[2020/07/08 15:52:19.516 +08:00] [ERROR] [ddl.go:523] ["[ddl] get history DDL job failed, check again"] [error="tikv aborts txn: leveldb: closed"] [errorVerbose="tikv aborts txn: leveldb: closed\ngithub.com/pingcap/tidb/store/tikv.extractKeyErr\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:442\ngithub.com/pingcap/tidb/store/tikv.extractLockFromKeyErr\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:423\ngithub.com/pingcap/tidb/store/tikv.(*tikvSnapshot).get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:368\ngithub.com/pingcap/tidb/store/tikv.(*tikvSnapshot).Get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/snapshot.go:298\ngithub.com/pingcap/tidb/kv.(*unionStore).Get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/kv/union_store.go:113\ngithub.com/pingcap/tidb/store/tikv.(*tikvTxn).Get\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/store/tikv/txn.go:142\ngithub.com/pingcap/tidb/structure.(*TxStructure).HGet\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/structure/hash.go:59\ngithub.com/pingcap/tidb/meta.(*Meta).getHistoryDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/meta/meta.go:743\ngithub.com/pingcap/tidb/meta.(*Meta).GetHistoryDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/meta/meta.go:756\ngithub.com/pingcap/tidb/ddl.(*ddl).getHistoryDDLJob.func1\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_worker.go:263\ngithub.com/pingcap/tidb/kv.RunInNewTxn\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/kv/txn.go:47\ngithub.com/pingcap/tidb/ddl.(*ddl).getHistoryDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_worker.go:260\ngithub.com/pingcap/tidb/ddl.(*ddl).doDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl.go:521\ngithub.com/pingcap/tidb/ddl.(*ddl).DropTable\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_api.go:3689\ngithub.com/pingcap/dm/pkg/schema.(*Tracker).DropTable\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/pkg/schema/tracker.go:140\ngithub.com/pingcap/dm/syncer.(*RemoteCheckPoint).Rollback\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/checkpoint.go:559\ngithub.com/pingcap/dm/syncer.(*Syncer).Process\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/syncer.go:545\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373"] [stack="github.com/pingcap/tidb/ddl.(*ddl).doDDLJob\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl.go:523\ngithub.com/pingcap/tidb/ddl.(*ddl).DropTable\n\t/Users/huangjiahao/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20200423094549-0ad7ce6cdae6/ddl/ddl_api.go:3689\ngithub.com/pingcap/dm/pkg/schema.(*Tracker).DropTable\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/pkg/schema/tracker.go:140\ngithub.com/pingcap/dm/syncer.(*RemoteCheckPoint).Rollback\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/checkpoint.go:559\ngithub.com/pingcap/dm/syncer.(*Syncer).Process\n\t/Users/huangjiahao/go/src/github.com/pingcap/dm/syncer/syncer.go:545"

4. Versions of the cluster

   • DM version (run dmctl -V or dm-worker -V or dm-master -V):

Release Version: v2.0.0-beta.2-10-g48ff774a
Git Commit Hash: 48ff774
Git Branch: master
UTC Build Time: 2020-07-06 03:39:14
Go Version: go version go1.14 darwin/amd64

[GMHDBJD]

This is the log of mock tidb store
Same endless log when we close dom when stop-task sometimes.
Maybe it's the same bug with this issure

[tiancaiamao]

#18048 memory leak is caused by global variable reference.
If pd is closed, it maybe related to pingcap/tidb#18336
Or the store has been closed, and the background DDL goroutine still using the store and retry on error forever, so there is the endless log.

[csuzhangxc]

#18048 memory leak is caused by global variable reference.
If pd is closed, it maybe related to pingcap/tidb#18336
Or the store has been closed, and the background DDL goroutine still using the store and retry on error forever, so there is the endless log.

@tiancaiamao We are using mock tikv store (without PD) in DM, is this the same cause as pingcap/tidb#18336?

[lance6716]

may fix by pingcap/tidb#18844