_notes.md

Things to know

• Lobsters doesn't use Puma's preload_app! because it relies on phased restarts. This seem to cause massive GVL contention after a deploy.
• Would be worth trying to exclude that data, but aside from the very begining it's not clear where deploys are in the dataset. Need to check with @pushcx.

Observations

• The IO heavy requests are in the higher percentile.
• IO heavy requests are the one suffering the most from GVL contention.
  • Which makes sense, the more IO you do, the more you need to re-acquire the GVL, so the most you suffer if it is contented.
• Same controller actions have a very wide range of IO vs CPU
  • Could be because of very different datasets returned by the parameters (e.g story with handful of comments, vs story with hundreds of comments)
  • Could be that the DB sometimes suffer from some locking, making IOs much longer.

Missed opportunities

• Would be interesting to improve gvl_timing gem to include the number of GVL_READY event, so that we have a number of IOs in addition to the total duration.
• Request realtime would have been nice to log as well.
• Request datetime would have nice to log as well, so that we could see correlations between spikes of traffic and contention, this sorts of things.
• Logging the pid would have allowed to do per worker analysis.

lobsters-timings.md

Data set: https://gist.github.com/byroot/e1fcfd1f8e172f5d9c5bfecefebdb15f#file-production-gvl-log

total io%: 40.07

total io and stall%: 48.81

average response time ms: 81.49

average stall ms: 11.88

---

overall 618474 requests

overall	cpu	io	GVL	total	io%	count
p0-10	5.6	0.1	0.0	5.8	1.5%	61849
p50-60	34.8	8.8	0.2	43.7	20.2%	61849
p90-99	130.7	123.7	29.8	284.1	48.6%	55658
p99-99.9	180.2	744.5	345.1	1269.8	80.5%	5566
p99.9-100	261.0	1889.5	1969.8	4120.2	87.9%	618

home#index 184341 requests

home#index	cpu	io	GVL	total	io%	count
p0-10	15.5	2.5	0.0	18.0	13.9%	18436
p50-60	31.6	4.2	0.1	35.9	11.7%	18436
p90-99	101.4	97.1	44.2	242.7	48.9%	16583
p99-99.9	138.3	373.6	473.2	985.1	73.0%	1659
p99.9-100	286.6	1064.7	2933.9	4285.2	78.8%	184

stories#show 155152 requests

stories#show	cpu	io	GVL	total	io%	count
p0-10	19.1	7.3	0.0	26.3	27.6%	15517
p50-60	47.6	17.1	0.1	64.7	26.4%	15517
p90-99	106.4	155.2	37.8	299.4	59.3%	13957
p99-99.9	158.7	494.2	265.9	918.8	75.7%	1396
p99.9-100	266.0	997.9	2706.7	3970.6	79.0%	155

rack middleware 101819 requests

	cpu	io	GVL	total	io%	count
p0-10	3.2	0.0	0.0	3.3	0.8%	10183
p50-60	7.4	0.2	0.0	7.7	2.2%	10183
p90-99	13.0	9.6	46.2	68.9	42.4%	9163
p99-99.9	23.5	54.1	201.2	278.9	69.7%	917
p99.9-100	64.8	657.2	1234.6	1956.7	91.0%	101

users#show 62836 requests

users#show	cpu	io	GVL	total	io%	count
p0-10	9.6	1.8	0.0	11.5	16.1%	6285
p50-60	15.0	2.6	0.0	17.6	14.6%	6285
p90-99	25.6	12.7	76.6	114.8	33.1%	5652
p99-99.9	53.3	101.9	250.8	405.9	65.6%	566
p99.9-100	103.1	711.4	1866.2	2680.7	87.3%	62

home#single_tag 37584 requests

home#single_tag	cpu	io	GVL	total	io%	count
p0-10	29.9	3.5	0.0	33.4	10.4%	3760
p50-60	130.2	62.2	2.4	194.9	32.3%	3760
p90-99	227.0	132.7	47.0	406.8	36.9%	3378
p99-99.9	371.2	475.6	799.1	1645.9	56.2%	338
p99.9-100	424.9	1331.6	3407.5	5164.0	75.8%	37

lobsters.rb

require 'bundler/inline'

gemfile do
  gem 'activesupport'
  gem 'markdown-tables'
end

require 'json'
require 'active_support/all'

path = ARGV.first

class Request
  attr_reader :gc_ms, :run_ms, :idle_ms, :stall_ms, :io_percent, :method, :action

  def initialize(hash)
    @gc_ms = hash[:gc_ms]
    @run_ms = hash[:run_ms]
    @idle_ms = hash[:idle_ms]
    @stall_ms = hash[:stall_ms]
    @io_percent = hash[:io_percent]
    @method = hash[:method]
    @action = hash[:action]
  end

  def total_ms
    @run_ms + @idle_ms + @stall_ms
  end
end

requests = []
File.open(path).each_line do |line|
  requests << Request.new(JSON.parse(line, symbolize_names: true, freeze: true))
end

puts "Data set: https://gist.github.com/byroot/e1fcfd1f8e172f5d9c5bfecefebdb15f#file-production-gvl-log"
puts

print "total io%: "
total_run_ms = requests.sum(&:run_ms)
total_idle_ms = requests.sum(&:idle_ms)
puts ((total_idle_ms / (total_run_ms + total_idle_ms)) * 100.0).round(2)
puts

print "total io and stall%: "
total_stall_ms = requests.sum(&:stall_ms)
puts (((total_idle_ms + total_stall_ms) / (total_run_ms + total_idle_ms + total_stall_ms)) * 100.0).round(2)
puts

print "average response time ms: "
puts ((total_stall_ms + total_run_ms + total_idle_ms) / requests.size).round(2)
puts

print "average stall ms: "
puts (total_stall_ms / requests.size).round(2)
puts
puts

puts '-' * 10

def avg(data, &block)
  data.sum(&block) / data.size
end

def row(name, group)
  io_percent = (group.sum(&:idle_ms) / (group.sum(&:run_ms) + group.sum(&:idle_ms))) * 100.0
  [
    name,
    avg(group, &:run_ms).round(1),
    avg(group, &:idle_ms).round(1),
    avg(group, &:stall_ms).round(1),
    avg(group, &:total_ms).round(1),
    "#{io_percent.round(1)}%",
    group.size,
  ]
end

def compute_percentiles(action, requests)
  puts "### #{action || 'rack middleware'} #{requests.size} requests"
  puts

  requests.sort_by!(&:total_ms)

  decile = ((requests.size / 10.0).ceil)
  first_decile = requests[0..decile]
  mid_decile = requests[(5*decile)..(6*decile)]
  last_decile = requests[(9 * decile)..-1]
  percentile = decile / 10
  last_percentile = last_decile.slice!((-percentile)..-1)
  mill = percentile / 10
  last_mill = last_percentile.slice!((-mill)..-1)

  labels = [action, "cpu", "io", "GVL", "total", "io%", "count"]

  rows = [
    row("p0-10", first_decile),
    row("p50-60", mid_decile),
    row("p90-99", last_decile),
    row("p99-99.9", last_percentile),
    row("p99.9-100", last_mill),
  ]

  puts MarkdownTables.make_table(labels, rows, is_rows: true)
  puts
  puts
end

compute_percentiles("overall", requests)

requests_by_action = requests.group_by(&:action).sort_by { |_a, r| -r.size }
requests_by_action.first(5).each do |action, requests|
  compute_percentiles(action, requests)
end