Re: BUG_ON in rcu_sync_func triggered

Re: BUG_ON in rcu_sync_func triggered

[Oleg Nesterov]

Hi Nikolay,

On 09/12, Nikolay Borisov wrote:
>
> [ 2213.610208] ------------[ cut here ]------------
> [ 2213.614243] kernel BUG at kernel/rcu/sync.c:152!
> [ 2213.618270] invalid opcode: 0000 [#1] SMP 
> [ 2213.696629] CPU: 5 PID: 0 Comm: swapper/5 Not tainted 4.4.2-clouder2 #1
> [ 2213.702891] Hardware name: Supermicro X9DRW/X9DRW, BIOS 1.0b 10/11/2012
> [ 2213.709155] task: ffff880276a24e00 ti: ffff880276a40000 task.ti: ffff880276a40000
> [ 2213.716391] RIP: 0010:[<ffffffff810a4af0>]  [<ffffffff810a4af0>] rcu_sync_func+0xa0/0xb0
> [ 2213.724407] RSP: 0018:ffff88047fc83da8  EFLAGS: 00010297
> [ 2213.729211] RAX: ffffffff810a4a50 RBX: ffff88025c6b22a0 RCX: 0000000180200018
> [ 2213.736056] RDX: 0000000180200019 RSI: ffffea0011ca1000 RDI: ffff88025c6b22a0
> [ 2213.742903] RBP: ffff88047fc83dd8 R08: ffffea0011ca1010 R09: 0000000000000000
> [ 2213.749750] R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000000009
> [ 2213.756597] R13: ffff88025c6b2278 R14: 0000000000000000 R15: ffff880276a40008
> [ 2213.763445] FS:  0000000000000000(0000) GS:ffff88047fc80000(0000) knlGS:0000000000000000
> [ 2213.777149] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 2213.782533] CR2: 0000000003a04028 CR3: 0000000001c0a000 CR4: 00000000000406e0
> [ 2213.789379] Stack:
> [ 2213.790491]  0000000000000008 000000000000000a ffff88047fc83dd8 ffff8804749ec600
> [ 2213.797971]  0000000000000009 000000000000000a ffff88047fc83ec8 ffffffff810a9878
> [ 2213.805457]  ffff88047fc83de0 ffff88047fc8d178 ffff88047fc95580 0000000000000000
> [ 2213.812931] Call Trace:
> [ 2213.814519]  <IRQ> 
> [ 2213.815299]  [<ffffffff810a9878>] rcu_process_callbacks+0x2a8/0x720
> [ 2213.821704]  [<ffffffff8108be0d>] ? run_rebalance_domains+0x18d/0x290
> [ 2213.827776]  [<ffffffff81058ee0>] __do_softirq+0x120/0x320
> [ 2213.832780]  [<ffffffff810ae803>] ? hrtimer_interrupt+0x113/0x1e0
> [ 2213.838464]  [<ffffffff810591b5>] irq_exit+0x75/0x80
> [ 2213.842885]  [<ffffffff816394ba>] smp_apic_timer_interrupt+0x4a/0x60
> [ 2213.848857]  [<ffffffff81637c29>] apic_timer_interrupt+0x89/0x90
> [ 2213.854437]  <EOI> 
> [ 2213.855217]  [<ffffffff8152d912>] ? cpuidle_enter_state+0x152/0x2c0
> [ 2213.861620]  [<ffffffff8152d907>] ? cpuidle_enter_state+0x147/0x2c0
> [ 2213.867495]  [<ffffffff8107cb0d>] ? ttwu_do_wakeup+0x1d/0xe0
> [ 2213.872689]  [<ffffffff8152da97>] cpuidle_enter+0x17/0x20
> [ 2213.877594]  [<ffffffff81094188>] cpu_startup_entry+0x248/0x390
> [ 2213.883081]  [<ffffffff810ba802>] ? clockevents_register_device+0x102/0x160
> [ 2213.889736]  [<ffffffff810ba550>] ? clockevents_config+0x70/0xa0
> [ 2213.895320]  [<ffffffff810ba88c>] ? clockevents_config_and_register+0x2c/0x40
> [ 2213.902169]  [<ffffffff81034ec9>] start_secondary+0xf9/0x100
> [ 2213.933638] RIP  [<ffffffff810a4af0>] rcu_sync_func+0xa0/0xb0
> [ 2213.939118]  RSP <ffff88047fc83da8>
> 
> 
> The bug on in question is this: BUG_ON(rsp->gp_state != GP_PASSED);
> 
> Have you seen something like that before - the kernel is fairly old 4.4.2,

No... thanks, I'll try to look tomorrow.

Oleg.

Re: BUG_ON in rcu_sync_func triggered

[Nikolay Borisov]

On 09/12/2016 04:01 PM, Oleg Nesterov wrote:
> Hi Nikolay,
> 
[SNIP..]
>>
>>
>> The bug on in question is this: BUG_ON(rsp->gp_state != GP_PASSED);
>>
>> Have you seen something like that before - the kernel is fairly old 4.4.2,
> 
> No... thanks, I'll try to look tomorrow.

I just re-run the test with kernel 4.4.14 and PROVE_RCU and DEBUG_RCU_OBJECTS 
enabled and here is what I got: 

[ 2380.195422] ------------[ cut here ]------------
[ 2380.195770] kernel BUG at kernel/rcu/sync.c:111!
[ 2380.196107] invalid opcode: 0000 [#1] SMP
[ 2380.204519] CPU: 5 PID: 16265 Comm: fsfreeze Not tainted 4.4.14-clouder5-debug #6
[ 2380.205109] Hardware name: Supermicro X9DRW/X9DRW, BIOS 1.0b 10/11/2012
[ 2380.205453] task: ffff880444572d00 ti: ffff880450690000 task.ti: ffff880450690000
[ 2380.206043] RIP: 0010:[<ffffffff810c1c93>]  [<ffffffff810c1c93>] rcu_sync_enter+0xf3/0x100
[ 2380.206723] RSP: 0018:ffff880450693db8  EFLAGS: 00010202
[ 2380.207062] RAX: ffff880444572d00 RBX: ffff880445cfe4f8 RCX: 0000000000000006
[ 2380.207406] RDX: 0000000000000006 RSI: ffff8804445734a0 RDI: ffff880444572d00
[ 2380.207750] RBP: ffff880450693df8 R08: 0000000000000004 R09: 0000000000000000
[ 2380.208094] R10: 0000000000000000 R11: 0000000000000000 R12: ffff880445cfe500
[ 2380.208436] R13: 0000000000000001 R14: 0000000000000003 R15: 0000000000000000
[ 2380.214641] FS:  00007faaf3bde700(0000) GS:ffff88047fc80000(0000) knlGS:0000000000000000
[ 2380.215235] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2380.215577] CR2: 00007f3f67f4d038 CR3: 000000045722d000 CR4: 00000000000406e0
[ 2380.215924] Stack:
[ 2380.216259]  0000000000000000 dead000000000100 dead000000000200 ffff880444572d00
[ 2380.217179]  0000000000000000 ffff880445cfe4f8 ffff880445cfe640 0000000000000000
[ 2380.218105]  ffff880450693e48 ffffffff810a9ded ffff880450693e68 ffffffff81351093
[ 2380.219026] Call Trace:
[ 2380.219366]  [<ffffffff810a9ded>] percpu_down_write+0x1d/0xf0
[ 2380.219715]  [<ffffffff81351093>] ? call_rwsem_down_write_failed+0x13/0x20
[ 2380.220062]  [<ffffffff811cc5ef>] sb_wait_write+0x2f/0x60
[ 2380.220402]  [<ffffffff811cc817>] freeze_super+0x87/0x140
[ 2380.220744]  [<ffffffff811deb08>] do_vfs_ioctl+0x428/0x570
[ 2380.221085]  [<ffffffff811cf1e5>] ? SYSC_newfstat+0x25/0x30
[ 2380.221427]  [<ffffffff811ea9e6>] ? __fget_light+0x66/0x90
[ 2380.221767]  [<ffffffff811decc9>] SyS_ioctl+0x79/0x90
[ 2380.222111]  [<ffffffff8169851b>] entry_SYSCALL_64_fastpath+0x16/0x73
[ 2380.222454] Code: 75 c0 ba 02 00 00 00 4c 89 e7 e8 59 0f fe ff 83 3b 02 75 e5 48 8d 75 c0 4c 89 e7 e8 18 0c fe ff 48 83 c4 28 5b 41 5c 41 5d 5d c3 <0f> 0b 66 66 2e 0f 1f 84 00 00 00 00 00 66 66 66 66 90 55 48 89
[ 2380.228692] RIP  [<ffffffff810c1c93>] rcu_sync_enter+0xf3/0x100
[ 2380.229114]  RSP <ffff880450693db8>

