Log duration using seconds instead of the default Duration.String(). …

…It would help the log collector to parse the duration. (#9015)

executor/adapter.go

@@ -396,12 +396,12 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) {
 	execDetail := sessVars.StmtCtx.GetExecDetails()
 	if costTime < threshold {
 		logutil.SlowQueryLogger.Debugf(
-			"[QUERY] %vcost_time:%v %s succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v",
-			internal, costTime, execDetail, succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql)
+			"[QUERY] %vcost_time:%vs %s succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v",
+			internal, costTime.Seconds(), execDetail, succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql)
 	} else {
 		logutil.SlowQueryLogger.Warnf(
-			"[SLOW_QUERY] %vcost_time:%v %s succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v",
-			internal, costTime, execDetail, succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql)
+			"[SLOW_QUERY] %vcost_time:%vs %s succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v",
+			internal, costTime.Seconds(), execDetail, succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql)
 		metrics.TotalQueryProcHistogram.Observe(costTime.Seconds())
 		metrics.TotalCopProcHistogram.Observe(execDetail.ProcessTime.Seconds())
 		metrics.TotalCopWaitHistogram.Observe(execDetail.WaitTime.Seconds())

util/execdetails/execdetails.go

@@ -53,13 +53,13 @@ type CommitDetails struct {
 func (d ExecDetails) String() string {
 	parts := make([]string, 0, 6)
 	if d.ProcessTime > 0 {
-		parts = append(parts, fmt.Sprintf("process_time:%v", d.ProcessTime))
+		parts = append(parts, fmt.Sprintf("process_time:%vs", d.ProcessTime.Seconds()))
 	}
 	if d.WaitTime > 0 {
-		parts = append(parts, fmt.Sprintf("wait_time:%v", d.WaitTime))
+		parts = append(parts, fmt.Sprintf("wait_time:%vs", d.WaitTime.Seconds()))
 	}
 	if d.BackoffTime > 0 {
-		parts = append(parts, fmt.Sprintf("backoff_time:%v", d.BackoffTime))
+		parts = append(parts, fmt.Sprintf("backoff_time:%vs", d.BackoffTime.Seconds()))
 	}
 	if d.RequestCount > 0 {
 		parts = append(parts, fmt.Sprintf("request_count:%d", d.RequestCount))
@@ -73,23 +73,23 @@ func (d ExecDetails) String() string {
 	commitDetails := d.CommitDetail
 	if commitDetails != nil {
 		if commitDetails.PrewriteTime > 0 {
-			parts = append(parts, fmt.Sprintf("prewrite_time:%v", commitDetails.PrewriteTime))
+			parts = append(parts, fmt.Sprintf("prewrite_time:%vs", commitDetails.PrewriteTime.Seconds()))
 		}
 		if commitDetails.CommitTime > 0 {
-			parts = append(parts, fmt.Sprintf("commit_time:%v", commitDetails.CommitTime))
+			parts = append(parts, fmt.Sprintf("commit_time:%vs", commitDetails.CommitTime.Seconds()))
 		}
 		if commitDetails.GetCommitTsTime > 0 {
-			parts = append(parts, fmt.Sprintf("get_commit_ts_time:%v", commitDetails.GetCommitTsTime))
+			parts = append(parts, fmt.Sprintf("get_commit_ts_time:%vs", commitDetails.GetCommitTsTime.Seconds()))
 		}
 		if commitDetails.TotalBackoffTime > 0 {
-			parts = append(parts, fmt.Sprintf("total_backoff_time:%v", commitDetails.TotalBackoffTime))
+			parts = append(parts, fmt.Sprintf("total_backoff_time:%vs", commitDetails.TotalBackoffTime.Seconds()))
 		}
 		resolveLockTime := atomic.LoadInt64(&commitDetails.ResolveLockTime)
 		if resolveLockTime > 0 {
-			parts = append(parts, fmt.Sprintf("resolve_lock_time:%d", time.Duration(resolveLockTime)))
+			parts = append(parts, fmt.Sprintf("resolve_lock_time:%vs", time.Duration(resolveLockTime).Seconds()))
 		}
 		if commitDetails.LocalLatchTime > 0 {
-			parts = append(parts, fmt.Sprintf("local_latch_wait_time:%v", commitDetails.LocalLatchTime))
+			parts = append(parts, fmt.Sprintf("local_latch_wait_time:%vs", commitDetails.LocalLatchTime.Seconds()))
 		}
 		if commitDetails.WriteKeys > 0 {
 			parts = append(parts, fmt.Sprintf("write_keys:%d", commitDetails.WriteKeys))

util/execdetails/execdetails_test.go

@@ -20,14 +20,26 @@ import (
 
 func TestString(t *testing.T) {
 	detail := &ExecDetails{
-		ProcessTime:   time.Second,
+		ProcessTime:   2*time.Second + 5*time.Millisecond,
 		WaitTime:      time.Second,
 		BackoffTime:   time.Second,
 		RequestCount:  1,
 		TotalKeys:     100,
 		ProcessedKeys: 10,
+		CommitDetail: &CommitDetails{
+			GetCommitTsTime:   time.Second,
+			PrewriteTime:      time.Second,
+			CommitTime:        time.Second,
+			LocalLatchTime:    time.Second,
+			TotalBackoffTime:  time.Second,
+			ResolveLockTime:   1000000000, // 10^9 ns = 1s
+			WriteKeys:         1,
+			WriteSize:         1,
+			PrewriteRegionNum: 1,
+			TxnRetry:          1,
+		},
 	}
-	expected := "process_time:1s wait_time:1s backoff_time:1s request_count:1 total_keys:100 processed_keys:10"
+	expected := "process_time:2.005s wait_time:1s backoff_time:1s request_count:1 total_keys:100 processed_keys:10 prewrite_time:1s commit_time:1s get_commit_ts_time:1s total_backoff_time:1s resolve_lock_time:1s local_latch_wait_time:1s write_keys:1 write_size:1 prewrite_region:1 txn_retry:1"
 	if str := detail.String(); str != expected {
 		t.Errorf("got:\n%s\nexpected:\n%s", str, expected)
 	}