Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1741336 > unrolled thread

Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule be Tasks RCU quiescent state

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state Sasha Levin <levinsasha928@gmail.com> - 2017-09-28 11:40 +0200
    Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-28 14:40 +0200
      Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state "Levin, Alexander (Sasha Levin)" <alexander.levin@verizon.com> - 2017-09-28 17:50 +0200
        Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state Peter Zijlstra <peterz@infradead.org> - 2017-09-28 18:10 +0200
          Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state "Levin, Alexander (Sasha Levin)" <alexander.levin@verizon.com> - 2017-09-28 18:30 +0200
        Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-28 18:10 +0200
          Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state Peter Zijlstra <peterz@infradead.org> - 2017-09-28 18:20 +0200
            Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-28 18:40 +0200
          Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state Boqun Feng <boqun.feng@gmail.com> - 2017-09-29 11:40 +0200
            Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state Paolo Bonzini <pbonzini@redhat.com> - 2017-09-29 12:10 +0200
              Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state Boqun Feng <boqun.feng@gmail.com> - 2017-09-29 12:30 +0200
              Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state Peter Zijlstra <peterz@infradead.org> - 2017-09-29 12:40 +0200
                Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state Paolo Bonzini <pbonzini@redhat.com> - 2017-09-29 13:50 +0200
                  Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-29 19:00 +0200
              Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule  be Tasks RCU quiescent state "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-29 19:00 +0200

#1741336 — Re: [PATCH v3 tip/core/rcu 40/40] rcu: Make non-preemptive schedule be Tasks RCU quiescent state

On Wed, Apr 19, 2017 at 9:58 AM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:
> Currently, a call to schedule() acts as a Tasks RCU quiescent state
> only if a context switch actually takes place.  However, just the
> call to schedule() guarantees that the calling task has moved off of
> whatever tracing trampoline that it might have been one previously.
> This commit therefore plumbs schedule()'s "preempt" parameter into
> rcu_note_context_switch(), which then records the Tasks RCU quiescent
> state, but only if this call to schedule() was -not- due to a preemption.
>
> To avoid adding overhead to the common-case context-switch path,
> this commit hides the rcu_note_context_switch() check under an existing
> non-common-case check.
>
> Suggested-by: Steven Rostedt <rostedt@goodmis.org>
> Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

Hey Paul,

I'm seeing the following on the latest -next kernel, and suspect it's
caused bit this patch:

------------[ cut here ]------------
WARNING: CPU: 0 PID: 6974 at kernel/rcu/tree_plugin.h:329
rcu_preempt_note_context_switch kernel/rcu/tree_plugin.h:329 [inline]
WARNING: CPU: 0 PID: 6974 at kernel/rcu/tree_plugin.h:329
rcu_note_context_switch+0x16c/0x2210 kernel/rcu/tree.c:458
Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 6974 Comm: syz-fuzzer Not tainted 4.13.0-next-20170908+ #246
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.1-1ubuntu1 04/01/2014
Call Trace:
 __dump_stack lib/dump_stack.c:16 [inline]
 dump_stack+0x11d/0x1e5 lib/dump_stack.c:52
 panic+0x1bc/0x3b7 kernel/panic.c:181
 __warn+0x1c4/0x1d9 kernel/panic.c:542
 report_bug+0x211/0x2d0 lib/bug.c:183
 fixup_bug+0x3f/0x90 arch/x86/kernel/traps.c:178
 do_trap_no_signal arch/x86/kernel/traps.c:212 [inline]
 do_trap+0x260/0x390 arch/x86/kernel/traps.c:261
 do_error_trap+0x133/0x380 arch/x86/kernel/traps.c:298
 do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:311
 invalid_op+0x18/0x20 arch/x86/entry/entry_64.S:905
RIP: 0010:rcu_preempt_note_context_switch kernel/rcu/tree_plugin.h:329 [inline]
RIP: 0010:rcu_note_context_switch+0x16c/0x2210 kernel/rcu/tree.c:458
RSP: 0018:ffff88003b2debc8 EFLAGS: 00010002
RAX: 0000000000000001 RBX: 1ffff1000765bd85 RCX: 0000000000000000
RDX: 1ffff100075d7882 RSI: ffffffffb5c7da20 RDI: ffff88003aebc410
RBP: ffff88003b2def30 R08: dffffc0000000000 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000000 R12: ffff88003b2def08
R13: 0000000000000000 R14: ffff88003aebc040 R15: ffff88003aebc040
 __schedule+0x201/0x2240 kernel/sched/core.c:3292
 schedule+0x113/0x460 kernel/sched/core.c:3421
 kvm_async_pf_task_wait+0x43f/0x940 arch/x86/kernel/kvm.c:158
 do_async_page_fault+0x72/0x90 arch/x86/kernel/kvm.c:271
 async_page_fault+0x22/0x30 arch/x86/entry/entry_64.S:1069
RIP: 0010:format_decode+0x240/0x830 lib/vsprintf.c:1996
RSP: 0018:ffff88003b2df520 EFLAGS: 00010283
RAX: 000000000000003f RBX: ffffffffb5d1e141 RCX: ffff88003b2df670
RDX: 0000000000000001 RSI: dffffc0000000000 RDI: ffffffffb5d1e140
RBP: ffff88003b2df560 R08: dffffc0000000000 R09: 0000000000000000
R10: ffff88003b2df718 R11: 0000000000000000 R12: ffff88003b2df5d8
R13: 0000000000000064 R14: ffffffffb5d1e140 R15: 0000000000000000
 vsnprintf+0x173/0x1700 lib/vsprintf.c:2136
 sprintf+0xbe/0xf0 lib/vsprintf.c:2386
 proc_self_get_link+0xfb/0x1c0 fs/proc/self.c:23
 get_link fs/namei.c:1047 [inline]
 link_path_walk+0x1041/0x1490 fs/namei.c:2127
 path_openat+0x2d0/0x3600 fs/namei.c:3527
 do_filp_open+0x263/0x3c0 fs/namei.c:3562
 do_sys_open+0x515/0x6f0 fs/open.c:1059
 SYSC_openat fs/open.c:1086 [inline]
 SyS_openat+0x30/0x40 fs/open.c:1080
 do_syscall_64+0x26a/0x800 arch/x86/entry/common.c:287
 entry_SYSCALL64_slow_path+0x25/0x25
