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

　AtCoderにて、System.out.printlnを複数回呼び出すと、[AtCoder228_C](https://atcoder.jp/contests/abc228/tasks/abc228_c)や[AtCoder231_C](https://atcoder.jp/contests/abc231/tasks/abc231_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を複数回呼び出します。計測に利用するコードは以下のものです。
```Java: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で出力します。計測に利用するコードは以下のものです。

```Java: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メソッドによりフラッシュ(標準出力)されるタイミングを調整する。計測に利用するコードは以下のものです。

```Java: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で実行しました。実行結果の分布の箱ひげ図は以下のものになりました。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/846337/56ddd5b2-286f-ff54-7591-27c079a879fa.png)
　また、実行結果の平均値・中央値・最大値・最小値・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|