[IMPALA-3100] Runtime filter kenrel spinlock contention driven by memory allocation - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Critical
Resolution: Fixed
Affects Version/s: Impala 2.5.0
Fix Version/s: Impala 2.5.0
Component/s: Backend
Labels:
None

Description

It appears that runtime filters are causing high spinning in the kernel which is driven by memory allocation and deallocation of runtime filters.

CPU Time
1 of 14: 31.4% (1.150s of 3.668s)

impalad ! base::internal::SpinLockDelay - [unknown source file]
impalad ! SpinLock::SlowLock + 0xa6 - [unknown source file]
impalad ! tcmalloc::CentralFreeList::InsertRange + 0x3f - [unknown source file]
impalad ! tcmalloc::ThreadCache::ReleaseToCentralCache + 0x8d - [unknown source file]
impalad ! tcmalloc::ThreadCache::Scavenge + 0x3e - [unknown source file]
impalad ! operator delete + 0x2a3 - [unknown source file]
impalad ! std::vector<std::string, std::allocator<std::string>>::~vector + 0x50 - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::process_UpdateFilter + 0x319 - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::dispatchCall + 0xe8 - [unknown source file]
impalad ! apache::thrift::TDispatchProcessor::process + 0xab - [unknown source file]
impalad ! apache::thrift::server::TThreadedServer::Task::run + 0x22e - [unknown source file]
impalad ! impala::ThriftThread::RunRunnable + 0x68 - [unknown source file]
impalad ! boost::detail::function::void_function_obj_invoker0<boost::_bi::bind_t<void, boost::_mfi::mf2<void, impala::ThriftThread, boost::shared_ptr<apache::thrift::concurrency::Runnable>, impala::Promise<unsigned long>*>, boost::_bi::list3<boost::_bi::value<impala::ThriftThread*>, boost::_bi::value<boost::shared_ptr<apache::thrift::concurrency::Runnable>>, boost::_bi::value<impala::Promise<unsigned long>*>>>, void>::invoke + 0x61 - [unknown source file]
impalad ! impala::Thread::SuperviseThread + 0x226 - [unknown source file]
impalad ! boost::detail::thread_data<boost::_bi::bind_t<void, void (*)(std::string const&, std::string const&, boost::function<void (void)>, impala::Promise<long>*), boost::_bi::list4<boost::_bi::value<std::string>, boost::_bi::value<std::string>, boost::_bi::value<boost::function<void (void)>>, boost::_bi::value<impala::Promise<long>*>>>>::run + 0x73 - [unknown source file]
impalad ! func@0xd30ef0 + 0xd9 - [unknown source file]
libpthread.so.0 ! start_thread + 0xd0 - [unknown source file]
libc.so.6 ! clone + 0x6c - [unknown source file]

CPU Time
2 of 14: 25.7% (0.943s of 3.668s)

