Measure processing time more precisely

Signed-off-by: Janne Mareike Koschinski <janne@kuschku.de>

main.go

@@ -30,10 +30,15 @@ var imageCounter = promauto.NewCounterVec(
 var imageCounterSuccess = imageCounter.WithLabelValues("success")
 var imageCounterFailure = imageCounter.WithLabelValues("failure")
 
-var imageProcessDuration = promauto.NewCounter(prometheus.CounterOpts{
+var imageProcessDuration = promauto.NewCounterVec(prometheus.CounterOpts{
 	Name: "imghost_process_duration",
-	Help: "The total amount of time spent processing images",
-})
+	Help: "The amount of time spent processing images",
+}, []string{"task"})
+var imageProcessDurationRead = imageProcessDuration.WithLabelValues("read")
+var imageProcessDurationClone = imageProcessDuration.WithLabelValues("clone")
+var imageProcessDurationCrop = imageProcessDuration.WithLabelValues("crop")
+var imageProcessDurationResize = imageProcessDuration.WithLabelValues("resize")
+var imageProcessDurationWrite = imageProcessDuration.WithLabelValues("write")
 
 func main() {
 	config := NewConfigFromEnv()

process.go

@@ -5,21 +5,21 @@ import (
 	"encoding/json"
 	"fmt"
 	"github.com/go-redis/redis/v8"
+	"github.com/prometheus/client_golang/prometheus"
 	"os"
 	"path/filepath"
 	"time"
 )
 
-func trackTime(start time.Time, function func(time.Duration)) {
-	function(time.Now().UTC().Sub(start.UTC()))
+func trackTimeSince(counter prometheus.Counter, start time.Time) time.Time {
+	now := time.Now().UTC()
+	counter.Add(float64(now.Sub(start).Milliseconds()) / 1000.0)
+	return now
 }
 
 func ProcessImage(ctx context.Context, config *Config, client *redis.Client, value string) {
 	queueGaugeInProgress.Inc()
 	defer queueGaugeInProgress.Dec()
-	defer trackTime(time.Now(), func(duration time.Duration) {
-		imageProcessDuration.Add(float64(duration.Milliseconds()))
-	})
 
 	image := Image{}
 	if err := json.Unmarshal([]byte(value), &image); err != nil {

resize.go

@@ -5,6 +5,7 @@ import (
 	"github.com/justjanne/imgconv"
 	"gopkg.in/gographics/imagick.v3/imagick"
 	"path/filepath"
+	"time"
 )
 
 func ResizeImage(config *Config, imageId string) []error {
@@ -13,6 +14,7 @@ func ResizeImage(config *Config, imageId string) []error {
 	wand := imagick.NewMagickWand()
 	defer wand.Destroy()
 
+	startRead := time.Now().UTC()
 	if err = wand.ReadImage(filepath.Join(config.SourceFolder, imageId)); err != nil {
 		return []error{err}
 	}
@@ -20,20 +22,26 @@ func ResizeImage(config *Config, imageId string) []error {
 	if originalImage, err = imgconv.NewImage(wand); err != nil {
 		return []error{err}
 	}
+	trackTimeSince(imageProcessDurationRead, startRead)
 
 	return runMany(len(config.Sizes), func(index int) error {
 		definition := config.Sizes[index]
 		path := filepath.Join(config.TargetFolder, fmt.Sprintf("%s%s", imageId, definition.Suffix))
+		startClone := time.Now().UTC()
 		image := originalImage.CloneImage()
+		startCrop := trackTimeSince(imageProcessDurationClone, startClone)
 		if err := image.Crop(definition.Size); err != nil {
 			return err
 		}
+		startResize := trackTimeSince(imageProcessDurationCrop, startCrop)
 		if err := image.Resize(definition.Size); err != nil {
 			return err
 		}
+		startWrite := trackTimeSince(imageProcessDurationResize, startResize)
 		if err := image.Write(config.Quality, path); err != nil {
 			return err
 		}
+		trackTimeSince(imageProcessDurationWrite, startWrite)
 		return nil
 	})
 }