Java 処理時間の計測｜nanoTimeとcurrentTimeMillis

Javaで処理時間を計測する基本は、処理の前後で System.nanoTime() を呼び、その差を取ることです。 nanoTime は「経過時間を測るための時計」で、パソコンの時刻設定が変わっても差の計算に影響しません。System.currentTimeMillis() や Instant.now() は「いま何時か」を知るための時計なので、開始時刻をログに残したいときに向いています。

この記事では、4つの計測方法の比較表、そのまま貼って使える計測ユーティリティ（Runnable を渡す版と try-with-resources 版）、同じ処理でも1回目と1万回目で時間が大きく変わる様子、ウォームアップ後に複数回測って平均と中央値を出す方法、単位変換の一覧、そしてベンチマーク用ツール JMH の最小構成までを扱います。コードの出力は、すべて下記の環境で動かしたものです。

確認環境：Ubuntu 24.04 / OpenJDK 21.0.10（StopWatch の例のみ Apache Commons Lang 3.14.0 を使用）。時間の数値はマシンや負荷によって変わるので、桁と傾向を見てください。

処理時間の計測方法の早見表

迷ったときの選び方は次のとおりです。

基本の書き方｜3つの方法を同じ処理で比べる

まずは基本形です。100万件の整数を並べ替える処理を、3つの方法で測ります。

import java.time.Duration;
import java.time.Instant;
import java.util.Arrays;
import java.util.Random;

public class Basic {
    // 計測したい処理：100万件の整数を並べ替える
    static int[] data() {
        return new Random(42).ints(1_000_000, 0, 1_000_000).toArray();
    }

    public static void main(String[] args) {
        // 1) System.currentTimeMillis()：ミリ秒
        int[] a = data();
        long startMs = System.currentTimeMillis();
        Arrays.sort(a);
        long endMs = System.currentTimeMillis();
        System.out.println("currentTimeMillis: " + (endMs - startMs) + " ms");

        // 2) System.nanoTime()：ナノ秒
        int[] b = data();
        long startNs = System.nanoTime();
        Arrays.sort(b);
        long elapsedNs = System.nanoTime() - startNs;
        System.out.println("nanoTime         : " + elapsedNs + " ns = "
                + elapsedNs / 1_000_000.0 + " ms");

        // 3) Instant + Duration：日時API
        int[] c = data();
        Instant start = Instant.now();
        Arrays.sort(c);
        Duration d = Duration.between(start, Instant.now());
        System.out.println("Instant+Duration : " + d.toMillis() + " ms (" + d + ")");
    }
}

実行コマンドは java Basic.java です（Java 11 以降は、1ファイルならコンパイルなしで実行できます）。

currentTimeMillis: 908 ms
nanoTime         : 314414839 ns = 314.414839 ms
Instant+Duration : 314 ms (PT0.314632045S)

書き方のポイントは3つです。

• データの準備（data() の呼び出し）は計測の外に置く。 測りたいのは並べ替えだけなので、開始時刻はその直前で取ります。
• nanoTime は差だけを使う。 単体の値は「ある時点からのナノ秒」で、日時としての意味はありません。
• Duration をそのまま表示すると PT0.314632045S という形式（ISO 8601）になる。 ミリ秒がほしいときは toMillis() を使います。

同じ処理なのに、1番目だけ時間が長い理由

上の出力では、同じ並べ替えなのに1番目（currentTimeMillis）だけ約900ミリ秒かかっています。これは計測方法の差ではなく、順番の差です。同じ方法（nanoTime）で5回続けて測ると、はっきり分かります。

import java.util.Arrays;
import java.util.Random;

public class Order {
    public static void main(String[] args) {
        // まったく同じ処理（100万件の並べ替え）を、同じ方法で5回測る
        for (int n = 1; n <= 5; n++) {
            int[] a = new Random(42).ints(1_000_000, 0, 1_000_000).toArray();
            long s = System.nanoTime();
            Arrays.sort(a);
            long ns = System.nanoTime() - s;
            System.out.printf("%d 回目: %.1f ms%n", n, ns / 1_000_000.0);
        }
    }
}

1 回目: 507.3 ms
2 回目: 249.9 ms
3 回目: 173.1 ms
4 回目: 360.2 ms
5 回目: 164.6 ms

