dpkg, apt のプロファイリング

上川
_________________________________________________________________________________________________________________________________________________

apt や dpkg のどの部分が一番遅いのか、実際にプロファイリングしてみます。この例をケーススタディーとして一般的にどういう作業をすればパフォーマンスチューニングが必要な部分を抽出できるのか、をあきらかにしてみましょう。

6.1 oprofile のインストールと設定方法

Debian のデフォルトのカーネルは oprofile をサポートしています^*20 。もし、自分でコンパイルしていたりして oprofile サポートを追加していない場合は、カーネルを oprofile サポート付きでコンパイルしなおします。オプションは CONFIG_OPROFILE です。メニューでは

Intrumentation support : Profiling Support : Oprofile system profiling (experimental)^*21

カーネルがサポートしている場合、 oprofile を利用するのに追加で必要なのはoprofileパッケージです。 apt-get install oprofileでインストールしましょう。

カーネルのシンボルのプロファイリング^*22 をするために、 vmlinux ファイルが必要です。カーネルを自分でコンパイルした場合には、ビルドしたディレクトリに vmlinux ファイルがあります。 make-kpkg を利用してビルドしたのであれば、

/lib/modules/$(uname -r)/build

から適切にリンクがはられているはずです。探してみてください。 ^*23

6.2 oprofile が自分の利用している CPU をサポートしていない場合

残念ながら 9 月現在時点の Debian Package では、 Intel core duo CPU 上では oprofile が動作しません。 oprofile は認識できていない場合、 cpu_type 変数が unset という値になります。カーネル側は cpu_type として i386/core を出力しているので、この時点でどうやらカーネル側のサポートは追加されているらしいということがわかります。

$ sudo opcontrol --init
cpu_type ’unset’ is not valid
$ opcontrol --list-events
Unable to open cpu_type file for reading
Make sure you have done opcontrol --init
cpu_type ’unset’ is not valid
$ cat /dev/oprofile/cpu_type
i386/core
$ uname -a
Linux coreduo 2.6.18-rc1dancer #2 SMP Sun Jul 9 09:57:01 JST 2006 i686 GNU/Linux

プロファイルを取得するという目的を考えると手段としてはいくつか考えられます。

今回は oprofile の開発メーリングリストを見たところ、 5 月の時点でだれかがパッチを書いているのを発見したので、それをとりこみます。念のため、今後作業する人のために BTS にも登録しました。 380462^*24

確認してみると、どうやら動作してくれていることがわかりました。ここで、当面重要なのは、 CPU_CLK_UNHALTED でしょう。 CPU サイクルがどの関数で消費されているのかということをトラッキングできます。まず CPU の処理負荷がかかっている部分を目視して、何か問題がないかを眺めてみて、何も問題なく、それなりに問題が追求できにくくなった後に、 L2 キャッシュのイベントの発生度合とかを確認していけばよいでしょう。

$ sudo opcontrol --init
$ sudo opcontrol --list-events
oprofile: available events for CPU type "Core Solo / Duo"

See Intel Architecture Developer’s Manual Volume 3, Appendix A and
Intel Architecture Optimization Reference Manual (730795-001)

CPU_CLK_UNHALTED: (counter: all)
        Unhalted clock cycles (min count: 6000)
        Unit masks (default 0x0)
        ----------
        0x00: Unhalted core cycles
        0x01: Unhalted bus cycles
        0x02: Unhalted bus cycles of this core while the other core is halted
INST_RETIRED: (counter: all)
        number of instructions retired (min count: 6000)
L2_RQSTS: (counter: all)
        number of L2 requests (min count: 6000)
        Unit masks (default 0xf)
        ----------
        0x08: (M)odified cache state
        0x04: (E)xclusive cache state
        0x02: (S)hared cache state
        0x01: (I)nvalid cache state
        0x0f: All cache states
        0x10: HW prefetched line only
        0x20: all prefetched line w/o regarding mask 0x10.

