地道に解決していくためのパフォーマンスチューニング講座　Vol.2　～I/Oと通信の改善～

データを持ってくるだけでなんでこんなに時間かかるの？

システムツー・ワンのテクニカルシステムエンジニアの「じょん（日本人）」です。前回に引き続きパフォーマンスチューニングのお話です。全5回のつもりで書いていますが、恐らく他の回に比べてもあからさまに実行時間が短くなる内容です。

そんな本稿、パフォーマンスチューニング講座第2回のテーマは「I/Oと通信の改善」。

ちょっと復習

---

パフォーマンスに影響する機器にはこんなのがありました。

データを不揮発性メモリに保存するのであれば補助記憶装置の読み書き（I/O）が発生し、サーバーなどの外部装置とのやり取りを行うのであれば通信が発生する。

I/Oとは

---

一般に補助記憶装置や外部記憶装置への読み書き、入出力装置とのやり取りを指す。演算に比べるとかなり時間のかかる処理である。

I/Oの実行時間の内訳

---

細かい処理は置いといて、ざっくり描くとこんな感じ。

実際にI/Oを行う際には、オーバーヘッドと呼ばれる実際の読み書き以外の前後の時間が発生する。同じ量、例えば1GBのデータを読み書きしようとしても、1GBを1回で読み書きするのと、1GBを100MBずつ10回に分けて読み書きするのでは、1回で読み書きする方が速くなる。つまり、I/Oの回数は抑えるべきである。

※少ない回数で読み書きすると1回の時間が長くなるため、途中で止まったときのリスクが大きいというデメリットもある。が、今回はパフォーマンスチューニングなので総合して速くなる方を選択する。

また、読み書きの時間はお察し？の通りデータ量に左右される。データ量はなるべくなるべく削減するべきである。I/Oは遅いため、演算が少し増えるくらいで済むのであればデータ量の削減を優先した方が良い場合も多い。

※演算がかなり複雑です、という場合には演算の結果を保存しておくためにI/Oが発生するのもやむなしである。

I/Oの改善をしてみよう

---

下記はtest1.csvファイル、test2.csvファイルからデータを読み込み、test3.csvファイルに書き出すというコードである。

public static void main(String[] args) {
	System.out.println("開始");
	int max = 100;
	for (int idx = 1; idx <= max; idx++) {
		System.out.println(idx + "/" + max);
		String content = readFile("test1.csv", idx);
		writeFile("test3.csv", content);
		content = readFile("test2.csv", 3000 + idx);
		writeFile("test3.csv", content);
	}
	System.out.println("終了");
}

private static String readFile(String path, int lineNo) {
	File file = new File(path);
	try (FileReader fr = new FileReader(file);
		BufferedReader br = new BufferedReader(fr)) {
		String content = null;
		for (int idx = 0; idx < lineNo; idx++) {
			content = br.readLine();
		}
		return content;
	} catch (Exception e) {
		e.printStackTrace();
		return null;
	}
}

private static void writeFile(String path, String content) {
	File file = new File(path);
	try (FileWriter fw = new FileWriter(file, true);
		BufferedWriter bw = new BufferedWriter(fw)) {
		bw.append(content + "\n");
	} catch (Exception e) {
		e.printStackTrace();
	}
}

これに第1回で紹介したStopwatchUtilを使用してホットスポットを探す。

public static void main(String[] args) {
	System.out.println("開始");

	StopwatchUtil.start(1);
	int max = 10000;
	for (int idx = 1; idx <= max; idx++) {
		StopwatchUtil.start(2);
		System.out.println(idx + "/" + max);
		StopwatchUtil.stop(2);
		StopwatchUtil.start(3);
		String content = readFile("test1.csv", idx);
		StopwatchUtil.stop(3);
		StopwatchUtil.start(4);
		writeFile("test3.csv", content);
		StopwatchUtil.stop(4);
		StopwatchUtil.start(5);
		content = readFile("test2.csv", 3000 + idx);
		StopwatchUtil.stop(5);
		StopwatchUtil.start(6);
		writeFile("test3.csv", content);
		StopwatchUtil.stop(6);
	}
	StopwatchUtil.stop(1);
	
	StopwatchUtil.showAll();
	System.out.println("終了");
}

