サーバーでのdiscobot証明書生成が非常に遅い

新しいメンバーには Discobot のチュートリアルを完了するよう促していますが、以前のスケーリング環境(staging)の Discourse インスタンスで既に経験した問題に、かなりの数が直面しています。最後の投稿に表示される証明書が生成され、実際に表示されるまでに非常に時間がかかり、読み込み・生成中である旨の表示もありません。ここで言う「非常に時間がかかる」とは 10〜20 秒の期間を指し、これではユーザーが諦めてしまうのに十分な時間です。Meta で試したところ、ここでは即座に表示されるようです。

証明書は /discobot/certificate.svg?date=Oct+28+2020&user_id=123 という URL を使用してオンデマンドで生成できることに気づいたため、いくつかのテストを行いました。最初は即座に生成されましたが、直近でチュートリアルを完了していないユーザー ID を使用すると、10〜20 秒の待機時間を強いられます(一度生成されると以降は高速になるため、どこかでキャッシュされていると思われます)。また、待機中に 500 エラーもいくつか発生しました。これは何らかのタイムアウトだと思われますが、次のリフレッシュでは正常に動作しました。

/logs には、関連するかどうかは不明ですが、以下の警告が表示されています:

Failed to process hijacked response correctly : Net::ReadTimeout

traceback
/usr/local/lib/ruby/2.6.0/net/protocol.rb:217:in `rbuf_fill'

/usr/local/lib/ruby/2.6.0/net/protocol.rb:191:in `readuntil'

/usr/local/lib/ruby/2.6.0/net/protocol.rb:201:in `readline'

/usr/local/lib/ruby/2.6.0/net/http/response.rb:40:in `read_status_line'

/usr/local/lib/ruby/2.6.0/net/http/response.rb:29:in `read_new'

/usr/local/lib/ruby/2.6.0/net/http.rb:1509:in `block in transport_request'

/usr/local/lib/ruby/2.6.0/net/http.rb:1506:in `catch'

/usr/local/lib/ruby/2.6.0/net/http.rb:1506:in `transport_request'

/usr/local/lib/ruby/2.6.0/net/http.rb:1479:in `request'

rack-mini-profiler-2.0.2/lib/patches/net_patches.rb:9:in `block in request_with_mini_profiler'

rack-mini-profiler-2.0.2/lib/mini_profiler/profiling_methods.rb:39:in `step'

rack-mini-profiler-2.0.2/lib/patches/net_patches.rb:8:in `request_with_mini_profiler'

/var/www/discourse/lib/final_destination.rb:370:in `block in safe_get'

/var/www/discourse/lib/final_destination.rb:414:in `block in safe_session'

/usr/local/lib/ruby/2.6.0/net/http.rb:920:in `start'

/usr/local/lib/ruby/2.6.0/net/http.rb:605:in `start'

/var/www/discourse/lib/final_destination.rb:411:in `safe_session'

/var/www/discourse/lib/final_destination.rb:362:in `safe_get'

/var/www/discourse/lib/final_destination.rb:131:in `get'

/var/www/discourse/lib/final_destination.rb:152:in `get'

/var/www/discourse/lib/file_helper.rb:55:in `download'

/var/www/discourse/plugins/discourse-narrative-bot/plugin.rb:113:in `fetch_avatar'

/var/www/discourse/plugins/discourse-narrative-bot/plugin.rb:98:in `block in generate'

/var/www/discourse/lib/hijack.rb:56:in `instance_eval'

/var/www/discourse/lib/hijack.rb:56:in `block in hijack'

/var/www/discourse/lib/scheduler/defer.rb:94:in `block in do_work'

rails_multisite-2.3.0/lib/rails_multisite/connection_management.rb:68:in `with_connection'

/var/www/discourse/lib/scheduler/defer.rb:89:in `do_work'

/var/www/discourse/lib/scheduler/defer.rb:79:in `block (2 levels) in start_thread'

証明書は外部ネットワークリクエストなしにローカルで生成されていると推測されますが、合っていますでしょうか?

マシンは t3a.medium(メモリ 4GB)で、フォーラムは特に混雑していません(負荷は約 0.4、メモリも十分に残っています)。証明書の生成を待っている間、CPU の使用率はほとんど変化しなかったため、ボトルネックではないようです。

私たちだけがこの問題に直面しているわけではありません experiencing thisthis も関連しているかは不明ですが)、しかしそこには役立つ情報は見当たりませんでした。

何か手がかりがあるのかわかりませんが、証明書 URL を数回リフレッシュすると、最終的に「スローダウンしてください」というエラーが表示されます。多くの人が同じ URL パスで証明書を生成している場合、URL のスロットリング機構が干渉している可能性はありませんか?おそらくそうではないのでしょうが、なぜこのようなことが起きているのか見当がつかない状態です。ご助言を歓迎します。

そのルートは確かに遅いですね。まだ新しいものですから。

速度を上げる試みの他に、メッセージに「Discobot が準備中です。1 分ほどお待ちください」という文言を追加して、ユーザーに伝えるのはどうでしょうか。

それが遅いことで知られていたとは知りませんでした。少なくとも、その点を明確にするために投稿を更新すれば役立つかもしれませんが、待ち時間が長いと、それでも一部の人は諦めてしまうかもしれません。

既存の SVG(推測ですが)にテキストを埋め込んで生成するのに 10〜20 秒もかかるのは、 unusually 長いように思えます。私の見る限り、これは CPU がボトルネックになっているようには見えません。ここでのボトルネックは何でしょうか?

ここでは「少々お待ちください、あなたのために素敵なものを生成中です!」という文言を前のステップに追加しようと考えていたのですが、try.discourse.org では証明書生成が非常に高速です:

discobot 最終ステップのタイムスタンプ:11 月 2 日 18:46 1604371566089
discobot 証明書生成ステップのタイムスタンプ:11 月 2 日 18:46 1604371567470

基盤となるタイムスタンプの単位が何なのかは正確にはわかりませんが、その差は 1381 です。

同じトピックに対して可能な限り素早く返信し、以下のようなタイムスタンプを取得しました。これは明らかに数秒未満の差です:

1604373488630
1604373492182

その差は 3552 です。私はペーストとキーボードショートカットを使って、文字通り可能な限り素早く投稿しました。

つまり…あなたのサーバーは単に…性能が低い…のでしょうか?

彼は投稿のことではなく、証明書画像の生成について話しているのだと思います。

確かに、私が問題にしているのは証明書の生成そのものであり、それを埋め込む返信投稿(こちらは迅速です)ではありません。この問題が当フォーラムのいくつかのメンバーに引き起こしている現象は以下の通りです:

いいえ、t3a.medium はミドルレンジのインスタンスであり、負荷も高くありません。

前述の通り、これは CPU 束縛の問題ではないようです。例えば /discobot/certificate.svg?date=Oct+28+2020&user_id=123 のようなリクエストが完了するのを待っている間でも、CPU の使用率は通常時(これも非常に低い状態)と比べて増加していないからです。

問題の核心は、ネットワークリクエストのタイムアウトにあるようです:

証明書に表示されるアバターは data:image/png;base64 のバブル(blob)のようです。私の確認範囲では、アバターのダウンロードを試みてタイムアウトしている可能性があります。これが処理を遅らせている原因ではないでしょうか?

参考までに、このフォーラムは SSO を使用しており、アバターは S3 に保存された HTTPS URL です。Docker コンテナ内からこれらのアバターのいくつかを取得してみましたが、動作し、ほぼ即座に完了しました。ファイアウォールの問題などもありません。フォーラムの他の機能は高速に動作しますが、証明書の生成時のみ非常に時間がかかります。

もし確認すべき点のヒントをいただければ、さらにデバッグを進める用意があります。

画像は try.discourse.org ではほぼ瞬時に表示されました。0.5 秒以上の顕著な遅延は、もしあるとしても気づきませんでした。信じられないなら、ご自身で試してみてください!

したがって、私が最初に言ったことに戻りますが、なぜあなたのサーバーではこれほど遅いのに、try.discourse.org ではこれほど速いのでしょうか?

確かにそうです… それが私がサポートを求めている理由です。

Docker ならあるまじき「自分のマシンでは動く」という状況だと理解していますが、残念ながらここに至り、私だけがこの問題を抱えているわけではないようです(参考リンク)。

こちら側でデバッグするためのヒントがあれば、ぜひ教えてください。

調査したところ、この問題は discourse-narrative-bot が証明書に含めるユーザーのアバターを取得する際にブロックしているように見えます。ここです:

このフォーラムは SSO を使用しており、アバターは Amazon S3 の URL です。Amazon は高速でレート制限もかけていません。とはいえ、その関数は以下のような形式のアバター URL を取得しています:

https://forum.tld/user_avatar/forum.tld/username/240/18705_2.png

証明書生成を遅らせているタイムアウトエラーは、Discourse の レート制限 に何らかの形で抵触していることが原因でしょうか?Discourse インスタンス自体からアバターが要求されすぎていた場合や、複数のユーザーがボットチュートリアルを実行している際に Amazon S3 に過剰なアクセスを試みていた場合などが考えられます。

興味深いですね。そこに base64 画像をインライン化しています。なぜ image svg タグで外部リソースにリンクしなかったのか気になりますね :thinking:

このプラグインの歴史を、この機能を初めて追加した時点までさかのぼって調べてみました:

どうやら、私たちは最初から base64 でインライン化されたアバターを使用していたようです。

編集:いくつか調査した結果、base64 でインライン化しているのは、証明書が img HTML タグを通じて読み込まれているためです。より安価なアバターを実現するには、デフォルトで CSP によってブロックされている object タグを使用するか、SVG 全体を投稿コンテンツにインライン化する必要があります。おそらく iframe が最善の策でしょう。

@tgxworld へのコメントについては、FIX: Make discobot certificate gen faster/non blocking by xfalcox · Pull Request #11344 · discourse/discourse · GitHub を作成しました。

SVG に base64 エンコードされたアバターを埋め込んでいるのは、ロゴが「そうしていた」のと同じ理由だと推測します。つまり、証明書がその時点でのスナップショットとなり、受賞者が外部依存関係なしに保存でき、後でも全く同じようにレンダリングされるようにするためです。

iframe 方式では、投稿で簡単に共有して自慢することが難しくなります。他のフォーラムでこれがどれほど一般的かはわかりませんが、当社のユーザーの中には、単に画像の URL をコピーして这种做法をする人も見かけます。

外部へのリンクにする場合、<image> を使うことで、allowed_iframes の変更を回避できるのではないでしょうか?

上記の PR をお読みいただければお分かりの通り、まさにそれが実装されています :grimacing:

ただし、現在行っているように HTML の img タグで SVG を読み込む場合、SVG 内の image タグに含まれる外部画像は読み込まれません。そのためには、object または iframe を使用して読み込む必要があります。

明らかに SVG について十分な知識がありませんでした。iframe アプローチでは証明書からの引用やコピーが防止されますが、何らかの形でこの問題が解決されていることは嬉しく思います。これにより、私たちの問題が解決されるだけでなく、証明書の欠落しているロゴの問題も解消されます。:+1:

@mentalstring 新しい証明書生成コードをマージしました。これではるかに高速になるはずです。

これマージされて嬉しいです。:+1:

現在は stable ブランチを使用しており、現時点でこれを十分にテストする方法がありません。しかし、fetch_avatar がもう使われなくなったのであれば、これで Net::ReadTimeout エラーが解消されることを期待しています。これを解決済みとしてマークしておきますが、更新時に何らかの理由で同じ問題に再び遭遇した場合は、再度オープンします。ありがとうございます!