mttest での同期トレース実験の検証 - Oracle® Developer Studio 12.5: パフォーマンスアナライザチュートリアル

言語:

`mttest` での同期トレース実験の検証

このセクションでは、前のセクションの mttest サンプルコードで作成した実験のデータを調査する方法を示します。

次のようにして、mttest ディレクトリからパフォーマンスアナライザを起動し、最初の実験をロードします。

% analyzer test.1.er

実験が開くと、パフォーマンスアナライザの「概要」ページが表示されます。

「クロックプロファイリング」メトリックが最初に表示され、色付きのバーが含まれます。大部分のスレッド時間が「ユーザー CPU 時間」で消費されます。「休眠時間」または「ユーザーロック時間」で一定の時間が消費されます。

「同期トレース」メトリックは、「同期待ち時間」および「同期待ちカウント」の 2 つのメトリックを含む 2 番目のグループに表示されます。

注 - 「同期待ち時間」および「同期待ちカウント」メトリックが表示されていない場合は、右へスクロールしてこれらの列を表示する必要があります。メトリックの列ヘッダーを右クリックし、「このメトリックの移動先」を選択し、ほかのメトリックとの関連でこのメトリックを表示するのに便利な場所を選択することによって、任意の列をより便利な場所に移動できます。

次の例では、「名前」列を「同期待ちカウント」メトリックのあとに移動します。

チュートリアルの以降のセクションで、これらのメトリックとその実装を調査できます。

同期トレースの理解

このセクションでは、同期トレースのデータと、そのデータをクロックプロファイリングデータと関連付ける方法について説明します。

「関数」ビューに移動し、列見出し「包括的 CPU 合計」をクリックし、包括的 CPU 合計時間に従ってソートします。
リストの先頭にある do_work() 関数を選択します。
「関数」ビューの下部にある「呼び出し元/呼び出し回数」パネルを見ると、do_work() は 2 つの場所から呼び出され、10 個の関数を呼び出しています。

do_work() はほとんどの場合、データを処理するスレッドの作成時に呼び出され、_lwp_start() から呼び出されるものとして示されます。do_work() は場合によっては、locktest() から呼び出されたあと、nothreads() という名前の 1 つのシングルスレッドタスクを呼び出します。

do_work() が呼び出す 10 個の関数は 10 個の異なるタスクを表し、各タスクはプログラムが実行した異なる同期メソッドを使用します。mttest で作成される一部の実験では、わずかな時間を使用してほかのタスクからワークブロックをフェッチする 11 番目の関数が記録されることがあります。この関数 fetch_work() は、前のスクリーンショットで「呼び出し」パネルに表示されています。

「呼び出し」パネルの最初の 2 つの呼び出し先を除き、すべての呼び出し先はほぼ同じ時間の「属性 CPU 合計時間」(10.6 秒以下) を示しています。
「呼び出し元-呼び出し先」ビューに切り替えます。

「呼び出し元-呼び出し先」ビューには「呼び出し元/呼び出し回数」パネルと同じ呼び出し元と呼び出し先が表示されますが、「属性同期待ち時間」など、「概要」ページで選択されたほかのメトリックも表示されます。

2 つの関数 lock_global() および lock_local() を探すと、これらの関数が示している「属性 CPU 合計時間」はほとんど同じですが、「属性同期待ち時間」は大きく異なっています。
lock_global() 関数を選択して「ソース」ビューに切り替えます。

すべての「同期待ち時間」は、「CPU 時間合計」が 0 である pthread_mutex_lock(&global_lock) の呼び出しがある行で費やされています。関数名から推測されるように、このタスクを実行する 4 つのスレッドはすべて、グローバルロックを 1 つずつ獲得するときに各自の処理を実行します。
「関数」ビューに戻って lock_global() を選択し、「フィルタ」アイコンをクリックして「フィルタの追加: 選択した関数を含むスタックのみを含める」を選択します。
「タイムライン」ビューを選択すると、4 つのスレッドが見えます。
タイムライン内でイベントの発生した領域を強調表示し、右クリックして「ズーム」->「選択した時間範囲にズーム」を選択することによって、関心のある領域にズームインします。
4 つのスレッドを調べて、待機に費やされた時間と計算に費やされた時間を比較します。

注 - 実験では、複数のスレッドが異なる時点で実行中および待機中になっている可能性があります。

ロックを取得するための最初のスレッド (スクリーンショットの T:15) は約 2.97 秒を費やしたあと、ロックを諦めます。そのスレッドのスレッド状態バーは緑色であり、その時間のすべてが「ユーザー CPU 時間」で消費され、「ユーザーロック時間」では消費されなかったことがわかります。また、同期トレースの呼び出しスタックを表す 2 番目のバーにはマークが付き、このスレッドの呼び出しスタックがないことを示しています。

