diff --git a/sources/src/caching/cache-reporting.ts b/sources/src/caching/cache-reporting.ts index 942df612..708ae90d 100644 --- a/sources/src/caching/cache-reporting.ts +++ b/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 ` - + + +
CountTotal Size (Mb)
CountTotal Size (Mb)Total Time (ms)
Entries Restored ${getCount(entries, e => e.restoredSize)} ${getSize(entries, e => e.restoredSize)}${getTime(entries, e => e.restoredTime)}
Entries Saved ${getCount(entries, e => e.savedSize)} ${getSize(entries, e => e.savedSize)}${getTime(entries, e => e.savedTime)}
` @@ -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` +} diff --git a/sources/src/caching/cache-utils.ts b/sources/src/caching/cache-utils.ts index 35d0564a..6e06910e 100644 --- a/sources/src/caching/cache-utils.ts +++ b/sources/src/caching/cache-utils.ts @@ -38,13 +38,14 @@ export async function restoreCache( ): Promise { 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 { 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) diff --git a/sources/src/caching/gradle-home-extry-extractor.ts b/sources/src/caching/gradle-home-extry-extractor.ts index 9a761b23..715da1f7 100644 --- a/sources/src/caching/gradle-home-extry-extractor.ts +++ b/sources/src/caching/gradle-home-extry-extractor.ts @@ -134,7 +134,7 @@ abstract class AbstractEntryExtractor { ): Promise { 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) { diff --git a/sources/src/caching/gradle-user-home-cache.ts b/sources/src/caching/gradle-user-home-cache.ts index 5d86d84f..3a47c2ea 100644 --- a/sources/src/caching/gradle-user-home-cache.ts +++ b/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 } diff --git a/sources/test/jest/cache-reporting.test.ts b/sources/test/jest/cache-reporting.test.ts index d728e6c4..7a3c307a 100644 --- a/sources/test/jest/cache-reporting.test.ts +++ b/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('bar').markRequested('3').markRestored('4', 333) + report.entry('foo').markRestored('4', 3300, 111) + 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'])