Add support for displaying extra IPC markers #2535

jimporter · 2020-05-05T05:17:32Z

This is the front-end side of bug 1613496. It's still a work-in-progress, but things should generally work. A picture's worth 1000 words:

Stuff that still needs done:

~~Cleanup~~
~~Tests~~
~~Supporting older profiles that don't have this extra info~~

Now is also probably a good time for us to start thinking about how we can present this information in a better way. Even prior to this work, trying to read IPC message info in the profiler was like drinking from the firehose. I'm open to ideas here.

One possibility would be if we showed an exponential average of IPC message queue times in the timeline track. Then if queue times spiked at a certain point in the profile, it'd be easy to see that and then drill down into why exactly that's happening. It could also be useful to provide a detailed tab at the bottom of the UI with information/charts/etc showing what's happening with IPC messages.

codecov · 2020-05-11T04:34:25Z

Codecov Report

Merging #2535 into master will increase coverage by 0.02%.
The diff coverage is 96.38%.

@@            Coverage Diff             @@
##           master    #2535      +/-   ##
==========================================
+ Coverage   86.55%   86.58%   +0.02%     
==========================================
  Files         217      217              
  Lines       17201    17242      +41     
  Branches     4442     4468      +26     
==========================================
+ Hits        14889    14929      +40     
- Misses       2116     2117       +1     
  Partials      196      196

Impacted Files	Coverage Δ
src/test/fixtures/profiles/processed-profile.js	`97.64% <ø> (ø)`
src/profile-logic/marker-data.js	`93.32% <96.00%> (+0.25%)`	⬆️
src/components/tooltip/Marker.js	`87.28% <100.00%> (+0.21%)`	⬆️
src/test/fixtures/profiles/gecko-profile.js	`100.00% <100.00%> (ø)`

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update dea0a66...6d87cb3. Read the comment docs.

jimporter · 2020-06-09T06:12:21Z

