[
https://issues.apache.org/jira/browse/IMPALA-5926?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Mostafa Mokhtar resolved IMPALA-5926.
-------------------------------------
Resolution: Fixed
> Avoid printing expensive stack when closing a session
> -----------------------------------------------------
>
> Key: IMPALA-5926
> URL: https://issues.apache.org/jira/browse/IMPALA-5926
> Project: IMPALA
> Issue Type: Bug
> Components: Backend
> Reporter: Mostafa Mokhtar
> Assignee: Mostafa Mokhtar
> Priority: Major
> Labels: ramp-up, trivial
>
> Noticed that session teardown is very slow due to printing expensive call
> stack, this issue is very similar to IMPALA-5275.
> From
> https://github.com/apache/incubator-impala/blob/master/be/src/service/impala-server.cc#L1116
> {code}
> // Unregister all open queries from this session.
> Status status("Session closed");
> {code}
> From vtune
> {code}
> CPU Time
> 1 of 8: 72.4% (51.420s of 71.065s)
> impalad ! google::OpenObjectFileContainingPcAndGetStartAddress - [unknown
> source file]
> impalad ! google::SymbolizeAndDemangle + 0x488 - [unknown source file]
> impalad ! google::DumpStackTrace.constprop.9 + 0x6e - [unknown source file]
> impalad ! impala::GetStackTrace + 0x1e - debug-util.cc:326
> impalad ! impala::Status::Status + 0x68 - status.cc:122
> impalad ! impala::ImpalaServer::CloseSessionInternal + 0x1f9 -
> impala-server.cc:1116
> impalad ! impala::ImpalaServer::CloseSession + 0x11d -
> impala-hs2-server.cc:383
> impalad !
> apache::hive::service::cli::thrift::TCLIServiceProcessor::process_CloseSession
> + 0x215 - TCLIService.cpp:4587
> impalad !
> apache::hive::service::cli::thrift::TCLIServiceProcessor::dispatchCall +
> 0x113 - TCLIService.cpp:4506
> impalad ! apache::thrift::TDispatchProcessor::process + 0xab -
> TDispatchProcessor.h:121
> impalad ! apache::thrift::server::TThreadPoolServer::Task::run + 0x22a -
> [unknown source file]
> impalad ! apache::thrift::concurrency::ThreadManager::Worker::run + 0x2c8 -
> [unknown source file]
> impalad ! impala::ThriftThread::RunRunnable + 0x68 - thrift-thread.cc:74
> impalad ! boost::_mfi::mf2<void, impala::ThriftThread,
> boost::shared_ptr<apache::thrift::concurrency::Runnable>,
> impala::Promise<unsigned long>*>::operator() + 0x3a - mem_fn_template.hpp:280
> impalad ! operator()<boost::_mfi::mf2<void, impala::ThriftThread,
> boost::shared_ptr<apache::thrift::concurrency::Runnable>,
> impala::Promise<long unsigned int>*>, boost::_bi::list0> + 0x1e - bind.hpp:392
> impalad ! 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>*>>>::operator() -
> bind_template.hpp:20
> 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 + 0x9 -
> function_template.hpp:153
> impalad ! boost::function0<void>::operator() + 0x1a -
> function_template.hpp:767
> impalad ! impala::Thread::SuperviseThread + 0x1a7 - thread.cc:352
> impalad ! operator()<void (*)(const std::basic_string<char>&, const
> std::basic_string<char>&, boost::function<void()>, impala::Promise<long
> int>*), boost::_bi::list0> + 0x5a - bind.hpp:457
> impalad ! 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>*>>>::operator() -
> bind_template.hpp:20
> 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 + 0x19 -
> thread.hpp:116
> impalad ! thread_proxy + 0xd9 - [unknown source file]
> libpthread-2.17.so ! start_thread + 0xc4 - [unknown source file]
> libc-2.17.so ! __clone + 0x6c - [unknown source file]
> {code}
> {code}
> I0912 18:05:28.278861 32644 status.cc:122] Session closed
> @ 0x8a1d59 impala::Status::Status()
> @ 0xb0319a impala::ImpalaServer::CloseSessionInternal()
> @ 0xb2be3e impala::ImpalaServer::CloseSession()
> @ 0xdecc76
> apache::hive::service::cli::thrift::TCLIServiceProcessor::process_CloseSession()
> @ 0xdf89d4
> apache::hive::service::cli::thrift::TCLIServiceProcessor::dispatchCall()
> @ 0x8719cc apache::thrift::TDispatchProcessor::process()
> @ 0x1c2cd6b
> apache::thrift::server::TThreadPoolServer::Task::run()
> @ 0x1c14709
> apache::thrift::concurrency::ThreadManager::Worker::run()
> @ 0xa3a239 impala::ThriftThread::RunRunnable()
> @ 0xa3b012
> boost::detail::function::void_function_obj_invoker0<>::invoke()
> @ 0xc3c0c2 impala::Thread::SuperviseThread()
> @ 0xc3c824 boost::detail::thread_data<>::run()
> @ 0xf37a7a thread_proxy
> @ 0x7fde88d22dc5 start_thread
> @ 0x7fde88a5176d __clone
> {code}
> When there is a large number of queries finishing at the same time this
> becomes more problematic as printing the stack trace acquires a lock which
> blocks other queries trying to close the session.
> A portion of this time shows up under "Unregister query" in the query
> timeline.
> {code}
> Query Timeline: 2m7s
> - Query submitted: 84.265us (84.265us)
> - Planning finished: 622.838ms (622.754ms)
> - Submit for admission: 664.240ms (41.401ms)
> - Completed admission: 3s622ms (2s958ms)
> - Ready to start on 7 backends: 3s716ms (94.521ms)
> - All 7 execution backends (8 fragment instances) started: 6s835ms
> (3s118ms)
> - Rows available: 21s924ms (15s088ms)
> - First row fetched: 22s187ms (263.418ms)
> - Unregister query: 2m7s (1m45s)
> - ComputeScanRangeAssignmentTimer: 26.472ms
> {code}
> This was captured when running 128 concurrent queries against the same
> coordinator.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
