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

fix: profiling concurrent transactions bug #2228

Conversation

armcknight
Copy link
Member

@armcknight armcknight commented Sep 26, 2022

There is an issue with the concurrent transaction profiling code when interacting with the automatic performance tracking, which works by keeping a list of root spans being profiled, and the transactions that are created for them for capturing in envelopes. I observed some spans not being converted to transactions, so the profiler wouldn't stop when the spans stopped and would go to the 30 second profile timeout before capturing profile data in an envelope. We need to capture a few edge cases in the main assumption that we can start/stop profiling every span.

TODO

Currently relies on a couple refactorings to the test suite to help work through some tests that are failing:

@armcknight armcknight changed the title Armcknight/fix profiling concurrent transactions bug fix: profiling concurrent transactions bug Sep 26, 2022
@github-actions
Copy link

github-actions bot commented Sep 26, 2022

Performance metrics 🚀

  Plain With Sentry Diff
Startup time 1226.38 ms 1265.21 ms 38.83 ms
Size 20.75 KiB 382.70 KiB 361.95 KiB

Baseline results on branch: master

Startup times

Revision Plain With Sentry Diff
7c867f1 1206.16 ms 1234.88 ms 28.71 ms
8607e67 1219.69 ms 1256.50 ms 36.81 ms
d4933ec 1201.23 ms 1235.63 ms 34.40 ms
2dcc3d7 1217.86 ms 1246.58 ms 28.72 ms
90ed869 1249.33 ms 1276.78 ms 27.45 ms
59afa00 1209.29 ms 1237.88 ms 28.59 ms
7138b7d 1243.40 ms 1252.08 ms 8.68 ms
0fdf0b2 1243.92 ms 1250.86 ms 6.94 ms
e2f1150 1220.39 ms 1249.94 ms 29.55 ms
5ecf9f6 1230.76 ms 1232.86 ms 2.10 ms

App size

Revision Plain With Sentry Diff
7c867f1 20.51 KiB 332.59 KiB 312.09 KiB
8607e67 20.50 KiB 338.99 KiB 318.49 KiB
d4933ec 20.75 KiB 368.04 KiB 347.29 KiB
2dcc3d7 20.75 KiB 374.15 KiB 353.40 KiB
90ed869 20.75 KiB 374.14 KiB 353.39 KiB
59afa00 20.50 KiB 365.16 KiB 344.65 KiB
7138b7d 20.51 KiB 331.79 KiB 311.28 KiB
0fdf0b2 20.51 KiB 332.90 KiB 312.39 KiB
e2f1150 20.51 KiB 333.10 KiB 312.59 KiB
5ecf9f6 20.51 KiB 332.66 KiB 312.15 KiB

Previous results on branch: armcknight/fix-profiling-concurrent-transactions-bug

Startup times

Revision Plain With Sentry Diff
cd2aefe 1199.47 ms 1229.72 ms 30.25 ms
aad2263 1223.00 ms 1244.26 ms 21.26 ms
e6d0a42 1217.10 ms 1246.74 ms 29.64 ms
9b216ef 1241.06 ms 1262.74 ms 21.68 ms
22f7ae3 1224.71 ms 1248.04 ms 23.33 ms
30d8d15 1226.12 ms 1244.80 ms 18.68 ms
73d83ca 1221.40 ms 1256.38 ms 34.98 ms
fcad946 1240.80 ms 1260.24 ms 19.44 ms
684a670 1237.26 ms 1253.46 ms 16.20 ms
55ace04 1215.53 ms 1249.14 ms 33.61 ms

App size

Revision Plain With Sentry Diff
cd2aefe 20.50 KiB 364.33 KiB 343.82 KiB
aad2263 20.75 KiB 381.10 KiB 360.34 KiB
e6d0a42 20.75 KiB 381.10 KiB 360.34 KiB
9b216ef 20.51 KiB 336.16 KiB 315.65 KiB
22f7ae3 20.75 KiB 381.10 KiB 360.34 KiB
30d8d15 20.75 KiB 381.10 KiB 360.35 KiB
73d83ca 20.50 KiB 368.72 KiB 348.21 KiB
fcad946 20.50 KiB 364.05 KiB 343.55 KiB
684a670 20.75 KiB 381.10 KiB 360.35 KiB
55ace04 20.50 KiB 368.63 KiB 348.12 KiB

@armcknight armcknight force-pushed the armcknight/fix-profiling-concurrent-transactions-bug branch 3 times, most recently from e121d44 to 1f99a68 Compare September 27, 2022 04:50
@github-actions
Copy link

This pull request has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!


"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀

