Bug 1557447 - Profiler support for IPC information; r=nika

This adds the ability to add profile markers for both the sender and recipient
sides of IPC messages. These can then be correlated with one another in the
profile visualization. For the UI component of this patch, see
<firefox-devtools/profiler#2172>.

Differential Revision: https://phabricator.services.mozilla.com/D42226

--HG--
extra : moz-landing-system : lando

browser/base/content/test/performance/browser_startup_syncIPC.js

@@ -283,13 +283,14 @@ add_task(async function() {
       let markerData = m[dataCol];
       if (
         !markerData ||
-        markerData.category != "IPC" ||
-        markerData.interval != "start"
+        markerData.type != "IPC" ||
+        !markerData.sync ||
+        markerData.direction != "sending"
       ) {
         continue;
       }
 
-      markersForCurrentPhase.push(markerName);
+      markersForCurrentPhase.push(markerData.messageType);
     }
   }
 

browser/base/content/test/performance/io/browser.ini

@@ -16,7 +16,7 @@ prefs =
   gfx.canvas.willReadFrequently.enable=true
 environment =
   MOZ_PROFILER_STARTUP=1
-  MOZ_PROFILER_STARTUP_FEATURES=js,mainthreadio
+  MOZ_PROFILER_STARTUP_FEATURES=js,mainthreadio,ipcmessages
   MOZ_PROFILER_STARTUP_ENTRIES=10000000
 [../browser_startup_mainthreadio.js]
 [../browser_startup_content_mainthreadio.js]

devtools/client/performance-new/components/Settings.js

@@ -186,6 +186,11 @@ const featureCheckboxes = [
     value: "preferencereads",
     title: "Track Preference Reads",
   },
+  {
+    name: "IPC Messages",
+    value: "ipcmessages",
+    title: "Track IPC messages.",
+  },
   {
     name: "JS Allocations",
     value: "jsallocations",

dom/media/mediasink/moz.build

@@ -16,6 +16,8 @@ EXPORTS += [
     'MediaSink.h'
 ]
 
+include('/ipc/chromium/chromium-config.mozbuild')
+
 FINAL_LIBRARY = 'xul'
 
 if CONFIG['CC_TYPE'] in ('clang', 'gcc'):

dom/performance/moz.build

@@ -46,4 +46,6 @@ include('/ipc/chromium/chromium-config.mozbuild')
 
 MOCHITEST_MANIFESTS += [ 'tests/mochitest.ini' ]
 
+include('/ipc/chromium/chromium-config.mozbuild')
+
 FINAL_LIBRARY = 'xul'

ipc/glue/MessageChannel.cpp

@@ -35,6 +35,10 @@
 using namespace mozilla::tasktracer;
 #endif
 
+#ifdef MOZ_GECKO_PROFILER
+#  include "ProfilerMarkerPayload.h"
+#endif
+
 // Undo the damage done by mozzconf.h
 #undef compress
 
@@ -1002,11 +1006,17 @@ bool MessageChannel::Send(Message* aMsg) {
     return false;
   }
 
+  if (msg->seqno() == 0) {
+    msg->set_seqno(NextSeqno());
+  }
+
   MonitorAutoLock lock(*mMonitor);
   if (!Connected()) {
     ReportConnectionError("MessageChannel", msg.get());
     return false;
   }
+
+  AddProfilerMarker(msg.get(), MessageDirection::eSending);
   SendMessageToLink(msg.release());
   return true;
 }
