3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Eric Wheeler]

Hello Kent, Ross, all:

We're getting bcache_gc backtraces and soft lockups; the system continues 
to be responsive and eventually recovers.  We are running 3.17-rc6. (This 
appears to be a continuation of the thread from 2014-09-15)

Please see the following two backtraces.  The first shows up in 
btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We 
will test with -rc7 this week, though I didn't see any bcache commits in 
rc7.

The server is quite busy:
   dd in userspace from dm-thinp snapshots to another server
   two DRBD verify's active backed by dm-thinp volumes
   note that, dd fills up the buffers so this could be operating with few
   pages free. (Though we have min-mem set to 256MB.)

I see we are hitting functions like bch_ptr_bad() and bch_extent_bad(). 
Could that indicate a cache corruption on our volume?

I'm happy to test patches if you have any suggestions or tests that I 
should run it through.

-Eric

(note that 5251 is the bcache_gc pid)

[131110.478867] NMI watchdog: BUG: soft lockup - CPU#2 stuck for 23s! [bcache_gc:5251]
[131110.479313] Modules linked in: dm_thin_pool dm_bio_prison 
dm_persistent_data dm_bufio sch_sfq nf_conntrack_ipv4 nf_defrag_ipv4 
xt_conntrack ipt_REJECT zram xt_c omment iptable_filter ip_tables drbd(OE) 
libcrc32c bnx2fc cnic uio fcoe libfcoe libfc bridge stp llc 8021q 
ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_ conntrack 
ip6table_filter ip6_tables ipv6 ext3 jbd vhost_net macvtap macvlan vhost 
tun kvm_intel kvm crc32c_intel bcache aesni_intel ablk_helper cryptd lrw 
gf128mul glue_helper aes_x86_64 iTCO_wdt iTCO_vendor_support serio_raw 
pcspkr i2c_i801 i2ccore lpc_ich mfd_core e1000e ptp pps_core bna sg 
sr_mod(E) cdrom(E) ext4(E) jbd2(E ) mbcache(E) usb_storage(E) sd_mod(E) 
crc_t10dif(E) crct10dif_common(E) video(E) ahci(E) libahci(E) bfa(E) 
scsi_transport_fc(E) arcmsr(E) dm_mirror(E) dm_region_has h(E) dm_log(E) 
dm_mod(E)

