Ruby might be slow, but bad code only makes it worse. This talk will teach you how to use powerful tools to see how your code is executed, so you can understand, debug and optimize it.
lsof -nPp -n Inhibits the conversion of network numbers to host names. -P Inhibits the conversion of port numbers to names for network files FD TYPE NAME cwd DIR /var/www/myapp txt REG /usr/bin/ruby mem REG /json-1.1.9/ext/json/ext/generator.so mem REG /json-1.1.9/ext/json/ext/parser.so mem REG /memcached-0.17.4/lib/rlibmemcached.so mem REG /mysql-2.8.1/lib/mysql_api.so 0u CHR /dev/null 1w REG /usr/local/nginx/logs/error.log 2w REG /usr/local/nginx/logs/error.log 3u IPv4 10.8.85.66:33326->10.8.85.68:3306 (ESTABLISHED) 10u IPv4 10.8.85.66:33327->10.8.85.68:3306 (ESTABLISHED) 11u IPv4 127.0.0.1:58273->127.0.0.1:11211 (ESTABLISHED) 12u REG /tmp/RackMultipart.28957.0 33u IPv4 174.36.83.42:37466->69.63.180.21:80 (ESTABLISHED) json memcached mysql http
tcpdump -i -s -nqA -i Network interface. -s Snarf len bytes of data from each packet. -n Don't convert addresses (host addresses, port numbers) to names. -q Quiet output. Print less protocol information. -A Print each packet (minus its link level header) in ASCII. -w Write the raw packets to file rather than printing them out.
libpcap expression, for example: tcp src port 80 tcp dst port 3306 tcpdump -i -w
strace -cp -c Count time, calls, and errors for each system call and report a summary on program exit. -p pid Attach to the process with the process ID pid and begin tracing. % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 50.39 0.000064 0 1197 592 read 34.65 0.000044 0 609 writev 14.96 0.000019 0 1226 epoll_ctl 0.00 0.000000 0 4 close 0.00 0.000000 0 1 select 0.00 0.000000 0 4 socket 0.00 0.000000 0 4 4 connect 0.00 0.000000 0 1057 epoll_wait ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000127 4134 596 total
% time seconds calls syscall ------ ----------- ------ ------- 95.94 76.685658 1086 clone 95s in the github test suite in clone() `git cmd` calls fork() which calls clone() posix-spawn gem sped up tests by 2x! stracing ruby: tests
• Sampling profiler: • 232 samples total • 83 samples were in /compute • 118 samples had /compute on the stack but were in another function • /compute accounts for 50% of process, but only 35% of time was in /compute itself require 'sinatra' get '/sleep' do sleep 0.25 'done' end get '/compute' do proc{ |n| a,b=0,1 n.times{ a,b = b,a+b } b }.call(10_000) 'done' end $ ab -c 1 -n 50 http://127.0.0.1:4567/compute $ ab -c 1 -n 50 http://127.0.0.1:4567/sleep == Sinatra has ended his set (crowd applauds) PROFILE: interrupts/evictions/bytes = 232/0/2152 Total: 232 samples 83 35.8% 35.8% 118 50.9% Sinatra::Application#GET /compute 56 24.1% 59.9% 56 24.1% garbage_collector 35 15.1% 75.0% 113 48.7% Integer#times
CPUPROFILE_OBJECTS=1 CPUPROFILE=app-objs.prof • object allocation profiler mode built-in • 1 sample = 1 object created • Time parsing is both CPU and object allocation intensive • using mysql2 moves this to C
1. Attach to running process $ sudo gdb ruby 23611 Attaching to program: ruby, process 23611 0x00007fa5113c0c93 in nanosleep () from /lib/libc.so.6 (gdb) c Continuing. Program received signal SIGBUS, Bus error. segv () at segv.c:7 7 array[1000000] = NULL; $ ps aux | grep ruby joe 23611 0.0 0.1 25424 7540 S Dec01 0:00 ruby test_segv.rb 2. Use a coredump $ sudo mkdir /cores $ sudo chmod 777 /cores $ sudo sysctl kernel.core_pattern=/cores/%e.core.%s.%p.%t Process.setrlimit Process::RLIMIT_CORE, 300*1024*1024 $ sudo gdb ruby /cores/ruby.core.6.23611.1259781224
def test require 'segv' 4.times do Dir.chdir '/tmp' do Hash.new{ segv }[0] end end end test() (gdb) where #0 segv () at segv.c:7 #1 0x000000000041f2be in call_cfunc () at eval.c:5727 ... #13 0x000000000043ba8c in rb_hash_default () at hash.c:521 ... #19 0x000000000043b92a in rb_hash_aref () at hash.c:429 ... #26 0x00000000004bb7bc in chdir_yield () at dir.c:728 #27 0x000000000041d8d7 in rb_ensure () at eval.c:5528 #28 0x00000000004bb93a in dir_s_chdir () at dir.c:816 ... #35 0x000000000041c444 in rb_yield () at eval.c:5142 #36 0x0000000000450690 in int_dotimes () at numeric.c:2834 ... #48 0x0000000000412a90 in ruby_run () at eval.c:1678 #49 0x000000000041014e in main () at main.c:48
def test require 'segv' 4.times do Dir.chdir '/tmp' do Hash.new{ segv }[0] end end end test() (gdb) ruby threads 0xa3e000 main curr thread THREAD_RUNNABLE WAIT_NONE node_vcall segv in test_segv.rb:5 node_call test in test_segv.rb:5 node_call call in test_segv.rb:5 node_call default in test_segv.rb:5 node_call [] in test_segv.rb:5 node_call test in test_segv.rb:4 node_call chdir in test_segv.rb:4 node_call test in test_segv.rb:3 node_call times in test_segv.rb:3 node_vcall test in test_segv.rb:9
mongrel sleeper thread 0x16814c00 thread THREAD_STOPPED WAIT_TIME(0.47) 1522 bytes node_fcall sleep in lib/mongrel/configurator.rb:285 node_fcall run in lib/mongrel/configurator.rb:285 node_fcall loop in lib/mongrel/configurator.rb:285 node_call run in lib/mongrel/configurator.rb:285 node_call initialize in lib/mongrel/configurator.rb:285 node_call new in lib/mongrel/configurator.rb:285 node_call run in bin/mongrel_rails:128 node_call run in lib/mongrel/command.rb:212 node_call run in bin/mongrel_rails:281 node_fcall (unknown) in bin/mongrel_rails:19 def run @listeners.each {|name,s| s.run } $mongrel_sleeper_thread = Thread.new { loop { sleep 1 } } end
god memory leaks (gdb) ruby objects arrays elements instances 94310 3 94311 3 94314 2 94316 1 5369 arrays 2863364 member elements many arrays with 90k+ elements! 5 separate god leaks fixed by Eric Lindvall with the help of gdb.rb! 43 God::Process 43 God::Watch 43 God::Driver 43 God::DriverEventQueue 43 God::Conditions::MemoryUsage 43 God::Conditions::ProcessRunning 43 God::Behaviors::CleanPidFile 45 Process::Status 86 God::Metric 327 God::System::SlashProcPoller 327 God::System::Process 406 God::DriverEvent
Memprof.track{ 100.times{ "abc" } 100.times{ 1.23 + 1 } 100.times{ Module.new } } 100 file.rb:2:String 100 file.rb:3:Float 100 file.rb:4:Module • like bleak_house, but for a given block of code • use Memprof::Middleware in your webapps to run track per request
{ "_id": "0x19c610", "file": "file.rb", "line": 2, "type": "string", "class": "0x1ba7f0", "class_name": "String", "length": 10, "data": "helloworld" } memory address of object file and line where string was created length and contents of this string instance address of the class “String” strings Memprof.dump{ "hello" + "world" }
Memprof.dump_all("myapp_heap.json") • dump out every single live object as json • one per line to specified file • analyze via • jsawk/grep • mongodb/couchdb • custom ruby scripts • libyajl + Boost Graph Library
plugging a leak in rails3 • in dev mode, rails3 is leaking 10mb per request # in environment.rb require `gem which memprof/signal`.strip let’s use memprof to find it!
plugging a leak in rails3 tell memprof to dump out the entire heap to json $ memprof --pid --name --key send the app some requests so it leaks $ ab -c 1 -n 30 http://localhost:3000/
• In development mode, Rails reloads all your application code on every request • ActionView::Partials::PartialRenderer is caching partials used by each controller as an optimization • But.. it ends up holding a reference to every single reloaded version of those controllers
tmm1
itsmedreamwalker
ogiwarat
star_zero
nozaki
devoc
teamlab
ivargrimstad
kojipole
jrsaruo
kazue
jxmtst
pulse1923
chriscoyier
matthewcrist
rmw
lauravandoore
notwaldorf
jakevdp
orderedlist
swwweet
brad_frost
sferik
addyosmani
bcantrill