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/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/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 270 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).
   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,
                                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_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