3. デバッグとプロファイル


3.1 デバッグ

Euphoriaのデバッグはその他の大多数のプログラミング言語より非常に簡単にできます。Euphoriaトランスレータによって提供されている広域ランタイムチェックは他の言語では追跡や発見に時間がかかる多くのバグを捕らえることができます。トランスレータがエラーを捕らたとき、スクリーン上に簡潔なエラーレポートを報告し、詳細なレポートをex.errと呼ばれるファイルに出力します。このファイルには発生したエラーの英語表記による完全な解説とコールスタックをトレースバックしたものが記載されています。ファイルex.errにはすべての変数の値のダンプと、最後に実行された随意的な命令文のリストが記載されています。非常に大きなシーケンスのときは、部分的なダンプリストのみ提示されます。ex.errが不便なときは、crash_file()を呼ぶことにより、別のファイル名を用いてあなたのシステム上の好きな場所に出力することができます。

さらに、ユーザ定義型(user-defined types)を作成して変数ごとに合法な値を正確に決定して代入することができます。これにより変数が非合法な値を割り当てられた瞬間にエラーレポートが表示されます。

まれに、プログラムはランタイムチェックでは検出できないロジックエラーにより不正な動作をすることがあります。どのようなプログラミング言語においてもソースコードを十分検証して、あなたがコーディングしたアルゴリズムを再考することは得策かもしれません。プログラム内のロジックを観察するための方法としてprint命令文を挿入することは現実的かもしれません。あなたがソースを編集または修正後にプログラムを再コンパイル・再リンクをすることなく再実行できたため、特にこの手法はEuphoriaのようなインタプリタ言語では重宝します。

さら強力なデバッグツールをインタプリタは提供しています。trace(1)を使用すると、あなたのプログラムの出力を見ている間に、もうひとつのトレースデバッグ用のスクリーンでプログラムの実行処理をトレース(追跡)できます。trace(2)はtrace(1)と動作は同じですが、トレーススクリーンが白黒表示になります。最後に、trace(3)を使うと、ctrace.outと呼ばれるファイルに実行された全ての命令文を結果として記録することができます。

特別な命令文であるwith trace / without traceでトレースを行うためにはプログラムの一部を選択します。単にtrace命令文をソースコードの開始行に挿入するとソースコードの全ての範囲をトレースします。時として、あなたは全てのユーザ定義型(user-defined types)の最初の行に with traceを配置することがありそれは好ましいことですが、ルーチン内では各変数に対する代入しかトレースできず以後のトレースを行うことはできません。その他の場合は、あなたがどのルーチンまたはどのようなルーチンがトレースされるか興味があり正確に理解している思うとき、これらからひとつだけトレース対象を選びたいかもしれません。もちろん、トレースウィンドウを表示しているときエンターキーではなく下矢印キーを押すとルーチンの実行を観察しながら処理好きなときにスキップすることができます。

トレース可能行のみctrace.outが出力されるか、またはex.errが"障害の原因となっているトレース行"に対してランタイムエラーが発生する必要があります。この情報が必要なのに取得できないなら、with traceを別の行に挿入してプログラムを再実行する必要があります。特にtrace(3)を使用する場合はwith traceの実行により行の処理速度は遅くなります。

あらかじめトレース行を決めた後に、trace()命令文の実行をしてプログラムを動的にトレースする機能が有効になる必要があります。これは単純に次のように記述できます:

        with trace
        trace(1)
プログラム先頭の処理開始と同時にトレースを開始することができます。一般に、特定のルーチンまたは条件文によってトレースのトリガーを有効にしたいときがあります。すなわち、
        if x < 0 then
            trace(1)
        end if

trace(0)命令文を実行するとトレースを無効にすることができます。また、トレースをトレーススクリーンで中止するために'qを入力する'とトレースを無効にすることもできます。traceはどのようなルーチンであっても外側に記述されていなければなりませんが、しかしwith traceはルーチンの内側外側に記述することができます。

