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 ?? ()