地道に解決していくためのパフォーマンスチューニング講座 Vol.1 ～考え方と時間計測の基本～
どこから手を付けて良いのか分からない！
システムツー・ワンのテクニカルシステムエンジニアの「じょん（日本人）」です。本日は私の好きな分野、プログラムのパフォーマンスチューニングについて。大学時代（何年前だか。。。）の研究内容がこれに関わる内容で、そのころ培った知識なども交えてお話できればと思います。
そんな本稿、パフォーマンスチューニング講座第1回のテーマは「考え方と時間計測の基本」。
前置きと注意事項
本講座では主に実行時間の改善を扱う。
例示に使用するコードはJavaだが、考え方は他言語にも当てはまる内容である。
パフォーマンス改善は突き詰めれば保守性、拡張性を損ない、マシン依存性を高める。
現在のマシンはスペックが上がっているため、
簡単な動作、速度を求められない動作に関しては、保守性、拡張性を優先した方が良い場面も多い。また、汎用アプリケーションに下手なマシン依存性を持たせるべきではない。
パフォーマンス改善を行うかの判断の一つの指標として、
「人がストレスを感じ始めるのは2秒程度」と言われることがある。
パフォーマンス問題の分類
一般に、パフォーマンスに問題がある場合は、下記のようなハードウェアやソフトウェアによる影響を考える。本講座ではプログラムの書き方にのみ言及する。
ハードウェア
機器性能
通信性能
機器同士や処理との相性
ソフトウェア
使用言語
使用OS
皆の書くプログラム←本講座ではここに言及
パフォーマンスに影響する機器
ハードウェア性能に言及しないと言っても、プログラムがハードウェア上で動くものである以上、最低限知らないといけない内容はある。下記は影響する機器をざっくり記載した図である。
CPUで演算が行われるが、その際にはキャッシュや主記憶装置などとのデータのやり取りが発生する。また、データを不揮発性メモリに保存するのであれば補助記憶装置の読み書き（I/O）が発生し、サーバーなどの外部装置とのやり取りを行うのであれば通信が発生する。
着目すべき時間
実行時間は大きく2つに分類できる。演算時間と通信・I/O時間である。
演算時間
演算周りに使う時間
単純なCPU効率の他に、メモリやキャッシュメモリの使い方なども含まれる
プログラムの書き方に強く依存する
レジスタに言及した話は本講座で行う予定はない
通信・I/O時間
インターネットに代表される他機器との通信や、補助記憶・外部記憶の読み書き、その他入出力装置とのやり取りにかかる時間
CPU時間には含まれないため、計測に使うライブラリ・関数に注意
実行時間-CPU時間とすればそれっぽい値にはなる、が、システムを使うユーザにとって通信時間なのかCPU時間なのかは大きな問題ではないので、チューニングには実行時間を見れば十分である
プログラムだけでは改善できないことも多い
実行時間の切り分け（例題）
例題として、Webシステムでリクエストを受け付けてからDBに登録するまでの処理を考える。行われる処理は下記のようになる。
リクエストでデータが送られる
リクエストからデータを取得、解析する
データを加工する
DBに登録する
レスポンスを作成する
レスポンスを返す
これらをパフォーマンスの観点で掘り下げると、下記のようなことを考えることになる。
１．リクエストでデータが送られる→通信
考えること
・送るデータの量
・送る回数
２．リクエストからデータを取得、解析する→演算
考えること
・取得、解析のロジック
・データの保持方法
・不要なデータの有無
３．データを加工する→演算
考えること
・加工のロジック
・不要なデータ加工の有無
４．DBに登録する→通信、演算、I/O
考えること
・接続の回数
・SQL発行の回数
・データの量
・ロックの仕方
・SQLの効率（副問い合わせに注意）
５．レスポンスを作成する→演算
考えること
・作成のロジック
・不要なデータ作成の有無
６．レスポンスを返す→通信
考えること
・返すデータの量
このように、問題を分解・洗い出し、その上で適切な対応を行う必要がある。
改善すべき場所を探す（実践）
とは言えここまでの話はまだ机上の話。もっと具体的に見るために下記のコードを用意した。main()メソッドの実行時間を改善したい場合、どこを改善するべきなのかを考えよう。
public class DummyHeavyProgram {
public void execute1() {
try {
Thread.sleep(5000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
public void execute2() {
try {
Thread.sleep(100);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
public static void main(String[] args) {
System.out.println("開始");
DummyHeavyProgram program = new DummyHeavyProgram();
program.execute1();
for (int idx = 0; idx < 100; idx++) {
program.execute2();
}
System.out.println("終了");
}この処理の中で特に時間がかかる処理は下記の2か所である。
program.execute1()
program.execute2()
※このような特に負荷のかかる箇所をホットスポットと呼ぶ。
ではまずどちらを直すべきだろうか。観点は、より「全体」の実行時間に影響する方を優先することである。execute1()は5秒かかるが、1回しか実行されない。execute2()は0.1秒しかかからないが、100回実行される。つまり、execute2()は合計10秒かかっている。直感に反するかもしれないが、今回はexecute2()を優先的に改善すべきである。
※execute1()は1秒削減しても合計1秒しか削減されないが、execute2()は0.01秒削減するだけで合計1秒削減される。実は速度改善のチャンスポイントなのである。
実行時間が分からないときは自分で測る
先の例ではThread.sleepで時間を明示しており、コードを読むだけでどこを改善すべきなのかが分かった。実際には当然そんなことは無い。時間を測定する処理を埋め込む必要がある。
ここで失敗しがちなのが、繰り返し実行される処理に対して1回分ずつの時間を測定してしまうことである。（上の例であれば、execute2()に対して0.1秒かかることしか確認しておらず、合計10秒かかっていることを確認していない状態。）
少し大変ではあるが、下記のように時間を合計するような仕組みを組むべきである。
System.out.println("開始");
long s1 = System.currentTimeMillis();
DummyHeavyProgram program = new DummyHeavyProgram();
long e1 = System.currentTimeMillis();
long s2 = System.currentTimeMillis();
program.execute1();
long e2 = System.currentTimeMillis();
long sum4 = 0;
long s3 = System.currentTimeMillis();
for (int idx = 0; idx < 100; idx++) {
long s4 = System.currentTimeMillis();
program.execute2();
long e4 = System.currentTimeMillis();
sum4 += e4 - s4; // 時間を足していく
}
long e3 = System.currentTimeMillis();
System.out.println("1 = " + (e1 - s1) + "msec.");
System.out.println("2 = " + (e2 - s2) + "msec.");
System.out.println("3 = " + (e3 - s3) + "msec.");
System.out.println("4 = " + sum4 + "msec.");
System.out.println("終了");※CPU時間を測るメソッドもあるが、「実行時間」を改善したい場合はCPU時間ではない、実際の時間を測るメソッドを使用するべきである。CPU時間については本稿では割愛する。
ぶっちゃけめんどい。。。
ここまで読んだ人の中には、ぶっちゃけ時間測る処理入れるのめんどい、という気持ちを持った人もいるのではないだろうか。私はめんどいと思う。時間計測を行うまでのハードルが無茶苦茶高いのである。
ということで、私が普段使っているクラス（Javaバージョン）を公開する。同じ発想で他の言語にも対応できるので、普段Javaを使用しない方は是非自分で作ってみて欲しい。
package util;
import java.util.HashMap;
import java.util.Map;
/**
* 時間計測Util
*
*/
public class StopwatchUtil {
private static Map<Object, Stopwatch> stopwatches = new HashMap<Object, Stopwatch>();
private static StopwatchUtil instance = new StopwatchUtil();
/**
* 含むか
* @param key
* @return
*/
public static boolean contains(Object key) {
return stopwatches.containsKey(key);
}
/**
* ストップウォッチ取得
* @param key
* @return
*/
private static Stopwatch get(Object key) {
if (contains(key)) {
return stopwatches.get(key);
}
else {
return null;
}
}
/**
* ストップウォッチ追加
* @param key
*/
private static void add(Object key) {
Stopwatch sw = instance.new Stopwatch(key);
stopwatches.put(key, sw);
}
/**
* ストップウォッチ作成
* @param key
* @return
*/
public static Stopwatch create(Object key) {
start(key);
return get(key);
}
/**
* 計測開始
* @param key
*/
public static void start(Object key) {
if (!contains(key)) {
add(key);
}
Stopwatch sw = get(key);
if (sw != null) {
sw.start();
}
}
/**
* 計測停止
* @param key
*/
public static void stop(Object key) {
if (!contains(key)) {
logging("Key[" + key + "] is not Stored");
return;
}
Stopwatch sw = get(key);
if (sw != null) {
sw.stop();
}
}
/**
* 時間出力
* @param key
*/
public static void show(Object key) {
if (!contains(key)) {
logging("Key[" + key + "] is not Stored");
return;
}
Stopwatch sw = get(key);
if (sw != null) {
sw.show();
}
}
/**
* ストップウォッチ削除
* @param key
*/
public static void remove(Object key) {
if (!contains(key)) {
logging("Key[" + key + "] is not Stored");
return;
}
Stopwatch sw = get(key);
if (sw != null) {
stopwatches.remove(key);
}
}
/**
* 全キーに対するアクション
* @param action
*/
private static void actionAll(IAction action) {
for (Object key : stopwatches.keySet()) {
action.exec(key);
}
}
/**
* 全件停止
*/
public static void stopAll() {
actionAll(new IAction() {
@Override
public void exec(Object key) {
stop(key);
}
});
}
/**
* 全件出力
*/
public static void showAll() {
actionAll(new IAction() {
@Override
public void exec(Object key) {
show(key);
}
});
}
/**
* 全件削除
*/
public static void removeAll() {
stopwatches.clear();
}
/**
* 出力
* @param message
*/
private static void logging(String message) {
String content = "StopwatchUtil: " + message;
System.out.println(content);
}
/**
* 時間計測クラス
*
*/
private class Stopwatch {
private long elapsedMilliseconds;
private Object key;
private boolean isRunning;
private long startTime;
/**
* コンストラクタ
* @param key
*/
public Stopwatch(Object key) {
this.key = key;
elapsedMilliseconds = 0;
startTime = 0;
}
/**
* 計測開始
*/
public void start() {
if (isRunning) {
logging("Already Started");
return;
}
startTime = System.currentTimeMillis();
isRunning = true;
}
/**
* 計測停止
*/
public void stop() {
if (!isRunning) {
logging("Already Stopped");
return;
}
elapsedMilliseconds += System.currentTimeMillis() - startTime;
startTime = 0;
isRunning = false;
}
/**
* 出力（msec.）
*/
public void show() {
logging(elapsedMilliseconds + "msec.");
}
/**
* 出力
* @param message
*/
private void logging(String message) {
String content = "Stopwatch[" + key + "]: " + message;
System.out.println(content);
}
}
/**
* アクション
*
*/
private interface IAction {
void exec(Object key);
}
}これで先の例を書き換えるとこうなる。
System.out.println("開始");
StopwatchUtil.start(1);
DummyHeavyProgram program = new DummyHeavyProgram();
StopwatchUtil.stop(1);
StopwatchUtil.start(2);
program.execute1();
StopwatchUtil.stop(2);
StopwatchUtil.start(3);
for (int idx = 0; idx < 100; idx++) {
StopwatchUtil.start(4);
program.execute2();
StopwatchUtil.stop(4);
}
StopwatchUtil.stop(3);
StopwatchUtil.showAll();
System.out.println("終了");時間の合計を計算する、ということを意識せずに使用できるのがこのクラスのポイントである。
最後に
これで直すべき点を探すことは出来るようになった。次回は実際に速度を改善する手法に触れていきたいと思う。