You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@impala.apache.org by "Mostafa Mokhtar (JIRA)" <ji...@apache.org> on 2017/11/01 01:47:02 UTC
[jira] [Resolved] (IMPALA-5926) Avoid printing expensive stack when
closing a session
[ 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)