Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Vlastimil Babka]

On 11/02/2017 06:45 PM, Steven Rostedt wrote:
...>  	__DEVKMSG_LOG_BIT_ON = 0,
>  	__DEVKMSG_LOG_BIT_OFF,
> @@ -1753,8 +1760,56 @@ asmlinkage int vprintk_emit(int facility
>  		 * semaphore.  The release will print out buffers and wake up
>  		 * /dev/kmsg and syslog() users.
>  		 */
> -		if (console_trylock())
> +		if (console_trylock()) {
>  			console_unlock();
> +		} else {
> +			struct task_struct *owner = NULL;
> +			bool waiter;
> +			bool spin = false;
> +
> +			printk_safe_enter_irqsave(flags);
> +
> +			raw_spin_lock(&console_owner_lock);
> +			owner = READ_ONCE(console_owner);
> +			waiter = READ_ONCE(console_waiter);
> +			if (!waiter && owner && owner != current) {
> +				WRITE_ONCE(console_waiter, true);
> +				spin = true;
> +			}
> +			raw_spin_unlock(&console_owner_lock);
> +
> +			/*
> +			 * If there is an active printk() writing to the
> +			 * consoles, instead of having it write our data too,
> +			 * see if we can offload that load from the active
> +			 * printer, and do some printing ourselves.
> +			 * Go into a spin only if there isn't already a waiter
> +			 * spinning, and there is an active printer, and
> +			 * that active printer isn't us (recursive printk?).
> +			 */
> +			if (spin) {
> +				/* We spin waiting for the owner to release us */
> +				spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
> +				/* Owner will clear console_waiter on hand off */
> +				while (!READ_ONCE(console_waiter))

This should not be negated, right? We should spin while it's true, not
false.

> +					cpu_relax();
> +
> +				spin_release(&console_owner_dep_map, 1, _THIS_IP_);
> +				printk_safe_exit_irqrestore(flags);
> +
> +				/*
> +				 * The owner passed the console lock to us.
> +				 * Since we did not spin on console lock, annotate
> +				 * this as a trylock. Otherwise lockdep will
> +				 * complain.
> +				 */
> +				mutex_acquire(&console_lock_dep_map, 0, 1, _THIS_IP_);
> +				console_unlock();
> +				printk_safe_enter_irqsave(flags);
> +			}
> +			printk_safe_exit_irqrestore(flags);
> +
> +		}
>  	}

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Steven Rostedt]

On Thu, 2 Nov 2017 23:16:16 +0100
Vlastimil Babka <vbabka@suse.cz> wrote:

> > +			if (spin) {
> > +				/* We spin waiting for the owner to release us */
> > +				spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
> > +				/* Owner will clear console_waiter on hand off */
> > +				while (!READ_ONCE(console_waiter))  
> 
> This should not be negated, right? We should spin while it's true, not
> false.

Ug, yes. How did that not crash in my tests.

Will fix.

-- Steve

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Sergey Senozhatsky]

On (11/02/17 23:15), Steven Rostedt wrote:
> On Thu, 2 Nov 2017 23:16:16 +0100
> Vlastimil Babka <vbabka@suse.cz> wrote:
> 
> > > +			if (spin) {
> > > +				/* We spin waiting for the owner to release us */
> > > +				spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
> > > +				/* Owner will clear console_waiter on hand off */
> > > +				while (!READ_ONCE(console_waiter))  
> > 
> > This should not be negated, right? We should spin while it's true, not
> > false.
> 
> Ug, yes. How did that not crash in my tests.

Ah, right... Good catch, Vlastimil. The V1 didn't work as expected
on my tests.

	-ss

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Steven Rostedt]

On Thu, 2 Nov 2017 21:09:32 -0700
John Hubbard <jhubbard@nvidia.com> wrote:

