hash table の lookup の実行時間は O(1) である。が、本当にそうなのか測ってみよう。
% ./miniruby -v
ruby 2.4.0dev (2016-10-12 trunk 56401) [x86_64-linux]
% ./miniruby -e '
def fmt(n) "%10d" % n end
puts "n,t[s]"
n = 1
h = {}
while n < 1e8
h[fmt(h.size)] = true while h.size < n
k = fmt(rand(n))
GC.start
GC.disable
h[k]
t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
h[k]
t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
GC.enable
t = t2-t1
puts "#{n},#{t}"
STDOUT.flush
n = (n*1.1).to_i+1
end' > hash-lookup-time.csv
グラフにしてみる。
hash-lookup-time.R:
library(ggplot2)
d <- read.csv("2016-10/hash-lookup-time.csv")
p <- ggplot(d, aes(n, t.s.)) +
geom_point() +
scale_x_log10() +
scale_y_continuous("t[s]", limits=c(0,2e-6))
print(p)
まぁ定数時間には見えない。n (Hash の要素数) が小さいと遅いし、n が大きくてもあるところから遅くなる。
なにが起きているのかな。
大きい方については、キャッシュに入らないからじゃないかな、と感じるのだが、確認したわけではない。
キャッシュに入らないから、というのを確認するにはどうしたらいいかといえば、キャッシュミスを数えればいいわけである。
しかし、どうしたら数えられるか知らなかったので、調べて見たところ、 PAPI というライブラリが使えそうである。Debian package にもなっている。
Ruby binding を作った人もいるようだ: PAPI gem
これらは以下のように install できる。
sudo aptitude install papi-tools gem install PAPI
gem のドキュメントはほとんどないが、適当に試したところ、以下のようにすれば動くようだ。
% ./ruby -rPAPI -e ' evset = PAPI::EventSet.new evset.add_named(%w[PAPI_TOT_INS PAPI_L1_DCM]) evset.start 3 ** 100 p evset.stop evset.start 3 ** 1000 p evset.stop ' [8689, 370] [29572, 676]
PAPI::EventSet オブジェクトを作って、add_named メソッドで数えたいイベントを指定して、start メソッドで数え始めて、stop メソッドで終了して結果を返す。
上の例だと、3 ** 100 を実行するのに、PAPI_TOT_INS が 8689回、PAPI_L1_DCM が 370回起きている。つまり、8689回インストラクションが実行され、L1 data cache の miss が 370回起きている。
3 ** 1000 を実行するのには、PAPI_TOT_INS が 29572回、PAPI_L1_DCM が 676回である。
数えられるイベントのリストは papi_avail コマンドや papi_native_avail コマンドで表示できる。（アーキテクチャによって異なる）
papi_avail では上記の PAPI_TOT_INS と PAPI_L1_DCM を含め PAPI が定義した（比較的）ポータブルなイベントが出てくる。
papi_native_avail はいろいろと生のイベントが出てくる。ix86arch::LLC_MISSES とか、perf::INSTRUCTIONS とか。perf:: というのは、名前からするともしかして perf のメカニズムを使っているのかもしれない。(PAPI はイベントを数えるいろいろなものを統一的に扱うフレームワークなので、perf を扱えてもおかしくない。)
大きい Hash のが遅くなるのを、PAPI を使っていろいろ試したところ、どうも、TLB miss が原因のように思われる。
% ./ruby -rPAPI -e '
events = %w[PAPI_TOT_INS PAPI_TOT_CYC PAPI_RES_STL PAPI_TLB_DM]
evset = PAPI::EventSet.new
evset.add_named(events)
def fmt(n) "%10d" % n end
puts "n,t[s],#{events.join(",")}"
n = 1
h = {}
while n < 1e7
h[fmt(h.size)] = true while h.size < n
k = fmt(rand(n))
GC.start
GC.disable
h[k]
t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
evset.start
h[k]
evrec = evset.stop
t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
GC.enable
t = t2-t1
puts [n,t,*evrec].join(",")
STDOUT.flush
n = (n*1.1).to_i+1
end' > hash-lookup-tlb.csv
まず、PAPI_TOT_CYC (Total cycles) をグラフにすると、だいたい実行時間と似た形になることがわかる。(1e8 まで調べるのは時間がかかるので、1e7 までにした)
次に、PAPI_TOT_INS (Instructions completed) をグラフにすると、これは一定なことが確認できる。つまり、遅くなっていても、実行した命令の数は変わっていないのだ。
実行命令数が変わっていないのに実行時間が増えているということは、CPUが動いていない時間が増えているということである。そこで、PAPI_RES_STL (Cycles stalled on any resource) をグラフにすると、実際にストールしているサイクル数が増えていることがわかる。
では stall が増える原因はなにかというと、おそらく TLB miss と思われる。これは PAPI_TLB_DM (Data translation lookaside buffer misses) で数えられる。これは実行時間や PAPI_TOT_CYC とよく似た形になっている。
なお、cache miss も同じように測定できる。
% ./ruby -rPAPI -e '
events = %w[PAPI_L1_DCM PAPI_L2_DCM PAPI_L3_TCM]
evset = PAPI::EventSet.new
evset.add_named(events)
def fmt(n) "%10d" % n end
puts "n,t[s],#{events.join(",")}"
n = 1
h = {}
while n < 1e7
h[fmt(h.size)] = true while h.size < n
k = fmt(rand(n))
GC.start
GC.disable
h[k]
t1 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
evset.start
h[k]
evrec = evset.stop
t2 = Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID)
GC.enable
t = t2-t1
puts [n,t,*evrec].join(",")
STDOUT.flush
n = (n*1.1).to_i+1
end' > hash-lookup-cache.csv
PAPI_L1_DCM (Level 1 data cache misses) は以下のようになる。
PAPI_L2_DCM (Level 2 data cache misses)
PAPI_L3_TCM (Level 3 cache misses)
どのレベルのキャッシュも大きな Hash で miss が増えており、とくに L3 は TLB miss と傾向が似ているが、TLB miss が起きるときには cache miss も起こると思うのでそんなものだろう。たぶん。