impalad ! base::internal::SpinLockDelay - [unknown source file]
impalad ! SpinLock::SlowLock + 0xa6 - [unknown source file]
impalad ! tcmalloc::CentralFreeList::RemoveRange + 0x43 - [unknown source file]
impalad ! tcmalloc::ThreadCache::FetchFromCentralCache + 0x62 - [unknown source file]
impalad ! tc_new + 0x407 - [unknown source file]
libstdc++.so.6 ! std::string::_Rep::_S_create + 0x58 - [unknown source file]
libstdc++.so.6 ! std::string::_M_mutate + 0x53 - [unknown source file]
libstdc++.so.6 ! std::string::_M_replace_safe + 0x1d - [unknown source file]
impalad ! apache::thrift::protocol::TBinaryProtocolT<apache::thrift::transport::TTransport>::readStringBody<std::string> + 0x5d - [unknown source file]
impalad ! apache::thrift::protocol::TVirtualProtocol<apache::thrift::protocol::TBinaryProtocolT<apache::thrift::transport::TTransport>, apache::thrift::protocol::TProtocolDefaults>::readBinary_virt + 0x2d - [unknown source file]
impalad ! impala::TBloomFilter::read + 0x1f5 - [unknown source file]
impalad ! impala::TUpdateFilterParams::read + 0x14c - [unknown source file]
impalad ! impala::ImpalaInternalService_UpdateFilter_args::read + 0xbc - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::process_UpdateFilter + 0x119 - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::dispatchCall + 0xe8 - [unknown source file]
impalad ! apache::thrift::TDispatchProcessor::process + 0xab - [unknown source file]
impalad ! apache::thrift::server::TThreadedServer::Task::run + 0x22e - [unknown source file]
impalad ! impala::ThriftThread::RunRunnable + 0x68 - [unknown source file]
impalad ! boost::detail::function::void_function_obj_invoker0<boost::_bi::bind_t<void, boost::_mfi::mf2<void, impala::ThriftThread, boost::shared_ptr<apache::thrift::concurrency::Runnable>, impala::Promise<unsigned long>*>, boost::_bi::list3<boost::_bi::value<impala::ThriftThread*>, boost::_bi::value<boost::shared_ptr<apache::thrift::concurrency::Runnable>>, boost::_bi::value<impala::Promise<unsigned long>*>>>, void>::invoke + 0x61 - [unknown source file]
impalad ! impala::Thread::SuperviseThread + 0x226 - [unknown source file]
impalad ! boost::detail::thread_data<boost::_bi::bind_t<void, void (*)(std::string const&, std::string const&, boost::function<void (void)>, impala::Promise<long>*), boost::_bi::list4<boost::_bi::value<std::string>, boost::_bi::value<std::string>, boost::_bi::value<boost::function<void (void)>>, boost::_bi::value<impala::Promise<long>*>>>>::run + 0x73 - [unknown source file]
impalad ! func@0xd30ef0 + 0xd9 - [unknown source file]
libpthread.so.0 ! start_thread + 0xd0 - [unknown source file]
libc.so.6 ! clone + 0x6c - [unknown source file]

CPU Time
5 of 14: 8.7% (0.321s of 3.668s)

impalad ! base::internal::SpinLockDelay - [unknown source file]
impalad ! SpinLock::SlowLock + 0xa6 - [unknown source file]
impalad ! tcmalloc::CentralFreeList::ReleaseListToSpans + 0x1a - [unknown source file]
impalad ! tcmalloc::CentralFreeList::InsertRange + 0x5c - [unknown source file]
impalad ! tcmalloc::ThreadCache::ReleaseToCentralCache + 0x8d - [unknown source file]
impalad ! tcmalloc::ThreadCache::Scavenge + 0x3e - [unknown source file]
impalad ! operator delete + 0x2a3 - [unknown source file]
impalad ! std::vector<std::string, std::allocator<std::string>>::~vector + 0x50 - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::process_UpdateFilter + 0x319 - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::dispatchCall + 0xe8 - [unknown source file]
impalad ! apache::thrift::TDispatchProcessor::process + 0xab - [unknown source file]
impalad ! apache::thrift::server::TThreadedServer::Task::run + 0x22e - [unknown source file]
impalad ! impala::ThriftThread::RunRunnable + 0x68 - [unknown source file]
impalad ! boost::detail::function::void_function_obj_invoker0<boost::_bi::bind_t<void, boost::_mfi::mf2<void, impala::ThriftThread, boost::shared_ptr<apache::thrift::concurrency::Runnable>, impala::Promise<unsigned long>*>, boost::_bi::list3<boost::_bi::value<impala::ThriftThread*>, boost::_bi::value<boost::shared_ptr<apache::thrift::concurrency::Runnable>>, boost::_bi::value<impala::Promise<unsigned long>*>>>, void>::invoke + 0x61 - [unknown source file]
impalad ! impala::Thread::SuperviseThread + 0x226 - [unknown source file]
impalad ! boost::detail::thread_data<boost::_bi::bind_t<void, void (*)(std::string const&, std::string const&, boost::function<void (void)>, impala::Promise<long>*), boost::_bi::list4<boost::_bi::value<std::string>, boost::_bi::value<std::string>, boost::_bi::value<boost::function<void (void)>>, boost::_bi::value<impala::Promise<long>*>>>>::run + 0x73 - [unknown source file]
impalad ! func@0xd30ef0 + 0xd9 - [unknown source file]
libpthread.so.0 ! start_thread + 0xd0 - [unknown source file]
libc.so.6 ! clone + 0x6c - [unknown source file]

