2011年12月29日

sched_clock() overflow after 208.5 days in Linux Kernel

えーっと、久しぶりに Linux Kernel にダメダメなバグが発見されて、よりにもよってうちの製品も影響を受けたので、ここに詳細を書くことにした。
つーか。新しい Kernel を使うなら皆で使おうよ。なんだよその「1つだけ」影響を受けて残りは「影響も受けないぐらい古い」ってのは…


概要
大雑把に 208.5日連続運転した Linux Kernel が突如として reboot する。

実機でなおかつ Time Stamp Counter を内包している必要があるので、Pentium4以降のプロセッサ(が、それはようするに今ある Intel 系CPU全部)か、その互換CPUである必要がある。32bit モード、64bit モードの区別はない。
逆に VMware や Xen など、仮想マシン上で動いている kernel に影響はない。これはそもそもバグを内包したルーチンを、仮想マシンで動いていると検出した Linux Kernel は使わなくなるからだ。

一切の予防的挙動は取られていないので、file systemなども含めて、non-volatile メディアに対する影響は甚大かつ破壊的。回避策はパッチの当たった Kernel をインストールしてrebootするか、200日以内に計画的に reboot する事のみ。


影響範囲
Linux Kernel 2.6.28 で導入されたパッチにバグがあり、3.1.5 で修正された。この間にリリースされた distribution は多分全部影響を受ける。

なお、具体的には
2.6系列:  2.6.32.50でfix
3.0系列:   3.0.13でfix
3.1系列:   3.1.5でfix
らしい。

商用 distribution で影響を受けているもの。

まずは SuSE11 SP1。fix パッチはこうなっている:
http://kernel.opensuse.org/cgit/kernel-source/commit/?id=413af9e6f17a1a1519cae0bfd1c1fe4409bb42a3

RHEL6も 2.6.32 base らいいのでこれも影響を受ける。
(2012/02/14追記: RHEL6 は kernel-2.6.32-220.4.2.el6 で修正が入ったらしい。http://rhn.redhat.com/errata/RHBA-2012-0124.html
ただし、ひどい事に「2012年1月24日に登録され、fix ができたのは2012-02-13という事になっている。3ヶ月近く何をしていたのか…)

多分Fedoraとかも影響をうけるはずだが、マシンを上げていないので判らない(何その手抜き)。
Fedora マシンを上げたら
「3.1.1→3.16 に kernel を更新」
という update が出ていた。 Fedora16使いは速攻で上げることをお勧めする。
また、Fedora15使いは速攻で Fedora16 にして、update を最新に持っていくことをおすすめする。


3.1.5のバグ修正後のコードはこう:
http://lxr.linux.no/linux+v3.1.5/arch/x86/include/asm/timer.h#L58
(LXRとか、こうやってソースコード丸ごと指定できるからありがたい)



なお、VMware とかの仮想環境では、このバグっているルーチンはそもそも利用されない。なのでこれは実機上で動かしている Linux Kernel でのみ、発生する。なので、VMで実験を…とかは一切効かない。


技術的詳細
最近の Intel processor やその互換CPUには Time Stamp Counter (TSC) という 64bit レジスタがある。

こいつは Intel の場合だと CPU 駆動クロックでカウントアップしていて、1tick ごとに+1していく。例えば 2GHz のCPUの場合、1秒で2Gづつ増えていくのだ。

また、AMDの場合だとCPUに投入されるクロックで 1tickごとに+1していく。大抵の場合は 800MHz なので1秒で800Mづつ増える。

判ると思うが、ほぼ nano 秒オーダーの時計として使えるので、リアルタイム制御をしたい場合、TSCはとてもありがたい。しかし、最近の電力消費量制御機構は、CPU駆動クロック周波数を変更してしまう。すると TSC の値は何がなんだか判らなくなる…
そこで、Linux Kernel 内部には cycles_2_ns() という関数があって、TSCの値をナノ秒に修正してくれる事になっている。

しかし、不幸はここに内包されていた


