[dev/cli/timings] report on time to dev server listening (#95120)

Co-authored-by: spalger <spalger@users.noreply.github.com>

docs/developer/telemetry.asciidoc

@@ -8,6 +8,7 @@ The operations we current report timing data for:
 * Total execution time of `yarn kbn bootstrap`.
 * Total execution time of `@kbn/optimizer` runs as well as the following metadata about the runs: The number of bundles created, the number of bundles which were cached, usage of `--watch`, `--dist`, `--workers` and `--no-cache` flags, and the count of themes being built.
 * The time from when you run `yarn start` until both the Kibana server and `@kbn/optimizer` are ready for use.
+* The time it takes for the Kibana server to start listening after it is spawned by `yarn start`.
 
 Along with the execution time of each execution, we ship the following information about your machine to the service:
 

src/dev/cli_dev_mode/cli_dev_mode.test.ts

@@ -31,6 +31,9 @@ const { Optimizer } = jest.requireMock('./optimizer');
 jest.mock('./dev_server');
 const { DevServer } = jest.requireMock('./dev_server');
 
+jest.mock('@kbn/dev-utils/target/ci_stats_reporter');
+const { CiStatsReporter } = jest.requireMock('@kbn/dev-utils/target/ci_stats_reporter');
+
 jest.mock('./get_server_watch_paths', () => ({
   getServerWatchPaths: jest.fn(() => ({
     watchPaths: ['<mock watch paths>'],
@@ -208,6 +211,11 @@ describe('#start()/#stop()', () => {
         run$: devServerRun$,
       };
     });
+    CiStatsReporter.fromEnv.mockImplementation(() => {
+      return {
+        isEnabled: jest.fn().mockReturnValue(false),
+      };
+    });
   });
 
   afterEach(() => {

src/dev/cli_dev_mode/cli_dev_mode.ts

@@ -10,7 +10,16 @@ import Path from 'path';
 
 import { REPO_ROOT, CiStatsReporter } from '@kbn/dev-utils';
 import * as Rx from 'rxjs';
-import { map, mapTo, filter, take, tap, distinctUntilChanged, switchMap } from 'rxjs/operators';
+import {
+  map,
+  mapTo,
+  filter,
+  take,
+  tap,
+  distinctUntilChanged,
+  switchMap,
+  concatMap,
+} from 'rxjs/operators';
 
 import { CliArgs } from '../../core/server/config';
 import { LegacyConfig } from '../../core/server/legacy';
@@ -167,29 +176,10 @@ export class CliDevMode {
     this.subscription = new Rx.Subscription();
     this.startTime = Date.now();
 
-    this.subscription.add(
-      this.getStarted$()
-        .pipe(
-          switchMap(async (success) => {
-            const reporter = CiStatsReporter.fromEnv(this.log.toolingLog);
-            await reporter.timings({
-              timings: [
-                {
-                  group: 'yarn start',
-                  id: 'started',
-                  ms: Date.now() - this.startTime!,
-                  meta: { success },
-                },
-              ],
-            });
-          })
-        )
-        .subscribe({
-          error: (error) => {
-            this.log.bad(`[ci-stats/timings] unable to record startup time:`, error.stack);
-          },
-        })
-    );
+    const reporter = CiStatsReporter.fromEnv(this.log.toolingLog);
+    if (reporter.isEnabled()) {
+      this.subscription.add(this.reportTimings(reporter));
+    }
 
     if (basePathProxy) {
       const serverReady$ = new Rx.BehaviorSubject(false);
@@ -245,6 +235,64 @@ export class CliDevMode {
     this.subscription.add(this.devServer.run$.subscribe(this.observer('dev server')));
   }
 
+  private reportTimings(reporter: CiStatsReporter) {
+    const sub = new Rx.Subscription();
+
+    sub.add(
+      this.getStarted$()
+        .pipe(
+          concatMap(async (success) => {
+            await reporter.timings({
+              timings: [
+                {
+                  group: 'yarn start',
+                  id: 'started',
+                  ms: Date.now() - this.startTime!,
+                  meta: { success },
+                },
+              ],
+            });
+          })
+        )
+        .subscribe({
+          error: (error) => {
+            this.log.bad(`[ci-stats/timings] unable to record startup time:`, error.stack);
+          },
+        })
+    );
+
+    sub.add(
+      this.devServer
+        .getRestartTime$()
+        .pipe(
+          concatMap(async ({ ms }, i) => {
+            await reporter.timings({
+              timings: [
+                {
+                  group: 'yarn start',
+                  id: 'dev server restart',
+                  ms,
+                  meta: {
+                    sequence: i + 1,
+                  },
+                },
+              ],
+            });
+          })
+        )
+        .subscribe({
+          error: (error) => {
+            this.log.bad(
+              `[ci-stats/timings] unable to record dev server restart time:`,
+              error.stack
+            );
+          },
+        })
+    );
+
+    return sub;
+  }
+
   /**
    * returns an observable that emits once the dev server and optimizer are started, emits
    * true if they both started successfully, otherwise false

src/dev/cli_dev_mode/dev_server.test.ts

@@ -15,6 +15,8 @@ import { extendedEnvSerializer } from './test_helpers';
 import { DevServer, Options } from './dev_server';
 import { TestLog } from './log';
 
+jest.useFakeTimers('modern');
+
 class MockProc extends EventEmitter {
   public readonly signalsSent: string[] = [];
 
@@ -91,6 +93,17 @@ const run = (server: DevServer) => {
   return subscription;
 };
 
+const collect = <T>(stream: Rx.Observable<T>) => {
+  const events: T[] = [];
+  const subscription = stream.subscribe({
+    next(item) {
+      events.push(item);
+    },
+  });
+  subscriptions.push(subscription);
+  return events;
+};
+
 afterEach(() => {
   if (currentProc) {
     currentProc.removeAllListeners();
@@ -107,6 +120,9 @@ describe('#run$', () => {
   it('starts the dev server with the right options', () => {
     run(new DevServer(defaultOptions)).unsubscribe();
 
+    // ensure that FORCE_COLOR is in the env for consistency in snapshot
+    process.env.FORCE_COLOR = process.env.FORCE_COLOR || 'true';
+
     expect(execa.node.mock.calls).toMatchInlineSnapshot(`
       Array [
         Array [
@@ -305,7 +321,106 @@ describe('#run$', () => {
     expect(currentProc.signalsSent).toEqual([]);
     sigint$.next();
     expect(currentProc.signalsSent).toEqual(['SIGINT']);
-    await new Promise((resolve) => setTimeout(resolve, 1000));
+    jest.advanceTimersByTime(100);
     expect(currentProc.signalsSent).toEqual(['SIGINT', 'SIGKILL']);
   });
 });
+
+describe('#getPhase$', () => {
+  it('emits "starting" when run$ is subscribed then emits "fatal exit" when server exits with code > 0, then starting once watcher fires and "listening" when the server is ready', () => {
+    const server = new DevServer(defaultOptions);
+    const events = collect(server.getPhase$());
+
+    expect(events).toEqual([]);
+    run(server);
+    expect(events).toEqual(['starting']);
+    events.length = 0;
+
+    isProc(currentProc);
+    currentProc.mockExit(2);
+    expect(events).toEqual(['fatal exit']);
+    events.length = 0;
+
+    restart$.next();
+    expect(events).toEqual(['starting']);
+    events.length = 0;
+
+    currentProc.mockListening();
+    expect(events).toEqual(['listening']);
+  });
+});
+
+describe('#getRestartTime$()', () => {
+  it('does not send event if server does not start listening before starting again', () => {
+    const server = new DevServer(defaultOptions);
+    const phases = collect(server.getPhase$());
+    const events = collect(server.getRestartTime$());
+    run(server);
+
+    isProc(currentProc);
+    restart$.next();
+    jest.advanceTimersByTime(1000);
+    restart$.next();
+    jest.advanceTimersByTime(1000);
+    restart$.next();
+    expect(phases).toMatchInlineSnapshot(`
+      Array [
+        "starting",
+        "starting",
+        "starting",
+        "starting",
+      ]
+    `);
+    expect(events).toEqual([]);
+  });
+
+  it('reports restart times', () => {
+    const server = new DevServer(defaultOptions);
+    const phases = collect(server.getPhase$());
+    const events = collect(server.getRestartTime$());
+
+    run(server);
+    isProc(currentProc);
+
+    restart$.next();
+    currentProc.mockExit(1);
+    restart$.next();
+    restart$.next();
+    restart$.next();
+    currentProc.mockExit(1);
+    restart$.next();
+    jest.advanceTimersByTime(1234);
+    currentProc.mockListening();
+    restart$.next();
+    restart$.next();
+    jest.advanceTimersByTime(5678);
+    currentProc.mockListening();
+
+    expect(phases).toMatchInlineSnapshot(`
+      Array [
+        "starting",
+        "starting",
+        "fatal exit",
+        "starting",
+        "starting",
+        "starting",
+        "fatal exit",
+        "starting",
+        "listening",
+        "starting",
+        "starting",
+        "listening",
+      ]
+    `);
+    expect(events).toMatchInlineSnapshot(`
+      Array [
+        Object {
+          "ms": 1234,
+        },
+        Object {
+          "ms": 5678,
+        },
+      ]
+    `);
+  });
+});

src/dev/cli_dev_mode/dev_server.ts

@@ -16,6 +16,7 @@ import {
   share,
   mergeMap,
   switchMap,
+  scan,
   takeUntil,
   ignoreElements,
 } from 'rxjs/operators';
@@ -73,6 +74,32 @@ export class DevServer {
     return this.phase$.asObservable();
   }
 
+  /**
+   * returns an observable of objects describing server start time.
+   */
+  getRestartTime$() {
+    return this.phase$.pipe(
+      scan((acc: undefined | { phase: string; time: number }, phase) => {
+        if (phase === 'starting') {
+          return { phase, time: Date.now() };
+        }
+
+        if (phase === 'listening' && acc?.phase === 'starting') {
+          return { phase, time: Date.now() - acc.time };
+        }
+
+        return undefined;
+      }, undefined),
+      mergeMap((desc) => {
+        if (desc?.phase !== 'listening') {
+          return [];
+        }
+
+        return [{ ms: desc.time }];
+      })
+    );
+  }
+
   /**
    * Run the Kibana server
    *