*: print an expensive query log when a query is out of memQuota #10799

XuHuaiyu · 2019-06-13T07:55:31Z

What problem does this PR solve?

Print an expensive query log when a query is out of memory quota.

What is changed and how it works?

Bind a hook for Action, and this hook will be triggered when a sql's memory usage is out of quota.
Print an expensive query log no matter the action is log or cancel since expensive query log is more detailed.

Check List

Tests

Manual test (add detailed scripts or steps below)

Change the MemQuotaQuery to 1<<15 (32KB), and run select * from t, then we get:

 [WARN] [expensivequery.go:150] [expensive_query] [cost_time=0.066961588s] [stats=t:409052062136664065] [conn_id=1] [user=root] [database=test] [table_ids="[44]"] [txn_start_ts=409052736881426432] [mem_max="32.4697265625 KB"] [sql="select * from t"]

Change the OOMAction to cancel and MemQuotaQuery to 1<<15(32KB), and run select * from t, then we get:

[WARN] [expensivequery.go:150] [expensive_query] [cost_time=0.070405408s] [stats=t:409052763423506432] [conn_id=1] [user=root] [database=test] [table_ids="[44]"] [txn_start_ts=409052764014379008] [mem_max="32.4697265625 KB"] [sql="select * from t"]
[2019/06/13 15:54:20.453 +08:00] [ERROR] [coprocessor.go:616] ["copIteratorWork meet panic"] [r="\"Out Of Memory Quota!\\n\\\"select * from t\\\"{\\n  \\\"quota\\\": 32 KB\\n  \\\"consumed\\\": 32.4697265625 KB\\n  \\\"TableReaderDistSQLTracker\\\"{\\n    \\\"quota\\\": 32 GB\\n    \\\"consumed\\\": 32.4697265625 KB\\n  }\\n}\\n\""] ["stack trace"="github.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask.func1\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:618\nruntime.gopanic\n\t/Users/xuhuaiyu/.gvm/gos/go1.12/src/runtime/panic.go:522\ngithub.com/pingcap/tidb/util/memory.(*PanicOnExceed).Action\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/util/memory/action.go:90\ngithub.com/pingcap/tidb/util/memory.(*Tracker).Consume\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/util/memory/tracker.go:161\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).sendToRespCh\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:553\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleCopResponse\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:824\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTaskOnce\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:683\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:626\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).run\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:465"] [stack="github.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask.func1\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:616\nruntime.gopanic\n\t/Users/xuhuaiyu/.gvm/gos/go1.12/src/runtime/panic.go:522\ngithub.com/pingcap/tidb/util/memory.(*PanicOnExceed).Action\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/util/memory/action.go:90\ngithub.com/pingcap/tidb/util/memory.(*Tracker).Consume\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/util/memory/tracker.go:161\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).sendToRespCh\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:553\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleCopResponse\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:824\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTaskOnce\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:683\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:626\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).run\n\t/Users/xuhuaiyu/Development/GOPATH/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:465"]

Code changes

Has exported function/method change
Has exported variable/fields change

Side effects

N/A

Related changes

Need to cherry-pick to the release branch
Need to update the documentation

codecov · 2019-06-13T08:00:21Z

Codecov Report

Merging #10799 into master will increase coverage by 0.0187%.
The diff coverage is 25%.

@@               Coverage Diff                @@
##             master     #10799        +/-   ##
================================================
+ Coverage   80.8285%   80.8473%   +0.0187%     
================================================
  Files           419        419                
  Lines         88611      88635        +24     
================================================
+ Hits          71623      71659        +36     
+ Misses        11760      11750        -10     
+ Partials       5228       5226         -2

tiancaiamao · 2019-06-17T03:26:01Z

ddl/ddl_test.go

 	SetHook(h Callback)
 	// SetInterceptoror sets the interceptor.
 	SetInterceptoror(h Interceptor)
 }

-// SetHook implements DDL.SetHook interface.
+// SetLogHook implements DDL.SetLogHook interface.


Comment and Function name is not consistent...
I think it can't pass this check #10787

…ve_log_mem

qw4990

LGTM

zz-jason · 2019-06-17T06:47:32Z

