Reading and Writing of FileStoredMap

以前、拙作のFileStoredMap(以下、FSM)がBerkeleyDB(以下、BDB)とどのくらい速度差があるか確認しました。その結果を以下のページに載せています。

FSMはメモリ上にデータを貯めておくバッファを持っていないので、少なくともreadが圧倒的に遅いことは予想できます。writeに関してもputの契機で都度RandomAccessFileに書き込んでいるので、差が出るとすればその部分かな、と考えていました。

一方、BDBの書き込みに関してはtransactionを使わないようにしていることから、データファイルに都度書き込みを行っているのではないかと判然と考えていました。しかし、実際にはかなり。そこで、hprofでcpuの使用時間を確認してみました。

Profiling cpu time

JVMオプションに以下を指定して実行し、cpuの使用時間を確認しました。といってもサンプリングによる計測なので、あくまで割合ですが。

-agentlib:hprof=cpu=samples,file=result.hprof,depth=20

Result of FileStoredMap

プロファイリングの結果を確認したところ、FSM実行時に呼び出されてる頻度が高いメソッドtop10は以下のようになっていました。

CPU SAMPLES BEGIN (total = 5168) Wed May  2 23:43:39 2012
rank   self  accum   count trace method
    1 28.25% 28.25%    1460 301392 bb.science.Lfsr.advance
    2 10.06% 38.31%     520 301398 bb.science.Lfsr.advance
    3  7.28% 45.59%     376 301173 org.bson.BSONEncoder._put
    4  4.64% 50.23%     240 300804 org.bson.BSONEncoder._put
    5  4.49% 54.72%     232 301396 bb.science.Lfsr.advance
    6  3.93% 58.65%     203 301029 org.bson.BSONEncoder._put
    7  1.97% 60.62%     102 301174 java.io.UnixFileSystem.getBooleanAttributes0
    8  1.63% 62.25%      84 301175 java.io.RandomAccessFile.writeBytes
    9  1.37% 63.62%      71 300922 sun.nio.cs.UTF_8$Decoder.decodeArrayLoop
    10  1.14% 64.76%      59 301192 java.io.RandomAccessFile.length

rank1、rank2、rank5はベンチマークのコードなので無視して構いません。rank3、rank4、rank6にBSONEncoder#_putが入っています。RandomAccessFileの操作が上位と予想していたので、ちょっと想定外です。

BSONEncoder#_putの呼び出しのシーケンスを確認してみました。

TRACE 301173:
        org.bson.BSONEncoder._put(BSONEncoder.java:434)
        org.bson.BSONEncoder._putValueString(BSONEncoder.java:390)
        org.bson.BSONEncoder._putString(BSONEncoder.java:358)
        org.bson.BSONEncoder.putString(BSONEncoder.java:353)
        org.bson.BSONEncoder._putObjectField(BSONEncoder.java:169)
        org.bson.BSONEncoder.putObject(BSONEncoder.java:123)
        org.bson.BSONEncoder.putObject(BSONEncoder.java:69)
        org.bson.BSONEncoder.encode(BSONEncoder.java:36)
        net.wrap_trap.collections.fsm.store.bson.BsonEntityService.toByteArray(BsonEntityService.java:100)

BSONObjectをbyte[]に変換するシーケンスのようです。

FSMではputの内側で文字列からbyte[]への変換を行っています。しかしBDBは以下のコードにあるように、先に文字列をbyte[]に変換し、それを基にDatabaseEntryを生成してそれをputしています。その違いでしょうか？

 1    @Override
 2    protected void write() {
 3        try {
 4            String value = getValue();
 5            for (int i = 1; i <= getEntries(); i++) {
 6                db.put(null, new DatabaseEntry(String.valueOf(i).getBytes("UTF-8")),
 7                       new DatabaseEntry(value.getBytes("UTF-8")));
 8            }
 9        } catch (DatabaseException e) {
10            throw new RuntimeException(e);
11        } catch (UnsupportedEncodingException e) {
12            throw new RuntimeException(e);
13        }
14    }

BSONEncoder#_put

BSONEncoder#_putが何を行っているか確認してみました。

mongo-java-driver/src/main/org/bson/BSONEncoder.java at 8766580cab81009fae143cc9a45e6f3f7d3d899d - mongodb/mongo-java-driver

指定された文字列をUTF-8に変換してstreamに書き込んでいます。String#getBytes(“UTF-8”)を使わないのは、変換結果をbyte[]に変えることなくそのままstreamに書き込む為でしょう。

