Microbenchmark for the cost of posting tasks to different pump types

Microbenchmark for the cost of posting tasks to different pump types

This adds microbenchmarks to measure the cost of posting a task to
a message loop running different pump types. This measures the wall and
(where supported) thread time that elapses from different numbers of
threads posting to one target. This is not designed to measure the time
taken by the target thread or fairness of posting threads.

Each test is set up with one target thread and 1-4 posting threads. The
posting threads each run one task that posts batches of tasks to the
target thread until they have been working for at least 5 seconds of
wall time. The tasks on the target thread simply increment a counter.
The test runner starts each posting thread, posts a start task to each
then joins them and then joins the target thread and aggregates stats.

BUG=412137
Committed: https://crrev.com/2e146d74f78041f91bd43562bd1a0210374a41eb
Cr-Commit-Position: refs/heads/master@{#297264}

[jamesr, 2014-09-08 22:27:36]

jamesr@chromium.org changed reviewers:
+ darin@chromium.org

[jamesr, 2014-09-08 22:27:36]

This seems to produce fairly stable times on linux and android and seems useful
to have around.  In total these tests run for ~50 seconds.  I'd like to test
posting to a TYPE_JAVA loop as well but haven't figured out the voodoo for
initializing JNI correctly on the target thread for this to work.

[jamesr, 2014-09-08 22:40:07]

Example results from a linux z620:

Posting to an I/O pump:

From 1 thread: .2955104117647059 us/task
From 4 threads: 2.8416995833333334 us/task

UI pump:

From 1 thread: .3040279393939394 us/task
From 4 threads: 1.5808721590909092 us/task

Default pump (mutex+condvar):

From 1 thread: .4047686290322581 us/task
From 4 threads: 3.384504833333333 us/task

It's interesting to me that the default pump is actually the slowest in terms of
cost to the posting thread.  I'd expect write()ing to an fd to be more expensive
than signal()ing a condvar, but maybe not?

Same numbers for android (nexus 4 on L)

Posting to an I/O pump:

From 1 thread: 3.3359993333333335 us/task
From 2 threads: 11.49977111111111 us/task
From 4 threads: 26.96333625 us/task

Default pump:

From 1 thread: 4.1472261538461535 us/task
From 2 threads: 13.33263375 us/task
From 4 threads: 27.737905 us/task

On the N4 with 4 threads the thread time is significantly lower than the wall
clock time, which makes sense since there aren't enough h/w threads around to
service 4 posting threads and 1 target thread, so we're spending a lot of time
descheduled.

Interestingly the I/O pump is faster than the default pump on android as well.

[piman, 2014-09-09 01:16:02]

On 2014/09/08 22:40:07, jamesr wrote:
> Example results from a linux z620:
> 
> Posting to an I/O pump:
> 
> From 1 thread: .2955104117647059 us/task
> From 4 threads: 2.8416995833333334 us/task
> 
> UI pump:
> 
> From 1 thread: .3040279393939394 us/task
> From 4 threads: 1.5808721590909092 us/task
> 
> Default pump (mutex+condvar):
> 
> From 1 thread: .4047686290322581 us/task
> From 4 threads: 3.384504833333333 us/task
> 
> It's interesting to me that the default pump is actually the slowest in terms
of
> cost to the posting thread.  I'd expect write()ing to an fd to be more
expensive
> than signal()ing a condvar, but maybe not?

The numbers are indeed surprising. A condvar should be a futex, which should
avoid syscalls when no contention (which I think should be the case at least for
1 thread).
What does perf say?

> 
> Same numbers for android (nexus 4 on L)
> 
> Posting to an I/O pump:
> 
> From 1 thread: 3.3359993333333335 us/task
> From 2 threads: 11.49977111111111 us/task
> From 4 threads: 26.96333625 us/task
> 
> Default pump:
> 
> From 1 thread: 4.1472261538461535 us/task
> From 2 threads: 13.33263375 us/task
> From 4 threads: 27.737905 us/task
> 
> On the N4 with 4 threads the thread time is significantly lower than the wall
> clock time, which makes sense since there aren't enough h/w threads around to
> service 4 posting threads and 1 target thread, so we're spending a lot of time
> descheduled.
> 
> Interestingly the I/O pump is faster than the default pump on android as well.

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

I'm also very surprised to see MessagePumpDefault performing more poorly.

https://codereview.chromium.org/551183002/diff/1/base/threading/thread_perfte...
File base/threading/thread_perftest.cc (right):

https://codereview.chromium.org/551183002/diff/1/base/threading/thread_perfte...
base/threading/thread_perftest.cc:304: void PostTasksToThread(MessageLoop::Type
target_type, int numPostingThreads) {
nit: numPostingThreads -> num_posting_threads

https://codereview.chromium.org/551183002/diff/1/base/threading/thread_perfte...
base/threading/thread_perftest.cc:316: posting_threads[i]->Start();
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?

[darin (slow to review), 2014-09-09 04:09:09]

On 2014/09/09 04:05:07, darin wrote:
> I'm also very surprised to see MessagePumpDefault performing more poorly.
> 
>
https://codereview.chromium.org/551183002/diff/1/base/threading/thread_perfte...
> File base/threading/thread_perftest.cc (right):
> 
>
https://codereview.chromium.org/551183002/diff/1/base/threading/thread_perfte...
> base/threading/thread_perftest.cc:304: void
PostTasksToThread(MessageLoop::Type
> target_type, int numPostingThreads) {
> nit: numPostingThreads -> num_posting_threads
> 
>
https://codereview.chromium.org/551183002/diff/1/base/threading/thread_perfte...
> base/threading/thread_perftest.cc:316: posting_threads[i]->Start();
> 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?

We should probably experiment with a POSIX-only implementation of
MessagePumpDefault that just uses a bool, cvar and mutex. I'm shocked to see how
complex WaitableEvent::Wait() is on POSIX. Maybe that is contributing to the
cost here.

-Darin

[epenner, 2014-09-09 04:40:16]

> > It's interesting to me that the default pump is actually the slowest in
terms
> of
> > cost to the posting thread.  I'd expect write()ing to an fd to be more
> expensive
> > than signal()ing a condvar, but maybe not?
> 
> The numbers are indeed surprising. A condvar should be a futex, which should
> avoid syscalls when no contention (which I think should be the case at least
for
> 1 thread).
> What does perf say?
> 

Hmm, however often the receiver is able to finish it's tasks, then the poster
will need to wake it up again (requiring the syscall). WaitableEvent does add a
few microseconds or so on Android (in the other tests in this file, so that
could also account for it).

Also, were the results above using thread time or clock time?

[jamesr, 2014-09-09 05:24:08]

On 2014/09/09 01:16:02, piman (Very slow to review) wrote:
> The numbers are indeed surprising. A condvar should be a futex, which should
> avoid syscalls when no contention (which I think should be the case at least
for
> 1 thread).
> What does perf say?

For posting to I/O from one thread the top symbols are:

Samples: 52K of event 'cycles', Event count (approx.): 41398048461              
                                                         
+  37.70%  base_perftests  [kernel.kallsyms]    [k] 0xffffffff8105266a
+   7.41%  base_perftests  base_perftests       [.]
base::subtle::RefCountedThreadSafeBase::AddRef() const
+   6.21%  base_perftests  [vdso]               [.] 0x00000000000009c5
+   6.16%  base_perftests  libc-2.15.so         [.] _int_free
+   5.13%  base_perftests  base_perftests       [.]
base::subtle::RefCountedThreadSafeBase::Release() const
+   4.93%  base_perftests  libc-2.15.so         [.] malloc
+   4.01%  base_perftests  libc-2.15.so         [.] _int_malloc
+   2.68%  base_perftests  libc-2.15.so         [.] malloc_consolidate.part.3
+   2.02%  base_perftests  base_perftests       [.] base::MessageLoop::DoWork()
+   1.58%  base_perftests  libpthread-2.15.so   [.] pthread_mutex_unlock
+   1.47%  base_perftests  libc-2.15.so         [.] 0x00000000000f49b3
+   1.45%  base_perftests  base_perftests       [.] event_base_loop
+   1.20%  base_perftests  base_perftests       [.]
tracked_objects::DeathData::RecordDeath(int, int, int)
+   1.18%  base_perftests  libc-2.15.so         [.] free
+   1.07%  base_perftests  libc-2.15.so         [.] __libc_disable_asynccancel
+   1.05%  base_perftests  libpthread-2.15.so   [.] pthread_mutex_lock
+   0.86%  base_perftests  libc-2.15.so         [.] __libc_enable_asynccancel
+   0.76%  base_perftests  base_perftests       [.]
tracked_objects::ThreadData::TallyADeath(tracked_objects::Births const&, int,
int)
+   0.75%  base_perftests  base_perftests       [.]
base::internal::IncomingTaskQueue::PostPendingTask(base::PendingTask*)
+   0.74%  base_perftests  base_perftests       [.]
base::debug::TaskAnnotator::RunTask(char const*, char const*, base::PendingTask
const&
+   0.66%  base_perftests  base_perftests       [.]
tracked_objects::ThreadData::Now()
+   0.60%  base_perftests  base_perftests       [.] base::internal::Invoker<1,
base::internal::BindState<base::internal::RunnableAdapter<v
+   0.58%  base_perftests  base_perftests       [.]
base::internal::CallbackBase::~CallbackBase()
+   0.56%  base_perftests  libc-2.15.so         [.] __lll_lock_wait_private
+   0.52%  base_perftests  base_perftests       [.]
tracked_objects::ThreadData::Get()

for posting to default:

+  18.66%  base_perftests  [kernel.kallsyms]    [k] 0xffffffff8105266a
+  14.23%  base_perftests  libc-2.15.so         [.] _int_free
+   9.34%  base_perftests  base_perftests       [.]
base::subtle::RefCountedThreadSafeBase::AddRef() const
+   9.34%  base_perftests  libc-2.15.so         [.] malloc
+   7.94%  base_perftests  base_perftests       [.]
base::subtle::RefCountedThreadSafeBase::Release() const
+   6.11%  base_perftests  libc-2.15.so         [.] _int_malloc
+   5.58%  base_perftests  libpthread-2.15.so   [.] pthread_mutex_unlock
+   4.47%  base_perftests  libpthread-2.15.so   [.] pthread_mutex_lock
+   2.31%  base_perftests  base_perftests       [.]
tracked_objects::ThreadData::TallyADeath(tracked_objects::Births const&, int,
int)
+   2.24%  base_perftests  libc-2.15.so         [.] free
+   2.23%  base_perftests  [vdso]               [.] 0x0000000000000988
+   1.50%  base_perftests  base_perftests       [.] base::MessageLoop::DoWork()
+   1.12%  base_perftests  base_perftests       [.]
tracked_objects::DeathData::RecordDeath(int, int, int)
+   1.03%  base_perftests  base_perftests       [.] base::internal::Invoker<1,
base::internal::BindState<base::internal::RunnableAdapter<v
+   1.00%  base_perftests  libpthread-2.15.so   [.] __lll_lock_wait
+   0.90%  base_perftests  libc-2.15.so         [.] __lll_lock_wait_private
+   0.89%  base_perftests  base_perftests       [.]
base::internal::IncomingTaskQueue::PostPendingTask(base::PendingTask*)
+   0.68%  base_perftests  base_perftests       [.]
base::debug::TaskAnnotator::RunTask(char const*, char const*, base::PendingTask
const&
+   0.59%  base_perftests  base_perftests       [.]
base::internal::CallbackBase::~CallbackBase()
+   0.55%  base_perftests  base_perftests       [.]
base::internal::IncomingTaskQueue::AddToIncomingQueue(tracked_objects::Location
const&
+   0.52%  base_perftests  base_perftests       [.]
tracked_objects::ThreadData::Get()
+   0.49%  base_perftests  base_perftests       [.]
tracked_objects::ThreadData::TallyABirth(tracked_objects::Location const&)

the very high prevalence of threadsafe refcount operations are mostly due to the
fact that we copy scoped_refptr<>s to bindstate a lot.  The fact that
tracked_objects shows up so highly in these is a bit alarming as well.  There's
also a lot that should be inlined here.

It's hard to tell from this where exactly the extra time is going, but
waitable_event on posix does a crapload more work than we need here.

[darin (slow to review), 2014-09-09 05:39:30]

Is it possible that AddRef and Release are happening while locks are held? Maybe
we could avoid that and see if it helps? Ditto for malloc and free. Maybe we are
seeing increased lock contention due to doing too much work under the incoming
queue lock.

[jamesr, 2014-09-09 06:15:56]

On 2014/09/09 04:09:09, darin wrote:
> We should probably experiment with a POSIX-only implementation of
> MessagePumpDefault that just uses a bool, cvar and mutex. I'm shocked to see
how
> complex WaitableEvent::Wait() is on POSIX. Maybe that is contributing to the
> cost here.
> 
> -Darin

Oddly even with this the MPDefault is 1/3 slower for both wall clock and thread
time: https://codereview.chromium.org/558553002/.

[darin (slow to review), 2014-09-09 06:21:41]

On 2014/09/09 06:15:56, jamesr wrote:
> On 2014/09/09 04:09:09, darin wrote:
> > We should probably experiment with a POSIX-only implementation of
> > MessagePumpDefault that just uses a bool, cvar and mutex. I'm shocked to see
> how
> > complex WaitableEvent::Wait() is on POSIX. Maybe that is contributing to the
> > cost here.
> > 
> > -Darin
> 
> Oddly even with this the MPDefault is 1/3 slower for both wall clock and
thread
> time: https://codereview.chromium.org/558553002/.

Fascinating!

[jamesr, 2014-09-18 01:22:24]

PS3 has separate benchmarks for the act of calling ScheduleWork() on a
particular pump type and the act of making a task, sticking it in a
base::internal::IncomingTaskQueue, reloading it into a thread-local queue, and
tossing items from it.  The second part runs single-threaded which doesn't show
all of the performance characteristics of the real system but is a lot easier to
reason about and shows some of the issues (for instance, on desktop
RefCountedThreadSafe dominates. On android the perf data is inconclusive).

This also adds a microbenchmark for java threads, which required adding some
code to JavaHandlerThread to make it possible to shut one down so I could have
multiple tests.  The numbers for it are pretty astounding.  Compare the
one-thread-signalling times for an I/O pump:

*RESULT task: 1_threads_scheduling_to_io_pump= 3.99726618705036 us/task
*RESULT task_thread_time: 1_threads_scheduling_to_io_pump= 3.9968025579536373
us/task

vs MessagePumpDefault:

*RESULT task: 1_threads_scheduling_to_default_pump= .9290340022296544 us/task
*RESULT task_thread_time: 1_threads_scheduling_to_default_pump=
.9272081010776663 us/task

vs a java pump:

*RESULT task: 1_threads_scheduling_to_default_pump= 121.22974418604652 us/task
*RESULT task_thread_time: 1_threads_scheduling_to_default_pump=
96.36986046511628 us/task

with 4 threads posting, the numbers are even worse

I/O:

*RESULT task: 4_threads_scheduling_to_io_pump= 3.5642128607053793 us/task
*RESULT task_thread_time: 4_threads_scheduling_to_io_pump= 2.70108015675098
us/task

MessagePumpDefault:

*RESULT task: 4_threads_scheduling_to_default_pump= 7.039696095673584 us/task
*RESULT task_thread_time: 4_threads_scheduling_to_default_pump=
4.4329145269081955 us/task

Java:

*RESULT task: 4_threads_scheduling_to_default_pump= 1740.3784375 us/task
*RESULT task_thread_time: 4_threads_scheduling_to_default_pump= 505.507 us/task

That's an *average* of 1.7 milliseconds *per task* and with the java pump we
always signal on every task.  profiling data leads me to believe this time is
mostly spent making the JNI call, allocating objects in the java heap (and thus
doing GCs) and doing synchronization inside the java world to handle the
runner's queue.

Hopefully the cost of signalling is much lower when we aren't getting the queue
size really big by posting quickly, but this is pretty alarming and needs some
more investigation.  First thing to try is to write another version of this
benchmark that runs the benchmark loop in java code to separate the JNI overhead
from actual logic.

[Sami, 2014-09-18 16:19:36]

Interesting. The cost in Java comes from the call to
Java_SystemMessageHandler_scheduleWork, right? I'm not sure why we need to spin
the native message loop once for every task we post.

[jamesr, 2014-09-27 01:09:05]

This is proving useful enough that I'd like to land it and start tracking
results on the bots for future improvements.  Could you take a look for review,
Darin?

[darin (slow to review), 2014-09-28 03:42:20]

LGTM

https://codereview.chromium.org/551183002/diff/80001/base/message_loop/messag...
File base/message_loop/message_loop.cc (right):

https://codereview.chromium.org/551183002/diff/80001/base/message_loop/messag...
base/message_loop/message_loop.cc:11: #include "base/format_macros.h"
nit: is this needed?

https://codereview.chromium.org/551183002/diff/80001/base/threading/thread_pe...
File base/threading/thread_perftest.cc (right):

https://codereview.chromium.org/551183002/diff/80001/base/threading/thread_pe...
base/threading/thread_perftest.cc:8: #include "base/format_macros.h"
nit: are these includes needed?

[jamesr, 2014-09-29 19:40:33]

The CQ bit was checked by jamesr@chromium.org

[jamesr, 2014-09-29 19:40:36]

On 2014/09/28 03:42:20, darin wrote:
>
https://codereview.chromium.org/551183002/diff/80001/base/message_loop/messag...
> File base/message_loop/message_loop.cc (right):
> 
>
https://codereview.chromium.org/551183002/diff/80001/base/message_loop/messag...
> base/message_loop/message_loop.cc:11: #include "base/format_macros.h"
> nit: is this needed?
> 
>
https://codereview.chromium.org/551183002/diff/80001/base/threading/thread_pe...
> File base/threading/thread_perftest.cc (right):
> 
>
https://codereview.chromium.org/551183002/diff/80001/base/threading/thread_pe...
> base/threading/thread_perftest.cc:8: #include "base/format_macros.h"
> nit: are these includes needed?

Nope, they were just for local debugging. Thanks!

[commit-bot: I haz the power, 2014-09-29 19:41:33]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/551183002/100001

[commit-bot: I haz the power, 2014-09-29 21:13:34]

Committed patchset #6 (id:100001) as 03c33a488b5c38ee08fe7c8050736c05cf770f2a

[commit-bot: I haz the power, 2014-09-29 21:15:54]

Patchset 6 (id:??) landed as
https://crrev.com/2e146d74f78041f91bd43562bd1a0210374a41eb
Cr-Commit-Position: refs/heads/master@{#297264}