[ https://issues.apache.org/jira/browse/IMPALA-6359?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Michael Ho resolved IMPALA-6359. -------------------------------- Resolution: Duplicate Fix Version/s: Not Applicable The mitigation is being tracked in IMPALA-5518. > Blocking in Service threads due to tcmalloc contention due to memory > allocations for RowBatch::Deserialize > ---------------------------------------------------------------------------------------------------------- > > Key: IMPALA-6359 > URL: https://issues.apache.org/jira/browse/IMPALA-6359 > Project: IMPALA > Issue Type: Sub-task > Components: Distributed Exec > Reporter: Mostafa Mokhtar > Assignee: Michael Ho > Priority: Critical > Fix For: Not Applicable > > > This is a regression compared to thrift with KRPC is enabled. > Results are based on running 48 concurrent TPCDS queries on a 40 node > cluster, regression is in the order of 2-4x (Will update the JIRA with a more > accurate number soon). > Service threads stall on memory allocation in the stack below, looking at the > Service threads memory allocation/deallocation I believe they won't benefit > much from the per thread cache as there is more allocations than > deallocations on this threads as a result they go to the CentralFreeList for > most allocations. > {code} > #0 0x00000000020931e7 in base::internal::SpinLockDelay(int volatile*, int, > int) () > #1 0x00000000020dde29 in SpinLock::SlowLock() () > #2 0x0000000002121668 in tcmalloc::CentralFreeList::Populate() () > #3 0x0000000002121768 in > tcmalloc::CentralFreeList::FetchFromOneSpansSafe(int, void**, void**) () > #4 0x00000000021217f4 in tcmalloc::CentralFreeList::RemoveRange(void**, > void**, int) () > #5 0x000000000212ef53 in > tcmalloc::ThreadCache::FetchFromCentralCache(unsigned long, unsigned long) () > #6 0x00000000021d37fb in tc_malloc () > #7 0x0000000000b27c3a in impala::MemPool::FindChunk(long, bool) () > #8 0x0000000000b354e6 in impala::MemPool::Allocate(long) () > #9 0x0000000000b34409 in impala::RowBatch::Deserialize(kudu::Slice const&, > kudu::Slice const&, long, bool) () > #10 0x0000000000b347fb in impala::RowBatch::RowBatch(impala::RowDescriptor > const*, impala::RowBatchHeaderPB const&, kudu::Slice const&, kudu::Slice > const&, impala::MemTracker*) () > #11 0x0000000000b15d68 in > impala::KrpcDataStreamRecvr::SenderQueue::AddBatchWork(long, > impala::RowBatchHeaderPB const&, kudu::Slice const&, kudu::Slice const&, > boost::unique_lock<impala::SpinLock>*) () > #12 0x0000000000b18715 in > impala::KrpcDataStreamRecvr::SenderQueue::AddBatch(impala::TransmitDataRequestPB > const*, kudu::rpc::RpcContext*) () > #13 0x0000000000b0e750 in > impala::KrpcDataStreamMgr::AddData(impala::TransmitDataRequestPB const*, > kudu::rpc::RpcContext*) () > #14 0x0000000001183305 in > kudu::rpc::GeneratedServiceIf::Handle(kudu::rpc::InboundCall*) () > #15 0x00000000011bad7d in impala::ImpalaServicePool::RunThread() () > #16 0x0000000000d18a73 in > impala::Thread::SuperviseThread(std::basic_string<char, > std::char_traits<char>, std::allocator<char> > const&, > std::basic_string<char, std::char_traits<char>, std::allocator<char> > > const&, boost::function<void ()()>, impala::Promise<long>*) () > {code} > I added logging to track allocations that take a long time and found that in > the extreme case some allocations take up to 10 seconds when allocating 16KB > of memory. > {code} > MonotonicStopWatch timer; > timer.Start(); > SCOPED_TIMER(recvr_->deserialize_row_batch_timer_); > // At this point, the row batch will be inserted into batch_queue_. > Close() will > // handle deleting any unconsumed batches from batch_queue_. Close() > cannot proceed > // until there are no pending insertion to batch_queue_. > batch.reset(new RowBatch(recvr_->row_desc(), header, tuple_offsets, > tuple_data, > recvr_->mem_tracker())); > timer.Stop(); > if (timer.ElapsedTime() > 1000000) { > LOG(INFO) << "TTT RowBatch allocation size:" << > header.uncompressed_size() << " allocation time " << timer.ElapsedTime(); > } > {code} > Call stacks from other threads that release RowBatch memory which also are > affected by the tcmalloc contention > {code} > #0 0x000000000212c1f4 in tcmalloc::PageHeap::MayMergeSpans(tcmalloc::Span*, > tcmalloc::Span*) () > #1 0x000000000212c54d in > tcmalloc::PageHeap::MergeIntoFreeList(tcmalloc::Span*) () > #2 0x000000000212c874 in tcmalloc::PageHeap::Delete(tcmalloc::Span*) () > #3 0x0000000002121090 in tcmalloc::CentralFreeList::ReleaseToSpans(void*) () > #4 0x000000000212111b in > tcmalloc::CentralFreeList::ReleaseListToSpans(void*) () > #5 0x000000000212138c in tcmalloc::CentralFreeList::InsertRange(void*, > void*, int) () > #6 0x000000000212f0f4 in > tcmalloc::ThreadCache::ReleaseToCentralCache(tcmalloc::ThreadCache::FreeList*, > unsigned long, int) () > #7 0x000000000212f1bc in > tcmalloc::ThreadCache::ListTooLong(tcmalloc::ThreadCache::FreeList*, unsigned > long) () > #8 0x00000000021d3d10 in tc_free () > #9 0x0000000000b26af8 in impala::MemPool::FreeAll() () > #10 0x0000000000b339b1 in impala::RowBatch::Reset() () > #11 0x0000000000fea7b1 in > impala::PartitionedAggregationNode::Open(impala::RuntimeState*) () > #12 0x0000000000b77dfd in impala::FragmentInstanceState::Open() () > #13 0x0000000000b7943b in impala::FragmentInstanceState::Exec() () > #14 0x0000000000b68a0a in > impala::QueryState::ExecFInstance(impala::FragmentInstanceState*) () > {code} > {code} > Thread 682 (Thread 0x7f61ebec4700 (LWP 28762)): > #0 0x00000000020931e7 in base::internal::SpinLockDelay(int volatile*, int, > int) () > #1 0x00000000020dde29 in SpinLock::SlowLock() () > #2 0x000000000212140f in tcmalloc::CentralFreeList::InsertRange(void*, > void*, int) () > #3 0x000000000212f0f4 in > tcmalloc::ThreadCache::ReleaseToCentralCache(tcmalloc::ThreadCache::FreeList*, > unsigned long, int) () > #4 0x000000000212f1bc in > tcmalloc::ThreadCache::ListTooLong(tcmalloc::ThreadCache::FreeList*, unsigned > long) () > #5 0x00000000021d3d10 in tc_free () > #6 0x0000000000b338b1 in impala::RowBatch::~RowBatch() () > #7 0x0000000000d8d1e3 in > impala::HdfsScanNode::GetNextInternal(impala::RuntimeState*, > impala::RowBatch*, bool*) () > #8 0x0000000000d8ebf2 in > impala::HdfsScanNode::GetNext(impala::RuntimeState*, impala::RowBatch*, > bool*) () > #9 0x0000000000fee76e in > impala::PartitionedHashJoinNode::NextProbeRowBatch(impala::RuntimeState*, > impala::RowBatch*) () > #10 0x0000000000ff43b1 in > impala::PartitionedHashJoinNode::GetNext(impala::RuntimeState*, > impala::RowBatch*, bool*) () > #11 0x0000000000fee76e in > impala::PartitionedHashJoinNode::NextProbeRowBatch(impala::RuntimeState*, > impala::RowBatch*) () > #12 0x0000000000ff43b1 in > impala::PartitionedHashJoinNode::GetNext(impala::RuntimeState*, > impala::RowBatch*, bool*) () > #13 0x0000000000fee76e in > impala::PartitionedHashJoinNode::NextProbeRowBatch(impala::RuntimeState*, > impala::RowBatch*) () > #14 0x0000000000ff43b1 in > impala::PartitionedHashJoinNode::GetNext(impala::RuntimeState*, > impala::RowBatch*, bool*) () > #15 0x0000000000fea54d in > impala::PartitionedAggregationNode::Open(impala::RuntimeState*) () > #16 0x0000000000b77dfd in impala::FragmentInstanceState::Open() () > #17 0x0000000000b7943b in impala::FragmentInstanceState::Exec() () > #18 0x0000000000b68a0a in > impala::QueryState::ExecFInstance(impala::FragmentInstanceState*) () > #19 0x0000000000d18a73 in > impala::Thread::SuperviseThread(std::basic_string<char, > std::char_traits<char>, std::allocator<char> > const&, > std::basic_string<char, std::char_traits<char>, std::allocator<char> > > const&, boost::function<void ()()>, impala::Promise<long>*) () > #20 0x0000000000d19204 in boost::detail::thread_data<boost::_bi::bind_t<void, > void (*)(std::basic_string<char, std::char_traits<char>, std::allocator<char> > > const&, std::basic_string<char, std::char_traits<char>, > std::allocator<char> > const&, boost::function<void ()()>, > impala::Promise<long>*), > boost::_bi::list4<boost::_bi::value<std::basic_string<char, > std::char_traits<char>, std::allocator<char> > >, > boost::_bi::value<std::basic_string<char, std::char_traits<char>, > std::allocator<char> > >, boost::_bi::value<boost::function<void ()()> >, > boost::_bi::value<impala::Promise<long>*> > > >::run() () > #21 0x000000000129bf5a in thread_proxy () > #22 0x000000326c607aa1 in start_thread () from /lib64/libpthread.so.0 > #23 0x000000326c2e893d in clone () from /lib64/libc.so.6 > {code} > This regression was observed with the tcmalloc options below > {code} > TCMALLOC_MAX_TOTAL_THREAD_CACHE_BYTES=2147483648 > TCMALLOC_TRANSFER_NUM_OBJ=40 > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)