CPU Time
1 of 13: 34.5% (0.620s of 1.795s)

impalad ! base::internal::SpinLockWake - [unknown source file]
impalad ! SpinLock::SlowUnlock + 0x13 - [unknown source file]
impalad ! tcmalloc::ThreadCache::ReleaseToCentralCache + 0x8d - [unknown source file]
impalad ! tcmalloc::ThreadCache::Scavenge + 0x3e - [unknown source file]
impalad ! operator delete + 0x2a3 - [unknown source file]
impalad ! std::vector<std::string, std::allocator<std::string>>::~vector + 0x50 - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::process_UpdateFilter + 0x319 - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::dispatchCall + 0xe8 - [unknown source file]
impalad ! apache::thrift::TDispatchProcessor::process + 0xab - [unknown source file]
impalad ! apache::thrift::server::TThreadedServer::Task::run + 0x22e - [unknown source file]
impalad ! impala::ThriftThread::RunRunnable + 0x68 - [unknown source file]
impalad ! boost::detail::function::void_function_obj_invoker0<boost::_bi::bind_t<void, boost::_mfi::mf2<void, impala::ThriftThread, boost::shared_ptr<apache::thrift::concurrency::Runnable>, impala::Promise<unsigned long>*>, boost::_bi::list3<boost::_bi::value<impala::ThriftThread*>, boost::_bi::value<boost::shared_ptr<apache::thrift::concurrency::Runnable>>, boost::_bi::value<impala::Promise<unsigned long>*>>>, void>::invoke + 0x61 - [unknown source file]
impalad ! impala::Thread::SuperviseThread + 0x226 - [unknown source file]
impalad ! boost::detail::thread_data<boost::_bi::bind_t<void, void (*)(std::string const&, std::string const&, boost::function<void (void)>, impala::Promise<long>*), boost::_bi::list4<boost::_bi::value<std::string>, boost::_bi::value<std::string>, boost::_bi::value<boost::function<void (void)>>, boost::_bi::value<impala::Promise<long>*>>>>::run + 0x73 - [unknown source file]
impalad ! func@0xd30ef0 + 0xd9 - [unknown source file]
libpthread.so.0 ! start_thread + 0xd0 - [unknown source file]
libc.so.6 ! clone + 0x6c - [unknown source file]

CPU Time
2 of 13: 23.3% (0.419s of 1.795s)

