divide error: bdi_dirty_limit+0x5a/0x9e

Hi all,

we're able to trigger the oops below when doing CPU hotplug tests.

	...

and from looking at the register dump below, the dividend, which should be in %rdx:%rax is 0 and the divisor (denominator) we've got from bdi_writeout_fraction and is in %rdi is also 0. Which is strange because fprop_fraction_percpu guards for division by zero by setting denominator to 1 if it were zero but what about the case where den > num? Can that even happen?

And also, what happens if num is 0? Which it kinda is by looking at %rcx where there's copy of it.

Quoted 4 lines · Borislav Petkov

Hi all,

we're able to trigger the oops below when doing CPU hotplug tests.

I hit this problem as well, which I reported here, a few days ago:
https://lkml.org/lkml/2012/9/13/222

Quoted 8 lines · Srivatsa S. Bhat

Quoted 4 lines · Borislav Petkov

Hi all,

we're able to trigger the oops below when doing CPU hotplug tests.

I hit this problem as well, which I reported here, a few days ago:
https://lkml.org/lkml/2012/9/13/222

Ok, your case shows even more info:

[  526.024180] divide error: 0000 [#1] SMP 
[  526.028144] Modules linked in: ipv6 cpufreq_conservative cpufreq_userspace cpufreq_powersave acpi_cpufreq mperf fuse loop dm_mod iTCO_wdt iTCO_vendor_support coretemp kvm_intel kvm cdc_ether pcspkr usbnet shpchp pci_hotplug i2c_i801 i2c_core ioatdma mii crc32c_intel serio_raw microcode lpc_ich mfd_core i7core_edac bnx2 dca edac_core tpm_tis tpm sg tpm_bios rtc_cmos button uhci_hcd ehci_hcd usbcore usb_common sd_mod crc_t10dif edd ext3 mbcache jbd fan processor mptsas mptscsih mptbase scsi_transport_sas scsi_mod thermal thermal_sys hwmon
[  526.028145] CPU 9 
[  526.028145] Pid: 2235, comm: flush-8:0 Not tainted 3.6.0-rc1-tglx-hotplug-0.0.0.28.36b5ec9-default #1 IBM IBM System x -[7870C4Q]-/68Y8033 
[  526.028145] RIP: 0010:[<ffffffff811276f6>]  [<ffffffff811276f6>] bdi_dirty_limit+0x66/0xc0
[  526.028145] RSP: 0018:ffff8811530bfcc0  EFLAGS: 00010206
[  526.028145] RAX: 0000000000b9877e RBX: 00000000001a8112 RCX: 28f5c28f5c28f5c3
[  526.028145] RDX: 0000000000000000 RSI: 0000000000b9877e RDI: 0000000000000000

%rax contains something != 0 but %rdi definitely is 0.

Quoted 21 lines · Borislav Petkov

Quoted 8 lines · Srivatsa S. Bhat

Quoted 4 lines · Borislav Petkov

Hi all,

we're able to trigger the oops below when doing CPU hotplug tests.

I hit this problem as well, which I reported here, a few days ago:
https://lkml.org/lkml/2012/9/13/222

Ok, your case shows even more info:

[  526.024180] divide error: 0000 [#1] SMP 
[  526.028144] Modules linked in: ipv6 cpufreq_conservative cpufreq_userspace cpufreq_powersave acpi_cpufreq mperf fuse loop dm_mod iTCO_wdt iTCO_vendor_support coretemp kvm_intel kvm cdc_ether pcspkr usbnet shpchp pci_hotplug i2c_i801 i2c_core ioatdma mii crc32c_intel serio_raw microcode lpc_ich mfd_core i7core_edac bnx2 dca edac_core tpm_tis tpm sg tpm_bios rtc_cmos button uhci_hcd ehci_hcd usbcore usb_common sd_mod crc_t10dif edd ext3 mbcache jbd fan processor mptsas mptscsih mptbase scsi_transport_sas scsi_mod thermal thermal_sys hwmon
[  526.028145] CPU 9 
[  526.028145] Pid: 2235, comm: flush-8:0 Not tainted 3.6.0-rc1-tglx-hotplug-0.0.0.28.36b5ec9-default #1 IBM IBM System x -[7870C4Q]-/68Y8033 
[  526.028145] RIP: 0010:[<ffffffff811276f6>]  [<ffffffff811276f6>] bdi_dirty_limit+0x66/0xc0
[  526.028145] RSP: 0018:ffff8811530bfcc0  EFLAGS: 00010206
[  526.028145] RAX: 0000000000b9877e RBX: 00000000001a8112 RCX: 28f5c28f5c28f5c3
[  526.028145] RDX: 0000000000000000 RSI: 0000000000b9877e RDI: 0000000000000000

Quoted 2 lines

%rax contains something != 0 but %rdi definitely is 0.

Yep.. So I tried putting a BUG_ON(!den) in fprop_fraction_percpu() to catch if we really got the code wrong somehow.. but unfortunately, with that added, I haven't been successful in reproducing the bug :(

Quoted 25 lines · Srivatsa S. Bhat

Quoted 23 lines · Borislav Petkov

Quoted 8 lines · Srivatsa S. Bhat

Quoted 4 lines · Borislav Petkov

Hi all,

we're able to trigger the oops below when doing CPU hotplug tests.

I hit this problem as well, which I reported here, a few days ago:
https://lkml.org/lkml/2012/9/13/222

Ok, your case shows even more info:

[  526.024180] divide error: 0000 [#1] SMP 
[  526.028144] Modules linked in: ipv6 cpufreq_conservative cpufreq_userspace cpufreq_powersave acpi_cpufreq mperf fuse loop dm_mod iTCO_wdt iTCO_vendor_support coretemp kvm_intel kvm cdc_ether pcspkr usbnet shpchp pci_hotplug i2c_i801 i2c_core ioatdma mii crc32c_intel serio_raw microcode lpc_ich mfd_core i7core_edac bnx2 dca edac_core tpm_tis tpm sg tpm_bios rtc_cmos button uhci_hcd ehci_hcd usbcore usb_common sd_mod crc_t10dif edd ext3 mbcache jbd fan processor mptsas mptscsih mptbase scsi_transport_sas scsi_mod thermal thermal_sys hwmon
[  526.028145] CPU 9 
[  526.028145] Pid: 2235, comm: flush-8:0 Not tainted 3.6.0-rc1-tglx-hotplug-0.0.0.28.36b5ec9-default #1 IBM IBM System x -[7870C4Q]-/68Y8033 
[  526.028145] RIP: 0010:[<ffffffff811276f6>]  [<ffffffff811276f6>] bdi_dirty_limit+0x66/0xc0
[  526.028145] RSP: 0018:ffff8811530bfcc0  EFLAGS: 00010206
[  526.028145] RAX: 0000000000b9877e RBX: 00000000001a8112 RCX: 28f5c28f5c28f5c3
[  526.028145] RDX: 0000000000000000 RSI: 0000000000b9877e RDI: 0000000000000000

%rax contains something != 0 but %rdi definitely is 0.

Quoted 3 lines

Yep.. So I tried putting a BUG_ON(!den) in fprop_fraction_percpu() to catch if we really got the code wrong somehow.. but unfortunately, with that added, I haven't been successful in reproducing the bug :(

Will you test such a line? At least the generic do_div() only uses the lower 32bits for division.

        WARN_ON(!(den & 0xffffffff));

Will you test such a line? At least the generic do_div() only uses the lower 32bits for division.

        WARN_ON(!(den & 0xffffffff));

Quoted 4 lines · Fengguang Wu

Will you test such a line? At least the generic do_div() only uses the lower 32bits for division.

        WARN_ON(!(den & 0xffffffff));

But, but, the asm output says:

  28:   48 89 c8                mov    %rcx,%rax
  2b:*  48 f7 f7                div    %rdi     <-- trapping instruction
  2e:   31 d2                   xor    %edx,%edx

and this version of DIV does an unsigned division of RDX:RAX by the contents of a *64-bit register* ... in our case %rdi.

Srivatsa's oops shows the same:

  28:   48 89 f0                mov    %rsi,%rax
  2b:*  48 f7 f7                div    %rdi     <-- trapping instruction
  2e:   41 8b 94 24 74 02 00    mov    0x274(%r12),%edx

Right?

Quoted 17 lines · Borislav Petkov

Quoted 4 lines · Fengguang Wu

Will you test such a line? At least the generic do_div() only uses the lower 32bits for division.

        WARN_ON(!(den & 0xffffffff));

But, but, the asm output says:

  28:   48 89 c8                mov    %rcx,%rax
  2b:*  48 f7 f7                div    %rdi     <-- trapping instruction
  2e:   31 d2                   xor    %edx,%edx

and this version of DIV does an unsigned division of RDX:RAX by the contents of a *64-bit register* ... in our case %rdi.

Srivatsa's oops shows the same:

Quoted 5 lines

  28:   48 89 f0                mov    %rsi,%rax
  2b:*  48 f7 f7                div    %rdi     <-- trapping instruction
  2e:   41 8b 94 24 74 02 00    mov    0x274(%r12),%edx

Right?

Right, that's why I said "at least". As for x86, I'm as clueless as you..

Quoted 24 lines · Fengguang Wu

Quoted 22 lines · Borislav Petkov

Quoted 4 lines · Fengguang Wu

Will you test such a line? At least the generic do_div() only uses the lower 32bits for division.

        WARN_ON(!(den & 0xffffffff));

But, but, the asm output says:

  28:   48 89 c8                mov    %rcx,%rax
  2b:*  48 f7 f7                div    %rdi     <-- trapping instruction
  2e:   31 d2                   xor    %edx,%edx

and this version of DIV does an unsigned division of RDX:RAX by the contents of a *64-bit register* ... in our case %rdi.

Srivatsa's oops shows the same:

  28:   48 89 f0                mov    %rsi,%rax
  2b:*  48 f7 f7                div    %rdi     <-- trapping instruction
  2e:   41 8b 94 24 74 02 00    mov    0x274(%r12),%edx

Right?

Quoted 1 line

Right, that's why I said "at least". As for x86, I'm as clueless as you..

Right, both oopses are on x86 so I don't think it is the bitness of the division.

Another thing those two have in common is that both happen when a CPU comes online. Srivatsa's is when CPU9 comes online (oops is detected on CPU9) and in our case CPU4 comes online but the oops says CPU0.

So it has to be hotplug-related.

we're able to trigger the oops below when doing CPU hotplug tests.

Disassembling the code section of the oops gives

   0:   1a 00                   sbb    (%rax),%al
   2:   b8 64 00 00 00          mov    $0x64,%eax
   7:   2b 05 5c a4 28 01       sub    0x128a45c(%rip),%eax        # 0x128a469
   d:   be 64 00 00 00          mov    $0x64,%esi
  12:   31 d2                   xor    %edx,%edx
  14:   8b 7d e0                mov    -0x20(%rbp),%edi
  17:   48 0f af c3             imul   %rbx,%rax
  1b:   48 f7 f6                div    %rsi
  1e:   31 d2                   xor    %edx,%edx
  20:   48 89 c1                mov    %rax,%rcx
  23:   48 0f af 4d e8          imul   -0x18(%rbp),%rcx
  28:   48 89 c8                mov    %rcx,%rax
  2b:*  48 f7 f7                div    %rdi     <-- trapping instruction
  2e:   31 d2                   xor    %edx,%edx
  30:   48 89 c1                mov    %rax,%rcx
  33:   41 8b 84 24 4c 01 00    mov    0x14c(%r12),%eax
  3a:   00 
  3b:   48 0f af c3             imul   %rbx,%rax
  3f:   48                      rex.W

in bdi_dirty_limit. The .s file contains then (annotations mine):

.globl bdi_dirty_limit
.type bdi_dirty_limit, @function
bdi_dirty_limit:

        pushq   %rbp    #
        movq    %rsp, %rbp      #,
        pushq   %r12    #
        pushq   %rbx    #
        subq    $48, %rsp       #,
        call    mcount
        movq    %rsi, %rbx      # dirty, dirty
        leaq    -32(%rbp), %rcx #, tmp65
        leaq    -24(%rbp), %rdx #, tmp66
        leaq    280(%rdi), %rsi #, tmp67
        movq    %rdi, %r12      # bdi, bdi
        movq    $writeout_completions, %rdi     #,
        call    fprop_fraction_percpu   #
        movl    $100, %eax      #, tmp69
        subl    bdi_min_ratio(%rip), %eax       # bdi_min_ratio, tmp70
        movl    $100, %esi      #, tmp75
        xorl    %edx, %edx      #
        mov     -32(%rbp), %edi # denominator, denominator
        imulq   %rbx, %rax      # dirty, tmp71
        divq    %rsi    # tmp75
        xorl    %edx, %edx      #			# most-significant part of bdi_dirty is already zeroed here
        movq    %rax, %rcx      # tmp71, tmp73
        imulq   -24(%rbp), %rcx # numerator, tmp73	# bdi_dirty *= numerator
        movq    %rcx, %rax      # tmp73,		# move bdi_dirty in place for next insn
        divq    %rdi		# denominator		<--- TRAP
        xorl    %edx, %edx      #
        movq    %rax, %rcx      #, tmp78
	...

and from looking at the register dump below, the dividend, which should be in %rdx:%rax is 0 and the divisor (denominator) we've got from bdi_writeout_fraction and is in %rdi is also 0. Which is strange because fprop_fraction_percpu guards for division by zero by setting denominator to 1 if it were zero but what about the case where den > num? Can that even happen?

And also, what happens if num is 0? Which it kinda is by looking at %rcx where there's copy of it.

Sep 23 17:41:08 lemure kernel: [ 381.245776] divide error: 0000 [#1] SMP
Sep 23 17:41:08 lemure kernel: [ 381.249725] Modules linked in: cpufreq_conservative cpufreq_userspace cpufreq_powersave i2c_piix4 tpm_tis rtc_cmos powernow_k8 tpm fam15
h_power k10temp tpm_bios mperf serio_raw crc32c_intel ghash_clmulni_intel
Sep 23 17:41:08 lemure kernel: [ 381.268531] CPU 0
Sep 23 17:41:08 lemure kernel: [ 381.270377] Pid: 6644, comm: flush-8:0 Not tainted 3.6.0-rc6-e5e77cf9-linus+ #1 AMD
Sep 23 17:41:08 lemure kernel: [ 381.279067] RIP: 0010:[<ffffffff810e8bc2>] [<ffffffff810e8bc2>] bdi_dirty_limit+0x5a/0x9e
Sep 23 17:41:08 lemure kernel: [ 381.287330] RSP: 0018:ffff88041ad03d40 EFLAGS: 00010246
Sep 23 17:41:08 lemure kernel: [ 381.292631] RAX: 0000000000000000 RBX: 00000000000621c3 RCX: 0000000000000000
Sep 23 17:41:08 lemure kernel: [ 381.299751] RDX: 0000000000000000 RSI: 0000000000000064 RDI: 0000000000000000
Sep 23 17:41:08 lemure kernel: [ 381.306870] RBP: ffff88041ad03d80 R08: 0000000000000008 R09: ffffffff8211e520
Sep 23 17:41:08 lemure kernel: [ 381.313989] R10: ffff88041ad03d10 R11: ffff88041ad03d10 R12: ffff88041a2d0158
Sep 23 17:41:08 lemure kernel: [ 381.321109] R13: ffff88041a2d0158 R14: ffff88041a2d02b0 R15: 0000000000000000
Sep 23 17:41:08 lemure kernel: [ 381.328228] FS: 00007f3db8ea7700(0000) GS:ffff88042ec00000(0000) knlGS:0000000000000000
Sep 23 17:41:08 lemure kernel: [ 381.336298] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Sep 23 17:41:08 lemure kernel: [ 381.342034] CR2: 0000000000d84270 CR3: 0000000418ce4000 CR4: 00000000000407f0
Sep 23 17:41:08 lemure kernel: [ 381.349151] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Sep 23 17:41:08 lemure kernel: [ 381.356263] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Sep 23 17:41:08 lemure kernel: [ 381.363384] Process flush-8:0 (pid: 6644, threadinfo ffff88041ad02000, task ffff8804198826c0)
Sep 23 17:41:08 lemure kernel: [ 381.371884] Stack:
Sep 23 17:41:08 lemure kernel: [ 381.373890] ffff88041ad03d80 ffffffff810e8e7a 0000000100013eb3 0000000000000000
Sep 23 17:41:08 lemure kernel: [ 381.381330] 2000000000000000 0000000000000000 fffffffffffffff7 0000000000000000
Sep 23 17:41:08 lemure kernel: [ 381.388769] ffff88041ad03dc0 ffffffff8114f9bd 000000010000c983 00000000000c4386
Sep 23 17:41:08 lemure kernel: [ 381.396208] Call Trace:
Sep 23 17:41:09 lemure kernel: [ 381.398654] [<ffffffff810e8e7a>] ? global_dirty_limits+0x3c/0x130
Sep 23 17:41:09 lemure kernel: [ 381.404823] [<ffffffff8114f9bd>] over_bground_thresh+0x5c/0x76
Sep 23 17:41:09 lemure kernel: [ 381.410729] [<ffffffff811503aa>] wb_do_writeback+0x193/0x1e9
Sep 23 17:41:09 lemure kernel: [ 381.416464] [<ffffffff811504ca>] bdi_writeback_thread+0xca/0x1ec
Sep 23 17:41:09 lemure kernel: [ 381.422545] [<ffffffff81150400>] ? wb_do_writeback+0x1e9/0x1e9
Sep 23 17:41:09 lemure kernel: [ 381.428455] [<ffffffff8105e75b>] kthread+0x8d/0x95
Sep 23 17:41:09 lemure kernel: [ 381.433323] [<ffffffff81940474>] kernel_thread_helper+0x4/0x10
Sep 23 17:41:09 lemure kernel: [ 381.439231] [<ffffffff8105e6ce>] ? kthread_freezable_should_stop+0x62/0x62
Sep 23 17:41:09 lemure kernel: [ 381.446178] [<ffffffff81940470>] ? gs_change+0xb/0xb
Sep 23 17:41:09 lemure kernel: [ 381.451217] Code: 1a 00 b8 64 00 00 00 2b 05 5c a4 28 01 be 64 00 00 00 31 d2 8b 7d e0 48 0f af c3 48 f7 f6 31 d2 48 89 c1 48 0f af 4d e8 48 89 c8 <48> f7 f7 31 d2 48 89 c1 41 8b 84 24 4c 01 00 00 48 0f af c3 48
Sep 23 17:41:10 lemure kernel: [ 381.471131] RIP [<ffffffff810e8bc2>] bdi_dirty_limit+0x5a/0x9e
Sep 23 17:41:10 lemure kernel: [ 381.477057] RSP <ffff88041ad03d40>
Sep 23 17:41:10 lemure kernel: [ 381.480604] ---[ end trace 703f173ed75f76a9 ]---

  fprop_fraction_percpu() does:
        do {
                seq = read_seqcount_begin(&p->sequence);
                fprop_reflect_period_percpu(p, pl);
                num = percpu_counter_read_positive(&pl->events);
                den = percpu_counter_read_positive(&p->events);
        } while (read_seqcount_retry(&p->sequence, seq));

        /*
         * Make fraction <= 1 and denominator > 0 even in presence of
         * percpu
         * counter errors
         */
        if (den <= num) {
                if (num)
                        den = num;
                else
                        den = 1;
        }
        *denominator = den;
        *numerator = num;

So after initial loop, num and den are >= 0 because
percpu_counter_read_positive() asserts that. If den == 0, then the condition is true and thus we always set den to value >= 1. So at least in the theoretical model of computation what you observe cannot happen :).

Because of use of percpu_counter_read_positive() it also doesn't seem like
some catch with sign extension (we always deal with non-negative numbers) and because you are on a 64-bit machine, s64 fits into long without. However, do_div() assumes divisor is 32-bit and we can indeed observe that in the disassembly where we prepare the divisor as:
mov -32(%rbp), %edi # denominator, denominator
(32-bit move insn used). I'm not quite sure if I read the stack in the dump correctly but -32(%rbp) seems to be 0x2000000000000000 which would fit what we see.

From dd0947226a0d5868ba0c2b8808162898396035b7 Mon Sep 17 00:00:00 2001
From: Jan Kara <[email protected]>
Date: Mon, 24 Sep 2012 16:17:16 +0200
Subject: [PATCH] lib: Debug flex proportions code

Signed-off-by Jan Kara <[email protected]>

---
 lib/flex_proportions.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

lib/flex_proportions.c +3 -1

index c785554..f88f793 100644
@@ -62,11 +62,13 @@ void fprop_global_destroy(struct fprop_global *p)
  */
 bool fprop_new_period(struct fprop_global *p, int periods)
 {
-	u64 events;
+	s64 events;
 	unsigned long flags;
 
 	local_irq_save(flags);
 	events = percpu_counter_sum(&p->events);
+	if (events < 0)
+		printk("Got negative events: %lld\n", (long long)events);
 	/*
 	 * Don't do anything if there are no events.
 	 */

Signature · 1 line

1.7.1

[ … ]

Conny, would you test pls?

Hi,

Quoted 3 lines · On Mon, 24 Sep 2012 16:36:09 +0200 Borislav Petkov <[email protected]> wrote:

[ a?| ]

Conny, would you test pls?

Sure thing.
Out of ~25 runs I only triggered it once, without the patch the trigger-rate is higher.

[   55.098249] Broke affinity for irq 81
[   55.105108] smpboot: CPU 1 is now offline
[   55.311216] smpboot: Booting Node 0 Processor 1 APIC 0x11
[   55.333022] LVT offset 0 assigned for vector 0x400
[   55.545877] smpboot: CPU 2 is now offline
[   55.753050] smpboot: Booting Node 0 Processor 2 APIC 0x12
[   55.775582] LVT offset 0 assigned for vector 0x400
[   55.986747] smpboot: CPU 3 is now offline
[   56.193839] smpboot: Booting Node 0 Processor 3 APIC 0x13
[   56.212643] LVT offset 0 assigned for vector 0x400
[   56.423201] Got negative events: -25

Quoted 12 lines · Conny Seidel

Hi,

Quoted 3 lines · On Mon, 24 Sep 2012 16:36:09 +0200 Borislav Petkov <[email protected]> wrote:

[ a?| ]

Conny, would you test pls?

Sure thing.
Out of ~25 runs I only triggered it once, without the patch the trigger-rate is higher.

Quoted 11 lines

[   55.098249] Broke affinity for irq 81
[   55.105108] smpboot: CPU 1 is now offline
[   55.311216] smpboot: Booting Node 0 Processor 1 APIC 0x11
[   55.333022] LVT offset 0 assigned for vector 0x400
[   55.545877] smpboot: CPU 2 is now offline
[   55.753050] smpboot: Booting Node 0 Processor 2 APIC 0x12
[   55.775582] LVT offset 0 assigned for vector 0x400
[   55.986747] smpboot: CPU 3 is now offline
[   56.193839] smpboot: Booting Node 0 Processor 3 APIC 0x13
[   56.212643] LVT offset 0 assigned for vector 0x400
[   56.423201] Got negative events: -25

I see it:

__percpu_counter_sum does for_each_online_cpu without doing get/put_online_cpus().

Quoted 16 lines

Quoted 4 lines

Sure thing.
Out of ~25 runs I only triggered it once, without the patch the trigger-rate is higher.

Quoted 11 lines

[   55.098249] Broke affinity for irq 81
[   55.105108] smpboot: CPU 1 is now offline
[   55.311216] smpboot: Booting Node 0 Processor 1 APIC 0x11
[   55.333022] LVT offset 0 assigned for vector 0x400
[   55.545877] smpboot: CPU 2 is now offline
[   55.753050] smpboot: Booting Node 0 Processor 2 APIC 0x12
[   55.775582] LVT offset 0 assigned for vector 0x400
[   55.986747] smpboot: CPU 3 is now offline
[   56.193839] smpboot: Booting Node 0 Processor 3 APIC 0x13
[   56.212643] LVT offset 0 assigned for vector 0x400
[   56.423201] Got negative events: -25

Quoted 5 lines

I see it:

__percpu_counter_sum does for_each_online_cpu without doing get/put_online_cpus().

Maybe I'm missing something, but that doesn't immediately tell me what's the exact source of the bug.. Note that there is a hotplug callback percpu_counter_hotcpu_callback() that takes the same fbc->lock before updating/resetting the percpu counters of offline CPU. So, though the synchronization is a bit weird, I don't immediately see a problematic race condition there.

Quoted 22 lines · Srivatsa S. Bhat

Quoted 16 lines

Quoted 4 lines

Sure thing.
Out of ~25 runs I only triggered it once, without the patch the trigger-rate is higher.

Quoted 11 lines

[   55.098249] Broke affinity for irq 81
[   55.105108] smpboot: CPU 1 is now offline
[   55.311216] smpboot: Booting Node 0 Processor 1 APIC 0x11
[   55.333022] LVT offset 0 assigned for vector 0x400
[   55.545877] smpboot: CPU 2 is now offline
[   55.753050] smpboot: Booting Node 0 Processor 2 APIC 0x12
[   55.775582] LVT offset 0 assigned for vector 0x400
[   55.986747] smpboot: CPU 3 is now offline
[   56.193839] smpboot: Booting Node 0 Processor 3 APIC 0x13
[   56.212643] LVT offset 0 assigned for vector 0x400
[   56.423201] Got negative events: -25

Quoted 5 lines

I see it:

__percpu_counter_sum does for_each_online_cpu without doing get/put_online_cpus().

Quoted 6 lines

Maybe I'm missing something, but that doesn't immediately tell me what's the exact source of the bug.. Note that there is a hotplug callback percpu_counter_hotcpu_callback() that takes the same fbc->lock before updating/resetting the percpu counters of offline CPU. So, though the synchronization is a bit weird, I don't immediately see a problematic race condition there.

Well, those oopses both happen when a cpu comes online.

According to when percpu_counter_hotcpu_callback is run (at CPU_DEAD) then those percpu variables should have correctly updated values.

So there has to be some other case where we read garbage which is a negative value - otherwise we wouldn't be seeing the debug output.

For example, look at the log output above: we bring down cpu 3 just to bring it right back online. So there has to be something fishy along that codepath...

Quoted 35 lines · Borislav Petkov

Quoted 22 lines · Srivatsa S. Bhat

Quoted 16 lines

Quoted 4 lines

Sure thing.
Out of ~25 runs I only triggered it once, without the patch the trigger-rate is higher.

Quoted 11 lines

[   55.098249] Broke affinity for irq 81
[   55.105108] smpboot: CPU 1 is now offline
[   55.311216] smpboot: Booting Node 0 Processor 1 APIC 0x11
[   55.333022] LVT offset 0 assigned for vector 0x400
[   55.545877] smpboot: CPU 2 is now offline
[   55.753050] smpboot: Booting Node 0 Processor 2 APIC 0x12
[   55.775582] LVT offset 0 assigned for vector 0x400
[   55.986747] smpboot: CPU 3 is now offline
[   56.193839] smpboot: Booting Node 0 Processor 3 APIC 0x13
[   56.212643] LVT offset 0 assigned for vector 0x400
[   56.423201] Got negative events: -25

Quoted 5 lines

I see it:

__percpu_counter_sum does for_each_online_cpu without doing get/put_online_cpus().

Quoted 6 lines

Maybe I'm missing something, but that doesn't immediately tell me what's the exact source of the bug.. Note that there is a hotplug callback percpu_counter_hotcpu_callback() that takes the same fbc->lock before updating/resetting the percpu counters of offline CPU. So, though the synchronization is a bit weird, I don't immediately see a problematic race condition there.

Well, those oopses both happen when a cpu comes online.

According to when percpu_counter_hotcpu_callback is run (at CPU_DEAD) then those percpu variables should have correctly updated values.

Quoted 6 lines

So there has to be some other case where we read garbage which is a negative value - otherwise we wouldn't be seeing the debug output.

For example, look at the log output above: we bring down cpu 3 just to bring it right back online. So there has to be something fishy along that codepath...

Well, I think the race happens when a CPU is dying and we call
percpu_counter_sum() after it is marked offline but before callbacks are run. percpu_counter_sum() then does not add died CPU's counter in the sum and thus total can go negative. If get/put_online_cpus() fixes this race, I'd be happy.

OTOH in theory, percpu_counter_sum() can return negative values even
without CPU hotplug when percpu_counter_sum() races with cpu local operations. It cannot happen with the current flexible proportion code but I think making the code more robust is a good idea. I'll send a patch for this. Still fixing the percpu counters would be nice as these races could cause random errors to computed proportions and that's bad for writeback.

In the attachment is a fix. Fengguang, can you please merge it? Thanks!

Quoted 1 line · On Mon, 24 Sep 2012 22:17:26 +0200 Jan Kara <[email protected]> wrote:

In the attachment is a fix. Fengguang, can you please merge it? Thanks!

I grabbed it. I also added the (missing, important) text "This bug causes a divide-by-zero oops in bdi_dirty_limit() in Borislav's 3.6.0-rc6 based kernel." And I stuck a cc:stable onto it.

[...]

From 1fd707552a67adf869958e479910d2f70452351b Mon Sep 17 00:00:00 2001
From: Jan Kara <[email protected]>
Date: Mon, 24 Sep 2012 16:17:16 +0200
Subject: [PATCH] lib: Fix corruption of denominator in flexible proportions

When racing with CPU hotplug, percpu_counter_sum() can return negative values for the number of observed events. This confuses fprop_new_period(), which uses unsigned type and as a result number of events is set to big *positive* number. From that moment on, things go pear shaped and can result e.g. in division by zero as denominator is later truncated to 32-bits.

Fix the issue by using a signed type in fprop_new_period(). That makes us bail out from the function without doing anything (mistakenly) thinking there are no events to age. That makes aging somewhat inaccurate but getting accurate data would be rather hard.

Reported-by Borislav Petkov <[email protected]>

Reported-by Srivatsa S. Bhat <[email protected]>

Signed-off-by Jan Kara <[email protected]>

---
 lib/flex_proportions.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

lib/flex_proportions.c +1 -2

index c785554..ebf3bac 100644
@@ -62,7 +62,7 @@ void fprop_global_destroy(struct fprop_global *p)
  */
 bool fprop_new_period(struct fprop_global *p, int periods)
 {
-	u64 events;
+	s64 events;
 	unsigned long flags;
 
 	local_irq_save(flags);
--

1.7.1

From: Srivatsa S. Bhat <[email protected]>

The CPU hotplug callback related to writeback calls writeback_set_ratelimit() during every state change in the hotplug sequence. This is unnecessary since num_online_cpus() changes only once during the entire hotplug operation.

So invoke the function only once per hotplug, thereby avoiding the unnecessary repetition of those costly calculations.

Signed-off-by Srivatsa S. Bhat <[email protected]>

---

Quoted 7 lines · Srivatsa S. Bhat

From: Srivatsa S. Bhat <[email protected]>

The CPU hotplug callback related to writeback calls writeback_set_ratelimit() during every state change in the hotplug sequence. This is unnecessary since num_online_cpus() changes only once during the entire hotplug operation.

Quoted 5 lines

So invoke the function only once per hotplug, thereby avoiding the unnecessary repetition of those costly calculations.

Signed-off-by Srivatsa S. Bhat <[email protected]>

---

Looks good to me. I'll include it in the writeback tree.

Quoted 6 lines · Srivatsa S. Bhat

From: Srivatsa S. Bhat <[email protected]>

The CPU hotplug callback related to writeback calls writeback_set_ratelimit() during every state change in the hotplug sequence. This is unnecessary since num_online_cpus() changes only once during the entire hotplug operation.

Quoted 5 lines

So invoke the function only once per hotplug, thereby avoiding the unnecessary repetition of those costly calculations.

Signed-off-by Srivatsa S. Bhat <[email protected]>

---

Looks good to me. I'll include it in the writeback tree.

Thanks,
Fengguang

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>