> On 11/02/2017 03:16 PM, Vlastimil Babka wrote:
> > On 11/02/2017 06:45 PM, Steven Rostedt wrote:  
> > ...>  	__DEVKMSG_LOG_BIT_ON = 0,
> >>  	__DEVKMSG_LOG_BIT_OFF,
> >> @@ -1753,8 +1760,56 @@ asmlinkage int vprintk_emit(int facility
> >>  		 * semaphore.  The release will print out buffers and wake up
> >>  		 * /dev/kmsg and syslog() users.
> >>  		 */
> >> -		if (console_trylock())
> >> +		if (console_trylock()) {
> >>  			console_unlock();
> >> +		} else {
> >> +			struct task_struct *owner = NULL;
> >> +			bool waiter;
> >> +			bool spin = false;
> >> +
> >> +			printk_safe_enter_irqsave(flags);
> >> +
> >> +			raw_spin_lock(&console_owner_lock);
> >> +			owner = READ_ONCE(console_owner);
> >> +			waiter = READ_ONCE(console_waiter);
> >> +			if (!waiter && owner && owner != current) {
> >> +				WRITE_ONCE(console_waiter, true);
> >> +				spin = true;
> >> +			}
> >> +			raw_spin_unlock(&console_owner_lock);
> >> +
> >> +			/*
> >> +			 * If there is an active printk() writing to the
> >> +			 * consoles, instead of having it write our data too,
> >> +			 * see if we can offload that load from the active
> >> +			 * printer, and do some printing ourselves.
> >> +			 * Go into a spin only if there isn't already a waiter
> >> +			 * spinning, and there is an active printer, and
> >> +			 * that active printer isn't us (recursive printk?).
> >> +			 */
> >> +			if (spin) {
> >> +				/* We spin waiting for the owner to release us */
> >> +				spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
> >> +				/* Owner will clear console_waiter on hand off */
> >> +				while (!READ_ONCE(console_waiter))  
> > 
> > This should not be negated, right? We should spin while it's true, not
> > false.
> >   
> 
> Vlastimil's right about the polarity problem above, but while I was trying
> to verify that, I noticed another problem: the "handoff" of the console lock
> is broken.
> 
> For example, if there are 3 or more threads, you can do the following:
> 
> thread A: holds the console lock, is printing, then moves into the console_unlock
>           phase
> 
> thread B: goes into the waiter spin loop above, and (once the polarity is corrected)
>           waits for console_waiter to become 0
> 
> thread A: finishing up, sets console_waiter --> 0
> 
> thread C: before thread B notices, thread C goes into the "else" section, sees that
>           console_waiter == 0, and sets console_waiter --> 1. So thread C now
>           becomes the waiter

But console_waiter only gets set to 1 if console_waiter is 0 *and*
console_owner is not NULL and is not current. console_owner is only
updated under a spin lock and console_waiter is only set under a spin
lock when console_owner is not NULL.

This means this scenario can not happen.


> 
> thread B: gets *very* unlucky and never sees the 1 --> 0 --> 1 transition of
>           console_waiter, so it continues waiting.  And now we have both B
>           and C in the same spin loop, and this is now broken.
> 
> At the root, this is really due to the absence of a pre-existing "hand-off this lock"
> mechanism. And this one here is not quite correct.
> 
> Solution ideas: for a true hand-off, there needs to be a bit more information
> exchanged. Conceptually, a (lock-protected) list of waiters (which would 
> only ever have zero or one entries) is a good way to start thinking about it.

As stated above, the console owner check will prevent this issue.

-- Steve

> 
> I talked it over with Mark Hairgrove here, he suggested a more sophisticated
> way of doing that sort of hand-off, using compare-and-exchange. I can turn that
> into a patch if you like (I'm not as fast as some folks, so I didn't attempt to
> do that right away), although I'm sure you have lots of ideas on how to do it.
> 

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Steven Rostedt]

On Fri, 3 Nov 2017 07:21:21 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Thu, 2 Nov 2017 21:09:32 -0700
> John Hubbard <jhubbard@nvidia.com> wrote:
>

 > 
> > For example, if there are 3 or more threads, you can do the following:
> > 
> > thread A: holds the console lock, is printing, then moves into the console_unlock
> >           phase
> > 
> > thread B: goes into the waiter spin loop above, and (once the polarity is corrected)
> >           waits for console_waiter to become 0
> > 
> > thread A: finishing up, sets console_waiter --> 0
> > 
> > thread C: before thread B notices, thread C goes into the "else" section, sees that
> >           console_waiter == 0, and sets console_waiter --> 1. So thread C now
> >           becomes the waiter  
> 
> But console_waiter only gets set to 1 if console_waiter is 0 *and*
> console_owner is not NULL and is not current. console_owner is only
> updated under a spin lock and console_waiter is only set under a spin
> lock when console_owner is not NULL.
> 
> This means this scenario can not happen.
> 
> 
> > 
> > thread B: gets *very* unlucky and never sees the 1 --> 0 --> 1 transition of
> >           console_waiter, so it continues waiting.  And now we have both B
> >           and C in the same spin loop, and this is now broken.
> > 
> > At the root, this is really due to the absence of a pre-existing "hand-off this lock"
> > mechanism. And this one here is not quite correct.
> > 
> > Solution ideas: for a true hand-off, there needs to be a bit more information
> > exchanged. Conceptually, a (lock-protected) list of waiters (which would 
> > only ever have zero or one entries) is a good way to start thinking about it.  
> 
> As stated above, the console owner check will prevent this issue.
> 

I'll condense the patch to show what I mean:

To become a waiter, a task must do the following:

+			printk_safe_enter_irqsave(flags);
+
+			raw_spin_lock(&console_owner_lock);
+			owner = READ_ONCE(console_owner);
+			waiter = READ_ONCE(console_waiter);
+			if (!waiter && owner && owner != current) {
+				WRITE_ONCE(console_waiter, true);
+				spin = true;
+			}
+			raw_spin_unlock(&console_owner_lock);


The new waiter gets set only if there isn't already a waiter *and*
there is an owner that is not current (and with the printk_safe_enter I
don't think that is even needed).

+				while (!READ_ONCE(console_waiter))
+					cpu_relax();

The spin is outside the spin lock. But only the owner can clear it.

Now the owner is doing a loop of this (with interrupts disabled)

+		raw_spin_lock(&console_owner_lock);
+		console_owner = current;
+		raw_spin_unlock(&console_owner_lock);

Write to consoles.

+		raw_spin_lock(&console_owner_lock);
+		waiter = READ_ONCE(console_waiter);
+		console_owner = NULL;
+		raw_spin_unlock(&console_owner_lock);

+		if (waiter)
+			break;

At this moment console_owner is NULL, and no new waiters can happen.
The next owner will be the waiter that is spinning.

+	if (waiter) {
+		WRITE_ONCE(console_waiter, false);

There is no possibility of another task sneaking in and becoming a
waiter at this moment. The console_owner was cleared under spin lock,
and a waiter is only set under the same spin lock if owner is set.
There will be no new owner sneaking in because to become the owner, you
must have the console lock. Since it is never released between the time
the owner clears console_waiter and the waiter takes the console lock,
there is no race.

-- Steve

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Steven Rostedt]

On Fri, 3 Nov 2017 07:54:04 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> The new waiter gets set only if there isn't already a waiter *and*
> there is an owner that is not current (and with the printk_safe_enter I
> don't think that is even needed).
> 
> +				while (!READ_ONCE(console_waiter))
> +					cpu_relax();

I still need to fix the patch. I cut and pasted the bad version. This
should have been:

	while (READ_ONCE(console_waiter))
		cpu_relax();

-- Steve

Re: [PATCH v3] printk: Add console owner and waiter logic to loadbalance console writes

[Tetsuo Handa]

John Hubbard wrote:
> On 11/03/2017 02:46 PM, John Hubbard wrote:
> > On 11/03/2017 04:54 AM, Steven Rostedt wrote:
> >> On Fri, 3 Nov 2017 07:21:21 -0400
> >> Steven Rostedt <rostedt@goodmis.org> wrote:
> [...]
> >>
> >> I'll condense the patch to show what I mean:
> >>
> >> To become a waiter, a task must do the following:
> >>
> >> +			printk_safe_enter_irqsave(flags);
> >> +
> >> +			raw_spin_lock(&console_owner_lock);
> >> +			owner = READ_ONCE(console_owner);
> >> +			waiter = READ_ONCE(console_waiter);

When CPU0 is writing to consoles after "console_owner = current;",
what prevents from CPU1 and CPU2 concurrently reached this line from
seeing waiter == false && owner != NULL && owner != current (which will
concurrently set console_waiter = true and spin = true) without
using atomic instructions?

> >> +			if (!waiter && owner && owner != current) {
> >> +				WRITE_ONCE(console_waiter, true);
> >> +				spin = true;
> >> +			}
> >> +			raw_spin_unlock(&console_owner_lock);
> >>
> >>
> >> The new waiter gets set only if there isn't already a waiter *and*
> >> there is an owner that is not current (and with the printk_safe_enter I
> >> don't think that is even needed).
> >>
> >> +				while (!READ_ONCE(console_waiter))
> >> +					cpu_relax();
> >>
> >> The spin is outside the spin lock. But only the owner can clear it.
> >>
> >> Now the owner is doing a loop of this (with interrupts disabled)
> >>
> >> +		raw_spin_lock(&console_owner_lock);
> >> +		console_owner = current;
> >> +		raw_spin_unlock(&console_owner_lock);
> >>
> >> Write to consoles.
> >>
> >> +		raw_spin_lock(&console_owner_lock);
> >> +		waiter = READ_ONCE(console_waiter);
> >> +		console_owner = NULL;
> >> +		raw_spin_unlock(&console_owner_lock);
> >>
> >> +		if (waiter)
> >> +			break;
> >>
> >> At this moment console_owner is NULL, and no new waiters can happen.
> >> The next owner will be the waiter that is spinning.
> >>
> >> +	if (waiter) {
> >> +		WRITE_ONCE(console_waiter, false);
> >>
> >> There is no possibility of another task sneaking in and becoming a
> >> waiter at this moment. The console_owner was cleared under spin lock,
> >> and a waiter is only set under the same spin lock if owner is set.
> >> There will be no new owner sneaking in because to become the owner, you
> >> must have the console lock. Since it is never released between the time
> >> the owner clears console_waiter and the waiter takes the console lock,
> >> there is no race.
> > 
> > Yes, you are right of course. That does close the window. Sorry about
> > missing that point.
> > 
> > I'll try to quickly put together a small patch on top of this, that
> > shows a simplification, to just use an atomic compare and swap between a
> > global atomic value, and a local (on the stack) flag value, just in
> > case that is of interest.
> > 
> > thanks
> > john h
> 
> Just a follow-up: I was unable to simplify this; the atomic compare-and-swap
> approach merely made it different, rather than smaller or simpler.

Why no need to use [cmp]xchg() approach?

> 
> So, after spending a fair amount of time with the patch, it looks good to me,
> for whatever that's worth. :) Thanks again for explaining the locking details.
> 
> thanks
> john h
> 
> > 
> >>
> >> -- Steve

Re: [PATCH v3] printk: Add console owner and waiter logic to loadbalance console writes

[Tetsuo Handa]

Tetsuo Handa wrote:
> John Hubbard wrote:
> > On 11/03/2017 02:46 PM, John Hubbard wrote:
> > > On 11/03/2017 04:54 AM, Steven Rostedt wrote:
> > >> On Fri, 3 Nov 2017 07:21:21 -0400
> > >> Steven Rostedt <rostedt@goodmis.org> wrote:
> > [...]
> > >>
> > >> I'll condense the patch to show what I mean:
> > >>
> > >> To become a waiter, a task must do the following:
> > >>
> > >> +			printk_safe_enter_irqsave(flags);
> > >> +
> > >> +			raw_spin_lock(&console_owner_lock);
> > >> +			owner = READ_ONCE(console_owner);
> > >> +			waiter = READ_ONCE(console_waiter);
> 
> When CPU0 is writing to consoles after "console_owner = current;",
> what prevents from CPU1 and CPU2 concurrently reached this line from
> seeing waiter == false && owner != NULL && owner != current (which will
> concurrently set console_waiter = true and spin = true) without
> using atomic instructions?

Oops. I overlooked that console_owner_lock is held.

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Tetsuo Handa]

I tried your patch with warn_alloc() torture. It did not cause lockups.
But I felt that possibility of failing to flush last second messages (such
as SysRq-c or SysRq-b) to consoles has increased. Is this psychological?

---------- vmcore-dmesg start ----------
[  169.016198] postgres cpuset=
[  169.032544]  filemap_fault+0x311/0x790
[  169.047745] /
[  169.047780]  mems_allowed=0
[  169.050577]  ? xfs_ilock+0x126/0x1a0 [xfs]
[  169.062769]  mems_allowed=0
[  169.065754]  ? down_read_nested+0x3a/0x60
[  169.065783]  ? xfs_ilock+0x126/0x1a0 [xfs]
[  189.700206] sysrq: SysRq :
[  189.700639]  __xfs_filemap_fault.isra.19+0x3f/0xe0 [xfs]
[  189.700799]  xfs_filemap_fault+0xb/0x10 [xfs]
[  189.703981] Trigger a crash
[  189.707032]  __do_fault+0x19/0xa0
[  189.710008] BUG: unable to handle kernel
[  189.713387]  __handle_mm_fault+0xbb3/0xda0
[  189.716473] NULL pointer dereference
[  189.719674]  handle_mm_fault+0x14f/0x300
[  189.722969]  at           (null)
[  189.722974] IP: sysrq_handle_crash+0x3b/0x70
[  189.726156]  ? handle_mm_fault+0x39/0x300
[  189.729537] PGD 1170dc067
[  189.732841]  __do_page_fault+0x23e/0x4f0
[  189.735876] P4D 1170dc067
[  189.739171]  do_page_fault+0x30/0x80
[  189.742323] PUD 1170dd067
[  189.745437]  page_fault+0x22/0x30
[  189.748329] PMD 0
[  189.751106] RIP: 0033:0x650390
[  189.756583] RSP: 002b:00007fffef6b1568 EFLAGS: 00010246
[  189.759574] Oops: 0002 [#1] SMP DEBUG_PAGEALLOC
[  189.762607] RAX: 0000000000000000 RBX: 00007fffef6b1594 RCX: 00007fae949caa20
[  189.765665] Modules linked in:
[  189.768423] RDX: 0000000000000008 RSI: 0000000000000000 RDI: 0000000000000000
[  189.768425] RBP: 00007fffef6b1590 R08: 0000000000000002 R09: 0000000000000010
[  189.771478]  ip6t_rpfilter
[  189.774297] R10: 0000000000000001 R11: 0000000000000246 R12: 0000000000000000
[  189.777016]  ipt_REJECT
[  189.779366] R13: 0000000000000000 R14: 00007fae969787e0 R15: 0000000000000004
[  189.782114]  nf_reject_ipv4
[  189.784839] CPU: 7 PID: 6959 Comm: sleep Not tainted 4.14.0-rc8+ #302
[  189.785113] Mem-Info:
---------- vmcore-dmesg end ----------

---------- serial console start ----------
[  168.975447] Mem-Info:
[  168.975453] active_anon:827953 inactive_anon:3376 isolated_anon:0
[  168.975453]  active_file:55 inactive_file:449 isolated_file:246
[  168.975453]  unevictable:0 dirty:2 writeback:68 unstable:0
[  168.975453]  slab_reclaimable:4344 slab_unreclaimable:36066
[  168.975453]  mapped:2250 shmem:3543 pagetables:9568 bounce:0
[  168.975453]  free:21398 free_pcp:175 free_cma:0
[  168.975458] Node 0 active_anon:3311812kB inactive_anon:13504kB active_file:220kB inactive_file:1796kB unevictable:0kB isolated(anon):0kB isolated(file):984kB mapped:9000kB dirty:8kB writeback:272kB shmem:14172kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 2869248kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[  168.975460] Node 0 DMA free:14756kB min:288kB low:360kB high:432kB active_anon:1088kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15904kB mlocked:0kB kernel_stack:0kB pagetables:28kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[  168.975482] lowmem_reserve[]: 0 2686 3619 3619
[  168.975489] Node 0 DMA32 free:53624kB min:49956kB low:62444kB high:74932kB active_anon:2691088kB inactive_anon:16kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:3129152kB managed:2751400kB mlocked:0kB kernel_stack:32kB pagetables:4232kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[  168.975494] lowmem_reserve[]: 0 0 932 932
[  168.975501] Node 0 Normal free:17212kB min:17336kB low:21668kB high:26000kB active_anon:619636kB inactive_anon:13488kB active_file:220kB inactive_file:2872kB unevictable:0kB writepending:280kB present:1048576kB managed:954828kB mlocked:0kB kernel_stack:22784kB pagetables:34012kB bounce:0kB free_pcp:700kB local_pcp:40kB free_cma:0kB
[  168.975505] lowmem_reserve[]: 0 0 0 0
[  168.975512] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 2*64kB (UM) 2*128kB (UM) 2*256kB (UM) 1*512kB (M) 1*1024kB (U) 0*2048kB 3*4096kB (M) = 14756kB
[  168.975536] Node 0 DMA32: 18*4kB (U) 14*8kB (UM) 14*16kB (UE) 37*32kB (UE) 9*64kB (UE) 4*128kB (UME) 1*256kB (M) 3*512kB (UME) 2*1024kB (UE) 3*2048kB (UME) 10*4096kB (M) = 53624kB
[    0.000000] Linux version 4.14.0-rc8+ (root@localhost.localdomain) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-16) (GCC)) #302 SMP Mon Nov 6 12:15:00 JST 2017
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.14.0-rc8+ root=UUID=98df1583-260a-423a-a193-182dade5d085 ro security=none sysrq_always_enabled console=ttyS0,115200n8 console=tty0 LANG=en_US.UTF-8 irqpoll nr_cpus=1 reset_devices cgroup_disable=memory mce=off numa=off udev.children-max=2 panic=10 rootflags=nofail acpi_no_memhotplug transparent_hugepage=never disable_cpu_apicid=0 elfcorehdr=867704K
---------- serial console end ----------

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Sergey Senozhatsky]

On (11/06/17 21:06), Tetsuo Handa wrote:
> I tried your patch with warn_alloc() torture. It did not cause lockups.
> But I felt that possibility of failing to flush last second messages (such
> as SysRq-c or SysRq-b) to consoles has increased. Is this psychological?

do I understand it correctly that there are "lost messages"?

sysrq-b does an immediate emergency reboot. "normally" it's not expected
to flush any pending logbuf messages because it's an emergency-reboot...
but in fact it does. and this is why sysrq-b is not 100% reliable:

	__handle_sysrq()
	{
	  pr_info("SysRq : ");

	  op_p = __sysrq_get_key_op(key);
	  pr_cont("%s\n", op_p->action_msg);

	    op_p->handler(key);

	  pr_cont("\n");
	}

those pr_info()/pr_cont() calls can spoil sysrq-b, depending on how
badly the system is screwed. if pr_info() deadlocks, then we never
go to op_p->handler(key)->emergency_restart(). even if you suppress
printing of info loglevel messages, pr_info() still goes to
console_unlock() and prints [console_seq, log_next_seq] messages,
if there any.

there is, however, a subtle behaviour change, I think.

previously, in some cases [?], pr_info("SysRq : ") from __handle_sysrq()
would flush logbuf messages. now we have that "break out of console_unlock()
loop even though there are pending messages, there is another CPU doing
printk()". so sysrb-b instead of looping in console_unlock() goes directly
to emergency_restart(). without the change it would have continued looping
in console_unlock() and would have called emergency_restart() only when
"console_seq == log_next_seq".

now... the "subtle" part here is that we had that thing:
	- *IF* __handle_sysrq() grabs the console_sem then it will not
	  return from console_unlock() until logbuf is empty. so
	  concurrent printk() messages won't get lost.

what we have now is:
	- if there are concurrent printk() then __handle_sysrq() does not
	  fully flush the logbuf *even* if it grabbed the console_sem.

> ---------- vmcore-dmesg start ----------
> [  169.016198] postgres cpuset=
> [  169.032544]  filemap_fault+0x311/0x790
> [  169.047745] /
> [  169.047780]  mems_allowed=0
> [  169.050577]  ? xfs_ilock+0x126/0x1a0 [xfs]
> [  169.062769]  mems_allowed=0
> [  169.065754]  ? down_read_nested+0x3a/0x60
> [  169.065783]  ? xfs_ilock+0x126/0x1a0 [xfs]
> [  189.700206] sysrq: SysRq :
> [  189.700639]  __xfs_filemap_fault.isra.19+0x3f/0xe0 [xfs]
> [  189.700799]  xfs_filemap_fault+0xb/0x10 [xfs]
> [  189.703981] Trigger a crash
> [  189.707032]  __do_fault+0x19/0xa0
> [  189.710008] BUG: unable to handle kernel
> [  189.713387]  __handle_mm_fault+0xbb3/0xda0
> [  189.716473] NULL pointer dereference
> [  189.719674]  handle_mm_fault+0x14f/0x300
> [  189.722969]  at           (null)
> [  189.722974] IP: sysrq_handle_crash+0x3b/0x70
> [  189.726156]  ? handle_mm_fault+0x39/0x300
> [  189.729537] PGD 1170dc067
> [  189.732841]  __do_page_fault+0x23e/0x4f0
> [  189.735876] P4D 1170dc067
> [  189.739171]  do_page_fault+0x30/0x80
> [  189.742323] PUD 1170dd067
> [  189.745437]  page_fault+0x22/0x30
> [  189.748329] PMD 0
> [  189.751106] RIP: 0033:0x650390
> [  189.756583] RSP: 002b:00007fffef6b1568 EFLAGS: 00010246
> [  189.759574] Oops: 0002 [#1] SMP DEBUG_PAGEALLOC
> [  189.762607] RAX: 0000000000000000 RBX: 00007fffef6b1594 RCX: 00007fae949caa20
> [  189.765665] Modules linked in:
> [  189.768423] RDX: 0000000000000008 RSI: 0000000000000000 RDI: 0000000000000000
> [  189.768425] RBP: 00007fffef6b1590 R08: 0000000000000002 R09: 0000000000000010
> [  189.771478]  ip6t_rpfilter
> [  189.774297] R10: 0000000000000001 R11: 0000000000000246 R12: 0000000000000000
> [  189.777016]  ipt_REJECT
> [  189.779366] R13: 0000000000000000 R14: 00007fae969787e0 R15: 0000000000000004
> [  189.782114]  nf_reject_ipv4
> [  189.784839] CPU: 7 PID: 6959 Comm: sleep Not tainted 4.14.0-rc8+ #302
> [  189.785113] Mem-Info:
> ---------- vmcore-dmesg end ----------

hm... wondering if this is a regression.

	-ss

Re: [PATCH v3] printk: Add console owner and waiter logic to loadbalance console writes

[Tetsuo Handa]

Sergey Senozhatsky wrote:
> On (11/06/17 21:06), Tetsuo Handa wrote:
> > I tried your patch with warn_alloc() torture. It did not cause lockups.
> > But I felt that possibility of failing to flush last second messages (such
> > as SysRq-c or SysRq-b) to consoles has increased. Is this psychological?
> 
> do I understand it correctly that there are "lost messages"?

Messages that were not written to consoles.

It seems that due to warn_alloc() torture, messages added to logbuf by SysRq
were not printed. When printk() is storming, we can't expect last second
messages are printed to consoles.

> hm... wondering if this is a regression.

I wish that there is an API which allows waiting for printk() messages
to be flushed. That is, associate serial number to each printk() request,
and allow callers to know current serial number (i.e. number of messages
in the logbuf) and current completed number (i.e. number of messages written
to consoles) and compare like time_after(). That is.

  printk("Hello\n");
  printk("World\n");
  seq = get_printk_queued_seq();

and then

  while (get_printk_completed_seq() < seq)
    msleep(1); // if caller can wait unconditionally.

or

  while (get_printk_completed_seq() < seq && !fatal_signal_pending(current))
    msleep(1); // if caller can wait unless killed.

or

  now = jiffies;
  while (get_printk_completed_seq() < seq && time_before(jiffies, now + HZ))
    cpu_relax(); // if caller cannot schedule().

and so on, for watchdog kernel threads can try to wait for printk() to flush.



By the way, I got below lockdep splat. Too timing dependent to reproduce.
( http://I-love.SAKURA.ne.jp/tmp/serial-20171107.txt.xz )

[    8.631358] fbcon: svgadrmfb (fb0) is primary device
[    8.654303] Console: switching to colour frame buffer device 160x48
[    8.659706]
[    8.659707] ======================================================
[    8.659707] WARNING: possible circular locking dependency detected
[    8.659708] 4.14.0-rc8+ #312 Not tainted
[    8.659708] ------------------------------------------------------
[    8.659708] systemd-udevd/184 is trying to acquire lock:
[    8.659709]  (&(&par->dirty.lock)->rlock){....}, at: [<ffffffffc0212fe3>] vmw_fb_dirty_mark+0x33/0xf0 [vmwgfx]
[    8.659710]
[    8.659710] but task is already holding lock:
[    8.659711]  (console_owner){....}, at: [<ffffffff8d0d5c63>] console_unlock+0x173/0x5c0
[    8.659712]
[    8.659712] which lock already depends on the new lock.
[    8.659712]
[    8.659713]
[    8.659713] the existing dependency chain (in reverse order) is:
[    8.659713]
[    8.659713] -> #4 (console_owner){....}:
[    8.659715]        lock_acquire+0x6d/0x90
[    8.659715]        console_unlock+0x199/0x5c0
[    8.659715]        vprintk_emit+0x4e0/0x540
[    8.659715]        vprintk_default+0x1a/0x20
[    8.659716]        vprintk_func+0x22/0x60
[    8.659716]        printk+0x53/0x6a
[    8.659716]        start_kernel+0x6d/0x4c3
[    8.659717]        x86_64_start_reservations+0x24/0x26
[    8.659717]        x86_64_start_kernel+0x6f/0x72
[    8.659717]        verify_cpu+0x0/0xfb
[    8.659717]
[    8.659718] -> #3 (logbuf_lock){..-.}:
[    8.659719]        lock_acquire+0x6d/0x90
[    8.659719]        _raw_spin_lock+0x2c/0x40
[    8.659719]        vprintk_emit+0x7f/0x540
[    8.659720]        vprintk_deferred+0x1b/0x40
[    8.659720]        printk_deferred+0x53/0x6f
[    8.659720]        unwind_next_frame.part.6+0x1ed/0x200
[    8.659721]        unwind_next_frame+0x11/0x20
[    8.659721]        __save_stack_trace+0x7d/0xf0
[    8.659721]        save_stack_trace+0x16/0x20
[    8.659721]        set_track+0x6b/0x1a0
[    8.659722]        free_debug_processing+0xce/0x2aa
[    8.659722]        __slab_free+0x1eb/0x2c0
[    8.659722]        kmem_cache_free+0x19a/0x1e0
[    8.659723]        file_free_rcu+0x23/0x40
[    8.659723]        rcu_process_callbacks+0x2ed/0x5b0
[    8.659723]        __do_softirq+0xf2/0x21e
[    8.659724]        irq_exit+0xe7/0x100
[    8.659724]        smp_apic_timer_interrupt+0x56/0x90
[    8.659724]        apic_timer_interrupt+0xa7/0xb0
[    8.659724]        vmw_send_msg+0x91/0xc0 [vmwgfx]
[    8.659725]
[    8.659725] -> #2 (&(&n->list_lock)->rlock){-.-.}:
[    8.659726]        lock_acquire+0x6d/0x90
[    8.659726]        _raw_spin_lock+0x2c/0x40
[    8.659727]        get_partial_node.isra.87+0x44/0x2c0
[    8.659727]        ___slab_alloc+0x262/0x610
[    8.659727]        __slab_alloc+0x41/0x85
[    8.659727]        kmem_cache_alloc+0x18a/0x1d0
[    8.659728]        __debug_object_init+0x3e2/0x400
[    8.659728]        debug_object_activate+0x12d/0x200
[    8.659728]        add_timer+0x6f/0x1b0
[    8.659729]        __queue_delayed_work+0x5b/0xa0
[    8.659729]        queue_delayed_work_on+0x4f/0xa0
[    8.659729]        check_lifetime+0x194/0x2e0
[    8.659730]        process_one_work+0x1c1/0x3e0
[    8.659730]        worker_thread+0x45/0x3c0
[    8.659730]        kthread+0xff/0x140
[    8.659730]        ret_from_fork+0x2a/0x40
[    8.659731]
[    8.659731] -> #1 (&base->lock){..-.}:
[    8.659732]        lock_acquire+0x6d/0x90
[    8.659732]        _raw_spin_lock_irqsave+0x44/0x60
[    8.659732]        lock_timer_base+0x78/0xa0
[    8.659733]        add_timer+0x46/0x1b0
[    8.659733]        __queue_delayed_work+0x5b/0xa0
[    8.659733]        queue_delayed_work_on+0x4f/0xa0
[    8.659734]        vmw_fb_dirty_mark+0xe2/0xf0 [vmwgfx]
[    8.659734]        vmw_fb_set_par+0x361/0x5e0 [vmwgfx]
[    8.659734]        fbcon_init+0x4e6/0x570
[    8.659734]        visual_init+0xd1/0x130
[    8.659735]        do_bind_con_driver+0x132/0x300
[    8.659735]        do_take_over_console+0x101/0x170
[    8.659735]        do_fbcon_takeover+0x52/0xb0
[    8.659736]        fbcon_event_notify+0x604/0x750
[    8.659736]        notifier_call_chain+0x44/0x70
[    8.659736]        __blocking_notifier_call_chain+0x4e/0x70
[    8.659737]        blocking_notifier_call_chain+0x11/0x20
[    8.659737]        fb_notifier_call_chain+0x16/0x20
[    8.659737]        register_framebuffer+0x25d/0x350
[    8.659737]        vmw_fb_init+0x488/0x590 [vmwgfx]
[    8.659738]        vmw_driver_load+0x1065/0x1210 [vmwgfx]
[    8.659738]        drm_dev_register+0x145/0x1e0 [drm]
[    8.659738]        drm_get_pci_dev+0x9a/0x160 [drm]
[    8.659739]        vmw_probe+0x10/0x20 [vmwgfx]
[    8.659739]        local_pci_probe+0x40/0xa0
[    8.659739]        pci_device_probe+0x14f/0x1c0
[    8.659740]        driver_probe_device+0x2a1/0x460
[    8.659740]        __driver_attach+0xdc/0xe0
[    8.659740]        bus_for_each_dev+0x6e/0xc0
[    8.659740]        driver_attach+0x19/0x20
[    8.659741]        bus_add_driver+0x40/0x260
[    8.659741]        driver_register+0x5b/0xe0
[    8.659741]        __pci_register_driver+0x66/0x70
[    8.659742]        vmwgfx_init+0x28/0x1000 [vmwgfx]
[    8.659742]        do_one_initcall+0x4c/0x1a2
[    8.659742]        do_init_module+0x56/0x1f2
[    8.659743]        load_module+0x1148/0x1940
[    8.659743]        SYSC_finit_module+0xa9/0x100
[    8.659743]        SyS_finit_module+0x9/0x10
[    8.659743]        entry_SYSCALL_64_fastpath+0x1f/0xbe
[    8.659744]
[    8.659744] -> #0 (&(&par->dirty.lock)->rlock){....}:
[    8.659745]        __lock_acquire+0x12a8/0x1530
[    8.659745]        lock_acquire+0x6d/0x90
[    8.659746]        _raw_spin_lock_irqsave+0x44/0x60
[    8.659746]        vmw_fb_dirty_mark+0x33/0xf0 [vmwgfx]
[    8.659746]        vmw_fb_imageblit+0x2b/0x30 [vmwgfx]
[    8.659746]        soft_cursor+0x1ae/0x230
[    8.659747]        bit_cursor+0x5dd/0x610
[    8.659747]        fbcon_cursor+0x151/0x1c0
[    8.659747]        hide_cursor+0x23/0x90
[    8.659748]        vt_console_print+0x3ab/0x3e0
[    8.659748]        console_unlock+0x46c/0x5c0
[    8.659748]        register_framebuffer+0x273/0x350
[    8.659748]        vmw_fb_init+0x488/0x590 [vmwgfx]
[    8.659749]        vmw_driver_load+0x1065/0x1210 [vmwgfx]
[    8.659749]        drm_dev_register+0x145/0x1e0 [drm]
[    8.659749]        drm_get_pci_dev+0x9a/0x160 [drm]
[    8.659750]        vmw_probe+0x10/0x20 [vmwgfx]
[    8.659750]        local_pci_probe+0x40/0xa0
[    8.659750]        pci_device_probe+0x14f/0x1c0
[    8.659751]        driver_probe_device+0x2a1/0x460
[    8.659751]        __driver_attach+0xdc/0xe0
[    8.659751]        bus_for_each_dev+0x6e/0xc0
[    8.659752]        driver_attach+0x19/0x20
[    8.659752]        bus_add_driver+0x40/0x260
[    8.659752]        driver_register+0x5b/0xe0
[    8.659752]        __pci_register_driver+0x66/0x70
[    8.659753]        vmwgfx_init+0x28/0x1000 [vmwgfx]
[    8.659753]        do_one_initcall+0x4c/0x1a2
[    8.659753]        do_init_module+0x56/0x1f2
[    8.659754]        load_module+0x1148/0x1940
[    8.659754]        SYSC_finit_module+0xa9/0x100
[    8.659754]        SyS_finit_module+0x9/0x10
[    8.659755]        entry_SYSCALL_64_fastpath+0x1f/0xbe
[    8.659755]
[    8.659755] other info that might help us debug this:
[    8.659755]
[    8.659755] Chain exists of:
[    8.659756]   &(&par->dirty.lock)->rlock --> logbuf_lock --> console_owner
[    8.659757]
[    8.659757]  Possible unsafe locking scenario:
[    8.659758]
[    8.659758]        CPU0                    CPU1
[    8.659758]        ----                    ----
[    8.659758]   lock(console_owner);
[    8.659759]                                lock(logbuf_lock);
[    8.659760]                                lock(console_owner);
[    8.659761]   lock(&(&par->dirty.lock)->rlock);
[    8.659761]
[    8.659761]  *** DEADLOCK ***
[    8.659762]
[    8.659762] 7 locks held by systemd-udevd/184:
[    8.659762]  #0:  (&dev->mutex){....}, at: [<ffffffff8d46fbac>] __driver_attach+0x4c/0xe0
[    8.659763]  #1:  (&dev->mutex){....}, at: [<ffffffff8d46fbba>] __driver_attach+0x5a/0xe0
[    8.659764]  #2:  (drm_global_mutex){+.+.}, at: [<ffffffffc0144189>] drm_dev_register+0x29/0x1e0 [drm]
[    8.659765]  #3:  (registration_lock){+.+.}, at: [<ffffffff8d38d6a1>] register_framebuffer+0x31/0x350
[    8.659767]  #4:  (console_lock){+.+.}, at: [<ffffffff8d38d8ea>] register_framebuffer+0x27a/0x350
[    8.659768]  #5:  (console_owner){....}, at: [<ffffffff8d0d5c63>] console_unlock+0x173/0x5c0
[    8.659769]  #6:  (printing_lock){....}, at: [<ffffffff8d4226f1>] vt_console_print+0x71/0x3e0
[    8.659770]
[    8.659770] stack backtrace:
[    8.659770] CPU: 0 PID: 184 Comm: systemd-udevd Not tainted 4.14.0-rc8+ #312
[    8.659771] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[    8.659771] Call Trace:
[    8.659772]  dump_stack+0x85/0xc9
[    8.659772]  print_circular_bug.isra.40+0x1f9/0x207
[    8.659772]  __lock_acquire+0x12a8/0x1530
[    8.659772]  ? soft_cursor+0x1ae/0x230
[    8.659773]  lock_acquire+0x6d/0x90
[    8.659773]  ? vmw_fb_dirty_mark+0x33/0xf0 [vmwgfx]
[    8.659773]  _raw_spin_lock_irqsave+0x44/0x60
[    8.659774]  ? vmw_fb_dirty_mark+0x33/0xf0 [vmwgfx]
[    8.659774]  vmw_fb_dirty_mark+0x33/0xf0 [vmwgfx]
[    8.659774]  vmw_fb_imageblit+0x2b/0x30 [vmwgfx]
[    8.659774]  soft_cursor+0x1ae/0x230
[    8.659775]  bit_cursor+0x5dd/0x610
[    8.659775]  ? vsnprintf+0x221/0x580
[    8.659775]  fbcon_cursor+0x151/0x1c0
[    8.659776]  ? bit_clear+0x110/0x110
[    8.659776]  hide_cursor+0x23/0x90
[    8.659776]  vt_console_print+0x3ab/0x3e0
[    8.659776]  console_unlock+0x46c/0x5c0
[    8.659777]  ? console_unlock+0x173/0x5c0
[    8.659777]  register_framebuffer+0x273/0x350
[    8.659777]  vmw_fb_init+0x488/0x590 [vmwgfx]
[    8.659778]  vmw_driver_load+0x1065/0x1210 [vmwgfx]
[    8.659778]  drm_dev_register+0x145/0x1e0 [drm]
[    8.659778]  ? pci_enable_device_flags+0xe0/0x130
[    8.659778]  drm_get_pci_dev+0x9a/0x160 [drm]
[    8.659779]  vmw_probe+0x10/0x20 [vmwgfx]
[    8.659779]  local_pci_probe+0x40/0xa0
[    8.659779]  pci_device_probe+0x14f/0x1c0
[    8.659780]  driver_probe_device+0x2a1/0x460
[    8.659780]  __driver_attach+0xdc/0xe0
[    8.659780]  ? driver_probe_device+0x460/0x460
[    8.659780]  bus_for_each_dev+0x6e/0xc0
[    8.659781]  driver_attach+0x19/0x20
[    8.659781]  bus_add_driver+0x40/0x260
[    8.659781]  driver_register+0x5b/0xe0
[    8.659782]  __pci_register_driver+0x66/0x70
[    8.659782]  ? 0xffffffffc0249000
[    8.659782]  vmwgfx_init+0x28/0x1000 [vmwgfx]
[    8.659782]  ? 0xffffffffc0249000
[    8.659783]  do_one_initcall+0x4c/0x1a2
[    8.659783]  ? do_init_module+0x1d/0x1f2
[    8.659783]  ? kmem_cache_alloc+0x18a/0x1d0
[    8.659783]  do_init_module+0x56/0x1f2
[    8.659784]  load_module+0x1148/0x1940
[    8.659784]  ? __symbol_put+0x60/0x60
[    8.659784]  SYSC_finit_module+0xa9/0x100
[    8.659784]  SyS_finit_module+0x9/0x10
[    8.659785]  entry_SYSCALL_64_fastpath+0x1f/0xbe
[    8.659785] RIP: 0033:0x7efea440f7f9
[    8.659785] RSP: 002b:00007fff881c9308 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[    8.659786] RAX: ffffffffffffffda RBX: 00005640f0f495f0 RCX: 00007efea440f7f9
[    8.659787] RDX: 0000000000000000 RSI: 00007efea4d2c099 RDI: 0000000000000011
[    8.659787] RBP: 00007efea4d2c099
[    8.659788] Lost 2 message(s)!

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Sergey Senozhatsky]

(Ccing Tejun)

On (11/07/17 10:40), Sergey Senozhatsky wrote:
> On (11/06/17 21:06), Tetsuo Handa wrote:
> > I tried your patch with warn_alloc() torture. It did not cause lockups.
> > But I felt that possibility of failing to flush last second messages (such
> > as SysRq-c or SysRq-b) to consoles has increased. Is this psychological?
> 
> do I understand it correctly that there are "lost messages"?
> 
> sysrq-b does an immediate emergency reboot. "normally" it's not expected
> to flush any pending logbuf messages because it's an emergency-reboot...
> but in fact it does. and this is why sysrq-b is not 100% reliable:
> 
> 	__handle_sysrq()
> 	{
> 	  pr_info("SysRq : ");
> 
> 	  op_p = __sysrq_get_key_op(key);
> 	  pr_cont("%s\n", op_p->action_msg);
> 
> 	    op_p->handler(key);
> 
> 	  pr_cont("\n");
> 	}
> 
> those pr_info()/pr_cont() calls can spoil sysrq-b, depending on how
> badly the system is screwed. if pr_info() deadlocks, then we never
> go to op_p->handler(key)->emergency_restart(). even if you suppress
> printing of info loglevel messages, pr_info() still goes to
> console_unlock() and prints [console_seq, log_next_seq] messages,
> if there any.
> 
> there is, however, a subtle behaviour change, I think.
> 
> previously, in some cases [?], pr_info("SysRq : ") from __handle_sysrq()
> would flush logbuf messages. now we have that "break out of console_unlock()
> loop even though there are pending messages, there is another CPU doing
> printk()". so sysrb-b instead of looping in console_unlock() goes directly
> to emergency_restart(). without the change it would have continued looping
> in console_unlock() and would have called emergency_restart() only when
> "console_seq == log_next_seq".
> 
> now... the "subtle" part here is that we had that thing:
> 	- *IF* __handle_sysrq() grabs the console_sem then it will not
> 	  return from console_unlock() until logbuf is empty. so
> 	  concurrent printk() messages won't get lost.
> 
> what we have now is:
> 	- if there are concurrent printk() then __handle_sysrq() does not
> 	  fully flush the logbuf *even* if it grabbed the console_sem.

the change goes further. I did express some of my concerns during the KS,
I'll just bring them to the list.


we now always shift printing from a save - scheduleable - context to
a potentially unsafe one - atomic. by example:

CPU0			CPU1~CPU10	CPU11

console_lock()

			printk();

console_unlock()			IRQ
 set console_owner			printk()
					 sees console_owner
					 set console_waiter
 sees console_waiter
 break
					 console_unlock()
					 ^^^^ lockup [?]


so we are forcibly moving console_unlock() from safe CPU0 to unsafe CPU11.
previously we would continue printing from a schedulable context.


another case. bare with me.

suppose that call_console_drivers() is slower than printk() -> log_store(),
which is often the case.

now assume the following:

CPU0				CPU1

IRQ				IRQ

printk()			printk()
printk()			printk()
printk()			printk()


which probably could have been handled something like this:

CPU0				CPU1

IRQ				IRQ

printk()			printk()
 log_store()
				 log_store()
 console_unlock()
  call_console_drivers()
				printk()
				 log_store()
 goto again;
  call_console_drivers()
				printk()
				 log_store()
 goto again;
  call_console_drivers()
printk()
 log_store()
  console_unlock()
   call_console_drivers()
printk()
 log_store()
  console_unlock()
   call_console_drivers()


so CPU0 printed all the messages.
CPU1 simply did 3 * log_store()
	// + spent some cycles on logbuf_lock spin_lock
	// + console_sem trylock


but now every CPU will do call_console_drivers() + busy loop.


CPU0				CPU1

IRQ				IRQ

printk()			printk()
 log_store()
				 log_store()
 console_unlock()
  set console_owner
				 sees console_owner
				 sets console_waiter
				 spin
  call_console_drivers()
  sees console_waiter
   break

printk()
 log_store()
				 console_unlock()
				  set console_owner
 sees console_owner
 sets console_waiter
 spin
				 call_console_drivers()
				 sees console_waiter
				  break

				printk()
				 log_store()
 console_unlock()
  set console_owner
				 sees console_owner
				 sets console_waiter
				 spin
  call_console_drivers()
  sees console_waiter
  break

printk()
 log_store()
				 console_unlock()
				  set console_owner
 sees console_owner
 sets console_waiter
 spin

				.... and so on

which not only brings the cost of call_console_drivers() from
CPU's own printk(), but it also brings the cost [busy spin] of
call_console_drivers() happening on _another_ CPU. am I wrong?

	-ss

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Steven Rostedt]

On Wed, 8 Nov 2017 14:19:55 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> the change goes further. I did express some of my concerns during the KS,
> I'll just bring them to the list.
> 
> 
> we now always shift printing from a save - scheduleable - context to
> a potentially unsafe one - atomic. by example:

And vice versa. We are now likely to go from a unscheduleable context
to a schedule one, where before, that didn't exist.

And my approach, makes it more likely that the task doing the printk
prints its own message, and less likely to print someone else's.

> 
> CPU0			CPU1~CPU10	CPU11
> 
> console_lock()
> 
> 			printk();
> 
> console_unlock()			IRQ
>  set console_owner			printk()
> 					 sees console_owner
> 					 set console_waiter
>  sees console_waiter
>  break
> 					 console_unlock()
> 					 ^^^^ lockup [?]

How?

> 
> 
> so we are forcibly moving console_unlock() from safe CPU0 to unsafe CPU11.
> previously we would continue printing from a schedulable context.

And previously, we could be in unsafe CPU11 printing, and keep adding
to the buffer from safe CPUs, keeping CPU11 from ever stopping.

If anything, the patch makes the situation better, not worse.

-- Steve

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Sergey Senozhatsky]

Hello Steven,

On (11/08/17 09:29), Steven Rostedt wrote:
> On Wed, 8 Nov 2017 14:19:55 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > the change goes further. I did express some of my concerns during the KS,
> > I'll just bring them to the list.
> > 
> > 
> > we now always shift printing from a save - scheduleable - context to
> > a potentially unsafe one - atomic. by example:
> 
> And vice versa. We are now likely to go from a unscheduleable context
> to a schedule one, where before, that didn't exist.

the existence of "and vice versa" is kinda alarming, isn't it? it's sort
of "yes, we can break some things, but we also can improve some things."

> And my approach, makes it more likely that the task doing the printk
> prints its own message, and less likely to print someone else's.
> 
> > 
> > CPU0			CPU1~CPU10	CPU11
> > 
> > console_lock()
> > 
> > 			printk();
> > 
> > console_unlock()			IRQ
> >  set console_owner			printk()
> > 					 sees console_owner
> > 					 set console_waiter
> >  sees console_waiter
> >  break
> > 					 console_unlock()
> > 					 ^^^^ lockup [?]
> 
> How?

oh, yes, the missing part - assume CPU1~CPU10 did 5000 printk() calls,
while console_sem was locked on CPU0. then we console_unlock() from CPU0
and shortly after IRQ->printk() from CPU11 forcibly takes over, so now
we are in console_unlock() from atomic, printing some 5000 messages.

	-ss

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Steven Rostedt]

On Thu, 9 Nov 2017 09:56:35 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> Hello Steven,
> 
> On (11/08/17 09:29), Steven Rostedt wrote:
> > On Wed, 8 Nov 2017 14:19:55 +0900
> > Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> >   
> > > the change goes further. I did express some of my concerns during the KS,
> > > I'll just bring them to the list.
> > > 
> > > 
> > > we now always shift printing from a save - scheduleable - context to
> > > a potentially unsafe one - atomic. by example:  
> > 
> > And vice versa. We are now likely to go from a unscheduleable context
> > to a schedule one, where before, that didn't exist.  
> 
> the existence of "and vice versa" is kinda alarming, isn't it? it's sort
> of "yes, we can break some things, but we also can improve some things."

Not really. Because the heuristic is that what calls printk will do the
printk.

> 
> > And my approach, makes it more likely that the task doing the printk
> > prints its own message, and less likely to print someone else's.
> >   
> > > 
> > > CPU0			CPU1~CPU10	CPU11
> > > 
> > > console_lock()
> > > 
> > > 			printk();
> > > 
> > > console_unlock()			IRQ
> > >  set console_owner			printk()
> > > 					 sees console_owner
> > > 					 set console_waiter
> > >  sees console_waiter
> > >  break
> > > 					 console_unlock()
> > > 					 ^^^^ lockup [?]  
> > 
> > How?  
> 
> oh, yes, the missing part - assume CPU1~CPU10 did 5000 printk() calls,
> while console_sem was locked on CPU0. then we console_unlock() from CPU0
> and shortly after IRQ->printk() from CPU11 forcibly takes over, so now
> we are in console_unlock() from atomic, printing some 5000 messages.

I'd say remove those 5000 printks ;-)

-- Steve

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Sergey Senozhatsky]

