What’s happening in your Rails app?
Introduction to
Introspection features of Ruby
Koichi Sasada
ko1@heroku.com

K.Sasada: What's happening in your Rails app? RailsConf2015

1

Short summary of this presentation
What’s happening in your Rails app?

GOOGLE IT• You can use many existing tools
to inspect your Rails application.

MAKE IT• Ruby/MRI provides many lowlevel features to make tools.
K.Sasada: What's happening in your Rails app? RailsConf2015

2

Koichi Sasada is a Programmer• MRI committer since 2007/01• Original YARV developer since 2004/01• YARV: Yet Another RubyVM• Introduced into Ruby (MRI) 1.9.0 and later• Introduce generational/incremental GC• Not a Rails programmer • C language programmer• My wife is a professional Rails dev 
K.Sasada: What's happening in your Rails app? RailsConf2015

3

Koichi is an Employee

Heroku: A Year in Review
Sponsor session
2:40PM-3:20PM@204H
K.Sasada: What's happening in your Rails app? RailsConf2015

4

Koichi is a member of Heroku Matz team
MissionDesign Ruby language
and improve quality of MRI
Heroku employs three full time Ruby core developers inJapan named “Matz team”
K.Sasada: What's happening in your Rails app? RailsConf2015

5

Heroku Matz team
Matz

Nobu
Ko1

Designer/director of Ruby
Quite active committer
Internal Hacker
6

Matz
Title collector• He has so many (job) title• Chairman - Ruby Association• Fellow - NaCl
• Chief architect, Ruby - Heroku• Research institute fellow – Rakuten• Chairman – NPO mruby Forum• Senior researcher – Kadokawa Ascii Research Lab• Visiting professor – Shimane University• Honorable citizen (living) – Matsue city
• Honorable member – Nihon Ruby no Kai• …

• This margin is too narrow to contain
K.Sasada: What's happening in your Rails app? RailsConf2015

7

Nobu
Great Patch monster

Ruby’s bug|> Fix Ruby|> Break Ruby|> And Fix Ruby
K.Sasada: What's happening in your Rails app? RailsConf2015

8

Nobu
Patch monster
COMMITRATIOIN LAST 5 YEARS
charliesom
shirosaki
sorah
tarui
xibbarryan
eregonwanabenagai
luislavena
ngoto
takano32
davidflanag
kanemotoa_matsuda
technoram
duerstiwamatsu
azav
keiju
murakensuke
kouji
gotokenheadius
arton
tmm1
jeg2
hsbt
okkez
eban
seki
evan
ayumin
nahi
ktsj
glass
nari
shyouheiembossmrkn
koue0%
yugui
nagachika
0%
0%
0%
0%
0%
0%
0%
0%
0%
0%
0%
0%
0%
an
a
0%
0%
0%
shugo
1%
1%
1%0%
knu
1%
nobu
1%
0%
tadf
1%
1%
mame
29%
2%
marcandre
2%
matz
2%
tenderlove
2%zzak
2%kazu2%
kosaki2%3%drbrain
3% ko1akr
naruse
svn
12%
4%usa
4% 8%
9%

Commit count of MRI

9

Ko1
EDD developer
EurukoCommit number of ko1 (last 3 years)
2013
RubyKaigi
2013
RubyConf
RubyConf
2012
2013

25

20

15

Ruby 2.0
105

EDD: Event Driven Development
K.Sasada: What's happening in your Rails app? RailsConf2015

2013/11/8

2013/9/8

2013/7/8

2013/5/8

2013/3/8

2013/1/8

2012/11/8

2012/9/8

2012/7/8

2012/5/8

2012/3/8

2012/1/8

2011/11/8

2011/9/8

2011/7/8

2011/5/8

2011/3/8

2011/1/8

2010/11/8

010Heroku Matz team and Ruby core team
Recent achievement

Ruby 2.2

http://www.flickr.com/photos/loginesta/5266114104

Current stable

K.Sasada: What's happening in your Rails app? RailsConf2015

11

Ruby 2.2
Syntax• Symbol key of Hash literal can be quoted{“foo-bar”: baz}#=> {:“foo-bar” => baz}#=> not {“foo-bar” => baz} like JSON

TRAP!!
Easy to misunderstand(I wrote a wrong code, already…)
K.Sasada: What's happening in your Rails app? RailsConf2015

12

Ruby 2.2
Classes and Methods• Some methods are introduces• Kernel#itself• String#unicode_normalize• Method#curry• Binding#receiver• Enumerable#slice_after, slice_before• File.birthtime• Etc.nprocessors•…
K.Sasada: What's happening in your Rails app? RailsConf201513