1回目がいちばん長く、回を重ねると短くなります（4回目のように、ほかのプログラムの影響で一時的に長くなる回もあります）。Java は実行しながらコードを最適化していくため、最初の数回は「準備運動」の時間が含まれるのです。この性質は後半の「ウォームアップ」で詳しく扱います。先に覚えておきたいのは、1回だけ測った値で結論を出さないという点です。

nanoTime と currentTimeMillis の違い

2つのメソッドは、名前は似ていても役割が違います。Java 21 の API ドキュメント（System クラス）の記載と、手元で調べた値を並べます。

実際に「値が変わる最小の幅」を調べてみます。値が変わるまで呼び続けて、変化の幅の最小値を出すプログラムです。

import java.time.Instant;

public class Granularity {
    public static void main(String[] args) {
        // 値が変わるまで呼び続け、変化の最小幅を調べる
        long minMs = Long.MAX_VALUE, minNs = Long.MAX_VALUE;
        for (int i = 0; i < 5; i++) {
            long t0 = System.currentTimeMillis(), t1;
            while ((t1 = System.currentTimeMillis()) == t0) { }
            minMs = Math.min(minMs, t1 - t0);
        }
        for (int i = 0; i < 100_000; i++) {
            long n0 = System.nanoTime(), n1;
            while ((n1 = System.nanoTime()) == n0) { }
            minNs = Math.min(minNs, n1 - n0);
        }
        System.out.println("currentTimeMillis の最小の変化幅: " + minMs + " ms");
        System.out.println("nanoTime の最小の変化幅         : " + minNs + " ns");
        System.out.println("currentTimeMillis の値: " + System.currentTimeMillis());
        System.out.println("nanoTime の値         : " + System.nanoTime());
        System.out.println("Instant.now()         : " + Instant.now());
    }
}

currentTimeMillis の最小の変化幅: 1 ms
nanoTime の最小の変化幅         : 23 ns
currentTimeMillis の値: 1791038538609
nanoTime の値         : 1798944387171
Instant.now()         : 2026-10-03T14:42:18.610152554Z

この環境では、currentTimeMillis は1ミリ秒刻み、nanoTime は数十ナノ秒刻みで値が変わりました。1ミリ秒より短い処理は、currentTimeMillis では 0 か 1 にしかならないので、nanoTime を使います。

もう1つの違いが、時計の変更です。currentTimeMillis と Instant.now() はシステムの時刻を読むので、計測の途中で時刻が調整される（時刻合わせや手動の変更）と、差が実際より長くなったり、マイナスになったりする可能性があります。nanoTime は API ドキュメントに「経過時間の計測にのみ使える」「システム時刻や壁時計の時刻とは関係しない」と書かれており、経過時間の計測はこちらが担当です。

タイムアウト判定は「差」で比べる

nanoTime の値は負の数になることもある、と API ドキュメントにあります。そのため、タイムアウトの判定は必ず差で書きます。ドキュメントに載っている形は次のとおりです。

public class TimeoutCheck {
    public static void main(String[] args) throws InterruptedException {
        long timeoutNanos = 200_000_000L;          // 200ms
        long startTime = System.nanoTime();
        int count = 0;
        // 差を取ってから比べる（startTime + timeoutNanos と比べる書き方は避ける）
        while (System.nanoTime() - startTime < timeoutNanos) {
            Thread.sleep(50);
            count++;
        }
        System.out.println("ループ回数: " + count);
    }
}

ループ回数: 4

コピペで使える計測ユーティリティ（Runnable版・try-with-resources版）

毎回「開始を取る → 終了を取る → 引き算 → 表示」と書くのは手間なので、小さなクラスにまとめます。標準ライブラリだけで動き、次の3通りで使えます。

import java.util.Arrays;
import java.util.Random;
import java.util.function.Supplier;

public class TimerDemo {

    /** 処理時間を測る小さなユーティリティ（標準ライブラリだけで動く） */
    static final class Timer implements AutoCloseable {
        private final String label;
        private final long start = System.nanoTime();

        private Timer(String label) { this.label = label; }

        /** try-with-resources 用：ブロックを抜けたときに表示する */
        static Timer start(String label) { return new Timer(label); }

