シーケンサーでのキャラクターへのアニメーション適用の遅延に関して

私たちのプロジェクトではTPS視点のインゲーム状態からシーケンサーを用いたイベント演出への切り替えを、暗転を用いずシームレスに行うことを目指しています。

しかし、シーケンサーの開始フレームにカメラとキャラクターのアニメーション再生を設定していても、カメラターゲットの切り替えに対してキャラクターのアニメーション適用が遅れてしまう問題が発生しています。

具体的にはシーケンサーを UMovieSceneSequencePlayer::Play() で再生開始してカメラが先に切り替わったあと、stat表示の更新が3回ほど行われたあとにアニメーションが適用されます。

UMovieSceneSequencePlayer::GetCurrentTime() を使ってシーケンサーの再生中フレームを確認していると、カメラが切り替わってからアニメーションが切り替わる直前のコマまで0のままになっており、アニメーションが切り替わったコマから1→2→3→… となっていました。

キャラクターへのアニメーション適用は下記ページを参考に、アニメーションセクションからアニメーションスロットを指定し、アニメーションブループリントでそのアニメーションスロットを参照することで行っています。

https://dev.epicgames.com/documentation/ja\-jp/unreal\-engine/blend\-gameplay\-animation\-to\-cinematic\-animation\-in\-unreal\-engine

改善策がありましたらご教示お願いいたします。

[Attachment Removed]

お世話になっております。

お問い合わせありがとうございます。

シーケンサーの開始フレームにカメラとキャラクターのアニメーション再生を設定していても、UMovieSceneSequencePlayer::GetCurrentTime()が0のまましばらくカウントが始まらず、アニメーションも動作しないとのことでしたが、こちらの「カメラの切り替え」はどのように設定されておられるか、念のため確認させてください。

・Cine Camera Actor トラックによるカメラ切り替えでしょうか?

・その場合、カメラにはアニメーションは入っておりますか?その場合、カメラのアニメーションもキャラクターへのアニメーションと同様、遅延しますでしょうか?

・また、参照先のURLにあるカメラカットトラックによるゲームカメラとのブレンドテクニックはお使いでしょうか?

・もし異なる方法でカメラを切り替えている場合は、実装について簡単にご説明いただけますと幸いです。

以上、よろしくお願いいたします。

[Attachment Removed]

お世話になっております。

お返事いただきありがとうございます。

>Cine Camera Actor トラックによるカメラ切り替えでしょうか?

はい。Cine Camera Actor トラックを配置し、Cine Camera Actor の座標やパラメータを調整のうえ、その Cine Camera Actor を カメラカットトラック の Camera Binding ID で紐づける形でカメラの切り替えを行っています。

>その場合、カメラにはアニメーションは入っておりますか?その場合、カメラのアニメーションもキャラクターへのアニメーションと同様、遅延しますでしょうか?

カメラにはアニメーションは入っておりません。カメラの座標を手動で入力しています。

>また、参照先のURLにあるカメラカットトラックによるゲームカメラとのブレンドテクニックはお使いでしょうか?

現状使っておりません。

以上、よろしくお願いいたします。

[Attachment Removed]

ありがとうございます。

再現がとれない旨承知いたしました。

また遅延が起きうる事例についての情報のご共有ありがとうございます。

以下ご質問に回答させていただきます。

>・当該シーケンサーを再生する手順(例: レベルブループリントから Play() など)

C++でUObjectを継承したイベント演出のマネージャークラスを作成しており、`FWorldDelegates::OnWorldPreActorTick.AddUObject`でそのマネージャークラスの更新処理を登録しています。

この登録した更新処理の中から Play() を呼んでいます。

>・当該シーケンサーの fps や Clock Source の設定

右記の設定です。fps: 60fps、Clock Source: Tick