[省略]

6.3 デバッグシンボルを収集する： dpkg と apt をコンパイルしなおす

まず、デバッグ情報がすでにあるパッケージについては、インストールします。今回では、大きいものとして、 libc6-dbg パッケージがあるので、それはインストールします。プロファイルの結果、イメージが上位に出現するなどで、必要そうであれば、あとで他のライブラリなどについてもデバッグ情報のあるバージョンを追加しましょう。

今回プロファイル対象の dpkg と apt はデフォルトではデバッグ情報がありません、プロファイル出力を確認しやすいように、デバッグシンボルを追加してコンパイルしなおします。

$ debuild -e DEB_BUILD_OPTIONS=nostrip

まず、 oprofile を実行するのを便利にするために、スクリプトを仕込みます。入力されたコマンドを 10 回実行してそのプロファイルを取得するというものです。

read CMD
sudo opcontrol --shutdown
sudo opcontrol --reset
sudo opcontrol --setup \
  --vmlinux=/lib/modules/$(uname -r)/build/vmlinux \
    --event=CPU_CLK_UNHALTED:180000:0:1:1 --separate=library
    sudo opcontrol --start
for A in $(seq 1 10); do
   $CMD
done
opcontrol --dump && \
opreport -l -p /lib/modules/$(uname -r)/kernel 2>/dev/null \
  | head -30

まず、デバッグ用のバイナリが正常に作成できているか簡単に確認します。まず、 apt-get update をループでまわしてみます。 libapt-pkg のシンボルレベルで確認できているので、デバッグシンボルが存在しているということがわかります。

sudo apt-get update
[中略]
CPU: Core Solo / Duo, speed 1833 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Unhalted clock cycles) with a unit mask of 0x00 (Unhalted core cycles) count 180000
samples  %        image name               app name                 symbol name
23823    46.3519  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
SHA1Transform(unsigned int*, unsigned char const*)
12732    24.7724  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
MD5Transform(unsigned int*, unsigned int const*)
4282      8.3314  processor.ko             processor                acpi_processor_idle
2584      5.0276  libc-2.3.6.so            apt-get                  (no symbols)
2012      3.9147  vmlinux                  vmlinux                  __copy_to_user_ll
503       0.9787  gpgv                     gpgv                     (no symbols)
222       0.4319  vmlinux                  vmlinux                  timer_interrupt
166       0.3230  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
MD5Summation::Add(unsigned char const*, unsigned long)
160       0.3113  vmlinux                  vmlinux                  page_fault
158       0.3074  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
SHA1Summation::Add(unsigned char const*, unsigned long)
140       0.2724  libstdc++.so.6.0.8       apt-get                  (no symbols)
134       0.2607  vmlinux                  vmlinux                  find_get_page
125       0.2432  ld-2.3.6.so              http                     do_lookup_x
123       0.2393  vmlinux                  vmlinux                  sysenter_past_esp
95        0.1848  libapt-pkg-libc6.3-6.so.3.11.0 apt-get                  .plt
94        0.1829  ld-2.3.6.so              gpgv                     do_lookup_x
89        0.1732  libc-2.3.6.so            http                     (no symbols)
89        0.1732  vmlinux                  vmlinux                  do_generic_mapping_read
88        0.1712  ld-2.3.6.so              file                     do_lookup_x
87        0.1693  vmlinux                  vmlinux                  memcpy
72        0.1401  ld-2.3.6.so              http                     strcmp
69        0.1343  vmlinux                  vmlinux                  _spin_lock
65        0.1265  vmlinux                  vmlinux                  vfs_read
64        0.1245  ld-2.3.6.so              gpgv                     _dl_elf_hash
62        0.1206  vmlinux                  vmlinux                  __handle_mm_fault
60        0.1167  ld-2.3.6.so              http                     _dl_elf_hash
58        0.1128  oprofiled                oprofiled                (no symbols)

