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 した…なんて事、その場に立ち会ったら心臓がショックで止まりかねないだろう…。

2011年12月11日

lunar eclipse

On year 2011, Dec. 10th around 21:30 - 00:00, we had Lunar Eclipse here at Japan.

Here's some of the photos I took.

Camera: RICOH CX1
Mode: ... ah .. I kept on changing it in the dark. So I'm not sure.
























And .. Battery run out ..... gosh ...

2011年11月24日

ホームゲート

都営大江戸線の青山一丁目駅。

ホームゲートが設置されているのに、まだ稼動していない。
ゲートは全開でその先にレールが見えている。

実運用が始まるとこんな光景はもう見られない。珍しいので撮影。

2011年9月23日

< 2.6.17 な Linux に存在する flock の double free バグ

Linux Kernel 2.6.17(正しくは 2.6.16.x で入ったのかもしれないが…) で新しく入った修正の一つに、flock(2) システムコール起因でカーネルがメモリをダブルバインドする、というものがある。

これを修正するパッチ自体は、2つ。
http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=993dfa8776308dcfd311cf77a3bbed4aa11e9868
http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=9cedc194a7735e5d74ad26d3825247dc65a4d98e
最初のパッチが問題の本質を直して、2つ目のパッチはその修正の際に、異常系処理が甘くてエラーが還らなくなっていたのを直した、というものだ。

あぁ、あれね、と判っている人はこのバグが高負荷時に結構酷い確率で頻発することも知っているでしょう。
RHEL4U4でもまだ直っていないので、是非 RedHat にギャーギャー言ってください。
*1

当然、ここでは「で? それはどういうバグなの?」という質問してくれる、ヨイ子のみんなのためにある。つーてもいきなり答はタイトルに書いてありますが。


*1) morikawaさん、情報ありがとうございます _o_。
つーかこれは修正し忘れですね。大昔、これを書き始めた時の情報を更新し忘れてました。



なぜコレをここに書くのかと言うと、理由は2つ。

1つ目は Linux Kernel の内部構造が double free に弱い(コレ自体はしょうがない)ため、類似のバグがあると、このバグを踏んだかなり後になってから いきなり kernel がぶっ倒れる、という事が多々あるからだ。この症状から真の原因を直接求めるのははっきり言って不可能に近い。が、なぜ不可能なのかをよく判っていない人に説明するのもかなり困難だ。なのでここに書いておけば、再びそういう目にあったときもここを見れば判る。

2つ目は、このバグがタイミング依存性の高い、かなりいやらしい構造をしたバグだから、だ。同期系のプログラムはかなり丁寧に動作を追わないと、いつ足元を掬われるか判らない。そのためには、いろいろな「実在したバグのケース」を記録しておくのが一番だ。というか、ややこしすぎて厳密に覚えていないと意味がないのに、すぐ忘れるからここに書くわけ。


とりあえず、パッチは上記にあるが、ソースコードはこんな感じだ。

2.6.16: http://lxr.linux.no/linux+v2.6.16/fs/locks.c の flock_lock_file()
2.6.17: http://lxr.linux.no/linux+v2.6.17/fs/locks.c の flock_lock_file()

で、この flock_lock_file() を呼び出しているのは sys_flock() 関数… flock() システムコールの入り口だ:
2.6.16: http://lxr.linux.no/linux+v2.6.16/fs/locks.c#L1495
2.6.17: http://lxr.linux.no/linux+v2.6.17/fs/locks.c#L1535

sys_flock() の中で flock_lock_file_wait() という関数が呼ばれている:
     http://lxr.linux.no/linux+v2.6.17/fs/locks.c#L1569

flock_lock_file_wait() はここだ:
     http://lxr.linux.no/linux+v2.6.17/fs/locks.c#L1496
で、flock_lock_file_wait() の中のここで flock_lock_file() が呼ばれている:
     http://lxr.linux.no/linux+v2.6.17/fs/locks.c#L1501

これが、全体の流れだ。

で、メインの処理は flock_lock_file() が受け持っている。

まず、flock_lock_file() の中で kernel 全体を lock している。つーてもシングルプロセッサの場合は何もしていなくて、SMPの場合だけ、lock が必要な場所で lock をかけている。これが lock_kernel() と unlock_kernel()。もし、kernel_lock がすでに取られていたら、SMPの場合はこのロックが解除されるのを待つことになる。

先に 2.6.17 …つまりバグが修正された後のコードを見て欲しい。lock_kernel() が呼ばれているのはここだ:
        http://lxr.linux.no/linux+v2.6.17/fs/locks.c#L739
一方、unlock_kernel() が呼ばれているのはここ:
        http://lxr.linux.no/linux+v2.6.17/fs/locks.c#L788

ようするに入り口の所すぐで kernel_lock を取得し、この関数から出ていくまで一度も解放しない。これが正しいやり方だ。この間のどこかで kernel_lock を解放してしまうと、仮にそのあとすぐ kernel_lock を再取得したとしても、その間に別CPUが処理に入り込んでくる危険性がある。

で、一方で 2.6.16 は
2.6.17と同様、関数の入り口でkernel_lock を取得している。
         http://lxr.linux.no/linux+v2.6.16/fs/locks.c#L722
で、関数の出口で kernel_lock を解放している:
         http://lxr.linux.no/linux+v2.6.16/fs/locks.c#L768

が、その途中で一度 kernel_lock を解放し:
        http://lxr.linux.no/linux+v2.6.16/fs/locks.c#L737
再度取得し直している。
        http://lxr.linux.no/linux+v2.6.16/fs/locks.c#L749

