Skip to content

Conversation

@amitkdutta
Copy link
Contributor

@amitkdutta amitkdutta commented Dec 1, 2022

Recently after shadowing a lot of traffic (where query failure rate is high), we found a crash which has following stack trace while looking in gdb:

(gdb) bt                                                                                                                                                                     
#0  ___pthread_mutex_lock (mutex=0x198) at pthread_mutex_lock.c:76                                                                                                           
#1  0x0000000007dc5943 in __gthread_mutex_lock (__mutex=0x198)
    at fbcode/third-party-buck/platform010/build/libgcc/include/c++/trunk/x86_64-facebook-linux/bits/gthr-default.h:749
#2  std::mutex::lock (this=0x198) at fbcode/third-party-buck/platform010/build/libgcc/include/c++/trunk/bits/std_mutex.h:100
#3  std::lock_guard<std::mutex>::lock_guard (this=<optimized out>, __m=...) at fbcode/third-party-buck/platform010/build/libgcc/include/c++/trunk/bits/std_mutex.h:229
#4  facebook::velox::exec::Task::state (this=0x0)
    at fbcode/buck-out/opt/gen/aab7ed39/velox/exec/velox_exec_lib#header-mode-symlink-tree-with-header-map,headers/velox/exec/Task.h:201
#5  facebook::presto::TaskManager::getResults (this=0x7fd1d016f280, taskId=..., bufferId=0, token=0, maxSize=..., maxWait=..., state=...)
    at third-party/presto_cpp/main/TaskManager.cpp:638
#6  0x0000000007de5cbd in facebook::presto::TaskResource::getResults(proxygen::HTTPMessage*, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&)::$_4::operator()(proxygen::HTTPMessage*, std::vector<std::unique_ptr<folly::IOBuf, std::default_delete<folly::IOBuf> >, std::allocator<std::unique_ptr<folly::IOBuf, std::default_delete<folly::IOBuf> > > > const&, proxygen::ResponseHandler*, std::shared_ptr<facebook::presto::http::CallbackRequestHandlerState>) const (this=0x7fd01076c260, downstream=0x7fd19c625e98, handlerState=...)
    at third-party/presto_cpp/main/TaskResource.cpp:335

Now, moving further in frame #5, we find that velox task is null

(gdb) f 5                                                                                                                                                                    
#5  facebook::presto::TaskManager::getResults (this=0x7fd1d016f280, taskId=..., bufferId=0, token=0, maxSize=..., maxWait=..., state=...)                                        at third-party/presto_cpp/main/TaskManager.cpp:638                                                                                                                       
638     third-party/presto_cpp/main/TaskManager.cpp: No such file or directory.                                                                                              
(gdb) print prestoTask->task                                                                                                                                                 
Could not find operator->.                                                                                                                                                   
(gdb) print prestoTask                                                                                                                                                       
$1 = {<std::__shared_ptr<facebook::presto::PrestoTask, __gnu_cxx::_S_atomic>> = {<std::__shared_ptr_access<facebook::presto::PrestoTask, __gnu_cxx::_S_atomic, false, false>>
 = {<No data fields>}, _M_ptr = 0x7f75f4ba1310, _M_refcount = {_M_pi = 0x7f75f4ba1300}}, <No data fields>}                                                                   
             
