From c365d7b0e2aa5c32dc5b82b65faf3058d50f54fa Mon Sep 17 00:00:00 2001 From: winkyao Date: Mon, 16 Jul 2018 15:40:55 +0800 Subject: [PATCH 1/4] ddl: add slow operations log to add indices, make trouble shooting easier. --- config/config.go | 10 +++++++--- ddl/index.go | 20 ++++++++++++++++++++ 2 files changed, 27 insertions(+), 3 deletions(-) diff --git a/config/config.go b/config/config.go index 1ed44ee9acf77..59fac01b6454c 100644 --- a/config/config.go +++ b/config/config.go @@ -84,6 +84,9 @@ type Log struct { SlowThreshold uint `toml:"slow-threshold" json:"slow-threshold"` ExpensiveThreshold uint `toml:"expensive-threshold" json:"expensive-threshold"` QueryLogMaxLen uint `toml:"query-log-max-len" json:"query-log-max-len"` + + // DDLSlowOprThreshold is the threshold of ddl slow operations. + DDLSlowOprThreshold uint `toml:"ddl-slow-opr-threshold" json:"ddl-slow-opr-threshold"` } // Security is the security section of the config. @@ -259,9 +262,10 @@ var defaultConf = Config{ LogRotate: true, MaxSize: logutil.DefaultLogMaxSize, }, - SlowThreshold: 300, - ExpensiveThreshold: 10000, - QueryLogMaxLen: 2048, + SlowThreshold: 300, + ExpensiveThreshold: 10000, + QueryLogMaxLen: 2048, + DDLSlowOprThreshold: 300, }, Status: Status{ ReportStatus: true, diff --git a/ddl/index.go b/ddl/index.go index 97bcd38b0e439..0ae11dcc61174 100644 --- a/ddl/index.go +++ b/ddl/index.go @@ -15,10 +15,12 @@ package ddl import ( "context" + "fmt" "time" "github.com/juju/errors" "github.com/pingcap/tidb/ast" + "github.com/pingcap/tidb/config" "github.com/pingcap/tidb/infoschema" "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/meta" @@ -552,8 +554,13 @@ func (w *addIndexWorker) fetchRowColVals(txn kv.Transaction, taskRange reorgInde w.idxRecords = w.idxRecords[:0] startTime := time.Now() handleOutOfRange := false + oprStartTime := time.Now() err := iterateSnapshotRows(w.sessCtx.GetStore(), w.table, txn.StartTS(), taskRange.startHandle, func(handle int64, recordKey kv.Key, rawRow []byte) (bool, error) { + oprEndTime := time.Now() + w.logSlowOperations(oprEndTime.Sub(oprStartTime), "iterateSnapshotRows in fetchRowColVals is slow", 0) + oprStartTime = oprEndTime + if !taskRange.endIncluded { handleOutOfRange = handle >= taskRange.endHandle } else { @@ -582,11 +589,23 @@ func (w *addIndexWorker) fetchRowColVals(txn kv.Transaction, taskRange reorgInde return w.idxRecords, handleOutOfRange, errors.Trace(err) } +func (w *addIndexWorker) logSlowOperations(elapsed time.Duration, slowMsg string, threshold uint) { + if threshold == 0 { + cfg := config.GetGlobalConfig() + threshold = cfg.Log.DDLSlowOprThreshold + } + + if elapsed >= time.Duration(threshold)*time.Millisecond { + log.Infof("[ddl-reorg][SLOW-OPERATIONS] elapsed time: %v, message: %v", elapsed, slowMsg) + } +} + // backfillIndexInTxn will backfill table index in a transaction, lock corresponding rowKey, if the value of rowKey is changed, // indicate that index columns values may changed, index is not allowed to be added, so the txn will rollback and retry. // backfillIndexInTxn will add w.batchCnt indices once, default value of w.batchCnt is 128. // TODO: make w.batchCnt can be modified by system variable. func (w *addIndexWorker) backfillIndexInTxn(handleRange reorgIndexTask) (nextHandle int64, addedCount, scanCount int, errInTxn error) { + oprStartTime := time.Now() errInTxn = kv.RunInNewTxn(w.sessCtx.GetStore(), true, func(txn kv.Transaction) error { addedCount = 0 scanCount = 0 @@ -624,6 +643,7 @@ func (w *addIndexWorker) backfillIndexInTxn(handleRange reorgIndexTask) (nextHan } return nil }) + w.logSlowOperations(time.Since(oprStartTime), "backfillIndexInTxn is slow", 3000) return } From 5d4ac8d1b16f01bde31c0ac2cd4d6f94f46fcfaf Mon Sep 17 00:00:00 2001 From: winkyao Date: Mon, 16 Jul 2018 15:46:12 +0800 Subject: [PATCH 2/4] remove useless imported package --- ddl/index.go | 1 - 1 file changed, 1 deletion(-) diff --git a/ddl/index.go b/ddl/index.go index 0ae11dcc61174..04273ec0528e8 100644 --- a/ddl/index.go +++ b/ddl/index.go @@ -15,7 +15,6 @@ package ddl import ( "context" - "fmt" "time" "github.com/juju/errors" From 5910f433c7f49c18c78faec390a3b1c6cabad561 Mon Sep 17 00:00:00 2001 From: winkyao Date: Mon, 16 Jul 2018 15:58:31 +0800 Subject: [PATCH 3/4] fix ci --- config/config.toml.example | 2 ++ 1 file changed, 2 insertions(+) diff --git a/config/config.toml.example b/config/config.toml.example index a950a2c5ba53a..492eb4a78b628 100644 --- a/config/config.toml.example +++ b/config/config.toml.example @@ -63,6 +63,8 @@ expensive-threshold = 10000 # Maximum query length recorded in log. query-log-max-len = 2048 +ddl-slow-opr-threshold = 300 + # File logging. [log.file] # Log file name. From 5beb4709e67af6916f22fbc6d675cca4f2000ff1 Mon Sep 17 00:00:00 2001 From: winkyao Date: Mon, 16 Jul 2018 17:52:45 +0800 Subject: [PATCH 4/4] use http api to change threshold. --- config/config.go | 10 +++------- config/config.toml.example | 2 -- ddl/index.go | 11 +++++------ docs/tidb_http_api.md | 8 ++++++++ server/http_handler.go | 11 +++++++++++ server/http_handler_test.go | 8 ++++++++ sessionctx/variable/tidb_vars.go | 2 ++ 7 files changed, 37 insertions(+), 15 deletions(-) diff --git a/config/config.go b/config/config.go index 59fac01b6454c..1ed44ee9acf77 100644 --- a/config/config.go +++ b/config/config.go @@ -84,9 +84,6 @@ type Log struct { SlowThreshold uint `toml:"slow-threshold" json:"slow-threshold"` ExpensiveThreshold uint `toml:"expensive-threshold" json:"expensive-threshold"` QueryLogMaxLen uint `toml:"query-log-max-len" json:"query-log-max-len"` - - // DDLSlowOprThreshold is the threshold of ddl slow operations. - DDLSlowOprThreshold uint `toml:"ddl-slow-opr-threshold" json:"ddl-slow-opr-threshold"` } // Security is the security section of the config. @@ -262,10 +259,9 @@ var defaultConf = Config{ LogRotate: true, MaxSize: logutil.DefaultLogMaxSize, }, - SlowThreshold: 300, - ExpensiveThreshold: 10000, - QueryLogMaxLen: 2048, - DDLSlowOprThreshold: 300, + SlowThreshold: 300, + ExpensiveThreshold: 10000, + QueryLogMaxLen: 2048, }, Status: Status{ ReportStatus: true, diff --git a/config/config.toml.example b/config/config.toml.example index 492eb4a78b628..a950a2c5ba53a 100644 --- a/config/config.toml.example +++ b/config/config.toml.example @@ -63,8 +63,6 @@ expensive-threshold = 10000 # Maximum query length recorded in log. query-log-max-len = 2048 -ddl-slow-opr-threshold = 300 - # File logging. [log.file] # Log file name. diff --git a/ddl/index.go b/ddl/index.go index 04273ec0528e8..d70a7bb62dcaa 100644 --- a/ddl/index.go +++ b/ddl/index.go @@ -15,11 +15,11 @@ package ddl import ( "context" + "sync/atomic" "time" "github.com/juju/errors" "github.com/pingcap/tidb/ast" - "github.com/pingcap/tidb/config" "github.com/pingcap/tidb/infoschema" "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/meta" @@ -557,7 +557,7 @@ func (w *addIndexWorker) fetchRowColVals(txn kv.Transaction, taskRange reorgInde err := iterateSnapshotRows(w.sessCtx.GetStore(), w.table, txn.StartTS(), taskRange.startHandle, func(handle int64, recordKey kv.Key, rawRow []byte) (bool, error) { oprEndTime := time.Now() - w.logSlowOperations(oprEndTime.Sub(oprStartTime), "iterateSnapshotRows in fetchRowColVals is slow", 0) + w.logSlowOperations(oprEndTime.Sub(oprStartTime), "iterateSnapshotRows in fetchRowColVals", 0) oprStartTime = oprEndTime if !taskRange.endIncluded { @@ -588,10 +588,9 @@ func (w *addIndexWorker) fetchRowColVals(txn kv.Transaction, taskRange reorgInde return w.idxRecords, handleOutOfRange, errors.Trace(err) } -func (w *addIndexWorker) logSlowOperations(elapsed time.Duration, slowMsg string, threshold uint) { +func (w *addIndexWorker) logSlowOperations(elapsed time.Duration, slowMsg string, threshold uint32) { if threshold == 0 { - cfg := config.GetGlobalConfig() - threshold = cfg.Log.DDLSlowOprThreshold + threshold = atomic.LoadUint32(&variable.DDLSlowOprThreshold) } if elapsed >= time.Duration(threshold)*time.Millisecond { @@ -642,7 +641,7 @@ func (w *addIndexWorker) backfillIndexInTxn(handleRange reorgIndexTask) (nextHan } return nil }) - w.logSlowOperations(time.Since(oprStartTime), "backfillIndexInTxn is slow", 3000) + w.logSlowOperations(time.Since(oprStartTime), "backfillIndexInTxn", 3000) return } diff --git a/docs/tidb_http_api.md b/docs/tidb_http_api.md index 0e98a7b84534b..2136d7eca10aa 100644 --- a/docs/tidb_http_api.md +++ b/docs/tidb_http_api.md @@ -110,6 +110,14 @@ timezone.* curl -x POST -d "log_level=info" http://{TiDBIP}:10080/settings ``` +1. Change TiDB DDL slow log threshold + + The unit is millisecond. + + ```shell + curl -x POST -d "ddl_slow_threshold=300" http://{TiDBIP}:10080/settings + ``` + 1. Get the column value by an encoded row and some information that can be obtained from a column of the table schema information. Argument example: rowBin=base64_encoded_row_value diff --git a/server/http_handler.go b/server/http_handler.go index 26db7e4c88681..6ac958a3faf3d 100644 --- a/server/http_handler.go +++ b/server/http_handler.go @@ -550,6 +550,17 @@ func (h settingsHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { return } } + if ddlSlowThreshold := req.Form.Get("ddl_slow_threshold"); ddlSlowThreshold != "" { + threshold, err1 := strconv.Atoi(ddlSlowThreshold) + if err1 != nil { + writeError(w, err1) + return + } + if threshold > 0 { + atomic.StoreUint32(&variable.DDLSlowOprThreshold, uint32(threshold)) + } + } + } else { writeData(w, config.GetGlobalConfig()) } diff --git a/server/http_handler_test.go b/server/http_handler_test.go index bee8996d07422..3404055719e82 100644 --- a/server/http_handler_test.go +++ b/server/http_handler_test.go @@ -620,6 +620,14 @@ func (ts *HTTPHandlerTestSuite) TestPostSettings(c *C) { c.Assert(atomic.LoadUint32(&variable.ProcessGeneralLog), Equals, uint32(0)) c.Assert(log.GetLevel(), Equals, log.InfoLevel) c.Assert(config.GetGlobalConfig().Log.Level, Equals, "info") + + // test ddl_slow_threshold + form = make(url.Values) + form.Set("ddl_slow_threshold", "200") + resp, err = http.PostForm("http://127.0.0.1:10090/settings", form) + c.Assert(err, IsNil) + c.Assert(resp.StatusCode, Equals, http.StatusOK) + c.Assert(atomic.LoadUint32(&variable.DDLSlowOprThreshold), Equals, uint32(200)) } func (ts *HTTPHandlerTestSuite) TestPprof(c *C) { diff --git a/sessionctx/variable/tidb_vars.go b/sessionctx/variable/tidb_vars.go index ee366c91c8166..9b7add0752596 100644 --- a/sessionctx/variable/tidb_vars.go +++ b/sessionctx/variable/tidb_vars.go @@ -221,4 +221,6 @@ var ( ProcessGeneralLog uint32 ddlReorgWorkerCounter int32 = DefTiDBDDLReorgWorkerCount maxDDLReorgWorkerCount int32 = 128 + // DDLSlowOprThreshold is the threshold for ddl slow operations, uint is millisecond. + DDLSlowOprThreshold uint32 = 300 )