とあるJavaアプリケーションでの出来事。
リリース版のアプリケーションが遅い。
調査の結果、ループの内側でDEBUGレベルのログをファイルに出力していたので、ループ回数が多くなればなるほど遅くなる実装であった。
ロガーは自前で、propertiesファイルにログ出力レベル(INFOなのかDEBUGなのかとか)を指定することで、ログファイルに出力するようにしていた。
リリース版のアプリケーションでは、デバッグ出力したくないので、DEBUGをfalseにしていたので、直ぐに遅い原因を突き止められなかった。
解決策の検討
実装レベルの解決策
”java 条件付きコンパイル”とかで、ググったらそれらしいのがあった。
ロガーにもう一工夫欲しい。普段の実行ではデバッグ出力は不要。デバッグするときだけ、動いてほしい。
設計レベルの解決策→経験で解決！？
ログファイルに出力されないから、動いていないと思い込んでいたが、実際にはファイルに出ていないだけで、処理は動いていたということ。
ログ出力レベルを外部ファイルから制御できるので、安易にデバッグ出力していたかも。
確かに、リリース版ではデバッグ出力されていないので、「仕様通りに動いている」けれど、「単に動けばいい」というわけではない。
こういった所への配慮が設計時にできることが重要。この辺の勘所は経験しないと身につかないものなのだろうか？工学的なアプローチがあるなら知りたい・・・。
実装による解決策：動いてほしいときだけ動かす
ググると、if文と定数値の組み合わる案とassertを使う案の2案がありそうです。
①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は発生しない。
// ポイント１：実行時に実行すべきか／そうでないか選択したい式を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>]
ソースと実行イメージ
ソース
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.