javaで作成したプログラムの処理時間計測について

Question

javaでプログラムを作成したのですが、これの処理時間を計測したいと考えています

実行してから終了するまでの時間の計測方法はわかるのですが
より正確に処理時間を把握するために複数回実行してその平均を
とりたいと考えています

プログラムの実行を指定回数自動で行い出力結果を得る
方法はありますか？

Comments

[m.ts10806]

これそのままプログラムに起こせば良いだけではないのでしょうか。
＞プログラムの実行を指定回数自動で行い出力結果を得る

Answer 1

forループか何かで繰り返し実行させ、処理時間の平均を出せばどうでしょう

Answer 2

java プロファイラ ツール
で google 検索すると、CPU 使用率の高いメソッドをみつけることなどができます。

検索結果からの紹介

• Java VisualVM でパフォーマンスのボトルネックを突き止める

http://www.techscore.com/blog/2017/12/11/identifying_performance_bottlenecks_with_jvisualvm/

• Java 解析ツール比較ガイド

https://www.xlsoft.com/jp/blog/blog/2018/02/17/post-3082/

Answer 3

あまりいろいろ気にせず素朴にやるなら自分でループを書いて実行速度の平均を計算するのが手っ取り早い気がしますが、その結果はタイマーの精度やJVMの最適化(Just-In-Time compilerによるネイティブコードへの自動コンパイルなど)やガーベージコレクターによる実行時間変動などにより大きく影響を受けますのでそうしたものに配慮する計測は意外に面倒だと思います。

自分が使ったことがないものを紹介するのはアレですがOpenJDKプロジェクトで公開されている性能計測用のライブラリーがあるとのことです。

http://openjdk.java.net/projects/code-tools/jmh/

これは単に「指定回数ループさせ実行時間の平均を取る」といった単純なものではなく指定した処理の1秒あたりの実行回数がどの程度なのかを誤差なども含めて自動計測してくれるようです。

上のページに使い方が書いてあるはずですが検索すると日本語での使用例の紹介なども見つかります。
https://blog.y-yuki.net/entry/2016/09/07/010000

---

なお、自分はそうまで真剣に性能測定に取り組んだことがなく大抵は「何回かあらかじめループさせてJITがコンパイルしてくれただろうことを期待した上でN回ループしたときの平均と標準偏差(時にGCの回数なども)を何回か計算し結果を目視で吟味する」といった程度のことしかしません。(アマチュアなもので...)

きちんとした測定とは言えませんがそれでも結構なコード量になります。前述のJMHを利用した方が確実だろうと思います。

import java.lang.management.ManagementFactory;
import java.lang.management.GarbageCollectorMXBean;
import java.util.stream.Stream;
import java.util.stream.Collectors;

// 測定対象1: プリミティブ型を用いた累加処理
class ProcPri implements Runnable {
  int result;

  public void run() {
    int sum = 0;
    for (int i = 0; i < 1_000_000; i++) {
      sum += i;
    }
    result = sum;
  }
}

// 測定対象2: ラッパータイプを用いた累加処理
class ProcBox implements Runnable {
  Integer result;

  public void run() {
    Integer sum = 0;
    for (int i = 0; i < 1_000_000; i++) {
      sum += i;
    }
    result = sum;
  }
}

// 測定用のコード
class ETM {
  public static void main(String[] args) {
    Runnable procPri = new ProcPri();
    Runnable procBox = new ProcBox();

    for (int i = 0; i < 10; i++) {
      etm("pri", procPri, 20);
      etm("box", procBox, 20);
    }
  }

  static void etm(String title, Runnable runnable, int n) {
    var gcs = ManagementFactory.getGarbageCollectorMXBeans().stream()
      .filter(GarbageCollectorMXBean::isValid)
      .collect(Collectors.toMap(identity(), GarbageCollectorMXBean::getCollectionCount));

    double s1 = 0, s2 = 0;

    for (int i = 0; i < n; i++) {
      long t = -System.nanoTime();
      runnable.run();
      t += System.nanoTime();
      s1 += t / 1E9;
      s2 += t * t /1E18; // すみません、1E18で割るのを忘れてたコードを載せてました。
    }

    double mean = s1 / n;
    double std = Math.sqrt(s2 / n - mean * mean);

    System.out.format("%s: mean %.9f std %.9f gc", title, mean, std);

    for (var gcBean: ManagementFactory.getGarbageCollectorMXBeans()) {
      if (gcBean.isValid()) {
        System.out.format(" %d", gcBean.getCollectionCount() - gcs.get(gcBean));
      }
    }
    System.out.println();
  }
}

===>

$ java ETM
pri: mean 0.000450753 std 0.000512748 gc 0 0 <= 初回はかなり時間がかかる。偏差も大きい
box: mean 0.004843579 std 0.002445166 gc 2 0
pri: mean 0.000279995 std 0.000000470 gc 0 0 <= 2回目はかなり偏差が小さくなる
box: mean 0.002278036 std 0.000452674 gc 2 0
pri: mean 0.000272811 std 0.000000488 gc 0 0
box: mean 0.003139957 std 0.001825407 gc 2 0 <= しかしGCが起きるようなものはやはり偏差大
pri: mean 0.000275036 std 0.000007335 gc 0 0
box: mean 0.002275702 std 0.000455196 gc 2 0
pri: mean 0.000282001 std 0.000020618 gc 0 0
box: mean 0.003770276 std 0.002332905 gc 1 0
...