f:id:keroqueue:20190724041408p:plain

概要

GPU-Z App for SplunkにCPUパフォーマンス、フレームレートのログを追加する話。
WindowsパフォーマンスモニターのログとOCATのログを追加で取り込んだが、CPU負荷が高く、ベンチのスコアに大きく影響が出てしまった。検討した結果、ログはMSI Afterburnerのみを取り込むことにした。
前回の記事はこちら。 keroqueue.hatenablog.com

概要
モチベーション
やったこと
今回の学び
ToDo
所感と雑記

モチベーション

以前漆黒ベンチを回してCPUのボトルネックを発見したことで、ゲーミング性能をモニタリングする上ではGPUのパフォーマンスだけでなく、CPUのパフォーマンスも重要であることがわかった。
しかし、作成中のGPU-Z App for SplunkはCPUパフォーマンスのログに対応しておらず、CPU負荷を確認するにはリアルタイムで目視する必要があり、またフレームレートのログもないため、ゲーミングパフォーマンスの可視化としてははいまいち。
そこで、GPU-Z App for SplunkにCPUパフォーマンス・フレームレートのログを追加することで、ダッシュボード上でモニタリングが完結することを目指すことにした。
そのため、エントリーのタイトルも "Windows PCのゲーミングパフォーマンスをSplunkで可視化する"に変更した。

やったこと

CPUパフォーマンスログの取り込み

Universal Forwarderは標準でホストのパフォーマンスログをある程度取ってこれる。インストールウィザードの”Enable Windows Inputs”で"CPU Load"にチェックを入れてあげると画像のようなログが取り込まれる。 f:id:keroqueue:20190724031913p:plain

ログから察するにWindows環境パフォーマンスモニターの値を持ってきているようだが、対象が_Totalの負荷だけになっている。他のインスタンスの負荷、クロック周波数の情報もほしいところ。
以下のドキュメント参考にinputs.confを書いた。 docs.splunk.com docs.splunk.com

