From 1033ba77d74d57b1027d5acf00b1f2d5526716f7 Mon Sep 17 00:00:00 2001
From: "lilong.129" <lilong.129@bytedance.com>
Date: Fri, 23 Jun 2023 23:06:56 +0800
Subject: [PATCH] feat: log step elapsed in seconds

---
 hrp/pkg/uixt/ocr_vedem.go |  2 +-
 hrp/runner.go             | 20 ++++++++++++--------
 2 files changed, 13 insertions(+), 9 deletions(-)

diff --git a/hrp/pkg/uixt/ocr_vedem.go b/hrp/pkg/uixt/ocr_vedem.go
index b6b71099..3ce8096a 100644
--- a/hrp/pkg/uixt/ocr_vedem.go
+++ b/hrp/pkg/uixt/ocr_vedem.go
@@ -248,7 +248,7 @@ func (s *veDEMImageService) GetImage(imageBuf *bytes.Buffer) (
 			log.Debug().
 				Str("X-TT-LOGID", logID).
 				Int("image_bytes", size).
-				Float64("elapsed_seconds", elapsed.Seconds()).
+				Float64("elapsed(s)", elapsed.Seconds()).
 				Msg("request OCR service success")
 			break
 		}
diff --git a/hrp/runner.go b/hrp/runner.go
index 829092cd..51e78eed 100644
--- a/hrp/runner.go
+++ b/hrp/runner.go
@@ -539,8 +539,9 @@ func (r *SessionRunner) Start(givenVars map[string]interface{}) error {
 				parsedName = step.Name()
 			}
 			stepName := convertString(parsedName)
-			log.Info().Str("step", stepName).
-				Str("type", string(step.Type())).Msg("run step start")
+			stepType := string(step.Type())
+			log.Info().Str("step", stepName).Str("type", stepType).Msg("run step start")
+			stepStartTime := time.Now()
 
 			// run times of step
 			loopTimes := step.Struct().Loops
@@ -563,10 +564,10 @@ func (r *SessionRunner) Start(givenVars map[string]interface{}) error {
 				}
 
 				// run step
-				stepStartTime := time.Now().Unix()
+				startTime := time.Now().Unix()
 				stepResult, err = step.Run(r)
 				stepResult.Name = stepName + loopIndex
-				stepResult.StartTime = stepStartTime
+				stepResult.StartTime = startTime
 
 				r.updateSummary(stepResult)
 			}
@@ -576,19 +577,22 @@ func (r *SessionRunner) Start(givenVars map[string]interface{}) error {
 				r.sessionVariables[k] = v
 			}
 
+			stepElapsed := time.Since(stepStartTime).Seconds()
 			if err == nil {
-				log.Info().Str("step", stepResult.Name).
-					Str("type", string(stepResult.StepType)).
+				log.Info().Str("step", stepName).
+					Str("type", stepType).
 					Bool("success", true).
+					Float64("elapsed(s)", stepElapsed).
 					Interface("exportVars", stepResult.ExportVars).
 					Msg("run step end")
 				continue
 			}
 
 			// failed
-			log.Error().Err(err).Str("step", stepResult.Name).
-				Str("type", string(stepResult.StepType)).
+			log.Error().Err(err).Str("step", stepName).
+				Str("type", stepType).
 				Bool("success", false).
+				Float64("elapsed(s)", stepElapsed).
 				Msg("run step end")
 
 			// interrupted or timeout, abort running