        /** Runnable を渡すと ms で表示する */
        static void measure(String label, Runnable task) {
            long s = System.nanoTime();
            task.run();
            print(label, System.nanoTime() - s);
        }

        /** 戻り値がある処理用 */
        static <T> T measure(String label, Supplier<T> task) {
            long s = System.nanoTime();
            T result = task.get();
            print(label, System.nanoTime() - s);
            return result;
        }

        @Override
        public void close() { print(label, System.nanoTime() - start); }

        private static void print(String label, long nanos) {
            System.out.printf("[%s] %.3f ms%n", label, nanos / 1_000_000.0);
        }
    }

    public static void main(String[] args) {
        int[] data = new Random(42).ints(1_000_000, 0, 1_000_000).toArray();

        // 1) Runnable を渡す
        Timer.measure("sort", () -> Arrays.sort(data.clone()));

        // 2) 戻り値を受け取る
        long sum = Timer.measure("sum", () -> Arrays.stream(data).asLongStream().sum());
        System.out.println("sum = " + sum);

        // 3) try-with-resources で囲む
        try (Timer t = Timer.start("sort+sum")) {
            int[] copy = data.clone();
            Arrays.sort(copy);
            Arrays.stream(copy).asLongStream().sum();
        }
    }
}

[sort] 1115.384 ms
[sum] 23.870 ms
sum = 500478794436
[sort+sum] 376.501 ms

try-with-resources 版は、ブロックを抜けるときに close() が自動で呼ばれる仕組みを使っています。途中で例外が投げられても close() は呼ばれるので、表示が抜けません。表示先をログに変えたいときは、print メソッドの中身を差し替えるだけで済みます。

なお、ここでも [sort] が約1.1秒、同じ並べ替えを含む [sort+sum] が約0.38秒と、先に実行したほうが長く出ています。前の章と同じ「1回目の準備運動」の影響です。

区間ごとに測る｜StopWatch 系の使い方

「読み込み・変換・保存のどこに時間がかかっているか」を知りたいときは、区間ごとに記録するストップウォッチが便利です。Java の標準ライブラリにはストップウォッチのクラスがないため、自作するか、ライブラリのものを使います。

自作の Stopwatch（標準ライブラリのみ）

import java.util.LinkedHashMap;
import java.util.Map;

public class MyStopwatch {
    /** 区間ごとに名前を付けて測る、自作のストップウォッチ */
    static final class Stopwatch {
        private final Map<String, Long> laps = new LinkedHashMap<>();
        private long last = System.nanoTime();

        /** 前回の lap（または生成）からの経過を記録する */
        void lap(String name) {
            long now = System.nanoTime();
            laps.merge(name, now - last, Long::sum);
            last = now;
        }

        void print() {
            long total = laps.values().stream().mapToLong(Long::longValue).sum();
            laps.forEach((name, ns) -> System.out.printf("%-8s %8.3f ms (%4.1f%%)%n",
                    name, ns / 1_000_000.0, 100.0 * ns / total));
            System.out.printf("%-8s %8.3f ms%n", "total", total / 1_000_000.0);
        }
    }

    public static void main(String[] args) throws InterruptedException {
        Stopwatch sw = new Stopwatch();
        Thread.sleep(30);          // 読み込みのつもり
        sw.lap("load");
        Thread.sleep(120);         // 変換のつもり
        sw.lap("convert");
        Thread.sleep(50);          // 保存のつもり
        sw.lap("save");
        sw.print();
    }
}

load       30.218 ms (15.0%)
convert   120.706 ms (60.0%)
save       50.143 ms (24.9%)
total     201.068 ms

割合まで出すと、「どこから手を付けると効果が大きいか」がひと目で分かります。同じ名前で lap を複数回呼ぶと合算されるので、ループの中でも使えます。

Apache Commons Lang の StopWatch

すでに Commons Lang を使っているなら、org.apache.commons.lang3.time.StopWatch が使えます。3.14.0 で動かした例です。

import java.util.Arrays;
import java.util.Random;
import java.util.concurrent.TimeUnit;
import org.apache.commons.lang3.time.StopWatch;

