Include cache save/restore times in Job Summary (#389)

Fixes #370

sources/src/caching/cache-reporting.ts

@@ -110,10 +110,12 @@ export class CacheEntryListener {
     requestedRestoreKeys: string[] | undefined
     restoredKey: string | undefined
     restoredSize: number | undefined
+    restoredTime: number | undefined
     notRestored: string | undefined
 
     savedKey: string | undefined
     savedSize: number | undefined
+    savedTime: number | undefined
     notSaved: string | undefined
 
     constructor(entryName: string) {
@@ -130,9 +132,10 @@ export class CacheEntryListener {
         return this
     }
 
-    markRestored(key: string, size: number | undefined): CacheEntryListener {
+    markRestored(key: string, size: number | undefined, time: number): CacheEntryListener {
         this.restoredKey = key
         this.restoredSize = size
+        this.restoredTime = time
         return this
     }
 
@@ -141,9 +144,10 @@ export class CacheEntryListener {
         return this
     }
 
-    markSaved(key: string, size: number | undefined): CacheEntryListener {
+    markSaved(key: string, size: number | undefined, time: number): CacheEntryListener {
         this.savedKey = key
         this.savedSize = size
+        this.savedTime = time
         return this
     }
 
@@ -182,14 +186,16 @@ ${renderEntryTable(entries)}
 function renderEntryTable(entries: CacheEntryListener[]): string {
     return `
 <table>
-    <tr><td></td><th>Count</th><th>Total Size (Mb)</th></tr>
+    <tr><td></td><th>Count</th><th>Total Size (Mb)</th><th>Total Time (ms)</tr>
     <tr><td>Entries Restored</td>
         <td>${getCount(entries, e => e.restoredSize)}</td>
         <td>${getSize(entries, e => e.restoredSize)}</td>
+        <td>${getTime(entries, e => e.restoredTime)}</td>
     </tr>
     <tr><td>Entries Saved</td>
         <td>${getCount(entries, e => e.savedSize)}</td>
         <td>${getSize(entries, e => e.savedSize)}</td>
+        <td>${getTime(entries, e => e.savedTime)}</td>
     </tr>
 </table>
     `
@@ -202,9 +208,11 @@ function renderEntryDetails(listener: CacheListener): string {
     Requested Key : ${entry.requestedKey ?? ''}
     Restored  Key : ${entry.restoredKey ?? ''}
               Size: ${formatSize(entry.restoredSize)}
+              Time: ${formatTime(entry.restoredTime)}
               ${getRestoredMessage(entry, listener.cacheWriteOnly)}
     Saved     Key : ${entry.savedKey ?? ''}
               Size: ${formatSize(entry.savedSize)}
+              Time: ${formatTime(entry.savedTime)}
               ${getSavedMessage(entry, listener.cacheReadOnly)}
 `
         )
@@ -264,9 +272,23 @@ function getSize(
     return Math.round(bytes / (1024 * 1024))
 }
 
+function getTime(
+    cacheEntries: CacheEntryListener[],
+    predicate: (value: CacheEntryListener) => number | undefined
+): number {
+    return cacheEntries.map(e => predicate(e) ?? 0).reduce((p, v) => p + v, 0)
+}
+
 function formatSize(bytes: number | undefined): string {
     if (bytes === undefined || bytes === 0) {
         return ''
     }
     return `${Math.round(bytes / (1024 * 1024))} MB (${bytes} B)`
 }
+
+function formatTime(ms: number | undefined): string {
+    if (ms === undefined || ms === 0) {
+        return ''
+    }
+    return `${ms} ms`
+}

sources/src/caching/cache-utils.ts

@@ -38,13 +38,14 @@ export async function restoreCache(
 ): Promise<cache.CacheEntry | undefined> {
     listener.markRequested(cacheKey, cacheRestoreKeys)
     try {
+        const startTime = Date.now()
         // Only override the read timeout if the SEGMENT_DOWNLOAD_TIMEOUT_MINS env var has NOT been set
         const cacheRestoreOptions = process.env[SEGMENT_DOWNLOAD_TIMEOUT_VAR]
             ? {}
             : {segmentTimeoutInMs: SEGMENT_DOWNLOAD_TIMEOUT_DEFAULT}
         const restoredEntry = await cache.restoreCache(cachePath, cacheKey, cacheRestoreKeys, cacheRestoreOptions)
         if (restoredEntry !== undefined) {
-            listener.markRestored(restoredEntry.key, restoredEntry.size)
+            listener.markRestored(restoredEntry.key, restoredEntry.size, Date.now() - startTime)
         }
         return restoredEntry
     } catch (error) {
@@ -56,8 +57,9 @@ export async function restoreCache(
 
 export async function saveCache(cachePath: string[], cacheKey: string, listener: CacheEntryListener): Promise<void> {
     try {
+        const startTime = Date.now()
         const savedEntry = await cache.saveCache(cachePath, cacheKey)
-        listener.markSaved(savedEntry.key, savedEntry.size)
+        listener.markSaved(savedEntry.key, savedEntry.size, Date.now() - startTime)
     } catch (error) {
         if (error instanceof cache.ReserveCacheError) {
             listener.markAlreadyExists(cacheKey)

sources/src/caching/gradle-home-extry-extractor.ts

@@ -134,7 +134,7 @@ abstract class AbstractEntryExtractor {
     ): Promise<ExtractedCacheEntry> {
         const restoredEntry = await restoreCache([pattern], cacheKey, [], listener)
         if (restoredEntry) {
-            core.info(`Restored ${artifactType} with key ${cacheKey} to ${pattern}`)
+            core.info(`Restored ${artifactType} with key ${cacheKey} to ${pattern} in ${listener.restoredTime}ms`)
             return new ExtractedCacheEntry(artifactType, pattern, cacheKey)
         } else {
             core.info(`Did not restore ${artifactType} with key ${cacheKey} to ${pattern}`)
@@ -232,8 +232,8 @@ abstract class AbstractEntryExtractor {
             cacheDebug(`No change to previously restored ${artifactType}. Not saving.`)
             entryListener.markNotSaved('contents unchanged')
         } else {
-            core.info(`Caching ${artifactType} with path '${pattern}' and cache key: ${cacheKey}`)
             await saveCache([pattern], cacheKey, entryListener)
+            core.info(`Saved ${artifactType} with key ${cacheKey} from ${pattern} in ${entryListener.savedTime}ms`)
         }
 
         for (const file of matchingFiles) {

sources/src/caching/gradle-user-home-cache.ts

@@ -60,7 +60,8 @@ export class GradleUserHomeCache {
     restoreKeys:[${cacheKey.restoreKeys}]`
         )
 
-        const cacheResult = await restoreCache(this.getCachePath(), cacheKey.key, cacheKey.restoreKeys, entryListener)
+        const cachePath = this.getCachePath()
+        const cacheResult = await restoreCache(cachePath, cacheKey.key, cacheKey.restoreKeys, entryListener)
         if (!cacheResult) {
             core.info(`${this.cacheDescription} cache not found. Will initialize empty.`)
             return
@@ -68,7 +69,9 @@ export class GradleUserHomeCache {
 
         core.saveState(RESTORED_CACHE_KEY_KEY, cacheResult.key)
 
-        core.info(`Restored ${this.cacheDescription} from cache key: ${cacheResult.key}`)
+        core.info(
+            `Restored ${this.cacheDescription} with key ${cacheResult.key} to ${cachePath.join()} in ${entryListener.restoredTime}ms`
+        )
 
         try {
             await this.afterRestore(listener)
@@ -120,9 +123,11 @@ export class GradleUserHomeCache {
             return
         }
 
-        core.info(`Caching ${this.cacheDescription} with cache key: ${cacheKey}`)
         const cachePath = this.getCachePath()
         await saveCache(cachePath, cacheKey, gradleHomeEntryListener)
+        core.info(
+            `Saved ${this.cacheDescription} with key ${cacheKey} from ${cachePath.join()} in ${gradleHomeEntryListener.savedTime}ms`
+        )
 
         return
     }

sources/test/jest/cache-reporting.test.ts

@@ -1,3 +1,4 @@
+import exp from 'constants'
 import {CacheEntryListener, CacheListener} from '../../src/caching/cache-reporting'
 
 describe('caching report', () => {
@@ -5,7 +6,7 @@ describe('caching report', () => {
         it('with one requested entry report', async () => {
             const report = new CacheListener()
             report.entry('foo').markRequested('1', ['2'])
-            report.entry('bar').markRequested('3').markRestored('4', 500)
+            report.entry('bar').markRequested('3').markRestored('4', 500, 1000)
             expect(report.fullyRestored).toBe(false)
         })
     })
@@ -22,13 +23,13 @@ describe('caching report', () => {
         })
         it('with restored entry report', async () => {
             const report = new CacheListener()
-            report.entry('bar').markRequested('3').markRestored('4', 300)
+            report.entry('bar').markRequested('3').markRestored('4', 300, 1000)
             expect(report.fullyRestored).toBe(true)
         })
         it('with multiple restored entry reportss', async () => {
             const report = new CacheListener()
-            report.entry('foo').markRestored('4', 3300)
+            report.entry('foo').markRestored('4', 3300, 111)
-            report.entry('bar').markRequested('3').markRestored('4', 333)
+            report.entry('bar').markRequested('3').markRestored('4', 333, 1000)
             expect(report.fullyRestored).toBe(true)
         })
     })
@@ -64,7 +65,7 @@ describe('caching report', () => {
             const report = new CacheListener()
             const entryReport = report.entry('foo')
             entryReport.markRequested('1', ['2', '3'])
-            entryReport.markSaved('4', 100)
+            entryReport.markSaved('4', 100, 1000)
 
             const stringRep = report.stringify()
             const reportClone: CacheListener = CacheListener.rehydrate(stringRep)
@@ -73,6 +74,8 @@ describe('caching report', () => {
             expect(entryClone.requestedKey).toBe('1')
             expect(entryClone.requestedRestoreKeys).toEqual(['2', '3'])
             expect(entryClone.savedKey).toBe('4')
+            expect(entryClone.savedSize).toBe(100)
+            expect(entryClone.savedTime).toBe(1000)
         })
         it('with live entry report', async () => {
             const report = new CacheListener()
@@ -85,7 +88,7 @@ describe('caching report', () => {
 
             // Check type and call method on rehydrated entry report
             expect(entryClone).toBeInstanceOf(CacheEntryListener)
-            entryClone.markSaved('4', 100)
+            entryClone.markSaved('4', 100, 1000)
 
             expect(entryClone.requestedKey).toBe('1')
             expect(entryClone.requestedRestoreKeys).toEqual(['2', '3'])