Bug 1240985 - Add some MessageChannel logging (r=dvander,a=sylvestre)
authorBill McCloskey <billm@mozilla.com>
Tue, 19 Jan 2016 17:23:28 -0800
changeset 310966 b7104abd6362cb12234de410bc5a1653be4d9f08
parent 310965 4a8be5bac3533eaf73bbe06d9ab3a3525c8abc23
child 310967 d1a3b8124b7aeac67e3c5f065f3112e5ed7aa965
push id5513
push userraliiev@mozilla.com
push dateMon, 25 Jan 2016 13:55:34 +0000
treeherdermozilla-beta@5ee97dd05b5c [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersdvander, sylvestre
bugs1240985
milestone45.0a2
Bug 1240985 - Add some MessageChannel logging (r=dvander,a=sylvestre)
ipc/glue/MessageChannel.cpp
--- a/ipc/glue/MessageChannel.cpp
+++ b/ipc/glue/MessageChannel.cpp
@@ -19,16 +19,24 @@
 #include "nsISupportsImpl.h"
 #include "nsContentUtils.h"
 
 #include "prprf.h"
 
 // Undo the damage done by mozzconf.h
 #undef compress
 
+// Logging seems to be somewhat broken on b2g.
+#ifdef MOZ_B2G
+#define IPC_LOG(...)
+#else
+static LazyLogModule sLogModule("ipc");
+#define IPC_LOG(...) MOZ_LOG(sLogModule, LogLevel::Debug, (__VA_ARGS__))
+#endif
+
 /*
  * IPC design:
  *
  * There are three kinds of messages: async, sync, and intr. Sync and intr
  * messages are blocking. Only intr and high-priority sync messages can nest.
  *
  * Terminology: To dispatch a message Foo is to run the RecvFoo code for
  * it. This is also called "handling" the message.
@@ -661,25 +669,29 @@ MessageChannel::OnMessageReceivedFromLin
     mMonitor->AssertCurrentThreadOwns();
 
     if (MaybeInterceptSpecialIOMessage(aMsg))
         return;
 
     // Regardless of the Interrupt stack, if we're awaiting a sync reply,
     // we know that it needs to be immediately handled to unblock us.
     if (aMsg.is_sync() && aMsg.is_reply()) {
+        IPC_LOG("Received reply seqno=%d xid=%d", aMsg.seqno(), aMsg.transaction_id());
+
         if (aMsg.seqno() == mTimedOutMessageSeqno) {
             // Drop the message, but allow future sync messages to be sent.
+            IPC_LOG("Received reply to timedout message; igoring; xid=%d", mTimedOutMessageSeqno);
             mTimedOutMessageSeqno = 0;
             return;
         }
 
         MOZ_ASSERT(aMsg.transaction_id() == mCurrentTransaction);
         MOZ_ASSERT(AwaitingSyncReply());
         MOZ_ASSERT(!mRecvd);
+        MOZ_ASSERT(!mTimedOutMessageSeqno);
 
         // Rather than storing errors in mRecvd, we mark them in
         // mRecvdErrors. We need a counter because multiple replies can arrive
         // when a timeout happens, as in the following example. Imagine the
         // child is running slowly. The parent sends a sync message P1. It times
         // out. The child eventually sends a sync message C1. While waiting for
         // the C1 response, the child dispatches P1. In doing so, it sends sync
         // message C2. At that point, it's valid for the parent to send error
@@ -726,16 +738,19 @@ MessageChannel::OnMessageReceivedFromLin
             mPending.erase((++it).base());
         }
     }
 
     bool shouldWakeUp = AwaitingInterruptReply() ||
                         (AwaitingSyncReply() && !ShouldDeferMessage(aMsg)) ||
                         AwaitingIncomingMessage();
 
+    IPC_LOG("Receive on link thread; seqno=%d, xid=%d, shouldWakeUp=%d",
+            aMsg.seqno(), aMsg.transaction_id(), shouldWakeUp);
+
     // There are three cases we're concerned about, relating to the state of the
     // main thread:
     //
     // (1) We are waiting on a sync reply - main thread is blocked on the
     //     IPC monitor.
     //   - If the message is high priority, we wake up the main thread to
     //     deliver the message depending on ShouldDeferMessage. Otherwise, we
     //     leave it in the mPending queue, posting a task to the main event
@@ -857,16 +872,17 @@ MessageChannel::Send(Message* aMsg, Mess
 
     MonitorAutoLock lock(*mMonitor);
 
     if (mTimedOutMessageSeqno) {
         // Don't bother sending another sync message if a previous one timed out
         // and we haven't received a reply for it. Once the original timed-out
         // message receives a reply, we'll be able to send more sync messages
         // again.
+        IPC_LOG("Send() failed due to previous timeout");
         return false;
     }
 
     if (mCurrentTransaction &&
         DispatchingSyncMessagePriority() == IPC::Message::PRIORITY_NORMAL &&
         msg->priority() > IPC::Message::PRIORITY_NORMAL)
     {
         // Don't allow sending CPOWs while we're dispatching a sync message.
@@ -943,23 +959,26 @@ MessageChannel::Send(Message* aMsg, Mess
         bool maybeTimedOut = !WaitForSyncNotify(handleWindowsMessages);
 
         if (!Connected()) {
             ReportConnectionError("MessageChannel::SendAndWait");
             return false;
         }
 
         if (WasTransactionCanceled(transaction, prio)) {
+            IPC_LOG("Other side canceled seqno=%d, xid=%d", seqno, transaction);
             return false;
         }
 
         // We only time out a message if it initiated a new transaction (i.e.,
         // if neither side has any other message Sends on the stack).
         bool canTimeOut = transaction == seqno;
         if (maybeTimedOut && canTimeOut && !ShouldContinueFromTimeout()) {
+            IPC_LOG("Timing out Send: xid=%d", transaction);
+
             // We might have received a reply during WaitForSyncNotify or inside
             // ShouldContinueFromTimeout (which drops the lock). We need to make
             // sure not to set mTimedOutMessageSeqno if that happens, since then
             // there would be no way to unset it.
             if (mRecvdErrors) {
                 mRecvdErrors--;
                 return false;
             }
@@ -1209,16 +1228,18 @@ MessageChannel::ProcessPendingRequest(co
     // therefore mPendingUrgentRequest is set *and* mRecvd is set as
     // well, because the link thread received both before the worker
     // thread woke up.
     //
     // In this case, we process the urgent message first, but we need
     // to save the reply.
     nsAutoPtr<Message> savedReply(mRecvd.forget());
 
+    IPC_LOG("Process pending: seqno=%d, xid=%d", aUrgent.seqno(), aUrgent.transaction_id());
+
     DispatchMessage(aUrgent);
     if (!Connected()) {
         ReportConnectionError("MessageChannel::ProcessPendingRequest");
         return false;
     }
 
     // In between having dispatched our reply to the parent process, and
     // re-acquiring the monitor, the parent process could have already
@@ -1282,16 +1303,18 @@ void
 MessageChannel::DispatchMessage(const Message &aMsg)
 {
     Maybe<AutoNoJSAPI> nojsapi;
     if (ScriptSettingsInitialized() && NS_IsMainThread())
         nojsapi.emplace();
 
     nsAutoPtr<Message> reply;
 
+    IPC_LOG("DispatchMessage: seqno=%d, xid=%d", aMsg.seqno(), aMsg.transaction_id());
+
     {
         AutoEnterTransaction transaction(this, aMsg);
 
         int id = aMsg.transaction_id();
         MOZ_ASSERT_IF(aMsg.is_sync(), id == mCurrentTransaction);
 
         {
             MonitorAutoUnlock unlock(*mMonitor);
@@ -2016,16 +2039,18 @@ MessageChannel::GetTopmostMessageRouting
     }
     const InterruptFrame& frame = mCxxStackFrames.back();
     return frame.GetRoutingId();
 }
 
 void
 MessageChannel::CancelCurrentTransactionInternal()
 {
+    mMonitor->AssertCurrentThreadOwns();
+
     // When we cancel a transaction, we need to behave as if there's no longer
     // any IPC on the stack. Anything we were dispatching or sending will get
     // canceled. Consequently, we have to update the state variables below.
     //
     // We also need to ensure that when any IPC functions on the stack return,
     // they don't reset these values using an RAII class like AutoSetValue. To
     // avoid that, these RAII classes check if the variable they set has been
     // tampered with (by us). If so, they don't reset the variable to the old