RIP: 0033:0x4889da
RSP: 002b:000000c4261eb8f0 EFLAGS: 00000206 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00000000004889da
RDX: 0000000000000002 RSI: 000000c42338d2c0 RDI: ffffffffffffff9c
RBP: 000000c4261eb980 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000206 R12: 0000000000000000
R13: 00000000ffffffee R14: 00000000000012c0 R15: 0000000000000100
Dumping ftrace buffer:
   (ftrace buffer empty)
Kernel Offset: 0x30000000 from 0xffffffff81000000 (relocation range:
0xffffffff80000000-0xffffffffbfffffff)
Rebooting in 86400 seconds..

[toc] | [next] | [standalone]

#1741500

On Thu, Sep 28, 2017 at 02:37:20AM -0700, Sasha Levin wrote:
> On Wed, Apr 19, 2017 at 9:58 AM, Paul E. McKenney
> <paulmck@linux.vnet.ibm.com> wrote:
> > Currently, a call to schedule() acts as a Tasks RCU quiescent state
> > only if a context switch actually takes place.  However, just the
> > call to schedule() guarantees that the calling task has moved off of
> > whatever tracing trampoline that it might have been one previously.
> > This commit therefore plumbs schedule()'s "preempt" parameter into
> > rcu_note_context_switch(), which then records the Tasks RCU quiescent
> > state, but only if this call to schedule() was -not- due to a preemption.
> >
> > To avoid adding overhead to the common-case context-switch path,
> > this commit hides the rcu_note_context_switch() check under an existing
> > non-common-case check.
> >
> > Suggested-by: Steven Rostedt <rostedt@goodmis.org>
> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> 
> Hey Paul,
> 
> I'm seeing the following on the latest -next kernel, and suspect it's
> caused bit this patch:

Hmmm...  kernel/rcu/tree_plugin.h:329 thinks that someone slept (as opposed
to was preempted) in an RCU read-side critical section.

If this is reproducible, could you please enable lockdep if you are not
already doing so?

							Thanx, Paul

> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 6974 at kernel/rcu/tree_plugin.h:329
> rcu_preempt_note_context_switch kernel/rcu/tree_plugin.h:329 [inline]
> WARNING: CPU: 0 PID: 6974 at kernel/rcu/tree_plugin.h:329
> rcu_note_context_switch+0x16c/0x2210 kernel/rcu/tree.c:458
> Kernel panic - not syncing: panic_on_warn set ...
> 
> CPU: 0 PID: 6974 Comm: syz-fuzzer Not tainted 4.13.0-next-20170908+ #246
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
> 1.10.1-1ubuntu1 04/01/2014
> Call Trace:
>  __dump_stack lib/dump_stack.c:16 [inline]
>  dump_stack+0x11d/0x1e5 lib/dump_stack.c:52
>  panic+0x1bc/0x3b7 kernel/panic.c:181
>  __warn+0x1c4/0x1d9 kernel/panic.c:542
>  report_bug+0x211/0x2d0 lib/bug.c:183
>  fixup_bug+0x3f/0x90 arch/x86/kernel/traps.c:178
>  do_trap_no_signal arch/x86/kernel/traps.c:212 [inline]
>  do_trap+0x260/0x390 arch/x86/kernel/traps.c:261
>  do_error_trap+0x133/0x380 arch/x86/kernel/traps.c:298
>  do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:311
>  invalid_op+0x18/0x20 arch/x86/entry/entry_64.S:905
> RIP: 0010:rcu_preempt_note_context_switch kernel/rcu/tree_plugin.h:329 [inline]
> RIP: 0010:rcu_note_context_switch+0x16c/0x2210 kernel/rcu/tree.c:458
> RSP: 0018:ffff88003b2debc8 EFLAGS: 00010002
> RAX: 0000000000000001 RBX: 1ffff1000765bd85 RCX: 0000000000000000
> RDX: 1ffff100075d7882 RSI: ffffffffb5c7da20 RDI: ffff88003aebc410
> RBP: ffff88003b2def30 R08: dffffc0000000000 R09: 0000000000000001
> R10: 0000000000000000 R11: 0000000000000000 R12: ffff88003b2def08
> R13: 0000000000000000 R14: ffff88003aebc040 R15: ffff88003aebc040
>  __schedule+0x201/0x2240 kernel/sched/core.c:3292
>  schedule+0x113/0x460 kernel/sched/core.c:3421
>  kvm_async_pf_task_wait+0x43f/0x940 arch/x86/kernel/kvm.c:158
>  do_async_page_fault+0x72/0x90 arch/x86/kernel/kvm.c:271
>  async_page_fault+0x22/0x30 arch/x86/entry/entry_64.S:1069
> RIP: 0010:format_decode+0x240/0x830 lib/vsprintf.c:1996
> RSP: 0018:ffff88003b2df520 EFLAGS: 00010283
> RAX: 000000000000003f RBX: ffffffffb5d1e141 RCX: ffff88003b2df670
> RDX: 0000000000000001 RSI: dffffc0000000000 RDI: ffffffffb5d1e140
> RBP: ffff88003b2df560 R08: dffffc0000000000 R09: 0000000000000000
> R10: ffff88003b2df718 R11: 0000000000000000 R12: ffff88003b2df5d8
> R13: 0000000000000064 R14: ffffffffb5d1e140 R15: 0000000000000000
>  vsnprintf+0x173/0x1700 lib/vsprintf.c:2136
>  sprintf+0xbe/0xf0 lib/vsprintf.c:2386
>  proc_self_get_link+0xfb/0x1c0 fs/proc/self.c:23
>  get_link fs/namei.c:1047 [inline]
>  link_path_walk+0x1041/0x1490 fs/namei.c:2127
>  path_openat+0x2d0/0x3600 fs/namei.c:3527
>  do_filp_open+0x263/0x3c0 fs/namei.c:3562
>  do_sys_open+0x515/0x6f0 fs/open.c:1059
>  SYSC_openat fs/open.c:1086 [inline]
>  SyS_openat+0x30/0x40 fs/open.c:1080
>  do_syscall_64+0x26a/0x800 arch/x86/entry/common.c:287
>  entry_SYSCALL64_slow_path+0x25/0x25
> RIP: 0033:0x4889da
> RSP: 002b:000000c4261eb8f0 EFLAGS: 00000206 ORIG_RAX: 0000000000000101
> RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00000000004889da
> RDX: 0000000000000002 RSI: 000000c42338d2c0 RDI: ffffffffffffff9c
> RBP: 000000c4261eb980 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000206 R12: 0000000000000000
> R13: 00000000ffffffee R14: 00000000000012c0 R15: 0000000000000100
> Dumping ftrace buffer:
>    (ftrace buffer empty)
> Kernel Offset: 0x30000000 from 0xffffffff81000000 (relocation range:
> 0xffffffff80000000-0xffffffffbfffffff)
> Rebooting in 86400 seconds..
> 