public class SwDemo {
    public static void main(String[] args) {
        int[] data = new Random(42).ints(1_000_000, 0, 1_000_000).toArray();

        StopWatch sw = StopWatch.createStarted();
        Arrays.sort(data);
        sw.split();                                  // 途中経過（ラップ）
        System.out.println("sort まで : " + sw.getSplitTime() + " ms");

        long sum = Arrays.stream(data).asLongStream().sum();
        sw.stop();
        System.out.println("合計      : " + sw.getTime() + " ms");
        System.out.println("ナノ秒    : " + sw.getNanoTime() + " ns");
        System.out.println("単位指定  : " + sw.getTime(TimeUnit.MICROSECONDS) + " μs");
        System.out.println("toString  : " + sw);
        System.out.println("sum = " + sum);
    }
}

実行コマンドは java -cp commons-lang3-3.14.0.jar SwDemo.java です。

sort まで : 352 ms
合計      : 419 ms
ナノ秒    : 419731871 ns
単位指定  : 419731 μs
toString  : 00:00:00.419
sum = 500478794436

単位変換の一覧｜TimeUnit と Duration.toMillis

nanoTime の差はナノ秒なので、表示するときはミリ秒や秒に直します。方法は「割り算」「TimeUnit」「Duration」の3つです。

表の値は、次のプログラムで出したものです。

import java.time.Duration;
import java.util.concurrent.TimeUnit;

public class Units {
    public static void main(String[] args) {
        long nanos = 1_234_567_890L;   // 約1.23秒

        System.out.println("--- 割り算 ---");
        System.out.println(nanos / 1_000 + " μs");
        System.out.println(nanos / 1_000_000 + " ms（整数：端数は切り捨て）");
        System.out.println(nanos / 1_000_000.0 + " ms（小数）");
        System.out.println(nanos / 1_000_000_000.0 + " s");

        System.out.println("--- TimeUnit ---");
        System.out.println(TimeUnit.NANOSECONDS.toMicros(nanos) + " μs");
        System.out.println(TimeUnit.NANOSECONDS.toMillis(nanos) + " ms");
        System.out.println(TimeUnit.NANOSECONDS.toSeconds(nanos) + " s");
        System.out.println(TimeUnit.MILLISECONDS.toNanos(5) + " ns（5msをnsへ）");
        System.out.println(TimeUnit.MILLISECONDS.convert(nanos, TimeUnit.NANOSECONDS) + " ms（convert）");

        System.out.println("--- Duration ---");
        Duration d = Duration.ofNanos(nanos);
        System.out.println(d);
        System.out.println(d.toNanos() + " ns");
        System.out.println(d.toMillis() + " ms");
        System.out.println(d.toSeconds() + " s");
        System.out.println(d.toSecondsPart() + " s + " + d.toMillisPart() + " ms（Part系）");
        System.out.println(d.getSeconds() + " s + " + d.getNano() + " ns（getSeconds/getNano）");
        System.out.printf("%d.%03d 秒%n", d.toSeconds(), d.toMillisPart());

        System.out.println("--- 小さい値 ---");
        long small = 480_000L;  // 0.48ms
        System.out.println(TimeUnit.NANOSECONDS.toMillis(small) + " ms（0に切り捨て）");
        System.out.println(Duration.ofNanos(small).toMillis() + " ms（0に切り捨て）");
        System.out.printf("%.3f ms%n", small / 1_000_000.0);
    }
}

--- 割り算 ---
1234567 μs
1234 ms（整数：端数は切り捨て）
1234.56789 ms（小数）
1.23456789 s
--- TimeUnit ---
1234567 μs
1234 ms
1 s
5000000 ns（5msをnsへ）
1234 ms（convert）
--- Duration ---
PT1.23456789S
1234567890 ns
1234 ms
1 s
1 s + 234 ms（Part系）
1 s + 234567890 ns（getSeconds/getNano）
1.234 秒
--- 小さい値 ---
0 ms（0に切り捨て）
0 ms（0に切り捨て）
0.480 ms

注意したいのは最後の3行です。TimeUnit の toMillis も Duration の toMillis も、端数を切り捨てた整数を返します。 0.48 ミリ秒の処理は 0 ms と表示されるので、短い処理を扱うときは nanos / 1_000_000.0 のように小数で割り、%.3f で桁をそろえて表示すると読みやすくなります。

