投機実行とOut of Orderはつよいというはなし
fluentdな人達と話していると定期的にRubyのオブジェクト生成が遅いとdisられます。
本質的にしょうがない部分もあるんですが、それにしても遅い部分も結構あるので、おもむろにperf stat
とperf record
を取ってみましょう。
% sudo perf stat -d ./miniruby -e'GC.disable;i=1000000;while (i-=1)>0;Hash.new;end' Performance counter stats for './miniruby -eGC.disable;i=1000000;while (i-=1)>0;Hash.new;end': 467.629812 task-clock (msec) # 0.993 CPUs utilized 19 context-switches # 0.041 K/sec 2 cpu-migrations # 0.004 K/sec 65547 page-faults # 0.140 M/sec 1356052041 cycles # 2.900 GHz [49.17%] 683406025 stalled-cycles-frontend # 50.40% frontend cycles idle [49.73%] <not supported> stalled-cycles-backend 1656503729 instructions # 1.22 insns per cycle # 0.41 stalled cycles per insn [63.34%] 330462548 branches # 706.676 M/sec [63.60%] 447683 branch-misses # 0.14% of all branches [63.93%] <not supported> L1-dcache-loads:HG 9560448 L1-dcache-load-misses:HG # 0.00% of all L1-dcache hits [63.35%] 0 LLC-loads:HG # 0.000 K/sec [62.52%] 0 LLC-load-misses:HG # 0.00% of all LL-cache hits [49.22%] 0.470869900 seconds time elapsed % sudo perf record ./miniruby -e'GC.disable;i=1000000;while (i-=1)>0;Hash.new;end' Lowering default frequency rate to 1750. Please consider tweaking /proc/sys/kernel/perf_event_max_sample_rate. [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.036 MB perf.data (~1585 samples) ] % sudo perf report --stdio # ======== # captured on: Wed Apr 20 15:09:24 2016 # hostname : tk2-243-31075 # os release : 3.13.0-77-generic # perf version : 3.13.11-ckt32 # arch : x86_64 # nrcpus online : 3 # nrcpus avail : 3 # cpudesc : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz # cpuid : GenuineIntel,6,62,4 # total memory : 2049828 kB # cmdline : /usr/lib/linux-tools-3.13.0-77/perf record ./miniruby -eGC.disable;i=1000000;while (i-=1 )>0;Hash.new;end # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_ke rn = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, attr_mmap2 = 0, attr_mmap = 1, attr_mmap_dat a = 0 # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5 # ======== # # Samples: 1K of event 'cycles' # Event count (approx.): 1582794433 # # Overhead Command Shared Object Symbol # ........ ........ .................. .......................................... # 13.72% miniruby [kernel.kallsyms] [k] clear_page_c_e 9.49% miniruby miniruby [.] vm_exec_core 7.36% miniruby libc-2.19.so [.] _int_malloc 6.15% miniruby miniruby [.] objspace_malloc_increase.isra.67 5.06% miniruby libc-2.19.so [.] malloc 4.10% miniruby libpthread-2.19.so [.] pthread_getspecific 3.97% miniruby libc-2.19.so [.] __libc_calloc 3.78% miniruby [kernel.kallsyms] [k] get_page_from_freelist 3.21% miniruby miniruby [.] rb_wb_protected_newobj_of 3.12% miniruby miniruby [.] rb_obj_call_init 2.98% miniruby miniruby [.] ruby_xcalloc 2.74% miniruby [kernel.kallsyms] [k] async_page_fault 2.28% miniruby miniruby [.] vm_call0_body.constprop.120 1.75% miniruby miniruby [.] vm_call_cfunc 1.44% miniruby miniruby [.] st_init_table_with_size 1.41% miniruby miniruby [.] rb_callable_method_entry 1.10% miniruby miniruby [.] rb_call0 1.08% miniruby [kernel.kallsyms] [k] handle_mm_fault 1.02% miniruby miniruby [.] vm_search_method.isra.77 0.95% miniruby [kernel.kallsyms] [k] __alloc_pages_nodemask 0.94% miniruby [kernel.kallsyms] [k] __mem_cgroup_commit_charge 0.86% miniruby [kernel.kallsyms] [k] __rmqueue […]
上位にカーネルやlibc、RubyVM実行エンジンの中心部であるvm_exec_core
が並んでいて、「あ、これは戦う敵を間違えたかな」って雰囲気が若干漂っていますが、強引に目に入ったruby_xcalloc
に食らいついていきます。いや、こいつただのcallocのラッパのくせに3%近く食ってて生意気じゃないですか。
とりあえずobjdump
で中身を眺めてみましょう。
% ruby -e'/\A0*(\h+)[ .a-z]*\t0*(\h+)/i=~`objdump -t miniruby|grep #{ARGV[0]||abort}`and exec"objdump -d --start-address=0x#{$1} --stop-address=#{"%#x"%[$1.hex+$2.hex]} miniruby|less"' ruby_xcalloc miniruby: file format elf64-x86-64 Disassembly of section .text: 0000000000496280 <ruby_xcalloc>: 496280: 48 8d 05 51 7a 44 00 lea 0x447a51(%rip),%rax # 8ddcd8 <ruby_current_vm> 496287: 41 54 push %r12 496289: 31 d2 xor %edx,%edx 49628b: 55 push %rbp 49628c: 53 push %rbx 49628d: 48 8b 00 mov (%rax),%rax 496290: 4c 8b a0 30 06 00 00 mov 0x630(%rax),%r12 496297: 48 c7 c0 ff ff ff ff mov $0xffffffffffffffff,%rax 49629e: 48 f7 f6 div %rsi 4962a1: 48 39 c7 cmp %rax,%rdi 4962a4: 0f 87 43 01 00 00 ja 4963ed <ruby_xcalloc+0x16d> 4962aa: 48 89 fb mov %rdi,%rbx 4962ad: 48 0f af de imul %rsi,%rbx 4962b1: 48 85 db test %rbx,%rbx 4962b4: 0f 88 96 00 00 00 js 496350 <ruby_xcalloc+0xd0> 4962ba: b8 01 00 00 00 mov $0x1,%eax 4962bf: 48 0f 44 d8 cmove %rax,%rbx 4962c3: 41 f6 44 24 10 40 testb $0x40,0x10(%r12) 4962c9: 75 45 jne 496310 <ruby_xcalloc+0x90> 4962cb: 48 89 de mov %rbx,%rsi 4962ce: bf 01 00 00 00 mov $0x1,%edi 4962d3: e8 68 11 f8 ff callq 417440 <calloc@plt> 4962d8: 48 89 c5 mov %rax,%rbp 4962db: 48 85 c0 test %rax,%rax 4962de: 0f 84 a4 00 00 00 je 496388 <ruby_xcalloc+0x108> 4962e4: 48 89 ef mov %rbp,%rdi 4962e7: e8 84 10 f8 ff callq 417370 <malloc_usable_size@plt> 4962ec: 4c 89 e7 mov %r12,%rdi 4962ef: b9 01 00 00 00 mov $0x1,%ecx 4962f4: 31 d2 xor %edx,%edx 4962f6: 48 89 c6 mov %rax,%rsi 4962f9: e8 e2 f7 ff ff callq 495ae0 <objspace_malloc_increase.isra.67> 4962fe: 48 89 e8 mov %rbp,%rax 496301: 5b pop %rbx 496302: 5d pop %rbp 496303: 41 5c pop %r12 496305: c3 retq 496306: 66 2e 0f 1f 84 00 00 nopw %cs:0x0(%rax,%rax,1) 49630d: 00 00 00 496310: e8 fb 2f 16 00 callq 5f9310 <ruby_native_thread_p> 496315: 85 c0 test %eax,%eax 496317: 74 b2 je 4962cb <ruby_xcalloc+0x4b> 496319: 49 8b 84 24 b0 01 00 mov 0x1b0(%r12),%rax 496320: 00 496321: 89 c6 mov %eax,%esi 496323: 83 e6 01 and $0x1,%esi 496326: 74 09 je 496331 <ruby_xcalloc+0xb1> 496328: 48 c1 e8 03 shr $0x3,%rax 49632c: 89 c6 mov %eax,%esi 49632e: 83 e6 01 and $0x1,%esi 496331: 41 b8 00 12 00 00 mov $0x1200,%r8d 496337: b9 01 00 00 00 mov $0x1,%ecx 49633c: ba 01 00 00 00 mov $0x1,%edx 496341: 4c 89 e7 mov %r12,%rdi 496344: e8 d7 f6 ff ff callq 495a20 <garbage_collect_with_gvl> 496349: eb 80 jmp 4962cb <ruby_xcalloc+0x4b> 49634b: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1) 496350: e8 9b a2 15 00 callq 5f05f0 <ruby_thread_has_gvl_p> 496355: 85 c0 test %eax,%eax 496357: 0f 85 a1 00 00 00 jne 4963fe <ruby_xcalloc+0x17e> 49635d: e8 ae 2f 16 00 callq 5f9310 <ruby_native_thread_p> 496362: 85 c0 test %eax,%eax 496364: 0f 84 88 00 00 00 je 4963f2 <ruby_xcalloc+0x172> 49636a: 48 8d 35 af 1a 17 00 lea 0x171aaf(%rip),%rsi # 607e20 <null_device+0x1378> 496371: 48 8d 3d 28 3f ff ff lea -0xc0d8(%rip),%rdi # 48a2a0 <negative_size_allocation_error_with_gvl> 496378: e8 33 e5 15 00 callq 5f48b0 <rb_thread_call_with_gvl> 49637d: e9 41 ff ff ff jmpq 4962c3 <ruby_xcalloc+0x43> 496382: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1) 496388: 41 b8 00 02 00 00 mov $0x200,%r8d 49638e: b9 01 00 00 00 mov $0x1,%ecx 496393: ba 01 00 00 00 mov $0x1,%edx 496398: be 01 00 00 00 mov $0x1,%esi 49639d: 4c 89 e7 mov %r12,%rdi 4963a0: e8 7b f6 ff ff callq 495a20 <garbage_collect_with_gvl> 4963a5: 85 c0 test %eax,%eax 4963a7: 74 1f je 4963c8 <ruby_xcalloc+0x148> 4963a9: 48 89 de mov %rbx,%rsi 4963ac: bf 01 00 00 00 mov $0x1,%edi 4963b1: e8 8a 10 f8 ff callq 417440 <calloc@plt> 4963b6: 48 85 c0 test %rax,%rax 4963b9: 74 0d je 4963c8 <ruby_xcalloc+0x148> 4963bb: 48 89 c5 mov %rax,%rbp 4963be: e9 21 ff ff ff jmpq 4962e4 <ruby_xcalloc+0x64> 4963c3: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1) 4963c8: e8 23 a2 15 00 callq 5f05f0 <ruby_thread_has_gvl_p> 4963cd: 85 c0 test %eax,%eax 4963cf: 75 51 jne 496422 <ruby_xcalloc+0x1a2> 4963d1: e8 3a 2f 16 00 callq 5f9310 <ruby_native_thread_p> 4963d6: 85 c0 test %eax,%eax 4963d8: 74 43 je 49641d <ruby_xcalloc+0x19d> 4963da: 48 8d 3d 6f d2 ff ff lea -0x2d91(%rip),%rdi # 493650 <ruby_memerror_body> 4963e1: 31 f6 xor %esi,%esi 4963e3: e8 c8 e4 15 00 callq 5f48b0 <rb_thread_call_with_gvl> 4963e8: e9 f7 fe ff ff jmpq 4962e4 <ruby_xcalloc+0x64> 4963ed: e8 0e d5 ff ff callq 493900 <ruby_malloc_size_overflow> 4963f2: 48 8d 3d 27 1a 17 00 lea 0x171a27(%rip),%rdi # 607e20 <null_device+0x1378> 4963f9: e8 63 1b f8 ff callq 417f61 <negative_size_allocation_error.part.52> 4963fe: 48 8d 05 3b b4 44 00 lea 0x44b43b(%rip),%rax # 8e1840 <rb_eNoMemError> 496405: 48 8d 15 14 1a 17 00 lea 0x171a14(%rip),%rdx # 607e20 <null_device+0x1378> 49640c: 48 8d 35 94 b7 18 00 lea 0x18b794(%rip),%rsi # 621ba7 <yytranslate+0x807> 496413: 48 8b 38 mov (%rax),%rdi 496416: 31 c0 xor %eax,%eax 496418: e8 e3 77 fd ff callq 46dc00 <rb_raise> 49641d: e8 6a 1b f8 ff callq 417f8c <garbage_collect_with_gvl.part.65> 496422: e8 89 a2 ff ff callq 4906b0 <rb_memerror>
ん、思ったよりもでかいぞ?
static void * objspace_xcalloc(rb_objspace_t *objspace, size_t count, size_t elsize) { void *mem; size_t size; size = xmalloc2_size(count, elsize); size = objspace_malloc_prepare(objspace, size); TRY_WITH_GC(mem = calloc(1, size)); size = objspace_malloc_size(objspace, mem, size); objspace_malloc_increase(objspace, mem, size, 0, MEMOP_TYPE_MALLOC); return objspace_malloc_fixup(objspace, mem, size); }
ソースを見るに、前半はcalloc
するサイズの補正、後半はエラー処理系って感じですかね。納得したようなそれでもまだ多すぎるだろうというような気持ちになりつつ改めて逆アセンブルの中身を見ると、冒頭にdiv
があります。そういえばこの連載ではdiv
が遅いのは前提としていましたがちゃんと見た方がいい気がしてきました。
機械語の速度はAgner FogさんのSoftware optimization resourcesにある"Instruction tables"を見るとよいです。以下の表はIvy Bridgeの場合の抜粋ですが、加算がめっちゃ速くて、除算がとても遅いことがわかりますね。(加算とか1クロックで3命令実行すごい)
Instruction | Operands | Latency | Throughputの逆数 |
---|---|---|---|
ADD SUB | r,r/i | 1 | 0.33 |
MUL IMUL | r64 | 3 | 1 |
IMUL | r64,r64,i | 3 | 1 |
DIV | r64 | 29-94 | 22-76 |
さて、このdivはruby_xmalloc2_sizeの中にあります。何をしているかというとオーバーフローチェックですね。正確にはC言語では符号無し整数はオーバーフローしないのでラップアラウンドチェックになります。
static inline size_t ruby_xmalloc2_size(const size_t count, const size_t elsize) { if (count > SIZE_MAX / elsize) { ruby_malloc_size_overflow(count, elsize); } return count * elsize; }
ところで、この種のチェックには二種類あります。チェックせずに実行すると例外が飛ぶゼロ除算エラーみたいなものと、今回のように単に意図と違う値が返ってくるものです。言い換えると、後者はとりあえず実行してからチェックしてもよいと言うことですね。チェックして違った場合、インテル® 64 アーキテクチャー および IA-32 アーキテクチャー 最適化リファレンス・マニュアルによると「分岐予測ミスには、約 20 サイクルのペナルティーが課せられる」のに加えて乗算のコストも無駄になるのですが、今回の場合どうせruby_malloc_size_overflow()
なので気にしません。そのようにしてみたパッチと結果が以下の通りです。
diff --git a/include/ruby/ruby.h b/include/ruby/ruby.h index c41465a..4c50dd2 100644 --- a/include/ruby/ruby.h +++ b/include/ruby/ruby.h @@ -1608,13 +1608,15 @@ rb_num2char_inline(VALUE x) void *rb_alloc_tmp_buffer(volatile VALUE *store, long len) RUBY_ATTR_ALLOC_SIZE((2)); void rb_free_tmp_buffer(volatile VALUE *store); NORETURN(void ruby_malloc_size_overflow(size_t, size_t)); +#define UNLIKELY(x) (__builtin_expect(!!(x), 0)) static inline size_t ruby_xmalloc2_size(const size_t count, const size_t elsize) { - if (count > SIZE_MAX / elsize) { + size_t v = count * elsize; + if (UNLIKELY(count > SIZE_MAX / elsize)) { ruby_malloc_size_overflow(count, elsize); } - return count * elsize; + return v; } /* allocates _n_ bytes temporary buffer and stores VALUE including it * in _v_. _n_ may be evaluated twice. */
00000000004961b0 <ruby_xcalloc>: 4961b0: 48 8d 05 21 7b 44 00 lea 0x447b21(%rip),%rax # 8ddcd8 <ruby_current_vm> 4961b7: 41 54 push %r12 4961b9: 31 d2 xor %edx,%edx 4961bb: 55 push %rbp 4961bc: 53 push %rbx 4961bd: 48 89 fb mov %rdi,%rbx 4961c0: 48 0f af de imul %rsi,%rbx 4961c4: 48 8b 00 mov (%rax),%rax 4961c7: 4c 8b a0 30 06 00 00 mov 0x630(%rax),%r12 4961ce: 48 c7 c0 ff ff ff ff mov $0xffffffffffffffff,%rax 4961d5: 48 f7 f6 div %rsi 4961d8: 48 39 c7 cmp %rax,%rdi 4961db: 0f 87 d7 00 00 00 ja 4962b8 <ruby_xcalloc+0x108> 4961e1: 48 85 db test %rbx,%rbx 4961e4: 0f 88 96 00 00 00 js 496280 <ruby_xcalloc+0xd0> 4961ea: b8 01 00 00 00 mov $0x1,%eax 4961ef: 48 0f 44 d8 cmove %rax,%rbx 4961f3: 41 f6 44 24 10 40 testb $0x40,0x10(%r12) 4961f9: 75 45 jne 496240 <ruby_xcalloc+0x90> 4961fb: 48 89 de mov %rbx,%rsi 4961fe: bf 01 00 00 00 mov $0x1,%edi 496203: e8 38 12 f8 ff callq 417440 <calloc@plt> [...]
% sudo perf stat -d ./miniruby -e'GC.disable;i=1000000;while (i-=1)>0;Hash.new;end' Performance counter stats for './miniruby -eGC.disable;i=1000000;while (i-=1)>0;Hash.new;end': 402.269177 task-clock (msec) # 0.992 CPUs utilized 23 context-switches # 0.057 K/sec 2 cpu-migrations # 0.005 K/sec 65554 page-faults # 0.163 M/sec 1164270325 cycles # 2.894 GHz [48.83%] 539587746 stalled-cycles-frontend # 46.35% frontend cycles idle [49.62%] <not supported> stalled-cycles-backend 1660044950 instructions # 1.43 insns per cycle # 0.33 stalled cycles per insn [63.91%] 330545296 branches # 821.702 M/sec [63.92%] 467450 branch-misses # 0.14% of all branches [64.22%] <not supported> L1-dcache-loads:HG 9303493 L1-dcache-load-misses:HG # 0.00% of all L1-dcache hits [63.35%] 0 LLC-loads:HG # 0.000 K/sec [62.30%] 0 LLC-load-misses:HG # 0.00% of all LL-cache hits [48.70%] 0.405514667 seconds time elapsed % sudo perf report --stdio # # Samples: 1K of event 'cycles' # Event count (approx.): 1292902007 # # Overhead Command Shared Object Symbol # ........ ........ .................. ........................................ # 15.05% miniruby [kernel.kallsyms] [k] clear_page_c_e 8.95% miniruby miniruby [.] objspace_malloc_increase.isra.67 7.57% miniruby libc-2.19.so [.] _int_malloc 7.15% miniruby miniruby [.] vm_exec_core 4.26% miniruby libc-2.19.so [.] malloc 3.93% miniruby libc-2.19.so [.] __libc_calloc 3.44% miniruby [kernel.kallsyms] [k] async_page_fault 3.43% miniruby [kernel.kallsyms] [k] get_page_from_freelist 2.64% miniruby miniruby [.] vm_call0_body.constprop.120 2.37% miniruby miniruby [.] ruby_xcalloc 2.17% miniruby miniruby [.] vm_call_cfunc 1.87% miniruby miniruby [.] rb_call0 1.50% miniruby miniruby [.] rb_callable_method_entry
0.46 → 0.40 なので結構変わりましたね。アセンブラ上ではimul → mov mov mov → div となっていますが、imulとmov mov movが同時に走って、divしながら投機的実行でZFを使うtestb直前まで走っちゃってるんじゃないでしょうか、たぶん。UNLIKELYなしだとそこまで性能向上無かったので、多分他の場所でもっと効いてるんだと思います。
最初はもうちょっと違う話を書くつもりだったんですが長くなったので今日はここまで
GZIPをZlibデータとして読めるのか?
結論
ムリ。
何がしたいの
例えばMySQLにGZIPのデータが入ってるとき、誰しもこのデータを文字列関数とUNCOMPRESS関数だけで解凍できないのだろうかと思うのでは無いでしょうか。
GZIP
+---+---+---+---+---+---+---+---+---+---+=======================+---+---+---+---+---+---+ |ID1|ID2|CM |FLG| MTIME |XFL|OS |...compressed blocks...| CRC32 | ISIZE | +---+---+---+---+---+---+---+---+---+---+=======================+---+---+---+---+---+---+
GZIPは"\x1F\x8B"ではじまり、少々のヘッダの後圧縮データが続き、CRC32、元データのサイズで終わる。
Zlib
+---+---+=====================+---+---+---+---+ |CMF|FLG|...compressed data...| ADLER32 | +---+---+=====================+---+---+---+---+
CMFとFLGの詳細はRFC1950を見ればいいけど、適当なヘッダをでっち上げるという観点だと"\x78\x9C"でよい。のだが、問題は末尾がADLER32だということである。
MySQLのUNCOMPRESS関数
+---+---+---+---+---+---+=====================+---+---+---+---+ | ISIZE |CMF|FLG|...compressed data...| ADLER32 | +---+---+---+---+---+---+=====================+---+---+---+---+
UNCOMPRESSが解凍できるのは、最初に元データの長さをつけたZlibです。
末尾のADLER32が不正な場合解凍に失敗してNULLにされてしまうので、CRC32しかないGZIPデータからは作ることが出来ません……。
なお、先頭に元データのサイズが必要ならZlibのデータも無理じゃないのか?と思うかもしれませんが、こちらはでたらめでも大丈夫です。たぶんUNCOMPRESSED_LENGTH用?。
まとめ
あきらめてクライアントで解凍しよう。
割り切れてるかの確認を高速化しようとして、コンパイラに負けた話
今日見ていきたいのはtime.c
のquo(VALUE x, VALUE y)
です。akrさんのRuby における 2038年問題の解決で述べられているとおり、RubyのTimeは内部表現にRationalを使えるようになっているので、その辺を司る部品ですね。
static VALUE quo(VALUE x, VALUE y) { VALUE ret; if (FIXNUM_P(x) && FIXNUM_P(y)) { long a, b, c; a = FIX2LONG(x); b = FIX2LONG(y); if (b == 0) rb_num_zerodiv(); c = a / b; if (c * b == a) { return LONG2NUM(c); } } ret = rb_funcall(x, id_quo, 1, y); if (RB_TYPE_P(ret, T_RATIONAL) && RRATIONAL(ret)->den == INT2FIX(1)) { ret = RRATIONAL(ret)->num; } return ret; }
x64アセンブラも見てみましょう。今日はOS Xで開発しているのでotool -tvV miniruby|less
で見ています。また、quo()は全てインライン化されていたので、ここではtime_subsecの逆アセンブル結果を見ていきます。
static VALUE time_subsec(VALUE time) { struct time_object *tobj; GetTimeval(time, tobj); return quo(w2v(wmod(tobj->timew, WINT2FIXWV(TIME_SCALE))), INT2FIX(TIME_SCALE)); }
_time_subsec: # original 0000000100147f10 pushq %rbp 0000000100147f11 movq %rsp, %rbp 0000000100147f14 pushq %r14 0000000100147f16 pushq %rbx 0000000100147f17 subq $0x10, %rsp 0000000100147f1b movq %rdi, %rbx 0000000100147f1e leaq _time_data_type(%rip), %rsi 0000000100147f25 callq _rb_check_typeddata 0000000100147f2a movb 0x30(%rax), %cl 0000000100147f2d andb $0x7, %cl 0000000100147f30 movzbl %cl, %ecx 0000000100147f33 cmpl $0x3, %ecx 0000000100147f36 je 0x100147ff7 0000000100147f3c movq (%rax), %rdi 0000000100147f3f leaq -0x18(%rbp), %rdx 0000000100147f43 leaq -0x20(%rbp), %rcx 0000000100147f47 movl $0x77359401, %esi ## imm = 0x77359401 0000000100147f4c callq _wdivmod 0000000100147f51 movq -0x20(%rbp), %rdi 0000000100147f55 testb $0x1, %dil 0000000100147f59 je 0x100147fa1 0000000100147f5b movq %rdi, %rcx 0000000100147f5e sarq %rcx0000000100147f61 movabsq $0x112e0be826d694b3, %rdx ## imm = 0x112E0BE826D694B3 0000000100147f6b movq %rcx, %rax 0000000100147f6e imulq %rdx 0000000100147f71 movq %rdx, %rax 0000000100147f74 shrq $0x3f, %rax 0000000100147f78 sarq $0x1a, %rdx 0000000100147f7c addq %rax, %rdx 0000000100147f7f imulq $0x3b9aca00, %rdx, %rax ## imm = 0x3B9ACA00 0000000100147f86 cmpq %rcx, %rax 0000000100147f89 jne 0x100147fa1 0000000100147f8b movabsq $0x4000000000000000, %rax ## imm = 0x4000000000000000 0000000100147f95 addq %rdx, %rax 0000000100147f98 js 0x100147fe7 0000000100147f9a leaq 0x1(%rdx,%rdx), %rax 0000000100147f9f jmp 0x100147fde 0000000100147fa1 movq _id_quo(%rip), %rsi 0000000100147fa8 movl $0x1, %edx 0000000100147fad movl $0x77359401, %ecx ## imm = 0x77359401 0000000100147fb2 xorl %eax, %eax 0000000100147fb4 callq _rb_funcall 0000000100147fb9 testb $0x7, %al 0000000100147fbb jne 0x100147fde 0000000100147fbd movq %rax, %rcx 0000000100147fc0 andq $-0x9, %rcx 0000000100147fc4 je 0x100147fde 0000000100147fc6 movq (%rax), %rcx 0000000100147fc9 andq $0x1f, %rcx 0000000100147fcd cmpq $0xf, %rcx 0000000100147fd1 jne 0x100147fde 0000000100147fd3 cmpq $0x3, 0x18(%rax) 0000000100147fd8 jne 0x100147fde 0000000100147fda movq 0x10(%rax), %rax 0000000100147fde addq $0x10, %rsp 0000000100147fe2 popq %rbx 0000000100147fe3 popq %r14 0000000100147fe5 popq %rbp 0000000100147fe6 retq 0000000100147fe7 movq %rdx, %rdi 0000000100147fea addq $0x10, %rsp 0000000100147fee popq %rbx 0000000100147fef popq %r14 0000000100147ff1 popq %rbp 0000000100147ff2 jmp _rb_int2big 0000000100147ff7 leaq _rb_eTypeError(%rip), %rax 0000000100147ffe movq (%rax), %r14 0000000100148001 movq %rbx, %rdi 0000000100148004 callq _rb_obj_class 0000000100148009 movq %rax, %rcx 000000010014800c leaq 0x8228e(%rip), %rsi ## literal pool for: "uninitialized %li\013" 0000000100148013 xorl %eax, %eax 0000000100148015 movq %r14, %rdi 0000000100148018 movq %rcx, %rdx 000000010014801b callq _rb_raise
とりあえず、その前にこのLONG2NUM
ですが、このquo
って基本割る数yが定数で使われるので、LONG2FIX
を使うようにしましょうか。
a = FIX2LONG(x); b = FIX2LONG(y); if (b == 0) rb_num_zerodiv(); + if (b == -1) LONG2NUM(-a); c = a / b; if (c * b == a) { - return LONG2NUM(c); + return LONG2FIX(c); } } ret = rb_funcall(x, id_quo, 1, y);
とすると、以下の通り_rb_int2big
が消えます。
_time_subsec: # use Fixnum 0000000100146f30 pushq %rbp 0000000100146f31 movq %rsp, %rbp 0000000100146f34 pushq %r14 0000000100146f36 pushq %rbx 0000000100146f37 subq $0x10, %rsp 0000000100146f3b movq %rdi, %rbx 0000000100146f3e leaq _time_data_type(%rip), %rsi 0000000100146f45 callq _rb_check_typeddata 0000000100146f4a movb 0x30(%rax), %cl 0000000100146f4d andb $0x7, %cl 0000000100146f50 movzbl %cl, %ecx 0000000100146f53 cmpl $0x3, %ecx 0000000100146f56 je 0x100146ff8 0000000100146f5c movq (%rax), %rdi 0000000100146f5f leaq -0x18(%rbp), %rdx 0000000100146f63 leaq -0x20(%rbp), %rcx 0000000100146f67 movl $0x77359401, %esi ## imm = 0x77359401 0000000100146f6c callq _wdivmod 0000000100146f71 movq -0x20(%rbp), %rdi 0000000100146f75 testb $0x1, %dil 0000000100146f79 je 0x100146fb2 0000000100146f7b movq %rdi, %rcx 0000000100146f7e sarq %rcx 0000000100146f81 movabsq $0x112e0be826d694b3, %rdx ## imm = 0x112E0BE826D694B3 0000000100146f8b movq %rcx, %rax 0000000100146f8e imulq %rdx 0000000100146f91 movq %rdx, %rax 0000000100146f94 shrq $0x3f, %rax 0000000100146f98 sarq $0x1a, %rdx 0000000100146f9c addq %rax, %rdx 0000000100146f9f imulq $0x3b9aca00, %rdx, %rax ## imm = 0x3B9ACA00 0000000100146fa6 cmpq %rcx, %rax 0000000100146fa9 jne 0x100146fb2 0000000100146fab leaq 0x1(%rdx,%rdx), %rax 0000000100146fb0 jmp 0x100146fef 0000000100146fb2 movq _id_quo(%rip), %rsi 0000000100146fb9 movl $0x1, %edx 0000000100146fbe movl $0x77359401, %ecx ## imm = 0x77359401 0000000100146fc3 xorl %eax, %eax 0000000100146fc5 callq _rb_funcall 0000000100146fca testb $0x7, %al 0000000100146fcc jne 0x100146fef 0000000100146fce movq %rax, %rcx 0000000100146fd1 andq $-0x9, %rcx 0000000100146fd5 je 0x100146fef 0000000100146fd7 movq (%rax), %rcx 0000000100146fda andq $0x1f, %rcx 0000000100146fde cmpq $0xf, %rcx 0000000100146fe2 jne 0x100146fef 0000000100146fe4 cmpq $0x3, 0x18(%rax) 0000000100146fe9 jne 0x100146fef 0000000100146feb movq 0x10(%rax), %rax 0000000100146fef addq $0x10, %rsp 0000000100146ff3 popq %rbx 0000000100146ff4 popq %r14 0000000100146ff6 popq %rbp 0000000100146ff7 retq 0000000100146ff8 leaq _rb_eTypeError(%rip), %rax 0000000100146fff movq (%rax), %r14 0000000100147002 movq %rbx, %rdi 0000000100147005 callq _rb_obj_class 000000010014700a movq %rax, %rcx 000000010014700d leaq 0x8228d(%rip), %rsi ## literal pool for: "uninitialized %li\013" 0000000100147014 xorl %eax, %eax 0000000100147016 movq %r14, %rdi 0000000100147019 movq %rcx, %rdx 000000010014701c callq _rb_raise 0000000100147021 nopw %cs:(%rax,%rax)
さて、今回のコードを見てまず注目したいのはc * b == a
です。これは直前のa / b
が割り切れたかを確認しているのですね。しかし、前回の記事を読んだ方ならピーンとくるのではないでしょうか。そう、/
と%
はコンパイラが一つにまとめてくれます。コンパイラにこのコードの意図を教えてあげましょう。
a = FIX2LONG(x); b = FIX2LONG(y); if (b == 0) rb_num_zerodiv(); + if (b == -1) LONG2NUM(-a); c = a / b; - if (c * b == a) { - return LONG2NUM(c); + if (a % b == 0) { + return LONG2FIX(c); } } ret = rb_funcall(x, id_quo, 1, y);
0000000100147ecc callq _wdivmod 0000000100147ed1 movq -0x20(%rbp), %rdi 0000000100147ed5 testb $0x1, %dil 0000000100147ed9 je 0x100147f0b 0000000100147edb movq %rdi, %rcx 0000000100147ede sarq %rcx 0000000100147ee1 movabsq $0x112e0be826d694b3, %rsi ## imm = 0x112E0BE826D694B3 0000000100147eeb movq %rcx, %rax 0000000100147eee imulq %rsi 0000000100147ef1 movq %rdx, %rax 0000000100147ef4 shrq $0x3f, %rax 0000000100147ef8 sarq $0x1a, %rdx 0000000100147efc addq %rax, %rdx 0000000100147eff imulq $0x3b9aca00, %rdx, %rax ## imm = 0x3B9ACA00 0000000100147f06 cmpq %rax, %rcx 0000000100147f09 je 0x100147f4a 0000000100147f0b movq _id_quo(%rip), %rsi 0000000100147f12 movl $0x1, %edx 0000000100147f17 movl $0x77359401, %ecx ## imm = 0x77359401 0000000100147f1c xorl %eax, %eax 0000000100147f1e callq _rb_funcall 0000000100147f23 testb $0x7, %al 0000000100147f25 jne 0x100147f63 0000000100147f27 movq %rax, %rcx 0000000100147f2a andq $-0x9, %rcx 0000000100147f2e je 0x100147f63 0000000100147f30 movq (%rax), %rcx 0000000100147f33 andq $0x1f, %rcx 0000000100147f37 cmpq $0xf, %rcx 0000000100147f3b jne 0x100147f63 0000000100147f3d cmpq $0x3, 0x18(%rax) 0000000100147f42 jne 0x100147f63 0000000100147f44 movq 0x10(%rax), %rax 0000000100147f48 jmp 0x100147f63 0000000100147f4a movq %rcx, %rax 0000000100147f4d imulq %rsi 0000000100147f50 movq %rdx, %rax 0000000100147f53 shrq $0x3f, %rax 0000000100147f57 sarq $0x1a, %rdx 0000000100147f5b addq %rax, %rdx 0000000100147f5e leaq 0x1(%rdx,%rdx), %rax 0000000100147f63 addq $0x10, %rsp 0000000100147f67 popq %rbx 0000000100147f68 popq %r14 0000000100147f6a popq %rbp 0000000100147f6b retq
……わかりづらいと思いますが、命令数が増えています。ていうか、そもそもアセンブラに前回登場したidivがいません、ふしぎ。
これは、定数の除算がコンパイル時点で乗算とシフトに置き換えられているからです。整数の割り算を掛け算に変換のシリーズが詳しいので解説は譲り、ここでは動きだけ確認しましょう。
- callq _wdivmod # wmodから戻ってくる
- movq -0x20(%rbp), %rdi # 戻り値を%rdiに入れる
- testb $0x1, %dil # 戻り値がFixnumか、1と論理積を取って判定。Fixnumの場合、VALUEは最下位ビットが1です。なお、これはquo(x, y)のxで、yは1000000000で定数なので消えています。
- je 0x100147f0b # ZFが0の時にジャンプ。つまり、Fixnumならジャンプしません
- movq %rdi, %rcx # %rdiの内容を%rcxにコピー
- sarq %rcx # rcx >> = 1 # つまり、xの数値です
- movabsq $0x112e0be826d694b3, %rsiに謎の値を入れる
- movq %rcx, %rax # %rcxの内容を%raxにコピー
- imulq %rsi # %rsi * %rax を計算し、下位64bitを%raxに、上位64bitを%rdxに入れます
- movq %rdx, %rax # %rdxを%raxにコピー
- shrq $0x3f, %rax # rax >>= 0x3f # 符号維持63bit右シフト
- sarq $0x1a, %rdx # rdx >>= 0x1a # 20bit右シフト
- addq %rax, %rdx %rdxに%raxを足す
- imulq $0x3b9aca00, %rdx, %rax # %rdx * 0x3b9aca00 を %raxにいれる (0x3b9aca00 == 1000000000)
- cmpq %rax, %rcx一致したか確認
微妙な誤差の調整を除いてまとめると、だいたい(123456789000000000*0x112e0be826d694b3)>>(64+0x1a) == 123456789
ってとこですね。
同じ割り算を連続して行うようなアプリケーションならば、このような最適化をその都度行ってJIT的に処理すると言うことも考えられますが、Rubyだとちょっとやりづらいですかねぇ。
さて、今回は既にコンパイラが十分に最適化していたため、目立った成果はありませんでした。次回こそ頑張りましょう。
Bignumの10進文字列化を速くしよう
んー、花粉症がひどいし、ここはぱーっとRubyでも高速化して景気づけしたいですね。
先日の日記 でRubyとCしか読めないこの日記の読者の皆さんも、アセンブラに親しみが持てるようになったのではないかと思います。せっかくなので、引き続きこの方向で頑張ってみましょう。
さて、3年前、akrさんが一度はマージしながらも断念した、Use 128 bit integer type in Bignumという案件があります。今日はここから始めます。同時期に公開された資料に「プログラミング言語 Ruby に GMP を組み込む」というものがあります。読むとakrさんの思想の一端が垣間見え、それはしばしばRubyの仕様に影響を与えたりしなくもないのですが、それはまた別の話。どうも1000bitあたりの基数変換(2進→10進 文字列化) が遅かったみたいですね。
しかし、冷静になって考えてみましょう。32bitでの計算を64bitで計算して遅くなるはずがありません。どこかに遅くしている犯人がいるに違いない。また、天下のIntel様の誇る21世紀のCPUや、人類の叡智の結晶GCCが悪いはずもないでしょう。つまり、CRubyが悪いに決まっています。容疑者が絞れたので、早速今日もperf
を使ってみましょう。
./miniruby -ve'n=Random.new.random_number(2**1000);n.to_s while 1'
などと雑なマイクロベンチマークを回しつつ、sudo perf top
で見てみましょう。
64.53% miniruby [.] big2str_2bdigits 21.09% miniruby [.] bigdivrem1 5.10% miniruby [.] big2str_karatsuba 1.98% miniruby [.] bary_addc.constprop.35 0.82% miniruby [.] bigdivrem_restoring 0.69% miniruby [.] power_cache_get_power 0.60% libc-2.19.so [.] _int_free
big2str_2bdigits
が1番のボトルネックみたいですね。詳細を見ます。
0.04 │ 3c: movslq 0x10(%rbx),%rdi ▒ 0.00 │ lea ruby_digitmap,%r9 ▒ │ movslq 0x4(%rbx),%rcx ▒ 0.03 │ nop ▒ 0.10 │ 50:┌─ mov %rsi,%rax ▒ 1.42 │ │ xor %edx,%edx ▒ 0.10 │ │ sub $0x1,%rdi ▒ 0.04 │ │ div %rcx ▒ 58.45 │ │ movzbl (%r9,%rdx,1),%eax ▒ 6.47 │ │ xor %edx,%edx ▒ │ │ mov %al,(%r8,%rdi,1) ▒ 1.69 │ │ movslq 0x4(%rbx),%rcx ▒ 0.11 │ │ mov %rsi,%rax ▒ │ │ div %rcx ▒ 27.79 │ │ mov %rax,%rsi ▒ 0.03 │ │ test %rdi,%rdi ▒ │ └──jne 50 ▒ │ movslq 0x10(%rbx),%rbp ▒ 0.09 │ 7d: add %rbp,0x20(%rbx) ▒ │ 81: mov 0x48(%rsp),%rax ▒ │ xor %fs:0x28,%rax
さて、ここで気付くのは最内ループにdivが2個あることです。Cソースを見ると、
p = b2s->ptr; j = b2s->hbase2_numdigits; do { p[--j] = ruby_digitmap[num % b2s->base]; num /= b2s->base; } while (j); len = b2s->hbase2_numdigits;
となっており、%と/の2回ですね。しかたないね…じゃなくて、待って欲しい。割り算の商と余りは一度に両方出せる。人間でも知ってますね。GCC様が知らないはずがありません。書き方を工夫してみましょう。
p = b2s->ptr; j = b2s->hbase2_numdigits; do { long idx = num % b2s->base; num /= b2s->base; p[--j] = ruby_digitmap[idx]; } while (j); len = b2s->hbase2_numdigits;
これならGCCも理解できたようで、無事divが1つになりました。
4291b0: 48 63 73 04 movslq 0x4(%rbx),%rsi 4291b4: 31 d2 xor %edx,%edx 4291b6: 48 83 e9 01 sub $0x1,%rcx 4291ba: 48 f7 f6 div %rsi 4291bd: 41 0f b6 14 10 movzbl (%r8,%rdx,1),%edx 4291c2: 88 14 0f mov %dl,(%rdi,%rcx,1) 4291c5: 48 85 c9 test %rcx,%rcx 4291c8: 75 e6 jne 4291b0 <big2str_2bdigits+0x50> 4291ca: 48 63 6b 10 movslq 0x10(%rbx),%rbp 4291ce: 48 01 6b 20 add %rbp,0x20(%rbx) 4291d2: 48 8b 44 24 48 mov 0x48(%rsp),%rax 4291d7: 64 48 33 04 25 28 00 xor %fs:0x28,%rax
BEFORE: % perf stat ./miniruby -ve'1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}' ruby 2.4.0dev (2016-03-14 trunk 54096) [x86_64-linux] Performance counter stats for './miniruby -ve1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}': 8686.042902 task-clock (msec) # 0.999 CPUs utilized 136 context-switches # 0.016 K/sec 2 cpu-migrations # 0.000 K/sec 1288 page-faults # 0.148 K/sec 25492506980 cycles # 2.935 GHz 13225449435 stalled-cycles-frontend # 51.88% frontend cycles idle <not supported> stalled-cycles-backend 22023197929 instructions # 0.86 insns per cycle # 0.60 stalled cycles per insn 3213414500 branches # 369.951 M/sec 4716993 branch-misses # 0.15% of all branches 8.695071305 seconds time elapsed AFTER (r54102): % perf stat ./miniruby -ve'1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}' ruby 2.4.0dev (2016-03-14 trunk 54096) [x86_64-linux] Performance counter stats for './miniruby -ve1000000.times{1394009519767279294246510141478471797669978954897613915557413368048327134214313607298484892788729181350733701973860680235136215859195604566916047459319639591913564242295277658139309044846000010192944937354743647901341274278586535726609303298455111458383678266601931358370666199705386621791721556094289.to_s}': 6391.824784 task-clock (msec) # 0.999 CPUs utilized 134 context-switches # 0.021 K/sec 3 cpu-migrations # 0.000 K/sec 1287 page-faults # 0.201 K/sec 18756613064 cycles # 2.934 GHz 9833932236 stalled-cycles-frontend # 52.43% frontend cycles idle <not supported> stalled-cycles-backend 20548725389 instructions # 1.10 insns per cycle # 0.48 stalled cycles per insn 3212938017 branches # 502.664 M/sec 4574367 branch-misses # 0.14% of all branches 6.400175165 seconds time elapsed
はい、簡単でしたね。
当初の予定からはちょっとずれた気もしますが、一パッチできたので今日はこの辺で。
CRubyとLink Time Optimizationについて
最近、夜寝る前にRubyのベンチマークを眺めたり、仕事の障害時のログを眺めるっていう悪趣味極まりない習慣がついてしまった。まぁ、草木も眠る丑三つ時にこの世の真理を求めて何かを読みふけるって言うのは、この業界にいる人間なら誰しもがやることなんじゃ無いかと思う。それと同じで現場百遍とも言うとおり、何度もprofileやログを眺めれば何か気付くこともあるんじゃないかと思って読んでいる……というわけではなくて、ふと見たくなる衝動に従っているだけだけど。
さて、Rubyのprofileを取るときに便利なのがRubyKaigi 2015でこさきさんも紹介していたperf。あまりに便利なせいで、プライベートでLinuxを触る時間が何千倍にも増えたくらい。あの発表はもっぱらperf-topの紹介だったけど、perfの使い方とかを見ると他にも色々な機能があることがわかる。例えば、昨日話題になったひたすらblockを実行するコードを見たくなったら、
% perf record ./miniruby --disable-gem -e'100_000_000.times{}' % perf report
とすると、
Samples: 8K of event 'cycles', Event count (approx.): 13538619277 27.11% miniruby miniruby [.] vm_exec_core 24.59% miniruby miniruby [.] invoke_block_from_c_0 12.85% miniruby miniruby [.] vm_push_frame.isra.69 12.76% miniruby miniruby [.] vm_exec 10.25% miniruby miniruby [.] rb_yield_1 9.72% miniruby miniruby [.] vm_callee_setup_block_arg 2.39% miniruby miniruby [.] int_dotimes 0.22% miniruby [kernel.kallsyms] [k] 0xffffffff8104f45a 0.01% miniruby miniruby [.] rb_ivar_get 0.01% miniruby miniruby [.] rb_frozen_class_p 0.01% miniruby miniruby [.] st_clear 0.01% miniruby miniruby [.] mix_id_table_insert 0.01% miniruby miniruby [.] mix_id_table_lookup 0.01% miniruby miniruby [.] rb_add_method_cfunc 0.01% miniruby miniruby [.] coderange_scan 0.01% miniruby libc-2.19.so [.] __libc_calloc 0.01% miniruby miniruby [.] hash_id_table_insert_key.part.19 0.01% miniruby miniruby [.] ruby_sip_hash24 0.01% miniruby miniruby [.] mix_id_table_foreach 0.01% miniruby miniruby [.] rb_enc_symname_type 0.00% miniruby libc-2.19.so [.] _int_malloc 0.00% miniruby miniruby [.] rb_define_method 0.00% miniruby miniruby [.] fstr_update_callback 0.00% miniruby libc-2.19.so [.] _IO_file_fopen@@GLIBC_2.2.5 0.00% miniruby miniruby [.] ruby_init_stack 0.00% miniruby libpthread-2.19.so [.] pthread_setname_np Press '?' for help on key bindings
という画面になる。こっからさらにカーソル[→]で各関数についての詳細を見れる。
Annotate vm_exec_core Zoom into miniruby(26888) thread Zoom into miniruby DSO Browse map details Run scripts for samples of thread [miniruby] Run scripts for samples of symbol [vm_exec_core] Run scripts for all samples Switch to another data file in PWD Exit
けど、Rubyのprofileを見るって観点だとあまり使えない項目ばかりなので、"Annotate vm_exec_core"を選んで逆アセンブル結果を表示します。
vm_exec_core /home/naruse/ruby/miniruby │ SET_GLOBAL((VALUE)entry, val); │ vzerou │ callq rb_gvar_set │ jmpq ffffffffffa33d50 │ nop │ { │ VALUE val; │ │ │ DEBUG_ENTER_INSN("putnil"); │ ADD_PC(1+0); │ lea 0x8(%r14),%rax │ mov %r14,%rcx 1.66 │ mov %rax,(%r15) 0.09 │ mov %rax,%r14 │ #line 267 "insns.def" │ val = Qnil; │ │ #line 382 "vm.inc" │ CHECK_VM_STACK_OVERFLOW_FOR_INSN(REG_CFP, 1); │ PUSH(val); 0.30 │ mov 0x8(%r15),%rax 0.13 │ movq $0x8,(%rax) 8.82 │ add $0x8,%rax 0.04 │ mov %rax,0x8(%r15) │ jmpq ffffffffffa33d50 │ nop │ { │ VALUE val; │ │ │ DEBUG_ENTER_INSN("putself"); │ ADD_PC(1+0); │ lea 0x8(%r14),%rdx │ mov %r14,%rcx │ putself │ () │ () │ (VALUE val) │ { │ val = GET_SELF(); │ mov 0x20(%r15),%rsi │ mov %rdx,(%r15) │ mov %rdx,%r14 │ #line 281 "insns.def" │ val = GET_SELF(); │ Press 'h' for help on key bindings
この日記の読者は、Cは読めてもアセンブラは読めない人が多いと思うけど、大丈夫、わたしも読めない。いつもぐぐって出てきたページとかを見ながら眺めてます。
さて、この8.82(vm_exec_core中の8%がここ)って出てるところでちょっと時間を食ってるみたいなんだけど、加算命令であるaddでそんなに時間がかかるはずはなくて、たぶん前後のメモリ書き込み命令movを待ってるんじゃ無いかと思う。つまり、わたしごときでは何か出来ることはない。
気を取り直して[←]を押し、他の関数……rb_yield_1を見てみよう。
rb_yield_1 /home/naruse/ruby/miniruby 5.86 │ sub $0x18,%rsp │ mov %rdi,0x8(%rsp) 14.30 │ mov ruby_current_thread,%rdi 2.70 │ mov 0x30(%rdi),%rax 1.69 │ mov 0x28(%rax),%rax 2.48 │ mov (%rax),%rsi 10.70 │ test $0x2,%sil │ jne 35 │ nop │28: and $0xfffffffffffffffc,%rsi │ mov (%rsi),%rsi │ test $0x2,%sil │ je 28 3.38 │35: and $0xfffffffffffffffc,%rsi │ je 59 3.15 │ mov (%rsi),%rdx 28.83 │ pushq $0x1 │ xor %r9d,%r9d │ mov $0x1,%ecx │ pushq $0x0 4.62 │ lea 0x18(%rsp),%r8 │ callq invoke_block_from_c_0 22.18 │ add $0x28,%rsp 0.11 │ retq │59: lea pathname_too_long.9784+0x500,%rdi │ xor %edx,%edx │ mov $0x8,%esi │ callq rb_vm_localjump_error
短いですね。[s]を押すとCのソースが消えてアセンブラだけになり、30行無いことがわかります。
二桁の数値がいくつも踊っているけど、単に短いからなのでそこは気にするところではなくて、気にするのはこの長さならinlineしてよくね?ってとこですね。inlineされていない理由は簡単は、単にrb_yield_1()はvm_eval.cにあって、それを呼んでるint_dotimes() ——この関数が何者かわかりますね?—— はnumeric.cにいるからですね。
じゃあinline化したら速くなるのかな?というのは気になるところで、int_dotimesをvm_eval.cに持ってきてもいいんだけど(よくないけど)、最近のコンパイラにはリンク時にオブジェクトファイルをまたいでinline化とかをしてくれる超技術Link Time Optimizationってのがついているので使って見ましょう。optflags='-O3 -fno-fast-math -march=native -flto'などと追加してビルドし、profileを取ってみます。
BEFORE: Performance counter stats for './miniruby --disable-gem -e100_000_000.times{}': 5153.515293 task-clock (msec) # 0.997 CPUs utilized 123 context-switches # 0.024 K/sec 1 cpu-migrations # 0.000 K/sec 873 page-faults # 0.169 K/sec 14894914453 cycles # 2.890 GHz 5256063515 stalled-cycles-frontend # 35.29% frontend cycles idle <not supported> stalled-cycles-backend 37123557344 instructions # 2.49 insns per cycle # 0.14 stalled cycles per insn 5304912019 branches # 1029.377 M/sec 202652 branch-misses # 0.00% of all branches 5.170935973 seconds time elapsed AFTER: Performance counter stats for './miniruby --disable-gem -e100_000_000.times{}': 4456.424594 task-clock (msec) # 0.997 CPUs utilized 269 context-switches # 0.060 K/sec 2 cpu-migrations # 0.000 K/sec 823 page-faults # 0.185 K/sec 13179265879 cycles # 2.957 GHz 3793118960 stalled-cycles-frontend # 28.78% frontend cycles idle <not supported> stalled-cycles-backend 36422695065 instructions # 2.76 insns per cycle # 0.10 stalled cycles per insn 5004776248 branches # 1123.047 M/sec 147323 branch-misses # 0.00% of all branches 4.471030258 seconds time elapsed
2割ほど速くなったようです。 ついでにint_dotimesを見てみると、さっきはrb_yield_1()の中にいた、rb_yieldやinvoke_block_from_c_0()を呼ぶコードがinline化されていることがわかりますね。
int_dotimes /home/naruse/ruby/miniruby │ mov %rbp,%rbx ▒ │ sar %rbx ▒ │ test %rbx,%rbx ▒ │ jle a9 ▒ │ lea 0x8(%rsp),%r12 ▒ │ xor %r13d,%r13d ▒ │ nop ▒ 5.38 │ 40: mov ruby_current_thread,%rdi ▒ │ lea 0x1(%r13,%r13,1),%rax ▒ │ mov %rax,0x8(%rsp) ▒ 16.46 │ mov 0x30(%rdi),%rax ▒ │ mov 0x28(%rax),%rax ▒ 0.67 │ mov (%rax),%rsi ▒ 14.33 │ test $0x2,%sil ▒ 7.39 │ jne 7d ▒ │ data32 data32 data32 data32 nopw %cs:0x0(%rax,%rax,1) ▒ │ 70: and $0xfffffffffffffffc,%rsi ▒ │ mov (%rsi),%rsi ▒ │ test $0x2,%sil ◆ │ je 70 ▒ 6.61 │ 7d: and $0xfffffffffffffffc,%rsi ▒ │ je 13a ▒ 0.11 │ mov (%rsi),%rdx ▒ 23.07 │ pushq $0x1 ▒ │ xor %r9d,%r9d ▒ │ mov %r12,%r8 ▒ │ pushq $0x0 ▒ 6.49 │ mov $0x1,%ecx ▒ │ add $0x1,%r13 ▒ │ callq invoke_block_from_c_0.lto_priv.567 ▒ 18.81 │ pop %rax ▒ 0.11 │ pop %rdx ▒ 0.56 │ cmp %r13,%rbx ▒ │ jne 40 ▒ │ a9: add $0x18,%rsp ▒ │ mov %rbp,%rax ▒ │ pop %rbx ▒ │ pop %rbp ▒ │ pop %r12 ▒ │ pop %r13 ▒ │ retq ▒ │ nop ▒ │ c0: mov %rbx,%rdi ▒ │ callq rb_yield ▒ │ mov %rbx,%rdi ▒ │ mov $0x3,%ecx ▒ │ xor %eax,%eax ▒ Press 'h' for help on key bindings
ちなみに、スピード狂の方々はご存じでしょうが、Rubyでループを最速に回せるのはwhileで、その場合の結果は以下のような感じでした。
Performance counter stats for './miniruby --disable-gem -ei=0;while i<100_000_000;i+=1;end': 2071.648179 task-clock (msec) # 0.998 CPUs utilized 35 context-switches # 0.017 K/sec 2 cpu-migrations # 0.001 K/sec 878 page-faults # 0.424 K/sec 6041423503 cycles # 2.916 GHz 2493938546 stalled-cycles-frontend # 41.28% frontend cycles idle <not supported> stalled-cycles-backend 14520079387 instructions # 2.40 insns per cycle # 0.17 stalled cycles per insn 1504280501 branches # 726.127 M/sec 116788 branch-misses # 0.01% of all branches 2.076396582 seconds time elapsed Samples: 3K of event 'cycles', Event count (approx.): 6014184501 99.69% miniruby miniruby [.] vm_exec_core 0.25% miniruby [kernel.kallsyms] [k] 0xffffffff8104f45a 0.02% miniruby miniruby [.] rb_class_foreach_subclass 0.01% miniruby miniruby [.] st_lookup 0.01% miniruby miniruby [.] ruby_sip_hash24 0.01% miniruby miniruby [.] rb_wb_protected_newobj_of 0.01% miniruby miniruby [.] rb_freeze_singleton_class 0.01% miniruby miniruby [.] fc_i 0.00% miniruby miniruby [.] thread_timer
バイトコードにコンパイルする際にエスケープ解析とかすればJITを導入しなくてもまだ倍速くする余地があるってことですかね……。これをやるのは読者の宿題に残しておくのでぜひ頑張って欲しい。
What is nil? No matter. What is nil? Never mind.
"What is nil?" is mysterious question in Ruby. You may answer like "nothing", "nothing exists", or "NULL". Brian, the founder of Rubinius, wrote his thoughts around Lonely operator.
CRuby developers sometimes discussed about nil for example [ruby-dev:29374] nil.to_s. The thread is talked about the behavior of nil.to_s
.
The use case of &.
Ruby solves real problem. Ruby's complexity is come from the complexity of the real world. When Ruby adds a new feature, it should be designed for real use case. For example Lonely operator (and the ancestor Object#try! of ActionSupport) are designed for below:
<% if current_user && current_user.premium? %> Hi,<%= current_user.name %>, we offer a new campaign! <% end %>
Rails programmers often write a template like this. In this case, current_user is nil when the user is not login yet; it's actually valid status.
Some people try to define NilClass#method_missing like Brian says. "The Hopelessly Egocentric Blog Post" is a good article about the idea. I summarize the article: don't try it. Rails developed Object#try/try! from the experience. Ruby agreed the conclusion and added &.
.
The use case of dig
The use case of Hash#dig and Array#dig is JSON from REST API. For example following Redmine's REST API (full result),
{ "issue": { "id": 11537, ... "assigned_to": { "id": 13, "name": "Yukihiro Matsumoto" }, "subject": "Introduce \"Safe navigation operator\"", "done_ratio": 100, "created_on": "2015-09-18T09:29:09Z", "updated_on": "2015-12-05T07:58:25Z", "closed_on": "2015-12-05T07:58:25Z" } }
You can get matz by json.dig('issue', 'assigned_to', 'name')
without suffering issue doesn't exist or it is not assigned anyone.
Traceable nils
I don't have a use case for this because I don't have an experience suffered to explore where a nil come from. When I hit "NoMethodError: undefined method `...' for nil:NilClass", it usually come from models. It doesn't need to trace. Or if people hit a trouble the issue is how the nil come from, not where the nil is born, I imagine. Anyway such experiment is interesting. I watch the reaction by developers.
therubyracer considered harmful
要約
therubyracerはやめてexecjsからnodeコマンド使え。
解説
Rails 3.1 で Asset Pipeline が導入されて以来、Gemfileにgem 'therubyracer'
と書く人も増えたのではないでしょうか。しかし、それがどの程度のリスクを背負っているのか自覚のない人も多いように感じます。
平時はChrome由来のJavaScriptエンジンであるv8を手軽にインストールできてスーパー便利なtherubyracer.gem & libv8.gemですが、その潜在的なリスクには震えるものがあります。最初にこれが世を騒がせたのは3年前のクリスマス前のことだったでしょうか。
v8
この問題の背景には、本質的に「v8のビルドは難しい」という点があります。雑にバージョンを選ぶとビルドが通りません。そもそもがChromeのためのものだからなんでしょうか。リリースする前に個別にパッチ当ててるんですかね。
libv8.gem
上記のような邪悪を封じ込めたのがlibv8.gemです。libv8.gemがインストールされていれば、楽に利用することが出来ます。バイナリのlibv8.gemが既にあれば楽ですが、時々ありません。例えば、2016年1月8日現在、El Capitan用のバイナリgemはありません。
自分でgemを作る場合は自分でv8もビルドするか、–with-system-v8でbrewなどから入れたv8を使うかを選ぶ必要があります。前者は言うまでもなく大変なのですが(2016年1月8日現在、正常にビルドが通りましたが3分かかりました)、後者もv8とlibv8のバージョン依存問題に加え、一度libv8.gemを作ったあとでうっかりbrew updateするとバイナリgemが壊れることがあります。
therubyracer.gem
therubyracerはlibv8への激しいバージョン依存があります。昔はプラットフォームによって正常にビルドできるlibv8のバージョンが違うのにtherubyracerがそれぞれ別のバージョンになっていてGemfileどう書けばいいんだ…とか泣いてた記憶があるんですが、さすがに今はそういうことはないのかな。
まとめ
以上の通り大変なので、この問題につっこんでいくことは特段の必要性が無い限り避けるべきです。(特段の必要性というのは、たとえば細かいJavaScriptコードを何度も繰り返し実行する必要がある、とかです)RailsのAsset Pipeラインの場合、execjsを用いてnodeコマンドを叩くことが出来ます。nodeコマンドならどのプラットフォームかによらず、いつでも簡単に新しいものを入れられるので安心安全です。無駄な仕事を減らして高い生産性を保ちましょう。