実行すると、下記のような結果が出る。

Stopwatch[1]: 159503msec.
Stopwatch[2]: 282msec.
Stopwatch[3]: 8277msec.
Stopwatch[4]: 71247msec.
Stopwatch[5]: 9939msec.
Stopwatch[6]: 69725msec.

4と6、つまりwriteFile周りに時間がかかっている＝writeFileがホットスポットであることがわかる。
今回はデータ量の削減は出来ないものとし、読み書きの回数を減らすことを考える。今回writeFileは改行しながら文字列をファイルに追記する仕組みがとられているので、2回に分けている出力を単純に1回にまとめてしまうこととする。

StopwatchUtil.start(3);
String content = readFile("test1.csv", idx) + "\n";
StopwatchUtil.stop(3);
StopwatchUtil.start(5);
content += readFile("test2.csv", 3000 + idx);
StopwatchUtil.stop(5);
StopwatchUtil.start(6);
writeFile("test3.csv", content);
StopwatchUtil.stop(6);

Stopwatch[3]: 8100msec.
Stopwatch[5]: 8491msec.
Stopwatch[6]: 67674msec.

先ほど3~6で合計159,188msec.であった処理が84,265msec.まで短縮された。writeFile1回分がそのまま削減されたような形である。
だが、そもそもwriteFileが毎回ファイルを開きなおしているのが問題である。writeFileを廃止し、ファイルを開くのを1回にする。

StopwatchUtil.start(7);
File file = new File("test3.csv");
try (FileWriter fw = new FileWriter(file, true);
	BufferedWriter bw = new BufferedWriter(fw)) {
	StopwatchUtil.stop(7);

	for (int idx = 1; idx <= max; idx++) {
		StopwatchUtil.start(2);
		System.out.println(idx + "/" + max);
		StopwatchUtil.stop(2);
		StopwatchUtil.start(3);
		String content = readFile("test1.csv", idx) + "\n";
		StopwatchUtil.stop(3);
		StopwatchUtil.start(5);
		content += readFile("test2.csv", 3000 + idx);
		StopwatchUtil.stop(5);
		StopwatchUtil.start(6);
		bw.append(content + "\n");
		StopwatchUtil.stop(6);
	}

	StopwatchUtil.start(8);
} catch (Exception e) {
	e.printStackTrace();
}
StopwatchUtil.stop(8);

Stopwatch[6]: 19msec.
Stopwatch[7]: 2msec.
Stopwatch[8]: 10msec.

先ほど6に67,674msec.掛かっていた処理が、6~8を合わせても31msec.となった。劇的な変化である。
これは共通化する際にやりがちなミスである。最初から分かっていればもう少し綺麗なコードにしやすいが、後から直そうとすると考えづらくなってしまう。

readFileも改善することはできるが、同じことの繰り返しになるため今回は省略する。手元で実行した結果としては、合計約2.7分かかっていた処理が約2秒となった。とにかく読み書きの回数は極力削減するべきである。

通信とは

---

一般には他演算装置（他のPCとかサーバーとか）とデータをやり取りする処理を指すが、同一演算装置内のプロセス間のやり取りを指すこともある。パフォーマンスチューニングの観点で注意すべきことはあまり変わらないため、今回は同一視する。

通信の実行時間の内訳

---

細かい処理は置いといて、ざっくり描くとこんな感じ。

処理の実体は違うとは思うが、パフォーマンスチューニングの観点において、I/Oとほぼ変わることは無い。（強いて言うのであれば、こちらがクライアントなのかサーバーなのかの違いはあるかもしれないが。）

通信の改善をしてみよう

---