The bug on is this one: BUG_ON(need_wait && need_sync); 

Interestingly, there wasn't any complaint from prove_rcu_locking. 

Regards, 
Nikolay 

Re: BUG_ON in rcu_sync_func triggered

[Oleg Nesterov]

On 09/13, Nikolay Borisov wrote:
>
>
> I just re-run the test with kernel 4.4.14 and PROVE_RCU and DEBUG_RCU_OBJECTS
> enabled and here is what I got:

Thanks again!

Damn. This reminds me that I forgot to send the patch which reworks rcu/sync.c.
Will do this week. But we need to investigate anyway, and I see nothing wrong
in the current code.

What did you do to reproduce?

> The bug on is this one: BUG_ON(need_wait && need_sync);

OK... perhaps the unbalanced up_write... I'll try to look at freeze/thaw code,
could test the debugging patch below meanwhile?

Oleg.


--- a/kernel/rcu/sync.c
+++ b/kernel/rcu/sync.c
@@ -82,6 +82,12 @@ void rcu_sync_init(struct rcu_sync *rsp, enum rcu_sync_type type)
 	rsp->gp_type = type;
 }
 
+static void xxx(struct rcu_sync *rsp)
+{
+	pr_crit("XXX: %p gp=%d cnt=%d cb=%d\n",
+		rsp, rsp->gp_state, rsp->gp_count, rsp->cb_state);
+}
+
 /**
  * rcu_sync_enter() - Force readers onto slowpath
  * @rsp: Pointer to rcu_sync structure to use for synchronization
@@ -102,13 +108,14 @@ void rcu_sync_enter(struct rcu_sync *rsp)
 	bool need_wait, need_sync;
 
 	spin_lock_irq(&rsp->rss_lock);
+	if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);
 	need_wait = rsp->gp_count++;
 	need_sync = rsp->gp_state == GP_IDLE;
 	if (need_sync)
 		rsp->gp_state = GP_PENDING;
 	spin_unlock_irq(&rsp->rss_lock);
 
-	BUG_ON(need_wait && need_sync);
+	if (WARN_ON(need_wait && need_sync)) xxx(rsp);
 
 	if (need_sync) {
 		gp_ops[rsp->gp_type].sync();
@@ -122,7 +129,7 @@ void rcu_sync_enter(struct rcu_sync *rsp)
 		 * Nobody has yet been allowed the 'fast' path and thus we can
 		 * avoid doing any sync(). The callback will get 'dropped'.
 		 */
-		BUG_ON(rsp->gp_state != GP_PASSED);
+		if (WARN_ON(rsp->gp_state != GP_PASSED)) xxx(rsp);
 	}
 }
 
@@ -149,8 +156,9 @@ static void rcu_sync_func(struct rcu_head *rcu)
 	struct rcu_sync *rsp = container_of(rcu, struct rcu_sync, cb_head);
 	unsigned long flags;
 
