feat: collect telemetry to understand time spent scanning images

We are looking to improve our process of scanning images. Right now we have no visibility into how long an average image scan takes. For this reason we collect the following timings: time spent in queue, time spent pulling images, time spent scanning images. Additionally, collect the current queue size at the start of the image scan.

Author: ivanstanev

src/scanner/index.ts

@@ -12,11 +12,16 @@ import {
   constructDepGraph,
   constructScanResults,
 } from '../transmitter/payload';
-import { IWorkload, ILocalWorkloadLocator } from '../transmitter/types';
+import {
+  IWorkload,
+  ILocalWorkloadLocator,
+  Telemetry,
+} from '../transmitter/types';
 import { IPullableImage, IScanImage } from './images/types';
 
 export async function processWorkload(
   workloadMetadata: IWorkload[],
+  telemetry: Partial<Telemetry>,
 ): Promise<void> {
   // every workload metadata references the same workload name, grab it from the first one
   const workloadName = workloadMetadata[0].name;
@@ -27,20 +32,24 @@ export async function processWorkload(
     'pulling unique images',
   );
   const imagesWithFileSystemPath = getImagesWithFileSystemPath(uniqueImages);
+  const imagePullStartTimestampMs = Date.now();
   const pulledImages = await pullImages(imagesWithFileSystemPath);
+  const imagePullDurationMs = Date.now() - imagePullStartTimestampMs;
   if (pulledImages.length === 0) {
     logger.info(
       { workloadName },
       'no images were pulled, halting scanner process.',
     );
     return;
   }
+  telemetry.imagePullDurationMs = imagePullDurationMs;
 
   try {
     await scanImagesAndSendResults(
       workloadName,
       pulledImages,
       workloadMetadata,
+      telemetry,
     );
   } finally {
     await removePulledImages(pulledImages);
@@ -105,8 +114,11 @@ async function scanImagesAndSendResults(
   workloadName: string,
   pulledImages: IPullableImage[],
   workloadMetadata: IWorkload[],
+  telemetry: Partial<Telemetry>,
 ): Promise<void> {
+  const imageScanStartTimestampMs = Date.now();
   const scannedImages = await scanImages(pulledImages);
+  const imageScanDurationMs = Date.now() - imageScanStartTimestampMs;
 
   if (scannedImages.length === 0) {
     logger.info(
@@ -116,6 +128,8 @@ async function scanImagesAndSendResults(
     return;
   }
 
+  telemetry.imageScanDurationMs = imageScanDurationMs;
+
   logger.info(
     { workloadName, imageCount: scannedImages.length },
     'successfully scanned images',
@@ -124,6 +138,7 @@ async function scanImagesAndSendResults(
   const scanResultsPayloads = constructScanResults(
     scannedImages,
     workloadMetadata,
+    telemetry,
   );
   const success = await sendScanResults(scanResultsPayloads);
   if (!success) {

src/supervisor/watchers/handlers/pod.ts

@@ -4,7 +4,7 @@ import { logger } from '../../../common/logger';
 import { config } from '../../../common/config';
 import { processWorkload } from '../../../scanner';
 import { sendWorkloadMetadata } from '../../../transmitter';
-import { IWorkload } from '../../../transmitter/types';
+import { IWorkload, Telemetry } from '../../../transmitter/types';
 import { constructWorkloadMetadata } from '../../../transmitter/payload';
 import { buildMetadataForWorkload } from '../../metadata-extractor';
 import { PodPhase } from '../types';
@@ -13,6 +13,13 @@ import { FALSY_WORKLOAD_NAME_MARKER } from './types';
 import { WorkloadKind } from '../../types';
 import { deleteWorkload } from './workload';
 
+export interface ImagesToScanQueueData {
+  workloadMetadata: IWorkload[];
+  imageKeys: string[];
+  /** The timestamp when this workload was added to the image scan queue. */
+  enqueueTimestampMs: number;
+}
+
 function deleteFailedKeysFromState(keys): void {
   try {
     for (const key of keys) {
@@ -33,10 +40,19 @@ function deleteFailedKeysFromState(keys): void {
   }
 }
 
-async function queueWorkerWorkloadScan(task, callback): Promise<void> {
-  const { workloadMetadata, imageKeys } = task;
+async function queueWorkerWorkloadScan(
+  task: ImagesToScanQueueData,
+  callback,
+): Promise<void> {
+  const { workloadMetadata, imageKeys, enqueueTimestampMs } = task;
+  /** Represents how long this workload spent waiting in the queue to be processed. */
+  const enqueueDurationMs = Date.now() - enqueueTimestampMs;
+  const telemetry: Partial<Telemetry> = {
+    enqueueDurationMs,
+    queueSize: workloadsToScanQueue.length(),
+  };
   try {
-    await processWorkload(workloadMetadata);
+    await processWorkload(workloadMetadata, telemetry);
   } catch (err) {
     logger.error(
       { err, task },
@@ -46,7 +62,7 @@ async function queueWorkerWorkloadScan(task, callback): Promise<void> {
   }
 }
 
-const workloadsToScanQueue = async.queue(
+const workloadsToScanQueue = async.queue<ImagesToScanQueueData>(
   queueWorkerWorkloadScan,
   config.WORKLOADS_TO_SCAN_QUEUE_WORKER_COUNT,
 );
@@ -82,7 +98,11 @@ function handleReadyPod(workloadMetadata: IWorkload[]): void {
   }
 
   if (imagesToScan.length > 0) {
-    workloadsToScanQueue.push({ workloadMetadata: imagesToScan, imageKeys });
+    workloadsToScanQueue.push({
+      workloadMetadata: imagesToScan,
+      imageKeys,
+      enqueueTimestampMs: Date.now(),
+    });
   }
 }
 

src/transmitter/payload.ts

@@ -12,6 +12,7 @@ import {
   ScanResultsPayload,
   IDependencyGraphPayload,
   IWorkloadEventsPolicyPayload,
+  Telemetry,
 } from './types';
 import { state } from '../state';
 
@@ -51,6 +52,7 @@ export function constructDepGraph(
 export function constructScanResults(
   scannedImages: IScanResult[],
   workloadMetadata: IWorkload[],
+  telemetry: Partial<Telemetry>,
 ): ScanResultsPayload[] {
   return scannedImages.map<ScanResultsPayload>((scannedImage) => {
     // We know that .find() won't return undefined
@@ -72,6 +74,7 @@ export function constructScanResults(
     };
 
     return {
+      telemetry,
       imageLocator,
       agentId: config.AGENT_ID,
       scanResults: scannedImage.scanResults,

src/transmitter/types.ts

@@ -42,6 +42,7 @@ export interface ScanResultsPayload {
   imageLocator: IImageLocator;
   agentId: string;
   scanResults: ScanResult[];
+  telemetry: Partial<Telemetry>;
 }
 
 export interface IWorkloadMetadataPayload {
@@ -96,3 +97,10 @@ export interface IRequestError {
   code: string;
   message: string;
 }
+
+export interface Telemetry {
+  enqueueDurationMs: number;
+  queueSize: number;
+  imagePullDurationMs: number;
+  imageScanDurationMs: number;
+}

test/system/kind.spec.ts

@@ -250,6 +250,12 @@ test('Kubernetes-Monitor with KinD', async (jestDoneCallback) => {
       try {
         expect(requestBody).toEqual<transmitterTypes.ScanResultsPayload>({
           agentId,
+          telemetry: {
+            enqueueDurationMs: expect.any(Number),
+            imagePullDurationMs: expect.any(Number),
+            imageScanDurationMs: expect.any(Number),
+            queueSize: expect.any(Number),
+          },
           imageLocator: expect.objectContaining({
             imageId: expect.any(String),
           }),

test/unit/transmitter-payload.spec.ts

@@ -60,8 +60,14 @@ describe('transmitter payload tests', () => {
         },
       ];
 
+      const telemetry: Record<string, number> = {};
+
       expect(() =>
-        payload.constructScanResults(scannedImages, workloadMetadata),
+        payload.constructScanResults(
+          scannedImages,
+          workloadMetadata,
+          telemetry,
+        ),
       ).toThrow();
     },
   );
@@ -97,6 +103,7 @@ describe('transmitter payload tests', () => {
         podSpec: podSpecFixture,
       },
     ];
+    const telemetry: Record<string, number> = {};
 
     // These values are populated at runtime (injected by the deployment) so we have to mock them
     // to make sure the function uses them to construct the payload (otherwise they are undefined).
@@ -110,6 +117,7 @@ describe('transmitter payload tests', () => {
     const payloads = payload.constructScanResults(
       scannedImages,
       workloadMetadata,
+      telemetry,
     );
     expect(payloads).toHaveLength(1);