1回目と1万回目で時間が変わる｜ウォームアップ

ここからが、処理時間の計測でいちばん大切なところです。同じ処理を1万回繰り返し、何回目に何ナノ秒かかったかを記録します。

import java.util.List;

public class Warmup {
    // 計測したい処理：1〜1000 の文字列を連結して長さを返す
    static int work() {
        StringBuilder sb = new StringBuilder();
        for (int i = 1; i <= 1000; i++) {
            sb.append(i).append(',');
        }
        return sb.length();
    }

    public static void main(String[] args) {
        int total = 10_000;
        long[] nanos = new long[total + 1];
        long check = 0;
        for (int n = 1; n <= total; n++) {
            long s = System.nanoTime();
            check += work();
            nanos[n] = System.nanoTime() - s;
        }
        for (int n : List.of(1, 2, 3, 10, 100, 1000, 5000, 10000)) {
            System.out.printf("%,6d 回目: %,10d ns (%.3f ms)%n", n, nanos[n], nanos[n] / 1_000_000.0);
        }
        System.out.println("check = " + check);
    }
}

     1 回目:     84,877 ns (0.085 ms)
     2 回目:     71,880 ns (0.072 ms)
     3 回目:     69,210 ns (0.069 ms)
    10 回目:     64,634 ns (0.065 ms)
   100 回目:     19,336 ns (0.019 ms)
 1,000 回目:     20,071 ns (0.020 ms)
 5,000 回目:      6,533 ns (0.007 ms)
10,000 回目:      6,379 ns (0.006 ms)
check = 38930000

1回目は約85,000ナノ秒、1万回目は約6,400ナノ秒。まったく同じ処理なのに、13倍ほどの差があります。

理由は、Java の実行の仕組みにあります。Java のプログラムは、最初は命令を1つずつ読み解きながら実行され、何度も呼ばれるメソッドは実行中に機械語へ変換されて速くなります。この変換を JIT コンパイル（Just-In-Time コンパイル）と呼びます。回数を重ねるほど速くなるのは、この最適化が段階的に進むためです。

JIT コンパイルを止めるオプション -Xint を付けて同じプログラムを動かすと、違いがよく分かります。

java -Xint Warmup.java

     1 回目:    505,368 ns (0.505 ms)
     2 回目:    436,710 ns (0.437 ms)
     3 回目:    480,666 ns (0.481 ms)
    10 回目:    364,536 ns (0.365 ms)
   100 回目:    410,142 ns (0.410 ms)
 1,000 回目:    361,728 ns (0.362 ms)
 5,000 回目:    404,863 ns (0.405 ms)
10,000 回目:    359,792 ns (0.360 ms)
check = 38930000

JIT コンパイルなしでは、1万回目になっても36万ナノ秒前後のままです。通常の実行で1万回目が6,400ナノ秒まで短くなったのは、JIT コンパイルのおかげだと確かめられます。

この性質から、次の2つが言えます。

• 速さを比べたいときは、本番の計測の前に同じ処理を十分な回数だけ動かしておく。 これをウォームアップと呼びます。
• 起動直後の1回だけ実行される処理（バッチの初期化など）を知りたいときは、1回目の値こそが知りたい値。 目的によって見るべき数字が変わります。

複数回測って平均と中央値を出す

ウォームアップをしてから複数回測り、平均・中央値・最小・95%点・最大を出すコードです。ウォームアップなしの場合と並べて表示します。

import java.util.Arrays;

public class Stats {
    static int work() {
        StringBuilder sb = new StringBuilder();
        for (int i = 1; i <= 1000; i++) {
            sb.append(i).append(',');
        }
        return sb.length();
    }

    /** ウォームアップしてから複数回測り、ナノ秒の配列を返す */
    static long[] measure(Runnable task, int warmup, int runs) {
        for (int i = 0; i < warmup; i++) task.run();   // 結果は捨てる
        long[] nanos = new long[runs];
        for (int i = 0; i < runs; i++) {
            long s = System.nanoTime();
            task.run();
            nanos[i] = System.nanoTime() - s;
        }
        return nanos;
    }

    static void report(String label, long[] nanos) {
        long[] sorted = nanos.clone();
        Arrays.sort(sorted);
        int n = sorted.length;
        double avg = Arrays.stream(sorted).average().orElse(0);
        double median = (n % 2 == 1) ? sorted[n / 2] : (sorted[n / 2 - 1] + sorted[n / 2]) / 2.0;
        long p95 = sorted[(int) Math.ceil(n * 0.95) - 1];
        System.out.printf("%-16s 平均 %,9.0f ns / 中央値 %,9.0f ns / 最小 %,7d ns / 95%%点 %,7d ns / 最大 %,9d ns%n",
                label, avg, median, sorted[0], p95, sorted[n - 1]);
    }

    static long sink;   // 結果を使うことで、処理が省かれないようにする

    public static void main(String[] args) {
        Runnable task = () -> sink += work();
        report("ウォームアップなし", measure(task, 0, 1000));
        report("ウォームアップあり", measure(task, 20_000, 1000));
        System.out.println("sink = " + sink);
    }
}

ウォームアップなし        平均   158,350 ns / 中央値    28,260 ns / 最小  24,081 ns / 95%点  79,009 ns / 最大 16,182,186 ns
ウォームアップあり        平均     6,489 ns / 中央値     6,095 ns / 最小   5,351 ns / 95%点   8,558 ns / 最大    53,750 ns
sink = 85646000

読み取れることを表にまとめます。

ウォームアップなしでは、平均（約158,000 ns）が中央値（約28,000 ns）の5倍以上になっています。1,000回のうち数回だけ、16ミリ秒のような飛び抜けて長い回があり、平均がそれに引っ張られたためです。平均と中央値が大きく離れているときは、外れ値があるサインです。ウォームアップありでは平均と中央値がほぼ同じ値になり、安定して測れていることが分かります。

結果を使って、処理が省かれないようにする

コードの中の sink += work() にも意味があります。JIT コンパイラは、結果がどこにも使われない計算を「不要」と判断して省くことがあります。そうなると、何もしていない時間を測ることになります。計測する処理の戻り値は、合計に足す・フィールドに入れるなどして必ず使うようにします。最後に sink を表示しているのも、そのためです。

計測に表示処理を含めない｜println の影響

もう1つ、数字が大きく変わる原因が、計測範囲の中の System.out.println です。

public class PrintCost {
    public static void main(String[] args) {
        int n = 10_000;
        long sum = 0;

        // A) ループの中で println する（表示の時間も含まれる）
        long s1 = System.nanoTime();
        for (int i = 0; i < n; i++) {
            sum += i;
            System.out.println(i);
        }
        long withPrint = System.nanoTime() - s1;

        // B) 計算だけを測り、表示は計測の外で行う
        long s2 = System.nanoTime();
        for (int i = 0; i < n; i++) {
            sum += i;
        }
        long withoutPrint = System.nanoTime() - s2;

        System.err.printf("println あり: %.3f ms%n", withPrint / 1_000_000.0);
        System.err.printf("println なし: %.3f ms%n", withoutPrint / 1_000_000.0);
        System.err.println("sum = " + sum);
    }
}

java PrintCost.java > /dev/null で実行した結果です（1万行の表示は捨て、結果だけを標準エラーに出しています）。

println あり: 142.927 ms
println なし: 0.101 ms
sum = 99990000

同じ足し算でも、println を含めると約143ミリ秒、含めないと約0.1ミリ秒でした。println を計測範囲に入れると、測っているのはほぼ「表示にかかる時間」になります。 表示やログ出力、データの準備は、計測の外に出しましょう。

手計測でつまずきやすい点のチェックリスト

JMH の最小構成と、手計測との使い分け

ここまでの注意点（ウォームアップ、複数回の計測、結果を使う、統計を出す）を自動で面倒みてくれるのが、OpenJDK が提供するベンチマーク用ツール JMH（Java Microbenchmark Harness） です。この章の内容は、JMH の公式リポジトリ（github.com/openjdk/jmh）の README と公式サンプルに書かれている手順です。

プロジェクトの作り方（公式 README の手順）

公式 README は、Maven で独立したベンチマーク用プロジェクトを作る方法を推奨しています。IDE からの実行は、環境が制御されにくいので一般には推奨しない、とも書かれています。

