Ruby performance profiling

Minsk, SaM Solutions, 2013

Presented by Alexey Tulia

@AlexeyTulia, github.com/crible

Ruby. A programmer’s best friend

Ruby implementations

SLOW CODE

Reasons?

Garbage collection

Slow methods call

one iteration takes ~ 100ms

Garbage collection

Need one Gb?

Expect 128 GC calls!

You lose 128*0,1 = 12,8 sec

Allocated memory never returns to the system!

runs on every 8Mb of allocated memory

Garbage collection

More objects allocation -> more GC calls -> slow code

RUBY_HEAP_MIN_SLOTS=8000000

RUBY_GC_MALLOC_LIMIT=10000

Garbage collection tuning

performance patches

Ruby String performance

user system total real21 chars 0.250000 0.000000 0.250000 ( 0.247459)22 chars 0.250000 0.000000 0.250000 ( 0.246954)23 chars 0.250000 0.000000 0.250000 ( 0.248440)24 chars 0.480000 0.000000 0.480000 ( 0.478391)25 chars 0.480000 0.000000 0.480000 ( 0.479662)26 chars 0.480000 0.000000 0.480000 ( 0.481211)27 chars 0.490000 0.000000 0.490000 ( 0.490404)

Ruby String performance

Heap strings

Shared strings

Embedded strings

struct RString { long len; char *ptr;};

Ruby String performance

struct RString { long len; char * ptr; VALUE shared;};

struct RString { char ary[RSTRING_EMBED_LEN_MAX +1];}

RSTRING_EMBED_LEN_MAX = 23

Slow methods call

What can I do to improve performance?

Use C extensions or gems

Use plain SQL instead of frameworks

Use CPU and memory profiling

Use Rubinius or JRuby

THIS TALK IS ABOUT THE TOOLS

TO FIX THE ISSUES

BEFORE YOU REWRITE SH*T IN SCALA, PROFILE!

TOOLS FOR LINUX

LSOFSTRACELTRACE

TOOLS FOR CPU

Ruby-profperftools

perftools.rb

STRACE

trace system calls and signals

strace -cp <pid>strace -ttTp <pid> -o <file>

% time seconds uses/call calls errors syscall50,39 0,00064 0 1197 592 read

34,56 0,00044 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,0 0,000127 4134 596 total

strace -cp <pid>

LTRACEtrace dynamic library calls

ltrace -F <conf_file> -bg -x <symbol> -p pid

ltrace -F <conf_file> -bg -x <symbol> -p pid

-F <conf_file>

int mysql_real_query(addr,string,ulong);void garbage_collect(void);int memcached_set(addr,string,ulong,string,ulong);

ltrace -x garbage_collect

ltrace -x mysql_real_query

mysql_real_query(0x1c9e0500, "SET NAMES 'UTF8'", 16) = 0 <0.000324>mysql_real_query(0x1c9e0500, "SET SQL_AUTO_IS_NULL=0", 22) = 0 <0.000322>mysql_real_query(0x19c7a500, "SELECT * FROM `users`", 21) = 0 <1.206506>mysql_real_query(0x1c9e0500, "COMMIT", 6) = 0 <0.000181>

RUBY-PROFfast code profiler for Ruby

%self total self child calls name------------------------------------------------------------------------ 8.39 0.54 0.23 0.31 602 Array#each_index 7.30 0.41 0.20 0.21 1227 Integer#gcd 6.20 0.49 0.17 0.32 5760 Timecell#date 5.11 0.15 0.14 0.01 1 Magick::Image#to_blob

RUBY-PROF for CPU

KCachegrind

a tool for visualisation

http://kcachegrind.sourceforge.net

KCachegrind

KCachegrind

PERFTOOLS.RBgoogle’s performance tools for ruby code

CPUPROFILE=/tmp/myprof \

pprof --calgrind ./myapp /tmp/myprof

gem install perftools.rb

RUBYOPT="-r`gem which perftools | tail -1`" \ ruby my_app.rb

PERFTOOLS.RB

CPUPROFILE_REALTIME = 1

CPU/wall time

CPUPROFILE_OBJECTS = 1CPUPROFILE_METHODS = 1

Memory profilingGC::Profiler.report

module «objspace»

Ruby-prof

Out of the box in Ruby 1.9GC::Profiler.report

Out of the box in Ruby 1.9module «objspace»

Ruby-prof for memoryrvm install 1.9.3-p448 --patch railexpress

gem install ruby-prof

$ ruby-1.9.3-p448 test.rbThread ID: 14925700Fiber ID: 17378400Total: 3842.242188Sort by: self_time

%self total self wait child calls name 56.94 2187.766 2187.766 0.000 0.000 20000 String#chars 32.79 1259.953 1259.953 0.000 0.000 10000 Array#join 10.17 390.812 390.812 0.000 0.000 10000 Array#shuffle 0.01 3839.391 0.336 0.000 3839.055 1 Integer#times 0.00 1562.766 0.188 0.000 1562.578 10000

GDB.rb$  sudo  gdb.rb  13074    GNU  gdb  (GDB)  7.0    Reading  symbols  from  /usr/bin/ruby...done.    Attaching  to  program:  /usr/bin/ruby,  process  13074    0x00007fa8b9cb3c93  in  select  ()  from  /lib/libc.so.6

   (gdb)  ruby  eval  1+2    2

   (gdb)  ruby  eval  Thread.list.count    17

   (gdb)  ruby  objects  classes                  1  YAML::Syck::Resolver                  1  SystemStackError                  10  OptionParser::Switch::NoArgument

What should I remeber before CPU profiling?

Turn GC off (GC.disable)

do_smth is so slow!!!

Make it work

Make it right

Make it fast

When should I stop performance optimisation?

Premature optimization is the root of all evil(c) Donald Knuth

TOOLS MAKE PROFILING EASIER

LEARN THEM, USE THEM

Questions?

Thank you!