I was taking a look at the implementation for reporting the time spent on each part of an action processing.
Rails, by default will report timing for the view and db (ActiveRecord).
Both use class attributes for storing the timing (or accumulating them in the case of AR), which are shared among all threads.
This is fine if you're deploying using the fork approach, like done by Passenger or Unicorn (my current case), but once you decide to use a multi-threaded deployment strategy, like using Puma or Warbler on JRuby, those reported numbers are no longer reliable, specially under high load.
Maybe implementing them using thread locals (Thread.current[:foo]) would be more friendly to such environments.
It isn't a perfect solution as it won't report correct timings (whatever the correct definition would be) for some action like:
def some_action render json: Hash[[:sections, :fields].zip [ Thread.start {Section.all.to_a}, Thread.start {Field.all.to_a}, ].map &:value] end
But in that case, I don't even know how this should be reported ideally. For instance, suppose Section.all.to_a takes 50ms from DB while Field.all.to_a takes 70ms.
How would you explain an output like this?
Action completed in 80ms (view: 5ms, db: 120ms)
So, except for such cases, using thread locals would yield to more reliable results in the production logs for a quick inspect.
Is the overhead of using Thread.current so high when compared to "self.runtime"?
Cheers, Rodrigo.