# 1) ひな形を作る
mvn archetype:generate \
  -DinteractiveMode=false \
  -DarchetypeGroupId=org.openjdk.jmh \
  -DarchetypeArtifactId=jmh-java-benchmark-archetype \
  -DgroupId=org.sample \
  -DartifactId=test \
  -Dversion=1.0

# 2) ビルドする
cd test
mvn clean verify

# 3) 実行する
java -jar target/benchmarks.jar

ベンチマークの書き方（公式サンプルの形）

公式サンプルの1番目（JMHSample_01_HelloWorld）は、次の形です。測りたいメソッドに @Benchmark を付けると、JMH がそのメソッドをできるだけ正確に測るためのコードを生成します。

package org.openjdk.jmh.samples;

import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;

public class JMHSample_01_HelloWorld {

    @Benchmark
    public void wellHelloThere() {
        // this method was intentionally left blank.
    }

    public static void main(String[] args) throws RunnerException {
        Options opt = new OptionsBuilder()
                .include(JMHSample_01_HelloWorld.class.getSimpleName())
                .forks(1)
                .build();

        new Runner(opt).run();
    }
}

公式サンプルで使われている主なアノテーションは次のとおりです。

公式サンプルの8番目（JMHSample_08_DeadCode）では、「計算結果を使わないメソッドは、コンパイラに計算を省かれてしまう。結果を return すれば正しく測れる」ことが示されています。前の章で sink に足し込んだのと同じ考え方で、JMH では戻り値として返すだけで済みます。

手計測と JMH の使い分け

まず手計測で遅い箇所を見つけ、細かい書き方の差を比べたくなったら JMH へ進む、という順番が進めやすいです。データベースへの問い合わせやファイルの読み書きのように数ミリ秒以上かかる処理なら、この記事の Timer と Stats の形で十分に傾向をつかめます。

よくある質問

Q. nanoTime と currentTimeMillis、処理時間の計測にはどちらを使えばよいですか？ A. nanoTime です。経過時間を測るための時計で、システム時刻の変更に影響されず、1ミリ秒より短い時間も測れます。currentTimeMillis は「いま何時か」を数値で得るメソッドなので、タイムスタンプの記録に使います。

Q. Instant と Duration で測っても問題ありませんか？ A. 動きますし、開始日時を一緒に残せるのが利点です。ただし Instant.now() はシステムの UTC 時計を読むので、計測中に時刻が調整されると差に影響します。所要時間だけがほしいなら nanoTime、日時も残したいなら「開始日時は Instant、所要時間は nanoTime」と分けるのがおすすめです。

Q. 測るたびに値が変わります。どれを信じればよいですか？ A. 1回の値ではなく、ウォームアップ後に数十回〜数千回測った中央値を見てください。JIT コンパイル、GC、同じマシンで動くほかのプログラムの影響で、値は毎回変わります。平均と中央値が近ければ、安定して測れています。

Q. ウォームアップは何回くらい必要ですか？ A. 処理の内容によります。この記事の例では、100回目あたりで1段階、5,000回目までにもう1段階短くなりました。回数ごとの値を一度出力して、値が落ち着いたところを確かめるのが確実です。

まとめ

• 処理時間の計測は System.nanoTime() の差が基本。 経過時間専用の時計で、時刻変更の影響を受けない
• currentTimeMillis と Instant.now() は「いま何時か」の時計。 開始日時の記録に使う
• Timer ユーティリティにまとめると、Runnable を渡す形と try-with-resources の形で1行で測れる
• 同じ処理でも1回目は約85,000 ns、1万回目は約6,400 ns。 JIT コンパイルで速くなるので、比べるときはウォームアップしてから測る
• 複数回測って中央値を見る。 平均と中央値が離れていたら外れ値がある
• toMillis() は切り捨て。 短い処理は nanos / 1_000_000.0 で小数表示にする
• println やデータ準備は計測の外へ。 細かい比較は JMH に任せる

参考・出典

• Java SE 21 API ドキュメント：System（nanoTime / currentTimeMillis）、Instant（docs.oracle.com）
• JMH 公式リポジトリ：README、jmh-samples（github.com/openjdk/jmh）

株式会社RJC ― SI事業・SES事業・AI駆動開発。RJCは一緒に成長を楽しめる会社です。