type(型)の内側でトレースを有効にしたいときがあるかもしれません。プログラムを実行するとそれが失敗してex.errファイルに非合法な値を持たない奇妙な変数が設定され、それがどうして発生するのか疑問を持つと思います。変数に奇妙な値が代入されることに関心があるならば変数型を作成してtrace(1)を実行してください。すなわち、

        type positive_int(integer x)
            if x = 99 then
                trace(1) -- これは可能???
                return 1 -- そのまま
            else
                return x > 0
            end if
        end type

positive_int()が値を返すことによって、変数が奇妙な値に設定される原因となった命令文を正確に特定でき他の変数の値も調べることができます。この瞬間に何が発生したかを知るためにスクリーン出力を見て調べることもできます。positive_int()は0を返すように定義していますが、実際は奇妙な値(99)があるため1を返すことにより診断情報のダンプをex.errへ出力することができます。


3.1.1 トレーススクリーン

trace(1)またはtrace(2)命令文がインタプリタにより実行されるとき、メイン出力スクリーンは退避されトレーススクリーンが表示されます。この表示の見方としてプログラムの命令文として次に実行される反転表示がされた命令文といくつかの命令文の前後が表示されています。スクリーン下部の数行は変数名と値を表示するために予約されています。スクリーン上部の最初の一行目はこの時点で入力できるコマンド一覧を表示しています:

F1 - メイン出力スクリーンの表示 - これまでのプログラムの出力を表示します。
F2 - トレーススクリーンの再表示。トレース表示に戻るためにはメイン出力スクリーンを表示している間にキーを押してください。
Enter - 現在反転表示をしている命令文のみ実行する。
- 実行を継続しますが、ソースリスト内の任意の構文の後に出現する実行箇所を中断します。これはサブルーチン呼び出しを飛ばすことができます。また、全てのループの反復に立ち会うことなくforループまたはwhileループ終了後に現れる最初の命令文で停止することができます。
? - 変数の値を表示します。?を打鍵後に変数名の入力するためのプロンプトが表示されます。大半の変数は自動的に代入された値が表示されます。もし変数が現在表示されていないか、部分的に表示されているだけならば、あなたはそれを求めることができます。トレーススクリーン上で表示可能な巨大なシーケンスの行数は一行に制限されますが、巨大シーケンスを含む変数の値を求めるとき、スクリーンは消去されて整形されたシーケンスをスクロールしながら表示できます。なお、トレーススクリーンに戻ったときは変数は1行だけ表示されます。この時点においてプログラムで定義されていない変数は表示できません。未初期化変数は変数名の横に"< NO VALUE >"と示されます。変数のみ一般的ではない式を表示できます。プログラムをステップ実行すると、同時にシステムはスクリーンに表示する全ての値を更新します。ときどきスコープ外または長期更新されなかった変数を最近更新されたより新しい変数と比較して除去します。
q - トレースを終了してから通常の実行を再開します。次のtrace(1)が実行されたときトレースは再開されます。
Q - トレースを終了してから正常終了までプログラムを制限なく実行します。以後のtrace()命令文は無視します。
! - プログラムの実行を中止します。変数値のトレースバックとダンプ結果はex.errに書き込まれます。

プログラムをトレースすることにより、変数名と値はスクリーン最下部に自動的に表示されます。変数へ代入されたとき、いつでもその変数と新しい値が下部に表示されて閲覧することができます。この値は、常に最新のものになります。ルーチンから戻るとき、プライベート変数はスクリーンから自動的に消去されます。変数表示領域の表示可能範囲が限界になったとき、最も参照回数が少ない変数は新しい変数を表示するための領域を確保するために破棄されます。長いシーケンスの値の表示は80文字を超えた部分に関しては省略されます。

利便性のために、出力可能なASCII文字の範囲(32-127)の数値表現がASCII文字自身として表示されます。なお、ASCII文字は違う(または白黒モニターのクォートでは)配色になります。一般にEuphoriaは数値をASCII文字みなしているか不明なときは全ての変数に対して、この表現が適用されます。なお、ex.errで(クォートにて)ASCII文字が見られます。これは"ビジー"表示の際に実用的であるため、ASCII情報は非常に有用です。

