feat(profiling): js self profiling (#7273)

* feat(profiling): add boilerplate

* feat(profiling): add files and remove isDebugBuild in favor of __DEBUG_BUILD__

* ref(lint): fix linter errors on most files

* ref(profile): convert half the profile

* deps(sentry): start profiler

* ref(profiling): cleanup warnings and add os/device info

* rollback yarn change

* feat(hub): move start transaction

* Remove span.start for profiler.stop so that we don't have idletimeout causing long spans again

* feat(build): build esm/cjs and types

* ref(profiling): update txn to txn|undefined type

* test(profiling): add utils and tests for browser profiling integration

* test(tracing): assert onStartRouteTransaction is called by route instrumentation

* fix(verdaccio): add pkg to verdaccio config

* eslint: run --fix

* fix(profile): change platform to javascript

* ref(profiling): move profiling under browser package

* ref(profiling): remove undefined from txn type union in wrapStartTransaction

* fix(profiling): fix test

* ref(profiling): rename profile and move it under types

* chore(profiling): run linters

* ref(profiling): split sendProfile to avoid a circular ref

* ref(profiling): split cache

* chore(profiling): sort imports

* Update packages/browser/src/profiling/hubextensions.ts

Co-authored-by: Luca Forstner <luca.forstner@sentry.io>

* Update packages/browser/src/profiling/integration.ts

Co-authored-by: Luca Forstner <luca.forstner@sentry.io>

* Update packages/browser/src/profiling/integration.ts

* lint

---------

Co-authored-by: k-fish <kevan.fisher@sentry.io>
Co-authored-by: Luca Forstner <luca.forstner@sentry.io>

packages/browser/src/index.ts

@@ -32,3 +32,8 @@ export { Replay } from '@sentry/replay';
 // __ROLLUP_EXCLUDE_OFFLINE_FROM_BUNDLES_BEGIN__
 export { makeBrowserOfflineTransport } from './transports/offline';
 // __ROLLUP_EXCLUDE_OFFLINE_FROM_BUNDLES_END__
+
+// __ROLLUP_EXCLUDE_BROWSER_PROFILING_FROM_BUNDLES_BEGIN__
+export { onProfilingStartRouteTransaction } from './profiling/hubextensions';
+export { BrowserProfilingIntegration } from './profiling/integration';
+// __ROLLUP_EXCLUDE_BROWSER_PROFILING_FROM_BUNDLES_END__

packages/browser/src/profiling/cache.ts

@@ -0,0 +1,72 @@
+import type { Event } from '@sentry/types';
+
+/**
+ * Creates a cache that evicts keys in fifo order
+ * @param size {Number}
+ */
+export function makeProfilingCache<Key extends string, Value extends Event>(
+  size: number,
+): {
+  get: (key: Key) => Value | undefined;
+  add: (key: Key, value: Value) => void;
+  delete: (key: Key) => boolean;
+  clear: () => void;
+  size: () => number;
+} {
+  // Maintain a fifo queue of keys, we cannot rely on Object.keys as the browser may not support it.
+  let evictionOrder: Key[] = [];
+  let cache: Record<string, Value> = {};
+
+  return {
+    add(key: Key, value: Value) {
+      while (evictionOrder.length >= size) {
+        // shift is O(n) but this is small size and only happens if we are
+        // exceeding the cache size so it should be fine.
+        const evictCandidate = evictionOrder.shift();
+
+        if (evictCandidate !== undefined) {
+          // eslint-disable-next-line @typescript-eslint/no-dynamic-delete
+          delete cache[evictCandidate];
+        }
+      }
+
+      // in case we have a collision, delete the old key.
+      if (cache[key]) {
+        this.delete(key);
+      }
+
+      evictionOrder.push(key);
+      cache[key] = value;
+    },
+    clear() {
+      cache = {};
+      evictionOrder = [];
+    },
+    get(key: Key): Value | undefined {
+      return cache[key];
+    },
+    size() {
+      return evictionOrder.length;
+    },
+    // Delete cache key and return true if it existed, false otherwise.
+    delete(key: Key): boolean {
+      if (!cache[key]) {
+        return false;
+      }
+
+      // eslint-disable-next-line @typescript-eslint/no-dynamic-delete
+      delete cache[key];
+
+      for (let i = 0; i < evictionOrder.length; i++) {
+        if (evictionOrder[i] === key) {
+          evictionOrder.splice(i, 1);
+          break;
+        }
+      }
+
+      return true;
+    },
+  };
+}
+
+export const PROFILING_EVENT_CACHE = makeProfilingCache<string, Event>(20);

packages/browser/src/profiling/hubextensions.ts

@@ -0,0 +1,259 @@
+import { getCurrentHub, getMainCarrier } from '@sentry/core';
+import type { CustomSamplingContext, Hub, Transaction, TransactionContext } from '@sentry/types';
+import { logger, uuid4 } from '@sentry/utils';
+
+import { WINDOW } from '../helpers';
+import type { JSSelfProfile, JSSelfProfiler, ProcessedJSSelfProfile } from './jsSelfProfiling';
+import { sendProfile } from './sendProfile';
+
+// Max profile duration.
+const MAX_PROFILE_DURATION_MS = 30_000;
+
+// While we experiment, per transaction sampling interval will be more flexible to work with.
+type StartTransaction = (
+  this: Hub,
+  transactionContext: TransactionContext,
+  customSamplingContext?: CustomSamplingContext,
+) => Transaction | undefined;
+
+/**
+ * Check if profiler constructor is available.
+ * @param maybeProfiler
+ */
+function isJSProfilerSupported(maybeProfiler: unknown): maybeProfiler is typeof JSSelfProfiler {
+  return typeof maybeProfiler === 'function';
+}
+
+/**
+ * Safety wrapper for startTransaction for the unlikely case that transaction starts before tracing is imported -
+ * if that happens we want to avoid throwing an error from profiling code.
+ * see https://github.com/getsentry/sentry-javascript/issues/4731.
+ *
+ * @experimental
+ */
+export function onProfilingStartRouteTransaction(transaction: Transaction | undefined): Transaction | undefined {
+  if (!transaction) {
+    if (__DEBUG_BUILD__) {
+      logger.log('[Profiling] Transaction is undefined, skipping profiling');
+    }
+    return transaction;
+  }
+
+  return wrapTransactionWithProfiling(transaction);
+}
+
+/**
+ * Wraps startTransaction and stopTransaction with profiling related logic.
+ * startProfiling is called after the call to startTransaction in order to avoid our own code from
+ * being profiled. Because of that same reason, stopProfiling is called before the call to stopTransaction.
+ */
+function wrapTransactionWithProfiling(transaction: Transaction): Transaction {
+  // Feature support check first
+  const JSProfiler = WINDOW.Profiler;
+  if (!isJSProfilerSupported(JSProfiler)) {
+    if (__DEBUG_BUILD__) {
+      logger.log(
+        '[Profiling] Profiling is not supported by this browser, Profiler interface missing on window object.',
+      );
+    }
+    return transaction;
+  }
+
+  // profilesSampleRate is multiplied with tracesSampleRate to get the final sampling rate.
+  if (!transaction.sampled) {
+    if (__DEBUG_BUILD__) {
+      logger.log('[Profiling] Transaction is not sampled, skipping profiling');
+    }
+    return transaction;
+  }
+
+  const client = getCurrentHub().getClient();
+  const options = client && client.getOptions();
+
+  // @ts-ignore not part of the browser options yet
+  const profilesSampleRate = (options && options.profilesSampleRate) || 0;
+  if (profilesSampleRate === undefined) {
+    if (__DEBUG_BUILD__) {
+      logger.log('[Profiling] Profiling disabled, enable it by setting `profilesSampleRate` option to SDK init call.');
+    }
+    return transaction;
+  }
+
+  // Check if we should sample this profile
+  if (Math.random() > profilesSampleRate) {
+    if (__DEBUG_BUILD__) {
+      logger.log('[Profiling] Skip profiling transaction due to sampling.');
+    }
+    return transaction;
+  }
+
+  // From initial testing, it seems that the minimum value for sampleInterval is 10ms.
+  const samplingIntervalMS = 10;
+  // Start the profiler
+  const maxSamples = Math.floor(MAX_PROFILE_DURATION_MS / samplingIntervalMS);
+  const profiler = new JSProfiler({ sampleInterval: samplingIntervalMS, maxBufferSize: maxSamples });
+  if (__DEBUG_BUILD__) {
+    logger.log(`[Profiling] started profiling transaction: ${transaction.name || transaction.description}`);
+  }
+
+  // We create "unique" transaction names to avoid concurrent transactions with same names
+  // from being ignored by the profiler. From here on, only this transaction name should be used when
+  // calling the profiler methods. Note: we log the original name to the user to avoid confusion.
+  const profileId = uuid4();
+
+  // A couple of important things to note here:
+  // `CpuProfilerBindings.stopProfiling` will be scheduled to run in 30seconds in order to exceed max profile duration.
+  // Whichever of the two (transaction.finish/timeout) is first to run, the profiling will be stopped and the gathered profile
+  // will be processed when the original transaction is finished. Since onProfileHandler can be invoked multiple times in the
+  // event of an error or user mistake (calling transaction.finish multiple times), it is important that the behavior of onProfileHandler
+  // is idempotent as we do not want any timings or profiles to be overriden by the last call to onProfileHandler.
+  // After the original finish method is called, the event will be reported through the integration and delegated to transport.
+  let processedProfile: ProcessedJSSelfProfile | null = null;
+
+  /**
+   * Idempotent handler for profile stop
+   */
+  function onProfileHandler(): void {
+    // Check if the profile exists and return it the behavior has to be idempotent as users may call transaction.finish multiple times.
+    if (!transaction) {
+      return;
+    }
+    if (processedProfile) {
+      if (__DEBUG_BUILD__) {
+        logger.log(
+          '[Profiling] profile for:',
+          transaction.name || transaction.description,
+          'already exists, returning early',
+        );
+      }
+      return;
+    }
+
+    profiler
+      .stop()
+      .then((p: JSSelfProfile): void => {
+        if (maxDurationTimeoutID) {
+          WINDOW.clearTimeout(maxDurationTimeoutID);
+          maxDurationTimeoutID = undefined;
+        }
+
+        if (__DEBUG_BUILD__) {
+          logger.log(`[Profiling] stopped profiling of transaction: ${transaction.name || transaction.description}`);
+        }
+
+        // In case of an overlapping transaction, stopProfiling may return null and silently ignore the overlapping profile.
+        if (!p) {
+          if (__DEBUG_BUILD__) {
+            logger.log(
+              `[Profiling] profiler returned null profile for: ${transaction.name || transaction.description}`,
+              'this may indicate an overlapping transaction or a call to stopProfiling with a profile title that was never started',
+            );
+          }
+          return;
+        }
+
+        // If a profile has less than 2 samples, it is not useful and should be discarded.
+        if (p.samples.length < 2) {
+          return;
+        }
+
+        processedProfile = { ...p, profile_id: profileId };
+        sendProfile(profileId, processedProfile);
+      })
+      .catch(error => {
+        if (__DEBUG_BUILD__) {
+          logger.log('[Profiling] error while stopping profiler:', error);
+        }
+        return null;
+      });
+  }
+
+  // Enqueue a timeout to prevent profiles from running over max duration.
+  let maxDurationTimeoutID: number | undefined = WINDOW.setTimeout(() => {
+    if (__DEBUG_BUILD__) {
+      logger.log(
+        '[Profiling] max profile duration elapsed, stopping profiling for:',
+        transaction.name || transaction.description,
+      );
+    }
+    void onProfileHandler();
+  }, MAX_PROFILE_DURATION_MS);
+
+  // We need to reference the original finish call to avoid creating an infinite loop
+  const originalFinish = transaction.finish.bind(transaction);
+
+  /**
+   * Wraps startTransaction and stopTransaction with profiling related logic.
+   * startProfiling is called after the call to startTransaction in order to avoid our own code from
+   * being profiled. Because of that same reason, stopProfiling is called before the call to stopTransaction.
+   */
+  function profilingWrappedTransactionFinish(): Promise<Transaction> {
+    if (!transaction) {
+      return originalFinish();
+    }
+    // onProfileHandler should always return the same profile even if this is called multiple times.
+    // Always call onProfileHandler to ensure stopProfiling is called and the timeout is cleared.
+    onProfileHandler();
+
+    // Set profile context
+    transaction.setContext('profile', { profile_id: profileId });
+
+    return originalFinish();
+  }
+
+  transaction.finish = profilingWrappedTransactionFinish;
+  return transaction;
+}
+
+/**
+ * Wraps startTransaction with profiling logic. This is done automatically by the profiling integration.
+ */
+function __PRIVATE__wrapStartTransactionWithProfiling(startTransaction: StartTransaction): StartTransaction {
+  return function wrappedStartTransaction(
+    this: Hub,
+    transactionContext: TransactionContext,
+    customSamplingContext?: CustomSamplingContext,
+  ): Transaction | undefined {
+    const transaction: Transaction | undefined = startTransaction.call(this, transactionContext, customSamplingContext);
+    if (transaction === undefined) {
+      if (__DEBUG_BUILD__) {
+        logger.log('[Profiling] Transaction is undefined, skipping profiling');
+      }
+      return transaction;
+    }
+
+    return wrapTransactionWithProfiling(transaction);
+  };
+}
+
+/**
+ * Patches startTransaction and stopTransaction with profiling logic.
+ */
+export function addProfilingExtensionMethods(): void {
+  const carrier = getMainCarrier();
+  if (!carrier.__SENTRY__) {
+    if (__DEBUG_BUILD__) {
+      logger.log("[Profiling] Can't find main carrier, profiling won't work.");
+    }
+    return;
+  }
+  carrier.__SENTRY__.extensions = carrier.__SENTRY__.extensions || {};
+
+  if (!carrier.__SENTRY__.extensions['startTransaction']) {
+    if (__DEBUG_BUILD__) {
+      logger.log(
+        '[Profiling] startTransaction does not exists, profiling will not work. Make sure you import @sentry/tracing package before @sentry/profiling-node as import order matters.',
+      );
+    }
+    return;
+  }
+
+  if (__DEBUG_BUILD__) {
+    logger.log('[Profiling] startTransaction exists, patching it with profiling functionality...');
+  }
+
+  carrier.__SENTRY__.extensions['startTransaction'] = __PRIVATE__wrapStartTransactionWithProfiling(
+    // This is already patched by sentry/tracing, we are going to re-patch it...
+    carrier.__SENTRY__.extensions['startTransaction'] as StartTransaction,
+  );
+}

packages/browser/src/profiling/integration.ts

@@ -0,0 +1,48 @@
+import type { Event, EventProcessor, Integration } from '@sentry/types';
+import { logger } from '@sentry/utils';
+
+import { PROFILING_EVENT_CACHE } from './cache';
+import { addProfilingExtensionMethods } from './hubextensions';
+
+/**
+ * Browser profiling integration. Stores any event that has contexts["profile"]["profile_id"]
+ * This exists because we do not want to await async profiler.stop calls as transaction.finish is called
+ * in a synchronous context. Instead, we handle sending the profile async from the promise callback and
+ * rely on being able to pull the event from the cache when we need to construct the envelope. This makes the
+ * integration less reliable as we might be dropping profiles when the cache is full.
+ *
+ * @experimental
+ */
+export class BrowserProfilingIntegration implements Integration {
+  public readonly name: string = 'BrowserProfilingIntegration';
+
+  /**
+   * @inheritDoc
+   */
+  public setupOnce(addGlobalEventProcessor: (callback: EventProcessor) => void): void {
+    // Patching the hub to add the extension methods.
+    // Warning: we have an implicit dependency on import order and we will fail patching if the constructor of
+    // BrowserProfilingIntegration is called before @sentry/tracing is imported. This is because we need to patch
+    // the methods of @sentry/tracing which are patched as a side effect of importing @sentry/tracing.
+    addProfilingExtensionMethods();
+
+    // Add our event processor
+    addGlobalEventProcessor(this.handleGlobalEvent.bind(this));
+  }
+
+  /**
+   * @inheritDoc
+   */
+  public handleGlobalEvent(event: Event): Event {
+    const profileId = event.contexts && event.contexts['profile'] && event.contexts['profile']['profile_id'];
+
+    if (profileId && typeof profileId === 'string') {
+      if (__DEBUG_BUILD__) {
+        logger.log('[Profiling] Profiling event found, caching it.');
+      }
+      PROFILING_EVENT_CACHE.add(profileId, event);
+    }
+
+    return event;
+  }
+}