Add support for MAX_EXECUTION_TIME. #10541

db-storage · 2019-05-20T09:13:01Z

This feature is request by Feature 7008.
Add support for system variable "session.max_execution_time" and "global.max_execution_time".
Support hint in Select Statement linke: "SELECT /*+ MAX_EXECUTION_TIME(1000) */ * FROM t1".
Add some unit test for the above(all tests passed).

What problem does this PR solve?

Fixes #7008

What is changed and how it works?

If the max_execution_time is valid for select statement(by system variable "session.max_execution_time" or "global.max_execution_time" or hint), then check if max_execution_time has been exceeded each time before getting new chunk, and return error if it happens.

Check List

Tests

Unit test

With ingested delay, in order to make query time exceeds max_execution_time.

Integration test

`mysql> select /+ MAX_EXECUTION_TIME(100)/ * from litong where SLEEP(2) and exists (select * from test3 where test3.num>=litong.num);
ERROR 1907 (HY000): Query execution was interrupted, max_execution_time exceeded.
mysql> select * from litong where SLEEP(2);
Empty set (4.00 sec)

mysql> select * from litong;
+-----+------+
| id | num |
+-----+------+
| 100 | 28 |
| 101 | 28 |
+-----+------+
2 rows in set (0.00 sec)`

Code changes

Has interface methods change

Side effects

Related changes

Need to cherry-pick to the release branch
Need to update the documentation
Need to be included in the release note

CLAassistant · 2019-05-20T09:13:11Z

All committers have signed the CLA.

codecov · 2019-05-20T09:17:10Z

Codecov Report

Merging #10541 into master will decrease coverage by 0.1956%.
The diff coverage is 89.8305%.

@@               Coverage Diff                @@
##             master     #10541        +/-   ##
================================================
- Coverage   81.3393%   81.1436%   -0.1957%     
================================================
  Files           419        419                
  Lines         90002      89153       -849     
================================================
- Hits          73207      72342       -865     
- Misses        11546      11563        +17     
+ Partials       5249       5248         -1

shenli · 2019-05-20T09:28:29Z

server/conn.go

