server: handle kill signal during write result to connection #52882

wshwsh12 · 2024-04-25T07:43:21Z

What problem does this PR solve?

Issue Number: close #44009

Problem Summary:

What changed and how does it work?

Check List

Tests

Unit test
Integration test
Manual test (add detailed scripts or steps below)
No need to test
- I checked and no code files have been changed.

Side effects

Performance regression: Consumes more CPU
Performance regression: Consumes more Memory
Breaking backward compatibility

Documentation

Release note

Please refer to Release Notes Language Style Guide to write a quality release note.

None

tiprow · 2024-04-25T07:43:38Z

Hi @wshwsh12. Thanks for your PR.

PRs from untrusted users cannot be marked as trusted with /ok-to-test in this repo meaning untrusted PR authors can never trigger tests themselves. Collaborators can still trigger tests on the PR using /test all.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

wshwsh12 · 2024-04-25T07:45:10Z

Manual test

Create table t with one int column, and insert 1-8388608.
set @@global.tidb_enable_tmp_storage_on_oom = off; and set @@global.tidb_mem_quota_query = 5 << 30;
Use go-mysql-driver to query the sql "select count(1) from t group by a;", fetch 10000 rows and hang forever.
Wait 10 minutes and sql doesn't finished.
Create another session and try to kill query. kill tidb query xxxxxxxxx.
The memory usage is released. After the client is restored, other sql can still be queried.

tidb> kill tidb query 2631925768;
Query OK, 0 rows affected (0.00 sec)

tidb> show processlist;
+------------+------+-----------------+------+---------+------+---------------------------------+-----------------------------------+
| Id         | User | Host            | db   | Command | Time | State                           | Info                              |
+------------+------+-----------------+------+---------+------+---------------------------------+-----------------------------------+
| 2631925766 | root | 127.0.0.1:35256 | test | Query   |    0 | autocommit                      | show processlist                  |
| 2631925768 | root | 127.0.0.1:37406 | test | Query   |  516 | autocommit; wait query finished | select count(1) from t group by a |
+------------+------+-----------------+------+---------+------+---------------------------------+-----------------------------------+
2 rows in set (0.00 sec)

wshwsh12 · 2024-04-25T07:45:18Z

/ok-to-test

codecov · 2024-04-25T08:01:14Z

Codecov Report

Attention: Patch coverage is 76.00000% with 18 lines in your changes missing coverage. Please review.

Project coverage is 56.0530%. Comparing base (b8c0865) to head (43b6052).
Report is 16 commits behind head on master.

Additional details and impacted files

@@                Coverage Diff                @@
##             master     #52882         +/-   ##
=================================================
- Coverage   74.5303%   56.0530%   -18.4773%     
=================================================
  Files          1507       1657        +150     
  Lines        358289     635446     +277157     
=================================================
+ Hits         267034     356187      +89153     
- Misses        71847     255021     +183174     
- Partials      19408      24238       +4830

Flag	Coverage Δ
integration	`22.5263% <56.2500%> (?)`

Flags with carried forward coverage won't be shown. Click here to find out more.

Components	Coverage Δ
dumpling	`52.9656% <ø> (-2.2339%)`	⬇️
parser	`∅ <ø> (∅)`
br	`41.1319% <ø> (-2.6874%)`	⬇️

This reverts commit 0860b2a.

wshwsh12 · 2024-05-16T09:41:46Z

/retest

wshwsh12 · 2024-05-20T06:04:00Z

/retest

pkg/executor/adapter.go

pkg/session/session.go

pkg/server/server.go

pkg/executor/adapter.go

pkg/util/servermemorylimit/servermemorylimit.go

pkg/parser/mysql/const.go

purelind · 2024-06-07T00:43:33Z

/retest

pkg/executor/adapter.go

pkg/util/sqlkiller/sqlkiller.go

guo-shaoge · 2024-06-07T07:34:48Z

Other lgtm

XuHuaiyu · 2024-06-12T06:43:17Z

pkg/executor/adapter.go

-	executor   exec.Executor
+	fields   []*ast.ResultField
+	executor exec.Executor
+	// `Fields` maybe call after `Close`, and executor will clear in `Close` function, so we need to store the schema in recordSet to avoid null pointer exception.


Suggested change

// `Fields` maybe call after `Close`, and executor will clear in `Close` function, so we need to store the schema in recordSet to avoid null pointer exception.

// The `Fields` method may be called after `Close`, and the executor is cleared in the `Close` function.

// Therefore, we need to store the schema in `recordSet` to avoid a null pointer exception when calling `executor.Schema()`.

XuHuaiyu · 2024-06-12T06:43:54Z

pkg/util/servermemorylimit/servermemorylimit.go

+						// If kill sql fails after 60 seconds, the current SQL may be stuck in the write packet network stack.
+						// Now, we can reclaim the resource by calling `Finish` and start looking for the next SQL with large memory usage.