executor/executor.go

 	default:
-		sc.MemTracker.SetActionOnExceed(&memory.LogOnExceed{})
+		action := &memory.LogOnExceed{ConnID: ctx.GetSessionVars().ConnectionID}


should we return an unsupported oom action error?

executor/executor.go

zz-jason · 2019-06-17T06:49:19Z

server/server.go

@@ -490,8 +490,9 @@ func (s *Server) ShowProcessList() map[uint64]*util.ProcessInfo {
 		if atomic.LoadInt32(&client.status) == connStatusWaitShutdown {
 			continue
 		}
-		pi := client.ctx.ShowProcess()
-		rs[pi.ID] = pi
+		if pi := client.ctx.ShowProcess(); pi != nil {


Yes, #10740
But I'm not sure how to add a test case for it.

Do release 2.1 and 3.0 have this issue?

No, only master branch has this issue now.
Before refactoring the expensive log, this function will only be called when we use show processlist, the pi can be promised to be not null.

But this PR needs to be cherry-picked to release-3.0, so we'd better use another PR to fix it?

Could you add an UT about it?
And we should backport this UT to old releases.

util/memory/action.go

zz-jason · 2019-06-17T08:10:40Z

server/server.go

@@ -490,8 +490,9 @@ func (s *Server) ShowProcessList() map[uint64]*util.ProcessInfo {
 		if atomic.LoadInt32(&client.status) == connStatusWaitShutdown {
 			continue
 		}
-		pi := client.ctx.ShowProcess()
-		rs[pi.ID] = pi
+		if pi := client.ctx.ShowProcess(); pi != nil {


Do release 2.1 and 3.0 have this issue?

executor/executor.go

zz-jason · 2019-06-17T08:20:14Z

executor/executor.go

@@ -1303,11 +1303,15 @@ func ResetContextOfStmt(ctx sessionctx.Context, s ast.StmtNode) (err error) {
 	}
 	switch config.GetGlobalConfig().OOMAction {
 	case config.OOMActionCancel:
-		sc.MemTracker.SetActionOnExceed(&memory.PanicOnExceed{})
+		action := &memory.PanicOnExceed{ConnID: ctx.GetSessionVars().ConnectionID}
+		action.SetLogHook(domain.GetDomain(ctx).ExpensiveQueryHandle().LogOnQueryExceedMemQuota)


I think we don't need to add this log. When the query runs out of memory quota, it panics. The upper layer will recover that goroutine and log the panic reason and sql, which is "out of memory quota".

I think they are two different logs.
Expensive query log can provide us more info about the query.

can we change the panic message to the content we want to log?

alivxxx · 2019-06-18T04:35:09Z

ddl/ddl_test.go

@@ -46,7 +46,7 @@ type DDLForTest interface {
 	SetInterceptoror(h Interceptor)
 }

-// SetHook implements DDL.SetHook interface.
+// SetHook implements DDL.SetLogHook interface.


This line should not be changed.

zz-jason

LGTM

XuHuaiyu · 2019-06-18T07:44:59Z

/run-all-tests

alivxxx · 2019-06-18T07:53:32Z

util/memory/action.go

@@ -17,6 +17,7 @@ import (
 	"context"
 	"sync"

+	"fmt"


Move this upward.

alivxxx

LGTM

…cap#10799)

…) (#10849)

XuHuaiyu added 2 commits June 13, 2019 15:15

*: print an expensive query log when a query is out of memQuota

9394c32

update

43a6086

XuHuaiyu added type/enhancement The issue or PR belongs to an enhancement. sig/execution SIG execution labels Jun 13, 2019

XuHuaiyu requested review from tiancaiamao, zz-jason and qw4990 June 13, 2019 07:55

XuHuaiyu added the priority/P1 The issue has P1 priority. label Jun 13, 2019

tiancaiamao reviewed Jun 17, 2019

View reviewed changes

XuHuaiyu added 2 commits June 17, 2019 14:22

address comment

e4d3867

Merge branch 'master' of https://github.com/pingcap/tidb into expensi…

ac124e0

…ve_log_mem

qw4990 reviewed Jun 17, 2019

View reviewed changes

XuHuaiyu added the status/LGT1 Indicates that a PR has LGTM 1. label Jun 17, 2019

zz-jason reviewed Jun 17, 2019

View reviewed changes

XuHuaiyu added 2 commits June 17, 2019 15:36

address comment

35e7ce5

address comment

b0dd725

XuHuaiyu requested a review from zz-jason June 17, 2019 07:55

zz-jason reviewed Jun 17, 2019

View reviewed changes

XuHuaiyu requested a review from zz-jason June 18, 2019 02:22

alivxxx reviewed Jun 18, 2019

View reviewed changes

XuHuaiyu added 2 commits June 18, 2019 14:51

address comment

a760fd4

address comment

fa77b14

XuHuaiyu requested a review from alivxxx June 18, 2019 07:31

zz-jason reviewed Jun 18, 2019

View reviewed changes

alivxxx reviewed Jun 18, 2019

View reviewed changes

util/memory/action.go Outdated

@@ -17,6 +17,7 @@ import (

"context"

"sync"

"fmt"

Copy link

Contributor

alivxxx Jun 18, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Move this upward.

address comment

81b27aa

alivxxx approved these changes Jun 18, 2019

View reviewed changes

Merge branch 'master' into expensive_log_mem

b96ea5a

XuHuaiyu added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Jun 18, 2019

XuHuaiyu merged commit b0d6c5b into pingcap:master Jun 18, 2019

XuHuaiyu deleted the expensive_log_mem branch June 18, 2019 08:18

XuHuaiyu added a commit to XuHuaiyu/tidb that referenced this pull request Jun 19, 2019

*: print an expensive query log when a query is out of memQuota (ping…

3afad3d

…cap#10799)

XuHuaiyu mentioned this pull request Jun 19, 2019

*: print an expensive query log when a query is out of memQuota (#10799) #10849

Merged

zz-jason pushed a commit that referenced this pull request Jun 19, 2019

*: print an expensive query log when a query is out of memQuota (#10799…

a9298ee

…) (#10849)

SunRunAway mentioned this pull request Jun 27, 2019

TiDB panicked with "invalid memory address or nil pointer dereference" #10740

Closed

XuHuaiyu mentioned this pull request Feb 5, 2020

*: add document for expensive query log pingcap/docs-cn#2211

Merged

12 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

*: print an expensive query log when a query is out of memQuota #10799

*: print an expensive query log when a query is out of memQuota #10799

XuHuaiyu commented Jun 13, 2019

codecov bot commented Jun 13, 2019 •

edited

Loading

tiancaiamao Jun 17, 2019

qw4990 left a comment

zz-jason Jun 17, 2019

zz-jason Jun 17, 2019

XuHuaiyu Jun 17, 2019

zz-jason Jun 17, 2019

XuHuaiyu Jun 17, 2019

zz-jason Jun 18, 2019

SunRunAway Jun 27, 2019 •

edited

Loading

zz-jason Jun 17, 2019

zz-jason Jun 17, 2019

XuHuaiyu Jun 17, 2019 •

edited

Loading

zz-jason Jun 18, 2019

alivxxx Jun 18, 2019

zz-jason left a comment

XuHuaiyu commented Jun 18, 2019

alivxxx Jun 18, 2019

alivxxx left a comment

*: print an expensive query log when a query is out of memQuota #10799

*: print an expensive query log when a query is out of memQuota #10799

Conversation

XuHuaiyu commented Jun 13, 2019

What problem does this PR solve?

What is changed and how it works?

Check List

codecov bot commented Jun 13, 2019 • edited Loading

Codecov Report

Choose a reason for hiding this comment

qw4990 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

SunRunAway Jun 27, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

XuHuaiyu Jun 17, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zz-jason left a comment

Choose a reason for hiding this comment

XuHuaiyu commented Jun 18, 2019

Choose a reason for hiding this comment

alivxxx left a comment

Choose a reason for hiding this comment

codecov bot commented Jun 13, 2019 •

edited

Loading

SunRunAway Jun 27, 2019 •

edited

Loading

XuHuaiyu Jun 17, 2019 •

edited

Loading