Практический опыт профайлинга и оптимизации...

43
Ruby performance profiling Minsk, SaM Solutions, 2013 Presented by Alexey Tulia @AlexeyTulia, github.com/crible

description

Алексей Туля, Senior Software Developer в Sam Solutions «Практический опыт профайлинга и оптимизации производительности Ruby-приложений» В своем докладе Алексей сделает краткий обзор различных реализаций Ruby, попытается найти причины, почему Ruby медленный. Рассмотрит вопрос сборки мусора в Ruby и вызова методов – почему в Ruby это дорого. Расскажет и покажет, что делать, чтобы поднять производительность, проведет обзор утилит для поиска проблемных мест, обзор профайлеров и расскажет, как интерпретировать результаты. Доклад в основном нацелен на практический подход по поиску проблем. Материал предназначен для пользователей Linux, поэтому все практические советы будут для ОС Linux.

Transcript of Практический опыт профайлинга и оптимизации...

Page 1: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Ruby performance profiling

Minsk, SaM Solutions, 2013

Presented by Alexey Tulia

@AlexeyTulia, github.com/crible

Page 2: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Ruby. A programmer’s best friend

Page 3: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Ruby implementations

Page 4: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

SLOW CODE

Page 5: Практический опыт профайлинга и оптимизации производительности Ruby-приложений
Page 6: Практический опыт профайлинга и оптимизации производительности Ruby-приложений
Page 7: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Reasons?

Page 8: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Garbage collection

Slow methods call

Page 9: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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

Page 10: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Garbage collection

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

Page 11: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

RUBY_HEAP_MIN_SLOTS=8000000

RUBY_GC_MALLOC_LIMIT=10000

Garbage collection tuning

performance patches

Page 12: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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)

Page 13: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Ruby String performance

Heap strings

Shared strings

Embedded strings

Page 14: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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

Page 15: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Slow methods call

Page 16: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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

Page 17: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

THIS TALK IS ABOUT THE TOOLS

TO FIX THE ISSUES

Page 18: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

BEFORE YOU REWRITE SH*T IN SCALA, PROFILE!

Page 19: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

TOOLS FOR LINUX

LSOFSTRACELTRACE

Page 20: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

TOOLS FOR CPU

Ruby-profperftools

perftools.rb

Page 21: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

STRACE

trace system calls and signals

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

Page 22: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

% 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>

Page 23: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

LTRACEtrace dynamic library calls

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

Page 24: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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);

Page 25: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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>

Page 26: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

RUBY-PROFfast code profiler for Ruby

Page 27: Практический опыт профайлинга и оптимизации производительности 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

Page 28: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

KCachegrind

a tool for visualisation

http://kcachegrind.sourceforge.net

Page 29: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

KCachegrind

Page 30: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

KCachegrind

Page 31: Практический опыт профайлинга и оптимизации производительности Ruby-приложений
Page 32: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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

Page 33: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

PERFTOOLS.RB

CPUPROFILE_REALTIME = 1

CPU/wall time

CPUPROFILE_OBJECTS = 1CPUPROFILE_METHODS = 1

Page 34: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Memory profilingGC::Profiler.report

module «objspace»

Ruby-prof

Page 35: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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

Page 36: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Out of the box in Ruby 1.9module «objspace»

Page 37: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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

Page 38: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

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

Page 39: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

What should I remeber before CPU profiling?

Turn GC off (GC.disable)

do_smth is so slow!!!

Page 40: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Make it work

Make it right

Make it fast

Page 41: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

When should I stop performance optimisation?

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

Page 42: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

TOOLS MAKE PROFILING EASIER

LEARN THEM, USE THEM

Page 43: Практический опыт профайлинга и оптимизации производительности Ruby-приложений

Questions?

Thank you!