Suggested change

// If kill sql fails after 60 seconds, the current SQL may be stuck in the write packet network stack.

// Now, we can reclaim the resource by calling `Finish` and start looking for the next SQL with large memory usage.

// If the SQL cannot be terminated after 60 seconds, it may be stuck in the network stack while writing packets to the client,

// encountering some bugs that cause it to hang, or failing to detect the kill signal.

// In this case, the resources can be reclaimed by calling the `Finish` method, and then we can start looking for the next SQL with the largest memory usage.

XuHuaiyu · 2024-06-12T06:45:32Z

pkg/util/servermemorylimit/servermemorylimit.go

+					if seconds := time.Since(s.killStartTime) / time.Second; seconds >= 60 {
+						// If kill sql fails after 60 seconds, the current SQL may be stuck in the write packet network stack.
+						// Now, we can reclaim the resource by calling `Finish` and start looking for the next SQL with large memory usage.
+						logutil.BgLogger().Warn(fmt.Sprintf("global memory controller failed to kill the top-consumer in %ds, try to close the executors force", seconds))


Suggested change

logutil.BgLogger().Warn(fmt.Sprintf("global memory controller failed to kill the top-consumer in %ds, try to close the executors force", seconds))

logutil.BgLogger().Warn(fmt.Sprintf("global memory controller failed to kill the top consumer in %d seconds. Attempting to force close the executors.", seconds))

XuHuaiyu · 2024-06-12T06:59:13Z

pkg/util/sqlkiller/sqlkiller.go

@@ -41,11 +41,47 @@ const (
 type SQLKiller struct {
 	Signal killSignal
 	ConnID uint64
+	Finish func()
+	// InWriteResultSet is used to mark whether the query is calling clientConn.writeResultSet().


Suggested change

// InWriteResultSet is used to mark whether the query is calling clientConn.writeResultSet().

// InWriteResultSet is used to indicate whether the query is currently calling clientConn.writeResultSet().

// If the query is in writeResultSet and Finish() can acquire rs.finishLock, we can assume the query is waiting for the client to receive data from the server over network I/O.

XuHuaiyu · 2024-06-12T07:00:05Z

pkg/util/sqlkiller/sqlkiller.go

+	if atomic.CompareAndSwapUint32(&killer.Signal, 0, reason) {
+		status := atomic.LoadUint32(&killer.Signal)
+		err := killer.getKillError(status)
+		logutil.BgLogger().Warn("kill query started", zap.Uint64("conn", killer.ConnID), zap.String("reason", err.Error()))


logutil.BgLogger().Warn("kill query initiated", zap.Uint64("connection ID", killer.ConnID), zap.String("reason", err.Error()))

XuHuaiyu · 2024-06-12T07:05:15Z

pkg/util/sqlkiller/sqlkiller.go

+// FinishResultSet is used to finish the result set.
+// If the cancel signal is received and SQL is waiting for network IO, resource released can be performed first.


// FinishResultSet is used to close the result set.
// If a kill signal is sent but the SQL query is stuck in the network stack while writing packets to the client,
// encountering some bugs that cause it to hang, or failing to detect the kill signal, we can call Finish to release resources used during the SQL execution process.

XuHuaiyu · 2024-06-12T07:06:27Z

pkg/server/server.go

@@ -907,6 +907,12 @@ func (s *Server) Kill(connectionID uint64, query bool, maxExecutionTime bool) {
 		// Mark the client connection status as WaitShutdown, when clientConn.Run detect
 		// this, it will end the dispatch loop and exit.
 		conn.setStatus(connStatusWaitShutdown)
+		if conn.bufReadConn != nil {
+			// When we try `kill connection` and tidb is stuck in the write packet network stack, we can quickly exit the network stack and end the SQL by setting WriteDeadline.


Suggested change

// When we try `kill connection` and tidb is stuck in the write packet network stack, we can quickly exit the network stack and end the SQL by setting WriteDeadline.

// When attempting to 'kill connection' and TiDB is stuck in the network stack while writing packets,

// we can quickly exit the network stack and terminate the SQL execution by setting WriteDeadline.

XuHuaiyu · 2024-06-12T07:09:57Z

pkg/executor/adapter.go

+				status := a.stmt.Ctx.GetSessionVars().SQLKiller.GetKillSignal()
+				inWriteResultSet := a.stmt.Ctx.GetSessionVars().SQLKiller.InWriteResultSet.Load()
+				if status > 0 && inWriteResultSet {
+					logutil.BgLogger().Warn("kill query, this SQL may be stuck in the network I/O stack.", zap.Uint64("conn", a.stmt.Ctx.GetSessionVars().ConnectionID))


Suggested change

logutil.BgLogger().Warn("kill query, this SQL may be stuck in the network I/O stack.", zap.Uint64("conn", a.stmt.Ctx.GetSessionVars().ConnectionID))

logutil.BgLogger().Warn("kill query, this SQL might be stuck in the network stack while writing packets to the client.", zap.Uint64("connection ID", a.stmt.Ctx.GetSessionVars().ConnectionID))

XuHuaiyu · 2024-06-12T07:14:56Z

pkg/executor/adapter.go

+	// finishLock is a mutex used to synchronize access to the `Next` and `Finish` function of the adapter.
+	// It ensures that only one goroutine can access to the `Next` and `Finish` function at a time, preventing race conditions.
+	// When we terminate the current SQL externally(e.g. kill query), we may use an additional goroutine to call the Finish function.


Suggested change

// finishLock is a mutex used to synchronize access to the `Next` and `Finish` function of the adapter.

// It ensures that only one goroutine can access to the `Next` and `Finish` function at a time, preventing race conditions.

// When we terminate the current SQL externally(e.g. kill query), we may use an additional goroutine to call the Finish function.

// finishLock is a mutex used to synchronize access to the `Next` and `Finish` functions of the adapter.

// It ensures that only one goroutine can access the `Next` and `Finish` functions at a time, preventing race conditions.

// When we terminate the current SQL externally (e.g., kill query), an additional goroutine would be used to call the `Finish` function.

XuHuaiyu · 2024-06-12T07:15:50Z

pkg/executor/adapter.go

+				status := a.stmt.Ctx.GetSessionVars().SQLKiller.GetKillSignal()
+				inWriteResultSet := a.stmt.Ctx.GetSessionVars().SQLKiller.InWriteResultSet.Load()
+				if status > 0 && inWriteResultSet {
+					logutil.BgLogger().Warn("kill query, this SQL may be stuck in the network I/O stack.", zap.Uint64("conn", a.stmt.Ctx.GetSessionVars().ConnectionID))


will kill connection trigger this log?
if so, how do we distinguish kill query and kill connection from the log?

ti-chi-bot · 2024-06-12T08:08:21Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: guo-shaoge, XuHuaiyu

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [XuHuaiyu,guo-shaoge]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

ti-chi-bot · 2024-06-12T08:08:24Z

[LGTM Timeline notifier]

Timeline:

2024-06-07 07:49:34.014294992 +0000 UTC m=+105328.067606916: ☑️ agreed by guo-shaoge.
2024-06-12 08:08:23.653012723 +0000 UTC m=+538457.706324647: ☑️ agreed by XuHuaiyu.

wshwsh12 added 3 commits April 25, 2024 15:08

try

e17def0

add

3e8ea59

fix

a822d8d

ti-chi-bot bot added release-note-none Denotes a PR that doesn't merit a release note. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Apr 25, 2024

ti-chi-bot bot added the ok-to-test Indicates a PR is ready to be tested. label Apr 25, 2024

fix

719d49b

wshwsh12 added 4 commits April 25, 2024 16:10

fix

695292d

fix

f2e0dfa

only test

0860b2a

Revert "only test"

8e9e718

This reverts commit 0860b2a.

XuHuaiyu reviewed Jun 4, 2024

View reviewed changes

wshwsh12 added 2 commits June 5, 2024 14:21

add comments

d657643

add comments

0c3649d

wshwsh12 requested a review from XuHuaiyu June 6, 2024 03:43

wshwsh12 added 3 commits June 6, 2024 14:15

Merge remote-tracking branch 'upstream/master' into write-conn-timeout-2

f662fa1

processlist

ee96580

add comments

601de00

ti-chi-bot bot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Jun 6, 2024

add log

1587299

wshwsh12 force-pushed the write-conn-timeout-2 branch from ec4937d to 1587299 Compare June 6, 2024 08:13

add more log

372f8fa

add comments

4159a99

guo-shaoge reviewed Jun 7, 2024

View reviewed changes

pkg/executor/adapter.go Outdated Show resolved Hide resolved

guo-shaoge reviewed Jun 7, 2024

View reviewed changes

pkg/util/sqlkiller/sqlkiller.go Outdated Show resolved Hide resolved

address comments

4868d30

wshwsh12 requested a review from guo-shaoge June 7, 2024 07:44

guo-shaoge approved these changes Jun 7, 2024

View reviewed changes

ti-chi-bot bot added approved needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Jun 7, 2024

XuHuaiyu reviewed Jun 12, 2024

View reviewed changes

address comments

43b6052

XuHuaiyu approved these changes Jun 12, 2024

View reviewed changes

ti-chi-bot bot added lgtm and removed needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Jun 12, 2024

ti-chi-bot bot merged commit e9da2c0 into pingcap:master Jun 12, 2024
23 checks passed

wshwsh12 mentioned this pull request Jul 3, 2024

executor: fix tidb crash when calling Close and Finish #54390

Merged

13 tasks

ti-chi-bot mentioned this pull request Jul 3, 2024

executor: fix tidb crash when calling Close and Finish (#54390) #54416

Merged

13 tasks

gengliqi mentioned this pull request Sep 20, 2024

Truly kill a query when it exceeds max excution time even if mysql client gets stuck #39449

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

server: handle kill signal during write result to connection #52882

server: handle kill signal during write result to connection #52882

wshwsh12 commented Apr 25, 2024

tiprow bot commented Apr 25, 2024

wshwsh12 commented Apr 25, 2024

wshwsh12 commented Apr 25, 2024

codecov bot commented Apr 25, 2024 •

edited

Loading

wshwsh12 commented May 16, 2024

wshwsh12 commented May 20, 2024

purelind commented Jun 7, 2024

guo-shaoge commented Jun 7, 2024

XuHuaiyu Jun 12, 2024

XuHuaiyu Jun 12, 2024

XuHuaiyu Jun 12, 2024

XuHuaiyu Jun 12, 2024

XuHuaiyu Jun 12, 2024

XuHuaiyu Jun 12, 2024

XuHuaiyu Jun 12, 2024

XuHuaiyu Jun 12, 2024

XuHuaiyu Jun 12, 2024

XuHuaiyu Jun 12, 2024

ti-chi-bot bot commented Jun 12, 2024

ti-chi-bot bot commented Jun 12, 2024

	// `Fields` maybe call after `Close`, and executor will clear in `Close` function, so we need to store the schema in recordSet to avoid null pointer exception.
	// The `Fields` method may be called after `Close`, and the executor is cleared in the `Close` function.
	// Therefore, we need to store the schema in `recordSet` to avoid a null pointer exception when calling `executor.Schema()`.

		// If kill sql fails after 60 seconds, the current SQL may be stuck in the write packet network stack.
		// Now, we can reclaim the resource by calling `Finish` and start looking for the next SQL with large memory usage.

-						// If kill sql fails after 60 seconds, the current SQL may be stuck in the write packet network stack.
-						// Now, we can reclaim the resource by calling `Finish` and start looking for the next SQL with large memory usage.
+// If the SQL cannot be terminated after 60 seconds, it may be stuck in the network stack while writing packets to the client,
+// encountering some bugs that cause it to hang, or failing to detect the kill signal.
+// In this case, the resources can be reclaimed by calling the `Finish` method, and then we can start looking for the next SQL with the largest memory usage.

	logutil.BgLogger().Warn(fmt.Sprintf("global memory controller failed to kill the top-consumer in %ds, try to close the executors force", seconds))
	logutil.BgLogger().Warn(fmt.Sprintf("global memory controller failed to kill the top consumer in %d seconds. Attempting to force close the executors.", seconds))

-	// InWriteResultSet is used to mark whether the query is calling clientConn.writeResultSet().
+// InWriteResultSet is used to indicate whether the query is currently calling clientConn.writeResultSet().
+// If the query is in writeResultSet and Finish() can acquire rs.finishLock, we can assume the query is waiting for the client to receive data from the server over network I/O.

		// FinishResultSet is used to finish the result set.
		// If the cancel signal is received and SQL is waiting for network IO, resource released can be performed first.

	// When we try `kill connection` and tidb is stuck in the write packet network stack, we can quickly exit the network stack and end the SQL by setting WriteDeadline.
	// When attempting to 'kill connection' and TiDB is stuck in the network stack while writing packets,
	// we can quickly exit the network stack and terminate the SQL execution by setting WriteDeadline.

	logutil.BgLogger().Warn("kill query, this SQL may be stuck in the network I/O stack.", zap.Uint64("conn", a.stmt.Ctx.GetSessionVars().ConnectionID))
	logutil.BgLogger().Warn("kill query, this SQL might be stuck in the network stack while writing packets to the client.", zap.Uint64("connection ID", a.stmt.Ctx.GetSessionVars().ConnectionID))

server: handle kill signal during write result to connection #52882

server: handle kill signal during write result to connection #52882

Conversation

wshwsh12 commented Apr 25, 2024

What problem does this PR solve?

What changed and how does it work?

Check List

Release note

tiprow bot commented Apr 25, 2024

wshwsh12 commented Apr 25, 2024

Manual test

wshwsh12 commented Apr 25, 2024

codecov bot commented Apr 25, 2024 • edited Loading

Codecov Report

wshwsh12 commented May 16, 2024

wshwsh12 commented May 20, 2024

purelind commented Jun 7, 2024

guo-shaoge commented Jun 7, 2024

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ti-chi-bot bot commented Jun 12, 2024

ti-chi-bot bot commented Jun 12, 2024

[LGTM Timeline notifier]

codecov bot commented Apr 25, 2024 •

edited

Loading