>・t.maxfps コンソールコマンドを利用して、シーケンサーのfpsとゲームのfpsを合わせた場合(たとえばシーケンサーが30fpsなら、t.maxfps 30とする)にどうなるか。再生遅延やUMovieSceneSequencePlayer::GetCurrentTime()を取得したデバッグにおいて、なにか変化がみられるか?

こちらで症状が発生した状況で、すでにシーケンサーのfpsとゲームのfpsを合わせた状態になっていました。繰り返しになりますが 60fps で合わせております。

逆に片方を30fpsにした状態などでこちらでも何か変化するか確認を進めてさせていただこうと思います。

取り急ぎ回答となります。

以上、よろしくお願いいたします。

[Attachment Removed]

お世話になっております。

ご回答いただいた内容につきましてそれぞれ検証させていただきました。

まず オンラインストレージのご用意につきまして、ぜひお願いできればと思います。

なお、ログファイルについてはご提出が可能なのですが、Unreal Insights のキャプチャにつきましては機密情報を含む可能性が高いためご提出が難しい状況です。

Unreal Insights のキャプチャにつきまして、機密情報を含まない形でのご共有方法(一部スクリーンショットの切り出しなど)がございましたらぜひご教示お願いできればと思います。

以下、「カメラにダミーのアニメーションを入れる」「LogMovieSceneのログレベル変更」の検証結果について記載させていただきます。

>■カメラにダミーのアニメーションを入れる

カメラのTransformTrackに1フレームごとキーを打って簡単なダミーアニメーションを作成して再生し、動画を撮って確認しました。

後述の LogMovieSceneのログレベル変更 についての検証結果でも触れますが、PIE起動後1回目のシーケンサー再生と2回目以降のシーケンサー再生で結果が異なりましたのでそれぞれについて記載させていただきます。

1回目

動画をコマ送りで確認したところ、シーケンサー再生開始直後に1コマでシーケンサーの再生中フレームが5フレームほど飛んでしまっていました。

具体的には1コマ飛ばすとシーケンサー未再生の状態から再生中フレームが 5.78 まで飛んでいました。飛んだ先の 5.78フレーム ではカメラはシーケンサーの0フレーム目のアニメーションが適用されており、キャラはアニメーションが適用されていない状態でした。

もう1コマ進めて 6.78フレーム ではカメラについてはそのフレームのアニメーションが適用される一方、キャラはまだアニメーションが適用されていない状態でした。

その後コマ送りを進めて 13.78 フレームでキャラについてもアニメーションが適用されました。

2回目以降

同様に動画をコマ送りで確認したところ、シーケンサー再生開始直後 5コマほど再生中フレームが 0フレームのまま停止していました。この間カメラはシーケンサーの0フレームのアニメーションが適用されており、キャラはアニメーションが適用されていない状態でした。

その後 シーケンサーの再生中フレームが 2.00フレーム でカメラ、キャラともにそのフレームのアニメーションが適用されました。

>■LogMovieSceneのログレベル変更

起動引数 -LogCmds=“LogMovieScene VeryVerbose” を追加してログを確認しました。

こちらに関しても PIE起動後1回目のシーケンサー再生と2回目以降のシーケンサー再生で結果が異なりました。

1回目

Evaluating Sequence at frame のログ が 0,1,2,… と重複せず順番に表示されていました。

冒頭部分のログを転記いたします。

```

LogMovieScene: Verbose: Initialize - MovieSceneSequence: LS_TEST_SEQUENCE, TickResolution: 24000 fps, DisplayRate: 60 fps

LogTemp: CutScene Start

LogMovieScene: Verbose: PlayInternal - LS_TEST_SEQUENCE (current status: EMovieScenePlayerStatus::Stopped)

LogMovieScene: VeryVerbose: TimeController PrepareToPlay: Sequence started preparing: frame 0, subframe 0.000000. Frame rate: 60.000000 fps.

LogMovieScene: VeryVerbose: TimeController Start: Sequence started: frame 0, subframe 0.000000. Frame rate: 60.000000 fps.

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: Verbose: Starting new camera cut: ‘CineCameraActor_0’

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 1, subframe 0.000002 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 1, subframe 0.999987 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 2, subframe 0.999971 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 4, subframe 0.784105 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 5, subframe 0.784090 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 6, subframe 0.784075 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 7, subframe 0.784060 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 8, subframe 0.784044 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 9, subframe 0.784029 (60.000000 fps).

```

