feat: Add the plumbing for application blocking latencies client side metrics (#1575)

* Remove console log * Generate more documentation * Require a call to fetch the project when using MT * use same date provider for all metrics tracers * In the metrics traceer, don’t fetch the project for each call * Remove only * Add open telemetry api * Add TestExecuteQuery_EmptyResponse to failures * TestExecuteQuery_SingleSimpleRow known failures * Fix syntax in known failures * Add two tests to the known failures * TestSampleRowKeys_Retry_WithRetryInfo to known fai * Change word dimensions to attributes * Change more docs to use Attributes instead of dim * attributes * Test should use attributes as string * For Windows replace carriage return * Update documentation with types * Add metrics collector * Metrics handler, GCPMetricsHandler and tests add * Remove only * Add metrics handlers parameter to Doc * Don’t require retries to be passed into metrics collector * Remove testMeterProvider * Remove the attributesToString function * Eliminate unused class * Generate documentation for the IMetricsHandler * Generate documentation for GCPMetricsHandler * Restrict attributes interfaces and solve compile * 🦉 Updates from OwlBot post-processor See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md * use undefined instead of null * Introduce enums for allowable values * Add more headers * Remove only * Use null to pass values around. Not undefined * Modify test step * Add metrics * Don’t provide first response latency * Remove firstResponseLatency from operation metrics * Expose interface allowing undefined not null * Better explanations for design decision inline * Use attempt start time not operation start time for firstResponseLatency * Adjust tests for first response latency * Remove TODO * Use the MethodName enum instead of string * Don’t use enum for streaming operation * Remove copy/pasted comment * Rename to OperationMetricsCollector * Rename the method to getOperationAttributes * 🦉 Updates from OwlBot post-processor See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md * 🦉 Updates from OwlBot post-processor See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md * Add aggregate views to the GCP metrics handler * Adjust test based on enum changes * Update the documentation to be more descriptive * Add the state machine to the metrics collector * Use grpc code to report attempt/operation status * Remove parameters from JS Documentation * Update interfaces and some metrics - Introduce attributes interface for each metric. - First latency should be recorded per operation not per attempt - Update tests for firstResponseLatency change * Documentation for all the different interfaces * use operation start time as the benchmark * Final operation status shouldn’t be included per a * Move OnAttemptCompleteInfo Remove unused imports too * Provide AttemptOnlyAttributes in the only file In the only file that it is needed * Move over the OperationOnlyAttributes * Adjust the guard so that it is earlier * Adjust the test output file Dates don’t get read for rows after the first row anymore. * Change streaming back to STREAMING/UNARY * 🦉 Updates from OwlBot post-processor See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md * Change metrics handler interface to support each metric * Revert "Change metrics handler interface to support each metric" This reverts commit 2781561. * Supply the projectId later in the client side metrics lifecycle * Remove the GCPMetricsHandler file * Change location of the client-side-metrics-attribu file * Change common test utilities folder name * Remove aliases for grpc status * Should be MethodName type * Rename variable as it expands beyond latency * Remove private methods for building attributes * Replace the logger class with a simple object * Remove only * Remove the logger classes Replace them with a simpler object * Add stubs * Revert "Remove the GCPMetricsHandler file" This reverts commit b6f1302. * Add exporter and helper function * Add headers and fixture * Add milliseconds unit * Record to a histogram * Add necessary elements to the GCPMetricsHandler # Conflicts: #	src/client-side-metrics/gcp-metrics-handler.ts * Pass an exporter into the GCPMetricsHandler * Move file to tests * Remove unused import * Adapt the fixture to include the projectId * More exporter code fixes * Add the fixture. We are going to use it later * Solved compiler errors. Test almost passes * Address the failing export test * Fixed the exporter. It now writes data properly. * Test should complete when the export doesnt error * Add the fixture to the shared folder * Remove two files not in this PR * delete empty file * Remove files that are already in the other PR * Remove the metrics handler fixture * Use 3 metrics instead of 1 * Replace with proper buckets * Change the metrics handler fixture * Stop using stub in exporter * Use more realistic buckets * Remove the go request to export * Modify the fixtures to be more realistic * Change the mean * Remove only * Add the export input fixture * Reducing export interval makes time complete * Add the GCPMetricsHandler test * Add a stub for the otel export * Test calling export is now working * Remove old unused code * Change tests and json structure to work with metricsCollectorData structure * Update all the fixtures * Fix the view creation code Pass in latency buckets * Starting test for gcp-metrics-handler * Put tests in the proper places * Replace start and end time with more recent values * Utilize the new metrics handler interface * Solve compiler errors resulting from metrics handl * Update the fixture * rewrite the metric to request method * Add interfaces to work with type guards * Correct the compile error problems different metric types are under metrics not scope metrics * Fix expected OTEL output test * Remove TODOs * Fix test to compare pointwise * connectivity error count corrections * Correct the fixtures * Eliminate tests using the old export input fixture * Add headers * run linter * Modify the gcp-metrics-handler and test the proces end to end * Remove only * Use a fake projectId * Only call export once * Ensure test suite completes * Remove shutdown * remove async * Don’t export the data twice * Increase the timeout * Use the PushMetricExporter interface * Removed some interfaces that are not used anymore * Update JSdoc * Move fake start time and fake end time * Remove the TODO * Update documentation * Add additional information to the error reported * Move start time and end time * Try to use timestamps in order * Reduce timestamp delay * Remove only * Inline addFakeRecentTimestamps * Move replace timestamps into the only file it is used * Fix comment * Rename the metric types * Generate documentation for the new classes * Add documentation for monitored resource * Generate documentation for the other metrics * Generate documentation for the constructor * Get documentation for replaceTimestamps, fixtures * Reduce the interval time * Make view list based on latencies * Add a guard for count * Invert the for and if * Pull all attributes out * Eliminate the need for the type guard * Eliminate the data points interface * only * Revert "Eliminate the need for the type guard" This reverts commit 791e70d. * Pull timeseries into one variable Solve the descriptor issue * Eliminate an unused import * Add a comment that explains the usefulness of each metric attribute category * Remove the gce instance setting * Eliminate the gcp cloud provider setting * run all tests * Eliminate duplicate project id from monitored resource * Change the two metric names * Extend the timeout so that the exporter has chance to work * Use spread syntax * Changed metric to otel instruments * Remove optional on Otel instruments * Rename initialize to getMetrics * Pin promisify to version 4 * cast to string - compiler errors * Change the latency buckets Adjust the test fixtures as well to account for the latency bucket change. * Updated the resultCallback comment * Change the test description * Add a comment explaining what the test is about * Completed the test for two metrics handlers * remove only * Cast as histogram to make compile error go away * Move the duplicate copies of replaceTimestamps into one file * Take steps to eliminate the ExportInput interface * Add a header * Remove only * Eliminate ExportInput and dependencies * Eliminate constant * Push conversion to status back to metrics collect Also add if statement for timeseries. * Change property names to match MetricServiceClient expectation * Solve the app_profile_id issue * It is actually app_profile not app_profile_id * Add guards that stop the export call * Remove only * Add a new test for ten metrics handlers * Remove only * Do not pass data through the Resource object anymore * Add a test for writing duplicate points to MH * Eliminate interface * Set connectivity error count to 1 (not increment) * started integration of the application blocking la * Fix tests for an empty set of latencies * Reset operation latencies per operation * Add documentation for new metrics collector method * Change the test fixtures to include application la latencies * Update the fixture for metrics collection output * Fixture adjustments * Adjust the fixtures to work with application latencies * end times still need adjusting * Get the application latencies to appear in the fixtures * Don’t do status: undefined * remove status: undefined * Use the hrtime module instead of the Date module * Do a state check * Make it explicit that it is milliseconds * 🦉 Updates from OwlBot post-processor See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md * Run linter * Add the nanos to the fixture * Add attributes * Update the fixture with the converted value * Update the hundred calls fixture --------- Co-authored-by: Owl Bot <gcf-owl-bot[bot]@users.noreply.github.com>

Author: danieljbruce

src/client-side-metrics/exporter.ts

@@ -160,15 +160,16 @@ function getMetric(
 ) {
  const streaming = dataPoint.attributes.streaming;
  const app_profile = dataPoint.attributes.app_profile;
+ const status = dataPoint.attributes.status;
  return {
  type: metricName,
  labels: Object.assign(
  {
  method: dataPoint.attributes.method,
  client_uid: dataPoint.attributes.client_uid,
- status: dataPoint.attributes.status,
  client_name: dataPoint.attributes.client_name,
  },
+ status ? {status} : null,
  streaming ? {streaming} : null,
  app_profile ? {app_profile} : null,
  ),

src/client-side-metrics/gcp-metrics-handler.ts

@@ -236,7 +236,6 @@ export class GCPMetricsHandler implements IMetricsHandler {
  app_profile: data.metricsCollectorData.app_profile,
  method: data.metricsCollectorData.method,
  client_uid: data.metricsCollectorData.client_uid,
- status: data.status,
  client_name: data.client_name,
  instanceId: data.metricsCollectorData.instanceId,
  table: data.metricsCollectorData.table,
@@ -245,13 +244,24 @@ export class GCPMetricsHandler implements IMetricsHandler {
  };
  otelInstruments.operationLatencies.record(data.operationLatency, {
  streaming: data.streaming,
+ status: data.status,
+ ...commonAttributes,
+ });
+ otelInstruments.retryCount.add(data.retryCount, {
+ status: data.status,
+ ...commonAttributes,
+ });
+ otelInstruments.firstResponseLatencies.record(data.firstResponseLatency, {
+ status: data.status,
  ...commonAttributes,
  });
+ for (const applicationLatency of data.applicationLatencies) {
+ otelInstruments.applicationBlockingLatencies.record(
+ applicationLatency,
+ commonAttributes,
+ );
+ }
  otelInstruments.retryCount.add(data.retryCount, commonAttributes);
- otelInstruments?.firstResponseLatencies.record(
- data.firstResponseLatency,
- commonAttributes,
- );
  }
 
  /**

src/client-side-metrics/metrics-handler.ts

@@ -42,6 +42,7 @@ interface StandardData {
 export interface OnOperationCompleteData extends StandardData {
  firstResponseLatency?: number;
  operationLatency: number;
+ applicationLatencies: number[];
  retryCount?: number;
 }
 

src/client-side-metrics/operation-metrics-collector.ts

@@ -21,6 +21,7 @@ const root = gax.protobuf.loadSync(
  './protos/google/bigtable/v2/response_params.proto',
 );
 const ResponseParams = root.lookupType('ResponseParams');
+const {hrtime} = require('node:process');
 
 /**
  * An interface representing a tabular API surface, such as a Bigtable table.
@@ -63,8 +64,8 @@ enum MetricsCollectorState {
  */
 export class OperationMetricsCollector {
  private state: MetricsCollectorState;
- private operationStartTime: Date | null;
- private attemptStartTime: Date | null;
+ private operationStartTime: bigint | null;
+ private attemptStartTime: bigint | null;
  private zone: string | undefined;
  private cluster: string | undefined;
  private tabularApiSurface: ITabularApiSurface;
@@ -76,6 +77,8 @@ export class OperationMetricsCollector {
  private serverTime: number | null;
  private connectivityErrorCount: number;
  private streamingOperation: StreamingState;
+ private applicationLatencies: number[];
+ private lastRowReceivedTime: bigint | null;
 
  /**
  * @param {ITabularApiSurface} tabularApiSurface Information about the Bigtable table being accessed.
@@ -102,6 +105,8 @@ export class OperationMetricsCollector {
  this.serverTime = null;
  this.connectivityErrorCount = 0;
  this.streamingOperation = streamingOperation;
+ this.lastRowReceivedTime = null;
+ this.applicationLatencies = [];
  }
 
  private getMetricsCollectorData() {
@@ -124,8 +129,9 @@ export class OperationMetricsCollector {
  */
  onOperationStart() {
  if (this.state === MetricsCollectorState.OPERATION_NOT_STARTED) {
- this.operationStartTime = new Date();
+ this.operationStartTime = hrtime.bigint();
  this.firstResponseLatency = null;
+ this.applicationLatencies = [];
  this.state =
  MetricsCollectorState.OPERATION_STARTED_ATTEMPT_NOT_IN_PROGRESS;
  } else {
@@ -148,13 +154,15 @@ export class OperationMetricsCollector {
  this.state =
  MetricsCollectorState.OPERATION_STARTED_ATTEMPT_NOT_IN_PROGRESS;
  this.attemptCount++;
- const endTime = new Date();
+ const endTime = hrtime.bigint();
  if (projectId && this.attemptStartTime) {
- const totalTime = endTime.getTime() - this.attemptStartTime.getTime();
+ const totalMilliseconds = Number(
+ (endTime - this.attemptStartTime) / BigInt(1000000),
+ );
  this.metricsHandlers.forEach(metricsHandler => {
  if (metricsHandler.onAttemptComplete) {
  metricsHandler.onAttemptComplete({
- attemptLatency: totalTime,
+ attemptLatency: totalMilliseconds,
  serverLatency: this.serverTime ?? undefined,
  connectivityErrorCount: this.connectivityErrorCount,
  streaming: this.streamingOperation,
@@ -181,10 +189,11 @@ export class OperationMetricsCollector {
  ) {
  this.state =
  MetricsCollectorState.OPERATION_STARTED_ATTEMPT_IN_PROGRESS_NO_ROWS_YET;
- this.attemptStartTime = new Date();
+ this.attemptStartTime = hrtime.bigint();
  this.serverTime = null;
  this.serverTimeRead = false;
  this.connectivityErrorCount = 0;
+ this.lastRowReceivedTime = null;
  } else {
  console.warn('Invalid state transition attempted');
  }
@@ -202,10 +211,12 @@ export class OperationMetricsCollector {
  ) {
  this.state =
  MetricsCollectorState.OPERATION_STARTED_ATTEMPT_IN_PROGRESS_SOME_ROWS_RECEIVED;
- const endTime = new Date();
+ const endTime = hrtime.bigint();
  if (projectId && this.operationStartTime) {
- this.firstResponseLatency =
- endTime.getTime() - this.operationStartTime.getTime();
+ // first response latency is measured in total milliseconds.
+ this.firstResponseLatency = Number(
+ (endTime - this.operationStartTime) / BigInt(1000000),
+ );
  }
  }
  }
@@ -223,9 +234,11 @@ export class OperationMetricsCollector {
  MetricsCollectorState.OPERATION_STARTED_ATTEMPT_NOT_IN_PROGRESS
  ) {
  this.state = MetricsCollectorState.OPERATION_COMPLETE;
- const endTime = new Date();
+ const endTime = hrtime.bigint();
  if (projectId && this.operationStartTime) {
- const totalTime = endTime.getTime() - this.operationStartTime.getTime();
+ const totalMilliseconds = Number(
+ (endTime - this.operationStartTime) / BigInt(1000000),
+ );
  {
  this.metricsHandlers.forEach(metricsHandler => {
  if (metricsHandler.onOperationComplete) {
@@ -235,9 +248,10 @@ export class OperationMetricsCollector {
  metricsCollectorData: this.getMetricsCollectorData(),
  client_name: `nodejs-bigtable/${version}`,
  projectId,
- operationLatency: totalTime,
+ operationLatency: totalMilliseconds,
  retryCount: this.attemptCount - 1,
  firstResponseLatency: this.firstResponseLatency ?? undefined,
+ applicationLatencies: this.applicationLatencies,
  });
  }
  });
@@ -281,6 +295,38 @@ export class OperationMetricsCollector {
  }
  }
 
+ /**
+ * Called when a row from the Bigtable stream reaches the application user.
+ *
+ * This method is used to calculate the latency experienced by the application
+ * when reading rows from a Bigtable stream. It records the time between the
+ * previous row being received and the current row reaching the user. These
+ * latencies are then collected and reported as `applicationBlockingLatencies`
+ * when the operation completes.
+ */
+ onRowReachesUser() {
+ if (
+ this.state ===
+ MetricsCollectorState.OPERATION_STARTED_ATTEMPT_IN_PROGRESS_NO_ROWS_YET ||
+ this.state ===
+ MetricsCollectorState.OPERATION_STARTED_ATTEMPT_IN_PROGRESS_SOME_ROWS_RECEIVED ||
+ this.state ===
+ MetricsCollectorState.OPERATION_STARTED_ATTEMPT_NOT_IN_PROGRESS
+ ) {
+ const currentTime = hrtime.bigint();
+ if (this.lastRowReceivedTime) {
+ // application latency is measured in total milliseconds.
+ const applicationLatency = Number(
+ (currentTime - this.lastRowReceivedTime) / BigInt(1000000),
+ );
+ this.applicationLatencies.push(applicationLatency);
+ }
+ this.lastRowReceivedTime = currentTime;
+ } else {
+ console.warn('Invalid state transition attempted');
+ }
+ }
+
  /**
  * Called when status information is received. Extracts zone and cluster information.
  * @param {object} status The received status information.