bpftraceを使ってバイナリの謎の性能劣化を突き止めろ

サイボウズ社内ではC++で開発している製品があります。 未知のバッファオーバーランなどの脆弱性への対策として、重要なコンポーネントについてはプロダクション環境で利用しているバイナリでも AddressSanitizer を有効にしてビルドしています。

その製品で利用しているコンパイラをgcc5.3.0からgcc7.5.0に更新したところ性能劣化が発生しました。 製品コードとは別の部分が原因のため、根本原因の追跡が難しそうです。perf,bpftraceを使って性能劣化を追いかけてみましょう。

本記事で利用しているAddressSanitizer, bpftrace, perfコマンドはネット上に良質な記事がありますので、使い方などの解説は今回は省略させていただきます。

gcc7.5.0において、性能劣化が発生する再現コードとして次のようなものを用意しました。

#include <string.h>
#include <iostream>
#include <string>
#include <vector>
int main() {
  const int L = 1000000;
  const int N = 1000;
  const int R = 100;
  std::vector<std::string> bufs(N, std::string(L, 'A'));
  int hash = 0;
  for(int r = 0; r < R; r++) {
    for (int i = 0; i < N; i++) {
      int sum = strlen(bufs[i].c_str() + r);
      const char* found = strchr(bufs[i].c_str(), 'A');
      hash += (sum + *found) % 10;
    }
  }
  std::cout << hash << std::endl;
}

AddressSanitizerを有効化(-fsanitize=address -static-libasan)してコンパイル、実行時間を計測してみます。

$ gcc -v # => gcc version 7.5.0 (Ubuntu 7.5.0-3ubuntu1~18.04) 
$ g++ -DNDEBUG -std=c++11 -Wall -Wextra -fsanitize=address -O3 -g -static-libasan samplecode.cpp
$ time ./a.out
450000

real    0m36.898s
user    0m36.426s
sys 0m0.380s

比較としてAddressSanitizerを無効化してコンパイル、実行時間を計測してみます。

$ g++ -DNDEBUG -std=c++11 -Wall -Wextra -O3 -g  samplecode.cpp
$ time ./a.out 
450000

real    0m5.058s
user    0m4.805s
sys 0m0.253s

AddressSanitizerの性能影響に関する考察 を読むと

The average slowdown introduced by full instrumentation (red) is 1.73. When only writes are instrumented (blue), the average slowdown is 1.26

とありますので、AddressSanitizerの意図していない性能劣化が起きていると考えてよさそうです。

perfコマンドでパフォーマンス劣化のホットスポットを探る

AddressSanitizer有効化したバイナリをperfコマンドで計測してみます。

$ sudo perf record ./a.out --stdio
$ sudo perf report --stdio
# To display the perf.data header info, please use --header/--header-only options.
# Overhead  Command  Shared Object       Symbol                                                                               
# ........  .......  ..................  .....................................................................................
#
    83.86%  a.out    a.out               [.] __sanitizer::internal_strlen
    12.70%  a.out    libc-2.27.so        [.] __strlen_avx2
     1.36%  a.out    a.out               [.] __sanitizer::mem_is_zero

perfの診断結果から__sanitizer::internal_strlenが性能劣化の大部分を占めていることがわかります。 __sanitizer::internal_strlenはgccのレポジトリを探すとAddressSanitizerのコードということがわかります。

__sanitizer::internal_strlenが遅い理由は最後に簡単に紹介しています。これ以上の深入りはしません。

bpftraceを使ってあやしいコードを絞り込む

bpftraceはバイナリ上の呼び出しをトレースすることができるのでこれを利用します。

bpftraceで発生したuprobeのトレーシングにstrlen関連に絞り込んでみましょう。

$ sudo bpftrace -l 'uprobe:/home/yokotaso/a.out' | grep strlen
uprobe:/home/yokotaso/a.out:_ZN11__sanitizer15internal_strlenEPKc
uprobe:/home/yokotaso/a.out:__asan_internal_strlen
uprobe:/home/yokotaso/a.out:__interceptor_strlen
uprobe:/home/yokotaso/a.out:__interceptor_strlen.part.24
uprobe:/home/yokotaso/a.out:strlen

_ZN11__sanitizer15internal_strlenEPKc は nmとobjdump を使って調べると、性能劣化の原因になっている __sanitizer::internal_strlenということがわかります。

$ nm a.out | grep _ZN11__sanitizer15internal_strlenEPKc
00000000000d87f0 t _ZN11__sanitizer15internal_strlenEPKc

