[Boost-users] [ASIO] "perf" shows overhead of function calls is very high

Subject: [Boost-users] [ASIO] "perf" shows overhead of function calls is very high
From: Junchang Wang (junchangwang_at_[hidden])
Date: 2012-11-15 17:10:44

Hi list,

I'm new to Boost.asio and am solving scaling problems of a Openflow (TCP
based) server.

We are using one single io_service for packets receiving and transmitting.
A thread pool calling io_service::run() processes HTTP requests. A
multi-core server is used. I found we can't get benefits from increasing
the size of thread pool when it's size is larger than 6. In other words the
system doesn't scale any more on more than 6 cores. I checked the program
carefully and can make sure there's no lock contention.

I profile the program with Linux perf, and it turns out up to 36% of CPU
time is wasted in function calls.
36.39%
         :        0000000000103300
<boost::detail::function::void_function_obj_invoker3<vigil::openflow::v1::construct_and_load<vigil::openflow::v1::ofp_packet_out,
vigil::
         :                BOOST_FUNCTION_TEMPLATE_PARMS
         :              >
         :              struct BOOST_FUNCTION_VOID_FUNCTION_OBJ_INVOKER
         :              {
         :                static BOOST_FUNCTION_VOID_RETURN_TYPE
         :                invoke(function_buffer& function_obj_ptr
BOOST_FUNCTION_COMMA
    0.02 :          103300:       push   %rbp
   99.66 :          103301:       mov    %rsp,%rbp
    0.00 :          103304:       push   %r12
    0.04 :          103306:       mov    %rcx,%r12

I printed out the call stack (attached at the tail of this email). It seems
for a single packet processing there are more than 30 function calls within
Boost. Can that explain why the CPU time on function calls is so high? Are
there some ways to avoid this kind of cost?

Thanks a lot.

--Junchang

================

#0  vigil::openflow::Openflow_datapath::send (this=<optimized out>,
msg=0x7ffff567f920) at
../../../../src/coreapps/openflow/openflow-datapath.cc:199
#1  0x00007ffff4c50724 in
vigil::openflow::Openflow_datapath::handle_handshake (this=0x7ffff007dd80,
e=...) at ../../../../src/coreapps/openflow/openflow-datapath.cc:305
#2  0x00007ffff4c5086a in
vigil::openflow::Openflow_datapath::handle_message (this=0x7ffff007dd80,
msg=0x7ffff567f920)
    at ../../../../src/coreapps/openflow/openflow-datapath.cc:228
#3  0x00007ffff4c50a39 in vigil::openflow::Openflow_datapath::recv_cb
(this=0x7ffff007dd80, bytes_transferred=<optimized out>)
    at ../../../../src/coreapps/openflow/openflow-datapath.cc:164
#4  0x00007ffff7bad130 in operator() (a0=<optimized out>,
this=0x7ffff007d4b8) at
/usr/include/boost/function/function_template.hpp:1013
#5
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp,
boost::asio::stream_socket_service<boost::asio::ip::tcp> > >::handle_recv (
    this=0x7ffff007d480, ec=..., bytes_transferred=<optimized out>) at
../../../src/lib/connection.cc:185
#6  0x00007ffff7bb5fba in
call<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> >, boost::system::error_code const, unsigned long const>
(b2=@0x7ffff568fa10: 8, b1=..., u=..., this=0x7ffff568f9e0) at
/usr/include/boost/bind/mem_fn_template.hpp:271
#7
operator()<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > > (u=..., this=0x7ffff568f9e0, a2=@0x7ffff568fa10: 8,
    a1=...) at /usr/include/boost/bind/mem_fn_template.hpp:286
#8  operator()<boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, const boost::system::error_code&, const long unsigned int&>,
boost::_bi::list2<const boost::system::error_code&, const long unsigned
int&> > (a=<synthetic pointer>, f=..., this=0x7ffff568f9f0)
    at /usr/include/boost/bind/bind.hpp:392
#9  operator()<boost::system::error_code, long unsigned int>
(a2=@0x7ffff568fa10: 8, a1=..., this=0x7ffff568f9e0) at
/usr/include/boost/bind/bind_template.hpp:102
#10 operator() (this=0x7ffff568f9e0) at
/usr/include/boost/asio/detail/bind_handler.hpp:97
#11
asio_handler_invoke<boost::asio::detail::binder2<boost::_bi::bind_t<void,
boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> >,
boost::system::error_code, unsigned long> > (
    function=<error reading variable: access outside bounds of object
referenced via synthetic pointer>) at
/usr/include/boost/asio/handler_invoke_hook.hpp:64
#12
boost_asio_handler_invoke_helpers::invoke<boost::asio::detail::binder2<boost::_bi::bind_t<void,
boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> >,
boost::system::error_code, unsigned long>, boost::_bi::bind_t<void,
boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> > > (function=...,
context=...) at /usr/include/boost/asio/detail/handler_invoke_helpers.hpp:39
#13 0x00007ffff7bb637b in
asio_handler_invoke<boost::asio::detail::binder2<boost::_bi::bind_t<void,
boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> >,
boost::system::error_code, unsigned long>, boost::_bi::bind_t<void,
boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> >,
boost::system::error_code, unsigned long> (this_handler=0x7ffff568fbf0,
function=...) at /usr/include/boost/asio/detail/bind_handler.hpp:132
#14 invoke<boost::asio::detail::binder2<boost::_bi::bind_t<void,
boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> >,
boost::system::error_code, unsigned long>,
boost::asio::detail::binder2<boost::_bi::bind_t<void,
boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> >,
boost::system::error_code, unsigned long> > (context=..., function=...) at
/usr/include/boost/asio/detail/handler_invoke_helpers.hpp:39
#15
boost::asio::detail::strand_service::dispatch<boost::asio::detail::binder2<boost::_bi::bind_t<void,
boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp,
boost::asio::stream_socket_service<boost::asio::ip::tcp> > >,
boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp,
boost::asio::stream_socket_service<boost::asio::ip::tcp> > > > >,
boost::arg<1> (*)(), boost::arg<2> (*)()> >, boost::system::error_code,
unsigned long> > (this=0x7ffff0001560, impl=@0x7ffff568fbb0:
0x7ffff0047d80, handler=...)
    at /usr/include/boost/asio/detail/impl/strand_service.hpp:97