2回目以降

Evaluating Sequence at frame 0 のログが 重複して11個ほど表示されたあとに、1,2,3,… と表示されていました。

同様に冒頭部分のログを転記いたします。

```

LogMovieScene: Verbose: StopInternal - LS_TEST_SEQUENCE (at: Frame: 299 Subframe: 1.000000, current status: EMovieScenePlayerStatus::Stopped)

LogMovieScene: Verbose: Initialize - MovieSceneSequence: LS_TEST_SEQUENCE, TickResolution: 24000 fps, DisplayRate: 60 fps

LogTemp: CutScene Start

LogMovieScene: Verbose: PlayInternal - LS_TEST_SEQUENCE (current status: EMovieScenePlayerStatus::Stopped)

LogMovieScene: VeryVerbose: TimeController PrepareToPlay: Sequence started preparing: frame 0, subframe 0.000000. Frame rate: 60.000000 fps.

LogMovieScene: VeryVerbose: TimeController Start: Sequence started: frame 0, subframe 0.000000. Frame rate: 60.000000 fps.

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: Warning: Found 1 duplicate object(s) while resolving binding GERALT (BE8BC600441740BB1FC8449CABC73903) in /Game/Event/Test/ZeroFrameTest/LS_TEST_SEQUENCE.LS_TEST_SEQUENCE

LogMovieScene: Verbose: Starting new camera cut: ‘CineCameraActor_1’

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.000000 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 0, subframe 0.999756 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 1, subframe 0.999969 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 2, subframe 0.999725 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 3, subframe 0.999939 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 5, subframe 0.259247 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 6, subframe 0.259003 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 7, subframe 0.259216 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 8, subframe 0.258972 (60.000000 fps).

LogMovieScene: VeryVerbose: Evaluating sequence LS_TEST_SEQUENCE at frame 9, subframe 0.259186 (60.000000 fps).

```

以上、よろしくお願いいたします。

[Attachment Removed]

お世話になっております。

ご返答ありがとうございます。

期間が空いてしまい大変恐縮ですが、遅ればせながらオンラインストレージへログとUnreal Insightsのキャプチャ結果をアップロードさせていただきました。

それぞれファイル名が「1回目」「2回目」となっておりますが、PIE起動後初回のシーケンサー再生時のものが「1回目」、2回目のシーケンサー再生時のものが「2回目」となっております。

ご確認いただけますと幸いです。

また不備がございましたらご連絡お願いいたします。

>シーケンスプレイヤーから現在の再生地点を取得して画面にデバッグ出力しておられると推測しますが、念のためどのような実装で取得されているか確認させていただいてもよろしいでしょうか。

下記のような関数を作成してシーケンスプレイヤーの現在の再生地点を取得しています。

float CurrentTime(ULevelSequencePlayer* LSPlayer)
{
	if (!LSPlayer) return 0;
	int32 CurrentFrame = LSPlayer->GetCurrentTime().Time.FrameNumber.Value;
	float SubTime = LSPlayer->GetCurrentTime().Time.GetSubFrame();
	return CurrentFrame + SubTime;
}

これを利用したデバッグ文字列表示処理を、前述の「C++でUObjectを継承したイベント演出のマネージャークラス」の FWorldDelegates::OnWorldPostActorTick.AddUObject に登録することで実装しております。

以上、よろしくお願いいたします。

[Attachment Removed]

お世話になっております。

大変お待たせしており申し訳ありません。

