Update Onyx.printMetrics format #89
Conversation
This doesn't represent accurate or useful information It was just the total time divided by the count of decorated methods
For example copying the raw data to excel allow for easier formatting sorting and other math operations
This does not happen while debugging with Chrome, which is what I used for the most of the time and never noticed the issue Since the update for Reanimated 2 (TurboModules/JSI) It's no longer possible to use the old (Chrome) debugging flow I've discovered the timing information was not at all relative to app launch, the duration between start/end is correct but the start/end values are otherwise useless if they display like 8468.7min To be useful they need to be relative to app launch time Since timing otherwise works correct, we can capture an offset - APP_LAUNCH_TIME and subtract this value from the timings we make to capture a correct start/end time relative to APP_LAUNCH_TIME
| /* For some reason `performance.now()` does not start from `0` but a very large offset | ||
| * like `508,080,000` see: https://github.com/facebook/react-native/issues/30069 | ||
| * Capturing an offset allows us to record start/ends times relative to app launch time */ | ||
| const APP_LAUNCH_TIME = performance.now(); |
There was a problem hiding this comment.
I've found this issue after I switched to the "new" debugging flow today: https://expensify.slack.com/archives/C01GTK53T8Q/p1626422647390900?thread_ts=1626297548.276300&cid=C01GTK53T8Q
There was a problem hiding this comment.
It's related to the "old" chrome debugger not being used
|
@marcaaron Since the update for Reanimated 2 (TurboModules/JSI)
The other PR adds MD table formatting like this Which would allow you to paste data like this: Onyx Benchmark
|
| @@ -6,6 +6,11 @@ import _ from 'underscore'; | |||
| */ | |||
| let stats = {}; | |||
|
|
|||
| /* For some reason `performance.now()` does not start from `0` but a very large offset | |||
| * like `508,080,000` see: https://github.com/facebook/react-native/issues/30069 | |||
| * Capturing an offset allows us to record start/ends times relative to app launch time */ | |||
There was a problem hiding this comment.
Interesting, since it is supposed to be more reliable than Date, but still has this issue? 🤔
Not a blocker, but I'm not sure I'd expect it this to be 0. performance.now() returns elapsed since the time origin (or is supposed to at least).
There was a problem hiding this comment.
Yeah it will never be 0 but the origin is definitely not app launch the benchmark would say something like "Last call finished at: 3940min" which is useless
There was a problem hiding this comment.
Got it that makes more sense to me now. Thanks for the explanation.
| @@ -20,7 +25,7 @@ function decorateWithMetrics(func, alias = func.name) { | |||
| stats[alias] = []; | |||
|
|
|||
| function decorated(...args) { | |||
| const startTime = performance.now(); | |||
| const startTime = performance.now() - APP_LAUNCH_TIME; | |||
There was a problem hiding this comment.
I'm trying to understand the reliability of this next usage of performance.now() here and which metric this will make more reliable. Is it just the endTime? Since all the other metrics are relative to performance.now() but that one will tell us the actual time from when Onyx started doing work and when it finished for each method?
There was a problem hiding this comment.
This doesn't make anything more or less reliable, just keeps our start/end times relative to app launch
Differences between performance.now() are reliable but the initial time given by performance.now() is ridiculously high - and I can't match the value to anything - it's not the current unix ts, it's not the time since app launch
It's a value like 508 million and increases as time passes. Might be relative to midnight 00:00 UTC ? But that doesn't help us track boot time 😄
On the old flow, when this was provided by Chrome, the value will be very close to 0 initially and so you know a value of 1000 means something started/ended a second past app launch
By capturing our own reference point APP_LAUNCH_TIME we keep start/end times relative to that point
so we have more useful information
There was a problem hiding this comment.
If I remove this, I'll get this ATM: "Last call finished at: 8907.4min" so it's not midnight
It might be the time since last reboot, let me check
Yep seems to be it: "Last call finished at: 10.0min"
I guess it uses some clock managed by the OS and that's what it returns
There was a problem hiding this comment.
Haha, ok awesome, thanks for the explanation.
Very weird, but now that we are interested in something besides relative times also very necessary.
|
@kidroca ah that's annoying, I wasn't expecting an effect like that from updating that library 🤔 but the markdown table looks very slick 👏 |
@marcaaron
Details
This PR does not change how Onyx work and only affects dev, debug, benchmark usages
The changes here update the print format so that a summary table is printed
This table can be easily selected and pasted in xls
Sample Output
Related Issues
Expensify/App#2667
Automated Tests
Covered by existing tests
Linked PRs