2012 年 7 月 1 日のうるう秒挿入時に発生した Linux カーネルの不具合に関する情報

last update: 2012-09-12

更新履歴

はじめに

日本時間 2012 年 7 月 1 日 9:00 にうるう秒が挿入されましたが、その際 Linux カーネルに起因する不具合により、各所で騒ぎになりました。行きがかり上、成り行きを追いかけているのですが、なかなか長期間になってきていいかげんメモを残さないと自分でも整理がつかなくなってきたので、まとめてみました。

まだ関連パッチが流れたりしているので、このページも今後何度か更新する...かもしれません。次回のうるう秒は 2015 年の予定なので、カーネルの修正もゆるゆると、という感じのようです。

基礎知識

「1秒の定義」、「TAI と UT1 と UTC の関係」、「うるう秒とは」等については、この辺りの記述がまとまっていてわかりやすいと思います。あとこことか。大事なポイントは

という感じでしょうか。

NTP についても、いろいろなサイトで解説されているので、適当に参照してください。詳細についてはこちらがとても参考になります。

くらいがわかっていればよいかと思います。

ご存知の方も多いと思いますが、メインラインの Linux カーネルに関する技術的なやり取りは、LKML (Linux Kernel Mailing List) で行われています。本事象に関連する LKML のスレッドを Google SpreadSheet にまとめました。以下で「LKML まとめシート」と記載している部分は、これのことを意味しています。また、脈絡もなく「thread#XX」とか書いてあった場合も、LKML まとめシートのスレッド番号を指していると思ってください。

2012-07-01 のうるう秒挿入で何が起きたか

おそらく最も最初の報告は LKML のこの投稿ではないかと思います。

UTC Date: 2012-07-01 00:57:24
Subject: Leap second insertion causes futex to repeatedly timeout
From: Jan Engelhardt
Date: Sun, 1 Jul 2012 02:57:24 +0200 (CEST)
marc.info
lkml.org
発生してから 1 時間以内に事象を把握してこのような報告ができる、というのはよく考えるとすごいですね。

事象としては、

となります。いずれのアプリケーションの場合も、事象発生中に strace 等でシステムコールをトレースすると、futex 関連のタイムアウトが大量に発生している点が共通した特徴のようです。特に MySQL は Web 系のサービスをやっているサイトでよく使われているのと、Java は最近 Hadoop や Cassandra 等の分散環境のミドルウェアの基盤として活躍しているので、いろいろな場所でこの問題が発生していたのではないかと思われます。

futex (Fast Userspace Mutex) とは、効率のよいロックや同期の機構をユーザー空間で実現するための Linux 特有の仕組みで、POSIX mutex のような上位ライブラリでのロック機構を実装する際の基盤として使われます。スレッドを多用するような他のアプリケーションでも、もしかしたら同様の事象が発生していたかもしれません。ただし MySQL の場合は、こちらのバグ情報を見ると、RHEL6 + MySQL v5.5 だと発生するものの、RHEL6 + MySQL v5.1 や RHEL5 + MySQL v5.5 だと発生しないそうです。スレッドの使い方や実装方法によっても発生するかどうかが変わってくるようです。

返信として、

UTC Date: 2012-07-01 08:16:13
Subject: Re: Leap second insertion causes futex to repeatedly timeout
From: john stultz
Date: Sun, 1 Jul 2012 01:16:13 -0700
marc.info
lkml.org
の中で、「date コマンドで時刻を設定し直せば直るということは、うるう秒の処理時に clock_was_set() を呼んでないのが原因かも」という意見が出ます。最終的にはこの見解はビンゴで、うるう秒処理の中で clock_was_set() 相当の処理を実行するようなパッチがこの後提案されます。このメールを書いた John Stultz という人はアメリカ人にしては珍しく (?)、自分が悪いわけでは全くないのに "Again, my apologies for the trouble." とか言っちゃったりして、この後献身的にパッチを書いて、本事象の修正パッチ作成をリードしていきます。彼は少し前に NTP 周りのコードを修正したりしていたので、自分のせいでエンバグしたと思って責任を感じてたのかもしれません。いずれにしてもこの人、この後のやり取りを見ていても、アメリカ人離れした真面目さ・性格のよさがにじみ出ていてる気がします。

どうでもいい情報ですが、この John Stultz という人は IBM に所属しており、主に Linux カーネルのコードを書いている人のようです。timekeeping サブシステムの整理とか RealTime 関連での仕事が多い印象があります。最近は linaro.org のメールアドレスで ARM 周りをいじったりもしてます。さらにどうでもいいですが、RCU の実装とか Parallel Programming Book の著者である Paul E. McKenney も最近は linaro.org な活動をしていたりと、IBM で Linux カーネルに関わっている人たちは最近なんだか ARM づいているように見えます。

さて話を戻して。このメールの後、本事象の報告が各地で増えていきます。日本語の情報はおそらく @sh2nd さんのブログエントリが一番早かったのではないかと思います。私自身は、本事象について初めて目にしたのは @sh2nd さんの tweet でした。詳細はよくわかりませんが、Mixi や LinkedIn も被害を受けたというもあります。

