\chapter{バグ検出実験} \label{chapter:result}
\ref{chapter:test} 章で説明したテスト環境を用いて実際に Super Dandy
の OpenGL バージョン、Cerium バージョン、そして Task Dandy 上において
テストを実行した。ここでは、出力されたテストログの比較や実際にテスト結果を
用いて行ったデバッグ例、\ref{sec:create_random} 節で提案した Task への乱数の
受け渡しの検証、そしてビデオモードによる実行速度の比較をしながら本研究の
評価を述べる。

\section{開発した環境における検出方法}\label{sec:how2test}
まずはじめに OpenGL バージョンの Super Dandy を Capture モードでプレイする。
プレイはエンディングまで行い、プレイヤーの入力データを保存する。
これは OpenGL バージョンが Cerium バージョンと Task Dandy の目標とする
動作であるからである。次に Cerium バージョン、Task Dandy を Trace モードで
実行し、入力データを読み込ませる。そして各バージョンそれぞれから得られた
テストログを比較、考察し、バグの発生していると思われる箇所を特定する。

\subsection{OpenGL バージョンと Cerium バージョンの比較}
OpenGL バージョンと Cerium バージョンのテストから生成されたテストログの
比較を行い、違いがあるかどうか検証した。ゲームはエンディングまでプレイし、
Cerium バージョンは画面描画を行わないモードで実行し、出力されたテストログの
データは unix コマンドの wc(word count) コマンドを実行して検証した。
結果を表 \ref{tb:test_log} にまとめる。

\begin{table}[h]
\caption{Super Dandy のテストログの比較}
\begin{tabular}{c|c|c|c} 
\hline
\hline
  & 大きさ & 行数 & 単語数 \\ \hline \hline
OpenGL & 349486 byte & 3411 & 37194\\ \hline
Cerium & 349471 byte & 3411 & 37195\\ \hline
\end{tabular}
\label{tb:test_log}
\end{table}

2 つのテストログに大きな差異は無いことがわかる。また Super Dandy を 1 回
エンディングまでプレイしたときに作られるテストログの大きさは 約 350 KB と
いうことが分かった。
また、以下にこの 2 つのテストログに対して diff を取った結果を示す。

\begin{verbatim}
% diff log/demo_log log/dandy_log
1a2
> Use Joystick
3410,3411c3411,3412
< 83.308451 FPS
< move: average:49usec, peak:1091usec
---
> 0.000000 FPS
> game end
\end{verbatim}

表示されている各パラメータとメッセージは OpenGL や Cerium 依存のメッセージ
である。0.000000 FPS と表示されるのは Cerium 側のメッセージであるが、これは
描画を行わないビデオモードで実行したことにより、正しく FPS が計算
できなかった為と思われる。この結果より Super Dandy の OpenGL バージョンと 
Cerium バージョンの動作は同じであると言える。

\subsection{データの同期問題の検出と対処方法}
\ref{sec:how2test}の方法でテストを行い、しばらく実行させていると以下のような
テストログが取れた。

\begin{verbatim}
super dandy(OpenGL) >>
F64: CREATE  [NAME]enemy_greenclab_0  [COORD]x= 120.000000  y= -128.000000 ...
F85: DELETE  [NAME]enemy_greenclab_0  [COORD]x= 120.000000  y= -44.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
F96: CREATE  [NAME]enemy_greenclab_1  [COORD]x= 56.000000  y= -128.000000 ...
F96: CREATE  [NAME]enemy_greenclab_2  [COORD]x= 184.000000  y= -128.000000 ...
F109: DELETE  [NAME]enemy_greenclab_1  [COORD]x= 56.000000  y= -24.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
F117: DELETE  [NAME]enemy_greenclab_2  [COORD]x= 184.000000  y= 40.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0

<< task dandy
F64: CREATE  [NAME]enemy_greenclab_0  [COORD]x= 120.000000  y= -128.000000 ...
F85: DELETE  [NAME]enemy_greenclab_0  [COORD]x= 120.000000  y= -44.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
F96: CREATE  [NAME]enemy_greenclab_1  [COORD]x= 56.000000  y= -128.000000 ...
F96: CREATE  [NAME]enemy_greenclab_2  [COORD]x= 184.000000  y= -128.000000 ...
F109: DELETE  [NAME]enemy_greenclab_1  [COORD]x= 56.000000  y= -24.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
F109: DELETE  [NAME]enemy_greenclab_2  [COORD]x= 184.000000  y= -24.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
\end{verbatim}

ここで Super Dandy と Task Dandy の 2 つのログを比較したときの特徴を
洗いだすと以下のようになる。

\begin{itemize}
\item Super Dandy では別フレームで被弾した敵オブジェクトが Task Dandy では
  同フレーム内で被弾している
\item 同フレーム内で被弾したときの弾丸の数が一致している
\item それ以外のログは Super Dandy と Task Dandy 共に一緒である
\end{itemize}

こうした結果から 2 つのオブジェクト間で弾丸データの同期が取れていない、と
いう仮説を立てた。Task Dandy では create\_task 時に弾丸データを Property 
として他のオブジェクトデータと共にまとめて set\_inData するようにしているが、
このデータは create\_task 時のデータであり、先に実行された Collision Task 
内でそのデータに変更があったとしても 別の Collision Task で使用するデータに
反映されることはない。

Collision Task 間でデータを同期させるには、Collision Task を同じ CPU に送り、
\ref{sec:global} 節にある global\_alloc で予め衝突判定に必要なパラメータの
領域を LS に確保し、その領域のパラメータで衝突判定を行う方法が考えられる。
その場合、メインメモリ側のパラメータは獲得した得点や弾丸の描画などの処理に
使われるため、SPE 内に確保された共用領域のパラメータの変更を毎フレーム
メインメモリ側に反映させる必要がある。
(図\ref{fig:collision_reflect})

\begin{figure}[h]
\begin{center}
\includegraphics[scale=0.6]{images/collision_reflect.pdf}
\end{center}
\caption{共用領域による Collision Task の同期}
\label{fig:collision_reflect}
\end{figure}

以上のことをふまえて Collision Task を書き換え、再び同じプレイヤー入力で
テストログを出力させた。以下にその結果を示す。

\begin{verbatim}
super dandy>>
F64: CREATE  [NAME]enemy_greenclab_0  [COORD]x= 120.000000  y= -128.000000 ...
F85: DELETE  [NAME]enemy_greenclab_0  [COORD]x= 120.000000  y= -44.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
F96: CREATE  [NAME]enemy_greenclab_1  [COORD]x= 56.000000  y= -128.000000 ...
F96: CREATE  [NAME]enemy_greenclab_2  [COORD]x= 184.000000  y= -128.000000 ...
F109: DELETE  [NAME]enemy_greenclab_1  [COORD]x= 56.000000  y= -24.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
F117: DELETE  [NAME]enemy_greenclab_2  [COORD]x= 184.000000  y= 40.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0

<< task dandy
F64: CREATE  [NAME]enemy_greenclab_0  [COORD]x= 120.000000  y= -128.000000 ...
F85: DELETE  [NAME]enemy_greenclab_0  [COORD]x= 120.000000  y= -44.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
F96: CREATE  [NAME]enemy_greenclab_1  [COORD]x= 56.000000  y= -128.000000 ...
F96: CREATE  [NAME]enemy_greenclab_2  [COORD]x= 184.000000  y= -128.000000 ...
F109: DELETE  [NAME]enemy_greenclab_1  [COORD]x= 56.000000  y= -24.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
F117: DELETE  [NAME]enemy_greenclab_2  [COORD]x= 184.000000  y= 40.000000 ...
             [BULLET]tlv1 = 2, tlv2 = 0 llv1 = 0
\end{verbatim}

この結果よりオブジェクトの処理の結果がフレーム単位で同じであることがわかる。
よって共用領域を利用した Collision Task のデータ同期が非常に有効に働いている
ことがわかった。

\section{Task への乱数受け渡しによるバグの再現性の検証}
\ref{sec:create_random} 節で述べた Task への乱数受け渡しの手法が期待通りの
動きをするかどうか、多数の隕石オブジェクトが生成されるステージで全ての隕石
オブジェクトが生成されるのを観察し、検証した。Super Dandy におけるこの
隕石オブジェクトは以下のような実装となっている。

\begin{verbatim}
CHARACTER * chara_state22(CHARACTER *p)
{
  int sf;

  sf = random() % 4;
  if((sf == 0) || (sf == 1))
    {
      p->x = -35;
      p->y = random() % (120 - 35);
      p->vx = (random() % 4 + 1);
      p->vy = random() % 3 + 1;
      p->state = chara_state23;
    }
  if((sf == 2))
    {
      p->x = random() % 290;
      p->y = -30;
      p->vx = random() % 3 - 1;
      p->vy = (random() % 4 + 1);
      p->state = chara_state23;
    }
  if(sf == 3)
    {
      p->x = 320;
      p->y = random() % (120 - 35);
      p->vx = (random() % 4 + 1) * -1;
      p->vy = random() % 3 -1;
      p->state = chara_state23;
    }
  return p;
}
\end{verbatim}

このオブジェクトは乱数によって 3 種類の処理に分かれる。処理の中では xy 座標
、xy 方向の速度が決定し、次の状態へ遷移する、という動作になっている。
そこで、この処理が行われた直後のオブジェクトの座標を記録し、Super Dandy、
Task Dandy 双方のデータに違いがあるかどうか調べた。Task Dandy 側の隕石
オブジェクトの実装は以下のようになっている。

\begin{verbatim}
static int
state22(SchedTask *smanager, void *rbuf, void *wbuf)
{
    int rand1 = (int)smanager->get_param(0);
    int rand2 = (int)smanager->get_param(1);
    int rand3 = (int)smanager->get_param(2);
    int rand4 = (int)smanager->get_param(3);

    CHARACTER *p = (CHARACTER*)smanager->get_input(rbuf, 0);

      int sf = rand1 % 4;
      if((sf == 0) || (sf == 1))
      {
	  p->x = -35;
	  p->y = rand2 % (120 - 35);
	  p->vx = (rand3 % 4 + 1);
	  p->vy = rand4 % 3 + 1;
	  p->state_task = STATE23;
      }
      if((sf == 2))
      {
	  p->x = rand2 % 290;
	  p->y = -30;
	  p->vx = rand3 % 3 - 1;
	  p->vy = (rand4 % 4 + 1);
	  p->state_task = STATE23;
      }
      if(sf == 3)
      {
	  p->x = 320;
	  p->y = rand2 % (120 - 35);
	  p->vx = (rand3 % 4 + 1) * -1;
	  p->vy = rand4 % 3 -1;
	  p->state_task = STATE23;
      }

      smanager->swap();
      return 0;
}
\end{verbatim}

この 2 つを実行したログは以下のようになった。

\begin{verbatim}
demolog >>
[COORD]x= 320.000000  y= 66.000000  vx= -2.000000  vy= 0.000000
[COORD]x= -35.000000  y= 20.000000  vx= 3.000000  vy= 1.000000
[COORD]x= -35.000000  y= 36.000000  vx= 3.000000  vy= 2.000000
[COORD]x= 89.000000  y= -30.000000  vx= 1.000000  vy= 3.000000
[COORD]x= -35.000000  y= 81.000000  vx= 1.000000  vy= 2.000000
[COORD]x= 320.000000  y= 8.000000  vx= -4.000000  vy= -1.000000
[COORD]x= 220.000000  y= -30.000000  vx= 1.000000  vy= 4.000000
....

<< tdandylog
[COORD]x= 320.000000  y= 66.000000  vx= -2.000000  vy= 0.000000
[COORD]x= -35.000000  y= 20.000000  vx= 3.000000  vy= 1.000000
[COORD]x= -35.000000  y= 36.000000  vx= 3.000000  vy= 2.000000
[COORD]x= 89.000000  y= -30.000000  vx= 1.000000  vy= 3.000000
[COORD]x= -35.000000  y= 81.000000  vx= 1.000000  vy= 2.000000
[COORD]x= 320.000000  y= 8.000000  vx= -4.000000  vy= -1.000000
[COORD]x= 220.000000  y= -30.000000  vx= 1.000000  vy= 4.000000
....

