Rubyでのプロファイリング

Slide 1

Slide 1 text

RubyͰͷϓϩϑΝΠϦϯά @talkto_me

Slide 2

Slide 2 text

$ who am i ForkwellͷΤϯδχΞ Twitter : @talkto_me GitHub : @ta1kt0me

Slide 3

Slide 3 text

ϓϩϑΝΠϦϯάͨ͠࿩

Slide 4

Slide 4 text

΍Γํ ⏰

Slide 5

Slide 5 text

ForkwellͰ࢖ͬͯΔ΋ͷ • rack-mini-proﬁler • http://yachibit.hatenablog.jp/entry/ 2013/05/29/004756 • New Relic

Slide 6

Slide 6 text

໰୊

Slide 7

Slide 7 text

ຖिਫ༵೔ɺCPU࢖༻཰͕ 100%ۙ͘ʹͳΔ

Slide 8

Slide 8 text

όονॲཧ͕ݪҼͬΆ͍

Slide 9

Slide 9 text

໰୊ͷը૾

Slide 10

Slide 10 text

rack-mini-proﬁler࢖͑ͳ͍

Slide 11

Slide 11 text

stack-prof https://github.com/tmm1/stackprof • CPU΍Wall clock౳ͷ৘ใΛج४ʹαϯϓϦϯά͠ ͯϓϩϑΝΠϦϯά͢Δπʔϧ • graphviz΍ﬂamegraphͰॲཧͷՄࢹԽ • ຊਓʹΑΔղઆಈը(Ruby Kaigi 2014) • https://www.youtube.com/watch? v=sQn9y1zl2-0

Slide 12

Slide 12 text

΍ͬͨ͜ͱ • ܭଌ༻Ϟδϡʔϧ௥Ճ • stackprofͰ໰୊Օॴಛఆ ͍ͭͰʹॲཧ࣌ؒଌΔ

Slide 13

Slide 13 text

४උ # lib/app_profiler.rb module AppProfiler def run StackProf.run(mode: :cpu, out: 'tmp/profile.dump', raw: true) do super end end end FooBatch.prepend Profiler

Slide 14

Slide 14 text

prependศར

Slide 15

Slide 15 text

ଌ⏰Δ $ time bundle exec rails runner ‘require ”app_profiler”;FooBatch.execute’ bundle exec rails runner 3.24s user 0.61s system 0% cpu 2:05:06.16 total

Slide 16

Slide 16 text

timeʁ • /usr/bin/time • zsh૊ΈࠐΈͷtime • zsh࢖͏ͱ `which time`͸Τϥʔ • $TIMEFMTͰද߲ࣔ໨ΛઃఆͰ͖Δ

Slide 17

Slide 17 text

