ref(apm): Always use monotonic clock for time calculations #2485

HazAT · 2020-03-10T10:47:44Z

Refactoring of our time calculations, now everything is based on monotonic timeOrigin.

kamilogorek · 2020-03-10T11:17:45Z

Can we get this in the same PR as well please? getsentry/sentry-python#644 (comment)

HazAT · 2020-03-10T12:52:18Z

@kamilogorek I think this is not relevant, we never did this.

rhcarvalho

We managed to do a nice clean up, awesome!!

packages/utils/src/misc.ts

packages/apm/src/span.ts

packages/utils/src/misc.ts

packages/apm/src/span.ts

packages/apm/src/integrations/tracing.ts

packages/apm/src/span.ts

rhcarvalho · 2020-03-10T11:09:18Z

packages/apm/src/integrations/tracing.ts

@@ -460,6 +453,7 @@ export class Tracing implements Integration {
      logger.log('[Tracing] finishIdleTransaction', active.transaction);
      // true = use timestamp of last span
      active.finish(true);
+      Tracing._resetActiveTransaction();


@HazAT could you remind me what this fixes?

Wondering if we need to call it from more places.

Since we didn't "unset" the transction (clean up) after it flushed, it produced a weird debug output if you switched tabs that the active transaction was "unset" because of page going to background.

rhcarvalho · 2020-03-10T11:31:23Z

packages/apm/src/integrations/tracing.ts

@@ -542,6 +536,11 @@ export class Tracing implements Integration {
        const startTime = Tracing._msToSec(entry.startTime as number);
        const duration = Tracing._msToSec(entry.duration as number);

+        if (transactionSpan.op === 'navigation' && timeOrigin + startTime < transactionSpan.startTimestamp) {
+          logger.log('[Tracing] Discarded performance entry because of navigation');


Was useful for debugging.

Do we expect this to cause a lot of pollution in the console in SPAs?

Is there enough info if we need to debug a problem? We logged the entry when manually testing this.

Just want to gauge the noise/signal ratio here.

Good point, I think we can remove this.
For now, my premise was, since this integration is anyway very beta I thought the more output the better.

Suggested change

logger.log('[Tracing] Discarded performance entry because of navigation');

logger.log('[Tracing] Discarded performance entry because of navigation', entry);

Could we do that? If we discard an entry, will be good to know what it was instead of just seeing a number of log messages that are equal in the console.

Talked outside of GH and decided to remove it for now.

We can always add it back if needed.

rhcarvalho · 2020-03-10T15:57:48Z

Failed Travis build:

https://travis-ci.com/getsentry/sentry-javascript/jobs/296533185

Build output (truncated)

@sentry/apm: $ jest
@sentry/apm: PASS test/span.test.ts
@sentry/apm: PASS test/tracing.test.ts
@sentry/apm: PASS test/hub.test.ts
@sentry/apm: -------------------|----------|----------|----------|----------|-------------------|
@sentry/apm: File               |  % Stmts | % Branch |  % Funcs |  % Lines | Uncovered Line #s |
@sentry/apm: -------------------|----------|----------|----------|----------|-------------------|
@sentry/apm: All files          |    42.09 |    20.19 |    40.26 |    40.63 |                   |
@sentry/apm:  src               |    83.61 |    42.86 |    91.67 |    82.61 |                   |
@sentry/apm:   hubextensions.ts |    65.38 |       50 |       75 |    65.38 |... 28,59,60,64,65 |
@sentry/apm:   index.ts         |      100 |      100 |      100 |      100 |                   |
@sentry/apm:   span.ts          |    87.64 |    35.71 |       95 |     86.9 |... 88,294,296,298 |
@sentry/apm:  src/integrations  |    23.33 |    11.84 |    16.98 |    22.35 |                   |
@sentry/apm:   express.ts       |    15.38 |        0 |        0 |    13.51 |... 36,137,138,140 |
@sentry/apm:   index.ts         |      100 |      100 |      100 |      100 |                   |
@sentry/apm:   tracing.ts       |    23.35 |    12.16 |    23.08 |    23.11 |... 28,830,836,849 |
@sentry/apm: -------------------|----------|----------|----------|----------|-------------------|
@sentry/apm: Test Suites: 3 passed, 3 total
@sentry/apm: Tests:       31 passed, 31 total
@sentry/apm: Snapshots:   0 total
@sentry/apm: Time:        4.506s
@sentry/apm: Ran all test suites.
@sentry/apm: Jest did not exit one second after the test run has completed.
@sentry/apm: This usually means that there are asynchronous operations that weren't stopped in your tests. Consider running Jest with `--detectOpenHandles` to troubleshoot this issue.
No output has been received in the last 10m0s, this potentially indicates a stalled build or something wrong with the build itself.
Check the details on how to adjust your build configuration on: https://docs.travis-ci.com/user/common-build-problems/#build-times-out-because-no-output-was-received
The build has been terminated

Debugging it with --detectOpenHandles (and running only apm tests, will drop the commit later)

rhcarvalho · 2020-03-10T16:05:40Z

Tests ran but job is still hanging: https://travis-ci.com/getsentry/sentry-javascript/jobs/296559174

...
@sentry/apm: Test Suites: 3 passed, 3 total
@sentry/apm: Tests:       31 passed, 31 total
@sentry/apm: Snapshots:   0 total
@sentry/apm: Time:        4.614s
@sentry/apm: Ran all test suites.

Nothing helpful from --detectOpenHandles so far.

rhcarvalho · 2020-03-10T16:12:05Z

For the record, there's an open issue in jest related to what we're seeing now:

jestjs/jest#7287

Wondering if anything changed in our end recently that would trigger that.

Also remove offset time calculations since everything is based on timeOrigin

Document the argument using the same format used in microsoft/TypeScript code base.

Co-Authored-By: Rodolfo Carvalho <rodolfo.carvalho@sentry.io>

getsentry-bot · 2020-03-10T16:35:26Z

	Messages
📖	@sentry/browser bundle gzip'ed minified size: (ES5: 16.8545 kB) (ES6: 15.8916 kB)
📖	✅ TSLint passed

Generated by 🚫 dangerJS against caa5aa0

rhcarvalho · 2020-03-10T16:46:04Z

Removing the empty tests in bbf54ad seemed to have fixed it (tested locally).

We may reintroduce this later on-demand. For now, reduce noise.

rhcarvalho · 2020-03-10T16:56:54Z

All green in the relevant parts of https://travis-ci.com/github/getsentry/sentry-javascript/builds/152669617

rhcarvalho · 2020-03-10T19:12:26Z

Only CI failure is integration tests in browserstack https://travis-ci.com/github/getsentry/sentry-javascript/jobs/296606639

Seems like just a flake again.... do we even have tracing integration tests?!

HazAT requested a review from rhcarvalho March 10, 2020 10:47

HazAT requested a review from kamilogorek as a code owner March 10, 2020 10:47

HazAT self-assigned this Mar 10, 2020

HazAT changed the title ~~ref: Always use monotonic clock for time calculations~~ ref(apm): Always use monotonic clock for time calculations Mar 10, 2020

rhcarvalho reviewed Mar 10, 2020

View reviewed changes

HazAT and others added 6 commits March 10, 2020 17:32

ref(apm): Always use monotonic clock for time calculations

c89e9ca

Also remove offset time calculations since everything is based on timeOrigin

ref: Changelog

fe1c9b9

doc: Document trimming of transaction end time

75f07ce

doc(apm): Document argument to Span.finish inline

7d71161

Document the argument using the same format used in microsoft/TypeScript code base.

Update packages/apm/src/span.ts

2940fdc

Co-Authored-By: Rodolfo Carvalho <rodolfo.carvalho@sentry.io>

ref: Remove empty blocking test

bbf54ad

rhcarvalho force-pushed the ref-apm-timing branch from 5596731 to bbf54ad Compare March 10, 2020 16:32

Remove logging for discarded entries

caa5aa0

We may reintroduce this later on-demand. For now, reduce noise.

rhcarvalho approved these changes Mar 10, 2020

View reviewed changes

Merge branch 'master' into ref-apm-timing

639778d

HazAT merged commit 1be9b73 into master Mar 11, 2020

HazAT deleted the ref-apm-timing branch March 11, 2020 07:36

hlian mentioned this pull request Mar 12, 2020

sentry v5.14.0, Cannot find name 'Performance' #2494

Closed

This was referenced Mar 14, 2020

[Snyk] Upgrade @sentry/browser from 5.13.2 to 5.14.0 ausgaben/web#35

Merged

[Snyk] Upgrade @sentry/node from 5.7.1 to 5.14.0 WFCD/genesis#305

Merged

[Snyk] Upgrade @sentry/node from 5.7.1 to 5.14.0 WFCD/tennotv#56

Merged

snyk-bot mentioned this pull request Apr 10, 2020

[Snyk] Upgrade @sentry/node from 5.14.0 to 5.14.2 guerronc/ecommerce-api#5

Open

This was referenced Apr 22, 2020

[Snyk] Upgrade @sentry/node from 5.13.2 to 5.15.4 tonesto7/homebridge-smartthings-v2#132

Closed

[Snyk] Upgrade @sentry/node from 5.12.5 to 5.15.4 liquality/atomicagent#50

Closed

[Snyk] Upgrade @sentry/node from 5.5.0 to 5.15.4 AtomicLoans/liquidator#26

Open

snyk-bot mentioned this pull request May 5, 2020

[Snyk] Upgrade @sentry/node from 5.9.0 to 5.15.4 alphagov/pay-toolbox#376

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ref(apm): Always use monotonic clock for time calculations #2485

ref(apm): Always use monotonic clock for time calculations #2485

HazAT commented Mar 10, 2020

kamilogorek commented Mar 10, 2020

HazAT commented Mar 10, 2020

rhcarvalho left a comment

rhcarvalho Mar 10, 2020

HazAT Mar 10, 2020

rhcarvalho Mar 10, 2020

HazAT Mar 10, 2020

rhcarvalho Mar 10, 2020

rhcarvalho Mar 10, 2020

rhcarvalho commented Mar 10, 2020

rhcarvalho commented Mar 10, 2020

rhcarvalho commented Mar 10, 2020

getsentry-bot commented Mar 10, 2020 •

edited

rhcarvalho commented Mar 10, 2020

rhcarvalho commented Mar 10, 2020

rhcarvalho commented Mar 10, 2020

	logger.log('[Tracing] Discarded performance entry because of navigation');
	logger.log('[Tracing] Discarded performance entry because of navigation', entry);

ref(apm): Always use monotonic clock for time calculations #2485

ref(apm): Always use monotonic clock for time calculations #2485

Conversation

HazAT commented Mar 10, 2020

kamilogorek commented Mar 10, 2020

HazAT commented Mar 10, 2020

rhcarvalho left a comment

Choose a reason for hiding this comment

rhcarvalho Mar 10, 2020

Choose a reason for hiding this comment

HazAT Mar 10, 2020

Choose a reason for hiding this comment

rhcarvalho Mar 10, 2020

Choose a reason for hiding this comment

HazAT Mar 10, 2020

Choose a reason for hiding this comment

rhcarvalho Mar 10, 2020

Choose a reason for hiding this comment

rhcarvalho Mar 10, 2020

Choose a reason for hiding this comment

rhcarvalho commented Mar 10, 2020

rhcarvalho commented Mar 10, 2020

rhcarvalho commented Mar 10, 2020

getsentry-bot commented Mar 10, 2020 • edited

rhcarvalho commented Mar 10, 2020

rhcarvalho commented Mar 10, 2020

rhcarvalho commented Mar 10, 2020

getsentry-bot commented Mar 10, 2020 •

edited