@gregtatum This should finally be ready for review (I wasn't able to request review on this PR, so hopefully just pinging you is the right way to do it). The screenshot at the top should explain the general idea here, but if you'd like to try this out, you can check out an interactive preview here.

Edit: I forgot to mention, this is an addition to the feature from #2172.

gregtatum

Thanks for the contribution! I think most everything is solid here. I left a few comments on the Flow types used. I'm only marking this as "Request changes" as I'd like to do some manual testing with a real profile. Could you please provide me with a profile that includes the new Gecko work? Then I can test it manually and approve it for landing.

src/components/tooltip/Marker.js

gregtatum · 2020-06-17T19:26:20Z

src/components/tooltip/Marker.js

@@ -629,6 +636,18 @@ function getMarkerDetails(
          <TooltipDetails>
            <TooltipDetail label="Type">{data.messageType}</TooltipDetail>
            <TooltipDetail label="Sync">{data.sync.toString()}</TooltipDetail>
+            <TooltipDetail label="Send Thread Latency">
+              {_maybeFormatDuration(data.startTime, data.sendStartTime)}


Optional: I think it would be better to omit the label if it's unknown.

I waffled back and forth on this a bit myself, but ended up with this way because I found it easier to understand the data with the "unknown" strings:

Since each of the 4 timespans have very different meanings (and conveying those meanings well with a short phrase each is hard), being able to remember "the Nth timespan means _____" helped me understand the measurements for a particular IPC message more quickly

Having an "unknown" value in the UI is also potentially helpful if someone reading the profile is expecting all 4 values to be known (similarly to (1), I find it easier to say "oh, the last timespan says 'unknown'; I must not be collecting markers on the recipient's I/O thread").

That said, I wouldn't be too upset if the "unknown" fields went away. (Also, in the future, I plan to provide a better high-level UI summarizing this data so that people reading the profile don't have to drill down into every single IPC marker to see the latencies. That might reduce the value of the "unknown" fields, since you'd be able to get this information in a better way...)

src/profile-logic/marker-data.js

src/types/markers.js

gregtatum · 2020-06-17T19:26:20Z

src/profile-logic/marker-data.js

+          return 2;
+        default:
+          // 'endpoint'
+          return 0;


How backwards compatible are these changes?

These changes should all support older profiles; IPC markers in old profiles won't have a "phase" field, but we can guarantee that they all happened during the "endpoint" phase (since that was the only time we recorded IPC markers back then). It might be helpful to provide some automated tests here, but I'd probably have to change some of the Flow type-checking so we don't get errors.

src/profile-logic/marker-data.js

jimporter · 2020-06-18T04:03:40Z

@gregtatum Ok, I think I've address all your review comments. I left open two of them above just to verify that my responses are satisfactory. :)

src/test/fixtures/profiles/processed-profile.js

gregtatum

Thanks for handling the review comments! Everything looks good on my end. I would suggest, as a follow-up for bonus points it would be nice to document this feature.

We have end-user docs available here:

https://github.com/firefox-devtools/profiler/blob/master/docs-user/memory-allocations.md

These get published to profiler.firefox.com/docs once we deploy.

gregtatum · 2020-06-22T14:57:58Z

src/types/markers.js

+export type IPCMarkerPayload = {|
+  ...IPCMarkerPayload_Gecko,
+
+  // These fields are added in the deriving process from `IPCSharedData`, and


Perfect, thank you!

gregtatum · 2020-06-22T14:57:58Z

src/types/markers.js

+  // These fields are added in the deriving process from `IPCSharedData`, and
+  // correspond to data from all the markers associated with a particular IPC
+  // message.
+  startTime?: Milliseconds,


Is startTime really optional? In the Gecko payload it's not marked as optional.

Maybe I'm storing this data wrong, but after all the markers a single IPC message are correlated together, startTime is the timestamp of the first marker for that IPC message (i.e. the marker with direction = sending and phase = endpoint). Since that marker might not have been recorded, this time could be undefined.

However, in deriveMarkersFromRawMarkerTable, we set start and dur for all the markers (my understanding is that these fields are the ones that the timeline uses for rendering the markers). If we didn't record the first marker for our IPC message, start will be the timestamp for the current message and dur will be 0.

I think this logic is ok (I didn't see any issues in the UI at least), but maybe it'd be better to change things so we can't have undefined start/end times...

gregtatum · 2020-06-22T14:57:58Z

src/types/markers.js

+  sendStartTime?: Milliseconds,
+  sendEndTime?: Milliseconds,
+  recvEndTime?: Milliseconds,
+  endTime?: Milliseconds,


Same question for endTime.

jimporter · 2020-06-22T19:01:37Z

While thinking about this, I realized that there's a bug here: currently there are (up to) 5 markers for each IPC message. For the sender thread, recipient thread, and recipient I/O thread, there's only one marker each; that means we can use that marker, combine it with our correlated data, and show the "full" marker without issues.

However, on the sender I/O thread, there are two markers ("send start" and "send end"). Since the "full" correlated marker for both of these would be identical, they're redundant! It should be easy to fix this though: in deriveMarkersFromRawMarkerTable, when we're processing the "send end" marker, check if we have correlated data from the "send start" marker, and if so, skip the current marker. I'll push a fix for this to the PR later today...

jimporter · 2020-06-23T03:01:17Z

@gregtatum Just re-requesting a quick review to make sure the docs look ok, as well as the fix for the bug I mentioned in my last comment.

Note: since this renames transferBegin to transferStart, the sample profile I shared won't work. If you want a new sample profile, just let me know and I'll post one. :)

gregtatum

Thanks! I think we're good to merge this now.

Firefox now creates up to 5 profiler markers for each IPC message. In addition to the previously-existing "start" and "end" markers, we now have ones for "starting to send bytes", "finished sending bytes", and "finished receiving bytes". These are all correlated together to provide time deltas between each phase of the IPC message. More documentation for how to use this feature is available in <docs-user/ipc-messages.md>.

…cessed by the IO thread queues r=gerald,froydnj This adds 3 new profiler markers for each IPC message: * One just before the first byte is sent over the IPC channel * One just after the last byte is sent over the IPC channel * One just after the last byte is received from the IPC channel With the already-existing IPC markers (for when SendXXX and RecvXXX are called), this allows us to calculate the following statistics: * Send thread latency * IPC send duration * IPC recv latency * Recv thread latency For more information on how this is presented in the UI, see: <firefox-devtools/profiler#2535>. Differential Revision: https://phabricator.services.mozilla.com/D70790

jimporter force-pushed the jimporter:ipc-phases branch 2 times, most recently from 49d0dac to 6dfa033 May 6, 2020

jimporter force-pushed the jimporter:ipc-phases branch 3 times, most recently from 86d4a87 to 7ec43c3 Jun 9, 2020

jimporter changed the title ~~[WIP] Add support for displaying extra IPC markers~~ Add support for displaying extra IPC markers Jun 9, 2020

julienw requested a review from gregtatum Jun 17, 2020

gregtatum requested changes Jun 17, 2020

View changes

jimporter force-pushed the jimporter:ipc-phases branch from 0378461 to a04cf99 Jun 18, 2020

jimporter requested a review from gregtatum Jun 18, 2020

jimporter reviewed Jun 18, 2020

View changes

src/test/fixtures/profiles/processed-profile.js Outdated Show resolved Hide resolved

gregtatum approved these changes Jun 22, 2020

View changes

jimporter requested a review from gregtatum Jun 23, 2020

jimporter force-pushed the jimporter:ipc-phases branch from 9efb6a5 to 050c034 Jun 23, 2020

gregtatum approved these changes Jun 24, 2020

View changes

jimporter force-pushed the jimporter:ipc-phases branch from 050c034 to 6d87cb3 Jun 24, 2020

jimporter deleted the jimporter:ipc-phases branch Jun 24, 2020

jimporter mentioned this pull request Jun 30, 2020

Rename IPC message tooltip labels to be more descriptive #2616

Merged

firefox-devtools / profiler

Add support for displaying extra IPC markers #2535

Add support for displaying extra IPC markers #2535

jimporter commented May 5, 2020 •

edited

codecov bot commented May 11, 2020 •

edited

jimporter commented Jun 9, 2020 •

edited

gregtatum left a comment

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

jimporter commented Jun 18, 2020

gregtatum left a comment

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

jimporter commented Jun 22, 2020

jimporter commented Jun 23, 2020

gregtatum left a comment

firefox-devtools / profiler

Add support for displaying extra IPC markers #2535

Add support for displaying extra IPC markers #2535

Conversation

jimporter commented May 5, 2020 • edited

codecov bot commented May 11, 2020 • edited

Codecov Report

jimporter commented Jun 9, 2020 • edited

gregtatum left a comment

This comment has been minimized.

gregtatum Jun 17, 2020 Member

This comment has been minimized.

jimporter Jun 17, 2020 Author Contributor

This comment has been minimized.

gregtatum Jun 17, 2020 Member

This comment has been minimized.

jimporter Jun 17, 2020 Author Contributor

jimporter commented Jun 18, 2020

gregtatum left a comment

This comment has been minimized.

gregtatum Jun 22, 2020 Member

This comment has been minimized.

gregtatum Jun 22, 2020 Member

This comment has been minimized.

jimporter Jun 22, 2020 Author Contributor

This comment has been minimized.

gregtatum Jun 22, 2020 Member

jimporter commented Jun 22, 2020

jimporter commented Jun 23, 2020

gregtatum left a comment

jimporter commented May 5, 2020 •

edited

codecov bot commented May 11, 2020 •

edited

jimporter commented Jun 9, 2020 •

edited

gregtatum Jun 17, 2020
Member

jimporter Jun 17, 2020
Author Contributor

gregtatum Jun 17, 2020
Member

jimporter Jun 17, 2020
Author Contributor

gregtatum Jun 22, 2020
Member

gregtatum Jun 22, 2020
Member

jimporter Jun 22, 2020
Author Contributor

gregtatum Jun 22, 2020
Member