投機実行と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なしだとそこまで性能向上無かったので、多分他の場所でもっと効いてるんだと思います。
最初はもうちょっと違う話を書くつもりだったんですが長くなったので今日はここまで
