[IMPALA-1890] Race between ~BufferedBlockMgr() destructor and WriteComplete()

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: Product Backlog
• Fix Version/s: Impala 2.2
• Assignee: Ippokratis Pandis
• Reporter: Ippokratis Pandis
• Created: 17/Mar/15 05:04
• Updated: 20/Dec/15 00:05
• Resolved: 18/Mar/15 18:03

Description

We were looking on the code on the BufferedBlockMgr destructor and noticed that it acquires lock_ . The comment above it says that it is for synchronizing with WriteComplete(), see code below, which makes no sense. Because if there is indeed a race and the destructor wins, then the loser (the disk-io thread that executes the WriteComplete() callback) is going to access invalid or reset memory. While I was adding some dchecks about it, Dan managed to hit the problem in his S3 tests, after he fixed IMPALA-1863.

This problem looks very related to IMPALA-1873, probably a different manifestation of the same error. Filling it as a different JIRA as it is a slightly different stack.

The code of the BufferedBlockMgr destructor with the lock_ and the comment about WriteComplete():

  // Grab this lock to synchronize with io threads in WriteComplete(). We need those
  // to finish to ensure that memory buffers remain valid for any in-progress writes.
  lock_guard<mutex> lock(lock_);
  // Delete tmp files.
  BOOST_FOREACH(TmpFileMgr::File& file, tmp_files_) {
    file.Remove();
  }
  tmp_files_.clear();

  // Free memory resources.
  BOOST_FOREACH(BufferDescriptor* buffer, all_io_buffers_) {
    mem_tracker_->Release(buffer->len);
    delete[] buffer->buffer;
  }
  DCHECK_EQ(mem_tracker_->consumption(), 0);
  mem_tracker_->UnregisterFromParent();
  mem_tracker_.reset();
}

The stack trace Dan hit:

#3  0x0000003a6982bad0 in __assert_fail () from /lib64/libc.so.6
#4  0x0000000000f3c0cd in boost::scoped_ptr<impala::MemTracker>::operator-> (this=0x9611248) at /usr/include/boost/smart_ptr/scoped_ptr.hpp:97
#5  0x0000000000f90772 in impala::BufferedBlockMgr::DebugInternal (this=0x9611200) at /home/dhecht/src/Impala/be/src/runtime/buffered-block-mgr.cc:1078
#6  0x0000000000f8d3dc in impala::BufferedBlockMgr::WriteComplete (this=0x9611200, block=0x20ea7440, write_status=...) at /home/dhecht/src/Impala/be/src/runtime/buffered-block-mgr.cc:754
#7  0x0000000000f9c6e0 in boost::_mfi::mf2<void, impala::BufferedBlockMgr, impala::BufferedBlockMgr::Block*, impala::Status const&>::operator() (this=0x83fb160, p=0x9611200, a1=0x20ea7440, a2=...)
    at /usr/include/boost/bind/mem_fn_template.hpp:280
#8  0x0000000000f9c375 in boost::_bi::list3<boost::_bi::value<impala::BufferedBlockMgr*>, boost::_bi::value<impala::BufferedBlockMgr::Block*>, boost::arg<1> >::operator()<boost::_mfi::mf2<void, impala::BufferedBlockMgr, impala::BufferedBlockMgr::Block*, impala::Status const&>, boost::_bi::list1<impala::Status const&> > (this=0x83fb170, f=..., a=...) at /usr/include/boost/bind/bind.hpp:392
#9  0x0000000000f9bb7e in boost::_bi::bind_t<boost::_bi::unspecified, boost::_mfi::mf2<void, impala::BufferedBlockMgr, impala::BufferedBlockMgr::Block*, impala::Status const&>, boost::_bi::list3<boost::_bi::value<impala::BufferedBlockMgr*>, boost::_bi::value<impala::BufferedBlockMgr::Block*>, boost::arg<1> > >::operator()<impala::Status> (this=0x83fb160, a1=...)
    at /usr/include/boost/bind/bind_template.hpp:47
#10 0x0000000000f9b1f4 in boost::detail::function::void_function_obj_invoker1<boost::_bi::bind_t<boost::_bi::unspecified, boost::_mfi::mf2<void, impala::BufferedBlockMgr, impala::BufferedBlockMgr::Block*, impala::Status const&>, boost::_bi::list3<boost::_bi::value<impala::BufferedBlockMgr*>, boost::_bi::value<impala::BufferedBlockMgr::Block*>, boost::arg<1> > >, void, impala::Status const&>::invoke (
    function_obj_ptr=..., a0=...) at /usr/include/boost/function/function_template.hpp:153
#11 0x0000000000fafe16 in boost::function1<void, impala::Status const&>::operator() (this=0x1cb62e50, a0=...) at /usr/include/boost/function/function_template.hpp:1013
#12 0x0000000000fa9cab in impala::DiskIoMgr::HandleWriteFinished (this=0x5dd45a0, writer=0x949c1e0, write_range=0x1cb62e00, write_status=...) at /home/dhecht/src/Impala/be/src/runtime/disk-io-mgr.cc:858
#13 0x0000000000fab7c7 in impala::DiskIoMgr::Write (this=0x5dd45a0, writer_context=0x949c1e0, write_range=0x1cb62e00) at /home/dhecht/src/Impala/be/src/runtime/disk-io-mgr.cc:1053
#14 0x0000000000faa63a in impala::DiskIoMgr::WorkLoop (this=0x5dd45a0, disk_queue=0x85ae460) at /home/dhecht/src/Impala/be/src/runtime/disk-io-mgr.cc:940


---The mem-tracker has already been freed:---

(gdb) f 6
#6  0x0000000000f8d3dc in impala::BufferedBlockMgr::WriteComplete (this=0x9611200, block=0x20ea7440, write_status=...) at /home/dhecht/src/Impala/be/src/runtime/buffered-block-mgr.cc:754
754       DCHECK(Validate()) << endl << DebugInternal();
(gdb) p mem_tracker_
$3 = {
  px = 0x0
}