[Reporting] Add logging of CPU usage and memory consumption by Chromi…

…um (#99109) (#100384)

* Add logging of CPU usage by chromium
* Add logging of memory consumption by chromium
* Add PDF report byte length logging
* Add PNG report byte length logging
# Conflicts:
#	x-pack/plugins/reporting/server/browsers/chromium/driver_factory/index.ts

x-pack/plugins/reporting/server/browsers/chromium/driver_factory/index.ts

@@ -5,6 +5,7 @@
  * 2.0.
  */
 
+import apm from 'elastic-apm-node';
 import { i18n } from '@kbn/i18n';
 import del from 'del';
 import fs from 'fs';
@@ -22,6 +23,7 @@ import { LevelLogger } from '../../../lib';
 import { safeChildProcess } from '../../safe_child_process';
 import { HeadlessChromiumDriver } from '../driver';
 import { args } from './args';
+import { Metrics, getMetrics } from './metrics';
 
 type BrowserConfig = CaptureConfig['browser']['chromium'];
 type ViewportConfig = CaptureConfig['viewport'];
@@ -70,6 +72,9 @@ export class HeadlessChromiumDriverFactory {
 
       let browser: puppeteer.Browser;
       let page: puppeteer.Page;
+      let devTools: puppeteer.CDPSession | undefined;
+      let startMetrics: Metrics | undefined;
+
       try {
         browser = await puppeteer.launch({
           pipe: !this.browserConfig.inspect,
@@ -83,11 +88,13 @@ export class HeadlessChromiumDriverFactory {
         } as puppeteer.LaunchOptions);
 
         page = await browser.newPage();
-        await page.emulateTimezone(browserTimezone);
+        devTools = await page.target().createCDPSession();
+
+        await devTools.send('Performance.enable', { timeDomain: 'timeTicks' });
+        startMetrics = await devTools.send('Performance.getMetrics');
 
         // Log version info for debugging / maintenance
-        const client = await page.target().createCDPSession();
-        const versionInfo = await client.send('Browser.getVersion');
+        const versionInfo = await devTools.send('Browser.getVersion');
         logger.debug(`Browser version: ${JSON.stringify(versionInfo)}`);
 
         await page.emulateTimezone(browserTimezone);
@@ -105,6 +112,24 @@ export class HeadlessChromiumDriverFactory {
 
       const childProcess = {
         async kill() {
+          try {
+            if (devTools && startMetrics) {
+              const endMetrics = await devTools.send('Performance.getMetrics');
+              const { cpu, cpuInPercentage, memory, memoryInMegabytes } = getMetrics(
+                startMetrics,
+                endMetrics
+              );
+
+              apm.currentTransaction?.setLabel('cpu', cpu, false);
+              apm.currentTransaction?.setLabel('memory', memory, false);
+              logger.debug(
+                `Chromium consumed CPU ${cpuInPercentage}% Memory ${memoryInMegabytes}MB`
+              );
+            }
+          } catch (error) {
+            logger.error(error);
+          }
+
           try {
             await browser.close();
           } catch (err) {

x-pack/plugins/reporting/server/browsers/chromium/driver_factory/metrics.test.ts

@@ -0,0 +1,67 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0; you may not use this file except in compliance with the Elastic License
+ * 2.0.
+ */
+
+jest.mock('os');
+
+import { cpus } from 'os';
+import { Metrics, getMetrics } from './metrics';
+
+describe('getMetrics', () => {
+  const start = {
+    metrics: [
+      { name: 'ProcessTime', value: 10 },
+      { name: 'Timestamp', value: 1000 },
+      { name: 'JSHeapTotalSize', value: 1 * 1024 * 1024 },
+    ],
+  } as Metrics;
+  const end = {
+    metrics: [
+      { name: 'ProcessTime', value: 110 },
+      { name: 'Timestamp', value: 2000 },
+      { name: 'JSHeapTotalSize', value: 5 * 1024 * 1024 },
+    ],
+  } as Metrics;
+
+  beforeEach(() => {
+    (cpus as jest.MockedFunction<typeof cpus>).mockReturnValue([{} as any]);
+  });
+
+  describe('cpu', () => {
+    it('should evaluate CPU usage during the runtime', () => {
+      const { cpu } = getMetrics(start, end);
+
+      expect(cpu).toBe(0.1);
+    });
+
+    it('should respect a number of virtual cores available', () => {
+      (cpus as jest.MockedFunction<typeof cpus>).mockReturnValue([{} as any, {} as any]);
+      const { cpu } = getMetrics(start, end);
+
+      expect(cpu).toBe(0.05);
+    });
+
+    it('should return CPU usage in percentage', () => {
+      const { cpuInPercentage } = getMetrics(start, end);
+
+      expect(cpuInPercentage).toBe(10);
+    });
+  });
+
+  describe('memory', () => {
+    it('should evaluate memory consumption during the runtime', () => {
+      const { memory } = getMetrics(start, end);
+
+      expect(memory).toBe(5 * 1024 * 1024);
+    });
+
+    it('should return memory consumption in megabytes', () => {
+      const { memoryInMegabytes } = getMetrics(start, end);
+
+      expect(memoryInMegabytes).toBe(5);
+    });
+  });
+});

x-pack/plugins/reporting/server/browsers/chromium/driver_factory/metrics.ts

@@ -0,0 +1,72 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0; you may not use this file except in compliance with the Elastic License
+ * 2.0.
+ */
+
+import type { Metrics as PuppeteerMetrics } from 'puppeteer';
+import { cpus } from 'os';
+
+declare module 'puppeteer' {
+  interface CDPSession {
+    send(command: 'Performance.getMetrics'): Promise<RawMetrics>;
+  }
+}
+
+type RawMetrics = Metrics;
+
+export interface Metrics {
+  metrics: Metric[];
+}
+
+interface Metric {
+  name: keyof NormalizedMetrics;
+  value: unknown;
+}
+
+interface NormalizedMetrics extends Required<PuppeteerMetrics> {
+  ProcessTime: number;
+}
+
+interface PerformanceMetrics {
+  cpu: number;
+  cpuInPercentage: number;
+  memory: number;
+  memoryInMegabytes: number;
+}
+
+function normalizeMetrics({ metrics }: Metrics) {
+  return (Object.fromEntries(
+    metrics.map(({ name, value }) => [name, value])
+  ) as unknown) as NormalizedMetrics;
+}
+
+function getCpuUsage(start: NormalizedMetrics, end: NormalizedMetrics) {
+  return (end.ProcessTime - start.ProcessTime) / (end.Timestamp - start.Timestamp) / cpus().length;
+}
+
+function toPercentage(value: number) {
+  return Math.round((value + Number.EPSILON) * 10000) / 100;
+}
+
+function toMegabytes(value: number) {
+  return Math.round((value / 1024 / 1024 + Number.EPSILON) * 100) / 100;
+}
+
+export function getMetrics(start: Metrics, end: Metrics): PerformanceMetrics {
+  const startMetrics = normalizeMetrics(start);
+  const endMetrics = normalizeMetrics(end);
+
+  const cpu = getCpuUsage(startMetrics, endMetrics);
+  const cpuInPercentage = toPercentage(cpu);
+  const { JSHeapTotalSize: memory } = endMetrics;
+  const memoryInMegabytes = toMegabytes(memory);
+
+  return {
+    cpu,
+    cpuInPercentage,
+    memory,
+    memoryInMegabytes,
+  };
+}

x-pack/plugins/reporting/server/export_types/png/execute_job/index.ts

@@ -7,7 +7,7 @@
 
 import apm from 'elastic-apm-node';
 import * as Rx from 'rxjs';
-import { catchError, map, mergeMap, takeUntil } from 'rxjs/operators';
+import { catchError, finalize, map, mergeMap, takeUntil } from 'rxjs/operators';
 import { PNG_JOB_TYPE } from '../../../../common/constants';
 import { TaskRunResult } from '../../../lib/tasks';
 import { RunTaskFn, RunTaskFnFactory } from '../../../types';
@@ -51,20 +51,17 @@ export const runTaskFnFactory: RunTaskFnFactory<
           job.layout
         );
       }),
-      map(({ base64, warnings }) => {
-        if (apmGeneratePng) apmGeneratePng.end();
-
-        return {
-          content_type: 'image/png',
-          content: base64,
-          size: (base64 && base64.length) || 0,
-          warnings,
-        };
-      }),
+      map(({ base64, warnings }) => ({
+        content_type: 'image/png',
+        content: base64,
+        size: (base64 && base64.length) || 0,
+        warnings,
+      })),
       catchError((err) => {
         jobLogger.error(err);
         return Rx.throwError(err);
-      })
+      }),
+      finalize(() => apmGeneratePng?.end())
     );
 
     const stop$ = Rx.fromEventPattern(cancellationToken.on);

x-pack/plugins/reporting/server/export_types/png/lib/generate_png.ts

@@ -7,13 +7,22 @@
 
 import apm from 'elastic-apm-node';
 import * as Rx from 'rxjs';
-import { map } from 'rxjs/operators';
+import { finalize, map, tap } from 'rxjs/operators';
 import { ReportingCore } from '../../../';
 import { LevelLogger } from '../../../lib';
 import { LayoutParams, PreserveLayout } from '../../../lib/layouts';
 import { ScreenshotResults } from '../../../lib/screenshots';
 import { ConditionalHeaders } from '../../common';
 
+function getBase64DecodedSize(value: string) {
+  // @see https://en.wikipedia.org/wiki/Base64#Output_padding
+  return (
+    (value.length * 3) / 4 -
+    Number(value[value.length - 1] === '=') -
+    Number(value[value.length - 2] === '=')
+  );
+}
+
 export async function generatePngObservableFactory(reporting: ReportingCore) {
   const getScreenshots = await reporting.getScreenshotsObservable();
 
@@ -33,26 +42,36 @@ export async function generatePngObservableFactory(reporting: ReportingCore) {
     if (apmLayout) apmLayout.end();
 
     const apmScreenshots = apmTrans?.startSpan('screenshots_pipeline', 'setup');
+    let apmBuffer: typeof apm.currentSpan;
     const screenshots$ = getScreenshots({
       logger,
       urls: [url],
       conditionalHeaders,
       layout,
       browserTimezone,
     }).pipe(
-      map((results: ScreenshotResults[]) => {
-        if (apmScreenshots) apmScreenshots.end();
-        if (apmTrans) apmTrans.end();
+      tap(() => {
+        apmScreenshots?.end();
+        apmBuffer = apmTrans?.startSpan('get_buffer', 'output') ?? null;
+      }),
+      map((results: ScreenshotResults[]) => ({
+        base64: results[0].screenshots[0].base64EncodedData,
+        warnings: results.reduce((found, current) => {
+          if (current.error) {
+            found.push(current.error.message);
+          }
+          return found;
+        }, [] as string[]),
+      })),
+      tap(({ base64 }) => {
+        const byteLength = getBase64DecodedSize(base64);
 
-        return {
-          base64: results[0].screenshots[0].base64EncodedData,
-          warnings: results.reduce((found, current) => {
-            if (current.error) {
-              found.push(current.error.message);
-            }
-            return found;
-          }, [] as string[]),
-        };
+        logger.debug(`PNG buffer byte length: ${byteLength}`);
+        apmTrans?.setLabel('byte_length', byteLength, false);
+      }),
+      finalize(() => {
+        apmBuffer?.end();
+        apmTrans?.end();
       })
     );
 

x-pack/plugins/reporting/server/export_types/printable_pdf/lib/generate_pdf.ts

@@ -89,7 +89,11 @@ export async function generatePdfObservableFactory(reporting: ReportingCore) {
           tracker.startGetBuffer();
           logger.debug(`Generating PDF Buffer...`);
           buffer = await pdfOutput.getBuffer();
-          logger.debug(`PDF buffer byte length: ${buffer?.byteLength || 0}`);
+
+          const byteLength = buffer?.byteLength ?? 0;
+          logger.debug(`PDF buffer byte length: ${byteLength}`);
+          tracker.setByteLength(byteLength);
+
           tracker.endGetBuffer();
         } catch (err) {
           logger.error(`Could not generate the PDF buffer!`);

x-pack/plugins/reporting/server/export_types/printable_pdf/lib/tracker.ts

@@ -8,6 +8,7 @@
 import apm from 'elastic-apm-node';
 
 interface PdfTracker {
+  setByteLength: (byteLength: number) => void;
   startLayout: () => void;
   endLayout: () => void;
   startScreenshots: () => void;
@@ -77,6 +78,9 @@ export function getTracker(): PdfTracker {
     endGetBuffer() {
       if (apmGetBuffer) apmGetBuffer.end();
     },
+    setByteLength(byteLength: number) {
+      apmTrans?.setLabel('byte_length', byteLength, false);
+    },
     end() {
       if (apmTrans) apmTrans.end();
     },

x-pack/plugins/reporting/server/lib/screenshots/observable.ts

@@ -7,16 +7,7 @@
 
 import apm from 'elastic-apm-node';
 import * as Rx from 'rxjs';
-import {
-  catchError,
-  concatMap,
-  first,
-  mergeMap,
-  take,
-  takeUntil,
-  tap,
-  toArray,
-} from 'rxjs/operators';
+import { catchError, concatMap, first, mergeMap, take, takeUntil, toArray } from 'rxjs/operators';
 import { HeadlessChromiumDriverFactory } from '../../browsers';
 import { CaptureConfig } from '../../types';
 import {
@@ -66,7 +57,9 @@ export function screenshotsObservableFactory(
 
     return create$.pipe(
       mergeMap(({ driver, exit$ }) => {
-        if (apmCreatePage) apmCreatePage.end();
+        apmCreatePage?.end();
+        exit$.subscribe({ error: () => apmTrans?.end() });
+
         return Rx.from(urls).pipe(
           concatMap((url, index) => {
             const setup$: Rx.Observable<ScreenSetupData> = Rx.of(1).pipe(
@@ -151,10 +144,7 @@ export function screenshotsObservableFactory(
           toArray()
         );
       }),
-      first(),
-      tap(() => {
-        if (apmTrans) apmTrans.end();
-      })
+      first()
     );
   };
 }