+		//MaxExecDuration() return 0 if there is no limit
+		if rs.MaxExecDuration().Nanoseconds() > 0 &&
+			time.Now().After(rs.StartExecTime().Add(rs.MaxExecDuration())) {
+			return errors.New("Query execution was interrupted, max_execution_time exceeded")


Is there an standard error code for this type of error in MySQL?

If the execution is blocked at line 1311 for a long time, it may exceed the maxExecDuration.

Is there an standard error code for this type of error in MySQL?
Error code 1907 added to parser, refer to PR

If the execution is blocked at line 1311 for a long time, it may exceed the maxExecDuration.
Fixed by closing result set and context on timeout.

It is better to use this predefined error in parser repo,

https://github.com/pingcap/parser/blob/f74198ed55281727f26567edd2fae775bc6c5366/mysql/errname.go#L335

It is better to use this predefined error in parser repo,

OK, I will add and use the error code.
By the way, should all published Mysql error codes be imported in batch?

Basically, it will be defined when it is used.

breezewish · 2019-05-21T05:44:11Z

I think this should also be pushed down to TiKV to support per-statement max execution time limit.

alivxxx · 2019-05-21T09:47:23Z

server/conn.go

+		//MaxExecDuration() return 0 if there is no limit
+		if rs.MaxExecDuration().Nanoseconds() > 0 &&
+			time.Now().After(rs.StartExecTime().Add(rs.MaxExecDuration())) {
+			return errors.New("Query execution was interrupted, max_execution_time exceeded")


But this cannot work for cases like HashAgg which consumes all of its child's input and finally returns result?

server/conn.go

qw4990 · 2019-05-22T06:01:22Z

I think this should also be pushed down to TiKV to support per-statement max execution time limit.

We can do this later after finishing MaxExecTime in TiDB.

db-storage · 2019-05-23T12:56:07Z

code changed per review comments, please review again.

qw4990 · 2019-05-29T02:48:08Z

@db-storage please fix CI problems and resolve conflicts.

jackysp · 2019-05-29T03:07:23Z

So many unrelated changes in this PR, maybe need a squash.

db-storage · 2019-05-29T04:08:28Z

@db-storage please fix CI problems and resolve conflicts.

The last committed code depends on Error Code defined in parser, refer to PR.

I will resolve conflicts and do a squash.

tiancaiamao · 2019-05-29T08:06:50Z

This commit use context cancel to implement MAX_EXECUTION_TIME.

Cancel context is the way we used to implement kill xxx in the past, it has some drawbacks:

all executor must handle the cancel signal... if some executor don't obey the rule, cancel can't work
handle cancel signal makes the code complex
as cancel makes the code complex... it's more likely to cause goroutine leak
cancel will not kill 2PC (known issue)

In commit #9844, we turn to use executor.Close
I think it's better to keep just one implementation, we should clean up the cancel way later.
Caller should use Kill() to terminate the executation of a session

In this PR #10350, there is a background goroutine that monitoring all slow queries, maybe it's better to wait the PR to be merged and implement MAX_EXECUTION_TIME after that.

db-storage · 2019-05-29T08:33:45Z

This commit use context cancel to implement MAX_EXECUTION_TIME.

Cancel context is the way we used to implement kill xxx in the past, it has some drawbacks:

all executor must handle the cancel signal... if some executor don't obey the rule, cancel can't work

handle cancel signal makes the code complex

as cancel makes the code complex... it's more likely to cause goroutine leak

cancel will not kill 2PC (known issue)

recordSet.Close() is called too when the execution is timed out.
The MAX_EXECUTION_TIME hint is permitted only for SELECT statements. Refer to mysql doc. So there should be no 2PC involved.

In commit #9844, we turn to use executor.Close
I think it's better to keep just one implementation, we should clean up the cancel way later.
Caller should use Kill() to terminate the executation of a session

I can't find executor.Close in commit #9844，did you mean 'resultSet.Close'?

In this PR #10350, there is a background goroutine that monitoring all slow queries, maybe it's better to wait the PR to be merged and implement MAX_EXECUTION_TIME after that.

In order to use the same go routine? when will PR #10350 be merged?

tiancaiamao · 2019-05-29T08:51:22Z

I can't find executor.Close in commit #9844，did you mean 'resultSet.Close'?

Yes, 'resultSet.Close'

In order to use the same go routine? when will PR #10350 be merged?

In order to make the code easier to maintain ... add a monitoring goroutine is a more general solution @XuHuaiyu will take charge of that PR and I guess it won't be too long get merged

shenli · 2019-06-09T14:34:53Z

@db-storage Please resolve the conflicts.

- Use existing slow query handler to monitor registered queries; - Don't use resultSet's CancelFunc, use Close only; - Add error errMaxExecTimeExceeded; - Modify writeChunk, don't send EOF if execution timed out.

db-storage · 2019-06-12T07:30:49Z

@db-storage Please resolve the conflicts.

Conflicts solved.
Rebased code with PR #10350 merged.
Use the same handler to monitor queries with max_execution_time(by hint of system variable).
In addition to the original UT cases, added test from mysql client.

`mysql> select /+ MAX_EXECUTION_TIME(100)/ * from litong where SLEEP(2) and exists (select * from test3 where test3.num>=litong.num);
ERROR 1907 (HY000): Query execution was interrupted, max_execution_time exceeded.
mysql> select * from litong where SLEEP(2);
Empty set (4.00 sec)

mysql> select * from litong;
+-----+------+
| id | num |
+-----+------+
| 100 | 28 |
| 101 | 28 |
+-----+------+
2 rows in set (0.00 sec)`

tiancaiamao · 2019-06-13T07:57:16Z

PTAL @qw4990 @XuHuaiyu

…e bug. 'make all' passed.

tiancaiamao · 2019-06-22T06:36:37Z

sessionctx/variable/tidb_vars.go

@@ -334,7 +334,8 @@ const (
 	DefTiDBUseFastAnalyze              = false
 	DefTiDBSkipIsolationLevelCheck     = false
 	DefTiDBWaitTableSplitFinish        = false
-	DefTiDBExpensiveQueryTimeThreshold = 60 // 60s
+	DefTiDBExpensiveQueryTimeThreshold = 100 // 100 ms


100ms is too small as the default value for ExpensiveQueryTimeThreshold, it makes TiDB print a log of logs.
I think 60s may be a better default value here.

And note that the check interval of the ticker is not necessary to be ExpensiveQueryTimeThreshold / 2 because the check interval value is shared with MAX_EXECUTION_TIME check interval, maybe 100ms is a good choice.

It means the MAX_EXECUTION_TIME will be less accurate if the check interval is 100ms. That's acceptable as the code is simple enough in my opinion. We can polish the code after this feature is merged, adopting a dynamic check interval.

…rval in ExpensiveQueryTimeThreshold; 'make all' passed

tiancaiamao · 2019-06-22T07:25:06Z

LGTM

PTAL @XuHuaiyu @qw4990

crazycs520 · 2019-06-24T15:14:55Z

sessionctx/variable/session.go

@@ -682,6 +686,12 @@ func (s *SessionVars) SetSystemVar(name string, val string) error {
 		if isAutocommit {
 			s.SetStatusFlag(mysql.ServerStatusInTrans, false)
 		}
+	case MaxExecutionTime:
+		timeoutMS := tidbOptInt64(val, 0)


How about use tidbOptPositiveInt32.

…ke all' passed.

sessionctx/variable/session.go

sessionctx/variable/tidb_vars.go

util/expensivequery/expensivequery.go

crazycs520

LGTM

crazycs520 · 2019-06-24T16:57:06Z

/run-all-tests

crazycs520 · 2019-06-24T17:11:42Z

/run-all-tests

coderplay · 2022-08-02T19:06:47Z

I think this should also be pushed down to TiKV to support per-statement max execution time limit.

We can do this later after finishing MaxExecTime in TiDB.

Did we? @zhangjinpeng1987

shenli added the contribution This PR is from a community contributor. label May 20, 2019

jackysp requested review from tiancaiamao May 20, 2019 09:23

jackysp added the sig/execution SIG execution label May 20, 2019

shenli reviewed May 20, 2019

View reviewed changes

qw4990 self-requested a review May 21, 2019 05:32

alivxxx reviewed May 21, 2019

View reviewed changes

qw4990 reviewed May 22, 2019

View reviewed changes

server/conn.go Outdated Show resolved Hide resolved

db-storage force-pushed the support_max_excution_time branch 3 times, most recently from b9f7706 to 4f272e8 Compare May 29, 2019 07:29

db-storage force-pushed the support_max_excution_time branch 2 times, most recently from a1f7962 to 2f9d152 Compare May 29, 2019 12:01

- Add support for MAX_EXECUTION_TIME;

e9e5222

- Use existing slow query handler to monitor registered queries; - Don't use resultSet's CancelFunc, use Close only; - Add error errMaxExecTimeExceeded; - Modify writeChunk, don't send EOF if execution timed out.

db-storage force-pushed the support_max_excution_time branch from 2f9d152 to e9e5222 Compare June 12, 2019 07:23

modify for gofmt

0dc47c3

tiancaiamao and others added 2 commits June 20, 2019 13:56

tiny clean up

b0f37d1

change ExpensiveQueryHandle's default tick interval to 100ms, fix som…

d2a6d1c

…e bug. 'make all' passed.

tiancaiamao reviewed Jun 22, 2019

View reviewed changes

Change ExpensiveQueryTimeThreshold back to 60s; use 100ms ticker inte…

3f58e52

…rval in ExpensiveQueryTimeThreshold; 'make all' passed

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

crazycs520 reviewed Jun 24, 2019

View reviewed changes

db-storage and others added 3 commits June 24, 2019 23:28

Merge branch 'master' into support_max_excution_time

9caf33d

replace tidbOptInt64 with tidbOptPositiveInt32; fix gofmt errors; 'ma…

fd14077

…ke all' passed.

Merge branch 'master' into support_max_excution_time

8b79367

crazycs520 reviewed Jun 24, 2019

View reviewed changes

sessionctx/variable/session.go Outdated Show resolved Hide resolved

crazycs520 reviewed Jun 24, 2019

View reviewed changes

sessionctx/variable/tidb_vars.go Outdated Show resolved Hide resolved

crazycs520 reviewed Jun 24, 2019

View reviewed changes

util/expensivequery/expensivequery.go Outdated Show resolved Hide resolved

minor changes per review comment

6609ecc

crazycs520 approved these changes Jun 24, 2019

View reviewed changes

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

crazycs520 merged commit a57b6e6 into pingcap:master Jun 24, 2019

tiancaiamao pushed a commit to tiancaiamao/tidb that referenced this pull request Jun 25, 2019

*: Add support for MAX_EXECUTION_TIME. (pingcap#10541)

7110c56

tiancaiamao mentioned this pull request Jun 25, 2019

*: Add support for MAX_EXECUTION_TIME. (#10541) #10940

Merged

jackysp pushed a commit that referenced this pull request Jun 26, 2019

*: Add support for MAX_EXECUTION_TIME. (#10541) (#10940)

7214234

tiancaiamao added a commit to tiancaiamao/tidb that referenced this pull request Jul 2, 2019

*: Add support for MAX_EXECUTION_TIME (pingcap#10541)

05309d7

tiancaiamao mentioned this pull request Jul 2, 2019

*: Add support for MAX_EXECUTION_TIME (#10541) (#10963) #11026

Merged

winkyao pushed a commit that referenced this pull request Jul 15, 2019

*: Add support for MAX_EXECUTION_TIME (#10541) (#10963) (#11026)

3ad5ff6

xhebox mentioned this pull request Aug 17, 2022

test: ichi title chec #37130

Closed

12 tasks

xhebox mentioned this pull request Oct 27, 2022

*: skip log timeout on maxExecutiontime as slow query for DDL statement. #38671

Merged

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add support for MAX_EXECUTION_TIME. #10541

Add support for MAX_EXECUTION_TIME. #10541

db-storage commented May 20, 2019 •

edited

Loading

CLAassistant commented May 20, 2019 •

edited

Loading

codecov bot commented May 20, 2019 •

edited

Loading

shenli May 20, 2019

shenli May 20, 2019

db-storage May 21, 2019 •

edited

Loading

db-storage May 21, 2019 •

edited

Loading

jackysp May 21, 2019 •

edited

Loading

db-storage May 21, 2019

jackysp May 21, 2019

breezewish commented May 21, 2019

alivxxx May 21, 2019

qw4990 commented May 22, 2019

db-storage commented May 23, 2019 •

edited

Loading

qw4990 commented May 29, 2019

jackysp commented May 29, 2019

db-storage commented May 29, 2019

tiancaiamao commented May 29, 2019

db-storage commented May 29, 2019 •

edited

Loading

tiancaiamao commented May 29, 2019

shenli commented Jun 9, 2019

db-storage commented Jun 12, 2019

tiancaiamao commented Jun 13, 2019

tiancaiamao Jun 22, 2019

tiancaiamao commented Jun 22, 2019

crazycs520 Jun 24, 2019

db-storage Jun 24, 2019

crazycs520 left a comment

crazycs520 commented Jun 24, 2019

crazycs520 commented Jun 24, 2019

coderplay commented Aug 2, 2022

Add support for MAX_EXECUTION_TIME. #10541

Add support for MAX_EXECUTION_TIME. #10541

Conversation

db-storage commented May 20, 2019 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Check List

CLAassistant commented May 20, 2019 • edited Loading

codecov bot commented May 20, 2019 • edited Loading

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

db-storage May 21, 2019 • edited Loading

Choose a reason for hiding this comment

db-storage May 21, 2019 • edited Loading

Choose a reason for hiding this comment

jackysp May 21, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

breezewish commented May 21, 2019

Choose a reason for hiding this comment

qw4990 commented May 22, 2019

db-storage commented May 23, 2019 • edited Loading

qw4990 commented May 29, 2019

jackysp commented May 29, 2019

db-storage commented May 29, 2019

tiancaiamao commented May 29, 2019

db-storage commented May 29, 2019 • edited Loading

tiancaiamao commented May 29, 2019

shenli commented Jun 9, 2019

db-storage commented Jun 12, 2019

tiancaiamao commented Jun 13, 2019

Choose a reason for hiding this comment

tiancaiamao commented Jun 22, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

crazycs520 left a comment

Choose a reason for hiding this comment

crazycs520 commented Jun 24, 2019

crazycs520 commented Jun 24, 2019

coderplay commented Aug 2, 2022

db-storage commented May 20, 2019 •

edited

Loading

CLAassistant commented May 20, 2019 •

edited

Loading

codecov bot commented May 20, 2019 •

edited

Loading

db-storage May 21, 2019 •

edited

Loading

db-storage May 21, 2019 •

edited

Loading

jackysp May 21, 2019 •

edited

Loading

db-storage commented May 23, 2019 •

edited

Loading

db-storage commented May 29, 2019 •

edited

Loading