sudo dpkg -i ../dselect_1.13.22_i386.deb
[中略]
CPU: Core Solo / Duo, speed 1833 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Unhalted clock cycles) with a unit mask of 0x00 (Unhalted core cycles) count 180000
samples  %        image name               app name                 symbol name
41009    32.6009  libc-2.3.6.so            dpkg                     (no symbols)
27485    21.8497  processor.ko             processor                acpi_processor_idle
14863    11.8156  dpkg                     dpkg                     parsedb
4845      3.8516  dpkg                     dpkg                     findnamenode
2691      2.1393  dpkg                     dpkg                     findpackage
1994      1.5852  dpkg                     dpkg                     f_dependency
1742      1.3848  vmlinux                  vmlinux                  get_page_from_freelist
1660      1.3196  dpkg-deb                 dpkg-deb                 inflate_fast
1552      1.2338  dpkg                     dpkg                     iterpkgnext
1520      1.2084  dpkg                     dpkg                     .plt
1500      1.1925  dpkg                     dpkg                     varbufaddbuf
1192      0.9476  dpkg                     dpkg                     filesdbinit
1080      0.8586  dpkg                     dpkg                     w_dependency
1001      0.7958  dpkg                     dpkg                     varbufdependency
988       0.7854  dpkg                     dpkg                     nfmalloc
884       0.7028  dpkg                     dpkg                     illegal_packagename
849       0.6749  vmlinux                  vmlinux                  page_fault
802       0.6376  vmlinux                  vmlinux                  __copy_from_user_ll_nocache_nozero
687       0.5461  dpkg                     dpkg                     ensure_packagefiles_available
633       0.5032  dpkg                     dpkg                     varbufaddc
568       0.4515  dpkg                     dpkg                     f_filecharf
516       0.4102  vmlinux                  vmlinux                  __copy_to_user_ll
473       0.3760  dpkg                     dpkg                     copy_dependency_links
458       0.3641  dpkg                     dpkg                     parseversion
427       0.3395  dpkg                     dpkg                     ensure_package_clientdata
406       0.3228  dpkg                     dpkg                     nfstrsave
384       0.3053  dpkg                     dpkg                     varbufrecord

パッケージをインストールして削除する、というループを回してみましょう。 apt-listbugsとapt-listchangesが含まれており、 ruby と python の処理負荷が高いことがわかります。また、 libc6 のなかで何か重たい処理をしているのがわかります。

sudo apt-get install -y dsh; sudo apt-get remove -y libdshconfig1
[中略]
Counted CPU_CLK_UNHALTED events (Unhalted clock cycles) with a unit mask of 0x00 (Unhalted core cycles) count 180000
samples  %        image name               app name                 symbol name
195383   24.3783  processor                processor                (no symbols)
114285   14.2595  libc-2.3.6.so            dpkg                     (no symbols)
67157     8.3793  libruby1.8.so.1.8.4      ruby1.8                  (no symbols)
48893     6.1005  libc-2.3.6.so            dpkg-query               (no symbols)
41537     5.1826  dpkg                     dpkg                     parsedb
30685     3.8286  perl                     perl                     (no symbols)
28353     3.5377  dpkg-query               dpkg-query               parsedb
26135     3.2609  python2.4                python2.4                (no symbols)
13951     1.7407  libc-2.3.6.so            ruby1.8                  (no symbols)
10023     1.2506  libc-2.3.6.so            apt-get                  (no symbols)
9138      1.1402  dpkg                     dpkg                     findnamenode
7914      0.9874  vmlinux                  vmlinux                  get_page_from_freelist
7656      0.9553  dpkg                     dpkg                     findpackage
5963      0.7440  vmlinux                  vmlinux                  read_hpet
5777      0.7208  libc-2.3.6.so            perl                     (no symbols)
5465      0.6819  dpkg                     dpkg                     f_dependency
5108      0.6373  dpkg-query               dpkg-query               findpackage
4525      0.5646  dpkg                     dpkg                     filesdbinit
4452      0.5555  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
pkgDepCache::CheckDep(pkgCache::DepIterator, int,
pkgCache::PkgIterator&)
4237      0.5287  vmlinux                  vmlinux                  page_fault
4182      0.5218  dpkg                     dpkg                     .plt
4101      0.5117  dpkg                     dpkg                     varbufaddbuf
3874      0.4834  dpkg-query               dpkg-query               f_dependency
3744      0.4671  dpkg                     dpkg                     iterpkgnext
3645      0.4548  libstdc++.so.6.0.8       apt-get                  (no symbols)
3287      0.4101  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
pkgProblemResolver::MakeScores()
3277      0.4089  vmlinux                  vmlinux                  delay_tsc