On (11/08/17 22:29), Steven Rostedt wrote:
> > On (11/08/17 09:29), Steven Rostedt wrote:
> > > On Wed, 8 Nov 2017 14:19:55 +0900
> > > Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> > >   
> > > > the change goes further. I did express some of my concerns during the KS,
> > > > I'll just bring them to the list.
> > > > 
> > > > 
> > > > we now always shift printing from a save - scheduleable - context to
> > > > a potentially unsafe one - atomic. by example:  
> > > 
> > > And vice versa. We are now likely to go from a unscheduleable context
> > > to a schedule one, where before, that didn't exist.  
> > 
> > the existence of "and vice versa" is kinda alarming, isn't it? it's sort
> > of "yes, we can break some things, but we also can improve some things."
> 
> Not really. Because the heuristic is that what calls printk will do the
> printk.

so what we are looking at

   a) we take over printing. can be from safe context to unsafe context
      [well, bad karma]. can be from unsafe context to a safe one. or from
      safe context to another safe context... or from one unsafe context to
      another unsafe context [bad karma again]. we really never know, no
      one does.

      lots of uncertainties - "may be X, may be Y, may be Z". a bigger
      picture: we still can have the same lockup scenarios as we do
      have today.

      and we also bring busy loop with us, so the new console_sem
      owner [regardless its current context] CPU must wait until the
      current console_sem finishes its call_console_drivers(). I
      mentioned it in my another email, you seemed to jump over that
      part. was it irrelevant or wrong?

