Skip to content

Instantly share code, notes, and snippets.

@jrafanie

jrafanie/cow_wat.rb

Last active January 22, 2016 22:32
Show Gist options
  • Save jrafanie/d74824add7b2a22acb30 to your computer and use it in GitHub Desktop.
Save jrafanie/d74824add7b2a22acb30 to your computer and use it in GitHub Desktop.
Download ZIP
Unexpected copy on write
Raw
cow_wat.rb
# From: http://stackoverflow.com/questions/30353272/garbage-collector-in-ruby-2-2-provokes-unexpected-cow
# Modified to use rails and bundler/inline magic to load rails instead of creating a big object
require 'bundler'
begin
require 'bundler/inline'
rescue LoadError => e
$stderr.puts 'Bundler version 1.10 or later is required. Please update your Bundler'
raise e
end
Bundler.ui.level = "error"
gemfile(true) do
source 'https://rubygems.org'
gem 'rails', "4.2.5"
gem 'sqlite3'
gem 'fog'
gem 'mime-types'
end
require 'active_record'
require 'logger'
$start_time = Time.new
# Monitor use of Resident and Virtual memory.
class Memory
shared_dirty = '.+?Shared_Dirty:\s+(\d+)'
priv_dirty = '.+?Private_Dirty:\s+(\d+)'
MEM_REGEXP = /#{shared_dirty}#{priv_dirty}/m
# get memory usage
def self.get_memory_map(pids)
memory_map = {}
memory_map[:pids_found] = {}
memory_map[:shared_dirty] = 0
memory_map[:priv_dirty] = 0
pids.each do |pid|
begin
lines = nil
lines = File.read("/proc/#{pid}/smaps")
rescue
lines = nil
end
if lines
lines.scan(MEM_REGEXP) do |shared_dirty, priv_dirty|
memory_map[:pids_found][pid] = true
memory_map[:shared_dirty] += shared_dirty.to_i
memory_map[:priv_dirty] += priv_dirty.to_i
end
end
end
memory_map[:pids_found] = memory_map[:pids_found].keys
return memory_map
end
# get the processes and get the value of the memory usage
def self.memory_usage
pids = [$$]
result = self.get_memory_map(pids)
result[:pids] = pids
return result
end
# print the values of the private and shared memories
def self.log(process_name='', log_tag="")
count, minor, major = GC.stat.values_at(:count, :minor_gc_count, :major_gc_count)
if process_name == "header"
$stderr.puts " %-6s %5s %-25s %10s %10s %5s %5s %5s\n" % ["process", "pid", "log", "priv_dirty", "shared_dirty", "count", "minor", "major"]
else
time = Time.new - $start_time
mem = Memory.memory_usage
$stderr.puts " %-6s %5d %-25s %10d %10d %5d %5d %5d\n" % [process_name, $$, log_tag, mem[:priv_dirty] / 1000, mem[:shared_dirty] / 1000, count, minor, major]
end
end
end
# function to delay the processes a bit
def time_step(n)
while Time.new - $start_time < n
sleep(0.01)
end
end
##### main #####
$stderr.puts "ruby version #{RUBY_VERSION}"
GC.disable
# print the column headers and first line
Memory.log("header")
Memory.log("Parent", "post alloc")
lab_time = Time.new - $start_time
if lab_time < 3.9
lab_time = 0
end
count = rand(4)
count.times do
GC.enable; GC.start; GC.disable
end
Memory.log("Parent", "pre-fork GC #{count} times")
# start the forking
pid = fork do
Memory.log("Child", "initial")
time = rand(4)
time_step(time + lab_time)
Memory.log("Child", "#{time} initial")
3.times do
# force GC when nothing happened
GC.enable; GC.start; GC.disable
time = 4
time_step(time + lab_time)
Memory.log("Child", "#{time} empty GC")
end
sleep(1)
STDOUT.flush
exit!
end
time = rand(4)
time_step(time + lab_time)
Memory.log("Parent", "#{time} fork")
count = rand(4)
count.times do
GC.enable; GC.start; GC.disable
end
Memory.log("Parent", "After fork GC #{count} times")
# wait for the child to finish
Process.wait(pid)
Raw
output.log
[root@localhost ~]# for x in 1 2 3 4 5 6 7 8 9 10; do ruby fork_gc_not_cow_friendly.rb 1> /dev/null; done;
ruby version 2.2.4
process pid log priv_dirty shared_dirty count minor major
Parent 18539 post alloc 84 0 11 8 3
Parent 18539 pre-fork GC 1 times 84 0 12 8 4
Child 18542 initial 18 66 12 8 4
Child 18542 0 initial 21 63 12 8 4
Parent 18539 1 fork 35 48 12 8 4
Parent 18539 After fork GC 3 times 35 48 15 8 7
Child 18542 4 empty GC 36 48 13 8 5
Child 18542 4 empty GC 36 48 14 8 6
Child 18542 4 empty GC 36 48 15 8 7
ruby version 2.2.4
process pid log priv_dirty shared_dirty count minor major
Parent 18545 post alloc 84 0 11 8 3
Parent 18545 pre-fork GC 3 times 84 0 14 8 6
Child 18548 initial 0 84 14 8 6
Parent 18545 1 fork 1 83 14 8 6
Child 18548 1 initial 1 83 14 8 6
Parent 18545 After fork GC 1 times 16 68 15 8 7
Child 18548 4 empty GC 17 67 15 8 7
Child 18548 4 empty GC 17 67 16 8 8
Child 18548 4 empty GC 17 67 17 8 9
ruby version 2.2.4
process pid log priv_dirty shared_dirty count minor major
Parent 18552 post alloc 84 0 11 8 3
Parent 18552 pre-fork GC 3 times 84 0 14 8 6
Child 18555 initial 0 84 14 8 6
Child 18555 1 initial 1 83 14 8 6
Parent 18552 2 fork 16 68 14 8 6
Parent 18552 After fork GC 3 times 16 68 17 8 9
Child 18555 4 empty GC 16 67 15 8 7
Child 18555 4 empty GC 17 67 16 8 8
Child 18555 4 empty GC 17 67 17 8 9
ruby version 2.2.4
process pid log priv_dirty shared_dirty count minor major
Parent 18558 post alloc 84 0 11 8 3
Parent 18558 pre-fork GC 3 times 84 0 14 8 6
Parent 18558 0 fork 5 78 14 8 6
Child 18561 initial 5 78 14 8 6
Parent 18558 After fork GC 2 times 19 65 16 8 8
Child 18561 1 initial 19 64 14 8 6
Child 18561 4 empty GC 20 64 15 8 7
Child 18561 4 empty GC 20 63 16 8 8
Child 18561 4 empty GC 20 63 17 8 9
ruby version 2.2.4
process pid log priv_dirty shared_dirty count minor major
Parent 18564 post alloc 84 0 11 8 3
Parent 18564 pre-fork GC 1 times 84 0 12 8 4
Parent 18564 0 fork 0 84 12 8 4
Child 18567 initial 0 84 12 8 4
Child 18567 0 initial 1 82 12 8 4
Parent 18564 After fork GC 3 times 22 62 15 8 7
Child 18567 4 empty GC 23 61 13 8 5
Child 18567 4 empty GC 23 61 14 8 6
Child 18567 4 empty GC 23 61 15 8 7
ruby version 2.2.4
process pid log priv_dirty shared_dirty count minor major
Parent 18570 post alloc 84 0 11 8 3
Parent 18570 pre-fork GC 0 times 84 0 11 8 3
Child 18577 initial 4 80 11 8 3
Child 18577 2 initial 7 77 11 8 3
Parent 18570 3 fork 63 20 11 8 3
Parent 18570 After fork GC 2 times 64 20 13 8 5
Child 18577 4 empty GC 64 20 12 8 4
Child 18577 4 empty GC 64 20 13 8 5
Child 18577 4 empty GC 64 20 14 8 6
ruby version 2.2.4
process pid log priv_dirty shared_dirty count minor major
Parent 18580 post alloc 84 0 11 8 3
Parent 18580 pre-fork GC 0 times 84 0 11 8 3
Child 18583 initial 2 82 11 8 3
Child 18583 1 initial 5 79 11 8 3
Parent 18580 1 fork 5 79 11 8 3
Parent 18580 After fork GC 0 times 8 76 11 8 3
Child 18583 4 empty GC 66 19 12 8 4
Child 18583 4 empty GC 66 18 13 8 5
Child 18583 4 empty GC 66 18 14 8 6
ruby version 2.2.4
process pid log priv_dirty shared_dirty count minor major
Parent 18587 post alloc 84 0 11 8 3
Parent 18587 pre-fork GC 3 times 84 0 14 8 6
Parent 18587 0 fork 20 64 14 8 6
Child 18590 initial 20 64 14 8 6
Child 18590 0 initial 34 50 14 8 6
Parent 18587 After fork GC 1 times 45 39 15 8 7
Child 18590 4 empty GC 46 38 15 8 7
Child 18590 4 empty GC 46 38 16 8 8
Child 18590 4 empty GC 46 38 17 8 9
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment