FPGA開発日記

FPGAというより、コンピュータアーキテクチャかもね! カテゴリ別記事インデックス https://sites.google.com/site/fpgadevelopindex/

ISSのプロファイリング(xv6のブートにかかる時間が遅い)

現状のISSだが、やはりxv6をフルにブートしようとすると遅い。デバッグモードを有効にするとさらに遅い。

CPUPROFILE=/tmp/profile.out  ~/swimmer_riscv/build_mips/swimmer_mips --imgfile ~/xv6-mips/xv6.img --max 1000000
Swimmer-RISCV
  Version 20150919 Revision 14ab13d
  developed by Masayuki Kimura <masayuki.kimura.1986@gmail.com>
<Info: NewMemory Region 1fc00000 is defined.>
PROFILE: interrupts/evictions/bytes = 182/70/19904
vagrant@vagrant-ubuntu-vivid-64:~/xv6-mips$ pprof swimmer.prof ~/swimmer_riscv/build_mips/swimmer_mips
Using local file swimmer.prof.
Using local file /home/vagrant/swimmer_riscv/build_mips/swimmer_mips.
/home/vagrant/swimmer_riscv/build_mips/swimmer_mips: header size >= 2**16
vagrant@vagrant-ubuntu-vivid-64:~/xv6-mips$ pprof ~/swimmer_riscv/build_mips/swimmer_mips swimmer.prof
Using local file /home/vagrant/swimmer_riscv/build_mips/swimmer_mips.
Using local file swimmer.prof.
substr outside of string at /usr/local/bin/pprof line 3695.
Use of uninitialized value in string eq at /usr/local/bin/pprof line 3695.
substr outside of string at /usr/local/bin/pprof line 3697.
Use of uninitialized value in string eq at /usr/local/bin/pprof line 3697.
swimmer.prof: header size >= 2**16
vagrant@vagrant-ubuntu-vivid-64:~/xv6-mips$ pprof ~/swimmer_riscv/build_mips/swimmer_mips /tmp/profile.out
Using local file /home/vagrant/swimmer_riscv/build_mips/swimmer_mips.
Using local file /tmp/profile.out.
Welcome to pprof!  For help, type 'help'.
(pprof) top
Total: 182 samples
      32  17.6%  17.6%       32  17.6% std::less::operator
      28  15.4%  33.0%      100  54.9% std::_Rb_tree::_M_lower_bound
      18   9.9%  42.9%       23  12.6% std::_Rb_tree_node::_M_valptr
      13   7.1%  50.0%       42  23.1% std::_Rb_tree::_S_key
      13   7.1%  57.1%       30  16.5% std::_Rb_tree::_S_value
       9   4.9%  62.1%       12   6.6% std::_Rb_tree::end
       9   4.9%  67.0%      135  74.2% std::_Rb_tree::find
       7   3.8%  70.9%        7   3.8% std::_Select1st::operator
       7   3.8%  74.7%        7   3.8% std::__addressof
       5   2.7%  77.5%        5   2.7% std::_Rb_tree_iterator::_Rb_tree_iterator

うーん、やはりメモリフェッチとかの動作がネックになっているかな。このあたりは、データ構造をよほど変えない限りこれ以上改善は望めないか。

フルパワーでデバッグモードを活用した場合。

 CPUPROFILE=/tmp/profile.out ~/swimmer_riscv/build_mips/swimmer_mips --imgfile ~/xv6-mips/xv6.img --out debug.log --debug_func --debug_gvar --max 500000 --debug --binfile kernel --only_info_load
PROFILE: interrupts/evictions/bytes = 637/293/37760

pprof ~/swimmer_riscv/build_mips/swimmer_mips /tmp/profile.out
Using local file /home/vagrant/swimmer_riscv/build_mips/swimmer_mips.
Using local file /tmp/profile.out.
Welcome to pprof!  For help, type 'help'.
(pprof) top
Total: 637 samples
      62   9.7%   9.7%       62   9.7% _IO_vfprintf_internal
      61   9.6%  19.3%       61   9.6% __gnu_cxx::__normal_iterator::__normal_iterator
      59   9.3%  28.6%       93  14.6% std::vector::end
      57   8.9%  37.5%       71  11.1% __gnu_cxx::operator!=
      53   8.3%  45.8%      224  35.2% EnvBase::FindSymbol
      47   7.4%  53.2%       65  10.2% __gnu_cxx::__normal_iterator::operator++
      28   4.4%  57.6%       28   4.4% __gnu_cxx::__normal_iterator::base
      23   3.6%  61.2%       85  13.3% EnvBase::FindGVariable
      13   2.0%  63.3%       14   2.2% EnvBase::PrintInst
      12   1.9%  65.1%       12   1.9% __gnu_cxx::__normal_iterator::operator*

あらまー、やはり、シンボルの探索など、デバッグ情報の探索にかなり時間がかかっているのね。