トレーススクリーンは、メイン出力スクリーンと同じグラフィックスモードを選択します。これは、両方を高速かつ簡単に切り替えられるようにするためです。

トレースではプログラムがキーボード入力を要求するとき、メイン出力スクリーンに切り替わり、通常はどおりキーボードから入力を促します。これはgets()による入力(一行読み込み)において好ましい動作です。get_key()を呼ぶ(迅速にキーボードをサンプリングする)と文字を8秒の間に入力する機会を与えるか、そうでなければ今回のget_key()による呼び出しで入力が無かったと仮定されます。これはget_key()による入力の有無を検査することができます。


3.1.2 トレースファイル

プログラムでtrace(3)が呼ばれたとき、トレースファイルが有効になります。このファイルctrace.outは現在ディレクトリに作成されます。これにはプログラムで実行された最新500件のEuphoriaの命令文が含まれています。これには最高500件の命令を保持できるリングバッファが用意されます。ctrace.outが終端に到達したとき、常に次の命令文は先頭に戻って出力されます。実行された最後の命令文の後には常に"=== THE END ==="が続いて出力されます。理由としてバッファがリング構造であるため、実行された最後の命令文は何処でもctrace.outに現れることができます。なお、"=== THE END ==="に来る命令文は最後の500番目です。

このトレース方式はインタプリタおよびEuphoria→C言語トランスレータの両方で対応しています。これにより機械レベルのエラーが発生してしまいEuphoriaが診断用ファイルex.errを書き出すのが阻止されてしまうときに役に立ちます。実行された最後の命令を分析することにより、プログラムが暴走した原因を特定できるかもしれません。それは恐らく最後の命令文はpoke()による違法なメモリー領域操作、C言語ルーチンの呼び出しだと思われます。また、場合によってはインタプリタまたはトランスレータのバグかもしれません。

命令文が実行されるにソースコードの命令文はctrace.outへの出力とフラッシュが行われ、実行にクラッシュが起こったとき、恐らくctrace.outで最後の命令文を見ることができます。



3.2 プロファイル

with profile(DOS32, WIN32, Linux, FreeBSD)、またはwith profile_time(DOS32専用)を指定すると、profileが呼ばれたときにプログラムの特別なリストがプログラム完了後にインタプリタによって生成されます。このリストは現在のディレクトリにex.proファイルとして書き出されます。

プロファイルは2つの方式があります: 実行回数プロファイル時間プロファイルwith profileを指定すると実行回数プロファイルになります。with profile_timeを指定すると時間プロファイルになります。単一のプログラム実行時にプロファイルの2つの方式を併用することはできません。2つの方式を別々に実行する必要があります。

プロファイルの両方の方式でdemo\benchにあるペンチマークデモプログラムsieve8k.exを実行したとします。結果としてsieve8k.pro(実行回数プロファイル)とsieve8k.pro2(時間プロファイル)が生成されます。

実行回数プロファイルはプログラムで各命令文が何回実行されたかの正確に表します。命令文が一切実行されないときは回数フィールドは空です。

時間プロファイル(DOS32専用)は各命令文の実行合計時間の概算を表します。プログラムのプロファイル時間は百分率で概算したもので表されます。命令文が一切実行されないときは百分率フィールドは空です。0.00が現れたとき、それは命令文がサンプリングされたが0.01のスコアを得るのに不十分であることを意味します。

コンパイルされた命令文のみwith profileまたはwith profile_timeでリストに表されます。通常はプロファイルではwith profileまたはwith profile_timeのどちらかをメインの.exファイルの最上部で指定することにより完全なリストを取得できます。なお、このファイルはカラーディスプレイ上のEuphoria標準エディタで閲覧できます。

プロファイルは様々な方法でプログラム開発を支援することができます:

  • プログラムを高速化するための手がかりとして、どの命令文が頻繁に実行されているか明らかにします。
  • プログラムが実際に方法で希望通り動作しているか確認することができます。
  • 入力データについての統計を提供します。
  • どのコードの部分がテストされなかった明らかにします。 - あなたのユーザが最初に不具合に遭遇しないようにするためです。

