[
https://issues.apache.org/jira/browse/IMPALA-8732?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Joe McDonnell resolved IMPALA-8732.
-----------------------------------
Resolution: Fixed
Fix Version/s: Impala 3.3.0
> tcmalloc contention in Coordinator::BackendState::Exec()
> --------------------------------------------------------
>
> Key: IMPALA-8732
> URL: https://issues.apache.org/jira/browse/IMPALA-8732
> Project: IMPALA
> Issue Type: Bug
> Components: Backend
> Affects Versions: Impala 2.12.0, Impala 3.3.0
> Reporter: Joe McDonnell
> Assignee: Joe McDonnell
> Priority: Critical
> Fix For: Impala 3.3.0
>
>
> A cluster with several dozen nodes running Impala 2.12 observed slow query
> startup:
> {noformat}
> Query Timeline
> Query submitted: 63.19us (63194)
> Planning finished: 815ms (815243445)
> Submit for admission: 1.21s (1206292509)
> Completed admission: 1.21s (1206462581)
> Ready to start on 83 backends: 1.40s (1395408016) <------
> All 83 execution backends (84 fragment instances) started: 3.3m
> (196968242656) <-------
> Rows available: 3.3m (197012769471)
> Cancelled: 3.3m (197012953528)
> Released admission control resources: 3.3m (197029124587)
> Unregister query: 3.3m (197241887354){noformat}
> This corresponds to the time spent in Coordinator::StartBackendExec() where
> the coordinator submits the ExecQueryFInstances messages to the
> ExecEnv::exec_rpc_thread_pool_ and waits for the thread pool to send the
> messages via Coordinator::BackendState:;Exec(). This time did not show up in
> the backend startup latency:
> {noformat}
> Backend startup latencies: Count: 83, min / max: 1ms / 619ms, 25th %-ile:
> 2ms, 50th %-ile: 2ms, 75th %-ile: 3ms, 90th %-ile: 4ms, 95th %-ile: 8ms,
> 99.9th %-ile: 619ms{noformat}
> This means that the time is spent on the coordinator side, and it is not
> related to RPCs.
> Examining the logs from the affected Impala coordinator shows a backlog on
> the ExecEnv::exec_rpc_thread_pool_. Specifically, I processed the logs
> looking for "starting execution on X backends for query_id=" messages and
> their corresponding "started execution on X backends for query_id=" messages
> and tracked the number of outstanding starting queries. There was no burst of
> query activity; the number of outstanding starting queries accumulated over
> the course of a minute, reaching 30 at times.
> I wrote a script to track the number of outstanding starting queries in the
> real time and dump the Impalad's pstack if the problem showed up (defined as
> number of starting queries > 10).
> This revealed contention on tcmalloc in Coordinator::BackendState::Exec()
> when copying the TQueryCtx (specifically when copying a map of
> THdfsPartitions and their corresponding TExpr/TExprNode). The pstacks showed
> stacks like these:
> {noformat}
> #0 0x000000000211519a in base::internal::SpinLockDelay(int volatile*, int,
> int) ()
> #1 0x0000000002160b69 in SpinLock::SlowLock() ()
> #2 0x00000000021a4568 in tcmalloc::CentralFreeList::Populate() ()
> #3 0x00000000021a4668 in
> tcmalloc::CentralFreeList::FetchFromOneSpansSafe(int, void**, void**) ()
> #4 0x00000000021a46f4 in tcmalloc::CentralFreeList::RemoveRange(void**,
> void**, int) ()
> #5 0x00000000021b1e53 in
> tcmalloc::ThreadCache::FetchFromCentralCache(unsigned long, unsigned long) ()
> #6 0x0000000002258978 in tc_newarray ()
> #7 0x00000000009644e7 in impala::TExpr*
> std::__uninitialized_copy<false>::__uninit_copy<__gnu_cxx::__normal_iterator<impala::TExpr
> const*, std::vector<impala::TExpr, std::allocator<impala::TExpr> > >,
> impala::TExpr*>(__gnu_cxx::__normal_iterator<impala::TExpr const*,
> std::vector<impala::TExpr, std::allocator<impala::TExpr> > >,
> __gnu_cxx::__normal_iterator<impala::TExpr const*, std::vector<impala::TExpr,
> std::allocator<impala::TExpr> > >, impala::TExpr*) ()
> #8 0x000000000096509a in
> _ZNSt8_Rb_treeIlSt4pairIKlN6impala14THdfsPartitionEESt10_Select1stIS4_ESt4lessIlESaIS4_EE14_M_create_nodeIJRKS4_EEEPSt13_Rb_tree_nodeIS4_EDpOT_
> ()
> #9 0x00000000009654e3 in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> > >::_M_copy(std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> > const*, std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> >*) ()
> #10 0x0000000000965513 in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> > >::_M_copy(std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> > const*, std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> >*) ()
> #11 0x0000000000965513 in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> > >::_M_copy(std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> > const*, std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> >*) ()
> #12 0x000000000096556b in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> > >::_M_copy(std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> > const*, std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> >*) ()
> #13 0x000000000096556b in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> > >::_M_copy(std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> > const*, std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> >*) ()
> #14 0x000000000096556b in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> > >::_M_copy(std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> > const*, std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> >*) ()
> #15 0x000000000096556b in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> > >::_M_copy(std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> > const*, std::_Rb_tree_node<std::pair<long
> const, impala::THdfsPartition> >*) ()
> #16 0x0000000000a2f59b in impala::THdfsTable::THdfsTable(impala::THdfsTable
> const&) ()
> #17 0x0000000000af53c0 in
> impala::TTableDescriptor::TTableDescriptor(impala::TTableDescriptor const&) ()
> #18 0x0000000000c7ccd0 in std::vector<impala::TTableDescriptor,
> std::allocator<impala::TTableDescriptor>
> >::operator=(std::vector<impala::TTableDescriptor,
> std::allocator<impala::TTableDescriptor> > const&) ()
> #19 0x000000000126eb71 in
> impala::Coordinator::BackendState::Exec(impala::TQueryCtx const&,
> impala::DebugOptions const&, boost::unordered::unordered_map<int,
> impala::Coordinator::FilterState, boost::hash<int>, std::equal_to<int>,
> std::allocator<std::pair<int const, impala::Coordinator::FilterState> > >
> const&, impala::CountingBarrier*) (){noformat}
> and
> {noformat}
> #0 0x000000000211519a in base::internal::SpinLockDelay(int volatile*, int,
> int) ()
> #1 0x0000000002160b69 in SpinLock::SlowLock() ()
> #2 0x00000000021a3fd8 in tcmalloc::CentralFreeList::ReleaseToSpans(void*) ()
> #3 0x00000000021a401b in
> tcmalloc::CentralFreeList::ReleaseListToSpans(void*) ()
> #4 0x00000000021a428c in tcmalloc::CentralFreeList::InsertRange(void*,
> void*, int) ()
> #5 0x00000000021b1ff4 in
> tcmalloc::ThreadCache::ReleaseToCentralCache(tcmalloc::ThreadCache::FreeList*,
> unsigned long, int) ()
> #6 0x00000000021b20bc in
> tcmalloc::ThreadCache::ListTooLong(tcmalloc::ThreadCache::FreeList*, unsigned
> long) ()
> #7 0x0000000002256c10 in tc_free ()
> #8 0x00000000009520b1 in std::vector<impala::TExpr,
> std::allocator<impala::TExpr> >::~vector() ()
> #9 0x0000000000953823 in impala::THdfsPartition::~THdfsPartition() ()
> #10 0x0000000000954709 in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #11 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #12 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #13 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #14 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #15 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #16 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #17 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #18 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #19 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #20 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #21 0x00000000009546fc in std::_Rb_tree<long, std::pair<long const,
> impala::THdfsPartition>, std::_Select1st<std::pair<long const,
> impala::THdfsPartition> >, std::less<long>, std::allocator<std::pair<long
> const, impala::THdfsPartition> >
> >::_M_erase(std::_Rb_tree_node<std::pair<long const, impala::THdfsPartition>
> >*) ()
> #22 0x00000000009547ff in impala::THdfsTable::~THdfsTable() ()
> #23 0x0000000000af4544 in impala::TTableDescriptor::~TTableDescriptor() ()
> #24 0x0000000000bc575f in impala::TDescriptorTable::~TDescriptorTable() ()
> #25 0x0000000000bc59b3 in impala::TQueryCtx::~TQueryCtx() ()
> #26 0x0000000000bc6158 in
> impala::TExecQueryFInstancesParams::~TExecQueryFInstancesParams() ()
> #27 0x000000000126f68f in
> impala::Coordinator::BackendState::Exec(impala::TQueryCtx const&,
> impala::DebugOptions const&, boost::unordered::unordered_map<int,
> impala::Coordinator::FilterState, boost::hash<int>, std::equal_to<int>,
> std::allocator<std::pair<int const, impala::Coordinator::FilterState> > >
> const&, impala::CountingBarrier*) (){noformat}
--
This message was sent by Atlassian JIRA
(v7.6.14#76016)
