Translated message

A translation of this page exists in English.

Warning message

This translation is outdated. For the most up-to-date information, please refer to the English version.

RHEL6 において、 thread_group_times の divide_error でプロセスの utimes (ユーザー領域の時間) が間違っているか、クラッシュする

Solution Verified - Updated -

Environment

  • Red Hat Enterprise Linux 6 (64 ビット)
  • 2.6.32-220.11.1.el6 - 2.6.32-220.26.1.el6
  • 2.6.32-279.el6 - 2.6.32-279.10.1.el6

Issue

  • 全く異なる 3 つの症状を示す 1 つの原因があります。

a) プロセスの "utime" (時間フィールドで ps と示される) で長期間実行しているプロセスを示している

  • たとえば、以下のようになります。
$ ps
UID        PID  PPID  C STIME TTY          TIME CMD
root    50925 50923 99 Aug06 ?        213555-20:29:38 test_application
  • TIME フィールドは、/proc/PID/stat フィールドでフィールド 14 に相当し、カーネルに報告される "utime" 値です。
$ cat /proc/50925/stat
40275 (test_application) S 40273 36692 35927 0 -1 4202496 399678594 489450 31722 0 974453227234
870691207771 39 6381 20 0 17 0 116189537 2022604800 14289 18446744073709551615 4194304 20071776
140734177595376 1407341775887 52 238159815987 0 0 6 8414376 18446744073709551615 0 0 17 0 0 0 3419 0 0

b) システムが thread_group_times() で突然クラッシュする

  • たとえば、以下のようになります。
