Microbenchmark for the cost of posting tasks to different pump types

base/threading/thread_perftest.cc

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/base_switches.h"
 #include "base/bind.h"
 #include "base/command_line.h"
+#include "base/format_macros.h"
 #include "base/memory/scoped_vector.h"
+#include "base/strings/stringprintf.h"
 #include "base/synchronization/condition_variable.h"
 #include "base/synchronization/lock.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/threading/thread.h"
 #include "base/time/time.h"
 #include "build/build_config.h"
 #include "testing/gtest/include/gtest/gtest.h"
 #include "testing/perf/perf_test.h"
 
 #if defined(OS_POSIX)
@@ skipping 234 matching lines @@
   bool signaled_;
 };
 
 // This is meant to test the absolute minimal context switching time
 // using our own base synchronization code.
 typedef EventPerfTest<ConditionVariableEvent> ConditionVariablePerfTest;
 TEST_F(ConditionVariablePerfTest, EventPingPong) {
   RunPingPongTest("4_ConditionVariable_Threads", 4);
 }
 
+class PostTaskTest : public testing::Test {
+ public:
+  PostTaskTest() : target_("target thread"), counter_(0) {
+    // Disable the task profiler as it adds significant cost!
+    CommandLine::Init(0, NULL);
+    CommandLine::ForCurrentProcess()->AppendSwitchASCII(
+        switches::kProfilerTiming, switches::kProfilerTimingDisabledValue);
+  }
+
+  void Increment() { counter_++; }
+
+  void PostTasks(int index) {
+    base::TimeTicks start = base::TimeTicks::HighResNow();
+    base::TimeTicks thread_start;
+    if (TimeTicks::IsThreadNowSupported())
+      thread_start = base::TimeTicks::ThreadNow();
+    base::TimeDelta minimum = base::TimeDelta::Max();
+    base::TimeDelta maximum = base::TimeDelta();
+    base::TimeTicks now, lastnow = start;
+    do {
+      for (size_t i = 0; i < kBatchSize; ++i) {
+        target_.message_loop()->PostTask(
+            FROM_HERE,
+            base::Bind(&PostTaskTest::Increment, base::Unretained(this)));
+      }
+      now = base::TimeTicks::HighResNow();
+      base::TimeDelta laptime = now - lastnow;
+      lastnow = now;
+      minimum = std::min(minimum, laptime);
+      maximum = std::max(maximum, laptime);
+    } while (now - start < base::TimeDelta::FromSeconds(kTargetTimeSec));
+    posting_times_[index] = now - start;
+    if (TimeTicks::IsThreadNowSupported())
+      posting_thread_times_[index] =
+          base::TimeTicks::ThreadNow() - thread_start;
+    min_batch_times_[index] = minimum;
+    max_batch_times_[index] = maximum;
+  }
+
+  void PostTasksToThread(MessageLoop::Type target_type, int numPostingThreads) {

[darin (slow to review), 2014/09/09 04:05:07]

nit: numPostingThreads -> num_posting_threads

+    counter_ = 0;
+    target_.StartWithOptions(Thread::Options(target_type, 0u));
+
+    ScopedVector<Thread> posting_threads;
+    posting_times_.reset(new base::TimeDelta[numPostingThreads]);
+    posting_thread_times_.reset(new base::TimeDelta[numPostingThreads]);
+    min_batch_times_.reset(new base::TimeDelta[numPostingThreads]);
+    max_batch_times_.reset(new base::TimeDelta[numPostingThreads]);
+
+    for (int i = 0; i < numPostingThreads; ++i) {
+      posting_threads.push_back(new Thread("posting thread"));
+      posting_threads[i]->Start();

[darin (slow to review), 2014/09/09 04:05:06]

Start() blocks the calling thread until the target thread starts. Would it be
worth starting all of the threads first, and then calling PostTask on each?
Maybe that would help increase contention in the numPostingThreads > 1 case?

+      posting_threads[i]->message_loop()->PostTask(
+          FROM_HERE,
+          base::Bind(&PostTaskTest::PostTasks, base::Unretained(this), i));
+    }
+
+    for (int i = 0; i < numPostingThreads; ++i) {
+      posting_threads[i]->Stop();
+    }
+    target_.Stop();
+    base::TimeDelta total_time;
+    base::TimeDelta total_thread_time;
+    base::TimeDelta min_batch_time = base::TimeDelta::Max();
+    base::TimeDelta max_batch_time = base::TimeDelta();
+    for (int i = 0; i < numPostingThreads; ++i) {
+      total_time += posting_times_[i];
+      total_thread_time += posting_thread_times_[i];
+      min_batch_time = std::min(min_batch_time, min_batch_times_[i]);
+      max_batch_time = std::max(max_batch_time, max_batch_times_[i]);
+    }
+    std::string trace = StringPrintf(
+        "%d_threads_posting_to_%s_pump",
+        numPostingThreads,
+        target_type == MessageLoop::TYPE_IO
+            ? "io"
+            : (target_type == MessageLoop::TYPE_UI ? "ui" : "default"));
+    perf_test::PrintResult(
+        "task",
+        "",
+        trace,
+        total_time.InMicroseconds() / static_cast<double>(counter_),
+        "us/task",
+        true);
+    perf_test::PrintResult(
+        "task",
+        "_min_batch_time",
+        trace,
+        min_batch_time.InMicroseconds() / static_cast<double>(kBatchSize),
+        "us/task",
+        false);
+    perf_test::PrintResult(
+        "task",
+        "_max_batch_time",
+        trace,
+        max_batch_time.InMicroseconds() / static_cast<double>(kBatchSize),
+        "us/task",
+        false);
+    if (TimeTicks::IsThreadNowSupported()) {
+      perf_test::PrintResult(
+          "task",
+          "_thread_time",
+          trace,
+          total_thread_time.InMicroseconds() / static_cast<double>(counter_),
+          "us/task",
+          true);
+    }
+  }
+
+ private:
+  base::Thread target_;
+  scoped_ptr<base::TimeDelta[]> posting_times_;
+  scoped_ptr<base::TimeDelta[]> posting_thread_times_;
+  scoped_ptr<base::TimeDelta[]> min_batch_times_;
+  scoped_ptr<base::TimeDelta[]> max_batch_times_;
+  int counter_;
+
+  static const size_t kTargetTimeSec = 5;
+  static const size_t kBatchSize = 100000;
+};
+
+TEST_F(PostTaskTest, ThreadTimeToIOFromOneThread) {
+  PostTasksToThread(MessageLoop::TYPE_IO, 1);
+}
+
+TEST_F(PostTaskTest, ThreadTimeToIOFromTwoThreads) {
+  PostTasksToThread(MessageLoop::TYPE_IO, 2);
+}
+
+TEST_F(PostTaskTest, ThreadTimeToIOFromFourThreads) {
+  PostTasksToThread(MessageLoop::TYPE_IO, 4);
+}
+
+TEST_F(PostTaskTest, ThreadTimeToUIFromOneThread) {
+  PostTasksToThread(MessageLoop::TYPE_UI, 1);
+}
+
+TEST_F(PostTaskTest, ThreadTimeToUIFromTwoThreads) {
+  PostTasksToThread(MessageLoop::TYPE_UI, 2);
+}
+
+TEST_F(PostTaskTest, ThreadTimeToUIFromFourThreads) {
+  PostTasksToThread(MessageLoop::TYPE_UI, 4);
+}
+
+TEST_F(PostTaskTest, ThreadTimeToDefaultFromOneThread) {
+  PostTasksToThread(MessageLoop::TYPE_DEFAULT, 1);
+}
+
+TEST_F(PostTaskTest, ThreadTimeToDefaultFromTwoThreads) {
+  PostTasksToThread(MessageLoop::TYPE_DEFAULT, 2);
+}
+
+TEST_F(PostTaskTest, ThreadTimeToDefaultFromFourThreads) {
+  PostTasksToThread(MessageLoop::TYPE_DEFAULT, 4);
+}
+
 #if defined(OS_POSIX)
 
 // Absolutely 100% minimal posix waitable event. If there is a better/faster
 // way to force a context switch, we should use that instead.
 class PthreadEvent {
  public:
   PthreadEvent(bool manual_reset, bool initially_signaled) {
     DCHECK(!manual_reset);
     DCHECK(!initially_signaled);
     pthread_mutex_init(&mutex_, 0);
@@ skipping 32 matching lines @@
 typedef EventPerfTest<PthreadEvent> PthreadEventPerfTest;
 TEST_F(PthreadEventPerfTest, EventPingPong) {
   RunPingPongTest("4_PthreadCondVar_Threads", 4);
 }
 
 #endif
 
 }  // namespace
 
 }  // namespace base