時々、プログラムの実行において特定の動作を明確にしたいときがあります。例えば 言語戦争ゲームでは、ゲームの大半が十分高速であると判明しましたが四方八方に2500ピクセルを射出して惑星が爆発したとき処理落ちが起こりました。ゆえに爆発ルーチンを高速化する必要が出てきました。それに残りのコードも好ましいものではありませんでした。解決策は言語戦争ゲームのはじめにwith profile_timeを記述した直後にprofile(0)を呼び出してプロファイリングを無効にしたあとに、profile(1)を爆発ルーチンのはじめに、profile(0)をルーチンの終わりに呼び出します。さて、この方法でゲームを実行して多数の爆発を生成して爆発エフェクト処理の多くのサンプルを記録しました。サンプルが他の低レベルルーチンに対して頻繁にアクセスされるならば、それらのサンプルが爆発中に発生することを理解していました。単にプログラム全体にプロファイルを行ったならば、概念が明白ではなくても低レベルルーチンが船体の移動、光線銃の描画に使用されることが理解できます。profile()は同様に実行回数プロファイルでも開発を支援することができます。


3.2.1 時間プロファイルに関していくつかの追加の注意点

システムクロックのクリックごとに、割り込みが発生します。Euphoriaはwith profile_timeを使用したときに正確な時間で割り込みが発生するごとに実行開始された命令文を確認してプログラムをサンプリングします。

割り込みは1秒につき18.2回発生しますが、tick_rate()を呼び出すことにより、より多くのサンプルを対象にできるため非常に高いレートを選択でき、より正確な時間プロファイルを取得することができます。tick_rate()を呼び出さないときは、規定値としてtick_rate(100)が呼び出されて自動的にプロファイルが開始されます。さらに上(最高1000まで)に設定することができますが、しかしプログラムの動作に悪影響を及ぼすかもしれません。

サンプルごとに4バイトのメモリが必要であり、通常は25000サンプルの空きバッファが予約されています。25000以上のサンプルが必要ならば次のように要求することができます:

        with profile_time 100000
100000サンプル(たとえば)の空き領域を予約します。バッファオーバーフローになったときはex.proの行頭で警告を見ることになります。1秒に100サンプルを使用するため規定値の25000サンプルを使い切るまでに250秒間プログラムを動作させることができます。Euphoriaが割り込み扱っている間にサンプルバッファを動的に拡張することは不可能です。そのためプログラムで必要な容量を指定しなければならないかもしれません。Euphoriaは実行可能な各上位命令文の完了後に今まで蓄積されたサンプルの処理を行い、多くのサンプルのバッファを開放します。このようにプロファイルは実際のところ予約した開き領域よりも多くのサンプルを対象とすることができます。

ex.proの左端に示される割合は、サンプルの合計取得数によって特定の命令文がサンプルされた回数を除算することにより計算されます。例えば、命令文が最大500サンプルのうち50回サンプルされたならば、値として10.0(10パーセント)が命令文の横端に現れます。with profile(0)によりプロファイルが無効なとき割り込みは無視され、サンプルは行われずサンプルの合計は増加しません。

多くのサンプルを取得することにより精度の高い正確な結果を得ることができます。しかし、警戒すべき状況の1つとしてプログラム自身がtime()に進行によるウェイトを用いてクロック割り込みに同期させる場合があります。このときクロックが進んだ直後に実行される命令文は一切サンプリングされないかもしないため、非常に湾曲した表現が与えられることになります。例えば、

        while time() < LIMIT do
        end while
        x += 1 -- この命令文はサンプリングされない。

時々、return命令文の隣で大部分の割合を消費していることが見受けられることがあります。これは通常においてルーチン内で使用される一時的なプライベート変数領域の開放により費やされる時間です。新しい値を大きなシーケンスに割り当てるとき大規模な領域の開放が発生します。

ディスクスワップが開始されてしてしまう原因として、例えば命令文がスワップアウトされた巨大なシーケンスの要素にアクセスするなど、長時間スワップファイルにアクセスする必要がある命令文が原因になっていることが確認できるかもしれません。

 

第二部 - ライブラリルーチン に続きます...