問題は、この L737 出の開放の後、L749 での再ロックまでの間に、別のCPUが flock_lock_file() 関数に入ってくる危険性がある、ということだ。最初の git パッチ にはこうある:

sys_flock() currently has a race which can result in a double free in the
multi-thread case.

Thread 1 Thread 2

sys_flock(file, LOCK_EX)
sys_flock(file, LOCK_UN)

If Thread 2 removes the lock from inode->i_lock before Thread 1 tests for
list_empty(&lock->fl_link) at the end of sys_flock, then both threads will
end up calling locks_free_lock for the same lock.
ちょっと見辛いし判りづらいな:
SMP環境において

Thread1: sys_flock(file, LOCK_EX)
Thread2: sys_flock(file, LOCK_UN)

がほぼ同時に呼ばれたとする。ただし、最初に kernel_lock を取得したのは Thread1 の方だ。で、Thread1 が最初の unlock_kernel() を呼んだ。

この瞬間に Thread2 は kernel_lock を取得できる。で、ここ:
        http://lxr.linux.no/linux+v2.6.16/fs/locks.c#L734
この場所で、inode->i_lock を解放する。
で、ここを通り抜けた後、Thread2 が unlock_kernel() を呼ぶと、Thread1 が flock_lock_file() の後半部を通り抜け、flock_lock_file_wait() へと戻り、そこから sys_flock() へと帰る。

問題は、Thread1 が sys_flock() へと帰った後。ここ:
http://lxr.linux.no/linux+v2.6.16/fs/locks.c#L1532
で、lock_free_lock() を呼んでしまうことだ。結果として、同じロックを2重解放してしまう。

lock_free_lock() のコードはここだ:
2.6.16:    http://lxr.linux.no/linux+v2.6.16/fs/locks.c#L157
2.6.17:    http://lxr.linux.no/linux+v2.6.17/fs/locks.c#L169

ここで問題なのはただ1点、kmem_cache_free() を呼び出すところだ。これを同じ構造体に対して行なってしまう。結果として、2重解放が行われる。



二重解放されたメモリは、やがて再利用される。二箇所の、全然関係ない所で。
それぞれを利用している kernel thread や、ルーチンはまさか他の人も同じ部分を利用している人がいるなんて考えてコーディングされていない。というか、それを疑ったら何もできなくなっちゃう。

で、ある日。自分が昔設定した値に従って処理を実行しようとしたのに、実はその値は別の人が別の目的で書いた値で…結果としてそのせいで、kernel 全体がクラッシュする、という状態に陥るのです。

2011年9月16日

Brave to stay

This brave Mantis has been on "outside" of the window of 29th Floor elevator hall since noon.
I shoot this photo on my way back to home, 17:48, and (s)he was still there!

Hanging upside down on the glass must be tremendously tough job. And since (s)he have a wing to fly, it's not hard for h(im|er) to give up and fly a little bit aside for better environment. What a brave.

...

Well ... it might simply be that this insect was stupid as to stay though ... staying on tough situation for nothing ...

2011年6月11日

リサイクルループに着目しよう

節電が叫ばれている。一般家庭も企業も15%ぐらいは節電して欲しいそうだ。

で、老人が「ペカペカ光るもの」は「電気を食うに違いない」とボケを垂れ流している。が、正直、それではたいして節電にならない。本当に電気を食うものってそんな所にはないからだ。

というか、「ペカペカと光る」とか「キンキンに冷える」とか、そういう擬音付きキーワードな代物は、別に昨日今日目の敵にされたわけじゃない。なのでアチラコチラに工夫がしてあって、実はかなり電力を食わないようになっているのだ。だからそんな所を今更攻めたって、たいして節電になどならぬ。

じゃぁ、どこにエネルギーは消費されているか?
エコロジーだともてはやされたもの。CO2削減にはこれ、ともてはやされたものにこそエネルギー消費は隠れている。
というわけでリサイクルを槍玉にあげてみよう。

リサイクルって言うのは「モノ」の形状を変えて、同じ物体をなんども変形させながら使い回しする、っていうのが基本発想だ。ペットボトルを粉砕して溶かしてもう一度ペットボトルにするとか。紙をパルプに戻して漂白してまた紙にするとか。「モノ」を無駄に破棄しない、と言う意味では素晴らしい。

でもちょっとまってくれ。そもそも、その「モノ」は何のために消費されているのだ? 我々は「ペットボトルを買いたい」わけじゃない。我々は「紙が欲しい」わけじゃない。
ペットボトルなら、その中にあるジュースが欲しいのだ。紙が欲しいのではなく、紙に印刷されている情報が欲しいのだったり、紙に包まれている中身が欲しかったりするのだ。まさに輸送のためのケースがペットボトルであり、紙なわけだ。だからこそリサイクル出来るぐらい損傷少なくペットボトルや紙を回収できる。

しかし、リサイクル・ループはエネルギー的に見れば決してただじゃない。輸送にはガソリンが、加工には電気が使われているはずだ。

じゃぁ、ペットボトルを使わない、紙を使わないで目的を達することは出来ないだろうか?
非炭酸系の飲み物をペットボトルから紙容器に切り替えるとか。
新聞を紙から電子版に変えるとか。

本来の目的からすれば別に欲しいわけじゃないモノを使わないようにする事で、リサイクル・ループを流れるモノの絶対量を減らす。しかも「本来の目的」は別にセーブしなくてよい事になる。


今回の節電は、目先の電力消費量を変えるのではなく、リサイクル・ループを流れる物流を減らしつつ、無駄にモノを廃棄しない、という形を取らないと苦しいと思う。目先のペカペカしたものを排除するような発想では、長期的に見ると必要なエネルギーが減らないままだ。