[IMPALA-7903] DCHECK in RawValue::PrintValue() hit with VLOG level 3

• Type: Improvement
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Fix Version/s: Impala 3.2.0
• Component/s: Backend
• Labels: broken-build crash
• Target Version: Impala 3.2.0
• Epic Color: ghx-label-2
• Assignee: Gabor Kaszab
• Reporter: Tim Armstrong
• Created: 27/Nov/18 23:56
• Updated: 10/Dec/18 23:44
• Resolved: 10/Dec/18 09:10

Description

We hit this DCHECK here on an exhaustive test run:

#0  0x00007fda93d441f7 in raise () from /lib64/libc.so.6
#1  0x00007fda93d458e8 in abort () from /lib64/libc.so.6
#2  0x00000000046679f4 in google::DumpStackTraceAndExit() ()
#3  0x000000000465e44d in google::LogMessage::Fail() ()
#4  0x000000000465fcf2 in google::LogMessage::SendToLog() ()
#5  0x000000000465de27 in google::LogMessage::Flush() ()
#6  0x00000000046613ee in google::LogMessageFatal::~LogMessageFatal() ()
#7  0x0000000001f2a9b5 in impala::RawValue::PrintValue (value=0x3a21f93e, type=..., scale=-1, stream=0x7fd9e92a9bd0) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/runtime/raw-value.cc:279
#8  0x0000000001f29b42 in impala::RawValue::PrintValue (value=0x3a21f93e, type=..., scale=-1, str=0x7fd9e92a9f30) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/runtime/raw-value.cc:111
#9  0x0000000002121f9e in impala::PrintTuple (t=0x3a21f93e, d=...) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/util/debug-util.cc:168
#10 0x000000000212217c in impala::PrintRow (row=0xf1a6000, d=...) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/util/debug-util.cc:181
#11 0x0000000001ec0829 in impala::RowBatch::VLogRows (this=0x5cda7740, context=...) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/runtime/row-batch.cc:579
#12 0x0000000001f11d82 in impala::FragmentInstanceState::ExecInternal (this=0x1c1b8000) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/runtime/fragment-instance-state.cc:328
#13 0x0000000001f0ea39 in impala::FragmentInstanceState::Exec (this=0x1c1b8000) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/runtime/fragment-instance-state.cc:93
#14 0x0000000001f1f01d in impala::QueryState::ExecFInstance (this=0x3f565000, fis=0x1c1b8000) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/runtime/query-state.cc:571
#15 0x0000000001f1d326 in impala::QueryState::<lambda()>::operator()(void) const (__closure=0x7fd9e92aaba8) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/runtime/query-state.cc:480
#16 0x0000000001f1fdc5 in boost::detail::function::void_function_obj_invoker0<impala::QueryState::StartFInstances()::<lambda()>, void>::invoke(boost::detail::function::function_buffer &) (function_obj_ptr=...) at /data/jenkins/workspace/impala-asf-master-exhaustive/Impala-Toolchain/boost-1.57.0-p3/include/boost/function/function_template.hpp:153
#17 0x0000000001d38206 in boost::function0<void>::operator() (this=0x7fd9e92aaba0) at /data/jenkins/workspace/impala-asf-master-exhaustive/Impala-Toolchain/boost-1.57.0-p3/include/boost/function/function_template.hpp:767
#18 0x00000000021baa5f in impala::Thread::SuperviseThread(std::string const&, std::string const&, boost::function<void ()>, impala::ThreadDebugInfo const*, impala::Promise<long, (impala::PromiseMode)0>*) (name=..., category=..., functor=..., parent_thread_info=0x7fd9d4d87850, thread_started=0x7fd9d4d867f0) at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/util/thread.cc:359
#19 0x00000000021c2d7f in boost::_bi::list5<boost::_bi::value<std::string>, boost::_bi::value<std::string>, boost::_bi::value<boost::function<void ()> >, boost::_bi::value<impala::ThreadDebugInfo*>, boost::_bi::value<impala::Promise<long, (impala::PromiseMode)0>*> >::operator()<void (*)(std::string const&, std::string const&, boost::function<void ()>, impala::ThreadDebugInfo const*, impala::Promise<long, (impala::PromiseMode)0>*), boost::_bi::list0>(boost::_bi::type<void>, void (*&)(std::string const&, std::string const&, boost::function<void ()>, impala::ThreadDebugInfo const*, impala::Promise<long, (impala::PromiseMode)0>*), boost::_bi::list0&, int) (this=0x119ff8fc0, f=@0x119ff8fb8: 0x21ba6f8 <impala::Thread::SuperviseThread(std::string const&, std::string const&, boost::function<void ()>, impala::ThreadDebugInfo const*, impala::Promise<long, (impala::PromiseMode)0>*)>, a=...) at /data/jenkins/workspace/impala-asf-master-exhaustive/Impala-Toolchain/boost-1.57.0-p3/include/boost/bind/bind.hpp:525
#20 0x00000000021c2ca3 in boost::_bi::bind_t<void, void (*)(std::string const&, std::string const&, boost::function<void ()>, impala::ThreadDebugInfo const*, impala::Promise<long, (impala::PromiseMode)0>*), boost::_bi::list5<boost::_bi::value<std::string>, boost::_bi::value<std::string>, boost::_bi::value<boost::function<void ()> >, boost::_bi::value<impala::ThreadDebugInfo*>, boost::_bi::value<impala::Promise<long, (impala::PromiseMode)0>*> > >::operator()() (this=0x119ff8fb8) at /data/jenkins/workspace/impala-asf-master-exhaustive/Impala-Toolchain/boost-1.57.0-p3/include/boost/bind/bind_template.hpp:20
#21 0x00000000021c2c66 in boost::detail::thread_data<boost::_bi::bind_t<void, void (*)(std::string const&, std::string const&, boost::function<void ()>, impala::ThreadDebugInfo const*, impala::Promise<long, (impala::PromiseMode)0>*), boost::_bi::list5<boost::_bi::value<std::string>, boost::_bi::value<std::string>, boost::_bi::value<boost::function<void ()> >, boost::_bi::value<impala::ThreadDebugInfo*>, boost::_bi::value<impala::Promise<long, (impala::PromiseMode)0>*> > > >::run() (this=0x119ff8e00) at /data/jenkins/workspace/impala-asf-master-exhaustive/Impala-Toolchain/boost-1.57.0-p3/include/boost/thread/detail/thread.hpp:116
#22 0x0000000003589b7a in thread_proxy ()
#23 0x00007fda940d9e25 in start_thread () from /lib64/libpthread.so.0
#24 0x00007fda93e0734d in clone () from /lib64/libc.so.6