すごく簡単に言うと、TSCの値を必要な Scale Factor 倍すれば nano sec になる。しかし、TSCの値は nano sec に近い。当然 Scale Factor は 1.0 に近い、微妙な浮動小数点になってしまう。

そうだ! Scale Factor を分数で表そう!!
SC/1024 で表現して、
SCを整数にしておけば、
SCを掛け算した後、
右に10bit シフトすれば済むよっ!!!

…この段階で何か嫌な予感がしなかったんだろうか、こいつらは…


とにかく、元の式は、TSCの値を 64bit 変数に代入し、それに 32bit のSC ( コード上は per_cpu() という関数の戻り値) を掛けて、10bit 右にシフトする、というものになった。


さて。ちょっとここで視点を変えてほしい。
「TSCに SC を掛けて、その後 1024 で割ると nano sec になる」
って事は、

TSCにSCを掛けると
大雑把に pico sec の精度の数字ができる

って事だ。
210 = 1024 ≒ 1000 = 103

なので、メートル法の縮尺単位が1つ変化する度に10bit消費される。
(ここは試験に出ます)

すると、pico sec レベルでの数字を扱うと、1秒を扱うには 40bit 必要、ということだ。しかるに、この値は 64bit の変数に代入されいてる。って事は「1秒以上」の表現には 24bit しか有効桁数がないって事だ。

224 / ( 24 * 60 * 60 ) = 194.180741日

実際には、1024の方が若干大きいので、その端数が載る。具体的には 64bit変数を最後に 10bit 右にシフトするので、有効桁数は 54bitになる。これが nano sec で表された時刻なのだから、

254 / ( 24 * 60 * 60 * 1000 * 1000 * 1000 ) 
= 208.499983日

めでたく、今回 overflow を起こした日数そのものが出てくる。64bitは、無限にでかいに等しい桁数ではないのだ。

かくして、cycles_2_ns() は、208.5日経つと、桁あふれを起こして 0 に近い値を出力する。sched_clock() はこの値を利用しているため、ここもぶち飛ぶ。

スケジューラーはここの値に強く依存しているので、突如として 54bit の数字が 0 になると、カーネルのあちこちがぶっ飛んでしまい、reboot に至る。


感想
497日問題の反省
全く活かされておらずっっ!!!


------

あれから2年…どうやら新しい 208.5日問題が発見されたらしい…

今回は私なんぞよりよほどわかりやすく説明してくれる人が現れた。お陰でリンクを貼るだけで済む。ありがたや、ありがたや… (-人-)

今度のは CPU のバグとペアになっていて、reboot すると freeze する、という実に悪質な…実運用に入っているサーバのメンテナンスとかで再起動しようとしたら freeze した…なんて事、その場に立ち会ったら心臓がショックで止まりかねないだろう…。

