投機実行とOut of Orderはつよいというはなし

fluentdな人達と話していると定期的にRubyのオブジェクト生成が遅いとdisられます。

本質的にしょうがない部分もあるんですが、それにしても遅い部分も結構あるので、おもむろにperf statperf 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なしだとそこまで性能向上無かったので、多分他の場所でもっと効いてるんだと思います。

最初はもうちょっと違う話を書くつもりだったんですが長くなったので今日はここまで