434行目のCharacter#charCountはunicodeの文字種からサイズを取得しているだけなので、そんなに重い処理にはならないはずです。また、このメソッドの中が重いのではなくBSONEncoder#_putの434行目が重いと出ているだけなので、UTF-8の文字列の書き込み回数が多いことに起因するものと思われます。

Result of BerkeleyDB

UTF-8の文字列の書き込み回数が多いということであれば、BDBの結果もそうなるはずです。BDBのプロファイリング結果は以下となっています。

CPU SAMPLES BEGIN (total = 12574) Thu May  3 00:29:56 2012
rank   self  accum   count trace method
    1 15.29% 15.29%    1922 300699 sun.nio.ch.FileChannelImpl.force0
    2 11.37% 26.66%    1430 301803 bb.science.Lfsr.advance
    3 11.13% 37.79%    1400 300687 java.util.zip.Adler32.updateBytes
    4 10.70% 48.50%    1346 300666 java.io.RandomAccessFile.writeBytes
    5  7.17% 55.66%     901 301806 bb.science.Lfsr.advance
    6  5.17% 60.83%     650 301253 sun.nio.cs.UTF_8.updatePositions
    7  2.16% 62.99%     271 301805 bb.science.Lfsr.advance
    8  2.01% 65.00%     253 300762 sun.nio.ch.FileChannelImpl.force0
    9  1.76% 66.76%     221 301248 java.lang.StringCoding$StringEncoder.encode
    10  1.52% 68.28%     191 301015 sun.nio.cs.UTF_8.updatePositions

FSMと同様にbb.scienceから始まるのはベンチマークのコードなので無視します。rank1の呼び出しシーケンスは以下のようになっていました。

TRACE 300699:
        sun.nio.ch.FileChannelImpl.force0(FileChannelImpl.java:Unknown line)
        sun.nio.ch.FileChannelImpl.force(FileChannelImpl.java:399)
        com.sleepycat.je.log.FileManager$LogEndFileDescriptor.force(FileManager.java:3048)
        com.sleepycat.je.log.FileManager$LogEndFileDescriptor.access$500(FileManager.java:2715)
        com.sleepycat.je.log.FileManager.syncLogEnd(FileManager.java:2030)
        com.sleepycat.je.log.FileManager.syncLogEndAndFinishFile(FileManager.java:2045)
        com.sleepycat.je.log.LogBufferPool.getWriteBuffer(LogBufferPool.java:203)
        com.sleepycat.je.log.LogManager.serialLogInternal(LogManager.java:598)
        com.sleepycat.je.log.SyncedLogManager.serialLog(SyncedLogManager.java:40)
        com.sleepycat.je.log.LogManager.multiLog(LogManager.java:395)
        com.sleepycat.je.log.LogManager.log(LogManager.java:335)
        com.sleepycat.je.tree.LN.logInternal(LN.java:534)
        com.sleepycat.je.tree.LN.optionalLog(LN.java:350)
        com.sleepycat.je.dbi.CursorImpl.insertNewSlot(CursorImpl.java:948)
        com.sleepycat.je.dbi.CursorImpl.putInternal(CursorImpl.java:834)
        com.sleepycat.je.dbi.CursorImpl.put(CursorImpl.java:774)

ログの書き込み時のファイル同期ですかね。「UTF_8」という文字が含まれているrank6、rank10のシーケンスは以下のとおりです。

TRACE 301253:
        sun.nio.cs.UTF_8.updatePositions(UTF_8.java:76)
        sun.nio.cs.UTF_8$Encoder.encodeArrayLoop(UTF_8.java:411)
        sun.nio.cs.UTF_8$Encoder.encodeLoop(UTF_8.java:466)
        java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:561)
        java.lang.StringCoding$StringEncoder.encode(StringCoding.java:258)
        java.lang.StringCoding.encode(StringCoding.java:290)
        java.lang.String.getBytes(String.java:954)
        net.wrap_trap.collections.fsm.bench.BerkeleyDbBench.write(BerkeleyDbBench.java:48)

Getting UTF-8 bytecode

FSMとBDBでプロファイリング結果を比較してみると、FSMはStringをUTF-8にバイトコード変換する箇所が重いと出ていました。一方で、BDBではUTF-8への変換がtop 10にランクインしているものの、一番重い処理ではありませんでした。しかしBDBの方がwriteは圧倒的に速いわけで、どうもBSONEncoder#_putのUTF-8変換に問題がありそうに見えます。

