diff --git a/api/app/grade.go b/api/app/grade.go index 2ef47a8..b5e14be 100644 --- a/api/app/grade.go +++ b/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 diff --git a/api/app/grade_requests.go b/api/app/grade_requests.go index f0b92ce..6c0aa70 100644 --- a/api/app/grade_requests.go +++ b/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. diff --git a/api/app/prometheus.go b/api/app/prometheus.go index 7b37dd1..94390d5 100644 --- a/api/app/prometheus.go +++ b/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) } diff --git a/api/shared/shared_structs.go b/api/shared/shared_structs.go index 2e00ce4..f56dbe6 100644 --- a/api/shared/shared_structs.go +++ b/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, diff --git a/api/worker/submission_handler.go b/api/worker/submission_handler.go index 580c09a..ac36835 100644 --- a/api/worker/submission_handler.go +++ b/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