[ci-stats] Collects additional timings for cli tools (#113030)

* [ci-stats] Collects additional metrics about bootstrap

Signed-off-by: Tyler Smalley <tyler.smalley@elastic.co>

* test reporting

* [ci-stats] Collects additional metrics about bootstrap

Signed-off-by: Tyler Smalley <tyler.smalley@elastic.co>

* Move ts timing to build_ts_refs_cli script

Signed-off-by: Tyler Smalley <tyler.smalley@elastic.co>

* Add timings to run

Signed-off-by: Tyler Smalley <tyler.smalley@elastic.co>

* info debug level

Signed-off-by: Tyler Smalley <tyler.smalley@elastic.co>

* fix build

* Move report function to dev-utils
align name of tests
report from functional test runner

* report snapshot install \ ready times
fix event names

* Report memory usage and branch hash

* fix eslint

* fix integration test

* build

* mergy merge

* mergy merge 2

* eslint

* eslint

* ready events

* Update packages/kbn-es/src/cli_commands/snapshot.js

Co-authored-by: Tyler Smalley <tylersmalley@gmail.com>

* Update packages/kbn-es/src/cluster.js

Co-authored-by: Tyler Smalley <tylersmalley@gmail.com>

* Update packages/kbn-es/src/cli_commands/snapshot.js

Co-authored-by: Tyler Smalley <tylersmalley@gmail.com>

* Update packages/kbn-test/src/functional_tests/cli/start_servers/cli.js

Co-authored-by: Tyler Smalley <tylersmalley@gmail.com>

* Update src/dev/run_check_published_api_changes.ts

Co-authored-by: Tyler Smalley <tylersmalley@gmail.com>

* Update packages/kbn-test/src/jest/run.ts

Co-authored-by: Tyler Smalley <tylersmalley@gmail.com>

* Update src/dev/run_i18n_check.ts

Co-authored-by: Tyler Smalley <tylersmalley@gmail.com>

* Update packages/kbn-test/src/functional_test_runner/cli.ts

Co-authored-by: Tyler Smalley <tylersmalley@gmail.com>

* code review

* pm

* merge

* dist

* jest fix

Co-authored-by: Tyler Smalley <tyler.smalley@elastic.co>
Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>
Co-authored-by: Tyler Smalley <tylersmalley@gmail.com>

packages/kbn-dev-utils/src/ci_stats_reporter/ci_stats_reporter.ts

@@ -82,6 +82,7 @@ export class CiStatsReporter {
     const upstreamBranch = options.upstreamBranch ?? this.getUpstreamBranch();
     const kibanaUuid = options.kibanaUuid === undefined ? this.getKibanaUuid() : options.kibanaUuid;
     let email;
+    let branch;
 
     try {
       const { stdout } = await execa('git', ['config', 'user.email']);
@@ -90,19 +91,33 @@ export class CiStatsReporter {
       this.log.debug(e.message);
     }
 
+    try {
+      const { stdout } = await execa('git', ['branch', '--show-current']);
+      branch = stdout;
+    } catch (e) {
+      this.log.debug(e.message);
+    }
+
+    const memUsage = process.memoryUsage();
     const isElasticCommitter = email && email.endsWith('@elastic.co') ? true : false;
 
     const defaultMetadata = {
+      kibanaUuid,
+      isElasticCommitter,
       committerHash: email
         ? crypto.createHash('sha256').update(email).digest('hex').substring(0, 20)
         : undefined,
+      email: isElasticCommitter ? email : undefined,
+      branch: isElasticCommitter ? branch : undefined,
       cpuCount: Os.cpus()?.length,
       cpuModel: Os.cpus()[0]?.model,
       cpuSpeed: Os.cpus()[0]?.speed,
-      email: isElasticCommitter ? email : undefined,
       freeMem: Os.freemem(),
-      isElasticCommitter,
-      kibanaUuid,
+      memoryUsageRss: memUsage.rss,
+      memoryUsageHeapTotal: memUsage.heapTotal,
+      memoryUsageHeapUsed: memUsage.heapUsed,
+      memoryUsageExternal: memUsage.external,
+      memoryUsageArrayBuffers: memUsage.arrayBuffers,
       nestedTiming: process.env.CI_STATS_NESTED_TIMING ? true : false,
       osArch: Os.arch(),
       osPlatform: Os.platform(),

packages/kbn-dev-utils/src/ci_stats_reporter/index.ts

@@ -8,3 +8,4 @@
 
 export * from './ci_stats_reporter';
 export * from './ship_ci_stats_cli';
+export { getTimeReporter } from './report_time';

packages/kbn-dev-utils/src/ci_stats_reporter/report_time.ts

@@ -0,0 +1,25 @@
+/*
+ * 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 and the Server Side Public License, v 1; you may not use this file except
+ * in compliance with, at your election, the Elastic License 2.0 or the Server
+ * Side Public License, v 1.
+ */
+
+import { CiStatsReporter, ToolingLog } from '..';
+
+export const getTimeReporter = (log: ToolingLog, group: string) => {
+  const reporter = CiStatsReporter.fromEnv(log);
+  return async (startTime: number, id: string, meta: Record<string, any>) => {
+    await reporter.timings({
+      timings: [
+        {
+          group,
+          id,
+          ms: Date.now() - startTime,
+          meta,
+        },
+      ],
+    });
+  };
+};

packages/kbn-es/src/cli_commands/snapshot.js

@@ -8,6 +8,7 @@
 
 const dedent = require('dedent');
 const getopts = require('getopts');
+import { ToolingLog, getTimeReporter } from '@kbn/dev-utils';
 const { Cluster } = require('../cluster');
 
 exports.description = 'Downloads and run from a nightly snapshot';
@@ -36,6 +37,13 @@ exports.help = (defaults = {}) => {
 };
 
 exports.run = async (defaults = {}) => {
+  const runStartTime = Date.now();
+  const log = new ToolingLog({
+    level: 'info',
+    writeTo: process.stdout,
+  });
+  const reportTime = getTimeReporter(log, 'scripts/es snapshot');
+
   const argv = process.argv.slice(2);
   const options = getopts(argv, {
     alias: {
@@ -56,12 +64,22 @@ exports.run = async (defaults = {}) => {
   if (options['download-only']) {
     await cluster.downloadSnapshot(options);
   } else {
+    const installStartTime = Date.now();
     const { installPath } = await cluster.installSnapshot(options);
 
     if (options.dataArchive) {
       await cluster.extractDataDirectory(installPath, options.dataArchive);
     }
 
-    await cluster.run(installPath, options);
+    reportTime(installStartTime, 'installed', {
+      success: true,
+      ...options,
+    });
+
+    await cluster.run(installPath, {
+      reportTime,
+      startTime: runStartTime,
+      ...options,
+    });
   }
 };

packages/kbn-es/src/cluster.js

@@ -240,7 +240,7 @@ exports.Cluster = class Cluster {
    * @return {undefined}
    */
   _exec(installPath, opts = {}) {
-    const { skipNativeRealmSetup = false, ...options } = opts;
+    const { skipNativeRealmSetup = false, reportTime = () => {}, startTime, ...options } = opts;
 
     if (this._process || this._outcome) {
       throw new Error('ES has already been started');
@@ -321,10 +321,17 @@ exports.Cluster = class Cluster {
       await nativeRealm.setPasswords(options);
     });
 
+    let reportSent = false;
     // parse and forward es stdout to the log
     this._process.stdout.on('data', (data) => {
       const lines = parseEsLog(data.toString());
       lines.forEach((line) => {
+        if (!reportSent && line.message.includes('publish_address')) {
+          reportSent = true;
+          reportTime(startTime, 'ready', {
+            success: true,
+          });
+        }
         this._log.info(line.formattedMessage);
       });
     });
@@ -341,7 +348,16 @@ exports.Cluster = class Cluster {
 
       // JVM exits with 143 on SIGTERM and 130 on SIGINT, dont' treat them as errors
       if (code > 0 && !(code === 143 || code === 130)) {
+        reportTime(startTime, 'abort', {
+          success: true,
+          error: code,
+        });
         throw createCliError(`ES exited with code ${code}`);
+      } else {
+        reportTime(startTime, 'error', {
+          success: false,
+          error: `exited with ${code}`,
+        });
       }
     });
   }

packages/kbn-pm/dist/index.js

@@ -9014,6 +9014,7 @@ class CiStatsReporter {
     const upstreamBranch = (_options$upstreamBran = options.upstreamBranch) !== null && _options$upstreamBran !== void 0 ? _options$upstreamBran : this.getUpstreamBranch();
     const kibanaUuid = options.kibanaUuid === undefined ? this.getKibanaUuid() : options.kibanaUuid;
     let email;
+    let branch;
 
     try {
       const {
@@ -9024,16 +9025,32 @@ class CiStatsReporter {
       this.log.debug(e.message);
     }
 
+    try {
+      const {
+        stdout
+      } = await (0, _execa.default)('git', ['branch', '--show-current']);
+      branch = stdout;
+    } catch (e) {
+      this.log.debug(e.message);
+    }
+
+    const memUsage = process.memoryUsage();
     const isElasticCommitter = email && email.endsWith('@elastic.co') ? true : false;
     const defaultMetadata = {
+      kibanaUuid,
+      isElasticCommitter,
       committerHash: email ? _crypto.default.createHash('sha256').update(email).digest('hex').substring(0, 20) : undefined,
+      email: isElasticCommitter ? email : undefined,
+      branch: isElasticCommitter ? branch : undefined,
       cpuCount: (_Os$cpus = _os.default.cpus()) === null || _Os$cpus === void 0 ? void 0 : _Os$cpus.length,
       cpuModel: (_Os$cpus$ = _os.default.cpus()[0]) === null || _Os$cpus$ === void 0 ? void 0 : _Os$cpus$.model,
       cpuSpeed: (_Os$cpus$2 = _os.default.cpus()[0]) === null || _Os$cpus$2 === void 0 ? void 0 : _Os$cpus$2.speed,
-      email: isElasticCommitter ? email : undefined,
       freeMem: _os.default.freemem(),
-      isElasticCommitter,
-      kibanaUuid,
+      memoryUsageRss: memUsage.rss,
+      memoryUsageHeapTotal: memUsage.heapTotal,
+      memoryUsageHeapUsed: memUsage.heapUsed,
+      memoryUsageExternal: memUsage.external,
+      memoryUsageArrayBuffers: memUsage.arrayBuffers,
       nestedTiming: process.env.CI_STATS_NESTED_TIMING ? true : false,
       osArch: _os.default.arch(),
       osPlatform: _os.default.platform(),

packages/kbn-test/src/functional_test_runner/cli.ts

@@ -9,7 +9,7 @@
 import { resolve } from 'path';
 import { inspect } from 'util';
 
-import { run, createFlagError, Flags } from '@kbn/dev-utils';
+import { run, createFlagError, Flags, ToolingLog, getTimeReporter } from '@kbn/dev-utils';
 import exitHook from 'exit-hook';
 
 import { FunctionalTestRunner } from './functional_test_runner';
@@ -27,6 +27,12 @@ const parseInstallDir = (flags: Flags) => {
 };
 
 export function runFtrCli() {
+  const runStartTime = Date.now();
+  const toolingLog = new ToolingLog({
+    level: 'info',
+    writeTo: process.stdout,
+  });
+  const reportTime = getTimeReporter(toolingLog, 'scripts/functional_test_runner');
   run(
     async ({ flags, log }) => {
       const functionalTestRunner = new FunctionalTestRunner(
@@ -68,9 +74,19 @@ export function runFtrCli() {
 
         teardownRun = true;
         if (err) {
+          await reportTime(runStartTime, 'total', {
+            success: false,
+            err: err.message,
+            ...flags,
+          });
           log.indent(-log.indent());
           log.error(err);
           process.exitCode = 1;
+        } else {
+          await reportTime(runStartTime, 'total', {
+            success: true,
+            ...flags,
+          });
         }
 
         try {

packages/kbn-test/src/functional_tests/cli/start_servers/cli.js

@@ -18,6 +18,8 @@ import { processOptions, displayHelp } from './args';
 export async function startServersCli(defaultConfigPath) {
   await runCli(displayHelp, async (userOptions) => {
     const options = processOptions(userOptions, defaultConfigPath);
-    await startServers(options);
+    await startServers({
+      ...options,
+    });
   });
 }

packages/kbn-test/src/functional_tests/tasks.ts

@@ -9,7 +9,7 @@
 import { relative } from 'path';
 import * as Rx from 'rxjs';
 import { startWith, switchMap, take } from 'rxjs/operators';
-import { withProcRunner, ToolingLog, REPO_ROOT } from '@kbn/dev-utils';
+import { withProcRunner, ToolingLog, REPO_ROOT, getTimeReporter } from '@kbn/dev-utils';
 import dedent from 'dedent';
 
 import {
@@ -147,7 +147,14 @@ interface StartServerOptions {
   useDefaultConfig?: boolean;
 }
 
-export async function startServers(options: StartServerOptions) {
+export async function startServers({ ...options }: StartServerOptions) {
+  const runStartTime = Date.now();
+  const toolingLog = new ToolingLog({
+    level: 'info',
+    writeTo: process.stdout,
+  });
+  const reportTime = getTimeReporter(toolingLog, 'scripts/functional_tests_server');
+
   const log = options.createLogger();
   const opts = {
     ...options,
@@ -170,6 +177,11 @@ export async function startServers(options: StartServerOptions) {
       },
     });
 
+    reportTime(runStartTime, 'ready', {
+      success: true,
+      ...options,
+    });
+
     // wait for 5 seconds of silence before logging the
     // success message so that it doesn't get buried
     await silence(log, 5000);

packages/kbn-test/src/jest/run.ts

@@ -21,7 +21,8 @@ import { resolve, relative, sep as osSep } from 'path';
 import { existsSync } from 'fs';
 import { run } from 'jest';
 import { buildArgv } from 'jest-cli/build/cli';
-import { ToolingLog } from '@kbn/dev-utils';
+import { ToolingLog, getTimeReporter } from '@kbn/dev-utils';
+import { map } from 'lodash';
 
 // yarn test:jest src/core/server/saved_objects
 // yarn test:jest src/core/public/core_system.test.ts
@@ -35,9 +36,14 @@ export function runJest(configName = 'jest.config.js') {
     writeTo: process.stdout,
   });
 
+  const runStartTime = Date.now();
+  const reportTime = getTimeReporter(log, 'scripts/jest');
+  let cwd: string;
+  let testFiles: string[];
+
   if (!argv.config) {
-    const cwd = process.env.INIT_CWD || process.cwd();
-    const testFiles = argv._.splice(2).map((p) => resolve(cwd, p));
+    cwd = process.env.INIT_CWD || process.cwd();
+    testFiles = argv._.splice(2).map((p) => resolve(cwd, p));
     const commonTestFiles = commonBasePath(testFiles);
     const testFilesProvided = testFiles.length > 0;
 
@@ -73,7 +79,14 @@ export function runJest(configName = 'jest.config.js') {
     process.env.NODE_ENV = 'test';
   }
 
-  run();
+  run().then(() => {
+    // Success means that tests finished, doesn't mean they passed.
+    reportTime(runStartTime, 'total', {
+      success: true,
+      isXpack: cwd.includes('x-pack'),
+      testFiles: map(testFiles, (testFile) => relative(cwd, testFile)),
+    });
+  });
 }
 
 /**

src/dev/run_check_published_api_changes.ts

@@ -6,7 +6,7 @@
  * Side Public License, v 1.
  */
 
-import { ToolingLog } from '@kbn/dev-utils';
+import { ToolingLog, getTimeReporter } from '@kbn/dev-utils';
 import {
   Extractor,
   IConfigFile,
@@ -27,6 +27,9 @@ const log = new ToolingLog({
   writeTo: process.stdout,
 });
 
+const runStartTime = Date.now();
+const reportTime = getTimeReporter(log, 'scripts/check_published_api_changes');
+
 /*
  * Step 1: execute build:types
  * This users tsconfig.types.json to generate types in `target/types`
@@ -184,6 +187,7 @@ async function run(folder: string, { opts }: { opts: Options }): Promise<boolean
       log.error(e);
       return false;
     }
+
     log.info(`${folder} API: updated documentation ✔`);
   }
 
@@ -262,9 +266,22 @@ async function run(folder: string, { opts }: { opts: Options }): Promise<boolean
   }
 
   if (results.includes(false)) {
+    reportTime(runStartTime, 'error', {
+      success: false,
+      ...opts,
+    });
     process.exitCode = 1;
+  } else {
+    reportTime(runStartTime, 'total', {
+      success: true,
+      ...opts,
+    });
   }
 })().catch((e) => {
+  reportTime(runStartTime, 'error', {
+    success: false,
+    error: e.message,
+  });
   log.error(e);
   process.exitCode = 1;
 });

src/dev/run_i18n_check.ts

@@ -9,7 +9,7 @@
 import chalk from 'chalk';
 import Listr from 'listr';
 
-import { createFailError, run } from '@kbn/dev-utils';
+import { createFailError, run, ToolingLog, getTimeReporter } from '@kbn/dev-utils';
 import { ErrorReporter, I18nConfig } from './i18n';
 import {
   extractDefaultMessages,
@@ -19,6 +19,14 @@ import {
   mergeConfigs,
 } from './i18n/tasks';
 
+const toolingLog = new ToolingLog({
+  level: 'info',
+  writeTo: process.stdout,
+});
+
+const runStartTime = Date.now();
+const reportTime = getTimeReporter(toolingLog, 'scripts/i18n_check');
+
 const skipOnNoTranslations = ({ config }: { config: I18nConfig }) =>
   !config.translations.length && 'No translations found.';
 
@@ -116,13 +124,24 @@ run(
       const reporter = new ErrorReporter();
       const messages: Map<string, { message: string }> = new Map();
       await list.run({ messages, reporter });
-    } catch (error) {
+
+      reportTime(runStartTime, 'total', {
+        success: true,
+      });
+    } catch (error: Error | ErrorReporter) {
       process.exitCode = 1;
       if (error instanceof ErrorReporter) {
         error.errors.forEach((e: string | Error) => log.error(e));
+        reportTime(runStartTime, 'error', {
+          success: false,
+        });
       } else {
         log.error('Unhandled exception!');
         log.error(error);
+        reportTime(runStartTime, 'error', {
+          success: false,
+          error: error.message,
+        });
       }
     }
   },