@@ -1531,6 +1541,7 @@ bool MessageChannel::Send(Message* aMsg, Message* aReply) {
   // msg will be destroyed soon, but name() is not owned by msg.
   const char* msgName = msg->name();
 
+  AddProfilerMarker(msg.get(), MessageDirection::eSending);
   SendMessageToLink(msg.release());
 
   while (true) {
@@ -1618,6 +1629,8 @@ bool MessageChannel::Send(Message* aMsg, Message* aReply) {
   MOZ_RELEASE_ASSERT(reply->type() == replyType, "wrong reply type");
   MOZ_RELEASE_ASSERT(reply->is_sync());
 
+  AddProfilerMarker(reply.get(), MessageDirection::eReceiving);
+
   *aReply = std::move(*reply);
   if (aReply->size() >= kMinTelemetryMessageSize) {
     Telemetry::Accumulate(Telemetry::IPC_REPLY_SIZE,
@@ -1668,6 +1681,9 @@ bool MessageChannel::Call(Message* aMsg, Message* aReply) {
   msg->set_interrupt_remote_stack_depth_guess(mRemoteStackDepthGuess);
   msg->set_interrupt_local_stack_depth(1 + InterruptStackDepth());
   mInterruptStack.push(MessageInfo(*msg));
+
+  AddProfilerMarker(msg.get(), MessageDirection::eSending);
+
   mLink->SendMessage(msg.release());
 
   while (true) {
@@ -1775,6 +1791,8 @@ bool MessageChannel::Call(Message* aMsg, Message* aReply) {
       // this frame and return the reply.
       mInterruptStack.pop();
 
+      AddProfilerMarker(&recvd, MessageDirection::eReceiving);
+
       bool is_reply_error = recvd.is_reply_error();
       if (!is_reply_error) {
         *aReply = std::move(recvd);
@@ -2087,6 +2105,7 @@ void MessageChannel::DispatchMessage(Message&& aMsg) {
 
   IPC_LOG("DispatchMessage: seqno=%d, xid=%d", aMsg.seqno(),
           aMsg.transaction_id());
+  AddProfilerMarker(&aMsg, MessageDirection::eReceiving);
 
   {
     AutoEnterTransaction transaction(this, aMsg);
@@ -2125,6 +2144,8 @@ void MessageChannel::DispatchMessage(Message&& aMsg) {
   if (reply && ChannelConnected == mChannelState) {
     IPC_LOG("Sending reply seqno=%d, xid=%d", aMsg.seqno(),
             aMsg.transaction_id());
+    AddProfilerMarker(reply.get(), MessageDirection::eSending);
+
     mLink->SendMessage(reply.forget());
   }
 }
@@ -2226,6 +2247,7 @@ void MessageChannel::DispatchInterruptMessage(ActorLifecycleProxy* aProxy,
 
   MonitorAutoLock lock(*mMonitor);
   if (ChannelConnected == mChannelState) {
+    AddProfilerMarker(reply.get(), MessageDirection::eSending);
     mLink->SendMessage(reply.forget());
   }
 }
@@ -2810,6 +2832,19 @@ void MessageChannel::DumpInterruptStack(const char* const pfx) const {
   }
 }
 
+void MessageChannel::AddProfilerMarker(const IPC::Message* aMessage,
+                                       MessageDirection aDirection) {
+#ifdef MOZ_GECKO_PROFILER
+  if (profiler_feature_active(ProfilerFeature::IPCMessages)) {
+    int32_t pid = mPeerPid == -1 ? base::GetCurrentProcId() : mPeerPid;
+    PROFILER_ADD_MARKER_WITH_PAYLOAD(
+        "IPC", IPC, IPCMarkerPayload,
+        (pid, aMessage->seqno(), aMessage->type(), mSide, aDirection,
+         aMessage->is_sync(), TimeStamp::Now()));
+  }
+#endif
+}
+
 int32_t MessageChannel::GetTopmostMessageRoutingId() const {
   MOZ_RELEASE_ASSERT(MessageLoop::current() == mWorkerLoop);
   if (mCxxStackFrames.empty()) {

ipc/glue/MessageChannel.h

@@ -50,6 +50,11 @@ class RefCountedMonitor : public Monitor {
   ~RefCountedMonitor() {}
 };
 
+enum class MessageDirection {
+  eSending,
+  eReceiving,
+};
+
 enum class SyncSendError {
   SendSuccess,
   PreviousTimeout,
@@ -463,6 +468,9 @@ class MessageChannel : HasResultCodes, MessageLoop::DestructionObserver {
   // debugger with all threads paused.
   void DumpInterruptStack(const char* const pfx = "") const;
 
+  void AddProfilerMarker(const IPC::Message* aMessage,
+                         MessageDirection aDirection);
+
  private:
   // Called from both threads
   size_t InterruptStackDepth() const {

ipc/glue/ProtocolUtils.h

@@ -627,11 +627,6 @@ inline bool LoggingEnabledFor(const char* aTopLevelProtocol) {
 #endif
 }
 
-enum class MessageDirection {
-  eSending,
-  eReceiving,
-};
-
 MOZ_NEVER_INLINE void LogMessageForProtocol(const char* aTopLevelProtocol,
                                             base::ProcessId aOtherPid,
                                             const char* aContextDescription,

ipc/ipdl/ipdl/lower.py

@@ -4742,14 +4742,9 @@ def sendBlocking(self, md, msgexpr, replyexpr, actor=None):
              + [Whitespace.NL,
                 StmtDecl(Decl(Type.BOOL, sendok.name)),
                 StmtBlock([
-                    StmtExpr(ExprCall(ExprVar('AUTO_PROFILER_TRACING'),
-                                      [ExprLiteral.String("IPC"),
-                                       ExprLiteral.String(self.protocol.name + "::" +
-                                                          md.prettyMsgName()),
-                                       ExprVar('OTHER')])),
-                    StmtExpr(ExprAssn(sendok, ExprCall(send,
-                                                       args=[msgexpr,
-                                                             ExprAddrOf(replyexpr)]))),
+                    StmtExpr(ExprAssn(sendok, ExprCall(
+                        send, args=[msgexpr, ExprAddrOf(replyexpr)]
+                    ))),
                 ])
                 ])
         )

js/public/ProfilingCategory.h

@@ -71,6 +71,9 @@
   END_CATEGORY                                                                \
   BEGIN_CATEGORY(DOM, "DOM", "blue")                                          \
     SUBCATEGORY(DOM, DOM, "Other")                                            \
+  END_CATEGORY                                                                \
+  BEGIN_CATEGORY(IPC, "IPC", "lightgreen")                                    \
+    SUBCATEGORY(IPC, IPC, "Other")                                            \
   END_CATEGORY
 
 namespace JS {

toolkit/components/extensions/schemas/geckoProfiler.json

@@ -39,7 +39,8 @@
           "jsallocations",
           "nostacksampling",
           "nativeallocations",
-          "preferencereads"
+          "preferencereads",
+          "ipcmessages"
         ]
       },
       {

tools/profiler/core/ProfilerMarkerPayload.cpp

@@ -967,3 +967,53 @@ void NativeAllocationMarkerPayload::StreamPayload(
                     aUniqueStacks);
   aWriter.IntProperty("size", mSize);
 }
+
+BlocksRingBuffer::Length IPCMarkerPayload::TagAndSerializationBytes() const {
+  return CommonPropsTagAndSerializationBytes() +
+         BlocksRingBuffer::SumBytes(mOtherPid, mMessageSeqno, mMessageType,
+                                    mSide, mDirection, mSync);
+}
+
+void IPCMarkerPayload::SerializeTagAndPayload(
+    BlocksRingBuffer::EntryWriter& aEntryWriter) const {
+  static const DeserializerTag tag = TagForDeserializer(Deserialize);
+  SerializeTagAndCommonProps(tag, aEntryWriter);
+  aEntryWriter.WriteObject(mOtherPid);
+  aEntryWriter.WriteObject(mMessageSeqno);
+  aEntryWriter.WriteObject(mMessageType);
+  aEntryWriter.WriteObject(mSide);
+  aEntryWriter.WriteObject(mDirection);
+  aEntryWriter.WriteObject(mSync);
+}
+
+// static
+UniquePtr<ProfilerMarkerPayload> IPCMarkerPayload::Deserialize(
+    BlocksRingBuffer::EntryReader& aEntryReader) {
+  ProfilerMarkerPayload::CommonProps props =
+      DeserializeCommonProps(aEntryReader);
+  auto otherPid = aEntryReader.ReadObject<int32_t>();
+  auto messageSeqno = aEntryReader.ReadObject<int32_t>();
+  auto messageType = aEntryReader.ReadObject<IPC::Message::msgid_t>();
+  auto mSide = aEntryReader.ReadObject<ipc::Side>();
+  auto mDirection = aEntryReader.ReadObject<ipc::MessageDirection>();
+  auto mSync = aEntryReader.ReadObject<bool>();
+  return UniquePtr<ProfilerMarkerPayload>(
+      new IPCMarkerPayload(std::move(props), otherPid, messageSeqno,
+                           messageType, mSide, mDirection, mSync));
+}
+
+void IPCMarkerPayload::StreamPayload(SpliceableJSONWriter& aWriter,
+                                     const TimeStamp& aProcessStartTime,
+                                     UniqueStacks& aUniqueStacks) const {
+  using namespace mozilla::ipc;
+  StreamCommonProps("IPC", aWriter, aProcessStartTime, aUniqueStacks);
+  aWriter.IntProperty("otherPid", mOtherPid);
+  aWriter.IntProperty("messageSeqno", mMessageSeqno);
+  aWriter.StringProperty("messageType",
+                         IPC::StringFromIPCMessageType(mMessageType));
+  aWriter.StringProperty("side", mSide == ParentSide ? "parent" : "child");
+  aWriter.StringProperty("direction", mDirection == MessageDirection::eSending
+                                          ? "sending"
+                                          : "receiving");
+  aWriter.BoolProperty("sync", mSync);
+}

tools/profiler/public/GeckoProfiler.h

@@ -180,7 +180,10 @@ class Vector;
                                                                                \
     MACRO(16, "nativeallocations", NativeAllocations,                          \
           "Collect the stacks from a smaller subset of all native "            \
-          "allocations, biasing towards collecting larger allocations")
+          "allocations, biasing towards collecting larger allocations")        \
+                                                                               \
+    MACRO(17, "ipcmessages", IPCMessages,                                      \
+          "Have the IPC layer track cross-process messages")
 
 struct ProfilerFeature {
 #  define DECLARE(n_, str_, Name_, desc_)                     \

tools/profiler/public/ProfilerMarkerPayload.h

@@ -16,6 +16,7 @@
 #include "mozilla/UniquePtr.h"
 #include "mozilla/Preferences.h"
 #include "mozilla/UniquePtrExtensions.h"
+#include "mozilla/ipc/ProtocolUtils.h"
 #include "mozilla/net/TimingStruct.h"
 
 #include "nsString.h"
@@ -703,6 +704,43 @@ class NativeAllocationMarkerPayload : public ProfilerMarkerPayload {
   int64_t mSize;
 };
 
+class IPCMarkerPayload : public ProfilerMarkerPayload {
+ public:
+  IPCMarkerPayload(int32_t aOtherPid, int32_t aMessageSeqno,
+                   IPC::Message::msgid_t aMessageType, mozilla::ipc::Side aSide,
+                   mozilla::ipc::MessageDirection aDirection, bool aSync,
+                   const mozilla::TimeStamp& aStartTime)
+      : ProfilerMarkerPayload(aStartTime, aStartTime),
+        mOtherPid(aOtherPid),
+        mMessageSeqno(aMessageSeqno),
+        mMessageType(aMessageType),
+        mSide(aSide),
+        mDirection(aDirection),
+        mSync(aSync) {}
+
+  DECL_STREAM_PAYLOAD
+
+ private:
+  IPCMarkerPayload(CommonProps&& aCommonProps, int32_t aOtherPid,
+                   int32_t aMessageSeqno, IPC::Message::msgid_t aMessageType,
+                   mozilla::ipc::Side aSide,
+                   mozilla::ipc::MessageDirection aDirection, bool aSync)
+      : ProfilerMarkerPayload(std::move(aCommonProps)),
+        mOtherPid(aOtherPid),
+        mMessageSeqno(aMessageSeqno),
+        mMessageType(aMessageType),
+        mSide(aSide),
+        mDirection(aDirection),
+        mSync(aSync) {}
+
+  int32_t mOtherPid;
+  int32_t mMessageSeqno;
+  IPC::Message::msgid_t mMessageType;
+  mozilla::ipc::Side mSide;
+  mozilla::ipc::MessageDirection mDirection;
+  bool mSync;
+};
+
 namespace mozilla {
 
 // Serialize a pointed-at ProfilerMarkerPayload, may be null when there are no

tools/profiler/tests/browser/browser.ini

@@ -9,5 +9,6 @@ support-files =
 [browser_test_feature_jsallocations.js]
 [browser_test_feature_preferencereads.js]
 [browser_test_feature_nativeallocations.js]
+[browser_test_feature_ipcmessages.js]
 [browser_test_profile_single_frame_page_info.js]
 [browser_test_profile_multi_frame_page_info.js]