[toc] | [prev] | [next] | [standalone]

#1741652

On Thu, Sep 28, 2017 at 05:30:55AM -0700, Paul E. McKenney wrote:
>On Thu, Sep 28, 2017 at 02:37:20AM -0700, Sasha Levin wrote:
>> On Wed, Apr 19, 2017 at 9:58 AM, Paul E. McKenney
>> <paulmck@linux.vnet.ibm.com> wrote:
>> > Currently, a call to schedule() acts as a Tasks RCU quiescent state
>> > only if a context switch actually takes place.  However, just the
>> > call to schedule() guarantees that the calling task has moved off of
>> > whatever tracing trampoline that it might have been one previously.
>> > This commit therefore plumbs schedule()'s "preempt" parameter into
>> > rcu_note_context_switch(), which then records the Tasks RCU quiescent
>> > state, but only if this call to schedule() was -not- due to a preemption.
>> >
>> > To avoid adding overhead to the common-case context-switch path,
>> > this commit hides the rcu_note_context_switch() check under an existing
>> > non-common-case check.
>> >
>> > Suggested-by: Steven Rostedt <rostedt@goodmis.org>
>> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>>
>> Hey Paul,
>>
>> I'm seeing the following on the latest -next kernel, and suspect it's
>> caused bit this patch:
>
>Hmmm...  kernel/rcu/tree_plugin.h:329 thinks that someone slept (as opposed
>to was preempted) in an RCU read-side critical section.
>
>If this is reproducible, could you please enable lockdep if you are not
>already doing so?

lockdep was on, as far as I can tell.

It happened once in ~3 weeks of fuzzing, so not sure how easily I can reproduce.

-- 

Thanks,
Sasha

[toc] | [prev] | [next] | [standalone]

#1741677

On Thu, Sep 28, 2017 at 03:38:16PM +0000, Levin, Alexander (Sasha Levin) wrote:
> On Thu, Sep 28, 2017 at 05:30:55AM -0700, Paul E. McKenney wrote:

> >Hmmm...  kernel/rcu/tree_plugin.h:329 thinks that someone slept (as opposed
> >to was preempted) in an RCU read-side critical section.

Sasha, was this on one of those kernels that did a printk() from
scheduler context?

[toc] | [prev] | [next] | [standalone]

#1741699

On Thu, Sep 28, 2017 at 06:08:56PM +0200, Peter Zijlstra wrote:
>On Thu, Sep 28, 2017 at 03:38:16PM +0000, Levin, Alexander (Sasha Levin) wrote:
>> On Thu, Sep 28, 2017 at 05:30:55AM -0700, Paul E. McKenney wrote:
>
>> >Hmmm...  kernel/rcu/tree_plugin.h:329 thinks that someone slept (as opposed
>> >to was preempted) in an RCU read-side critical section.
>
>Sasha, was this on one of those kernels that did a printk() from
>scheduler context?

No, it was an older kernel (about a month old -next), I also didn't do
any CPU hotplug in this set of tests.

-- 

Thanks,
Sasha

[toc] | [prev] | [next] | [standalone]

#1741683

