From 9980e9100c0c8eb0bfdaaca901be1128a109e89e Mon Sep 17 00:00:00 2001 From: djshow832 <873581766@qq.com> Date: Mon, 9 Dec 2019 16:11:49 +0800 Subject: [PATCH] infoschema, util: add table `events_statements_summary_by_digest_history` (#13813) --- config/config.go | 20 +- config/config.toml.example | 9 + config/config_test.go | 6 + domain/global_vars_cache.go | 14 +- executor/set.go | 2 + infoschema/perfschema/const.go | 68 ++- infoschema/perfschema/tables.go | 19 +- infoschema/perfschema/tables_test.go | 45 ++ session/session.go | 1 + sessionctx/variable/sysvar.go | 5 +- sessionctx/variable/tidb_vars.go | 6 +- sessionctx/variable/varsutil.go | 5 + sessionctx/variable/varsutil_test.go | 7 + util/stmtsummary/statement_summary.go | 564 +++++++++++++-------- util/stmtsummary/statement_summary_test.go | 463 ++++++++++------- 15 files changed, 829 insertions(+), 405 deletions(-) diff --git a/config/config.go b/config/config.go index acfb545dd45d6..55cddea622b94 100644 --- a/config/config.go +++ b/config/config.go @@ -323,10 +323,16 @@ type PessimisticTxn struct { // StmtSummary is the config for statement summary. type StmtSummary struct { + // Enable statement summary or not. + Enable bool `toml:"enable" json:"enable"` // The maximum number of statements kept in memory. MaxStmtCount uint `toml:"max-stmt-count" json:"max-stmt-count"` // The maximum length of displayed normalized SQL and sample SQL. MaxSQLLength uint `toml:"max-sql-length" json:"max-sql-length"` + // The refresh interval of statement summary. + RefreshInterval int `toml:"refresh-interval" json:"refresh-interval"` + // The maximum history size of statement summary. + HistorySize int `toml:"history-size" json:"history-size"` } var defaultConf = Config{ @@ -428,8 +434,11 @@ var defaultConf = Config{ MaxRetryCount: 256, }, StmtSummary: StmtSummary{ - MaxStmtCount: 100, - MaxSQLLength: 4096, + Enable: false, + MaxStmtCount: 100, + MaxSQLLength: 4096, + RefreshInterval: 1800, + HistorySize: 24, }, } @@ -603,6 +612,13 @@ func (c *Config) Valid() error { if c.TiKVClient.MaxTxnTimeUse == 0 { return fmt.Errorf("max-txn-time-use should be greater than 0") } + + if c.StmtSummary.HistorySize < 0 { + return fmt.Errorf("history-size in [stmt-summary] should be greater than or equal to 0") + } + if c.StmtSummary.RefreshInterval <= 0 { + return fmt.Errorf("refresh-interval in [stmt-summary] should be greater than 0") + } return nil } diff --git a/config/config.toml.example b/config/config.toml.example index 7154ff144570b..b3b9d5dc9dcc9 100644 --- a/config/config.toml.example +++ b/config/config.toml.example @@ -339,8 +339,17 @@ enable = true max-retry-count = 256 [stmt-summary] +# enable statement summary. +enable = false + # max number of statements kept in memory. max-stmt-count = 100 # max length of displayed normalized sql and sample sql. max-sql-length = 4096 + +# the refresh interval of statement summary, it's counted in seconds. +refresh-interval = 1800 + +# the maximum history size of statement summary. +history-size = 24 diff --git a/config/config_test.go b/config/config_test.go index df2f6785f37d8..7d3efe4520452 100644 --- a/config/config_test.go +++ b/config/config_test.go @@ -76,8 +76,11 @@ max-batch-size=128 region-cache-ttl=6000 store-limit=0 [stmt-summary] +enable=true max-stmt-count=1000 max-sql-length=1024 +refresh-interval=100 +history-size=100 `) c.Assert(err, IsNil) @@ -104,8 +107,11 @@ max-sql-length=1024 c.Assert(conf.TiKVClient.StoreLimit, Equals, int64(0)) c.Assert(conf.TokenLimit, Equals, uint(1000)) c.Assert(conf.SplitRegionMaxNum, Equals, uint64(10000)) + c.Assert(conf.StmtSummary.Enable, Equals, true) c.Assert(conf.StmtSummary.MaxStmtCount, Equals, uint(1000)) c.Assert(conf.StmtSummary.MaxSQLLength, Equals, uint(1024)) + c.Assert(conf.StmtSummary.RefreshInterval, Equals, 100) + c.Assert(conf.StmtSummary.HistorySize, Equals, 100) c.Assert(f.Close(), IsNil) c.Assert(os.Remove(configFile), IsNil) diff --git a/domain/global_vars_cache.go b/domain/global_vars_cache.go index 1715e339c5be3..e03fe87fba998 100644 --- a/domain/global_vars_cache.go +++ b/domain/global_vars_cache.go @@ -70,19 +70,17 @@ func (gvc *GlobalVariableCache) Disable() { // checkEnableServerGlobalVar processes variables that acts in server and global level. func checkEnableServerGlobalVar(rows []chunk.Row) { for _, row := range rows { + sVal := "" + if !row.IsNull(1) { + sVal = row.GetString(1) + } switch row.GetString(0) { case variable.TiDBEnableStmtSummary: - sVal := "" - if !row.IsNull(1) { - sVal = row.GetString(1) - } stmtsummary.StmtSummaryByDigestMap.SetEnabled(sVal, false) case variable.TiDBStmtSummaryRefreshInterval: - sVal := "" - if !row.IsNull(1) { - sVal = row.GetString(1) - } stmtsummary.StmtSummaryByDigestMap.SetRefreshInterval(sVal, false) + case variable.TiDBStmtSummaryHistorySize: + stmtsummary.StmtSummaryByDigestMap.SetHistorySize(sVal, false) } } } diff --git a/executor/set.go b/executor/set.go index 0f19b67fb4993..2a980262d52a8 100644 --- a/executor/set.go +++ b/executor/set.go @@ -202,6 +202,8 @@ func (e *SetExecutor) setSysVariable(name string, v *expression.VarAssignment) e stmtsummary.StmtSummaryByDigestMap.SetEnabled(valStr, !v.IsGlobal) case variable.TiDBStmtSummaryRefreshInterval: stmtsummary.StmtSummaryByDigestMap.SetRefreshInterval(valStr, !v.IsGlobal) + case variable.TiDBStmtSummaryHistorySize: + stmtsummary.StmtSummaryByDigestMap.SetHistorySize(valStr, !v.IsGlobal) } return nil diff --git a/infoschema/perfschema/const.go b/infoschema/perfschema/const.go index 47957720608bc..5174fd15a2927 100644 --- a/infoschema/perfschema/const.go +++ b/infoschema/perfschema/const.go @@ -37,6 +37,7 @@ var perfSchemaTables = []string{ tableStagesHistory, tableStagesHistoryLong, tableEventsStatementsSummaryByDigest, + tableEventsStatementsSummaryByDigestHistory, tableTiDBProfileCPU, tableTiDBProfileMemory, tableTiDBProfileMutex, @@ -444,7 +445,72 @@ const tableEventsStatementsSummaryByDigest = "CREATE TABLE if not exists events_ "LAST_SEEN TIMESTAMP(6) NOT NULL," + "QUERY_SAMPLE_TEXT LONGTEXT DEFAULT NULL);" -// tableTiDBProfileCPU contains the columns name definitions for table events_cpu_profile_graph +// tableEventsStatementsSummaryByDigestHistory contains the column name definitions for table +// events_statements_summary_by_digest_history. +const tableEventsStatementsSummaryByDigestHistory = "CREATE TABLE if not exists events_statements_summary_by_digest_history (" + + "SUMMARY_BEGIN_TIME TIMESTAMP(6) NOT NULL," + + "STMT_TYPE VARCHAR(64) NOT NULL," + + "SCHEMA_NAME VARCHAR(64) DEFAULT NULL," + + "DIGEST VARCHAR(64) NOT NULL," + + "DIGEST_TEXT LONGTEXT NOT NULL," + + "TABLE_NAMES TEXT DEFAULT NULL," + + "INDEX_NAMES TEXT DEFAULT NULL," + + "SAMPLE_USER VARCHAR(64) DEFAULT NULL," + + "EXEC_COUNT BIGINT(20) UNSIGNED NOT NULL," + + "SUM_LATENCY BIGINT(20) UNSIGNED NOT NULL," + + "MAX_LATENCY BIGINT(20) UNSIGNED NOT NULL," + + "MIN_LATENCY BIGINT(20) UNSIGNED NOT NULL," + + "AVG_LATENCY BIGINT(20) UNSIGNED NOT NULL," + + "AVG_PARSE_LATENCY BIGINT(20) UNSIGNED NOT NULL," + + "MAX_PARSE_LATENCY BIGINT(20) UNSIGNED NOT NULL," + + "AVG_COMPILE_LATENCY BIGINT(20) UNSIGNED NOT NULL," + + "MAX_COMPILE_LATENCY BIGINT(20) UNSIGNED NOT NULL," + + "COP_TASK_NUM BIGINT(20) UNSIGNED NOT NULL," + + "AVG_COP_PROCESS_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_COP_PROCESS_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_COP_PROCESS_ADDRESS VARCHAR(256) DEFAULT NULL," + + "AVG_COP_WAIT_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_COP_WAIT_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_COP_WAIT_ADDRESS VARCHAR(256) DEFAULT NULL," + + "AVG_PROCESS_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_PROCESS_TIME BIGINT(20) UNSIGNED NOT NULL," + + "AVG_WAIT_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_WAIT_TIME BIGINT(20) UNSIGNED NOT NULL," + + "AVG_BACKOFF_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_BACKOFF_TIME BIGINT(20) UNSIGNED NOT NULL," + + "AVG_TOTAL_KEYS BIGINT(20) UNSIGNED NOT NULL," + + "MAX_TOTAL_KEYS BIGINT(20) UNSIGNED NOT NULL," + + "AVG_PROCESSED_KEYS BIGINT(20) UNSIGNED NOT NULL," + + "MAX_PROCESSED_KEYS BIGINT(20) UNSIGNED NOT NULL," + + "AVG_PREWRITE_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_PREWRITE_TIME BIGINT(20) UNSIGNED NOT NULL," + + "AVG_COMMIT_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_COMMIT_TIME BIGINT(20) UNSIGNED NOT NULL," + + "AVG_GET_COMMIT_TS_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_GET_COMMIT_TS_TIME BIGINT(20) UNSIGNED NOT NULL," + + "AVG_COMMIT_BACKOFF_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_COMMIT_BACKOFF_TIME BIGINT(20) UNSIGNED NOT NULL," + + "AVG_RESOLVE_LOCK_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_RESOLVE_LOCK_TIME BIGINT(20) UNSIGNED NOT NULL," + + "AVG_LOCAL_LATCH_WAIT_TIME BIGINT(20) UNSIGNED NOT NULL," + + "MAX_LOCAL_LATCH_WAIT_TIME BIGINT(20) UNSIGNED NOT NULL," + + "AVG_WRITE_KEYS DOUBLE UNSIGNED NOT NULL," + + "MAX_WRITE_KEYS BIGINT(20) UNSIGNED NOT NULL," + + "AVG_WRITE_SIZE DOUBLE NOT NULL," + + "MAX_WRITE_SIZE BIGINT(20) UNSIGNED NOT NULL," + + "AVG_PREWRITE_REGIONS DOUBLE NOT NULL," + + "MAX_PREWRITE_REGIONS INT(11) UNSIGNED NOT NULL," + + "AVG_TXN_RETRY DOUBLE NOT NULL," + + "MAX_TXN_RETRY INT(11) UNSIGNED NOT NULL," + + "BACKOFF_TYPES VARCHAR(1024) DEFAULT NULL," + + "AVG_MEM BIGINT(20) UNSIGNED NOT NULL," + + "MAX_MEM BIGINT(20) UNSIGNED NOT NULL," + + "AVG_AFFECTED_ROWS DOUBLE UNSIGNED NOT NULL," + + "FIRST_SEEN TIMESTAMP(6) NOT NULL," + + "LAST_SEEN TIMESTAMP(6) NOT NULL," + + "QUERY_SAMPLE_TEXT LONGTEXT DEFAULT NULL);" + +// tableTiDBProfileCPU contains the columns name definitions for table tidb_profile_cpu const tableTiDBProfileCPU = "CREATE TABLE IF NOT EXISTS " + tableNameTiDBProfileCPU + " (" + "FUNCTION VARCHAR(512) NOT NULL," + "PERCENT_ABS VARCHAR(8) NOT NULL," + diff --git a/infoschema/perfschema/tables.go b/infoschema/perfschema/tables.go index aa3229f731365..62970019bb7e8 100644 --- a/infoschema/perfschema/tables.go +++ b/infoschema/perfschema/tables.go @@ -26,13 +26,14 @@ import ( ) const ( - tableNameEventsStatementsSummaryByDigest = "events_statements_summary_by_digest" - tableNameTiDBProfileCPU = "tidb_profile_cpu" - tableNameTiDBProfileMemory = "tidb_profile_memory" - tableNameTiDBProfileMutex = "tidb_profile_mutex" - tableNameTiDBProfileAllocs = "tidb_profile_allocs" - tableNameTiDBProfileBlock = "tidb_profile_block" - tableNameTiDBProfileGoroutines = "tidb_profile_goroutines" + tableNameEventsStatementsSummaryByDigest = "events_statements_summary_by_digest" + tableNameEventsStatementsSummaryByDigestHistory = "events_statements_summary_by_digest_history" + tableNameTiDBProfileCPU = "tidb_profile_cpu" + tableNameTiDBProfileMemory = "tidb_profile_memory" + tableNameTiDBProfileMutex = "tidb_profile_mutex" + tableNameTiDBProfileAllocs = "tidb_profile_allocs" + tableNameTiDBProfileBlock = "tidb_profile_block" + tableNameTiDBProfileGoroutines = "tidb_profile_goroutines" ) // perfSchemaTable stands for the fake table all its data is in the memory. @@ -96,7 +97,9 @@ func (vt *perfSchemaTable) Meta() *model.TableInfo { func (vt *perfSchemaTable) getRows(ctx sessionctx.Context, cols []*table.Column) (fullRows [][]types.Datum, err error) { switch vt.meta.Name.O { case tableNameEventsStatementsSummaryByDigest: - fullRows = stmtsummary.StmtSummaryByDigestMap.ToDatum() + fullRows = stmtsummary.StmtSummaryByDigestMap.ToCurrentDatum() + case tableNameEventsStatementsSummaryByDigestHistory: + fullRows = stmtsummary.StmtSummaryByDigestMap.ToHistoryDatum() case tableNameTiDBProfileCPU: fullRows, err = (&profile.Collector{}).ProfileGraph("cpu") case tableNameTiDBProfileMemory: diff --git a/infoschema/perfschema/tables_test.go b/infoschema/perfschema/tables_test.go index c92f80682ebfd..69aad67bdb7c1 100644 --- a/infoschema/perfschema/tables_test.go +++ b/infoschema/perfschema/tables_test.go @@ -188,3 +188,48 @@ func (s *testTableSuite) TestStmtSummaryTable(c *C) { from performance_schema.events_statements_summary_by_digest`, ).Check(testkit.Rows()) } + +// Test events_statements_summary_by_digest_history. +func (s *testTableSuite) TestStmtSummaryHistoryTable(c *C) { + tk := testkit.NewTestKitWithInit(c, s.store) + + tk.MustExec("drop table if exists t") + tk.MustExec("create table t(a int, b varchar(10), key k(a))") + + // Statement summary is disabled by default. + tk.MustQuery("select @@global.tidb_enable_stmt_summary").Check(testkit.Rows("0")) + tk.MustExec("insert into t values(1, 'a')") + tk.MustQuery("select * from performance_schema.events_statements_summary_by_digest_history").Check(testkit.Rows()) + + tk.MustExec("set global tidb_enable_stmt_summary = 1") + tk.MustQuery("select @@global.tidb_enable_stmt_summary").Check(testkit.Rows("1")) + defer tk.MustExec("set global tidb_enable_stmt_summary = false") + + // Invalidate the cache manually so that tidb_enable_stmt_summary works immediately. + s.dom.GetGlobalVarsCache().Disable() + // Disable refreshing summary. + tk.MustExec("set global tidb_stmt_summary_refresh_interval = 999999999") + tk.MustQuery("select @@global.tidb_stmt_summary_refresh_interval").Check(testkit.Rows("999999999")) + + // Create a new session to test. + tk = testkit.NewTestKitWithInit(c, s.store) + + // Test INSERT + tk.MustExec("insert into t values(1, 'a')") + tk.MustExec("insert into t values(2, 'b')") + tk.MustExec("insert into t VALUES(3, 'c')") + tk.MustExec("/**/insert into t values(4, 'd')") + tk.MustQuery(`select stmt_type, schema_name, table_names, index_names, exec_count, cop_task_num, avg_total_keys, + max_total_keys, avg_processed_keys, max_processed_keys, avg_write_keys, max_write_keys, avg_prewrite_regions, + max_prewrite_regions, avg_affected_rows, query_sample_text + from performance_schema.events_statements_summary_by_digest_history + where digest_text like 'insert into t%'`, + ).Check(testkit.Rows("insert test test.t 4 0 0 0 0 0 2 2 1 1 1 /**/insert into t values(4, 'd')")) + + tk.MustExec("set global tidb_stmt_summary_history_size = 0") + tk.MustQuery(`select stmt_type, schema_name, table_names, index_names, exec_count, cop_task_num, avg_total_keys, + max_total_keys, avg_processed_keys, max_processed_keys, avg_write_keys, max_write_keys, avg_prewrite_regions, + max_prewrite_regions, avg_affected_rows, query_sample_text + from performance_schema.events_statements_summary_by_digest_history`, + ).Check(testkit.Rows()) +} diff --git a/session/session.go b/session/session.go index 8269df52e6968..e95519a53e6c7 100644 --- a/session/session.go +++ b/session/session.go @@ -1721,6 +1721,7 @@ var builtinGlobalVariable = []string{ variable.TiDBTxnMode, variable.TiDBEnableStmtSummary, variable.TiDBStmtSummaryRefreshInterval, + variable.TiDBStmtSummaryHistorySize, variable.TiDBMaxDeltaSchemaCount, variable.TiDBStoreLimit, } diff --git a/sessionctx/variable/sysvar.go b/sessionctx/variable/sysvar.go index e796fca262a11..3c69319d1b87c 100644 --- a/sessionctx/variable/sysvar.go +++ b/sessionctx/variable/sysvar.go @@ -714,8 +714,9 @@ var defaultSysVars = []*SysVar{ {ScopeSession, TiDBLowResolutionTSO, "0"}, {ScopeSession, TiDBExpensiveQueryTimeThreshold, strconv.Itoa(DefTiDBExpensiveQueryTimeThreshold)}, {ScopeSession, TiDBAllowRemoveAutoInc, BoolToIntStr(DefTiDBAllowRemoveAutoInc)}, - {ScopeGlobal | ScopeSession, TiDBEnableStmtSummary, "0"}, - {ScopeGlobal | ScopeSession, TiDBStmtSummaryRefreshInterval, strconv.Itoa(DefTiDBStmtSummaryRefreshInterval)}, + {ScopeGlobal | ScopeSession, TiDBEnableStmtSummary, BoolToIntStr(config.GetGlobalConfig().StmtSummary.Enable)}, + {ScopeGlobal | ScopeSession, TiDBStmtSummaryRefreshInterval, strconv.Itoa(config.GetGlobalConfig().StmtSummary.RefreshInterval)}, + {ScopeGlobal | ScopeSession, TiDBStmtSummaryHistorySize, strconv.Itoa(config.GetGlobalConfig().StmtSummary.HistorySize)}, {ScopeGlobal | ScopeSession, TiDBStoreLimit, strconv.FormatInt(atomic.LoadInt64(&config.GetGlobalConfig().TiKVClient.StoreLimit), 10)}, } diff --git a/sessionctx/variable/tidb_vars.go b/sessionctx/variable/tidb_vars.go index e800ae2d1a9ac..b9a91c3d4e4eb 100644 --- a/sessionctx/variable/tidb_vars.go +++ b/sessionctx/variable/tidb_vars.go @@ -298,6 +298,9 @@ const ( // TiDBStmtSummaryRefreshInterval indicates the refresh interval in seconds for each statement summary. TiDBStmtSummaryRefreshInterval = "tidb_stmt_summary_refresh_interval" + // TiDBStmtSummaryHistorySize indicates the history size of each statement summary. + TiDBStmtSummaryHistorySize = "tidb_stmt_summary_history_size" + // TiDBStoreLimit indicates the limit of sending request to a store, 0 means without limit. TiDBStoreLimit = "tidb_store_limit" ) @@ -365,8 +368,7 @@ const ( DefTiDBExpensiveQueryTimeThreshold = 60 // 60s DefWaitSplitRegionTimeout = 300 // 300s DefTiDBAllowRemoveAutoInc = false - DefTiDBStmtSummaryRefreshInterval = 1800 // 1800s - DefInnodbLockWaitTimeout = 50 // 50s + DefInnodbLockWaitTimeout = 50 // 50s DefTiDBStoreLimit = 0 ) diff --git a/sessionctx/variable/varsutil.go b/sessionctx/variable/varsutil.go index 47a4f28786078..9e6856342d600 100644 --- a/sessionctx/variable/varsutil.go +++ b/sessionctx/variable/varsutil.go @@ -616,6 +616,11 @@ func ValidateSetSystemVar(vars *SessionVars, name string, value string) (string, return "", nil } return checkUInt64SystemVar(name, value, 1, math.MaxUint32, vars) + case TiDBStmtSummaryHistorySize: + if value == "" { + return "", nil + } + return checkUInt64SystemVar(name, value, 0, math.MaxUint8, vars) } return value, nil } diff --git a/sessionctx/variable/varsutil_test.go b/sessionctx/variable/varsutil_test.go index 17d0d5f14e754..df85046bb528e 100644 --- a/sessionctx/variable/varsutil_test.go +++ b/sessionctx/variable/varsutil_test.go @@ -304,6 +304,11 @@ func (s *testVarsutilSuite) TestVarsutil(c *C) { val, err = GetSessionSystemVar(v, TiDBStmtSummaryRefreshInterval) c.Assert(err, IsNil) c.Assert(val, Equals, "10") + + SetSessionSystemVar(v, TiDBStmtSummaryHistorySize, types.NewStringDatum("10")) + val, err = GetSessionSystemVar(v, TiDBStmtSummaryHistorySize) + c.Assert(err, IsNil) + c.Assert(val, Equals, "10") } func (s *testVarsutilSuite) TestValidate(c *C) { @@ -363,6 +368,8 @@ func (s *testVarsutilSuite) TestValidate(c *C) { {TiDBEnableStmtSummary, "", false}, {TiDBStmtSummaryRefreshInterval, "a", true}, {TiDBStmtSummaryRefreshInterval, "", false}, + {TiDBStmtSummaryHistorySize, "a", true}, + {TiDBStmtSummaryHistorySize, "", false}, } for _, t := range tests { diff --git a/util/stmtsummary/statement_summary.go b/util/stmtsummary/statement_summary.go index 28e43e7645916..96428278fa331 100644 --- a/util/stmtsummary/statement_summary.go +++ b/util/stmtsummary/statement_summary.go @@ -15,6 +15,7 @@ package stmtsummary import ( "bytes" + "container/list" "fmt" "sort" "strconv" @@ -59,9 +60,8 @@ type stmtSummaryByDigestMap struct { // It's rare to read concurrently, so RWMutex is not needed. sync.Mutex summaryMap *kvcache.SimpleLRUCache - // These fields are used for rolling summary. + // beginTimeForCurInterval is the begin time for current summary. beginTimeForCurInterval int64 - lastCheckExpireTime int64 // sysVars encapsulates system variables needed to control statement summary. sysVars struct { @@ -70,12 +70,20 @@ type stmtSummaryByDigestMap struct { sessionEnabled string // setInSession indicates whether statement summary has been set in any session. globalEnabled string + // These variables indicate the refresh interval of summaries. // They must be > 0. sessionRefreshInterval string globalRefreshInterval string // A cached result. It must be read atomically. refreshInterval int64 + + // These variables indicate the max history size of each summary. + // They must be > 0. + sessionHistorySize string + globalHistorySize string + // A cached result. It must be read atomically. + historySize int32 } } @@ -85,19 +93,29 @@ var StmtSummaryByDigestMap = newStmtSummaryByDigestMap() // stmtSummaryByDigest is the summary for each type of statements. type stmtSummaryByDigest struct { // It's rare to read concurrently, so RWMutex is not needed. + // Mutex is only used to lock `history`. sync.Mutex - // Each summary is summarized between [beginTime, beginTime + interval]. - beginTime int64 - // basic + // Each element in history is a summary in one interval. + history *list.List + // Following fields are common for each summary element. + // They won't change once this object is created, so locking is not needed. schemaName string digest string stmtType string normalizedSQL string - sampleSQL string tableNames string - indexNames string - sampleUser string - execCount int64 +} + +// stmtSummaryByDigestElement is the summary for each type of statements in current interval. +type stmtSummaryByDigestElement struct { + sync.Mutex + // Each summary is summarized between [beginTime, beginTime + refreshInterval]. + beginTime int64 + // basic + sampleSQL string + sampleUser string + indexNames []string + execCount int64 // latency sumLatency time.Duration maxLatency time.Duration @@ -179,13 +197,15 @@ type StmtExecInfo struct { func newStmtSummaryByDigestMap() *stmtSummaryByDigestMap { maxStmtCount := config.GetGlobalConfig().StmtSummary.MaxStmtCount ssMap := &stmtSummaryByDigestMap{ - summaryMap: kvcache.NewSimpleLRUCache(maxStmtCount, 0, 0), - beginTimeForCurInterval: 0, - lastCheckExpireTime: 0, + summaryMap: kvcache.NewSimpleLRUCache(maxStmtCount, 0, 0), } - // sysVars.defaultEnabled will be initialized in package variable. - ssMap.sysVars.sessionEnabled = "" - ssMap.sysVars.globalEnabled = "" + // Initialize these configurations by values in the config file. + // They may be overwritten by system variables later. + if config.GetGlobalConfig().StmtSummary.Enable { + ssMap.sysVars.globalEnabled = "1" + } + ssMap.sysVars.refreshInterval = int64(config.GetGlobalConfig().StmtSummary.RefreshInterval) + ssMap.sysVars.historySize = int32(config.GetGlobalConfig().StmtSummary.HistorySize) return ssMap } @@ -194,52 +214,42 @@ func (ssMap *stmtSummaryByDigestMap) AddStatement(sei *StmtExecInfo) { // All times are counted in seconds. now := time.Now().Unix() + intervalSeconds := ssMap.refreshInterval() + historySize := ssMap.historySize() + key := &stmtSummaryByDigestKey{ schemaName: sei.SchemaName, digest: sei.Digest, } // Enclose the block in a function to ensure the lock will always be released. - value, ok := func() (kvcache.Value, bool) { + value, beginTime, ok := func() (kvcache.Value, int64, bool) { ssMap.Lock() defer ssMap.Unlock() // Check again. Statements could be added before disabling the flag and after Clear(). if !ssMap.Enabled() { - return nil, false + return nil, 0, false } - // Check refreshing every second. - if now > ssMap.lastCheckExpireTime { - intervalSeconds := ssMap.RefreshInterval() - if intervalSeconds <= 0 { - return nil, false - } - - if ssMap.beginTimeForCurInterval+intervalSeconds <= now { - // `beginTimeForCurInterval` is a multiple of intervalSeconds, so that when the interval is a multiple - // of 60 (or 600, 1800, 3600, etc), begin time shows 'XX:XX:00', not 'XX:XX:01'~'XX:XX:59'. - ssMap.beginTimeForCurInterval = now / intervalSeconds * intervalSeconds - } - ssMap.lastCheckExpireTime = now + if ssMap.beginTimeForCurInterval+intervalSeconds <= now { + // `beginTimeForCurInterval` is a multiple of intervalSeconds, so that when the interval is a multiple + // of 60 (or 600, 1800, 3600, etc), begin time shows 'XX:XX:00', not 'XX:XX:01'~'XX:XX:59'. + ssMap.beginTimeForCurInterval = now / intervalSeconds * intervalSeconds } + beginTime := ssMap.beginTimeForCurInterval value, ok := ssMap.summaryMap.Get(key) - // Replacing an element in LRU cache can only be `Delete` + `Put`. - if ok && (value.(*stmtSummaryByDigest).beginTime < ssMap.beginTimeForCurInterval) { - ssMap.summaryMap.Delete(key) - ok = false - } if !ok { - newSummary := newStmtSummaryByDigest(sei, ssMap.beginTimeForCurInterval) + newSummary := newStmtSummaryByDigest(sei, beginTime, historySize) ssMap.summaryMap.Put(key, newSummary) } - return value, ok + return value, beginTime, ok }() // Lock a single entry, not the whole cache. if ok { - value.(*stmtSummaryByDigest).add(sei) + value.(*stmtSummaryByDigest).add(sei, beginTime, historySize) } } @@ -250,19 +260,18 @@ func (ssMap *stmtSummaryByDigestMap) Clear() { ssMap.summaryMap.DeleteAll() ssMap.beginTimeForCurInterval = 0 - ssMap.lastCheckExpireTime = 0 } -// ToDatum converts statement summary to datum. -func (ssMap *stmtSummaryByDigestMap) ToDatum() [][]types.Datum { +// ToCurrentDatum converts current statement summaries to datum. +func (ssMap *stmtSummaryByDigestMap) ToCurrentDatum() [][]types.Datum { ssMap.Lock() values := ssMap.summaryMap.Values() + beginTime := ssMap.beginTimeForCurInterval ssMap.Unlock() rows := make([][]types.Datum, 0, len(values)) for _, value := range values { - ssbd := value.(*stmtSummaryByDigest) - record := ssbd.toDatum(ssMap.beginTimeForCurInterval) + record := value.(*stmtSummaryByDigest).toCurrentDatum(beginTime) if record != nil { rows = append(rows, record) } @@ -270,6 +279,21 @@ func (ssMap *stmtSummaryByDigestMap) ToDatum() [][]types.Datum { return rows } +// ToHistoryDatum converts history statements summaries to datum. +func (ssMap *stmtSummaryByDigestMap) ToHistoryDatum() [][]types.Datum { + ssMap.Lock() + values := ssMap.summaryMap.Values() + ssMap.Unlock() + + historySize := ssMap.historySize() + rows := make([][]types.Datum, 0, len(values)*historySize) + for _, value := range values { + records := value.(*stmtSummaryByDigest).toHistoryDatum(historySize) + rows = append(rows, records...) + } + return rows +} + // GetMoreThanOnceSelect gets select SQLs that occurred more than once. func (ssMap *stmtSummaryByDigestMap) GetMoreThanOnceSelect() ([]string, []string) { ssMap.Lock() @@ -283,9 +307,14 @@ func (ssMap *stmtSummaryByDigestMap) GetMoreThanOnceSelect() ([]string, []string // `stmtType` won't change once created, so locking is not needed. if ssbd.stmtType == "select" { ssbd.Lock() - if ssbd.execCount > 1 { - schemas = append(schemas, ssbd.schemaName) - sqls = append(sqls, ssbd.sampleSQL) + if ssbd.history.Len() > 0 { + ssElement := ssbd.history.Back().Value.(*stmtSummaryByDigestElement) + ssElement.Lock() + if ssbd.history.Len() > 1 || ssElement.execCount > 1 { + schemas = append(schemas, ssbd.schemaName) + sqls = append(sqls, ssElement.sampleSQL) + } + ssElement.Unlock() } ssbd.Unlock() } @@ -383,25 +412,68 @@ func (ssMap *stmtSummaryByDigestMap) SetRefreshInterval(value string, inSession interval = 0 } } - if interval > 0 { - atomic.StoreInt64(&ssMap.sysVars.refreshInterval, int64(interval)) + // If session and global variables are both '', use the value in config. + if interval <= 0 { + interval = config.GetGlobalConfig().StmtSummary.RefreshInterval } + atomic.StoreInt64(&ssMap.sysVars.refreshInterval, int64(interval)) } -func (ssMap *stmtSummaryByDigestMap) RefreshInterval() int64 { +// refreshInterval gets the refresh interval for summaries. +func (ssMap *stmtSummaryByDigestMap) refreshInterval() int64 { return atomic.LoadInt64(&ssMap.sysVars.refreshInterval) } +// SetHistorySize sets the history size for all summaries. +func (ssMap *stmtSummaryByDigestMap) SetHistorySize(value string, inSession bool) { + ssMap.sysVars.Lock() + if inSession { + ssMap.sysVars.sessionHistorySize = value + } else { + ssMap.sysVars.globalHistorySize = value + } + sessionHistorySize := ssMap.sysVars.sessionHistorySize + globalHistorySize := ssMap.sysVars.globalHistorySize + ssMap.sysVars.Unlock() + + // Calculate the cached `historySize`. + size := -1 + var err error + if ssMap.isSet(sessionHistorySize) { + size, err = strconv.Atoi(sessionHistorySize) + if err != nil { + size = -1 + } + } + if size < 0 { + size, err = strconv.Atoi(globalHistorySize) + if err != nil { + size = -1 + } + } + // If session and global variables are both '', use the value in config. + if size < 0 { + size = config.GetGlobalConfig().StmtSummary.HistorySize + } + atomic.StoreInt32(&ssMap.sysVars.historySize, int32(size)) +} + +// historySize gets the history size for summaries. +func (ssMap *stmtSummaryByDigestMap) historySize() int { + return int(atomic.LoadInt32(&ssMap.sysVars.historySize)) +} + // newStmtSummaryByDigest creates a stmtSummaryByDigest from StmtExecInfo. -func newStmtSummaryByDigest(sei *StmtExecInfo, beginTime int64) *stmtSummaryByDigest { +func newStmtSummaryByDigest(sei *StmtExecInfo, beginTime int64, historySize int) *stmtSummaryByDigest { // Trim SQL to size MaxSQLLength. maxSQLLength := config.GetGlobalConfig().StmtSummary.MaxSQLLength normalizedSQL := sei.NormalizedSQL if len(normalizedSQL) > int(maxSQLLength) { - normalizedSQL = normalizedSQL[:maxSQLLength] + // Make sure the memory of original `normalizedSQL` will be released. + normalizedSQL = string([]byte(normalizedSQL[:maxSQLLength])) } - // Use "," to separate table names and index names to support FIND_IN_SET. + // Use "," to separate table names to support FIND_IN_SET. var buffer bytes.Buffer for i, value := range sei.StmtCtx.Tables { buffer.WriteString(strings.ToLower(value.DB)) @@ -414,232 +486,310 @@ func newStmtSummaryByDigest(sei *StmtExecInfo, beginTime int64) *stmtSummaryByDi tableNames := buffer.String() ssbd := &stmtSummaryByDigest{ - beginTime: beginTime, schemaName: sei.SchemaName, digest: sei.Digest, stmtType: strings.ToLower(sei.StmtCtx.StmtType), normalizedSQL: normalizedSQL, tableNames: tableNames, - indexNames: strings.Join(sei.StmtCtx.IndexNames, ","), - minLatency: sei.TotalLatency, - backoffTypes: make(map[fmt.Stringer]int), - firstSeen: sei.StartTime, - lastSeen: sei.StartTime, + history: list.New(), } - ssbd.add(sei) + ssbd.add(sei, beginTime, historySize) return ssbd } -func (ssbd *stmtSummaryByDigest) add(sei *StmtExecInfo) { +func (ssbd *stmtSummaryByDigest) add(sei *StmtExecInfo, beginTime int64, historySize int) { + // Enclose this block in a function to ensure the lock will always be released. + ssElement, isElementNew := func() (*stmtSummaryByDigestElement, bool) { + ssbd.Lock() + defer ssbd.Unlock() + + var ssElement *stmtSummaryByDigestElement + isElementNew := true + if ssbd.history.Len() > 0 { + lastElement := ssbd.history.Back().Value.(*stmtSummaryByDigestElement) + if lastElement.beginTime >= beginTime { + ssElement = lastElement + isElementNew = false + } + } + if isElementNew { + // If the element is new created, `ssElement.add(sei)` should be done inside the lock of `ssbd`. + ssElement = newStmtSummaryByDigestElement(sei, beginTime) + ssbd.history.PushBack(ssElement) + } + + // `historySize` might be modified anytime, so check expiration every time. + // Even if history is set to 0, current summary is still needed. + for ssbd.history.Len() > historySize && ssbd.history.Len() > 1 { + ssbd.history.Remove(ssbd.history.Front()) + } + + return ssElement, isElementNew + }() + + // Lock a single entry, not the whole `ssbd`. + if !isElementNew { + ssElement.add(sei) + } +} + +func (ssbd *stmtSummaryByDigest) toCurrentDatum(beginTimeForCurInterval int64) []types.Datum { + var ssElement *stmtSummaryByDigestElement + + ssbd.Lock() + if ssbd.history.Len() > 0 { + ssElement = ssbd.history.Back().Value.(*stmtSummaryByDigestElement) + } + ssbd.Unlock() + + // `ssElement` is lazy expired, so expired elements could also be read. + // `beginTime` won't change since `ssElement` is created, so locking is not needed here. + if ssElement == nil || ssElement.beginTime < beginTimeForCurInterval { + return nil + } + return ssElement.toDatum(ssbd) +} + +func (ssbd *stmtSummaryByDigest) toHistoryDatum(historySize int) [][]types.Datum { + // Collect all history summaries to an array. + ssElements := ssbd.collectHistorySummaries(historySize) + + rows := make([][]types.Datum, 0, len(ssElements)) + for _, ssElement := range ssElements { + rows = append(rows, ssElement.toDatum(ssbd)) + } + return rows +} + +// collectHistorySummaries puts at most `historySize` summaries to an array. +func (ssbd *stmtSummaryByDigest) collectHistorySummaries(historySize int) []*stmtSummaryByDigestElement { ssbd.Lock() defer ssbd.Unlock() - if sei.User != "" { - ssbd.sampleUser = sei.User + ssElements := make([]*stmtSummaryByDigestElement, 0, ssbd.history.Len()) + for listElement := ssbd.history.Front(); listElement != nil && len(ssElements) < historySize; listElement = listElement.Next() { + ssElement := listElement.Value.(*stmtSummaryByDigestElement) + ssElements = append(ssElements, ssElement) } + return ssElements +} + +func newStmtSummaryByDigestElement(sei *StmtExecInfo, beginTime int64) *stmtSummaryByDigestElement { + ssElement := &stmtSummaryByDigestElement{ + beginTime: beginTime, + minLatency: sei.TotalLatency, + firstSeen: sei.StartTime, + lastSeen: sei.StartTime, + backoffTypes: make(map[fmt.Stringer]int, 0), + } + ssElement.add(sei) + return ssElement +} +func (ssElement *stmtSummaryByDigestElement) add(sei *StmtExecInfo) { maxSQLLength := config.GetGlobalConfig().StmtSummary.MaxSQLLength sampleSQL := sei.OriginalSQL if len(sampleSQL) > int(maxSQLLength) { - sampleSQL = sampleSQL[:maxSQLLength] + // Make sure the memory of original `sampleSQL` will be released. + sampleSQL = string([]byte(sampleSQL[:maxSQLLength])) } - ssbd.sampleSQL = sampleSQL - ssbd.execCount++ + + ssElement.Lock() + defer ssElement.Unlock() + + if sei.User != "" { + ssElement.sampleUser = sei.User + } + ssElement.sampleSQL = sampleSQL + ssElement.indexNames = sei.StmtCtx.IndexNames + ssElement.execCount++ // latency - ssbd.sumLatency += sei.TotalLatency - if sei.TotalLatency > ssbd.maxLatency { - ssbd.maxLatency = sei.TotalLatency + ssElement.sumLatency += sei.TotalLatency + if sei.TotalLatency > ssElement.maxLatency { + ssElement.maxLatency = sei.TotalLatency } - if sei.TotalLatency < ssbd.minLatency { - ssbd.minLatency = sei.TotalLatency + if sei.TotalLatency < ssElement.minLatency { + ssElement.minLatency = sei.TotalLatency } - ssbd.sumParseLatency += sei.ParseLatency - if sei.ParseLatency > ssbd.maxParseLatency { - ssbd.maxParseLatency = sei.ParseLatency + ssElement.sumParseLatency += sei.ParseLatency + if sei.ParseLatency > ssElement.maxParseLatency { + ssElement.maxParseLatency = sei.ParseLatency } - ssbd.sumCompileLatency += sei.CompileLatency - if sei.CompileLatency > ssbd.maxCompileLatency { - ssbd.maxCompileLatency = sei.CompileLatency + ssElement.sumCompileLatency += sei.CompileLatency + if sei.CompileLatency > ssElement.maxCompileLatency { + ssElement.maxCompileLatency = sei.CompileLatency } // coprocessor numCopTasks := int64(sei.CopTasks.NumCopTasks) - ssbd.numCopTasks += numCopTasks - ssbd.sumCopProcessTime += sei.CopTasks.AvgProcessTime.Nanoseconds() * numCopTasks - if sei.CopTasks.MaxProcessTime > ssbd.maxCopProcessTime { - ssbd.maxCopProcessTime = sei.CopTasks.MaxProcessTime - ssbd.maxCopProcessAddress = sei.CopTasks.MaxProcessAddress + ssElement.numCopTasks += numCopTasks + ssElement.sumCopProcessTime += sei.CopTasks.AvgProcessTime.Nanoseconds() * numCopTasks + if sei.CopTasks.MaxProcessTime > ssElement.maxCopProcessTime { + ssElement.maxCopProcessTime = sei.CopTasks.MaxProcessTime + ssElement.maxCopProcessAddress = sei.CopTasks.MaxProcessAddress } - ssbd.sumCopWaitTime += sei.CopTasks.AvgWaitTime.Nanoseconds() * numCopTasks - if sei.CopTasks.MaxWaitTime > ssbd.maxCopWaitTime { - ssbd.maxCopWaitTime = sei.CopTasks.MaxWaitTime - ssbd.maxCopWaitAddress = sei.CopTasks.MaxWaitAddress + ssElement.sumCopWaitTime += sei.CopTasks.AvgWaitTime.Nanoseconds() * numCopTasks + if sei.CopTasks.MaxWaitTime > ssElement.maxCopWaitTime { + ssElement.maxCopWaitTime = sei.CopTasks.MaxWaitTime + ssElement.maxCopWaitAddress = sei.CopTasks.MaxWaitAddress } // TiKV - ssbd.sumProcessTime += sei.ExecDetail.ProcessTime - if sei.ExecDetail.ProcessTime > ssbd.maxProcessTime { - ssbd.maxProcessTime = sei.ExecDetail.ProcessTime + ssElement.sumProcessTime += sei.ExecDetail.ProcessTime + if sei.ExecDetail.ProcessTime > ssElement.maxProcessTime { + ssElement.maxProcessTime = sei.ExecDetail.ProcessTime } - ssbd.sumWaitTime += sei.ExecDetail.WaitTime - if sei.ExecDetail.WaitTime > ssbd.maxWaitTime { - ssbd.maxWaitTime = sei.ExecDetail.WaitTime + ssElement.sumWaitTime += sei.ExecDetail.WaitTime + if sei.ExecDetail.WaitTime > ssElement.maxWaitTime { + ssElement.maxWaitTime = sei.ExecDetail.WaitTime } - ssbd.sumBackoffTime += sei.ExecDetail.BackoffTime - if sei.ExecDetail.BackoffTime > ssbd.maxBackoffTime { - ssbd.maxBackoffTime = sei.ExecDetail.BackoffTime + ssElement.sumBackoffTime += sei.ExecDetail.BackoffTime + if sei.ExecDetail.BackoffTime > ssElement.maxBackoffTime { + ssElement.maxBackoffTime = sei.ExecDetail.BackoffTime } - ssbd.sumTotalKeys += sei.ExecDetail.TotalKeys - if sei.ExecDetail.TotalKeys > ssbd.maxTotalKeys { - ssbd.maxTotalKeys = sei.ExecDetail.TotalKeys + ssElement.sumTotalKeys += sei.ExecDetail.TotalKeys + if sei.ExecDetail.TotalKeys > ssElement.maxTotalKeys { + ssElement.maxTotalKeys = sei.ExecDetail.TotalKeys } - ssbd.sumProcessedKeys += sei.ExecDetail.ProcessedKeys - if sei.ExecDetail.ProcessedKeys > ssbd.maxProcessedKeys { - ssbd.maxProcessedKeys = sei.ExecDetail.ProcessedKeys + ssElement.sumProcessedKeys += sei.ExecDetail.ProcessedKeys + if sei.ExecDetail.ProcessedKeys > ssElement.maxProcessedKeys { + ssElement.maxProcessedKeys = sei.ExecDetail.ProcessedKeys } // txn commitDetails := sei.ExecDetail.CommitDetail if commitDetails != nil { - ssbd.commitCount++ - ssbd.sumPrewriteTime += commitDetails.PrewriteTime - if commitDetails.PrewriteTime > ssbd.maxPrewriteTime { - ssbd.maxPrewriteTime = commitDetails.PrewriteTime + ssElement.commitCount++ + ssElement.sumPrewriteTime += commitDetails.PrewriteTime + if commitDetails.PrewriteTime > ssElement.maxPrewriteTime { + ssElement.maxPrewriteTime = commitDetails.PrewriteTime } - ssbd.sumCommitTime += commitDetails.CommitTime - if commitDetails.CommitTime > ssbd.maxCommitTime { - ssbd.maxCommitTime = commitDetails.CommitTime + ssElement.sumCommitTime += commitDetails.CommitTime + if commitDetails.CommitTime > ssElement.maxCommitTime { + ssElement.maxCommitTime = commitDetails.CommitTime } - ssbd.sumGetCommitTsTime += commitDetails.GetCommitTsTime - if commitDetails.GetCommitTsTime > ssbd.maxGetCommitTsTime { - ssbd.maxGetCommitTsTime = commitDetails.GetCommitTsTime + ssElement.sumGetCommitTsTime += commitDetails.GetCommitTsTime + if commitDetails.GetCommitTsTime > ssElement.maxGetCommitTsTime { + ssElement.maxGetCommitTsTime = commitDetails.GetCommitTsTime } - ssbd.sumCommitBackoffTime += commitDetails.CommitBackoffTime - if commitDetails.CommitBackoffTime > ssbd.maxCommitBackoffTime { - ssbd.maxCommitBackoffTime = commitDetails.CommitBackoffTime + ssElement.sumCommitBackoffTime += commitDetails.CommitBackoffTime + if commitDetails.CommitBackoffTime > ssElement.maxCommitBackoffTime { + ssElement.maxCommitBackoffTime = commitDetails.CommitBackoffTime } resolveLockTime := atomic.LoadInt64(&commitDetails.ResolveLockTime) - ssbd.sumResolveLockTime += resolveLockTime - if resolveLockTime > ssbd.maxResolveLockTime { - ssbd.maxResolveLockTime = resolveLockTime + ssElement.sumResolveLockTime += resolveLockTime + if resolveLockTime > ssElement.maxResolveLockTime { + ssElement.maxResolveLockTime = resolveLockTime } - ssbd.sumLocalLatchTime += commitDetails.LocalLatchTime - if commitDetails.LocalLatchTime > ssbd.maxLocalLatchTime { - ssbd.maxLocalLatchTime = commitDetails.LocalLatchTime + ssElement.sumLocalLatchTime += commitDetails.LocalLatchTime + if commitDetails.LocalLatchTime > ssElement.maxLocalLatchTime { + ssElement.maxLocalLatchTime = commitDetails.LocalLatchTime } - ssbd.sumWriteKeys += int64(commitDetails.WriteKeys) - if commitDetails.WriteKeys > ssbd.maxWriteKeys { - ssbd.maxWriteKeys = commitDetails.WriteKeys + ssElement.sumWriteKeys += int64(commitDetails.WriteKeys) + if commitDetails.WriteKeys > ssElement.maxWriteKeys { + ssElement.maxWriteKeys = commitDetails.WriteKeys } - ssbd.sumWriteSize += int64(commitDetails.WriteSize) - if commitDetails.WriteSize > ssbd.maxWriteSize { - ssbd.maxWriteSize = commitDetails.WriteSize + ssElement.sumWriteSize += int64(commitDetails.WriteSize) + if commitDetails.WriteSize > ssElement.maxWriteSize { + ssElement.maxWriteSize = commitDetails.WriteSize } prewriteRegionNum := atomic.LoadInt32(&commitDetails.PrewriteRegionNum) - ssbd.sumPrewriteRegionNum += int64(prewriteRegionNum) - if prewriteRegionNum > ssbd.maxPrewriteRegionNum { - ssbd.maxPrewriteRegionNum = prewriteRegionNum + ssElement.sumPrewriteRegionNum += int64(prewriteRegionNum) + if prewriteRegionNum > ssElement.maxPrewriteRegionNum { + ssElement.maxPrewriteRegionNum = prewriteRegionNum } - ssbd.sumTxnRetry += int64(commitDetails.TxnRetry) - if commitDetails.TxnRetry > ssbd.maxTxnRetry { - ssbd.maxTxnRetry = commitDetails.TxnRetry + ssElement.sumTxnRetry += int64(commitDetails.TxnRetry) + if commitDetails.TxnRetry > ssElement.maxTxnRetry { + ssElement.maxTxnRetry = commitDetails.TxnRetry } commitDetails.Mu.Lock() for _, backoffType := range commitDetails.Mu.BackoffTypes { - if _, ok := ssbd.backoffTypes[backoffType]; ok { - ssbd.backoffTypes[backoffType] += 1 - } else { - ssbd.backoffTypes[backoffType] = 1 - } + ssElement.backoffTypes[backoffType] += 1 } commitDetails.Mu.Unlock() } // other - ssbd.sumAffectedRows += sei.StmtCtx.AffectedRows() - ssbd.sumMem += sei.MemMax - if sei.MemMax > ssbd.maxMem { - ssbd.maxMem = sei.MemMax + ssElement.sumAffectedRows += sei.StmtCtx.AffectedRows() + ssElement.sumMem += sei.MemMax + if sei.MemMax > ssElement.maxMem { + ssElement.maxMem = sei.MemMax } - if sei.StartTime.Before(ssbd.firstSeen) { - ssbd.firstSeen = sei.StartTime + if sei.StartTime.Before(ssElement.firstSeen) { + ssElement.firstSeen = sei.StartTime } - if ssbd.lastSeen.Before(sei.StartTime) { - ssbd.lastSeen = sei.StartTime + if ssElement.lastSeen.Before(sei.StartTime) { + ssElement.lastSeen = sei.StartTime } } -func (ssbd *stmtSummaryByDigest) toDatum(oldestBeginTime int64) []types.Datum { - ssbd.Lock() - defer ssbd.Unlock() - - if ssbd.beginTime < oldestBeginTime { - return nil - } +func (ssElement *stmtSummaryByDigestElement) toDatum(ssbd *stmtSummaryByDigest) []types.Datum { + ssElement.Lock() + defer ssElement.Unlock() return types.MakeDatums( - types.Time{Time: types.FromGoTime(time.Unix(ssbd.beginTime, 0)), Type: mysql.TypeTimestamp}, + types.Time{Time: types.FromGoTime(time.Unix(ssElement.beginTime, 0)), Type: mysql.TypeTimestamp}, ssbd.stmtType, ssbd.schemaName, ssbd.digest, ssbd.normalizedSQL, convertEmptyToNil(ssbd.tableNames), - convertEmptyToNil(ssbd.indexNames), - convertEmptyToNil(ssbd.sampleUser), - ssbd.execCount, - int64(ssbd.sumLatency), - int64(ssbd.maxLatency), - int64(ssbd.minLatency), - avgInt(int64(ssbd.sumLatency), ssbd.execCount), - avgInt(int64(ssbd.sumParseLatency), ssbd.execCount), - int64(ssbd.maxParseLatency), - avgInt(int64(ssbd.sumCompileLatency), ssbd.execCount), - int64(ssbd.maxCompileLatency), - ssbd.numCopTasks, - avgInt(ssbd.sumCopProcessTime, ssbd.numCopTasks), - int64(ssbd.maxCopProcessTime), - convertEmptyToNil(ssbd.maxCopProcessAddress), - avgInt(ssbd.sumCopWaitTime, ssbd.numCopTasks), - int64(ssbd.maxCopWaitTime), - convertEmptyToNil(ssbd.maxCopWaitAddress), - avgInt(int64(ssbd.sumProcessTime), ssbd.execCount), - int64(ssbd.maxProcessTime), - avgInt(int64(ssbd.sumWaitTime), ssbd.execCount), - int64(ssbd.maxWaitTime), - avgInt(int64(ssbd.sumBackoffTime), ssbd.execCount), - int64(ssbd.maxBackoffTime), - avgInt(ssbd.sumTotalKeys, ssbd.execCount), - ssbd.maxTotalKeys, - avgInt(ssbd.sumProcessedKeys, ssbd.execCount), - ssbd.maxProcessedKeys, - avgInt(int64(ssbd.sumPrewriteTime), ssbd.commitCount), - int64(ssbd.maxPrewriteTime), - avgInt(int64(ssbd.sumCommitTime), ssbd.commitCount), - int64(ssbd.maxCommitTime), - avgInt(int64(ssbd.sumGetCommitTsTime), ssbd.commitCount), - int64(ssbd.maxGetCommitTsTime), - avgInt(ssbd.sumCommitBackoffTime, ssbd.commitCount), - ssbd.maxCommitBackoffTime, - avgInt(ssbd.sumResolveLockTime, ssbd.commitCount), - ssbd.maxResolveLockTime, - avgInt(int64(ssbd.sumLocalLatchTime), ssbd.commitCount), - int64(ssbd.maxLocalLatchTime), - avgFloat(ssbd.sumWriteKeys, ssbd.commitCount), - ssbd.maxWriteKeys, - avgFloat(ssbd.sumWriteSize, ssbd.commitCount), - ssbd.maxWriteSize, - avgFloat(ssbd.sumPrewriteRegionNum, ssbd.commitCount), - int(ssbd.maxPrewriteRegionNum), - avgFloat(ssbd.sumTxnRetry, ssbd.commitCount), - ssbd.maxTxnRetry, - formatBackoffTypes(ssbd.backoffTypes), - avgInt(ssbd.sumMem, ssbd.execCount), - ssbd.maxMem, - avgFloat(int64(ssbd.sumAffectedRows), ssbd.execCount), - types.Time{Time: types.FromGoTime(ssbd.firstSeen), Type: mysql.TypeTimestamp}, - types.Time{Time: types.FromGoTime(ssbd.lastSeen), Type: mysql.TypeTimestamp}, - ssbd.sampleSQL, + convertEmptyToNil(strings.Join(ssElement.indexNames, ",")), + convertEmptyToNil(ssElement.sampleUser), + ssElement.execCount, + int64(ssElement.sumLatency), + int64(ssElement.maxLatency), + int64(ssElement.minLatency), + avgInt(int64(ssElement.sumLatency), ssElement.execCount), + avgInt(int64(ssElement.sumParseLatency), ssElement.execCount), + int64(ssElement.maxParseLatency), + avgInt(int64(ssElement.sumCompileLatency), ssElement.execCount), + int64(ssElement.maxCompileLatency), + ssElement.numCopTasks, + avgInt(ssElement.sumCopProcessTime, ssElement.numCopTasks), + int64(ssElement.maxCopProcessTime), + convertEmptyToNil(ssElement.maxCopProcessAddress), + avgInt(ssElement.sumCopWaitTime, ssElement.numCopTasks), + int64(ssElement.maxCopWaitTime), + convertEmptyToNil(ssElement.maxCopWaitAddress), + avgInt(int64(ssElement.sumProcessTime), ssElement.execCount), + int64(ssElement.maxProcessTime), + avgInt(int64(ssElement.sumWaitTime), ssElement.execCount), + int64(ssElement.maxWaitTime), + avgInt(int64(ssElement.sumBackoffTime), ssElement.execCount), + int64(ssElement.maxBackoffTime), + avgInt(ssElement.sumTotalKeys, ssElement.execCount), + ssElement.maxTotalKeys, + avgInt(ssElement.sumProcessedKeys, ssElement.execCount), + ssElement.maxProcessedKeys, + avgInt(int64(ssElement.sumPrewriteTime), ssElement.commitCount), + int64(ssElement.maxPrewriteTime), + avgInt(int64(ssElement.sumCommitTime), ssElement.commitCount), + int64(ssElement.maxCommitTime), + avgInt(int64(ssElement.sumGetCommitTsTime), ssElement.commitCount), + int64(ssElement.maxGetCommitTsTime), + avgInt(ssElement.sumCommitBackoffTime, ssElement.commitCount), + ssElement.maxCommitBackoffTime, + avgInt(ssElement.sumResolveLockTime, ssElement.commitCount), + ssElement.maxResolveLockTime, + avgInt(int64(ssElement.sumLocalLatchTime), ssElement.commitCount), + int64(ssElement.maxLocalLatchTime), + avgFloat(ssElement.sumWriteKeys, ssElement.commitCount), + ssElement.maxWriteKeys, + avgFloat(ssElement.sumWriteSize, ssElement.commitCount), + ssElement.maxWriteSize, + avgFloat(ssElement.sumPrewriteRegionNum, ssElement.commitCount), + int(ssElement.maxPrewriteRegionNum), + avgFloat(ssElement.sumTxnRetry, ssElement.commitCount), + ssElement.maxTxnRetry, + formatBackoffTypes(ssElement.backoffTypes), + avgInt(ssElement.sumMem, ssElement.execCount), + ssElement.maxMem, + avgFloat(int64(ssElement.sumAffectedRows), ssElement.execCount), + types.Time{Time: types.FromGoTime(ssElement.firstSeen), Type: mysql.TypeTimestamp}, + types.Time{Time: types.FromGoTime(ssElement.lastSeen), Type: mysql.TypeTimestamp}, + ssElement.sampleSQL, ) } diff --git a/util/stmtsummary/statement_summary_test.go b/util/stmtsummary/statement_summary_test.go index 464994ad258c2..800a7413b04f9 100644 --- a/util/stmtsummary/statement_summary_test.go +++ b/util/stmtsummary/statement_summary_test.go @@ -14,6 +14,7 @@ package stmtsummary import ( + "container/list" "fmt" "strings" "sync" @@ -38,7 +39,8 @@ type testStmtSummarySuite struct { func (s *testStmtSummarySuite) SetUpSuite(c *C) { s.ssMap = newStmtSummaryByDigestMap() s.ssMap.SetEnabled("1", false) - s.ssMap.SetRefreshInterval("1800", false) + s.ssMap.SetRefreshInterval("999999999", false) + s.ssMap.SetHistorySize("1", false) } func TestT(t *testing.T) { @@ -50,12 +52,10 @@ func TestT(t *testing.T) { func (s *testStmtSummarySuite) TestAddStatement(c *C) { s.ssMap.Clear() now := time.Now().Unix() - s.ssMap.beginTimeForCurInterval = now - // to disable expiring - s.ssMap.lastCheckExpireTime = now + 60 + s.ssMap.beginTimeForCurInterval = now + 60 tables := []stmtctx.TableEntry{{DB: "db1", Table: "tb1"}, {DB: "db2", Table: "tb2"}} - indexes := []string{"a"} + indexes := []string{"a", "b"} // first statement stmtExecInfo1 := generateAnyExecInfo() @@ -64,15 +64,10 @@ func (s *testStmtSummarySuite) TestAddStatement(c *C) { schemaName: stmtExecInfo1.SchemaName, digest: stmtExecInfo1.Digest, } - expectedSummary := stmtSummaryByDigest{ - beginTime: now, - schemaName: stmtExecInfo1.SchemaName, - stmtType: stmtExecInfo1.StmtCtx.StmtType, - digest: stmtExecInfo1.Digest, - normalizedSQL: stmtExecInfo1.NormalizedSQL, + expectedSummaryElement := stmtSummaryByDigestElement{ + beginTime: now + 60, sampleSQL: stmtExecInfo1.OriginalSQL, - tableNames: "db1.tb1,db2.tb2", - indexNames: "a", + indexNames: stmtExecInfo1.StmtCtx.IndexNames, sampleUser: stmtExecInfo1.User, execCount: 1, sumLatency: stmtExecInfo1.TotalLatency, @@ -126,6 +121,16 @@ func (s *testStmtSummarySuite) TestAddStatement(c *C) { firstSeen: stmtExecInfo1.StartTime, lastSeen: stmtExecInfo1.StartTime, } + history := list.New() + history.PushBack(&expectedSummaryElement) + expectedSummary := stmtSummaryByDigest{ + schemaName: stmtExecInfo1.SchemaName, + stmtType: stmtExecInfo1.StmtCtx.StmtType, + digest: stmtExecInfo1.Digest, + normalizedSQL: stmtExecInfo1.NormalizedSQL, + tableNames: "db1.tb1,db2.tb2", + history: history, + } s.ssMap.AddStatement(stmtExecInfo1) summary, ok := s.ssMap.summaryMap.Get(key) c.Assert(ok, IsTrue) @@ -189,57 +194,58 @@ func (s *testStmtSummarySuite) TestAddStatement(c *C) { StartTime: time.Date(2019, 1, 1, 10, 10, 20, 10, time.UTC), } stmtExecInfo2.StmtCtx.AddAffectedRows(200) - expectedSummary.execCount++ - expectedSummary.sampleSQL = stmtExecInfo2.OriginalSQL - expectedSummary.sampleUser = stmtExecInfo2.User - expectedSummary.sumLatency += stmtExecInfo2.TotalLatency - expectedSummary.maxLatency = stmtExecInfo2.TotalLatency - expectedSummary.sumParseLatency += stmtExecInfo2.ParseLatency - expectedSummary.maxParseLatency = stmtExecInfo2.ParseLatency - expectedSummary.sumCompileLatency += stmtExecInfo2.CompileLatency - expectedSummary.maxCompileLatency = stmtExecInfo2.CompileLatency - expectedSummary.numCopTasks += int64(stmtExecInfo2.CopTasks.NumCopTasks) - expectedSummary.sumCopProcessTime += int64(stmtExecInfo2.CopTasks.AvgProcessTime) * int64(stmtExecInfo2.CopTasks.NumCopTasks) - expectedSummary.maxCopProcessTime = stmtExecInfo2.CopTasks.MaxProcessTime - expectedSummary.maxCopProcessAddress = stmtExecInfo2.CopTasks.MaxProcessAddress - expectedSummary.sumCopWaitTime += int64(stmtExecInfo2.CopTasks.AvgWaitTime) * int64(stmtExecInfo2.CopTasks.NumCopTasks) - expectedSummary.maxCopWaitTime = stmtExecInfo2.CopTasks.MaxWaitTime - expectedSummary.maxCopWaitAddress = stmtExecInfo2.CopTasks.MaxWaitAddress - expectedSummary.sumProcessTime += stmtExecInfo2.ExecDetail.ProcessTime - expectedSummary.maxProcessTime = stmtExecInfo2.ExecDetail.ProcessTime - expectedSummary.sumWaitTime += stmtExecInfo2.ExecDetail.WaitTime - expectedSummary.maxWaitTime = stmtExecInfo2.ExecDetail.WaitTime - expectedSummary.sumBackoffTime += stmtExecInfo2.ExecDetail.BackoffTime - expectedSummary.maxBackoffTime = stmtExecInfo2.ExecDetail.BackoffTime - expectedSummary.sumTotalKeys += stmtExecInfo2.ExecDetail.TotalKeys - expectedSummary.maxTotalKeys = stmtExecInfo2.ExecDetail.TotalKeys - expectedSummary.sumProcessedKeys += stmtExecInfo2.ExecDetail.ProcessedKeys - expectedSummary.maxProcessedKeys = stmtExecInfo2.ExecDetail.ProcessedKeys - expectedSummary.sumGetCommitTsTime += stmtExecInfo2.ExecDetail.CommitDetail.GetCommitTsTime - expectedSummary.maxGetCommitTsTime = stmtExecInfo2.ExecDetail.CommitDetail.GetCommitTsTime - expectedSummary.sumPrewriteTime += stmtExecInfo2.ExecDetail.CommitDetail.PrewriteTime - expectedSummary.maxPrewriteTime = stmtExecInfo2.ExecDetail.CommitDetail.PrewriteTime - expectedSummary.sumCommitTime += stmtExecInfo2.ExecDetail.CommitDetail.CommitTime - expectedSummary.maxCommitTime = stmtExecInfo2.ExecDetail.CommitDetail.CommitTime - expectedSummary.sumLocalLatchTime += stmtExecInfo2.ExecDetail.CommitDetail.LocalLatchTime - expectedSummary.maxLocalLatchTime = stmtExecInfo2.ExecDetail.CommitDetail.LocalLatchTime - expectedSummary.sumCommitBackoffTime += stmtExecInfo2.ExecDetail.CommitDetail.CommitBackoffTime - expectedSummary.maxCommitBackoffTime = stmtExecInfo2.ExecDetail.CommitDetail.CommitBackoffTime - expectedSummary.sumResolveLockTime += stmtExecInfo2.ExecDetail.CommitDetail.ResolveLockTime - expectedSummary.maxResolveLockTime = stmtExecInfo2.ExecDetail.CommitDetail.ResolveLockTime - expectedSummary.sumWriteKeys += int64(stmtExecInfo2.ExecDetail.CommitDetail.WriteKeys) - expectedSummary.maxWriteKeys = stmtExecInfo2.ExecDetail.CommitDetail.WriteKeys - expectedSummary.sumWriteSize += int64(stmtExecInfo2.ExecDetail.CommitDetail.WriteSize) - expectedSummary.maxWriteSize = stmtExecInfo2.ExecDetail.CommitDetail.WriteSize - expectedSummary.sumPrewriteRegionNum += int64(stmtExecInfo2.ExecDetail.CommitDetail.PrewriteRegionNum) - expectedSummary.maxPrewriteRegionNum = stmtExecInfo2.ExecDetail.CommitDetail.PrewriteRegionNum - expectedSummary.sumTxnRetry += int64(stmtExecInfo2.ExecDetail.CommitDetail.TxnRetry) - expectedSummary.maxTxnRetry = stmtExecInfo2.ExecDetail.CommitDetail.TxnRetry - expectedSummary.backoffTypes[tikv.BoTxnLock] = 1 - expectedSummary.sumMem += stmtExecInfo2.MemMax - expectedSummary.maxMem = stmtExecInfo2.MemMax - expectedSummary.sumAffectedRows += stmtExecInfo2.StmtCtx.AffectedRows() - expectedSummary.lastSeen = stmtExecInfo2.StartTime + expectedSummaryElement.execCount++ + expectedSummaryElement.indexNames = indexes + expectedSummaryElement.sampleSQL = stmtExecInfo2.OriginalSQL + expectedSummaryElement.sampleUser = stmtExecInfo2.User + expectedSummaryElement.sumLatency += stmtExecInfo2.TotalLatency + expectedSummaryElement.maxLatency = stmtExecInfo2.TotalLatency + expectedSummaryElement.sumParseLatency += stmtExecInfo2.ParseLatency + expectedSummaryElement.maxParseLatency = stmtExecInfo2.ParseLatency + expectedSummaryElement.sumCompileLatency += stmtExecInfo2.CompileLatency + expectedSummaryElement.maxCompileLatency = stmtExecInfo2.CompileLatency + expectedSummaryElement.numCopTasks += int64(stmtExecInfo2.CopTasks.NumCopTasks) + expectedSummaryElement.sumCopProcessTime += int64(stmtExecInfo2.CopTasks.AvgProcessTime) * int64(stmtExecInfo2.CopTasks.NumCopTasks) + expectedSummaryElement.maxCopProcessTime = stmtExecInfo2.CopTasks.MaxProcessTime + expectedSummaryElement.maxCopProcessAddress = stmtExecInfo2.CopTasks.MaxProcessAddress + expectedSummaryElement.sumCopWaitTime += int64(stmtExecInfo2.CopTasks.AvgWaitTime) * int64(stmtExecInfo2.CopTasks.NumCopTasks) + expectedSummaryElement.maxCopWaitTime = stmtExecInfo2.CopTasks.MaxWaitTime + expectedSummaryElement.maxCopWaitAddress = stmtExecInfo2.CopTasks.MaxWaitAddress + expectedSummaryElement.sumProcessTime += stmtExecInfo2.ExecDetail.ProcessTime + expectedSummaryElement.maxProcessTime = stmtExecInfo2.ExecDetail.ProcessTime + expectedSummaryElement.sumWaitTime += stmtExecInfo2.ExecDetail.WaitTime + expectedSummaryElement.maxWaitTime = stmtExecInfo2.ExecDetail.WaitTime + expectedSummaryElement.sumBackoffTime += stmtExecInfo2.ExecDetail.BackoffTime + expectedSummaryElement.maxBackoffTime = stmtExecInfo2.ExecDetail.BackoffTime + expectedSummaryElement.sumTotalKeys += stmtExecInfo2.ExecDetail.TotalKeys + expectedSummaryElement.maxTotalKeys = stmtExecInfo2.ExecDetail.TotalKeys + expectedSummaryElement.sumProcessedKeys += stmtExecInfo2.ExecDetail.ProcessedKeys + expectedSummaryElement.maxProcessedKeys = stmtExecInfo2.ExecDetail.ProcessedKeys + expectedSummaryElement.sumGetCommitTsTime += stmtExecInfo2.ExecDetail.CommitDetail.GetCommitTsTime + expectedSummaryElement.maxGetCommitTsTime = stmtExecInfo2.ExecDetail.CommitDetail.GetCommitTsTime + expectedSummaryElement.sumPrewriteTime += stmtExecInfo2.ExecDetail.CommitDetail.PrewriteTime + expectedSummaryElement.maxPrewriteTime = stmtExecInfo2.ExecDetail.CommitDetail.PrewriteTime + expectedSummaryElement.sumCommitTime += stmtExecInfo2.ExecDetail.CommitDetail.CommitTime + expectedSummaryElement.maxCommitTime = stmtExecInfo2.ExecDetail.CommitDetail.CommitTime + expectedSummaryElement.sumLocalLatchTime += stmtExecInfo2.ExecDetail.CommitDetail.LocalLatchTime + expectedSummaryElement.maxLocalLatchTime = stmtExecInfo2.ExecDetail.CommitDetail.LocalLatchTime + expectedSummaryElement.sumCommitBackoffTime += stmtExecInfo2.ExecDetail.CommitDetail.CommitBackoffTime + expectedSummaryElement.maxCommitBackoffTime = stmtExecInfo2.ExecDetail.CommitDetail.CommitBackoffTime + expectedSummaryElement.sumResolveLockTime += stmtExecInfo2.ExecDetail.CommitDetail.ResolveLockTime + expectedSummaryElement.maxResolveLockTime = stmtExecInfo2.ExecDetail.CommitDetail.ResolveLockTime + expectedSummaryElement.sumWriteKeys += int64(stmtExecInfo2.ExecDetail.CommitDetail.WriteKeys) + expectedSummaryElement.maxWriteKeys = stmtExecInfo2.ExecDetail.CommitDetail.WriteKeys + expectedSummaryElement.sumWriteSize += int64(stmtExecInfo2.ExecDetail.CommitDetail.WriteSize) + expectedSummaryElement.maxWriteSize = stmtExecInfo2.ExecDetail.CommitDetail.WriteSize + expectedSummaryElement.sumPrewriteRegionNum += int64(stmtExecInfo2.ExecDetail.CommitDetail.PrewriteRegionNum) + expectedSummaryElement.maxPrewriteRegionNum = stmtExecInfo2.ExecDetail.CommitDetail.PrewriteRegionNum + expectedSummaryElement.sumTxnRetry += int64(stmtExecInfo2.ExecDetail.CommitDetail.TxnRetry) + expectedSummaryElement.maxTxnRetry = stmtExecInfo2.ExecDetail.CommitDetail.TxnRetry + expectedSummaryElement.backoffTypes[tikv.BoTxnLock] = 1 + expectedSummaryElement.sumMem += stmtExecInfo2.MemMax + expectedSummaryElement.maxMem = stmtExecInfo2.MemMax + expectedSummaryElement.sumAffectedRows += stmtExecInfo2.StmtCtx.AffectedRows() + expectedSummaryElement.lastSeen = stmtExecInfo2.StartTime s.ssMap.AddStatement(stmtExecInfo2) summary, ok = s.ssMap.summaryMap.Get(key) @@ -304,35 +310,35 @@ func (s *testStmtSummarySuite) TestAddStatement(c *C) { StartTime: time.Date(2019, 1, 1, 10, 10, 0, 10, time.UTC), } stmtExecInfo3.StmtCtx.AddAffectedRows(20000) - expectedSummary.execCount++ - expectedSummary.sampleUser = stmtExecInfo3.User - expectedSummary.sampleSQL = stmtExecInfo3.OriginalSQL - expectedSummary.sumLatency += stmtExecInfo3.TotalLatency - expectedSummary.minLatency = stmtExecInfo3.TotalLatency - expectedSummary.sumParseLatency += stmtExecInfo3.ParseLatency - expectedSummary.sumCompileLatency += stmtExecInfo3.CompileLatency - expectedSummary.numCopTasks += int64(stmtExecInfo3.CopTasks.NumCopTasks) - expectedSummary.sumCopProcessTime += int64(stmtExecInfo3.CopTasks.AvgProcessTime) * int64(stmtExecInfo3.CopTasks.NumCopTasks) - expectedSummary.sumCopWaitTime += int64(stmtExecInfo3.CopTasks.AvgWaitTime) * int64(stmtExecInfo3.CopTasks.NumCopTasks) - expectedSummary.sumProcessTime += stmtExecInfo3.ExecDetail.ProcessTime - expectedSummary.sumWaitTime += stmtExecInfo3.ExecDetail.WaitTime - expectedSummary.sumBackoffTime += stmtExecInfo3.ExecDetail.BackoffTime - expectedSummary.sumTotalKeys += stmtExecInfo3.ExecDetail.TotalKeys - expectedSummary.sumProcessedKeys += stmtExecInfo3.ExecDetail.ProcessedKeys - expectedSummary.sumGetCommitTsTime += stmtExecInfo3.ExecDetail.CommitDetail.GetCommitTsTime - expectedSummary.sumPrewriteTime += stmtExecInfo3.ExecDetail.CommitDetail.PrewriteTime - expectedSummary.sumCommitTime += stmtExecInfo3.ExecDetail.CommitDetail.CommitTime - expectedSummary.sumLocalLatchTime += stmtExecInfo3.ExecDetail.CommitDetail.LocalLatchTime - expectedSummary.sumCommitBackoffTime += stmtExecInfo3.ExecDetail.CommitDetail.CommitBackoffTime - expectedSummary.sumResolveLockTime += stmtExecInfo3.ExecDetail.CommitDetail.ResolveLockTime - expectedSummary.sumWriteKeys += int64(stmtExecInfo3.ExecDetail.CommitDetail.WriteKeys) - expectedSummary.sumWriteSize += int64(stmtExecInfo3.ExecDetail.CommitDetail.WriteSize) - expectedSummary.sumPrewriteRegionNum += int64(stmtExecInfo3.ExecDetail.CommitDetail.PrewriteRegionNum) - expectedSummary.sumTxnRetry += int64(stmtExecInfo3.ExecDetail.CommitDetail.TxnRetry) - expectedSummary.backoffTypes[tikv.BoTxnLock] = 2 - expectedSummary.sumMem += stmtExecInfo3.MemMax - expectedSummary.sumAffectedRows += stmtExecInfo3.StmtCtx.AffectedRows() - expectedSummary.firstSeen = stmtExecInfo3.StartTime + expectedSummaryElement.execCount++ + expectedSummaryElement.sampleUser = stmtExecInfo3.User + expectedSummaryElement.sampleSQL = stmtExecInfo3.OriginalSQL + expectedSummaryElement.sumLatency += stmtExecInfo3.TotalLatency + expectedSummaryElement.minLatency = stmtExecInfo3.TotalLatency + expectedSummaryElement.sumParseLatency += stmtExecInfo3.ParseLatency + expectedSummaryElement.sumCompileLatency += stmtExecInfo3.CompileLatency + expectedSummaryElement.numCopTasks += int64(stmtExecInfo3.CopTasks.NumCopTasks) + expectedSummaryElement.sumCopProcessTime += int64(stmtExecInfo3.CopTasks.AvgProcessTime) * int64(stmtExecInfo3.CopTasks.NumCopTasks) + expectedSummaryElement.sumCopWaitTime += int64(stmtExecInfo3.CopTasks.AvgWaitTime) * int64(stmtExecInfo3.CopTasks.NumCopTasks) + expectedSummaryElement.sumProcessTime += stmtExecInfo3.ExecDetail.ProcessTime + expectedSummaryElement.sumWaitTime += stmtExecInfo3.ExecDetail.WaitTime + expectedSummaryElement.sumBackoffTime += stmtExecInfo3.ExecDetail.BackoffTime + expectedSummaryElement.sumTotalKeys += stmtExecInfo3.ExecDetail.TotalKeys + expectedSummaryElement.sumProcessedKeys += stmtExecInfo3.ExecDetail.ProcessedKeys + expectedSummaryElement.sumGetCommitTsTime += stmtExecInfo3.ExecDetail.CommitDetail.GetCommitTsTime + expectedSummaryElement.sumPrewriteTime += stmtExecInfo3.ExecDetail.CommitDetail.PrewriteTime + expectedSummaryElement.sumCommitTime += stmtExecInfo3.ExecDetail.CommitDetail.CommitTime + expectedSummaryElement.sumLocalLatchTime += stmtExecInfo3.ExecDetail.CommitDetail.LocalLatchTime + expectedSummaryElement.sumCommitBackoffTime += stmtExecInfo3.ExecDetail.CommitDetail.CommitBackoffTime + expectedSummaryElement.sumResolveLockTime += stmtExecInfo3.ExecDetail.CommitDetail.ResolveLockTime + expectedSummaryElement.sumWriteKeys += int64(stmtExecInfo3.ExecDetail.CommitDetail.WriteKeys) + expectedSummaryElement.sumWriteSize += int64(stmtExecInfo3.ExecDetail.CommitDetail.WriteSize) + expectedSummaryElement.sumPrewriteRegionNum += int64(stmtExecInfo3.ExecDetail.CommitDetail.PrewriteRegionNum) + expectedSummaryElement.sumTxnRetry += int64(stmtExecInfo3.ExecDetail.CommitDetail.TxnRetry) + expectedSummaryElement.backoffTypes[tikv.BoTxnLock] = 2 + expectedSummaryElement.sumMem += stmtExecInfo3.MemMax + expectedSummaryElement.sumAffectedRows += stmtExecInfo3.StmtCtx.AffectedRows() + expectedSummaryElement.firstSeen = stmtExecInfo3.StartTime s.ssMap.AddStatement(stmtExecInfo3) summary, ok = s.ssMap.summaryMap.Get(key) @@ -366,78 +372,98 @@ func (s *testStmtSummarySuite) TestAddStatement(c *C) { } func matchStmtSummaryByDigest(first, second *stmtSummaryByDigest) bool { - if first.beginTime != second.beginTime || - first.schemaName != second.schemaName || - !strings.EqualFold(first.stmtType, second.stmtType) || + if first.schemaName != second.schemaName || first.digest != second.digest || first.normalizedSQL != second.normalizedSQL || - first.sampleSQL != second.sampleSQL || - first.sampleUser != second.sampleUser || first.tableNames != second.tableNames || - first.indexNames != second.indexNames || - first.execCount != second.execCount || - first.sumLatency != second.sumLatency || - first.maxLatency != second.maxLatency || - first.minLatency != second.minLatency || - first.sumParseLatency != second.sumParseLatency || - first.maxParseLatency != second.maxParseLatency || - first.sumCompileLatency != second.sumCompileLatency || - first.maxCompileLatency != second.maxCompileLatency || - first.numCopTasks != second.numCopTasks || - first.sumCopProcessTime != second.sumCopProcessTime || - first.maxCopProcessTime != second.maxCopProcessTime || - first.maxCopProcessAddress != second.maxCopProcessAddress || - first.sumCopWaitTime != second.sumCopWaitTime || - first.maxCopWaitTime != second.maxCopWaitTime || - first.maxCopWaitAddress != second.maxCopWaitAddress || - first.sumProcessTime != second.sumProcessTime || - first.maxProcessTime != second.maxProcessTime || - first.sumWaitTime != second.sumWaitTime || - first.maxWaitTime != second.maxWaitTime || - first.sumBackoffTime != second.sumBackoffTime || - first.maxBackoffTime != second.maxBackoffTime || - first.sumTotalKeys != second.sumTotalKeys || - first.maxTotalKeys != second.maxTotalKeys || - first.sumProcessedKeys != second.sumProcessedKeys || - first.maxProcessedKeys != second.maxProcessedKeys || - first.sumGetCommitTsTime != second.sumGetCommitTsTime || - first.maxGetCommitTsTime != second.maxGetCommitTsTime || - first.sumPrewriteTime != second.sumPrewriteTime || - first.maxPrewriteTime != second.maxPrewriteTime || - first.sumCommitTime != second.sumCommitTime || - first.maxCommitTime != second.maxCommitTime || - first.sumLocalLatchTime != second.sumLocalLatchTime || - first.maxLocalLatchTime != second.maxLocalLatchTime || - first.sumCommitBackoffTime != second.sumCommitBackoffTime || - first.maxCommitBackoffTime != second.maxCommitBackoffTime || - first.sumResolveLockTime != second.sumResolveLockTime || - first.maxResolveLockTime != second.maxResolveLockTime || - first.sumWriteKeys != second.sumWriteKeys || - first.maxWriteKeys != second.maxWriteKeys || - first.sumWriteSize != second.sumWriteSize || - first.maxWriteSize != second.maxWriteSize || - first.sumPrewriteRegionNum != second.sumPrewriteRegionNum || - first.maxPrewriteRegionNum != second.maxPrewriteRegionNum || - first.sumTxnRetry != second.sumTxnRetry || - first.maxTxnRetry != second.maxTxnRetry || - first.sumMem != second.sumMem || - first.maxMem != second.maxMem || - first.sumAffectedRows != second.sumAffectedRows || - first.firstSeen != second.firstSeen || - first.lastSeen != second.lastSeen { + !strings.EqualFold(first.stmtType, second.stmtType) { return false } - if len(first.backoffTypes) != len(second.backoffTypes) { + if first.history.Len() != second.history.Len() { return false } - for key, value1 := range first.backoffTypes { - value2, ok := second.backoffTypes[key] - if ok != true { + ele1 := first.history.Front() + ele2 := second.history.Front() + for { + if ele1 == nil { + break + } + ssElement1 := ele1.Value.(*stmtSummaryByDigestElement) + ssElement2 := ele2.Value.(*stmtSummaryByDigestElement) + if ssElement1.beginTime != ssElement2.beginTime || + ssElement1.sampleSQL != ssElement2.sampleSQL || + ssElement1.sampleUser != ssElement2.sampleUser || + ssElement1.execCount != ssElement2.execCount || + ssElement1.sumLatency != ssElement2.sumLatency || + ssElement1.maxLatency != ssElement2.maxLatency || + ssElement1.minLatency != ssElement2.minLatency || + ssElement1.sumParseLatency != ssElement2.sumParseLatency || + ssElement1.maxParseLatency != ssElement2.maxParseLatency || + ssElement1.sumCompileLatency != ssElement2.sumCompileLatency || + ssElement1.maxCompileLatency != ssElement2.maxCompileLatency || + ssElement1.numCopTasks != ssElement2.numCopTasks || + ssElement1.sumCopProcessTime != ssElement2.sumCopProcessTime || + ssElement1.maxCopProcessTime != ssElement2.maxCopProcessTime || + ssElement1.maxCopProcessAddress != ssElement2.maxCopProcessAddress || + ssElement1.sumCopWaitTime != ssElement2.sumCopWaitTime || + ssElement1.maxCopWaitTime != ssElement2.maxCopWaitTime || + ssElement1.maxCopWaitAddress != ssElement2.maxCopWaitAddress || + ssElement1.sumProcessTime != ssElement2.sumProcessTime || + ssElement1.maxProcessTime != ssElement2.maxProcessTime || + ssElement1.sumWaitTime != ssElement2.sumWaitTime || + ssElement1.maxWaitTime != ssElement2.maxWaitTime || + ssElement1.sumBackoffTime != ssElement2.sumBackoffTime || + ssElement1.maxBackoffTime != ssElement2.maxBackoffTime || + ssElement1.sumTotalKeys != ssElement2.sumTotalKeys || + ssElement1.maxTotalKeys != ssElement2.maxTotalKeys || + ssElement1.sumProcessedKeys != ssElement2.sumProcessedKeys || + ssElement1.maxProcessedKeys != ssElement2.maxProcessedKeys || + ssElement1.sumGetCommitTsTime != ssElement2.sumGetCommitTsTime || + ssElement1.maxGetCommitTsTime != ssElement2.maxGetCommitTsTime || + ssElement1.sumPrewriteTime != ssElement2.sumPrewriteTime || + ssElement1.maxPrewriteTime != ssElement2.maxPrewriteTime || + ssElement1.sumCommitTime != ssElement2.sumCommitTime || + ssElement1.maxCommitTime != ssElement2.maxCommitTime || + ssElement1.sumLocalLatchTime != ssElement2.sumLocalLatchTime || + ssElement1.maxLocalLatchTime != ssElement2.maxLocalLatchTime || + ssElement1.sumCommitBackoffTime != ssElement2.sumCommitBackoffTime || + ssElement1.maxCommitBackoffTime != ssElement2.maxCommitBackoffTime || + ssElement1.sumResolveLockTime != ssElement2.sumResolveLockTime || + ssElement1.maxResolveLockTime != ssElement2.maxResolveLockTime || + ssElement1.sumWriteKeys != ssElement2.sumWriteKeys || + ssElement1.maxWriteKeys != ssElement2.maxWriteKeys || + ssElement1.sumWriteSize != ssElement2.sumWriteSize || + ssElement1.maxWriteSize != ssElement2.maxWriteSize || + ssElement1.sumPrewriteRegionNum != ssElement2.sumPrewriteRegionNum || + ssElement1.maxPrewriteRegionNum != ssElement2.maxPrewriteRegionNum || + ssElement1.sumTxnRetry != ssElement2.sumTxnRetry || + ssElement1.maxTxnRetry != ssElement2.maxTxnRetry || + ssElement1.sumMem != ssElement2.sumMem || + ssElement1.maxMem != ssElement2.maxMem || + ssElement1.sumAffectedRows != ssElement2.sumAffectedRows || + ssElement1.firstSeen != ssElement2.firstSeen || + ssElement1.lastSeen != ssElement2.lastSeen { return false } - if value1 != value2 { + if len(ssElement1.backoffTypes) != len(ssElement2.backoffTypes) { return false } + for key, value1 := range ssElement1.backoffTypes { + value2, ok := ssElement2.backoffTypes[key] + if !ok || value1 != value2 { + return false + } + } + if len(ssElement1.indexNames) != len(ssElement2.indexNames) { + return false + } + for key, value1 := range ssElement1.indexNames { + if value1 != ssElement2.indexNames[key] { + return false + } + } + ele1 = ele1.Next() + ele2 = ele2.Next() } return true } @@ -522,11 +548,11 @@ func (s *testStmtSummarySuite) TestToDatum(c *C) { stmtExecInfo1 := generateAnyExecInfo() s.ssMap.AddStatement(stmtExecInfo1) - datums := s.ssMap.ToDatum() + datums := s.ssMap.ToCurrentDatum() c.Assert(len(datums), Equals, 1) n := types.Time{Time: types.FromGoTime(time.Unix(s.ssMap.beginTimeForCurInterval, 0)), Type: mysql.TypeTimestamp} t := types.Time{Time: types.FromGoTime(stmtExecInfo1.StartTime), Type: mysql.TypeTimestamp} - match(c, datums[0], n, "select", stmtExecInfo1.SchemaName, stmtExecInfo1.Digest, stmtExecInfo1.NormalizedSQL, + expectedDatum := []interface{}{n, "select", stmtExecInfo1.SchemaName, stmtExecInfo1.Digest, stmtExecInfo1.NormalizedSQL, "db1.tb1,db2.tb2", "a", stmtExecInfo1.User, 1, int64(stmtExecInfo1.TotalLatency), int64(stmtExecInfo1.TotalLatency), int64(stmtExecInfo1.TotalLatency), int64(stmtExecInfo1.TotalLatency), int64(stmtExecInfo1.ParseLatency), int64(stmtExecInfo1.ParseLatency), int64(stmtExecInfo1.CompileLatency), @@ -548,7 +574,12 @@ func (s *testStmtSummarySuite) TestToDatum(c *C) { stmtExecInfo1.ExecDetail.CommitDetail.PrewriteRegionNum, stmtExecInfo1.ExecDetail.CommitDetail.PrewriteRegionNum, stmtExecInfo1.ExecDetail.CommitDetail.TxnRetry, stmtExecInfo1.ExecDetail.CommitDetail.TxnRetry, "txnLock:1", stmtExecInfo1.MemMax, stmtExecInfo1.MemMax, stmtExecInfo1.StmtCtx.AffectedRows(), - t, t, stmtExecInfo1.OriginalSQL) + t, t, stmtExecInfo1.OriginalSQL} + match(c, datums[0], expectedDatum...) + + datums = s.ssMap.ToHistoryDatum() + c.Assert(len(datums), Equals, 1) + match(c, datums[0], expectedDatum...) } // Test AddStatement and ToDatum parallel. @@ -574,7 +605,7 @@ func (s *testStmtSummarySuite) TestAddStatementParallel(c *C) { } // There would be 32 summaries. - datums := s.ssMap.ToDatum() + datums := s.ssMap.ToCurrentDatum() c.Assert(len(datums), Equals, loops) } @@ -583,7 +614,7 @@ func (s *testStmtSummarySuite) TestAddStatementParallel(c *C) { } wg.Wait() - datums := s.ssMap.ToDatum() + datums := s.ssMap.ToCurrentDatum() c.Assert(len(datums), Equals, loops) } @@ -645,7 +676,8 @@ func (s *testStmtSummarySuite) TestMaxSQLLength(c *C) { // Length of normalizedSQL and sampleSQL should be maxSQLLength. summary := value.(*stmtSummaryByDigest) c.Assert(len(summary.normalizedSQL), Equals, int(maxSQLLength)) - c.Assert(len(summary.sampleSQL), Equals, int(maxSQLLength)) + ssElement := summary.history.Back().Value.(*stmtSummaryByDigestElement) + c.Assert(len(ssElement.sampleSQL), Equals, int(maxSQLLength)) } // Test setting EnableStmtSummary to 0. @@ -659,14 +691,14 @@ func (s *testStmtSummarySuite) TestDisableStmtSummary(c *C) { stmtExecInfo1 := generateAnyExecInfo() s.ssMap.AddStatement(stmtExecInfo1) - datums := s.ssMap.ToDatum() + datums := s.ssMap.ToCurrentDatum() c.Assert(len(datums), Equals, 0) // Set true in session scope, it will overwrite global scope. s.ssMap.SetEnabled("1", true) s.ssMap.AddStatement(stmtExecInfo1) - datums = s.ssMap.ToDatum() + datums = s.ssMap.ToCurrentDatum() c.Assert(len(datums), Equals, 1) // Set false in global scope, it shouldn't work. @@ -678,33 +710,64 @@ func (s *testStmtSummarySuite) TestDisableStmtSummary(c *C) { stmtExecInfo2.NormalizedSQL = "normalized_sql2" stmtExecInfo2.Digest = "digest2" s.ssMap.AddStatement(stmtExecInfo2) - datums = s.ssMap.ToDatum() + datums = s.ssMap.ToCurrentDatum() c.Assert(len(datums), Equals, 2) // Unset in session scope. s.ssMap.SetEnabled("", true) s.ssMap.beginTimeForCurInterval = now + 60 s.ssMap.AddStatement(stmtExecInfo2) - datums = s.ssMap.ToDatum() + datums = s.ssMap.ToCurrentDatum() c.Assert(len(datums), Equals, 0) // Unset in global scope. s.ssMap.SetEnabled("", false) s.ssMap.beginTimeForCurInterval = now + 60 s.ssMap.AddStatement(stmtExecInfo1) - datums = s.ssMap.ToDatum() + datums = s.ssMap.ToCurrentDatum() c.Assert(len(datums), Equals, 0) // Set back. s.ssMap.SetEnabled("1", false) } +// Test disable and enable statement summary concurrently with adding statements. +func (s *testStmtSummarySuite) TestEnableSummaryParallel(c *C) { + s.ssMap.Clear() + + threads := 8 + loops := 32 + wg := sync.WaitGroup{} + wg.Add(threads) + + addStmtFunc := func() { + defer wg.Done() + stmtExecInfo1 := generateAnyExecInfo() + + // Add 32 times with same digest. + for i := 0; i < loops; i++ { + // Sometimes enable it and sometimes disable it. + s.ssMap.SetEnabled(fmt.Sprintf("%d", i%2), false) + s.ssMap.AddStatement(stmtExecInfo1) + // Try to read it. + s.ssMap.ToHistoryDatum() + } + s.ssMap.SetEnabled("1", false) + } + + for i := 0; i < threads; i++ { + go addStmtFunc() + } + // Ensure that there's no deadlocks. + wg.Wait() + + // Ensure that it's enabled at last. + c.Assert(s.ssMap.Enabled(), IsTrue) +} + // Test GetMoreThanOnceSelect. -func (s *testStmtSummarySuite) TestGetMoreThenOnceSelect(c *C) { +func (s *testStmtSummarySuite) TestGetMoreThanOnceSelect(c *C) { s.ssMap.Clear() - now := time.Now().Unix() - // to disable expiration - s.ssMap.beginTimeForCurInterval = now + 60 stmtExecInfo1 := generateAnyExecInfo() stmtExecInfo1.OriginalSQL = "insert 1" @@ -745,6 +808,8 @@ func (s *testStmtSummarySuite) TestFormatBackoffTypes(c *C) { func (s *testStmtSummarySuite) TestRefreshCurrentSummary(c *C) { s.ssMap.Clear() now := time.Now().Unix() + s.ssMap.SetRefreshInterval("1800", false) + s.ssMap.SetHistorySize("10", false) s.ssMap.beginTimeForCurInterval = now + 10 stmtExecInfo1 := generateAnyExecInfo() @@ -756,16 +821,64 @@ func (s *testStmtSummarySuite) TestRefreshCurrentSummary(c *C) { c.Assert(s.ssMap.summaryMap.Size(), Equals, 1) value, ok := s.ssMap.summaryMap.Get(key) c.Assert(ok, IsTrue) - c.Assert(value.(*stmtSummaryByDigest).beginTime, Equals, s.ssMap.beginTimeForCurInterval) - c.Assert(value.(*stmtSummaryByDigest).execCount, Equals, int64(1)) + ssElement := value.(*stmtSummaryByDigest).history.Back().Value.(*stmtSummaryByDigestElement) + c.Assert(ssElement.beginTime, Equals, s.ssMap.beginTimeForCurInterval) + c.Assert(ssElement.execCount, Equals, int64(1)) s.ssMap.beginTimeForCurInterval = now - 1900 - value.(*stmtSummaryByDigest).beginTime = now - 1900 - s.ssMap.lastCheckExpireTime = now - 10 + ssElement.beginTime = now - 1900 s.ssMap.AddStatement(stmtExecInfo1) c.Assert(s.ssMap.summaryMap.Size(), Equals, 1) value, ok = s.ssMap.summaryMap.Get(key) c.Assert(ok, IsTrue) - c.Assert(value.(*stmtSummaryByDigest).beginTime, Greater, now-1900) - c.Assert(value.(*stmtSummaryByDigest).execCount, Equals, int64(1)) + c.Assert(value.(*stmtSummaryByDigest).history.Len(), Equals, 2) + ssElement = value.(*stmtSummaryByDigest).history.Back().Value.(*stmtSummaryByDigestElement) + c.Assert(ssElement.beginTime, Greater, now-1900) + c.Assert(ssElement.execCount, Equals, int64(1)) + + s.ssMap.SetRefreshInterval("10", false) + s.ssMap.beginTimeForCurInterval = now - 20 + ssElement.beginTime = now - 20 + s.ssMap.AddStatement(stmtExecInfo1) + c.Assert(value.(*stmtSummaryByDigest).history.Len(), Equals, 3) +} + +// Test expiring statement summary to history. +func (s *testStmtSummarySuite) TestSummaryHistory(c *C) { + s.ssMap.Clear() + now := time.Now().Unix() + s.ssMap.SetRefreshInterval("10", false) + s.ssMap.SetHistorySize("10", false) + + stmtExecInfo1 := generateAnyExecInfo() + key := &stmtSummaryByDigestKey{ + schemaName: stmtExecInfo1.SchemaName, + digest: stmtExecInfo1.Digest, + } + for i := 0; i < 11; i++ { + s.ssMap.beginTimeForCurInterval = now + int64(i+1)*10 + s.ssMap.AddStatement(stmtExecInfo1) + c.Assert(s.ssMap.summaryMap.Size(), Equals, 1) + value, ok := s.ssMap.summaryMap.Get(key) + c.Assert(ok, IsTrue) + ssbd := value.(*stmtSummaryByDigest) + if i < 10 { + c.Assert(ssbd.history.Len(), Equals, i+1) + ssElement := ssbd.history.Back().Value.(*stmtSummaryByDigestElement) + c.Assert(ssElement.beginTime, Equals, s.ssMap.beginTimeForCurInterval) + c.Assert(ssElement.execCount, Equals, int64(1)) + } else { + c.Assert(ssbd.history.Len(), Equals, 10) + ssElement := ssbd.history.Back().Value.(*stmtSummaryByDigestElement) + c.Assert(ssElement.beginTime, Equals, s.ssMap.beginTimeForCurInterval) + ssElement = ssbd.history.Front().Value.(*stmtSummaryByDigestElement) + c.Assert(ssElement.beginTime, Equals, now+20) + } + } + datum := s.ssMap.ToHistoryDatum() + c.Assert(len(datum), Equals, 10) + + s.ssMap.SetHistorySize("5", false) + datum = s.ssMap.ToHistoryDatum() + c.Assert(len(datum), Equals, 5) }