Adding more detail to MessageQueue::Dispatch logging.

webrtc/base/messagequeue.cc

 /*
  *  Copyright 2004 The WebRTC Project Authors. All rights reserved.
  *
  *  Use of this source code is governed by a BSD-style license
  *  that can be found in the LICENSE file in the root of the source
  *  tree. An additional intellectual property rights grant can be found
  *  in the file PATENTS.  All contributing project authors may
  *  be found in the AUTHORS file in the root of the source tree.
  */
 #include <algorithm>
 
 #include "webrtc/base/atomicops.h"
 #include "webrtc/base/checks.h"
 #include "webrtc/base/common.h"
 #include "webrtc/base/logging.h"
 #include "webrtc/base/messagequeue.h"
+#include "webrtc/base/stringencode.h"
 #include "webrtc/base/thread.h"
 #include "webrtc/base/trace_event.h"
 
 namespace rtc {
 
 const int kMaxMsgLatency = 150;  // 150 ms
+const int kSlowDispatchLoggingThreshold = 50;  // 50 ms
 
 //------------------------------------------------------------------
 // MessageQueueManager
 
 MessageQueueManager* MessageQueueManager::instance_ = NULL;
 
 MessageQueueManager* MessageQueueManager::Instance() {
   // Note: This is not thread safe, but it is first called before threads are
   // spawned.
   if (!instance_)
@@ skipping 85 matching lines @@
   // Post a delayed message at the current time and wait for it to be dispatched
   // on all queues, which will ensure that all messages that came before it were
   // also dispatched.
   volatile int queues_not_done;
   auto functor = [&queues_not_done] { AtomicOps::Decrement(&queues_not_done); };
   FunctorMessageHandler<void, decltype(functor)> handler(functor);
   {
     CritScope cs(&crit_);
     queues_not_done = static_cast<int>(message_queues_.size());
     for (MessageQueue* queue : message_queues_) {
-      queue->PostDelayed(0, &handler);
+      queue->PostDelayed(RTC_FROM_HERE, 0, &handler);
     }
   }
   // Note: One of the message queues may have been on this thread, which is why
   // we can't synchronously wait for queues_not_done to go to 0; we need to
   // process messages as well.
   while (AtomicOps::AcquireLoad(&queues_not_done) > 0) {
     rtc::Thread::Current()->ProcessMessages(0);
   }
 }
 
@@ skipping 195 matching lines @@
       if (cmsElapsed >= cmsWait)
         return false;
     }
   }
   return false;
 }
 
 void MessageQueue::ReceiveSends() {
 }
 
-void MessageQueue::Post(MessageHandler* phandler,
+void MessageQueue::Post(const Location& posted_from,
+                        MessageHandler* phandler,
                         uint32_t id,
                         MessageData* pdata,
                         bool time_sensitive) {
   if (fStop_)
     return;
 
   // Keep thread safe
   // Add the message to the end of the queue
   // Signal for the multiplexer to return
 
   {
     CritScope cs(&crit_);
     Message msg;
+    msg.posted_from = posted_from;
     msg.phandler = phandler;
     msg.message_id = id;
     msg.pdata = pdata;
     if (time_sensitive) {
       msg.ts_sensitive = TimeMillis() + kMaxMsgLatency;
     }
     msgq_.push_back(msg);
   }
   WakeUpSocketServer();
 }
 
-void MessageQueue::PostDelayed(int cmsDelay,
+void MessageQueue::PostDelayed(const Location& posted_from,
+                               int cmsDelay,
                                MessageHandler* phandler,
                                uint32_t id,
                                MessageData* pdata) {
-  return DoDelayPost(cmsDelay, TimeAfter(cmsDelay), phandler, id, pdata);
+  return DoDelayPost(posted_from, cmsDelay, TimeAfter(cmsDelay), phandler, id,
+                     pdata);
 }
 
-void MessageQueue::PostAt(uint32_t tstamp,
+void MessageQueue::PostAt(const Location& posted_from,
+                          uint32_t tstamp,
                           MessageHandler* phandler,
                           uint32_t id,
                           MessageData* pdata) {
   // This should work even if it is used (unexpectedly).
   int64_t delay = static_cast<uint32_t>(TimeMillis()) - tstamp;
-  return DoDelayPost(delay, tstamp, phandler, id, pdata);
+  return DoDelayPost(posted_from, delay, tstamp, phandler, id, pdata);
 }
 
-void MessageQueue::PostAt(int64_t tstamp,
+void MessageQueue::PostAt(const Location& posted_from,
+                          int64_t tstamp,
                           MessageHandler* phandler,
                           uint32_t id,
                           MessageData* pdata) {
-  return DoDelayPost(TimeUntil(tstamp), tstamp, phandler, id, pdata);
+  return DoDelayPost(posted_from, TimeUntil(tstamp), tstamp, phandler, id,
+                     pdata);
 }
 
-void MessageQueue::DoDelayPost(int64_t cmsDelay,
+void MessageQueue::DoDelayPost(const Location& posted_from,
+                               int64_t cmsDelay,
                                int64_t tstamp,
                                MessageHandler* phandler,
                                uint32_t id,
                                MessageData* pdata) {
   if (fStop_) {
     return;
   }
 
   // Keep thread safe
   // Add to the priority queue. Gets sorted soonest first.
   // Signal for the multiplexer to return.
 
   {
     CritScope cs(&crit_);
     Message msg;
+    msg.posted_from = posted_from;
     msg.phandler = phandler;
     msg.message_id = id;
     msg.pdata = pdata;
     DelayedMessage dmsg(cmsDelay, tstamp, dmsgq_next_num_, msg);
     dmsgq_.push(dmsg);
     // If this message queue processes 1 message every millisecond for 50 days,
     // we will wrap this number.  Even then, only messages with identical times
     // will be misordered, and then only briefly.  This is probably ok.
     VERIFY(0 != ++dmsgq_next_num_);
   }
@@ skipping 60 matching lines @@
       }
     } else {
       *new_end++ = *it;
     }
   }
   dmsgq_.container().erase(new_end, dmsgq_.container().end());
   dmsgq_.reheap();
 }
 
 void MessageQueue::Dispatch(Message *pmsg) {
-  TRACE_EVENT0("webrtc", "MessageQueue::Dispatch");
+  TRACE_EVENT2("webrtc", "MessageQueue::Dispatch", "src_file_and_line",
+               pmsg->posted_from.file_and_line(), "src_func",
+               pmsg->posted_from.function_name());
+  int64_t start_time = TimeMillis();
   pmsg->phandler->OnMessage(pmsg);
+  int64_t end_time = TimeMillis();
+  int64_t diff = TimeDiff(end_time, start_time);
+  if (diff >= kSlowDispatchLoggingThreshold) {
+    LOG(LS_INFO) << "Message took " << diff << "ms to dispatch. Posted from: "
+                 << pmsg->posted_from.ToString();
+  }
 }
 
 }  // namespace rtc