またこの現象は、古いカーネルだと発生しないようです。ディストリビューションで言うと、CentOS5 / RHEL5 だと発生しないけど CentOS6 / RHEL6 だと発生する。SLES だと SLES11 が発生するけど SLES10 はたぶん大丈夫。Ubuntu はここを見ると 10.04 Lucid と 12.04 Precise で発生するようです。

少し深堀りしてみる

ここまでの話は、LKML のメールを追いかけたりインターネットの情報を検索すれば出てくるのですが、ここでいくつかの疑問が生じてきます。clock_was_set() は何をする関数なのか、なぜ古いカーネルだと発生せずに新しいカーネルだと発生するのか、clock_was_set() を呼ばないことがなぜ futex のタイムアウトにつながるのか、等々。これらの疑問について、少し掘り下げてみます。

clock_was_set() 関数は何をしているか

まず、clock_was_set() 関数について。John Stultz のメールによると、「date コマンドで時刻を手動設定し直すと直る、という報告から、うるう秒処理の中で clock_was_set() が呼ばれていないと思う」とのことでした。言い換えると、date コマンドで時刻を設定すると clock_was_set() 関数が呼ばれることが予想できます。というわけで、date コマンドで時刻を設定するときに呼ばれるシステムコール settimeofday(2) を見てみます (以下参照しているソースコードは全て、この問題が発生したときの最新 upstream である v3.5-rc5 です)。

do_settimeofday() @kernel/time/timekeeping.c [mainline v3.5-rc5]
/**
 * do_settimeofday - Sets the time of day
 * @tv:		pointer to the timespec variable containing the new time
 *
 * Sets the time of day to the new time and update NTP and notify hrtimers
 */
int do_settimeofday(const struct timespec *tv)
{
	struct timespec ts_delta;
	unsigned long flags;

	if ((unsigned long)tv->tv_nsec >= NSEC_PER_SEC)
		return -EINVAL;

	write_seqlock_irqsave(&timekeeper.lock, flags);

	timekeeping_forward_now();

	ts_delta.tv_sec = tv->tv_sec - timekeeper.xtime.tv_sec;
	ts_delta.tv_nsec = tv->tv_nsec - timekeeper.xtime.tv_nsec;
	timekeeper.wall_to_monotonic =
			timespec_sub(timekeeper.wall_to_monotonic, ts_delta);

	timekeeper.xtime = *tv;
	timekeeping_update(true);

	write_sequnlock_irqrestore(&timekeeper.lock, flags);

	/* signal hrtimers about time change */
	clock_was_set();

	return 0;
}

大雑把に眺めると、timekeeper.lock を保持した状態で timekeeper を更新して、最後に clock_was_set() を実行しているのですが、もっと大雑把にコメントだけ流し読みすると、clock_was_set() は時刻が変更したことを hrtimer に通知している関数であることがわかります。ここで、hrtimer は High Resolution Timer のことで、カーネルで高精度タイマーを実現する仕組みです。タイマーというのは、「xx秒後に指定した処理を実行する」的な処理をするときに使います。

結局、date コマンドで時刻を設定すると、カーネル内の「時計」を設定して時刻を変更した後、時刻の変化に応じて「タイマー」の情報も調整しているわけです。で、これを踏まえて John Stultz のメールを読み直すと、うるう秒を挿入する際、本来なら時刻を 1 秒進めて、さらに hrtimer の情報もそれに応じて調整し直す必要があるのですが、この hrtimer の調整をしていなかった、ということになります。

なぜ古いカーネルだと発生せずに新しいカーネルだと発生するのか

この「時刻を変更する」と「hrtimer の情報を (時刻の変更に応じて) 更新する」というのは必ずセットで実施しないといけないのですが、うるう秒処理の場合になぜ後者の処理が抜け落ちていたのでしょうか。実は以前はうるう秒処理の中でちゃんと clock_was_set() を呼んでいたのに、この変更によって削除されていたのでした。commit ログを見ると、v2.6.21.5 くらいのバージョンのときにうるう秒処理で発生した問題に対応するために削除してしまったようです。この結果、v2.6.22 以降のカーネルでうるう秒処理の中で clock_was_set() を呼ばなくなっているので、同様の問題が発生することになります。

Linux ディストリビューションによっては、カーネルに独自のパッチをバックポートをしていて、ベースとなるバージョンから相当変わってる場合もありますが、おおざっぱにはこの 2.6.22 というバージョンが、発生する / しないの境界になりそうです。そういう視点で見ると、CentOS5 / RHEL5 (カーネルバージョンは 2.6.18 がベース) で発生しないのに CentOS6 / RHEL6 (カーネルバージョンは 2.6.32 がベース) だと発生するのも納得できます。

clock_was_set() を呼び忘れたことがなぜ futex のタイムアウトにつながるのか

この疑問については、John Stultz の
UTC Date: 2012-07-01 22:05:08
Subject: Re: [PATCH 0/2][RFC] Potential fix for leapsecond caused futex issue (v2)
From: John Stultz
Date: Sun, 01 Jul 2012 15:05:08 -0700
marc.info
lkml.org
というメールで説明されています。全体としては ということが発生しているのですが、特に問題になるのは、1 秒未満で発火するようにセットされたタイマーの場合です。特にループの中で、
  1. 1 秒未満で発火するようにタイマーをセット
  2. 適当な条件が成立したらループを抜ける
  3. そうでなければタイマーを再セット