Ruby 2.2
Improvements• Improve GC• Symbol GC• Incremental GC• Improved promotion algorithm• Young objects promote after 4 GCs• Fast keyword parameters• Use frozen string literals if possible
K.Sasada: What's happening in your Rails app? RailsConf2015

14

Ruby 2.2
Symbol GC
before = Symbol.all_symbols.size
1_000_000.times{|i| i.to_s.to_sym} # Make 1M symbols
after = Symbol.all_symbols.size; p [before, after]# Ruby 2.1#=> [2_378, 1_002_378] # not GCed # Ruby 2.2#=> [2_456, 2_456] # GCed! 
K.Sasada: What's happening in your Rails app? RailsConf2015

15

Ruby 2.2
Symbol GC (cont.)
TRAP!!
Ruby 2.2.0 has memory leak error!

•Upgrade Ruby 2.2.2• Memory (object) leak problem• Symbols has corresponding String objects• Symbols are collected, but Strings are not collected! (leak)• Ruby 2.2.1 solved this problem!!
• However, 2.2.1 also has problem (rarely you encounter BUG at the end of process [Bug#10933] ← not big issue, I want to believe)• Finally Ruby 2.2.2 had solved it!!
K.Sasada: What's happening in your Rails app? RailsConf2015

16

Ruby 2.2
Fast keyword parameters
Execution time (sec)“Keyword parameters” introduced in Ruby 2.0 is useful, but slow!!
20

Evaluation on Ruby 2.1

15x30 slower

1050foo6(1, 2, 3, 4, 5, 6)

foo_kw6(k1: 1, k2: 2, k3: 3, k4: 4, k5: 5, k6: 6)

Repeat 10M times
K.Sasada: What's happening in your Rails app? RailsConf201517

Ruby 2.2
Fast keyword parameters
Execution time (sec)

Ruby 2.2 optimizes method dispatch with keyword parameters
20
15

x14 faster!!

10
50foo6(1, 2, 3, 4, 5, 6)

foo_kw6(k1: 1, k2: 2, k3: 3, k4: 4, k5: 5, k6: 6)

Repeat 10M times

Ruby 2.1

But still x2 times slower

Ruby 2.2 compare with normal dispatch

K.Sasada: What's happening in your Rails app? RailsConf201518

Ruby 2.2
Incremental GC

Goal
BeforeRuby 2.1
Ruby 2.1 RGenGC
Throughput
Pause time

Low
Long

High
Long

Incremental
GC
Low
Short

K.Sasada: What's happening in your Rails app? RailsConf2015

Ruby 2.2
Gen+IncGC

High
Short

19

RGenGC from Ruby 2.1: Micro-benchmark
3000

Time (ms)

2500
2000

704.843669

x2.5 faster

1500
1000

1699.805974

500

867.740319

087.230735
RGenGCnototal marktotal sweep

K.Sasada: What's happening in your Rails app? RailsConf2015

20

RGenGC from Ruby 2.1: Pause time
Most of cases, FASTER (w/o rgengc)
K.Sasada: What's happening in your Rails app? RailsConf2015

21

RGenGC from Ruby 2.1: Pause time
Several peaks (w/o rgengc)
K.Sasada: What's happening in your Rails app? RailsConf2015

22

Ruby 2.2 Incremental GC
Short pause time 

K.Sasada: What's happening in your Rails app? RailsConf2015

23

Ruby 2.3

http://www.flickr.com/photos/adafruit/8483990604

Next version will be released the end of this year
Catch me and give me your feedback later
K.Sasada: What's happening in your Rails app? RailsConf201524http://www.flickr.com/photos/donkeyhotey/8422065722

Break

K.Sasada: What's happening in your Rails app? RailsConf2015

25

What’s happening in your Rails app?
Introduction to
Introspection features of Ruby

Today’s topic#駄洒落クラブK.Sasada: What's happening in your Rails app? RailsConf2015

26

#駄洒落クラブ (DAJARE Club)• DAJARE is something like PUN in Japanese• #駄洒落クラブ is associated by our HERO Aaron
Patterson @tenderlove• Many (Japanese) Rubyists have joined• Recommendation: Join our club if you arelearning Japanese
K.Sasada: What's happening in your Rails app? RailsConf2015

27

#駄洒落クラブ (DAJARE Club)

K.Sasada: What's happening in your Rails app? RailsConf2015

28

Introspection features of Ruby

for MRI

K.Sasada: What's happening in your Rails app? RailsConf2015

29

Launch your applicationon the Layered computer structureYour Rails app
Framework / Libraries / Tools

Ruby interpreter
Operating System
Hardware
K.Sasada: What's happening in your Rails app? RailsConf201530

Launch your applicationon the Layered computer structureYour Rails app
Framework / Libraries / Tools

Ruby interpreter

Black box

Operating System
Hardware
K.Sasada: What's happening in your Rails app? RailsConf2015

31

Launch your applicationon the Layered computer structureYour Rails app (3 days later)
Framework / Libraries / Tools

Ruby interpreter

Black box

Operating System
Hardware
K.Sasada: What's happening in your Rails app? RailsConf2015

32

Trouble will come from a black box
Performanceissue• Slow requests…
• Memory
consuming…

Unknown
behavior• Unexpected values…
• Difficult debugging…

https://www.flickr.com/photos/wingedwolf/5471047557/
K.Sasada: What's happening in your Rails app? RailsConf2015

33

Layered computer structure
How to inspect your Rails application?
Your Rails app
Framework / Libraries / Tools
Ruby interpreter

Operating System
Hardware
K.Sasada: What's happening in your Rails app? RailsConf2015

34

1. Use existing tools
2. Make your own tools
K.Sasada: What's happening in your Rails app? RailsConf2015

35

1. Use existing toolsYour Rails app
Framework / Libraries / Tools

Tools & Services

Ruby interpreter

Operating System
Hardware
K.Sasada: What's happening in your Rails app? RailsConf2015

36

Great presentations at RailsConf2015“Prying Open The Black Box” by Godfrey Chan
“Speed Science” by Richard Schneeman
Keynote: Aaron Patterson…
K.Sasada: What's happening in your Rails app? RailsConf2015

37

Performance issue
Slow requests…
Memory consuming …

K.Sasada: What's happening in your Rails app? RailsConf2015

38

The easiest way to solve performance issue is…

Use PX: Performance dyno on Heroku(or another high-performance machine)
Dyno Size
1X
2X
PX

Memory(RAM)
512MB
1024MB
6GB

CPU Share

Multitenant

Compute

1x

yes

1x-4x

2x
100%

yes
no

4x-8x
40x

Price/dynohour
$0.05
$0.10
$0.80

https://devcenter.heroku.com/articles/dyno-size
https://blog.heroku.com/archives/2014/2/3/heroku-xl
K.Sasada: What's happening in your Rails app? RailsConf2015

39

Performance issue
We need to know what happen in a black box
Slow requests• Which part is slow?
• DB?
• External API access?
• Your Ruby app?
• Application?
• GC?

Memory consuming• Who is consuming
memory?
• Correct GC Parameter?

K.Sasada: What's happening in your Rails app? RailsConf2015

40

Analyze slow requests
Use New Relic

http://newrelic.com/application-monitoring/features
K.Sasada: What's happening in your Rails app? RailsConf2015

41

Analyze slow requests
Use New Relic• “Dive into Ruby VM Stats with New Relic”
http://blog.newrelic.com/2014/04/23/ruby-vm-stats/• “Ruby VM measurements”
https://docs.newrelic.com/docs/ruby/ruby-vm-stats

IMPORTANTYou can use New Relic very easily
on Heroku as an Add-on
K.Sasada: What's happening in your Rails app? RailsConf2015

42

Analyze slow requests
Performance profilers“Debugging Ruby Performance” by Aman Gupta• https://speakerdeck.com/tmm1/debugging-rubyperformance“Ruby 2.1 in Production” by Aman Gupta• http://rubykaigi.org/2014/presentation/S-AmanGupta
K.Sasada: What's happening in your Rails app? RailsConf2015

43

Analyze memory consumption issues
Background• Ruby has GC• Automatic object recycling and memory management• Ruby 2.2 has “Incremental and generational” GC• https://engineering.heroku.com/blogs/2015-02-04incremental-gc• Issues• Incorrect GC parameters (environment variables)• Object leaking• MRI bugs
K.Sasada: What's happening in your Rails app? RailsConf2015

44

Analyze memory consumption issues
Background• Generational GC (from Ruby 2.1)
• Collect only newer objects• Old objects can remain long time unexpectedly→ Object leaking

K.Sasada: What's happening in your Rails app? RailsConf2015

45

Analyze memory consumption issues
Tools (pickup my original two)
Measure GC statistics• gc_tracer.gem
Find object creation locations• allocation_tracer.gem
K.Sasada: What's happening in your Rails app? RailsConf2015

46

Analyze memory consumption issues
GC Tracer in your app• Require and call “GC::Tracer.start_logging(filename)”• You can specify logging filename by env val“GC_TRACER_LOGFILE”• All GC related information are recorded into
“filename” (or STDERR)

K.Sasada: What's happening in your Rails app? RailsConf2015

47

Analyze memory consumption issues
Allocation Tracer in your app# Source code
require 'allocation_tracer'
require 'pp'

ObjectSpace::AllocationTracer.setup(%i{path line class})
pp ObjectSpace::AllocationTracer.trace{
50_000.times{|i|# result

i.to_s{["t.rb", 7, String]=>[50000, 1, 40960, 0, 6, 1745520],

i.to_s["t.rb", 8, String]=>[50000, 0, 40950, 0, 1, 1745560],

i.to_s["t.rb", 9, String]=>[50000, 1, 40963, 0, 6, 1745480]}}}
K.Sasada: What's happening in your Rails app? RailsConf2015

48

GC/Allocation tracer
Use as Rack middleware
You only need to write the following lines# Sample in config.ru# GC tracer
require 'rack/gc_tracer'
use Rack::GCTracerMiddleware, view_page_path: '/gc_tracer', filename: '/tmp/rails-gc_tracer'# Allocation Tracer
require 'rack/allocation_tracer'
use Rack::AllocationTracerMiddleware

Warning: You should not use Allocation Tracer inproduction because it has big overhead

K.Sasada: What's happening in your Rails app? RailsConf2015

49

Demo App
http://atdot.net/ab/
K.Sasada: What's happening in your Rails app? RailsConf2015

50

GC Tracer
Events• Capture information on every GC related events• Start marking, start sweeping, end sweeping (default events)• Enter GC, exit GC, newobj, freeobj (optional events)

Inc GC

Ruby

Mark

Mark

exit

exit
start
enter

enter

Mark

Mark

exit
enter

exit
enter

Mark Sweep

Sweep

exit

end_mark exit
enter

Sweep

enter

K.Sasada: What's happening in your Rails app? RailsConf2015

exit

exit
enter

Sweep

Sweep

enter

end_sweep
exit

enter

51

GC Tracer
Captured information• GC.stat results (statistics for current GC)• https://docs.google.com/spreadsheets/d/11Ua4uBr6o0knORrZLEIIUkHJ9JRzRR0NyZfrhEEnc8/edit?usp=sharing• GC. latest_gc_info• Result of get_gusage (on supported OSs)
• Custom fields• You can add any numbers• “Access number” field on Rack mode
K.Sasada: What's happening in your Rails app? RailsConf2015

52

GC Tracer
How to see the log• “Debugging memory leaks in Ruby” by Sam Saffron• http://samsaffron.com/archive/2015/03/31/debuggingmemory-leaks-in-ruby• Send me ko1@heroku.com your gc_tracer log

K.Sasada: What's happening in your Rails app? RailsConf2015

53

Allocation tracer• Object allocation status for each line
• # of created objects• # of old objects• Total ages (total ages / # of created objects = the average age)• Minimum / maximum ages
• Consumed memory bytes• # of created objects helps to find out newobj overheads• # of old objects helps to find out unexpected long lifetime objects• A bit slow (tracking all object creation and recycling)
K.Sasada: What's happening in your Rails app? RailsConf2015

54

Unknown behavior
K.Sasada: What's happening in your Rails app? RailsConf201555

Tools to reveal unknown behaviors• Debugger• pry• Byebug•…

• Error messages• better_errors• did_you_mean• pretty_backtrrace•…
K.Sasada: What's happening in your Rails app? RailsConf2015

56

“Did you mean?” gem
https://github.com/yuki24/did_you_mean
class User
attr_accessor :first_name, :last_name
def to_s; "#{f1rst_name} #{last_name}"; end
enduser.to_s# => NameError: undefined local variable or method `f1rst_name' for#<User:0x0000000928fad8>## Did you mean? #first_name#
K.Sasada: What's happening in your Rails app? RailsConf2015
57

“Pretty backtrace” gem
https://github.com/ko1/pretty_backtrace# Source code

# Error message

require 'pretty_backtrace/enable'
def fib nn < 1 ? raise : fib(n-1)
End

test.rb:5:in `fib' (n = 0): unhandled
exceptionfrom test.rb:5:in `fib' (n = 1)
from test.rb:5:in `fib' (n = 2)
from test.rb:5:in `fib' (n = 3)
from test.rb:8:in `<main>'fib(3)

K.Sasada: What's happening in your Rails app? RailsConf201558

No suitable tools.

How to do it?

K.Sasada: What's happening in your Rails app? RailsConf201559

2. Make your own toolsYour Rails app

You canmake it!

Framework / Libraries / Tools
Ruby interpreter

Ruby
providesprimitives

Operating System
Hardware

K.Sasada: What's happening in your Rails app? RailsConf2015

60

Low level Ruby APIs
• TracePoint• Hook events• Exception• Add your favorite information to error messages• Reflection features• debug_inspect gem• And more…
K.Sasada: What's happening in your Rails app? RailsConf2015

61

Easy tracking with TracePoint
Example: Where is the “#index” method called?

# insert this part of code into boot code
TracePoint.new(:call) do |tp|
if tp.method_id == :index
pp [tp, caller_locations]endend.enable
K.Sasada: What's happening in your Rails app? RailsConf2015

62

Modify exceptions

Example: Modify raised exception backtraces with ♥# srcTracePoint.new(:raise){|tp|e = tp.raised_exception
e.set_backtrace(
e.backtrace.map{|line|
line + "<3<3<3"})}.enable{raise}# result
t.rb:5:in `block in <main>'<3<3<3:unhandled exception
from t.rb:4:in `enable'<3<3<3from t.rb:4:in `<main>'<3<3<3

K.Sasada: What's happening in your Rails app? RailsConf2015

63

Reflection API
Example: Getting local variable name# src

# result

def foo of: STDOUT, if: STDIN[:of, #<IO:<STDOUT>>]
binding.local_variables.each{|lv|[:if, #<IO:<STDOUT>>]
p [lv, binding.local_variable_get(lv)] }# BTW: how to get the value of “if”?
endfoo
K.Sasada: What's happening in your Rails app? RailsConf2015

64

Debug Inspect gem
Example: Getting bindings for all frames# source code

# result

require 'debug_inspector‘ # gem[]

def local_variables_for_frames[:n]

RubyVM::DebugInspector.open{|dc|[:n]dc.backtrace_locations.size.times{|i|[:n]p dc.frame_binding(i).local_variables if dc.frame_binding(i)

[:n]
[]

}}

end
def fib n; n < 1 ? local_variables_for_frames : fib(n-1); end

fib(3)
K.Sasada: What's happening in your Rails app? RailsConf2015

65

Combination of techniques• Examples• Track “raise” events• Modify backtrace• Get local variables from binding• Get bindings for each method frames

Combining all examples makes“Pretty Backtrace” gem
K.Sasada: What's happening in your Rails app? RailsConf2015

66

Advanced hacking
Escape from Ruby world

K.Sasada: What's happening in your Rails app? RailsConf2015

67

Make C extensions with low level C APIs
• See “ruby/debug.h”• TracePoint with internal events• rb_profile APIs
• rb_debug_inspect APIs
• GC inspection APIs

K.Sasada: What's happening in your Rails app? RailsConf2015

68

Hack Ruby
• “Ruby Under a Microscope”• By Pat Shaughnessy• http://patshaughnessy.net/rubyunder-a-microscope• “Ruby Hacking Guide”• By Minero Aoki, written in Japanese• English translation: http://rubyhacking-guide.github.io/
K.Sasada: What's happening in your Rails app? RailsConf2015

69

Combine with low level toolsYour Rails app

Framework / Libraries / Tools
gdb
perf(linux)Ruby interpreter

Operating Systemvalgrind…

Hardware
K.Sasada: What's happening in your Rails app? RailsConf2015

70

Hacking low level systems
Your Rails app

Framework / Libraries / Tools
Ruby interpreter

Hack here!!

Operating System
Hardware
K.Sasada: What's happening in your Rails app? RailsConf2015

71

Rails programming is fun.
Low-level programming is also fun!
(sometimes)

K.Sasada: What's happening in your Rails app? RailsConf2015

72

Message of this talkYou can introspect yourRails application withexisting tools

You can make your own
inspection tools foryour Rails application• So many efforts on thispurpose• Please find them

• Recent Ruby/MRI will
help you• I can help you, too

K.Sasada: What's happening in your Rails app? RailsConf2015

73

Thank you for your attention

Koichi Sasada<ko1@heroku.com>

K.Sasada: What's happening in your Rails app? RailsConf2015

74