i-Vinci TechBlog
株式会社i-Vinciの技術ブログ

処理速度を計測してみた

こんにちは！入社n年目のApple信者、TOMOです。

AWSのEC2インスタンスにMacが選択可能なことを知り、しかもデータセンターのサーバーラックにMac miniをそのまま内蔵して実現していることに驚きを隠せません。
もしかしてiOSアプリ開発のためにMac買う必要ない...？
参考: AWS、Macインスタンスの仕組みを説明。市販のMac miniをそのままラックに組み込みThunderbolt経由でストレージやネットワークへ接続。AWS re:Invent 2020

普段私は業務アプリ開発に従事しているのですが、ふと「このコードってどのくらいの速度で動作しているんだろう」と思うことがあります。
もちろん相当速いことはわかるのですが、具体的な速度は想像つきません。

じゃあ検証してみよう

残念ながら処理速度について深い知識は持ち合わせていないので、いつも書いている業務アプリのコードがどのくらいの速さで動いているのか？に着目して検証してみたいと思います。過度なツッコミはご遠慮ください

検証環境 1

  • Core i7-14700KF、メモリ 64GB
  • Windows 11 Pro 23H2
  • openjdk 21.0.3 2024-04-16 LTS
  • 手持ちのPCで一番強いやつ

まずは結論

  • 処理の内容によって処理時間は変わります。（身も蓋もない）
  • おおよそ1秒間に6250行（ステップ）の業務処理を実行できそう。

検証 1

まずは簡単な例から。

public class Step1 {
    public static void main(String[] args) {
        System.out.println("処理開始");
        long startMs = System.currentTimeMillis();

        int result = 0;
        for (int i = 0; i < 100000000; i++) {
            result += 1;
        }
        System.out.println("result: " + result);

        long endMs = System.currentTimeMillis();
        System.out.println("処理終了");
        System.out.println("処理時間は" + (endMs - startMs) + "ミリ秒");
    }
}
処理開始
result: 100000000
処理終了
処理時間は2ミリ秒

結果は2ミリ秒でした。
超　速　い　・　・　・

簡単な加算（+代入）処理を1億回ループしています。1ループの処理は

  • i < 100000000 の評価
  • result += 1;
  • i++

の3行だと考えると、1億回ループしているので全部の処理で約3億行。
3億行の処理を2ミリ秒で終わらせてしましいました・・・
まぁでもこんな処理、業務コードに書きませんね

検証 2

ちょっと条件分岐もある例をということで、下位パイセンのナベアツネタコードをパクッリスペクトして

public class Step2 {
    public static void main(String[] args) {
        System.out.println("処理開始");
        long startMs = System.currentTimeMillis();

        for (int i = 1; i <= 30; i++) {
            if (IsMetamorphoseOjyohin(i)) {
                System.out.print(String.format("★%d★,", i));
            } else {
                System.out.print(String.format("%d,", i));
            }
        }
        System.out.println();

        long endMs = System.currentTimeMillis();
        System.out.println("処理終了");
        System.out.println("処理時間は" + (endMs - startMs) + "ミリ秒");
    }

    private static boolean IsMetamorphoseOjyohin(int num) {
        if (num % 3 == 0)
            return true;
        return Integer.toString(num).contains("3");
    }
}
処理開始
1,2,★3★,4,5,★6★,7,8,★9★,10,11,★12★,★13★,14,★15★,16,17,★18★,19,20,★21★,22,★23★,★24★,25,26,★27★,28,29,★30★,
処理終了
処理時間は8ミリ秒

