Translated message

A translation of this page exists in English.

起動時に "schedule_timeout" エラーと udevd プロセスのバックトレースがコンソールに表示される

Solution Unverified - Updated -

Environment

  • Red Hat Enterprise Linux (RHEL) 6

Issue

  • schedule_timeout の udevd プロセスのカーネルバックトレースが、ログに複数回表示されます。
  May 17 20:12:56 example kernel: schedule_timeout: wrong timeout value ffffffffffffe9e0
  May 17 20:12:56 example kernel:Pid:3560, comm: udevd Not tainted 2.6.32-220.13.1.el6.x86_64 #1
  May 17 20:12:56 example kernel:Call Trace:
  May 17 20:12:56 example kernel:[<ffffffff814ede79>] ? schedule_timeout+0x2c9/0x2e0
  May 17 20:12:56 example kernel:[<ffffffff8107c260>] ? process_timeout+0x0/0x10
  May 17 20:12:56 example kernel:[<ffffffff810cc0c9>] ? audit_log_start+0x259/0x490
  May 17 20:12:56 example kernel:[<ffffffff8105e940>] ? default_wake_function+0x0/0x20
  May 17 20:12:56 example kernel:[<ffffffff810cafa6>] ? audit_buffer_free+0x76/0xa0
  May 17 20:12:56 example kernel:[<ffffffff810d31f5>] ? audit_log_exit+0xc5/0x1150

Resolution

この問題は BZ 962976 で修正され、以下のエラータが利用できます。

RHBA-2013-1169 (RHEL6.2.z)
RHBA-2013-1190 (RHEL6.3.z)
RHSA-2013-1173 (RHEL6.4.z)
RHSA-2013-1645 (RHEL6.5)

Root Cause

タイムアウト値がマイナスになっているため、schedule_timeout() でエラーが発生しました。audit_log_start() 関数は、タイムアウトを計算して jiffies の古いコピーから schedule_timeout() に渡し、現在の jiffies 値を引きます。現在の値は進みますが、結果はマイナスになります。schedule_timeout() でタイムアウト値がマイナスになっていることを確認すると、呼び出しが実際には行われないため、現在のタスクはおそらくビジーループに陥ります。

この場合、タイムアウト値が間違っているため、プロセスがコンテキストスイッチされません。ここで、コンテキストスイッチは、指定した時間遅延するように設定されており、監査バックログが削除されるまで新しい監査ログイベントをすべてスロットルします。遅延が発生しないため、監査ログイベントが発生する速度が、監査ログに記載できる速度を超えるため、監査レコードが落ちます。これにより、メッセージが過度にシステムログに印刷されるため、不必要な CPU オーバーヘッドが発生されます。

Diagnostic Steps

バグが見つかりました。

struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
                                     int type)
{
        struct audit_buffer     *ab     = NULL;
        struct timespec         t;
        unsigned int            uninitialized_var(serial);
        int reserve;
        unsigned long timeout_start = jiffies;
...
        while (audit_backlog_limit
               && skb_queue_len(&audit_skb_queue) > audit_backlog_limit + reserve) {
                if (gfp_mask & __GFP_WAIT && audit_backlog_wait_time
                    && time_before(jiffies, timeout_start + audit_backlog_wait_time)) {   <--- jiffies is < timeout here

                        /* Wait for auditd to drain the queue a little */
                        DECLARE_WAITQUEUE(wait, current);
                        set_current_state(TASK_INTERRUPTIBLE);
                        add_wait_queue(&audit_backlog_wait, &wait);

                        if (audit_backlog_limit &&
                            skb_queue_len(&audit_skb_queue) > audit_backlog_limit)
                                schedule_timeout(timeout_start + audit_backlog_wait_time - jiffies);   <--- jiffies is > timeout here
...

schedule_timeout() への呼び出しが、マイナスのタイムアウト値を渡します。その間に 'timeout_start' が初期化されます。そしてタイムアウトの引数が計算されると jiffies カウンターが 'timeout_start + audit_backlog_wait_time' を超えるため、結果がマイナスとなります。

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.