いただいたログ強化コードをエンジンに組み込み、ログを取りましたのでオンラインストレージのほうへアップさせていただきました。

それぞれ「1回目_ログ強化.txt」「2回目_ログ強化.txt」のファイルをアップさせていただいております。

以上、よろしくお願いいたします。

[Attachment Removed]

ご回答ありがとうございました。

ご回答をもとに、当方で簡単な再現プロジェクトを組んでみたのですが、現時点では再現ができておりません。

確かに、設定や呼び出し方によってはシーケンサーのアニメーション再生がアクタに反映されるまで遅延が生じることがあります。

たとえば、アクタのTickからシーケンサーのPlay()を呼び出した場合、そのフレームでは MovieSceneSequenceTick がすでに終了しているため、次フレームで初めてシーケンスプレイヤーのTimeが進むことになります(構造上の1フレームの遅延)。一方、カメラのビューポートへの反映はそのフレームで行われるため、そこに1フレームのギャップを感じる可能性はあります。

ただし、

> UMovieSceneSequencePlayer::GetCurrentTime() を使ってシーケンサーの再生中フレームを確認していると、カメラが切り替わってからアニメーションが切り替わる直前のコマまで0のままになっており、アニメーションが切り替わったコマから1→2→3→… となっていました。

こちらのご報告を拝見するに、シーケンサーのプレイヤーの再生中フレームが0のまま、何フレームか留まっていたということですので、「キャラクターへのアニメーション適用が遅延した」というより、「シーケンサーのプレイヤーの再生進行が即座に始まらなかった」という症状のように感じられます。シーケンサー全体が再生地点0に留まっていますので、もしカメラにアニメーションがついていれば、同様に遅延するはずです。

さらに調査を進めてまいりますが、いくつか、追加で確認させていただきたいことがあります。

・当該シーケンサーを再生する手順(例: レベルブループリントから Play() など)

・当該シーケンサーの fps や Clock Source の設定

・t.maxfps コンソールコマンドを利用して、シーケンサーのfpsとゲームのfpsを合わせた場合(たとえばシーケンサーが30fpsなら、t.maxfps 30とする)にどうなるか。再生遅延やUMovieSceneSequencePlayer::GetCurrentTime()を取得したデバッグにおいて、なにか変化がみられるか?

以上、よろしくお願いいたします。

[Attachment Removed]

お世話になっております。

ご回答ありがとうございます。

fpsやClock Sourceの情報をありがとうございました。特に問題となる設定ではないようです。

開発チームとも協議いたしましたが、社内外に類似の例がなく、Play()してからGetCurrentTime()​が始まるまで、なぜシーケンスプレイヤーのみが固まってしまうのか、もう少し追加の情報が必要という結論となりました。

元投稿で、​

> stat表示の更新が3回ほど行われたあとにアニメーションが適用されます。

とおっしゃられていたことから、ゲームは固まっておらず、ゲームフレームが3 Tickほど進行したあとでシーケンスプレイヤーの再生が始まるという現象が起きていると解釈しております。

状況の調査のために以下をお試しいただけますでしょうか。

■カメラにダミーのアニメーションを入れる

​もし可能であれば、カメラのほうにもダミーで動きをつけていただくと、「キャラのアニメーション適用だけが遅延しているのか」それとも「シーケンサー全体で遅延しているのか」の判定が視覚的に行えると思います。

■LogMovieSceneのログレベル変更

起動引数 -LogCmds=“LogMovieScene VeryVerbose” か、

もしくはプロジェクトの DefaultEngine.ini に、

[Core.Log]
LogMovieScene=VeryVerbose

を記述し、カットシーン再生時になにかおかしなログが記録されていないか見ていただくことはできますでしょうか。​特に、Play() 呼び出し後のフレームごとに「Evaluating sequence … at frame N」というログが出力されるはずですので、frame が 0 のままになっているフレームが何フレーム続くか確認できるのではないかと考えております。