divide error:0000 [#1] SMP 
...
CPU 1 
Modules linked in: ipv6 power_meter hpilo hpwdt ipmi_si ipmi_msghandler sg microcode serio_raw iTCO_wdt iTCO_vendor_support bnx2 i7core_edac edac_core shpchp ext4 mbcache jbd2 sr_mod cdrom sd_mod crc_t10dif pata_acpi ata_generic ata_piix hpsa radeon ttm drm_kms_helper drm i2c_algo_bit i2c_core dm_mirror dm_region_hash dm_log dm_mod [last unloaded: scsi_wait_scan]

Pid:2484, comm:XXXXX Not tainted 2.6.32-279.el6.x86_64 #1 HP ProLiant DL380 G6
RIP:0010:[<ffffffff81058226>]  [<ffffffff81058226>] thread_group_times+0x56/0xb0
RSP:0018:ffff880414ec9eb8  EFLAGS:00010046
RAX:943882ab68e17428 RBX: ffff880415e5f000 RCX:00000000ff6373b8
RDX:0000000000000000 RSI: ffff880414ec9eb8 RDI:000f38eb448809cb
RBP: ffff880414ec9ef8 R08:0000000094935de3 R09: ffff880415e5f000
R10:0000189800000000 R11:0000000000000202 R12: ffff880414ec9f08
R13: ffff880414ec9f10 R14:0000000000000000 R15:0000000000000006
FS:00007f911dbf0700(0000) GS:ffff88042e400000(0000) knlGS:0000000000000000
CS:0010 DS:0000 ES:0000 CR0:0000000080050033
CR2:00007f691244e330 CR3:000000081489d000 CR4:00000000000006e0
DR0:0000000000000000 DR1:0000000000000000 DR2:0000000000000000
DR3:0000000000000000 DR6:00000000ffff0ff0 DR7:0000000000000400
Process XXXXX (pid:2484, threadinfo ffff880414ec8000, task ffff880414e04080)
Stack:
 ...
Call Trace:
 [<ffffffff8108979d>] do_sys_times+0x4d/0xd0
 [<ffffffff81089864>] sys_times+0x44/0x70
 [<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b
Code:49 89 d4 e8 7d b4 03 00 4c 8b 75 c8 4c 03 75 c0 48 8b 7d d0 e8 6c 9a 01 00 4d 85 f6 48 89 c1 74 0d 48 0f af 45 c0 45 89 f6 31 d2 <49> f7 f6 4c 8b b3 d8 03 00 00 48 8b 93 e0 03 00 00 4c 39 f0 49 
RIP  [<ffffffff81058226>] thread_group_times+0x56/0xb0
 RSP <ffff880414ec9eb8>

c) システムが task_times() で突然クラッシュする

  • たとえば、以下のようになります。
crash> log
divide error:0000 [#1] SMP 
last sysfs file:/sys/devices/system/cpu/cpu15/cpufreq/scaling_setspeed
CPU 2 
Modules linked in: bluetooth rfkill bonding ipv6 bridge stp llc nfs lockd fscache nfs_acl auth_rpcgss autofs4 sunrpc pcc_cpufreq power_meter
sg microcode serio_raw iTCO_wdt iTCO_vendor_support hpilo hpwdt bnx2 i7core_edac edac_core shpchp ext4 mbcache jbd2 sd_mod crc_t10dif
hpsa radeon ttm drm_kms_helper drm i2c_algo_bit i2c_core dm_mirror dm_region_hash dm_log dm_mod [last unloaded: ipv6]
Pid:3177, comm: splunkd Tainted:G        W  ----------------   2.6.32-220.13.1.el6.x86_64 #1 HP ProLiant DL380 G7
RIP:0010:[<ffffffff810569d8>]  [<ffffffff810569d8>] task_times+0x58/0xb0
RSP:0018:ffff880c0f65be38  EFLAGS:00010246
RAX: e54ba6d1fdf60eda RBX: ffff8808a1745500 RCX:00000001001ef539
RDX:0000000000000000 RSI: ffff880c0f65bf18 RDI:000f4418615082a5
RBP: ffff880c0f65be68 R08:0000000000000001 R09:00000000000007de
R10:000000000000000d R11:0000000000000202 R12: ffff880c0f65bf10
R13: ffff880c0f65bf18 R14:0000000000000000 R15:00000000e52fefaa
FS:00007f334c7fd700(0000) GS:ffff880028220000(0000) knlGS:0000000000000000
CS:0010 DS:0000 ES:0000 CR0:0000000080050033
CR2:00007f331ce05000 CR3:0000000c0dbef000 CR4:00000000000006e0
DR0:0000000000000000 DR1:0000000000000000 DR2:0000000000000000
DR3:0000000000000000 DR6:00000000ffff0ff0 DR7:0000000000000400
Process splunkd (pid:3177, threadinfo ffff880c0f65a000, task ffff8808a1745500)
Stack:
 ffff880800000000 ffff8808a1745500 ffff880c0f65be78 0000000000000001
<0> 00007f334bc2e568 00007f334bc2e548 ffff880c0f65bf68 ffffffff81087573
<0> 0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
 [<ffffffff81087573>] getrusage+0x83/0x340
 [<ffffffff81087866>] sys_getrusage+0x36/0x40
 [<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b
Code: f5 49 89 d4 4d 89 fe 4c 03 b7 88 05 00 00 48 8b bf 80 00 00 00 e8 b9 95 01 00 4d 85 f6 48 89 c1 74 0c 49 0f af c7 45 89 f6 31 d2
<49> f7 f6 4c 8b b3 a8 05 00 00 48 8b 93 b0 05 00 00 4c 8b 7d f8 
RIP  [<ffffffff810569d8>] task_times+0x58/0xb0
 RSP <ffff880c0f65be38>

crash> bt
PID:3177   TASK: ffff8808a1745500  CPU:2   COMMAND:"splunkd"
 #0 [ffff880c0f65baf0] machine_kexec at ffffffff8103214b
 #1 [ffff880c0f65bb50] crash_kexec at ffffffff810b90c2
 #2 [ffff880c0f65bc20] oops_end at ffffffff814f09b0
 #3 [ffff880c0f65bc50] die at ffffffff8100f26b
 #4 [ffff880c0f65bc80] do_trap at ffffffff814f02a4
 #5 [ffff880c0f65bce0] do_divide_error at ffffffff8100cfff
 #6 [ffff880c0f65bd80] divide_error at ffffffff8100be7b
    [exception RIP: task_times+0x58]
    RIP: ffffffff810569d8  RSP: ffff880c0f65be38  RFLAGS:00010246
    RAX: e54ba6d1fdf60eda  RBX: ffff8808a1745500  RCX:00000001001ef539
    RDX:0000000000000000  RSI: ffff880c0f65bf18  RDI:000f4418615082a5
    RBP: ffff880c0f65be68   R8:0000000000000001   R9:00000000000007de
    R10:000000000000000d  R11:0000000000000202  R12: ffff880c0f65bf10
    R13: ffff880c0f65bf18  R14:0000000000000000  R15:00000000e52fefaa
    ORIG_RAX: ffffffffffffffff  CS:0010  SS:0018
 #7 [ffff880c0f65be70] getrusage at ffffffff81087573
 #8 [ffff880c0f65bf70] sys_getrusage at ffffffff81087866
 #9 [ffff880c0f65bf80] system_call_fastpath at ffffffff8100b0f2

Resolution

  • セキュリティアドバイザリリリースで修正されました。

  • 使用しているカーネルのバージョンが 2.6.32-279.11.1.el6.x86_64 以降であることを確認します (上のリンクの [Packages] タブを参照)。

Root Cause

  • 64 ビットシステムのコードで正しい演算が実行されていません。特に、32 ビットの除数だけが期待されているにも関わらず 64 ビットの除数を提供する関数を使用して除算が実行されます。除算関数 0 は、低い 32 ビットの除数を拡大し、間違った結果となります。または、その低い 32 ビットが 0 になると、ゼロ除算が行われるためクラッシュします。

  • この問題は、(以下に示す) cputime タイプのサイズに正しい除算関数を呼び出す scale_utime() 関数を導入すると解決できました。

static cputime_t scale_utime(cputime_t utime, cputime_t rtime, cputime_t total)
{
    u64 temp = (__force u64) rtime;

    temp *= (__force u64) utime;

    if (sizeof(cputime_t) == 4)
        do_div(temp, (__force u32) total);
    else
        temp = div64_u64(temp, (__force u64) total);

    return (__force cputime_t) temp;
}

Diagnostic Steps

a) utime 値が間違っている場合

  • top または ps に記載されるプロセスは、長期生存しているプロセスのユーザープロセスに対して非常に大きくなります。/proc/<pid>/stat (フィールド #14) から取得される top の正確な値は、おおよそ 18446744073709617152 になります。この番号は、/proc/<pid>/stat で有効なその他のフィールドに表示されている可能性もあります。

    • 各プロセスで、間違っているとされる /proc/PID/stat、/proc/PID/status、および /proc/PID/statm のコピーを取得します。
    • 影響を受けるプロセスの 1つに対して、/proc/PID のすべてを取得します。
    • フィールド 14 は非常に大きな数字です。

b) thread_group_times() の divide_error でクラッシュが発生した場合

  • vmcore を取得してください。
  • divide_error が発生した cpu のバックトレースを確認します。ここでは、以下のようになります。
    PID:2484
COMMAND:"XXXXX"
   TASK: ffff880414e04080  [THREAD_INFO: ffff880414ec8000]
    CPU:1
  STATE:TASK_RUNNING (PANIC)
crash> bt
PID:2484   TASK: ffff880414e04080  CPU:1   COMMAND:"XXXXX"
 #0 [ffff880414ec9b70] machine_kexec at ffffffff8103281b
 #1 [ffff880414ec9bd0] crash_kexec at ffffffff810ba662
 #2 [ffff880414ec9ca0] oops_end at ffffffff81501290
 #3 [ffff880414ec9cd0] die at ffffffff8100f26b
 #4 [ffff880414ec9d00] do_trap at ffffffff81500b84
 #5 [ffff880414ec9d60] do_divide_error at ffffffff8100cfff
 #6 [ffff880414ec9e00] divide_error at ffffffff8100be7b
    [exception RIP: thread_group_times+86]
    RIP: ffffffff81058226  RSP: ffff880414ec9eb8  RFLAGS:00010046
    RAX:943882ab68e17428  RBX: ffff880415e5f000  RCX: 00000000ff6373b8
    RDX:0000000000000000  RSI: ffff880414ec9eb8  RDI:000f38eb448809cb
    RBP: ffff880414ec9ef8   R8:0000000094935de3   R9: ffff880415e5f000
    R10:0000189800000000  R11:0000000000000202  R12: ffff880414ec9f08
    R13: ffff880414ec9f10  R14:0000000000000000  R15:0000000000000006
    ORIG_RAX: ffffffffffffffff  CS:0010  SS:0018
 #7 [ffff880414ec9f00] do_sys_times at ffffffff8108979d
 #8 [ffff880414ec9f40] sys_times at ffffffff81089864
 #9 [ffff880414ec9f80] system_call_fastpath at ffffffff8100b0f2
    RIP:00000038a2cab3fa  RSP:00007fff430f30b0  RFLAGS:00000246
    RAX:0000000000000064  RBX: ffffffff8100b0f2  RCX:0000000000000000
    RDX:00007fff430f33e0  RSI:0000000000000000  RDI:00007fff430f33e0
    RBP:00007fff430f3400   R8:000000025f0fe968   R9:00000000000038d0
    R10:0000189800000000  R11:0000000000000202  R12:0000000009527b40
    R13:00000000000014f0  R14:000000000bb1e9d8  R15:0000000009527b40
    ORIG_RAX:0000000000000064  CS:0033  SS:002b
  • divide_error の RIP は、thread_group_times()do_div() 呼び出しにおける div 命令です。

c) task_times() の divide_error でクラッシュが発生した場合

  • vmcore を取得してください。
  • divide_error が発生した cpu のバックトレースを確認します。ここでは、 以下のようになります。
crash> bt
PID:3177   TASK: ffff8808a1745500  CPU:2   COMMAND:"splunkd"
 #0 [ffff880c0f65baf0] machine_kexec at ffffffff8103214b
 #1 [ffff880c0f65bb50] crash_kexec at ffffffff810b90c2
 #2 [ffff880c0f65bc20] oops_end at ffffffff814f09b0
 #3 [ffff880c0f65bc50] die at ffffffff8100f26b
 #4 [ffff880c0f65bc80] do_trap at ffffffff814f02a4
 #5 [ffff880c0f65bce0] do_divide_error at ffffffff8100cfff
 #6 [ffff880c0f65bd80] divide_error at ffffffff8100be7b
    [exception RIP: task_times+0x58]
    RIP: ffffffff810569d8  RSP: ffff880c0f65be38  RFLAGS:00010246
    RAX: e54ba6d1fdf60eda  RBX: ffff8808a1745500  RCX:00000001001ef539
    RDX:0000000000000000  RSI: ffff880c0f65bf18  RDI:000f4418615082a5
    RBP: ffff880c0f65be68   R8:0000000000000001   R9:00000000000007de
    R10:000000000000000d  R11:0000000000000202  R12: ffff880c0f65bf10
    R13: ffff880c0f65bf18  R14:0000000000000000  R15:00000000e52fefaa
    ORIG_RAX: ffffffffffffffff  CS:0010  SS:0018
 #7 [ffff880c0f65be70] getrusage at ffffffff81087573
 #8 [ffff880c0f65bf70] sys_getrusage at ffffffff81087866
 #9 [ffff880c0f65bf80] system_call_fastpath at ffffffff8100b0f2

crash> dis -r task_times+0x58
...skip...
0xffffffff810569c2 <task_times+0x42>:   callq  0xffffffff8106ff80 <nsecs_to_jiffies>
0xffffffff810569c7 <task_times+0x47>:   test   %r14,%r14
0xffffffff810569ca <task_times+0x4a>:   mov    %rax,%rcx
0xffffffff810569cd <task_times+0x4d>:   je     0xffffffff810569db <task_times+0x5b>
0xffffffff810569cf <task_times+0x4f>:   imul   %r15,%rax
0xffffffff810569d3 <task_times+0x53>:   mov    %r14d,%r14d
0xffffffff810569d6 <task_times+0x56>:   xor    %edx,%edx
0xffffffff810569d8 <task_times+0x58>:   div    %r14

[kernel-2.6.32-220.13.1.el6/kernel/sched.c:5665]
void task_times(struct task_struct *p, cputime_t *ut, cputime_t *st)
{
        ...skip...
        if (total) {
                u64 temp = rtime;

                temp *= utime;
                do_div(temp, total);          <<< THE CRASH IS HERE
                utime = (cputime_t)temp;
        } else
                utime = rtime;
        ...skip...
  • divide_error の RIP は、task_times()do_div() 呼び出しにおける div %r14 命令です。

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.

Comments