Gnuplot Heroku runtime metrics

.gitignore

*.tsv
*.gz
*.dat
*.png
*.json

gnuplot

#!/usr/bin/env gnuplot

set terminal png size 1800, 800
set output "memory.png"
set title "app memory and performance"

set xdata time
set timefmt "%s"

set grid
set xtics 86400
set key outside

set y2tics

set style line 1 lc rgb '#0060ad' lt 1 lw 2 pi -1 ps 1.0
set style line 2 lc rgb '#dd181f' lt 9 lw 2 pi -1 ps 1.0
set style line 3 lc rgb '#ffa500' lt 9 lw 1 pi -1 ps 1.0

# limit x range like this:
#plot [1490572804:1494374383]

# date -v-2w -j -f "%a %b %d %T %Z %Y" "`date`" "+%s"
#"releases.dat" using 1:(0):(0):(360) notitle with vectors ls 3 nohead, \

# date -u -v-2w +%s
# date -u -j -f '%F' "2017-08-01" +%s
# date -u -j -f '%F' "2017-10-01" +%s

plot [1506822212:] \
     "releases.dat" using 1:(440):2 notitle with labels offset 0,char 1.1 rotate by 45, \
     "memory.dat" using 1:2 title "total" with lines, \
     "" using 1:3 title "rss" with lines, \
     "" using 1:6 title "pgin" with line ls 1 axes x1y2, \
     "" using 1:7 title "pgout" with line ls 2 axes x1y2, \
     "" using 1:4 title "cache" with lines ls 1, \
     "" using 1:5 title "swap" with lines, \
     "rpm.dat" using 1:($2+200) title "rpm-GET" with lines, \
     "" using 1:($3+300) title "rpm-HEAD" with lines, \
     "cpu.dat" using ($1):($2+200) title "load-avg-1m" with lines, \
     "error.dat" using 1:(500):2 notitle with labels offset 0,char 1.1 rotate by 45 textcolor rgb 'red'

parse-papertrail.rb

#!/usr/bin/env ruby
# https://devcenter.heroku.com/articles/log-runtime-metrics
# http://help.papertrailapp.com/kb/how-it-works/permanent-log-archives/
# ./parse-papertrail.rb < 2017-03-28.tsv

require "date"

c = %w[id generated_at received_at source_id source_name source_ip facility_name severity_name program message].map.with_index { |k,i| [i, k.to_sym] }.to_h

metric = ARGV[0] || "memory"

last_t = nil
num_requests = { "GET" => 0, "HEAD" => 0 }
rpm_bucket_size = 60*60
# pry_continue = true

while STDIN.gets
  cols = $_.split("\t").map.with_index { |v,i| [c[i], v] }.to_h
  # puts cols.map.with_index { |v,i| [c[i], v] }.to_h
  next if (%w[memory cpu].include?(metric)) and (cols[:program] != "heroku/web.1" or !cols[:message].start_with?("source=web.1 dyno=heroku"))
  next if (%w[rpm error].include?(metric)) and cols[:program] != "heroku/router"

  t = DateTime.strptime(cols[:received_at], "%FT%TZ")

  data = cols[:message].scan(/([^= ]+)=(?:"([^"]+)"|([^ ]+))/).map { |k,v1,v2| [k, v1 || v2] }.to_h if %w[memory cpu rpm error].include?(metric)

  next if metric == "error" and data["at"] != "error"

  # ./parse-papertrail.rb < appname/2017-03-28.tsv
  # data.each do |k,v|
  #   next if !k.start_with?("sample#memory_")
  #   puts "#{k["sample#".length..-1]}: #{v}"
  # end
  # break

  if metric == "memory" and data["sample#memory_total"]
    puts "#{t.strftime("%s")} #{data["sample#memory_total"]} #{data["sample#memory_rss"]} #{data["sample#memory_cache"]} #{data["sample#memory_swap"]} #{data["sample#memory_pgpgin"]} #{data["sample#memory_pgpgout"]}"
  elsif metric == "cpu" and data["sample#load_avg_1m"]
    puts "#{t.strftime("%s")} #{data["sample#load_avg_1m"]} #{data["sample#load_avg_5m"]} #{data["sample#load_avg_15m"]}"
  elsif metric == "rpm"
    last_t = t if !last_t
    method = data["method"]
    # if pry_continue
    #   require "pry"; Pry.config.input = IO.new(IO.sysopen("/dev/tty","r+")); binding.pry
    # end
    diff = t.strftime("%s").to_i - last_t.strftime("%s").to_i
    if diff >= rpm_bucket_size
      t_clamped = last_t.strftime("%s").to_i
      t_seconds = t_clamped % rpm_bucket_size
      t_clamped = t_clamped - t_seconds + rpm_bucket_size/2
      puts "#{t_clamped} #{num_requests["GET"]} #{num_requests["HEAD"]}"
      num_requests = { "GET" => 0, "HEAD" => 0 }
      last_t = t
    end
    num_requests[method] ||= 0
    num_requests[method] += 1
  elsif metric == "error"
    puts "#{t.strftime("%s")} #{data["code"]} #{data["status"]}"
  end
