遅い、ループ内でデバッグ出力してた。デバッグ出力はデバッグするときだけにしたい。

# とあるJavaアプリケーションでの出来事。
リリース版のアプリケーションが遅い。
調査の結果、ループの内側でDEBUGレベルのログをファイルに出力していたので、ループ回数が多くなればなるほど遅くなる実装であった。
ロガーは自前で、propertiesファイルにログ出力レベル(INFOなのかDEBUGなのかとか)を指定することで、ログファイルに出力するようにしていた。
リリース版のアプリケーションでは、デバッグ出力したくないので、DEBUGをfalseにしていたので、直ぐに遅い原因を突き止められなかった。

# 解決策の検討
## 実装レベルの解決策
”java 条件付きコンパイル”とかで、ググったらそれらしいのがあった。
ロガーにもう一工夫欲しい。普段の実行ではデバッグ出力は不要。デバッグするときだけ、動いてほしい。
## 設計レベルの解決策→経験で解決！？
ログファイルに出力されないから、動いていないと思い込んでいたが、実際にはファイルに出ていないだけで、処理は動いていたということ。

ログ出力レベルを外部ファイルから制御できるので、安易にデバッグ出力していたかも。
確かに、リリース版ではデバッグ出力されていないので、「仕様通りに動いている」けれど、「単に動けばいい」というわけではない。

こういった所への配慮が設計時にできることが重要。この辺の勘所は経験しないと身につかないものなのだろうか？工学的なアプローチがあるなら知りたい・・・。

# 実装による解決策：動いてほしいときだけ動かす
ググると、if文と定数値の組み合わる案とassertを使う案の2案がありそうです。
①if文と定数値を組み合わせる案

```java:if文と定数値を組み合わせる案
static final ENABLE_LOG = true;
if(ENABLE_LOG) putDebug("HelloWorld");
```
コンパイル時に定数をfalseにすると、デバッグ出力がOFFになる。リリース版アプリケーションをビルドする都度、falseにソースを修正するのは、ソースの完全性からするとよくないので却下。
②assert案はjava実行時オプションで制御できるので、これがよさそう。
javaの実行時オプションでassertを有効にすれば、assert内の式が評価されるので、その時にデバッグ出力されるようにできる。
例えば、こんな感じの実装。ポイントは２つ。
ポイント１：実行時に実行すべきか／そうでないか選択したい式をassertで括る。
ポイント２：assertで評価する式は必ずtrueを返す。こうすることで、assertは常に成功し、java.lang.AssertionErrorは発生しない。


```java:コード断片
// ポイント１：実行時に実行すべきか／そうでないか選択したい式をassertで括る。
assert (
  new Object() {
    boolean putDebug(String m) {
      System.out.println("DEBUG:" + m);
      // ポイント２：assertで評価する式は必ずtrueを返す。こうすることで、assertは常に成功し、
      // java.lang.AssertionErrorは発生しない。
      return true;
    }
  }.putDebug(msg)
);
```

java実行時のオプション引数は次の通り。assertが有効になり、assertが評価される。
細かいオプションの意味はググってください。
``` java実行時オプション
 -ea[:<packagename>...|:<classname>]もしくは、
 -enableassertions[:<packagename>...|:<classname>]
```

# ソースと実行イメージ
## ソース
```java:HelloWorld.java
public class HelloWorld {

  public static void main(String[] args) {
    HelloWorld me = new HelloWorld();
    me.proc();
  }

  private void proc() {
    long t1 = System.nanoTime();
    System.out.println("START:" + t1);

    // 1から10までの足し算
    int n = 0;
    for(int i = 1; i <= 10; i++) {
      n += i;
      // あまり良くない実装。ループの中でデバッグ出力している。
      // もし、これが沢山のループだったら・・・。
      // でも、デバッグしたいときには出力したい。
      putDebug("count:" + n);
    }

    System.out.println("TOTAL OF 1 TO 10:" + n);
    long t2 = System.nanoTime();

    System.out.println("END  :" + t2);
    System.out.println("ELAPS:" + (t2 - t1) + "nano sec.");
  }

  /**
   * デバッグ出力。
   * @param msg デバッグ出力メッセージ。
   */
  private void putDebug(String msg) {
    assert (
      new Object() {
        boolean putDebug(String m) {
          // 遅さを実感するためにsleepを入れている
          try {
            Thread.sleep(2000);
          } catch(Exception e) {
          }
          System.out.println("DEBUG:" + m);
          return true;
        }
      }.putDebug(msg)
    );
  }
}
```

## 実行イメージ
``` 
### コンパイル
$ javac -encoding UTF-8 HelloWorld.java

### java実行時にassertオプション無しで実行。
$ java HelloWorld
START:1434821812083983
TOTAL OF 1 TO 10:55
END  :1434821812347997
ELAPS:264014nano sec.

### java実行時にassertオプション有りで実行。
$ java -ea:HelloWorld HelloWorld
START:1434715681533673
DEBUG:count:1
DEBUG:count:3
DEBUG:count:6
DEBUG:count:10
DEBUG:count:15
DEBUG:count:21
DEBUG:count:28
DEBUG:count:36
DEBUG:count:45
DEBUG:count:55
TOTAL OF 1 TO 10:55
END  :1434735713491751
ELAPS:20031958078nano sec.
```