Deadlock race when calling ScheduledTask#reschedule

[snickell]

I believe I've found a deadlock in ScheduledTask / TimerSet, which appears to be present in both old (1.2.3) and current (1.3.6) concurrent-ruby.

If one creates a ScheduledTask, and calls reschedule() on it from the main thread on it right as the TimerSet background thread wakes up to run the #process_tasks loop, a deadlock can occur.

Thread 1: ScheduledTask#reschedule is called explicitly:

1. locks ScheduledTask.synchronize (scheduled_task.rb:265)
2. calls ns_reschedule, which in turn calls TimerSet#remove_task
3. which tries to lock TimerSet.synchronize (timer_set.rb:117)

Thread 2: TimerSet#process_tasks runs auto in the background:

1. Calls task = synchronize { @queue.pop } (timer_set.rb:167)
2. This locks TImerSet.synchronize
3. @queue.pop tries to pop the soonest work item, which results in invoking ScheduledTask#schedule_time to sort/compare queue items
4. which tries to lock ScheduledTask.synchronize before accessing @time (scheduled_task.rb:207)

Below I show two threads which are deadlocked in this fashion, showing the issue, and where each thread grabs each lock. One thread is a puma request thread, which ends up calling ScheduledTask#reschedule.

# put_metric_data request #2 (TID-dh2ik puma srv tp 005)
#
# Lock Conditions: 
# - TimerSet: trying to lock
# - ScheduledTask: locked
#
[171733] Thread: TID-dh2ik puma srv tp 005
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in 'synchronize'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in 'synchronize'
#### <---- TRY TO LOCK TimerSet.synchronize ####
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:116:in 'remove_task' 
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:328:in 'ns_reschedule'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:265:in 'block in reschedule' 
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:46:in 'synchronize'
#### <---- LOCK ScheduledTask.synchronize ####
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:265:in 'reschedule'
# SNIP, long puma/rails request backtrace which doesn't use concurrent


# concurrent-ruby scheduled_task (TID-4jpio worker-1)
#
# Lock Conditions: 
# - TimerSet: locked
# - ScheduledTask: trying to lock
#
[171733] Thread: TID-4jpio worker-1
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in 'synchronize'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in 'synchronize'
#### <---- TRY TO LOCK ScheduledTask.synchronize ####
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:207:in 'schedule_time'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:214:in '<=>'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/collection/ruby_non_concurrent_priority_queue.rb:120:in 'ordered?'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/collection/ruby_non_concurrent_priority_queue.rb:133:in 'sink'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/collection/ruby_non_concurrent_priority_queue.rb:70:in 'pop'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:164:in 'block (2 levels) in process_tasks'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in 'block in synchronize'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in 'synchronize'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in 'synchronize'
#### <---- LOCK TimerSet.synchronize ####
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:164:in 'block in process_tasks' 
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:144:in 'loop'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:144:in 'process_tasks'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in 'run_task'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in 'block (3 levels) in create_worker'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in 'loop'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in 'block (2 levels) in create_worker'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in 'catch'
concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in 'block in create_worker'

[snickell]

We have worked around the deadlock by using a custom Concurrent::ScheduledTask subclass that overrides reschedule to take locks in the same order as Concurrent::TimerSet#process_tasks:

class NoDeadlockScheduledTask < Concurrent::ScheduledTask
  def reschedule(delay)
    Concurrent.global_timer_set.send(:synchronize) do
      super(delay)
    end
  end
end

(in our case we're using the global timer_set (default), if you override timer_set, you'll need to call synchronize on your instance)

[bensheldon]

@snickell thank you for the report and the excellent analysis! Those look like clear conditions for a deadlock to me.

I'll take a longer look at this, but it seems to me that there are several places in ScheduledTask that potentially lock the ScheduledTask before the TimerSet is locked and it would be good to get all of those locks properly ordered. I think the "correct" hierarchy is to always do the collection object locks (the Timerset) before the individual objects locks (the ScheduledTask.

Thanks again! Please make a PR if you're available to.

[snickell]

I'm happy to take a pass at it. Its a little awkward to have the child (ScheduledTask) explicitly lock the collection (TimerSet) before calling into it in multiple places, but I agree its the correct hierarchy functionally even if the encapsulation is a little meh.

Alternatively, afaict there's only two places where TimerSet#process_tasks locks ScheduledTask, both via calls to ScheduledTask#schedule_time, which does synchronize { @time }. If schedule_time didn't call synchronize to guard access to @time (is it needed?), the whole chain of deadlockery would unwind. Elegant if possible+safe.

[snickell]

I'm not a Ruby expert, but shouldn't the GVL mean that simple assignment to an @instance_variable won't cause a state tear? I.e. its functionally atomic from within Ruby code?

I only see two references to @time in ScheduledTask:

A read wrapped in the lone synchronize causing the lock inversion:

    def schedule_time
      synchronize { @time }
    end

A simple assignment

    def ns_schedule(delay)
      @delay = delay
      @time = Concurrent.monotonic_time + @delay
      @parent.send(:post_task, self)
    end

Million dollar question: is the synchronize() in schedule_time actually needed for thread-safety? Because I believe removing that would remove the whole class of deadlocks. My initial guess is "not needed".

[snickell]

After reading about how JRuby handles volatility, I think perhaps using Concurrent's own attr_volatile might be the way to go for the "remove synchronize from schedule_time()" idea:

class ScheduledTask < IVar
  attr_volatile :scheduled_time

  def ns_schedule(delay)
    @delay = delay
    self.scheduled_time = Concurrent.monotonic_time + @delay
    @parent.send(:post_task, self)
  end
end

After scanning the codebase, I haven't found a reason its unsafe to modify @time while leaving the rest of the object unlocked, largely because scheduled_task.rb doesn't actually read @time itself internally.

@bensheldon Happy to draft a PR in this flavor, or in the slightly less spicy "wrap several methods in ScheduledTask in TimerSet.synchronize blocks" flavor, as your judgement leads.