-	BUG_ON(rsp->gp_state != GP_PASSED);
-	BUG_ON(rsp->cb_state == CB_IDLE);
+	if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);
+	if (WARN_ON(rsp->gp_state != GP_PASSED)) xxx(rsp);
+	if (WARN_ON(rsp->cb_state == CB_IDLE)) xxx(rsp);
 
 	spin_lock_irqsave(&rsp->rss_lock, flags);
 	if (rsp->gp_count) {
@@ -189,6 +197,7 @@ static void rcu_sync_func(struct rcu_head *rcu)
 void rcu_sync_exit(struct rcu_sync *rsp)
 {
 	spin_lock_irq(&rsp->rss_lock);
+	if (WARN_ON(rsp->gp_count <= 0)) xxx(rsp);
 	if (!--rsp->gp_count) {
 		if (rsp->cb_state == CB_IDLE) {
 			rsp->cb_state = CB_PENDING;
@@ -208,7 +217,7 @@ void rcu_sync_dtor(struct rcu_sync *rsp)
 {
 	int cb_state;
 
-	BUG_ON(rsp->gp_count);
+	if (WARN_ON(rsp->gp_count)) xxx(rsp);
 
 	spin_lock_irq(&rsp->rss_lock);
 	if (rsp->cb_state == CB_REPLAY)
@@ -218,6 +227,6 @@ void rcu_sync_dtor(struct rcu_sync *rsp)
 
 	if (cb_state != CB_IDLE) {
 		gp_ops[rsp->gp_type].wait();
-		BUG_ON(rsp->cb_state != CB_IDLE);
+		if (WARN_ON(rsp->cb_state != CB_IDLE)) xxx(rsp);
 	}
 }

Re: BUG_ON in rcu_sync_func triggered

[Oleg Nesterov]

On 09/13, Oleg Nesterov wrote:
>
> OK... perhaps the unbalanced up_write... I'll try to look at freeze/thaw code,

Heh, yes, it looks racy or I am totally confused.

> could test the debugging patch below meanwhile?

Yes please. I'll send you another patch (hopefully fix) later, but it
would be nice if you can test this patch to get more info.

Thanks,

Oleg.

> --- a/kernel/rcu/sync.c
> +++ b/kernel/rcu/sync.c
> @@ -82,6 +82,12 @@ void rcu_sync_init(struct rcu_sync *rsp, enum rcu_sync_type type)
>  	rsp->gp_type = type;
>  }
>  
> +static void xxx(struct rcu_sync *rsp)
> +{
> +	pr_crit("XXX: %p gp=%d cnt=%d cb=%d\n",
> +		rsp, rsp->gp_state, rsp->gp_count, rsp->cb_state);
> +}
> +
>  /**
>   * rcu_sync_enter() - Force readers onto slowpath
>   * @rsp: Pointer to rcu_sync structure to use for synchronization
> @@ -102,13 +108,14 @@ void rcu_sync_enter(struct rcu_sync *rsp)
>  	bool need_wait, need_sync;
>  
>  	spin_lock_irq(&rsp->rss_lock);
> +	if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);
>  	need_wait = rsp->gp_count++;
>  	need_sync = rsp->gp_state == GP_IDLE;
>  	if (need_sync)
>  		rsp->gp_state = GP_PENDING;
>  	spin_unlock_irq(&rsp->rss_lock);
>  
> -	BUG_ON(need_wait && need_sync);
> +	if (WARN_ON(need_wait && need_sync)) xxx(rsp);
>  
>  	if (need_sync) {
>  		gp_ops[rsp->gp_type].sync();
> @@ -122,7 +129,7 @@ void rcu_sync_enter(struct rcu_sync *rsp)
>  		 * Nobody has yet been allowed the 'fast' path and thus we can
>  		 * avoid doing any sync(). The callback will get 'dropped'.
>  		 */
> -		BUG_ON(rsp->gp_state != GP_PASSED);
> +		if (WARN_ON(rsp->gp_state != GP_PASSED)) xxx(rsp);
>  	}
>  }
>  
> @@ -149,8 +156,9 @@ static void rcu_sync_func(struct rcu_head *rcu)
>  	struct rcu_sync *rsp = container_of(rcu, struct rcu_sync, cb_head);
>  	unsigned long flags;
>  
> -	BUG_ON(rsp->gp_state != GP_PASSED);
> -	BUG_ON(rsp->cb_state == CB_IDLE);
> +	if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);
> +	if (WARN_ON(rsp->gp_state != GP_PASSED)) xxx(rsp);
> +	if (WARN_ON(rsp->cb_state == CB_IDLE)) xxx(rsp);
>  
>  	spin_lock_irqsave(&rsp->rss_lock, flags);
>  	if (rsp->gp_count) {
> @@ -189,6 +197,7 @@ static void rcu_sync_func(struct rcu_head *rcu)
>  void rcu_sync_exit(struct rcu_sync *rsp)
>  {
>  	spin_lock_irq(&rsp->rss_lock);
> +	if (WARN_ON(rsp->gp_count <= 0)) xxx(rsp);
>  	if (!--rsp->gp_count) {
>  		if (rsp->cb_state == CB_IDLE) {
>  			rsp->cb_state = CB_PENDING;
> @@ -208,7 +217,7 @@ void rcu_sync_dtor(struct rcu_sync *rsp)
>  {
>  	int cb_state;
>  
> -	BUG_ON(rsp->gp_count);
> +	if (WARN_ON(rsp->gp_count)) xxx(rsp);
>  
>  	spin_lock_irq(&rsp->rss_lock);
>  	if (rsp->cb_state == CB_REPLAY)
> @@ -218,6 +227,6 @@ void rcu_sync_dtor(struct rcu_sync *rsp)
>  
>  	if (cb_state != CB_IDLE) {
>  		gp_ops[rsp->gp_type].wait();
> -		BUG_ON(rsp->cb_state != CB_IDLE);
> +		if (WARN_ON(rsp->cb_state != CB_IDLE)) xxx(rsp);
>  	}
>  }

Re: BUG_ON in rcu_sync_func triggered

[Nikolay Borisov]

On 09/13/2016 04:43 PM, Oleg Nesterov wrote:
> On 09/13, Oleg Nesterov wrote:
>>
>> OK... perhaps the unbalanced up_write... I'll try to look at freeze/thaw code,
> 
> Heh, yes, it looks racy or I am totally confused.
> 
>> could test the debugging patch below meanwhile?
> 
> Yes please. I'll send you another patch (hopefully fix) later, but it
> would be nice if you can test this patch to get more info.

I've already started testing with this patch on 4.4.20 this time to see
what happens, but I'll likely get results tomorrow. For now I wasn't
able to crash it.

> 
> Thanks,
> 
> Oleg.
> 
>> --- a/kernel/rcu/sync.c
>> +++ b/kernel/rcu/sync.c
>> @@ -82,6 +82,12 @@ void rcu_sync_init(struct rcu_sync *rsp, enum rcu_sync_type type)
>>  	rsp->gp_type = type;
>>  }
>>  
>> +static void xxx(struct rcu_sync *rsp)
>> +{
>> +	pr_crit("XXX: %p gp=%d cnt=%d cb=%d\n",
>> +		rsp, rsp->gp_state, rsp->gp_count, rsp->cb_state);
>> +}
>> +
>>  /**
>>   * rcu_sync_enter() - Force readers onto slowpath
>>   * @rsp: Pointer to rcu_sync structure to use for synchronization
>> @@ -102,13 +108,14 @@ void rcu_sync_enter(struct rcu_sync *rsp)
>>  	bool need_wait, need_sync;
>>  
>>  	spin_lock_irq(&rsp->rss_lock);
>> +	if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);
>>  	need_wait = rsp->gp_count++;
>>  	need_sync = rsp->gp_state == GP_IDLE;
>>  	if (need_sync)
>>  		rsp->gp_state = GP_PENDING;
>>  	spin_unlock_irq(&rsp->rss_lock);
>>  
>> -	BUG_ON(need_wait && need_sync);
>> +	if (WARN_ON(need_wait && need_sync)) xxx(rsp);
>>  
>>  	if (need_sync) {
>>  		gp_ops[rsp->gp_type].sync();
>> @@ -122,7 +129,7 @@ void rcu_sync_enter(struct rcu_sync *rsp)
>>  		 * Nobody has yet been allowed the 'fast' path and thus we can
>>  		 * avoid doing any sync(). The callback will get 'dropped'.
>>  		 */
>> -		BUG_ON(rsp->gp_state != GP_PASSED);
>> +		if (WARN_ON(rsp->gp_state != GP_PASSED)) xxx(rsp);
>>  	}
>>  }
>>  
>> @@ -149,8 +156,9 @@ static void rcu_sync_func(struct rcu_head *rcu)
>>  	struct rcu_sync *rsp = container_of(rcu, struct rcu_sync, cb_head);
>>  	unsigned long flags;
>>  
>> -	BUG_ON(rsp->gp_state != GP_PASSED);
>> -	BUG_ON(rsp->cb_state == CB_IDLE);
>> +	if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);
>> +	if (WARN_ON(rsp->gp_state != GP_PASSED)) xxx(rsp);
>> +	if (WARN_ON(rsp->cb_state == CB_IDLE)) xxx(rsp);
>>  
>>  	spin_lock_irqsave(&rsp->rss_lock, flags);
>>  	if (rsp->gp_count) {
>> @@ -189,6 +197,7 @@ static void rcu_sync_func(struct rcu_head *rcu)
>>  void rcu_sync_exit(struct rcu_sync *rsp)
>>  {
>>  	spin_lock_irq(&rsp->rss_lock);
>> +	if (WARN_ON(rsp->gp_count <= 0)) xxx(rsp);
>>  	if (!--rsp->gp_count) {
>>  		if (rsp->cb_state == CB_IDLE) {
>>  			rsp->cb_state = CB_PENDING;
>> @@ -208,7 +217,7 @@ void rcu_sync_dtor(struct rcu_sync *rsp)
>>  {
>>  	int cb_state;
>>  
>> -	BUG_ON(rsp->gp_count);
>> +	if (WARN_ON(rsp->gp_count)) xxx(rsp);
>>  
>>  	spin_lock_irq(&rsp->rss_lock);
>>  	if (rsp->cb_state == CB_REPLAY)
>> @@ -218,6 +227,6 @@ void rcu_sync_dtor(struct rcu_sync *rsp)
>>  
>>  	if (cb_state != CB_IDLE) {
>>  		gp_ops[rsp->gp_type].wait();
>> -		BUG_ON(rsp->cb_state != CB_IDLE);
>> +		if (WARN_ON(rsp->cb_state != CB_IDLE)) xxx(rsp);
>>  	}
>>  }
> 

Re: BUG_ON in rcu_sync_func triggered

[Nikolay Borisov]

On 09/13/2016 05:35 PM, Nikolay Borisov wrote:
> 
> 
> On 09/13/2016 04:43 PM, Oleg Nesterov wrote:
>> On 09/13, Oleg Nesterov wrote:
>>>
>>> OK... perhaps the unbalanced up_write... I'll try to look at freeze/thaw code,
>>
>> Heh, yes, it looks racy or I am totally confused.
>>
>>> could test the debugging patch below meanwhile?
>>
>> Yes please. I'll send you another patch (hopefully fix) later, but it
>> would be nice if you can test this patch to get more info.
> 
> I've already started testing with this patch on 4.4.20 this time to see
> what happens, but I'll likely get results tomorrow. For now I wasn't
> able to crash it.

Actually forget that, here is a warning that this triggered: 

[  844.284959] ------------[ cut here ]------------
[  844.290454] WARNING: CPU: 2 PID: 1900 at kernel/rcu/sync.c:160 rcu_sync_func+0xc8/0x150()
[  844.300154] Modules linked in: xt_state act_police cls_basic sch_ingress veth rbd libceph openvswitch nf_defrag_ipv6 nf_nat_ftp nf_conntrack_ftp xt_owner iptable_mangle xt_nat iptable_nat nf_nat_ipv4 nf_nat xt_CT iptable_raw nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ip6table_filter ip6_tables rdma_ucm ib_ucm ib_uverbs rdma_cm iw_cm dm_mirror dm_region_hash dm_log ib_umad ib_ipoib ib_cm ib_sa ib_mad ib_core ib_addr ipv6 x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul ixgbe mdio ipmi_devintf ipmi_si ipmi_msghandler igb i2c_algo_bit sb_edac edac_core i2c_i801 lpc_ich mfd_core ioatdma dca shpchp dm_thin_pool dm_bio_prison dm_persistent_data dm_bufio
[  844.375006] CPU: 2 PID: 1900 Comm: fio Not tainted 4.4.20-clouder1 #9
[  844.382524] Hardware name: Supermicro X9DRW/X9DRW, BIOS 1.0b 10/11/2012
[  844.390241]  0000000000000000 ffff880277d03d78 ffffffff81307a9b 000000000000076c
[  844.399416]  0000000000000000 0000000000000000 00000000000000a0 ffff880277d03db8
[  844.408598]  ffffffff81054a85 ffff880277d03dc8 ffff88047527daa0 ffff88047527da78
[  844.417771] Call Trace:
[  844.420822]  <IRQ>  [<ffffffff81307a9b>] dump_stack+0x6b/0xa0
[  844.427659]  [<ffffffff81054a85>] warn_slowpath_common+0x95/0xe0
[  844.434695]  [<ffffffff81054aea>] warn_slowpath_null+0x1a/0x20
[  844.441532]  [<ffffffff810ab788>] rcu_sync_func+0xc8/0x150
[  844.447983]  [<ffffffff810b0620>] rcu_process_callbacks+0x290/0x740
[  844.455310]  [<ffffffff810bbc52>] ? ktime_get+0x52/0xc0
[  844.461459]  [<ffffffff810590f3>] __do_softirq+0x113/0x330
[  844.467909]  [<ffffffff810593e5>] irq_exit+0x75/0x80
[  844.473775]  [<ffffffff8163ea16>] smp_apic_timer_interrupt+0x46/0x55
[  844.481200]  [<ffffffff8163d069>] apic_timer_interrupt+0x89/0x90
[  844.488234]  <EOI>  [<ffffffff811477b0>] ? shrink_inactive_list+0x1e0/0x5c0
[  844.496426]  [<ffffffff811477a8>] ? shrink_inactive_list+0x1d8/0x5c0
[  844.503848]  [<ffffffff8113c468>] ? global_dirty_limits+0x98/0xc0
[  844.510984]  [<ffffffff8113c909>] ? throttle_vm_writeout+0x39/0xc0
[  844.518214]  [<ffffffff811481c9>] shrink_lruvec+0x289/0x390
[  844.524754]  [<ffffffff8119a6f9>] ? mem_cgroup_iter+0x2a9/0x3e0
[  844.531687]  [<ffffffff811ce98c>] ? wb_queue_work+0x8c/0x100
[  844.538333]  [<ffffffff811483fa>] shrink_zone+0x12a/0x360
[  844.544686]  [<ffffffff8119e9b8>] ? vmpressure+0x88/0x90
[  844.550943]  [<ffffffff811489ad>] do_try_to_free_pages+0x17d/0x450
[  844.558174]  [<ffffffff81199451>] ? mem_cgroup_select_victim_node+0x1d1/0x1f0
[  844.566468]  [<ffffffff81148d35>] try_to_free_mem_cgroup_pages+0xb5/0x190
[  844.574375]  [<ffffffff8119d9dd>] try_charge+0x22d/0x720
[  844.580631]  [<ffffffff8113025e>] ? find_get_entry+0x3e/0xd0
[  844.587281]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
[  844.593827]  [<ffffffff8130c443>] ? radix_tree_lookup_slot+0x13/0x30
[  844.601251]  [<ffffffff8119e637>] mem_cgroup_try_charge+0x57/0x150
[  844.608478]  [<ffffffff81131b2c>] __add_to_page_cache_locked+0x4c/0x270
[  844.616194]  [<ffffffff811db990>] ? __block_commit_write+0x80/0xb0
[  844.623419]  [<ffffffff81131d78>] add_to_page_cache_lru+0x28/0x80
[  844.630548]  [<ffffffff81131e67>] pagecache_get_page+0x97/0x1e0
[  844.637484]  [<ffffffff81131fdb>] grab_cache_page_write_begin+0x2b/0x50
[  844.645202]  [<ffffffff8123ff2d>] ext4_da_write_begin+0x17d/0x330
[  844.652334]  [<ffffffff8123c716>] ? ext4_dirty_inode+0x66/0x80
[  844.659167]  [<ffffffff8112ff80>] generic_perform_write+0xd0/0x1f0
[  844.666385]  [<ffffffff81132916>] __generic_file_write_iter+0x196/0x1f0
[  844.674102]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
[  844.680648]  [<ffffffff81233b0f>] ext4_file_write_iter+0x11f/0x3a0
[  844.687874]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
[  844.694418]  [<ffffffff812339f0>] ? ext4_unwritten_wait+0xc0/0xc0
[  844.701547]  [<ffffffff811f1a1e>] aio_run_iocb+0x1ee/0x290
[  844.707999]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
[  844.714537]  [<ffffffff811f1de1>] do_io_submit+0x321/0x530
[  844.720989]  [<ffffffff811f1388>] ? SyS_io_getevents+0x58/0xc0
[  844.727828]  [<ffffffff81002017>] ? trace_hardirqs_on_thunk+0x17/0x19
[  844.735345]  [<ffffffff811f2000>] SyS_io_submit+0x10/0x20
[  844.741701]  [<ffffffff8163c357>] entry_SYSCALL_64_fastpath+0x12/0x6a
[  844.749230] ---[ end trace 5f72aeec215954f4 ]---
[  844.754708] XXX: ffff88047527da78 gp=2 cnt=0 cb=1

Re: BUG_ON in rcu_sync_func triggered

[Nikolay Borisov]

On 09/13/2016 05:38 PM, Nikolay Borisov wrote:
> 
> 
> On 09/13/2016 05:35 PM, Nikolay Borisov wrote:
>>
>>
>> On 09/13/2016 04:43 PM, Oleg Nesterov wrote:
>>> On 09/13, Oleg Nesterov wrote:
>>>>
>>>> OK... perhaps the unbalanced up_write... I'll try to look at freeze/thaw code,
>>>
>>> Heh, yes, it looks racy or I am totally confused.
>>>
>>>> could test the debugging patch below meanwhile?
>>>
>>> Yes please. I'll send you another patch (hopefully fix) later, but it
>>> would be nice if you can test this patch to get more info.
>>
>> I've already started testing with this patch on 4.4.20 this time to see
>> what happens, but I'll likely get results tomorrow. For now I wasn't
>> able to crash it.
> 
> Actually forget that, here is a warning that this triggered: 
> 
> [  844.284959] ------------[ cut here ]------------
> [  844.290454] WARNING: CPU: 2 PID: 1900 at kernel/rcu/sync.c:160 rcu_sync_func+0xc8/0x150()
> [  844.300154] Modules linked in: xt_state act_police cls_basic sch_ingress veth rbd libceph openvswitch nf_defrag_ipv6 nf_nat_ftp nf_conntrack_ftp xt_owner iptable_mangle xt_nat iptable_nat nf_nat_ipv4 nf_nat xt_CT iptable_raw nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ip6table_filter ip6_tables rdma_ucm ib_ucm ib_uverbs rdma_cm iw_cm dm_mirror dm_region_hash dm_log ib_umad ib_ipoib ib_cm ib_sa ib_mad ib_core ib_addr ipv6 x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul ixgbe mdio ipmi_devintf ipmi_si ipmi_msghandler igb i2c_algo_bit sb_edac edac_core i2c_i801 lpc_ich mfd_core ioatdma dca shpchp dm_thin_pool dm_bio_prison dm_persistent_data dm_bufio
> [  844.375006] CPU: 2 PID: 1900 Comm: fio Not tainted 4.4.20-clouder1 #9
> [  844.382524] Hardware name: Supermicro X9DRW/X9DRW, BIOS 1.0b 10/11/2012
> [  844.390241]  0000000000000000 ffff880277d03d78 ffffffff81307a9b 000000000000076c
> [  844.399416]  0000000000000000 0000000000000000 00000000000000a0 ffff880277d03db8
> [  844.408598]  ffffffff81054a85 ffff880277d03dc8 ffff88047527daa0 ffff88047527da78
> [  844.417771] Call Trace:
> [  844.420822]  <IRQ>  [<ffffffff81307a9b>] dump_stack+0x6b/0xa0
> [  844.427659]  [<ffffffff81054a85>] warn_slowpath_common+0x95/0xe0
> [  844.434695]  [<ffffffff81054aea>] warn_slowpath_null+0x1a/0x20
> [  844.441532]  [<ffffffff810ab788>] rcu_sync_func+0xc8/0x150
> [  844.447983]  [<ffffffff810b0620>] rcu_process_callbacks+0x290/0x740
> [  844.455310]  [<ffffffff810bbc52>] ? ktime_get+0x52/0xc0
> [  844.461459]  [<ffffffff810590f3>] __do_softirq+0x113/0x330
> [  844.467909]  [<ffffffff810593e5>] irq_exit+0x75/0x80
> [  844.473775]  [<ffffffff8163ea16>] smp_apic_timer_interrupt+0x46/0x55
> [  844.481200]  [<ffffffff8163d069>] apic_timer_interrupt+0x89/0x90
> [  844.488234]  <EOI>  [<ffffffff811477b0>] ? shrink_inactive_list+0x1e0/0x5c0
> [  844.496426]  [<ffffffff811477a8>] ? shrink_inactive_list+0x1d8/0x5c0
> [  844.503848]  [<ffffffff8113c468>] ? global_dirty_limits+0x98/0xc0
> [  844.510984]  [<ffffffff8113c909>] ? throttle_vm_writeout+0x39/0xc0
> [  844.518214]  [<ffffffff811481c9>] shrink_lruvec+0x289/0x390
> [  844.524754]  [<ffffffff8119a6f9>] ? mem_cgroup_iter+0x2a9/0x3e0
> [  844.531687]  [<ffffffff811ce98c>] ? wb_queue_work+0x8c/0x100
> [  844.538333]  [<ffffffff811483fa>] shrink_zone+0x12a/0x360
> [  844.544686]  [<ffffffff8119e9b8>] ? vmpressure+0x88/0x90
> [  844.550943]  [<ffffffff811489ad>] do_try_to_free_pages+0x17d/0x450
> [  844.558174]  [<ffffffff81199451>] ? mem_cgroup_select_victim_node+0x1d1/0x1f0
> [  844.566468]  [<ffffffff81148d35>] try_to_free_mem_cgroup_pages+0xb5/0x190
> [  844.574375]  [<ffffffff8119d9dd>] try_charge+0x22d/0x720
> [  844.580631]  [<ffffffff8113025e>] ? find_get_entry+0x3e/0xd0
> [  844.587281]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
> [  844.593827]  [<ffffffff8130c443>] ? radix_tree_lookup_slot+0x13/0x30
> [  844.601251]  [<ffffffff8119e637>] mem_cgroup_try_charge+0x57/0x150
> [  844.608478]  [<ffffffff81131b2c>] __add_to_page_cache_locked+0x4c/0x270
> [  844.616194]  [<ffffffff811db990>] ? __block_commit_write+0x80/0xb0
> [  844.623419]  [<ffffffff81131d78>] add_to_page_cache_lru+0x28/0x80
> [  844.630548]  [<ffffffff81131e67>] pagecache_get_page+0x97/0x1e0
> [  844.637484]  [<ffffffff81131fdb>] grab_cache_page_write_begin+0x2b/0x50
> [  844.645202]  [<ffffffff8123ff2d>] ext4_da_write_begin+0x17d/0x330
> [  844.652334]  [<ffffffff8123c716>] ? ext4_dirty_inode+0x66/0x80
> [  844.659167]  [<ffffffff8112ff80>] generic_perform_write+0xd0/0x1f0
> [  844.666385]  [<ffffffff81132916>] __generic_file_write_iter+0x196/0x1f0
> [  844.674102]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
> [  844.680648]  [<ffffffff81233b0f>] ext4_file_write_iter+0x11f/0x3a0
> [  844.687874]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
> [  844.694418]  [<ffffffff812339f0>] ? ext4_unwritten_wait+0xc0/0xc0
> [  844.701547]  [<ffffffff811f1a1e>] aio_run_iocb+0x1ee/0x290
> [  844.707999]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
> [  844.714537]  [<ffffffff811f1de1>] do_io_submit+0x321/0x530
> [  844.720989]  [<ffffffff811f1388>] ? SyS_io_getevents+0x58/0xc0
> [  844.727828]  [<ffffffff81002017>] ? trace_hardirqs_on_thunk+0x17/0x19
> [  844.735345]  [<ffffffff811f2000>] SyS_io_submit+0x10/0x20
> [  844.741701]  [<ffffffff8163c357>] entry_SYSCALL_64_fastpath+0x12/0x6a
> [  844.749230] ---[ end trace 5f72aeec215954f4 ]---
> [  844.754708] XXX: ffff88047527da78 gp=2 cnt=0 cb=1
> 

This is :

if (WARN_ON(rsp->gp_state != GP_PASSED)) xxx(rsp);

Re: BUG_ON in rcu_sync_func triggered

[Oleg Nesterov]

On 09/13, Nikolay Borisov wrote:
>
> On 09/13/2016 05:35 PM, Nikolay Borisov wrote:
> >
> > On 09/13/2016 04:43 PM, Oleg Nesterov wrote:
> >> On 09/13, Oleg Nesterov wrote:
> >>>
> >>> OK... perhaps the unbalanced up_write... I'll try to look at freeze/thaw code,
> >>
> >> Heh, yes, it looks racy or I am totally confused.
> >>
> >>> could test the debugging patch below meanwhile?
> >>
> >> Yes please. I'll send you another patch (hopefully fix) later, but it
> >> would be nice if you can test this patch to get more info.
> >
> > I've already started testing with this patch on 4.4.20 this time

I think it would be better to stay with the same kernel version to
debug the problem...

> Actually forget that, here is a warning that this triggered:
>
> [  844.290454] WARNING: CPU: 2 PID: 1900 at kernel/rcu/sync.c:160 rcu_sync_func+0xc8/0x150()
> ...
> [  844.754708] XXX: ffff88047527da78 gp=2 cnt=0 cb=1

Hmm. Thanks. Please show us all the warnings you get.

Oleg.

Re: BUG_ON in rcu_sync_func triggered

[Nikolay Borisov]

On 09/13/2016 06:20 PM, Oleg Nesterov wrote:
> On 09/13, Nikolay Borisov wrote:
>>
>> On 09/13/2016 05:35 PM, Nikolay Borisov wrote:
>>>
>>> On 09/13/2016 04:43 PM, Oleg Nesterov wrote:
>>>> On 09/13, Oleg Nesterov wrote:
>>>>>
>>>>> OK... perhaps the unbalanced up_write... I'll try to look at freeze/thaw code,
>>>>
>>>> Heh, yes, it looks racy or I am totally confused.
>>>>
>>>>> could test the debugging patch below meanwhile?
>>>>
>>>> Yes please. I'll send you another patch (hopefully fix) later, but it
>>>> would be nice if you can test this patch to get more info.
>>>
>>> I've already started testing with this patch on 4.4.20 this time
> 
> I think it would be better to stay with the same kernel version to
> debug the problem...
> 
>> Actually forget that, here is a warning that this triggered:
>>
>> [  844.290454] WARNING: CPU: 2 PID: 1900 at kernel/rcu/sync.c:160 rcu_sync_func+0xc8/0x150()
>> ...
>> [  844.754708] XXX: ffff88047527da78 gp=2 cnt=0 cb=1
> 
> Hmm. Thanks. Please show us all the warnings you get.

What I showed you yesterday was the only warning that I got. On the same kernel another run produced the following warnings: 

[  556.869624] ------------[ cut here ]------------
[  556.875128] WARNING: CPU: 6 PID: 20210 at kernel/rcu/sync.c:111 rcu_sync_enter+0x148/0x1a0()
[  556.885142] Modules linked in: xt_state act_police cls_basic sch_ingress veth rbd libceph openvswitch nf_defrag_ipv6 nf_nat_ftp nf_conntrack_ftp xt_owner iptable_mangle xt_nat iptable_nat nf_nat_ipv4 nf_nat xt_CT iptable_raw nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ip6table_filter ip6_tables rdma_ucm ib_ucm ib_uverbs rdma_cm iw_cm dm_mirror dm_region_hash dm_log ib_umad ib_ipoib ib_cm ib_sa ib_mad ib_core ib_addr ipv6 x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul ixgbe mdio ipmi_devintf ipmi_si ipmi_msghandler igb i2c_algo_bit sb_edac edac_core i2c_i801 lpc_ich mfd_core ioatdma dca shpchp dm_thin_pool dm_bio_prison dm_persistent_data dm_bufio
[  556.960028] CPU: 6 PID: 20210 Comm: fsfreeze Not tainted 4.4.20-clouder1 #9
[  556.968143] Hardware name: Supermicro X9DRW/X9DRW, BIOS 1.0b 10/11/2012
[  556.975963]  0000000000000000 ffff880256b43cf8 ffffffff81307a9b 0000000000004ef2
[  556.985182]  0000000000000000 0000000000000000 000000000000006f ffff880256b43d38
[  556.994383]  ffffffff81054a85 ffff880473326b10 ffff880473326b08 ffff880473326b10
[  557.003589] Call Trace:
[  557.006656]  [<ffffffff81307a9b>] dump_stack+0x6b/0xa0
[  557.012737]  [<ffffffff81054a85>] warn_slowpath_common+0x95/0xe0
[  557.019781]  [<ffffffff81054aea>] warn_slowpath_null+0x1a/0x20
[  557.026645]  [<ffffffff810ab9a8>] rcu_sync_enter+0x148/0x1a0
[  557.033309]  [<ffffffff8109c9be>] percpu_down_write+0x1e/0xf0
[  557.040074]  [<ffffffff81315683>] ? call_rwsem_down_write_failed+0x13/0x20
[  557.048092]  [<ffffffff811a868b>] freeze_super+0xab/0x1b0
[  557.054456]  [<ffffffff811b7c0d>] do_vfs_ioctl+0x29d/0x560
[  557.060920]  [<ffffffff811aae7e>] ? SYSC_newfstat+0x2e/0x40
[  557.067480]  [<ffffffff811b7f62>] SyS_ioctl+0x92/0xa0
[  557.073465]  [<ffffffff8163c357>] entry_SYSCALL_64_fastpath+0x12/0x6a
[  557.081015] ---[ end trace fc087420ac1d8f16 ]---
[  557.086507] XXX: ffff880473326b08 gp=2 cnt=-1 cb=1
[  557.092326] rbd: rbd19: added with size 0x500000000

This is: if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);



[  557.094835] ------------[ cut here ]------------
[  557.094841] WARNING: CPU: 1 PID: 0 at kernel/rcu/sync.c:159 rcu_sync_func+0xf9/0x150()
[  557.094873] Modules linked in: xt_state act_police cls_basic sch_ingress veth rbd libceph openvswitch nf_defrag_ipv6 nf_nat_ftp nf_conntrack_ftp xt_owner iptable_mangle xt_nat iptable_nat nf_nat_ipv4 nf_nat xt_CT iptable_raw nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ip6table_filter ip6_tables rdma_ucm ib_ucm ib_uverbs rdma_cm iw_cm dm_mirror dm_region_hash dm_log ib_umad ib_ipoib ib_cm ib_sa ib_mad ib_core ib_addr ipv6 x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul ixgbe mdio ipmi_devintf ipmi_si ipmi_msghandler igb i2c_algo_bit sb_edac edac_core i2c_i801 lpc_ich mfd_core ioatdma dca shpchp dm_thin_pool dm_bio_prison dm_persistent_data dm_bufio
[  557.094876] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G        W       4.4.20-clouder1 #9
[  557.094877] Hardware name: Supermicro X9DRW/X9DRW, BIOS 1.0b 10/11/2012
[  557.094879]  0000000000000000 ffff880277c83d78 ffffffff81307a9b 0000000000000000
[  557.094881]  0000000000000000 0000000000000000 000000000000009f ffff880277c83db8
[  557.094882]  ffffffff81054a85 0000000000000000 ffff880473326bc0 ffff880473326b98
[  557.094882] Call Trace:
[  557.094889]  <IRQ>  [<ffffffff81307a9b>] dump_stack+0x6b/0xa0
[  557.094892]  [<ffffffff81054a85>] warn_slowpath_common+0x95/0xe0
[  557.094893]  [<ffffffff81054aea>] warn_slowpath_null+0x1a/0x20
[  557.094894]  [<ffffffff810ab7b9>] rcu_sync_func+0xf9/0x150
[  557.094897]  [<ffffffff810b0620>] rcu_process_callbacks+0x290/0x740
[  557.094900]  [<ffffffff810590f3>] __do_softirq+0x113/0x330
[  557.094902]  [<ffffffff810593e5>] irq_exit+0x75/0x80
[  557.094905]  [<ffffffff8163ea16>] smp_apic_timer_interrupt+0x46/0x55
[  557.094907]  [<ffffffff8163d069>] apic_timer_interrupt+0x89/0x90
[  557.094911]  <EOI>  [<ffffffff81530cbc>] ? cpuidle_enter_state+0x14c/0x2e0
[  557.094912]  [<ffffffff81530cb1>] ? cpuidle_enter_state+0x141/0x2e0
[  557.094914]  [<ffffffff81530e67>] cpuidle_enter+0x17/0x20
[  557.094916]  [<ffffffff81096d70>] cpu_startup_entry+0x310/0x370
[  557.094919]  [<ffffffff810c2aac>] ? clockevents_config_and_register+0x2c/0x40
[  557.094923]  [<ffffffff81035359>] start_secondary+0xf9/0x100
[  557.094924] ---[ end trace fc087420ac1d8f17 ]---
[  557.094925] XXX: ffff880473326b98 gp=2 cnt=-1 cb=1

This is: 
if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);

I'd say the warnings are pretty consistent between 4.4.14 and 4.4.20. 
Another run on the same kernel (no reboots between tries) produced the following: 

[  700.981151] ------------[ cut here ]------------
[  700.986643] WARNING: CPU: 3 PID: 2428 at kernel/rcu/sync.c:111 rcu_sync_enter+0x148/0x1a0()
[  700.996541] Modules linked in: xt_state act_police cls_basic sch_ingress veth rbd libceph openvswitch nf_defrag_ipv6 nf_nat_ftp nf_conntrack_ftp xt_owner iptable_mangle xt_nat iptable_nat nf_nat_ipv4 nf_nat xt_CT iptable_raw nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ip6table_filter ip6_tables rdma_ucm ib_ucm ib_uverbs rdma_cm iw_cm dm_mirror dm_region_hash dm_log ib_umad ib_ipoib ib_cm ib_sa ib_mad ib_core ib_addr ipv6 x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul ixgbe mdio ipmi_devintf ipmi_si ipmi_msghandler igb i2c_algo_bit sb_edac edac_core i2c_i801 lpc_ich mfd_core ioatdma dca shpchp dm_thin_pool dm_bio_prison dm_persistent_data dm_bufio
[  701.071212] CPU: 3 PID: 2428 Comm: fsfreeze Tainted: G        W       4.4.20-clouder1 #9
[  701.080816] Hardware name: Supermicro X9DRW/X9DRW, BIOS 1.0b 10/11/2012
[  701.088530]  0000000000000000 ffff88006b5efcf8 ffffffff81307a9b 000000000000097c
[  701.097711]  0000000000000000 0000000000000000 000000000000006f ffff88006b5efd38
[  701.106870]  ffffffff81054a85 ffff880079ab9310 ffff880079ab9308 ffff880079ab9310
[  701.116039] Call Trace:
[  701.119084]  [<ffffffff81307a9b>] dump_stack+0x6b/0xa0
[  701.125149]  [<ffffffff81054a85>] warn_slowpath_common+0x95/0xe0
[  701.132184]  [<ffffffff81054aea>] warn_slowpath_null+0x1a/0x20
[  701.139027]  [<ffffffff810ab9a8>] rcu_sync_enter+0x148/0x1a0
[  701.145674]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
[  701.152221]  [<ffffffff8109c9be>] percpu_down_write+0x1e/0xf0
[  701.158962]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
[  701.165511]  [<ffffffff811a868b>] freeze_super+0xab/0x1b0
[  701.171867]  [<ffffffff811b7c0d>] do_vfs_ioctl+0x29d/0x560
[  701.178319]  [<ffffffff811aae7e>] ? SYSC_newfstat+0x2e/0x40
[  701.184959]  [<ffffffff811b7f62>] SyS_ioctl+0x92/0xa0
[  701.190926]  [<ffffffff8163c357>] entry_SYSCALL_64_fastpath+0x12/0x6a
[  701.198446] ---[ end trace fc087420ac1d8f18 ]---
[  701.203915] XXX: ffff880079ab9308 gp=0 cnt=-1 cb=0

[  701.209624] ------------[ cut here ]------------
[  701.215193] WARNING: CPU: 3 PID: 2428 at kernel/rcu/sync.c:118 rcu_sync_enter+0x7e/0x1a0()
[  701.224996] Modules linked in: xt_state act_police cls_basic sch_ingress veth rbd libceph openvswitch nf_defrag_ipv6 nf_nat_ftp nf_conntrack_ftp xt_owner iptable_mangle xt_nat iptable_nat nf_nat_ipv4 nf_nat xt_CT iptable_raw nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ip6table_filter ip6_tables rdma_ucm ib_ucm ib_uverbs rdma_cm iw_cm dm_mirror dm_region_hash dm_log ib_umad ib_ipoib ib_cm ib_sa ib_mad ib_core ib_addr ipv6 x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul ixgbe mdio ipmi_devintf ipmi_si ipmi_msghandler igb i2c_algo_bit sb_edac edac_core i2c_i801 lpc_ich mfd_core ioatdma dca shpchp dm_thin_pool dm_bio_prison dm_persistent_data dm_bufio
[  701.299721] CPU: 3 PID: 2428 Comm: fsfreeze Tainted: G        W       4.4.20-clouder1 #9
[  701.309325] Hardware name: Supermicro X9DRW/X9DRW, BIOS 1.0b 10/11/2012
[  701.317038]  0000000000000000 ffff88006b5efcf8 ffffffff81307a9b 000000000000097c
[  701.326203]  0000000000000000 0000000000000000 0000000000000076 ffff88006b5efd38
[  701.335382]  ffffffff81054a85 0000000000000007 ffff880079ab9308 ffff880079ab9310
[  701.344556] Call Trace:
[  701.347610]  [<ffffffff81307a9b>] dump_stack+0x6b/0xa0
[  701.353674]  [<ffffffff81054a85>] warn_slowpath_common+0x95/0xe0
[  701.360705]  [<ffffffff81054aea>] warn_slowpath_null+0x1a/0x20
[  701.367543]  [<ffffffff810ab8de>] rcu_sync_enter+0x7e/0x1a0
[  701.374090]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
[  701.380637]  [<ffffffff8109c9be>] percpu_down_write+0x1e/0xf0
[  701.387379]  [<ffffffff8107b0b2>] ? __might_sleep+0x52/0x90
[  701.393928]  [<ffffffff811a868b>] freeze_super+0xab/0x1b0
[  701.400281]  [<ffffffff811b7c0d>] do_vfs_ioctl+0x29d/0x560
[  701.406737]  [<ffffffff811aae7e>] ? SYSC_newfstat+0x2e/0x40
[  701.413283]  [<ffffffff811b7f62>] SyS_ioctl+0x92/0xa0
[  701.419249]  [<ffffffff8163c357>] entry_SYSCALL_64_fastpath+0x12/0x6a
[  701.426773] ---[ end trace fc087420ac1d8f19 ]---
[  701.432273] XXX: ffff880079ab9308 gp=1 cnt=0 cb=0

Regards, 
Nikolay 


> 
> Oleg.
> 

Re: BUG_ON in rcu_sync_func triggered

[Oleg Nesterov]

On 09/14, Nikolay Borisov wrote:
>
> [  557.006656]  [<ffffffff81307a9b>] dump_stack+0x6b/0xa0
> [  557.012737]  [<ffffffff81054a85>] warn_slowpath_common+0x95/0xe0
> [  557.019781]  [<ffffffff81054aea>] warn_slowpath_null+0x1a/0x20
> [  557.026645]  [<ffffffff810ab9a8>] rcu_sync_enter+0x148/0x1a0
> [  557.033309]  [<ffffffff8109c9be>] percpu_down_write+0x1e/0xf0
> [  557.040074]  [<ffffffff81315683>] ? call_rwsem_down_write_failed+0x13/0x20
> [  557.048092]  [<ffffffff811a868b>] freeze_super+0xab/0x1b0
> [  557.054456]  [<ffffffff811b7c0d>] do_vfs_ioctl+0x29d/0x560
> [  557.060920]  [<ffffffff811aae7e>] ? SYSC_newfstat+0x2e/0x40
> [  557.067480]  [<ffffffff811b7f62>] SyS_ioctl+0x92/0xa0
> [  557.073465]  [<ffffffff8163c357>] entry_SYSCALL_64_fastpath+0x12/0x6a
> [  557.081015] ---[ end trace fc087420ac1d8f16 ]---
> [  557.086507] XXX: ffff880473326b08 gp=2 cnt=-1 cb=1
> [  557.092326] rbd: rbd19: added with size 0x500000000
>
> This is: if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);

Thanks a lot. This is what I wanted to see. However, I can't understand why
you did not hit the similar WARN_ON(rsp->gp_count <= 0) in rcu_sync_exit()
before that.

OK, in any case this doesn't look as a bug in rcu/sync.c, could you please
try the fix below? Not sure it will help, perhaps there is something else...
No need to revert the previous debugging patch.

Thanks,

Oleg.


diff --git a/fs/super.c b/fs/super.c
index d78b984..a90bdff 100644
--- a/fs/super.c
+++ b/fs/super.c
@@ -1344,7 +1344,9 @@ int thaw_super(struct super_block *sb)
 	int error;
 
 	down_write(&sb->s_umount);
-	if (sb->s_writers.frozen == SB_UNFROZEN) {
+	if (sb->s_writers.frozen != SB_FREEZE_COMPLETE) {
+		if (sb->s_writers.frozen != SB_UNFROZEN)
+			pr_crit("THAW: hit the race: %d\n", sb->s_writers.frozen);
 		up_write(&sb->s_umount);
 		return -EINVAL;
 	}

Re: BUG_ON in rcu_sync_func triggered

[Nikolay Borisov]

On Wed, Sep 14, 2016 at 3:58 PM, Oleg Nesterov <oleg@redhat.com> wrote:
> On 09/14, Nikolay Borisov wrote:
>>
>> [  557.006656]  [<ffffffff81307a9b>] dump_stack+0x6b/0xa0
>> [  557.012737]  [<ffffffff81054a85>] warn_slowpath_common+0x95/0xe0
>> [  557.019781]  [<ffffffff81054aea>] warn_slowpath_null+0x1a/0x20
>> [  557.026645]  [<ffffffff810ab9a8>] rcu_sync_enter+0x148/0x1a0
>> [  557.033309]  [<ffffffff8109c9be>] percpu_down_write+0x1e/0xf0
>> [  557.040074]  [<ffffffff81315683>] ? call_rwsem_down_write_failed+0x13/0x20
>> [  557.048092]  [<ffffffff811a868b>] freeze_super+0xab/0x1b0
>> [  557.054456]  [<ffffffff811b7c0d>] do_vfs_ioctl+0x29d/0x560
>> [  557.060920]  [<ffffffff811aae7e>] ? SYSC_newfstat+0x2e/0x40
>> [  557.067480]  [<ffffffff811b7f62>] SyS_ioctl+0x92/0xa0
>> [  557.073465]  [<ffffffff8163c357>] entry_SYSCALL_64_fastpath+0x12/0x6a
>> [  557.081015] ---[ end trace fc087420ac1d8f16 ]---
>> [  557.086507] XXX: ffff880473326b08 gp=2 cnt=-1 cb=1
>> [  557.092326] rbd: rbd19: added with size 0x500000000
>>
>> This is: if (WARN_ON(rsp->gp_count < 0)) xxx(rsp);
>
> Thanks a lot. This is what I wanted to see. However, I can't understand why
> you did not hit the similar WARN_ON(rsp->gp_count <= 0) in rcu_sync_exit()
> before that.
>
> OK, in any case this doesn't look as a bug in rcu/sync.c, could you please
> try the fix below? Not sure it will help, perhaps there is something else...
> No need to revert the previous debugging patch.
>
> Thanks,
>
> Oleg.
>
>
> diff --git a/fs/super.c b/fs/super.c
> index d78b984..a90bdff 100644
> --- a/fs/super.c
> +++ b/fs/super.c
> @@ -1344,7 +1344,9 @@ int thaw_super(struct super_block *sb)
>         int error;
>
>         down_write(&sb->s_umount);
> -       if (sb->s_writers.frozen == SB_UNFROZEN) {
> +       if (sb->s_writers.frozen != SB_FREEZE_COMPLETE) {
> +               if (sb->s_writers.frozen != SB_UNFROZEN)
> +                       pr_crit("THAW: hit the race: %d\n", sb->s_writers.frozen);
>                 up_write(&sb->s_umount);
>                 return -EINVAL;
>         }
>

I was away on holiday so that's why I was silent. However, with this
patch applied I couldn't reproduce the issue nor the pr_crit
triggered. Have you had any moments of epiphany re. this issue? Should
some FS people be involved in the discussion?

Re: BUG_ON in rcu_sync_func triggered

[Oleg Nesterov]

On 09/23, Nikolay Borisov wrote:
>
> > --- a/fs/super.c
> > +++ b/fs/super.c
> > @@ -1344,7 +1344,9 @@ int thaw_super(struct super_block *sb)
> >         int error;
> >
> >         down_write(&sb->s_umount);
> > -       if (sb->s_writers.frozen == SB_UNFROZEN) {
> > +       if (sb->s_writers.frozen != SB_FREEZE_COMPLETE) {
> > +               if (sb->s_writers.frozen != SB_UNFROZEN)
> > +                       pr_crit("THAW: hit the race: %d\n", sb->s_writers.frozen);
> >                 up_write(&sb->s_umount);
> >                 return -EINVAL;
> >         }
> >
> 
> I was away on holiday so that's why I was silent. However, with this
> patch applied I couldn't reproduce the issue nor the pr_crit
> triggered.

Great, thanks a lot.

> Have you had any moments of epiphany re. this issue?

Well, after I failed to find any problem in rcu/sync.c I started to
look at the callers and found this race.

> Should
> some FS people be involved in the discussion?

Sure. I'll send the patch with CC's. Probably next week, I am too
busy right now.

Thanks Nikolay,

Oleg.