Firefox 37 東京アメッシュの初回表示が異常に遅い

プライベートのメインブラウザは Firefox なのですが、このところ 東京アメッシュ だけなぜか表示が異常に遅くなってしまいました。IE や Chrome はすぐに表示されますので、Firefox 固有の問題のようです。
Firefox を起動後、東京アメッシュ の初回表示だけが30秒ほどかかってしまいます。2回目以降はすぐに表示されます。ブラウザを閉じ再起動しても初回が遅い事象が再現されます。「重い」というより通信処理待ちの遅延のような感じです。
遅延に気付いたのはバージョンが36.x頃だったと思いますが、時間はかかりますが30秒程度で表示されるのでしばらく放置していましたが、少し時間が取れましたので調査してみました。環境は Windows7 32bit ですが、64bit でも同様の症状が再現されてます。ただ 東京アメッシュ の推奨ブラウザに Firefox の名前がないのが少々気になりますが。

Firefox ユーザは少数なのかあまり情報がなかったのですが、ここにきて Firefox Input(Twitter) や 2ch で、ちらほら同様の症状の報告が上がってきました。
Firefox もとい Mozilla といえば Netscape Navigator Gold 2.0 からのコアユーザでして、かれこれ20年になりますかね(汗)

この 2ch の 781 レスから、どうやら Firefox 設定の「オプション > セキュリティ」タブの「攻撃サイトととして報告されているサイトをブロックする(K)」のチェックを外すと直るらしい。

「攻撃サイト…」「偽装サイト…」についての説明は mozilla support に詳しく記載されています。

オプション > セキュリティ 説明
攻撃サイトとして報告されているサイトをブロックする この設定は、マルウェアのサイトやファイルから防護します。
偽装サイトとして報告されているサイトをブロックする この設定は、閲覧者をだまして個人情報や銀行の暗証番号などを入力させようとする詐欺サイトを警告します。

この「攻撃サイト…」もとい「セーフブラウジング」のキーワードからさらに調査しますと MozillaZine.jpフォーラム に辿りつきました。

こちらの情報ですと「攻撃サイト…」に加え「偽装サイト…」についても違いがあるようです。また「東京アメッシュ」だけでなく「バンダイチャンネル」でも同様の症状が起きているようです。
確かに「攻撃サイト…」のチェックを外しますと「東京アメッシュ」が正常にすぐ表示されますね!

ということで、この表示遅延の原因やボトルネックがどこなのかを調査してみることにしました。
まずはいつからなのか、バージョン毎に表示速度を調べてみました。表示速度の計測にはブラウザ(クライアント側)の問題ですので、お手軽なブラウザ機能の Navigation Timing API を使用しました。いわゆる Javascript の window.performance でブラウザの一連の処理速度を計測できます。
詳細は割愛しますが、impressが提供しているブックマークレットによる計測を使用することにしました。
ブラウザ(クライアント側)の問題ということは、処理速度はPC性能に左右されますので、フォーカスするのは処理時間そのものではなく設定による処理時間の差になります。

Firefox
バージョン
オプション > セキュリティ 表示速度(秒)
攻撃サイト 偽装サイト 初回 2回目
32.0.3 0.233 0.227
0.225 0.165
0.208 0.190
0.244 0.165
33.0 27.391 0.199
27.274 0.219
27.488 0.157
0.216 0.154
33.1.1 27.560 0.188
27.177 0.223
26.893 0.158
0.252 0.162
34.0.5 27.701 0.185
27.653 0.209
27.424 0.207
0.245 0.204
35.0.1 28.299 0.192
28.232 0.210
28.244 0.200
0.245 0.188
36.0.4 25.510 0.186
26.295 0.209
25.814 0.205
0.479 0.159
37.0.2 25.408 0.404
0.535 0.341
25.677 0.384
0.400 0.355

上記の結果から、32.0.3までは問題なかったのが、33.0以降初回表示が遅くなっているのが見てとれます。また33.0~36.0.4までは「攻撃サイト…」「偽装サイト…」ともチェックを外さないと直らなかったのが37.0.2では「攻撃サイト…」のみとなっているのがわかるかと思います。なお処理時間はPC性能に依存します。

さてこの遅延の間、明らかにクライアントのPCでの処理に時間がかかっており、なにをやらかしているのか非常に気になるのでさらに調べてみました。
まず、Process Explorer にて Firefox の当該プロセスを追いますと、やはりこの30秒間はCPU使用率が100%ではないですが30~40%程度とある程度負荷がかかっているのがわかりました。重い原因でよくあるのが、Flashなど応答のないスクリプト警告で「(応答なし)」となる事象なのですが、今回の遅延では「(応答なし)」にはなりませんでした。

「攻撃サイト…」のセーフブラウジング機能については、ブラウザがダウンロードしたファイルのハッシュ値を Google(https://safebrowsing.google.com) へ問い合わせし有無害判定を請う機能なのですが、「攻撃サイト…」を有効にし、ブラウザコンソールで通信ログをトレースしますと、確かに以下のURLにPOSTリクエストしているのがわかりました。
[cc] https://safebrowsing.google.com/safebrowsing/gethash?client=navclient-auto-ffox&appver=37.0.2&pver=2.2
[/cc] そこで Live HTTP Headers にて Google へリクエストの再送信を試みましたが、特段 Google 側が重いという事象はありませんでした。レスポンスタイムもミリ秒単位でしたし、やはり Google へ問い合わせ後のブラウザの処理に時間がかかっているようです。

ここで重要なのがこの遅延の間、以降の通信(リクエスト)が「処理待ち」状態になることです。この事象が究明のカギになりそうな気がします。
これらからあくまで仮説ですが「セーフブラウジング機能により Google に問い合わせし、取得データをもとにブラウザで共通使用するリソースがなんらかの処理で排他ロックされ、以降の通信が処理待ちになる」というように思えてなりません。

「攻撃サイト…」「偽装サイト…」のセーフブラウジング機能はローカルにデータベースがありそうなので、調べてみますと案の定、以下のプロファイル配下の safebrowsing フォルダに保存されているのがわかりました。
[cc] %LOCALAPPDATA%\Mozilla\Firefox\Profiles\xxxxxxx.default\safebrowsing
[/cc]
遅延の間、このフォルダをウォッチしていますと以下のようにフォルダがリネーム&削除&再作成を繰り返しているのがわかりました。おそらくCPU負荷が高いのは、ファイルI/Oで取られているのが原因のように思います。
[cc] \safebrowsing
↓ (rename)
\safebrowsing-backup
↓ (rename)
\safebrowsing-to_delete
↓ (delete & new)
\safebrowsing
↓ (loop)
[/cc]

ではこのsafebrowingフォルダが、なぜリネーム&削除&再作成を繰り返すのか?という根本原因の特定にはまだ至っておりません。Firefoxのソースを舐めないと解らないかもしれません。

セーフブラウジングの「攻撃サイトのチェックを外す」ということはセキュリティレベルを下げることに繋がりますので、判断は分かれるかと思いますが、ただセーフブラウジングがどの程度セキュリティに貢献しているかは不明です(汗)すでにアンチウィルスソフトで対応できている気もしないでもないですが。。。

取り急ぎ、ここまでは判明しました。


2015/05/16 追記
Firefox 38.0.1 でも遅延継続中ですが、技術的なことはさておき、攻撃サイトのチェックをしたまま、アメッシュの表示を早くしたいのであれば、単純に英語サイトを表示すればよいかと思います。

降雨画像は同じですから、これでこれまでの遅延ストレスから一気に解消されます(笑)とりわけ気象などの公共情報は即表示されないとイライラ感が倍増しますからね!

なぜ日本語サイトだけGoogleへセーフブラウジングの問い合わせに行くのか、またsafebrowsingフォルダの作成削除を繰り返すのか、HTMLソースなどもdiffって追ってみましたが、いまだ原因究明には至っておりません。


2015/09/19 追記
ようやく原因が判明したようですね。
https://bugzilla.mozilla.org/show_bug.cgi?id=1164518#c43
[cc] 7000[1a73a900]: Checking fragment tokyo-ame.jwa.or.jp/ja/images/, hash FB928D3D9BB6B30740D5C8BD9D82B50B4CD53692752DB091B3C61C9F4AE3E031 (3D8D92FB)
0[4d1000]: nsHttpChannel::BeginConnect [this=1c423400] 7000[1a73a900]: Probe in goog-malware-shavar: 3D8D92FB, found 1
0[4d1000]: host=tokyo-ame.jwa.or.jp port=-1
7000[1a73a900]: Found a result in goog-malware-shavar: Not complete. (Age: 86400s)
[/cc]
結局、「tokyo-ame.jwa.or.jp/ja/images/」URL の Hash Prefix (3D8D92FB) をローカルのマルウェア(goog-malware-shavar)データベースに照会したら1件ヒットしたことがトリガーになり、safebrowsing.google.com へ Full-Length Hashes を問い合わせに行き、結果をデータベース更新(再構築)するようです。このデータベース更新もとい再構築こそが上記で指摘した safebrowsing フォルダの作成削除になります。ここでピンときますよね。「tokyo-ame.jwa.or.jp/ja/images/」という URL はボタンなどの画像をリクエストする度にこの処理が行われるということですよね。ログを grep しますとざっと67画像。一方 safebrowsing.google.com への問い合わせは41件。「3D8D92FB, found 1」ごとに safebrowsing.google.com へ問い合わせているのではなく、どこかのタイミングで問い合わせているようです(もしくはリミッタかもしれません)。1回の処理に概ね500~1000ms(0.5~1秒)、全く同じ処理を41回も safebrowsing.google.com へ問い合わせ、その都度データベースを再構築するわけですから時間がかかるわけですよね。Hash Prefix ですからたまたま「tokyo-ame.jwa.or.jp/ja/images/」がマルウェア対象の Hash Prefix と一致してしまった可能性が高いですね。
[cc height=”200″] http://tokyo-ame.jwa.or.jp/ja/images/button/headmenu/home_on.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/headmenu/guidance.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/headmenu/amesh.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/headmenu/link.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/headmenu/english.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/headmenu/gesui.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_west.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_north.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_south.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/west23.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/east23.gif
http://tokyo-ame.jwa.or.jp/ja/images/map/explanation.gif
http://tokyo-ame.jwa.or.jp/ja/images/spacer.gif
http://tokyo-ame.jwa.or.jp/ja/images/time_panel/time_panel_lane.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/back.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/next.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/play.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/stop.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/stop2.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/history.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/whole.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/magnify.gif
http://tokyo-ame.jwa.or.jp/ja/images/sub_title/info_list.gif
http://tokyo-ame.jwa.or.jp/ja/images/sub_title/warn.gif
http://tokyo-ame.jwa.or.jp/ja/images/hanrei.gif
http://tokyo-ame.jwa.or.jp/ja/images/navi_map/navi_map.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/details_ja.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_west/okutama.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_west/hinohara.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_west/ome.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_west/hinode.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_north/musashimurayama.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_north/tachikawa.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_south/hachioji.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/tama_south/hino.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/west23/nerima.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/west23/suginami.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/west23/setagaya.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/east23/adachi.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/area/east23/koto.gif
http://tokyo-ame.jwa.or.jp/ja/images/now_loading.gif
http://tokyo-ame.jwa.or.jp/ja/images/anim.gif
http://tokyo-ame.jwa.or.jp/ja/images/error_display.gif
http://tokyo-ame.jwa.or.jp/ja/images/bg/header_bg.gif
http://tokyo-ame.jwa.or.jp/ja/images/amesh_logo.gif
http://tokyo-ame.jwa.or.jp/ja/images/bg/headmenu_bg.gif
http://tokyo-ame.jwa.or.jp/ja/images/bg/headinfo_bg.gif
http://tokyo-ame.jwa.or.jp/ja/images/time_panel/time_panel_knob_blink.gif
http://tokyo-ame.jwa.or.jp/ja/images/time_panel/time_panel_knob.gif
http://tokyo-ame.jwa.or.jp/ja/images/time_panel/time_panel_knob_click.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/back_off.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/back_on.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/next_off.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/next_on.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/play_off.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/play_on.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/stop_off.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/stop_on.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/stop2_off.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/stop2_on.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/history_off.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/history_on.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/whole_off.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/whole_on.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/magnify_off.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/magnify_on.gif
http://tokyo-ame.jwa.or.jp/ja/images/button/operate/details.gif
[/cc]

取り急ぎ addPrefix() の対処療法を行うようですが、根本的にこの safebrowsing 処理のロジックはどうなんでしょう?「found 1」になった場合、そのURLのユニーク一覧を保持しておきレスポンス最後に safebrowsing.google.com へ一括問い合わせしデータベース更新は一度だけとかはできないんでしょうかね。または67画像で41回問い合わせですからこのバッファをもう少し多めに取ったらよいと思うのですが。問い合わせ処理とデータベース更新処理は別スレッドのようなので難しいのかな?
もしくは問い合わせとデータベース更新を同期処理にするとか。またはそもそも再構築ではなくマージ(追記)とかできないんでしょうかね。このままではまた同じような Hash Prefix が一致するサイトが出てきそうな感じがしますね。いずれにしても、safebrowsing 処理のロジックは改善の余地がありますね。

この修正がどのバージョンで反映されるかは不明ですが、もう少し時間がかかりそうですね。


2015/09/23 追記
東京アメッシュの初回表示が異常に遅い不具合は解消されました。ユーザ側で特になにか行う必要はありません。直らない場合は Firefox の再起動を行って頂ければ修正されるはずです。

FireFox は起動時にリモートの safebrowsing サーバから最新の safebrowsing データを取得しデータベースを再構築しますが、その中に「tokyo-ame.jwa.or.jp/ja/images/」URL の Hash が登録されたようで「3D8D92FB, found 0」となり、無事修正されました。ということはホワイトリストに追加されたってことなのでしょうかね。このあたりがまだよくわかってませんが(汗)safebrowsing のデータが Firefox 本体依存ではなく外部データであったため思ったより早く修正されましたね。このため不具合が起き始めた Firefox33~ でも修正されています。でも直って良かったですね。

■ bugzilla
https://bugzilla.mozilla.org/show_bug.cgi?id=1164518