vs.

   b) we offload to printk_kthread [safe context].


why (a) is better than (b)?

	-ss

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Steven Rostedt]

On Thu, 9 Nov 2017 13:45:48 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

>
> so what we are looking at
> 
>    a) we take over printing. can be from safe context to unsafe context
>       [well, bad karma]. can be from unsafe context to a safe one. or from
>       safe context to another safe context... or from one unsafe context to
>       another unsafe context [bad karma again]. we really never know, no
>       one does.
> 
>       lots of uncertainties - "may be X, may be Y, may be Z". a bigger
>       picture: we still can have the same lockup scenarios as we do
>       have today.
> 
>       and we also bring busy loop with us, so the new console_sem
>       owner [regardless its current context] CPU must wait until the
>       current console_sem finishes its call_console_drivers(). I
>       mentioned it in my another email, you seemed to jump over that
>       part. was it irrelevant or wrong?
> 
> vs.
> 
>    b) we offload to printk_kthread [safe context].
> 
> 
> why (a) is better than (b)?
> 


What does safe context mean? Do we really want to allow the printk
thread to sleep when there's more to print? What happens if there's a
crash at that moment? How do we safely flush out all the data when the
printk thread is sleeping?

Now we could have something that uses both nicely. When the
printk_thread wakes up (we need to figure out when to do that), then it
could constantly take over.


	CPU1				CPU2
	----				----
   console_unlock()
     start printing a lot
     (more than one, wake up printk_thread)

					printk thread wakes up

					becomes the waiter

   sees waiter hands off

					starts printing

   printk()
     becomes waiter

					sees waiter hands off
					then becomes new waiter! <-- key

    starts printing
    sees waiter hands off
					continues printing


