GoogleのエキスパートがChromeのフリーズを直すまでの奮闘記
「24コアもあるCPUを積んでいるハイエンドPCであるにもかかわらずGmailを使っている際にChromeがフリーズしてしまった」という現象に遭遇したブルース・ドーソンさんが、その原因を発見するまでの取り組みをブログに書き残しています。なお、ドーソンさんはGoogleでChromeを開発しているエキスパート開発者です。
24-core CPU and I can’t type an email (part one) | Random ASCII
ある日の朝、ドーソンさんは極めて日常的な「メールを書く」という作業をGmailで行っていたところ、入力した文字が遅れて表示されるなどの怪しい挙動を見せた後、突然Gmailが応答しなくなってしまうという事態に遭遇しました。
さすがエキスパートと言うべきか、ドーソンさんは普段から「UIforETW」というイベント追跡ツールをバックグラウンドで立ち上げており、「Ctrl+Win+R」を押すだけで過去30秒間のイベント情報がディスクに保存されるようになっています。こうして保存したイベント情報を「Windows Performance Analyzer」という解析ツールに読み込ませ、同じブログの記事でやったようにフリーズした時の特徴である「イベントループにおけるメッセージポンプの停止」を見つけることでフリーズの原因となっているスレッドを突き止めることができます。
大抵は上記の方法で原因が判明するのですが、今回はこの方法ではうまく行かなかったとのこと。Chromeはフリーズ後もイベントループが働いている証拠であるメッセージポンプを行っており、また無限ループに陥っていたり完全に何もしていなかったりするスレッドも見つけられず、解析ツール上でのChromeは「何も入力されなかったので待機状態に移行した」ようにしか見えなかったそうです。
UIforETWには入力したキーの情報を保存する「キーロガー」機能も付いているのですが、セキュリティ上の理由によりデフォルトではプライベートモードとなっており、全ての入力が「1」もしくは「A」と表示されるようになっています。ドーソンさんはこのキーロガー機能をプライベートモードからフル機能モードに切り替え、また同様のフリーズが起きるのを待ったそうです。
幸いなことに(？)次の日にまたフリーズが起きたので、ドーソンさんはイベント情報を保存すると同時に次のようなメモ書きを残しました。
「defer to those with more scuba experience」と入力したところ、「those」の後ろでGmailが少しフリーズし、その後「experience」まで入力された。
GmailタブのPID(プロセスID)は27368。
解析ツールで見たキーボードの入力イベントは以下の画像の通り。イベントが発生したタイミングは右上の紫色のダイアモンドで表示されており、、フリーズが起きたタイミングをはっきりと特定することができました。そしてこのフリーズが起きていたタイミングでは画像の下部に表示されているCPU使用率がほぼ0となっていることも読み取れます。
フリーズが起きたタイミングが判明したので、この期間のchrome.exeプロセスのスレッドを詳細に調べてみると、フリーズしていた2.81秒の間にスレッドは正常に440回呼び出されていることが分かりました。2.81秒間に440回というのは約6msごとに1回呼び出されている計算になり、これは正常な応答を返すのに十分な呼び出し回数です。さらに原因調査をすすめていくと、それぞれの呼び出しにおいて同じスタックが積まれていることが判明しました。該当部分を単純な形で表すと以下のようになります。
chrome_child.dll (stack base)
KernelBase.dll!VirtualAlloc
ntoskrnl.exe!MiCommitVadCfgBits
ntoskrnl.exe!MiPopulateCfgBitMap
ntoskrnl.exe!ExAcquirePushLockExclusiveEx
ntoskrnl.exe!KeWaitForSingleObject (stack leaf)
ChromeがVirtualAllocを呼び出し、そのVirtualAllocが「CfgBits」という何かを書き替えるために排他的な書き込み権限であるロックを取得しようとしています。ドーソンさんは最初、ChromeがVirtualAllocを440回呼び出したのかと思ったそうですが、実際にはVirtualAllocは1回しか呼び出されておらず、さらには「ロックが利用可能になった」という通知があったにもかかわらず439回連続でロックの取得に失敗していたそうです。これはロックを開放したプロセスがすぐに同じロックを取得してしまっていたためとのこと。
Windowsのロックは後からロックを試みたスレッドが先にロックすることを許す「unfair」なものであるため、上記のような「ずっと同じロックを再取得し続ける」動作ができるようになっています。そして今回ロックを再取得し続けていたのはWmiPrvSE.exeで、これが以下のようなスタックでロックを開放していました。
ntoskrnl.exe!KiSystemServiceCopyEnd (stack base)
ntoskrnl.exe!NtQueryVirtualMemory
ntoskrnl.exe!MmQueryVirtualMemory
ntoskrnl.exe!MiUnlockAndDereferenceVad
ntoskrnl.exe!ExfTryToWakePushLock (stack leaf)
そしてドーソンさんはこのWmiPrvSE.exeが何に時間を使っているのかを調査したとのこと。時間がかかっていた部分のスタックは以下のようになっていました。
WmiPerfClass.dll!EnumSelectCounterObjects (stack base)
WmiPerfClass.dll!ConvertCounterPath
pdh.dll!PdhiTranslateCounter
pdh.dll!GetSystemPerfData
KernelBase.dll!blah-blah-blah
advapi32.dll!blah-blah-blah
perfproc.dll!blah-blah-blah
perfproc.dll!GetProcessVaData
ntdll.dll!NtQueryVirtualMemory
ntoskrnl.exe!NtQueryVirtualMemory
ntoskrnl.exe!MmQueryVirtualMemory
ntoskrnl.exe!MiQueryAddressSpan
ntoskrnl.exe!MiQueryAddressState
ntoskrnl.exe!MiGetNextPageTable (stack leaf)
上記のデータにある「NtQueryVirtualMemory」はプロセスメモリをスキャンするのに使用されますが、このNtQueryVirtualMemoryがGetProcessVaDataから呼び出されています。このあたりが怪しいと踏んだドーソンさんは、NtQueryVirtualMemoryを呼び出して特定のプロセスのアドレス空間をスキャンするプログラムを自分で作成してみたそうです。プログラムはちゃんと動作したのですが、Gmailプロセスをスキャンする際には10秒以上という極めて長い時間がかかり、さらにGmailのフリーズを誘発させました。
ドーソンさんは自分でスキャンするプログラムを作成したため、さまざまな統計を取ることができたとのこと。NtQueryVirtualMemoryは、予約されていたり、特定の保護設定がされていたりするなどの一致する属性を持つアドレス空間の連続した範囲をブロックとして返してくれます。調査によるとGmailプロセスは合計2万6000個のブロックを持っていたのですが、1万6000個のブロックを持つ別のプロセスをスキャンしてみたところ一瞬でスキャンが終わったので、ブロックの個数が問題という訳ではなさそうです。
今度はGmailプロセスをVMMapで見てみると、Shareableカテゴリに4万9684個のブロックで361,836KiBのメモリが使用されており、さらにそのメモリ予約量は2TiBに至っていることが判明。
そしてこの2TiBのメモリ予約はControl Flow Guard(CFG)に使用されています。ここでドーソンさんは最初に確認したChromeのコールスタックに「MiCommitVadCfgBits」が積まれていたことを思い出し、今回の問題の原因がこのCFGにあることが分かったそうです。
CFGはエクスプロイトを防止するためのものですが、このCFGが予約した2TiBのメモリの中身は疎なビット列となっており、ユーザー用の128TiBのメモリ空間のうちどのアドレスが正当なターゲットなのかを管理しています。ドーソンさんは先ほど作成した仮想メモリスキャナーを走らせ、このCFGの2TiBのメモリ予約にいくつブロックが存在し、さらにそのうちいくつが実行可能なものとなっているのかを調べてみたそうです。CFGメモリは実行可能メモリを指し示すものなので、ドーソンさんは実行可能メモリの各ブロックに対してCFGメモリブロックが1つずつ存在するかと予想していたそうですが、実際には実行可能メモリ98ブロックに対してCFGメモリは2万4866ブロックもありました。なお、先ほどのVMMapでの表示は4万9684ブロックとなっていましたが、これはドーソンさんのツールがコミットされているブロックのみカウントするのに対し、VMMapはコミットされたブロックに加えて予約されているブロックもカウントするためです。
Scan time, Committed, page tables, committed blocks
Total: 41.763s, 1457.7 MiB, 67.7 MiB, 32112, 98 code blocks
CFG: 41.759s, 353.3 MiB, 59.2 MiB, 24866
実行可能メモリが配置されたときにCFGメモリブロックも配置されるのですが、上の結果からは実行可能メモリが開放されたときにCFGメモリが開放されていないように見えます。
ドーソンさんはこの挙動を確かめるため、VAllocStressという「ランダムなアドレスに実行可能メモリのブロックを割り当てて開放する」というプログラムを作成しました。このプログラムのアルゴリズムは以下の通り。
1. 以下のループを大量に回す
A. VirtualAllocを使って実行可能メモリをランダムなアドレスに配置する
B. そのメモリを開放する
2. その後、以下のループを無限に回す
A. CPUホッグを避けるために500ms待機する
B. VirtualAllocを使用して実行可能メモリをある一定のアドレスに配置する
C. Bの動作にかかる時間が500msを超えていればメッセージを表示
D. メモリを開放する
上記の単純なプログラムを実行し、さらに前述の仮想メモリスキャナーで動作の様子を監視すると見事にCFGメモリブロックが断片化していき、スキャニングに長い時間がかかるようになることが確かめられました。ついにはVAllocStressプログラムがフリーズし、問題の再現に成功したとのこと。
これで問題の原因は判明しましたが、続いてChromeはどのようにしてこの問題を引き起こしていたのかという調査に移ります。ChromeでJavaScriptを動作させているV8エンジンはメモリ管理にCodeRangeオブジェクトを使用していますが、一つ一つのCodeRangeオブジェクトの大きさは128MiBまでに制限されています。この制限があるため、ドーソンさんはCFGが過度に割り当てられることはないだろうと思っていたそうです。
ところが、CodeRangeオブジェクトが複数発生するとなると話は異なります。ドーソンさんの調査によって、Gmailを開いている間、数分おきにCodeRangeオブジェクトが生成され消去されるということを繰り返していたことが判明します。さらにデバッガを使うことでWorkerThread::StartがそれらのCodeRangeオブジェクトを生成していることが分かり、全容が解明されました。
ドーソンさんの調査によって判明した問題の全容は以下の通り。
1. Gmailではオフラインモードのためにサービスワーカーが使用されている。
2. サービスワーカーの仕様で、サービスワーカーは数分おきに起動と終了を繰り返す
3. それぞれのサービスワーカーはCodeRangeオブジェクトを取得し、このCodeRangeオブジェクトがJavaScriptからJITで生成されたコードを実行するために47bitのアドレス空間からランダムな場所に実行可能メモリを確保する
4. 新しいコードが割り当てられた時、CFGメモリ予約がエントリーを受け取る
5. このCFGの割り当てはプロセスが終了するまで永遠に開放されない
6. 肥大したCFGメモリをスキャンするNtQueryVirtualMemoryが非常に遅くなる
なお、このCFGメモリのスキャンが遅くなる問題は2018年4月のWindows 10 RS4アップデートで修正されています。また、ChromeのJavaScriptエンジンであるV8のチームも問題を引き起こす原因となったCodeRangeオブジェクトを再利用するように修正しています。また、今回の調査でドーソンさんが作成した2つのプログラム「VirtualScan」「VAllocStress」はGitHubで公開されています。
