-
-
Notifications
You must be signed in to change notification settings - Fork 340
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
feat: profile concurrent transactions #2105
feat: profile concurrent transactions #2105
Conversation
This comment was marked as outdated.
This comment was marked as outdated.
061086e
to
a66d5ce
Compare
Performance metrics 🚀
|
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.
@armcknight, can you please elaborate on why profiling uses mach_absoluate_time/clock_gettime_nsec_np(CLOCK_UPTIME_RAW)
? I just gave this PR a glance because still WIP.
895129a
to
693bd04
Compare
@philipphofmann I left some details in a previous comment on the timestamp stuff, but basically, that API does not have a fixed reference date like NSDate does, so they can't be compared against each other, but I needed to get the relative timestamps of transactions that are linked to a given profile. |
Oh but you asked why profiling uses the system time instead of NSDate... I think because it's guaranteed to be monotonic whereas NSDate is not, and it's also much faster than NSDate, just a syscall vs alloc/initing new class instances. Check out https://kandelvijaya.com/2016/10/25/precisiontiminginios/ |
|
c0fc528
to
b02a820
Compare
This comment was marked as outdated.
This comment was marked as outdated.
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.
First pass, it looks good.
A few comments to address.
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.
Just gave this a quick glance, will do a full review on Monday.
4c2631d
to
0e48b2e
Compare
Performance metrics 🚀
|
Revision | Plain | With Sentry | Diff |
---|---|---|---|
5025d2e | 1248.52 ms | 1251.72 ms | 3.20 ms |
b869536 | 1250.37 ms | 1274.84 ms | 24.47 ms |
5025d2e | 1245.14 ms | 1268.58 ms | 23.44 ms |
4a66f00 | 1259.84 ms | 1281.66 ms | 21.82 ms |
4a66f00 | 1224.73 ms | 1241.14 ms | 16.41 ms |
9fc2dd0 | 1246.14 ms | 1275.00 ms | 28.86 ms |
App size
Revision | Plain | With Sentry | Diff |
---|---|---|---|
5025d2e | 20.51 KiB | 331.79 KiB | 311.28 KiB |
b869536 | 20.51 KiB | 331.79 KiB | 311.28 KiB |
5025d2e | 20.51 KiB | 331.79 KiB | 311.28 KiB |
4a66f00 | 20.51 KiB | 331.79 KiB | 311.28 KiB |
4a66f00 | 20.51 KiB | 331.79 KiB | 311.28 KiB |
9fc2dd0 | 20.50 KiB | 331.79 KiB | 311.28 KiB |
Previous results on branch: armcknight/profile-concurrent-transactions
Startup times
Revision | Plain | With Sentry | Diff |
---|---|---|---|
0264ffd | 1202.52 ms | 1240.36 ms | 37.84 ms |
586e4e8 | 1201.44 ms | 1237.12 ms | 35.68 ms |
1db0272 | 1201.75 ms | 1245.74 ms | 43.99 ms |
c7ab130 | 1237.20 ms | 1242.43 ms | 5.22 ms |
962039b | 1227.00 ms | 1252.12 ms | 25.12 ms |
e951eb0 | 1198.49 ms | 1228.20 ms | 29.71 ms |
fb3beab | 1234.20 ms | 1248.73 ms | 14.53 ms |
App size
Revision | Plain | With Sentry | Diff |
---|---|---|---|
0264ffd | 20.51 KiB | 335.71 KiB | 315.21 KiB |
586e4e8 | 20.51 KiB | 335.71 KiB | 315.21 KiB |
1db0272 | 20.51 KiB | 335.71 KiB | 315.21 KiB |
c7ab130 | 20.51 KiB | 335.71 KiB | 315.20 KiB |
962039b | 20.51 KiB | 335.72 KiB | 315.21 KiB |
e951eb0 | 20.51 KiB | 335.71 KiB | 315.21 KiB |
fb3beab | 20.51 KiB | 335.71 KiB | 315.21 KiB |
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.
This is going to be a cool feature and looking forward to seeing this PR merged. I added a couple of comments.
c750768
to
1edb474
Compare
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.
@philipphofmann here are the changes to the test code that I moved from the hub tests to the new profiler swift tests. RE #2105 (comment)
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.
I think the race condition still is possible, and I have a few concerns about the tests.
50e8263
to
d474029
Compare
…imeout interval; clean up a couple things in tests
492bc68
to
380d6e7
Compare
This reverts commit e43ce74.
* master: release: 7.26.0 meta: Fix Changelog concurrent transactions (#2229) build(deps): bump fastlane from 2.210.0 to 2.210.1 (#2224) Revert "feat: profile concurrent transactions (#2105)" (#2225) fix: Align core data span operations (#2222) test: Remove empty assert msg for AppStateTests (#2221) meta: Fix Changelog (#2219) ref: Add typealias for bytes (#2209) feat: profile concurrent transactions (#2105) ci: Readd cache for UI tests (#2215) # Conflicts: # Sentry.xcodeproj/project.pbxproj
We currently only profile one transaction at a time–if subsequent transactions are begun, only the first will be profiled. Now we will start the profiler for a transaction, and keep it running until the last stacked transaction is finished.
This PR also moves the growing amount of profiling-related code from
SentryTracer.m
back intoSentryProfiler.mm
. There are three methods there that the tracer calls:+ [SentryProfiler startForSpanID:hub:]
: will start a profiler if there's not one already running, and add the span id to the profiler's list of concurrent transactions it's tracking+ [SentryProfiler stopProfilingSpan:]
:- if the provided span id is the last one being profiled, stops the profiler
- otherwise, remove that span from tracking and continue profiling
+ [SentryProfiler linkTransaction:]
: grabs the appropriate profiler instance waiting on this transaction for a span it was profiling, and captures an envelope with the data it has gathered if it was the last transaction it was waiting onAlso moved the call to stop the profiler to after another early return in
- [SentryTracer finishInternal:]
, which I wonder if this was causing premature stoppage of the profiler when UI event tracking was enabled, which I first noticed in the benchmark tests: https://github.com/getsentry/sentry-cocoa/pull/2105/files#diff-84fda3cf94bf21dd7ceabf3c0ced60d74c124620d5a8dfdd3b8661563a79ec49R447. Similarly, also moved the call to capture the profiling envelope there until after the early return that drops transactions due to pre-warm durations (with a function to do so:+ [SentryProfiler dropTransaction:]
)