buffer: ~2x slowdown in master compared to v12.x

[mscdex]

• Version: master
• Platform: Linux foo 5.0.0-36-generic #39~18.04.1-Ubuntu SMP Tue Nov 12 11:09:50 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: buffer

I was running some benchmarks (for private code) and noticed a significant slowdown with some Buffer methods. Here is a comparison of the C++ portion of --prof between v12.16.1 and master:

v12.16.1:

Details

 [C++]:
   ticks  total  nonlib   name
     66    4.2%    8.4%  void node::Buffer::(anonymous namespace)::StringSlice<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&)
     54    3.4%    6.9%  __libc_read
     48    3.0%    6.1%  node::Buffer::(anonymous namespace)::ParseArrayIndex(node::Environment*, v8::Local<v8::Value>, unsigned long, unsigned long*)
     35    2.2%    4.5%  v8::ArrayBuffer::GetContents()
     35    2.2%    4.5%  epoll_pwait
     27    1.7%    3.4%  v8::internal::Builtin_TypedArrayPrototypeBuffer(int, unsigned long*, v8::internal::Isolate*)
     26    1.6%    3.3%  v8::String::NewFromUtf8(v8::Isolate*, char const*, v8::NewStringType, int)
     24    1.5%    3.1%  node::native_module::NativeModuleEnv::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
     22    1.4%    2.8%  __pthread_cond_signal
     20    1.3%    2.5%  node::StringBytes::Encode(v8::Isolate*, char const*, unsigned long, node::encoding, v8::Local<v8::Value>*)
     16    1.0%    2.0%  v8::Value::IsArrayBufferView() const
     14    0.9%    1.8%  v8::ArrayBufferView::Buffer()
      9    0.6%    1.1%  v8::internal::FixedArray::set(int, v8::internal::Object)
      8    0.5%    1.0%  v8::ArrayBufferView::ByteLength()
      7    0.4%    0.9%  v8::Value::IntegerValue(v8::Local<v8::Context>) const
      6    0.4%    0.8%  v8::ArrayBufferView::ByteOffset()
      5    0.3%    0.6%  __libc_malloc
      4    0.3%    0.5%  write
      4    0.3%    0.5%  v8::internal::libc_memmove(void*, void const*, unsigned long)
      4    0.3%    0.5%  node::binding::GetInternalBinding(v8::FunctionCallbackInfo<v8::Value> const&)
      3    0.2%    0.4%  v8::internal::libc_memset(void*, int, unsigned long)
      3    0.2%    0.4%  __lll_unlock_wake
      2    0.1%    0.3%  void node::StreamBase::JSMethod<&node::StreamBase::WriteBuffer>(v8::FunctionCallbackInfo<v8::Value> const&)
      2    0.1%    0.3%  fwrite
      2    0.1%    0.3%  do_futex_wait.constprop.1
      2    0.1%    0.3%  __clock_gettime
      2    0.1%    0.3%  __GI___pthread_mutex_unlock
      1    0.1%    0.1%  void node::StreamBase::JSMethod<&(int node::StreamBase::WriteString<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&))>(v8::FunctionCallbackInfo<v8::Value> const&)
      1    0.1%    0.1%  v8::internal::Scope::DeserializeScopeChain(v8::internal::Isolate*, v8::internal::Zone*, v8::internal::ScopeInfo, v8::internal::DeclarationScope*, v8::internal::AstValueFactory*, v8::internal::Scope::DeserializationMode)
      1    0.1%    0.1%  v8::internal::RuntimeCallTimerScope::RuntimeCallTimerScope(v8::internal::Isolate*, v8::internal::RuntimeCallCounterId)
      1    0.1%    0.1%  v8::EscapableHandleScope::Escape(unsigned long*)
      1    0.1%    0.1%  std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_int<long>(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, long) const
      1    0.1%    0.1%  std::ostream::sentry::sentry(std::ostream&)
      1    0.1%    0.1%  std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long)
      1    0.1%    0.1%  std::__detail::_Prime_rehash_policy::_M_need_rehash(unsigned long, unsigned long, unsigned long) const
      1    0.1%    0.1%  non-virtual thunk to node::LibuvStreamWrap::GetAsyncWrap()
      1    0.1%    0.1%  node::LibuvStreamWrap::ReadStart()::{lambda(uv_stream_s*, long, uv_buf_t const*)#2}::_FUN(uv_stream_s*, long, uv_buf_t const*)
      1    0.1%    0.1%  node::CustomBufferJSListener::OnStreamRead(long, uv_buf_t const&)
      1    0.1%    0.1%  node::AsyncWrap::EmitTraceEventBefore()
      1    0.1%    0.1%  mprotect
      1    0.1%    0.1%  getpid
      1    0.1%    0.1%  cfree
      1    0.1%    0.1%  __lll_lock_wait

master:

Details

 [C++]:
   ticks  total  nonlib   name
    155    6.5%   14.0%  std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release()
     88    3.7%    7.9%  __GI___pthread_mutex_lock
     87    3.7%    7.8%  v8::ArrayBuffer::GetBackingStore()
     71    3.0%    6.4%  __GI___pthread_mutex_unlock
     54    2.3%    4.9%  void node::Buffer::(anonymous namespace)::StringSlice<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&)
     36    1.5%    3.2%  node::Buffer::(anonymous namespace)::ParseArrayIndex(node::Environment*, v8::Local<v8::Value>, unsigned long, unsigned long*)
     32    1.4%    2.9%  v8::internal::Builtin_TypedArrayPrototypeBuffer(int, unsigned long*, v8::internal::Isolate*)
     31    1.3%    2.8%  v8::Value::IntegerValue(v8::Local<v8::Context>) const
     27    1.1%    2.4%  node::native_module::NativeModuleEnv::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
     27    1.1%    2.4%  epoll_pwait
     26    1.1%    2.3%  v8::String::NewFromUtf8(v8::Isolate*, char const*, v8::NewStringType, int)
     20    0.8%    1.8%  v8::Value::IsArrayBufferView() const
     20    0.8%    1.8%  __libc_read
     19    0.8%    1.7%  __pthread_cond_signal
     16    0.7%    1.4%  node::StringBytes::Encode(v8::Isolate*, char const*, unsigned long, node::encoding, v8::Local<v8::Value>*)
     13    0.5%    1.2%  v8::ArrayBufferView::Buffer()
     10    0.4%    0.9%  v8::internal::FixedArray::set(int, v8::internal::Object)
      6    0.3%    0.5%  v8::internal::libc_memset(void*, int, unsigned long)
      6    0.3%    0.5%  v8::internal::RuntimeCallTimerScope::RuntimeCallTimerScope(v8::internal::Isolate*, v8::internal::RuntimeCallCounterId)
      5    0.2%    0.5%  v8::internal::libc_memmove(void*, void const*, unsigned long)
      5    0.2%    0.5%  v8::ArrayBufferView::ByteLength()
      4    0.2%    0.4%  write
      4    0.2%    0.4%  void node::StreamBase::JSMethod<&node::StreamBase::WriteBuffer>(v8::FunctionCallbackInfo<v8::Value> const&)
      4    0.2%    0.4%  do_futex_wait.constprop.1
      4    0.2%    0.4%  __lll_lock_wait
      3    0.1%    0.3%  node::binding::GetInternalBinding(v8::FunctionCallbackInfo<v8::Value> const&)
      3    0.1%    0.3%  _init
      2    0.1%    0.2%  v8::BackingStore::Data() const
      2    0.1%    0.2%  fwrite
      2    0.1%    0.2%  cfree
      2    0.1%    0.2%  __lll_unlock_wake
      2    0.1%    0.2%  __libc_malloc
      1    0.0%    0.1%  v8::internal::DeclarationScope::DeclareDefaultFunctionVariables(v8::internal::AstValueFactory*)
      1    0.0%    0.1%  v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*)
      1    0.0%    0.1%  v8::internal::AstValueFactory::GetOneByteStringInternal(v8::internal::Vector<unsigned char const>)
      1    0.0%    0.1%  std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::do_put(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, long) const
      1    0.0%    0.1%  operator new[](unsigned long)
      1    0.0%    0.1%  node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
      1    0.0%    0.1%  node::TCPWrap::Connect(v8::FunctionCallbackInfo<v8::Value> const&)
      1    0.0%    0.1%  node::Environment::RunAndClearNativeImmediates(bool)
      1    0.0%    0.1%  node::AsyncWrap::EmitTraceEventBefore()
      1    0.0%    0.1%  mprotect
      1    0.0%    0.1%  __pthread_cond_timedwait
      1    0.0%    0.1%  __fxstat
      1    0.0%    0.1%  __GI___pthread_getspecific