% diff demolog tdandylog
%
\end{verbatim}

以上の結果より、生成された隕石オブジェクトの座標と速度が一致しているのが
わかる。

\section{ビデオモードによる実行時間の比較}
\ref{sec:video_none} 節で説明した描画を行わないビデオモードと通常の
ビデオモードで実行時間を計測し、その差がどの程度あるのかを比較した。
実行時間の計測には Unix 環境で使用できる time コマンドを使用し、計測モデル
として OpenGL バージョン と Cerium バージョンの Super Dandy と Task Dandy 
を使用した。以下が計測結果である。先頭の OpenGL バージョンは高さと幅を 1 に
設定したため、ほとんど描画処理を行わない。また、下段 3 つは画面のサイズを
1200 x 800 として実行している。
(表\ref{tb:test_time})

\begin{table}[h]
\caption{ビデオモードによる実行時間の比較}
\begin{tabular}{c|c|c|c|c} 
\hline
\hline
  & ユーザー時間 & システム時間 & CPU 使用率 & トータル時間 \\ \hline \hline
OpenGL(w=1,h=1) & 39.67 sec & 27.17 sec & 19 \% & 335.06 sec \\ \hline
Cerium(no video) & 42.40 sec & 24.46 sec & 20 \% & 334.21 sec \\ \hline
Task(no video) & 103.25 sec & 28.74 sec & 34 \% & 385.17 sec \\ \hline \hline
OpenGL & 40.56 sec & 27.60 sec & 20 \% & 336.09 sec \\ \hline
Cerium & 4641.32 sec & 416.23 sec & 99 \% & 5066.11 sec \\ \hline
Task & 6242.26 sec &  486.65 sec &  101 \% & 6643.16 sec \\ \hline
\end{tabular}
\label{tb:test_time}
\end{table}

高さ 1、幅 1 の OpenGL バージョンと Cerium バージョンの no video では
ユーザー時間とシステム時間の大小が逆になっているが、トータル時間は
ほとんど差が無くなっている。これは描画処理を除けば 2 つのバージョンの処理に
ほとんど差がないことが理由と考えられる。一方、 Task Dandy ではユーザー時間が
大きく増加し、それに伴ってトータル時間も増加している。これは Cerium 内での
Task の処理が発生したためと思われる。Task の処理で 50 秒ほどの差がうまれた
のは、今回実験した環境が Fifo であるためで、これを Cell を用いた並列環境で
実行すれば、この処理時間は小さくなると考えられる。

次に描画処理を行った時の実行時間だが、OpenGL は描画を行わない場合との差が
ほとんど見られない。一方で Cerium バージョンや Task Dandy では非常に多くの
処理時間が発生している。これは \ref{sec:rendering} 節で述べた 3 つの Task 
による描画処理が多くの処理時間を要し、さらに Fifo 環境であるため、Task に
分割した時のオーバーヘッドが膨大になっているからだと思われる。

\section{評価}
今回構築したテスト環境によって実際に Collision 処理でのデータの同期のバグを
見つけるなど、並列処理におけるバグに対しても効果を得ることができた。
実行環境は Fifo であったが、Task の定義などの基本的な並列処理の
エミュレーションはできており、ある程度の並列処理のバグを発見することができる
と考えられる。

また、プレイヤーの入力を記録することにより、画面の描画が行わなくても、
内部処理のテストログを残すことが可能となった。このテストログだけでは
直接的なデバッグの手助けにはならないが、旧バージョンのテストログの比較を
行うことで、どのあたりでバグが発生しているのか、ある程度の場所を特定すること
ができる。

また、描画を行わないことによって大幅にデバッグの時間を短縮することが
できた。この手法は特に描画処理が遅い環境において効果的であり、効率的な
テスト環境を構築できたのではないかと思われる。
しかし、この方法では描画処理のバグを見つけることや、ゲーム
の詳細な動きを知覚することはできないため、描画モードとの使い分けが重要だと
考えられる。