6.4 テスト環境の作成

テスト用の環境を作成します。今回は chroot 内部で大量の apt-get update, apt-get install と apt-get remove をループで実行してベンチマークをとってみましょう。

dpkg と apt を変更すると最悪システムが動作しなくなるため、テスト用に環境を準備することは大切です。

chroot 内部では、 chroot 外部のファイルにアクセスすることができません。そのため、 bind-mount を行い、外部のファイルを中に見せます。中で必要になるファイルとしては、 apt/dpkg のデバッグ版、 oprofile の修正版パッケージ（あれば）、そして実行中の Linux kernel に対応する vmlinux ファイルです。

$ sudo cowbuilder --login --bindmount $(pwd)
# apt-get install gnupg
# apt-get update
# apt-get install oprofile libc6-dbg
# dpkg -i (bind-moumt したところにおいた事前準備した apt/dpkg/oprofile)
# apt-get -y install gnome; apt-get -y remove libglib2.0-0
# unset LD_PRELOAD
# unset COWDANCER_ILISTFILE
# mount -t oprofilefs nodev /dev/oprofile >/dev/null

chroot で調べてみると、 perl が一番重たい処理をしているということがわかりました。こりゃチューニングしにくいですね。依存関係の解決などの処理に時間がかかっているかと仮説をたてていたのですが、特に露骨に目立って負荷の高い関数というのは見付けることはできませんでした。

apt-get install -y dsh; apt-get remove -y libdshconfig1
[中略]
CPU: Core Solo / Duo, speed 1833 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Unhalted clock cycles) with a unit mask of 0x00 (Unhalted core cycles) count 180000
samples  %        image name               app name                 symbol name
51258    32.2132  processor                processor                (no symbols)
7929      4.9830  libc-2.3.6.so            apt-get                  (no symbols)
7321      4.6009  libc-2.3.6.so            dpkg                     (no symbols)
5239      3.2925  vmlinux                  vmlinux                  read_hpet
4377      2.7507  libc-2.3.6.so            perl                     (no symbols)
4282      2.6910  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
pkgDepCache::CheckDep(pkgCache::DepIterator, int,
pkgCache::PkgIterator&)
2888      1.8150  libstdc++.so.6.0.8       apt-get                  (no symbols)
2570      1.6151  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
debVersioningSystem::CmpFragment(char const*, char const*, char const*,
char const*)
2548      1.6013  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
pkgProblemResolver::MakeScores()
2045      1.2852  dpkg                     dpkg                     parsedb
2019      1.2688  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
debVersioningSystem::DoCmpVersion(char const*, char const*, char
const*, char const*)
1722      1.0822  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
pkgDepCache::Update(OpProgress*)
1571      0.9873  dpkg                     dpkg                     findnamenode
1558      0.9791  perl                     perl                     Perl_sv_gets
1461      0.9182  perl                     perl                     Perl_yyparse
1408      0.8849  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
debVersioningSystem::CheckDep(char const*, int, char const*)
1222      0.7680  vmlinux                  vmlinux                  __copy_to_user_ll
1181      0.7422  vmlinux                  vmlinux                  get_page_from_freelist
1129      0.7095  perl                     perl                     S_hv_fetch_common
1055      0.6630  perl                     perl                     Perl_yylex
1054      0.6624  ldconfig                 ldconfig                 (no symbols)
1051      0.6605  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
OpProgress::CheckChange(float)
1050      0.6599  vmlinux                  vmlinux                  page_fault
911       0.5725  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
pkgPolicy::GetCandidateVer(pkgCache::PkgIterator)
816       0.5128  dpkg                     dpkg                     filesdbinit
815       0.5122  libapt-pkg-libc6.3-6.so.3.11.0 apt-get
pkgDepCache::DependencyState(pkgCache::DepIterator&)
793       0.4984  libapt-pkg-libc6.3-6.so.3.11.0 apt-get                  .plt