As you will see, master has these additional items at the top of the list:

    155    6.5%   14.0%  std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release()
     88    3.7%    7.9%  __GI___pthread_mutex_lock
     87    3.7%    7.8%  v8::ArrayBuffer::GetBackingStore()
     71    3.0%    6.4%  __GI___pthread_mutex_unlock

Is there some way we can avoid this slowdown?

[addaleax]

@mscdex Can you provide the output uname -a (what the issue template asks for for Platform:)? Is this on arm/arm64/x86/x64/something else? That’s probably relevant here.

[mscdex]

Added.

[mscdex]

Additionally, I'm using gcc 7.4.0 to compile if that matters.

[mmarchini]

Can you try #32116? If this is some regression on V8, it might already be fixed (or it might be worse on 8.1, but let's hope not).

[addaleax]

The prof output makes it seem like the reason is that std::shared_ptr as we compile it on x64 seems to not use atomic instructions, but rather mutexes. I don’t quite know why it does that, but it’s probably something that can be addressed by passing compile flags. (That might be ABI-breaking but we could do it for v14.x, see #30786 for a related ARM issue.)

Or it’s unrelated to that, but that’s not what the prof output says.

[mscdex]

@mmarchini The V8 8.1 branch has the same performance as master.

[addaleax]

(__gnu_cxx::_Lock_policy)2 is _S_atomic, though, so … not quite sure that that’s actually responsible for the mutex lock/unlock calls.

[mscdex]

I've also now tried:

• Compiling v12.16.1 locally (was using the binary from the website before)

• Compiling master with gcc 9.2.1

• Compiling master with -march=native

• Removing calls to GetBackingStore() where possible

• Reverting to GetContents() in places

All changes made little to no difference.

[mmarchini]

@mscdex do you see similar results with any of the benchmarks from benchmark/buffers? Maybe some benchmark similar to your private code?

[mscdex]

@mmarchini Yes, for example:

                                                                       confidence improvement accuracy (*)   (**)  (***)
 buffers/buffer-tostring.js n=1000000 len=1024 args=0 encoding='utf8'        ***    -31.66 %       ±0.42% ±0.55% ±0.72%

[mscdex]

The --prof-process output for that buffer-tostring benchmark shows basically the same top results as I showed originally.

[puzpuzpuz]

If that helps, I can also see the same performance degradation on 4.15.0-88-generic #88-Ubuntu SMP Tue Feb 11 20:11:34 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux, gcc 7.5.0:

$ node benchmark/compare.js --old ../node-v12.x/node --new ./node --filter buffer-tostring --runs 10 --set len=1024 --set encoding=utf8 buffers | Rscript benchmark/compare.R
[00:00:25|% 100| 1/1 files | 20/20 runs | 3/3 configs]: Done
                                                                       confidence improvement accuracy (*)   (**)  (***)
 buffers/buffer-tostring.js n=1000000 len=1024 args=0 encoding='utf8'        ***    -34.37 %       ±1.24% ±1.70% ±2.32%
 buffers/buffer-tostring.js n=1000000 len=1024 args=1 encoding='utf8'        ***    -31.29 %       ±0.59% ±0.82% ±1.12%
 buffers/buffer-tostring.js n=1000000 len=1024 args=3 encoding='utf8'        ***    -32.47 %       ±0.98% ±1.34% ±1.83%