Skip to content

Commit 0f8ee23

Browse files
andrew-nowakandrew-nowak
authored
Merge pull request #4471 from guardian/an/stopwatch-crop-pngquanting
add a stopwatch around cropping pngquanting
2 parents fa6d732 + 5b5c4db commit 0f8ee23

5 files changed

Lines changed: 101 additions & 56 deletions

File tree

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

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -83,7 +83,7 @@ class ImageOperations(playPath: String) extends GridLogging {
8383
colourModel: Option[String],
8484
fileType: MimeType,
8585
isTransformedFromSource: Boolean
86-
)(implicit logMarker: LogMarker): Future[File] = {
86+
)(implicit logMarker: LogMarker): Future[File] = Stopwatch.async("magick crop image") {
8787
for {
8888
outputFile <- createTempFile(s"crop-", s"${fileType.fileExtension}", tempDir)
8989
cropSource = addImage(sourceFile)
@@ -115,7 +115,7 @@ class ImageOperations(playPath: String) extends GridLogging {
115115
qual: Double = 100d,
116116
tempDir: File,
117117
fileType: MimeType
118-
)(implicit logMarker: LogMarker): Future[File] = {
118+
)(implicit logMarker: LogMarker): Future[File] = Stopwatch.async("magick resize image") {
119119
for {
120120
outputFile <- createTempFile(s"resize-", s".${fileType.fileExtension}", tempDir)
121121
resizeSource = addImage(sourceFile)
@@ -127,12 +127,14 @@ class ImageOperations(playPath: String) extends GridLogging {
127127
yield outputFile
128128
}
129129

130-
def optimiseImage(resizedFile: File, mediaType: MimeType): File = mediaType match {
130+
def optimiseImage(resizedFile: File, mediaType: MimeType)(implicit logMarker: LogMarker): File = mediaType match {
131131
case Png =>
132132
val fileName: String = resizedFile.getAbsolutePath
133133

134134
val optimisedImageName: String = fileName.split('.')(0) + "optimised.png"
135-
Seq("pngquant","-s8", "--quality", "1-85", fileName, "--output", optimisedImageName).!
135+
Stopwatch("pngquant") {
136+
Seq("pngquant", "-s10", "--quality", "1-85", fileName, "--output", optimisedImageName).!
137+
}
136138

137139
new File(optimisedImageName)
138140
case Jpeg => resizedFile

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

Lines changed: 16 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@ package com.gu.mediaservice.lib.imaging.im4jwrapper
22

33
import java.util.concurrent.Executors
44
import java.io.File
5-
import com.gu.mediaservice.lib.logging.{GridLogging, LogMarker}
5+
import com.gu.mediaservice.lib.logging.{GridLogging, LogMarker, Stopwatch}
66
import org.im4java.process.ArrayListOutputConsumer
77

88
import scala.jdk.CollectionConverters._
@@ -82,18 +82,22 @@ object ImageMagick extends GridLogging {
8282
}
8383

8484
def runConvertCmd(op: IMOperation, useImageMagick: Boolean)(implicit logMarker: LogMarker): Future[Unit] = {
85-
logger.info(logMarker, s"Using ${if(useImageMagick) { "imagemagick" } else { "graphicsmagick" }} for imaging conversion operation $op")
86-
87-
Future(new ConvertCmd(!useImageMagick).run(op))
85+
Stopwatch.async(s"Using ${if(useImageMagick) "imagemagick" else "graphicsmagick"} for imaging conversion operation '$op'") {
86+
Future {
87+
new ConvertCmd(!useImageMagick).run(op)
88+
}
89+
}
8890
}
8991

90-
def runIdentifyCmd(op: IMOperation, useImageMagick: Boolean)(implicit logMarker: LogMarker): Future[List[String]] = Future {
91-
logger.info(logMarker, s"Using ${if(useImageMagick) { "imagemagick" } else { "graphicsmagick" }} for imaging identification operation $op")
92-
93-
val cmd = new IdentifyCmd(!useImageMagick)
94-
val output = new ArrayListOutputConsumer()
95-
cmd.setOutputConsumer(output)
96-
cmd.run(op)
97-
output.getOutput.asScala.toList
92+
def runIdentifyCmd(op: IMOperation, useImageMagick: Boolean)(implicit logMarker: LogMarker): Future[List[String]] = {
93+
Stopwatch.async(s"Using ${if (useImageMagick) "imagemagick" else "graphicsmagick"} for imaging identification operation '$op'") {
94+
Future {
95+
val cmd = new IdentifyCmd(!useImageMagick)
96+
val output = new ArrayListOutputConsumer()
97+
cmd.setOutputConsumer(output)
98+
cmd.run(op)
99+
output.getOutput.asScala.toList
100+
}
101+
}
98102
}
99103
}

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

Lines changed: 27 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,9 @@ package com.gu.mediaservice.lib.logging
33
import java.time.ZonedDateTime
44
import com.gu.mediaservice.lib.DateTimeUtils
55

6+
import scala.concurrent.{ExecutionContext, Future}
67
import scala.concurrent.duration._
8+
import scala.util.control.NonFatal
79

810
case class DurationForLogging(startTime: ZonedDateTime, duration: Duration) extends LogMarker {
911
def toMillis: Long = duration.toMillis
@@ -32,15 +34,37 @@ class Stopwatch {
3234
object Stopwatch extends GridLogging {
3335
def start: Stopwatch = new Stopwatch
3436

35-
def apply[T](label: String)(body: => T)(implicit marker: LogMarker): T = {
37+
def async[T](label: String)(body: Future[T])(implicit marker: LogMarker, ec: ExecutionContext): Future[T] = {
38+
val stopwatch = new Stopwatch
39+
try {
40+
body.onComplete { _ =>
41+
logger.info(addMarkers("elapsed" -> s"${stopwatch.elapsed.duration.toMillis} ms").toLogMarker,
42+
s"Stopwatch: $label")
43+
}
44+
body
45+
} catch {
46+
case NonFatal(e) =>
47+
logger.error(
48+
addMarkers("elapsed" -> s"${stopwatch.elapsed.duration.toMillis} ms").toLogMarker,
49+
s"Stopwatch: $label: errored",
50+
e)
51+
throw e
52+
}
53+
}
3654

55+
def apply[T](label: String)(body: => T)(implicit marker: LogMarker): T = {
3756
val stopwatch = new Stopwatch
3857
try {
3958
val result = body
40-
logger.info(addMarkers("elapsed" -> stopwatch.elapsed.duration.toString).toLogMarker, s"Stopwatch: $label")
59+
logger.info(addMarkers("elapsed" -> s"${stopwatch.elapsed.duration.toMillis} ms").toLogMarker, s"Stopwatch: $label")
4160
result
4261
} catch {
43-
case e: Exception => logger.error(s"Stopwatch: $label ${stopwatch.elapsed} ns", e); throw e
62+
case NonFatal(e) =>
63+
logger.error(
64+
addMarkers("elapsed" -> s"${stopwatch.elapsed.duration.toMillis} ms").toLogMarker,
65+
s"Stopwatch: $label: errored",
66+
e)
67+
throw e
4468
}
4569
}
4670

‎cropper/app/lib/Crops.scala‎

Lines changed: 48 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -22,10 +22,13 @@ class Crops(config: CropperConfig, store: CropStore, imageOperations: ImageOpera
2222

2323
private val cropQuality = 75d
2424
private val masterCropQuality = 95d
25+
// For PNGs, Magick considers "quality" parameter as effort spent on compression - 1 meaning none, 100 meaning max.
26+
// We don't overly care about output crop file sizes here, but prefer a fast output, so turn it right down.
27+
private val pngCropQuality = 1d
2528

2629
def outputFilename(source: SourceImage, bounds: Bounds, outputWidth: Int, fileType: MimeType, isMaster: Boolean = false): String = {
2730
val masterString: String = if (isMaster) "master/" else ""
28-
s"${source.id}/${Crop.getCropId(bounds)}/${masterString}$outputWidth${fileType.fileExtension}"
31+
s"${source.id}/${Crop.getCropId(bounds)}/$masterString$outputWidth${fileType.fileExtension}"
2932
}
3033

3134
def createMasterCrop(
@@ -36,41 +39,52 @@ class Crops(config: CropperConfig, store: CropStore, imageOperations: ImageOpera
3639
colourModel: Option[String],
3740
)(implicit logMarker: LogMarker): Future[MasterCrop] = {
3841

39-
val source = crop.specification
40-
val metadata = apiImage.metadata
41-
val iccColourSpace = FileMetadataHelper.normalisedIccColourSpace(apiImage.fileMetadata)
42-
43-
logger.info(logMarker, s"creating master crop for ${apiImage.id}")
44-
45-
for {
46-
strip <- imageOperations.cropImage(
47-
sourceFile, apiImage.source.mimeType, source.bounds, masterCropQuality, config.tempDir,
48-
iccColourSpace, colourModel, mediaType, isTransformedFromSource = false
49-
)
50-
file: File <- imageOperations.appendMetadata(strip, metadata)
51-
dimensions = Dimensions(source.bounds.width, source.bounds.height)
52-
filename = outputFilename(apiImage, source.bounds, dimensions.width, mediaType, isMaster = true)
53-
sizing = store.storeCropSizing(file, filename, mediaType, crop, dimensions)
54-
dirtyAspect = source.bounds.width.toFloat / source.bounds.height
55-
aspect = crop.specification.aspectRatio.flatMap(AspectRatio.clean).getOrElse(dirtyAspect)
42+
Stopwatch.async(s"creating master crop for ${apiImage.id}") {
43+
val source = crop.specification
44+
val metadata = apiImage.metadata
45+
val iccColourSpace = FileMetadataHelper.normalisedIccColourSpace(apiImage.fileMetadata)
46+
// pngs are always lossless, so quality only means effort spent compressing them. We don't
47+
// care too much about filesize of master crops, so skip expensive compression to get faster cropping
48+
val quality = if (mediaType == Png) pngCropQuality else masterCropQuality
49+
50+
for {
51+
strip <- imageOperations.cropImage(
52+
sourceFile, apiImage.source.mimeType, source.bounds, quality, config.tempDir,
53+
iccColourSpace, colourModel, mediaType, isTransformedFromSource = false
54+
)
55+
file: File <- imageOperations.appendMetadata(strip, metadata)
56+
dimensions = Dimensions(source.bounds.width, source.bounds.height)
57+
filename = outputFilename(apiImage, source.bounds, dimensions.width, mediaType, isMaster = true)
58+
sizing = store.storeCropSizing(file, filename, mediaType, crop, dimensions)
59+
dirtyAspect = source.bounds.width.toFloat / source.bounds.height
60+
aspect = crop.specification.aspectRatio.flatMap(AspectRatio.clean).getOrElse(dirtyAspect)
61+
}
62+
yield MasterCrop(sizing, file, dimensions, aspect)
5663
}
57-
yield MasterCrop(sizing, file, dimensions, aspect)
5864
}
5965

6066
def createCrops(sourceFile: File, dimensionList: List[Dimensions], apiImage: SourceImage, crop: Crop, cropType: MimeType)(implicit logMarker: LogMarker): Future[List[Asset]] = {
61-
logger.info(logMarker, s"creating crops for ${apiImage.id}")
62-
63-
Future.sequence(dimensionList.map { dimensions =>
64-
for {
65-
file <- imageOperations.resizeImage(sourceFile, apiImage.source.mimeType, dimensions, cropQuality, config.tempDir, cropType)
66-
optimisedFile = imageOperations.optimiseImage(file, cropType)
67-
filename = outputFilename(apiImage, crop.specification.bounds, dimensions.width, cropType)
68-
sizing <- store.storeCropSizing(optimisedFile, filename, cropType, crop, dimensions)
69-
_ <- delete(file)
70-
_ <- delete(optimisedFile)
71-
}
72-
yield sizing
73-
})
67+
val quality = if (cropType == Png) pngCropQuality else cropQuality
68+
69+
Stopwatch.async(s"creating crops for ${apiImage.id}") {
70+
Future.sequence(dimensionList.map { dimensions =>
71+
val cropLogMarker = logMarker ++ Map("crop-dimensions" -> s"${dimensions.width}x${dimensions.height}")
72+
for {
73+
file <- imageOperations.resizeImage(sourceFile,
74+
apiImage.source.mimeType,
75+
dimensions,
76+
quality,
77+
config.tempDir,
78+
cropType)(cropLogMarker)
79+
optimisedFile = imageOperations.optimiseImage(file, cropType)(cropLogMarker)
80+
filename = outputFilename(apiImage, crop.specification.bounds, dimensions.width, cropType)
81+
sizing <- store.storeCropSizing(optimisedFile, filename, cropType, crop, dimensions)(cropLogMarker)
82+
_ <- delete(file)
83+
_ <- delete(optimisedFile)
84+
}
85+
yield sizing
86+
})
87+
}
7488
}
7589

7690
def deleteCrops(id: String)(implicit logMarker: LogMarker): Future[Unit] = store.deleteCrops(id)
@@ -97,7 +111,7 @@ class Crops(config: CropperConfig, store: CropStore, imageOperations: ImageOpera
97111
val hasAlpha = apiImage.fileMetadata.colourModelInformation.get("hasAlpha").flatMap(a => Try(a.toBoolean).toOption).getOrElse(true)
98112
val cropType = Crops.cropType(mimeType, colourType, hasAlpha)
99113

100-
Stopwatch(s"making crop assets for ${apiImage.id} ${Crop.getCropId(source.bounds)}") {
114+
Stopwatch.async(s"making crop assets for ${apiImage.id} ${Crop.getCropId(source.bounds)}") {
101115
for {
102116
sourceFile <- tempFileFromURL(secureUrl, "cropSource", "", config.tempDir)
103117
colourModel <- ImageOperations.identifyColourModel(sourceFile, mimeType)
@@ -126,8 +140,7 @@ object Crops {
126140
val outputAsPng = hasAlpha || isGraphic
127141

128142
mediaType match {
129-
case Png if outputAsPng => Png
130-
case Tiff if outputAsPng => Png
143+
case Png | Tiff if outputAsPng => Png
131144
case _ => Jpeg
132145
}
133146
}

‎image-loader/app/model/Uploader.scala‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -330,8 +330,10 @@ class Uploader(val store: ImageLoaderStore,
330330
(implicit logMarker: LogMarker): Future[ImageUpload] = {
331331
val sideEffectDependencies = ImageUploadOpsDependencies(toImageUploadOpsCfg(config), imageOps,
332332
storeSource, storeThumbnail, storeOptimisedImage)
333-
val finalImage = fromUploadRequestShared(uploadRequest, sideEffectDependencies, imageProcessor)
334-
finalImage.map(img => Stopwatch("finalImage"){ImageUpload(uploadRequest, img)})
333+
Stopwatch.async("finalImage") {
334+
val finalImage = fromUploadRequestShared(uploadRequest, sideEffectDependencies, imageProcessor)
335+
finalImage.map(img => ImageUpload(uploadRequest, img))
336+
}
335337
}
336338

337339
private def storeSource(storableOriginalImage: StorableOriginalImage)

0 commit comments

Comments
 (0)