読者です 読者をやめる 読者になる 読者になる

細かすぎて伝わらない「形態素解析器 kagome のメモリ周りの話」を pprof で調べる

はじめに

きっかけは形態素解析kagome にいただいた Issue です.

github.com

端的に言うと,

入力文字列に対して,前から1文字ずつずらしながら辞書引きを繰り返して,可能性のある形態素をすべて洗い出すんですが,その際に辞書を CommonPrefixSearch するメソッドでメモリをアロケートしすぎじゃないか?

というお問い合わせです.

たしかに 800MB くらいアロケートしてるように見えます.ひえー

というわけで調査.

道具は揃っている

golang では pprof が使えます.これで速度パフォーマンスとメモリ使用状況が確認できます.

使い方は,KLabGames Tech さんがまとめてくださっているすばらしい記事がありますので,こちらを参照ください.

あと,いくつかの OS バージョンではうまく動かないときがあるので,こっちの Issue も目を通しておくと吉です.

状況の確認

Issue でもらっている状況はこれ.

23:14 $ go test -v ./tokenizer -run=^$ -bench=. -benchmem -benchtime=5s -memprofile=master_mem.prof
PASS
BenchmarkAnalyzeNormal-4       20000        289632 ns/op       19177 B/op        581 allocs/op
BenchmarkAnalyzeSearch-4       20000        390959 ns/op       19177 B/op        581 allocs/op
BenchmarkAnalyzeExtended-4     20000        390214 ns/op       19174 B/op        581 allocs/op
ok      github.com/ikawaha/kagome/tokenizer 32.808s
23:16 $ go tool pprof --alloc_space tokenizer.test master_mem.prof
Entering interactive mode (type "help" for commands)
(pprof) top
1679.93MB of 1689.81MB total (99.42%)
Dropped 23 nodes (cum <= 8.45MB)
Showing top 10 nodes out of 39 (cum >= 11.28MB)
      flat  flat%   sum%        cum   cum%
  810.04MB 47.94% 47.94%  1038.54MB 61.46%  github.com/ikawaha/kagome/internal/dic.IndexTable.CommonPrefixSearch
  410.10MB 24.27% 72.21%  1449.64MB 85.79%  github.com/ikawaha/kagome/tokenizer.Tokenizer.Analyze
  228.50MB 13.52% 85.73%   228.50MB 13.52%  github.com/ikawaha/kagome/internal/da.DoubleArray.CommonPrefixSearch
  114.90MB  6.80% 92.53%   114.90MB  6.80%  bytes.makeSlice
   50.49MB  2.99% 95.52%    50.49MB  2.99%  strings.genSplit
      41MB  2.43% 97.94%       41MB  2.43%  encoding/binary.Read
   10.34MB  0.61% 98.55%    32.84MB  1.94%  github.com/ikawaha/kagome/internal/da.Read
    8.98MB  0.53% 99.09%    59.47MB  3.52%  github.com/ikawaha/kagome/internal/dic.NewContents
    3.31MB   0.2% 99.28%    12.81MB  0.76%  github.com/ikawaha/kagome/internal/dic.LoadConnectionTable
    2.28MB  0.13% 99.42%    11.28MB  0.67%  github.com/ikawaha/kagome/internal/dic.LoadMorphSlice

alloc_space を調べてみると,確かに CommonPrefixSearch() がトップにいます.しかも 800MB くらい alloc してます.

実際のコードのどこで alloc が頻繁に行われてるのかを pprof の list コマンドで知ることが出来ます.

(pprof) list CommonPrefixSearch
Total: 1.65GB
ROUTINE ======================== github.com/ikawaha/kagome/internal/da.DoubleArray.CommonPrefixSearch in /Users/ikawaha/lib/go/src/github.com/ikawaha/kagome/internal/da/da.go
  228.50MB   228.50MB (flat, cum) 13.52% of Total
         .          .    101:       if q >= bufLen || int(d[q].Check) != p {
         .          .    102:           break
         .          .    103:       }
         .          .    104:       ahead := int(d[q].Base) + int(terminator)
         .          .    105:       if ahead < bufLen && int(d[ahead].Check) == q && int(d[ahead].Base) <= 0 {
     110MB      110MB    106:           ids = append(ids, int(-d[ahead].Base))
  118.50MB   118.50MB    107:           lens = append(lens, i+1)
         .          .    108:       }
         .          .    109:   }
         .          .    110:   return
         .          .    111:}
         .          .    112:

