feat(tracing): Reset IdleTimeout based on activities count #4531
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,5 +1,11 @@ | ||
| // Store finish reasons in tuple to save on bundle size | ||
| // Readonly type should enforce that this is not mutated. | ||
| export const FINISH_REASON_TAG = 'finishReason' as const; | ||
|
|
||
| export const IDLE_TRANSACTION_FINISH_REASONS = [ | ||
| 'heartbeatFailed', | ||
| 'idleTimeout', | ||
| 'documentHidden', | ||
| 'finalTimeout', | ||
| 'externalFinish', | ||
| ] as const; | ||
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,14 +1,18 @@ | ||
| /* eslint-disable max-lines */ | ||
| import { Hub } from '@sentry/hub'; | ||
| import { TransactionContext } from '@sentry/types'; | ||
| import { getGlobalObject, logger, timestampWithMs } from '@sentry/utils'; | ||
|
|
||
| import { FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS } from './constants'; | ||
| 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; | ||
|
|
||
| const global = getGlobalObject<Window>(); | ||
|
|
||
| /** | ||
| * @inheritDoc | ||
| */ | ||
|
|
@@ -56,6 +60,14 @@ export class IdleTransaction extends Transaction { | |
| // Activities store a list of active spans | ||
| public activities: Record<string, boolean> = {}; | ||
|
|
||
| /** | ||
| * | ||
| * Defaults to `externalFinish`, which means transaction.finish() was called outside of the idle transaction (for example, | ||
| * by a navigation transaction ending the previous pageload/navigation in some routing instrumentation). | ||
| * @default 'externalFinish' | ||
| */ | ||
| public finishReason: typeof IDLE_TRANSACTION_FINISH_REASONS[number] = IDLE_TRANSACTION_FINISH_REASONS[4]; | ||
|
|
||
| // Track state of activities in previous heartbeat | ||
| private _prevHeartbeatString: string | undefined; | ||
|
|
||
|
|
@@ -71,18 +83,29 @@ export class IdleTransaction extends Transaction { | |
| * 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. | ||
| */ | ||
| private _idleTimeoutID: ReturnType<typeof global.setTimeout> | undefined; | ||
|
|
||
| public constructor( | ||
| transactionContext: TransactionContext, | ||
| private readonly _idleHub?: Hub, | ||
| /** | ||
| * The time to wait in ms until the idle transaction will be finished. | ||
| * @default 1000 | ||
| * | ||
| * TODO: Make _idleTimeout and _finalTimeout required to reduce duplication when setting the options | ||
| * in `BrowserTracing`. This is considered a breaking change to the IdleTransaction API, | ||
| * so we need to make sure we communicate it with react native. | ||
| */ | ||
| private readonly _idleTimeout: number = DEFAULT_IDLE_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, | ||
| /** | ||
| * The final value that a transaction cannot exceed | ||
| * @default 30000 | ||
| * @experimental | ||
| * @internal | ||
| */ | ||
| private readonly _finalTimeout: number = DEFAULT_FINAL_TIMEOUT, | ||
| ) { | ||
| super(transactionContext, _idleHub); | ||
|
|
||
|
|
@@ -96,18 +119,22 @@ export class IdleTransaction extends Transaction { | |
| _idleHub.configureScope(scope => scope.setSpan(this)); | ||
| } | ||
|
|
||
| this._startIdleTimeout(); | ||
| global.setTimeout(() => { | ||
|
There was a problem hiding this comment. Does this need to be called on There was a problem hiding this comment. It makes it less likely to fail in the future - so I set it this way. |
||
| if (!this._finished) { | ||
| this.finishReason = IDLE_TRANSACTION_FINISH_REASONS[3]; /* 'finalTimeout' */ | ||
| this.finish(); | ||
| } | ||
| }, this._finalTimeout); | ||
| } | ||
|
|
||
| /** {@inheritDoc} */ | ||
| public finish(endTimestamp: number = timestampWithMs()): string | undefined { | ||
| this._finished = true; | ||
| this.activities = {}; | ||
|
|
||
| this.setTag(FINISH_REASON_TAG, this.finishReason); | ||
|
|
||
| if (this.spanRecorder) { | ||
| logger.log('[Tracing] finishing IdleTransaction', new Date(endTimestamp * 1000).toISOString(), this.op); | ||
|
|
||
|
|
@@ -189,15 +216,35 @@ export class IdleTransaction extends Transaction { | |
| this.spanRecorder.add(this); | ||
| } | ||
|
|
||
| /** | ||
| * Cancels the existing idletimeout, if there is one | ||
| */ | ||
| private _cancelIdleTimeout(): void { | ||
| if (this._idleTimeoutID) { | ||
| global.clearTimeout(this._idleTimeoutID); | ||
| this._idleTimeoutID = undefined; | ||
| } | ||
| } | ||
|
|
||
| /** | ||
| * Creates an idletimeout | ||
| */ | ||
| private _startIdleTimeout(endTimestamp?: Parameters<IdleTransaction['finish']>[0]): void { | ||
| this._cancelIdleTimeout(); | ||
|
There was a problem hiding this comment. I wonder what test covers the behaviour changes? Does its 2 test cases will to it? |
||
| this._idleTimeoutID = global.setTimeout(() => { | ||
| if (!this._finished && Object.keys(this.activities).length === 0) { | ||
| this.finishReason = IDLE_TRANSACTION_FINISH_REASONS[1]; /* 'idleTimeout' */ | ||
| this.finish(endTimestamp); | ||
| } | ||
| }, this._idleTimeout); | ||
| } | ||
|
|
||
| /** | ||
| * Start tracking a specific activity. | ||
| * @param spanId The span id that represents the activity | ||
| */ | ||
| private _pushActivity(spanId: string): void { | ||
| this._cancelIdleTimeout(); | ||
| logger.log(`[Tracing] pushActivity: ${spanId}`); | ||
| this.activities[spanId] = true; | ||
| logger.log('[Tracing] new activities count', Object.keys(this.activities).length); | ||
|
|
@@ -219,14 +266,8 @@ export class IdleTransaction extends Transaction { | |
| 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 endTimestamp = timestampWithMs() + timeout / 1000; | ||
| this._startIdleTimeout(endTimestamp); | ||
| } | ||
| } | ||
|
|
||
|
|
@@ -253,7 +294,7 @@ export class IdleTransaction extends Transaction { | |
| if (this._heartbeatCounter >= 3) { | ||
| logger.log(`[Tracing] Transaction finished because of no change for 3 heart beats`); | ||
| this.setStatus('deadline_exceeded'); | ||
| this.finishReason = IDLE_TRANSACTION_FINISH_REASONS[0]; /* 'heartbeatFailed' */ | ||
| this.finish(); | ||
| } else { | ||
| this._pingHeartbeat(); | ||
|
|
@@ -265,7 +306,7 @@ export class IdleTransaction extends Transaction { | |
| */ | ||
| private _pingHeartbeat(): void { | ||
| logger.log(`pinging Heartbeat -> current counter: ${this._heartbeatCounter}`); | ||
| global.setTimeout(() => { | ||
| this._beat(); | ||
| }, HEARTBEAT_INTERVAL); | ||
| } | ||
|
|
||
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -9,7 +9,16 @@ import { | |
| } from '../src/idletransaction'; | ||
| import { Span } from '../src/span'; | ||
|
|
||
| type TransportSendRequest = Transports.BaseTransport['_sendRequest']; | ||
|
|
||
| export class SimpleTransport extends Transports.BaseTransport { | ||
| protected _sendRequest( | ||
| _req: Parameters<TransportSendRequest>[0], | ||
| _payload: Parameters<TransportSendRequest>[1], | ||
| ): ReturnType<TransportSendRequest> { | ||
| throw new Error('Method not implemented.'); | ||
| } | ||
| } | ||
AbhiPrasad marked this conversation as resolved.
Show resolved
Hide resolved
|
||
|
|
||
| const dsn = 'https://[email protected]/42'; | ||
| let hub: Hub; | ||
|
|
@@ -103,7 +112,7 @@ describe('IdleTransaction', () => { | |
|
|
||
| expect(transaction.activities).toMatchObject({ [span.spanId]: true, [childSpan.spanId]: true }); | ||
| span.finish(); | ||
| jest.advanceTimersByTime(DEFAULT_IDLE_TIMEOUT + 1); | ||
|
|
||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
| expect(transaction.activities).toMatchObject({ [childSpan.spanId]: true }); | ||
|
|
@@ -229,63 +238,63 @@ describe('IdleTransaction', () => { | |
| transaction.startChild({}); | ||
|
|
||
| // Beat 1 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
|
|
||
| // Beat 2 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
|
|
||
| // Beat 3 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(1); | ||
| }); | ||
|
|
||
| it('resets after new activities are added', () => { | ||
| const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT, false, 50000); | ||
| const mockFinish = jest.spyOn(transaction, 'finish'); | ||
| transaction.initSpanRecorder(10); | ||
|
|
||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
| transaction.startChild({}); | ||
|
|
||
| // Beat 1 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
|
|
||
| const span = transaction.startChild(); // push activity | ||
|
|
||
| // Beat 1 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
|
|
||
| // Beat 2 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
|
|
||
| transaction.startChild(); // push activity | ||
| transaction.startChild(); // push activity | ||
|
|
||
| // Beat 1 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
|
|
||
| // Beat 2 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
|
|
||
| span.finish(); // pop activity | ||
|
|
||
| // Beat 1 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
|
|
||
| // Beat 2 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(0); | ||
|
|
||
| // Beat 3 | ||
| jest.advanceTimersByTime(HEARTBEAT_INTERVAL); | ||
| expect(mockFinish).toHaveBeenCalledTimes(1); | ||
|
|
||
| // Heartbeat does not keep going after finish has been called | ||
|
|
||
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
given that this shows up in the UI, and I as a user of sentry would probably not understand what this means if I hadn't already found this issue and read this PR, does it make more sense to name this something that indicates it's a forced timeout due to thrashing? hard to come up with a concise name but maybe something like
thrashedSpanTimeoutortimeoutInfinitePoll? (idleTimeoutwas a similarly confusing name to me, it's not obvious that's the sort of "intended finish reason" for normal transactions, but realize that probably can't be changed anymore)There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Good catch.
Its behaviour seems like as the
maxTransactionDurationconfiguration.There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
does it make sense to re-use that configuration option here then (as opposed to creating a new one), and similarly re-use the "deadline_exceeded" finishReason? or is there value in having them both be separate? I guess a default timeout of 600 seconds is pretty excessive for this particular use case...