That is, we keep the waiter logic, and if anyone starts printing too
much, it wakes up the printk thread (hopefully on another CPU, or the
printk thread should migrate)  when the printk thread starts running it
becomes the new waiter if the console lock is still held (just like in
printk). Then it gets handed off the printk. We could just have the
printk thread keep going, though I'm not sure I would want to let it
schedule while printing. But it could also hand off printks (like
above), but then take it back immediately. This would mean that a
printk caller from a "critical" path will only get to do one message,
before the printk thread asks for it again.

Perhaps we could have more than one printk thread that migrates around,
and they each hand off the printing. This makes sure the printing
always happens and that it never stops due to the console_lock holder
sleeping and we never lock up one CPU that does printing. This would
work with just two printk threads. When one starts a printk loop,
another one wakes up on another CPU and becomes the waiter to get the
handoff of the console_lock. Then the first could schedule out (migrate
if the current CPU is busy), and take over. In  fact, this would
basically have two CPUs bouncing back and forth to do the printing.

This gives us our cake and we get to eat it too.

One, printing never stops (no scheduling out), as there's two threads
to share the load (obiously only on SMP machines).

There's no lock up. There's two threads that print a little, pass off
the console lock, do a cond_resched(), then takes over again.

Bascially, what I'm saying is that this is not two different solutions.
There is two algorithms that can work together to give us reliable
output and not lock up the system in doing so.