なるほど,idslens というリストに要素を追加していく部分でメモリがたくさん確保されてるみたいですね・・・. Issue でも指摘されてるように,idslens は初期容量が 0 なので,追加するたびにメモリが確保されてるんかな・・・

だがしかし

しかし,よく考えると alloc_space は確保されたメモリの総容量で,確保されてGCで回収されてるものも含めての量なのです. ためしに,どのくらいの回数これが確保されてるのか調べてみます.alloc_objects を指定すると調べられます.

23:24 $ go tool pprof --alloc_objects tokenizer.test master_mem.prof
(pprof) list CommonPrefixSearch
Total: 38827588
ROUTINE ======================== github.com/ikawaha/kagome/internal/da.DoubleArray.CommonPrefixSearch in /Users/ikawaha/lib/go/src/github.com/ikawaha/kagome/internal/da/da.go
  13615329   13615329 (flat, cum) 35.07% of Total
         .          .    101:       if q >= bufLen || int(d[q].Check) != p {
         .          .    102:           break
         .          .    103:       }
         .          .    104:       ahead := int(d[q].Base) + int(terminator)
         .          .    105:       if ahead < bufLen && int(d[ahead].Check) == q && int(d[ahead].Base) <= 0 {
   6455404    6455404    106:           ids = append(ids, int(-d[ahead].Base))
   7159925    7159925    107:           lens = append(lens, i+1)
         .          .    108:       }
         .          .    109:   }
         .          .    110:   return
         .          .    111:}
         .          .    112:

ids に注目すると 650万回くらいオブジェクトが生成されてます.ざっくり計算すると,110MB ÷ 650万回 ≒ 18 byte/オブジェクト くらいの量です.

実際メモリはどれくらい使われてるか?

実際の GC で回収されなかったメモリは inuse_space で調べられます.

23:20 $ go tool pprof --inuse_space tokenizer.test master_mem.prof
Entering interactive mode (type "help" for commands)
(pprof) top
104741.70kB of 104741.70kB total (  100%)
Dropped 26 nodes (cum <= 523.71kB)
Showing top 10 nodes out of 36 (cum >= 896.99kB)
      flat  flat%   sum%        cum   cum%
45574.26kB 43.51% 43.51% 45574.26kB 43.51%  strings.genSplit
   32768kB 31.28% 74.80%    32768kB 31.28%  bytes.makeSlice
   10592kB 10.11% 84.91%    10592kB 10.11%  github.com/ikawaha/kagome/internal/da.Read
    9192kB  8.78% 93.68% 54766.26kB 52.29%  github.com/ikawaha/kagome/internal/dic.NewContents
 3388.57kB  3.24% 96.92%  3388.57kB  3.24%  github.com/ikawaha/kagome/internal/dic.LoadConnectionTable
 2329.88kB  2.22% 99.14%  2329.88kB  2.22%  github.com/ikawaha/kagome/internal/dic.LoadMorphSlice
  896.99kB  0.86%   100%   896.99kB  0.86%  reflect.mapassign
         0     0%   100%    32768kB 31.28%  bytes.(*Buffer).ReadFrom
         0     0%   100%   896.99kB  0.86%  encoding/gob.(*Decoder).Decode
         0     0%   100%   896.99kB  0.86%  encoding/gob.(*Decoder).DecodeValue

だいたい 100MBちょっとでしょうか.辞書がだいたい 50MB くらい使用するのが分かってるので,実行に必要なメモリは 50MB くらいだと思われます. そんなに多くはないんじゃないかな・・・と思います.また,CommonPrefixSearch() 由来のメモリはここには現れてないみたいです.リークはしてないんじゃないかな・・・.

速度パフォーマンスを調べてみる

cpuのプロファイルをとってみます.

