Skip to content

[HEAVILY WIP] ref(tracing): Refactor IdleTimeout Algorithm #4471

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 8 commits into from
Closed

[HEAVILY WIP] ref(tracing): Refactor IdleTimeout Algorithm #4471

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
ab3bc01
ref(tracing): Remove IdleTransaction heartbeat
AbhiPrasad Jan 28, 2022
759a0d4
start tracking idletimeout timeout
AbhiPrasad Jan 28, 2022
6df80aa
make activities private
AbhiPrasad Jan 28, 2022
6537fc1
new constants
AbhiPrasad Jan 28, 2022
3923288
make _transactionSpanID private
AbhiPrasad Jan 28, 2022
62ece1a
refactor settimeout
AbhiPrasad Jan 28, 2022
7038609
change how defaults propogate
AbhiPrasad Jan 28, 2022
11f6dc9
set timeout and finish
AbhiPrasad Jan 31, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 14 additions & 3 deletions packages/tracing/src/browser/browsertracing.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@ import { EventProcessor, Integration, Transaction, TransactionContext } from '@s
import { getGlobalObject, logger } from '@sentry/utils';

import { startIdleTransaction } from '../hubextensions';
import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../idletransaction';
import { DEFAULT_FINAL_TIMEOUT,DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../idletransaction';
import { extractTraceparentData, secToMs } from '../utils';
import { registerBackgroundTabDetection } from './backgroundtab';
import { MetricsInstrumentation } from './metrics';
Expand All @@ -27,6 +27,15 @@ export interface BrowserTracingOptions extends RequestInstrumentationOptions {
*/
idleTimeout: number;

/**
*
* Time is in ms
*
* Default: 10000
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Didn't we say 10_000 is a bit too short given that many transactions will be on 3g connections etc?

*
*/
finalTimeout: number;

/**
* Flag to enable/disable creation of `navigation` transaction on history changes.
*
Expand Down Expand Up @@ -93,6 +102,7 @@ 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,
Expand Down Expand Up @@ -201,7 +211,7 @@ export class BrowserTracing implements Integration {
}

// eslint-disable-next-line @typescript-eslint/unbound-method
const { beforeNavigate, idleTimeout, maxTransactionDuration } = this.options;
const { beforeNavigate, idleTimeout, maxTransactionDuration, finalTimeout } = this.options;

const parentContextFromHeader = context.op === 'pageload' ? getHeaderContext() : undefined;

Expand All @@ -228,8 +238,9 @@ export class BrowserTracing implements Integration {
const idleTransaction = startIdleTransaction(
hub,
finalContext,
idleTimeout,
true,
idleTimeout,
finalTimeout,
{ location }, // for use in the tracesSampler
);
idleTransaction.registerBeforeFinishCallback((transaction, endTimestamp) => {
Expand Down
9 changes: 5 additions & 4 deletions packages/tracing/src/hubextensions.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -186,14 +186,15 @@ function _startTransaction(
export function startIdleTransaction(
hub: Hub,
transactionContext: TransactionContext,
idleTimeout?: number,
onScope?: boolean,
customSamplingContext?: CustomSamplingContext,
onScope: boolean,
idleTimeout: number,
finalTimeout: number,
customSamplingContext: CustomSamplingContext,
): IdleTransaction {
const client = hub.getClient();
const options = (client && client.getOptions()) || {};

let transaction = new IdleTransaction(transactionContext, hub, idleTimeout, onScope);
let transaction = new IdleTransaction(transactionContext, hub, onScope, idleTimeout, finalTimeout);
transaction = sample(transaction, options, {
parentSampled: transactionContext.parentSampled,
transactionContext,
Expand Down
139 changes: 37 additions & 102 deletions packages/tracing/src/idletransaction.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,8 +6,10 @@ import { FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS } from './constants'
import { Span, SpanRecorder } from './span';
import { Transaction } from './transaction';

// 1 second
export const DEFAULT_IDLE_TIMEOUT = 1000;
export const HEARTBEAT_INTERVAL = 5000;
// 10 seconds
export const DEFAULT_FINAL_TIMEOUT = 10000;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

See comment above, should likely bump final timeout.


/**
* @inheritDoc
Expand All @@ -16,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 = '',
private readonly _transactionSpanId: string,
maxlen?: number,
) {
super(maxlen);
Expand All @@ -28,7 +30,7 @@ export class IdleTransactionSpanRecorder extends SpanRecorder {
public add(span: Span): void {
// We should make sure we do not push and pop activities for
// the transaction that this span recorder belongs to.
if (span.spanId !== this.transactionSpanId) {
if (span.spanId !== this._transactionSpanId) {
// We patch span.finish() to pop an activity after setting an endTimestamp.
span.finish = (endTimestamp?: number) => {
span.endTimestamp = typeof endTimestamp === 'number' ? endTimestamp : timestampWithMs();
Expand All @@ -54,35 +56,20 @@ export type BeforeFinishCallback = (transactionSpan: IdleTransaction, endTimesta
*/
export class IdleTransaction extends Transaction {
// Activities store a list of active spans
public activities: Record<string, boolean> = {};

// Track state of activities in previous heartbeat
private _prevHeartbeatString: string | undefined;

// Amount of times heartbeat has counted. Will cause transaction to finish after 3 beats.
private _heartbeatCounter: number = 0;

// We should not use heartbeat if we finished a transaction
private _finished: boolean = false;
private _activities: Record<string, boolean> = {};

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.
*/
private _initTimeout: ReturnType<typeof setTimeout> | undefined;
private _idleTimeoutID: ReturnType<typeof setTimeout> | undefined;
private _finalTimeoutID: ReturnType<typeof 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
*/
private readonly _idleTimeout: number = DEFAULT_IDLE_TIMEOUT,
private readonly _idleHub: Hub,
// 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,
private readonly _onScope: boolean,
private readonly _idleTimeout: number,
private readonly _finalTimeout: number,
) {
super(transactionContext, _idleHub);

Expand All @@ -96,17 +83,15 @@ export class IdleTransaction extends Transaction {
_idleHub.configureScope(scope => scope.setSpan(this));
}

this._initTimeout = setTimeout(() => {
if (!this._finished) {
this.finish();
}
}, this._idleTimeout);
this._idleTimeoutID = setTimeout(this.finish.bind(this), this._idleTimeout);
this._finalTimeoutID = setTimeout(() => {

}, this._finalTimeout)
Comment on lines +87 to +89
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more. 

this.setTag(FINISH_REASON_TAG, <final>);
this.finish();

???

}

/** {@inheritDoc} */
public finish(endTimestamp: number = timestampWithMs()): string | undefined {
this._finished = true;
this.activities = {};
this._activities = {};

if (this.spanRecorder) {
logger.log('[Tracing] finishing IdleTransaction', new Date(endTimestamp * 1000).toISOString(), this.op);
Expand Down Expand Up @@ -167,24 +152,7 @@ export class IdleTransaction extends Transaction {
*/
public initSpanRecorder(maxlen?: number): void {
if (!this.spanRecorder) {
const pushActivity = (id: string): void => {
if (this._finished) {
return;
}
this._pushActivity(id);
};
const popActivity = (id: string): void => {
if (this._finished) {
return;
}
this._popActivity(id);
};

this.spanRecorder = new IdleTransactionSpanRecorder(pushActivity, popActivity, this.spanId, maxlen);

// Start heartbeat so that transactions do not run forever.
logger.log('Starting heartbeat');
this._pingHeartbeat();
this.spanRecorder = new IdleTransactionSpanRecorder(this._pushActivity.bind(this), this._popActivity.bind(this), this.spanId, maxlen);
}
this.spanRecorder.add(this);
}
Expand All @@ -194,80 +162,47 @@ export class IdleTransaction extends Transaction {
* @param spanId The span id that represents the activity
*/
private _pushActivity(spanId: string): void {
if (this._initTimeout) {
clearTimeout(this._initTimeout);
this._initTimeout = undefined;
const id = this._idleTimeoutID;
if (id) {
clearTimeout(id)
this._idleTimeoutID = undefined;
}
logger.log(`[Tracing] pushActivity: ${spanId}`);
this.activities[spanId] = true;
logger.log('[Tracing] new activities count', Object.keys(this.activities).length);
this._activities[spanId] = true;
logger.log('[Tracing] new activities count', Object.keys(this._activities).length);
}

/**
* Remove an activity from usage
* @param spanId The span id that represents the activity
*/
private _popActivity(spanId: string): void {
if (this.activities[spanId]) {
if (this._activities[spanId]) {
logger.log(`[Tracing] popActivity ${spanId}`);
// eslint-disable-next-line @typescript-eslint/no-dynamic-delete
delete this.activities[spanId];
logger.log('[Tracing] new activities count', Object.keys(this.activities).length);
delete this._activities[spanId];
logger.log('[Tracing] new activities count', Object.keys(this._activities).length);
}

if (Object.keys(this.activities).length === 0) {
if (Object.keys(this._activities).length === 0) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you confirm if activities includes ongoing http requests? I was thinking along the lines of TTI quiescence (see https://github.com/WICG/time-to-interactive#definition)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yup can confirm it does.

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);
this._idleTimeoutID = this._setTimeoutAndFinish(timeout, end, IDLE_TRANSACTION_FINISH_REASONS[1]);
}
}

/**
* Checks when entries of this.activities are not changing for 3 beats.
* If this occurs we finish the transaction.
* JSDoc
*/
private _beat(): void {
// We should not be running heartbeat if the idle transaction is finished.
if (this._finished) {
return;
}

const heartbeatString = Object.keys(this.activities).join('');

if (heartbeatString === this._prevHeartbeatString) {
this._heartbeatCounter += 1;
} else {
this._heartbeatCounter = 1;
}

this._prevHeartbeatString = heartbeatString;

if (this._heartbeatCounter >= 3) {
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();
}
}

/**
* Pings the heartbeat
*/
private _pingHeartbeat(): void {
logger.log(`pinging Heartbeat -> current counter: ${this._heartbeatCounter}`);
setTimeout(() => {
this._beat();
}, HEARTBEAT_INTERVAL);
private _setTimeoutAndFinish(timeout: number, endTimestamp?: number, finishReason?: typeof IDLE_TRANSACTION_FINISH_REASONS[number]): ReturnType<typeof setTimeout> {
return setTimeout(() => {
if (finishReason) {
this.setTag(FINISH_REASON_TAG, finishReason)
}
this.finish(endTimestamp);
}, timeout);
}
}

Expand Down
Loading