add a stopwatch around cropping pngquanting

common-lib/src/main/scala/com/gu/mediaservice/lib/imaging/ImageOperations.scala

@@ -83,7 +83,7 @@ class ImageOperations(playPath: String) extends GridLogging {
     colourModel: Option[String],
     fileType: MimeType,
     isTransformedFromSource: Boolean
-  )(implicit logMarker: LogMarker): Future[File] = {
+  )(implicit logMarker: LogMarker): Future[File] = Stopwatch.async("magick crop image") {
     for {
       outputFile <- createTempFile(s"crop-", s"${fileType.fileExtension}", tempDir)
       cropSource    = addImage(sourceFile)
@@ -115,7 +115,7 @@ class ImageOperations(playPath: String) extends GridLogging {
     qual: Double = 100d,
     tempDir: File,
     fileType: MimeType
-  )(implicit logMarker: LogMarker): Future[File] = {
+  )(implicit logMarker: LogMarker): Future[File] = Stopwatch.async("magick resize image") {
     for {
       outputFile  <- createTempFile(s"resize-", s".${fileType.fileExtension}", tempDir)
       resizeSource = addImage(sourceFile)
@@ -127,12 +127,14 @@ class ImageOperations(playPath: String) extends GridLogging {
     yield outputFile
   }
 
-  def optimiseImage(resizedFile: File, mediaType: MimeType): File = mediaType match {
+  def optimiseImage(resizedFile: File, mediaType: MimeType)(implicit logMarker: LogMarker): File = mediaType match {
     case Png =>
       val fileName: String = resizedFile.getAbsolutePath
 
       val optimisedImageName: String = fileName.split('.')(0) + "optimised.png"
-      Seq("pngquant","-s8",  "--quality", "1-85", fileName, "--output", optimisedImageName).!
+      Stopwatch("pngquant") {
+        Seq("pngquant", "-s10", "--quality", "1-85", fileName, "--output", optimisedImageName).!
+      }
 
       new File(optimisedImageName)
     case Jpeg => resizedFile

common-lib/src/main/scala/com/gu/mediaservice/lib/imaging/im4jwrapper/ImageMagick.scala

@@ -2,7 +2,7 @@ package com.gu.mediaservice.lib.imaging.im4jwrapper
 
 import java.util.concurrent.Executors
 import java.io.File
-import com.gu.mediaservice.lib.logging.{GridLogging, LogMarker}
+import com.gu.mediaservice.lib.logging.{GridLogging, LogMarker, Stopwatch}
 import org.im4java.process.ArrayListOutputConsumer
 
 import scala.jdk.CollectionConverters._
@@ -82,18 +82,22 @@ object ImageMagick extends GridLogging {
   }
 
   def runConvertCmd(op: IMOperation, useImageMagick: Boolean)(implicit logMarker: LogMarker): Future[Unit] = {
-    logger.info(logMarker, s"Using ${if(useImageMagick) { "imagemagick" } else { "graphicsmagick" }} for imaging conversion operation $op")
-
-    Future(new ConvertCmd(!useImageMagick).run(op))
+    Stopwatch.async(s"Using ${if(useImageMagick) "imagemagick" else "graphicsmagick"} for imaging conversion operation '$op'") {
+      Future {
+        new ConvertCmd(!useImageMagick).run(op)
+      }
+    }
   }
 
-  def runIdentifyCmd(op: IMOperation, useImageMagick: Boolean)(implicit logMarker: LogMarker): Future[List[String]] = Future {
-    logger.info(logMarker, s"Using ${if(useImageMagick) { "imagemagick" } else { "graphicsmagick" }} for imaging identification operation $op")
-
-    val cmd = new IdentifyCmd(!useImageMagick)
-    val output = new ArrayListOutputConsumer()
-    cmd.setOutputConsumer(output)
-    cmd.run(op)
-    output.getOutput.asScala.toList
+  def runIdentifyCmd(op: IMOperation, useImageMagick: Boolean)(implicit logMarker: LogMarker): Future[List[String]] = {
+    Stopwatch.async(s"Using ${if (useImageMagick) "imagemagick" else "graphicsmagick"} for imaging identification operation '$op'") {
+      Future {
+        val cmd = new IdentifyCmd(!useImageMagick)
+        val output = new ArrayListOutputConsumer()
+        cmd.setOutputConsumer(output)
+        cmd.run(op)
+        output.getOutput.asScala.toList
+      }
+    }
   }
 }

common-lib/src/main/scala/com/gu/mediaservice/lib/logging/Stopwatch.scala

@@ -3,7 +3,9 @@ package com.gu.mediaservice.lib.logging
 import java.time.ZonedDateTime
 import com.gu.mediaservice.lib.DateTimeUtils
 
+import scala.concurrent.{ExecutionContext, Future}
 import scala.concurrent.duration._
+import scala.util.control.NonFatal
 
 case class DurationForLogging(startTime: ZonedDateTime, duration: Duration) extends LogMarker {
   def toMillis: Long = duration.toMillis
@@ -32,15 +34,37 @@ class Stopwatch  {
 object Stopwatch extends GridLogging {
   def start: Stopwatch = new Stopwatch
 
-  def apply[T](label: String)(body: => T)(implicit marker: LogMarker): T = {
+  def async[T](label: String)(body: Future[T])(implicit marker: LogMarker, ec: ExecutionContext): Future[T] = {
+    val stopwatch = new Stopwatch
+    try {
+      body.onComplete { _ =>
+        logger.info(addMarkers("elapsed" -> s"${stopwatch.elapsed.duration.toMillis} ms").toLogMarker,
+          s"Stopwatch: $label")
+      }
+      body
+    } catch {
+      case NonFatal(e) =>
+        logger.error(
+          addMarkers("elapsed" -> s"${stopwatch.elapsed.duration.toMillis} ms").toLogMarker,
+          s"Stopwatch: $label: errored",
+          e)
+        throw e
+    }
+  }
 
+  def apply[T](label: String)(body: => T)(implicit marker: LogMarker): T = {
     val stopwatch = new Stopwatch
     try {
       val result = body
-      logger.info(addMarkers("elapsed" -> stopwatch.elapsed.duration.toString).toLogMarker, s"Stopwatch: $label")
+      logger.info(addMarkers("elapsed" -> s"${stopwatch.elapsed.duration.toMillis} ms").toLogMarker, s"Stopwatch: $label")
       result
     } catch {
-      case e: Exception => logger.error(s"Stopwatch: $label ${stopwatch.elapsed} ns", e); throw e
+      case NonFatal(e) =>
+        logger.error(
+          addMarkers("elapsed" -> s"${stopwatch.elapsed.duration.toMillis} ms").toLogMarker,
+          s"Stopwatch: $label: errored",
+          e)
+        throw e
     }
   }
 

cropper/app/lib/Crops.scala

@@ -22,10 +22,13 @@ class Crops(config: CropperConfig, store: CropStore, imageOperations: ImageOpera
 
   private val cropQuality = 75d
   private val masterCropQuality = 95d
+  // For PNGs, Magick considers "quality" parameter as effort spent on compression - 1 meaning none, 100 meaning max.
+  // We don't overly care about output crop file sizes here, but prefer a fast output, so turn it right down.
+  private val pngCropQuality = 1d
 
   def outputFilename(source: SourceImage, bounds: Bounds, outputWidth: Int, fileType: MimeType, isMaster: Boolean = false): String = {
     val masterString: String = if (isMaster) "master/" else ""
-    s"${source.id}/${Crop.getCropId(bounds)}/${masterString}$outputWidth${fileType.fileExtension}"
+    s"${source.id}/${Crop.getCropId(bounds)}/$masterString$outputWidth${fileType.fileExtension}"
   }
 
   def createMasterCrop(
@@ -36,41 +39,52 @@ class Crops(config: CropperConfig, store: CropStore, imageOperations: ImageOpera
     colourModel: Option[String],
   )(implicit logMarker: LogMarker): Future[MasterCrop] = {
 
-    val source   = crop.specification
-    val metadata = apiImage.metadata
-    val iccColourSpace = FileMetadataHelper.normalisedIccColourSpace(apiImage.fileMetadata)
-
-    logger.info(logMarker, s"creating master crop for ${apiImage.id}")
-
-    for {
-      strip <- imageOperations.cropImage(
-        sourceFile, apiImage.source.mimeType, source.bounds, masterCropQuality, config.tempDir,
-        iccColourSpace, colourModel, mediaType, isTransformedFromSource = false
-      )
-      file: File <- imageOperations.appendMetadata(strip, metadata)
-      dimensions  = Dimensions(source.bounds.width, source.bounds.height)
-      filename    = outputFilename(apiImage, source.bounds, dimensions.width, mediaType, isMaster = true)
-      sizing      = store.storeCropSizing(file, filename, mediaType, crop, dimensions)
-      dirtyAspect = source.bounds.width.toFloat / source.bounds.height
-      aspect      = crop.specification.aspectRatio.flatMap(AspectRatio.clean).getOrElse(dirtyAspect)
+    Stopwatch.async(s"creating master crop for ${apiImage.id}") {
+      val source = crop.specification
+      val metadata = apiImage.metadata
+      val iccColourSpace = FileMetadataHelper.normalisedIccColourSpace(apiImage.fileMetadata)
+      // pngs are always lossless, so quality only means effort spent compressing them. We don't
+      // care too much about filesize of master crops, so skip expensive compression to get faster cropping
+      val quality = if (mediaType == Png) pngCropQuality else masterCropQuality
+
+      for {
+        strip <- imageOperations.cropImage(
+          sourceFile, apiImage.source.mimeType, source.bounds, quality, config.tempDir,
+          iccColourSpace, colourModel, mediaType, isTransformedFromSource = false
+        )
+        file: File <- imageOperations.appendMetadata(strip, metadata)
+        dimensions = Dimensions(source.bounds.width, source.bounds.height)
+        filename = outputFilename(apiImage, source.bounds, dimensions.width, mediaType, isMaster = true)
+        sizing = store.storeCropSizing(file, filename, mediaType, crop, dimensions)
+        dirtyAspect = source.bounds.width.toFloat / source.bounds.height
+        aspect = crop.specification.aspectRatio.flatMap(AspectRatio.clean).getOrElse(dirtyAspect)
+      }
+      yield MasterCrop(sizing, file, dimensions, aspect)
     }
-    yield MasterCrop(sizing, file, dimensions, aspect)
   }
 
   def createCrops(sourceFile: File, dimensionList: List[Dimensions], apiImage: SourceImage, crop: Crop, cropType: MimeType)(implicit logMarker: LogMarker): Future[List[Asset]] = {
-    logger.info(logMarker, s"creating crops for ${apiImage.id}")
-
-    Future.sequence(dimensionList.map { dimensions =>
-      for {
-        file          <- imageOperations.resizeImage(sourceFile, apiImage.source.mimeType, dimensions, cropQuality, config.tempDir, cropType)
-        optimisedFile = imageOperations.optimiseImage(file, cropType)
-        filename      = outputFilename(apiImage, crop.specification.bounds, dimensions.width, cropType)
-        sizing        <- store.storeCropSizing(optimisedFile, filename, cropType, crop, dimensions)
-        _             <- delete(file)
-        _             <- delete(optimisedFile)
-      }
-      yield sizing
-    })
+    val quality = if (cropType == Png) pngCropQuality else cropQuality
+
+    Stopwatch.async(s"creating crops for ${apiImage.id}") {
+      Future.sequence(dimensionList.map { dimensions =>
+        val cropLogMarker = logMarker ++ Map("crop-dimensions" -> s"${dimensions.width}x${dimensions.height}")
+        for {
+          file <- imageOperations.resizeImage(sourceFile,
+            apiImage.source.mimeType,
+            dimensions,
+            quality,
+            config.tempDir,
+            cropType)(cropLogMarker)
+          optimisedFile = imageOperations.optimiseImage(file, cropType)(cropLogMarker)
+          filename = outputFilename(apiImage, crop.specification.bounds, dimensions.width, cropType)
+          sizing <- store.storeCropSizing(optimisedFile, filename, cropType, crop, dimensions)(cropLogMarker)
+          _ <- delete(file)
+          _ <- delete(optimisedFile)
+        }
+        yield sizing
+      })
+    }
   }
 
   def deleteCrops(id: String)(implicit logMarker: LogMarker): Future[Unit] = store.deleteCrops(id)
@@ -97,7 +111,7 @@ class Crops(config: CropperConfig, store: CropStore, imageOperations: ImageOpera
     val hasAlpha = apiImage.fileMetadata.colourModelInformation.get("hasAlpha").flatMap(a => Try(a.toBoolean).toOption).getOrElse(true)
     val cropType = Crops.cropType(mimeType, colourType, hasAlpha)
 
-    Stopwatch(s"making crop assets for ${apiImage.id} ${Crop.getCropId(source.bounds)}") {
+    Stopwatch.async(s"making crop assets for ${apiImage.id} ${Crop.getCropId(source.bounds)}") {
       for {
         sourceFile <- tempFileFromURL(secureUrl, "cropSource", "", config.tempDir)
         colourModel <- ImageOperations.identifyColourModel(sourceFile, mimeType)
@@ -126,8 +140,7 @@ object Crops {
     val outputAsPng = hasAlpha || isGraphic
 
     mediaType match {
-      case Png if outputAsPng => Png
-      case Tiff if outputAsPng => Png
+      case Png | Tiff if outputAsPng => Png
       case _ => Jpeg
     }
   }

image-loader/app/model/Uploader.scala

@@ -330,8 +330,10 @@ class Uploader(val store: ImageLoaderStore,
                        (implicit logMarker: LogMarker): Future[ImageUpload] = {
     val sideEffectDependencies = ImageUploadOpsDependencies(toImageUploadOpsCfg(config), imageOps,
       storeSource, storeThumbnail, storeOptimisedImage)
-    val finalImage = fromUploadRequestShared(uploadRequest, sideEffectDependencies, imageProcessor)
-    finalImage.map(img => Stopwatch("finalImage"){ImageUpload(uploadRequest, img)})
+    Stopwatch.async("finalImage") {
+      val finalImage = fromUploadRequestShared(uploadRequest, sideEffectDependencies, imageProcessor)
+      finalImage.map(img => ImageUpload(uploadRequest, img))
+    }
   }
 
   private def storeSource(storableOriginalImage: StorableOriginalImage)