@armcknight armcknight force-pushed the armcknight/reinstate-profiling-concurrent-transactions branch from 32a2fe2 to 5e599d4 Compare October 25, 2022 00:49
@armcknight armcknight force-pushed the armcknight/fix-profiling-concurrent-transactions-bug branch from 386f820 to e9cf5d4 Compare October 25, 2022 01:01
@armcknight armcknight force-pushed the armcknight/reinstate-profiling-concurrent-transactions branch from 01910a7 to 3ebeb6d Compare October 25, 2022 19:17
Base automatically changed from armcknight/reinstate-profiling-concurrent-transactions to master October 25, 2022 22:56
@armcknight armcknight force-pushed the armcknight/fix-profiling-concurrent-transactions-bug branch 2 times, most recently from 411f5ab to cd58976 Compare October 29, 2022 02:59
@armcknight armcknight marked this pull request as ready for review October 29, 2022 02:59
Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Sources/Sentry/include/SentryTransaction.h Outdated Show resolved Hide resolved
@armcknight armcknight force-pushed the armcknight/fix-profiling-concurrent-transactions-bug branch 2 times, most recently from cbc793a to 8e78ca6 Compare November 1, 2022 06:54
Sources/Sentry/SentryProfiler.mm Show resolved Hide resolved
Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Copy link
Member

@philipphofmann philipphofmann left a comment

Choose a reason for hiding this comment

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

We now have an issue where if a transaction exceed 500 seconds (SENTRY_AUTO_TRANSACTION_MAX_DURATION), that transaction is simply discarded. But, we'll have already sent a profiler envelope with that transaction ID. Shouldn't we instead just upload a truncated transaction instead of discarding it, in the case that it's definitely for an auto UI event trace, and not due to prewarming? See again the code I linked above.

We could finish the transaction with .deadlineExceeded or .aborted if that happens.

Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Sources/Sentry/SentryTransactionContext.m Outdated Show resolved Hide resolved
Sources/Sentry/SentryUIViewControllerPerformanceTracker.m Outdated Show resolved Hide resolved
Sources/Sentry/SentryUIEventTracker.m Outdated Show resolved Hide resolved
@armcknight armcknight force-pushed the armcknight/fix-profiling-concurrent-transactions-bug branch from 06547d0 to 386b191 Compare November 4, 2022 03:12
@philipphofmann
Copy link
Member

if I'm understanding what I observed correctly, we never sent transactions for things like button clicks

No, we send transactions for button clicks if the transaction contains child spans.

Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Sources/Sentry/SentryTracer.m Outdated Show resolved Hide resolved
Copy link
Member

@philipphofmann philipphofmann left a comment

Choose a reason for hiding this comment

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

The response to #2228 (comment) could lead to a bigger refactoring.

@armcknight armcknight force-pushed the armcknight/fix-profiling-concurrent-transactions-bug branch 2 times, most recently from a986d17 to 8386ba5 Compare November 19, 2022 07:19
@armcknight armcknight force-pushed the armcknight/fix-profiling-concurrent-transactions-bug branch 3 times, most recently from 9fb0f28 to c93f841 Compare November 19, 2022 10:52
… fixtures as possible

- convert private/test categories on SentryClient to class extensions so that properties work; remove the duplicate property declarations
- the private test init for SentryClient doesn't have to be nullable; lift the internal construction of the file manager to the real public init and add a new parameter for file managers for the test init
- fix nullability/force-unwraps of TestClients throughout test code
Make it the default for TestClient and change most test cases to use
    it. In many places it's only needed for the initializer that lists
    it as nonnull, but it isn't actually used.

Fix SentryCrashIntegrationTests fixtures to use the current date provider set in clearTestState and to use an appropriate file manager
@armcknight armcknight mentioned this pull request Nov 22, 2022
1 task
@armcknight armcknight marked this pull request as draft November 22, 2022 04:04
@armcknight armcknight force-pushed the armcknight/fix-profiling-concurrent-transactions-bug branch from c93f841 to 6dd2673 Compare November 22, 2022 04:15
@armcknight armcknight changed the base branch from master to armcknight/test/base-unit-test-class November 22, 2022 04:15
@github-actions
Copy link

github-actions bot commented Nov 22, 2022

Fails
🚫 Please consider adding a changelog entry for the next release.

Instructions and example for changelog

Please add an entry to CHANGELOG.md to the "Unreleased" section. Make sure the entry includes this PR's number.

Example:

## Unreleased

- profiling concurrent transactions bug ([#2228](https://github.com/getsentry/sentry-cocoa/pull/2228))

If none of the above apply, you can opt out of this check by adding #skip-changelog to the PR description.

Generated by 🚫 dangerJS against 2a74fcc

- trying to delete crash records before running initialization causes
    a nil crash; guard for NULL in the offending function
- there were only a handful of test cases that need a nil client, just
    do that explicitly for each one of those and remove the
    repetitious calls to `givenSDKWithHub`

- fix an issue with the base test class always resetting app start measurement would invoke the callback in the test case before the invocation we're interested in
@armcknight armcknight force-pushed the armcknight/test/base-unit-test-class branch from fe55062 to 0d18635 Compare November 22, 2022 04:31
@armcknight armcknight force-pushed the armcknight/fix-profiling-concurrent-transactions-bug branch from ff2acfa to 9883941 Compare November 22, 2022 04:32
@armcknight armcknight force-pushed the armcknight/test/base-unit-test-class branch 4 times, most recently from dcc0527 to 61e199e Compare November 24, 2022 02:07
@armcknight
Copy link
Member Author

Closing this PR until we have something definitive.

@armcknight armcknight closed this Dec 1, 2022
@armcknight armcknight deleted the armcknight/fix-profiling-concurrent-transactions-bug branch March 21, 2023 01:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants