Serious drops with BonDriver_Mirakurun #4
Comments
|
報告ありがとうございます． 同様の報告をTwitter上でも確認しており，動作確認用のWindows環境を構築して解析する予定です． mirakcでの不具合解析方法はまだ確立していませんが，いくつか使える機能があります． RUST_LOG環境変数 # mirakcのログレベルのみをdebugに
export RUST_LOG=info,mirakc=debug
# actix-webを含む全てのcrateのログレベルをdebugに
export RUST_LOG=debug
MIRAKC_ARIB_LOG環境変数
ログはstderrに出力されますが，そのままではmirakcはこれを/dev/nullに捨てます．環境変数 export MIRAKC_DEBUG_CHILD_PROCESS=1
export MIRAKC_ARIG_LOG=infoactix-webとスレッド
もしチューナーがN個あるなら， /api/channels/<type>/<channel>/streamを試してみるBonDriver_Mirakurun + TVTestで可能かどうか分かりませんが，/api/channels///stream APIで試してみる方法が考えられます． これを使うと，チューナーからの出力をそのままストリーミングするので（NULLもそのまま），mirakc-aribコマンドとの問題の切り分けができます． decode/preprocess/postprocessを無効にしてみる出力結果はpreprocessおよびpostprocess適用前のTSパケットとなりますが，この状態でパケットのドロップが発生していないのであれば，原因はpreprocess/postprocess使用時となり，切り分けができます． |
|
ドロップ問題なので関係ないとは思いますが，mirakcには未実装のREST APIが多数あります．
|
|
解説ありがとうございます。 1./api/channels/(type)/(channel)/streamを試してみる 2.decode/preprocess/postprocessを無効にしてみる 上にも記載いたしましたが、同じ環境でもmpc、vlc等で直接http://:40772/api/channels/(type)/(channel)/streamにアクセスすると問題なく視聴が可能です。 |
|
TVTestでの視聴によるログを取得しましたので貼り付けておきます。 2020-01-05T00:13:57.336 DEBUG tokio_reactor > adding I/O source: 8388608 |
|
確認ありがとうございます．ストリーミング中に別のAPIが呼び出されていないので，プールされているスレッドが枯渇しているわけでもなさそうです． これまでの結果をまとめると．．．
受信電波には問題はないと仮定した場合にドロップが発生する可能性がある箇所は．．．
のどれかということになります． 直接受信時にはドロップが発生しないということなので，以下の可能性が考えられます．
後者の可能性もありますが，恐らく前者の可能性のほうが高いと思います． mirakcのバッファーサイズが関係しているのかもしれません． mirakcが利用している
ということがありそうです． もし，利用しているデバイスドライバー，チューナープログラムにバッファーがあふれたときにログを出力する機能があるなら，あふれているかどうか確認できると思います． |
|
BonDriver_Mirakurunのコードを見てみたのですが，結構複雑ですね． 単にコードを見ただけなので間違った指摘かもしれませんが， は 例えば，
がロックの外で行われています． もし， はロックの外で行われています． あとは， 上記のような箇所が原因でBonDriver_Mirakurunでドロップが発生している可能性があるかもしれません． |
|
次に、ご指摘のm_pGrabTsDataですが、これはデータの送受信に関する処理のため、可能な限りロックフリーを目指してatomicを駆使して処理を行っています。 ざっくり言うと、 ご指摘の通り、際どい処理であることには変わらず、コンパイラの最適化等で期待した処理にならない可能性もあるため、自分の理解のためにも後でもう少し処理の詳細を記載しようと思います。 なお、ドロップと排他制御（atomic）の関連という意味では、get_TsStream |
|
説明ありがとうございます．
putとgetで書き換える変数が異なるので，データが上書きされたりすることがないこを確認しました． やはり上流のどこかでバッファーがあふれているのではないかと推測します． |
|
m_pGrabTsDataにRing BufferのOverflowチェックを入れて検証してみました。 Overflowの前にもドロップしているためあまり意味がなさそうですが、読み出しのバッファを10倍にしてみたところOverflowはなくなりましたが、ドロップの状況に変化はないです。 recvで受け取ったデータに余計なデータが含まれていてTVTestでうまく処理できない感じがします。 |
|
調査ありがとうございます． mirakcとMirakurunのフィルタリングの違いを調べてみます． mirakcで通過させているパケットの種類は |
|
ありがとうございます。こちらでも不要と思われるパケットを削除して試してみます。 |
|
recvの後 |
|
こちらの調査が進んでおらず申し訳ないです．． ドロップチェックに利用しているプログラム名を教えていただけますか？こちらでもチェックしてみます． PATとPMTはチューナーが出力したものを書き換えているので，CCやCRCがおかしくなったりしているのかもしれません． |
|
TVTestで視聴しているとドロップカウントが増加していきます。映像自体も乱れてまともに見れない状況です。上記の直接ファイルに書き出したTSをMPCで再生しても同じような映像です。 なおmirakc-aribの影響を除くために |
|
Windows環境を構築して確認してみました． まず，
未実装の 「ストリーム情報の表示」を見て分かったことは，存在しないはずのPIDがtvtestに受信されていることです．つまり，どこかでデータが壊れていることを意味しています．mirakcよりも下流だと考えるのは早計です．上流で壊れた可能性も否定できません． 調査を継続します． |
|
もし，そちらでも再現するようでしたら，恐らくbondriver_mirakurunもしくはtvtestのどこかに不具合があるのだと思います． テスト環境
手順
# http.py
import SimpleHTTPServer
import SocketServer
ADDRESS = '0.0.0.0'
PORT = 40772
class CustomHandler(SimpleHTTPServer.SimpleHTTPRequestHandler):
def __init__(self, req, client_addr, server):
SimpleHTTPServer.SimpleHTTPRequestHandler.__init__(self, req, client_addr, server)
def do_GET(self):
self.path = '/stream'
SimpleHTTPServer.SimpleHTTPRequestHandler.do_GET(self)
class MyTCPServer(SocketServer.ThreadingTCPServer):
allow_reuse_address = True
if __name__ == '__main__':
httpd = MyTCPServer((ADDRESS, PORT), CustomHandler)
httpd.allow_reuse_address = True
print "Serving at port", PORT
httpd.serve_forever()
発生するドロップはランダムに見えます．ドロップが全く発生しない場合もありました．また，PIDごとの入力数も変化しました．入力数＋ドロップが常に同じ数というわけでもありませんでした． |
|
検証ありがとうございます。BonDriver_MirakurunはWinsock2を使っていますが、これだとデータをうまく受信できないのかもしれませんね。。。 |
|
時間ができたときで構いませんので，同じ手順で問題が発生するかどうか確認してください． 現時点では，私の環境でのみ確認した現象です．まだ１サンプルにすぎませんし，原因特定には至っていないため，上流を原因箇所から除外するのは早計だと考えています． 注意喚起のため，このissueはbugのままOpen状態を維持しておきます．上記手順で問題が再現した場合や，下流の原因箇所が特定できた場合は，コメントを追記していただけるとありがたいです． |
|
お世話になっております。 あとは、可能でしたら、複数のクライアントからチューナーを共有できるようにしていただけたら大変うれしいです。 |
|
報告ありがとうございます．
非同期化作業が終わったら検討してみます．ただ，対応のためには相当修正が必要だろうとは思っています． |
|
ご検討のほどよろしくお願いいたします。 さて、とりあえず視聴できるようになったためコミットいたしました。
2つのチャンネルを同時に視聴しているため、mirakcのサーバーのシェルで「ps aux」を叩いてみると、当然recpt1（mirakc-aribも）が2つ起動されているのが見えますが、 これはもしかしたら、チャンネル変更時の 一難去ってまた一難です。。。 |
|
固まったところのログを貼っておきます。（テレ朝 ch.24 -> TBS Ch.22） 2020-01-12T02:43:22.775 INFO actix_web::middleware::logger > 192.xxx.xxx.xxx:51919 "GET /api/channels/GR/26/stream?decode=1 HTTP/1.1" 200 19898368 "-" "BonDriver_Mirakurun/1.0" 10.451457 |
|
そのような現象の原因として，２つの可能性が考えられます． 背景チューナーの開放はactix-webのHTTPトランザクション終了後に行われます． HTTPトランザクション終了のリソース開放時に，チューナー開放のためのメッセージが送出されます． このメッセージはキューに入りますから，これ以降に新しいチューナーの要求があった場合は，正しく割り当てられます．なぜなら，キューに入った順でメッセージが処理されるからです． /api/xxx/streamでの，actix-webのトランザクション終了のタイミングはTCP切断時です．もちろん，actix-webから切断する場合はこの限りではありませんが，今回はクライアント側から切断するケースなので，actix-webから切断するケースについては原因の可能性から排除します． 可能性１：tuner開放処理が完了する前に次のリクエストがきており，その結果，チューナーを割り当てられないこの場合，以下のようなログが出力されます． 解決案再接続のタイミングをもっと遅らせるか，TCP切断時のコールバックが呼び出された後で再接続する必要があるのではないかと思われます． 可能性２：HTTP keep-aliveが有効になっており，TCPの接続が継続されているwinhttpは初期値でkeep-aliveが有効になっているようです． 解決案上記でkeep-alive自体を無効にしてしまうか，個別に"Connection: close"ヘッダーをつければ，TCP接続が切れます． |
|
ちなみに，tvtest１つだけの場合に問題が発生しない理由として，チューナーが２つ以上存在することが挙げられます． この場合，対象チューナーの開放が完了していなくても，別のチューナーを割り当てることができるので，問題は発生しません． おすすめはしませんが，同時に使用するtvtestの数よりも多いチューナー（GRなどの種別ごとにこの条件を適用する必要があります）を用意すれば問題は発生しません． |
|
詳細なご説明ありがとうございます。アドバイスをもとにkeep-aliveを無効にした上で試行錯誤の結果、やっと実用に耐える程度にもっていけました。
コールバック関数で処理しようと試みましたが、WINHTTP_CALLBACK_STATUS_CONNECTION_CLOSEDが発行されることはなく、WINHTTP_CALLBACK_STATUS_HANDLE_CLOSINGはWinHttpCloseHandle()の直後（実際の切断の前）に発行されてしまうため、切断のタイミングを取得することはできませんでした。よって500msのウエイト（iniで指定可能）をおくことで対応しました。 ただし、これだとチューナーの切断に間に合わないことがあり、その場合はStatus codeとして401が返ってくることがわかりましたのでリトライを行う（リトライループから抜けない）ようにしました。 この状況で、上記と同じTVTestを2つ起動し、片方（TVTest-B）のチャンネルを変更していくことを繰り返した結果、前回の時と同様5～6回目で、WinHttpSendRequest() そこで、力技ではありますが、TIME_OUTを100msに設定し、 config.ymlで「workers: 6」にしていることから、mirakcですべてのスレッドが埋まってしまったためにレスポンスを返せない（停止）しているのではないかという感じもするのですが、再度すぐにWinHttpSendRequest()でリクエストすると動き出すのでよくわかりませんでした。 |
|
停止した時、および、再度WinHttpSendRequest()でリクエストして動き出したときのログを貼っておきます。（日テレ -> テレ朝） 2020-01-13T16:32:36.843 INFO actix_web::middleware::logger > 192.xxx.xxx.xxx:61710 "GET /api/services/3274001056/stream?decode=1 HTTP/1.1" 200 8645368 "-" "BonDriver_Mirakurun/1.0" 5.716843
2020-01-13T16:32:56.162 DEBUG tokio_reactor > adding I/O source: 58720256 「SERVICE_SPLIT=0」でも同じ状況です。 |
|
指摘の通り，プールされているスレッドを使い切っているものと思われます． Fiddlerやtcpdump/wiresharkでHTTP/TCP通信を解析すれば原因が特定できるかもしれません．
過去に以下のような問題が報告されているので，actix-webの不具合である可能性も十分あります． |
|
のタイミングで「チューナー開放メッセージを送信」となるため，スリープなしでも問題が発生していないのだと推測されます． フィルターなし フィルターあり ここで
|
|
原理的には |
|
詳細なご回答ありがとうございます。 とりあえずの対応としてSTATUS CODE 200が返ってくるまでSleep(200)でGETを繰り返すことといたしました。 |
|
f80e24a で遅延が短くなったと思います．確認してみてください． |
|
ほぼ遅延がなくなりました。 |
|
ところで、TOKYO MX1（3239123608）とMX2（3239123610）の間でチャンネル切り替えを数回繰り返してみたのですが、「Reuse tuner already activated with GR 16」になるときと、通常のチャンネル切り替えと同様にTuner close -> openになるときがありました。本来的には常に「Reuse tuner already activated with GR 16」となるのではと思った次第です。 using B25... |
|
タイミングの問題ですね． どちらも同じチャンネルなので，チューナーが閉じられる前に次のリクエストが処理されると，reuseになります． どちらも期待動作です． 仮に（ほぼ無理ですが），遅延を0にできたなら，reuseすることはなくなります． |
|
承知しました。早速のご回答ありがとうございます。 ごくたまになのですが、チャンネル切り替え後に映像が出てこない場合があるようなので、もう少し検証してみます。 |
|
テストを重ねていたところ、1点不便なことがありました。 例えば、デフォルトの設定では毎時7分に「update-schedules」が開始され、この後20分弱「Handle UpdateSchedulesMessage」の処理が実行されます。この間にTVTestを起動するとmirakcがepg処理（もしくは強制的なチャンネル変更）を行っているためか映像が表示されません。 GETリクエストの際にepg処理を中断するようなオプションを入れていただくことは可能でしょうか。 |
|
念の為、epg処理中にTVTestで視聴（テレ朝）を試みた際のログを貼っておきます。 2020-02-14T10:07:00.001Z INFO mirakc::job > update-schedules: Scheduled for 2020-02-14 20:07:00 +09:00 |
|
何らかの不具合が起きているようです． subscribeとunsubscribeのユーザーが一致していません． これを修正すれば，機能追加などは必要なく期待動作するもとも思われます． |
|
よくわからないです。。。 状況としては、mirakcにアクセスしているのはBonDriver_mirakcとEPGStationのみです。 10:07に録画サーバーでmirakcによる自動の番組情報の取得が開始され、その直後に別のPCでTVTestを起動してBonDriver_mirakcでmirakcにアクセスしています。 「2020-02-14T10:07:00.002Z INFO mirakc::tuner > tuner#0.7779.1: Subscribed: Job(eit-collector) (priority=-1)」はpriority=-1なのでmirakc自身によるtunerアクセス、「2020-02-14T10:07:09.822Z INFO mirakc::tuner > tuner#0.7779.1: Unsubscribed: Web(remote="192.168.xxx.xxx:57749" agent="BonDriver_mirakc/1.0") (priority=0)」はBonDriver_mirakcによるアクセスだというのはわかるのですが。。。 いったんEPGStationを停止して検証してみます。 ちなみに同様の現象はmirakcの起動直後「Always update schedules at startup」の直後でも再現可能で、この場合はブラウザによる「api/services/ID/stream」でも確認できます（ダウンロードが一瞬で停止する）。 |
|
たぶん誤解されたのだと思いますが，不具合はmirakc側で発生しています．mirakcのバグです． 各mpeg tsストリームには一意のidが割り振られていて，これを使って開放処理を行っています． 上記ログの ですが，確保時のユーザー（ こちらで修正しますので，少々お待ち下さい． |
|
いつもありがとうございます。報告ばかりで協力できず申し訳ありません。 実はあと1つ他の不具合の可能性を発見しております。 |
|
報告をいただけるだけで十分助かっています．本当はユニットテストなどで見つけるべき不具合なのですが，actorのテストが結構厄介でうまくテストできていない状況です．仕方ないので，実際に動かしてテストしていますが，効率が良くないです．．
可能性としては，利用している epgstaionを使っていると，10分間隔くらいでいくつかのREST APIを呼び出すので，問題が見つかっていないだけなのかもしれません． |
|
感覚的には「HTTPリクエストが来たのでタスクスケジューラーが起きて，溜まっていたタイマー処理を実行した」のように感じます。 |
|
ありがとうございます．こちらでも，開放処理の誤りの修正後に動作を確認してみます． |
|
3d7127d で開放処理の不具合を修正しました．DockerHubのmasterタグも更新されています． |
|
お世話になっております。 最後に、 2807172 によってsocketが使えるようになったようですが、mirakcのconfig.ymlで あと余談ですが、BonDriver_Mirakurunでは相変わらずドロップで使用できないため、BonDriver_mirakcを使用する必要があります。 |
|
こちらこそありがとうございました．おかげでmirakcの不具合も減りました．
少なくとも， 念の為，dockerを使って動作確認してみましたが，epgstationとmirakcはunix domain socketを使って通信できているように見えます． macOS上でmirakcを起動し，
ドキュメントではBonDriver_Mirakurunで使えるみたいに書いてあるので，書き換えておきます． 想像ですが，BonDriver_Mirakurunまたはmirakcに何らかのタイミングに依存した問題があるのだろうと思います．ひとまずBonDriver_mirakcで動かせるようにしていただいたので，時間があるときにBonDriver_Mirakurunの動作を見てみることにします． |
|
ご返答ありがとうございます。 なお当然ながら、Mirakurunでは問題ありませんし、mirakcでも |
|
ファイルのアクセス権とかでしょうか？
設定の問題ではないと思います．パスは異なりますが，同じような設定でmirakc/EPGStation間でUDSが動作することを確認済みです．先のコメントのログを見てください． |
|
多分アクセス権ですね． mirakcをEPGStationと同じユーザーで実行するか，mirakc実行後にソケットファイルのパーミッションを変更すれば（ |
|
パーミッション（chmod 0777）、ユーザー変更、どちらでもできました。ありがとうございます。 |
申し訳ありませんが，そのような設定を追加する考えはありません． 個人的意見ですが，安全上の理由などがない限りは，利用者側で対応可能なことまでアプリケーションで対応する必要はないと考えています． 今回の場合ですと，mirakc起動後にchmodしたり，SUID/SGIDを使うなどで回避可能なので，類似機能をアプリケーションに実装する必要はないと考えています． |
|
承知いたしました。 ありがとうございました。 |
|
README.mdの記述 は |
|
そうですね．書き換えておきます． |
mirakc + BonDriver_Mirakurun + TVTestを下記の環境で使用しておりますが、
大量のドロップが発生して、まともに視聴できない状況です。
Server:
CPU: Ryzen
Memory: 16GB
OS: OpenmediaVault4 (Debian Stretch)
Tuner: PT2 (chardev) + recpt1
Client: Core i7
CPU: Intel
Memory: 8GB
OS: Windows 10
本家のBonDriver_Mirakurunを少しシンプルに改造してみましたがそれでも同じ状況でした。
https://github.com/epgdatacapbon/BonDriver_Mirakurun/blob/develop/BonDriver_Mirakurun.cpp
でのTS読み込み処理は非常に簡単で、576行目でsocketにconnectし、596行目でGETでrequestして、607行目から始まるThreadの619行目のrecvで読み込んでいるだけです。
Mirakurunを使用した場合には特に問題はありません。
mpc-beやvlcでのhttp接続の視聴に問題はないため、actix-webの仕様をよくわかっていないのが原因と思われますが、なにかアドバイスいただけましたら幸いです。
The text was updated successfully, but these errors were encountered: