Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

*: add last ru consumption for tidb_last_query_info #49769

Merged
merged 4 commits into from
Jan 3, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
35 changes: 34 additions & 1 deletion pkg/executor/adapter.go
Original file line number Diff line number Diff line change
Expand Up @@ -49,6 +49,7 @@ import (
plannercore "github.com/pingcap/tidb/pkg/planner/core"
"github.com/pingcap/tidb/pkg/plugin"
"github.com/pingcap/tidb/pkg/sessionctx"
"github.com/pingcap/tidb/pkg/sessionctx/sessionstates"
"github.com/pingcap/tidb/pkg/sessionctx/stmtctx"
"github.com/pingcap/tidb/pkg/sessionctx/variable"
"github.com/pingcap/tidb/pkg/sessiontxn"
Expand Down Expand Up @@ -1404,7 +1405,7 @@ func (a *ExecStmt) FinishExecuteStmt(txnTS uint64, err error, hasMoreResults boo
}
}
sessVars.PrevStmt = FormatSQL(a.GetTextToLog(false))

a.recordLastQueryInfo(err)
a.observePhaseDurations(sessVars.InRestrictedSQL, execDetail.CommitDetail)
executeDuration := time.Since(sessVars.StartTime) - sessVars.DurationCompile
if sessVars.InRestrictedSQL {
Expand Down Expand Up @@ -1449,6 +1450,38 @@ func (a *ExecStmt) FinishExecuteStmt(txnTS uint64, err error, hasMoreResults boo
}
}

func (a *ExecStmt) recordLastQueryInfo(err error) {
sessVars := a.Ctx.GetSessionVars()
// Record diagnostic information for DML statements
recordLastQuery := false
switch typ := a.StmtNode.(type) {
case *ast.ShowStmt:
recordLastQuery = typ.Tp != ast.ShowSessionStates
case *ast.ExecuteStmt, ast.DMLNode:
recordLastQuery = true
}
if recordLastQuery {
var lastRUConsumption float64
if ruDetailRaw := a.GoCtx.Value(util.RUDetailsCtxKey); ruDetailRaw != nil {
ruDetail := ruDetailRaw.(*util.RUDetails)
lastRUConsumption = ruDetail.RRU() + ruDetail.WRU()
}
failpoint.Inject("mockRUConsumption", func(_ failpoint.Value) {
lastRUConsumption = float64(len(sessVars.StmtCtx.OriginalSQL))
})
// Keep the previous queryInfo for `show session_states` because the statement needs to encode it.
sessVars.LastQueryInfo = sessionstates.QueryInfo{
Copy link
Contributor

@glorv glorv Jan 2, 2024

Choose a reason for hiding this comment

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

Another question: is it better that when the statement type is not exec or dml, the lastQueryInfo/LastRUConsumption should be reset instead of just keep unchanged?

Copy link
Member Author

Choose a reason for hiding this comment

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

I think we can keep unchanged.

TxnScope: sessVars.CheckAndGetTxnScope(),
StartTS: sessVars.TxnCtx.StartTS,
ForUpdateTS: sessVars.TxnCtx.GetForUpdateTS(),
LastRUConsumption: lastRUConsumption,
}
if err != nil {
sessVars.LastQueryInfo.ErrMsg = err.Error()
}
}
}

func (a *ExecStmt) checkPlanReplayerCapture(txnTS uint64) {
if kv.GetInternalSourceType(a.GoCtx) == kv.InternalTxnStats {
return
Expand Down
17 changes: 0 additions & 17 deletions pkg/session/session.go
Original file line number Diff line number Diff line change
Expand Up @@ -2351,23 +2351,6 @@ func runStmt(ctx context.Context, se *session, s sqlexec.Statement) (rs sqlexec.

sessVars := se.sessionVars

// Record diagnostic information for DML statements
Copy link
Contributor

Choose a reason for hiding this comment

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

This seems to be a behavior change. Before this PR, LastQueryInfo is record even if this function returns error, but after this change, if runStmt returns error and the returned RecordSet is nil, FinishExecuteStmt won't be called so LastQueryInfo won't be recorded either.

Copy link
Member Author

@nolouch nolouch Dec 26, 2023

Choose a reason for hiding this comment

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

Most errors occur during the execution stage, before it records the error of the compile+optimize stage. I think it's reasonable move to here. and you can see the manual test on the issue text. I kill the pd, it can record pd timeout error during execution.

Copy link
Member Author

Choose a reason for hiding this comment

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

cc @djshow832 is it ok to move to FinishExecuteStmt?

if stmt, ok := s.(*executor.ExecStmt).StmtNode.(ast.DMLNode); ok {
// Keep the previous queryInfo for `show session_states` because the statement needs to encode it.
if showStmt, ok := stmt.(*ast.ShowStmt); !ok || showStmt.Tp != ast.ShowSessionStates {
defer func() {
sessVars.LastQueryInfo = sessionstates.QueryInfo{
TxnScope: sessVars.CheckAndGetTxnScope(),
StartTS: sessVars.TxnCtx.StartTS,
ForUpdateTS: sessVars.TxnCtx.GetForUpdateTS(),
}
if err != nil {
sessVars.LastQueryInfo.ErrMsg = err.Error()
}
}()
}
}

// Save origTxnCtx here to avoid it reset in the transaction retry.
origTxnCtx := sessVars.TxnCtx
err = se.checkTxnAborted(s)
Expand Down
2 changes: 1 addition & 1 deletion pkg/session/test/variable/BUILD.bazel
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@ go_test(
"variable_test.go",
],
flaky = True,
shard_count = 9,
shard_count = 10,
deps = [
"//pkg/config",
"//pkg/kv",
Expand Down
22 changes: 22 additions & 0 deletions pkg/session/test/variable/variable_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ package variable
import (
"context"
"fmt"
"strings"
"testing"

"github.com/pingcap/failpoint"
Expand Down Expand Up @@ -362,3 +363,24 @@ func TestIsolationRead(t *testing.T) {
require.True(t, hasTiFlash)
require.False(t, hasTiKV)
}

func TestLastQueryInfo(t *testing.T) {
require.NoError(t, failpoint.Enable("github.com/pingcap/tidb/pkg/executor/mockRUConsumption", `return()`))
defer func() {
require.NoError(t, failpoint.Disable("github.com/pingcap/tidb/pkg/executor/mockRUConsumption"))
}()
store := testkit.CreateMockStore(t)
tk := testkit.NewTestKit(t, store)
tk.MustExec("use test")
tk.MustExec("drop table if exists t")
tk.MustExec("create table t(a int, b int, index idx(a))")
tk.MustExec(`prepare stmt1 from 'select * from t'`)
tk.MustExec("execute stmt1")
checkMatch := func(actual []string, expected []interface{}) bool {
return strings.Contains(actual[0], expected[0].(string))
}
tk.MustQuery("select @@tidb_last_query_info;").CheckWithFunc(testkit.Rows(`"last_ru_consumption":15`), checkMatch)
tk.MustExec("select a from t where a = 1")
tk.MustQuery("select @@tidb_last_query_info;").CheckWithFunc(testkit.Rows(`"last_ru_consumption":27`), checkMatch)
tk.MustQuery("select @@tidb_last_query_info;").CheckWithFunc(testkit.Rows(`"last_ru_consumption":30`), checkMatch)
}
9 changes: 5 additions & 4 deletions pkg/sessionctx/sessionstates/session_states.go
Original file line number Diff line number Diff line change
Expand Up @@ -49,10 +49,11 @@ type PreparedStmtInfo struct {

// QueryInfo represents the information of last executed query. It's used to expose information for test purpose.
type QueryInfo struct {
TxnScope string `json:"txn_scope"`
StartTS uint64 `json:"start_ts"`
ForUpdateTS uint64 `json:"for_update_ts"`
ErrMsg string `json:"error,omitempty"`
TxnScope string `json:"txn_scope"`
StartTS uint64 `json:"start_ts"`
ForUpdateTS uint64 `json:"for_update_ts"`
LastRUConsumption float64 `json:"last_ru_consumption"`
ErrMsg string `json:"error,omitempty"`
}

// LastDDLInfo represents the information of last DDL. It's used to expose information for test purpose.
Expand Down