On Thu, Sep 28, 2017 at 03:38:16PM +0000, Levin, Alexander (Sasha Levin) wrote:
> On Thu, Sep 28, 2017 at 05:30:55AM -0700, Paul E. McKenney wrote:
> >On Thu, Sep 28, 2017 at 02:37:20AM -0700, Sasha Levin wrote:
> >> On Wed, Apr 19, 2017 at 9:58 AM, Paul E. McKenney
> >> <paulmck@linux.vnet.ibm.com> wrote:
> >> > Currently, a call to schedule() acts as a Tasks RCU quiescent state
> >> > only if a context switch actually takes place.  However, just the
> >> > call to schedule() guarantees that the calling task has moved off of
> >> > whatever tracing trampoline that it might have been one previously.
> >> > This commit therefore plumbs schedule()'s "preempt" parameter into
> >> > rcu_note_context_switch(), which then records the Tasks RCU quiescent
> >> > state, but only if this call to schedule() was -not- due to a preemption.
> >> >
> >> > To avoid adding overhead to the common-case context-switch path,
> >> > this commit hides the rcu_note_context_switch() check under an existing
> >> > non-common-case check.
> >> >
> >> > Suggested-by: Steven Rostedt <rostedt@goodmis.org>
> >> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> >>
> >> Hey Paul,
> >>
> >> I'm seeing the following on the latest -next kernel, and suspect it's
> >> caused bit this patch:
> >
> >Hmmm...  kernel/rcu/tree_plugin.h:329 thinks that someone slept (as opposed
> >to was preempted) in an RCU read-side critical section.
> >
> >If this is reproducible, could you please enable lockdep if you are not
> >already doing so?
> 
> lockdep was on, as far as I can tell.
> 
> It happened once in ~3 weeks of fuzzing, so not sure how easily I can reproduce.

Oh, wait...  Looking at the stack trace:

> Call Trace:
>  __dump_stack lib/dump_stack.c:16 [inline]
>  dump_stack+0x11d/0x1e5 lib/dump_stack.c:52
>  panic+0x1bc/0x3b7 kernel/panic.c:181
>  __warn+0x1c4/0x1d9 kernel/panic.c:542
>  report_bug+0x211/0x2d0 lib/bug.c:183
>  fixup_bug+0x3f/0x90 arch/x86/kernel/traps.c:178
>  do_trap_no_signal arch/x86/kernel/traps.c:212 [inline]
>  do_trap+0x260/0x390 arch/x86/kernel/traps.c:261
>  do_error_trap+0x133/0x380 arch/x86/kernel/traps.c:298
>  do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:311
>  invalid_op+0x18/0x20 arch/x86/entry/entry_64.S:905
> RIP: 0010:rcu_preempt_note_context_switch kernel/rcu/tree_plugin.h:329 [inline]
> RIP: 0010:rcu_note_context_switch+0x16c/0x2210 kernel/rcu/tree.c:458
> RSP: 0018:ffff88003b2debc8 EFLAGS: 00010002
> RAX: 0000000000000001 RBX: 1ffff1000765bd85 RCX: 0000000000000000
> RDX: 1ffff100075d7882 RSI: ffffffffb5c7da20 RDI: ffff88003aebc410
> RBP: ffff88003b2def30 R08: dffffc0000000000 R09: 0000000000000001
> R10: 0000000000000000 R11: 0000000000000000 R12: ffff88003b2def08
> R13: 0000000000000000 R14: ffff88003aebc040 R15: ffff88003aebc040

Up to here is all about the kernel complaining.

>  __schedule+0x201/0x2240 kernel/sched/core.c:3292
>  schedule+0x113/0x460 kernel/sched/core.c:3421
>  kvm_async_pf_task_wait+0x43f/0x940 arch/x86/kernel/kvm.c:158

It is kvm_async_pf_task_wait() that calls schedule(), but it carefully
sets state to make that legal.  Except...

>  do_async_page_fault+0x72/0x90 arch/x86/kernel/kvm.c:271
>  async_page_fault+0x22/0x30 arch/x86/entry/entry_64.S:1069
> RIP: 0010:format_decode+0x240/0x830 lib/vsprintf.c:1996
> RSP: 0018:ffff88003b2df520 EFLAGS: 00010283
> RAX: 000000000000003f RBX: ffffffffb5d1e141 RCX: ffff88003b2df670
> RDX: 0000000000000001 RSI: dffffc0000000000 RDI: ffffffffb5d1e140
> RBP: ffff88003b2df560 R08: dffffc0000000000 R09: 0000000000000000
> R10: ffff88003b2df718 R11: 0000000000000000 R12: ffff88003b2df5d8
> R13: 0000000000000064 R14: ffffffffb5d1e140 R15: 0000000000000000
>  vsnprintf+0x173/0x1700 lib/vsprintf.c:2136

We took a page fault in vsnprintf() while doing link_path_walk(),
which looks to be within an RCU read-side critical section.

Maybe the page fault confused lockdep?

Sigh.  It is going to be a real pain if all printk()s need to be
outside of RCU read-side critical sections due to the possibility of
page faults...

							Thanx, Paul

>  sprintf+0xbe/0xf0 lib/vsprintf.c:2386
>  proc_self_get_link+0xfb/0x1c0 fs/proc/self.c:23
>  get_link fs/namei.c:1047 [inline]
>  link_path_walk+0x1041/0x1490 fs/namei.c:2127
>  path_openat+0x2d0/0x3600 fs/namei.c:3527
>  do_filp_open+0x263/0x3c0 fs/namei.c:3562
>  do_sys_open+0x515/0x6f0 fs/open.c:1059
>  SYSC_openat fs/open.c:1086 [inline]
>  SyS_openat+0x30/0x40 fs/open.c:1080
>  do_syscall_64+0x26a/0x800 arch/x86/entry/common.c:287
>  entry_SYSCALL64_slow_path+0x25/0x25
> RIP: 0033:0x4889da
> RSP: 002b:000000c4261eb8f0 EFLAGS: 00000206 ORIG_RAX: 0000000000000101
> RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00000000004889da
> RDX: 0000000000000002 RSI: 000000c42338d2c0 RDI: ffffffffffffff9c
> RBP: 000000c4261eb980 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000206 R12: 0000000000000000
> R13: 00000000ffffffee R14: 00000000000012c0 R15: 0000000000000100
> Dumping ftrace buffer:
>    (ftrace buffer empty)
> Kernel Offset: 0x30000000 from 0xffffffff81000000 (relocation range:
> 0xffffffff80000000-0xffffffffbfffffff)
> Rebooting in 86400 seconds..

