おまぬけ活動日誌

最近のツッコまれどころ

この日誌から Google してもらう


2005年06月06日(Mon) ビール飲み過ぎで起動が遅いです [同日]

なんちて

Pythonの起動は遅い(かもしれない)

enbug diaryより。へぇ。ちょっと手元でも実験してみました。

$ time perl -e ''
real    0m0.003s
user    0m0.000s
sys     0m0.003s
$ time ruby -e ''
real    0m0.005s
user    0m0.003s
sys     0m0.002s
$ time python -c ''
real    0m0.016s
user    0m0.011s
sys     0m0.005s

ほんとだ。perl, v5.8.5、ruby 1.8.3、Python 2.3.4です。

straceするとシステムコールの回数がわかるのかな。

$ strace perl -e '' 2>&1 | wc -l
141
$ strace ruby -e '' 2>&1 | wc -l
121
$ strace python -c '' 2>&1 | wc -l
718

ふむふむ。じゃあ起動して終了するまでにreadしたバイト数。

$ strace -e trace=read perl -e '' 2>&1 | awk '{s+=$NF}END{print(s)}'
4132
$ strace -e trace=read ruby -e '' 2>&1 | awk '{s+=$NF}END{print(s)}'
3104
$ strace -e trace=read python -c '' 2>&1 | awk '{s+=$NF}END{print(s)}'
142929

1.5桁ほどちがいますね。バイトコードを実行するようになってるあたりが違うのでしょうか?

$ strace -e trace=open python -c '' 2>&1 | grep -v ENOENT | lv

なんだか日本語エンコーディング関連のようなファイル名が沢山見えました。ならば、

$ LANG=C time python -c ''
0.00user 0.00system 0:00.02elapsed 65%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+606minor)pagefaults 0swaps

速くなった?

$ LANG=C time perl -e ''
0.00user 0.00system 0:00.00elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+309minor)pagefaults 0swaps
$ LANG=C time ruby -e ''
0.00user 0.00system 0:00.00elapsed 60%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+358minor)pagefaults 0swaps

うんにゃ。しかしロケールでtimeの出力が違うのにびっくり。(追記:普段はja_JP.EUC-JPになってます。、下にもっと追記)

readしたバイト数をファイル名に関連づけられるともう少しいろいろわかるのでしょうけど、また今度にしまーす。

(もっと追記)timeの出力が変化するのはロケールのせいじゃなかったです。LANG=ja_JP.EUC-JP time …でもLANG=Cを付けた時と同じ出力が得られました。コマンドラインの最初にtimeを書くとbashの予約語のtimeとして解釈されて、LANG=…の後にtimeを書くとコマンド名として解釈されて/usr/bin/timeが実行される、というのが真相のようです。失礼しました。

straceからファイル名と読んだデータの大きさを得る

そういうわけで簡単なスクリプトを作ってみました。ファイル名にダブルクォーテーションが含まれてたりするとどうなるか知らない。

#!/usr/bin/ruby
# Copyright 2005 by zunda at freeshell.org, distributed under GPL

fds = Hash.new
bytes = Hash.new( 0 )
ARGF.each do |line|
  if /^open\("([^"]+)",[^)]+\)\s*=\s(\d+)/ =~ line then
    path = $1
    fd = $2.to_i
    fds[fd] = path if fd >= 0
  elsif /^read\((\d+),[^)]+\)\s*=\s(\d+)/ =~ line then
    fd = $1.to_i
    byte = $2.to_i
    bytes[fds[fd]] += byte
  end
end
bytes.to_a.sort_by{|x| x[1]}.reverse.each do |x|
  puts "#{'%5d' % x[1]} bytes from #{x[0]}"
end

ここではstrace.rbというファイル名にしてあります。結果はというと、

$ LANG=C strace perl -e '' 2>&1 | ruby strace.rb  | head -5
  512 bytes from /lib/tls/libpthread.so.0
  512 bytes from /lib/libutil.so.1
  512 bytes from /lib/tls/libm.so.6
  512 bytes from /lib/tls/libc.so.6
  512 bytes from /usr/lib/perl5/5.8.5/i686-linux-thread-multi/CORE/libperl.so
$ LANG=C strace ruby -e '' 2>&1 | ruby strace.rb  | head -5
  512 bytes from /lib/tls/libpthread.so.0
  512 bytes from /lib/tls/libm.so.6
  512 bytes from /lib/tls/libc.so.6
  512 bytes from /usr/lib/libruby.so.1.8
  512 bytes from /lib/libcrypt.so.1
$ LANG=C strace python -c '' 2>&1 | ruby strace.rb  | head -5
28530 bytes from /usr/lib/python2.3/codecs.pyc
27272 bytes from /usr/lib/python2.3/os.pyc
14433 bytes from /usr/lib/python2.3/posixpath.pyc
11831 bytes from /usr/lib/python2.3/UserDict.pyc
11787 bytes from /usr/lib/python2.3/site.pyc

へぇ。バイトコードになったPythonスクリプトをたくさん読んでるのかな?

perlでもrubyでも、そしてpythonでも、共有オブジェクトは512バイトずつ読まれてるのですが、ELFでは最初の512バイトにシンボルテーブルが書かれてたりするのでしょうか。いつか調べるー。いつー。

仕事すすみません。

す、すみません…。

select(2)ってデータがなくても返るのかな。man select_tutをよおおく読もう。

うりゃ。man -t select_tut | ps2pdf - - >| select_tut.pdf


作り手とその取り巻きだけが楽しんでる間は本物じゃない。その中身が理解できない人々の生活を変えてこそ本物だ


zunda <zunda at freeshell.org>