end

if metric == "rpm" && num_requests.values.any? { |v| v > 0 }
  # This timestamp might need adjusting
  puts "#{last_t.strftime("%s").to_i-last_t.second} #{num_requests["GET"]} #{num_requests["HEAD"]}"
end

if t.hour != 23 && t.minute != 59
  puts ""
end

# memory_total: 352.30MB
# memory_rss: 346.89MB
# memory_cache: 1.08MB
# memory_swap: 4.34MB
# memory_pgpgin: 219355pages
# memory_pgpgout: 130276pages
# memory_quota: 512.00MB

process.sh

#!/bin/bash -e
if [ "$1" == "flush" ]; then
  rm -f date
fi
if [ -e date ]; then
  starttime=$(date -u -j -f '%FT%H:%M:%SZ' "$(cat date)T00:00:00Z" +%s)
else
  rm -f memory.dat cpu.dat rpm.dat error.dat
  starttime=$(date -u -j -f '%FT%H:%M:%SZ' "2017-10-01T00:00:00Z" +%s)
  ((starttime--))
fi

find rssbox -name '*.tsv' | sort | while read -r f; do
  if [[ $f =~ dt=(.+)/ ]]; then
    dt=${BASH_REMATCH[1]}
    unixtime=$(date -u -j -f '%FT%H:%M:%SZ' "${dt}T00:00:00Z" +%s)
    if (( $unixtime <= $starttime )); then
      continue
    fi
    echo "$dt" > date
  else
    continue
  fi

  echo "$f"
  ./parse-papertrail.rb memory < "$f" >> memory.dat &
  ./parse-papertrail.rb cpu < "$f" >> cpu.dat &
  ./parse-papertrail.rb rpm < "$f" >> rpm.dat &
  ./parse-papertrail.rb error < "$f" >> error.dat &
  wait # running multiple jobs gives me a 3x speed improvement
done
./gnuplot

releases.sh

#!/bin/bash
mkdir -p backups
mv releases.json backups/releases.old.$(date +%F-%H-%M-%S).json
if [[ ! -f "releases.json" ]]; then
  app=appname
  heroku_token=$(heroku auth:token)
  curl -s -H "Range: ; max=1000" -H "Accept: application/vnd.heroku+json; version=3" -u ":$heroku_token" "https://api.heroku.com/apps/$app/releases" -o releases.json
fi

rm releases.dat
cat releases.json | jq -Mr 'map(select(.description | startswith("Deploy") or startswith("Rollback")))[] | [.created_at, .version|tostring] | join(" ")' | while read date ver; do
  unixtime=$(date -u -j -f '%FT%TZ' "$date" +%s)
  if [[ "$ver" == "203" ]]; then
    text="heroku-16"
  elif [[ "$ver" == "220" ]]; then
    text="http"
  elif [[ "$ver" == "232" ]]; then
    text="yajl"
  elif [[ "$ver" == "233" ]]; then
    text="freeze"
  elif [[ "$ver" == "253" ]]; then
    text="gems"
  elif [[ "$ver" == "254" ]]; then
    text="ruby2.5"
  elif [[ "$ver" == "324" ]]; then
    text="ruby2.6"
  else
    text="v$ver"
  fi
  echo "$unixtime $text" >> releases.dat
done

sync.sh

#!/bin/bash
aws s3 sync s3://bucket-papertrail/heroku/ .

find appname -name '*.tsv.gz' | while read -r f; do
  if [[ ! -f "${f%.*}" ]]; then
    gunzip -k "$f"
  fi
done