23:24 $ go test -v ./tokenizer -run=^$ -bench=. -benchtime=5s -memprofile=master_cpu.prof
PASS
BenchmarkAnalyzeNormal-4       20000        287270 ns/op
BenchmarkAnalyzeSearch-4       20000        336573 ns/op
BenchmarkAnalyzeExtended-4     20000        349246 ns/op
ok      github.com/ikawaha/kagome/tokenizer 30.424s
23:26 $ go tool pprof tokenizer.test master_cpu.prof
Entering interactive mode (type "help" for commands)
(pprof) top
111.29MB of 111.29MB total (  100%)
Dropped 36 nodes (cum <= 0.56MB)
Showing top 10 nodes out of 36 (cum >= 1.88MB)
      flat  flat%   sum%        cum   cum%
   52.51MB 47.18% 47.18%    52.51MB 47.18%  strings.genSplit
      32MB 28.75% 75.94%       32MB 28.75%  bytes.makeSlice
   10.34MB  9.29% 85.23%    10.34MB  9.29%  github.com/ikawaha/kagome/internal/da.Read
    8.98MB  8.07% 93.30%    61.48MB 55.25%  github.com/ikawaha/kagome/internal/dic.NewContents
    3.31MB  2.97% 96.27%     3.31MB  2.97%  github.com/ikawaha/kagome/internal/dic.LoadConnectionTable
    2.28MB  2.04% 98.31%     2.28MB  2.04%  github.com/ikawaha/kagome/internal/dic.LoadMorphSlice
    1.88MB  1.69%   100%     1.88MB  1.69%  reflect.mapassign
         0     0%   100%       32MB 28.75%  bytes.(*Buffer).ReadFrom
         0     0%   100%     1.88MB  1.69%  encoding/gob.(*Decoder).Decode
         0     0%   100%     1.88MB  1.69%  encoding/gob.(*Decoder).DecodeValue

ここにも CommonPrefixSeach() は出てきません.パフォーマンス的にみても CommonPrefixSearch() のメモリ確保が問題になっているとは考えにくそうです.

とはいえ確かに効率悪い

CommonPrefixSearch() のコードは下記のようなものなんですが,返値の変数は関数定義のところで宣言されていて,その容量は 0 です. なので,メモリを確保するときは少し多めに確保しておくように修正します.

修正後

func (d DoubleArray) CommonPrefixSearch(input string) (ids, lens []int) {
        const initCapacity = 8
        var (
                p, q  int
                alloc bool
        )
        bufLen := len(d)
        for i, size := 0, len(input); i < size; i++ {
                p = q
                q = int(d[p].Base) + int(input[i])
                if q >= bufLen || int(d[q].Check) != p {
                        break
                }
                ahead := int(d[q].Base) + int(terminator)
                if ahead < bufLen && int(d[ahead].Check) == q && int(d[ahead].Base) <= 0 {
                        if !alloc {
                                ids = make([]int, 0, initCapacity)
                                lens = make([]int, 0, initCapacity)
                                alloc = true
                        }
                        ids = append(ids, int(-d[ahead].Base))
                        lens = append(lens, i+1)
                }
        }
        return
}

これでプロファイルをとってみます.

まず実際の使用量.まぁ,それほど変わりません.

23:35 $ go tool pprof --inuse_space tokenizer.test fixalloc_mem.prof
Entering interactive mode (type "help" for commands)
(pprof) top
114.29MB of 114.29MB total (  100%)
Dropped 24 nodes (cum <= 0.57MB)
Showing top 10 nodes out of 36 (cum >= 1.38MB)
      flat  flat%   sum%        cum   cum%
   56.01MB 49.01% 49.01%    56.01MB 49.01%  strings.genSplit
      32MB 28.00% 77.00%       32MB 28.00%  bytes.makeSlice
   10.34MB  9.05% 86.06%    10.34MB  9.05%  github.com/ikawaha/kagome/internal/da.Read
    8.98MB  7.85% 93.91%    64.98MB 56.86%  github.com/ikawaha/kagome/internal/dic.NewContents
    3.31MB  2.90% 96.81%     3.31MB  2.90%  github.com/ikawaha/kagome/internal/dic.LoadConnectionTable
    2.28MB  1.99% 98.80%     2.28MB  1.99%  github.com/ikawaha/kagome/internal/dic.LoadMorphSlice
    1.38MB  1.20%   100%     1.38MB  1.20%  reflect.mapassign
         0     0%   100%       32MB 28.00%  bytes.(*Buffer).ReadFrom
         0     0%   100%     1.38MB  1.20%  encoding/gob.(*Decoder).Decode
         0     0%   100%     1.38MB  1.20%  encoding/gob.(*Decoder).DecodeValue

で,alloc_space をみてみると・・・.さっきより増えてるー.