-- Steve

Re: [PATCH v3] printk: Add console owner and waiter logic to load balance console writes

[Sergey Senozhatsky]

On (11/09/17 00:06), Steven Rostedt wrote:
> What does safe context mean?

"safe" means that we don't cause lockups, stalls, sched throttlings, etc.
by doing console_unlock() from that context [task].


> Do we really want to allow the printk thread to sleep when there's more
> to print? What happens if there's a crash at that moment? How do we safely
> flush out all the data when the printk thread is sleeping?

printk-kthread does not schedule with the console_sem locked. one
of the changes to console_unlock() introduced with printk-kthread,
which we can't have without offloading.


> Now we could have something that uses both nicely. When the
> printk_thread wakes up (we need to figure out when to do that), then it
> could constantly take over.

certainly we can have a better hand-off scheme in printk-kthread patch set.


> 
> 	CPU1				CPU2
> 	----				----
>    console_unlock()
>      start printing a lot
>      (more than one, wake up printk_thread)
> 
> 					printk thread wakes up
> 
> 					becomes the waiter
> 
>    sees waiter hands off
> 
> 					starts printing
> 
>    printk()
>      becomes waiter
> 
> 					sees waiter hands off
> 					then becomes new waiter! <-- key
> 
>     starts printing
>     sees waiter hands off
> 					continues printing