$ objdump -CSlw -M intel a.out | c++filt | grep 00000000000d87f0 -A10
00000000000d87f0 <__sanitizer::internal_strlen(char const*)>:
__sanitizer::internal_strlen(char const*)():
   d87f0:   31 c0                   xor    eax,eax
   d87f2:   80 3f 00                cmp    BYTE PTR [rdi],0x0
   d87f5:   74 19                   je     d8810 <__sanitizer::internal_strlen(char const*)+0x20>
   d87f7:   66 0f 1f 84 00 00 00 00 00  nop    WORD PTR [rax+rax*1+0x0]
   d8800:   48 83 c0 01             add    rax,0x1
   d8804:   80 3c 07 00             cmp    BYTE PTR [rdi+rax*1],0x0
   d8808:   75 f6                   jne    d8800 <__sanitizer::internal_strlen(char const*)+0x10>
   d880a:   f3 c3                   repz ret 
   d880c:   0f 1f 40 00             nop    DWORD PTR [rax+0x0]

_ZN11__sanitizer15internal_strlenEPKcの正体が分かったので、bpftraceのトレーシング結果に一度戻りましょう。 フック処理を仕込んでいそうな __interceptor_strlen を調べてみます。

__interceptorのマクロ定義 を 確認すると呼び出したい関数本体が実行される前に前処理をフックしている様子がわかると思います。

strlenのinterceptorの実装 も 確認するとstrlenを呼び出す前に、処理をフックしている様子がわかると思います。

INTERCEPTOR(SIZE_T, strlen, const char *s) {
  // Sometimes strlen is called prior to InitializeCommonInterceptors,
  // in which case the REAL(strlen) typically used in
  // COMMON_INTERCEPTOR_ENTER will fail.  We use internal_strlen here
  // to handle that.
  if (COMMON_INTERCEPTOR_NOTHING_IS_INITIALIZED)
    return internal_strlen(s);
  void *ctx;
  COMMON_INTERCEPTOR_ENTER(ctx, strlen, s);
  SIZE_T result = REAL(strlen)(s);
  if (common_flags()->intercept_strlen)
    COMMON_INTERCEPTOR_READ_RANGE(ctx, s, result + 1);
  return result;
}

__interceptor_* から _ZN11__sanitizer15internal_strlenEPKc の呼び出しを起きるケースを追いかけてみましょう。

bpftraceで特定のバイナリのシンボルの呼び出し回数を測定することができます。 呼び出し元の手がかりが得られそうです。

$ cat strlencount.bc
uprobe:/home/yokotaso/a.out:_ZN11__sanitizer15internal_strlenEPKc,
uprobe:/home/yokotaso/a.out:__interceptor_* { @[probe] = count(); }

$ sudo bpftrace strlencount.bc
Attaching 385 probes...
^C

... Ommit ...
@[uprobe:/home/yokotaso/a.out:__interceptor_memcpy]: 1000
@[uprobe:/home/yokotaso/a.out:__interceptor_strchr]: 100000
@[uprobe:/home/yokotaso/a.out:__interceptor_index]: 100000
@[uprobe:/home/yokotaso/a.out:__interceptor_strlen]: 100000
@[uprobe:/home/yokotaso/a.out:_ZN11__sanitizer15internal_strlenEPKc]: 100026

perfの段階では、strlenが犯人の雰囲気でしたが、__interceptor_strlen, __interceptor_strchr も呼び出されており strchrも容疑の疑いが出てきました。

strlenの冤罪と真犯人strchr

再現コードでstrlenのみをコールするように修正したコードをコンパイルして実行してみます。

$ sudo bpftrace strlencount.bc
Attaching 385 probes...
^C
... Ommit ...
@[uprobe:/home/yokotaso/a.out:__interceptor_malloc]: 11
@[uprobe:/home/yokotaso/a.out:_ZN11__sanitizer15internal_strlenEPKc]: 26
@[uprobe:/home/yokotaso/a.out:__interceptor_memcpy]: 1000
@[uprobe:/home/yokotaso/a.out:__interceptor_strlen]: 100000

Oops!strlenは犯人ではありませんでした!

再現コードでstrchrのみをコールするように修正したコードをコンパイルして実行してみます。

$ sudo bpftrace strlencount.bc
Attaching 385 probes...
^C
... Ommit ...
@[uprobe:/home/yokotaso/a.out:__interceptor_memcpy]: 1000
@[uprobe:/home/yokotaso/a.out:__interceptor_strlen]: 100000
@[uprobe:/home/yokotaso/a.out:__interceptor_index]: 100000
@[uprobe:/home/yokotaso/a.out:__interceptor_strchr]: 100000
@[uprobe:/home/yokotaso/a.out:_ZN11__sanitizer15internal_strlenEPKc]: 100026

真犯人は...strchr!お前だ!証拠もあがってるぞ!

実装を確認してみると、strchrは悪影響を及ぼしているinternal_strlenを無条件に呼び出してしまっています。 AddressSanitizerのstrlenを確認するとinternal_strlenは、特定の条件で呼び出されるようになっていることがわかります。

• strchrのinterceptor定義
• strlenのinterceptor定義