的なことをするような場合、カーネル内の時計と hrtimer の base.offset が 1 秒ずれているせいで、タイマーセット ⇒ すぐタイムアウト、を延々と繰り返すことになり、結果としてそのアプリケーションで CPU 負荷が急激に上がる状態になります。このような処理は futex 関連のロック待ちや同期処理でよく使われるロジックだそうです。そんなわけで、この不具合が「特定のアプリケーションで futex のタイムアウトが頻発して CPU 使用率が高騰する」という事象として現れた、ということのようです (この辺りもしかしたら読み違えているかもしれない...)

修正が困難な理由

次の節で LKML に投稿された修正パッチをひとつひとつ見ていくのですが、「うるう秒処理のときにclock_was_set() を呼んでいなかった」という根本原因がすぐにわかったにも関わらず、意外と修正に時間がかかります。具体的なパッチの内容を説明する前に、その理由を書いてみます。

NTP による時刻更新

まず本題の前に、NTP による時刻更新がカーネル内部でどのように書かれているかについて記載します。NTP の時刻更新は、ロジックの根っこは second_overflow() @kernel/time/ntp.c にあり、update_wall_time() @kernel/time/timekeeping.c から呼ばれます (見てるソースは v3.5-rc5 なので、中井さんの本に書いてあるのとちょっと異なります)。update_wall_time() は「設定された clock source を用いて wall time を更新する」関数で、タイマー割り込みごとに下記のコールパスで呼ばれます。

  do_timer() @kernel/time/timekeeping.c
    update_wall_time() @kernel/time/timekeeping.c
      second_overflow() @kernel/time/ntp.c

clock_was_set() のヒミツ

clock_was_set() は前節で書いたように、settimeofday(2) で使われている関数で、時刻の更新を hrtimer に通知します。特徴的なのは、この関数はハードウェア割り込みのコンテキストでは呼ぶことができない点です。具体的には、clock_was_set() は

clock_was_set() @kernel/hrtimer.c
  on_each_cpu() @kernel/smp.c
    smp_call_function() @kernel/smp.c
      smp_call_function_many() @kernel/smp.c
というパスで実行されます。on_each_cpu() は引数で渡された関数 (この場合は retrigger_next_event() @kernel/hrtimer.c) を、全ての CPU 上で実行する仕組みなのですが、中で呼んでいる smp_call_function* がハードウェア割り込みコンテキストで使えないのです。

つまり、date コマンドを実行した場合は、do_settimeofday() ⇒ clock_was_set() がプリエンプティブなプロセスコンテキストから呼ばれるのでいいのですが、NTP の時刻更新の場合は、上記のとおりタイマー割り込みのコンテキストから呼ばれるので、そのままだと clock_was_set() が使えないのです。

hrtimer は per-cpu なデータなので、hrtimer の情報を更新するためには on_each_cpu() のような仕組みを使わざるを得ないのですが、そのためには「ハードウェア割り込みコンテキストでは呼べない」という特性をなんとかしないといけないわけです。そのため、clock_was_set() 相当の処理をハードウェア割り込みのコンテキストからでも安全に呼べるように、カーネルコードを修正していくことになります。

おまけ: per-cpu なデータ構造について

per-cpu とは、SMP 環境において各プロセッサのキャッシュラインを有効活用するための、Linux カーネル独自のデータ配置の方法です。 通常、複数の CPU が同じメモリ領域にアクセスすると、それぞれの CPU でキャッシュラインの無効化が頻発するため、キャッシュフィルに時間がかかってしまいスケールしにくくなる場合があります。per-cpu なデータは

とすることで、キャッシュラインを汚さずにそれぞれの CPU が自分のデータにアクセスできるようになります。per-cpu API は C のマクロで、専用のデータセクションを用意してリンカスクリプトでごにょごにょしているようですが、詳細はよくわかりませんでした...

hrtimer は頻繁にアクセスされるデータ構造なので、この仕組みを使って各 CPU 用にデータを「キャッシュ」しているわけですが、時刻を変更した場合はこの各 CPU 用に持っている hrtimer の情報をそれぞれ更新する必要があるのです。

おまけ: update_wall_time(), hrtimer_interrupt(), hrtimer_init 辺りの呼び出しの流れ

blockdiag を使ってブロック図にしてみました。Google Chrome だとうまく表示されないかも... 手元の Mac OS X 10.8.1 の場合、Safari v6.0、Firefox v15.0 だと大丈夫で、Chrome v21.0.1180.82 だとフォントがうまくおさまりませんでした。 (ブロック図の svg ファイル)

LKML 関連スレッド流し読み

LKML に投稿された修正パッチ、それにまつわる議論やバグ報告などを見ていきます。

1. 修正案 v1 - v4

