Rubyでのプロファイリング

http://forkwell.connpass.com/event/24457/

Transcript

1. RubyͰͷϓϩϑΝΠϦϯά @talkto_me
2. $ who am i ForkwellͷΤϯδχΞ Twitter : @talkto_me GitHub : @ta1kt0me
3. ϓϩϑΝΠϦϯάͨ͠࿩
4. ΍Γํ ⏰
5. ForkwellͰ࢖ͬͯΔ΋ͷ • rack-mini-profiler • http://yachibit.hatenablog.jp/entry/ 2013/05/29/004756 • New Relic
6. ໰୊
7. ຖिਫ༵೔ɺCPU࢖༻཰͕ 100%ۙ͘ʹͳΔ
8. όονॲཧ͕ݪҼͬΆ͍
9. ໰୊ͷը૾
10. rack-mini-profiler࢖͑ͳ͍
11. stack-prof https://github.com/tmm1/stackprof • CPU΍Wall clock౳ͷ৘ใΛج४ʹαϯϓϦϯά͠ ͯϓϩϑΝΠϦϯά͢Δπʔϧ • graphviz΍flamegraphͰॲཧͷՄࢹԽ • ຊਓʹΑΔղઆಈը(Ruby Kaigi 2014) • https://www.youtube.com/watch? v=sQn9y1zl2-0
12. ΍ͬͨ͜ͱ • ܭଌ༻Ϟδϡʔϧ௥Ճ • stackprofͰ໰୊Օॴಛఆ ͍ͭͰʹॲཧ࣌ؒଌΔ
13. ४උ # 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
14. prependศར
15. ଌ⏰Δ $ 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
16. timeʁ • /usr/bin/time • zsh૊ΈࠐΈͷtime • zsh࢖͏ͱ `which time`͸Τϥʔ • $TIMEFMTͰද߲ࣔ໨ΛઃఆͰ͖Δ
17. ௐ΂Δ $ 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 ………
18. ௐ΂Δ • ৚݅ʹҰக͢ΔσʔλΛඞཁͳ਺͚ͩsample ϝιουͰऔಘ͍ͯ͠Δॲཧ͕සൟʹ࣮ߦ͞ Ε͍ͯΔ
19. ௚͢ • ࠷ॳ͔Βඞཁͳ਺͚ͩϥϯμϜʹऔಘ͢Δͱ ͍͍ͷͰ͸ʁͱ༧ଌཱͯΔ
20. ଌ⏰Δ $ 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
21. ௐ΂Δ • αϯϓϧ਺ • 5687375 -> 436714 • GCൃੜճ਺ • 86731 -> 12812 • Mysql2::Result#eachͷݺͼग़͠αϯϓϧ਺ • 5045720 -> 285386
22. ·ͱΊ • ͪΐͬͱͨ͠ؾ͖ͮͰύϑΥʔϚϯε͸վળ͢ Δʢ͔΋ʣ • prependศར • ॲཧΛೖΕ͍ͨΫϥεΛมߋ͢Δඞཁ͕ͳ͍ ͷͰɺͪΐͬͱͨ͠ϋοΫָ͕ʹͳΔ • stackprofศར
23. ͓·͚
24. • ॲཧ࣌ؒܭଌπʔϧ • benchmark • benchmark-ips • ϓϩϑΝΠϦϯάπʔϧ • profile • ruby-prof • rblineprof • stackprof-remote • rbtrace
25. benchmark • rubyͷඪ४ϥΠϒϥϦ • http://ruby-doc.org/stdlib-2.3.0_preview1/ libdoc/benchmark/rdoc/Benchmark.html • ಛఆͷॲཧͷ࣌ؒΛܭଌͰ͖Δ
26. 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) )
27. benchmark-ips • https://github.com/evanphx/benchmark-ips • ෳ਺ͷॲཧ࣌ؒͷൺֱ͕Ͱ͖Δ • Rails GuideͰਪ঑͞Ε͍ͯΔύϑΥʔϚϯε ܭଌπʔϧ • http://edgeguides.rubyonrails.org/ contributing_to_ruby_on_rails.html
28. 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
29. profile • rubyͷඪ४ϥΠϒϥϦ • http://docs.ruby-lang.org/ja/2.3.0/library/ profile.html • profileϥΠϒϥϦΛrequire͢Ε͹ϓϩάϥϜͷมߋ͍ Βͳ͍ • ݁ՌΛඪ४Τϥʔʹग़ྗ͢Δ • ॏΊ
30. profile $ 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 ……
31. ruby-prof • https://github.com/ruby-prof/ruby-prof • profileʹൺ΂ͯɺϝιουͷίʔϧελοΫ ΛhtmlͰάϥϑΟΧϧʹදݱͰ͖ͨΓɺϨ ϙʔτػೳ͕ॆ࣮
32. 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 <Class::Dir>#[] 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
33. 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
34. 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 <Class::Dir>#[] 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
35. stackprof-remote • https://github.com/quirkey/stackprof-remote • stack-profΛϦϞʔτͰ࣮ߦͰ͖ΔΑ͏ʹ͢Δ πʔϧΒ͍͠ • ࢼͯ͠ͳ͍
36. rbtrace • https://github.com/tmm1/rbtrace • ࣮ߦதͷRubyͷϓϩηεʹΞλονͯ͠ɺϝ ιουͷ࣮ߦ࣌ؒΛ֬ೝͰ͖Δ • Gemfileʹ `gem ‘rbtrace’`ͱॻ͚͹OK
37. 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
38. ͋Γ͕ͱ͏͍͟͝·ͨ͠