しかし、このコードを見る限りUTF-8の変換処理そのものに無駄はないように見えます。果たして何が問題なのでしょうか？

Change the putting value

これまで、putしていた値は”a”のみで構成される10Kの文字列でした。BDBの検証コードでは、もしかしたらこの文字列をUTF-8に変換する部分が動的に最適化されてしまい、このような違いとなったのではないかと考え、UUIDに変えてみました。

// 変更前
protected String createValue(String str, int n) {
    String ret = "";
    for (; n > 0; n >>>= 1, str += str) {
        if ((n & 1) > 0) {
            ret += str;
        }
    }
    return ret;
}

// 変更後
protected String createUUID() {
    return UUID.randomUUID().toString();
}

Second Result

putする値をUUIDに変更後、再度FSMのプロファイリングをしてみたところ、以下のような結果になりました。

CPU SAMPLES BEGIN (total = 5462) Thu May  3 03:20:31 2012
rank   self  accum   count trace method
    1 22.61% 22.61%    1235 301363 bb.science.Lfsr.advance
    2 14.39% 37.00%     786 301368 bb.science.Lfsr.advance
    3  4.87% 41.87%     266 301365 bb.science.Lfsr.advance
    4  2.65% 44.53%     145 301167 java.io.UnixFileSystem.getBooleanAttributes0
    5  2.18% 46.70%     119 301160 java.io.RandomAccessFile.length
    6  1.21% 47.91%      66 300833 java.io.UnixFileSystem.getBooleanAttributes0
    7  1.10% 49.01%      60 301153 java.io.UnixFileSystem.getBooleanAttributes0
    8  0.95% 49.96%      52 300871 java.io.RandomAccessFile.length
    9  0.81% 50.77%      44 301155 java.io.RandomAccessFile.write
    10  0.73% 51.50%      40 301156 java.io.RandomAccessFile.write
    11  0.70% 52.20%      38 301158 java.io.RandomAccessFile.writeBytes
    12  0.64% 52.84%      35 301179 java.io.RandomAccessFile.seek
    13  0.59% 53.42%      32 301207 java.io.RandomAccessFile.length
    14  0.57% 53.99%      31 301133 java.io.RandomAccessFile.write
    15  0.57% 54.56%      31 301196 java.io.RandomAccessFile.write
    16  0.55% 55.11%      30 301135 java.io.RandomAccessFile.length
    17  0.51% 55.62%      28 301173 java.io.RandomAccessFile.write
    18  0.48% 56.10%      26 301175 java.io.RandomAccessFile.write
    19  0.48% 56.57%      26 301203 java.io.RandomAccessFile.write
    20  0.46% 57.03%      25 301171 java.io.RandomAccessFile.write

BSONEncoder#_putがtop 20外となりました。そしてRandomAccessFileの操作が上位を占めており、想定していた結果にかなり近いです。この結果、BSONEncoder#_putの速度は、putする文字列の長さによって大きく変わるようです。

BDBの方は以下のとおり。

CPU SAMPLES BEGIN (total = 11881) Thu May  3 03:25:23 2012
rank   self  accum   count trace method
    1 17.50% 17.50%    2079 300781 java.util.zip.Adler32.updateBytes
    2 12.83% 30.33%    1524 302540 bb.science.Lfsr.advance
    3  5.81% 36.13%     690 300803 sun.nio.ch.FileChannelImpl.force0
    4  4.22% 40.35%     501 302545 bb.science.Lfsr.advance
    5  3.33% 43.68%     396 301840 java.nio.HeapByteBuffer.<init>
    6  2.72% 46.40%     323 301245 java.nio.HeapByteBuffer.<init>
    7  1.75% 48.15%     208 302543 bb.science.Lfsr.advance
    8  1.58% 49.73%     188 300605 sun.nio.ch.FileChannelImpl.force0
    9  1.16% 50.90%     138 301860 com.sleepycat.je.dbi.CursorImpl.hashCode
    10  1.07% 51.97%     127 301912 com.sleepycat.je.log.FileManager$LogEndFileDescriptor.<init>

こちらもUTF-8への変換処理はtop 10外となり、HeapByteBufferの生成が上位に上がってきました。

Conclusion

コードは何も変えてないのですが、取り合えず以下のことが分かりました。

mongo-java-driverは長い文字列を書き込む際に処理が重くなる可能性がある
- String#getBytes(“UTF-8”)との比較は別途してみたい
FileStoredMapのwriteを改善するには、RandomAccessFileへの操作を工夫する必要がある