#16 0x00007ffff7bb66fa in
dispatch<boost::asio::detail::binder2<boost::_bi::bind_t<void,
boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> >,
boost::system::error_code, unsigned long> > (
    handler=<error reading variable: access outside bounds of object
referenced via synthetic pointer>, this=0x7ffff568fba8) at
/usr/include/boost/asio/strand.hpp:159
#17 operator()<boost::system::error_code, long unsigned int>
(arg2=<synthetic pointer>, arg1=..., this=0x7ffff568fba8)
    at /usr/include/boost/asio/detail/wrapped_handler.hpp:65
#18 operator()<boost::system::error_code, long unsigned int>
(arg2=<optimized out>, arg1=..., this=0x7ffff568fba0) at
../../../src/lib/connection.cc:64
#19 operator() (this=0x7ffff568fba0) at
/usr/include/boost/asio/detail/bind_handler.hpp:97
#20
asio_handler_invoke<boost::asio::detail::binder2<vigil::custom_alloc_handler<boost::asio::detail::wrapped_handler<boost::asio::io_service::strand,
boost::_bi::bind_t<void, boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> > > >,
boost::system::error_code, unsigned long> > (function=<error reading
variable: access outside bounds of object referenced via synthetic pointer>)
    at /usr/include/boost/asio/handler_invoke_hook.hpp:64
#21
invoke<boost::asio::detail::binder2<vigil::custom_alloc_handler<boost::asio::detail::wrapped_handler<boost::asio::io_service::strand,
boost::_bi::bind_t<void, boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> > > >,
boost::system::error_code, unsigned long>,
vigil::custom_alloc_handler<boost::asio::detail::wrapped_handler<boost::asio::io_service::strand,
boost::_bi::bind_t<void, boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
>, boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp>
> > >, boost::arg<1> (*)(), boost::arg<2> (*)()> > > > > (function=...,
context=...) at /usr/include/boost/asio/detail/handler_invoke_helpers.hpp:39
#22
boost::asio::detail::reactive_socket_recv_op<boost::asio::mutable_buffers_1,
vigil::custom_alloc_handler<boost::asio::detail::wrapped_handler<boost::asio::io_service::strand,
boost::_bi::bind_t<void, boost::_mfi::mf2<void,
vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp,
boost::asio::stream_socket_service<boost::asio::ip::tcp> > >,
boost::system::error_code const&, unsigned long const&>,
boost::_bi::list3<boost::_bi::value<boost::shared_ptr<vigil::Stream_connection<boost::asio::basic_stream_socket<boost::asio::ip::tcp,
boost::asio::stream_socket_service<boost::asio::ip::tcp> > > > >,
boost::arg<1> (*)(), boost::arg<2> (*)()> > > > >::do_complete
(owner=0x6d6b30, base=<optimized out>) at
/usr/include/boost/asio/detail/reactive_socket_recv_op.hpp:106
#23 0x0000000000487343 in complete (owner=..., this=0x7ffff007d510) at
/usr/include/boost/asio/detail/task_io_service_operation.hpp:35
#24 boost::asio::detail::task_io_service::do_one (this=0x6d6b30, lock=...,
this_idle_thread=0x7ffff568fdd0) at
/usr/include/boost/asio/detail/impl/task_io_service.ipp:278
#25 0x00000000004874b0 in boost::asio::detail::task_io_service::run
(this=0x6d6b30, ec=...) at
/usr/include/boost/asio/detail/impl/task_io_service.ipp:130
#26 0x00000000004875c9 in boost::asio::io_service::run (this=0x6d68f8) at
/usr/include/boost/asio/impl/io_service.ipp:57
#27 0x00007ffff7971ce9 in thread_proxy () from
/usr/lib/libboost_thread.so.1.46.1
#28 0x00007ffff5f2ee9a in start_thread () from
/lib/x86_64-linux-gnu/libpthread.so.0
#29 0x00007ffff6237cbd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#30 0x0000000000000000 in ?? ()