impalad ! base::internal::SpinLockWake - [unknown source file]
impalad ! SpinLock::SlowUnlock + 0x13 - [unknown source file]
impalad ! tcmalloc::CentralFreeList::RemoveRange + 0xc6 - [unknown source file]
impalad ! tcmalloc::ThreadCache::FetchFromCentralCache + 0x62 - [unknown source file]
impalad ! tc_new + 0x407 - [unknown source file]
libstdc++.so.6 ! std::string::_Rep::_S_create + 0x58 - [unknown source file]
libstdc++.so.6 ! std::string::_M_mutate + 0x53 - [unknown source file]
libstdc++.so.6 ! std::string::_M_replace_safe + 0x1d - [unknown source file]
impalad ! apache::thrift::protocol::TBinaryProtocolT<apache::thrift::transport::TTransport>::readStringBody<std::string> + 0x5d - [unknown source file]
impalad ! apache::thrift::protocol::TVirtualProtocol<apache::thrift::protocol::TBinaryProtocolT<apache::thrift::transport::TTransport>, apache::thrift::protocol::TProtocolDefaults>::readBinary_virt + 0x2d - [unknown source file]
impalad ! impala::TBloomFilter::read + 0x1f5 - [unknown source file]
impalad ! impala::TUpdateFilterParams::read + 0x14c - [unknown source file]
impalad ! impala::ImpalaInternalService_UpdateFilter_args::read + 0xbc - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::process_UpdateFilter + 0x119 - [unknown source file]
impalad ! impala::ImpalaInternalServiceProcessor::dispatchCall + 0xe8 - [unknown source file]
impalad ! apache::thrift::TDispatchProcessor::process + 0xab - [unknown source file]
impalad ! apache::thrift::server::TThreadedServer::Task::run + 0x22e - [unknown source file]
impalad ! impala::ThriftThread::RunRunnable + 0x68 - [unknown source file]
impalad ! boost::detail::function::void_function_obj_invoker0<boost::_bi::bind_t<void, boost::_mfi::mf2<void, impala::ThriftThread, boost::shared_ptr<apache::thrift::concurrency::Runnable>, impala::Promise<unsigned long>*>, boost::_bi::list3<boost::_bi::value<impala::ThriftThread*>, boost::_bi::value<boost::shared_ptr<apache::thrift::concurrency::Runnable>>, boost::_bi::value<impala::Promise<unsigned long>*>>>, void>::invoke + 0x61 - [unknown source file]
impalad ! impala::Thread::SuperviseThread + 0x226 - [unknown source file]
impalad ! boost::detail::thread_data<boost::_bi::bind_t<void, void (*)(std::string const&, std::string const&, boost::function<void (void)>, impala::Promise<long>*), boost::_bi::list4<boost::_bi::value<std::string>, boost::_bi::value<std::string>, boost::_bi::value<boost::function<void (void)>>, boost::_bi::value<impala::Promise<long>*>>>>::run + 0x73 - [unknown source file]
impalad ! func@0xd30ef0 + 0xd9 - [unknown source file]
libpthread.so.0 ! start_thread + 0xd0 - [unknown source file]
libc.so.6 ! clone + 0x6c - [unknown source file]

From perf

-  29.05%        impalad  [kernel.kallsyms]        [k] _spin_lock                                                            
   - _spin_lock                                                                                                               
      - 53.23% futex_wake                                                                                                     
           do_futex                                                                                                           
           sys_futex                                                                                                          
         - system_call_fastpath                                                                                               
            - 94.88% __lll_unlock_wake                                                                                        
                 34.13% 0x29                                                                                                  
                 32.69% 0                                                                                                     
                 17.37% 0x128e8180                                                                                            
                 15.81% 0x128de000                                                                                            
            - 5.12% base::internal::SpinLockWake(int volatile*, bool)                                                         
               - 100.00% SpinLock::SlowUnlock(unsigned long)                                                                  
                  + 55.82% tcmalloc::ThreadCache::ReleaseToCentralCache(tcmalloc::ThreadCache::FreeList*, unsigned long, int) 
                  + 43.08% tcmalloc::CentralFreeList::RemoveRange(void**, void**, int)                                        
                  + 0.57% tcmalloc::CentralFreeList::Populate()                                                               
                  + 0.52% tcmalloc::CentralFreeList::ReleaseToSpans(void*)                                                    
      - 43.80% futex_wait_setup                                                                                               
           futex_wait                                                                                                         
           do_futex                                                                                                           
           sys_futex                                                                                                          
         - system_call_fastpath                                                                                               
            + 89.47% __lll_lock_wait                                                                                          
            - 10.53% base::internal::SpinLockDelay(int volatile*, int, int)                                                   
               - 100.00% SpinLock::SlowLock()                                                                                 
                  + 53.81% tcmalloc::CentralFreeList::InsertRange(void*, void*, int)                                          
                  + 41.05% tcmalloc::CentralFreeList::RemoveRange(void**, void**, int)                                        
                  + 4.49% tcmalloc::CentralFreeList::ReleaseListToSpans(void*)                                                
                  + 0.66% tcmalloc::CentralFreeList::Populate()

Attachments

Issue Links

is related to

IMPALA-3103 Improve efficiency of BloomFilter Thrift serialisation

Resolved

Activity

People

Assignee:: Henry Robinson

Reporter:: Mostafa Mokhtar

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 29/Feb/16 20:55

Updated:: 01/Mar/16 15:35

Resolved:: 01/Mar/16 15:35