Merge pull request #4105 from github/henrymercer/tools-download-telemetry

Improve CodeQL tools download time telemetry

lib/entry-points.js

@@ -151503,10 +151503,10 @@ async function downloadAndExtract(codeqlURL, compressionMethod, dest, authorizat
   logger.info(
     `Downloading CodeQL tools from ${codeqlURL} . This may take a while.`
   );
+  const startTime = import_perf_hooks2.performance.now();
   try {
     if (compressionMethod === "zstd" && process.platform === "linux") {
       logger.info(`Streaming the extraction of the CodeQL bundle.`);
-      const toolsInstallStart = import_perf_hooks2.performance.now();
       await downloadAndExtractZstdWithStreaming(
         codeqlURL,
         dest,
@@ -151515,15 +151515,13 @@ async function downloadAndExtract(codeqlURL, compressionMethod, dest, authorizat
         tarVersion,
         logger
       );
-      const combinedDurationMs = Math.round(
-        import_perf_hooks2.performance.now() - toolsInstallStart
-      );
+      const totalDurationMs = Math.round(import_perf_hooks2.performance.now() - startTime);
       logger.info(
         `Finished downloading and extracting CodeQL bundle to ${dest} (${formatDuration(
-          combinedDurationMs
+          totalDurationMs
         )}).`
       );
-      return {};
+      return { totalDurationMs };
     }
   } catch (e) {
     core11.warning(
@@ -151565,7 +151563,11 @@ async function downloadAndExtract(codeqlURL, compressionMethod, dest, authorizat
   } finally {
     await cleanUpPath(archivedBundlePath, "CodeQL bundle archive", logger);
   }
-  return { downloadDurationMs };
+  return {
+    downloadDurationMs,
+    extractionDurationMs,
+    totalDurationMs: Math.round(import_perf_hooks2.performance.now() - startTime)
+  };
 }
 async function downloadAndExtractZstdWithStreaming(codeqlURL, dest, authorization, headers, tarVersion, logger) {
   fs13.mkdirSync(dest, { recursive: true });
@@ -161677,6 +161679,12 @@ async function sendCompletedStatusReport2(startedAt, config, configFile, toolsIn
   if (toolsDownloadStatusReport?.downloadDurationMs !== void 0) {
     initToolsDownloadFields.tools_download_duration_ms = toolsDownloadStatusReport.downloadDurationMs;
   }
+  if (toolsDownloadStatusReport?.extractionDurationMs !== void 0) {
+    initToolsDownloadFields.tools_extraction_duration_ms = toolsDownloadStatusReport.extractionDurationMs;
+  }
+  if (toolsDownloadStatusReport?.totalDurationMs !== void 0) {
+    initToolsDownloadFields.tools_total_duration_ms = toolsDownloadStatusReport.totalDurationMs;
+  }
   if (toolsFeatureFlagsValid !== void 0) {
     initToolsDownloadFields.tools_feature_flags_valid = toolsFeatureFlagsValid;
   }
@@ -162697,6 +162705,12 @@ async function sendCompletedStatusReport3(startedAt, toolsInput, toolsDownloadSt
   if (toolsDownloadStatusReport?.downloadDurationMs !== void 0) {
     initToolsDownloadFields.tools_download_duration_ms = toolsDownloadStatusReport.downloadDurationMs;
   }
+  if (toolsDownloadStatusReport?.extractionDurationMs !== void 0) {
+    initToolsDownloadFields.tools_extraction_duration_ms = toolsDownloadStatusReport.extractionDurationMs;
+  }
+  if (toolsDownloadStatusReport?.totalDurationMs !== void 0) {
+    initToolsDownloadFields.tools_total_duration_ms = toolsDownloadStatusReport.totalDurationMs;
+  }
   if (toolsFeatureFlagsValid !== void 0) {
     initToolsDownloadFields.tools_feature_flags_valid = toolsFeatureFlagsValid;
   }

src/init-action.ts

@@ -174,6 +174,14 @@ async function sendCompletedStatusReport(
     initToolsDownloadFields.tools_download_duration_ms =
       toolsDownloadStatusReport.downloadDurationMs;
   }
+  if (toolsDownloadStatusReport?.extractionDurationMs !== undefined) {
+    initToolsDownloadFields.tools_extraction_duration_ms =
+      toolsDownloadStatusReport.extractionDurationMs;
+  }
+  if (toolsDownloadStatusReport?.totalDurationMs !== undefined) {
+    initToolsDownloadFields.tools_total_duration_ms =
+      toolsDownloadStatusReport.totalDurationMs;
+  }
   if (toolsFeatureFlagsValid !== undefined) {
     initToolsDownloadFields.tools_feature_flags_valid = toolsFeatureFlagsValid;
   }

src/setup-codeql-action.ts

@@ -85,6 +85,14 @@ async function sendCompletedStatusReport(
     initToolsDownloadFields.tools_download_duration_ms =
       toolsDownloadStatusReport.downloadDurationMs;
   }
+  if (toolsDownloadStatusReport?.extractionDurationMs !== undefined) {
+    initToolsDownloadFields.tools_extraction_duration_ms =
+      toolsDownloadStatusReport.extractionDurationMs;
+  }
+  if (toolsDownloadStatusReport?.totalDurationMs !== undefined) {
+    initToolsDownloadFields.tools_total_duration_ms =
+      toolsDownloadStatusReport.totalDurationMs;
+  }
   if (toolsFeatureFlagsValid !== undefined) {
     initToolsDownloadFields.tools_feature_flags_valid = toolsFeatureFlagsValid;
   }

src/setup-codeql.test.ts

@@ -234,6 +234,7 @@ test.serial(
       codeqlFolder: "codeql",
       statusReport: {
         downloadDurationMs: 200,
+        totalDurationMs: 300,
       },
       toolsVersion: LINKED_CLI_VERSION.cliVersion,
     });
@@ -286,6 +287,7 @@ test.serial(
       codeqlFolder: "codeql",
       statusReport: {
         downloadDurationMs: 200,
+        totalDurationMs: 300,
       },
       toolsVersion: expectedVersion,
     });

src/status-report.ts

@@ -620,8 +620,21 @@ export interface InitWithConfigStatusReport extends InitStatusReport {
 
 /** Fields of the init status report populated when the tools source is `download`. */
 export interface InitToolsDownloadFields {
-  /** Time taken to download the bundle, in milliseconds. */
+  /**
+   * Time taken to download the bundle, in milliseconds. Not populated when the bundle is downloaded
+   * and extracted concurrently.
+   */
   tools_download_duration_ms?: number;
+  /**
+   * Time taken to extract the bundle, in milliseconds. Not populated when the bundle is downloaded
+   * and extracted concurrently.
+   */
+  tools_extraction_duration_ms?: number;
+  /**
+   * Total time taken to make the bundle available on disk, in milliseconds. This includes any time
+   * spent on a streaming attempt that failed and fell back to downloading before extracting.
+   */
+  tools_total_duration_ms?: number;
   /**
    * Whether the relevant tools dotcom feature flags have been misconfigured.
    * Only populated if we attempt to determine the default version based on the dotcom feature flags. */

src/tools-download.test.ts

@@ -15,7 +15,7 @@ import { withTmpDir } from "./util";
 setupTests(test);
 
 test.serial(
-  "downloadAndExtract reports the duration when downloading before extracting",
+  "downloadAndExtract reports the durations when downloading before extracting",
   async (t) => {
     await withTmpDir(async (tmpDir) => {
       const archivePath = path.join(tmpDir, "codeql-bundle.tar.gz");
@@ -34,6 +34,8 @@ test.serial(
       );
 
       t.assert(Number.isInteger(statusReport.downloadDurationMs));
+      t.assert(Number.isInteger(statusReport.extractionDurationMs));
+      t.assert(Number.isInteger(statusReport.totalDurationMs));
     });
   },
 );
@@ -67,6 +69,7 @@ test.serial(
       );
 
       t.assert(Number.isInteger(statusReport.downloadDurationMs));
+      t.assert(Number.isInteger(statusReport.totalDurationMs));
       t.true(request.isDone());
       t.false(extractTarZst.called);
       t.true(downloadTool.calledOnce);
@@ -76,7 +79,7 @@ test.serial(
 );
 
 test.serial(
-  "downloadAndExtract omits the download duration when streaming extraction",
+  "downloadAndExtract reports only the total duration when streaming extraction",
   async (t) => {
     await withTmpDir(async (tmpDir) => {
       sinon.stub(process, "platform").value("linux");
@@ -106,7 +109,9 @@ test.serial(
         getRunnerLogger(true),
       );
 
-      t.deepEqual(statusReport, {});
+      t.assert(Number.isInteger(statusReport.totalDurationMs));
+      t.is(statusReport.downloadDurationMs, undefined);
+      t.is(statusReport.extractionDurationMs, undefined);
       t.false(downloadTool.called);
       t.true(extractTarZst.calledOnce);
       t.true(request.isDone());

src/tools-download.ts

@@ -31,7 +31,21 @@ const STREAMING_STALL_TIMEOUT_MS = 5 * 60 * 1000; // 5 minutes
 const TOOLCACHE_TOOL_NAME = "CodeQL";
 
 export type ToolsDownloadStatusReport = {
+  /**
+   * Time spent downloading the bundle, in milliseconds. Not populated when the bundle is downloaded
+   * and extracted concurrently, since the two cannot be told apart.
+   */
   downloadDurationMs?: number;
+  /**
+   * Time spent extracting the bundle, in milliseconds. Not populated when the bundle is downloaded
+   * and extracted concurrently, since the two cannot be told apart.
+   */
+  extractionDurationMs?: number;
+  /**
+   * Total time taken to make the bundle available on disk, in milliseconds. This includes any time
+   * spent on a streaming attempt that failed and fell back to downloading before extracting.
+   */
+  totalDurationMs: number;
 };
 
 export async function downloadAndExtract(
@@ -47,11 +61,12 @@ export async function downloadAndExtract(
     `Downloading CodeQL tools from ${codeqlURL} . This may take a while.`,
   );
 
+  const startTime = performance.now();
+
   try {
     if (compressionMethod === "zstd" && process.platform === "linux") {
       logger.info(`Streaming the extraction of the CodeQL bundle.`);
 
-      const toolsInstallStart = performance.now();
       await downloadAndExtractZstdWithStreaming(
         codeqlURL,
         dest,
@@ -61,16 +76,14 @@ export async function downloadAndExtract(
         logger,
       );
 
-      const combinedDurationMs = Math.round(
-        performance.now() - toolsInstallStart,
-      );
+      const totalDurationMs = Math.round(performance.now() - startTime);
       logger.info(
         `Finished downloading and extracting CodeQL bundle to ${dest} (${formatDuration(
-          combinedDurationMs,
+          totalDurationMs,
         )}).`,
       );
 
-      return {};
+      return { totalDurationMs };
     }
   } catch (e) {
     core.warning(
@@ -98,7 +111,7 @@ export async function downloadAndExtract(
     )}).`,
   );
 
-  let extractionDurationMs: number;
+  let extractionDurationMs: number | undefined;
 
   try {
     logger.info("Extracting CodeQL bundle.");
@@ -120,7 +133,11 @@ export async function downloadAndExtract(
     await cleanUpPath(archivedBundlePath, "CodeQL bundle archive", logger);
   }
 
-  return { downloadDurationMs };
+  return {
+    downloadDurationMs,
+    extractionDurationMs,
+    totalDurationMs: Math.round(performance.now() - startTime),
+  };
 }
 
 async function downloadAndExtractZstdWithStreaming(