Possible severe impact on resque performance

[paneq]

I described the investigation process deeply in my blogpost

TLDR:

Sometimes this 60s sleep in ensure block is reached after resque child finished processing a job. Ruby might wait for this thread to finish and in that time for one minute resque is waiting for the child process with Honeybadger thread to die. Until this happens resque is not processing new jobs.

  def work
    flush_metrics if metrics.flush?
    flush_traces if traces.flush?
  rescue StandardError => e
    error {
      msg = "error in agent thread class=%s message=%s\n\t%s"
      sprintf(msg, e.class, e.message.dump, Array(e.backtrace).join("\n\t"))
    }
  ensure
    sleep(delay)
  end

Related Ruby bug: https://bugs.ruby-lang.org/issues/12298

[joshuap]

Thanks for reporting! This is a weird one; interested to hear what the Ruby team has to say. In any case, we'll take a closer look at this also.

[joshuap]

After studying this some more I'm thinking the solution in our case is to just not sleep during the ensure block. I think we can avoid this entirely with something like:

  def work
    flush_metrics if metrics.flush?
    flush_traces if traces.flush?
    sleep(delay)
  rescue StandardError => e
    error {
      msg = "error in agent thread class=%s message=%s\n\t%s"
      sprintf(msg, e.class, e.message.dump, Array(e.backtrace).join("\n\t"))
    }
    sleep(delay)
  end

(assuming the rescue isn't invoked when the thread is killed.) I should have a fix this week.

@paneq Really great writeup, btw.

[mbell697]

In general using Thread.kill is not safe, the best solution is to not rely on it. In particular this bit of code is also extremely suspect:

honeybadger-ruby/lib/honeybadger/agent/worker.rb

Line 86 in 84ba2d3

thread.join # Allow ensure blocks to execute.

.