23:36 $ go tool pprof --alloc_space tokenizer.test fixalloc_mem.prof
Entering interactive mode (type "help" for commands)
(pprof) top
2424.25MB of 2434.64MB total (99.57%)
Dropped 23 nodes (cum <= 12.17MB)
Showing top 10 nodes out of 37 (cum >= 13.28MB)
      flat  flat%   sum%        cum   cum%
  991.06MB 40.71% 40.71%   991.06MB 40.71%  github.com/ikawaha/kagome/internal/da.DoubleArray.CommonPrefixSearch
  791.54MB 32.51% 73.22%  1782.60MB 73.22%  github.com/ikawaha/kagome/internal/dic.IndexTable.CommonPrefixSearch
  399.54MB 16.41% 89.63%  2183.15MB 89.67%  github.com/ikawaha/kagome/tokenizer.Tokenizer.Analyze
  113.22MB  4.65% 94.28%   113.22MB  4.65%  bytes.makeSlice
   61.99MB  2.55% 96.83%    61.99MB  2.55%  strings.genSplit
      42MB  1.73% 98.55%       42MB  1.73%  encoding/binary.Read
   10.34MB  0.42% 98.98%    29.84MB  1.23%  github.com/ikawaha/kagome/internal/da.Read
    8.98MB  0.37% 99.34%    70.97MB  2.91%  github.com/ikawaha/kagome/internal/dic.NewContents
    3.31MB  0.14% 99.48%    14.81MB  0.61%  github.com/ikawaha/kagome/internal/dic.LoadConnectionTable
    2.28MB 0.093% 99.57%    13.28MB  0.55%  github.com/ikawaha/kagome/internal/dic.LoadMorphSlice

まぁ,そうですよね.多めに確保するんだからこの量は増えますよね.

細かく見てみると・・・

(pprof) list CommonPrefixSearch
Total: 2.38GB
ROUTINE ======================== github.com/ikawaha/kagome/internal/da.DoubleArray.CommonPrefixSearch in /Users/ikawaha/lib/go/src/github.com/ikawaha/kagome/internal/da/da.go
  991.06MB   991.06MB (flat, cum) 40.71% of Total
         .          .    106:           break
         .          .    107:       }
         .          .    108:       ahead := int(d[q].Base) + int(terminator)
         .          .    109:       if ahead < bufLen && int(d[ahead].Check) == q && int(d[ahead].Base) <= 0 {
         .          .    110:           if !alloc {
  503.53MB   503.53MB    111:               ids = make([]int, 0, initCapacity)
  487.53MB   487.53MB    112:               lens = make([]int, 0, initCapacity)
         .          .    113:               alloc = true
         .          .    114:           }
         .          .    115:           ids = append(ids, int(-d[ahead].Base))
         .          .    116:           lens = append(lens, i+1)
         .          .    117:       }

メモリを確保したら append ではメモリ確保が起こってないようですね.

最後にパフォーマンスは?

あんまかわらんかな・・・・.

00:28 $ go test -v ./tokenizer -run=^$ -bench=. -benchtime=5s -memprofile=fixalloc_cpu.prof
PASS
BenchmarkAnalyzeNormal-4       30000        238184 ns/op
BenchmarkAnalyzeSearch-4       20000        316875 ns/op
BenchmarkAnalyzeExtended-4     20000        322532 ns/op
ok      github.com/ikawaha/kagome/tokenizer 34.504s
23:34 $ go tool pprof tokenizer.test fixalloc_cpu.prof
Entering interactive mode (type "help" for commands)
(pprof) top
113446.89kB of 113446.89kB total (  100%)
Dropped 25 nodes (cum <= 567.23kB)
Showing top 10 nodes out of 36 (cum >= 896.99kB)
      flat  flat%   sum%        cum   cum%
54279.45kB 47.85% 47.85% 54279.45kB 47.85%  strings.genSplit
   32768kB 28.88% 76.73%    32768kB 28.88%  bytes.makeSlice
   10592kB  9.34% 86.07%    10592kB  9.34%  github.com/ikawaha/kagome/internal/da.Read
    9192kB  8.10% 94.17% 63471.45kB 55.95%  github.com/ikawaha/kagome/internal/dic.NewContents
 3388.57kB  2.99% 97.16%  3388.57kB  2.99%  github.com/ikawaha/kagome/internal/dic.LoadConnectionTable
 2329.88kB  2.05% 99.21%  2329.88kB  2.05%  github.com/ikawaha/kagome/internal/dic.LoadMorphSlice
  896.99kB  0.79%   100%   896.99kB  0.79%  reflect.mapassign
         0     0%   100%    32768kB 28.88%  bytes.(*Buffer).ReadFrom
         0     0%   100%   896.99kB  0.79%  encoding/gob.(*Decoder).Decode
         0     0%   100%   896.99kB  0.79%  encoding/gob.(*Decoder).DecodeValue

こんな理解であってるのだろうか?長期運用の実績はないので、何か様子がおかしいとかあったら教えてほしいです。突っ込みお待ちしています.