I think this started happening because test_webpages toggles the log level and was enable recently IMPALA-7691. Clearly we shouldn't be hitting this DCHECK anyway.

It looks like this is a FIXED_UDA_INTERMEDIATE, so I think the batches being logged were being shuffled as part of the exchange for an aggregate:

(gdb) frame 7
#7  0x0000000001f2a9b5 in impala::RawValue::PrintValue (value=0x3a21f93e, type=..., scale=-1, 
    stream=0x7fd9e92a9bd0)
    at /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/runtime/raw-value.cc:279
279	in /data/jenkins/workspace/impala-asf-master-exhaustive/repos/Impala/be/src/runtime/raw-value.cc
(gdb) info args
value = 0x3a21f93e
type = @0xee87688: {
  type = impala::TYPE_FIXED_UDA_INTERMEDIATE, 
  len = 24, 
  static MAX_VARCHAR_LENGTH = 65535, 
  static MAX_CHAR_LENGTH = 255, 
  precision = -1, 
  scale = -1, 
  static MAX_PRECISION = 38, 
  static MAX_SCALE = 38, 
  static MIN_ADJUSTED_SCALE = 6, 
  static MAX_DECIMAL4_PRECISION = 9, 
  static MAX_DECIMAL8_PRECISION = 18, 
  children = {
    <std::_Vector_base<impala::ColumnType, std::allocator<impala::ColumnType> >> = {
      _M_impl = {
        <std::allocator<impala::ColumnType>> = {
          <__gnu_cxx::new_allocator<impala::ColumnType>> = {<No data fields>}, <No data fields>}, 
        members of std::_Vector_base<impala::ColumnType, std::allocator<impala::ColumnType> >::_Vector_impl: 
        _M_start = 0x0, 
        _M_finish = 0x0, 
        _M_end_of_storage = 0x0
      }
    }, <No data fields>}, 
  field_names = {
    <std::_Vector_base<std::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> > > >> = {
      _M_impl = {
        <std::allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> > >> = {
          <__gnu_cxx::new_allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> > >> = {<No data fields>}, <No data fields>}, 
        members of std::_Vector_base<std::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> > > >::_Vector_impl: 
        _M_start = 0x0, 
        _M_finish = 0x0, 
        _M_end_of_storage = 0x0
      }
    }, <No data fields>}, 
  static LLVM_CLASS_NAME = 0x4a57fb0 "struct.impala::ColumnType"
}
scale = -1

Issue Links

• relates to: IMPALA-7473 RawValue::PrintValue() hits general protection fault with VLOG level 3