​これにより、0フレーム目で足踏みしているのか、評価は進行しているがアニメーション適用が遅延しているのか、あるいは評価の開始が停滞(再生が即開始されない)のかを見極められると思われます。

​そのため、カットシーン再生時のPlay()呼び出し付近にも何らかのログ("CutScene Start"など)を出していただけますと、ログ解析時に目印になります。

■Unreal Insightsキャプチャ

Unreal Insightsでカットシーン開始時前後の状況をキャプチャしていただくことは可能でしょうか?

・カットシーン再生時に「CutScene Start」などのブックマークを仕込んでおく(TRACE_BOOKMARK(TEXT(“CutScene Start”));など)

・Traceチャンネルは -trace=default -statnamedevent で指定

・カットシーンが始まる前にTrace開始​

のように手配していただくのが理想です。​

ログファイル、utraceファイルはご提供いただければ当方でも解析いたします。よろしければ提出用のオンラインストレージ(Box)を準備しますので、お申し付けください。

​以上、よろしくお願いいたします。​

[Attachment Removed]

​お世話になっております。

ご確認および貴重な情報をありがとうございます。

オンラインストレージへの招待を別途メールにて送らせていただきましたので、ご確認ください。

機密情報に関するお話も別途メール差し上げましたのでご確認いただけますと幸いです。

動画の観測とログのお話を整理しますと、

■1回目の場合

・ログは0, 1, 2, 3...と先頭フレームからなめていっているにも関わらず、レンダリングに反映されず、5フレーム後にようやく反映されるもキャラは動かず

・このときキャラのアニメが1フレーム遅れるのであればまだ説明が効くのに、さらに5フレーム遅れてようやく適用

■2回目の場合

・ログは0フレームで10フレーム以上0コマ目で停滞を記録、見た目は​シーケンサー再生開始直後5コマほど 0フレームのまま停止

・​シーケンサーの再生フレームが「2フレーム」に達したとき、カメラとキャラの適用が開始

というお話かと思います。

シーケンサーの再生中フレームを記録してくださっているのが調査の大きな助けになっております。

シーケンスプレイヤーから現在の再生地点を取得して画面にデバッグ出力しておられると推測しますが、念のためどのような実装で取得されているか確認させていただいてもよろしいでしょうか。

※併せてメールの方もご確認いただけますと幸いです。

以上、よろしくお願いいたします。​

[Attachment Removed]

お世話になっております。

ログファイルと.utraceのご提供ありがとうございました。

[Image Removed]​拝見しましたところ、確かにシーケンス再生開始のフレームに紐づく描画処理で2-3フレーム相当の大きなヒッチが発生しており(画像は「2回目」のもの)、疑わしい描画の固まりが発生している可能性があります。ただ、一方でログファイルのほうには 0 フレーム目のまま再生地点で動かないログが記録されていたり、観察上は 0... 1... 2... とフレームを順番になめていっているのに、絵的には2フレームほど飛ぶ場合が報告されていたりなど、描画停滞だけでは説明できないものがあります。

そこで大変お手数ですが、以下のログ強化コードをエンジン側に仕込み、​もう一度「1回目」と「2回目」のログを取得し、ご提出願えませんでしょうか。Evaluationにおいて、シーケンサーの再生が「0フレーム目」で停滞してしまう原因を突き止めたいと考えています。