ௐ΂Δ $ bundle exec stackprof tmp/profile.dump ================================== Mode: cpu(1000) Samples: 5687375 (0.01% miss rate) GC: 86731 (1.52%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 5045720 (88.7%) 5045720 (88.7%) Mysql2::Result#each 96460 (1.7%) 64387 (1.1%) ActiveRecord::LazyAttributeHash#[] 52823 (0.9%) 52738 (0.9%) Mysql2::Client#query 27139 (0.5%) 27139 (0.5%) ActiveRecord::Attribute#initialize 20650 (0.4%) 20650 (0.4%) block in ActiveRecord::Result#hash_rows ………

Slide 18

Slide 18 text

ௐ΂Δ • ৚݅ʹҰக͢ΔσʔλΛඞཁͳ਺͚ͩsample ϝιουͰऔಘ͍ͯ͠Δॲཧ͕සൟʹ࣮ߦ͞ Ε͍ͯΔ

Slide 19

Slide 19 text

௚͢ • ࠷ॳ͔Βඞཁͳ਺͚ͩϥϯμϜʹऔಘ͢Δͱ ͍͍ͷͰ͸ʁͱ༧ଌཱͯΔ

Slide 20

Slide 20 text

ଌ⏰Δ $ time bundle exec rails runner ‘require “app_profiler";FooBatch.execute' bundle exec rails runner 3.37s user 0.45s system 0% cpu 11:39.89 total

Slide 21

Slide 21 text

ௐ΂Δ • αϯϓϧ਺ • 5687375 -> 436714 • GCൃੜճ਺ • 86731 -> 12812 • Mysql2::Result#eachͷݺͼग़͠αϯϓϧ਺ • 5045720 -> 285386

Slide 22

Slide 22 text

·ͱΊ • ͪΐͬͱͨ͠ؾ͖ͮͰύϑΥʔϚϯε͸վળ͢ Δʢ͔΋ʣ • prependศར • ॲཧΛೖΕ͍ͨΫϥεΛมߋ͢Δඞཁ͕ͳ͍ ͷͰɺͪΐͬͱͨ͠ϋοΫָ͕ʹͳΔ • stackprofศར

Slide 23

Slide 23 text

͓·͚

Slide 24

Slide 24 text

• ॲཧ࣌ؒܭଌπʔϧ • benchmark • benchmark-ips • ϓϩϑΝΠϦϯάπʔϧ • proﬁle • ruby-prof • rblineprof • stackprof-remote • rbtrace

Slide 25

Slide 25 text

benchmark • rubyͷඪ४ϥΠϒϥϦ • http://ruby-doc.org/stdlib-2.3.0_preview1/ libdoc/benchmark/rdoc/Benchmark.html • ಛఆͷॲཧͷ࣌ؒΛܭଌͰ͖Δ

Slide 26

Slide 26 text

benchmark require 'benchmark' module AppProfiler def run puts Benchmark::CAPTION puts Benchmark.measure { super } end end FooBatch.prepend Profiler $ bundle exec rails runner 'require "app_profiler";FooBatch.execute' user system total real 0.260000 0.120000 0.380000 ( 0.437103) )

Slide 27

Slide 27 text

benchmark-ips • https://github.com/evanphx/benchmark-ips • ෳ਺ͷॲཧ࣌ؒͷൺֱ͕Ͱ͖Δ • Rails GuideͰਪ঑͞Ε͍ͯΔύϑΥʔϚϯε ܭଌπʔϧ • http://edgeguides.rubyonrails.org/ contributing_to_ruby_on_rails.html

Slide 28

Slide 28 text

benchmark-ips require 'benchmark/ips' nums = 1_000_000.times.map { rand } Benchmark.ips do |x| x.report('last') { nums.last } x.report('minus one index') { nums[-1] } x.report('last one index') { nums[nums.length - 1] } x.compare! end alculating ------------------------------------- last 123.090k i/100ms minus one index 125.563k i/100ms last one index 124.122k i/100ms ------------------------------------------------- last 8.163M (±11.6%) i/s - 40.004M minus one index 9.364M (± 9.2%) i/s - 46.333M last one index 8.506M (± 6.8%) i/s - 42.326M Comparison: minus one index: 9364326.4 i/s last one index: 8506110.5 i/s - 1.10x slower last: 8162777.3 i/s - 1.15x slower

Slide 29

Slide 29 text

profile • rubyͷඪ४ϥΠϒϥϦ • http://docs.ruby-lang.org/ja/2.3.0/library/ profile.html • profileϥΠϒϥϦΛrequire͢Ε͹ϓϩάϥϜͷมߋ͍ Βͳ͍ • ݁ՌΛඪ४Τϥʔʹग़ྗ͢Δ • ॏΊ

Slide 30

Slide 30 text

proﬁle $ bundle exec rails runner 'require "profile"; FooBatch.execute' 2> tmp/profile.txt % cumulative self self total time seconds seconds calls ms/call ms/call name 7.22 0.13 0.13 49 2.65 9.80 Kernel#require 3.89 0.20 0.07 1645 0.04 0.98 Array#each 3.33 0.26 0.06 2749 0.02 0.11 BindingOfCaller::BindingExtensions#callers 2.78 0.31 0.05 1106 0.05 0.06 Mail::Field#responsible_for? 2.78 0.36 0.05 26 1.92 1.92 Dir.[] 2.22 0.40 0.04 2860 0.01 0.08 BetterErrors::ExceptionExtension#set_backtrace 2.22 0.44 0.04 8 5.00 10.00 Mail::Parsers::Ragel::AddressListsMachine.parse 1.67 0.47 0.03 37 0.81 2.97 Kernel#loop 1.67 0.50 0.03 185 0.16 0.16 Module#module_eval ……