下記はphpが配置されたウェブサーバー経由でDBにアクセスし、取得した名称を出力するコードである。http://○○/test.phpにPOSTでSQL文を送ると、そのSQLでDBにアクセスした結果が返ってきて、TestDataというオブジェクトの配列に変換されて取得される。取得したデータの内有効なもの（enableが0でないもの）の名称を出力している。また、全件ではなくidが1～29のものを出力するためにidでの絞り込みを行う。

public class Main {

	public static void main(String[] args) {
        try {
            HttpClient client = HttpClient.newHttpClient();
            ObjectMapper objectMapper = new ObjectMapper();
            
            for (int id = 1; id < 30; id++) {
                HttpRequest request = HttpRequest
                		.newBuilder(URI.create("http://○○/test.php"))
                		.header("Content-Type","application/x-www-form-urlencoded")
                		.POST(HttpRequest.BodyPublishers.ofString("sql=select * from Test where id = " + id + " order by id;"))
                		.build();
    			var res = client.send(request, HttpResponse.BodyHandlers.ofString());
    			TestData[] dataArr = objectMapper.readValue(res.body(), TestData[].class);
    			for (TestData data : dataArr) {
    				if (data.enable != 0) {
    					System.out.println(data.id + ": " + data.name);
    				}
    			}
            }
		} catch (IOException e) {
			e.printStackTrace();
		} catch (InterruptedException e) {
			e.printStackTrace();
		}
	}
	

}

class TestData {
	public int id; // 連番
	public String name;
	public String thumbnail; // 画像のバイナリデータを文字列で
	public int enable; // 0がFalse
}

これのホットスポットは実際に通信する部分とそれを解析する部分なので、client.send()とobjectMapper.readValue()の処理である。具体的には20,841msec.かかっている。まずはI/Oのときと同様回数を減らすことにする。
idに1つずつ値を入れているが、まとめて取得する方式にする。

HttpRequest request = HttpRequest
		.newBuilder(URI.create("http://○○/test.php"))
		.header("Content-Type","application/x-www-form-urlencoded")
		.POST(HttpRequest.BodyPublishers.ofString("sql=select * from Test where id >= 1 and id < 30 order by id;"))
		.build();

この変更だけで6,103msec.となる。通信においても回数を減らすことが大切である。
次に通信のデータ量を抑える。真っ先に思いつくのはデータを取得した後にenableで有効なデータだけ処理するのではなく、そもそもenableで有効なデータだけ取得すれば良い。

HttpRequest request = HttpRequest
		.newBuilder(URI.create("http://○○/test.php"))
		.header("Content-Type","application/x-www-form-urlencoded")
		.POST(HttpRequest.BodyPublishers.ofString("sql=select * from Test where id >= 1 and id < 30 and enable <> 0 order by id;"))
		.build();

enable=0のデータの件数にもよるが、今回実施した内容では4,562msec.となった。
もう一つ減らさなければいけないデータがある。それは不必要な画像データである。画像データは他のデータに比べても大きくなりがちである。取得するデータはnameだけにする。

HttpRequest request = HttpRequest
		.newBuilder(URI.create("http://○○/test.php"))
		.header("Content-Type","application/x-www-form-urlencoded")
		.POST(HttpRequest.BodyPublishers.ofString("sql=select name from Test where id >= 1 and id < 30 and enable <> 0 order by id;"))
		.build();

これで処理時間は556msec.となった。約20秒かかっていた処理が約0.5秒となる計算である。

※この見出しは通信の話としてはいるが、DBへのアクセスも含んでおり、I/Oの影響もある。どちらも注意する事項としては似ているためあまり気にしないこととしている。

最後に

---

I/Oも通信も回数を抑える、データの量を抑えるというのが大切な点である。頭では分かっていても、意識しないと見落とし、望ましくない書き方をしてしまうことも多々ある。「あ、I/Oや通信に関するコードを書く場面だ」と思ったら本稿を思い出して欲しい。次は演算処理の実行時間の改善に触れていく予定である。