結果は8ミリ秒でした。
こちらはループ数は少ない（30回）ですが、検証1より時間がかかっています。
1ループの処理を見ていくと、

  • i <= 30
  • if (IsMetamorphoseOjyohin(i)) {
  • if (num % 3 == 0)
  • return true;
    • または return Integer.toString(num).contains("3");
  • System.out.print(String.format("★%d★,", i));
    • または System.out.print(String.format("%d,", i));
  • i++

の6行といったところでしょうか。
6行を30回ループしているので、約180行を8ミリ秒で処理したことになります。
今回はString.formatやcontainsなど、内部処理が重そうな関数を使用しているため、検証1より時間がかかったのではないかと思います。

検証 3

今度は、なんとなく重いイメージのある処理3種を1000回ずつ実行してみて、処理時間を確認してみました。

  • なんとなく重いイメージのある処理
    • 検索処理(list.indexOf)
    • 並べ替え処理(Collections.sort)
    • ファイル出力(PrintWriter)

検索処理(list.indexOf)

import java.util.ArrayList;
import java.util.Random;

public class Step3 {
    public static void main(String[] args) {
        // 準備は計測から除外
        Random random = new Random();
        ArrayList<String> list = new ArrayList<>();
        for (int i = 0; i < 1000; i++) {
            list.add(Integer.toString(random.nextInt(1000)));
        }

        System.out.println("処理開始");
        long startMs = System.currentTimeMillis();

        int hitCount = 0;
        for (int i = 0; i < 1000; i++) {
            if (list.indexOf(Integer.toString(i)) >= 0) {
                hitCount++;
            }
        }
        System.out.println("検索ヒット件数: " + hitCount);

        long endMs = System.currentTimeMillis();
        System.out.println("処理終了");
        System.out.println("処理時間は" + (endMs - startMs) + "ミリ秒");
    }
}
処理開始
検索ヒット件数: 631
処理終了
処理時間は4ミリ秒

並べ替え処理(Collections.sort)

import java.util.ArrayList;
import java.util.Collections;
import java.util.Random;

public class Step4 {
    public static void main(String[] args) {

        System.out.println("処理開始");
        long processNs = 0;

        for (int i = 0; i < 1000; i++) {

            Random random = new Random();
            ArrayList<String> list = new ArrayList<>();
            for (int j = 0; j < 1000; j++) {
                list.add(Integer.toString(random.nextInt(1000)));
            }

            long startNs = System.nanoTime();
            Collections.sort(list);
            long endNs = System.nanoTime();
            processNs += endNs - startNs;
        }

        System.out.println("処理終了");
        System.out.println("処理時間は" + processNs / 1000 / 1000 + "ミリ秒");
    }
}
処理開始
処理終了
処理時間は139ミリ秒

ファイル出力(PrintWriter)

import java.io.BufferedWriter;
import java.io.IOException;
import java.io.PrintWriter;
import java.nio.charset.StandardCharsets;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;

public class Step5 {
    public static void main(String[] args) throws IOException {
        System.out.println("処理開始");
        long startMs = System.currentTimeMillis();

        Path path = Paths.get(new java.io.File(".").getCanonicalPath(), "output.txt");
        try (
                BufferedWriter bw = Files.newBufferedWriter(path, StandardCharsets.UTF_8);
                PrintWriter pw = new PrintWriter(bw);
        ) {
            for (int i = 0; i < 1000; i++) {
                pw.println(String.format("i: %d", i));
            }
        } catch (IOException e) {
            e.printStackTrace();
        }

        long endMs = System.currentTimeMillis();
        System.out.println("処理終了");
        System.out.println("処理時間は" + (endMs - startMs) + "ミリ秒");
    }
}
処理開始
処理終了
処理時間は13ミリ秒

結果は以下の通りです。

  • 検索処理(list.indexOf)
    • 4ミリ秒
  • 並べ替え処理(Collections.sort)
    • 139ミリ秒
  • ファイル出力(PrintWriter)
    • 13ミリ秒

処理の内容によって、処理時間はまったく異なるということが分かりました。
並べ替えは特に時間がかかる処理のようですね。

ここまでの検証で、業務コード中の1行でも、その処理の内容によって処理時間が変わってくることが分かりました。
（呼び出す関数の内部実装によるので、当たり前といえば当たり前ですね）

「このコードってどのくらいの速度で動作しているんだろう」の結論としては、「処理による」が見え隠れしてきてしまっています。次は何の検証をしようか・・・。

検証 4

検証1～3の処理を混ぜて業務処理に近いコードとし、処理時間を計測してみます。
その時間をもとに、1秒間でどれくらいの行数を処理できるかも出してみようと思います。

  1. ナベアツ処理：ナベアツ結果リストを取得（30行分）
  2. 検索処理：ナベアツ結果リストを検索し、お上品ではない件数を取得
  3. 並べ替え処理：ナベアツ結果リストを並べ替え
  4. ファイル出力：ナベアツ結果リストをファイルに出力
import java.io.BufferedWriter;
import java.io.IOException;
import java.io.PrintWriter;
import java.nio.charset.StandardCharsets;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.ArrayList;
import java.util.Collections;

public class Step6 {
    public static void main(String[] args) throws IOException {
        System.out.println("処理開始");
        long startMs = System.currentTimeMillis();

        ArrayList<String> nabeList = new ArrayList<>();

        // ナベアツ処理
        for (int i = 1; i <= 30; i++) {
            if (IsMetamorphoseOjyohin(i)) {
                nabeList.add(String.format("★%d★", i));
            } else {
                nabeList.add(String.format("%d", i));
            }
        }

        // 検索処理
        int notOjyohinCount = 0;
        for (int i = 1; i <= 30; i++) {
            if (nabeList.indexOf(Integer.toString(i)) >= 0) {
                notOjyohinCount++;
            }
        }
        System.out.println("お上品ではない件数: " + notOjyohinCount);

        // 並べ替え処理
        Collections.sort(nabeList);

        // ファイル出力
        Path path = Paths.get(new java.io.File(".").getCanonicalPath(), "output.txt");
        try (
                BufferedWriter bw = Files.newBufferedWriter(path, StandardCharsets.UTF_8);
                PrintWriter pw = new PrintWriter(bw);) {
            for (String line : nabeList) {
                pw.println(line);
            }
        } catch (IOException e) {
            e.printStackTrace();
        }

        long endMs = System.currentTimeMillis();
        System.out.println("処理終了");
        System.out.println("処理時間は" + (endMs - startMs) + "ミリ秒");
    }

    private static boolean IsMetamorphoseOjyohin(int num) {
        if (num % 3 == 0)
            return true;
        return Integer.toString(num).contains("3");
    }
}
処理開始
お上品ではない件数: 18
処理終了
処理時間は8ミリ秒

結果は8ミリ秒でした。
また、本処理はステップカウンタで実行50行でした。（※検証1～3の行数カウント方法とは異なります）

8msで50行処理できたので、
同様の処理を1秒間(1000ms)動かすとおおよそ6250行の処理が実行できることなります。

結論

  • 処理の内容によって処理時間は変わる
  • 並べ替え処理は時間がかかる
  • 今回の検証では、1秒間におおよそ6250行（ステップ）の業務処理を実行できる

あとがき

お読み頂きありがとうございました。
今回は、1番処理（待ち）時間が発生するであろう外部との通信処理は行いませんでしたが、
内部処理だけだとかなりの速度で処理が流れていることが実感できました。

皆さんもコードを書くとき、
「6250ステップ書いたからこれが1秒くらいで実行されるのか～」
などと妄想しながら書いてみると、今までよりちょっとだけ楽しみながらコードを書くことができるかもしれません。

最新記事