diff --git a/CHANGELOG.md b/CHANGELOG.md index bb29698e4da4..28a3aa98f59a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,8 @@ - [core] fix: Call `bindClient` when creating new `Hub` to make integrations work automatically (#2665) - [gatsby] feat: Add @sentry/gatsby package (#2652) - [core] ref: Rename `whitelistUrls/blacklistUrls` to `allowUrls/denyUrls` +- [react] ref: Refactor Profiler to account for update and render (#2677) +- [tracing] feat: Add ability to get span from activity using `getActivitySpan` (#2677) ## 5.17.0 diff --git a/packages/apm/src/integrations/tracing.ts b/packages/apm/src/integrations/tracing.ts index 81d30a8189fc..59601c76c858 100644 --- a/packages/apm/src/integrations/tracing.ts +++ b/packages/apm/src/integrations/tracing.ts @@ -1,3 +1,4 @@ +// tslint:disable: max-file-line-count import { Hub } from '@sentry/hub'; import { Event, EventProcessor, Integration, Severity, Span, SpanContext, TransactionContext } from '@sentry/types'; import { @@ -817,6 +818,9 @@ export class Tracing implements Integration { /** * Removes activity and finishes the span in case there is one + * @param id the id of the activity being removed + * @param spanData span data that can be updated + * */ public static popActivity(id: number, spanData?: { [key: string]: any }): void { // The !id is on purpose to also fail with 0 @@ -866,6 +870,20 @@ export class Tracing implements Integration { }, timeout); } } + + /** + * Get span based on activity id + */ + public static getActivitySpan(id: number): Span | undefined { + if (!id) { + return undefined; + } + const activity = Tracing._activities[id]; + if (activity) { + return activity.span; + } + return undefined; + } } /** diff --git a/packages/react/src/index.ts b/packages/react/src/index.ts index fc67e410912c..3d8842ad43d6 100644 --- a/packages/react/src/index.ts +++ b/packages/react/src/index.ts @@ -1,22 +1,24 @@ import { addGlobalEventProcessor, SDK_VERSION } from '@sentry/browser'; function createReactEventProcessor(): void { - addGlobalEventProcessor(event => { - event.sdk = { - ...event.sdk, - name: 'sentry.javascript.react', - packages: [ - ...((event.sdk && event.sdk.packages) || []), - { - name: 'npm:@sentry/react', - version: SDK_VERSION, - }, - ], - version: SDK_VERSION, - }; + if (addGlobalEventProcessor) { + addGlobalEventProcessor(event => { + event.sdk = { + ...event.sdk, + name: 'sentry.javascript.react', + packages: [ + ...((event.sdk && event.sdk.packages) || []), + { + name: 'npm:@sentry/react', + version: SDK_VERSION, + }, + ], + version: SDK_VERSION, + }; - return event; - }); + return event; + }); + } } export * from '@sentry/browser'; diff --git a/packages/react/src/profiler.tsx b/packages/react/src/profiler.tsx index 8cf86ed89009..8ef7d6966f63 100644 --- a/packages/react/src/profiler.tsx +++ b/packages/react/src/profiler.tsx @@ -1,6 +1,6 @@ import { getCurrentHub } from '@sentry/browser'; -import { Integration, IntegrationClass } from '@sentry/types'; -import { logger } from '@sentry/utils'; +import { Integration, IntegrationClass, Span } from '@sentry/types'; +import { logger, timestampWithMs } from '@sentry/utils'; import * as hoistNonReactStatic from 'hoist-non-react-statics'; import * as React from 'react'; @@ -10,91 +10,167 @@ const TRACING_GETTER = ({ id: 'Tracing', } as any) as IntegrationClass; +let globalTracingIntegration: Integration | null = null; +const getTracingIntegration = () => { + if (globalTracingIntegration) { + return globalTracingIntegration; + } + + globalTracingIntegration = getCurrentHub().getIntegration(TRACING_GETTER); + return globalTracingIntegration; +}; + /** - * - * Based on implementation from Preact: - * https:github.com/preactjs/preact/blob/9a422017fec6dab287c77c3aef63c7b2fef0c7e1/hooks/src/index.js#L301-L313 - * - * Schedule a callback to be invoked after the browser has a chance to paint a new frame. - * Do this by combining requestAnimationFrame (rAF) + setTimeout to invoke a callback after - * the next browser frame. - * - * Also, schedule a timeout in parallel to the the rAF to ensure the callback is invoked - * even if RAF doesn't fire (for example if the browser tab is not visible) - * - * This is what we use to tell if a component activity has finished - * + * Warn if tracing integration not configured. Will only warn once. */ -function afterNextFrame(callback: Function): void { - let timeout: number | undefined; - let raf: number; - - const done = () => { - window.clearTimeout(timeout); - window.cancelAnimationFrame(raf); - window.setTimeout(callback); - }; - - raf = window.requestAnimationFrame(done); - timeout = window.setTimeout(done, 100); +function warnAboutTracing(name: string): void { + if (globalTracingIntegration === null) { + logger.warn( + `Unable to profile component ${name} due to invalid Tracing Integration. Please make sure the Tracing integration is setup properly.`, + ); + } } /** - * getInitActivity pushes activity based on React component mount + * pushActivity creates an new react activity. + * Is a no-op if Tracing integration is not valid * @param name displayName of component that started activity */ -const getInitActivity = (name: string): number | null => { - const tracingIntegration = getCurrentHub().getIntegration(TRACING_GETTER); - - if (tracingIntegration !== null) { - // tslint:disable-next-line:no-unsafe-any - return (tracingIntegration as any).constructor.pushActivity(name, { - description: `<${name}>`, - op: 'react', - }); +function pushActivity(name: string, op: string): number | null { + if (globalTracingIntegration === null) { + return null; } - logger.warn( - `Unable to profile component ${name} due to invalid Tracing Integration. Please make sure to setup the Tracing integration.`, - ); - return null; -}; + // tslint:disable-next-line:no-unsafe-any + return (globalTracingIntegration as any).constructor.pushActivity(name, { + description: `<${name}>`, + op: `react.${op}`, + }); +} + +/** + * popActivity removes a React activity. + * Is a no-op if Tracing integration is not valid. + * @param activity id of activity that is being popped + */ +function popActivity(activity: number | null): void { + if (activity === null || globalTracingIntegration === null) { + return; + } + + // tslint:disable-next-line:no-unsafe-any + (globalTracingIntegration as any).constructor.popActivity(activity); +} + +/** + * Obtain a span given an activity id. + * Is a no-op if Tracing integration is not valid. + * @param activity activity id associated with obtained span + */ +function getActivitySpan(activity: number | null): Span | undefined { + if (activity === null || globalTracingIntegration === null) { + return undefined; + } + + // tslint:disable-next-line:no-unsafe-any + return (globalTracingIntegration as any).constructor.getActivitySpan(activity) as Span | undefined; +} export type ProfilerProps = { + // The name of the component being profiled. name: string; + // If the Profiler is disabled. False by default. This is useful if you want to disable profilers + // in certain environments. + disabled?: boolean; + // If time component is on page should be displayed as spans. True by default. + hasRenderSpan?: boolean; + // If component updates should be displayed as spans. True by default. + hasUpdateSpan?: boolean; + // props given to component being profiled. + updateProps: { [key: string]: any }; }; +/** + * The Profiler component leverages Sentry's Tracing integration to generate + * spans based on component lifecycles. + */ class Profiler extends React.Component { - public activity: number | null; + // The activity representing how long it takes to mount a component. + public mountActivity: number | null = null; + // The span of the mount activity + public mountSpan: Span | undefined = undefined; + // The span of the render + public renderSpan: Span | undefined = undefined; + + public static defaultProps: Partial = { + disabled: false, + hasRenderSpan: true, + hasUpdateSpan: true, + }; + public constructor(props: ProfilerProps) { super(props); + const { name, disabled = false } = this.props; - this.activity = getInitActivity(this.props.name); + if (disabled) { + return; + } + + if (getTracingIntegration()) { + this.mountActivity = pushActivity(name, 'mount'); + } else { + warnAboutTracing(name); + } } // If a component mounted, we can finish the mount activity. public componentDidMount(): void { - afterNextFrame(this.finishProfile); - } - - // Sometimes a component will unmount first, so we make - // sure to also finish the mount activity here. - public componentWillUnmount(): void { - afterNextFrame(this.finishProfile); + this.mountSpan = getActivitySpan(this.mountActivity); + popActivity(this.mountActivity); + this.mountActivity = null; } - public finishProfile = () => { - if (!this.activity) { - return; + public componentDidUpdate({ updateProps, hasUpdateSpan = true }: ProfilerProps): void { + // Only generate an update span if hasUpdateSpan is true, if there is a valid mountSpan, + // and if the updateProps have changed. It is ok to not do a deep equality check here as it is expensive. + // We are just trying to give baseline clues for further investigation. + if (hasUpdateSpan && this.mountSpan && updateProps !== this.props.updateProps) { + // See what props haved changed between the previous props, and the current props. This is + // set as data on the span. We just store the prop keys as the values could be potenially very large. + const changedProps = Object.keys(updateProps).filter(k => updateProps[k] !== this.props.updateProps[k]); + if (changedProps.length > 0) { + // The update span is a point in time span with 0 duration, just signifying that the component + // has been updated. + const now = timestampWithMs(); + this.mountSpan.startChild({ + data: { + changedProps, + }, + description: `<${this.props.name}>`, + endTimestamp: now, + op: `react.update`, + startTimestamp: now, + }); + } } + } - const tracingIntegration = getCurrentHub().getIntegration(TRACING_GETTER); - if (tracingIntegration !== null) { - // tslint:disable-next-line:no-unsafe-any - (tracingIntegration as any).constructor.popActivity(this.activity); - this.activity = null; + // If a component is unmounted, we can say it is no longer on the screen. + // This means we can finish the span representing the component render. + public componentWillUnmount(): void { + const { name, hasRenderSpan = true } = this.props; + + if (this.mountSpan && hasRenderSpan) { + // If we were able to obtain the spanId of the mount activity, we should set the + // next activity as a child to the component mount activity. + this.mountSpan.startChild({ + description: `<${name}>`, + endTimestamp: timestampWithMs(), + op: `react.render`, + startTimestamp: this.mountSpan.endTimestamp, + }); } - }; + } public render(): React.ReactNode { return this.props.children; @@ -103,16 +179,22 @@ class Profiler extends React.Component { /** * withProfiler is a higher order component that wraps a - * component in a {@link Profiler} component. + * component in a {@link Profiler} component. It is recommended that + * the higher order component be used over the regular {@link Profiler} component. * * @param WrappedComponent component that is wrapped by Profiler - * @param name displayName of component being profiled + * @param options the {@link ProfilerProps} you can pass into the Profiler */ -function withProfiler

(WrappedComponent: React.ComponentType

, name?: string): React.FC

{ - const componentDisplayName = name || WrappedComponent.displayName || WrappedComponent.name || UNKNOWN_COMPONENT; +function withProfiler

( + WrappedComponent: React.ComponentType

, + // We do not want to have `updateProps` given in options, it is instead filled through the HOC. + options?: Pick, Exclude>, +): React.FC

{ + const componentDisplayName = + (options && options.name) || WrappedComponent.displayName || WrappedComponent.name || UNKNOWN_COMPONENT; const Wrapped: React.FC

= (props: P) => ( - + ); @@ -132,17 +214,40 @@ function withProfiler

(WrappedComponent: React.ComponentType

* Requires React 16.8 or above. * @param name displayName of component being profiled */ -function useProfiler(name: string): void { - const [activity] = React.useState(() => getInitActivity(name)); +function useProfiler( + name: string, + options: { disabled?: boolean; hasRenderSpan?: boolean } = { + disabled: false, + hasRenderSpan: true, + }, +): void { + const [mountActivity] = React.useState(() => { + if (options && options.disabled) { + return null; + } + + if (getTracingIntegration()) { + return pushActivity(name, 'mount'); + } + + warnAboutTracing(name); + return null; + }); React.useEffect(() => { - afterNextFrame(() => { - const tracingIntegration = getCurrentHub().getIntegration(TRACING_GETTER); - if (tracingIntegration !== null) { - // tslint:disable-next-line:no-unsafe-any - (tracingIntegration as any).constructor.popActivity(activity); + const mountSpan = getActivitySpan(mountActivity); + popActivity(mountActivity); + + return () => { + if (mountSpan && options.hasRenderSpan) { + mountSpan.startChild({ + description: `<${name}>`, + endTimestamp: timestampWithMs(), + op: `react.render`, + startTimestamp: mountSpan.endTimestamp, + }); } - }); + }; }, []); } diff --git a/packages/react/test/profiler.test.tsx b/packages/react/test/profiler.test.tsx index 84a6f3e546b5..0da9d9545099 100644 --- a/packages/react/test/profiler.test.tsx +++ b/packages/react/test/profiler.test.tsx @@ -1,14 +1,21 @@ +import { SpanContext } from '@sentry/types'; import { render } from '@testing-library/react'; import { renderHook } from '@testing-library/react-hooks'; import * as React from 'react'; import { UNKNOWN_COMPONENT, useProfiler, withProfiler } from '../src/profiler'; +const TEST_SPAN_ID = '518999beeceb49af'; +const TEST_TIMESTAMP = '123456'; + +const mockStartChild = jest.fn((spanArgs: SpanContext) => ({ ...spanArgs })); const mockPushActivity = jest.fn().mockReturnValue(1); const mockPopActivity = jest.fn(); const mockLoggerWarn = jest.fn(); - -let integrationIsNull = false; +const mockGetActivitySpan = jest.fn().mockReturnValue({ + spanId: TEST_SPAN_ID, + startChild: mockStartChild, +}); jest.mock('@sentry/utils', () => ({ logger: { @@ -16,6 +23,7 @@ jest.mock('@sentry/utils', () => ({ mockLoggerWarn(message); }, }, + timestampWithMs: () => TEST_TIMESTAMP, })); jest.mock('@sentry/browser', () => ({ @@ -29,26 +37,22 @@ jest.mock('@sentry/browser', () => ({ public setupOnce: () => void = jest.fn(); public static pushActivity: () => void = mockPushActivity; public static popActivity: () => void = mockPopActivity; + public static getActivitySpan: () => void = mockGetActivitySpan; } - - if (!integrationIsNull) { - return new MockIntegration('test'); - } - - return null; + return new MockIntegration('test'); }, }), })); -describe('withProfiler', () => { - beforeEach(() => { - jest.useFakeTimers(); - mockPushActivity.mockClear(); - mockPopActivity.mockClear(); - mockLoggerWarn.mockClear(); - integrationIsNull = false; - }); +beforeEach(() => { + mockPushActivity.mockClear(); + mockPopActivity.mockClear(); + mockLoggerWarn.mockClear(); + mockGetActivitySpan.mockClear(); + mockStartChild.mockClear(); +}); +describe('withProfiler', () => { it('sets displayName properly', () => { const TestComponent = () =>

Hello World

; @@ -59,7 +63,7 @@ describe('withProfiler', () => { it('sets a custom displayName', () => { const TestComponent = () =>

Hello World

; - const ProfiledComponent = withProfiler(TestComponent, 'BestComponent'); + const ProfiledComponent = withProfiler(TestComponent, { name: 'BestComponent' }); expect(ProfiledComponent.displayName).toBe('profiler(BestComponent)'); }); @@ -68,95 +72,158 @@ describe('withProfiler', () => { expect(ProfiledComponent.displayName).toBe(`profiler(${UNKNOWN_COMPONENT})`); }); - it('popActivity() is called when unmounted', () => { - const ProfiledComponent = withProfiler(() =>

Hello World

); + describe('mount span', () => { + it('does not get created if Profiler is disabled', () => { + const ProfiledComponent = withProfiler(() =>

Testing

, { disabled: true }); + expect(mockPushActivity).toHaveBeenCalledTimes(0); + render(); + expect(mockPushActivity).toHaveBeenCalledTimes(0); + }); - expect(mockPopActivity).toHaveBeenCalledTimes(0); - const profiler = render(); - profiler.unmount(); + it('is created when a component is mounted', () => { + const ProfiledComponent = withProfiler(() =>

Testing

); - jest.runAllTimers(); + expect(mockPushActivity).toHaveBeenCalledTimes(0); + expect(mockGetActivitySpan).toHaveBeenCalledTimes(0); + expect(mockPopActivity).toHaveBeenCalledTimes(0); - expect(mockPopActivity).toHaveBeenCalledTimes(1); - expect(mockPopActivity).toHaveBeenLastCalledWith(1); - }); + render(); - it('pushActivity() is called when mounted', () => { - const ProfiledComponent = withProfiler(() =>

Testing

); + expect(mockPushActivity).toHaveBeenCalledTimes(1); + expect(mockPushActivity).toHaveBeenLastCalledWith(UNKNOWN_COMPONENT, { + description: `<${UNKNOWN_COMPONENT}>`, + op: 'react.mount', + }); + expect(mockGetActivitySpan).toHaveBeenCalledTimes(1); + expect(mockGetActivitySpan).toHaveBeenLastCalledWith(1); - expect(mockPushActivity).toHaveBeenCalledTimes(0); - render(); - expect(mockPushActivity).toHaveBeenCalledTimes(1); - expect(mockPushActivity).toHaveBeenLastCalledWith(UNKNOWN_COMPONENT, { - description: `<${UNKNOWN_COMPONENT}>`, - op: 'react', + expect(mockPopActivity).toHaveBeenCalledTimes(1); + expect(mockPopActivity).toHaveBeenLastCalledWith(1); }); }); - it('does not start an activity when integration is disabled', () => { - integrationIsNull = true; - const ProfiledComponent = withProfiler(() =>

Hello World

); + describe('render span', () => { + it('is created on unmount', () => { + const ProfiledComponent = withProfiler(() =>

Testing

); + expect(mockStartChild).toHaveBeenCalledTimes(0); + + const component = render(); + component.unmount(); + + expect(mockStartChild).toHaveBeenCalledTimes(1); + expect(mockStartChild).toHaveBeenLastCalledWith( + expect.objectContaining({ + description: `<${UNKNOWN_COMPONENT}>`, + op: 'react.render', + }), + ); + }); - expect(mockPushActivity).toHaveBeenCalledTimes(0); - expect(mockLoggerWarn).toHaveBeenCalledTimes(0); + it('is not created if hasRenderSpan is false', () => { + const ProfiledComponent = withProfiler(() =>

Testing

, { hasRenderSpan: false }); + expect(mockStartChild).toHaveBeenCalledTimes(0); - const profiler = render(); - expect(mockPopActivity).toHaveBeenCalledTimes(0); - expect(mockPushActivity).toHaveBeenCalledTimes(0); + const component = render(); + component.unmount(); - expect(mockLoggerWarn).toHaveBeenCalledTimes(1); + expect(mockStartChild).toHaveBeenCalledTimes(0); + }); + }); + + describe('update span', () => { + it('is created when component is updated', () => { + const ProfiledComponent = withProfiler((props: { num: number }) =>
{props.num}
); + const { rerender } = render(); + expect(mockStartChild).toHaveBeenCalledTimes(0); + + // Dispatch new props + rerender(); + expect(mockStartChild).toHaveBeenCalledTimes(1); + expect(mockStartChild).toHaveBeenLastCalledWith({ + data: { changedProps: ['num'] }, + description: `<${UNKNOWN_COMPONENT}>`, + endTimestamp: TEST_TIMESTAMP, + op: 'react.update', + startTimestamp: TEST_TIMESTAMP, + }); + + // New props yet again + rerender(); + expect(mockStartChild).toHaveBeenCalledTimes(2); + expect(mockStartChild).toHaveBeenLastCalledWith({ + data: { changedProps: ['num'] }, + description: `<${UNKNOWN_COMPONENT}>`, + endTimestamp: TEST_TIMESTAMP, + op: 'react.update', + startTimestamp: TEST_TIMESTAMP, + }); + + // Should not create spans if props haven't changed + rerender(); + expect(mockStartChild).toHaveBeenCalledTimes(2); + }); - profiler.unmount(); - expect(mockPopActivity).toHaveBeenCalledTimes(0); + it('does not get created if hasUpdateSpan is false', () => { + const ProfiledComponent = withProfiler((props: { num: number }) =>
{props.num}
, { + hasUpdateSpan: false, + }); + const { rerender } = render(); + expect(mockStartChild).toHaveBeenCalledTimes(0); + + // Dispatch new props + rerender(); + expect(mockStartChild).toHaveBeenCalledTimes(0); + }); }); }); describe('useProfiler()', () => { - beforeEach(() => { - jest.useFakeTimers(); - mockPushActivity.mockClear(); - mockPopActivity.mockClear(); - mockLoggerWarn.mockClear(); - integrationIsNull = false; - }); - - it('popActivity() is called when unmounted', () => { - // tslint:disable-next-line: no-void-expression - const profiler = renderHook(() => useProfiler('Example')); - expect(mockPopActivity).toHaveBeenCalledTimes(0); - profiler.unmount(); + describe('mount span', () => { + it('does not get created if Profiler is disabled', () => { + // tslint:disable-next-line: no-void-expression + renderHook(() => useProfiler('Example', { disabled: true })); + expect(mockPushActivity).toHaveBeenCalledTimes(0); + }); - jest.runAllTimers(); + it('is created when a component is mounted', () => { + // tslint:disable-next-line: no-void-expression + renderHook(() => useProfiler('Example')); - expect(mockPopActivity).toHaveBeenCalled(); - expect(mockPopActivity).toHaveBeenLastCalledWith(1); - }); + expect(mockPushActivity).toHaveBeenCalledTimes(1); + expect(mockPushActivity).toHaveBeenLastCalledWith('Example', { + description: '', + op: 'react.mount', + }); + expect(mockGetActivitySpan).toHaveBeenCalledTimes(1); + expect(mockGetActivitySpan).toHaveBeenLastCalledWith(1); - it('pushActivity() is called when mounted', () => { - expect(mockPushActivity).toHaveBeenCalledTimes(0); - // tslint:disable-next-line: no-void-expression - const profiler = renderHook(() => useProfiler('Example')); - profiler.unmount(); - expect(mockPushActivity).toHaveBeenCalledTimes(1); - expect(mockPushActivity).toHaveBeenLastCalledWith('Example', { - description: ``, - op: 'react', + expect(mockPopActivity).toHaveBeenCalledTimes(1); + expect(mockPopActivity).toHaveBeenLastCalledWith(1); }); }); - it('does not start an activity when integration is disabled', () => { - integrationIsNull = true; - expect(mockPushActivity).toHaveBeenCalledTimes(0); - expect(mockLoggerWarn).toHaveBeenCalledTimes(0); - - // tslint:disable-next-line: no-void-expression - const profiler = renderHook(() => useProfiler('Example')); - expect(mockPopActivity).toHaveBeenCalledTimes(0); - expect(mockPushActivity).toHaveBeenCalledTimes(0); - - expect(mockLoggerWarn).toHaveBeenCalledTimes(1); + describe('render span', () => { + it('does not get created when hasRenderSpan is false', () => { + // tslint:disable-next-line: no-void-expression + const component = renderHook(() => useProfiler('Example', { hasRenderSpan: false })); + expect(mockStartChild).toHaveBeenCalledTimes(0); + component.unmount(); + expect(mockStartChild).toHaveBeenCalledTimes(0); + }); - profiler.unmount(); - expect(mockPopActivity).toHaveBeenCalledTimes(0); + it('is created by default', () => { + // tslint:disable-next-line: no-void-expression + const component = renderHook(() => useProfiler('Example')); + + expect(mockStartChild).toHaveBeenCalledTimes(0); + component.unmount(); + expect(mockStartChild).toHaveBeenCalledTimes(1); + expect(mockStartChild).toHaveBeenLastCalledWith( + expect.objectContaining({ + description: '', + op: 'react.render', + }), + ); + }); }); });