これがGoogleエンジニアの実力!「問題解決」奮闘記を公開

著者:
投稿日:
更新日:

Googleのエキスパートエンジニアが担当プロダクトのChromeのフリーズを直すまでの奮闘記を公開しました。

ブルース・ドーソン

GoogleでChromeを開発しているエキスパート開発者


事の発端は、

「24コアもあるCPUを積んでいるハイエンドPCにかかわらず、Gmailを併用するとChromeがフリーズしてしまった」

という現象に遭遇したことです。


ブルース・ドーソンさんが、その原因を発見するまでの取り組みをブログに書き残しています。

入力した文字が遅れて表示されるなどの怪しい挙動を見せた後、突然Gメールが応答しなくなってしまった

ドーソンさんは普段から「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のプロセスのスレッドを詳細に調査

フリーズしていた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)

さらに、GmailプロセスをVMMapで調査

上記のデータにある「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(Control Flow Guard)とは?

CFGはエクスプロイトを防止するためのもの。

このCFGが予約した2TiBのメモリの中身は疎なビット列となっており、ユーザー用の128TiBのメモリ空間のうちどのアドレスが正当なターゲットなのかを管理しています。ドーソンさんは先ほど作成した仮想メモリスキャナーを走らせ、このCFGの2TiBのメモリ予約にいくつブロックが存在し、さらにそのうちいくつが実行可能なものとなっているのかを調べてみたそうです。CFGメモリは実行可能メモリを指し示すものなので、ドーソンさんは実行可能メモリの各ブロックに対してCFGメモリブロックが1つずつ存在するかと予想していたそうですが、実際には実行可能メモリ98ブロックに対してCFGメモリは2万4866ブロックもありました。なお、先ほどのVMMapでの表示は4万9684ブロックとなっていましたが、これはドーソンさんのツールがコミットされているブロックのみカウントするのに対し、VMMapはコミットされたブロックに加えて予約されているブロックもカウントするためです。

実行可能メモリが開放されたときにCFGメモリが開放されていない

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アップデートで修正されています。

実際に使用されたコードも見ることができます

アイテムを追加
  • 画像
  • 動画
  • 引用
  • Twitter
  • テキスト
  • 見出し
	

著者プロフィール
Sharetube