### inputs.conf
[perfmon://CPU Load]
counters = % Processor Time
disabled = 0
instances = *
interval = 1
object = Processor
useEnglishOnly=true
index = win_perform

[perfmon://CPU Frequency]
counters = Processor Frequency
disabled = 0
instances = *
interval = 1
object = Processor Information
useEnglishOnly=true
index = win_perform

適当にタイムチャートで出してみた。負荷はうまく取れているようだが、クロック周波数が常にベースクロックとなっていている。
パフォーマンスモニターで% of Maximum Frequencyカウンターを確認したが、常に1になっていた。他のモニタリングツール(CAMなど)ではクロック周波数が変動しているが...。
調べても原因がわからなかったため、ひとまず置いておくことに。 f:id:keroqueue:20190724031402p:plain f:id:keroqueue:20190724031132p:plain

フレームレートログの取り込み

フレームレートのログはOCATから取ることにした。 github.com

OCATのログは、任意のディレクトリにプロセス毎で作成される。フォーマットはcsv。 f:id:keroqueue:20190722212509p:plain

デフォルトではフレームレートがカラムに含まれないため、メイン画面でWrite performance summaryにチェックを入れる必要がある。
また、このログには絶対時間のカラムがなく、時間はduration(TimeInSecondsカラム)で表現される。そのため、絶対時間はファイル名内のロギング開始日時+durationで算出する必要がある。
取り込み時の_timeはファイル名から取ってサーチ時にevalで再計算をすることは可能だが、internal fieldを毎回弄るのは非効率だしサーチ時の時間範囲の指定が不自由になるので、インデックス時に_timeをうまいこと設定する方法がないか調べた。その結果、INGEST_EVALが使えそうだった。 docs.splunk.com

INGEST_EVALは7.2で追加されたtransforms.confのアトリビュートで、evalで処理した後のイベントをインデクサーへ送信できるというもの。
以下のようにprops.confとtransforms.confを設定することで、ファイル名内のロギング開始日時+durationを'_time'としたイベントをインデックスすることができた。

### props.conf
[ocat]
HEADER_FIELD_LINE_NUMBER = 1
INDEXED_EXTRACTIONS = csv
KV_MODE = none
LINE_BREAKER = ([\r\n]+)|([\n]+)
NO_BINARY_CHECK = true
SHOULD_LINEMERGE = false
TRUNCATE = 0
TZ = Asia/Tokyo
category = Custom
description = OCAT Capture Log
disabled = false
pulldown_type = true
TRANSFORM-time = extract_ocat_time

### transforms.conf
[extract_ocat_time]
INGEST_EVAL = _time=strptime(replace(source,".*OCAT-.+?(?=\d{4})(\d{4}-\d{2}-\d{2}T\d{6})\.csv$","\1"),"%Y-%m-%dT%H%M%S")+TimeInSeconds

INGEST_EVALを使って開始日時とdurationの情報しかないログの'_time'をインデックス時に設定#splunk pic.twitter.com/ZPqI4RtUIr
— げんまいろえ (@kqlg4) 2019年7月15日

漆黒ベンチのフレームレートをタイムチャートにしてみた。上で記載したWrite performance summaryにチェックを入れ忘れていたため、別のフィールドからフレームレートを算出している。 f:id:keroqueue:20190724033825p:plain

フレームレートにCPU, GPUのパフォーマンスをオーバーレイするとこんな感じ。 f:id:keroqueue:20190724042745p:plain f:id:keroqueue:20190724041408p:plain

フレームレートがガクッと下がる時はCPUの負荷が高まっているのに対してGPUの負荷が下がっている。このことから、GPUの処理速度にCPUが追い付いておらず、CPUにボトルネックがあるのではと予想がつく。
もしGPU負荷が高い状態でフレームレートが出ていないのであれば、GPUのスペック不足である可能性が高い。

問題発覚

GPU-Z, CPUパフォーマンス, OCATの3種のログを取りながら漆黒ベンチを回すと、GPU-Zのみの時よりも1000以上スコアに差があることに気がついた(爆)
この差はさすがに無視できないため、必要なログを取得できる別の方法を探すことに。

ログ	スコア	平均フレームレート[fps]	最低フレームレート[fps]	ローディングタイム合計(s)
GPU-Z	11586	88.31619	36	19.62
GPU-Z+CPUパフォーマンス+OCAT	10163	80.26615	33	19.925

MSI Afterburner へ

色々調査した結果、MSI Afterburnerが良さそうなので試してみることに。

www.msi.com

Afterburnerでロギングできる項目は以下。GPU-Z+CPUパフォーマンス+OCATと比べて遜色ない。

[GPU]

GPU temperature
GPU usage
FB usage
VID usage
BUS usage
Memory usage
Core clock
Memory clock
Power
Fan speed
Fan speed 2
Fan tachometer
Fan tachometer 2
Temp limit
Power limit
Voltage limit
No load limit

[CPU]

CPU1-n temperature
CPU temperature
CPU1-n usage
CPU usage
CPU1-n clock
CPU clock
CPU power

[Memory]

RAM usage
Commit charge

[Framerate]

Framerate
Frametime
Framerate Min
Framerate Avg
Framerate Max
Framerate 1% Low
Framerate 0.1% Low

ログは拡張子が.hmlとなっており、開くと専用のビュアーが立ち上がる。 f:id:keroqueue:20190725010555p:plain

テキストとして開くと中身はcsv。先頭のカラムがログ種別を示しているようで、00はバージョン情報、01はGPU情報、02はカラム情報、03は単位やグラフのmax, minなどの情報、80がログとなっているようだ。 f:id:keroqueue:20190725011120p:plain f:id:keroqueue:20190725011146p:plain

splunkへの取り込みは02の行をカラム名とすればよさそう。
あと気になるのはパフォーマンスへの影響。GPU-Zのみ、GPU-Z+CPUパフォーマンス+OCAT、Afterburnerのみで、漆黒ベンチの結果を比べてみた。

ログ	スコア(MAX比)	平均フレームレート(MAX比)[fps]	最低フレームレート(MAX比)[fps]	ローディングタイム合計(s)
なし	11703	89.0257	36	19.935
GPU-Z	11586 (0.99)	88.31619 (0.99)	36 (1)	19.62
GPU-Z+CPUパフォーマンス+OCAT	10163 (0.87)	80.26615 (0.90)	33 (0.92)	19.925
Afterburner	11496 (0.98)	87.49484 (0.98)	36 (1)	20.192

GPU-Zのみの場合よりは若干負荷がかかっているが、MAX-2%くらいなら許容範囲ということにして、Afterburnerを採用する。

今回の学び

perfmon://スタンザでWindowsパフォーマンスカウンターの値を送信することができる
INGEST_EVALを使うことで、evalで処理した後のイベントをインデクサーへ送信することができる (7.2以降)

ToDo

CPUパフォーマンス取得とOCAT、負荷がかかっているはどっち?
要件, 設計見直し (app名や取り込みログなど)
Afterburnerログ取り込み, フィールド定義
ダッシュボード開発

所感と雑記

色々取り込んだログは必要なくなったが、急がば回れ。Afterburnerのログのみで完結できそうなので、ベストな状態になったと思う。
そして...

きたた〜 pic.twitter.com/KOtXG1WkDk
— げんまいろえ (@kqlg4) 2019年7月21日

keroqueue logs

アウトプット癖をつけるために始めました。何を書くかはよくわかりません。

Windows PCのゲーミングパフォーマンスをSplunkで可視化する #2 CPU, フレームレートのログ追加

概要