【Java】System.out.printlnを複数回呼び出した場合、AtCoderでTLEになってしまうので実際に実行時間を計測してみた

　AtCoderにて、System.out.printlnを複数回呼び出すと、AtCoder228_CやAtCoder231_Cのように最悪$10^5$行くらいの文字列を出力する場合、TLEになる場合がありました。
　標準出力の複数回呼び出しによるオーバーヘッドの時間がかかりTLEになったものだと思います。本記事では同じ長さの文字列について、System.out.printlnを複数回呼び出して標準出力した場合の時間と、一度に標準出力した場合の時間を実際に比較しようと思います。
　計測するコードの実装内容は$0～10^5$をインクリメントした文字列を改行して出力する処理です。この処理を100回繰り返して各実行毎の実行時間を取得します。$10^5$にした理由はAtCoderで出力する行数として、よく見かけるからです。
　計測する手法は以下の三パターンです。

• 手法-1 System.out.printlnの複数回呼び出して出力する。
• 手法-2 StringBuilderにより文字を連結させてから一度に出力する。
• 手法-3 PrintWriterオブジェクトを利用し、フラッシュ(標準出力)されるのを1回にする。

手法-1 System.out.printlnの複数回呼び出し

　単純にSystem.out.printlnを複数回呼び出します。計測に利用するコードは以下のものです。

System.out.printlnの複数回呼び出しのサンプルコード

public class PrintTest1 {

	public static void main(String[] args) throws IOException {

		// 出力する時刻を格納するリスト
		List<String> results = new ArrayList<String>();
		System.out.println("計算開始");
		for (int i = 0; i < 100; i++) {
			// 開始時刻の取得(ミリ秒)
			long startTime = System.currentTimeMillis();
			// 計算
			caliculate();
			// 計算時刻の格納
			results.add(String.valueOf(System.currentTimeMillis() - startTime));

			try {
				//1秒待機する
				Thread.sleep(1000);
			} catch (InterruptedException e) {
			}
		}

		// 結果の出力
		Files.write(Paths.get("output1.log"), results);
		System.out.println("計算終了");

	}

	/**
	 * System.out.printlnを用いて0～10^5の数字を標準出力する
	 */
	public static void caliculate() {
		for (int i = 0; i <= 100000; i++) {
			System.out.println(i);
		}
	}
}

手法-2 StringBuilderによる文字連結

　StringBuilderによって文字を連結させた後、一度にSystem.out.printlnで出力します。計測に利用するコードは以下のものです。

StringBuilderによる文字連結した場合のサンプルコード

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Paths;
import java.util.ArrayList;
import java.util.List;

public class PrintTest2 {

	public static void main(String[] args) throws IOException {

		// 出力する時刻を格納するリスト
		List<String> results = new ArrayList<String>();
		System.out.println("計算開始");
		for (int i = 0; i < 100; i++) {
			// 開始時刻の取得(ミリ秒)
			long startTime = System.currentTimeMillis();
			// 計算
			caliculate();
			// 計算時刻の格納
			results.add(String.valueOf(System.currentTimeMillis() - startTime));

			try {
				//1秒待機する
				Thread.sleep(1000);
			} catch (InterruptedException e) {
			}
		}

		// 結果の出力
		Files.write(Paths.get("output2.log"), results);
		System.out.println("計算終了");

	}

	/**
	 * StringBuilderを用いて0～10^5の数字を標準出力する
	 */
	public static void caliculate() {
		StringBuilder sb = new StringBuilder();
		for (int i = 0; i <= 100000; i++) {
			sb.append(i).append('\r').append('\n');
		}
		System.out.print(sb.toString());
	}

}

手法-3 PrintWriterを利用する

　PrintWriterオブジェクトを利用して、flushメソッドによりフラッシュ(標準出力)されるタイミングを調整する。計測に利用するコードは以下のものです。

PrintWriterを利用した場合のサンプルコード

import java.io.IOException;
import java.io.PrintWriter;
import java.nio.file.Files;
import java.nio.file.Paths;
import java.util.ArrayList;
import java.util.List;

