Adding more detail to MessageQueue::Dispatch logging.

webrtc/base/messagequeue.cc

Index: webrtc/base/messagequeue.cc
diff --git a/webrtc/base/messagequeue.cc b/webrtc/base/messagequeue.cc
index e8b5bf5bc1f4836b91c1fddef30aad2fa071d6f1..7b8244612afd9ad66ce8bd6c3b16dd9167b8f7b9 100644
--- a/webrtc/base/messagequeue.cc
+++ b/webrtc/base/messagequeue.cc
@@ -13,11 +13,13 @@
 #include "webrtc/base/common.h"
 #include "webrtc/base/logging.h"
 #include "webrtc/base/messagequeue.h"
+#include "webrtc/base/stringencode.h"
 #include "webrtc/base/trace_event.h"
 
 namespace rtc {
 
 const int kMaxMsgLatency = 150;  // 150 ms
+const int kSlowDispatchLoggingThreshold = 50;  // 50 ms
 
 //------------------------------------------------------------------
 // MessageQueueManager
@@ -308,7 +310,8 @@ bool MessageQueue::Get(Message *pmsg, int cmsWait, bool process_io) {
 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) {
@@ -322,6 +325,7 @@ void MessageQueue::Post(MessageHandler* phandler,
   {
     CritScope cs(&crit_);
     Message msg;
+    msg.posted_from = posted_from;
     msg.phandler = phandler;
     msg.message_id = id;
     msg.pdata = pdata;
@@ -333,30 +337,36 @@ void MessageQueue::Post(MessageHandler* phandler,
   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).
   int 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(int cmsDelay,
+void MessageQueue::DoDelayPost(const Location& posted_from,
+                               int cmsDelay,
                                int64_t tstamp,
                                MessageHandler* phandler,
                                uint32_t id,
@@ -371,6 +381,7 @@ void MessageQueue::DoDelayPost(int cmsDelay,
   {
     CritScope cs(&crit_);
     Message msg;
+    msg.posted_from = posted_from;
     msg.phandler = phandler;
     msg.message_id = id;
     msg.pdata = pdata;
@@ -451,8 +462,18 @@ void MessageQueue::Clear(MessageHandler* phandler,
 }
 
 void MessageQueue::Dispatch(Message *pmsg) {
-  TRACE_EVENT0("webrtc", "MessageQueue::Dispatch");
+  TRACE_EVENT3("webrtc", "MessageQueue::Dispatch", "src_file",
+               pmsg->posted_from.file_name(), "src_func",
+               pmsg->posted_from.function_name(), "src_line",
+               pmsg->posted_from.line_number());
+  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: "

[tommi, 2016/05/31 19:56:27]

LS_WARNING?

[Taylor Brandstetter, 2016/06/02 22:38:41]

I'd prefer INFO since this is more for performance debugging than for indicating
a problem. What do you think, Peter?

[pthatcher1, 2016/06/03 00:09:30]

INFO is fine.

+                 << pmsg->posted_from.ToString();
+  }
 }
 
 }  // namespace rtc