【メモ】ヒープ領域を16mにして小さいながらも50,000,000件あるデータをGroovyであれこれしようとした結果ｗｗｗｗｗｗｗｗｗｗｗ

OOMが発生してた(´・ω・｀)

まあ、予想通りです。

---

元々Groovyで1～6のランダムな数値を発生させて、それがどういう分布になるかを確認するスクリプトを書いていただけだったのですが、デフォルトのJVM起動オプションで試行回数5,000,000回でやってみたところOOMが発生したので、JVM起動オプションをそろそろちゃんと勉強する機会かなと感じたので、小さなヒープサイズからそれなりのヒープサイズまで、試行回数もそれなりに幅をもたせて実行することにしました。

実行したのは次のスクリプトです。

def options = [
    '-XX:+PrintGCDetails',
    '-XX:+PrintGCDateStamps',
    '-XX:+UseConcMarkSweepGC',
    '-XX:+HeapDumpOnOutOfMemoryError'
].join(' ')

[].class.metaClass.define {
    collect = {Object initial, Closure c ->
        def result = []
        def prev = initial
        delegate.each {item ->
            prev = c(prev, item)
            result << prev
        }
        result
    }
}

def opts = (1..8).collect{2}.collect(8) {prev, item ->
    prev * item
}.collect {
    [value: "cmd /c set JAVA_OPTS=-Xms${it}m -Xmx${it}m ${options}", mem: it]
}

def cmds = (1..11).collect{it % 2 == 1 ? 5:2}.collect(100) {prev, item ->
    size:prev * item
}.collect {
    def file = "dice_${it}.groovy"
    [cmd:"cmd /c echo def size = ${it} > $file & cmd /c type base.groovy.tmp >> $file & groovy $file & cmd /c del $file", size:it]
}

def size = opts.size() * cmds.size()
def fin = 0

opts.each {opt ->
    cmds.each {cmd ->
        println "execution ${++fin}/${size} memory size[${String.format('%4d', opt.mem)}] data size[${String.format('%8d', cmd.size)}]"
        def result = "${opt.value} -Xloggc:dice_${String.format('%04d', opt.mem)}_${String.format('%08d', cmd.size)}.log & ${cmd.cmd}".execute().waitFor()
        println "execution ${fin}/${size} memory size[${String.format('%4d', opt.mem)}] data size[${String.format('%8d', cmd.size)}] finished"
    }
}

グッチャグチャしていますが、ヒープサイズは16mから2048mまでの8段階、試行回数は500回～50,000,000回までの11段階の組み合わせで、計88回実行させています。

実行させたスクリプトは次のとおりです。

@Grab('org.codehaus.gpars:gpars:1.2.1')
import static groovyx.gpars.GParsPool.*
import java.nio.file.*

def log = Paths.get('C:', 'Users', 'mike', 'groovy', 'dice', 'dice_env.log').toFile()
log.append("data-size[${size}] - option[${System.getenv('JAVA_OPTS')}]\n")

IntRange.metaClass.define{
    random = {
        delegate.min() + new Random().nextInt(delegate.size())
    }
}

withPool(8) {
    def list = []
    10.times {
        def start = System.currentTimeMillis()
        (new IntRange(1,size)).collectParallel {
            (1..6).random()
        }.groupByParallel {it}.collectParallel {
            [value: it.key, count: it.value.size()]
        }.each {
            print "${it.value} -> ${it.count} "
        }
        println ''
        def end = System.currentTimeMillis()
        list << end - start
    }
    log.append(String.format('%8d -> %8.2f ms\n', size, list.sum()/(list.size() as double)))
}

---

たとえば、これの16mでの起動時は次のようなログが残ります。

data-size[500] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_00000500.log ]
     500 ->    84.20 ms
data-size[1000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_00001000.log ]
    1000 ->    92.10 ms
data-size[5000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_00005000.log ]
    5000 ->    98.20 ms
data-size[10000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_00010000.log ]
   10000 ->   443.00 ms
data-size[50000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_00050000.log ]
   50000 ->   608.40 ms
data-size[100000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_00100000.log ]
  100000 ->  1073.20 ms
data-size[500000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_00500000.log ]
data-size[1000000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_01000000.log ]
data-size[5000000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_05000000.log ]
data-size[10000000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_10000000.log ]
data-size[50000000] - option[-Xms16m -Xmx16m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -Xloggc:dice_0016_50000000.log ]

OOMが発生すると500000 -> 2015.11 msのようなログが出なくなります。

上記の場合だと16mのヒープサイズで試行回数500,000回からOOMが出ていることがわかります。

GCログの解析はあとでやる( ｰ`дｰ´)ｷﾘｯ

---

以上、元旦の3時とか4時とかにずっとこんなんやってた