2 番目のスレッド (スクリーンショットの T:17) は「ユーザーロック時間」で 2.99 秒待ったあと、2.90 秒にわたって計算し、ロックを諦めます。同期トレースの呼び出しスタックは「ユーザーロック時間」と同時期です。

3 番目のスレッド (T:14) は「ユーザーロック時間」で 5.98 秒待ったあと、2.95 秒にわたって計算し、ロックを諦めます。

最後のスレッド (T:16) は「ユーザーロック時間」で 8.98 秒待ったあと、2.84 秒にわたって計算します。合計の計算は 2.97+2.90+2.95+2.84、つまり 11.7 秒でした。

合計の同期待ちは 2.99 + 5.98 + 8.98、つまり 17.95 秒でした。このことは「関数」ビューで確認できます (17.954 秒と報告されています)。
「アクティブなフィルタ」パネルの「X」をクリックしてフィルタを削除します。
「関数」ビューに戻り、関数 lock_local() を選択して「ソース」ビューに切り替えます。

pthread_mutex_lock(&array->lock) の呼び出しがある行 (スクリーンショットの行 1043) で、「同期待ち時間」は 0 です。その理由は、ロックがワークブロックにローカルであるため、競合がなく、4 つのスレッドすべてが同時に計算することです。

ここまで見てきた実験は、測定に基づくしきい値を使用して記録されたものです。次のセクションでは、make コマンドの実行時にしきい値をゼロにして記録された 2 番目の実験と比較します。

同期トレースのある 2 つの実験の比較

このセクションでは 2 つの実験を比較します。test.1.er 実験は、測定に基づくイベント記録しきい値を使用して記録されました。test.2.er 実験は、mttest プログラムの実行で発生したすべての同期イベントが含まれるよう、しきい値をゼロにして記録されました。

ツールバーにある「実験を比較」ボタンをクリック、または「ファイル」->「実験を比較」を選択します。

「実験を比較」ダイアログボックスが開きます。

すでに開いている test.1.er 実験は「ベースライン」グループに表示されます。ベースライン実験と比較する実験を「比較グループ」パネルに追加する必要があります。

実験の比較、およびベースラインと比較する複数の実験の追加に関する詳細は、ダイアログボックスの「ヘルプ」ボタンをクリックしてください。
「比較実験 1」の隣にある「...」ボタンをクリックし、「実験の選択」ダイアログで test.2.er 実験を開きます。
「実験を比較」ダイアログで「了解」をクリックし、2 番目の実験をロードします。

両方の実験のデータが含まれた状態で、「概要」ページがふたたび開きます。

「クロックプロファイリング」メトリックは、それぞれの実験に対応する 2 本の色付きバーをメトリックごとに表示します。test.1.er ベースライン実験のデータは上側です。

データバーにマウスカーソルを合わせると、ベースライングループおよび比較グループのデータと、数値および % で表されたグループ間の差がポップアップテキストで表示されます。

2 番目の実験では、記録された「CPU 時間合計」がわずかに多い一方、「同期待ちカウント」はほぼ 3 倍になっています。
「関数」ビューに切り替え、「包括的同期待ち時間カウント」列の下の「ベースライン」というサブ列ヘッダーをクリックして、最初の実験のイベント数で関数をソートします。

test.1.er と test.2.er の差がもっとも大きいのは do_work() であり、これには、lock_global() や lock_local() など、この関数が直接または間接的に呼び出すすべての関数で生じた差が含まれます。

ヒント - 比較形式を変更すると、さらに簡単に差を比較できます。ツールバーの「設定」ボタンをクリックし、「書式」タブを選択し、「比較形式」から「デルタ」を選択します。変更を適用したあと、test.2.er のメトリックは、test.1.er のメトリックからのプラスまたはマイナスの差として表示されます。前のスクリーンショットで、選択された pthread_mutex_lock() 関数は、test.2.er の「包括的同期待ちカウント」列で +88 を示します。
「呼び出し元-呼び出し先」ビューを選択します。

2 つの呼び出し元 lock_global() および lock_local() に注目します。

lock_global() 関数は、test.1.er では「属性同期待ちカウント」に対して 3 つのイベントを示しますが、test.2.er では 4 つのイベントを示します。理由は、test.1.er ではロックを獲得するための最初のスレッドがストールしなかったため、イベントが記録されなかったことです。test.2.er 実験では、すべてのイベントを記録するようにしきい値が記録されていたため、最初のスレッドのロック獲得も記録されました。

同様に、最初の実験では、ロックの競合がなかったため lock_local() に対してはイベントが記録されませんでした。2 番目の実験では 4 つのイベントがありましたが、遅延は合算しても無視できる程度でした。