Print cache performance statistics at the end of the build

Cache write statistics is printed always
Cache read statistics is printed in case reads take more than 1 second in total

src/main/kotlin/ch/myniva/gradle/caching/s3/AwsS3Plugin.kt

@@ -18,13 +18,11 @@ package ch.myniva.gradle.caching.s3
 import ch.myniva.gradle.caching.s3.internal.AwsS3BuildCacheServiceFactory
 import org.gradle.api.Plugin
 import org.gradle.api.initialization.Settings
-import org.slf4j.LoggerFactory
+import org.gradle.api.logging.Logging
 
-class AwsS3Plugin : Plugin<Settings> {
-    companion object {
-        private val logger = LoggerFactory.getLogger(AwsS3Plugin::class.java)
-    }
+private val logger = Logging.getLogger(AwsS3Plugin::class.java)
 
+class AwsS3Plugin : Plugin<Settings> {
     override fun apply(settings: Settings) {
         logger.info("Registering S3 build cache")
         settings.buildCache.registerBuildCacheService(

src/main/kotlin/ch/myniva/gradle/caching/s3/internal/AwsS3BuildCacheService.kt

@@ -20,12 +20,15 @@ import com.amazonaws.services.s3.model.AmazonS3Exception
 import com.amazonaws.services.s3.model.ObjectMetadata
 import com.amazonaws.services.s3.model.PutObjectRequest
 import com.amazonaws.services.s3.model.StorageClass
+import org.gradle.api.logging.LogLevel
+import org.gradle.api.logging.Logging
 import org.gradle.caching.*
-import org.slf4j.LoggerFactory
 import java.io.ByteArrayInputStream
 import java.io.ByteArrayOutputStream
 import java.io.IOException
 
+private val logger = Logging.getLogger(AwsS3BuildCacheService::class.java)
+
 class AwsS3BuildCacheService internal constructor(
     private val s3: AmazonS3,
     private val bucketName: String,
@@ -35,32 +38,60 @@ class AwsS3BuildCacheService internal constructor(
 ) : BuildCacheService {
     companion object {
         private const val BUILD_CACHE_CONTENT_TYPE = "application/vnd.gradle.build-cache-artifact"
-        private val logger = LoggerFactory.getLogger(AwsS3BuildCacheService::class.java)
     }
 
-    override fun close() = s3.shutdown()
+    private val cacheLoads = Stopwatch()
+    private val cacheHits = Stopwatch()
+    private val cacheStores = Stopwatch()
+
+    override fun close() {
+        fun Long.mib() = (this + 512L * 1024) / (1024L * 1024)
+
+        s3.shutdown()
+        if (cacheLoads.starts != 0) {
+            logger.log(
+                if (cacheHits.elapsed > 1000) LogLevel.LIFECYCLE else LogLevel.INFO,
+                "S3 cache reads: ${cacheHits.starts}, requests: ${cacheLoads.starts}, " +
+                        "elapsed time: ${cacheLoads.elapsed}ms, processed: ${cacheLoads.bytes.mib()}MiB"
+            )
+        }
+        if (cacheStores.starts != 0) {
+            logger.lifecycle(
+                "S3 cache writes: ${cacheStores.starts}, " +
+                        "elapsed time: ${cacheStores.elapsed}ms, sent to cache: ${cacheStores.bytes.mib()}MiB"
+            )
+        }
+    }
 
     private fun BuildCacheKey.getBucketPath() = if (path.isNullOrEmpty()) {
         hashCode
     } else {
         "$path/$hashCode"
     }
 
-    override fun load(key: BuildCacheKey, reader: BuildCacheEntryReader): Boolean {
+    override fun load(key: BuildCacheKey, reader: BuildCacheEntryReader): Boolean = cacheLoads {
+        loadInternal(key, reader)
+    }
+
+    private fun Stopwatch.loadInternal(key: BuildCacheKey, reader: BuildCacheEntryReader): Boolean {
         val bucketPath = key.getBucketPath()
         try {
             s3.getObject(bucketName, bucketPath).use { s3Object ->
-                if (s3Object.objectMetadata.contentLength > maximumCachedObjectLength) {
+                val contentLength = s3Object.objectMetadata.contentLength
+                if (contentLength > maximumCachedObjectLength) {
                     logger.info(
                         "Cache item '{}' '{}' in S3 bucket size is {}, and it exceeds maximumCachedObjectLength {}. Will skip the retrieval",
                         key.displayName,
                         bucketPath,
-                        s3Object.objectMetadata.contentLength,
+                        contentLength,
                         maximumCachedObjectLength
                     )
                     return false
                 }
-                reader.readFrom(s3Object.objectContent)
+                bytesProcessed(contentLength)
+                cacheHits {
+                    reader.readFrom(s3Object.objectContent)
+                }
             }
             return true
         } catch (e: AmazonS3Exception) {
@@ -85,7 +116,11 @@ class AwsS3BuildCacheService internal constructor(
         }
     }
 
-    override fun store(key: BuildCacheKey, writer: BuildCacheEntryWriter) {
+    override fun store(key: BuildCacheKey, writer: BuildCacheEntryWriter) = cacheStores {
+        storeInternal(key, writer)
+    }
+
+    private fun Stopwatch.storeInternal(key: BuildCacheKey, writer: BuildCacheEntryWriter) {
         val bucketPath = key.getBucketPath()
         val itemSize = writer.size
         if (itemSize > maximumCachedObjectLength) {
@@ -98,6 +133,7 @@ class AwsS3BuildCacheService internal constructor(
             )
             return
         }
+        bytesProcessed(itemSize)
         logger.info("Start storing cache entry '{}' in S3 bucket", bucketPath)
         val meta = ObjectMetadata().apply {
             contentType = BUILD_CACHE_CONTENT_TYPE
@@ -118,5 +154,4 @@ class AwsS3BuildCacheService internal constructor(
             throw BuildCacheException("Error while storing cache object in S3 bucket", e)
         }
     }
-
 }

src/main/kotlin/ch/myniva/gradle/caching/s3/internal/AwsS3BuildCacheServiceFactory.kt

@@ -27,11 +27,9 @@ import org.gradle.caching.BuildCacheService
 import org.gradle.caching.BuildCacheServiceFactory
 import org.slf4j.LoggerFactory
 
-class AwsS3BuildCacheServiceFactory : BuildCacheServiceFactory<AwsS3BuildCache> {
-    companion object {
-        private val logger = LoggerFactory.getLogger(AwsS3BuildCacheServiceFactory::class.java)
-    }
+private val logger = LoggerFactory.getLogger(AwsS3BuildCacheServiceFactory::class.java)
 
+class AwsS3BuildCacheServiceFactory : BuildCacheServiceFactory<AwsS3BuildCache> {
     override fun createBuildCacheService(
         config: AwsS3BuildCache,
         describer: BuildCacheServiceFactory.Describer

src/main/kotlin/ch/myniva/gradle/caching/s3/internal/Stopwatch.kt

@@ -0,0 +1,47 @@
+/*
+ * Copyright 2019 Vladimir Sitnikov <sitnikov.vladimir@gmail.com>
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ *
+ */
+package ch.myniva.gradle.caching.s3.internal
+
+import java.util.concurrent.atomic.AtomicInteger
+import java.util.concurrent.atomic.AtomicLong
+
+class Stopwatch {
+    val elapsed: Long get() = elapsedTime.get()
+    val starts: Int get() = startCount.get()
+    val bytes: Long get() = bytesProcessed.get()
+
+    private var elapsedTime = AtomicLong()
+    private var startCount = AtomicInteger()
+    private var bytesProcessed = AtomicLong()
+
+    fun bytesProcessed(bytes: Long) {
+        bytesProcessed.addAndGet(bytes)
+    }
+
+    operator fun <T> invoke(bytes: Long = 0, action: Stopwatch.() -> T): T {
+        val startTime = System.currentTimeMillis()
+        startCount.incrementAndGet()
+        if (bytes != 0L) {
+            bytesProcessed.addAndGet(bytes)
+        }
+        try {
+            return action()
+        } finally {
+            elapsedTime.addAndGet(System.currentTimeMillis() - startTime)
+        }
+    }
+}