Adding more detail to MessageQueue::Dispatch logging.
Every message will now be traced with the location from which it was
posted, including function name, file and line number.
This CL also writes a normal LOG message when the dispatch took more
than a certain amount of time (currently 50ms).
This logging should help us identify messages that are taking
longer than expected to be dispatched.
R=pthatcher@webrtc.org, tommi@webrtc.org
Review URL: https://codereview.webrtc.org/2019423006 .
Cr-Commit-Position: refs/heads/master@{#13104}
diff --git a/webrtc/base/thread_unittest.cc b/webrtc/base/thread_unittest.cc
index bf3cbd0..b0c8cb5 100644
--- a/webrtc/base/thread_unittest.cc
+++ b/webrtc/base/thread_unittest.cc
@@ -72,7 +72,8 @@
uint32_t prev = reinterpret_cast<const uint32_t*>(buf)[0];
uint32_t result = Next(prev);
- post_thread_->PostDelayed(200, post_handler_, 0, new TestMessage(result));
+ post_thread_->PostDelayed(RTC_FROM_HERE, 200, post_handler_, 0,
+ new TestMessage(result));
}
private:
@@ -211,7 +212,7 @@
th2.Start();
// Get the messages started.
- th1.PostDelayed(100, &msg_client, 0, new TestMessage(1));
+ th1.PostDelayed(RTC_FROM_HERE, 100, &msg_client, 0, new TestMessage(1));
// Give the clients a little while to run.
// Messages will be processed at 100, 300, 500, 700, 900.
@@ -272,18 +273,18 @@
Thread thread;
thread.Start();
// Try calling functors.
- EXPECT_EQ(42, thread.Invoke<int>(FunctorA()));
+ EXPECT_EQ(42, thread.Invoke<int>(RTC_FROM_HERE, FunctorA()));
AtomicBool called;
FunctorB f2(&called);
- thread.Invoke<void>(f2);
+ thread.Invoke<void>(RTC_FROM_HERE, f2);
EXPECT_TRUE(called.get());
// Try calling bare functions.
struct LocalFuncs {
static int Func1() { return 999; }
static void Func2() {}
};
- EXPECT_EQ(999, thread.Invoke<int>(&LocalFuncs::Func1));
- thread.Invoke<void>(&LocalFuncs::Func2);
+ EXPECT_EQ(999, thread.Invoke<int>(RTC_FROM_HERE, &LocalFuncs::Func1));
+ thread.Invoke<void>(RTC_FROM_HERE, &LocalFuncs::Func2);
}
// Verifies that two threads calling Invoke on each other at the same time does
@@ -299,13 +300,13 @@
struct LocalFuncs {
static void Set(bool* out) { *out = true; }
static void InvokeSet(Thread* thread, bool* out) {
- thread->Invoke<void>(Bind(&Set, out));
+ thread->Invoke<void>(RTC_FROM_HERE, Bind(&Set, out));
}
};
bool called = false;
other_thread.Invoke<void>(
- Bind(&LocalFuncs::InvokeSet, current_thread, &called));
+ RTC_FROM_HERE, Bind(&LocalFuncs::InvokeSet, current_thread, &called));
EXPECT_TRUE(called);
}
@@ -342,7 +343,7 @@
struct LocalFuncs {
static void Set(LockedBool* out) { out->Set(true); }
static void InvokeSet(Thread* thread, LockedBool* out) {
- thread->Invoke<void>(Bind(&Set, out));
+ thread->Invoke<void>(RTC_FROM_HERE, Bind(&Set, out));
}
// Set |out| true and call InvokeSet on |thread|.
@@ -362,7 +363,8 @@
AsyncInvoker invoker;
invoker.AsyncInvoke<void>(
- thread1, Bind(&SetAndInvokeSet, &async_invoked, thread2, out));
+ RTC_FROM_HERE, thread1,
+ Bind(&SetAndInvokeSet, &async_invoked, thread2, out));
EXPECT_TRUE_WAIT(async_invoked.Get(), 2000);
}
@@ -373,8 +375,9 @@
// Start the sequence A --(invoke)--> B --(async invoke)--> C --(invoke)--> A.
// Thread B returns when C receives the call and C should be blocked until A
// starts to process messages.
- thread_b.Invoke<void>(Bind(&LocalFuncs::AsyncInvokeSetAndWait,
- &thread_c, thread_a, &thread_a_called));
+ thread_b.Invoke<void>(RTC_FROM_HERE,
+ Bind(&LocalFuncs::AsyncInvokeSetAndWait, &thread_c,
+ thread_a, &thread_a_called));
EXPECT_FALSE(thread_a_called.Get());
EXPECT_TRUE_WAIT(thread_a_called.Get(), 2000);
@@ -424,7 +427,7 @@
}
void AsyncInvokeIntCallback(AsyncInvoker* invoker, Thread* thread) {
expected_thread_ = thread;
- invoker->AsyncInvoke(thread, FunctorC(),
+ invoker->AsyncInvoke(RTC_FROM_HERE, RTC_FROM_HERE, thread, FunctorC(),
&AsyncInvokeTest::IntCallback,
static_cast<AsyncInvokeTest*>(this));
invoke_started_.Set();
@@ -452,7 +455,7 @@
thread.Start();
// Try calling functor.
AtomicBool called;
- invoker.AsyncInvoke<void>(&thread, FunctorB(&called));
+ invoker.AsyncInvoke<void>(RTC_FROM_HERE, &thread, FunctorB(&called));
EXPECT_TRUE_WAIT(called.get(), kWaitTimeout);
}
@@ -463,7 +466,7 @@
thread.Start();
// Try calling functor.
SetExpectedThreadForIntCallback(Thread::Current());
- invoker.AsyncInvoke(&thread, FunctorA(),
+ invoker.AsyncInvoke(RTC_FROM_HERE, RTC_FROM_HERE, &thread, FunctorA(),
&AsyncInvokeTest::IntCallback,
static_cast<AsyncInvokeTest*>(this));
EXPECT_EQ_WAIT(42, int_value_, kWaitTimeout);
@@ -476,7 +479,7 @@
// Try destroying invoker during call.
{
AsyncInvoker invoker;
- invoker.AsyncInvoke(&thread, FunctorC(),
+ invoker.AsyncInvoke(RTC_FROM_HERE, RTC_FROM_HERE, &thread, FunctorC(),
&AsyncInvokeTest::IntCallback,
static_cast<AsyncInvokeTest*>(this));
}
@@ -491,9 +494,10 @@
Thread thread;
thread.Start();
// Try calling functor.
- thread.Invoke<void>(Bind(&AsyncInvokeTest::AsyncInvokeIntCallback,
- static_cast<AsyncInvokeTest*>(this),
- &invoker, Thread::Current()));
+ thread.Invoke<void>(
+ RTC_FROM_HERE,
+ Bind(&AsyncInvokeTest::AsyncInvokeIntCallback,
+ static_cast<AsyncInvokeTest*>(this), &invoker, Thread::Current()));
// Wait for the call to begin.
ASSERT_TRUE(invoke_started_.Wait(kWaitTimeout));
}
@@ -508,9 +512,10 @@
{
AsyncInvoker invoker;
// Try calling functor.
- thread.Invoke<void>(Bind(&AsyncInvokeTest::AsyncInvokeIntCallback,
- static_cast<AsyncInvokeTest*>(this),
- &invoker, Thread::Current()));
+ thread.Invoke<void>(
+ RTC_FROM_HERE,
+ Bind(&AsyncInvokeTest::AsyncInvokeIntCallback,
+ static_cast<AsyncInvokeTest*>(this), &invoker, Thread::Current()));
// Wait for the call to begin.
ASSERT_TRUE(invoke_started_.Wait(kWaitTimeout));
}
@@ -524,10 +529,8 @@
AtomicBool flag1;
AtomicBool flag2;
// Queue two async calls to the current thread.
- invoker.AsyncInvoke<void>(Thread::Current(),
- FunctorB(&flag1));
- invoker.AsyncInvoke<void>(Thread::Current(),
- FunctorB(&flag2));
+ invoker.AsyncInvoke<void>(RTC_FROM_HERE, Thread::Current(), FunctorB(&flag1));
+ invoker.AsyncInvoke<void>(RTC_FROM_HERE, Thread::Current(), FunctorB(&flag2));
// Because we haven't pumped messages, these should not have run yet.
EXPECT_FALSE(flag1.get());
EXPECT_FALSE(flag2.get());
@@ -542,11 +545,9 @@
AtomicBool flag1;
AtomicBool flag2;
// Queue two async calls to the current thread, one with a message id.
- invoker.AsyncInvoke<void>(Thread::Current(),
- FunctorB(&flag1),
+ invoker.AsyncInvoke<void>(RTC_FROM_HERE, Thread::Current(), FunctorB(&flag1),
5);
- invoker.AsyncInvoke<void>(Thread::Current(),
- FunctorB(&flag2));
+ invoker.AsyncInvoke<void>(RTC_FROM_HERE, Thread::Current(), FunctorB(&flag2));
// Because we haven't pumped messages, these should not have run yet.
EXPECT_FALSE(flag1.get());
EXPECT_FALSE(flag2.get());
@@ -569,7 +570,8 @@
}
void AsyncInvokeIntCallback(GuardedAsyncInvoker* invoker, Thread* thread) {
expected_thread_ = thread;
- invoker->AsyncInvoke(FunctorC(), &GuardedAsyncInvokeTest::IntCallback,
+ invoker->AsyncInvoke(RTC_FROM_HERE, RTC_FROM_HERE, FunctorC(),
+ &GuardedAsyncInvokeTest::IntCallback,
static_cast<GuardedAsyncInvokeTest*>(this));
invoke_started_.Set();
}
@@ -604,12 +606,12 @@
thread->Start();
std::unique_ptr<GuardedAsyncInvoker> invoker;
// Create the invoker on |thread|.
- thread->Invoke<void>(CreateInvoker(&invoker));
+ thread->Invoke<void>(RTC_FROM_HERE, CreateInvoker(&invoker));
// Kill |thread|.
thread = nullptr;
// Try calling functor.
AtomicBool called;
- EXPECT_FALSE(invoker->AsyncInvoke<void>(FunctorB(&called)));
+ EXPECT_FALSE(invoker->AsyncInvoke<void>(RTC_FROM_HERE, FunctorB(&called)));
// With thread gone, nothing should happen.
WAIT(called.get(), kWaitTimeout);
EXPECT_FALSE(called.get());
@@ -622,12 +624,13 @@
thread->Start();
std::unique_ptr<GuardedAsyncInvoker> invoker;
// Create the invoker on |thread|.
- thread->Invoke<void>(CreateInvoker(&invoker));
+ thread->Invoke<void>(RTC_FROM_HERE, CreateInvoker(&invoker));
// Kill |thread|.
thread = nullptr;
// Try calling functor.
EXPECT_FALSE(
- invoker->AsyncInvoke(FunctorC(), &GuardedAsyncInvokeTest::IntCallback,
+ invoker->AsyncInvoke(RTC_FROM_HERE, RTC_FROM_HERE, FunctorC(),
+ &GuardedAsyncInvokeTest::IntCallback,
static_cast<GuardedAsyncInvokeTest*>(this)));
// With thread gone, callback should be cancelled.
Thread::Current()->ProcessMessages(kWaitTimeout);
@@ -640,7 +643,7 @@
GuardedAsyncInvoker invoker;
// Try calling functor.
AtomicBool called;
- EXPECT_TRUE(invoker.AsyncInvoke<void>(FunctorB(&called)));
+ EXPECT_TRUE(invoker.AsyncInvoke<void>(RTC_FROM_HERE, FunctorB(&called)));
EXPECT_TRUE_WAIT(called.get(), kWaitTimeout);
}
@@ -648,7 +651,7 @@
GuardedAsyncInvoker invoker;
// Try calling functor.
SetExpectedThreadForIntCallback(Thread::Current());
- EXPECT_TRUE(invoker.AsyncInvoke(FunctorA(),
+ EXPECT_TRUE(invoker.AsyncInvoke(RTC_FROM_HERE, RTC_FROM_HERE, FunctorA(),
&GuardedAsyncInvokeTest::IntCallback,
static_cast<GuardedAsyncInvokeTest*>(this)));
EXPECT_EQ_WAIT(42, int_value_, kWaitTimeout);
@@ -659,7 +662,8 @@
{
GuardedAsyncInvoker invoker;
EXPECT_TRUE(
- invoker.AsyncInvoke(FunctorC(), &GuardedAsyncInvokeTest::IntCallback,
+ invoker.AsyncInvoke(RTC_FROM_HERE, RTC_FROM_HERE, FunctorC(),
+ &GuardedAsyncInvokeTest::IntCallback,
static_cast<GuardedAsyncInvokeTest*>(this)));
}
// With invoker gone, callback should be cancelled.
@@ -674,7 +678,8 @@
Thread thread;
thread.Start();
// Try calling functor.
- thread.Invoke<void>(Bind(&GuardedAsyncInvokeTest::AsyncInvokeIntCallback,
+ thread.Invoke<void>(RTC_FROM_HERE,
+ Bind(&GuardedAsyncInvokeTest::AsyncInvokeIntCallback,
static_cast<GuardedAsyncInvokeTest*>(this),
&invoker, Thread::Current()));
// Wait for the call to begin.
@@ -691,7 +696,8 @@
{
GuardedAsyncInvoker invoker;
// Try calling functor.
- thread.Invoke<void>(Bind(&GuardedAsyncInvokeTest::AsyncInvokeIntCallback,
+ thread.Invoke<void>(RTC_FROM_HERE,
+ Bind(&GuardedAsyncInvokeTest::AsyncInvokeIntCallback,
static_cast<GuardedAsyncInvokeTest*>(this),
&invoker, Thread::Current()));
// Wait for the call to begin.
@@ -707,8 +713,8 @@
AtomicBool flag1;
AtomicBool flag2;
// Queue two async calls to the current thread.
- EXPECT_TRUE(invoker.AsyncInvoke<void>(FunctorB(&flag1)));
- EXPECT_TRUE(invoker.AsyncInvoke<void>(FunctorB(&flag2)));
+ EXPECT_TRUE(invoker.AsyncInvoke<void>(RTC_FROM_HERE, FunctorB(&flag1)));
+ EXPECT_TRUE(invoker.AsyncInvoke<void>(RTC_FROM_HERE, FunctorB(&flag2)));
// Because we haven't pumped messages, these should not have run yet.
EXPECT_FALSE(flag1.get());
EXPECT_FALSE(flag2.get());
@@ -723,8 +729,8 @@
AtomicBool flag1;
AtomicBool flag2;
// Queue two async calls to the current thread, one with a message id.
- EXPECT_TRUE(invoker.AsyncInvoke<void>(FunctorB(&flag1), 5));
- EXPECT_TRUE(invoker.AsyncInvoke<void>(FunctorB(&flag2)));
+ EXPECT_TRUE(invoker.AsyncInvoke<void>(RTC_FROM_HERE, FunctorB(&flag1), 5));
+ EXPECT_TRUE(invoker.AsyncInvoke<void>(RTC_FROM_HERE, FunctorB(&flag2)));
// Because we haven't pumped messages, these should not have run yet.
EXPECT_FALSE(flag1.get());
EXPECT_FALSE(flag2.get());
@@ -759,7 +765,7 @@
TEST_F(ComThreadTest, ComInited) {
Thread* thread = new ComThread();
EXPECT_TRUE(thread->Start());
- thread->Post(this, 0);
+ thread->Post(RTC_FROM_HERE, this, 0);
EXPECT_TRUE_WAIT(done_, 1000);
delete thread;
}
