Skip to content

Commit

Permalink
store: fix timing of prewrite binlog in slow log (pingcap#15273) (pin…
Browse files Browse the repository at this point in the history 
…gcap#15276)
  • Loading branch information
@jackysp
jackysp authored Mar 11, 2020
1 parent bd70523 commit e4b30a4
Show file tree
Hide file tree
Showing 5 changed files with 68 additions and 65 deletions.
1 change: 1 addition & 0 deletions go.sum
View file
Original file line number Diff line number Diff line change
Expand Up @@ -183,6 +183,7 @@ github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d h1:GoAlyOgbOEIFd
github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
github.com/remyoudompheng/bigfft v0.0.0-20190512091148-babf20351dd7 h1:FUL3b97ZY2EPqg2NbXKuMHs5pXJB9hjj1fDHnF2vl28=
github.com/remyoudompheng/bigfft v0.0.0-20190512091148-babf20351dd7/go.mod h1:qqbHyh8v60DhA7CoWK5oRCqLrMHRGoxYCSS9EjAz6Eo=
github.com/sergi/go-diff v1.0.1-0.20180205163309-da645544ed44 h1:tB9NOR21++IjLyVx3/PCPhWMwqGNCMQEH96A6dMZ/gc=
github.com/sergi/go-diff v1.0.1-0.20180205163309-da645544ed44/go.mod h1:0CfEIISq7TuYL3j771MWULgwwjU+GofnZX9QAmXWZgo=
github.com/shirou/gopsutil v2.18.10+incompatible h1:cy84jW6EVRPa5g9HAHrlbxMSIjBhDSX0OFYyMYminYs=
github.com/shirou/gopsutil v2.18.10+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA=
Expand Down
100 changes: 50 additions & 50 deletions infoschema/slow_log.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -44,7 +44,7 @@ var slowQueryCols = []columnInfo{
{variable.SlowLogParseTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
{variable.SlowLogCompileTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
{execdetails.PreWriteTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
{execdetails.BinlogPrewriteTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
{execdetails.WaitPrewriteBinlogTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
{execdetails.CommitTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
{execdetails.GetCommitTSTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
{execdetails.CommitBackoffTimeStr, mysql.TypeDouble, 22, 0, nil, nil},
Expand Down Expand Up @@ -196,52 +196,52 @@ func getOneLine(reader *bufio.Reader) ([]byte, error) {
}

type slowQueryTuple struct {
time time.Time
txnStartTs uint64
user string
host string
connID uint64
queryTime float64
parseTime float64
compileTime float64
preWriteTime float64
binlogPrewriteTime float64
commitTime float64
getCommitTSTime float64
commitBackoffTime float64
backoffTypes string
resolveLockTime float64
localLatchWaitTime float64
writeKeys uint64
writeSize uint64
prewriteRegion uint64
txnRetry uint64
processTime float64
waitTime float64
backOffTime float64
lockKeysTime float64
requestCount uint64
totalKeys uint64
processKeys uint64
db string
indexIDs string
digest string
statsInfo string
avgProcessTime float64
p90ProcessTime float64
maxProcessTime float64
maxProcessAddress string
avgWaitTime float64
p90WaitTime float64
maxWaitTime float64
maxWaitAddress string
memMax int64
prevStmt string
sql string
isInternal bool
succ bool
plan string
planDigest string
time time.Time
txnStartTs uint64
user string
host string
connID uint64
queryTime float64
parseTime float64
compileTime float64
preWriteTime float64
waitPrewriteBinlogTime float64
commitTime float64
getCommitTSTime float64
commitBackoffTime float64
backoffTypes string
resolveLockTime float64
localLatchWaitTime float64
writeKeys uint64
writeSize uint64
prewriteRegion uint64
txnRetry uint64
processTime float64
waitTime float64
backOffTime float64
lockKeysTime float64
requestCount uint64
totalKeys uint64
processKeys uint64
db string
indexIDs string
digest string
statsInfo string
avgProcessTime float64
p90ProcessTime float64
maxProcessTime float64
maxProcessAddress string
avgWaitTime float64
p90WaitTime float64
maxWaitTime float64
maxWaitAddress string
memMax int64
prevStmt string
sql string
isInternal bool
succ bool
plan string
planDigest string
}

func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string, lineNum int) error {
Expand Down Expand Up @@ -275,8 +275,8 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string,
st.compileTime, err = strconv.ParseFloat(value, 64)
case execdetails.PreWriteTimeStr:
st.preWriteTime, err = strconv.ParseFloat(value, 64)
case execdetails.BinlogPrewriteTimeStr:
st.binlogPrewriteTime, err = strconv.ParseFloat(value, 64)
case execdetails.WaitPrewriteBinlogTimeStr:
st.waitPrewriteBinlogTime, err = strconv.ParseFloat(value, 64)
case execdetails.CommitTimeStr:
st.commitTime, err = strconv.ParseFloat(value, 64)
case execdetails.GetCommitTSTimeStr:
Expand Down Expand Up @@ -369,7 +369,7 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum {
record = append(record, types.NewFloat64Datum(st.parseTime))
record = append(record, types.NewFloat64Datum(st.compileTime))
record = append(record, types.NewFloat64Datum(st.preWriteTime))
record = append(record, types.NewFloat64Datum(st.binlogPrewriteTime))
record = append(record, types.NewFloat64Datum(st.waitPrewriteBinlogTime))
record = append(record, types.NewFloat64Datum(st.commitTime))
record = append(record, types.NewFloat64Datum(st.getCommitTSTime))
record = append(record, types.NewFloat64Datum(st.commitBackoffTime))
Expand Down
6 changes: 4 additions & 2 deletions infoschema/tables_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -313,7 +313,9 @@ type mockSessionManager struct {
processInfoMap map[uint64]*util.ProcessInfo
}

func (sm *mockSessionManager) ShowProcessList() map[uint64]*util.ProcessInfo { return sm.processInfoMap }
func (sm *mockSessionManager) ShowProcessList() map[uint64]*util.ProcessInfo {
return sm.processInfoMap
}

func (sm *mockSessionManager) GetProcessInfo(id uint64) (*util.ProcessInfo, bool) {
rs, ok := sm.processInfoMap[id]
Expand Down Expand Up @@ -469,7 +471,7 @@ func (s *testTableSuite) TestSlowQuery(c *C) {
# Query_time: 4.895492
# Parse_time: 0.4
# Compile_time: 0.2
# Request_count: 1 Prewrite_time: 0.19 Binlog_prewrite_time: 0.21 Commit_time: 0.01 Commit_backoff_time: 0.18 Backoff_types: [txnLock] Resolve_lock_time: 0.03 Write_keys: 15 Write_size: 480 Prewrite_region: 1 Txn_retry: 8
# Request_count: 1 Prewrite_time: 0.19 Wait_prewrite_binlog_time: 0.21 Commit_time: 0.01 Commit_backoff_time: 0.18 Backoff_types: [txnLock] Resolve_lock_time: 0.03 Write_keys: 15 Write_size: 480 Prewrite_region: 1 Txn_retry: 8
# Process_time: 0.161 Request_count: 1 Total_keys: 100001 Process_keys: 100000
# Wait_time: 0.101
# Backoff_time: 0.092 LockKeys_time: 1.72
Expand Down
4 changes: 2 additions & 2 deletions store/tikv/2pc.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1119,7 +1119,6 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) (err error) {
}
}()

binlogPrewriteStart := time.Now()
binlogChan := c.prewriteBinlog()
prewriteBo := NewBackoffer(ctx, prewriteMaxBackoff).WithVars(c.txn.vars)
start := time.Now()
Expand All @@ -1133,7 +1132,9 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) (err error) {
commitDetail.Mu.Unlock()
}
if binlogChan != nil {
startWaitBinlog := time.Now()
binlogWriteResult := <-binlogChan
commitDetail.WaitPrewriteBinlogTime = time.Since(startWaitBinlog)
if binlogWriteResult != nil {
binlogSkipped = binlogWriteResult.Skipped()
binlogErr := binlogWriteResult.GetError()
Expand All @@ -1142,7 +1143,6 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) (err error) {
}
}
}
commitDetail.BinlogPrewriteTime = time.Since(binlogPrewriteStart)
if err != nil {
logutil.Logger(ctx).Debug("2PC failed on prewrite",
zap.Error(err),
Expand Down
22 changes: 11 additions & 11 deletions util/execdetails/execdetails.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -44,13 +44,13 @@ type ExecDetails struct {

// CommitDetails contains commit detail information.
type CommitDetails struct {
GetCommitTsTime time.Duration
PrewriteTime time.Duration
BinlogPrewriteTime time.Duration
CommitTime time.Duration
LocalLatchTime time.Duration
CommitBackoffTime int64
Mu struct {
GetCommitTsTime time.Duration
PrewriteTime time.Duration
WaitPrewriteBinlogTime time.Duration
CommitTime time.Duration
LocalLatchTime time.Duration
CommitBackoffTime int64
Mu struct {
sync.Mutex
BackoffTypes []fmt.Stringer
}
Expand Down Expand Up @@ -78,8 +78,8 @@ const (
ProcessKeysStr = "Process_keys"
// PreWriteTimeStr means the time of pre-write.
PreWriteTimeStr = "Prewrite_time"
// BinlogPrewriteTimeStr means the time of binlog prewrite
BinlogPrewriteTimeStr = "Binlog_prewrite_time"
// WaitPrewriteBinlogTimeStr means the time of waiting prewrite binlog finished when transaction committing.
WaitPrewriteBinlogTimeStr = "Wait_prewrite_binlog_time"
// CommitTimeStr means the time of commit.
CommitTimeStr = "Commit_time"
// GetCommitTSTimeStr means the time of getting commit ts.
Expand Down Expand Up @@ -131,8 +131,8 @@ func (d ExecDetails) String() string {
if commitDetails.PrewriteTime > 0 {
parts = append(parts, PreWriteTimeStr+": "+strconv.FormatFloat(commitDetails.PrewriteTime.Seconds(), 'f', -1, 64))
}
if commitDetails.BinlogPrewriteTime > 0 {
parts = append(parts, BinlogPrewriteTimeStr+": "+strconv.FormatFloat(commitDetails.BinlogPrewriteTime.Seconds(), 'f', -1, 64))
if commitDetails.WaitPrewriteBinlogTime > 0 {
parts = append(parts, WaitPrewriteBinlogTimeStr+": "+strconv.FormatFloat(commitDetails.WaitPrewriteBinlogTime.Seconds(), 'f', -1, 64))
}
if commitDetails.CommitTime > 0 {
parts = append(parts, CommitTimeStr+": "+strconv.FormatFloat(commitDetails.CommitTime.Seconds(), 'f', -1, 64))
Expand Down

0 comments on commit e4b30a4

Please sign in to comment.