add metrics to measure duration of test-runs

api/app/grade.go

@@ -160,6 +160,24 @@ func (rs *GradeResource) PublicResultEditHandler(w http.ResponseWriter, r *http.
 		).Inc()
 	}
 
+	totalTime := data.FinishedAt.Sub(data.EnqueuedAt)
+	runTime := data.FinishedAt.Sub(data.StartedAt)
+	waitTime := data.StartedAt.Sub(data.EnqueuedAt)
+
+	totalDockerTimeHist.WithLabelValues(
+		fmt.Sprintf("%d", submission.TaskID),
+		"public",
+	).Observe(totalTime.Seconds())
+
+	totalDockerRunTimeHist.WithLabelValues(
+		fmt.Sprintf("%d", submission.TaskID),
+		"public",
+	).Observe(runTime.Seconds())
+
+	totalDockerWaitTimeHist.WithLabelValues(
+		fmt.Sprintf("%d", submission.TaskID),
+		"public",
+	).Observe(waitTime.Seconds())
 	// currentGrade.PublicTestLog = data.Log
 	// currentGrade.PublicTestStatus = data.Status
 	// currentGrade.PublicExecutionState = 2
@@ -216,6 +234,25 @@ func (rs *GradeResource) PrivateResultEditHandler(w http.ResponseWriter, r *http
 		).Inc()
 	}
 
+	totalTime := data.FinishedAt.Sub(data.EnqueuedAt)
+	runTime := data.FinishedAt.Sub(data.StartedAt)
+	waitTime := data.StartedAt.Sub(data.EnqueuedAt)
+
+	totalDockerTimeHist.WithLabelValues(
+		fmt.Sprintf("%d", submission.TaskID),
+		"private",
+	).Observe(totalTime.Seconds())
+
+	totalDockerRunTimeHist.WithLabelValues(
+		fmt.Sprintf("%d", submission.TaskID),
+		"private",
+	).Observe(runTime.Seconds())
+
+	totalDockerWaitTimeHist.WithLabelValues(
+		fmt.Sprintf("%d", submission.TaskID),
+		"private",
+	).Observe(waitTime.Seconds())
+
 	// currentGrade.PrivateTestLog = data.Log
 	// currentGrade.PrivateTestStatus = data.Status
 	// currentGrade.PrivateExecutionState = 2

api/app/grade_requests.go