まず、 opreport の結果を確認します。カーネル空間で 16%, apt-get で 10%, perl で 7% であることがわかります。ここで重要なのは、この時点で dpkg をチューニングしても大して結果に反映しなさそうだということが明確になったことです。

# opreport
CPU: Core Solo / Duo, speed 1833 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Unhalted clock cycles) with a unit mask of 0x00 (Unhalted core cycles) count 180000
CPU_CLK_UNHALT...|
  samples|      %|
------------------
   182440 51.3356 processor
    59664 16.7885 vmlinux
    38517 10.8380 apt-get
        CPU_CLK_UNHALT...|
          samples|      %|
        ------------------
            25578 66.4070 libapt-pkg-libc6.3-6.so.3.11.0
             7929 20.5857 libc-2.3.6.so
             2888  7.4980 libstdc++.so.6.0.8
             1701  4.4162 apt-get
              381  0.9892 ld-2.3.6.so
               12  0.0312 anon (tgid:31689 range:0xb7f47000-0xb7f48000)
               11  0.0286 anon (tgid:31917 range:0xb7f49000-0xb7f4a000)
                9  0.0234 anon (tgid:31841 range:0xb7fcb000-0xb7fcc000)
                8  0.0208 anon (tgid:31765 range:0xb7f9d000-0xb7f9e000)
    27091  7.6230 perl
        CPU_CLK_UNHALT...|
          samples|      %|
        ------------------
            22216 82.0051 perl
             4377 16.1567 libc-2.3.6.so
              273  1.0077 libpthread-2.3.6.so
              214  0.7899 ld-2.3.6.so
                3  0.0111 libnss_compat-2.3.6.so
                2  0.0074 libdl-2.3.6.so
                2  0.0074 Fcntl.so
                1  0.0037 libnss_files-2.3.6.so
                1  0.0037 libnss_nis-2.3.6.so
                1  0.0037 IO.so
                1  0.0037 gettext.so
    23916  6.7296 opreport
        CPU_CLK_UNHALT...|
          samples|      %|
        ------------------
            14091 58.9187 opreport
             5445 22.7672 libc-2.3.6.so
             4119 17.2228 libstdc++.so.6.0.8
              257  1.0746 ld-2.3.6.so
                3  0.0125 libgcc_s.so.1
                1  0.0042 libpopt.so.0.0.0
    16010  4.5049 dpkg
        CPU_CLK_UNHALT...|
          samples|      %|
        ------------------
             8611 53.7851 dpkg
             7321 45.7277 libc-2.3.6.so
               74  0.4622 ld-2.3.6.so

この後試行錯誤して apt-get update の処理についてはチューニングできそうだ、ということがわかったのですが、それはまた別の機会に。

6.5 まとめ

この文章では Debian で oprofile を利用してボトルネックを検出する作業をするための手順についてまとめました。

6.6 参考文献

____________________________________________________________________________________________

Debian 勉強会資料

2006 年9 月16 日初版第1 刷発行
東京エリア Debian 勉強会（編集・印刷・発行）
__________________________