Share
Embed
Rubyのパフォーマンスプロファイリングの改善 / Enhancing performance profiling for Ruby
Ruby Association Activity Report
https://www.ruby.or.jp/ja/news/20240520_2
https://osyoyu.com/blog/2024/07/18/213247
osyoyu
July 19, 2024
Transcript
49 slides
-
༗༑ େี (osyoyu) | Ruby Association Activity Report 2024/7/19 Rubyͷ
ύϑΥʔϚϯεϓϩϑΝΠϦϯάͷվળ -
pp self (ࣗݾհ) • ༗༑ େี (Daisuke Aritomo) • github.com/osyoyu
ͳͲ • גࣜձࣾεϚʔτόϯΫۈ -
ύϑΥʔϚϯεϓϩϑΝΠϦϯάͱ • ϓϩάϥϜͷੑೳͷνϡʔχϯάΛ͢ΔͨΊʹ • ʮϓϩϑΝΠϥʯΛͬͯɺϓϩάϥϜͷ࣮ߦΛৄࡉʹ؍͢Δ͜ͱ • ߴԽɾ࠷దԽͷώϯτʹ͢Δ • e.g. "WebΞϓϦέʔγϣϯSQLͷ࣮ߦ͕ͪେ"
ͬͯຊ? • CPUϓϩϑΝΠϥ = ؔɾϝιου୯ҐͰͷ࣮ߦ࣌ؒΛܭଌ • ώʔϓϓϩϑΝΠϥ = ώʔϓϝϞϦͷར༻ঢ়گΛܭଌ -
RubyϓϩϑΝΠϥͷݱگ (2023) StackProf Sampling In-Process rb_pro fi le_frames() Φʔόʔϔου ΞΫςΟϒͳεϨουͷΈΛ؍Մೳ
ruby-prof Tracing In-Process TracePoint ͯ͢ͷϝιουݺͼग़͠Λਖ਼֬ʹՄ ߴΦʔόʔϔου rbspy Sampling Out-of-Process process_vm_readv(2) ϓϩάϥϜͷมߋͳ͠ͰಋೖՄೳ RubyͷόʔδϣϯʹରԠͨ͠ͷ͕ඞཁ • ͘ΘΕΔϓϩϑΝΠϥ͕͍͔ͭ͘ଘࡏ͢Δ • ͦΕͧΕͷಛ͕͋ΓɺͲΕ͕࠷͙͢Ε͍ͯΔͱ͍͏ͷͰͳ͍ • (ࠓճͷϓϩδΣΫτͰCPUϓϩϑΝΠϥʹߜͬͯௐࠪ) -
RubyϓϩϑΝΠϥͷݱگ (2023) Sampling Tracing ҰఆͷपظͰαϯϓϧΛऔಘ͢Δɺ౷ܭతͳख๏ 👍 Low overhead / 👎
৴པੑྼΔ શϝιουΤϯτϦʔͱϦλʔϯΛه͢Δ 👍 ৴པੑ࣮֬ / 👎 High overhead In-Process Out-of-Process RubyϓϩηεʹϓϩϑΝΠϥΛઃஔ͢Δख๏ 👍 ॲཧܥʹؔ͢Δଟ༷ͳใΛऔಘՄ 👎 ಋೖ͕ෳࡶʹͳΓ͕ͪ ϓϩηε֎͔ΒϝϞϦಡΈऔΓͰใΛऔಘ 👍 ಋೖɾ͍ํ͕γϯϓϧ 👎 Έͱͯ͠ෳࡶɺॲཧܥͷै͕େม StackProf Sampling In-Process rb_pro fi le_frames() Φʔόʔϔου ΞΫςΟϒͳεϨουͷΈΛ؍Մೳ ruby-prof Tracing In-Process TracePoint ͯ͢ͷϝιουݺͼग़͠Λਖ਼֬ʹՄ ߴΦʔόʔϔου rbspy Sampling Out-of-Process process_vm_readv(2) ϓϩάϥϜͷมߋͳ͠ͰಋೖՄೳ RubyͷόʔδϣϯʹରԠͨ͠ͷ͕ඞཁ -
ϓϩδΣΫτͷΰʔϧઃఆ RubyҎ֎ͷݴޠॲཧܥͷϓϩϑΝΠϥΛ؍ • Go (pprof) Java (JFR, async-pro fi
le, ...) ͷΤίγεςϜ͕ඇৗʹॆ࣮ • ݴޠػೳʹ͋Θͤͨػೳ͕ॆ࣮͍ͯ͠Δ • ಛʹ pprof (Go) ಄ͻͱͭൈ͚͍ͯΔ • Xcode, Android Studio ΈࠐΈͷϓϩϑΝΠϥۃΊͯڧྗ • CPU, Memory, Network, Battery, Events, શ෦·ͱΊͯݟΒΕΔ → Ruby ͷಛੑΛΑΓ౿·͑ͨϓϩϑΝΠϦϯάΛՄೳʹ͍ͨ͠ -
ϓϩδΣΫτͷΰʔϧઃఆ RubyͷಛੑΛ౿·͑ͨϓϩϑΝΠϧΛͰ͖Δ͜ͱ - RubyεϨου୯ҐͰͷ݁ՌΛग़ྗͰ͖Δ - RubyҎ֎ͷ෦ (C) ΛϒϥοΫϘοΫεʹ͠ͳ͍ - Global
VM Lock (GVL) ͷӨڹΛܭଌͰ͖Δ ͙͢ΕͨϏδϡΞϥΠζΛ௨ͨ͠ੳΛՄೳʹ͢Δ͜ͱ - ੳʹ༗༻ͳࢹΛఏڙ͢Δ ҎԼͷੑ࣭Λͦͳ࣮͑ͨݧతͳϓϩϑΝΠϥΛ࣮͢Δɻ ·ͨɺ͜ΕΒͷՌΛRubyΤίγεςϜʹؐݩ͢Δɻ -
ϓϩδΣΫτͷՌ The depths of profiling Ruby Daisuke Aritomo (@osyoyu) RubyKaigi
2024Ͱͷൃද "The depths of pro fi ling Ruby" -
Pf2 ϓϩϑΝΠϥ • Rubyͷ "۱ʑ·Ͱ" "ਖ਼֬ʹ" ଌఆ Ͱ͖Δ͜ͱΛࢦ͢ • RubyϑϨʔϜ
• C (Native) ϑϨʔϜ • GVLͷ༗ঢ়گ • Sampling, In-process ͳϓϩϑΝΠϥ ͱͯ͠ઃܭ • ͙͢ΕͨϏδϡΞϥΠζͦͳ͑Δ -
͍͔ͨ % bundle exec pf2 run -- ruby main.rb [Pf2]
Listening on localhost:51502. [Pf2] Open https://profiler.firefox.com/from-url/ http%3A%2F%2Flocalhost%3A51502%2Fprofile for visualization. Pf2.profile(mode: :wall) { # code to be profiled fib(200) } ίϚϯυϥΠϯ͔Β ruby શମΛϓϩϑΝΠϧ ϓϩάϥϜͷҰ෦͚ͩΛϓϩϑΝΠϧ -
Firefox Profilerͷར༻ • ϏδϡΞϥΠζॏཁͳػೳ͕ͩɺͦΕࣗମͰ1ϓϩδΣΫτʹͳΔ΄Ͳେ͖͍ • ຊϓϩδΣΫτͰɺͷߴ͍طଘͷϏδϡΞϥΠβ = Firefox Pro fi
lerʹ RubyͷཁૉΛϚοϐϯά͢Δ͜ͱͰରԠ • Firefox Pro fi lerͷϓϩϑΝΠϥػೳ·͍ͬͨͬͯ͘ͳ͍ ϓϩϑΝΠϧσʔλࣗମ Firefox Pro fi ler ʹඇґଘɻ ଞͷϏδϡΞϥΠβʢgo tool pprofʣʹରԠ -
[σϞ] Optcarrot % pf2 run -- bin/optcarrot 'examples/Lan Master.zip' [Pf2]
Listening on localhost:51502. [Pf2] Open https://profiler.firefox.com/from-url/ http%3A%2F%2Flocalhost%3A51502%2Fprofile for visualization. -
[σϞ] Multi-threaded Mandelbrot "Mandelbrot set" by Wolfgang Beyer. Licensed under
CC BY-SA 3.0 https://creativecommons.org/licenses/by-sa/3.0/ • Ϛϯσϧϒϩू߹ = ࣜʹΑͬͯఆٛ͞ΕΔ • Ϛϯσϧϒϩू߹Λܭࢉ͠ɺࠨਤΛϓϩοτ ͢ΔϓϩάϥϜΛϓϩϑΝΠϧ • ฒྻԽ͕Α͘ޮ͘ͷͱͯ͠ΒΕΔ • ͜͜Ͱ16 threadsͰܭࢉ -
[σϞ] Rails (osyoyu.com/blog) https://pro fi ler. fi refox.com/from-url/https%3A%2F%2Fosyoyu-pf2prof.s3.ap- northeast-1.amazonaws.com%2Fincunabula-latest. fi
refoxpro fi ler.json/calltree/?v=10 osyoyu.com/blog ͷ3ඵ͝ͱʹߋ৽͞ΕΔϓϩϑΝΠϧΛެ։த -
Pf2ͷΈͷུ֓ αϯϓϧͷऩू ҰఆपظͰϓϩάϥϜͷ࣮ߦঢ়گΛऔಘ ूܭ ໊ؔͷ෮ݩͳͲ ϏδϡΞϥΠζ Call tree fl amegraphͳͲͷ͔Γ͍͢දݱ
• Ұఆ࣌ؒ͝ͱʹ • RubyͷελοΫͱ • CͷελοΫΛऩू • ϝϞϦ্ʹอଘ • σϑΥϧτͷपظ9ms -
Pf2ͷΈͷུ֓ αϯϓϧͷऩू ҰఆपظͰϓϩάϥϜͷ࣮ߦঢ়گΛऔಘ ूܭ ໊ؔͷ෮ݩͳͲ ϏδϡΞϥΠζ Call tree fl amegraphͳͲͷ͔Γ͍͢දݱ
• ऩूͨ͠αϯϓϧΛूܭ͠ɺ ग़ݱճͷଟ͍ϝιουΛܭࢉ • ϝιου໊ͷ෮ݩ͜ͷλΠϛϯά Ͱߦ͏ • αϯϓϧऩू࣌ϙΠϯλ͚ͩΛ อ͍࣋ͯ͠Δ -
Pf2ͷΈͷུ֓ αϯϓϧͷऩू ҰఆपظͰϓϩάϥϜͷ࣮ߦঢ়گΛऔಘ ूܭ ໊ؔͷ෮ݩͳͲ ϏδϡΞϥΠζ Call tree fl amegraphͳͲͷ͔Γ͍͢දݱ
• طଘͷϏδϡΞϥΠβ͕ղऍͰ͖Δ ܗࣜΛग़ྗ -
Thread୯ҐͰͷߴͳϓϩϑΝΠϦϯά • pthread ୯ҐͰͷγάφϧઃఆ & Ruby 3.3 ͰՃͨ͠ rb_pro fi
le_thread_frames() Λར༻ • ؔ৺ͷ͋ΔεϨουΛ໌ࣔతʹࢦఆ͢Δ͜ͱՄೳʹͳͬͨ 0ms 10ms 20ms 30ms Ruby Thread 1 Ruby Thread 2 SIGPROF SIGPROF Using CPU Using CPU Using CPU γάφϧϋϯυϥ rb_pro fi le_thread_frames() Λ͍ελοΫΛऔಘ γάφϧϋϯυϥ -
C (Native) ίʔυͷϓϩϑΝΠϦϯά • RubyͰCͰ࣮͞Εͨػೳ͕ͨ͘͞Μ͋Δ • C֦ுɺRuby෦ͷॲཧ • RubyͷϓϩϑΝΠϦϯάػೳ rb_pro
fi le_frames() Ͱ͜ΕΛ؍Ͱ͖ͳ͍ • libbacktrace Λར༻͠ɺ࣮ߦதͷΞυϨεʢPCʣΛอଘ͢Δ͜ͱͰରԠ 0ms 10ms 20ms 30ms Ruby Thread 1 SIGPROF Using CPU Using CPU γάφϧϋϯυϥ rb_pro fi le_thread_frames() + PCͷอଘ -
C֦ுͷϓϩϑΝΠϦϯά mysql2 gem ͷྫ read_query_result ΫΤϦͷड৴ύʔεʹ ppoll ΫΤϦͷ࣮ߦ = αʔόʔଆʹ
do_send_query ΫΤϦͷૹ৴ = ωοτϫʔΫʹ -
ʮݟ͑ͳ͍ʯCίʔυͷՄࢹԽ a.k.a. Native Stack Consolidation <main> Integer#times block in <main>
Kernel#foo block (2 levels) in <main> main() ruby_run_node() rb_ec_exec_node() rb_vm_exec() vm_exec_core() rb_yield() rb_foo() vm_call_cfunc_with_cfra main() ruby_run_node() rb_ec_exec_node() rb_vm_exec() <main> Integer#times block in <main> Kernel#my_cfunc vm_callc_cfunc_with_cframe() vm_exec_core() rb_yield() Kernel#foo block (2 levels) in <main> Ruby/CͰผʑʹऩूͨ͠ ελοΫΛ "Ϛʔδ" ͢Δ ෦ʹ՝͕͋Δ -
ʮݟ͑ͳ͍ʯCίʔυͷՄࢹԽ <main> Integer#times block in <main> Kernel#my_cfunc block (2 levels)
in <main> Kernel#foo block (2 levels) in <main> main() ruby_run_node() rb_ec_exec_node() rb_vm_exec() vm_exec_core() rb_yield() rb_foo() main() ruby_run_node() rb_ec_exec_node() rb_vm_exec() ωΠςΟϒίʔυͷ main() ͔ΒߏஙΛ։࢝ rb_vm_exec() Λൃݟͨ͠ Β Ruby ελοΫʹ͏ͭΔ -
ʮݟ͑ͳ͍ʯCίʔυͷՄࢹԽ <main> Integer#times block in <main> Kernel#my_cfunc block (2 levels)
in <main> Kernel#foo block (2 levels) in <main> main() ruby_run_node() rb_ec_exec_node() rb_vm_exec() vm_exec_core() rb_yield() rb_foo() main() ruby_run_node() rb_ec_exec_node() rb_vm_exec() <main> Integer#times block in <main> Kernel#my_cfunc cfunc Λൃݟͨ͠Β C ͷε λοΫʹΔ -
ʮݟ͑ͳ͍ʯCίʔυͷՄࢹԽ <main> Integer#times block in <main> Kernel#my_cfunc block (2 levels)
in <main> Kernel#foo block (2 levels) in <main> main() ... ... vm_callc_cfunc_with_cframe() my_cfunc() vm_exec_core() ... 0x7cabca (non-cfunc) (non-cfunc) 0x7cabca 0x7c0009 0x7c0010 #[repr(C)] pub struct rb_callable_method_entry_struct { pub flags: VALUE, pub def: *mut rb_method_definition_struct, // ... } #[repr(C)] pub struct rb_method_definition_struct { pub type_: c_int, _padding: [c_char; 4], pub cfunc: rb_method_cfunc_struct, } #[repr(C)] pub struct rb_method_cfunc_struct { pub func: *mut c_void, } ͜ͷΈͷͨΊʹଟͷ struct Λ CRuby ͔Βίϐʔ͍ͯ͠Δ... rb_pro fi le_frames() ͷฦΓ͔ΒͨͲΕΔ cfunc ͷϙΠϯλͱҰக͢ΔΞυϨεΛϚονϯά -
ʮݟ͑ͳ͍ʯCίʔυͷՄࢹԽ <main> Integer#times block in <main> Kernel#my_cfunc block (2 levels)
in <main> Kernel#foo block (2 levels) in <main> main() ruby_run_node() rb_ec_exec_node() rb_vm_exec() vm_exec_core() rb_yield() rb_foo() main() ruby_run_node() rb_ec_exec_node() rb_vm_exec() <main> Integer#times block in <main> Kernel#my_cfunc vm_callc_cfunc_with_cframe() vm_exec_core() rb_yield() Kernel#foo block (2 levels) in <main> શͯফඅͨ͠Βྃ -
ߴͳεέδϡʔϦϯά • εέδϡʔϦϯά = αϯϓϦϯάपظͷௐ • Stackprof CPU time
ʹରԠ͍ͯ͠Δ • ϓϩηε͕Ұఆͷ CPU ࣌ؒΛফඅͨ͠ΒαϯϓϦϯάΛΒͤΔΈ • ͔͠͠ɺεϨουؒͰॲཧʹภΓ͕͋Δ࣌ɺ݁Ռ͕͓͔͘͠ͳΔ • Linux ݶఆͰ͋Δ͕ɺtimer_create(2) ͷ CLOCK_THREAD_CPUTIME_ID ΦϓγϣϯΛ͏͜ͱͰɺεϨου୯ҐͷܭଌΛ࣮ݱ͍ͯ͠Δ -
ߴͳεέδϡʔϦϯά job() 0ms 10ms 20ms 30ms job() job() • σϑΥϧτͷपظ
9ms ͱͨ͠ • Lockstep sampling (पظੑͷ͋Δ࣮ߦΛݟಀͯ͠͠·͏) ରࡦ ݟಀ͢ ݟಀ͢ ݟಀ͢ -
͓·͚: RustʹΑΔ࣮ͷײ unsafe { • Pf2ͷC֦ு෦΄ͱΜͲRustͰ࣮ͨ͠ • αϯϓϧͷετϨʔδΛ࣮͢Δʹ͋ͨͬͯྑ͔ͬͨ • Ruby
C APIlibcΛݺͼग़͢෦Ͱ΄΅ C ͷݟͨ (unsafe) • RustͰgemΛͭ͘ΔΤίγεςϜ·ͩ·ͩൃల్্ • CRuby͕ఏڙ͢ΔϚΫϩ (INT2FIX) ͑ͳ͔ͬͨΓ • ruby masterͰϏϧυͰ͖ͳ͔ͬͨΓ } -
ϓϩϑΝΠϥͷΦʔόʔϔουͷධՁ ࣮ߦ࣌ؒ • optcarrot (ϑΝϛίϯΤϛϡ Ϩʔλ) ͰϕϯνϚʔΫ • CPU-bound
CPU ϓϩϑ ΝΠϥʹͱͬͯݫ͍݅͠ • Φʔόʔϔου 1-2% Ͱ ͋Δ͜ͱ͕ࣔ͞Εͨ -
ϓϩϑΝΠϥͷΦʔόʔϔουͷධՁ ফඅϝϞϦ • ऩूͨ͠αϯϓϧΛϝϞϦʹอଘ͢Δ߹্ɺϝϞϦফඅ૿େ͢Δ • 3.01ඵͷ optcarrot ࣮ߦͰͷϝϞϦফඅ (time -v
ʹΑΔ maximum RSS) • Pf2ແޮ ... 58.9 MB • Pf2༗ޮ ... 69.3 MB • ελοΫͷେ͖͞ͱ࣌ؒʹରͯ͠ઢܗʹ৳ͼΔ • RailsΞϓϦέʔγϣϯͰΑΓݦஶʹͳΔ -
ϝϞϦফඅͷվળ • αϯϓϧ1ͭ͋ͨΓ14KBͷͣ • 111 samples/ඵ = 1.5 MB/ඵ •
·ͨɺframesΛ࣋ͭ͜ͱͰCRubyͷ ϑϨʔϜ (Callable Method Entry) ͕ GC͞Εͳ͘ͳΓɺϝϞϦফඅ͕૿େ • ਖ਼֬ͳௐࠪʹϓϩϑΝΠϥͷ ϓϩϑΝΠϥ͕ඞཁ……ʂ // 14038 bytes (14 KB) pub struct Sample { pub ruby_thread: VALUE, // 8 bytes pub timestamp: Instant, // 16 bytes pub line_count: i32, // 4 bytes // frames = rb_profile_frames() pub frames: [VALUE; 500], // 4000 bytes pub linenos: [i32; 500], // 2000 bytes // 8008 bytes pub c_backtrace_pcs: [usize; 1001], } -
ॲཧܥͱϓϩϑΝΠϥͷؔͷมԽ • C API ॲཧܥͷ෦࣮Λ؍ ͠Α͏ͱࢥ͏ͱɺॲཧܥͷ෦Ҏ֎ ʹஔ͖ॴ͕ͳ͍ • M:N ͕ਐΉͱɺ1
Thread = 1 pthread ͷԾఆ͕յΕɺݱࡏͷख๏͕ద༻͠ ͮΒ͘ͳΔ • → CRuby ʹػೳΛՃ͍ͯ͘͠ํ๏ Λݕ౼ current Pf2 -
·ͱΊ • ৽͍͠ϓϩϑΝΠϥ "Pf2" Λ։ൃ͠·ͨ͠ • Ruby ݻ༗ͷػೳʹΑ͘ରԠͨ͠ϓϩϑΝΠϥͱͯ͠ ࠓޙਐԽ͍ͤͨ͞ •
Ruby ϓϩϑΝΠϦϯάͷڥશମΛྑ͍͖͍ͯͨ͘͠