Skip to content
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.

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

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

Merged
merged 2 commits into from May 6, 2022
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
1 change: 1 addition & 0 deletions MIGRATION.md
Expand Up @@ -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

Expand Down
Expand Up @@ -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' });
});
Expand Up @@ -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',
});
});
2 changes: 0 additions & 2 deletions 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';
Expand Down Expand Up @@ -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]);
Copy link
Member

Choose a reason for hiding this comment

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

Just because I am interested: What prompted this change? Was it just unnecessary?

Copy link
Member Author

Choose a reason for hiding this comment

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

We had these in when we were investigating ways to improve LCP accuracy, but now that the investigative work is over, we can remove these tags (and save bundle accordingly).

See: #4251

activeTransaction.finish();
}
});
Expand Down
55 changes: 20 additions & 35 deletions packages/tracing/src/browser/browsertracing.ts
Expand Up @@ -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 {
Expand All @@ -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.
*
Expand All @@ -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
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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;

Expand Down Expand Up @@ -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;
}
}
Expand All @@ -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 {
Copy link
Member Author

Choose a reason for hiding this comment

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

we can remove maxTransactionDuration because it will be effectively replaced by finalTimeout.

const diff = endTimestamp - transaction.startTimestamp;
const isOutdatedTransaction = endTimestamp && (diff > maxDuration || diff < 0);
if (isOutdatedTransaction) {
transaction.setStatus('deadline_exceeded');
transaction.setTag('maxTransactionDurationExceeded', 'true');
}
}
5 changes: 0 additions & 5 deletions packages/tracing/src/constants.ts

This file was deleted.

6 changes: 4 additions & 2 deletions packages/tracing/src/hubextensions.ts
@@ -1,3 +1,4 @@
/* eslint-disable max-lines */
import { getMainCarrier, Hub } from '@sentry/hub';
import {
ClientOptions,
Expand Down Expand Up @@ -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,
Expand Down
71 changes: 45 additions & 26 deletions packages/tracing/src/idletransaction.ts
@@ -1,23 +1,26 @@
/* eslint-disable max-lines */
import { Hub } from '@sentry/hub';
import { TransactionContext } from '@sentry/types';
import { logger, timestampWithMs } from '@sentry/utils';
import { getGlobalObject, 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;

const global = getGlobalObject<Window>();
Copy link
Member

Choose a reason for hiding this comment

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

Can we rename this to globalObject? Just to get rid of ambiguity with node's global object.

Copy link
Member Author

Choose a reason for hiding this comment

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

Removed the getGlobalObject call.


/**
* @inheritDoc
*/
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);
Expand Down Expand Up @@ -69,25 +72,27 @@ 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 a
Copy link
Member

Choose a reason for hiding this comment

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

Let's finish this comment :D

*/
private _initTimeout: ReturnType<typeof setTimeout> | undefined;
private _idleTimeoutID: ReturnType<typeof global.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.
Copy link
Member

Choose a reason for hiding this comment

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

Doesn't have to be worded this way but it took me a while to understand when this timer should be started and stopped.

Suggested change
* The time to wait in ms until the idle transaction will be finished.
* 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.

* @default 1000
*/
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);
Copy link
Member

Choose a reason for hiding this comment

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

I think we can make the hub parameter of clearActiveTransaction() down at the bottom non-optional now.


Expand All @@ -97,16 +102,19 @@ export class IdleTransaction extends Transaction {
_idleHub.configureScope(scope => scope.setSpan(this));
}

this._initTimeout = setTimeout(() => {
this._startIdleTimeout();
global.setTimeout(() => {
Copy link
Member

Choose a reason for hiding this comment

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

Are we sure we want to go through with global.setTimeout? getGlobalObject() may very well be just an empty object in some environments, whereas we can pretty much assume that setTimeout is just available in the global scope of all environments.

Copy link
Member Author

Choose a reason for hiding this comment

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

Yeah fair, I'll revert.

if (!this._finished) {
this.setStatus('deadline_exceeded');
this.finish();
}
}, this._idleTimeout);
}, this._finalTimeout);
}

/** {@inheritDoc} */
public finish(endTimestamp: number = timestampWithMs()): string | undefined {
this._finished = true;
this._cancelIdleTimeout();
Copy link
Member

Choose a reason for hiding this comment

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

Do we actually need to cancel here? _startIdleTimeout already checks for _finished before calling finish().

Copy link
Member Author

Choose a reason for hiding this comment

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

We do not, updated.

this.activities = {};

if (this.spanRecorder) {
Expand Down Expand Up @@ -193,15 +201,34 @@ 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();
Copy link
Member

Choose a reason for hiding this comment

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

Even though I get why we would call cancel here (just to be safe), I think we could get away with not calling it, because everywhere we call start() there is no way a idletimeout is running. I'll leave it up to you to keep or remove it.

this._idleTimeoutID = global.setTimeout(() => {
if (!this._finished && Object.keys(this.activities).length === 0) {
this.finish(endTimestamp);
Copy link
Member

Choose a reason for hiding this comment

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

Do we maybe want to add a this.setStatus('deadline_exceeded'); here so that transactions that are cancelled because of the idleTimeout also have that status?

Copy link
Member Author

Choose a reason for hiding this comment

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

No - because idletimeout should be how all idle transactions end regularly.

}
}, 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);
Expand All @@ -220,17 +247,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);
}
}

Expand All @@ -257,7 +277,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();
Expand All @@ -269,7 +288,7 @@ export class IdleTransaction extends Transaction {
*/
private _pingHeartbeat(): void {
IS_DEBUG_BUILD && logger.log(`pinging Heartbeat -> current counter: ${this._heartbeatCounter}`);
setTimeout(() => {
global.setTimeout(() => {
this._beat();
}, HEARTBEAT_INTERVAL);
}
Expand Down