[131110.481865] CPU: 2 PID: 5251 Comm: bcache_gc Tainted: G           OEL 3.17.0-rc6 #1
[131110.482287] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
[131110.482714] task: ffff8807f4b08e20 ti: ffff8807e51f8000 task.ti: ffff8807e51f8000
[131110.483148] RIP: 0010:[<ffffffffa03a7a13>]  [<ffffffffa03a7a13>] bch_extent_bad+0xf3/0x1c0 [bcache]
[131110.483576] RSP: 0018:ffff8807e51fbb68  EFLAGS: 00000246
[131110.483794] RAX: 00000004eb93f476 RBX: ffff8807e51fbe08 RCX: 000000000000000a
[131110.484235] RDX: ffffc90017145000 RSI: 00000004eb93f476 RDI: ffff8807ec8c0000
[131110.484657] RBP: ffff8807e51fbb78 R08: 0000000000000001 R09: 0000000000000000
[131110.485096] R10: 000007ffffffffff R11: 000000000000000c R12: 000007ffffffffff
[131110.485524] R13: ffff8807e51fbb58 R14: ffffffffa03a78d5 R15: ffff8807e51fbb48
[131110.485969] FS:  0000000000000000(0000) GS:ffff88082fc80000(0000) knlGS:0000000000000000
[131110.486393] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[131110.486609] CR2: 00007f5ff8e6c000 CR3: 0000000001a14000 CR4: 00000000001427e0
[131110.487051] Stack:
[131110.487261]  ffff8807e51fbbc8 ffff8807eccf64d0 ffff8807e51fbb88 ffffffffa039fa5a
[131110.487694]  ffff8807e51fbbb8 ffffffffa039fa29 0000000000000dad ffff8807eccf64d0
[131110.488140]  ffff8807e51fbbc8 ffff8807e51fbcb8 ffff8807e51fbc38 ffffffffa039fdc0
[131110.488583] Call Trace:
[131110.488803]  [<ffffffffa039fa5a>] bch_ptr_bad+0xa/0x10 [bcache]
[131110.489037]  [<ffffffffa039fa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
[131110.489453]  [<ffffffffa039fdc0>] btree_gc_count_keys+0x50/0x70 [bcache]
[131110.489677]  [<ffffffffa03a60bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
[131110.489923]  [<ffffffffa03a1d2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
[131110.490146]  [<ffffffffa03a62e1>] bch_btree_gc_root+0x101/0x110 [bcache]
[131110.490371]  [<ffffffffa03a64db>] bch_btree_gc+0x1eb/0x460 [bcache]
[131110.490597]  [<ffffffff81096f60>] ? bit_waitqueue+0xa0/0xa0
[131110.490821]  [<ffffffffa03a6788>] bch_gc_thread+0x38/0x120 [bcache]
[131110.491062]  [<ffffffffa03a6750>] ? bch_btree_gc+0x460/0x460 [bcache]
[131110.491284]  [<ffffffff8107812e>] kthread+0xce/0xf0
[131110.491505]  [<ffffffff81078060>] ? kthread_freezable_should_stop+0x70/0x70
[131110.491732]  [<ffffffff815c52bc>] ret_from_fork+0x7c/0xb0
[131110.491970]  [<ffffffff81078060>] ? kthread_freezable_should_stop+0x70/0x70
[131110.492194] Code: 0f 1f 84 00 00 00 00 00 48 8b 74 c3 10 48 89 f0 48 c1 e8 33 25 ff 0f 00 00 48 8b 94 c7 40 0c 00 00 48 89 f0 48 8b 92 d8 0a 00 00 <48> c1 e8 08 4c 21 d0 48 d3 e8 48 8d 04 40 0f b6 54 82 06 40 28


Second backtrace:

[131146.469270] INFO: rcu_sched self-detected stall on CPU { 2}  (t=11613552 jiffies g=3817860 c=3817859 q=24121607)
[131146.469724] Task dump for CPU 2:
[131146.469943] bcache_gc       R  running task        0  5251      2 0x00000088
[131146.470168]  0000000000000003 ffff88082fc83d18 ffffffff8107ef97 0000000000000002
[131146.470625]  ffffffff81a4cc80 ffff88082fc83d38 ffffffff8107f03f ffff88082fc83d38
[131146.471058]  ffffffff81a4cc80 ffff88082fc83d68 ffffffff810b5b41 ffffffff81a4cc80
[131146.471507] Call Trace:
[131146.471718]  <IRQ>  [<ffffffff8107ef97>] sched_show_task+0xa7/0x110
[131146.471948]  [<ffffffff8107f03f>] dump_cpu_task+0x3f/0x50
[131146.472167]  [<ffffffff810b5b41>] rcu_dump_cpu_stacks+0x91/0xd0
[131146.472406]  [<ffffffff810b5c5e>] print_cpu_stall+0xde/0x140
[131146.472630]  [<ffffffff810b610e>] __rcu_pending+0x1fe/0x210
[131146.472855]  [<ffffffff810b73fd>] rcu_check_callbacks+0xdd/0x190
[131146.473077]  [<ffffffff810bad28>] update_process_times+0x48/0x80
[131146.473321]  [<ffffffff810cc1e9>] tick_sched_handle+0x39/0x80
[131146.473540]  [<ffffffff810cc434>] tick_sched_timer+0x54/0x90
[131146.473764]  [<ffffffff810bd384>] __run_hrtimer+0x74/0x1d0
[131146.473986]  [<ffffffff810cc3e0>] ? tick_nohz_handler+0xc0/0xc0
[131146.474208]  [<ffffffff810bd716>] hrtimer_interrupt+0x106/0x280
[131146.474453]  [<ffffffffa039fa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
[131146.474668]  [<ffffffff810387cb>] local_apic_timer_interrupt+0x3b/0x60
[131146.474884]  [<ffffffff815c7ec5>] smp_apic_timer_interrupt+0x45/0x60
[131146.475100]  [<ffffffffa039fa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
[131146.475332]  [<ffffffff815c61dd>] apic_timer_interrupt+0x6d/0x80
[131146.475544]  <EOI>  [<ffffffffa03a7951>] ? bch_extent_bad+0x31/0x1c0 [bcache]
[131146.475967]  [<ffffffffa03a794d>] ? bch_extent_bad+0x2d/0x1c0 [bcache]
[131146.476183]  [<ffffffffa039fa5a>] bch_ptr_bad+0xa/0x10 [bcache]
[131146.476418]  [<ffffffffa039fa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
[131146.476845]  [<ffffffffa039fdc0>] btree_gc_count_keys+0x50/0x70 [bcache]
[131146.477064]  [<ffffffffa03a60bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
[131146.477302]  [<ffffffffa03a1d2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
[131146.477521]  [<ffffffffa03a62e1>] bch_btree_gc_root+0x101/0x110 [bcache]
[131146.477747]  [<ffffffffa03a64db>] bch_btree_gc+0x1eb/0x460 [bcache]
[131146.477964]  [<ffffffff81096f60>] ? bit_waitqueue+0xa0/0xa0
[131146.478182]  [<ffffffffa03a6788>] bch_gc_thread+0x38/0x120 [bcache]
[131146.478416]  [<ffffffffa03a6750>] ? bch_btree_gc+0x460/0x460 [bcache]
[131146.478634]  [<ffffffff8107812e>] kthread+0xce/0xf0
[131146.478847]  [<ffffffff81078060>] ? kthread_freezable_should_stop+0x70/0x70
[131146.479066]  [<ffffffff815c52bc>] ret_from_fork+0x7c/0xb0
[131146.479302]  [<ffffffff81078060>] ? kthread_freezable_should_stop+0x70/0x70



--
Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298

Re: 3.17: bcache_gc: BUG: soft lockup - CPU#2 stuck for 22s!

[Eric Wheeler]

Hello all,

We are still getting bcache soft lockups from time to time.  These are our 
current stacktraces in bcache_gc and rcu_sched.  We recently re-formatted 
the bcache volumes so I believe it is unlikely to be data corruption 
(unless these bugs cause corruption).

I'm happy to do testing or provide more information if you need it. 
Hopefully these four backtraces can shed light on the issue:

CPU: 0 PID: 960 Comm: bcache_gc Tainted: G           OEL 3.17.0 #2
Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
task: ffff88080a37d220 ti: ffff880037a9c000 task.ti: ffff880037a9c000
RIP: 0010:[<ffffffffa0392ab6>]  [<ffffffffa0392ab6>] bch_extent_bad+0x196/0x1c0 [bcache]
RSP: 0018:ffff880037a9fb68  EFLAGS: 00000202
RAX: 0000000000000001 RBX: 000007ffffffffff RCX: 000000000000000a
RDX: 0000000000000000 RSI: 00000004ce41a924 RDI: ffff88080c100000
RBP: ffff880037a9fb78 R08: 0000000000000001 R09: 0000000000000001
R10: 000007ffffffffff R11: 0000000000000080 R12: 000007ffffffffff
R13: ffff880037a9fb58 R14: ffffffffa03928d5 R15: ffff880037a9fb48
FS:  0000000000000000(0000) GS:ffff88082fc00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007ff7b409aff0 CR3: 0000000001a14000 CR4: 00000000001407f0
Stack:
  ffff880037a9fbc8 ffff880809d4f4d0 ffff880037a9fb88 ffffffffa038aa5a
  ffff880037a9fbb8 ffffffffa038aa29 000000000000222f ffff880809d4f4d0
  ffff880037a9fbc8 ffff880037a9fcb8 ffff880037a9fc38 ffffffffa038adc0
Call Trace:
  [<ffffffffa038aa5a>] bch_ptr_bad+0xa/0x10 [bcache]
  [<ffffffffa038aa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
  [<ffffffff8107813e>] kthread+0xce/0xf0
  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
Code: 0f 84 a7 fe ff ff e8 cd d4 22 e1 b8 01 00 00 00 e9 9d fe ff ff 85 d2 0f 85 90 fe ff ff 0f 1f 84 00 00 00 00 00 41 ff c1 44 89 c8 <4c> 39 c0 0f 82 31 ff ff ff 31 c0 e9 77 fe ff ff e8 98 d4 22 e1


INFO: rcu_sched self-detected stall on CPU { 0}  (t=55337634 jiffies g=1978715 c=1978714 q=106641981)
Task dump for CPU 0:
bcache_gc       R  running task        0   960      2 0x00000008
  0000000000000001 ffff88082fc03d18 ffffffff8107efa7 0000000000000000
  ffffffff81a4cc80 ffff88082fc03d38 ffffffff8107f04f ffff88082fc03d38
  ffffffff81a4cc80 ffff88082fc03d68 ffffffff810b5b01 ffffffff81a4cc80
Call Trace:
  <IRQ>  [<ffffffff8107efa7>] sched_show_task+0xa7/0x110
  [<ffffffff8107f04f>] dump_cpu_task+0x3f/0x50
  [<ffffffff810b5b01>] rcu_dump_cpu_stacks+0x91/0xd0
  [<ffffffff810b5c1e>] print_cpu_stall+0xde/0x140
  [<ffffffff810b60ce>] __rcu_pending+0x1fe/0x210
  [<ffffffff810b73bd>] rcu_check_callbacks+0xdd/0x190
  [<ffffffff810bace8>] update_process_times+0x48/0x80
  [<ffffffff810cc1a9>] tick_sched_handle+0x39/0x80
  [<ffffffff810cc3f4>] tick_sched_timer+0x54/0x90
  [<ffffffff810bd344>] __run_hrtimer+0x74/0x1d0
  [<ffffffff810cc3a0>] ? tick_nohz_handler+0xc0/0xc0
  [<ffffffff810bd6d6>] hrtimer_interrupt+0x106/0x280
  [<ffffffffa038aa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
  [<ffffffff8103884b>] local_apic_timer_interrupt+0x3b/0x60
  [<ffffffff815c7d85>] smp_apic_timer_interrupt+0x45/0x60
  [<ffffffff815c609d>] apic_timer_interrupt+0x6d/0x80
  <EOI>  [<ffffffffa0392a26>] ? bch_extent_bad+0x106/0x1c0 [bcache]
  [<ffffffffa039294d>] ? bch_extent_bad+0x2d/0x1c0 [bcache]
  [<ffffffffa038aa5a>] bch_ptr_bad+0xa/0x10 [bcache]
  [<ffffffffa038aa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
  [<ffffffff8107813e>] kthread+0xce/0xf0
  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70


NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [bcache_gc:960]
Modules linked in: [...]
CPU: 0 PID: 960 Comm: bcache_gc Tainted: G           OEL 3.17.0 #2
Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
task: ffff88080a37d220 ti: ffff880037a9c000 task.ti: ffff880037a9c000
RIP: 0010:[<ffffffffa0391ed6>]  [<ffffffffa0391ed6>] __ptr_invalid+0x6/0xd0 [bcache]
RSP: 0018:ffff880037a9fab0  EFLAGS: 00000287
RAX: 0000000000000018 RBX: 000007ffffffffff RCX: 9000001003000001
RDX: 0000000000000000 RSI: ffff8807ea24a168 RDI: ffff88080c100000
RBP: ffff880037a9fab8 R08: ffff8807ea24a180 R09: 0000000000000001
R10: 000007ffffffffff R11: 0000000000000030 R12: ffffffffffffff10
R13: ffff880037a9fab8 R14: 0000000000000000 R15: ffff880037a9fe08
FS:  0000000000000000(0000) GS:ffff88082fc00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007ff7b409aff0 CR3: 0000000001a14000 CR4: 00000000001407f0
Stack:
  ffff880809d4f4d0 ffff880037a9fb48 ffffffffa03928d5 ffff880037a9fb58
  000007ffffffffff ffff880037a9fda8 ffff880037a9fe08 0000000000000080
  000007ffffffffff 0000000100000000 ffff880037a9fcb8 0000000000003795
Call Trace:
  [<ffffffffa03928d5>] __bch_extent_invalid+0xa5/0xd0 [bcache]
  [<ffffffffa0392912>] bch_extent_invalid+0x12/0x20 [bcache]
  [<ffffffffa039294d>] bch_extent_bad+0x2d/0x1c0 [bcache]
  [<ffffffffa038aa5a>] bch_ptr_bad+0xa/0x10 [bcache]
  [<ffffffffa038aa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
  [<ffffffff8107813e>] kthread+0xce/0xf0
  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
Code: 12 48 81 c4 88 00 00 00 5b 41 5c 41 5d 41 5e 41 5f c9 c3 e8 2d 8a cc e0 90 90 90 90 90 90 90 90 90 90 90 90 90 55 48 89 e5 41 54 <53> 0f 1f 44 00 00 4c 8b 1e 4d 89 d9 49 c1 e9 3c 41 83 e1 07 0f


CPU: 0 PID: 960 Comm: bcache_gc Tainted: G           OEL 3.17.0 #2
Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
task: ffff88080a37d220 ti: ffff880037a9c000 task.ti: ffff880037a9c000
RIP: 0010:[<ffffffffa038a711>]  [<ffffffffa038a711>] bch_btree_iter_next+0x21/0x300 [bcache]
RSP: 0018:ffff880037a9fb78  EFLAGS: 00000202
RAX: 9000000028000001 RBX: 000007ffffffffff RCX: 000000000000000a
RDX: ffffffffa038aa50 RSI: ffff880809d4f4d0 RDI: ffff880037a9fbc8
RBP: ffff880037a9fb88 R08: 0000000000000001 R09: 0000000000000001
R10: 000007ffffffffff R11: 000000000000007d R12: ffff880037a9fe08
R13: ffff880037a9fda8 R14: 000007ffffffffff R15: ffff880037a9fb58
FS:  0000000000000000(0000) GS:ffff88082fc00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007ff7b409aff0 CR3: 0000000001a14000 CR4: 00000000001407f0
Stack:
  ffff880037a9fbc8 ffff880809d4f4d0 ffff880037a9fbb8 ffffffffa038aa18
  00000000000007b6 ffff880809d4f4d0 ffff880037a9fbc8 ffff880037a9fcb8
  ffff880037a9fc38 ffffffffa038adc0 0000000000000004 0000000000000001
Call Trace:
  [<ffffffffa038aa18>] bch_btree_iter_next_filter+0x28/0x50 [bcache]
  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
  [<ffffffff8107813e>] kthread+0xce/0xf0
  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
Code: 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 54 53 0f 1f 44 00 00 45 31 e4 48 89 fb 48 83 7f 08 00 74 57 4c 8b 67 10 49 8b 04 24 <48> c1 e8 3c 83 e0 07 4d 8d 44 c4 10 48 8b 47 18 4c 89 47 10 49



--
Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298

On Sun, 28 Sep 2014, Eric Wheeler wrote:

> Hello Kent, Ross, all:
>
> We're getting bcache_gc backtraces and soft lockups; the system continues to 
> be responsive and eventually recovers.  We are running 3.17-rc6. (This 
> appears to be a continuation of the thread from 2014-09-15)
>
> Please see the following two backtraces.  The first shows up in 
> btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We will 
> test with -rc7 this week, though I didn't see any bcache commits in rc7.
>
> The server is quite busy:
>  dd in userspace from dm-thinp snapshots to another server
>  two DRBD verify's active backed by dm-thinp volumes
>  note that, dd fills up the buffers so this could be operating with few
>  pages free. (Though we have min-mem set to 256MB.)
>
> I see we are hitting functions like bch_ptr_bad() and bch_extent_bad(). Could 
> that indicate a cache corruption on our volume?
>
> I'm happy to test patches if you have any suggestions or tests that I should 
> run it through.
>
> -Eric
>
> (note that 5251 is the bcache_gc pid)
>
> [131110.478867] NMI watchdog: BUG: soft lockup - CPU#2 stuck for 23s! 
> [bcache_gc:5251]
> [131110.479313] Modules linked in: dm_thin_pool dm_bio_prison 
> dm_persistent_data dm_bufio sch_sfq nf_conntrack_ipv4 nf_defrag_ipv4 
> xt_conntrack ipt_REJECT zram xt_c omment iptable_filter ip_tables drbd(OE) 
> libcrc32c bnx2fc cnic uio fcoe libfcoe libfc bridge stp llc 8021q ip6t_REJECT 
> nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_ conntrack ip6table_filter 
> ip6_tables ipv6 ext3 jbd vhost_net macvtap macvlan vhost tun kvm_intel kvm 
> crc32c_intel bcache aesni_intel ablk_helper cryptd lrw gf128mul glue_helper 
> aes_x86_64 iTCO_wdt iTCO_vendor_support serio_raw pcspkr i2c_i801 i2ccore 
> lpc_ich mfd_core e1000e ptp pps_core bna sg sr_mod(E) cdrom(E) ext4(E) jbd2(E 
> ) mbcache(E) usb_storage(E) sd_mod(E) crc_t10dif(E) crct10dif_common(E) 
> video(E) ahci(E) libahci(E) bfa(E) scsi_transport_fc(E) arcmsr(E) 
> dm_mirror(E) dm_region_has h(E) dm_log(E) dm_mod(E)
>
> [131110.481865] CPU: 2 PID: 5251 Comm: bcache_gc Tainted: G           OEL 
> 3.17.0-rc6 #1
> [131110.482287] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 
> 01/09/2014
> [131110.482714] task: ffff8807f4b08e20 ti: ffff8807e51f8000 task.ti: 
> ffff8807e51f8000
> [131110.483148] RIP: 0010:[<ffffffffa03a7a13>]  [<ffffffffa03a7a13>] 
> bch_extent_bad+0xf3/0x1c0 [bcache]
> [131110.483576] RSP: 0018:ffff8807e51fbb68  EFLAGS: 00000246
> [131110.483794] RAX: 00000004eb93f476 RBX: ffff8807e51fbe08 RCX: 
> 000000000000000a
> [131110.484235] RDX: ffffc90017145000 RSI: 00000004eb93f476 RDI: 
> ffff8807ec8c0000
> [131110.484657] RBP: ffff8807e51fbb78 R08: 0000000000000001 R09: 
> 0000000000000000
> [131110.485096] R10: 000007ffffffffff R11: 000000000000000c R12: 
> 000007ffffffffff
> [131110.485524] R13: ffff8807e51fbb58 R14: ffffffffa03a78d5 R15: 
> ffff8807e51fbb48
> [131110.485969] FS:  0000000000000000(0000) GS:ffff88082fc80000(0000) 
> knlGS:0000000000000000
> [131110.486393] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [131110.486609] CR2: 00007f5ff8e6c000 CR3: 0000000001a14000 CR4: 
> 00000000001427e0
> [131110.487051] Stack:
> [131110.487261]  ffff8807e51fbbc8 ffff8807eccf64d0 ffff8807e51fbb88 
> ffffffffa039fa5a
> [131110.487694]  ffff8807e51fbbb8 ffffffffa039fa29 0000000000000dad 
> ffff8807eccf64d0
> [131110.488140]  ffff8807e51fbbc8 ffff8807e51fbcb8 ffff8807e51fbc38 
> ffffffffa039fdc0
> [131110.488583] Call Trace:
> [131110.488803]  [<ffffffffa039fa5a>] bch_ptr_bad+0xa/0x10 [bcache]
> [131110.489037]  [<ffffffffa039fa29>] bch_btree_iter_next_filter+0x39/0x50 
> [bcache]
> [131110.489453]  [<ffffffffa039fdc0>] btree_gc_count_keys+0x50/0x70 [bcache]
> [131110.489677]  [<ffffffffa03a60bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
> [131110.489923]  [<ffffffffa03a1d2c>] ? btree_gc_mark_node+0xdc/0x210 
> [bcache]
> [131110.490146]  [<ffffffffa03a62e1>] bch_btree_gc_root+0x101/0x110 [bcache]
> [131110.490371]  [<ffffffffa03a64db>] bch_btree_gc+0x1eb/0x460 [bcache]
> [131110.490597]  [<ffffffff81096f60>] ? bit_waitqueue+0xa0/0xa0
> [131110.490821]  [<ffffffffa03a6788>] bch_gc_thread+0x38/0x120 [bcache]
> [131110.491062]  [<ffffffffa03a6750>] ? bch_btree_gc+0x460/0x460 [bcache]
> [131110.491284]  [<ffffffff8107812e>] kthread+0xce/0xf0
> [131110.491505]  [<ffffffff81078060>] ? 
> kthread_freezable_should_stop+0x70/0x70
> [131110.491732]  [<ffffffff815c52bc>] ret_from_fork+0x7c/0xb0
> [131110.491970]  [<ffffffff81078060>] ? 
> kthread_freezable_should_stop+0x70/0x70
> [131110.492194] Code: 0f 1f 84 00 00 00 00 00 48 8b 74 c3 10 48 89 f0 48 c1 
> e8 33 25 ff 0f 00 00 48 8b 94 c7 40 0c 00 00 48 89 f0 48 8b 92 d8 0a 00 00 
> <48> c1 e8 08 4c 21 d0 48 d3 e8 48 8d 04 40 0f b6 54 82 06 40 28
>
>
> Second backtrace:
>
> [131146.469270] INFO: rcu_sched self-detected stall on CPU { 2}  (t=11613552 
> jiffies g=3817860 c=3817859 q=24121607)
> [131146.469724] Task dump for CPU 2:
> [131146.469943] bcache_gc       R  running task        0  5251      2 
> 0x00000088
> [131146.470168]  0000000000000003 ffff88082fc83d18 ffffffff8107ef97 
> 0000000000000002
> [131146.470625]  ffffffff81a4cc80 ffff88082fc83d38 ffffffff8107f03f 
> ffff88082fc83d38
> [131146.471058]  ffffffff81a4cc80 ffff88082fc83d68 ffffffff810b5b41 
> ffffffff81a4cc80
> [131146.471507] Call Trace:
> [131146.471718]  <IRQ>  [<ffffffff8107ef97>] sched_show_task+0xa7/0x110
> [131146.471948]  [<ffffffff8107f03f>] dump_cpu_task+0x3f/0x50
> [131146.472167]  [<ffffffff810b5b41>] rcu_dump_cpu_stacks+0x91/0xd0
> [131146.472406]  [<ffffffff810b5c5e>] print_cpu_stall+0xde/0x140
> [131146.472630]  [<ffffffff810b610e>] __rcu_pending+0x1fe/0x210
> [131146.472855]  [<ffffffff810b73fd>] rcu_check_callbacks+0xdd/0x190
> [131146.473077]  [<ffffffff810bad28>] update_process_times+0x48/0x80
> [131146.473321]  [<ffffffff810cc1e9>] tick_sched_handle+0x39/0x80
> [131146.473540]  [<ffffffff810cc434>] tick_sched_timer+0x54/0x90
> [131146.473764]  [<ffffffff810bd384>] __run_hrtimer+0x74/0x1d0
> [131146.473986]  [<ffffffff810cc3e0>] ? tick_nohz_handler+0xc0/0xc0
> [131146.474208]  [<ffffffff810bd716>] hrtimer_interrupt+0x106/0x280
> [131146.474453]  [<ffffffffa039fa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
> [131146.474668]  [<ffffffff810387cb>] local_apic_timer_interrupt+0x3b/0x60
> [131146.474884]  [<ffffffff815c7ec5>] smp_apic_timer_interrupt+0x45/0x60
> [131146.475100]  [<ffffffffa039fa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
> [131146.475332]  [<ffffffff815c61dd>] apic_timer_interrupt+0x6d/0x80
> [131146.475544]  <EOI>  [<ffffffffa03a7951>] ? bch_extent_bad+0x31/0x1c0 
> [bcache]
> [131146.475967]  [<ffffffffa03a794d>] ? bch_extent_bad+0x2d/0x1c0 [bcache]
> [131146.476183]  [<ffffffffa039fa5a>] bch_ptr_bad+0xa/0x10 [bcache]
> [131146.476418]  [<ffffffffa039fa29>] bch_btree_iter_next_filter+0x39/0x50 
> [bcache]
> [131146.476845]  [<ffffffffa039fdc0>] btree_gc_count_keys+0x50/0x70 [bcache]
> [131146.477064]  [<ffffffffa03a60bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
> [131146.477302]  [<ffffffffa03a1d2c>] ? btree_gc_mark_node+0xdc/0x210 
> [bcache]
> [131146.477521]  [<ffffffffa03a62e1>] bch_btree_gc_root+0x101/0x110 [bcache]
> [131146.477747]  [<ffffffffa03a64db>] bch_btree_gc+0x1eb/0x460 [bcache]
> [131146.477964]  [<ffffffff81096f60>] ? bit_waitqueue+0xa0/0xa0
> [131146.478182]  [<ffffffffa03a6788>] bch_gc_thread+0x38/0x120 [bcache]
> [131146.478416]  [<ffffffffa03a6750>] ? bch_btree_gc+0x460/0x460 [bcache]
> [131146.478634]  [<ffffffff8107812e>] kthread+0xce/0xf0
> [131146.478847]  [<ffffffff81078060>] ? 
> kthread_freezable_should_stop+0x70/0x70
> [131146.479066]  [<ffffffff815c52bc>] ret_from_fork+0x7c/0xb0
> [131146.479302]  [<ffffffff81078060>] ? 
> kthread_freezable_should_stop+0x70/0x70
>
>
>
> --
> Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
> 888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
> www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

Re: 3.17: bcache_gc: BUG: soft lockup - CPU#2 stuck for 22s!

[Zhu Yanhai]

Eric,
Is Cpu 0 busy at the moment you see the back trace? Could you please
check whether this patch helps?

http://thread.gmane.org/gmane.linux.kernel.bcache.devel/2713

Theoretically this livelock does exist all the way, however we can't
reproduce it on 3.17 kernel, or maybe it's just because the stress is
not big enough. Anyway it can be reproduced easily on RHEL6 kernel (we
have ported bcache back to the RHEL6 kernel). Dunno if it's caused by
the differences between the schedulers.

-zyh

2014-10-27 10:52 GMT+08:00 Eric Wheeler <bcache@lists.ewheeler.net>:
> Hello all,
>
> We are still getting bcache soft lockups from time to time.  These are our
> current stacktraces in bcache_gc and rcu_sched.  We recently re-formatted
> the bcache volumes so I believe it is unlikely to be data corruption (unless
> these bugs cause corruption).
>
> I'm happy to do testing or provide more information if you need it.
> Hopefully these four backtraces can shed light on the issue:
>
> CPU: 0 PID: 960 Comm: bcache_gc Tainted: G           OEL 3.17.0 #2
> Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
> task: ffff88080a37d220 ti: ffff880037a9c000 task.ti: ffff880037a9c000
> RIP: 0010:[<ffffffffa0392ab6>]  [<ffffffffa0392ab6>]
> bch_extent_bad+0x196/0x1c0 [bcache]
> RSP: 0018:ffff880037a9fb68  EFLAGS: 00000202
> RAX: 0000000000000001 RBX: 000007ffffffffff RCX: 000000000000000a
> RDX: 0000000000000000 RSI: 00000004ce41a924 RDI: ffff88080c100000
> RBP: ffff880037a9fb78 R08: 0000000000000001 R09: 0000000000000001
> R10: 000007ffffffffff R11: 0000000000000080 R12: 000007ffffffffff
> R13: ffff880037a9fb58 R14: ffffffffa03928d5 R15: ffff880037a9fb48
> FS:  0000000000000000(0000) GS:ffff88082fc00000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007ff7b409aff0 CR3: 0000000001a14000 CR4: 00000000001407f0
> Stack:
>  ffff880037a9fbc8 ffff880809d4f4d0 ffff880037a9fb88 ffffffffa038aa5a
>  ffff880037a9fbb8 ffffffffa038aa29 000000000000222f ffff880809d4f4d0
>  ffff880037a9fbc8 ffff880037a9fcb8 ffff880037a9fc38 ffffffffa038adc0
> Call Trace:
>  [<ffffffffa038aa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>  [<ffffffffa038aa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
>  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
>  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
>  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
>  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
>  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
>  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
>  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
>  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
>  [<ffffffff8107813e>] kthread+0xce/0xf0
>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
> Code: 0f 84 a7 fe ff ff e8 cd d4 22 e1 b8 01 00 00 00 e9 9d fe ff ff 85 d2
> 0f 85 90 fe ff ff 0f 1f 84 00 00 00 00 00 41 ff c1 44 89 c8 <4c> 39 c0 0f 82
> 31 ff ff ff 31 c0 e9 77 fe ff ff e8 98 d4 22 e1
>
>
> INFO: rcu_sched self-detected stall on CPU { 0}  (t=55337634 jiffies
> g=1978715 c=1978714 q=106641981)
> Task dump for CPU 0:
> bcache_gc       R  running task        0   960      2 0x00000008
>  0000000000000001 ffff88082fc03d18 ffffffff8107efa7 0000000000000000
>  ffffffff81a4cc80 ffff88082fc03d38 ffffffff8107f04f ffff88082fc03d38
>  ffffffff81a4cc80 ffff88082fc03d68 ffffffff810b5b01 ffffffff81a4cc80
> Call Trace:
>  <IRQ>  [<ffffffff8107efa7>] sched_show_task+0xa7/0x110
>  [<ffffffff8107f04f>] dump_cpu_task+0x3f/0x50
>  [<ffffffff810b5b01>] rcu_dump_cpu_stacks+0x91/0xd0
>  [<ffffffff810b5c1e>] print_cpu_stall+0xde/0x140
>  [<ffffffff810b60ce>] __rcu_pending+0x1fe/0x210
>  [<ffffffff810b73bd>] rcu_check_callbacks+0xdd/0x190
>  [<ffffffff810bace8>] update_process_times+0x48/0x80
>  [<ffffffff810cc1a9>] tick_sched_handle+0x39/0x80
>  [<ffffffff810cc3f4>] tick_sched_timer+0x54/0x90
>  [<ffffffff810bd344>] __run_hrtimer+0x74/0x1d0
>  [<ffffffff810cc3a0>] ? tick_nohz_handler+0xc0/0xc0
>  [<ffffffff810bd6d6>] hrtimer_interrupt+0x106/0x280
>  [<ffffffffa038aa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
>  [<ffffffff8103884b>] local_apic_timer_interrupt+0x3b/0x60
>  [<ffffffff815c7d85>] smp_apic_timer_interrupt+0x45/0x60
>  [<ffffffff815c609d>] apic_timer_interrupt+0x6d/0x80
>  <EOI>  [<ffffffffa0392a26>] ? bch_extent_bad+0x106/0x1c0 [bcache]
>  [<ffffffffa039294d>] ? bch_extent_bad+0x2d/0x1c0 [bcache]
>  [<ffffffffa038aa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>  [<ffffffffa038aa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
>  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
>  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
>  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
>  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
>  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
>  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
>  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
>  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
>  [<ffffffff8107813e>] kthread+0xce/0xf0
>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>
>
> NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [bcache_gc:960]
> Modules linked in: [...]
> CPU: 0 PID: 960 Comm: bcache_gc Tainted: G           OEL 3.17.0 #2
> Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
> task: ffff88080a37d220 ti: ffff880037a9c000 task.ti: ffff880037a9c000
> RIP: 0010:[<ffffffffa0391ed6>]  [<ffffffffa0391ed6>] __ptr_invalid+0x6/0xd0
> [bcache]
> RSP: 0018:ffff880037a9fab0  EFLAGS: 00000287
> RAX: 0000000000000018 RBX: 000007ffffffffff RCX: 9000001003000001
> RDX: 0000000000000000 RSI: ffff8807ea24a168 RDI: ffff88080c100000
> RBP: ffff880037a9fab8 R08: ffff8807ea24a180 R09: 0000000000000001
> R10: 000007ffffffffff R11: 0000000000000030 R12: ffffffffffffff10
> R13: ffff880037a9fab8 R14: 0000000000000000 R15: ffff880037a9fe08
> FS:  0000000000000000(0000) GS:ffff88082fc00000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007ff7b409aff0 CR3: 0000000001a14000 CR4: 00000000001407f0
> Stack:
>  ffff880809d4f4d0 ffff880037a9fb48 ffffffffa03928d5 ffff880037a9fb58
>  000007ffffffffff ffff880037a9fda8 ffff880037a9fe08 0000000000000080
>  000007ffffffffff 0000000100000000 ffff880037a9fcb8 0000000000003795
> Call Trace:
>  [<ffffffffa03928d5>] __bch_extent_invalid+0xa5/0xd0 [bcache]
>  [<ffffffffa0392912>] bch_extent_invalid+0x12/0x20 [bcache]
>  [<ffffffffa039294d>] bch_extent_bad+0x2d/0x1c0 [bcache]
>  [<ffffffffa038aa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>  [<ffffffffa038aa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
>  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
>  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
>  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
>  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
>  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
>  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
>  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
>  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
>  [<ffffffff8107813e>] kthread+0xce/0xf0
>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
> Code: 12 48 81 c4 88 00 00 00 5b 41 5c 41 5d 41 5e 41 5f c9 c3 e8 2d 8a cc
> e0 90 90 90 90 90 90 90 90 90 90 90 90 90 55 48 89 e5 41 54 <53> 0f 1f 44 00
> 00 4c 8b 1e 4d 89 d9 49 c1 e9 3c 41 83 e1 07 0f
>
>
> CPU: 0 PID: 960 Comm: bcache_gc Tainted: G           OEL 3.17.0 #2
> Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
> task: ffff88080a37d220 ti: ffff880037a9c000 task.ti: ffff880037a9c000
> RIP: 0010:[<ffffffffa038a711>]  [<ffffffffa038a711>]
> bch_btree_iter_next+0x21/0x300 [bcache]
> RSP: 0018:ffff880037a9fb78  EFLAGS: 00000202
> RAX: 9000000028000001 RBX: 000007ffffffffff RCX: 000000000000000a
> RDX: ffffffffa038aa50 RSI: ffff880809d4f4d0 RDI: ffff880037a9fbc8
> RBP: ffff880037a9fb88 R08: 0000000000000001 R09: 0000000000000001
> R10: 000007ffffffffff R11: 000000000000007d R12: ffff880037a9fe08
> R13: ffff880037a9fda8 R14: 000007ffffffffff R15: ffff880037a9fb58
> FS:  0000000000000000(0000) GS:ffff88082fc00000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007ff7b409aff0 CR3: 0000000001a14000 CR4: 00000000001407f0
> Stack:
>  ffff880037a9fbc8 ffff880809d4f4d0 ffff880037a9fbb8 ffffffffa038aa18
>  00000000000007b6 ffff880809d4f4d0 ffff880037a9fbc8 ffff880037a9fcb8
>  ffff880037a9fc38 ffffffffa038adc0 0000000000000004 0000000000000001
> Call Trace:
>  [<ffffffffa038aa18>] bch_btree_iter_next_filter+0x28/0x50 [bcache]
>  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
>  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
>  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
>  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
>  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
>  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
>  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
>  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
>  [<ffffffff8107813e>] kthread+0xce/0xf0
>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
> Code: 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 54 53 0f 1f 44 00 00 45
> 31 e4 48 89 fb 48 83 7f 08 00 74 57 4c 8b 67 10 49 8b 04 24 <48> c1 e8 3c 83
> e0 07 4d 8d 44 c4 10 48 8b 47 18 4c 89 47 10 49
>
>
>
> --
> Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
> 888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
> www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298
>
> On Sun, 28 Sep 2014, Eric Wheeler wrote:
>
>> Hello Kent, Ross, all:
>>
>> We're getting bcache_gc backtraces and soft lockups; the system continues
>> to be responsive and eventually recovers.  We are running 3.17-rc6. (This
>> appears to be a continuation of the thread from 2014-09-15)
>>
>> Please see the following two backtraces.  The first shows up in
>> btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We will
>> test with -rc7 this week, though I didn't see any bcache commits in rc7.
>>
>> The server is quite busy:
>>  dd in userspace from dm-thinp snapshots to another server
>>  two DRBD verify's active backed by dm-thinp volumes
>>  note that, dd fills up the buffers so this could be operating with few
>>  pages free. (Though we have min-mem set to 256MB.)
>>
>> I see we are hitting functions like bch_ptr_bad() and bch_extent_bad().
>> Could that indicate a cache corruption on our volume?
>>
>> I'm happy to test patches if you have any suggestions or tests that I
>> should run it through.
>>
>> -Eric
>>
>> (note that 5251 is the bcache_gc pid)
>>
>> [131110.478867] NMI watchdog: BUG: soft lockup - CPU#2 stuck for 23s!
>> [bcache_gc:5251]
>> [131110.479313] Modules linked in: dm_thin_pool dm_bio_prison
>> dm_persistent_data dm_bufio sch_sfq nf_conntrack_ipv4 nf_defrag_ipv4
>> xt_conntrack ipt_REJECT zram xt_c omment iptable_filter ip_tables drbd(OE)
>> libcrc32c bnx2fc cnic uio fcoe libfcoe libfc bridge stp llc 8021q
>> ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_ conntrack
>> ip6table_filter ip6_tables ipv6 ext3 jbd vhost_net macvtap macvlan vhost tun
>> kvm_intel kvm crc32c_intel bcache aesni_intel ablk_helper cryptd lrw
>> gf128mul glue_helper aes_x86_64 iTCO_wdt iTCO_vendor_support serio_raw
>> pcspkr i2c_i801 i2ccore lpc_ich mfd_core e1000e ptp pps_core bna sg
>> sr_mod(E) cdrom(E) ext4(E) jbd2(E ) mbcache(E) usb_storage(E) sd_mod(E)
>> crc_t10dif(E) crct10dif_common(E) video(E) ahci(E) libahci(E) bfa(E)
>> scsi_transport_fc(E) arcmsr(E) dm_mirror(E) dm_region_has h(E) dm_log(E)
>> dm_mod(E)
>>
>> [131110.481865] CPU: 2 PID: 5251 Comm: bcache_gc Tainted: G           OEL
>> 3.17.0-rc6 #1
>> [131110.482287] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS
>> 2.10 01/09/2014
>> [131110.482714] task: ffff8807f4b08e20 ti: ffff8807e51f8000 task.ti:
>> ffff8807e51f8000
>> [131110.483148] RIP: 0010:[<ffffffffa03a7a13>]  [<ffffffffa03a7a13>]
>> bch_extent_bad+0xf3/0x1c0 [bcache]
>> [131110.483576] RSP: 0018:ffff8807e51fbb68  EFLAGS: 00000246
>> [131110.483794] RAX: 00000004eb93f476 RBX: ffff8807e51fbe08 RCX:
>> 000000000000000a
>> [131110.484235] RDX: ffffc90017145000 RSI: 00000004eb93f476 RDI:
>> ffff8807ec8c0000
>> [131110.484657] RBP: ffff8807e51fbb78 R08: 0000000000000001 R09:
>> 0000000000000000
>> [131110.485096] R10: 000007ffffffffff R11: 000000000000000c R12:
>> 000007ffffffffff
>> [131110.485524] R13: ffff8807e51fbb58 R14: ffffffffa03a78d5 R15:
>> ffff8807e51fbb48
>> [131110.485969] FS:  0000000000000000(0000) GS:ffff88082fc80000(0000)
>> knlGS:0000000000000000
>> [131110.486393] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [131110.486609] CR2: 00007f5ff8e6c000 CR3: 0000000001a14000 CR4:
>> 00000000001427e0
>> [131110.487051] Stack:
>> [131110.487261]  ffff8807e51fbbc8 ffff8807eccf64d0 ffff8807e51fbb88
>> ffffffffa039fa5a
>> [131110.487694]  ffff8807e51fbbb8 ffffffffa039fa29 0000000000000dad
>> ffff8807eccf64d0
>> [131110.488140]  ffff8807e51fbbc8 ffff8807e51fbcb8 ffff8807e51fbc38
>> ffffffffa039fdc0
>> [131110.488583] Call Trace:
>> [131110.488803]  [<ffffffffa039fa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>> [131110.489037]  [<ffffffffa039fa29>] bch_btree_iter_next_filter+0x39/0x50
>> [bcache]
>> [131110.489453]  [<ffffffffa039fdc0>] btree_gc_count_keys+0x50/0x70
>> [bcache]
>> [131110.489677]  [<ffffffffa03a60bf>] btree_gc_recurse+0x1bf/0x2e0
>> [bcache]
>> [131110.489923]  [<ffffffffa03a1d2c>] ? btree_gc_mark_node+0xdc/0x210
>> [bcache]
>> [131110.490146]  [<ffffffffa03a62e1>] bch_btree_gc_root+0x101/0x110
>> [bcache]
>> [131110.490371]  [<ffffffffa03a64db>] bch_btree_gc+0x1eb/0x460 [bcache]
>> [131110.490597]  [<ffffffff81096f60>] ? bit_waitqueue+0xa0/0xa0
>> [131110.490821]  [<ffffffffa03a6788>] bch_gc_thread+0x38/0x120 [bcache]
>> [131110.491062]  [<ffffffffa03a6750>] ? bch_btree_gc+0x460/0x460 [bcache]
>> [131110.491284]  [<ffffffff8107812e>] kthread+0xce/0xf0
>> [131110.491505]  [<ffffffff81078060>] ?
>> kthread_freezable_should_stop+0x70/0x70
>> [131110.491732]  [<ffffffff815c52bc>] ret_from_fork+0x7c/0xb0
>> [131110.491970]  [<ffffffff81078060>] ?
>> kthread_freezable_should_stop+0x70/0x70
>> [131110.492194] Code: 0f 1f 84 00 00 00 00 00 48 8b 74 c3 10 48 89 f0 48
>> c1 e8 33 25 ff 0f 00 00 48 8b 94 c7 40 0c 00 00 48 89 f0 48 8b 92 d8 0a 00
>> 00 <48> c1 e8 08 4c 21 d0 48 d3 e8 48 8d 04 40 0f b6 54 82 06 40 28
>>
>>
>> Second backtrace:
>>
>> [131146.469270] INFO: rcu_sched self-detected stall on CPU { 2}
>> (t=11613552 jiffies g=3817860 c=3817859 q=24121607)
>> [131146.469724] Task dump for CPU 2:
>> [131146.469943] bcache_gc       R  running task        0  5251      2
>> 0x00000088
>> [131146.470168]  0000000000000003 ffff88082fc83d18 ffffffff8107ef97
>> 0000000000000002
>> [131146.470625]  ffffffff81a4cc80 ffff88082fc83d38 ffffffff8107f03f
>> ffff88082fc83d38
>> [131146.471058]  ffffffff81a4cc80 ffff88082fc83d68 ffffffff810b5b41
>> ffffffff81a4cc80
>> [131146.471507] Call Trace:
>> [131146.471718]  <IRQ>  [<ffffffff8107ef97>] sched_show_task+0xa7/0x110
>> [131146.471948]  [<ffffffff8107f03f>] dump_cpu_task+0x3f/0x50
>> [131146.472167]  [<ffffffff810b5b41>] rcu_dump_cpu_stacks+0x91/0xd0
>> [131146.472406]  [<ffffffff810b5c5e>] print_cpu_stall+0xde/0x140
>> [131146.472630]  [<ffffffff810b610e>] __rcu_pending+0x1fe/0x210
>> [131146.472855]  [<ffffffff810b73fd>] rcu_check_callbacks+0xdd/0x190
>> [131146.473077]  [<ffffffff810bad28>] update_process_times+0x48/0x80
>> [131146.473321]  [<ffffffff810cc1e9>] tick_sched_handle+0x39/0x80
>> [131146.473540]  [<ffffffff810cc434>] tick_sched_timer+0x54/0x90
>> [131146.473764]  [<ffffffff810bd384>] __run_hrtimer+0x74/0x1d0
>> [131146.473986]  [<ffffffff810cc3e0>] ? tick_nohz_handler+0xc0/0xc0
>> [131146.474208]  [<ffffffff810bd716>] hrtimer_interrupt+0x106/0x280
>> [131146.474453]  [<ffffffffa039fa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
>> [131146.474668]  [<ffffffff810387cb>] local_apic_timer_interrupt+0x3b/0x60
>> [131146.474884]  [<ffffffff815c7ec5>] smp_apic_timer_interrupt+0x45/0x60
>> [131146.475100]  [<ffffffffa039fa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
>> [131146.475332]  [<ffffffff815c61dd>] apic_timer_interrupt+0x6d/0x80
>> [131146.475544]  <EOI>  [<ffffffffa03a7951>] ? bch_extent_bad+0x31/0x1c0
>> [bcache]
>> [131146.475967]  [<ffffffffa03a794d>] ? bch_extent_bad+0x2d/0x1c0 [bcache]
>> [131146.476183]  [<ffffffffa039fa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>> [131146.476418]  [<ffffffffa039fa29>] bch_btree_iter_next_filter+0x39/0x50
>> [bcache]
>> [131146.476845]  [<ffffffffa039fdc0>] btree_gc_count_keys+0x50/0x70
>> [bcache]
>> [131146.477064]  [<ffffffffa03a60bf>] btree_gc_recurse+0x1bf/0x2e0
>> [bcache]
>> [131146.477302]  [<ffffffffa03a1d2c>] ? btree_gc_mark_node+0xdc/0x210
>> [bcache]
>> [131146.477521]  [<ffffffffa03a62e1>] bch_btree_gc_root+0x101/0x110
>> [bcache]
>> [131146.477747]  [<ffffffffa03a64db>] bch_btree_gc+0x1eb/0x460 [bcache]
>> [131146.477964]  [<ffffffff81096f60>] ? bit_waitqueue+0xa0/0xa0
>> [131146.478182]  [<ffffffffa03a6788>] bch_gc_thread+0x38/0x120 [bcache]
>> [131146.478416]  [<ffffffffa03a6750>] ? bch_btree_gc+0x460/0x460 [bcache]
>> [131146.478634]  [<ffffffff8107812e>] kthread+0xce/0xf0
>> [131146.478847]  [<ffffffff81078060>] ?
>> kthread_freezable_should_stop+0x70/0x70
>> [131146.479066]  [<ffffffff815c52bc>] ret_from_fork+0x7c/0xb0
>> [131146.479302]  [<ffffffff81078060>] ?
>> kthread_freezable_should_stop+0x70/0x70
>>
>>
>>
>> --
>> Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
>> 888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
>> www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re[2]: 3.17: bcache_gc: BUG: soft lockup - CPU#2 stuck for 22s!

[Pavel Goran]

Hello Zhu,

Friday, October 31, 2014, 3:20:32 PM, you wrote:

> Theoretically this livelock does exist all the way, however we can't
> reproduce it on 3.17 kernel, or maybe it's just because the stress is
> not big enough. Anyway it can be reproduced easily on RHEL6 kernel (we
> have ported bcache back to the RHEL6 kernel). Dunno if it's caused by
> the differences between the schedulers.

My  experience  shows that scheduler can be a factor here. I regularly had the
lockup  issue  while  running  a kernel with BFS scheduler (pf-kernel). Then I
switched  to  CFS  and lockups disappeared. (Now I'm running 3.17 with BFS and
with the October 18 patch from the mailing list, no issues as of yet.)

Pavel Goran
  

Re: 3.17: bcache_gc: BUG: soft lockup - CPU#2 stuck for 22s!

[Eric Wheeler]

On Fri, 31 Oct 2014, Zhu Yanhai wrote:> Eric,
> Is Cpu 0 busy at the moment you see the back trace?

I'm not sure, how would I verify that?  Does dmesg show that somehow?

> Could you please check whether this patch helps?
> http://thread.gmane.org/gmane.linux.kernel.bcache.devel/2713

Building it into 3.17.2 right now.  This is a very intermittent problem, 
so I don't have a 100% testcase to flag it down.  If it comes up again 
I'll reply to this thread---but hopefully the patch fixes it and finds its 
way upstream.

We're using CFQ now though we had deadline before and I think the problem 
showed up more frequently with deadline (but that is certainly 
subjective).

-Eric

> Theoretically this livelock does exist all the way, however we can't
> reproduce it on 3.17 kernel, or maybe it's just because the stress is
> not big enough. Anyway it can be reproduced easily on RHEL6 kernel (we
> have ported bcache back to the RHEL6 kernel). Dunno if it's caused by
> the differences between the schedulers.
>
> -zyh
>
> 2014-10-27 10:52 GMT+08:00 Eric Wheeler <bcache@lists.ewheeler.net>:
>> Hello all,
>>
>> We are still getting bcache soft lockups from time to time.  These are our
>> current stacktraces in bcache_gc and rcu_sched.  We recently re-formatted
>> the bcache volumes so I believe it is unlikely to be data corruption (unless
>> these bugs cause corruption).
>>
>> I'm happy to do testing or provide more information if you need it.
>> Hopefully these four backtraces can shed light on the issue:
>>
>> CPU: 0 PID: 960 Comm: bcache_gc Tainted: G           OEL 3.17.0 #2
>> Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
>> task: ffff88080a37d220 ti: ffff880037a9c000 task.ti: ffff880037a9c000
>> RIP: 0010:[<ffffffffa0392ab6>]  [<ffffffffa0392ab6>]
>> bch_extent_bad+0x196/0x1c0 [bcache]
>> RSP: 0018:ffff880037a9fb68  EFLAGS: 00000202
>> RAX: 0000000000000001 RBX: 000007ffffffffff RCX: 000000000000000a
>> RDX: 0000000000000000 RSI: 00000004ce41a924 RDI: ffff88080c100000
>> RBP: ffff880037a9fb78 R08: 0000000000000001 R09: 0000000000000001
>> R10: 000007ffffffffff R11: 0000000000000080 R12: 000007ffffffffff
>> R13: ffff880037a9fb58 R14: ffffffffa03928d5 R15: ffff880037a9fb48
>> FS:  0000000000000000(0000) GS:ffff88082fc00000(0000) knlGS:0000000000000000
>> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> CR2: 00007ff7b409aff0 CR3: 0000000001a14000 CR4: 00000000001407f0
>> Stack:
>>  ffff880037a9fbc8 ffff880809d4f4d0 ffff880037a9fb88 ffffffffa038aa5a
>>  ffff880037a9fbb8 ffffffffa038aa29 000000000000222f ffff880809d4f4d0
>>  ffff880037a9fbc8 ffff880037a9fcb8 ffff880037a9fc38 ffffffffa038adc0
>> Call Trace:
>>  [<ffffffffa038aa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>>  [<ffffffffa038aa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
>>  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
>>  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
>>  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
>>  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
>>  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
>>  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
>>  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
>>  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
>>  [<ffffffff8107813e>] kthread+0xce/0xf0
>>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>>  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
>>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>> Code: 0f 84 a7 fe ff ff e8 cd d4 22 e1 b8 01 00 00 00 e9 9d fe ff ff 85 d2
>> 0f 85 90 fe ff ff 0f 1f 84 00 00 00 00 00 41 ff c1 44 89 c8 <4c> 39 c0 0f 82
>> 31 ff ff ff 31 c0 e9 77 fe ff ff e8 98 d4 22 e1
>>
>>
>> INFO: rcu_sched self-detected stall on CPU { 0}  (t=55337634 jiffies
>> g=1978715 c=1978714 q=106641981)
>> Task dump for CPU 0:
>> bcache_gc       R  running task        0   960      2 0x00000008
>>  0000000000000001 ffff88082fc03d18 ffffffff8107efa7 0000000000000000
>>  ffffffff81a4cc80 ffff88082fc03d38 ffffffff8107f04f ffff88082fc03d38
>>  ffffffff81a4cc80 ffff88082fc03d68 ffffffff810b5b01 ffffffff81a4cc80
>> Call Trace:
>>  <IRQ>  [<ffffffff8107efa7>] sched_show_task+0xa7/0x110
>>  [<ffffffff8107f04f>] dump_cpu_task+0x3f/0x50
>>  [<ffffffff810b5b01>] rcu_dump_cpu_stacks+0x91/0xd0
>>  [<ffffffff810b5c1e>] print_cpu_stall+0xde/0x140
>>  [<ffffffff810b60ce>] __rcu_pending+0x1fe/0x210
>>  [<ffffffff810b73bd>] rcu_check_callbacks+0xdd/0x190
>>  [<ffffffff810bace8>] update_process_times+0x48/0x80
>>  [<ffffffff810cc1a9>] tick_sched_handle+0x39/0x80
>>  [<ffffffff810cc3f4>] tick_sched_timer+0x54/0x90
>>  [<ffffffff810bd344>] __run_hrtimer+0x74/0x1d0
>>  [<ffffffff810cc3a0>] ? tick_nohz_handler+0xc0/0xc0
>>  [<ffffffff810bd6d6>] hrtimer_interrupt+0x106/0x280
>>  [<ffffffffa038aa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
>>  [<ffffffff8103884b>] local_apic_timer_interrupt+0x3b/0x60
>>  [<ffffffff815c7d85>] smp_apic_timer_interrupt+0x45/0x60
>>  [<ffffffff815c609d>] apic_timer_interrupt+0x6d/0x80
>>  <EOI>  [<ffffffffa0392a26>] ? bch_extent_bad+0x106/0x1c0 [bcache]
>>  [<ffffffffa039294d>] ? bch_extent_bad+0x2d/0x1c0 [bcache]
>>  [<ffffffffa038aa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>>  [<ffffffffa038aa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
>>  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
>>  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
>>  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
>>  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
>>  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
>>  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
>>  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
>>  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
>>  [<ffffffff8107813e>] kthread+0xce/0xf0
>>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>>  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
>>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>>
>>
>> NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [bcache_gc:960]
>> Modules linked in: [...]
>> CPU: 0 PID: 960 Comm: bcache_gc Tainted: G           OEL 3.17.0 #2
>> Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
>> task: ffff88080a37d220 ti: ffff880037a9c000 task.ti: ffff880037a9c000
>> RIP: 0010:[<ffffffffa0391ed6>]  [<ffffffffa0391ed6>] __ptr_invalid+0x6/0xd0
>> [bcache]
>> RSP: 0018:ffff880037a9fab0  EFLAGS: 00000287
>> RAX: 0000000000000018 RBX: 000007ffffffffff RCX: 9000001003000001
>> RDX: 0000000000000000 RSI: ffff8807ea24a168 RDI: ffff88080c100000
>> RBP: ffff880037a9fab8 R08: ffff8807ea24a180 R09: 0000000000000001
>> R10: 000007ffffffffff R11: 0000000000000030 R12: ffffffffffffff10
>> R13: ffff880037a9fab8 R14: 0000000000000000 R15: ffff880037a9fe08
>> FS:  0000000000000000(0000) GS:ffff88082fc00000(0000) knlGS:0000000000000000
>> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> CR2: 00007ff7b409aff0 CR3: 0000000001a14000 CR4: 00000000001407f0
>> Stack:
>>  ffff880809d4f4d0 ffff880037a9fb48 ffffffffa03928d5 ffff880037a9fb58
>>  000007ffffffffff ffff880037a9fda8 ffff880037a9fe08 0000000000000080
>>  000007ffffffffff 0000000100000000 ffff880037a9fcb8 0000000000003795
>> Call Trace:
>>  [<ffffffffa03928d5>] __bch_extent_invalid+0xa5/0xd0 [bcache]
>>  [<ffffffffa0392912>] bch_extent_invalid+0x12/0x20 [bcache]
>>  [<ffffffffa039294d>] bch_extent_bad+0x2d/0x1c0 [bcache]
>>  [<ffffffffa038aa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>>  [<ffffffffa038aa29>] bch_btree_iter_next_filter+0x39/0x50 [bcache]
>>  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
>>  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
>>  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
>>  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
>>  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
>>  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
>>  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
>>  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
>>  [<ffffffff8107813e>] kthread+0xce/0xf0
>>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>>  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
>>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>> Code: 12 48 81 c4 88 00 00 00 5b 41 5c 41 5d 41 5e 41 5f c9 c3 e8 2d 8a cc
>> e0 90 90 90 90 90 90 90 90 90 90 90 90 90 55 48 89 e5 41 54 <53> 0f 1f 44 00
>> 00 4c 8b 1e 4d 89 d9 49 c1 e9 3c 41 83 e1 07 0f
>>
>>
>> CPU: 0 PID: 960 Comm: bcache_gc Tainted: G           OEL 3.17.0 #2
>> Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.10 01/09/2014
>> task: ffff88080a37d220 ti: ffff880037a9c000 task.ti: ffff880037a9c000
>> RIP: 0010:[<ffffffffa038a711>]  [<ffffffffa038a711>]
>> bch_btree_iter_next+0x21/0x300 [bcache]
>> RSP: 0018:ffff880037a9fb78  EFLAGS: 00000202
>> RAX: 9000000028000001 RBX: 000007ffffffffff RCX: 000000000000000a
>> RDX: ffffffffa038aa50 RSI: ffff880809d4f4d0 RDI: ffff880037a9fbc8
>> RBP: ffff880037a9fb88 R08: 0000000000000001 R09: 0000000000000001
>> R10: 000007ffffffffff R11: 000000000000007d R12: ffff880037a9fe08
>> R13: ffff880037a9fda8 R14: 000007ffffffffff R15: ffff880037a9fb58
>> FS:  0000000000000000(0000) GS:ffff88082fc00000(0000) knlGS:0000000000000000
>> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> CR2: 00007ff7b409aff0 CR3: 0000000001a14000 CR4: 00000000001407f0
>> Stack:
>>  ffff880037a9fbc8 ffff880809d4f4d0 ffff880037a9fbb8 ffffffffa038aa18
>>  00000000000007b6 ffff880809d4f4d0 ffff880037a9fbc8 ffff880037a9fcb8
>>  ffff880037a9fc38 ffffffffa038adc0 0000000000000004 0000000000000001
>> Call Trace:
>>  [<ffffffffa038aa18>] bch_btree_iter_next_filter+0x28/0x50 [bcache]
>>  [<ffffffffa038adc0>] btree_gc_count_keys+0x50/0x70 [bcache]
>>  [<ffffffffa03910bf>] btree_gc_recurse+0x1bf/0x2e0 [bcache]
>>  [<ffffffffa038cd2c>] ? btree_gc_mark_node+0xdc/0x210 [bcache]
>>  [<ffffffffa03912e1>] bch_btree_gc_root+0x101/0x110 [bcache]
>>  [<ffffffffa03914db>] bch_btree_gc+0x1eb/0x460 [bcache]
>>  [<ffffffff81096f70>] ? bit_waitqueue+0xa0/0xa0
>>  [<ffffffffa0391788>] bch_gc_thread+0x38/0x120 [bcache]
>>  [<ffffffffa0391750>] ? bch_btree_gc+0x460/0x460 [bcache]
>>  [<ffffffff8107813e>] kthread+0xce/0xf0
>>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>>  [<ffffffff815c517c>] ret_from_fork+0x7c/0xb0
>>  [<ffffffff81078070>] ? kthread_freezable_should_stop+0x70/0x70
>> Code: 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 54 53 0f 1f 44 00 00 45
>> 31 e4 48 89 fb 48 83 7f 08 00 74 57 4c 8b 67 10 49 8b 04 24 <48> c1 e8 3c 83
>> e0 07 4d 8d 44 c4 10 48 8b 47 18 4c 89 47 10 49
>>
>>
>>
>> --
>> Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
>> 888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
>> www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298
>>
>> On Sun, 28 Sep 2014, Eric Wheeler wrote:
>>
>>> Hello Kent, Ross, all:
>>>
>>> We're getting bcache_gc backtraces and soft lockups; the system continues
>>> to be responsive and eventually recovers.  We are running 3.17-rc6. (This
>>> appears to be a continuation of the thread from 2014-09-15)
>>>
>>> Please see the following two backtraces.  The first shows up in
>>> btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We will
>>> test with -rc7 this week, though I didn't see any bcache commits in rc7.
>>>
>>> The server is quite busy:
>>>  dd in userspace from dm-thinp snapshots to another server
>>>  two DRBD verify's active backed by dm-thinp volumes
>>>  note that, dd fills up the buffers so this could be operating with few
>>>  pages free. (Though we have min-mem set to 256MB.)
>>>
>>> I see we are hitting functions like bch_ptr_bad() and bch_extent_bad().
>>> Could that indicate a cache corruption on our volume?
>>>
>>> I'm happy to test patches if you have any suggestions or tests that I
>>> should run it through.
>>>
>>> -Eric
>>>
>>> (note that 5251 is the bcache_gc pid)
>>>
>>> [131110.478867] NMI watchdog: BUG: soft lockup - CPU#2 stuck for 23s!
>>> [bcache_gc:5251]
>>> [131110.479313] Modules linked in: dm_thin_pool dm_bio_prison
>>> dm_persistent_data dm_bufio sch_sfq nf_conntrack_ipv4 nf_defrag_ipv4
>>> xt_conntrack ipt_REJECT zram xt_c omment iptable_filter ip_tables drbd(OE)
>>> libcrc32c bnx2fc cnic uio fcoe libfcoe libfc bridge stp llc 8021q
>>> ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_ conntrack
>>> ip6table_filter ip6_tables ipv6 ext3 jbd vhost_net macvtap macvlan vhost tun
>>> kvm_intel kvm crc32c_intel bcache aesni_intel ablk_helper cryptd lrw
>>> gf128mul glue_helper aes_x86_64 iTCO_wdt iTCO_vendor_support serio_raw
>>> pcspkr i2c_i801 i2ccore lpc_ich mfd_core e1000e ptp pps_core bna sg
>>> sr_mod(E) cdrom(E) ext4(E) jbd2(E ) mbcache(E) usb_storage(E) sd_mod(E)
>>> crc_t10dif(E) crct10dif_common(E) video(E) ahci(E) libahci(E) bfa(E)
>>> scsi_transport_fc(E) arcmsr(E) dm_mirror(E) dm_region_has h(E) dm_log(E)
>>> dm_mod(E)
>>>
>>> [131110.481865] CPU: 2 PID: 5251 Comm: bcache_gc Tainted: G           OEL
>>> 3.17.0-rc6 #1
>>> [131110.482287] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS
>>> 2.10 01/09/2014
>>> [131110.482714] task: ffff8807f4b08e20 ti: ffff8807e51f8000 task.ti:
>>> ffff8807e51f8000
>>> [131110.483148] RIP: 0010:[<ffffffffa03a7a13>]  [<ffffffffa03a7a13>]
>>> bch_extent_bad+0xf3/0x1c0 [bcache]
>>> [131110.483576] RSP: 0018:ffff8807e51fbb68  EFLAGS: 00000246
>>> [131110.483794] RAX: 00000004eb93f476 RBX: ffff8807e51fbe08 RCX:
>>> 000000000000000a
>>> [131110.484235] RDX: ffffc90017145000 RSI: 00000004eb93f476 RDI:
>>> ffff8807ec8c0000
>>> [131110.484657] RBP: ffff8807e51fbb78 R08: 0000000000000001 R09:
>>> 0000000000000000
>>> [131110.485096] R10: 000007ffffffffff R11: 000000000000000c R12:
>>> 000007ffffffffff
>>> [131110.485524] R13: ffff8807e51fbb58 R14: ffffffffa03a78d5 R15:
>>> ffff8807e51fbb48
>>> [131110.485969] FS:  0000000000000000(0000) GS:ffff88082fc80000(0000)
>>> knlGS:0000000000000000
>>> [131110.486393] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>>> [131110.486609] CR2: 00007f5ff8e6c000 CR3: 0000000001a14000 CR4:
>>> 00000000001427e0
>>> [131110.487051] Stack:
>>> [131110.487261]  ffff8807e51fbbc8 ffff8807eccf64d0 ffff8807e51fbb88
>>> ffffffffa039fa5a
>>> [131110.487694]  ffff8807e51fbbb8 ffffffffa039fa29 0000000000000dad
>>> ffff8807eccf64d0
>>> [131110.488140]  ffff8807e51fbbc8 ffff8807e51fbcb8 ffff8807e51fbc38
>>> ffffffffa039fdc0
>>> [131110.488583] Call Trace:
>>> [131110.488803]  [<ffffffffa039fa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>>> [131110.489037]  [<ffffffffa039fa29>] bch_btree_iter_next_filter+0x39/0x50
>>> [bcache]
>>> [131110.489453]  [<ffffffffa039fdc0>] btree_gc_count_keys+0x50/0x70
>>> [bcache]
>>> [131110.489677]  [<ffffffffa03a60bf>] btree_gc_recurse+0x1bf/0x2e0
>>> [bcache]
>>> [131110.489923]  [<ffffffffa03a1d2c>] ? btree_gc_mark_node+0xdc/0x210
>>> [bcache]
>>> [131110.490146]  [<ffffffffa03a62e1>] bch_btree_gc_root+0x101/0x110
>>> [bcache]
>>> [131110.490371]  [<ffffffffa03a64db>] bch_btree_gc+0x1eb/0x460 [bcache]
>>> [131110.490597]  [<ffffffff81096f60>] ? bit_waitqueue+0xa0/0xa0
>>> [131110.490821]  [<ffffffffa03a6788>] bch_gc_thread+0x38/0x120 [bcache]
>>> [131110.491062]  [<ffffffffa03a6750>] ? bch_btree_gc+0x460/0x460 [bcache]
>>> [131110.491284]  [<ffffffff8107812e>] kthread+0xce/0xf0
>>> [131110.491505]  [<ffffffff81078060>] ?
>>> kthread_freezable_should_stop+0x70/0x70
>>> [131110.491732]  [<ffffffff815c52bc>] ret_from_fork+0x7c/0xb0
>>> [131110.491970]  [<ffffffff81078060>] ?
>>> kthread_freezable_should_stop+0x70/0x70
>>> [131110.492194] Code: 0f 1f 84 00 00 00 00 00 48 8b 74 c3 10 48 89 f0 48
>>> c1 e8 33 25 ff 0f 00 00 48 8b 94 c7 40 0c 00 00 48 89 f0 48 8b 92 d8 0a 00
>>> 00 <48> c1 e8 08 4c 21 d0 48 d3 e8 48 8d 04 40 0f b6 54 82 06 40 28
>>>
>>>
>>> Second backtrace:
>>>
>>> [131146.469270] INFO: rcu_sched self-detected stall on CPU { 2}
>>> (t=11613552 jiffies g=3817860 c=3817859 q=24121607)
>>> [131146.469724] Task dump for CPU 2:
>>> [131146.469943] bcache_gc       R  running task        0  5251      2
>>> 0x00000088
>>> [131146.470168]  0000000000000003 ffff88082fc83d18 ffffffff8107ef97
>>> 0000000000000002
>>> [131146.470625]  ffffffff81a4cc80 ffff88082fc83d38 ffffffff8107f03f
>>> ffff88082fc83d38
>>> [131146.471058]  ffffffff81a4cc80 ffff88082fc83d68 ffffffff810b5b41
>>> ffffffff81a4cc80
>>> [131146.471507] Call Trace:
>>> [131146.471718]  <IRQ>  [<ffffffff8107ef97>] sched_show_task+0xa7/0x110
>>> [131146.471948]  [<ffffffff8107f03f>] dump_cpu_task+0x3f/0x50
>>> [131146.472167]  [<ffffffff810b5b41>] rcu_dump_cpu_stacks+0x91/0xd0
>>> [131146.472406]  [<ffffffff810b5c5e>] print_cpu_stall+0xde/0x140
>>> [131146.472630]  [<ffffffff810b610e>] __rcu_pending+0x1fe/0x210
>>> [131146.472855]  [<ffffffff810b73fd>] rcu_check_callbacks+0xdd/0x190
>>> [131146.473077]  [<ffffffff810bad28>] update_process_times+0x48/0x80
>>> [131146.473321]  [<ffffffff810cc1e9>] tick_sched_handle+0x39/0x80
>>> [131146.473540]  [<ffffffff810cc434>] tick_sched_timer+0x54/0x90
>>> [131146.473764]  [<ffffffff810bd384>] __run_hrtimer+0x74/0x1d0
>>> [131146.473986]  [<ffffffff810cc3e0>] ? tick_nohz_handler+0xc0/0xc0
>>> [131146.474208]  [<ffffffff810bd716>] hrtimer_interrupt+0x106/0x280
>>> [131146.474453]  [<ffffffffa039fa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
>>> [131146.474668]  [<ffffffff810387cb>] local_apic_timer_interrupt+0x3b/0x60
>>> [131146.474884]  [<ffffffff815c7ec5>] smp_apic_timer_interrupt+0x45/0x60
>>> [131146.475100]  [<ffffffffa039fa50>] ? bch_ptr_invalid+0x10/0x10 [bcache]
>>> [131146.475332]  [<ffffffff815c61dd>] apic_timer_interrupt+0x6d/0x80
>>> [131146.475544]  <EOI>  [<ffffffffa03a7951>] ? bch_extent_bad+0x31/0x1c0
>>> [bcache]
>>> [131146.475967]  [<ffffffffa03a794d>] ? bch_extent_bad+0x2d/0x1c0 [bcache]
>>> [131146.476183]  [<ffffffffa039fa5a>] bch_ptr_bad+0xa/0x10 [bcache]
>>> [131146.476418]  [<ffffffffa039fa29>] bch_btree_iter_next_filter+0x39/0x50
>>> [bcache]
>>> [131146.476845]  [<ffffffffa039fdc0>] btree_gc_count_keys+0x50/0x70
>>> [bcache]
>>> [131146.477064]  [<ffffffffa03a60bf>] btree_gc_recurse+0x1bf/0x2e0
>>> [bcache]
>>> [131146.477302]  [<ffffffffa03a1d2c>] ? btree_gc_mark_node+0xdc/0x210
>>> [bcache]
>>> [131146.477521]  [<ffffffffa03a62e1>] bch_btree_gc_root+0x101/0x110
>>> [bcache]
>>> [131146.477747]  [<ffffffffa03a64db>] bch_btree_gc+0x1eb/0x460 [bcache]
>>> [131146.477964]  [<ffffffff81096f60>] ? bit_waitqueue+0xa0/0xa0
>>> [131146.478182]  [<ffffffffa03a6788>] bch_gc_thread+0x38/0x120 [bcache]
>>> [131146.478416]  [<ffffffffa03a6750>] ? bch_btree_gc+0x460/0x460 [bcache]
>>> [131146.478634]  [<ffffffff8107812e>] kthread+0xce/0xf0
>>> [131146.478847]  [<ffffffff81078060>] ?
>>> kthread_freezable_should_stop+0x70/0x70
>>> [131146.479066]  [<ffffffff815c52bc>] ret_from_fork+0x7c/0xb0
>>> [131146.479302]  [<ffffffff81078060>] ?
>>> kthread_freezable_should_stop+0x70/0x70
>>>
>>>
>>>
>>> --
>>> Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
>>> 888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
>>> www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Kent Overstreet]

On Sun, Sep 28, 2014 at 05:25:37PM -0700, Eric Wheeler wrote:
> Hello Kent, Ross, all:
> 
> We're getting bcache_gc backtraces and soft lockups; the system continues to
> be responsive and eventually recovers.  We are running 3.17-rc6. (This
> appears to be a continuation of the thread from 2014-09-15)
> 
> Please see the following two backtraces.  The first shows up in
> btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We will
> test with -rc7 this week, though I didn't see any bcache commits in rc7.
> 
> The server is quite busy:
>   dd in userspace from dm-thinp snapshots to another server
>   two DRBD verify's active backed by dm-thinp volumes
>   note that, dd fills up the buffers so this could be operating with few
>   pages free. (Though we have min-mem set to 256MB.)
> 
> I see we are hitting functions like bch_ptr_bad() and bch_extent_bad().
> Could that indicate a cache corruption on our volume?

No - those are the normal "check the validity of medata" functions.

> I'm happy to test patches if you have any suggestions or tests that I should
> run it through.

I think it might just be a missing cond_resched()... there's a check during
garbage collection for need_resched() but it appears we might not actually be
calling schedule() then.

Try this patch:

commit a64afc92e17e709bdd1618edd04bc608f6a44c55
Author: Kent Overstreet <kmo@daterainc.com>
Date:   Sat Nov 1 13:44:13 2014 -0700

    bcache: Add a cond_resched() call to gc
    
    Change-Id: Id4f18c533b80ddb40df94ed0bb5e2a236a4bc325

diff --git a/drivers/md/bcache/btree.c b/drivers/md/bcache/btree.c
index 00cde40db5..218f21ac02 100644
--- a/drivers/md/bcache/btree.c
+++ b/drivers/md/bcache/btree.c
@@ -1741,6 +1741,7 @@ static void bch_btree_gc(struct cache_set *c)
 	do {
 		ret = btree_root(gc_root, c, &op, &writes, &stats);
 		closure_sync(&writes);
+		cond_resched();
 
 		if (ret && ret != -EAGAIN)
 			pr_warn("gc failed!");

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Stefan Seyfried]

Hi Kent,

Am 01.11.2014 um 21:44 schrieb Kent Overstreet:
> On Sun, Sep 28, 2014 at 05:25:37PM -0700, Eric Wheeler wrote:
>> Hello Kent, Ross, all:
>>
>> We're getting bcache_gc backtraces and soft lockups; the system continues to
>> be responsive and eventually recovers.  We are running 3.17-rc6. (This
>> appears to be a continuation of the thread from 2014-09-15)
>>
>> Please see the following two backtraces.  The first shows up in
>> btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We will
>> test with -rc7 this week, though I didn't see any bcache commits in rc7.
>>
>> The server is quite busy:
>>   dd in userspace from dm-thinp snapshots to another server
>>   two DRBD verify's active backed by dm-thinp volumes
>>   note that, dd fills up the buffers so this could be operating with few
>>   pages free. (Though we have min-mem set to 256MB.)
>>
>> I see we are hitting functions like bch_ptr_bad() and bch_extent_bad().
>> Could that indicate a cache corruption on our volume?
> 
> No - those are the normal "check the validity of medata" functions.
> 
>> I'm happy to test patches if you have any suggestions or tests that I should
>> run it through.
> 
> I think it might just be a missing cond_resched()... there's a check during
> garbage collection for need_resched() but it appears we might not actually be
> calling schedule() then.

I'm still hitting this quite often (once per week?), the machine does
not recover and for I cannot shut it down but need to reboot it hard.

I have seen this with 3.16.6 (openSUSE 13.2 standard kernel) and 3.17.2
(latest stable as of that boot).

This is on an old core2 duo, one CPU is always spinning in the kernel
when this happens.
I have also seen the machine recover from this, but the last occurences
have been deadly.

My setup is:
* a 60GB LV on a Crucial CT240M500 SSD as cache device (other LVs on
that SSD are for testing other stuff)
* 30GB /home   on rotating rust (a LV on a 2TB WD 2.5" drive)
* 750GB /space a LV on the same rotating rust
* 4GB /var/log/journal again a LV on the 2.5" drive

/space is used for both big-file storage (ISOs, some videos) and for
lots-of-small-files storage (yocto project embedded development, ccache
directory, ....)
/var/log/journal is the latest addition to the bcache set, after
updating to openSUSE 13.2. I would say that I only see the problems
since I added /var/log/journal, but that happened directly after
updating to 13.2 which also includes a kernel update from 3.11.10 to
3.16.x, so it could be both.

I cannot see that any specific action triggers the but, the machine is
just idling along and suddenly the soft lockup detector triggers...

> 
> Try this patch:
> 
> commit a64afc92e17e709bdd1618edd04bc608f6a44c55
> Author: Kent Overstreet <kmo@daterainc.com>
> Date:   Sat Nov 1 13:44:13 2014 -0700
> 
>     bcache: Add a cond_resched() call to gc
>     
>     Change-Id: Id4f18c533b80ddb40df94ed0bb5e2a236a4bc325
> 
> diff --git a/drivers/md/bcache/btree.c b/drivers/md/bcache/btree.c
> index 00cde40db5..218f21ac02 100644
> --- a/drivers/md/bcache/btree.c
> +++ b/drivers/md/bcache/btree.c
> @@ -1741,6 +1741,7 @@ static void bch_btree_gc(struct cache_set *c)
>  	do {
>  		ret = btree_root(gc_root, c, &op, &writes, &stats);
>  		closure_sync(&writes);
> +		cond_resched();
>  
>  		if (ret && ret != -EAGAIN)
>  			pr_warn("gc failed!");
> 

I have rebuilt the 3.17.3 bcache module with this patch now and will see
if that helps. This is not yet in 3.18-rc, is there a reason why this is
not going upstream? The issue is certainly annoying...

Best regards,

	Stefan
-- 
Stefan Seyfried
Linux Consultant & Developer
Mail: seyfried@b1-systems.de GPG Key: 0x731B665B

B1 Systems GmbH
Osterfeldstraße 7 / 85088 Vohburg / http://www.b1-systems.de
GF: Ralph Dehner / Unternehmenssitz: Vohburg / AG: Ingolstadt,HRB 3537

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Kent Overstreet]

Before the patch goes upstream I need it tested so I know if it fixes
the actual issue or not.

On Fri, Nov 21, 2014 at 2:54 PM, Stefan Seyfried
<stefan.seyfried@googlemail.com> wrote:
> Hi Kent,
>
> Am 01.11.2014 um 21:44 schrieb Kent Overstreet:
>> On Sun, Sep 28, 2014 at 05:25:37PM -0700, Eric Wheeler wrote:
>>> Hello Kent, Ross, all:
>>>
>>> We're getting bcache_gc backtraces and soft lockups; the system continues to
>>> be responsive and eventually recovers.  We are running 3.17-rc6. (This
>>> appears to be a continuation of the thread from 2014-09-15)
>>>
>>> Please see the following two backtraces.  The first shows up in
>>> btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We will
>>> test with -rc7 this week, though I didn't see any bcache commits in rc7.
>>>
>>> The server is quite busy:
>>>   dd in userspace from dm-thinp snapshots to another server
>>>   two DRBD verify's active backed by dm-thinp volumes
>>>   note that, dd fills up the buffers so this could be operating with few
>>>   pages free. (Though we have min-mem set to 256MB.)
>>>
>>> I see we are hitting functions like bch_ptr_bad() and bch_extent_bad().
>>> Could that indicate a cache corruption on our volume?
>>
>> No - those are the normal "check the validity of medata" functions.
>>
>>> I'm happy to test patches if you have any suggestions or tests that I should
>>> run it through.
>>
>> I think it might just be a missing cond_resched()... there's a check during
>> garbage collection for need_resched() but it appears we might not actually be
>> calling schedule() then.
>
> I'm still hitting this quite often (once per week?), the machine does
> not recover and for I cannot shut it down but need to reboot it hard.
>
> I have seen this with 3.16.6 (openSUSE 13.2 standard kernel) and 3.17.2
> (latest stable as of that boot).
>
> This is on an old core2 duo, one CPU is always spinning in the kernel
> when this happens.
> I have also seen the machine recover from this, but the last occurences
> have been deadly.
>
> My setup is:
> * a 60GB LV on a Crucial CT240M500 SSD as cache device (other LVs on
> that SSD are for testing other stuff)
> * 30GB /home   on rotating rust (a LV on a 2TB WD 2.5" drive)
> * 750GB /space a LV on the same rotating rust
> * 4GB /var/log/journal again a LV on the 2.5" drive
>
> /space is used for both big-file storage (ISOs, some videos) and for
> lots-of-small-files storage (yocto project embedded development, ccache
> directory, ....)
> /var/log/journal is the latest addition to the bcache set, after
> updating to openSUSE 13.2. I would say that I only see the problems
> since I added /var/log/journal, but that happened directly after
> updating to 13.2 which also includes a kernel update from 3.11.10 to
> 3.16.x, so it could be both.
>
> I cannot see that any specific action triggers the but, the machine is
> just idling along and suddenly the soft lockup detector triggers...
>
>>
>> Try this patch:
>>
>> commit a64afc92e17e709bdd1618edd04bc608f6a44c55
>> Author: Kent Overstreet <kmo@daterainc.com>
>> Date:   Sat Nov 1 13:44:13 2014 -0700
>>
>>     bcache: Add a cond_resched() call to gc
>>
>>     Change-Id: Id4f18c533b80ddb40df94ed0bb5e2a236a4bc325
>>
>> diff --git a/drivers/md/bcache/btree.c b/drivers/md/bcache/btree.c
>> index 00cde40db5..218f21ac02 100644
>> --- a/drivers/md/bcache/btree.c
>> +++ b/drivers/md/bcache/btree.c
>> @@ -1741,6 +1741,7 @@ static void bch_btree_gc(struct cache_set *c)
>>       do {
>>               ret = btree_root(gc_root, c, &op, &writes, &stats);
>>               closure_sync(&writes);
>> +             cond_resched();
>>
>>               if (ret && ret != -EAGAIN)
>>                       pr_warn("gc failed!");
>>
>
> I have rebuilt the 3.17.3 bcache module with this patch now and will see
> if that helps. This is not yet in 3.18-rc, is there a reason why this is
> not going upstream? The issue is certainly annoying...
>
> Best regards,
>
>         Stefan
> --
> Stefan Seyfried
> Linux Consultant & Developer
> Mail: seyfried@b1-systems.de GPG Key: 0x731B665B
>
> B1 Systems GmbH
> Osterfeldstraße 7 / 85088 Vohburg / http://www.b1-systems.de
> GF: Ralph Dehner / Unternehmenssitz: Vohburg / AG: Ingolstadt,HRB 3537

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Eric Wheeler]

[-- Attachment #1: Type: text/plain, Size: 5259 bytes --]

> Before the patch goes upstream I need it tested so I know if it fixes 
> the actual issue or not.

We have been using the rcu_sched patch and the cond_resched patch together 
(both attached) since November 3rd on 3.17.2 without any bcache 
backtraces. bcache is running in writeback mode. The server is 
predominantly write-only with relatively few reads.

To sum up, the attached two patches (plus the for-jens pull) have fixed all
of our bcache problems since 3.14.y.  These patches on 3.17.2 seem quite stable.

-Eric


--
Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298

On Fri, 21 Nov 2014, Kent Overstreet wrote:

>
> On Fri, Nov 21, 2014 at 2:54 PM, Stefan Seyfried
> <stefan.seyfried@googlemail.com> wrote:
>> Hi Kent,
>>
>> Am 01.11.2014 um 21:44 schrieb Kent Overstreet:
>>> On Sun, Sep 28, 2014 at 05:25:37PM -0700, Eric Wheeler wrote:
>>>> Hello Kent, Ross, all:
>>>>
>>>> We're getting bcache_gc backtraces and soft lockups; the system continues to
>>>> be responsive and eventually recovers.  We are running 3.17-rc6. (This
>>>> appears to be a continuation of the thread from 2014-09-15)
>>>>
>>>> Please see the following two backtraces.  The first shows up in
>>>> btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We will
>>>> test with -rc7 this week, though I didn't see any bcache commits in rc7.
>>>>
>>>> The server is quite busy:
>>>>   dd in userspace from dm-thinp snapshots to another server
>>>>   two DRBD verify's active backed by dm-thinp volumes
>>>>   note that, dd fills up the buffers so this could be operating with few
>>>>   pages free. (Though we have min-mem set to 256MB.)
>>>>
>>>> I see we are hitting functions like bch_ptr_bad() and bch_extent_bad().
>>>> Could that indicate a cache corruption on our volume?
>>>
>>> No - those are the normal "check the validity of medata" functions.
>>>
>>>> I'm happy to test patches if you have any suggestions or tests that I should
>>>> run it through.
>>>
>>> I think it might just be a missing cond_resched()... there's a check during
>>> garbage collection for need_resched() but it appears we might not actually be
>>> calling schedule() then.
>>
>> I'm still hitting this quite often (once per week?), the machine does
>> not recover and for I cannot shut it down but need to reboot it hard.
>>
>> I have seen this with 3.16.6 (openSUSE 13.2 standard kernel) and 3.17.2
>> (latest stable as of that boot).
>>
>> This is on an old core2 duo, one CPU is always spinning in the kernel
>> when this happens.
>> I have also seen the machine recover from this, but the last occurences
>> have been deadly.
>>
>> My setup is:
>> * a 60GB LV on a Crucial CT240M500 SSD as cache device (other LVs on
>> that SSD are for testing other stuff)
>> * 30GB /home   on rotating rust (a LV on a 2TB WD 2.5" drive)
>> * 750GB /space a LV on the same rotating rust
>> * 4GB /var/log/journal again a LV on the 2.5" drive
>>
>> /space is used for both big-file storage (ISOs, some videos) and for
>> lots-of-small-files storage (yocto project embedded development, ccache
>> directory, ....)
>> /var/log/journal is the latest addition to the bcache set, after
>> updating to openSUSE 13.2. I would say that I only see the problems
>> since I added /var/log/journal, but that happened directly after
>> updating to 13.2 which also includes a kernel update from 3.11.10 to
>> 3.16.x, so it could be both.
>>
>> I cannot see that any specific action triggers the but, the machine is
>> just idling along and suddenly the soft lockup detector triggers...
>>
>>>
>>> Try this patch:
>>>
>>> commit a64afc92e17e709bdd1618edd04bc608f6a44c55
>>> Author: Kent Overstreet <kmo@daterainc.com>
>>> Date:   Sat Nov 1 13:44:13 2014 -0700
>>>
>>>     bcache: Add a cond_resched() call to gc
>>>
>>>     Change-Id: Id4f18c533b80ddb40df94ed0bb5e2a236a4bc325
>>>
>>> diff --git a/drivers/md/bcache/btree.c b/drivers/md/bcache/btree.c
>>> index 00cde40db5..218f21ac02 100644
>>> --- a/drivers/md/bcache/btree.c
>>> +++ b/drivers/md/bcache/btree.c
>>> @@ -1741,6 +1741,7 @@ static void bch_btree_gc(struct cache_set *c)
>>>       do {
>>>               ret = btree_root(gc_root, c, &op, &writes, &stats);
>>>               closure_sync(&writes);
>>> +             cond_resched();
>>>
>>>               if (ret && ret != -EAGAIN)
>>>                       pr_warn("gc failed!");
>>>
>>
>> I have rebuilt the 3.17.3 bcache module with this patch now and will see
>> if that helps. This is not yet in 3.18-rc, is there a reason why this is
>> not going upstream? The issue is certainly annoying...
>>
>> Best regards,
>>
>>         Stefan
>> --
>> Stefan Seyfried
>> Linux Consultant & Developer
>> Mail: seyfried@b1-systems.de GPG Key: 0x731B665B
>>
>> B1 Systems GmbH
>> Osterfeldstra?e 7 / 85088 Vohburg / http://www.b1-systems.de
>> GF: Ralph Dehner / Unternehmenssitz: Vohburg / AG: Ingolstadt,HRB 3537
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>


[-- Attachment #2: bcache-cond_resched.patch --]
[-- Type: text/x-patch, Size: 324 bytes --]

--- a/drivers/md/bcache/btree.c	2014-11-03 16:51:01.720000000 -0800
+++ b/drivers/md/bcache/btree.c	2014-11-03 16:51:26.456000000 -0800
@@ -1741,6 +1741,7 @@
 	do {
 		ret = btree_root(gc_root, c, &op, &writes, &stats);
 		closure_sync(&writes);
+		cond_resched();
 
 		if (ret && ret != -EAGAIN)
 			pr_warn("gc failed!");

[-- Attachment #3: bcache-rcu-sched-bugfix.patch --]
[-- Type: text/x-patch, Size: 480 bytes --]

diff --git a/drivers/md/bcache/btree.c b/drivers/md/bcache/btree.c
index 00cde40..d14560a 100644
--- a/drivers/md/bcache/btree.c
+++ b/drivers/md/bcache/btree.c
@@ -2162,8 +2162,10 @@ int bch_btree_insert_check_key(struct btree *b, struct btree_op *op,
 		rw_lock(true, b, b->level);
 
 		if (b->key.ptr[0] != btree_ptr ||
-		    b->seq != seq + 1)
+		    b->seq != seq + 1) {
+			op->lock = b->c->root->level + 1;
 			goto out;
+		}
 	}
 
 	SET_KEY_PTRS(check_key, 1);
-- 
1.7.1

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Stefan Seyfried]

Hi Eric,

Am 22.11.2014 um 01:22 schrieb Eric Wheeler:
>> Before the patch goes upstream I need it tested so I know if it fixes 
>> the actual issue or not.
> 
> We have been using the rcu_sched patch and the cond_resched patch together 
> (both attached) since November 3rd on 3.17.2 without any bcache 
> backtraces. bcache is running in writeback mode. The server is 
> predominantly write-only with relatively few reads.

Is the rcu_sched patch supposed to help the same or a totally different
problem? Means: should I also apply it, rebuild the module and reboot
(resetting the test time to zero :-)

I had the "deadly" soft lockup once per week since updating to
3.16/3.17, so I can only tell if it might help in two weeks earliest.

> To sum up, the attached two patches (plus the for-jens pull) have fixed all
> of our bcache problems since 3.14.y.  These patches on 3.17.2 seem quite stable.

That's good to hear :-)

Best regards,

	Stefan
-- 
Stefan Seyfried
Linux Consultant & Developer -- GPG Key: 0x731B665B

B1 Systems GmbH
Osterfeldstraße 7 / 85088 Vohburg / http://www.b1-systems.de
GF: Ralph Dehner / Unternehmenssitz: Vohburg / AG: Ingolstadt,HRB 3537

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Eric Wheeler]

>>> Before the patch goes upstream I need it tested so I know if it fixes
>>> the actual issue or not.
>>
>> We have been using the rcu_sched patch and the cond_resched patch together
>> (both attached) since November 3rd on 3.17.2 without any bcache
>> backtraces. bcache is running in writeback mode. The server is
>> predominantly write-only with relatively few reads.
>
> Is the rcu_sched patch supposed to help the same or a totally different
> problem? Means: should I also apply it, rebuild the module and reboot
> (resetting the test time to zero :-)

The second backtrace mentioned on this link is the issue that I believe is 
fixed with the rcu_sched patch:

https://www.mail-archive.com/linux-bcache@vger.kernel.org/msg02623.html

The error starts with a message like "INFO: rcu_sched self-detected stall 
on CPU"

-Eric



> I had the "deadly" soft lockup once per week since updating to
> 3.16/3.17, so I can only tell if it might help in two weeks earliest.
>
>> To sum up, the attached two patches (plus the for-jens pull) have fixed all
>> of our bcache problems since 3.14.y.  These patches on 3.17.2 seem quite stable.
>
> That's good to hear :-)
>
> Best regards,
>
> 	Stefan
> -- 
> Stefan Seyfried
> Linux Consultant & Developer -- GPG Key: 0x731B665B
>
> B1 Systems GmbH
> Osterfeldstra?e 7 / 85088 Vohburg / http://www.b1-systems.de
> GF: Ralph Dehner / Unternehmenssitz: Vohburg / AG: Ingolstadt,HRB 3537
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Stefan Seyfried]

Hi all,

Am 24.11.2014 um 19:52 schrieb Eric Wheeler:
>>>> Before the patch goes upstream I need it tested so I know if it fixes
>>>> the actual issue or not.
>>>
>>> We have been using the rcu_sched patch and the cond_resched patch
>>> together
>>> (both attached) since November 3rd on 3.17.2 without any bcache
>>> backtraces. bcache is running in writeback mode. The server is
>>> predominantly write-only with relatively few reads.
>>
>> Is the rcu_sched patch supposed to help the same or a totally different
>> problem? Means: should I also apply it, rebuild the module and reboot
>> (resetting the test time to zero :-)

Ok, I am also running both patches, my uptime is 10 days and I'm right
now doing a bit of the usual stress-testing on the bcached partitions
(find /m1 /m2 /m3 > /dev/null which does read-mostly, and a rebuild of
all my yocto-project embedded board targets, which does read-write)

I have not seen any problems yet, so the patches don't seem to hurt.

>> I had the "deadly" soft lockup once per week since updating to
>> 3.16/3.17, so I can only tell if it might help in two weeks earliest.

It's not two weeks yet, but getting close.

Load average never goes below 1 (with 3 bcache-backed mounts).

Best regards,

	Stefan
-- 
Stefan Seyfried
Linux Consultant & Developer -- GPG Key: 0x731B665B

B1 Systems GmbH
Osterfeldstraße 7 / 85088 Vohburg / http://www.b1-systems.de
GF: Ralph Dehner / Unternehmenssitz: Vohburg / AG: Ingolstadt,HRB 3537

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Thomas Stein]

Am 03.12.14 10:32, schrieb Stefan Seyfried:

> It's not two weeks yet, but getting close.
> 
> Load average never goes below 1 (with 3 bcache-backed mounts).

Ah. I see. So the load bug is still there. Thanks for the info.

best regards
t.

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Thomas Stein]

On Friday 21 November 2014 16:22:08 Eric Wheeler wrote:
> > Before the patch goes upstream I need it tested so I know if it fixes
> > the actual issue or not.
> 
> We have been using the rcu_sched patch and the cond_resched patch together
> (both attached) since November 3rd on 3.17.2 without any bcache
> backtraces. bcache is running in writeback mode. The server is
> predominantly write-only with relatively few reads.
> 
> To sum up, the attached two patches (plus the for-jens pull) have fixed all
> of our bcache problems since 3.14.y.  These patches on 3.17.2 seem quite
> stable.

Is the bug " Load average never goes below 2 " gone too?

cheers
t.

> -Eric
> 
> 
> --
> Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
> 888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
> www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298
> 
> On Fri, 21 Nov 2014, Kent Overstreet wrote:
> > On Fri, Nov 21, 2014 at 2:54 PM, Stefan Seyfried
> > 
> > <stefan.seyfried@googlemail.com> wrote:
> >> Hi Kent,
> >> 
> >> Am 01.11.2014 um 21:44 schrieb Kent Overstreet:
> >>> On Sun, Sep 28, 2014 at 05:25:37PM -0700, Eric Wheeler wrote:
> >>>> Hello Kent, Ross, all:
> >>>> 
> >>>> We're getting bcache_gc backtraces and soft lockups; the system
> >>>> continues to be responsive and eventually recovers.  We are running
> >>>> 3.17-rc6. (This appears to be a continuation of the thread from
> >>>> 2014-09-15)
> >>>> 
> >>>> Please see the following two backtraces.  The first shows up in
> >>>> btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We
> >>>> will test with -rc7 this week, though I didn't see any bcache commits
> >>>> in rc7.>>>> 
> >>>> The server is quite busy:
> >>>>   dd in userspace from dm-thinp snapshots to another server
> >>>>   two DRBD verify's active backed by dm-thinp volumes
> >>>>   note that, dd fills up the buffers so this could be operating with
> >>>>   few
> >>>>   pages free. (Though we have min-mem set to 256MB.)
> >>>> 
> >>>> I see we are hitting functions like bch_ptr_bad() and bch_extent_bad().
> >>>> Could that indicate a cache corruption on our volume?
> >>> 
> >>> No - those are the normal "check the validity of medata" functions.
> >>> 
> >>>> I'm happy to test patches if you have any suggestions or tests that I
> >>>> should run it through.
> >>> 
> >>> I think it might just be a missing cond_resched()... there's a check
> >>> during
> >>> garbage collection for need_resched() but it appears we might not
> >>> actually be calling schedule() then.
> >> 
> >> I'm still hitting this quite often (once per week?), the machine does
> >> not recover and for I cannot shut it down but need to reboot it hard.
> >> 
> >> I have seen this with 3.16.6 (openSUSE 13.2 standard kernel) and 3.17.2
> >> (latest stable as of that boot).
> >> 
> >> This is on an old core2 duo, one CPU is always spinning in the kernel
> >> when this happens.
> >> I have also seen the machine recover from this, but the last occurences
> >> have been deadly.
> >> 
> >> My setup is:
> >> * a 60GB LV on a Crucial CT240M500 SSD as cache device (other LVs on
> >> that SSD are for testing other stuff)
> >> * 30GB /home   on rotating rust (a LV on a 2TB WD 2.5" drive)
> >> * 750GB /space a LV on the same rotating rust
> >> * 4GB /var/log/journal again a LV on the 2.5" drive
> >> 
> >> /space is used for both big-file storage (ISOs, some videos) and for
> >> lots-of-small-files storage (yocto project embedded development, ccache
> >> directory, ....)
> >> /var/log/journal is the latest addition to the bcache set, after
> >> updating to openSUSE 13.2. I would say that I only see the problems
> >> since I added /var/log/journal, but that happened directly after
> >> updating to 13.2 which also includes a kernel update from 3.11.10 to
> >> 3.16.x, so it could be both.
> >> 
> >> I cannot see that any specific action triggers the but, the machine is
> >> just idling along and suddenly the soft lockup detector triggers...
> >> 
> >>> Try this patch:
> >>> 
> >>> commit a64afc92e17e709bdd1618edd04bc608f6a44c55
> >>> Author: Kent Overstreet <kmo@daterainc.com>
> >>> Date:   Sat Nov 1 13:44:13 2014 -0700
> >>> 
> >>>     bcache: Add a cond_resched() call to gc
> >>>     
> >>>     Change-Id: Id4f18c533b80ddb40df94ed0bb5e2a236a4bc325
> >>> 
> >>> diff --git a/drivers/md/bcache/btree.c b/drivers/md/bcache/btree.c
> >>> index 00cde40db5..218f21ac02 100644
> >>> --- a/drivers/md/bcache/btree.c
> >>> +++ b/drivers/md/bcache/btree.c
> >>> @@ -1741,6 +1741,7 @@ static void bch_btree_gc(struct cache_set *c)
> >>> 
> >>>       do {
> >>>       
> >>>               ret = btree_root(gc_root, c, &op, &writes, &stats);
> >>>               closure_sync(&writes);
> >>> 
> >>> +             cond_resched();
> >>> 
> >>>               if (ret && ret != -EAGAIN)
> >>>               
> >>>                       pr_warn("gc failed!");
> >> 
> >> I have rebuilt the 3.17.3 bcache module with this patch now and will see
> >> if that helps. This is not yet in 3.18-rc, is there a reason why this is
> >> not going upstream? The issue is certainly annoying...
> >> 
> >> Best regards,
> >> 
> >>         Stefan
> >> 
> >> --
> >> Stefan Seyfried
> >> Linux Consultant & Developer
> >> Mail: seyfried@b1-systems.de GPG Key: 0x731B665B
> >> 
> >> B1 Systems GmbH
> >> Osterfeldstra?e 7 / 85088 Vohburg / http://www.b1-systems.de
> >> GF: Ralph Dehner / Unternehmenssitz: Vohburg / AG: Ingolstadt,HRB 3537
> > 
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: 3.17-rc6: bcache_gc: BUG: soft lockup - CPU#2 stuck for 23s!

[Eric Wheeler]

> Is the bug " Load average never goes below 2 " gone too?

Load on that system is 1.29.

-Eric



> cheers
> t.
>
>> -Eric
>>
>>
>> --
>> Eric Wheeler, President           eWheeler, Inc. dba Global Linux Security
>> 888-LINUX26 (888-546-8926)        Fax: 503-716-3878           PO Box 25107
>> www.GlobalLinuxSecurity.pro       Linux since 1996!     Portland, OR 97298
>>
>> On Fri, 21 Nov 2014, Kent Overstreet wrote:
>>> On Fri, Nov 21, 2014 at 2:54 PM, Stefan Seyfried
>>>
>>> <stefan.seyfried@googlemail.com> wrote:
>>>> Hi Kent,
>>>>
>>>> Am 01.11.2014 um 21:44 schrieb Kent Overstreet:
>>>>> On Sun, Sep 28, 2014 at 05:25:37PM -0700, Eric Wheeler wrote:
>>>>>> Hello Kent, Ross, all:
>>>>>>
>>>>>> We're getting bcache_gc backtraces and soft lockups; the system
>>>>>> continues to be responsive and eventually recovers.  We are running
>>>>>> 3.17-rc6. (This appears to be a continuation of the thread from
>>>>>> 2014-09-15)
>>>>>>
>>>>>> Please see the following two backtraces.  The first shows up in
>>>>>> btree_gc_count_keys(), the other is triggered somehow by rcu_sched.  We
>>>>>> will test with -rc7 this week, though I didn't see any bcache commits
>>>>>> in rc7.>>>>
>>>>>> The server is quite busy:
>>>>>>   dd in userspace from dm-thinp snapshots to another server
>>>>>>   two DRBD verify's active backed by dm-thinp volumes
>>>>>>   note that, dd fills up the buffers so this could be operating with
>>>>>>   few
>>>>>>   pages free. (Though we have min-mem set to 256MB.)
>>>>>>
>>>>>> I see we are hitting functions like bch_ptr_bad() and bch_extent_bad().
>>>>>> Could that indicate a cache corruption on our volume?
>>>>>
>>>>> No - those are the normal "check the validity of medata" functions.
>>>>>
>>>>>> I'm happy to test patches if you have any suggestions or tests that I
>>>>>> should run it through.
>>>>>
>>>>> I think it might just be a missing cond_resched()... there's a check
>>>>> during
>>>>> garbage collection for need_resched() but it appears we might not
>>>>> actually be calling schedule() then.
>>>>
>>>> I'm still hitting this quite often (once per week?), the machine does
>>>> not recover and for I cannot shut it down but need to reboot it hard.
>>>>
>>>> I have seen this with 3.16.6 (openSUSE 13.2 standard kernel) and 3.17.2
>>>> (latest stable as of that boot).
>>>>
>>>> This is on an old core2 duo, one CPU is always spinning in the kernel
>>>> when this happens.
>>>> I have also seen the machine recover from this, but the last occurences
>>>> have been deadly.
>>>>
>>>> My setup is:
>>>> * a 60GB LV on a Crucial CT240M500 SSD as cache device (other LVs on
>>>> that SSD are for testing other stuff)
>>>> * 30GB /home   on rotating rust (a LV on a 2TB WD 2.5" drive)
>>>> * 750GB /space a LV on the same rotating rust
>>>> * 4GB /var/log/journal again a LV on the 2.5" drive
>>>>
>>>> /space is used for both big-file storage (ISOs, some videos) and for
>>>> lots-of-small-files storage (yocto project embedded development, ccache
>>>> directory, ....)
>>>> /var/log/journal is the latest addition to the bcache set, after
>>>> updating to openSUSE 13.2. I would say that I only see the problems
>>>> since I added /var/log/journal, but that happened directly after
>>>> updating to 13.2 which also includes a kernel update from 3.11.10 to
>>>> 3.16.x, so it could be both.
>>>>
>>>> I cannot see that any specific action triggers the but, the machine is
>>>> just idling along and suddenly the soft lockup detector triggers...
>>>>
>>>>> Try this patch:
>>>>>
>>>>> commit a64afc92e17e709bdd1618edd04bc608f6a44c55
>>>>> Author: Kent Overstreet <kmo@daterainc.com>
>>>>> Date:   Sat Nov 1 13:44:13 2014 -0700
>>>>>
>>>>>     bcache: Add a cond_resched() call to gc
>>>>>
>>>>>     Change-Id: Id4f18c533b80ddb40df94ed0bb5e2a236a4bc325
>>>>>
>>>>> diff --git a/drivers/md/bcache/btree.c b/drivers/md/bcache/btree.c
>>>>> index 00cde40db5..218f21ac02 100644
>>>>> --- a/drivers/md/bcache/btree.c
>>>>> +++ b/drivers/md/bcache/btree.c
>>>>> @@ -1741,6 +1741,7 @@ static void bch_btree_gc(struct cache_set *c)
>>>>>
>>>>>       do {
>>>>>
>>>>>               ret = btree_root(gc_root, c, &op, &writes, &stats);
>>>>>               closure_sync(&writes);
>>>>>
>>>>> +             cond_resched();
>>>>>
>>>>>               if (ret && ret != -EAGAIN)
>>>>>
>>>>>                       pr_warn("gc failed!");
>>>>
>>>> I have rebuilt the 3.17.3 bcache module with this patch now and will see
>>>> if that helps. This is not yet in 3.18-rc, is there a reason why this is
>>>> not going upstream? The issue is certainly annoying...
>>>>
>>>> Best regards,
>>>>
>>>>         Stefan
>>>>
>>>> --
>>>> Stefan Seyfried
>>>> Linux Consultant & Developer
>>>> Mail: seyfried@b1-systems.de GPG Key: 0x731B665B
>>>>
>>>> B1 Systems GmbH
>>>> Osterfeldstra?e 7 / 85088 Vohburg / http://www.b1-systems.de
>>>> GF: Ralph Dehner / Unternehmenssitz: Vohburg / AG: Ingolstadt,HRB 3537
>>>
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bcache" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>