Slide 31

Slide 31 text

ruby-prof • https://github.com/ruby-prof/ruby-prof • proﬁleʹൺ΂ͯɺϝιουͷίʔϧελοΫ ΛhtmlͰάϥϑΟΧϧʹදݱͰ͖ͨΓɺϨ ϙʔτػೳ͕ॆ࣮

Slide 32

Slide 32 text

ruby-prof module AppProfiler def run result = RubyProf.profile do super end printer = RubyProf::FlatPrinter.new(result) File.open('tmp/ruby_prof.txt', 'w') { |file| printer.print(file) } end end FooBatch.prepend AppProfiler $ bundle exec rails runner 'require "app_profiler"; FooBatch.execute' $ head -13 tmp/ruby_prof.txt Measure Mode: wall_time Thread ID: 70360380996060 Fiber ID: 70360318592320 Total: 0.602138 Sort by: self_time %self total self wait child calls name 6.55 0.040 0.039 0.000 0.000 16 Mysql2::Client#_query 4.44 0.249 0.027 0.000 0.222 41 *Kernel#require 3.63 0.022 0.022 0.000 0.000 13 #[] 1.99 0.012 0.012 0.000 0.000 7 Module#inspect 1.70 0.010 0.010 0.000 0.000 5939 Symbol#to_s 1.33 0.026 0.008 0.000 0.018 542 *Module#class_eval

Slide 33

Slide 33 text

rblineprof • https://github.com/tmm1/rblineprof • Rubyͷ2.1Ҏ্ͩͱmasterΛ࢖͏ඞཁ͕͋Δ • https://github.com/tmm1/rblineprof/pull/27 • ࣮ߦߦ͝ͱͷॲཧ࣌ؒΛϓϩϑΝΠϧ͢Δ • σϑΥϧτͩͱϨϙʔτػೳ͕ͳ͍ͷͰɺrblineprof-reportΛ Ұॹʹ࢖͏ͱྑ͍ײ͡ • https://github.com/sonots/rblineprof-report

Slide 34

Slide 34 text

ruby-prof module AppProfiler def run result = RubyProf.profile do super end printer = RubyProf::CallStackPrinter.new(result) File.open('tmp/profile.html', 'w') { |file| printer.print(file) } end end FooBatch.prepend AppProfiler $ bundle exec rails runner 'require "app_profiler"; FooBatch.execute' $ head -13 tmp/ruby_prof.txt Measure Mode: wall_time Thread ID: 70360380996060 Fiber ID: 70360318592320 Total: 0.602138 Sort by: self_time %self total self wait child calls name 6.55 0.040 0.039 0.000 0.000 16 Mysql2::Client#_query 4.44 0.249 0.027 0.000 0.222 41 *Kernel#require 3.63 0.022 0.022 0.000 0.000 13 #[] 1.99 0.012 0.012 0.000 0.000 7 Module#inspect 1.70 0.010 0.010 0.000 0.000 5939 Symbol#to_s 1.33 0.026 0.008 0.000 0.018 542 *Module#class_eval

Slide 35

Slide 35 text

stackprof-remote • https://github.com/quirkey/stackprof-remote • stack-profΛϦϞʔτͰ࣮ߦͰ͖ΔΑ͏ʹ͢Δ πʔϧΒ͍͠ • ࢼͯ͠ͳ͍

Slide 36

Slide 36 text

rbtrace • https://github.com/tmm1/rbtrace • ࣮ߦதͷRubyͷϓϩηεʹΞλονͯ͠ɺϝ ιουͷ࣮ߦ࣌ؒΛ֬ೝͰ͖Δ • Gemﬁleʹ `gem ‘rbtrace’`ͱॻ͚͹OK

Slide 37

Slide 37 text

rbtrace $ bundle exec rbtrace -p $RUBY_PID -m show # p: pid, m: method name *** attached to process 21066 FoosController#show <1.182228> *** detached from process 21066

Slide 38

Slide 38 text

͋Γ͕ͱ͏͍͟͝·ͨ͠