Merge pull request #285 from nerdalert/job-times

Add queue time and job time reporting

gobot/cmd/root.go

@@ -257,14 +257,13 @@ func receiveResults(ctx context.Context, redisHostPort string, logger *zap.Sugar
 			if result == "" {
 				continue
 			}
-
-			prNumber, err := r.Get("jobs:" + result + ":pr_number").Result()
+			prNumber, err := r.Get(buildRedisKey(result, handlers.RedisKeyPRNumber)).Result()
 			if err != nil || prNumber == "" {
 				logger.Errorf("No PR number found for job %s", result)
 				continue
 			}
 
-			installID, err := r.Get("jobs:" + result + ":installation_id").Result()
+			installID, err := r.Get(buildRedisKey(result, handlers.RedisKeyInstallationID)).Result()
 			if err != nil || installID == "" {
 				logger.Errorf("No installation ID found for job %s", result)
 				continue
@@ -275,37 +274,57 @@ func receiveResults(ctx context.Context, redisHostPort string, logger *zap.Sugar
 				continue
 			}
 
-			repoOwner, err := r.Get("jobs:" + result + ":repo_owner").Result()
+			repoOwner, err := r.Get(buildRedisKey(result, handlers.RedisKeyRepoOwner)).Result()
 			if err != nil || repoOwner == "" {
 				logger.Errorf("No repo owner found for job %s", result)
 				continue
 			}
 
-			repoName, err := r.Get("jobs:" + result + ":repo_name").Result()
+			repoName, err := r.Get(buildRedisKey(result, handlers.RedisKeyRepoName)).Result()
 			if err != nil || repoName == "" {
 				logger.Errorf("No repo name found for job %s", result)
 				continue
 			}
 
-			jobType, err := r.Get("jobs:" + result + ":job_type").Result()
-			if err != nil || repoName == "" {
+			jobType, err := r.Get(buildRedisKey(result, handlers.RedisKeyJobType)).Result()
+			if err != nil || jobType == "" {
 				logger.Errorf("No job type found for job %s", result)
 				continue
 			}
 
-			prSha, err := r.Get("jobs:" + result + ":pr_sha").Result()
-			if err != nil || repoName == "" {
-				logger.Errorf("No pr sha found for job %s", result)
+			prSha, err := r.Get(buildRedisKey(result, handlers.RedisKeyPRSHA)).Result()
+			if err != nil || prSha == "" {
+				logger.Errorf("No PR SHA found for job %s", result)
 				continue
 			}
 
-			jobDuration, err := r.Get("jobs:" + result + ":duration").Result()
-			if err != nil || jobDuration == "" {
-				// Do not break out of the current iteration since the job could have failed without a duration
-				logger.Warnf("No job duration time found for job %s", result)
+			requestTimeStr, err := r.Get(buildRedisKey(result, handlers.RedisKeyRequestTime)).Result()
+			if err != nil || requestTimeStr == "" {
+				logger.Errorf("No request time found for job %s", result)
+				continue
 			}
+			requestTime, err := strconv.ParseInt(requestTimeStr, 10, 64)
+			if err != nil {
+				logger.Errorf("Error parsing request time for job %s: %v", result, err)
+				continue
+			}
+			totalTime := time.Now().Unix() - requestTime
 
-			logger.Infof("Processing result for %s/%s#%s, job ID: %s ", repoOwner, repoName, prNumber, result)
+			prURL := fmt.Sprintf("https://github.com/%s/%s/pull/%s", repoOwner, repoName, prNumber)
+
+			jobDuration, err := r.Get(buildRedisKey(result, handlers.RedisKeyDuration)).Result()
+			if err != nil || jobDuration == "" {
+				logger.Infof("Job result for %s/%s#%s, job ID: %s, GitHub URL: %s (No job duration time found for job)", repoOwner, repoName, prNumber, result, prURL)
+			} else {
+
+				jobDurationInt, err := strconv.ParseInt(jobDuration, 10, 64)
+				if err != nil {
+					logger.Errorf("Error parsing duration time for job %s: %v", result, err)
+					continue
+				}
+				queueTime := totalTime - jobDurationInt
+				logger.Infof("Job result for %s/%s#%s, job ID: %s, job duration: %s, queue time: %d URL: %s", repoOwner, repoName, prNumber, result, jobDuration, queueTime, prURL)
+			}
 
 			var statusContext string
 			switch jobType {
@@ -412,3 +431,8 @@ func receiveResults(ctx context.Context, redisHostPort string, logger *zap.Sugar
 		}
 	}
 }
+
+// buildRedisKey constructs a Redis key for job attributes.
+func buildRedisKey(jobID, keyType string) string {
+	return fmt.Sprintf("%s:%s:%s", handlers.RedisKeyJobs, jobID, keyType)
+}

gobot/handlers/issue_comment.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"strconv"
 	"strings"
+	"time"
 
 	"github.com/go-redis/redis/v8"
 	"github.com/google/go-github/v60/github"
@@ -23,6 +24,20 @@ const (
 	BotEnabled        = "Bot is successfully enabled."
 )
 
+const (
+	RedisKeyJobs           = "jobs"
+	RedisKeyPRNumber       = "pr_number"
+	RedisKeyPRSHA          = "pr_sha"
+	RedisKeyAuthor         = "author"
+	RedisKeyInstallationID = "installation_id"
+	RedisKeyRepoOwner      = "repo_owner"
+	RedisKeyRepoName       = "repo_name"
+	RedisKeyJobType        = "job_type"
+	RedisKeyErrors         = "errors"
+	RedisKeyRequestTime    = "request_time"
+	RedisKeyDuration       = "duration"
+)
+
 type PRCommentHandler struct {
 	githubapp.ClientCreator
 	Logger         *zap.SugaredLogger
@@ -136,53 +151,59 @@ func (h *PRCommentHandler) queueGenerateJob(ctx context.Context, client *github.
 		DB:       0,  // use default DB
 	})
 
-	jobNumber, err := r.Incr(ctx, "jobs").Result()
+	jobNumber, err := r.Incr(ctx, RedisKeyJobs).Result()
+	if err != nil {
+		return err
+	}
+
+	err = setJobKey(r, jobNumber, RedisKeyPRNumber, prComment.prNum)
 	if err != nil {
 		return err
 	}
 
-	err = setJobKey(r, jobNumber, "pr_number", prComment.prNum)
+	err = setJobKey(r, jobNumber, RedisKeyPRSHA, prComment.prSha)
 	if err != nil {
 		return err
 	}
 
-	err = setJobKey(r, jobNumber, "pr_sha", prComment.prSha)
+	err = setJobKey(r, jobNumber, RedisKeyAuthor, prComment.author)
 	if err != nil {
 		return err
 	}
 
-	err = setJobKey(r, jobNumber, "author", prComment.author)
+	err = setJobKey(r, jobNumber, RedisKeyInstallationID, prComment.installID)
 	if err != nil {
 		return err
 	}
 
-	err = setJobKey(r, jobNumber, "installation_id", prComment.installID)
+	err = setJobKey(r, jobNumber, RedisKeyRepoOwner, prComment.repoOwner)
 	if err != nil {
 		return err
 	}
 
-	err = setJobKey(r, jobNumber, "repo_owner", prComment.repoOwner)
+	err = setJobKey(r, jobNumber, RedisKeyRepoName, prComment.repoName)
 	if err != nil {
 		return err
 	}
 
-	err = setJobKey(r, jobNumber, "repo_name", prComment.repoName)
+	err = setJobKey(r, jobNumber, RedisKeyJobType, jobType)
 	if err != nil {
 		return err
 	}
 
-	err = setJobKey(r, jobNumber, "job_type", jobType)
+	err = setJobKey(r, jobNumber, RedisKeyErrors, "")
 	if err != nil {
 		return err
 	}
 
-	err = setJobKey(r, jobNumber, "errors", "")
+	err = setJobKey(r, jobNumber, RedisKeyRequestTime, strconv.FormatInt(time.Now().Unix(), 10))
 	if err != nil {
 		return err
 	}
 
 	err = r.LPush(ctx, "generate", strconv.FormatInt(jobNumber, 10)).Err()
 	if err != nil {
+		h.Logger.Errorf("Failed to LPUSH job %d to redis %v", jobNumber, err)
 		return err
 	}