So kvm_async_pf_task_wait() does a schedule(), and it carefully 

[toc] | [prev] | [next] | [standalone]

#1741692

On Thu, Sep 28, 2017 at 09:05:14AM -0700, Paul E. McKenney wrote:
> >  do_async_page_fault+0x72/0x90 arch/x86/kernel/kvm.c:271
> >  async_page_fault+0x22/0x30 arch/x86/entry/entry_64.S:1069
> > RIP: 0010:format_decode+0x240/0x830 lib/vsprintf.c:1996
> > RSP: 0018:ffff88003b2df520 EFLAGS: 00010283
> > RAX: 000000000000003f RBX: ffffffffb5d1e141 RCX: ffff88003b2df670
> > RDX: 0000000000000001 RSI: dffffc0000000000 RDI: ffffffffb5d1e140
> > RBP: ffff88003b2df560 R08: dffffc0000000000 R09: 0000000000000000
> > R10: ffff88003b2df718 R11: 0000000000000000 R12: ffff88003b2df5d8
> > R13: 0000000000000064 R14: ffffffffb5d1e140 R15: 0000000000000000
> >  vsnprintf+0x173/0x1700 lib/vsprintf.c:2136
> 
> We took a page fault in vsnprintf() while doing link_path_walk(),
> which looks to be within an RCU read-side critical section.
> 
> Maybe the page fault confused lockdep?
> 
> Sigh.  It is going to be a real pain if all printk()s need to be
> outside of RCU read-side critical sections due to the possibility of
> page faults...

printk() _should_ not fault AFAIK. If it does, you've done something
dodgy.

[toc] | [prev] | [next] | [standalone]

#1741701

On Thu, Sep 28, 2017 at 06:18:50PM +0200, Peter Zijlstra wrote:
> On Thu, Sep 28, 2017 at 09:05:14AM -0700, Paul E. McKenney wrote:
> > >  do_async_page_fault+0x72/0x90 arch/x86/kernel/kvm.c:271
> > >  async_page_fault+0x22/0x30 arch/x86/entry/entry_64.S:1069
> > > RIP: 0010:format_decode+0x240/0x830 lib/vsprintf.c:1996
> > > RSP: 0018:ffff88003b2df520 EFLAGS: 00010283
> > > RAX: 000000000000003f RBX: ffffffffb5d1e141 RCX: ffff88003b2df670
> > > RDX: 0000000000000001 RSI: dffffc0000000000 RDI: ffffffffb5d1e140
> > > RBP: ffff88003b2df560 R08: dffffc0000000000 R09: 0000000000000000
> > > R10: ffff88003b2df718 R11: 0000000000000000 R12: ffff88003b2df5d8
> > > R13: 0000000000000064 R14: ffffffffb5d1e140 R15: 0000000000000000
> > >  vsnprintf+0x173/0x1700 lib/vsprintf.c:2136
> > 
> > We took a page fault in vsnprintf() while doing link_path_walk(),
> > which looks to be within an RCU read-side critical section.
> > 
> > Maybe the page fault confused lockdep?
> > 
> > Sigh.  It is going to be a real pain if all printk()s need to be
> > outside of RCU read-side critical sections due to the possibility of
> > page faults...
> 
> printk() _should_ not fault AFAIK. If it does, you've done something
> dodgy.

And we really do have a page fault there.  Perhaps the fault of the caller
of printk(), printing some memory that is, as you say, dodgy?

								Thanx, Paul

[toc] | [prev] | [next] | [standalone]

#1742011

[Multipart message — attachments visible in raw view] — view raw

On Thu, Sep 28, 2017 at 04:05:14PM +0000, Paul E. McKenney wrote:
[...]
> >  __schedule+0x201/0x2240 kernel/sched/core.c:3292
> >  schedule+0x113/0x460 kernel/sched/core.c:3421
> >  kvm_async_pf_task_wait+0x43f/0x940 arch/x86/kernel/kvm.c:158
> 
> It is kvm_async_pf_task_wait() that calls schedule(), but it carefully
> sets state to make that legal.  Except...
> 
> >  do_async_page_fault+0x72/0x90 arch/x86/kernel/kvm.c:271
> >  async_page_fault+0x22/0x30 arch/x86/entry/entry_64.S:1069
> > RIP: 0010:format_decode+0x240/0x830 lib/vsprintf.c:1996
> > RSP: 0018:ffff88003b2df520 EFLAGS: 00010283
> > RAX: 000000000000003f RBX: ffffffffb5d1e141 RCX: ffff88003b2df670
> > RDX: 0000000000000001 RSI: dffffc0000000000 RDI: ffffffffb5d1e140
> > RBP: ffff88003b2df560 R08: dffffc0000000000 R09: 0000000000000000
> > R10: ffff88003b2df718 R11: 0000000000000000 R12: ffff88003b2df5d8
> > R13: 0000000000000064 R14: ffffffffb5d1e140 R15: 0000000000000000
> >  vsnprintf+0x173/0x1700 lib/vsprintf.c:2136
> 
> We took a page fault in vsnprintf() while doing link_path_walk(),
> which looks to be within an RCU read-side critical section.
> 
> Maybe the page fault confused lockdep?
> 
> Sigh.  It is going to be a real pain if all printk()s need to be
> outside of RCU read-side critical sections due to the possibility of
> page faults...
> 

Does this mean whenever we get a page fault in a RCU read-side critical
section, we may hit this?

Could we simply avoid to schedule() in kvm_async_pf_task_wait() if the
fault process is in a RCU read-side critical section as follow?

diff --git a/arch/x86/kernel/kvm.c b/arch/x86/kernel/kvm.c
index aa60a08b65b1..291ea13b23d2 100644
--- a/arch/x86/kernel/kvm.c
+++ b/arch/x86/kernel/kvm.c
@@ -140,7 +140,7 @@ void kvm_async_pf_task_wait(u32 token)
 
 	n.token = token;
 	n.cpu = smp_processor_id();
-	n.halted = is_idle_task(current) || preempt_count() > 1;
+	n.halted = is_idle_task(current) || preempt_count() > 1 || rcu_preempt_depth();
 	init_swait_queue_head(&n.wq);
 	hlist_add_head(&n.link, &b->list);
 	raw_spin_unlock(&b->lock);

(Add KVM folks and list Cced)

Regards,
Boqun

> 							Thanx, Paul
[...]

[toc] | [prev] | [next] | [standalone]

#1742024

[Multipart message — attachments visible in raw view] — view raw

On 29/09/2017 11:30, Boqun Feng wrote:
> On Thu, Sep 28, 2017 at 04:05:14PM +0000, Paul E. McKenney wrote:
> [...]
>>>  __schedule+0x201/0x2240 kernel/sched/core.c:3292
>>>  schedule+0x113/0x460 kernel/sched/core.c:3421
>>>  kvm_async_pf_task_wait+0x43f/0x940 arch/x86/kernel/kvm.c:158
>>
>> It is kvm_async_pf_task_wait() that calls schedule(), but it carefully
>> sets state to make that legal.  Except...
>>
>>>  do_async_page_fault+0x72/0x90 arch/x86/kernel/kvm.c:271
>>>  async_page_fault+0x22/0x30 arch/x86/entry/entry_64.S:1069
>>> RIP: 0010:format_decode+0x240/0x830 lib/vsprintf.c:1996
>>> RSP: 0018:ffff88003b2df520 EFLAGS: 00010283
>>> RAX: 000000000000003f RBX: ffffffffb5d1e141 RCX: ffff88003b2df670
>>> RDX: 0000000000000001 RSI: dffffc0000000000 RDI: ffffffffb5d1e140
>>> RBP: ffff88003b2df560 R08: dffffc0000000000 R09: 0000000000000000
>>> R10: ffff88003b2df718 R11: 0000000000000000 R12: ffff88003b2df5d8
>>> R13: 0000000000000064 R14: ffffffffb5d1e140 R15: 0000000000000000
>>>  vsnprintf+0x173/0x1700 lib/vsprintf.c:2136
>>
>> We took a page fault in vsnprintf() while doing link_path_walk(),
>> which looks to be within an RCU read-side critical section.
>>
>> Maybe the page fault confused lockdep?
>>
>> Sigh.  It is going to be a real pain if all printk()s need to be
>> outside of RCU read-side critical sections due to the possibility of
>> page faults...
>>
> 
> Does this mean whenever we get a page fault in a RCU read-side critical
> section, we may hit this?
> 
> Could we simply avoid to schedule() in kvm_async_pf_task_wait() if the
> fault process is in a RCU read-side critical section as follow?
> 
> diff --git a/arch/x86/kernel/kvm.c b/arch/x86/kernel/kvm.c
> index aa60a08b65b1..291ea13b23d2 100644
> --- a/arch/x86/kernel/kvm.c
> +++ b/arch/x86/kernel/kvm.c
> @@ -140,7 +140,7 @@ void kvm_async_pf_task_wait(u32 token)
>  
>  	n.token = token;
>  	n.cpu = smp_processor_id();
> -	n.halted = is_idle_task(current) || preempt_count() > 1;
> +	n.halted = is_idle_task(current) || preempt_count() > 1 || rcu_preempt_depth();
>  	init_swait_queue_head(&n.wq);
>  	hlist_add_head(&n.link, &b->list);
>  	raw_spin_unlock(&b->lock);
> 
> (Add KVM folks and list Cced)

Yes, that would work.  Mind to send it as a proper patch?

Thanks,

Paolo

> Regards,
> Boqun
> 
>> 							Thanx, Paul
> [...]
> 

[toc] | [prev] | [next] | [standalone]

#1742035

[Multipart message — attachments visible in raw view] — view raw

