planner: fix a sporadic panic due to the PR #7684 when using the prepared plan cache #7956

dbjoa · 2018-10-19T01:23:32Z

What problem does this PR solve?

Fix the panics are occurred sporadically after merging the PR #7684 when using the prepared plan cache.

2018/10/19 09:40:58.035 conn.go:427: [error] lastCmd UPDATE usertable SET field9=? WHERE YCSB_KEY = ?, runtime error: index out of range, goroutine 531 [running]:
github.com/pingcap/tidb/server.(*clientConn).Run.func1(0xc0071d09c0, 0xc007301dff)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/server/conn.go:425 +0x10c
panic(0x11dddc0, 0x225f220)
    /usr/local/go/src/runtime/panic.go:513 +0x1b9
github.com/pingcap/tidb/expression.(*builtinGetParamStringSig).evalString(0xc0080de400, 0x0, 0x0, 0x0, 0xc28114, 0xc0080de400, 0x15493a0, 0xc0072a2b60)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/builtin_other.go:772 +0x1ec
github.com/pingcap/tidb/expression.(*ScalarFunction).EvalString(0xc00802f1d0, 0x15493a0, 0xc0072a2b60, 0x0, 0x0, 0x17, 0x0, 0x0, 0x116bf00, 0x86ede8)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/scalar_function.go:217 +0x4c
github.com/pingcap/tidb/expression.(*ScalarFunction).Eval(0xc00802f1d0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/scalar_function.go:189 +0x439
github.com/pingcap/tidb/expression.foldConstant(0x15486e0, 0xc0080c50a0, 0x1, 0xc007ec5821, 0x1)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/constant_fold.go:145 +0x107
github.com/pingcap/tidb/expression.foldConstant(0x1548860, 0xc00802f270, 0x12a78a0, 0x13a0401, 0xc00802f270)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/constant_fold.go:95 +0x5ac
github.com/pingcap/tidb/expression.FoldConstant(0x1548860, 0xc00802f270, 0x13a042d, 0x4)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/constant_fold.go:34 +0x35
github.com/pingcap/tidb/expression.BuildCastFunction(0x15493a0, 0xc0072a2b60, 0x15486e0, 0xc0080c50a0, 0xc008102000, 0x1548860, 0xc00802f220)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/builtin_cast.go:1681 +0x2ba
github.com/pingcap/tidb/expression.WrapWithCastAsReal(0x15493a0, 0xc0072a2b60, 0x15486e0, 0xc0080c50a0, 0x1548860, 0xc00802f220)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/builtin_cast.go:1709 +0x135
github.com/pingcap/tidb/expression.newBaseBuiltinFuncWithTp(0x15493a0, 0xc0072a2b60, 0xc0080a4b60, 0x2, 0x2, 0xc0080a4b00, 0xc007300b96, 0x2, 0x2, 0x0, ...)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/builtin.go:74 +0x474
github.com/pingcap/tidb/expression.(*compareFunctionClass).generateCmpSigs(0xc00021f6b0, 0x15493a0, 0xc0072a2b60, 0xc0080a4b60, 0x2, 0x2, 0xc0080a4b01, 0x2, 0x2, 0x203002, ...)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/builtin_compare.go:1169 +0xbb
github.com/pingcap/tidb/expression.(*compareFunctionClass).getFunction(0xc00021f6b0, 0x15493a0, 0xc0072a2b60, 0xc0080a4b40, 0x2, 0x2, 0x2, 0x2, 0xc00805fec0, 0x0)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/builtin_compare.go:1163 +0x178
github.com/pingcap/tidb/expression.NewFunction(0x15493a0, 0xc0072a2b60, 0x139f7f2, 0x2, 0xc00805fec0, 0xc007301040, 0x2, 0x2, 0xc0073010b8, 0x10, ...)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/expression/scalar_function.go:87 +0x210
github.com/pingcap/tidb/planner/core.(*expressionRewriter).constructBinaryOpFunction(0xc007f7b900, 0x1548620, 0xc00807ae00, 0x15486e0, 0xc0080c50a0, 0x139f7f2, 0x2, 0x2, 0x10, 0x0, ...)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:184 +0xcc7
github.com/pingcap/tidb/planner/core.(*expressionRewriter).binaryOpToExpression(0xc007f7b900, 0xc008056b60)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:914 +0xe8
github.com/pingcap/tidb/planner/core.(*expressionRewriter).Leave(0xc007f7b900, 0x151ac00, 0xc008056b60, 0x1532c80, 0xc007f73c80, 0x1)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/planner/core/expression_rewriter.go:776 +0x8ec
github.com/pingcap/tidb/ast.(*BinaryOperationExpr).Accept(0xc008056b60, 0x1516b20, 0xc007f7b900, 0x1548920, 0xc0080a22c0, 0xc0073012e0)
    /home/jsheo/dev/deps/go/src/github.com/pingcap/tidb/ast/expressions.go:227 +0x1a9
github.com/pingcap/tidb/planner/core.(*PlanBuilder).rewriteExprNode(0xc007eeb130, 0xc007f7b900, 0x1532700, 0xc008056b60, 0x13a6900, 0x9, 0x1548f20,
2018/10/19 09:40:58.035 server.go:316: [info] con:9 close connection

What is changed and how it works?

Initialize UseCache of the statement context in BuildLogicalPlan

Check List

Tests

Manual test (add detailed scripts or steps below)
Enable the prepared plan cache in the TiDB configuration

[prepared-plan-cache]
enabled = true
capacity = 100

Deploy TiDB, TiKV, and PD with standalone mode
Create YCSB schema and user

create database ycsb;
use ycsb;
drop table usertable;

CREATE TABLE usertable (
    YCSB_KEY VARCHAR(255) PRIMARY KEY,
    FIELD0 TEXT, FIELD1 TEXT,
    FIELD2 TEXT, FIELD3 TEXT,
    FIELD4 TEXT, FIELD5 TEXT,
    FIELD6 TEXT, FIELD7 TEXT,
    FIELD8 TEXT, FIELD9 TEXT
) SHARD_ROW_ID_BITS = 2;

CREATE USER 'ycsb'@'localhost' IDENTIFIED BY 'pass';
CREATE USER 'ycsb'@'%' IDENTIFIED BY 'pass';
GRANT ALL ON *.* TO 'ycsb'@'localhost';
GRANT ALL ON *.* TO 'ycsb'@'%';

Load YCSB data

./bin/ycsb load jdbc \
        -P workloads/workloada \
        -s -p status.interval=10 \
        -p db.url='jdbc:mysql://127.0.0.1:4000/ycsb?useSSL=false&useServerPrepStmts=true&rewriteBatchedStatements=true' \
        -p db.driver=com.mysql.jdbc.Driver -p db.user=ycsb -p db.passwd=pass \
        -p jdbc.autocommit=true \
        -p recordcount=1000000 \
        -p jdbc.batchupdateapi=true \
        -p db.batchsize=100 \
        -threads 16

Run YCSB workloada (i.e., select : update = 1 : 1)

./bin/ycsb run jdbc \
        -P workloads/workloada \
        -s -p status.interval=10 \
        -p db.url='jdbc:mysql://127.0.0.1:4000/ycsb?useSSL=false&useServerPrepStmts=true&rewriteBatchedStatements=false' \
        -p db.driver=com.mysql.jdbc.Driver -p db.user=ycsb -p db.passwd=pass \
        -p jdbc.autocommit=true \
        -p operationcount=100000 \
        -target 1000 \
        -threads 10

Code changes

Has exported variable/fields change

Side effects

No

Related changes

Need to cherry-pick to the release branch

sre-bot · 2018-10-19T01:23:36Z

Hi contributor, thanks for your PR.

This patch needs to be approved by someone of admins. They should reply with "/ok-to-test" to accept this PR for running test automatically.

dbjoa · 2018-10-19T01:25:01Z

PTAL @jackysp

dbjoa · 2018-10-19T01:26:31Z

/run-all-tests

zz-jason · 2018-10-19T02:04:01Z

planner/core/optimizer.go

@@ -66,6 +66,7 @@ type logicalOptRule interface {
 func BuildLogicalPlan(ctx sessionctx.Context, node ast.Node, is infoschema.InfoSchema) (Plan, error) {
 	ctx.GetSessionVars().PlanID = 0
 	ctx.GetSessionVars().PlanColumnID = 0
+	ctx.GetSessionVars().StmtCtx.UseCache = false


StmtCtx.UseCache is set in: https://github.com/pingcap/tidb/blob/master/executor/prepared.go#L155

Then the function BuildLogicalPlan() is called. Maybe it's better to set StmtCtx.UseCache to false before the function BuildLogicalPlan() call: https://github.com/pingcap/tidb/blob/master/executor/prepared.go#L162

If we can ensure calling BuildLogicalPlan() at prepared.go#L162 only, setting the variable at the location as you said is good. Otherwise, setting the variable in BuildLogicalPlan() might be a good choice in order to prevent from a potential risk because StmtCtx.UseCache should be false in the call paths of BuildLogicalPlan().

Yes, we can ensure. Function BuildLogicalPlan() is only used in the test code and the prepare statements:

You can get the similar result by:

find . -name "*.go" | xargs grep --color -n "\<BuildLogicalPlan\>"

dbjoa · 2018-10-19T05:21:33Z

@zz-jason Thank you for the comment. I've updated the PR.

dbjoa · 2018-10-19T05:23:22Z

/run-all-tests

jackysp · 2018-10-19T07:56:33Z

I think we should add the following lines after

tidb/session/session.go

Line 846 in b7a8f91

s.PrepareTxnCtx(ctx)

	stmt := &ast.PrepareStmt{
		SQLText: sql,
	}
	if err = executor.ResetContextOfStmt(s, stmt); err != nil {
		return
	}

@dbjoa
I have not tested it. Could you please provide a simple case for this bug?

dbjoa · 2018-10-19T15:31:31Z

@jackysp
Unfortunately, I couldn't find a simple case to reproduce the bug. Please use YCSB as I mentioned above.

lysu · 2018-10-26T03:25:04Z

/run-all-tests

lysu · 2018-10-26T03:26:02Z

@dbjoa I will add a integeration test in internal test repo to cover this question.

lysu · 2018-10-29T09:14:46Z

/run-all-tests tidb-test=pr/637

lysu · 2018-10-29T09:20:02Z

It's a simple test case:

	public void testPrepareCacheIssue8065() throws Exception {
 		createTable("test_prepare1", "(a int)");
 		createTable("test_prepare2", "(a int, b int)");
 		try {
 			try (PreparedStatement pStmt = this.conn.prepareStatement("select * from test_prepare1 where a = ?")) {
 				pStmt.setInt(1, 1);
 				this.rs = pStmt.executeQuery();
 				while(this.rs.next()) {}
 			}
 			try (PreparedStatement pStmt = this.conn.prepareStatement("select * from test_prepare2 where a = ? and b = ?")) {
 				pStmt.setInt(1, 1);
 				pStmt.setInt(2, 2);
 				this.rs = pStmt.executeQuery();
 				while(this.rs.next()) {}
 			}
 		} finally {
 			if (this.rs != null) {
 				this.rs.close();
 			}
 			this.rs = null;
 		}
 	}

and 9643cde make plan-cache enable in CI env

lysu · 2018-10-29T09:21:54Z

@dbjoa how about @jackysp 's advise, I think call reset ctx if more safe too~? 😆

jackysp · 2018-10-29T09:29:00Z

@dbjoa I still prefer that we should reset the context of the statement, due to it may contain some other bugs if the context was not reset clearly.
I think you could consider @lysu ' pr #8067 or my suggestion.

…pared plan cache main: default enable prepare plan cache in test env

dbjoa · 2018-10-29T10:22:51Z

@jackysp, @lysu Thank you for the suggestion. I've updated the PR.

jackysp

LGTM

jackysp · 2018-10-29T10:48:10Z

PTAL @lysu

zz-jason

LGTM

zz-jason · 2018-10-29T11:05:50Z

/run-all-tests

…he prepared plan cache (pingcap#7956)

…ared plan cache (#7956) (#8826)

zz-jason added contribution This PR is from a community contributor. sig/planner SIG: Planner status/all tests passed labels Oct 19, 2018

zz-jason reviewed Oct 19, 2018

View reviewed changes

eurekaka mentioned this pull request Oct 24, 2018

[WIP] plan: skip plan building for execute #8043

Closed

dbjoa mentioned this pull request Oct 25, 2018

executor: reset stmtCtx at beginning of prepare #8067

Closed

planner: fix the potential panic due to the PR #7684 when using a pre…

7c69134

…pared plan cache main: default enable prepare plan cache in test env

jackysp reviewed Oct 29, 2018

View reviewed changes

zz-jason approved these changes Oct 29, 2018

View reviewed changes

zz-jason merged commit 33a0b0c into pingcap:master Oct 29, 2018

zz-jason added the status/LGT2 Indicates that a PR has LGTM 2. label Oct 29, 2018

XuHuaiyu mentioned this pull request Dec 26, 2018

executor: add test case for execute prepare_stmt using binary protocol #8825

Merged

XuHuaiyu pushed a commit to XuHuaiyu/tidb that referenced this pull request Dec 26, 2018

planner: fix a sporadic panic due to the PR pingcap#7684 when using t…

d85ad88

…he prepared plan cache (pingcap#7956)

XuHuaiyu mentioned this pull request Dec 26, 2018

planner: fix a sporadic panic due to the PR #7684 when using the prepared plan cache (#7956) #8826

Merged

zimulala pushed a commit that referenced this pull request Dec 26, 2018

planner: fix a sporadic panic due to the PR #7684 when using the prep…

8b970d7

…ared plan cache (#7956) (#8826)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

planner: fix a sporadic panic due to the PR #7684 when using the prepared plan cache #7956

planner: fix a sporadic panic due to the PR #7684 when using the prepared plan cache #7956

dbjoa commented Oct 19, 2018 •

edited by lysu

Loading

sre-bot commented Oct 19, 2018

dbjoa commented Oct 19, 2018

dbjoa commented Oct 19, 2018

zz-jason Oct 19, 2018

dbjoa Oct 19, 2018

zz-jason Oct 19, 2018

zz-jason Oct 19, 2018

dbjoa commented Oct 19, 2018

dbjoa commented Oct 19, 2018

jackysp commented Oct 19, 2018

dbjoa commented Oct 19, 2018

lysu commented Oct 26, 2018

lysu commented Oct 26, 2018

lysu commented Oct 29, 2018

lysu commented Oct 29, 2018

lysu commented Oct 29, 2018

jackysp commented Oct 29, 2018

dbjoa commented Oct 29, 2018

jackysp left a comment

jackysp commented Oct 29, 2018

zz-jason left a comment

zz-jason commented Oct 29, 2018

planner: fix a sporadic panic due to the PR #7684 when using the prepared plan cache #7956

planner: fix a sporadic panic due to the PR #7684 when using the prepared plan cache #7956

Conversation

dbjoa commented Oct 19, 2018 • edited by lysu Loading

What problem does this PR solve?

What is changed and how it works?

Check List

sre-bot commented Oct 19, 2018

dbjoa commented Oct 19, 2018

dbjoa commented Oct 19, 2018

zz-jason Oct 19, 2018

Choose a reason for hiding this comment

dbjoa Oct 19, 2018

Choose a reason for hiding this comment

zz-jason Oct 19, 2018

Choose a reason for hiding this comment

zz-jason Oct 19, 2018

Choose a reason for hiding this comment

dbjoa commented Oct 19, 2018

dbjoa commented Oct 19, 2018

jackysp commented Oct 19, 2018

dbjoa commented Oct 19, 2018

lysu commented Oct 26, 2018

lysu commented Oct 26, 2018

lysu commented Oct 29, 2018

lysu commented Oct 29, 2018

lysu commented Oct 29, 2018

jackysp commented Oct 29, 2018

dbjoa commented Oct 29, 2018

jackysp left a comment

Choose a reason for hiding this comment

jackysp commented Oct 29, 2018

zz-jason left a comment

Choose a reason for hiding this comment

zz-jason commented Oct 29, 2018

dbjoa commented Oct 19, 2018 •

edited by lysu

Loading