フォーラム › TuneBrowser › 一時的に再生が停滞して10数秒後に再開
-
投稿者投稿
-
2023-04-04 02:10 #13306Noir参加者
Tikiさん、はじめまして。
タイトルの現象は 5.2.2 UWP 版で以下の状況で発生しました。
・RAMDecode(すべて)
・ランダム再生
・WASAPI(Exclusive Event)現象発生中の動画を添付します。
(*動画は466kBまでサイズを落としていますが不適切でしたら削除お願いいたします)現象が発生してからの記録のため途中からですが、再生時間 0:51 で Player View の Time やインジゲーターが止まり、フリーズしかたかな?!と思ったのですが、録画中に 0:52, 0:53 と普通に再生が再開しました。現象発生から10数秒くらいだと思います。
なお、今回はじめて発生しました。これまでは以下の設定にしており、先週水木金土の4日間毎日10時間連続再生で発生しませんでした。
・RAMDecode(すべて)
・リピート再生
・Bit Perfect(BP2)
・WASAPI(Exclusive Event)リピート再生の有無とランダム再生の有無とBP2の有無が違いとなります。
これだけで原因を特定することは難しいと思いますので、次回発生時に何か調査のために役立つ情報収集ができれば、と思い投稿させていただきました。
よろしくお願いいたします。
Attachments:
2023-04-04 19:29 #13311Tikiキーマスターこんにちは。適切なサイズの動画ありがとうございます。
デコード待ちが発生したのかと予想しましたが、そうではありませんでした。スペクトル表示も完全に止まっていることから、おそらくビデオカードあたりで一時的なフリーズが発生したのではないかと思います (わたしのPCも含めて、環境によってはときどき発生しています。長くなると「予期しない状態を検知した」と表示されることもあります)。
2023-04-04 19:35 #13313Noir参加者Tikiさん、早速のご返事ありがとうございます。
恥ずかしながら Log Viewer の存在を知らなかったのですけど、フォーラムの他の投稿を拝見して存在を知りました。今度発生したときはログも参照してみます。
2023-04-08 05:24 #13335Noir参加者本日、再発しました。
Log Viewer の「Log」を拝見すると同じ曲が短時間に呼び出されていました。また「Player」を拝見すると 23:08 以前のログが消えていたので Nat King Cole\St. Louis Blues\05 Stay.wav のみの確認となりますが、デバイスのリスタートがなぜか走っていて、起動後同じ 72 秒にシークして再生するも再びリスタートする、という状況が 0.12~0.15 秒程度の間隔で繰り返されている状況でした。
UL32621: 2023/04/07 23:08:32,561: T00d2c: TL17: Restart device.
UL32742: 2023/04/07 23:08:32,600: T00d2c: TL17: Post PlayerNotify: 8677 [Seeked]
UL32760: 2023/04/07 23:08:32,689: T00d2c: TL17: Proc: [Seek] to 72.000 sec.
UL32761: 2023/04/07 23:08:32,689: T00d2c: TL17: Restart device.
UL32882: 2023/04/07 23:08:32,723: T00d2c: TL17: Post PlayerNotify: 8685 [Seeked]
UL32900: 2023/04/07 23:08:32,837: T00d2c: TL17: Proc: [Seek] to 72.000 sec.
UL32901: 2023/04/07 23:08:32,837: T00d2c: TL17: Restart device.
UL33022: 2023/04/07 23:08:32,871: T00d2c: TL17: Post PlayerNotify: 8693 [Seeked]
UL33040: 2023/04/07 23:08:32,954: T00d2c: TL17: Proc: [Seek] to 72.000 sec.
UL33041: 2023/04/07 23:08:32,954: T00d2c: TL17: Restart device.
UL33162: 2023/04/07 23:08:32,989: T00d2c: TL17: Post PlayerNotify: 8701 [Seeked]
UL33180: 2023/04/07 23:08:33,305: T00d2c: TL17: Proc: [Seek] to 72.080 sec.
UL33181: 2023/04/07 23:08:33,305: T00d2c: TL17: Restart device.
UL33303: 2023/04/07 23:08:33,349: T00d2c: TL17: Post PlayerNotify: 8709 [Seeked]
UL33320: 2023/04/07 23:08:33,458: T00d2c: TL17: Proc: [Seek] to 72.000 sec.
UL33321: 2023/04/07 23:08:33,458: T00d2c: TL17: Restart device.Attachments:
2023-04-08 05:32 #13337Noir参加者「Log」の該当箇所を張り付けそこないましたので追記します。
UL32606: 2023/04/07 23:08:32,423: T0199c: Calling Lua: OnPlaybackFile
UL32607: 2023/04/07 23:08:32,423: T0199c: – C:\Users\barod\Music\Nat King Cole\St. Louis Blues\05 Stay.wav
UL32608: 2023/04/07 23:08:32,423: T0199c: – 0
UL32609: 2023/04/07 23:08:32,423: T0199c: Calling Lua: Results:
UL32610: 2023/04/07 23:08:32,423: T0199c: –
UL32611: 2023/04/07 23:08:32,423: T0199c: –
UL32746: 2023/04/07 23:08:32,609: T0199c: Calling Lua: OnPlaybackFile
UL32747: 2023/04/07 23:08:32,609: T0199c: – C:\Users\barod\Music\Nat King Cole\St. Louis Blues\05 Stay.wav
UL32748: 2023/04/07 23:08:32,609: T0199c: – 0
UL32749: 2023/04/07 23:08:32,610: T0199c: Calling Lua: Results:
UL32750: 2023/04/07 23:08:32,610: T0199c: –
UL32751: 2023/04/07 23:08:32,610: T0199c: –
UL32886: 2023/04/07 23:08:32,733: T0199c: Calling Lua: OnPlaybackFile
UL32887: 2023/04/07 23:08:32,733: T0199c: – C:\Users\barod\Music\Nat King Cole\St. Louis Blues\05 Stay.wav
UL32888: 2023/04/07 23:08:32,733: T0199c: – 0
UL32889: 2023/04/07 23:08:32,734: T0199c: Calling Lua: Results:
UL32890: 2023/04/07 23:08:32,734: T0199c: –
UL32891: 2023/04/07 23:08:32,734: T0199c: –
UL33026: 2023/04/07 23:08:32,875: T0199c: Calling Lua: OnPlaybackFile
UL33027: 2023/04/07 23:08:32,875: T0199c: – C:\Users\barod\Music\Nat King Cole\St. Louis Blues\05 Stay.wav
UL33028: 2023/04/07 23:08:32,875: T0199c: – 0
UL33029: 2023/04/07 23:08:32,875: T0199c: Calling Lua: Results:
UL33030: 2023/04/07 23:08:32,875: T0199c: –
UL33031: 2023/04/07 23:08:32,875: T0199c: –2023-04-08 17:59 #13339Tikiキーマスターこんにちは。
ログのアップありがとうございます。この事象は、最初にご報告いただいた画面・操作のフリーズが発生したあと、発生したということでしょうか?
デバイスののスタートは、設定項目の
■ ツリー項目: 再生の設定 – WASAPIの設定 – (デバイス名)
■ プロパティ: 基本の設定 – 再生終了時にデバイスも終了させるがYesになっていると、シーク操作後に発生します (既定でYesになっています)。これはシーク時に一時的にデバイスを停止させた後、再開始に失敗するデバイスがあったためで、シークの都度そのように動作させるようになります。
今回のログでは見た目には何回もシーク操作が行われたかのような動作になっています。操作がフリーズしている間に、そのような操作をされたということはないでしょうか?
2023-04-08 18:20 #13340Noir参加者こんにちは、ご返信ありがとうございます。
はい、こちらは昨夜発生した現象になります。
実際手動でのシーク操作はしていない状況でございます。120~150 m sec 間隔での細かい手動操作を数秒間継続して行うことは不可能だと思います。
デバイスのリスタートの解釈が違っていたのでご教授ありがとうございます。デバイス側からリセットがかかっているわけではなかったのですね。
このときは席を外していたので聞いていなかったのと、Log Viewer の Play には残っていなかったのですが、Log には 22:52:34,918 – 22:54:08,500 の間、22:58:15,965 ー 22:58:25,935 の間、22:58:45,592 ー 22:59:07,887 の間にも「Calling Lua: OnPlaybackFile」が連続して記録されています。
考えられる原因はございますでしょうか?
2023-04-08 19:15 #13343Tikiキーマスターシーク操作は、短い間隔で連続して操作されたと考えているわけではなく、時間を置いて操作された結果がフリーズ解除後に一気に処理されたのかと考えました。
他には現在のところ考えられる原因はありません。引き続き検討します。
2023-04-08 19:19 #13344Noir参加者お力添えありがとうございます。
ログをディスクに出力できる設定項目を発見したので、本日からディスクに書き出してみます。
また UWP版も5.2.3が配信されましたので、本日より5.2.3で運用いたします。お手数をおかけいたしております。
引き続きどうぞよろしくお願いします。2023-04-11 01:26 #13359Noir参加者こんばんは!
土曜日は現象発生しませんでしたが、本日は現象が発生し、プレイヤーの起動から現象発生までのログが取得できましたので送ります。
- 17:12:13 ~ 22:08:00 までエラーなく再生
- 22:08:00,816 にアルバムを手動で切り替え
- 22:09:18,599 から Seek 77sec が連続して記録
22:09:18,599: T00a28: TL18: Proc: [Seek] to 77.420 sec.
よろしくお願いいたします。
Attachments:
2023-04-11 19:37 #13363Tikiキーマスターこんばんは。ログの送付ありがとうございました。
内容拝見しましたが、たしかに不可思議にSeekが繰り返されていることは確認できましたが、なぜそのような動作になっているのかはわかりませんでした。
Noirさんは、UWP版をご利用と伺いました。最近のマイクロソフトストアは、特定のユーザー向けにプライベートなリリースを行える機構がありますので、Noirさん向けに、この問題調査用の仕掛けを入れたTuneBrowserをリリースさせていただきたいと思います。
今回のケースは経験したことのない事象のため、おそらく一度では解決できず、複数回のやりとりになると思われます。どうぞその点についてご了承ください。
ご利用のマイクロソフトアカウントは、このフォーラムの登録メールアドレスとおなじでしょうか。異なる場合、ここにはメールアドレスは書かないで、ちがうという旨だけお知らせください。わたしから照会用のメールをお出しさせていただきます。
2023-04-11 21:29 #13364Noir参加者ご返信および多大なご協力ありがとうございます!
2つのアカウントで使用させていただいてますが、フォーラム用のアドレスはどちらとも異なってます。
よろしくお願いします。
2023-04-12 20:12 #13366Tikiキーマスターこんばんは。
アカウントの情報ありがとうございました。先ほど、お届けいただいた2つのメールアドレスに対して調査用のTuneBrowserのリリース手続きを行いました。これはマイクロソフトがパッケージフライトと呼んでいるリリース方式ですが、これも通常と同様にマイクロソフトストアの審査があります。そのため少々時間がかかるかもしれません。
今回のリリースでは、短時間にSeekが複数回発生すると(1秒間に4回です)、その状態を検出してダンプファイルを生成するようにしています。予期しない状態を検出したという文言と操作を問い合わせるダイアログボックスが表示されますので、送信を選択してください。
この予期しない状態の検出は、連発しないように1日1回だけ行われるようにしています。
わたしの環境では再現しない状況で検出の仕掛けを実装したので、もしかしたらうまく動作しない可能性もあります。現象が発生しているはずなのに検出できていないようであれば、お知らせくださると助かります。
よろしくお願いします。
2023-04-12 20:46 #13367Tikiキーマスターマイクロソフトストアから、フライトが公開されたとの連絡がありました。思ったより早かったです。Version は5.2.4です。
それともう一点、お伝えするのを忘れました。このバージョンはわたしの手許の開発中のものです。そのため5.2.3とは動作が異なるところがあります。ご了承ください。もし支障があれば、お知らせください。
2023-04-12 20:50 #13369Noir参加者2023-04-16 03:28 #13379Noir参加者4/12-15の4日間は現象発生なしでした。
前回、プレイリストを変えてから77秒という状況だったので、今週は試しに夕方に12-15時間分くらいのプレイリストを用意して、そのまま9-10時間TuneBrowserを操作しないで再生、という状況を試してみました。
この条件で4日間、現象出ていません。
そして、週明けは前回発生時のように、夕方に12-15時間分くらいのプレイリストを用意して再生をはじめるところまでは同じで、4-5時間経過後の21-22時くらいを目処に、プレイリストに含まれていない他のアルバムを選択する、という状況を試してみます。
現象発生の有無はたまたまなのかも知れませんが、ご連絡まで。
引き続きよろしくお願いいたします。
2023-04-16 08:37 #13380Tikiキーマスター状況のご報告ありがとうございました。
引き続き、よろしくお願いします。
2023-04-23 13:01 #13410Noir参加者結論から申し上げますと、先週は一度も発生しませんでした。
先週は前回発生時のように、夕方に12-15時間分くらいのプレイリストを用意して再生をはじめ、4-5時間経過後の21-22時くらいを目処に、プレイリストに含まれていない他のアルバムを選択する、という状況を月ー土と試しました。
せっかく仕込みを入れてくださったのに、一週間まるまる現象が発生しなかった状況ははじめてで、申し訳ない気持ちでおります。本来現象が出ないのはいいことなのですが、調べたいときに出ないのは困りますね。。。
引き続き使用してまいりますので、よろしくお願いいたします。
2023-04-23 23:15 #13411Tikiキーマスターご報告ありがとうございました。
もうしばらく、待ってみましょうか。よろしくお願いします。
2023-04-25 00:16 #13415Noir参加者こんばんは
ひさしぶりに現象が発生しました!
先ほどダンプファイルを送付させていただきました。1点、自動的にダイアログが表示されると思っていたのですけど、現象発生時に送信ダイアログは表示されませんでした。今回はログに以下の項目が残っていたので、手動で「ヘルプ」ー「ダンプファイル」ー「ダンプファイルの確認」を実行したところ見つかったので送付いたしました。
UL04710: 2023/04/24 23:17:16,591: T012f4: Generating dumpfile for unexpected state.
また、念のため現象発生時のログも添付いたします。
ダンプファイルの生成はお伝えいただいたとおり1日1度のみの生成でしたが、現象はこのあとも別の曲で発生していることがログから確認できました。
よろしくお願いいたします。
Attachments:
2023-04-25 23:40 #13417Tikiキーマスターダンプファイル受領しました。ありがとうございます。
内容を確認して、またご報告します。
2023-04-26 10:36 #13418Noir参加者大変お手数をおかけいたします。
ご調査よろしくお願いいたします。
2023-04-26 20:44 #13419Tikiキーマスターこんばんは。
内容確認しました。事象はしっかり記録されていました。
シークが繰り返された原因は、やはり短時間の間にマウスによるシーク操作が行われたためでした (1秒間に数回以上)。Noirさんがそんなに短時間にシーク操作を行うことはできないと言われていたことは承知しています。ですが、記録上はシークバーのコントロールに対して、マウス操作が行われてイベントが発生しています。
なにかそういった操作を発生させるような他のアプリケーションなどをご利用でないでしょうか。わたしも具体的には思いつきませんが…。
よろしくお願いします。
2023-04-26 21:04 #13420Noir参加者ご確認ありがとうございます。
サウンドデバイスになんらかのエラーが発生しているのかな、と思いましたが、想定外のご回答でした。
はじめのころに送った動画ではマウスカーソルが映ってなかったように、基本的に再生中はpc自体を操作しないので謎は深まりました。
以前と今回お送りしたログを拝見するとアルバムを切り替えて大体77秒というあたりの時間で現象がはじまってる点は気がかりです。
(それ以降の現象発生時は77秒ではないのですが、きっかけとなる最初の発生時は77秒)
またマウスクリックのイベントが再生や停止ボタンではなく、都合よくシークバーに行くものなのか、という疑問もございます。
今回の現象発生時、目の前に居なかったので逆にお聞きしたいのですが、ウインドウの状態はフォアグラウンドにありましたでしょうか?
バックグラウンドもしくは最小化することで回避できるものかわからないのですが、マウスイベントが何かしらの理由で誤クリックが発生するのであれば、最小化するという回避方法もありかな、と思いました。
2023-04-26 22:11 #13421Tikiキーマスター動画で確認できるのは、描画がフリーズしているということだったかと思います。その事象とシーク操作の連発とが、どういう関係にあるのかは、わたしにはわかりません。シーク操作が連発したから描画がフリーズしたのか、描画がフリーズする事象が発生したからシーク操作が連発したのか、という話ですが…。
ウインドウの状態はフォアグラウンドにありましたでしょうか?
ログをたどってみましたが、それ関係のイベントの記録はなく、わかりませんでした。
参考になるかどうかわかりませんが、ある連続操作のところのログは以下のような感じです。CTBarSliderCtrlはシーク用のスライダコントロール、OnLButtonDownはマウスボタンを押したイベント、OnLButtonUpはマウスボタンを離したイベント、時刻の “23:17:17,004.3101” の004.3101はミリ秒です。23:17:17に4回のマウスボタン操作の記録があります。
2023/04/24 23:17:17,004.3101 00002d34 TB::CTBarSliderCtrl::OnLButtonDown 2023/04/24 23:17:17,009.5103 00002d34 TB::CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:17,016.5236 00002d34 TB::CTBarSliderCtrl::OnLButtonDown 2023/04/24 23:17:17,019.9919 00002d34 TB::CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:17,029.6875 00002d34 TB::CTBarSliderCtrl::OnLButtonDown 2023/04/24 23:17:17,033.8597 00002d34 TB::CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:17,082.1819 00002d34 TB::CTBarSliderCtrl::OnLButtonDown 2023/04/24 23:17:17,146.1015 00002d34 TB::CTBarSliderCtrl::OnLButtonUp
2023-04-27 00:05 #13422Noir参加者ご連絡ありがとうございます。
こちらでどのような情報がログに記録されるか、試してみたのですが、このマウスイベントはログファイルには記録されていないダンプファイル固有の情報のようですね。
参考までに、キーボード入力の場合は違う記録がされますでしょうか?
OnLButtonDown と OnLButtonUp および GetCursorPos() などでカーソル位置を取得して Player ログに出力いただくことは可能でしょうか?キーボードイベントなども記録できるとありがたいです。
https://learn.microsoft.com/ja-jp/windows/win32/api/winuser/nf-winuser-getcursorpos
2023-04-27 02:00 #13424Noir参加者続けて失礼いたします。
#13415で添付いたしました「2023-04-24Log.zip」のログと「OnLButtonDown」および「OnLButtonUp」の時系列が気になりましたので共有させていただきます。
現象発生時の Log ファイルです
UL04236: 2023/04/24 23:17:16,042: T027a0: Calling Lua: OnPlaybackFile
UL04237: 2023/04/24 23:17:16,042: T027a0: - C:\Users\barod\Music\Harry Connick Jr\Only You\01 More.wav
UL04238: 2023/04/24 23:17:16,042: T027a0: - 0
UL04239: 2023/04/24 23:17:16,043: T027a0: Calling Lua: Results:
UL04240: 2023/04/24 23:17:16,043: T027a0: -
UL04241: 2023/04/24 23:17:16,043: T027a0: -
UL04392: 2023/04/24 23:17:16,216: T027a0: Calling Lua: OnPlaybackFile
UL04393: 2023/04/24 23:17:16,216: T027a0: - C:\Users\barod\Music\Harry Connick Jr\Only You\01 More.wav
UL04394: 2023/04/24 23:17:16,216: T027a0: - 0
UL04395: 2023/04/24 23:17:16,217: T027a0: Calling Lua: Results:
UL04396: 2023/04/24 23:17:16,217: T027a0: -
UL04397: 2023/04/24 23:17:16,217: T027a0: -
UL04541: 2023/04/24 23:17:16,330: T027a0: Calling Lua: OnPlaybackFile
UL04542: 2023/04/24 23:17:16,330: T027a0: - C:\Users\barod\Music\Harry Connick Jr\Only You\01 More.wav
UL04543: 2023/04/24 23:17:16,330: T027a0: - 0
UL04544: 2023/04/24 23:17:16,330: T027a0: Calling Lua: Results:
UL04545: 2023/04/24 23:17:16,330: T027a0: -
UL04546: 2023/04/24 23:17:16,330: T027a0: -
UL04690: 2023/04/24 23:17:16,479: T027a0: Calling Lua: OnPlaybackFile
UL04691: 2023/04/24 23:17:16,479: T027a0: - C:\Users\barod\Music\Harry Connick Jr\Only You\01 More.wav
UL04692: 2023/04/24 23:17:16,479: T027a0: - 0
UL04693: 2023/04/24 23:17:16,480: T027a0: Calling Lua: Results:
UL04694: 2023/04/24 23:17:16,480: T027a0: -
UL04695: 2023/04/24 23:17:16,480: T027a0: -
UL04710: 2023/04/24 23:17:16,591: T012f4: Generating dumpfile for unexpected state.
続いて、#13421 でお伝えいただいた「OnLButtonDown」および「OnLButtonUp」の時刻です
2023/04/24 23:17:17,004.3101 00002d34 TB::CTBarSliderCtrl::OnLButtonDown
2023/04/24 23:17:17,009.5103 00002d34 TB::CTBarSliderCtrl::OnLButtonUp
2023/04/24 23:17:17,016.5236 00002d34 TB::CTBarSliderCtrl::OnLButtonDown
2023/04/24 23:17:17,019.9919 00002d34 TB::CTBarSliderCtrl::OnLButtonUp
2023/04/24 23:17:17,029.6875 00002d34 TB::CTBarSliderCtrl::OnLButtonDown
2023/04/24 23:17:17,033.8597 00002d34 TB::CTBarSliderCtrl::OnLButtonUp
2023/04/24 23:17:17,082.1819 00002d34 TB::CTBarSliderCtrl::OnLButtonDown
2023/04/24 23:17:17,146.1015 00002d34 TB::CTBarSliderCtrl::OnLButtonUp
同時刻の Player ログには以下のみが記録されており、ファイルやデバイスに関する処理が記録されていません。また、Log ファイルには現象発生時に記録されている Calling Lua: OnPlaybackFile の記録がないようです。
UL04711: 2023/04/24 23:17:17,013: T02d34: TL18: Process seek message: 77.1
UL04712: 2023/04/24 23:17:17,014: T02d34: TL18: Process seek: 77.1
UL04713: 2023/04/24 23:17:17,014: T02d34: TL18: Apply current seek value to player: 77.1
UL04714: 2023/04/24 23:17:17,015: T02d34: TL18: Requesting player command: [Seek]
UL04715: 2023/04/24 23:17:17,023: T02d34: TL18: Process seek message: 77.0
UL04716: 2023/04/24 23:17:17,027: T02d34: TL18: Process seek: 77.0
UL04717: 2023/04/24 23:17:17,028: T02d34: TL18: Apply current seek value to player: 77.0
UL04718: 2023/04/24 23:17:17,028: T02d34: TL18: Requesting player command: [Seek]
UL04719: 2023/04/24 23:17:17,038: T02d34: TL18: Process seek message: 77.0
UL04720: 2023/04/24 23:17:17,039: T02d34: TL18: Process seek: 77.0
UL04721: 2023/04/24 23:17:17,039: T02d34: TL18: Apply current seek value to player: 77.0
UL04722: 2023/04/24 23:17:17,039: T02d34: TL18: Requesting player command: [Seek]
UL04723: 2023/04/24 23:17:17,150: T02d34: TL18: Process seek message: 77.0
UL04724: 2023/04/24 23:17:17,151: T02d34: TL18: Process seek: 77.0
UL04725: 2023/04/24 23:17:17,151: T02d34: TL18: Apply current seek value to player: 77.0
UL04726: 2023/04/24 23:17:17,151: T02d34: TL18: Requesting player command: [Seek]
また、それぞれのクリック速度が 5.2ms, 3.5ms, 4.2ms, 63.9ms と爆速なのでプログラムでしか実現できなさそうですが、該当マシンには自動化ツールのようなアプリをインストールしていないし思い浮かばない、という状況です。
よろしくお願いいたします。
2023-04-27 02:11 #13427Noir参加者Alt+Shift+x でコードに成形したらライン別になってしまいました。
「編集」を試みたのですが一定時間経過で間に合わず。読みにくくてすみません。。。
2023-04-27 20:20 #13428Tikiキーマスター例が悪かったようですみません。前後も含めたログを再掲させていただきます。
2023/04/24 23:17:15,994.0768 00002d34 CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:15,999.6647 000012f4 Processing PlayerCmd:[Seek] 2023/04/24 23:17:16,042.9781 000027a0 Calling Lua: OnPlaybackFile 2023/04/24 23:17:16,154.0533 00002d34 CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:16,159.4184 000012f4 Processing PlayerCmd:[Seek] 2023/04/24 23:17:16,216.7780 000027a0 Calling Lua: OnPlaybackFile 2023/04/24 23:17:16,281.9767 00002d34 CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:16,286.9115 000012f4 Processing PlayerCmd:[Seek] 2023/04/24 23:17:16,330.5251 000027a0 Calling Lua: OnPlaybackFile 2023/04/24 23:17:16,434.4246 00002d34 CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:16,440.0747 000012f4 Processing PlayerCmd:[Seek] 2023/04/24 23:17:16,479.8746 000027a0 Calling Lua: OnPlaybackFile 2023/04/24 23:17:16,586.1570 00002d34 CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:16,591.6618 000012f4 Processing PlayerCmd:[Seek] 2023/04/24 23:17:16,591.6794 000012f4 UnexpectedState caused: TooManySeek. 2023/04/24 23:17:17,009.5103 00002d34 CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:17,019.9919 00002d34 CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:17,033.8597 00002d34 CTBarSliderCtrl::OnLButtonUp 2023/04/24 23:17:17,146.1015 00002d34 CTBarSliderCtrl::OnLButtonUp
ここで、2023/04/24 23:17:16,591.6794で予期しない状態を検出しており、その後の2023/04/24 23:17:17以降のシークはこのログの範囲では処理されていませんでした。ここで挙げたログでは、23:17:15~23:17:16の間にも同様の事象が発生しています。気にされていたCalling Luaの行も含めてあります。
お詳しいようですのでさらに付加情報を申し上げると、00002d34とか000012f4はスレッドのIDです。2023/04/24 23:17:16,591.6794で再生制御を行っているスレッドが予期しない状態を検出しているため、23:17:17以降の操作はすぐには処理されない状態になっています。
スライダーによるシーク操作が短時間に連発していることについて、不思議に思われるのは当然と思います。わたしにもわかりません。すくなくともそのタイミングでのリアルタイムでのマウス操作ではないような気がします。ただTuneBrowserから見ると、スライダーが連続で操作されてその処理を行ったようにしか見えません。
ログの追加のご依頼もありましたが、すみませんがこれ以上のTuneBrowserを改修しての対応はご容赦いただければと思います。
あと、キーボード操作はマウスボタンではないので、一般にはキーボード操作をしたからといってマウスイベントが発生することはありません。
2023-04-27 20:31 #13429Noir参加者ありがとうございます
連投してしまったので抜けてしまったと思いますが、こちらはキーボードのキー押下操作とは別で、必ずマウスクリックになりますでしょうか?
こちらで見えればある程度進められるのですが、見えない部分なので細かくお尋ねしてすみません。
2023-04-27 20:42 #13430Tikiキーマスターキーボード操作はマウスボタンではないので、一般にはキーボード操作をしたからといってマウスイベントが発生することはありません。
2023-04-27 23:45 #13431Noir参加者ご回答ありがとうございます。
独自のログ出力だったのでマウスクリック以外も同じ記録がされないか気になっておりました。
お尋ねした理由は TuneBrowser ウィンドウ内のフォーカスが「スライダー」に当たった状態で Enter や Space などのキーが押下されて短時間にリピートされるほうがまだ現実的にありえるかな、という意図でお尋ねしました。
ですがマウスのボタンクリックということで想定は間違っていることが確認できました。ありがとうございます。もう1点、ご確認なのですが、
現象発生時の時間近辺で「スライダー以外」の場所にマウス クリックが発生しているか確認できますでしょうか?
これは謎の超高速クリック現象が「スライダーだけ」なのか「スライダー以外にも全方位的に発生」なのかを切り分けたいという意図になります。
よろしくお願いいたします。
なお、こちらではモニター画面をカメラで動画を撮り始めました。(PC内のツールでは動作に影響がある可能性もありますのでモニターを撮り続けております)
昨日と今日は現象出ていませんので、いつ発生するかわからないのですけど、わたし自身も音飛びなどをトリガーに事後に画面を見るという状況で、一度も発生までの過程を見ておりません。取得出来ましたら、ダンプ解析やログ解析での想定と、実際の画面の動きを照らし合わせたいと思っております。
2023-04-28 20:48 #13432Tikiキーマスターこんばんは。
ログをみるかぎりでは、スライダー以外ではマウスイベントは発生していないようでした。
簡単ですが、よろしくお願いします。
2023-04-28 21:05 #13433Tikiキーマスター念のため、なのですが、トピックタイトルにある「一時的に再生が停滞して10数秒後に再開」という現象は、最初にも書いたようにわたしの環境でも発生します。一昨日は、ある用途でUSB3.2 Gen2のディスクに大きな負荷をかけたときに、まさに描画も再生も停滞して十数秒後に再開する動作が発生しました。
その事象が起きたとしても、TuneBrowserからはどうにもできません。
いまここで議論をしているのは、シークが連発するという動作のほうですよね。今回お送りいただいたダンプファイル上は、シーク連発中、動作の停滞が発生しているようには見受けられませんでした (だからマウスイベントを処理できているわけですが)。ただダンプファイル上は性能への影響を抑制するため1秒~数秒間程度しか詳細のログがとれないようにしているので、それより前になにか起きていた可能性は否定はできません。
2023-04-28 21:22 #13434Noir参加者ご回答ありがとうございます。
はい、現在は「スライダーに超高速クリックが連発されることでシークが短時間に繰り返され再生が途切れる」という現象です。
Tikiさんのご協力のおかげで、当初の「再生が途切れる、そのとき描画が固まっていた」というぼんやりした状況から具体的に絞り込むことができました。また、スライダー以外へのクリックが記録されていなかった、とのことでまたひとつ絞り込めました。ありがとうございます。
以前お渡しした描画が止まった時の動画を撮影した当時は、まだログの存在を知らなかったので厳密な比較はできないのですけど、スライダーにシーク時間のポップアップが動画の前半で確認できます。
シーク時間のポップアップが確認されたため、同じようにスライダーへの超高速クリックが連発していたと想像しており、同一の現象と考えております。
-
投稿者投稿
- このトピックに返信するにはログインが必要です。