@@ -20,6 +20,7 @@ package app
 
 import (
 	"net/http"
+	"time"
 
 	"github.com/cgtuebingen/infomark-backend/symbol"
 	validation "github.com/go-ozzo/ozzo-validation"
@@ -60,8 +61,11 @@ func (body *GradeRequest) Validate() error {
 // GradeFromWorkerRequest represents the request a backendwork will sent
 // after completion.
 type GradeFromWorkerRequest struct {
-	Log    string               `json:"log" example:"failed in line ..."`
-	Status symbol.TestingResult `json:"status" example:"1"`
+	Log        string               `json:"log" example:"failed in line ..."`
+	Status     symbol.TestingResult `json:"status" example:"1"`
+	EnqueuedAt time.Time            `json:"enqueued_at"`
+	StartedAt  time.Time            `json:"started_at"`
+	FinishedAt time.Time            `json:"finished_at"`
 }
 
 // Bind preprocesses a GradeRequest.

api/app/prometheus.go

@@ -66,6 +66,39 @@ var (
 		//
 		[]string{"task_id", "kind"},
 	)
+
+	totalDockerTimeHist = prometheus.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Namespace: "worker",
+			Subsystem: "submissions",
+			Name:      "totalTime",
+			Help:      "Total time in seconds taken from received upload to finished docker run",
+		},
+		//
+		[]string{"task_id", "kind"},
+	)
+
+	totalDockerRunTimeHist = prometheus.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Namespace: "worker",
+			Subsystem: "submissions",
+			Name:      "totalRunTime",
+			Help:      "Total time in seconds taken spent inside docker when running tests",
+		},
+		//
+		[]string{"task_id", "kind"},
+	)
+
+	totalDockerWaitTimeHist = prometheus.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Namespace: "worker",
+			Subsystem: "submissions",
+			Name:      "totalWaitTime",
+			Help:      "Total time waited between uploading and fetched from worker",
+		},
+		//
+		[]string{"task_id", "kind"},
+	)
 )
 
 func init() {
@@ -74,4 +107,7 @@ func init() {
 	prometheus.MustRegister(totalDockerFailExitCounterVec)
 	prometheus.MustRegister(totalDockerSuccessExitCounterVec)
 	prometheus.MustRegister(totalFailedLoginsVec)
+	prometheus.MustRegister(totalDockerTimeHist)
+	prometheus.MustRegister(totalDockerRunTimeHist)
+	prometheus.MustRegister(totalDockerWaitTimeHist)
 }

api/shared/shared_structs.go

@@ -20,24 +20,29 @@ package shared
 
 import (
 	"fmt"
+	"time"
 )
 
 // SubmissionAMQPWorkerRequest is the message which is handed over to the background workers
 type SubmissionAMQPWorkerRequest struct {
-	SubmissionID      int64  `json:"submission_id"`
-	AccessToken       string `json:"access_token"`
-	FrameworkFileURL  string `json:"framework_file_url"`
-	SubmissionFileURL string `json:"submission_file_url"`
-	ResultEndpointURL string `json:"result_endpoint_url"`
-	DockerImage       string `json:"docker_image"`
-	Sha256            string `json:"sha_256"`
+	SubmissionID      int64     `json:"submission_id"`
+	AccessToken       string    `json:"access_token"`
+	FrameworkFileURL  string    `json:"framework_file_url"`
+	SubmissionFileURL string    `json:"submission_file_url"`
+	ResultEndpointURL string    `json:"result_endpoint_url"`
+	DockerImage       string    `json:"docker_image"`
+	Sha256            string    `json:"sha_256"`
+	EnqueuedAt        time.Time `json:"enqueued_at"`
 }
 
-// SubmissionWorkerResponse is the message handed from the workers to the server
-type SubmissionWorkerResponse struct {
-	Log    string `json:"log"`
-	Status int    `json:"status"`
-}
+// // SubmissionWorkerResponse is the message handed from the workers to the server
+// type SubmissionWorkerResponse struct {
+// 	Log        string    `json:"log"`
+// 	Status     int       `json:"status"`
+// 	EnqueuedAt time.Time `json:"enqueued_at"`
+// 	StartedAt  time.Time `json:"started_at"`
+// 	FinishedAt time.Time `json:"finished_at"`
+// }
 
 // NewSubmissionAMQPWorkerRequest creates a new message for the workers
 func NewSubmissionAMQPWorkerRequest(
@@ -46,6 +51,7 @@ func NewSubmissionAMQPWorkerRequest(
 
 	return &SubmissionAMQPWorkerRequest{
 		SubmissionID: submissionID,
+		EnqueuedAt:   time.Now(),
 		AccessToken:  accessToken,
 		FrameworkFileURL: fmt.Sprintf("%s/api/v1/courses/%d/tasks/%d/%s_file",
 			url,

api/worker/submission_handler.go

@@ -28,6 +28,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/cgtuebingen/infomark-backend/api/app"
 	"github.com/cgtuebingen/infomark-backend/api/helper"
 	"github.com/cgtuebingen/infomark-backend/api/shared"
 	"github.com/cgtuebingen/infomark-backend/service"
@@ -237,7 +238,7 @@ func (h *RealSubmissionHandler) Handle(body []byte) error {
 	// Under circumstances there is no guarantee that the following request will be issues
 	// BEFORE the actual test result.
 	// we use a HTTP Request to send the answer
-	// r = tape.BuildDataRequest("POST", msg.ResultEndpointURL, tape.ToH(&shared.SubmissionWorkerResponse{
+	// r = tape.BuildDataRequest("POST", msg.ResultEndpointURL, tape.ToH(&app.GradeFromWorkerRequest{
 	//   Log:    "submission is currently being tested ...",
 	//   Status: 1,
 	// }))
@@ -271,7 +272,9 @@ func (h *RealSubmissionHandler) Handle(body []byte) error {
 	var exit int64
 	var stdout string
 
-	var workerResp *shared.SubmissionWorkerResponse
+	workerResp := &app.GradeFromWorkerRequest{}
+	workerResp.EnqueuedAt = msg.EnqueuedAt
+	workerResp.StartedAt = time.Now()
 
 	stdout, exit, err = ds.Run(
 		msg.DockerImage,
@@ -292,10 +295,10 @@ func (h *RealSubmissionHandler) Handle(body []byte) error {
 	if exit == symbol.TestingResultSuccess.AsInt64() {
 		stdout = cleanDockerOutput(stdout)
 		// 3. push result back to server
-		workerResp = &shared.SubmissionWorkerResponse{
-			Log:    stdout,
-			Status: int(exit),
-		}
+		workerResp.Log = stdout
+		workerResp.Status = symbol.TestingResult(exit)
+		workerResp.FinishedAt = time.Now()
+
 	} else {
 
 		DefaultLogger.WithFields(logrus.Fields{
@@ -305,13 +308,12 @@ func (h *RealSubmissionHandler) Handle(body []byte) error {
 			"image":        msg.DockerImage,
 		}).Warn(err)
 
-		workerResp = &shared.SubmissionWorkerResponse{
-			Log: fmt.Sprintf(`
-        There has been an issue during testing your upload (The ID is %v).
+		workerResp.Log = fmt.Sprintf(`There has been an issue during testing your upload (The ID is %v).
         The testing-framework has failed (not the server).\n`,
-				msg.SubmissionID),
-			Status: int(exit),
-		}
+			msg.SubmissionID)
+		workerResp.Status = symbol.TestingResult(exit)
+		workerResp.FinishedAt = time.Now()
+
 	}
 
 	// we use a HTTP Request to send the answer