Bug 1240985 - Add some MessageChannel logging (r=dvander)
☠☠ backed out by 10d4e8736dbb ☠ ☠
authorBill McCloskey <billm@mozilla.com>
Tue, 19 Jan 2016 17:23:28 -0800
changeset 280846 34f87cc8ac248ec137f1450253f561cad84a2172
parent 280845 fddcf8b3b08835eb75c1bd986df3af677bae3f34
child 280847 12de76467424461300853e4953dfd3c6229ff5cb
push id29922
push usercbook@mozilla.com
push dateThu, 21 Jan 2016 10:51:00 +0000
treeherdermozilla-central@977d78a8dd78 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersdvander
bugs1240985
milestone46.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1240985 - Add some MessageChannel logging (r=dvander)
ipc/glue/MessageChannel.cpp
--- a/ipc/glue/MessageChannel.cpp
+++ b/ipc/glue/MessageChannel.cpp
@@ -18,16 +18,20 @@
 #include "nsDebug.h"
 #include "nsISupportsImpl.h"
 #include "nsContentUtils.h"
 #include "mozilla/Snprintf.h"
 
 // Undo the damage done by mozzconf.h
 #undef compress
 
+static LazyLogModule sLogModule("ipc");
+
+#define IPC_LOG(args...) MOZ_LOG(sLogModule, LogLevel::Debug, (args))
+
 /*
  * 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 +665,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 +734,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
@@ -858,16 +869,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.
@@ -944,23 +956,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;
             }
@@ -1210,16 +1225,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
@@ -1283,16 +1300,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);
@@ -2015,16 +2034,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