On Fri, Sep 29, 2017 at 10:01:24AM +0000, Paolo Bonzini wrote:
> On 29/09/2017 11:30, Boqun Feng wrote:
> > On Thu, Sep 28, 2017 at 04:05:14PM +0000, Paul E. McKenney wrote:
> > [...]
> >>>  __schedule+0x201/0x2240 kernel/sched/core.c:3292
> >>>  schedule+0x113/0x460 kernel/sched/core.c:3421
> >>>  kvm_async_pf_task_wait+0x43f/0x940 arch/x86/kernel/kvm.c:158
> >>
> >> It is kvm_async_pf_task_wait() that calls schedule(), but it carefully
> >> sets state to make that legal.  Except...
> >>
> >>>  do_async_page_fault+0x72/0x90 arch/x86/kernel/kvm.c:271
> >>>  async_page_fault+0x22/0x30 arch/x86/entry/entry_64.S:1069
> >>> RIP: 0010:format_decode+0x240/0x830 lib/vsprintf.c:1996
> >>> RSP: 0018:ffff88003b2df520 EFLAGS: 00010283
> >>> RAX: 000000000000003f RBX: ffffffffb5d1e141 RCX: ffff88003b2df670
> >>> RDX: 0000000000000001 RSI: dffffc0000000000 RDI: ffffffffb5d1e140
> >>> RBP: ffff88003b2df560 R08: dffffc0000000000 R09: 0000000000000000
> >>> R10: ffff88003b2df718 R11: 0000000000000000 R12: ffff88003b2df5d8
> >>> R13: 0000000000000064 R14: ffffffffb5d1e140 R15: 0000000000000000
> >>>  vsnprintf+0x173/0x1700 lib/vsprintf.c:2136
> >>
> >> We took a page fault in vsnprintf() while doing link_path_walk(),
> >> which looks to be within an RCU read-side critical section.
> >>
> >> Maybe the page fault confused lockdep?
> >>
> >> Sigh.  It is going to be a real pain if all printk()s need to be
> >> outside of RCU read-side critical sections due to the possibility of
> >> page faults...
> >>
> > 
> > Does this mean whenever we get a page fault in a RCU read-side critical
> > section, we may hit this?
> > 
> > Could we simply avoid to schedule() in kvm_async_pf_task_wait() if the
> > fault process is in a RCU read-side critical section as follow?
> > 
> > diff --git a/arch/x86/kernel/kvm.c b/arch/x86/kernel/kvm.c
> > index aa60a08b65b1..291ea13b23d2 100644
> > --- a/arch/x86/kernel/kvm.c
> > +++ b/arch/x86/kernel/kvm.c
> > @@ -140,7 +140,7 @@ void kvm_async_pf_task_wait(u32 token)
> >  
> >  	n.token = token;
> >  	n.cpu = smp_processor_id();
> > -	n.halted = is_idle_task(current) || preempt_count() > 1;
> > +	n.halted = is_idle_task(current) || preempt_count() > 1 || rcu_preempt_depth();
> >  	init_swait_queue_head(&n.wq);
> >  	hlist_add_head(&n.link, &b->list);
> >  	raw_spin_unlock(&b->lock);
> > 
> > (Add KVM folks and list Cced)
> 
> Yes, that would work.  Mind to send it as a proper patch?
> 

I'd love to ;-) In a minute.

Regards,
Boqun

> Thanks,
> 
> Paolo
> 
> > Regards,
> > Boqun
> > 
> >> 							Thanx, Paul
> > [...]
> > 
> 
> 

[toc] | [prev] | [next] | [standalone]

#1742044

On Fri, Sep 29, 2017 at 12:01:24PM +0200, Paolo Bonzini wrote:
> > Does this mean whenever we get a page fault in a RCU read-side critical
> > section, we may hit this?
> > 
> > Could we simply avoid to schedule() in kvm_async_pf_task_wait() if the
> > fault process is in a RCU read-side critical section as follow?
> > 
> > diff --git a/arch/x86/kernel/kvm.c b/arch/x86/kernel/kvm.c
> > index aa60a08b65b1..291ea13b23d2 100644
> > --- a/arch/x86/kernel/kvm.c
> > +++ b/arch/x86/kernel/kvm.c
> > @@ -140,7 +140,7 @@ void kvm_async_pf_task_wait(u32 token)
> >  
> >  	n.token = token;
> >  	n.cpu = smp_processor_id();
> > -	n.halted = is_idle_task(current) || preempt_count() > 1;
> > +	n.halted = is_idle_task(current) || preempt_count() > 1 || rcu_preempt_depth();
> >  	init_swait_queue_head(&n.wq);
> >  	hlist_add_head(&n.link, &b->list);
> >  	raw_spin_unlock(&b->lock);
> > 
> > (Add KVM folks and list Cced)
> 
> Yes, that would work.  Mind to send it as a proper patch?

I'm confused, why would we do an ASYNC PF at all here? Thing is, a
printk() shouldn't trigger a major fault _ever_. At worst it triggers
something like a vmalloc minor fault. And I'm thinking we should not do
the whole ASYNC machinery for minor faults.

[toc] | [prev] | [next] | [standalone]

#1742064

On 29/09/2017 12:34, Peter Zijlstra wrote:
> On Fri, Sep 29, 2017 at 12:01:24PM +0200, Paolo Bonzini wrote:
>>> Does this mean whenever we get a page fault in a RCU read-side critical
>>> section, we may hit this?
>>>
>>> Could we simply avoid to schedule() in kvm_async_pf_task_wait() if the
>>> fault process is in a RCU read-side critical section as follow?
>>>
>>> diff --git a/arch/x86/kernel/kvm.c b/arch/x86/kernel/kvm.c
>>> index aa60a08b65b1..291ea13b23d2 100644
>>> --- a/arch/x86/kernel/kvm.c
>>> +++ b/arch/x86/kernel/kvm.c
>>> @@ -140,7 +140,7 @@ void kvm_async_pf_task_wait(u32 token)
>>>  
>>>  	n.token = token;
>>>  	n.cpu = smp_processor_id();
>>> -	n.halted = is_idle_task(current) || preempt_count() > 1;
>>> +	n.halted = is_idle_task(current) || preempt_count() > 1 || rcu_preempt_depth();
>>>  	init_swait_queue_head(&n.wq);
>>>  	hlist_add_head(&n.link, &b->list);
>>>  	raw_spin_unlock(&b->lock);
>>>
>>> (Add KVM folks and list Cced)
>>
>> Yes, that would work.  Mind to send it as a proper patch?
> 
> I'm confused, why would we do an ASYNC PF at all here? Thing is, a
> printk() shouldn't trigger a major fault _ever_. At worst it triggers
> something like a vmalloc minor fault. And I'm thinking we should not do
> the whole ASYNC machinery for minor faults.

Async page faults are page faults _on the host_ side, and you cannot
control what the host pages out.  Of course the hypervisor filters out
some cases itself (e.g. IF=0) but in general you could get one at any time.

Paolo

[toc] | [prev] | [next] | [standalone]

#1742244

