executor: print arguments in execute statement in log files #7684

jackysp · 2018-09-13T06:08:24Z

What problem does this PR solve?

The log of the execute statement looks like

2018/09/13 13:52:31.659 session.go:1398: [info] [GENERAL_LOG] con:5 user:root@127.0.0.1 schema_ver:140 start_ts:0 sql:insert into t values (?)

We don't know what the exact argument value is.

What is changed and how it works?

Append arguments info into log files.

Check List

Tests

Unit test
Manual test
For slow query log, general log and debug log:

2018/09/13 13:55:07.553 adapter.go:371: [warning] [SLOW_QUERY] cost_time:1.002700677s  succ:true con:1 user:root@127.0.0.1 txn_start_ts:402867645723443200 database:test sql:SELECT sleep(?) [arguments: 1]
2018/09/13 13:52:31.659 session.go:1398: [info] [GENERAL_LOG] con:5 user:root@127.0.0.1 schema_ver:140 start_ts:0 sql:insert into t values (?) [arguments: 1]
2018/09/13 13:52:31.659 adapter.go:367: [debug] [QUERY] cost_time:53.653µs  succ:true con:5 user:root@127.0.0.1 txn_start_ts:402867605119696898 database:test sql:insert into t values (?) [arguments: 1]

Code changes

Has exported function/method change

Side effects

Increased code complexity

Related changes

Need to cherry-pick to the release branch

PTAL @coocood @shenli

jackysp · 2018-09-13T06:08:41Z

/run-all-tests

eurekaka · 2018-09-13T07:06:48Z

executor/prepared.go

-		execStmt.UsingVars[i] = ast.NewValueExpr(val)
+		expr := ast.NewValueExpr(val)
+		execStmt.UsingVars[i] = expr
+		str, err := expr.ToString()


CI failed because expr is nil

jackysp · 2018-09-13T07:20:21Z

/run-all-tests

winoros · 2018-09-13T09:11:42Z

types/datum.go

