ref(tracing): Reset IdleTimeout based on activities count (#5044)

Previously, when the activities count of an idle transaction hit 0, it would trigger a timeout for `idleTimeout` ms, and then always end the transaction. This means that if a span (like fetch/xhr request) started right after the activities count went to 0 (1 -> 0 -> 1), the transaction would always finish after `idleTimeout` ms, instead of waiting for the newest activity to finish.

This was primarily done to prevent polling conditions and to not artificially inflate duration. Nowadays though, web vitals like LCP are a lot more important as a measurement in transactions than the strict duration (as with activities, they are a bit arbitrary). By making `idleTimeout` be strict about finish after activities go to 0, we often times would miss the LCP value that the browser would record, leading to many transactions not having proper LCPs. 

To get the LCP value close to browser quality as possible, we now reset the `idleTimeout` timeout if there are still existing activities. The concern here is with polling. To prevent polling issues, we now also have an additional `finalTimeout` that is started when the idle transaction is created. This double timeout system (alongside the heartbeat), should always enforce that the transaction is finished.

Author: AbhiPrasad

MIGRATION.md

@@ -291,6 +291,7 @@ For our efforts to reduce bundle size of the SDK we had to remove and refactor p
 - Rename `UserAgent` integration to `HttpContext`. (see [#5027](https://github.com/getsentry/sentry-javascript/pull/5027))
 - Remove `SDK_NAME` export from `@sentry/browser`, `@sentry/node`, `@sentry/tracing` and `@sentry/vue` packages.
 - Removed `eventStatusFromHttpCode` to save on bundle size.
+- Replace `BrowserTracing` `maxTransactionDuration` option with `finalTimeout` option
 
 ## Sentry Angular SDK Changes
 

packages/integration-tests/suites/tracing/browsertracing/backgroundtab-custom/test.ts

@@ -36,5 +36,5 @@ sentryTest('should finish a custom transaction when the page goes background', a
   expect(id_before).toBe(id_after);
   expect(name_after).toBe(name_before);
   expect(status_after).toBe('cancelled');
-  expect(tags_after).toStrictEqual({ finishReason: 'documentHidden', visibilitychange: 'document.hidden' });
+  expect(tags_after).toStrictEqual({ visibilitychange: 'document.hidden' });
 });

packages/integration-tests/suites/tracing/browsertracing/backgroundtab-pageload/test.ts

@@ -17,6 +17,5 @@ sentryTest('should finish pageload transaction when the page goes background', a
   expect(pageloadTransaction.contexts?.trace.status).toBe('cancelled');
   expect(pageloadTransaction.contexts?.trace.tags).toMatchObject({
     visibilitychange: 'document.hidden',
-    finishReason: 'documentHidden',
   });
 });

packages/tracing/src/browser/backgroundtab.ts

@@ -1,6 +1,5 @@
 import { getGlobalObject, logger } from '@sentry/utils';
 
-import { FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS } from '../constants';
 import { IS_DEBUG_BUILD } from '../flags';
 import { IdleTransaction } from '../idletransaction';
 import { SpanStatusType } from '../span';
@@ -29,7 +28,6 @@ export function registerBackgroundTabDetection(): void {
           activeTransaction.setStatus(statusType);
         }
         activeTransaction.setTag('visibilitychange', 'document.hidden');
-        activeTransaction.setTag(FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS[2]);
         activeTransaction.finish();
       }
     });

packages/tracing/src/browser/browsertracing.ts

@@ -4,8 +4,8 @@ import { getGlobalObject, logger } from '@sentry/utils';
 
 import { IS_DEBUG_BUILD } from '../flags';
 import { startIdleTransaction } from '../hubextensions';