19 件のコメント:

  1. おおこれはひどい。。RHEL6もばっちり影響うけてますね。あと瑣末なことですがTSCはtime stamp counterです

    返信削除
  2. 今、Intel のマニュアルで「Stamp」だと確認しました。ご指摘ありがとうございます。

    それにしてもこういうのは勘弁して欲しい。

    返信削除
  3. この解説が真だとすると、再現率100%のはずですが、該当カーネル+Xeon E5450 3GHzで問題なく2年以上連続稼働している例がいくつかあるようです。負荷が低くてSpeedStepが効いてクロックが落ちてるのだとしても、このバグを踏むのに十分な期間のはずですが。。。何か見落としてるでしょうか?

    返信削除
  4. 私の知る限り、そのような場合は次のどれかです。10例ぐらい、そうだった:
    1) 仮想マシン上で動いているのでTSCを参照していない
    2) カーネルのバージョンが思っている程新しくなかった
    3) 実はリブートしていることに気がついていない

    比率は8:1:1ですね、今のところ

    返信削除
  5. RHEL6 ですが、6.0 の時点で Kernel2.6.32-71 という記載になっていますが‥影響受けるんですかねぇ‥?
    6.2 では 2.6.32-220 まで来ているようですが。
    客先サーバ再起動したくないです‥(w

    返信削除
  6. RHELのバージョンの読み方を知っているなら、最後の -71 とかいう人は-220 とかはRHの番号にすぎない、ベースは 2.6.32 とわかりますよね?!

    また、RHEL6のソースコードで作られた、Scientific Linux 6がこけているのですから、影響を受けないはずがない、とわかりますね?!!

    RHEL6.2はsrpmを見てないので知りませんが…、再起動は確定ですな。

    返信削除
  7. 3つとも該当しないようです。仮想マシンではなく、カーネルは2.6.32で、uptime計測で656 days稼働しています。

    どうやら他にも条件がありそうですね。

    返信削除
  8. カーネルのバージョンをkwsk!特にdistribution名を。

    656日が正しいとすると、208.5日を3回潜りぬけ、30.5日目と言うことになります。また1年と291日前に動かしたことになる。まる2年まで74日…2年前の3月24日前後ですか? スタートしたのは。2010年の3月段階で存在したカーネル…

    返信削除
  9. 私のところも2.6.33.7を使用しており、影響受けそうで、早急に調査する必要がありそうです;;

    解説内では2.6.28で混入とありますが、具体的にはどのコードが追加/修正されることでこの現象が発生するようになったのでしょうか?
    (2.6.18のカーネルも確認したのですが、同じようにTSCにSCを掛けて10bitシフトしているみたいでしたが・・・)

    返信削除
  10. http://lxr.linux.no/linux+v2.6.18/arch/i386/kernel/tsc.c#L99
    とかのことですね?
    でも、結局この出力をまともに使っている部分はなかったはずです。

    返信削除
  11. なるほど、2.6.28ではsched_clock()の出力を使用するコードが追加されたため、
    再起動等の現象が発生するのですね。

    sched_clock()の使い方を見てると、前回タスク等の動作時の時刻をsched_clock()の出力として
    覚えておいて、現時刻との差をスケジューラまわりで使用している感じがするのですが、
    sched_clock()の出力が0付近になると、この差があまりにも大きな数字になるから
    ふっとんでしまうのでしょうか?

    質問ばかりですいません。

    返信削除
  12. 差が負になると困るルーチンもあるでしょうし、div0 でぶっ飛ぶルーチンもあるでしょう。
    http://groups.google.com/group/kernelarchive/browse_thread/thread/9840fe9bb6df1c0e/6d1d2a1f9cc24430?show_docid=6d1d2a1f9cc24430&pli=1には、soft watchdog が強引にリセットをかけるケースが書かれていますが、これは負値が問題なケース。

    何が起こり得るのかを全部列挙することは不可能ですし、やる価値があるとも思えません。
    計画的に作られているOSでは無いので、どのユニットがどこの出力のどのような性質に依存しているか、という情報はすぐ時代遅れになりますし、今後のパッチ採用に反映される可能性はLinus君の性格からしてもあり得ない。

    さらに言うと、Linuxの腐った性質に「大きなパッチを受け取らない」癖に「構造改造を設計しない」という問題があります。結果、パッチ提供者は何をするかというと、大きなコードを小さなパッチに分割します。それを、何バージョンにも渡って提供し続け、道具が揃ったところで「組み立てるパッチ」を提供する。この行為は今回のようなdead code を大量にもたらします。で、長く存在しているので後になって「長く存在し(きっと)使われているのだから、大丈夫に違いない」と無評価に転用され、破綻をもたらす。

    こういう世界では既存のコードの、自分が行いたい改造に対する安全性と有効性だけに集中しないとやってられません。結果として「全体像」のない、「1つの破綻が、複数の箇所に悪影響をもたらし、どれが発現するかは判らない」コードができてしまいます。

    このようなプログラムを使う場合は、「根本的な障害箇所」が判ったら、波及範囲は気にしないに限りますヽ(´o`;

    返信削除
  13. 共有ありがとうございます。これは影響大きい。

    RHELのカーネルのソースを参照すると、

    http://www.takatan.net/lxr/source/arch/x86_64/kernel/time.c?v=2.6.18-194.el5#L599

    http://www.takatan.net/lxr/ident?v=2.6.18-194.el5;i=sched_clock

    (x86_64の場合)、ここをみると、RHEL5も、該当部分がバックポートされsched_clock()の参照があるようなので、影響受けそうです。

    sched_clock()のSCALE_FACTOR そのものは、相当昔からこの場所にあったんですねぇ。2.6.11には存在していた模様。

    返信削除
  14. 共有ありがとうございます。これは影響大きい。
    RHELのカーネルのソースを参照すると、

    takatan.net: time.c in 2.6.18-194.el5
    takatan.net: sched_clock()

    (x86_64の場合)、ここをみると、RHEL5も、該当部分がバックポートされsched_clock()の参照があるようなので、影響受けそうです。
    sched_clock()のSCALE_FACTOR そのものは、相当昔からこの場所にあったんですねぇ。2.6.11には存在していた模様。
    ということで、RHELを使っている方は、distro対応では、RHEL6とRHEL5の両方を意識しないと行けないとおもいます。CentOSも同様でしょうね。

    返信削除
  15. RHEL5に問題のコード部分が sched_clock()で使うようにバックポートされているようだ、と書いたが、既報の find_busiest_group())でdiv0になる部分はバックポートされていないっぽい。
    影響あるかどうかの調査は大変だなぁ。

    返信削除
  16. HODA@都内某所

    参考までに、手元で 251 日動いている RHEL6.0 実マシンの例です。

    hoda@xxxxxx:~$ cat /etc/redhat-release
    Red Hat Enterprise Linux Server release 6.0 (Santiago)
    hoda@xxxxxx:~$ uname -a
    Linux xxxxxx 2.6.32-71.29.1.el6.x86_64 #1 SMP Thu Apr 21 16:08:55 EDT 2011 x86_64 x86_64 x86_64 GNU/Linux
    hoda@xxxxxx:~$ uptime
    11:48:36 up 251 days, 57 min, 1 user, load average: 0.00, 0.00, 0.00

    1) 仮想マシン上で動いているのでTSCを参照していない
    実マシンです。

    2) カーネルのバージョンが思っている程新しくなかった
    上の通り、2.6.32 base です。

    3) 実はリブートしていることに気がついていない
    上の通り、251 日経っています。

    ただし、

    hoda@xxxxxx:~$ grep 'model name' /proc/cpuinfo
    model name : Intel(R) Xeon(R) CPU E5506 @ 2.13GHz
    model name : Intel(R) Xeon(R) CPU E5506 @ 2.13GHz
    model name : Intel(R) Xeon(R) CPU E5506 @ 2.13GHz
    model name : Intel(R) Xeon(R) CPU E5506 @ 2.13GHz
    hoda@xxxxxx:~$ grep MHz /proc/cpuinfo
    cpu MHz : 2111.000
    cpu MHz : 1791.000
    cpu MHz : 1770.000
    cpu MHz : 1791.000

    と、クロックは落ちています。

    返信削除
  17. > クロックは落ちています。
    これですかねぇ。tscはインテルの場合CPUの駆動クロックでカウントアップするので、動作周波数が変化したらベースになる時刻を変更した上で値をリセットするはずです。

    駆動クロックが変化しない、負荷がほぼ一定なサーバーとか、ワザと変更しないように設定しているとか(応答時間保証が必要だとこうする場合がある)ですと、cycle_2_ns() が溢れるが、負荷状況が変化する環境だと無事…

    kenn さんのコメントも含めて、関係はありそうですね。

    返信削除
  18. http://rhn.redhat.com/errata/RHBA-2012-0124.html
    ようやく、Red Hat 社から修正が出たようです。

    返信削除
  19. 2.6.35系のお話です。
    kernelのコンフィグレーションで、CONFIG_PARAVIRT=y とすると、
    __cycles_2_ns() を使う native_sched_clock() ではなくて
    paravirt_sched_clock() を使うようになるため、再起動しないようです。

    返信削除