7/1 中に、John Stultz から修正パッチ案 (RFC patch) が提案されます。1 つ目はこれです (LKML まとめシートの thread#3)。

UTC Date: 2012-07-01 09:36:11
Subject: [PATCH] [RFC] Potential fix for leapsecond caused futex related load spikes
From: John Stultz
Date: Sun,  1 Jul 2012 05:36:11 -0400
marc.info
lkml.org

再現プログラム (うるう秒をわざと発生させる) もちゃんと含まれているのが素敵です。

このパッチでは update_wall_time() の中で、timekeeper.lock を保持した状態で clock_was_set() を呼ぶようにしたのですが、これだと ハードウェア割り込みコンテキストから呼ばれた場合にアウトなので不十分です。そのため、すぐに不具合報告が来ます。

John はこのメールの中で "It had been a long day before I heard about this issue, so my brain is a little mushy right now. Reviews and extra testing would be greatly appreciated." (意訳: 「ほんと長い一日で、ぼくの脳みそは疲れてとろけちゃったよ」) とか書いています。現地時間で朝 5:00、多分ノンストップで解析してパッチを書いてたんじゃないかと想像します。

2 つ目のパッチがこちらです (LKML まとめシートの thread#4)。

UTC Date: 2012-07-01 18:29:59
Subject: [PATCH 0/2][RFC] Potential fix for leapsecond caused futex issue (v2)
From: John Stultz
Date: Sun,  1 Jul 2012 14:29:59 -0400
marc.info
lkml.org
update_wall_time() から clock_was_set() を呼び出せるように修正しています。 内容としては、clock_was_set() の中で、in_atomic() を使って割り込みコンテキストかどうかを判断し、割り込みコンテキストで呼ばれている場合は、ワークキューとして遅延処理の中で hrtimer のアップデート処理を実施するようになっています。 この修正方法には、Thomas Gleixner (タイマーサブシステムのメンテナ) から「on_each_cpu() はソフトウェア割り込みのコンテキストからは呼び出せるので、ワークキューよりも timer_list のタイマーにセットした方がいいんじゃない?ワークキューの遅延処理は実行開始が遅くなることがあるし」との指摘が入ります。timer_list は tick ベースの古典的なタイマー処理の仕組みです。

また、Prarit Bhargava という人が精力的に実機テストでパッチの検証を行ってくれます。Red Hat Bugzilla を見ると、RHEL6 カーネル用のパッチはこの人が作成したようです (BZ#836803)。

この後、さらに 2 回の提案を経て、パッチ案がだいたい収束します。ひとつ目はこちら (LKML まとめシートの thread#5)。

UTC Date: 2012-07-03 02:16:03
Subject: [PATCH 0/3][RFC] Potential fix for leapsecond caused futex issue (v3)
From: John Stultz
Date: Mon,  2 Jul 2012 22:16:03 -0400
marc.info
lkml.org

このパッチの変更点としては下記になります。

hrtimer は頻繁にアクセスされるため、per-cpu なデータとして持っているのですが、これらを矛盾なく更新するためにいろいろ工夫しているようです。

しかし、timer_list の初期化方法に問題があって softlockup が発生するため、それを修正して次のパッチ (LKML まとめシートの thread#6) が提案されます。

UTC Date: 2012-07-04 06:21:27
Subject: [PATCH 0/3][RFC] Fix for leapsecond caused futex issue (v4)
From: John Stultz
Date: Wed,  4 Jul 2012 02:21:27 -0400
marc.info
lkml.org

2. メインライン向けパッチ

次のメールによって、RFC patch v4 ほぼそのままの形で mainline へのパッチが提出されます (LKML まとめシートの thread#7)。

UTC Date: 2012-07-05 19:12:15
Subject: [PATCH 0/3] Fix for leapsecond caused hrtimer/futex issue
From: John Stultz
Date: Thu,  5 Jul 2012 15:12:15 -0400
marc.info
lkml.org

その後、Thomas Gleixner がレビュー・修正した内容を含んだアップデートも投稿されます (LKML まとめシートの thread#9)。John と Thomas とのやり取りは LKML では見えないので、おそらく個人宛メールや IRC 等でやり取りがあったのではないかと思います。

UTC Date: 2012-07-10 22:43:18
Subject: [PATCH 0/6] Fix for leapsecond caused hrtimer/futex issue (updated)
From: John Stultz
Date: Tue, 10 Jul 2012 18:43:18 -0400
marc.info
lkml.org
修正内容としては、前と比べて遅延処理の投げ方が変わって (timer_list を使わずに __raise_softirq_irqoff で softirq を上げるようになった)、あと割り込みコンテキストの中で行う hrtimer の処理がなるべく軽くなるように変更されているようです (ちょっと自信なし) 。各パッチの内容は次のようになります。
[PATCH 1/6] hrtimer: Provide clock_was_set_delayed()
  • hrtimer_cpu_base 構造体に、どの CPU が softirq を上げたかを示すフラグを追加
  • clock_was_delayed() 関数を新設、上記フラグをセットして softirq を上げる
[PATCH 2/6] timekeeping: Fix leapsecond triggered load spike issue うるう秒挿入時に clock_was_set_delayed() を呼び出す
[PATCH 3/6] timekeeping: Maintain ktime_t based offsets for hrtimers hrtimer の割り込みコンテキストでの処理を軽くしたいので、timespec ⇔ ktime_t の変換を割り込みコンテキスト内でしなくてもいいように、timekeeper 内で ktime_t でオフセットを保持する
[PATCH 4/6] hrtimers: Move lock held region in hrtimer_interrupt() hrtimer_interrupt 内で、cpu_base->lock を保持するクリティカルセクションを修正。ロックを取ってから ktimer_get() 呼び出す
[PATCH 5/6] timekeeping: Provide hrtimer update function ktime_get_update_offsets() 関数を新設。monotonic time と CLOCK_REALTIME、CLOCK_BOOTTIME のオフセットをアトミックに、かつ最小のオーバーヘッドで取得する
[PATCH 6/6] hrtimer: Update hrtimer base offsets each hrtimer_interrupt ktime_get() を ktime_get_update_offsets() で置き換える

再現プログラムにも少しバグがあったようでアップデートされました。

この辺りから、timekeeping サブシステムとか hrtimer 割り込みハンドラとかにも手が入って、パッチがなかなか大掛かりになってきています。v3.5 に向けてすでに 3.5-rc6 まで来ているので、-rc に入れるには大掛かりすぎるかも、という議論も出ています。また PATCH 1/6 の実装が汚すぎて嫌だとか、別の方法でも同じくらい汚くしか書けないとか、それほど頻繁に発生するわけではないうるう秒処理なんだからシンプルで堅牢な方法にしたいね等の意見が出ました。

最終的に、下記スレッドで PATCH 1/6、PATCH 2/6 のみ linus tree に対して pull request が出されました (実際にはリンク先のメールの commit は間違いで、正確にはその返信に載っている commit が該当します)。

UTC Date: 2012-07-13 21:09:24
Subject: [GIT pull] leap second fixes for 3.5
From: John Stultz
Date: Fri, 13 Jul 2012 23:09:24 +0200 (CEST)
marc.info
lkml.org

3. v3.6 向けクリーンナップ

下記メールから始まる一連のスレッドは、(v3.5 はもうすぐ出るのでその次の) v3.6 に向けての時刻関連サブシステムのクリーンナップです (LKML まとめシートの thread#10)。本事象のこれまでの議論とはあまり関係なさそうな変更も結構含まれているので、もっと以前のやり取りも含んでいるのかもしれません。

UTC Date: 2012-07-13 05:21:49
Subject: [PATCH 0/8] Time fixes and cleanups for 3.6
From: John Stultz
Date: Fri, 13 Jul 2012 01:21:49 -0400
marc.info
lkml.org

4. バグ報告: suspend からの復帰失敗

suspend から復帰できないというバグレポートがいくつか上がってきます (LKML まとめシートの thread#13、#14、#15、#25)。

UTC Date: 2012-07-15 20:40:49
Subject: [Regression][Revert request] Excessive delay or hang during resume from system suspend due to a hrtimer commit
From: Rafael J. Wysocki
Date: Sun, 15 Jul 2012 22:40:49 +0200
marc.info
lkml.org
UTC Date: 2012-07-15 19:28:41
Subject: 3.5-rcX: wakeup after s2ram doesn't work after a longer sleep time
From: Toralf Förster
Date: Sun, 15 Jul 2012 21:28:41 +0200
marc.info
lkml.org
UTC Date: 2012-07-16 13:27:05
Subject: regression 918227bb -> -rc7: does not wake up from sleep
From: Norbert Preining
Date: Mon, 16 Jul 2012 22:27:05 +0900
marc.info
lkml.org
UTC Date: 2012-07-19 04:46:29
Subject: 3.5-rc7 - can no longer wake up from suspend to RAM
From: Tomasz Chmielewski
Date: Thu, 19 Jul 2012 11:46:29 +0700
marc.info
lkml.org

それに対するパッチがこちらになります (LKML まとめシートの thread#16)。前から潜在していたものの、今回のクリーンナップまで現象が発生しなかったバグのようです。

UTC Date: 2012-07-16 16:50:42
Subject: [PATCH] timekeeping: Add missing update call in timekeeping_resume()
From: John Stultz
Date: Mon, 16 Jul 2012 12:50:42 -0400
marc.info
lkml.org

5. stable ブランチに対するバックポートパッチ

その後、各 stable ブランチに対して同様の修正が連投されます。

どうでもいいですが、stable ブランチってこんなにたくさんあったんですね。

6. v3.6 向けにさらにパッチ

v3.6 に向けての新たなパッチです (LKML まとめシートの thread#24)。PATCH 1/2 は別スレッドで提案されたマクロ定数名に関するもの。PATCH 2/2 は先の resume 失敗報告に関連して、同じような間違いが起きないようにするための修正です。2 ヶ所で保持している ktime_t の値を、一貫して更新できるような関数を新設して、これを使うと常に整合性を保てるようになります。

UTC Date: 2012-07-19 01:19:11
Subject: [PATCH 0/2] Additional time changes for 3.6
From: John Stultz
Date: Wed, 18 Jul 2012 21:19:11 -0400
marc.info
lkml.org

この後 v3.0.38、v3.4.6、v3.5 がそれぞれリリースされます。いずれも thread#9 の最初の 2 つのパッチを取り込んでいます。

7. バグ報告: 32 ビット Xen ゲストが起動時にパニック

32 ビット Xen ゲストで起動時にパニックするバグの報告 (LKML まとめシートの thread#29)

UTC Date: 2012-07-23 14:49:17
Subject: Was: Re: [GIT PULL] timer changes for v3.6, Is: Regression introduced by 1e75fa8be9fb61e1af46b5b3b176347a4c958ca1
From: Konrad Rzeszutek Wilk
Date: Mon, 23 Jul 2012 10:49:17 -0400
marc.info
lkml.org

その修正 (LKML まとめシートの thread#30)

UTC Date: 2012-07-23 20:22:37
Subject: [PATCH] time: Fix casting issue in tk_set_xtime and tk_xtime_add
From: John Stultz
Date: Mon, 23 Jul 2012 16:22:37 -0400
marc.info
lkml.org

8. バグ報告: 腐った CMOS で起動時にカーネルパニック

起動時にカーネルパニックするバグの報告 (LKML まとめシートの thread#34)。CMOS 設定で西暦が 8400 年に設定されていたために発生したとか、何だそりゃ...て感じですが。

UTC Date: 2012-07-30 03:51:56
Subject: boot panic regression introduced in 3.5-rc7
From: CAI Qian
Date: Sun, 29 Jul 2012 23:51:56 -0400 (EDT)
marc.info
lkml.org

その修正案 (LKML まとめシートの thread#35)。ktime_get_update_offsets() のセマンティックスを ktime_get() に合わせるのと、アホみたいに大きな西暦を設定しようとしたときのチェック追加の 2 点。

UTC Date: 2012-07-31 06:35:46
Subject: [PATCH 0/2][RFC] Better handling of insane CMOS values
From: John Stultz
Date: Tue, 31 Jul 2012 02:35:46 -0400
marc.info
lkml.org

ひとつ目のパッチは「そこまで頑張らなくても」という意見が出て、結局範囲チェックのみの修正となる (LKML まとめシートの thread#36)。

UTC Date: 2012-08-01 23:21:16
Subject: [PATCH] time: Limit time values that would overflow ktime_t
From: John Stultz
Date: Wed,  1 Aug 2012 19:21:16 -0400
marc.info
lkml.org

後日パッチはアップデートされます。 (LKML まとめシートの thread#42)

UTC Date: 2012-08-08 19:36:20
Subject: [PATCH] time: Improve sanity checking of timekeeping inputs
From: John Stultz
Date: Wed,  8 Aug 2012 15:36:20 -0400
marc.info
lkml.org

9. バグ報告: 時計が速く進みすぎる

別のバグ報告 (LKML まとめシートの thread#40)。時計が速く進みすぎて hangcheck timer が混乱する。報告した人が自分で bisect して問題となる commit を特定してしまうのがすごいですね。

UTC Date: 2012-08-03 14:18:02
Subject: [3.6-rc1] sched: clock counts too quickly
From: Tetsuo Handa
Date: Fri, 3 Aug 2012 23:18:02 +0900
marc.info
lkml.org

条件分岐の単純ミスのようです。

UTC Date: 2012-08-04 19:21:14
Subject: [PATCH] time: Fix adjustment cleanup bug in timekeeping_adjust()
From: Ingo Molnar
Date: Sat, 4 Aug 2012 21:21:14 +0200
marc.info
lkml.org

10. バグ報告: キャスト忘れ

別のバグ報告 + 修正パッチ (LKML まとめシートの thread#44)。キャスト関連。

UTC Date: 2012-08-19 20:09:01
Subject: [PATCH] time: Fix casting issue in timekeeping_forward_now
From: Andreas Schwab
Date: Sun, 19 Aug 2012 22:09:01 +0200
marc.info
lkml.org

thread#34、#44 のパッチの linux-tip への取り込み依頼 (LKML まとめシートの thread#47)。

UTC Date: 2012-08-22 00:30:45
Subject: [PATCH 0/4] Time fixes for 3.6
From: John Stultz
Date: Tue, 21 Aug 2012 20:30:45 -0400
marc.info
lkml.org

11. バグ報告: X.org がクラッシュする不具合

X.org が自爆する、という新たなバグ報告です (LKML まとめシートの thread#50)。

UTC Date: 2012-08-31 04:05:00
Subject: [REGRESSION] Xorg doesn't like 4e8b14526 "time: Improve sanity checking of timekeeping inputs"
From: Andreas Bombe
Date: Fri, 31 Aug 2012 06:05:00 +0200
marc.info
lkml.org

報告者の bisect により、前に報告された問題に対する修正の commit に起因していることまでは判明ずみ。ここで Linus Torvalds が降臨して、どの条件分岐で死んでいるのかを判別する方法を伝授し、それもすぐに判明します。ほぼ同時に John Stultz もパッチを作成し、それで問題が発生しなくなることも確認されました。

内容としては、X が "crazy-long" な時間をタイムアウト値として select(2) に渡しており、それを thread#42 で入れた「ktime_t のオーバーフローをチェックする仕組み」がはじいてしまったのが原因です。今までどおり「とてつもなく大きい値」は「ほぼ無限大 (KTIME_MAX)」とみなして処理を続けるように修正されました (正確には crazy-long な値が来た場合にはじく関数とはじかずに KTIME_MAX とみなす関数の 2 本だてになっています)。

Linus 曰く、「そもそも X もおかしいやろ、crazy-long な値を渡さなくてもいいし、監視する fd も 256 って多すぎるし」とのことです。

12. CONFIG_NO_HZ + CONFIG_CPU_IDLE のカーネルが数秒固まる場合がある

ThinkPad T61p が数秒固まる、という不具合報告です (LKML まとめシートの thread#52)。

UTC Date: 2012-09-06 09:22:32
Subject: CONFIG_NO_HZ + CONFIG_CPU_IDLE freeze the system (Was Re: [PATCH] acpi : remove power from acpi_processor_cx structure)
From: Daniel Lezcano
Date: Thu, 06 Sep 2012 11:22:32 +0200
marc.info
lkml.org

もともと全然関係ない ACPI 周りのスレッドで、「このパッチ入ってないよ」「ごめん入れとくよ、他に入れ忘れたパッチある?」「あるんだけどなんだか起動後にハングするので、今 bisect 中...」というやり取りがあって、そこからつながってきたメールスレッドになります。

症状としては、起動後しばらく放っておくと、コンソール入力してもエコーバックに数秒かかるようになる、発生しているときは ping にも反応しないけど、ping を打ち続けていると発生しない、というものです。 結局、timekeeping_get_ns() が返す 64 ビットの値を long の timespec.tv_nsec にそのまま保存していた (場合がある) のが問題で、32 ビットカーネルの場合、数秒でこの nsec がオーバーフローする ⇒ タイマーが発火しない、という問題だったようです。John Stultz によって次のメールでパッチが提出されました (LKML まとめシートの thread#58)。
UTC Date: 2012-09-11 23:26:03
Subject: [PATCH] time: Fix timeekeping_get_ns overflow on 32bit systems
From: John Stultz
Date: John Stultz 
marc.info
lkml.org

13. soft lockup が発生

たまに soft lockup の警告が出る、という報告です (LKML まとめシートの thread#53)。

UTC Date: 2012-09-09 07:59:27
Subject: BUG: soft lockup - CPU#1 stuck for 1024s!
From: Fengguang Wu
Date: Sun, 9 Sep 2012 15:59:27 +0800
marc.info
lkml.org
John Stultz が「3.6-rc2 で直ってる問題かも」と指摘し、報告者によって -rc5 で発生しないことが確認されました。

14. その後の修正の stable ブランチに対するバックポート

3.6 に施された修正の各 stable ブランチへのバックポートです (LKML まとめシートの thread#54 〜 #57)。

というわけで、だいぶ収束してきてはいますが、2012-09-12 現在、ちょろちょろとまだ関連する不具合が報告されたり、パッチが流れたりしている状態が続いています。

ディストリビューションの対応状況

軽く検索して見つかった範囲でまとめました。普段使わないディストリビューションだと、なかなか情報を探すのもうまくいかないものですね。もしもっとよいドキュメントが用意されているなら教えてください。

Red Hat Enterprise Linux

KB (KnowledgeBase) の内容は、Red Hat Network のアカウントがないと、文書の一部しか見れないかもしれません。
(KB15145) Leap Seconds in Red Hat Enterprise Linux
RHEL4、RHEL5 での既知の障害についての情報です。
(KB154713) Systems hang due to leap-second livelock.
RHEL6 では、本 Web ページで書いてきた障害以外にも、この KB に載っている不具合 (カーネルのハングアップ) があるそうです。
Bug 836748 - livelock in leapsecond insertion
KB154713 の bugzilla です。"reverting back to not using an hrtimer to inject leapseconds" と言っているので、中井さんの「プロのための Linuxシステム・10年効く技術 (Software Design plus)」で解説されていた hrtimer によるうるう秒挿入処理はなくなっちゃうかもしれないですね。kernel-2.6.32-294.el6 で修正が取り込まれたようです。というかパッチが 66 個って...
(KB154793) Why is there high CPU usage after inserting the leap second?
本 Web ページで記述した障害に関する KB です。
Bug 836803 - RHEL6: Potential fix for leapsecond caused futex related load spikes
KB154793 の bugzilla です。最終的に、LKML まとめシートの thread#9 に相当する修正が入ったように見えます。kernel-2.6.32-294.el6 に取り込まれたとのことです。
(KB173693) Leap Second Addition, and its Effects Explained
RHEL6 のうるう秒関連情報のサマリです。
RHBA-2012:1199-1 として、上記 2 つの KB/Bugzilla に載っている不具合が修正された RHEL6 用 errata kernel 2.6.32-279.5.2.el6 が先日リリースされました。RPM パッケージの Change Log はこちらです (RHN にログインする必要があります)。

SUSE Linux Enterprise Server

(KB7001865) Leap second handling in SUSE Linux products
SLES9 以降のうるう秒関連情報のサマリです。
(KB7010351) Leap second issues - June 30, 2012
SLES11 で発生するうるう秒関連の障害についての情報です。本ページで記述した CPU 使用率高騰の他に、デッドロック問題が 2 件ある、と記載されています。それぞれについてワークアラウンドが載っています。

本 KB は 8 月末に更新されており、 で修正されているようです。

Ubuntu

Addition of leap second causes spuriously high CPU usage and futex lockups
Ubuntu の障害情報です。

Debian GNU/Linux

Debian Bug report logs - #679882 linux: leap second fixes missing in 3.2 and 2.6.32 longterm
Debian の障害情報です。

役に立ちそうな情報

この辺りのサイトは見ておくと理解の助けになるかと思います。
System x における「うるう秒」の調整と対応について
Linux でうるう秒に対応する方法がまとまっています。
【Technical Notes】Linux システムクロックの『うるう秒』調整
Linux で NTP を使用する際の細かい動きがまとまっています。
【RHEL】這いよる閏秒 7月1日9:00(JST)の挙動(3年ぶりだな)
今回のうるう秒の検証を実際に RHEL5 で実施されています。
NTP設定 - とあるSIerの憂鬱
ntpd の動きについてとても参考になりました。

関連キーワード

あとでちゃんと書く、かも

雑感

今回の事象は、事前に防げなかったのでしょうか。うるう秒が正しく処理されるかについては、各ベンダーさんや、SI プロジェクトチーム、サービス事業社さん等でも、事前に調査された方もたくさんいらっしゃったと思います。これまで何度かあったうるう秒挿入で、検証方法等もだいぶ確立されていたのではないでしょうか。なのになぜ、今回の事象は事前に発見できなかったのでしょうか。

個人的には、今回の障害は、事前に発見することは困難だったのではないかと思っています。通常、うるう秒の検証は、Leap Indicator を擬似的に発生させたり日付を手動でうるう秒挿入直前に変更して、正しくうるう秒が挿入されることを確認して終わることが多いでしょう。しかし今回の事象は、うるう秒が挿入された上で、*特定の* アプリケーションを実行していないと発覚しないものでした。また事象の種類としても、「アプリケーションがコアダンプする」「カーネルがハングアップする」等のわかりやすいタイプではなく、CPU 使用率が高騰する、というものだったので、ある程度時間をかけて継続的にモニターしないと発見できなかったでしょう。もちろん理想的には、時刻修正の確認だけでなく、アプリケーション含め統合テストをやり直していれば発見できたかもしれません。しかし、あらゆるプロジェクトでうるう秒確認のために統合テストをやり直すのは、現実的には不可能でしょう。

理想的には、Linux カーネルのコードを開発する際に、変更した部分は単体テストして、問題ないことを確認しておくべきなのでしょう。ハードウェアに近い場所で動くソフトウェアの場合は特に、全てのパスを網羅できるようなテストケースを用意するのは困難な面もありますが、これはひとつひとつ地道に増やしていくしかないのかもしれません。幸い今回の障害に関しては、再現させるための負荷プログラムも用意されていますし、Red Hat も「テストケースを LTP (Linux Test Project) に突っ込む」と言っている (KB173693 参照) ので、同じ問題は今後は発生しないだろうと期待できます。

余談ですが、「仮想マシンをたくさん作って、それぞれで make randconfig で作った適当なカーネルで起動させる」というテストをしている人がいて、なかなか面白いテストだな、と思いました (LKML まとめシートの thread#46)。

Linux カーネルのように更新頻度の高いソフトウェアの場合、「前回のうるう秒では大丈夫だったから」という言い訳も通用しないのがつらいところです。特に今回のうるう秒は前回から 3 年半も空いていますし、実際 RHEL5 だと問題なかったのが RHEL6 だと問題が発生しています。時刻 / タイマー周りのコードが変化し続ける限り、うるう秒のたびにきっちり検証を続けていくしかなさそうです。

ところで NTP で時刻を合わせる際、STEP モードと SLEW モードという 2 つのモードがあります。STEP モードは一気に時刻をずらすためにすぐに時刻が正しくなりますが、アプリケーションから見て時間の逆行が発生する可能性があります。一方 SLEW モードの場合は、徐々にずらしていくことで時間の逆行を可能な限り発生しないようにするものの、時刻の同期に時間がかかります。今回の現象は、「ずらした時間より短い間隔で発火するタイマー」が CPU 使用率高騰のトリガーになっていました。これは STEP モードでの時刻同期が前提になっています。もし SLEW モードで同期していれば、ずらされる時間は最大でも 0.5 ミリ秒となるため、同じ現象が発生する確率はだいぶ小さくなったかもしれません。STEP モードと SLEW モードのどちらがいいかはケースバイケースなので、無条件に SLEW モードを勧めるつもりは全くないのですが、あくまで「たられば」の妄想としてメモしておきます。

@odhrfm さんに教えていただきましたが、最近の ntpd では、SLEW モードにすると Leap Indicator のうるう秒挿入ビットをセットしないようです。RHEL6.3 同梱の ntp-4.2.4p8-2.el6 を見ると、確かに SLEW モードの場合は変数 kern_enable が 0 になっており、kernel time discipline ではなく NTP daemon discipline で動くように見えます。したがって、SLEW モードに設定していた場合、そもそもこのような問題は発生しなかった、ということになります。

最後に

間違いの指摘やご意見などありましたら下記までご連絡いただけると助かります。