@@ -1501,6 +1501,8 @@ func (d *Datum) ToFloat64(sc *stmtctx.StatementContext) (float64, error) {
 // ToString gets the string representation of the datum.
 func (d *Datum) ToString() (string, error) {
 	switch d.Kind() {
+	case KindNull:


#6647
You may need to discuss with @coocood

winoros · 2018-09-13T09:12:12Z

types/datum.go

 	case KindMysqlDecimal:
 		return d.GetMysqlDecimal().String(), nil
+	case KindMysqlDuration:


Don't need this change?

I've reordered this part to make it easier to find which kind has not been converted.

jackysp · 2018-09-13T12:13:23Z

/run-all-tests

jackysp · 2018-09-14T02:45:07Z

/run-all-tests

coocood · 2018-09-14T05:18:11Z

@jackysp
Can we print those args only when needed?
This allocates memory and hurts performance.

jackysp · 2018-09-14T06:35:48Z

@coocood , it is easy to compose the arguments string only for the general log and the debug log, but it is not esay for the slow log.

jackysp · 2018-09-15T04:37:35Z

/run-all-tests

jackysp · 2018-09-15T06:35:24Z

PTAL @coocood

tiancaiamao · 2018-09-17T07:20:39Z

executor/executor.go

@@ -1060,3 +1063,104 @@ func (e *UnionExec) Close() error {
 	e.resourcePools = nil
 	return errors.Trace(e.baseExecutor.Close())
 }
+
+// ResetContextOfStmt resets the StmtContext and session variables.


It's moved or changed?

The change at Line 1149.

tiancaiamao · 2018-09-17T07:40:25Z

IMHO, move a function and change it is a bad habit. That will makes a PR harder to read.

coocood · 2018-09-17T07:47:25Z

LGTM

zimulala · 2018-09-25T07:31:36Z

session/session.go

@@ -1418,7 +1418,7 @@ func logStmt(node ast.StmtNode, vars *variable.SessionVars) {

 func logQuery(query string, vars *variable.SessionVars) {
 	if atomic.LoadUint32(&variable.ProcessGeneralLog) != 0 && !vars.InRestrictedSQL {
-		query = executor.QueryReplacer.Replace(query)
+		query = executor.QueryReplacer.Replace(query) + vars.GetExecuteArgumentsInfo()


I think put vars.GetExecuteArgumentsInfo() to line 1422 is better. Reduce the processing of strings.

zimulala · 2018-09-25T07:44:05Z

sessionctx/variable/session.go

+		} else {
+			str, err := v.ToString()
+			if err != nil {
+				terror.Log(err)


Add some details to this error log.

It has some details about it. Actually, it should not meet the error, just make the errcheck happy.

zimulala · 2018-09-25T07:59:18Z

executor/prepared.go

@@ -244,6 +238,9 @@ func (e *DeallocateExec) Next(ctx context.Context, chk *chunk.Chunk) error {
 // CompileExecutePreparedStmt compiles a session Execute command to a stmt.Statement.
 func CompileExecutePreparedStmt(ctx sessionctx.Context, ID uint32, args ...interface{}) (ast.Statement, error) {
 	execStmt := &ast.ExecuteStmt{ExecID: ID}
+	if err := ResetContextOfStmt(ctx, execStmt); err != nil {
+		return nil, err


Do we need to add the error trace?

I think no need now.

jackysp · 2018-09-25T08:29:52Z

PTAL @zimulala

jackysp · 2018-10-08T08:36:35Z

PTAL @zimulala

zimulala

LGTM

…7684)

…8053)

…ared plan cache (#7956)

…he prepared plan cache (pingcap#7956)

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

jackysp added 2 commits September 13, 2018 13:03

add arguments in execute statement

9cb794b

show in debug and slow query

2f0cceb

jackysp added type/enhancement The issue or PR belongs to an enhancement. sig/execution SIG execution labels Sep 13, 2018

eurekaka reviewed Sep 13, 2018

View reviewed changes

fix CI

3631775

winoros reviewed Sep 13, 2018

View reviewed changes

address comments

96f9a29

Merge branch 'master' into execute_args

d0bfa24

jackysp added the status/all tests passed label Sep 14, 2018

jackysp added 8 commits September 14, 2018 21:36

convert prepared params to a datum slice

f046a8d

get args when needed

7f4dbf7

print log when needed

93fd670

Merge branch 'execute_args' of github.com:jackysp/tidb into execute_args

b2c281f

fix some more

4635005

fix reset statement

617df56

prepare stmts in session var

0466a38

merge master

bab907e

tiancaiamao reviewed Sep 17, 2018

View reviewed changes

zimulala reviewed Sep 25, 2018

View reviewed changes

merge master

48f2a6f

merge master

3114517

zimulala previously approved these changes Oct 9, 2018

View reviewed changes

zimulala added the status/LGT2 Indicates that a PR has LGTM 2. label Oct 9, 2018

merge master

8faac5e

jackysp dismissed stale reviews from zimulala and ghost via 8faac5e October 9, 2018 06:26

Merge branch 'master' into execute_args

139e065

zimulala approved these changes Oct 9, 2018

View reviewed changes

jackysp merged commit ee0d4d6 into pingcap:master Oct 9, 2018

jackysp deleted the execute_args branch October 9, 2018 07:25

dbjoa mentioned this pull request Oct 19, 2018

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

Merged

jackysp added a commit to jackysp/tidb that referenced this pull request Oct 25, 2018

executor: print arguments in execute statement in log files (pingcap#…

225b3ae

…7684)

jackysp mentioned this pull request Oct 25, 2018

executor: print arguments in execute statement in log files #8052

Closed

jackysp added a commit to jackysp/tidb that referenced this pull request Oct 25, 2018

executor: print arguments in execute statement in log files (pingcap#…

be49295

…7684)

jackysp mentioned this pull request Oct 25, 2018

executor: print arguments in execute statement in log files (#7684) #8053

Merged

zz-jason pushed a commit that referenced this pull request Oct 25, 2018

executor: print arguments in execute statement in log files (#7684) (#…

7fb086f

…8053)

zz-jason pushed a commit that referenced this pull request Oct 29, 2018

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

33a0b0c

…ared plan cache (#7956)

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)

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

executor: print arguments in execute statement in log files #7684

executor: print arguments in execute statement in log files #7684

jackysp commented Sep 13, 2018

jackysp commented Sep 13, 2018

eurekaka Sep 13, 2018

jackysp commented Sep 13, 2018

winoros Sep 13, 2018

winoros Sep 13, 2018

jackysp Sep 13, 2018

jackysp commented Sep 13, 2018

jackysp commented Sep 14, 2018

coocood commented Sep 14, 2018

jackysp commented Sep 14, 2018

jackysp commented Sep 15, 2018

jackysp commented Sep 15, 2018

tiancaiamao Sep 17, 2018

jackysp Sep 17, 2018

tiancaiamao commented Sep 17, 2018

coocood commented Sep 17, 2018

zimulala Sep 25, 2018

zimulala Sep 25, 2018

jackysp Sep 25, 2018

zimulala Sep 25, 2018

jackysp Sep 25, 2018

jackysp commented Sep 25, 2018

jackysp commented Oct 8, 2018

zimulala left a comment

executor: print arguments in execute statement in log files #7684

executor: print arguments in execute statement in log files #7684

Conversation

jackysp commented Sep 13, 2018

What problem does this PR solve?

What is changed and how it works?

Check List

jackysp commented Sep 13, 2018

Choose a reason for hiding this comment

jackysp commented Sep 13, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jackysp commented Sep 13, 2018

jackysp commented Sep 14, 2018

coocood commented Sep 14, 2018

jackysp commented Sep 14, 2018

jackysp commented Sep 15, 2018

jackysp commented Sep 15, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tiancaiamao commented Sep 17, 2018

coocood commented Sep 17, 2018

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

jackysp commented Sep 25, 2018

jackysp commented Oct 8, 2018

zimulala left a comment

Choose a reason for hiding this comment