On Fri, Sep 29, 2017 at 01:44:56PM +0200, Paolo Bonzini wrote:
> On 29/09/2017 12:34, Peter Zijlstra wrote:
> > On Fri, Sep 29, 2017 at 12:01:24PM +0200, Paolo Bonzini wrote:
> >>> Does this mean whenever we get a page fault in a RCU read-side critical
> >>> section, we may hit this?
> >>>
> >>> Could we simply avoid to schedule() in kvm_async_pf_task_wait() if the
> >>> fault process is in a RCU read-side critical section as follow?
> >>>
> >>> diff --git a/arch/x86/kernel/kvm.c b/arch/x86/kernel/kvm.c
> >>> index aa60a08b65b1..291ea13b23d2 100644
> >>> --- a/arch/x86/kernel/kvm.c
> >>> +++ b/arch/x86/kernel/kvm.c
> >>> @@ -140,7 +140,7 @@ void kvm_async_pf_task_wait(u32 token)
> >>>  
> >>>  	n.token = token;
> >>>  	n.cpu = smp_processor_id();
> >>> -	n.halted = is_idle_task(current) || preempt_count() > 1;
> >>> +	n.halted = is_idle_task(current) || preempt_count() > 1 || rcu_preempt_depth();
> >>>  	init_swait_queue_head(&n.wq);
> >>>  	hlist_add_head(&n.link, &b->list);
> >>>  	raw_spin_unlock(&b->lock);
> >>>
> >>> (Add KVM folks and list Cced)
> >>
> >> Yes, that would work.  Mind to send it as a proper patch?
> > 
> > I'm confused, why would we do an ASYNC PF at all here? Thing is, a
> > printk() shouldn't trigger a major fault _ever_. At worst it triggers
> > something like a vmalloc minor fault. And I'm thinking we should not do
> > the whole ASYNC machinery for minor faults.
> 
> Async page faults are page faults _on the host_ side, and you cannot
> control what the host pages out.  Of course the hypervisor filters out
> some cases itself (e.g. IF=0) but in general you could get one at any time.

Just to make sure I am understanding this...  You take a page fault on
the host, and this causes a schedule() on the guest?  Or did I lose the
thread here?

								Thanx, Paul

[toc] | [prev] | [next] | [standalone]

#1742245

On Fri, Sep 29, 2017 at 12:01:24PM +0200, Paolo Bonzini wrote:
> On 29/09/2017 11:30, Boqun Feng wrote:
> > On Thu, Sep 28, 2017 at 04:05:14PM +0000, Paul E. McKenney wrote:
> > [...]
> >>>  __schedule+0x201/0x2240 kernel/sched/core.c:3292
> >>>  schedule+0x113/0x460 kernel/sched/core.c:3421
> >>>  kvm_async_pf_task_wait+0x43f/0x940 arch/x86/kernel/kvm.c:158
> >>
> >> It is kvm_async_pf_task_wait() that calls schedule(), but it carefully
> >> sets state to make that legal.  Except...
> >>
> >>>  do_async_page_fault+0x72/0x90 arch/x86/kernel/kvm.c:271
> >>>  async_page_fault+0x22/0x30 arch/x86/entry/entry_64.S:1069
> >>> RIP: 0010:format_decode+0x240/0x830 lib/vsprintf.c:1996
> >>> RSP: 0018:ffff88003b2df520 EFLAGS: 00010283
> >>> RAX: 000000000000003f RBX: ffffffffb5d1e141 RCX: ffff88003b2df670
> >>> RDX: 0000000000000001 RSI: dffffc0000000000 RDI: ffffffffb5d1e140
> >>> RBP: ffff88003b2df560 R08: dffffc0000000000 R09: 0000000000000000
> >>> R10: ffff88003b2df718 R11: 0000000000000000 R12: ffff88003b2df5d8
> >>> R13: 0000000000000064 R14: ffffffffb5d1e140 R15: 0000000000000000
> >>>  vsnprintf+0x173/0x1700 lib/vsprintf.c:2136
> >>
> >> We took a page fault in vsnprintf() while doing link_path_walk(),
> >> which looks to be within an RCU read-side critical section.
> >>
> >> Maybe the page fault confused lockdep?
> >>
> >> Sigh.  It is going to be a real pain if all printk()s need to be
> >> outside of RCU read-side critical sections due to the possibility of
> >> page faults...
> >>
> > 
> > Does this mean whenever we get a page fault in a RCU read-side critical
> > section, we may hit this?
> > 
> > Could we simply avoid to schedule() in kvm_async_pf_task_wait() if the
> > fault process is in a RCU read-side critical section as follow?
> > 
> > diff --git a/arch/x86/kernel/kvm.c b/arch/x86/kernel/kvm.c
> > index aa60a08b65b1..291ea13b23d2 100644
> > --- a/arch/x86/kernel/kvm.c
> > +++ b/arch/x86/kernel/kvm.c
> > @@ -140,7 +140,7 @@ void kvm_async_pf_task_wait(u32 token)
> >  
> >  	n.token = token;
> >  	n.cpu = smp_processor_id();
> > -	n.halted = is_idle_task(current) || preempt_count() > 1;
> > +	n.halted = is_idle_task(current) || preempt_count() > 1 || rcu_preempt_depth();
> >  	init_swait_queue_head(&n.wq);
> >  	hlist_add_head(&n.link, &b->list);
> >  	raw_spin_unlock(&b->lock);

This works for PREEMPT=y kernels, but can silently break RCU read-side
critical sections on PREEMPT=n kernels.

> > (Add KVM folks and list Cced)
> 
> Yes, that would work.  Mind to send it as a proper patch?

Just out of curiosity, why is printk() being passed something that can
page fault?

							Thanx, Paul

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web