実際にはこんな、頭脳明晰な調査ができたわけではなくperfコマンドの時点でstrlenが怪しいという認知バイアス沼にはまったあげく 泥臭くgccのコード修正履歴を追いかけて問題解決の糸口にしています。bpftraceを使ってstrchrが怪しい裏を取ったという形になります。 今後は、似たような問題が起きた時にbpftrace, perfを活用して問題解決の糸口をより簡単に見つけられそうです。

gcc-9以降はこの問題が解決されているようなので、この問題に遭遇している方がいらっしゃいましたら、gccのアップデートをしてみてください。

$ gcc -v
gcc version 9.3.0 (Ubuntu 9.3.0-17ubuntu1~20.04)
$ g++ -DNDEBUG -std=c++11 -Wall -Wextra -fsanitize=address -O3 -g -static-libasan samplecode.cpp
$ time ./a.out
450000

real    0m5.915s
user    0m5.524s
sys 0m0.380s

おまけ: internal_strlenはなぜ遅いのか？

パフォーマンス劣化の原因になった internal_strlen の実装ですが 遅くなる要因はないように見えます。

uptr internal_strlen(const char *s) {
  uptr i = 0;
  while (s[i]) i++;
  return i;
}

glicのstrlenを 読んでみると1バイトずつ読んでいるのではなく、4 or 8 バイトまとめて読んでいるから高速化されているみたいです。glibcのstrlenが高速化されているということなんですね。

size_t
STRLEN (const char *str)
{
  const char *char_ptr;
  const unsigned long int *longword_ptr;
  unsigned long int longword, himagic, lomagic;

  // ... Omitted ...
  /* All these elucidatory comments refer to 4-byte longwords,
     but the theory applies equally well to 8-byte longwords.  */

  longword_ptr = (unsigned long int *) char_ptr;

  /* Bits 31, 24, 16, and 8 of this number are zero.  Call these bits
     the "holes."  Note that there is a hole just to the left of
     each byte, with an extra at the end:

     bits:  01111110 11111110 11111110 11111111
     bytes: AAAAAAAA BBBBBBBB CCCCCCCC DDDDDDDD

     The 1-bits make sure that carries propagate to the next 0-bit.
     The 0-bits provide holes for carries to fall into.  */
  himagic = 0x80808080L;
  lomagic = 0x01010101L;
  if (sizeof (longword) > 4)
    {
      /* 64-bit version of the magic.  */
      /* Do the shift in two steps to avoid a warning if long has 32 bits.  */
      himagic = ((himagic << 16) << 16) | himagic;
      lomagic = ((lomagic << 16) << 16) | lomagic;
    }
  // ... Omitted ...

  /* Instead of the traditional loop which tests each character,
     we will test a longword at a time.  The tricky part is testing
     if *any of the four* bytes in the longword in question are zero.  */
  for (;;)
    {
      longword = *longword_ptr++;

      if (((longword - lomagic) & ~longword & himagic) != 0)
    {
      /* Which of the bytes was the zero?  If none of them were, it was
        a misfire; continue the search.  */

      const char *cp = (const char *) (longword_ptr - 1);

      if (cp[0] == 0)
        return cp - str;
      if (cp[1] == 0)
        return cp - str + 1;
      if (cp[2] == 0)
        return cp - str + 2;
      if (cp[3] == 0)
        return cp - str + 3;
      if (sizeof (longword) > 4)
        {
          if (cp[4] == 0)
        return cp - str + 4;
          if (cp[5] == 0)
        return cp - str + 5;
          if (cp[6] == 0)
        return cp - str + 6;
          if (cp[7] == 0)
        return cp - str + 7;
        }
    }
    }

なお、社内の本記事の対するフィードバックで追加情報をいただきました。(できるかぎり原文ママ)

strlenのCによる実装は古典的なものですが、実際には https://sourceware.org/git/?p=glibc.git;a=blob;f=sysdeps/x86_64/multiarch/strchr-avx2.S;h=413942b96a835c4a989fb9ea8777d3966b6bb973;hb=0679442defedf7e52a94264975880ab8674736b2 などのAVX2用にアセンブリ言語で書かれたものが使われます。

参考までに昔書いた文字列検索ライブラリの記事。 https://blog.cybozu.io/entry/2016/08/25/080000

全く知りませんでした。奥が深いです...!

まとめ

• gcc-7のAddress Sanitizerはstrchrがパフォーマンスに悪影響があるので問題がある場合はgcc-9に更新しましょう
• perf, bpftraceを活用すると、今まで難しかった調査が一般人でも追跡できることがある
• glibcのstrlenは速い。あとな、アセンブリ版もあるんやで。ありがとう、ｽｰﾊﾟｰﾊｯｶｰ

以上、bpftraceを使った謎の現象の真相究明レポートでした! bpftrace、困ったときに時に役にたつ事が多そうです。これを機にもっと知りたくなりました。

執筆: @yokotaso