public class PrintTest3 {

	public static void main(String[] args) throws IOException {

		// 出力する時刻を格納するリスト
		List<String> results = new ArrayList<String>();
		System.out.println("計算開始");
		for (int i = 0; i < 100; i++) {
			// 開始時刻の取得(ミリ秒)
			long startTime = System.currentTimeMillis();
			// 計算
			caliculate();
			// 計算時刻の格納
			results.add(String.valueOf(System.currentTimeMillis() - startTime));

			try {
				//1秒待機する
				Thread.sleep(1000);
			} catch (InterruptedException e) {
			}
		}

		// 結果の出力
		Files.write(Paths.get("output3.log"), results);
		System.out.println("計算終了");

	}

	/**
	 * PrintWriterとflushメソッドを用いて0～10^5の数字を標準出力する
	 */
	public static void caliculate() {
		PrintWriter pw = new PrintWriter(System.out);
		for (int i = 0; i <= 100000; i++) {
			pw.println(i);
		}
		pw.flush();
	}
}

計測結果と考察

　open-jdk-11.0.2で実行しました。実行結果の分布の箱ひげ図は以下のものになりました。

　また、実行結果の平均値・中央値・最大値・最小値・95%の信頼区間と99%の信頼区間は以下のものです。

(単位：ミリ秒)	手法1-System.out.println複数	手法2-StringBuilder	手法3-PrintWriter
平均値	563.51	208	246.13
中央値	573.5	192	250.5
最大値	864	354	374
最小値	448	94	135
標準偏差	62.4157606	75.35840291	61.73168644
95%信頼区間	12.38464102	14.95274205	12.24890587
95%信頼区間の最大値	575.894641	222.952742	258.3789059
95%信頼区間の最小値	551.125359	193.047258	233.8810941
99%信頼区間	16.39290943	19.79217207	16.21324382
99%信頼区間の最大値	579.9029094	227.7921721	262.3432438
99%信頼区間の最小値	547.1170906	188.2078279	229.9167562

　計測した環境ではSystem.out.printlnを複数呼び出した場合、他の手法と比較して約2倍以上かかってしまいました。最大でも800ミリ秒かかってしまうのでAtCoderの実行時間制限が2secの場合、致命傷になってしまいそうですね。System.out.printlnを複数回呼び出すのは避けた方がいいでしょう。

付録

実際に計測した生データが以下のものです。

手法1-System.out.println複数	手法2-StringBuilder	手法3-PrintWriter
572	141	154
595	99	141
558	94	135
567	100	144
589	99	143
603	102	152
583	109	164
578	108	169
550	114	152
552	110	172
586	128	140
597	120	143
566	117	165
864	118	162
583	119	163
594	122	160
480	124	178
487	124	169
463	128	174
487	132	175
472	135	174
503	140	191
475	133	192
480	147	197
713	138	197
477	143	206
474	147	191
505	146	194
448	160	201
488	150	213
471	155	202
539	342	205
561	160	205
613	156	216
584	154	215
592	166	208
590	167	228
507	164	218
668	160	232
620	164	235
598	171	227
593	168	240
641	170	234
649	179	229
610	180	242
606	182	257
631	186	249
642	180	248
626	180	236
605	190	251
566	186	244
467	194	270
466	195	270
478	194	258
493	198	269
573	205	250
588	204	258
583	197	260
576	197	269
572	258	290
512	206	273
543	282	265
545	244	269
563	248	274
584	257	272
586	271	277
583	288	282
580	284	292
597	270	299
605	275	278
556	294	290
582	280	291
597	280	290
545	290	281
574	291	295
629	293	292
604	291	313
620	298	295
504	234	299
455	234	300
485	241	316
549	238	313
504	248	324
591	242	307
627	308	313
539	247	314
558	284	307
524	304	316
547	301	348
621	328	334
593	317	335
596	321	315
539	325	321
604	336	325
548	315	319
606	325	343
547	326	374
616	339	338
518	354	348
478	342	350