there are corners cases here. learned the hard way. real reproducers
do exist.

wake_up_process() may enqueue printk_thread on the same rq that
current printk task is running on. so if your printk(), for instance,
is from IRQ then offloading won't happen.


> That is, we keep the waiter logic, and if anyone starts printing too
> much, it wakes up the printk thread (hopefully on another CPU, or the
> printk thread should migrate)  when the printk thread starts running it

it must migrate, yes. currently I'm playing games with the affinity
mask of printk-kthread when I do offloading.


> becomes the new waiter if the console lock is still held (just like in
> printk). Then it gets handed off the printk. We could just have the
> printk thread keep going, though I'm not sure I would want to let it
> schedule while printing. 

yes, scheduling under console_sem is not right. we don't want this.
not anymore, at least.


> But it could also hand off printks (like
> above), but then take it back immediately. This would mean that a
> printk caller from a "critical" path will only get to do one message,
> before the printk thread asks for it again.
> 
> Perhaps we could have more than one printk thread that migrates around,
> and they each hand off the printing. This makes sure the printing
> always happens and that it never stops due to the console_lock holder
> sleeping and we never lock up one CPU that does printing. This would
> work with just two printk threads. When one starts a printk loop,
> another one wakes up on another CPU and becomes the waiter to get the
> handoff of the console_lock. Then the first could schedule out (migrate
> if the current CPU is busy), and take over. In  fact, this would
> basically have two CPUs bouncing back and forth to do the printing.

can be. I pushed it much further, once. [probably too far].
and had per-CPU printk-kthreads :)


> This gives us our cake and we get to eat it too.
> 
> One, printing never stops (no scheduling out), as there's two threads
> to share the load (obiously only on SMP machines).
> 
> There's no lock up. There's two threads that print a little, pass off
> the console lock, do a cond_resched(), then takes over again.
> 
> Bascially, what I'm saying is that this is not two different solutions.
> There is two algorithms that can work together to give us reliable
> output and not lock up the system in doing so.

sure, I understand.

	-ss