-import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../idletransaction';
-import { extractTraceparentData, secToMs } from '../utils';
+import { DEFAULT_FINAL_TIMEOUT, DEFAULT_IDLE_TIMEOUT } from '../idletransaction';
+import { extractTraceparentData } from '../utils';
 import { registerBackgroundTabDetection } from './backgroundtab';
 import { MetricsInstrumentation } from './metrics';
 import {
@@ -15,19 +15,29 @@ import {
 } from './request';
 import { instrumentRoutingWithDefaults } from './router';
 
-export const DEFAULT_MAX_TRANSACTION_DURATION_SECONDS = 600;
-
 /** Options for Browser Tracing integration */
 export interface BrowserTracingOptions extends RequestInstrumentationOptions {
   /**
-   * The time to wait in ms until the transaction will be finished. The transaction will use the end timestamp of
-   * the last finished span as the endtime for the transaction.
+   * The time to wait in ms until the transaction will be finished during an idle state. An idle state is defined
+   * by a moment where there are no in-progress spans.
+   *
+   * The transaction will use the end timestamp of the last finished span as the endtime for the transaction.
+   * If there are still active spans when this the `idleTimeout` is set, the `idleTimeout` will get reset.
    * Time is in ms.
    *
    * Default: 1000
    */
   idleTimeout: number;
 
+  /**
+   * The max duration for a transaction. If a transaction duration hits the `finalTimeout` value, it
+   * will be finished.
+   * Time is in ms.
+   *
+   * Default: 30000
+   */
+  finalTimeout: number;
+
   /**
    * Flag to enable/disable creation of `navigation` transaction on history changes.
    *
@@ -42,15 +52,6 @@ export interface BrowserTracingOptions extends RequestInstrumentationOptions {
    */
   startTransactionOnPageLoad: boolean;
 
-  /**
-   * The maximum duration of a transaction before it will be marked as "deadline_exceeded".
-   * If you never want to mark a transaction set it to 0.
-   * Time is in seconds.
-   *
-   * Default: 600
-   */
-  maxTransactionDuration: number;
-
   /**
    * Flag Transactions where tabs moved to background with "cancelled". Browser background tab timing is
    * not suited towards doing precise measurements of operations. By default, we recommend that this option
@@ -94,8 +95,8 @@ export interface BrowserTracingOptions extends RequestInstrumentationOptions {
 
 const DEFAULT_BROWSER_TRACING_OPTIONS = {
   idleTimeout: DEFAULT_IDLE_TIMEOUT,
+  finalTimeout: DEFAULT_FINAL_TIMEOUT,
   markBackgroundTransactions: true,
-  maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION_SECONDS,
   routingInstrumentation: instrumentRoutingWithDefaults,
   startTransactionOnLocationChange: true,
   startTransactionOnPageLoad: true,
@@ -129,14 +130,10 @@ export class BrowserTracing implements Integration {
 
   private readonly _emitOptionsWarning?: boolean;
 
-  /** Store configured idle timeout so that it can be added as a tag to transactions */
-  private _configuredIdleTimeout: BrowserTracingOptions['idleTimeout'] | undefined = undefined;
-
   public constructor(_options?: Partial<BrowserTracingOptions>) {
     let tracingOrigins = defaultRequestInstrumentationOptions.tracingOrigins;
     // NOTE: Logger doesn't work in constructors, as it's initialized after integrations instances
     if (_options) {
-      this._configuredIdleTimeout = _options.idleTimeout;
       if (_options.tracingOrigins && Array.isArray(_options.tracingOrigins) && _options.tracingOrigins.length !== 0) {
         tracingOrigins = _options.tracingOrigins;
       } else {
@@ -205,7 +202,7 @@ export class BrowserTracing implements Integration {
     }
 
     // eslint-disable-next-line @typescript-eslint/unbound-method
-    const { beforeNavigate, idleTimeout, maxTransactionDuration } = this.options;
+    const { beforeNavigate, idleTimeout, finalTimeout } = this.options;
 
     const parentContextFromHeader = context.op === 'pageload' ? getHeaderContext() : undefined;
 
@@ -233,16 +230,14 @@ export class BrowserTracing implements Integration {
       hub,
       finalContext,
       idleTimeout,
+      finalTimeout,
       true,
       { location }, // for use in the tracesSampler
     );
-    idleTransaction.registerBeforeFinishCallback((transaction, endTimestamp) => {
+    idleTransaction.registerBeforeFinishCallback(transaction => {
       this._metrics.addPerformanceEntries(transaction);
-      adjustTransactionDuration(secToMs(maxTransactionDuration), transaction, endTimestamp);
     });
 
-    idleTransaction.setTag('idleTimeout', this._configuredIdleTimeout);
-
     return idleTransaction as Transaction;
   }
 }
@@ -266,13 +261,3 @@ export function getMetaContent(metaName: string): string | null {
   const el = getGlobalObject<Window>().document.querySelector(`meta[name=${metaName}]`);
   return el ? el.getAttribute('content') : null;
 }
-
-/** Adjusts transaction value based on max transaction duration */
-function adjustTransactionDuration(maxDuration: number, transaction: IdleTransaction, endTimestamp: number): void {
-  const diff = endTimestamp - transaction.startTimestamp;
-  const isOutdatedTransaction = endTimestamp && (diff > maxDuration || diff < 0);
-  if (isOutdatedTransaction) {
-    transaction.setStatus('deadline_exceeded');
-    transaction.setTag('maxTransactionDurationExceeded', 'true');
-  }
-}

packages/tracing/src/constants.ts

@@ -1,3 +1,4 @@
+/* eslint-disable max-lines */
 import { getMainCarrier, Hub } from '@sentry/hub';
 import {
   ClientOptions,
@@ -196,14 +197,15 @@ function _startTransaction(
 export function startIdleTransaction(
   hub: Hub,
   transactionContext: TransactionContext,
-  idleTimeout?: number,
+  idleTimeout: number,
+  finalTimeout: number,
   onScope?: boolean,
   customSamplingContext?: CustomSamplingContext,
 ): IdleTransaction {
   const client = hub.getClient();
   const options: Partial<ClientOptions> = (client && client.getOptions()) || {};
 
-  let transaction = new IdleTransaction(transactionContext, hub, idleTimeout, onScope);
+  let transaction = new IdleTransaction(transactionContext, hub, idleTimeout, finalTimeout, onScope);
   transaction = sample(transaction, options, {
     parentSampled: transactionContext.parentSampled,
     transactionContext,

packages/tracing/src/hubextensions.ts

@@ -1,13 +1,14 @@
+/* eslint-disable max-lines */
 import { Hub } from '@sentry/hub';
 import { TransactionContext } from '@sentry/types';
 import { logger, timestampWithMs } from '@sentry/utils';
 
-import { FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS } from './constants';
 import { IS_DEBUG_BUILD } from './flags';
 import { Span, SpanRecorder } from './span';
 import { Transaction } from './transaction';
 
 export const DEFAULT_IDLE_TIMEOUT = 1000;
+export const DEFAULT_FINAL_TIMEOUT = 30000;
 export const HEARTBEAT_INTERVAL = 5000;
 
 /**
@@ -17,7 +18,7 @@ export class IdleTransactionSpanRecorder extends SpanRecorder {
   public constructor(
     private readonly _pushActivity: (id: string) => void,
     private readonly _popActivity: (id: string) => void,
-    public transactionSpanId: string = '',
+    public transactionSpanId: string,
     maxlen?: number,
   ) {
     super(maxlen);
@@ -69,25 +70,28 @@ export class IdleTransaction extends Transaction {
   private readonly _beforeFinishCallbacks: BeforeFinishCallback[] = [];
 
   /**
-   * If a transaction is created and no activities are added, we want to make sure that
-   * it times out properly. This is cleared and not used when activities are added.
+   * Timer that tracks Transaction idleTimeout
    */
-  private _initTimeout: ReturnType<typeof setTimeout> | undefined;
+  private _idleTimeoutID: ReturnType<typeof setTimeout> | undefined;
 
   public constructor(
     transactionContext: TransactionContext,
-    private readonly _idleHub?: Hub,
+    private readonly _idleHub: Hub,
     /**
-     * The time to wait in ms until the idle transaction will be finished.
-     * @default 1000
+     * The time to wait in ms until the idle transaction will be finished. This timer is started each time
+     * there are no active spans on this transaction.
      */
     private readonly _idleTimeout: number = DEFAULT_IDLE_TIMEOUT,
+    /**
+     * The final value in ms that a transaction cannot exceed
+     */
+    private readonly _finalTimeout: number = DEFAULT_FINAL_TIMEOUT,
     // Whether or not the transaction should put itself on the scope when it starts and pop itself off when it ends
     private readonly _onScope: boolean = false,
   ) {
     super(transactionContext, _idleHub);
 
-    if (_idleHub && _onScope) {
+    if (_onScope) {
       // There should only be one active transaction on the scope
       clearActiveTransaction(_idleHub);
 
@@ -97,11 +101,13 @@ export class IdleTransaction extends Transaction {
       _idleHub.configureScope(scope => scope.setSpan(this));
     }
 
-    this._initTimeout = setTimeout(() => {
+    this._startIdleTimeout();
+    setTimeout(() => {
       if (!this._finished) {
+        this.setStatus('deadline_exceeded');
         this.finish();
       }
-    }, this._idleTimeout);
+    }, this._finalTimeout);
   }
 
   /** {@inheritDoc} */
@@ -193,15 +199,34 @@ export class IdleTransaction extends Transaction {
     this.spanRecorder.add(this);
   }
 
+  /**
+   * Cancels the existing idletimeout, if there is one
+   */
+  private _cancelIdleTimeout(): void {
+    if (this._idleTimeoutID) {
+      clearTimeout(this._idleTimeoutID);
+      this._idleTimeoutID = undefined;
+    }
+  }
+
+  /**
+   * Creates an idletimeout
+   */
+  private _startIdleTimeout(endTimestamp?: Parameters<IdleTransaction['finish']>[0]): void {
+    this._cancelIdleTimeout();
+    this._idleTimeoutID = setTimeout(() => {
+      if (!this._finished && Object.keys(this.activities).length === 0) {
+        this.finish(endTimestamp);
+      }
+    }, this._idleTimeout);
+  }
+
   /**
    * Start tracking a specific activity.
    * @param spanId The span id that represents the activity
    */
   private _pushActivity(spanId: string): void {
-    if (this._initTimeout) {
-      clearTimeout(this._initTimeout);
-      this._initTimeout = undefined;
-    }
+    this._cancelIdleTimeout();
     IS_DEBUG_BUILD && logger.log(`[Tracing] pushActivity: ${spanId}`);
     this.activities[spanId] = true;
     IS_DEBUG_BUILD && logger.log('[Tracing] new activities count', Object.keys(this.activities).length);
@@ -220,17 +245,10 @@ export class IdleTransaction extends Transaction {
     }
 
     if (Object.keys(this.activities).length === 0) {
-      const timeout = this._idleTimeout;
       // We need to add the timeout here to have the real endtimestamp of the transaction
       // Remember timestampWithMs is in seconds, timeout is in ms
-      const end = timestampWithMs() + timeout / 1000;
-
-      setTimeout(() => {
-        if (!this._finished) {
-          this.setTag(FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS[1]);
-          this.finish(end);
-        }
-      }, timeout);
+      const endTimestamp = timestampWithMs() + this._idleTimeout / 1000;
+      this._startIdleTimeout(endTimestamp);
     }
   }
 
@@ -257,7 +275,6 @@ export class IdleTransaction extends Transaction {
     if (this._heartbeatCounter >= 3) {
       IS_DEBUG_BUILD && logger.log('[Tracing] Transaction finished because of no change for 3 heart beats');
       this.setStatus('deadline_exceeded');
-      this.setTag(FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS[0]);
       this.finish();
     } else {
       this._pingHeartbeat();
@@ -278,14 +295,12 @@ export class IdleTransaction extends Transaction {
 /**
  * Reset transaction on scope to `undefined`
  */
-function clearActiveTransaction(hub?: Hub): void {
-  if (hub) {
-    const scope = hub.getScope();
-    if (scope) {
-      const transaction = scope.getTransaction();
-      if (transaction) {
-        scope.setSpan(undefined);
-      }
+function clearActiveTransaction(hub: Hub): void {
+  const scope = hub.getScope();
+  if (scope) {
+    const transaction = scope.getTransaction();
+    if (transaction) {
+      scope.setSpan(undefined);
     }
   }
 }