Engine/Source/Runtime/MovieScene/Private/MovieSceneSequencePlayer.cpp L:693付近

 void UMovieSceneSequencePlayer::SetPlaybackPosition(FMovieSceneSequencePlaybackParams InPlaybackParams)
 {
+	UE_LOG(LogMovieScene, VeryVerbose, TEXT("[F%llu] SetPlaybackPosition: PositionType=%d, UpdateMethod=%d, bHasJumped=%d"), (unsigned long long)GFrameCounter, (int)InPlaybackParams.PositionType, (int)InPlaybackParams.UpdateMethod, InPlaybackParams.bHasJumped ? 1 : 0);
 	if (Observer && !Observer->CanObserveSequence())
 	{
 		return;

同ファイル L:1140​ 付近

 void UMovieSceneSequencePlayer::UpdateTimeCursorPosition(FFrameTime NewPosition, EUpdatePositionMethod Method, bool bHasJumpedOverride)
 {
+	UE_LOG(LogMovieScene, VeryVerbose, TEXT("[F%llu] UpdateTimeCursorPosition: NewPos frame=%d subframe=%f, Method=%d, bHasJumped=%d"), (unsigned long long)GFrameCounter, NewPosition.FrameNumber.Value, NewPosition.GetSubFrame(), (int)Method, bHasJumpedOverride ? 1 : 0);
 	if (ensure(!IsEvaluating()))

同ファイル L:1450 ​ 付近

 	{
 		const FQualifiedFrameTime CurrentTime = GetCurrentTime();
 		const FString SequenceName = GetSequenceName(true);
-		UE_LOG(LogMovieScene, VeryVerbose, TEXT("Evaluating sequence %s at frame %d, subframe %f (%f fps)."), *SequenceName, CurrentTime.Time.FrameNumber.Value, CurrentTime.Time.GetSubFrame(), CurrentTime.Rate.AsDecimal());
+		UE_LOG(LogMovieScene, VeryVerbose, TEXT("[F%llu] Evaluating sequence %s at frame %d, subframe %f (%f fps) [Status=%s, TCState=%d, bSkipNext=%d]."), (unsigned long long)GFrameCounter, *SequenceName, CurrentTime.Time.FrameNumber.Value, CurrentTime.Time.GetSubFrame(), CurrentTime.Rate.AsDecimal(), *UEnum::GetValueAsString(GetPlaybackStatus()), (int)TimeControllerState, bSkipNextUpdate ? 1 : 0);
 	}

Engine/Source/Runtime/MovieScene/Private/MovieSceneTimeController.cpp L:206付近

 void FMovieSceneTimeController_Tick::OnTick(float DeltaSeconds, float InPlayRate)
 {
 	CurrentOffsetSeconds += DeltaSeconds * InPlayRate;
+	UE_LOG(LogMovieScene, VeryVerbose, TEXT("[F%llu] TimeController_Tick OnTick: DeltaSeconds=%f, PlayRate=%f -> CurrentOffsetSeconds=%f"), (unsigned long long)GFrameCounter, DeltaSeconds, InPlayRate, CurrentOffsetSeconds);
 }

​​以上、よろしくお願いいたします。

[Attachment Removed]

お世話になっております。

ログの強化策をお試しいただき、ありがとうございました!

ログを精査する中で、一点気になるところが見つかりました。

2回目のログの「TimeController_Tick OnTick…」の出力のところで、シーケンス開始から都合9フレームほど「PlayRate」が「0.000」に設定されていることが記録されております。当方で調べた限りでは、エンジンコードの中に自主的にPlayRateを0.0に設定するコードパスは見つかっておらず、この指定はAPIにパラメータとして渡された可能性が高いと考えております。

これは1回目のログでは確認されておらず、2回目のみの現象といえます。

以前、アニメ適用の遅延を録画してコマ送りで確認された際に、

> 同様に動画をコマ送りで確認したところ、シーケンサー再生開始直後 5コマほど再生中フレームが 0フレームのまま停止していました。

というご報告をいただいておりました。もしこの動画が30fpsで撮影されたものなら、PlayRate = 0.0の9フレーム区間は5コマの停止をかなりうまく説明できるかもしれませんが、仮に60fps撮影であったとしても調べる価値はあると思います。大変恐縮ですが、ゲームコード側で再生を制御する中でPlayRateを触っているコードがないか、ご確認いただくことはできますでしょうか。再生開始後の 0.0 だけでなく、しばらくして 1.0 が再セットされている点にも注目しております。何らかの制御が入っていると思われます。

全体として、当方は今のところ、

・①シーケンス再生開始時に発生するヒッチ(特に1回目)

・②パイプライン上の遅延(1-2フレームほど)

・③PlayRate = 0.0制御の存在

の3点の組み合わせで適用遅延が起きているのではないかと考えております。

本日確認をお願いしたいのはこの3点目となります。

1点目に関しては、お預かりしている.utraceを改めて解析し、社内の知見ともすり合わせて発生の可能性を確認して参ります。

解決まで時間を要してしまい誠に申し訳ありません。一旦お返事申し上げます。

以上、よろしくお願いいたします。

[Attachment Removed]

お世話になっております。

お預かりした .utrace およびログの解析を進めてまいりましたが、​先日お尋ねした PlayRate = 0.0 の疑問点以外の決定打をつかみかねており、追加の切り分けと調査をお願いいたしたくご返信申し上げます。

> 動画をコマ送りで確認したところ、シーケンサー再生開始直後に1コマでシーケンサーの再生中フレームが5フレームほど飛んでしまっていました。

> 具体的には1コマ飛ばすとシーケンサー未再生の状態から再生中フレームが 5.78 まで飛んでいました。飛んだ先の 5.78フレーム ではカメラはシーケンサーの0フレーム目のアニメーションが適用されており、キャラはアニメーションが適用されていない状態でした。

​こちらについては、5フレーム飛んだのではなく、「シーケンサー再生開始」のデバッグ表示を画面に出すところを含めて、5フレーム近く描画が停止していたのではないかと睨んでおります。これを考えたとき、第8236フレームのGPU0のレーンにある36.7ms の「LumenSceneUpdate(18 card captures)」と、RHIスレッドの34.4msのDLSS処理が気になっており、これらの処理を短縮した際に遅延も縮まるかどうかをみて、影響を確認したい次第です。

・1. カットシーン再生前にコマンド r.LumenScene.SurfaceCache.Freeze 1 ​を実行してLumenのカード更新を停止(GIや反射が不正確になります)

・2. DLSS関連処理のトリガーを抑制

→カットシーン再生前に r.ScreenPercentage 100 が実行されていることがBookmarkに残っており、このコマンドを発行しないように一時的に変更すれば抑制できるのではないかと考えております。

という2点の一時的な変更をほどこして、遅延問題がどの程度緩和されるか再観察していただけませんでしょうか。​もし変化がみられるようであれば、「1のみ→2のみ→両方」という手順で実験をして、どちらの影響が支配的であるか確認いただけると助かります。

> 飛んだ先の 5.78フレーム ではカメラはシーケンサーの0フレーム目のアニメーションが適用されており、キャラはアニメーションが適用されていない状態でした。

> もう1コマ進めて 6.78フレーム ではカメラについてはそのフレームのアニメーションが適用される一方、キャラはまだアニメーションが適用されていない状態でした。

> その後コマ送りを進めて 13.78 フレームでキャラについてもアニメーションが適用されました。

こちらについては、​過去の事例や.utraceから手がかりをつかむことができず、何らかの事情でシーケンサーから送り込まれたアニメーションがスキニングに反映されていない可能性を疑っております。こちらも切り分けのため、以下の作業とロギング強化を行い、再観察をお願いできればと思います。ログも頂戴できると助かります。

・3.シーケンサーで動かすSkeletal MeshのAnimation Modeを「Custom」に変更

・Animation セクションを右クリック>Properties>Playback→「Force Custom Mode」をオン

・この変更によりアニメーションがAnimBPのスロットを経由せず、Sequencerから直接適用されるようになります。​これで遅延が解消される場合、AnimBP周りで何かトラブルが生じているのではないかという切り分けが可能になります。

・4.以下の追加ログを仕込む​

​Engine\Source\Runtime\MovieSceneTracks\Private\Systems\MovieSceneSkeletalAnimationSystem.cpp:895

		if (!CanPlayAnimation(Params.SkeletalMeshComponent, Animation))
		{
+			UE_LOG(LogMovieScene, VeryVerbose, TEXT("[F%llu] SetAnimPosition: CanPlayAnimation=FAIL Comp=%s Mesh=%s Anim=%s"),
+				(unsigned long long)GFrameCounter,
+				*GetNameSafe(Params.SkeletalMeshComponent),
+				Params.SkeletalMeshComponent ? *GetNameSafe(Params.SkeletalMeshComponent->GetSkeletalMeshAsset()) : TEXT("null"),
+				*GetNameSafe(Animation));
			return;
		}
 
		UAnimSequencerInstance* SequencerInst = GetAnimSequencerInstance(Params.SkeletalMeshComponent);
		if (SequencerInst)
		{
+			UE_LOG(LogMovieScene, VeryVerbose, TEXT("[F%llu] SetAnimPosition[Custom]: Comp=%s Anim=%s From=%.4f To=%.4f W=%.3f bPlaying=%d"),
+				(unsigned long long)GFrameCounter,
+				*GetNameSafe(Params.SkeletalMeshComponent),
+				*GetNameSafe(Animation),
+				Params.FromPosition, Params.ToPosition, Params.Weight,
+				Params.bPlaying ? 1 : 0);
			PreAnimatedAnimInstanceStorage->BeginTrackingEntity(Params.EntityID, Params.bWantsRestoreState, Params.RootInstanceHandle, SequencerInst);
			PreAnimatedAnimInstanceStorage->CachePreAnimatedValue(FCachePreAnimatedValueParams(), SequencerInst);
 
// ... 中略
 
			const float AssetPlayRate = FMath::IsNearlyZero(Animation->RateScale) ? 1.0f : Animation->RateScale;
			TWeakObjectPtr<UAnimMontage> WeakMontage = FAnimMontageInstance::SetSequencerMontagePosition(
					AnimParams.SlotName,
					AnimInst,
					InstanceId,
					Animation,
					Params.FromPosition / AssetPlayRate,
					Params.ToPosition / AssetPlayRate,
					Params.Weight,
					bLooping,
					Params.bPlaying);
 
+			UE_LOG(LogMovieScene, VeryVerbose, TEXT("[F%llu] SetAnimPosition[Slot]: Comp=%s AnimInst=%s Slot=%s Anim=%s Montage=%s InstId=%d From=%.4f To=%.4f W=%.3f bPlaying=%d"),
+				(unsigned long long)GFrameCounter,
+				*GetNameSafe(Params.SkeletalMeshComponent),
+				*GetNameSafe(AnimInst),
+				*AnimParams.SlotName.ToString(),
+				*GetNameSafe(Animation),
+				*GetNameSafe(WeakMontage.Get()),
+				InstanceId,
+				Params.FromPosition, Params.ToPosition, Params.Weight,
+				Params.bPlaying ? 1 : 0);

また、恐れ入りますが、以前ご撮影いただいた動画について追加で2点ご確認いただけますでしょうか(再撮影は不要です)

・ ① 0〜13.78 フレームの間、キャラクターは「完全に静止」していましたか、それとも「通常のアイドル等のアニメーションが動いて」いましたでしょうか

・ ② 13.78 フレームでアニメーションが適用された瞬間は、「1コマでパチッと切り替わる」形でしたか、それとも「数コマかけてクロスフェードする」形でしたでしょうか

​​毎度お手数をおかけしますが、よろしくお願いいたします。

[Attachment Removed]

お世話になっております。

お返事をお待たせしてしまって大変申し訳ございません。

お返事の準備が整いましたので、ご相談を再開させていただけますと幸いです。

何卒よろしくお願いいたします。