(gdb) print *(facebook::presto::PrestoTask*)(0x7f75f4ba1310)                                                                                                                 
$2 = {id = {queryId_ = {static npos = 18446744073709551615,                                                                                                                  
      _M_dataplus = {<std::allocator<char>> = {<__gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>}, 
        _M_p = 0x7f75f4bfe360 "20221130_093038_00204_599h5"}, _M_string_length = 27, {_M_local_buf = "\033\000\000\000\000\000\000\000\240\344\277\364u\177\000", 
        _M_allocated_capacity = 27}}, stageId_ = 2, stageExecutionId_ = 0, id_ = 15},  
  task = {<std::__shared_ptr<facebook::velox::exec::Task, __gnu_cxx::_S_atomic>> = {<std::__shared_ptr_access<facebook::velox::exec::Task, __gnu_cxx::_S_atomic, false, false
>> = {<No data fields>}, _M_ptr = 0x0, _M_refcount = {_M_pi = 0x0}}, <No data fields>}, taskStarted = true, lastHeartbeatMs = 1669800638997, 
  mutex = {<std::__mutex_base> = {_M_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, 
            __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}}, <No data fields>}, error = {_M_exception_object = 0x7f751d453300}, info = {taskId = {
      static npos = 18446744073709551615, _M_dataplus = {<std::allocator<char>> = {<__gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>}, 
        _M_p = 0x7f7573c11620 "20221130_093038_00204_599h5.2.0.15"}, _M_string_length = 34, {_M_local_buf = "\"", '\000' <repeats 14 times>, _M_allocated_capacity = 34}}, 
    taskStatus = {taskInstanceIdLeastSignificantBits = -2430042805604977756, taskInstanceIdMostSignificantBits = 2200961769664181178, version = 25, 
      state = facebook::presto::protocol::TaskState::FAILED, self = {static npos = 18446744073709551615,

Hence the line prestoTask->task->state() crashes. Actually we always check Prestotask's error status before accessing it's velox task, this is one place where it was missing and causing random crashes. This PR fixes it, and put proper comments for taskstarted field of PrestoTask.

@amitkdutta amitkdutta requested a review from a team as a code owner December 1, 2022 07:59
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@amitkdutta CAn you please doublecheck that it is impossible to have this situation:

  1. getData() request comes and either it creates the new PrestoTask or some other thread does.
  2. That new PrestoTask does not have Velox Task (it is null).
  3. We throw this error.
  4. Velox Task is created for this PrestoTask.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is this special scenario that creates an empty PrestoTask without Velox Task in it. This scenario happens when error occurs while parsing or doing any protocol translation in task update endpoint. The empty shell PrestoTask was created to contain that error so that following getInfo()/getStatus() calls on that task can know what's going on. I think the crash here might be related to taht.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There was clearly a race here. Check line 630 of this file. There is an explicit check on error in PrestoTask and by that line prestoTask does not contain an error yet. But here it does at the current line.
It indicates an error PrestoTask being constructed at line 630 and when it gets here the error is populated. I think a blame from another angle would be unsafe usage of prestoTask (without lock).

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, this fix will not necessarily will fix the problem.
By that time we might still not have error in the task.
@tanjialiang Can the task in this special case be created with error from the start to avoid the race?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A way to verify is to print out the contained error to see if it is an error related to parsing/json/protocol etc.

Copy link
Contributor

@tanjialiang tanjialiang Dec 1, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, this fix will not necessarily will fix the problem. By that time we might still not have error in the task. @tanjialiang Can the task in this special case be created with error from the start to avoid the race?

The task(PrestoTask) is created from the start with Error in it. We cannot create a Velox task because error happens while creating that velox task.

The issue here is, while doing checks here and for lines above we never acquire a lock from presto task (idk why, but it seems to be intentional). And presto task state changes while we use stuff inside this presto task.

Copy link
Contributor

@xiaoxmeng xiaoxmeng left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@amitkdutta Good catch. Thanks for the fix. Consider to add a unit test to cover this!

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is some race conditions in prestoTask fields. So consider to change 'taskStarted' and 'error' to an atomic which seems to be necessary if we enabling tsan on presto cpp tests which might help us to catch this sort of condition in tests.

// NOTE: 'error' in PrestoTask might have been set here by async query failure code path even though we have checked 'error' right above this loop. Also createOrUpdateErrorTask sets both 'error' and 'taskStarted' but leave velox 'task' empty in async query failure case.

Also consider to create a unit test using testValue facility provided by Velox.

@spershin
Copy link
Contributor

spershin commented Dec 1, 2022

@amitkdutta , @tanjialiang , @xiaoxmeng
We had a discussion and came up with the following fix (comments are subject to refactoring):

  1. Change semantics and add comments for PrestoTask::taskStarted:
struct PrestoTask {
  const PrestoTaskId id;
  std::shared_ptr<velox::exec::Task> task;
  // Has the task been normally created and started.
  // When you create task with error - it has never been started.
  // When you create task from 'delete task' - it has never been started.
  // When you create task from any other endpoint, such as 'get result' - it has
  // not been started, until the actual 'create task' message comes.
  bool taskStarted = false;

  1. Remove this code from TaskManager::createOrUpdateErrorTask()
  // outside of prestoTask->mutex.
  prestoTask->taskStarted = true;

  1. Change this code in PrestoTask::updateStatusLocked()
    from
  if (!taskStarted) {
    info.taskStatus.state = protocol::TaskState::RUNNING;
    return info.taskStatus;
  }

to

  if (!taskStarted and error == nullptr) {
    protocol::TaskStatus ret = info.taskStatus;
    if (ret.state != protocol::TaskState::ABORTED) {
      ret.state = protocol::TaskState::PLANNED;
    }
    return ret;
  }

@amitkdutta
Copy link
Contributor Author

@amitkdutta , @tanjialiang , @xiaoxmeng We had a discussion and came up with the following fix (comments are subject to refactoring):

  1. Change semantics and add comments for PrestoTask::taskStarted:
struct PrestoTask {
  const PrestoTaskId id;
  std::shared_ptr<velox::exec::Task> task;
  // Has the task been normally created and started.
  // When you create task with error - it has never been started.
  // When you create task from 'delete task' - it has never been started.
  // When you create task from any other endpoint, such as 'get result' - it has
  // not been started, until the actual 'create task' message comes.
  bool taskStarted = false;
  1. Remove this code from TaskManager::createOrUpdateErrorTask()
  // outside of prestoTask->mutex.
  prestoTask->taskStarted = true;
  1. Change this code in PrestoTask::updateStatusLocked()
    from
  if (!taskStarted) {
    info.taskStatus.state = protocol::TaskState::RUNNING;
    return info.taskStatus;
  }

to

  if (!taskStarted and error == nullptr) {
    protocol::TaskStatus ret = info.taskStatus;
    if (ret.state != protocol::TaskState::ABORTED) {
      ret.state = protocol::TaskState::PLANNED;
    }
    return ret;
  }

@spershin @tanjialiang Addressed changes as you suggested. This solves the crash as well. Thanks for the suggestion.

Copy link
Contributor

@spershin spershin left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good.

@spershin spershin merged commit b80831f into prestodb:master Dec 2, 2022
@wanglinsong wanglinsong mentioned this pull request Jan 12, 2023
30 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants