背景
皆さんご存知の通りBitVisorにはtime (core/time.c) というのがあって、VMM起動時からの時間を計算しています。時間情報の元になっているのは、ACPIのPower Management Timer (PM_TMR)か、または、CPUのtime stamp counter (以下TSC)です。
ACPIのPower Management Timer (PM_TMR)は、I/Oポートから得ることができる24ビットの整数値で、3.579545MHzでインクリメントされるカウンターになっています。非常に扱いやすいものですが、CPUの外にあるため読み取りに時間がかかります。
TSCは、CPUの中にあり、CPUクロックで進む64ビット整数のカウンターです。読み取り時間は短く、精度は高いものの、マルチプロセッサがある環境においてはCPUごとにずれが生じる可能性があります。マルチコアの場合はずれがない場合も多いのですが、BitVisorは、複数の論理プロセッサがマルチプロセッサなのか、シングルプロセッサでマルチコア/マルチスレッディングなのかを区別していないため、ずれが生じるものと想定して実装されています。従来は電源管理のためのクロック周波数変動の影響を受けていましたが、invariant TSC対応のプロセッサはその影響を受けず、より扱いやすくなりました。
BitVisor / core/time.c Commit Log
上のhistoryを見ていただくとわかるように、2014年のバージョン1.4でinvariant TSCに対応した後、2021年になるまで修正はありませんでした。
ずれへの対処
TSCのプロセッサ間のずれに対処するため、BitVisorでは以下の変数を用いています:
- lastcputime (全プロセッサ共通)
- tsc (プロセッサごと)
- timediff (プロセッサごと)
lastcputimeは最後に取得した時間情報です。以前返した時間より前の時間を返してしまうのはまずいので、それを検出するのに使用します。
tscは起動時のTSCの値をとっておきます。
timediffは補正に使います。以前返した時間より前の時間が計算された時、そのプロセッサの時間情報はその差の分だけ他より遅れていると見ます。timediffにその差を蓄積し、以降の時間計算の際にtimediffを加えることで、時間を合わせていきます。
冷静に読んでいる皆さんはお気づきのことと思いますが、lastcputimeとの差だけ進める、ということは、他のプロセッサで最後に返した時間に合わせるということであって、補正後の時間が他のプロセッサにどれだけ追従できているかはわかりません。時間取得を毎秒100回している状況であれば、1/100秒以内程度のずれに収まることが期待できますが、最後の時間取得が3秒前だったとしたら、3秒分は遅れが残ったままになります。
バグ
今回見つかったのがこれです:
複数の論理プロセッサがあるUEFI環境で問題になる内容です。といっても今時はそんな環境が多数と思いますが...
問題は初期化の処理にありました。上述のtimediffを、常に0で初期化していました。
BIOS環境においては、すべての論理プロセッサを最初に起動し、同期を取った上でtscにその時の各プロセッサのTSCを保存し、timediffを0で初期化するので、大きなずれは生じませんでした。
UEFI環境では、すべての論理プロセッサを起動するのは、オペレーティングシステムが論理プロセッサ開始のためのプロセッサ間割り込みを送信する時まで遅延されています。例えば、BitVisor上で、GNU GRUBからGNU/Linuxを起動しようとする時、GNU GRUBが動作している間はBitVisorはひとつの論理プロセッサしか使用していません。そのような状況を思い浮かべれば、この遅延が通常でも数秒、場合によっては数分から数時間になる可能性もあることが容易に想像できます。
さて、timediffを0で初期化していたため、その遅延して起動された論理プロセッサにおける時間は0からスタートすることになっていました。当然、起動に使われた論理プロセッサで一度でも時間取得がされていれば、lastcputimeに0以外の値が保存されていますから、最初の時間取得の際には必ず補正がされる形となります。上述のようにこの補正は他のプロセッサで最後に返した時間に合わせるということですので、何度か補正が繰り返される場合がありました。
このバグの影響で発生した問題
このバグが見つかったきっかけは、NVMeのタイムアウトでした。drivers/nvme/nvme_io.cではidentifyなどのコマンドに2秒のタイムアウトが設定されていますが、そういうタイムアウトに引っかかったのです。最初は、NVMeのデバイスの問題や、ドライバーの実装の問題を想定しますが、調査を進めると、コマンド完了待ちのwhileループが、timeを取得しschedule()を繰り返している中で、取得した時間が飛んでいることがわかりました。例えばある時のtimeが10秒だったのが、1回schedule()を呼び出してもう一度timeを読み取ると13秒になる、というようなことが起きていました。
これを見つけた時は、オペレーティングシステムが何かの処理のために割り込み禁止状態を長く保持して、VM Exitがないまま実際に3秒経過したのではないか、とも考えましたが、それにしては見た目で何秒も止まっている様子がないし、panicログを見ても割り込み禁止状態にすらなっていません。それで詳しく調べると、大雑把には以下のようなことが起きていました (数字は正確なものではありません):
- VMM開始から10秒ほどですべての論理プロセッサが起動
- VMM開始から13秒ほどで、起動時に使われた論理プロセッサとは別の論理プロセッサでNVMeコマンドを発行し、完了待ちのため時間を取得すると、10秒が得られる (他のプロセッサで最後に返した時間に合わせる)
- schedule()でもう一度完了待ちに戻ってくると今度は起動時に使われた論理プロセッサで、時間を取得すると13秒が得られる
- 3秒経過と誤認識しタイムアウト
修正
修正内容は、すべての論理プロセッサを起動するタイミングで、起動時に使われた論理プロセッサで時間取得を行い、他の論理プロセッサはその情報を元にtimediffを初期化するようにしています。これにより、起動時に使われた論理プロセッサ以外では最初に必ず大きなずれが生じるという問題は解決しました。