Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-27 Thread Sergey Senozhatsky 
I'll Cc blockdev

On (03/27/18 08:36), bugzilla-dae...@bugzilla.kernel.org wrote:
> > --- Comment #17 from sergey.senozhatsky.w...@gmail.com ---
> > On (03/26/18 13:05), bugzilla-dae...@bugzilla.kernel.org wrote:
> > > Therefore the serial console is actually pretty fast. It seems that the
> > > deadline
> > > 10ms-per-character is not in the game here.
> > 
> > As the name suggests this is dmesg - content of logbuf. We can't tell
> > anything about serial consoles speed from it.
> 
> Grrr, you are right. It would be interesting to see the output from
> the serial port as well.
> 
> Anyway, it does not change the fact that printing so many same lines is
> useless. The throttling still would make sense and probably would
> solve the problem.

You are right.

Looking at backtraces 
(https://bugzilla.kernel.org/attachment.cgi?id=274953=edit)
there *probably* was just one CPU doing all printk-s and all printouts. And
there was one CPU waiting for that printing CPU to unlock the queue spin_lock.

The printing CPU was looping in scsi_request_fn() picking up requests
and calling sdev_printk() for each of them, because the device was
offline. Given that serial console is not very fast, that we called
serial console under queue spin_lock and the number of printks called,
it was enough to lockup the CPU which was spining on queue spin_lock and
to hard lockup the system.

scsi_request_fn() does unlock the queue lock later, but not in that
!scsi_device_online(sdev) error case.

scsi_request_fn()
{
for (;;) {
int rtn;
/*
 * get next queueable request.  We do this early to make sure
 * that the request is fully prepared even if we cannot
 * accept it.
 */
req = blk_peek_request(q);
if (!req)
break;

if (unlikely(!scsi_device_online(sdev))) {
sdev_printk(KERN_ERR, sdev,
"rejecting I/O to offline device\n");
scsi_kill_request(req, q);
continue;
^ still under spinlock
}
}

I'd probably just unlock/lock queue lock, rather than ratelimit printk-s,
before `continue'. Dunno.

James, Martin, what do you think?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-27 Thread Sergey Senozhatsky 
I'll Cc blockdev

On (03/27/18 08:36), bugzilla-dae...@bugzilla.kernel.org wrote:
> > --- Comment #17 from sergey.senozhatsky.w...@gmail.com ---
> > On (03/26/18 13:05), bugzilla-dae...@bugzilla.kernel.org wrote:
> > > Therefore the serial console is actually pretty fast. It seems that the
> > > deadline
> > > 10ms-per-character is not in the game here.
> > 
> > As the name suggests this is dmesg - content of logbuf. We can't tell
> > anything about serial consoles speed from it.
> 
> Grrr, you are right. It would be interesting to see the output from
> the serial port as well.
> 
> Anyway, it does not change the fact that printing so many same lines is
> useless. The throttling still would make sense and probably would
> solve the problem.

You are right.

Looking at backtraces 
(https://bugzilla.kernel.org/attachment.cgi?id=274953=edit)
there *probably* was just one CPU doing all printk-s and all printouts. And
there was one CPU waiting for that printing CPU to unlock the queue spin_lock.

The printing CPU was looping in scsi_request_fn() picking up requests
and calling sdev_printk() for each of them, because the device was
offline. Given that serial console is not very fast, that we called
serial console under queue spin_lock and the number of printks called,
it was enough to lockup the CPU which was spining on queue spin_lock and
to hard lockup the system.

scsi_request_fn() does unlock the queue lock later, but not in that
!scsi_device_online(sdev) error case.

scsi_request_fn()
{
for (;;) {
int rtn;
/*
 * get next queueable request.  We do this early to make sure
 * that the request is fully prepared even if we cannot
 * accept it.
 */
req = blk_peek_request(q);
if (!req)
break;

if (unlikely(!scsi_device_online(sdev))) {
sdev_printk(KERN_ERR, sdev,
"rejecting I/O to offline device\n");
scsi_kill_request(req, q);
continue;
^ still under spinlock
}
}

I'd probably just unlock/lock queue lock, rather than ratelimit printk-s,
before `continue'. Dunno.

James, Martin, what do you think?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-26 Thread Petr Mladek 
On Mon 2018-03-26 14:12:22, Sergey Senozhatsky wrote:
> Given how slow serial8250_console_putchar()->wait_for_xmitr() can be -
> 10ms of delay for every char - it's possible that we had no concurrent
> printk()-s from other CPUs. So may be we had just one printing CPU,
> and several CPUs spinning on a spin_lock which was owned by the printing
> CPU.
> 
> So that's why printk_deferred() helped here. It simply detached 8250
> and made spin_lock critical secrtion to be as fast as printk->log_store().
>
> But here comes the tricky part. Suppose that we:
> a) have at least two CPUs that call printk concurrently
> b) have hand off enabled
> 
> 
> Now, what will happen if we have something like this
> 
> CPU0  CPU1CPU2
>   spin_lock(queue_lock)
>printk printk
> cfqg_print_rwstat_recursive()   serial8250
>  spin_lock(queue_lock) printk 
>  serial8250
> serial8250printk
>
> serial8250
> 
> 
> I suspect that handoff may not be very helpful. CPU1 and CPU2 will wait for
> each to finish serial8250 and to hand off printing to each other. So CPU1
> will do 2 serial8250 invocations to printk its messages, and in between it
> will spin waiting for CPU2 to do its printk->serial8250 and to handoff
> printing to CPU1. The problem is that CPU1 will be under spin_lock() all
> that time, so CPU0 is going to suffer just like before.
> 
> Opinions?

It would help if Wen Yang could provide the entire log and also try the
Steven's patches. Otherwise, we are too speculating.

The 10ms delay-per-char looks scarry. But if I get it correctly, it
would happen only if we hit the deadline for each character. So,
a question is if the serial port is really that busy and if so why.

Also I wonder how many messages were actually printed under the
queue_lock. printk_deferred() seems to help but it is an immediate
offload. I wonder if the offload from console_unlock() would actually
help. It might fail to detect the critic situation if too many lines
are printed inside the lock and console_unlock() is called for each
line separately. Also it would fail when only single line caused that
big delay.

Best Regards,
Petr

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-26 Thread Petr Mladek 
On Mon 2018-03-26 14:12:22, Sergey Senozhatsky wrote:
> Given how slow serial8250_console_putchar()->wait_for_xmitr() can be -
> 10ms of delay for every char - it's possible that we had no concurrent
> printk()-s from other CPUs. So may be we had just one printing CPU,
> and several CPUs spinning on a spin_lock which was owned by the printing
> CPU.
> 
> So that's why printk_deferred() helped here. It simply detached 8250
> and made spin_lock critical secrtion to be as fast as printk->log_store().
>
> But here comes the tricky part. Suppose that we:
> a) have at least two CPUs that call printk concurrently
> b) have hand off enabled
> 
> 
> Now, what will happen if we have something like this
> 
> CPU0  CPU1CPU2
>   spin_lock(queue_lock)
>printk printk
> cfqg_print_rwstat_recursive()   serial8250
>  spin_lock(queue_lock) printk 
>  serial8250
> serial8250printk
>
> serial8250
> 
> 
> I suspect that handoff may not be very helpful. CPU1 and CPU2 will wait for
> each to finish serial8250 and to hand off printing to each other. So CPU1
> will do 2 serial8250 invocations to printk its messages, and in between it
> will spin waiting for CPU2 to do its printk->serial8250 and to handoff
> printing to CPU1. The problem is that CPU1 will be under spin_lock() all
> that time, so CPU0 is going to suffer just like before.
> 
> Opinions?

It would help if Wen Yang could provide the entire log and also try the
Steven's patches. Otherwise, we are too speculating.

The 10ms delay-per-char looks scarry. But if I get it correctly, it
would happen only if we hit the deadline for each character. So,
a question is if the serial port is really that busy and if so why.

Also I wonder how many messages were actually printed under the
queue_lock. printk_deferred() seems to help but it is an immediate
offload. I wonder if the offload from console_unlock() would actually
help. It might fail to detect the critic situation if too many lines
are printed inside the lock and console_unlock() is called for each
line separately. Also it would fail when only single line caused that
big delay.

Best Regards,
Petr

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-25 Thread Sergey Senozhatsky 
Cc-ing the kernel list and printk people.

Wen Yang, any chance we can switch to email? Bugzilla is not very handful.


On (03/26/18 02:40), bugzilla-dae...@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=199003
> 
> --- Comment #11 from Wen Yang (wen.yan...@zte.com.cn) ---
> Hello Steven,
> 
> +module_param_named(synchronous, printk_sync, bool, S_IRUGO);
> +MODULE_PARM_DESC(synchronous, "make printing to console synchronous");
> 
> It's depend on this kernel parameter(printk.synchronous), but this parameter 
> is
> readonly.
> So we must change grub files, and alse need to restart the server for changes
> to take effect.
> If we can configure it dynamically, it will be more useful.

So you are testing printk_kthread now, right? May I ask why?
Did Steven's patch help?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-25 Thread Sergey Senozhatsky 
Cc-ing the kernel list and printk people.

Wen Yang, any chance we can switch to email? Bugzilla is not very handful.


On (03/26/18 02:40), bugzilla-dae...@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=199003
> 
> --- Comment #11 from Wen Yang (wen.yan...@zte.com.cn) ---
> Hello Steven,
> 
> +module_param_named(synchronous, printk_sync, bool, S_IRUGO);
> +MODULE_PARM_DESC(synchronous, "make printing to console synchronous");
> 
> It's depend on this kernel parameter(printk.synchronous), but this parameter 
> is
> readonly.
> So we must change grub files, and alse need to restart the server for changes
> to take effect.
> If we can configure it dynamically, it will be more useful.

So you are testing printk_kthread now, right? May I ask why?
Did Steven's patch help?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-25 Thread Sergey Senozhatsky 
On (03/23/18 14:16), Petr Mladek wrote:
[..]
> If I get it correctly, the reporter of this bug has not tried
> Steven's patches yet.

It's not immediately clear.

It's not even completely clear if we are looking at "X cpus printk
1 cpu prints it all scenario" and it's not clear if hand off will be
helpful here. I'll try to explain.

What we see is:

CPU0 locked up on blkg->q->queue_lock

  [] cfqg_print_rwstat_recursive+0x36/0x40
  [] cgroup_seqfile_show+0x73/0x80
  [] ? seq_buf_alloc+0x17/0x40
  [] seq_read+0x10a/0x3b0
  [] vfs_read+0x9e/0x170
  [] SyS_read+0x7f/0xe0
  [] system_call_fastpath+0x16/0x1b

blkg->q->queue_lock was held by CPU7, which was spinnig in wait_for_xmitr().

 #5 [881ffb0b7548] __const_udelay at 81326678
 #6 [881ffb0b7558] wait_for_xmitr at 814056e0
 #7 [881ffb0b7580] serial8250_console_putchar at 814058ac
 #8 [881ffb0b75a0] uart_console_write at 8140035a
 #9 [881ffb0b75d0] serial8250_console_write at 814057fe
#10 [881ffb0b7618] call_console_drivers.constprop.17 at 81087011
#11 [881ffb0b7640] console_unlock at 810889e9
#12 [881ffb0b7680] vprintk_emit at 81088df4
#13 [881ffb0b76f0] dev_vprintk_emit at 81428e72
#14 [881ffb0b77a8] dev_printk_emit at 81428eee
#15 [881ffb0b7808] __dev_printk at 8142937e
#16 [881ffb0b7818] dev_printk at 8142942d
#17 [881ffb0b7888] sdev_prefix_printk at 81463771
#18 [881ffb0b7918] scsi_prep_state_check at 814598e4
#19 [881ffb0b7928] scsi_prep_fn at 8145992d
#20 [881ffb0b7960] blk_peek_request at 812f0826
#21 [881ffb0b7988] scsi_request_fn at 8145b588
#22 [881ffb0b79f0] __blk_run_queue at 812ebd63
#23 [881ffb0b7a08] blk_queue_bio at 812f1013 <<< acquired 
q->queue_lock
#24 [881ffb0b7a50] generic_make_request at 812ef209
#25 [881ffb0b7a98] submit_bio at 812ef351
#26 [881ffb0b7af0] xfs_submit_ioend_bio at a0146a63 [xfs]
#27 [881ffb0b7b00] xfs_submit_ioend at a0146b31 [xfs]
#28 [881ffb0b7b40] xfs_vm_writepages at a0146e18 [xfs]
#29 [881ffb0b7bb8] do_writepages at 8118da6e
#30 [881ffb0b7bc8] __writeback_single_inode at 812293a0
#31 [881ffb0b7c08] writeback_sb_inodes at 8122a08e
#32 [881ffb0b7cb0] __writeback_inodes_wb at 8122a2ef
#33 [881ffb0b7cf8] wb_writeback at 8122ab33
#34 [881ffb0b7d70] bdi_writeback_workfn at 8122cb2b
#35 [881ffb0b7e20] process_one_work at 810a851b
#36 [881ffb0b7e68] worker_thread at 810a9356
#37 [881ffb0b7ec8] kthread at 810b0b6f
#38 [881ffb0b7f50] ret_from_fork at 81697a18


Given how slow serial8250_console_putchar()->wait_for_xmitr() can be -
10ms of delay for every char - it's possible that we had no concurrent
printk()-s from other CPUs. So may be we had just one printing CPU,
and several CPUs spinning on a spin_lock which was owned by the printing
CPU.

So that's why printk_deferred() helped here. It simply detached 8250
and made spin_lock critical secrtion to be as fast as printk->log_store().


But here comes the tricky part. Suppose that we:
a) have at least two CPUs that call printk concurrently
b) have hand off enabled


Now, what will happen if we have something like this

CPU0CPU1CPU2
spin_lock(queue_lock)
 printk printk
cfqg_print_rwstat_recursive() serial8250
 spin_lock(queue_lock)   printk  
serial8250
  serial8250printk
 
serial8250


I suspect that handoff may not be very helpful. CPU1 and CPU2 will wait for
each to finish serial8250 and to hand off printing to each other. So CPU1
will do 2 serial8250 invocations to printk its messages, and in between it
will spin waiting for CPU2 to do its printk->serial8250 and to handoff
printing to CPU1. The problem is that CPU1 will be under spin_lock() all
that time, so CPU0 is going to suffer just like before.

Opinions?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-25 Thread Sergey Senozhatsky 
On (03/23/18 14:16), Petr Mladek wrote:
[..]
> If I get it correctly, the reporter of this bug has not tried
> Steven's patches yet.

It's not immediately clear.

It's not even completely clear if we are looking at "X cpus printk
1 cpu prints it all scenario" and it's not clear if hand off will be
helpful here. I'll try to explain.

What we see is:

CPU0 locked up on blkg->q->queue_lock

  [] cfqg_print_rwstat_recursive+0x36/0x40
  [] cgroup_seqfile_show+0x73/0x80
  [] ? seq_buf_alloc+0x17/0x40
  [] seq_read+0x10a/0x3b0
  [] vfs_read+0x9e/0x170
  [] SyS_read+0x7f/0xe0
  [] system_call_fastpath+0x16/0x1b

blkg->q->queue_lock was held by CPU7, which was spinnig in wait_for_xmitr().

 #5 [881ffb0b7548] __const_udelay at 81326678
 #6 [881ffb0b7558] wait_for_xmitr at 814056e0
 #7 [881ffb0b7580] serial8250_console_putchar at 814058ac
 #8 [881ffb0b75a0] uart_console_write at 8140035a
 #9 [881ffb0b75d0] serial8250_console_write at 814057fe
#10 [881ffb0b7618] call_console_drivers.constprop.17 at 81087011
#11 [881ffb0b7640] console_unlock at 810889e9
#12 [881ffb0b7680] vprintk_emit at 81088df4
#13 [881ffb0b76f0] dev_vprintk_emit at 81428e72
#14 [881ffb0b77a8] dev_printk_emit at 81428eee
#15 [881ffb0b7808] __dev_printk at 8142937e
#16 [881ffb0b7818] dev_printk at 8142942d
#17 [881ffb0b7888] sdev_prefix_printk at 81463771
#18 [881ffb0b7918] scsi_prep_state_check at 814598e4
#19 [881ffb0b7928] scsi_prep_fn at 8145992d
#20 [881ffb0b7960] blk_peek_request at 812f0826
#21 [881ffb0b7988] scsi_request_fn at 8145b588
#22 [881ffb0b79f0] __blk_run_queue at 812ebd63
#23 [881ffb0b7a08] blk_queue_bio at 812f1013 <<< acquired 
q->queue_lock
#24 [881ffb0b7a50] generic_make_request at 812ef209
#25 [881ffb0b7a98] submit_bio at 812ef351
#26 [881ffb0b7af0] xfs_submit_ioend_bio at a0146a63 [xfs]
#27 [881ffb0b7b00] xfs_submit_ioend at a0146b31 [xfs]
#28 [881ffb0b7b40] xfs_vm_writepages at a0146e18 [xfs]
#29 [881ffb0b7bb8] do_writepages at 8118da6e
#30 [881ffb0b7bc8] __writeback_single_inode at 812293a0
#31 [881ffb0b7c08] writeback_sb_inodes at 8122a08e
#32 [881ffb0b7cb0] __writeback_inodes_wb at 8122a2ef
#33 [881ffb0b7cf8] wb_writeback at 8122ab33
#34 [881ffb0b7d70] bdi_writeback_workfn at 8122cb2b
#35 [881ffb0b7e20] process_one_work at 810a851b
#36 [881ffb0b7e68] worker_thread at 810a9356
#37 [881ffb0b7ec8] kthread at 810b0b6f
#38 [881ffb0b7f50] ret_from_fork at 81697a18


Given how slow serial8250_console_putchar()->wait_for_xmitr() can be -
10ms of delay for every char - it's possible that we had no concurrent
printk()-s from other CPUs. So may be we had just one printing CPU,
and several CPUs spinning on a spin_lock which was owned by the printing
CPU.

So that's why printk_deferred() helped here. It simply detached 8250
and made spin_lock critical secrtion to be as fast as printk->log_store().


But here comes the tricky part. Suppose that we:
a) have at least two CPUs that call printk concurrently
b) have hand off enabled


Now, what will happen if we have something like this

CPU0CPU1CPU2
spin_lock(queue_lock)
 printk printk
cfqg_print_rwstat_recursive() serial8250
 spin_lock(queue_lock)   printk  
serial8250
  serial8250printk
 
serial8250


I suspect that handoff may not be very helpful. CPU1 and CPU2 will wait for
each to finish serial8250 and to hand off printing to each other. So CPU1
will do 2 serial8250 invocations to printk its messages, and in between it
will spin waiting for CPU2 to do its printk->serial8250 and to handoff
printing to CPU1. The problem is that CPU1 will be under spin_lock() all
that time, so CPU0 is going to suffer just like before.

Opinions?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-23 Thread Petr Mladek 
On Fri 2018-03-23 21:06:22, Sergey Senozhatsky wrote:
> > > Sometimes I really wish we had detached consoles. Direct printk()->console
> > > is nice and cool, but... we can't have it. I don't want to pressure for
> > > printk_kthread, but look at all those consoles. There are not so many ways
> > > out. What do you think?
> > 
> > If anything, perhaps we could have a printk thread that is triggered to
> > wake up if any print is taking a long time, or if there's a lot of
> > prints happening. And then it could try to print anything in the
> > buffer. Just the mere printk() in the thread should do the hand off.
> 
> OK. Let's think more about this. I have that "wake up printk_kthread if
> any print is taking a long time, or if there's a lot of prints happening"
> patch set: a watchdog threshold based solution. I didn't update it for a
> while, but can take a look. Detaching printouts does look to me like
> something we need to do.
> 
> Offloading does not work well enough with hand off (in its current
> form). Because the CPU that we offloaded printing from can re-take
> console_sem the very next time it calls printk().
> 
> Something like
> 
>spin_lock()
>   printk() -> 8250
>console_unlock()
>offloadprintk_kthread
>   printk() -> 8250 console_unlock()
>   printk() -> 8250  hand off
>console_unlock()
> 
> so if printk() -> 8250 is very slow and is under some spin_lock
> (like in case of Bug 199003) then offloading doesn't make that much
> difference here. Right? If we don't hand off from printk_kthread
> then things do look different.

If we do not offload from printk_kthread, it might cause softlockups.
This might be solved by rescheduling from printk_kthread. The question
is if it is acceptable. I believe so because we still have cond_resched()
in console_unlock().

We should just make sure to release console_sem before rescheduling.
Then any other process might eventually continue flushing the messages.
It would help to reduce loosing messages. It might be essential when
panic(), suspend, ... happen when printk_kthread is sleeping.

Sigh, I am afraid that we still might need to disable the offload
in various situations.


> > I wonder how bad it would be to wake the printk thread whenever a
> > printk() is executed. Printks really shouldn't be that common.
> 
> That didn't work quite well for me. But I must admit that my previous
> printk_kthread version had some major design problems - preemption in
> printk path [including printk_kthread preemption], the lack of any
> reliable way for any CPU to control what printk_kthread is doing, and
> so on and on. Current version, I guess, is better. But I don't do
> "vprintk_emit() -> wake_up(printk_kthread)", instead I let "direct"
> printks and wake_up(printk_kthread) only when current CPU spent too
> much time in call_console_drivers(); it's quite easy to track given
> that printk->console_unlock() is preempt_disable() now. Besides,
> offloading from console_unlock() automatically handles various cases
> for use. Like printk_deferred() -> IRQ -> console_unlock() and so on.
> 
> What do you think?

IMHO, the wakeup from console_unlock() and related to watchdog threshold
makes sense.

I am still not sure about the reliable way for CPU control. The more
scheduler code we call the more printk_deferred() calls will be
needed.

Sigh, I am afraid that the patchset will not be trivial. We might
still need some justification for all the changes. If I get it
correctly, the reporter of this bug has not tried Steven's patches
yet.

Best Regards,
Petr

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-23 Thread Petr Mladek 
On Fri 2018-03-23 21:06:22, Sergey Senozhatsky wrote:
> > > Sometimes I really wish we had detached consoles. Direct printk()->console
> > > is nice and cool, but... we can't have it. I don't want to pressure for
> > > printk_kthread, but look at all those consoles. There are not so many ways
> > > out. What do you think?
> > 
> > If anything, perhaps we could have a printk thread that is triggered to
> > wake up if any print is taking a long time, or if there's a lot of
> > prints happening. And then it could try to print anything in the
> > buffer. Just the mere printk() in the thread should do the hand off.
> 
> OK. Let's think more about this. I have that "wake up printk_kthread if
> any print is taking a long time, or if there's a lot of prints happening"
> patch set: a watchdog threshold based solution. I didn't update it for a
> while, but can take a look. Detaching printouts does look to me like
> something we need to do.
> 
> Offloading does not work well enough with hand off (in its current
> form). Because the CPU that we offloaded printing from can re-take
> console_sem the very next time it calls printk().
> 
> Something like
> 
>spin_lock()
>   printk() -> 8250
>console_unlock()
>offloadprintk_kthread
>   printk() -> 8250 console_unlock()
>   printk() -> 8250  hand off
>console_unlock()
> 
> so if printk() -> 8250 is very slow and is under some spin_lock
> (like in case of Bug 199003) then offloading doesn't make that much
> difference here. Right? If we don't hand off from printk_kthread
> then things do look different.

If we do not offload from printk_kthread, it might cause softlockups.
This might be solved by rescheduling from printk_kthread. The question
is if it is acceptable. I believe so because we still have cond_resched()
in console_unlock().

We should just make sure to release console_sem before rescheduling.
Then any other process might eventually continue flushing the messages.
It would help to reduce loosing messages. It might be essential when
panic(), suspend, ... happen when printk_kthread is sleeping.

Sigh, I am afraid that we still might need to disable the offload
in various situations.


> > I wonder how bad it would be to wake the printk thread whenever a
> > printk() is executed. Printks really shouldn't be that common.
> 
> That didn't work quite well for me. But I must admit that my previous
> printk_kthread version had some major design problems - preemption in
> printk path [including printk_kthread preemption], the lack of any
> reliable way for any CPU to control what printk_kthread is doing, and
> so on and on. Current version, I guess, is better. But I don't do
> "vprintk_emit() -> wake_up(printk_kthread)", instead I let "direct"
> printks and wake_up(printk_kthread) only when current CPU spent too
> much time in call_console_drivers(); it's quite easy to track given
> that printk->console_unlock() is preempt_disable() now. Besides,
> offloading from console_unlock() automatically handles various cases
> for use. Like printk_deferred() -> IRQ -> console_unlock() and so on.
> 
> What do you think?

IMHO, the wakeup from console_unlock() and related to watchdog threshold
makes sense.

I am still not sure about the reliable way for CPU control. The more
scheduler code we call the more printk_deferred() calls will be
needed.

Sigh, I am afraid that the patchset will not be trivial. We might
still need some justification for all the changes. If I get it
correctly, the reporter of this bug has not tried Steven's patches
yet.

Best Regards,
Petr

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-23 Thread Sergey Senozhatsky 
Hello Steven,

On (03/22/18 18:25), Steven Rostedt wrote:
> > static void wait_for_xmitr(struct uart_8250_port *up, int bits)
> > {
> > unsigned int status, tmout = 1;
> > 
> > /* Wait up to 10ms for the character(s) to be sent. */
> > for (;;) {

> > if (--tmout == 0)
> > break;
> > udelay(1);
> > touch_nmi_watchdog();
> > }
> > 
> > /* Wait up to 1s for flow control if necessary */
> > if (up->port.flags & UPF_CONS_FLOW) {
> > for (tmout = 100; tmout; tmout--) {

> > udelay(1);
> > touch_nmi_watchdog();
> > }
> > }
> > ...
> > }
> > 
> > a 1+ second long busy loop in the console driver is quite close to
> 
> Yeah that's nasty but shouldn't ever hit 1 second unless there's
> hardware issues.

Would probably agree. But even without that 1 second UPF_CONS_FLOW loop
(it seems that there are not so many consoles that have that flag set),
we have a 10ms [1 * udelay(1)] loop after every character. So if we
print a 512-bytes kernel message [1/2 of a max printk message length]
than its 0.01 * (512 + \r + \n) seconds. Which is a lot, unless I
miscalculated 1 * udelay(1). Delays in the first loop are normal,
probably not always 10ms, tho, but still.

[..]
> > Sometimes I really wish we had detached consoles. Direct printk()->console
> > is nice and cool, but... we can't have it. I don't want to pressure for
> > printk_kthread, but look at all those consoles. There are not so many ways
> > out. What do you think?
> 
> If anything, perhaps we could have a printk thread that is triggered to
> wake up if any print is taking a long time, or if there's a lot of
> prints happening. And then it could try to print anything in the
> buffer. Just the mere printk() in the thread should do the hand off.

OK. Let's think more about this. I have that "wake up printk_kthread if
any print is taking a long time, or if there's a lot of prints happening"
patch set: a watchdog threshold based solution. I didn't update it for a
while, but can take a look. Detaching printouts does look to me like
something we need to do.

Offloading does not work well enough with hand off (in its current
form). Because the CPU that we offloaded printing from can re-take
console_sem the very next time it calls printk().

Something like

   spin_lock()
printk() -> 8250
 console_unlock()
 offloadprintk_kthread
printk() -> 8250 console_unlock()
printk() -> 8250  hand off
 console_unlock()

so if printk() -> 8250 is very slow and is under some spin_lock
(like in case of Bug 199003) then offloading doesn't make that much
difference here. Right? If we don't hand off from printk_kthread
then things do look different.

> I wonder how bad it would be to wake the printk thread whenever a
> printk() is executed. Printks really shouldn't be that common.

That didn't work quite well for me. But I must admit that my previous
printk_kthread version had some major design problems - preemption in
printk path [including printk_kthread preemption], the lack of any
reliable way for any CPU to control what printk_kthread is doing, and
so on and on. Current version, I guess, is better. But I don't do
"vprintk_emit() -> wake_up(printk_kthread)", instead I let "direct"
printks and wake_up(printk_kthread) only when current CPU spent too
much time in call_console_drivers(); it's quite easy to track given
that printk->console_unlock() is preempt_disable() now. Besides,
offloading from console_unlock() automatically handles various cases
for use. Like printk_deferred() -> IRQ -> console_unlock() and so on.

What do you think?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-23 Thread Sergey Senozhatsky 
Hello Steven,

On (03/22/18 18:25), Steven Rostedt wrote:
> > static void wait_for_xmitr(struct uart_8250_port *up, int bits)
> > {
> > unsigned int status, tmout = 1;
> > 
> > /* Wait up to 10ms for the character(s) to be sent. */
> > for (;;) {

> > if (--tmout == 0)
> > break;
> > udelay(1);
> > touch_nmi_watchdog();
> > }
> > 
> > /* Wait up to 1s for flow control if necessary */
> > if (up->port.flags & UPF_CONS_FLOW) {
> > for (tmout = 100; tmout; tmout--) {

> > udelay(1);
> > touch_nmi_watchdog();
> > }
> > }
> > ...
> > }
> > 
> > a 1+ second long busy loop in the console driver is quite close to
> 
> Yeah that's nasty but shouldn't ever hit 1 second unless there's
> hardware issues.

Would probably agree. But even without that 1 second UPF_CONS_FLOW loop
(it seems that there are not so many consoles that have that flag set),
we have a 10ms [1 * udelay(1)] loop after every character. So if we
print a 512-bytes kernel message [1/2 of a max printk message length]
than its 0.01 * (512 + \r + \n) seconds. Which is a lot, unless I
miscalculated 1 * udelay(1). Delays in the first loop are normal,
probably not always 10ms, tho, but still.

[..]
> > Sometimes I really wish we had detached consoles. Direct printk()->console
> > is nice and cool, but... we can't have it. I don't want to pressure for
> > printk_kthread, but look at all those consoles. There are not so many ways
> > out. What do you think?
> 
> If anything, perhaps we could have a printk thread that is triggered to
> wake up if any print is taking a long time, or if there's a lot of
> prints happening. And then it could try to print anything in the
> buffer. Just the mere printk() in the thread should do the hand off.

OK. Let's think more about this. I have that "wake up printk_kthread if
any print is taking a long time, or if there's a lot of prints happening"
patch set: a watchdog threshold based solution. I didn't update it for a
while, but can take a look. Detaching printouts does look to me like
something we need to do.

Offloading does not work well enough with hand off (in its current
form). Because the CPU that we offloaded printing from can re-take
console_sem the very next time it calls printk().

Something like

   spin_lock()
printk() -> 8250
 console_unlock()
 offloadprintk_kthread
printk() -> 8250 console_unlock()
printk() -> 8250  hand off
 console_unlock()

so if printk() -> 8250 is very slow and is under some spin_lock
(like in case of Bug 199003) then offloading doesn't make that much
difference here. Right? If we don't hand off from printk_kthread
then things do look different.

> I wonder how bad it would be to wake the printk thread whenever a
> printk() is executed. Printks really shouldn't be that common.

That didn't work quite well for me. But I must admit that my previous
printk_kthread version had some major design problems - preemption in
printk path [including printk_kthread preemption], the lack of any
reliable way for any CPU to control what printk_kthread is doing, and
so on and on. Current version, I guess, is better. But I don't do
"vprintk_emit() -> wake_up(printk_kthread)", instead I let "direct"
printks and wake_up(printk_kthread) only when current CPU spent too
much time in call_console_drivers(); it's quite easy to track given
that printk->console_unlock() is preempt_disable() now. Besides,
offloading from console_unlock() automatically handles various cases
for use. Like printk_deferred() -> IRQ -> console_unlock() and so on.

What do you think?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-22 Thread Steven Rostedt 
On Thu, 22 Mar 2018 11:14:37 +0900
Sergey Senozhatsky  wrote:


> Looking at
>  
> printk()->call_console_drivers()->serial8250_console_putchar()->wait_for_xmitr()
> 
> ... wait_for_xmitr() can spin for over 1 second waiting for the UART_MSR_CTS
> bit.
> 
> static void wait_for_xmitr(struct uart_8250_port *up, int bits)
> {
>   unsigned int status, tmout = 1;
> 
>   /* Wait up to 10ms for the character(s) to be sent. */
>   for (;;) {
>   status = serial_in(up, UART_LSR);
> 
>   up->lsr_saved_flags |= status & LSR_SAVE_FLAGS;
> 
>   if ((status & bits) == bits)
>   break;
>   if (--tmout == 0)
>   break;
>   udelay(1);
>   touch_nmi_watchdog();
>   }
> 
>   /* Wait up to 1s for flow control if necessary */
>   if (up->port.flags & UPF_CONS_FLOW) {
>   for (tmout = 100; tmout; tmout--) {
>   unsigned int msr = serial_in(up, UART_MSR);
>   up->msr_saved_flags |= msr & MSR_SAVE_FLAGS;
>   if (msr & UART_MSR_CTS)
>   break;
>   udelay(1);
>   touch_nmi_watchdog();
>   }
>   }
>   ...
> }
> 
> a 1+ second long busy loop in the console driver is quite close to

Yeah that's nasty but shouldn't ever hit 1 second unless there's
hardware issues.

> "problems guaranteed". But, wait, there is even more. This wait_for_xmitr()
> busy wait is happening after every character we print on the console. So
> printk("foo") will generate 5 * wait_for_xmitr() busy loops [foo + \r + \n].
> They punch watchdog a lot, so at the least the system won't get killed
> by the hardlockup detector. But at the same time, it's still potentially a
> 1+ second busy loop in the console driver * strlen(message).
> 
> Sometimes I really wish we had detached consoles. Direct printk()->console
> is nice and cool, but... we can't have it. I don't want to pressure for
> printk_kthread, but look at all those consoles. There are not so many ways
> out. What do you think?

If anything, perhaps we could have a printk thread that is triggered to
wake up if any print is taking a long time, or if there's a lot of
prints happening. And then it could try to print anything in the
buffer. Just the mere printk() in the thread should do the hand off.

I wonder how bad it would be to wake the printk thread whenever a
printk() is executed. Printks really shouldn't be that common.

-- Steve

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-22 Thread Steven Rostedt 
On Thu, 22 Mar 2018 11:14:37 +0900
Sergey Senozhatsky  wrote:


> Looking at
>  
> printk()->call_console_drivers()->serial8250_console_putchar()->wait_for_xmitr()
> 
> ... wait_for_xmitr() can spin for over 1 second waiting for the UART_MSR_CTS
> bit.
> 
> static void wait_for_xmitr(struct uart_8250_port *up, int bits)
> {
>   unsigned int status, tmout = 1;
> 
>   /* Wait up to 10ms for the character(s) to be sent. */
>   for (;;) {
>   status = serial_in(up, UART_LSR);
> 
>   up->lsr_saved_flags |= status & LSR_SAVE_FLAGS;
> 
>   if ((status & bits) == bits)
>   break;
>   if (--tmout == 0)
>   break;
>   udelay(1);
>   touch_nmi_watchdog();
>   }
> 
>   /* Wait up to 1s for flow control if necessary */
>   if (up->port.flags & UPF_CONS_FLOW) {
>   for (tmout = 100; tmout; tmout--) {
>   unsigned int msr = serial_in(up, UART_MSR);
>   up->msr_saved_flags |= msr & MSR_SAVE_FLAGS;
>   if (msr & UART_MSR_CTS)
>   break;
>   udelay(1);
>   touch_nmi_watchdog();
>   }
>   }
>   ...
> }
> 
> a 1+ second long busy loop in the console driver is quite close to

Yeah that's nasty but shouldn't ever hit 1 second unless there's
hardware issues.

> "problems guaranteed". But, wait, there is even more. This wait_for_xmitr()
> busy wait is happening after every character we print on the console. So
> printk("foo") will generate 5 * wait_for_xmitr() busy loops [foo + \r + \n].
> They punch watchdog a lot, so at the least the system won't get killed
> by the hardlockup detector. But at the same time, it's still potentially a
> 1+ second busy loop in the console driver * strlen(message).
> 
> Sometimes I really wish we had detached consoles. Direct printk()->console
> is nice and cool, but... we can't have it. I don't want to pressure for
> printk_kthread, but look at all those consoles. There are not so many ways
> out. What do you think?

If anything, perhaps we could have a printk thread that is triggered to
wake up if any print is taking a long time, or if there's a lot of
prints happening. And then it could try to print anything in the
buffer. Just the mere printk() in the thread should do the hand off.

I wonder how bad it would be to wake the printk thread whenever a
printk() is executed. Printks really shouldn't be that common.

-- Steve

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-21 Thread Sergey Senozhatsky 
On (03/22/18 11:14), Sergey Senozhatsky wrote:
[..]
> Looking at
>  
> printk()->call_console_drivers()->serial8250_console_putchar()->wait_for_xmitr()
> 
> ... wait_for_xmitr() can spin for over 1 second waiting for the UART_MSR_CTS
> bit.

[..]

> a 1+ second long busy loop in the console driver is quite close to
> "problems guaranteed". But, wait, there is even more. This wait_for_xmitr()
> busy wait is happening after every character we print on the console. So
> printk("foo") will generate 5 * wait_for_xmitr() busy loops [foo + \r + \n].
> They punch watchdog a lot, so at the least the system won't get killed
> by the hardlockup detector. But at the same time, it's still potentially a
> 1+ second busy loop in the console driver * strlen(message).

One does not even need to have concurrent printk()-s in this case. A
single CPU doing several direct printks under spin_lock is already
enough:

CPUACPUB ~ CPUZ
spin_lock()
 printk->wait_for_xmitr spin_lock()
 printk->wait_for_xmitr
 ...
 printk->wait_for_xmitr << lockups >>
 printk->wait_for_xmitr
spin_unlock()

> Sometimes I really wish we had detached consoles. Direct printk()->console
> is nice and cool, but... we can't have it.

And this is, basically, what they do with printk_deferred(). We usually
use it to avoid deadlocks, but in this particular case it's used due to
the fact that direct printk() is way too painful, so they are detaching
printout and move it to another control path. Quite an interesting idea,
I must say.

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-21 Thread Sergey Senozhatsky 
On (03/22/18 11:14), Sergey Senozhatsky wrote:
[..]
> Looking at
>  
> printk()->call_console_drivers()->serial8250_console_putchar()->wait_for_xmitr()
> 
> ... wait_for_xmitr() can spin for over 1 second waiting for the UART_MSR_CTS
> bit.

[..]

> a 1+ second long busy loop in the console driver is quite close to
> "problems guaranteed". But, wait, there is even more. This wait_for_xmitr()
> busy wait is happening after every character we print on the console. So
> printk("foo") will generate 5 * wait_for_xmitr() busy loops [foo + \r + \n].
> They punch watchdog a lot, so at the least the system won't get killed
> by the hardlockup detector. But at the same time, it's still potentially a
> 1+ second busy loop in the console driver * strlen(message).

One does not even need to have concurrent printk()-s in this case. A
single CPU doing several direct printks under spin_lock is already
enough:

CPUACPUB ~ CPUZ
spin_lock()
 printk->wait_for_xmitr spin_lock()
 printk->wait_for_xmitr
 ...
 printk->wait_for_xmitr << lockups >>
 printk->wait_for_xmitr
spin_unlock()

> Sometimes I really wish we had detached consoles. Direct printk()->console
> is nice and cool, but... we can't have it.

And this is, basically, what they do with printk_deferred(). We usually
use it to avoid deadlocks, but in this particular case it's used due to
the fact that direct printk() is way too painful, so they are detaching
printout and move it to another control path. Quite an interesting idea,
I must say.

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-21 Thread Sergey Senozhatsky 
Hello Steven,

On (03/21/18 09:44), Steven Rostedt wrote:
[..]
> >  #4 [881ffb0b7540] delay_tsc at 81326724
> >  #5 [881ffb0b7548] __const_udelay at 81326678
> >  #6 [881ffb0b7558] wait_for_xmitr at 814056e0
> >  #7 [881ffb0b7580] serial8250_console_putchar at 814058ac
> >  #8 [881ffb0b75a0] uart_console_write at 8140035a
> >  #9 [881ffb0b75d0] serial8250_console_write at 814057fe
> > #10 [881ffb0b7618] call_console_drivers.constprop.17 at 81087011
> > #11 [881ffb0b7640] console_unlock at 810889e9
> > #12 [881ffb0b7680] vprintk_emit at 81088df4
> > #13 [881ffb0b76f0] dev_vprintk_emit at 81428e72
> > #14 [881ffb0b77a8] dev_printk_emit at 81428eee
> > #15 [881ffb0b7808] __dev_printk at 8142937e
> > #16 [881ffb0b7818] dev_printk at 8142942d
> > #17 [881ffb0b7888] sdev_prefix_printk at 81463771
> > #18 [881ffb0b7918] scsi_prep_state_check at 814598e4
> > #19 [881ffb0b7928] scsi_prep_fn at 8145992d
> > #20 [881ffb0b7960] blk_peek_request at 812f0826
> > #21 [881ffb0b7988] scsi_request_fn at 8145b588
> > #22 [881ffb0b79f0] __blk_run_queue at 812ebd63
> > #23 [881ffb0b7a08] blk_queue_bio at 812f1013
> > -》acquired q->queue_lock and wait for console_write to finish
> 
> What do you mean by "wait for console_write to finish" here?

*My guess*

I suppose a typical "printk->console_unlock() under spin_lock" thing

CPU0CPU1
spin_lock()
 printk spin_lock()
  console_unlock()
   for (;;)
call_console_drivers()

While other CPUs printk->log_store() and some (or may be just one) is locked
up on spin_lock(). So we have several lockup vectors here - one is
console_unlock() under spin_lock and the other one is CPUs spinning on the
very same spin_lock. So handoff should help here, no doubt. But it cannot help
if other CPUs will start to printk_deferred() instead of printk().


Looking at
 
printk()->call_console_drivers()->serial8250_console_putchar()->wait_for_xmitr()

... wait_for_xmitr() can spin for over 1 second waiting for the UART_MSR_CTS
bit.

static void wait_for_xmitr(struct uart_8250_port *up, int bits)
{
unsigned int status, tmout = 1;

/* Wait up to 10ms for the character(s) to be sent. */
for (;;) {
status = serial_in(up, UART_LSR);

up->lsr_saved_flags |= status & LSR_SAVE_FLAGS;

if ((status & bits) == bits)
break;
if (--tmout == 0)
break;
udelay(1);
touch_nmi_watchdog();
}

/* Wait up to 1s for flow control if necessary */
if (up->port.flags & UPF_CONS_FLOW) {
for (tmout = 100; tmout; tmout--) {
unsigned int msr = serial_in(up, UART_MSR);
up->msr_saved_flags |= msr & MSR_SAVE_FLAGS;
if (msr & UART_MSR_CTS)
break;
udelay(1);
touch_nmi_watchdog();
}
}
...
}

a 1+ second long busy loop in the console driver is quite close to
"problems guaranteed". But, wait, there is even more. This wait_for_xmitr()
busy wait is happening after every character we print on the console. So
printk("foo") will generate 5 * wait_for_xmitr() busy loops [foo + \r + \n].
They punch watchdog a lot, so at the least the system won't get killed
by the hardlockup detector. But at the same time, it's still potentially a
1+ second busy loop in the console driver * strlen(message).

Sometimes I really wish we had detached consoles. Direct printk()->console
is nice and cool, but... we can't have it. I don't want to pressure for
printk_kthread, but look at all those consoles. There are not so many ways
out. What do you think?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-21 Thread Sergey Senozhatsky 
Hello Steven,

On (03/21/18 09:44), Steven Rostedt wrote:
[..]
> >  #4 [881ffb0b7540] delay_tsc at 81326724
> >  #5 [881ffb0b7548] __const_udelay at 81326678
> >  #6 [881ffb0b7558] wait_for_xmitr at 814056e0
> >  #7 [881ffb0b7580] serial8250_console_putchar at 814058ac
> >  #8 [881ffb0b75a0] uart_console_write at 8140035a
> >  #9 [881ffb0b75d0] serial8250_console_write at 814057fe
> > #10 [881ffb0b7618] call_console_drivers.constprop.17 at 81087011
> > #11 [881ffb0b7640] console_unlock at 810889e9
> > #12 [881ffb0b7680] vprintk_emit at 81088df4
> > #13 [881ffb0b76f0] dev_vprintk_emit at 81428e72
> > #14 [881ffb0b77a8] dev_printk_emit at 81428eee
> > #15 [881ffb0b7808] __dev_printk at 8142937e
> > #16 [881ffb0b7818] dev_printk at 8142942d
> > #17 [881ffb0b7888] sdev_prefix_printk at 81463771
> > #18 [881ffb0b7918] scsi_prep_state_check at 814598e4
> > #19 [881ffb0b7928] scsi_prep_fn at 8145992d
> > #20 [881ffb0b7960] blk_peek_request at 812f0826
> > #21 [881ffb0b7988] scsi_request_fn at 8145b588
> > #22 [881ffb0b79f0] __blk_run_queue at 812ebd63
> > #23 [881ffb0b7a08] blk_queue_bio at 812f1013
> > -》acquired q->queue_lock and wait for console_write to finish
> 
> What do you mean by "wait for console_write to finish" here?

*My guess*

I suppose a typical "printk->console_unlock() under spin_lock" thing

CPU0CPU1
spin_lock()
 printk spin_lock()
  console_unlock()
   for (;;)
call_console_drivers()

While other CPUs printk->log_store() and some (or may be just one) is locked
up on spin_lock(). So we have several lockup vectors here - one is
console_unlock() under spin_lock and the other one is CPUs spinning on the
very same spin_lock. So handoff should help here, no doubt. But it cannot help
if other CPUs will start to printk_deferred() instead of printk().


Looking at
 
printk()->call_console_drivers()->serial8250_console_putchar()->wait_for_xmitr()

... wait_for_xmitr() can spin for over 1 second waiting for the UART_MSR_CTS
bit.

static void wait_for_xmitr(struct uart_8250_port *up, int bits)
{
unsigned int status, tmout = 1;

/* Wait up to 10ms for the character(s) to be sent. */
for (;;) {
status = serial_in(up, UART_LSR);

up->lsr_saved_flags |= status & LSR_SAVE_FLAGS;

if ((status & bits) == bits)
break;
if (--tmout == 0)
break;
udelay(1);
touch_nmi_watchdog();
}

/* Wait up to 1s for flow control if necessary */
if (up->port.flags & UPF_CONS_FLOW) {
for (tmout = 100; tmout; tmout--) {
unsigned int msr = serial_in(up, UART_MSR);
up->msr_saved_flags |= msr & MSR_SAVE_FLAGS;
if (msr & UART_MSR_CTS)
break;
udelay(1);
touch_nmi_watchdog();
}
}
...
}

a 1+ second long busy loop in the console driver is quite close to
"problems guaranteed". But, wait, there is even more. This wait_for_xmitr()
busy wait is happening after every character we print on the console. So
printk("foo") will generate 5 * wait_for_xmitr() busy loops [foo + \r + \n].
They punch watchdog a lot, so at the least the system won't get killed
by the hardlockup detector. But at the same time, it's still potentially a
1+ second busy loop in the console driver * strlen(message).

Sometimes I really wish we had detached consoles. Direct printk()->console
is nice and cool, but... we can't have it. I don't want to pressure for
printk_kthread, but look at all those consoles. There are not so many ways
out. What do you think?

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-21 Thread Steven Rostedt 
[ Adding LKML too ]

Link: https://bugzilla.kernel.org/show_bug.cgi?id=199003

>From the bugzilla report:

> Watchdog detected hard LOCKUP on cpu 16:
> [  557.369547] Kernel panic - not syncing: Hard LOCKUP
> [  557.369548] CPU: 16 PID: 11511 Comm: kubelet Tainted: GW  OE  
>  T 3.10.0-514.26.2.el7.x86_64 #1
> [  557.369548] Hardware name: ZTE EC600G3/XH20G2, BIOS UBF03.11.67_SVN65859 
> 12/29/2016
> [  557.369549]  818daafa 61eaf60c 88407d485b18 
> 816873ff
> [  557.369550]  88407d485b98 816807ea 000b0010 
> 88407d485ba8
> [  557.369551]  88407d485b48 61eaf60c 88407d485b88 
> 818da800
> [  557.369551] Call Trace:
> [  557.369552][] dump_stack+0x19/0x1b
> [  557.369555]  [] panic+0xe3/0x1f2
> [  557.369558]  [] nmi_panic+0x3f/0x40
> [  557.369559]  [] watchdog_overflow_callback+0xf9/0x100
> [  557.369560]  [] __perf_event_overflow+0x8e/0x1f0
> [  557.369562]  [] perf_event_overflow+0x14/0x20
> [  557.369563]  [] intel_pmu_handle_irq+0x1f8/0x4e0
> [  557.369564]  [] ? ioremap_page_range+0x27c/0x3e0
> [  557.369565]  [] ? vunmap_page_range+0x1c4/0x310
> [  557.369566]  [] ? unmap_kernel_range_noflush+0x11/0x20
> [  557.369567]  [] ? ghes_copy_tofrom_phys+0x124/0x210
> [  557.369568]  [] ? ghes_read_estatus+0xa0/0x190
> [  557.369569]  [] perf_event_nmi_handler+0x2b/0x50
> [  557.369571]  [] nmi_handle.isra.0+0x87/0x160
> [  557.369572]  [] ? cfqg_print_leaf_weight_device+0x40/0x40
> [  557.369573]  [] do_nmi+0x1d3/0x410
> [  557.369574]  [] ? cfqg_print_leaf_weight_device+0x40/0x40
> [  557.369575]  [] end_repeat_nmi+0x1e/0x2e
> [  557.369576]  [] ? cfqg_print_leaf_weight_device+0x40/0x40
> [  557.369577]  [] ? _raw_spin_lock_irq+0x3a/0x60
> [  557.369577]  [] ? _raw_spin_lock_irq+0x3a/0x60
> [  557.369579]  [] ? _raw_spin_lock_irq+0x3a/0x60
> [  557.369580]  <>  [] blkcg_print_blkgs+0x76/0xf0   
> 》 wait for blkg->q->queue_lock
> [  557.369581]  [] cfqg_print_rwstat_recursive+0x36/0x40
> [  557.369583]  [] cgroup_seqfile_show+0x73/0x80
> [  557.369584]  [] ? seq_buf_alloc+0x17/0x40
> [  557.369585]  [] seq_read+0x10a/0x3b0
> [  557.369586]  [] vfs_read+0x9e/0x170
> [  557.369587]  [] SyS_read+0x7f/0xe0
> [  557.369588]  [] system_call_fastpath+0x16/0x1b
> 
> source code:
> void blkcg_print_blkgs(struct seq_file *sf, struct blkcg *blkcg,
>  u64 (*prfill)(struct seq_file *,
>struct blkg_policy_data *, int),
>  const struct blkcg_policy *pol, int data,
>  bool show_total)
> {
>   struct blkcg_gq *blkg;
>   u64 total = 0;
> 
>   rcu_read_lock();
>   hlist_for_each_entry_rcu(blkg, >blkg_list, blkcg_node) {
>   spin_lock_irq(blkg->q->queue_lock);
>   ..
> }
>   
> 
> Another process,  "kworker/u113:1" acquired q->queue_lock and wait for 
> console_write to finish:
> 
> PID: 319TASK: 881ffb09edd0  CPU: 7   COMMAND: "kworker/u113:1"
>  #0 [881fffbc5e48] crash_nmi_callback at 8104d342
>  #1 [881fffbc5e58] nmi_handle at 81690477
>  #2 [881fffbc5eb0] do_nmi at 81690683
>  #3 [881fffbc5ef0] end_repeat_nmi at 8168f893
> [exception RIP: delay_tsc+68]
> RIP: 81326724  RSP: 881ffb0b7540  RFLAGS: 0046
> RAX: 0007  RBX: 81f89080  RCX: 0066a7d6eb5cfc9d
> RDX: 0066a7d6eb5d0629  RSI: 0007  RDI: 0a23
> RBP: 881ffb0b7540   R8:    R9: 
> R10: 03ff  R11: 0001  R12: 26f3
> R13: 0020  R14: 81d3c0fb  R15: 003b
> ORIG_RAX:   CS: 0010  SS: 0018
> ---  ---
>  #4 [881ffb0b7540] delay_tsc at 81326724
>  #5 [881ffb0b7548] __const_udelay at 81326678
>  #6 [881ffb0b7558] wait_for_xmitr at 814056e0
>  #7 [881ffb0b7580] serial8250_console_putchar at 814058ac
>  #8 [881ffb0b75a0] uart_console_write at 8140035a
>  #9 [881ffb0b75d0] serial8250_console_write at 814057fe
> #10 [881ffb0b7618] call_console_drivers.constprop.17 at 81087011
> #11 [881ffb0b7640] console_unlock at 810889e9
> #12 [881ffb0b7680] vprintk_emit at 81088df4
> #13 [881ffb0b76f0] dev_vprintk_emit at 81428e72
> #14 [881ffb0b77a8] dev_printk_emit at 81428eee
> #15 [881ffb0b7808] __dev_printk at 8142937e
> #16 [881ffb0b7818] dev_printk at 8142942d
> #17 [881ffb0b7888] sdev_prefix_printk at 81463771
> #18 [881ffb0b7918] scsi_prep_state_check at 814598e4
> #19 [881ffb0b7928] scsi_prep_fn at 8145992d
> #20 [881ffb0b7960] blk_peek_request at 812f0826
> #21 [881ffb0b7988] scsi_request_fn at 8145b588
> #22 [881ffb0b79f0] __blk_run_queue at 812ebd63
> #23

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-21 Thread Steven Rostedt 
[ Adding LKML too ]

Link: https://bugzilla.kernel.org/show_bug.cgi?id=199003

>From the bugzilla report:

> Watchdog detected hard LOCKUP on cpu 16:
> [  557.369547] Kernel panic - not syncing: Hard LOCKUP
> [  557.369548] CPU: 16 PID: 11511 Comm: kubelet Tainted: GW  OE  
>  T 3.10.0-514.26.2.el7.x86_64 #1
> [  557.369548] Hardware name: ZTE EC600G3/XH20G2, BIOS UBF03.11.67_SVN65859 
> 12/29/2016
> [  557.369549]  818daafa 61eaf60c 88407d485b18 
> 816873ff
> [  557.369550]  88407d485b98 816807ea 000b0010 
> 88407d485ba8
> [  557.369551]  88407d485b48 61eaf60c 88407d485b88 
> 818da800
> [  557.369551] Call Trace:
> [  557.369552][] dump_stack+0x19/0x1b
> [  557.369555]  [] panic+0xe3/0x1f2
> [  557.369558]  [] nmi_panic+0x3f/0x40
> [  557.369559]  [] watchdog_overflow_callback+0xf9/0x100
> [  557.369560]  [] __perf_event_overflow+0x8e/0x1f0
> [  557.369562]  [] perf_event_overflow+0x14/0x20
> [  557.369563]  [] intel_pmu_handle_irq+0x1f8/0x4e0
> [  557.369564]  [] ? ioremap_page_range+0x27c/0x3e0
> [  557.369565]  [] ? vunmap_page_range+0x1c4/0x310
> [  557.369566]  [] ? unmap_kernel_range_noflush+0x11/0x20
> [  557.369567]  [] ? ghes_copy_tofrom_phys+0x124/0x210
> [  557.369568]  [] ? ghes_read_estatus+0xa0/0x190
> [  557.369569]  [] perf_event_nmi_handler+0x2b/0x50
> [  557.369571]  [] nmi_handle.isra.0+0x87/0x160
> [  557.369572]  [] ? cfqg_print_leaf_weight_device+0x40/0x40
> [  557.369573]  [] do_nmi+0x1d3/0x410
> [  557.369574]  [] ? cfqg_print_leaf_weight_device+0x40/0x40
> [  557.369575]  [] end_repeat_nmi+0x1e/0x2e
> [  557.369576]  [] ? cfqg_print_leaf_weight_device+0x40/0x40
> [  557.369577]  [] ? _raw_spin_lock_irq+0x3a/0x60
> [  557.369577]  [] ? _raw_spin_lock_irq+0x3a/0x60
> [  557.369579]  [] ? _raw_spin_lock_irq+0x3a/0x60
> [  557.369580]  <>  [] blkcg_print_blkgs+0x76/0xf0   
> 》 wait for blkg->q->queue_lock
> [  557.369581]  [] cfqg_print_rwstat_recursive+0x36/0x40
> [  557.369583]  [] cgroup_seqfile_show+0x73/0x80
> [  557.369584]  [] ? seq_buf_alloc+0x17/0x40
> [  557.369585]  [] seq_read+0x10a/0x3b0
> [  557.369586]  [] vfs_read+0x9e/0x170
> [  557.369587]  [] SyS_read+0x7f/0xe0
> [  557.369588]  [] system_call_fastpath+0x16/0x1b
> 
> source code:
> void blkcg_print_blkgs(struct seq_file *sf, struct blkcg *blkcg,
>  u64 (*prfill)(struct seq_file *,
>struct blkg_policy_data *, int),
>  const struct blkcg_policy *pol, int data,
>  bool show_total)
> {
>   struct blkcg_gq *blkg;
>   u64 total = 0;
> 
>   rcu_read_lock();
>   hlist_for_each_entry_rcu(blkg, >blkg_list, blkcg_node) {
>   spin_lock_irq(blkg->q->queue_lock);
>   ..
> }
>   
> 
> Another process,  "kworker/u113:1" acquired q->queue_lock and wait for 
> console_write to finish:
> 
> PID: 319TASK: 881ffb09edd0  CPU: 7   COMMAND: "kworker/u113:1"
>  #0 [881fffbc5e48] crash_nmi_callback at 8104d342
>  #1 [881fffbc5e58] nmi_handle at 81690477
>  #2 [881fffbc5eb0] do_nmi at 81690683
>  #3 [881fffbc5ef0] end_repeat_nmi at 8168f893
> [exception RIP: delay_tsc+68]
> RIP: 81326724  RSP: 881ffb0b7540  RFLAGS: 0046
> RAX: 0007  RBX: 81f89080  RCX: 0066a7d6eb5cfc9d
> RDX: 0066a7d6eb5d0629  RSI: 0007  RDI: 0a23
> RBP: 881ffb0b7540   R8:    R9: 
> R10: 03ff  R11: 0001  R12: 26f3
> R13: 0020  R14: 81d3c0fb  R15: 003b
> ORIG_RAX:   CS: 0010  SS: 0018
> ---  ---
>  #4 [881ffb0b7540] delay_tsc at 81326724
>  #5 [881ffb0b7548] __const_udelay at 81326678
>  #6 [881ffb0b7558] wait_for_xmitr at 814056e0
>  #7 [881ffb0b7580] serial8250_console_putchar at 814058ac
>  #8 [881ffb0b75a0] uart_console_write at 8140035a
>  #9 [881ffb0b75d0] serial8250_console_write at 814057fe
> #10 [881ffb0b7618] call_console_drivers.constprop.17 at 81087011
> #11 [881ffb0b7640] console_unlock at 810889e9
> #12 [881ffb0b7680] vprintk_emit at 81088df4
> #13 [881ffb0b76f0] dev_vprintk_emit at 81428e72
> #14 [881ffb0b77a8] dev_printk_emit at 81428eee
> #15 [881ffb0b7808] __dev_printk at 8142937e
> #16 [881ffb0b7818] dev_printk at 8142942d
> #17 [881ffb0b7888] sdev_prefix_printk at 81463771
> #18 [881ffb0b7918] scsi_prep_state_check at 814598e4
> #19 [881ffb0b7928] scsi_prep_fn at 8145992d
> #20 [881ffb0b7960] blk_peek_request at 812f0826
> #21 [881ffb0b7988] scsi_request_fn at 8145b588
> #22 [881ffb0b79f0] __blk_run_queue at 812ebd63
> #23

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-21 Thread Sergey Senozhatsky 
On (03/20/18 09:34), bugzilla-dae...@bugzilla.kernel.org wrote:
[..]
> Thanks very much.
> commit e480af09c49736848f749a43dff2c902104f6691 avoided the NMI watchdog
> trigger.

Hm, okay... But "touch_nmi_watchdog() everywhere printk/console-related"
is not exactly where I wanted us to be.

By the way e480af09c49736848f749a43dff2c902104f6691 is from 2006.
Are you sure you meant exactly that commit? What kernel do you use?


Are you saying that none of Steven's patches helped on your setups?


> And this patch may  avdoid long time blocking:
> https://lkml.org/lkml/2018/3/8/584
> 
> We've test it several days.

Hm, printk_deferred is a bit dangerous; it moves console_unlock() to
IRQ. So you still can have the problem of stuck CPUs, it's just now
you shut up the watchdog. Did you test Steven's patches?


A tricky part about printk_deferred() is that it does not use hand off
mechanism. And even more...  What we have with "printk vs printk"
sceanrio

CPU0CPU1... CPUN

printk  printk
 console_unlock  hand off   printk
  console_unlock hand off
  console_unlock

turns into a good old "one CPU prints it all" when we have "printk vs
printk_deferred" case. Because printk_deferred just log_store messages
and then _may be_ it grabs the console_sem from IRQ and invokes
console_unlock().

So it's something like this

CPU0CPU1... CPUN

printk  printk_deffered
 console_unlock printk_deferred
 console_unlock
 console_unlock
... ... ...
printk_deffered printk_deferred
 console_unlock
 console_unlock


// offtopic  "I can has printk_kthread?"



You now touch_nmi_watchdog() from the console driver [well... at least this
is what e480af09c4973 is doing, but I'm not sure I see how come you didn't
have it applied], so that's why you don't see hard lockups on that CPU0. But
your printing CPU still can stuck, which will defer RCUs on that CPU, etc.
etc. etc. So I'd say that those two approaches

printk_deferred + touch_nmi_watchdog

combined can do quite some harm. One thing for sure - they don't really fix
any problems.

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-21 Thread Sergey Senozhatsky 
On (03/20/18 09:34), bugzilla-dae...@bugzilla.kernel.org wrote:
[..]
> Thanks very much.
> commit e480af09c49736848f749a43dff2c902104f6691 avoided the NMI watchdog
> trigger.

Hm, okay... But "touch_nmi_watchdog() everywhere printk/console-related"
is not exactly where I wanted us to be.

By the way e480af09c49736848f749a43dff2c902104f6691 is from 2006.
Are you sure you meant exactly that commit? What kernel do you use?


Are you saying that none of Steven's patches helped on your setups?


> And this patch may  avdoid long time blocking:
> https://lkml.org/lkml/2018/3/8/584
> 
> We've test it several days.

Hm, printk_deferred is a bit dangerous; it moves console_unlock() to
IRQ. So you still can have the problem of stuck CPUs, it's just now
you shut up the watchdog. Did you test Steven's patches?


A tricky part about printk_deferred() is that it does not use hand off
mechanism. And even more...  What we have with "printk vs printk"
sceanrio

CPU0CPU1... CPUN

printk  printk
 console_unlock  hand off   printk
  console_unlock hand off
  console_unlock

turns into a good old "one CPU prints it all" when we have "printk vs
printk_deferred" case. Because printk_deferred just log_store messages
and then _may be_ it grabs the console_sem from IRQ and invokes
console_unlock().

So it's something like this

CPU0CPU1... CPUN

printk  printk_deffered
 console_unlock printk_deferred
 console_unlock
 console_unlock
... ... ...
printk_deffered printk_deferred
 console_unlock
 console_unlock


// offtopic  "I can has printk_kthread?"



You now touch_nmi_watchdog() from the console driver [well... at least this
is what e480af09c4973 is doing, but I'm not sure I see how come you didn't
have it applied], so that's why you don't see hard lockups on that CPU0. But
your printing CPU still can stuck, which will defer RCUs on that CPU, etc.
etc. etc. So I'd say that those two approaches

printk_deferred + touch_nmi_watchdog

combined can do quite some harm. One thing for sure - they don't really fix
any problems.

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-05 Thread Sergey Senozhatsky 
Hello,

Let's switch to email.

Cc-ing Petr and Steven


On (03/05/18 07:50), bugzilla-dae...@bugzilla.kernel.org wrote:
> 
> https://bugzilla.kernel.org/show_bug.cgi?id=199003
> 
> yangwen (wen.yan...@zte.com.cn) changed:
> 
>What|Removed |Added
> 
>  CC||sergey.senozhat...@gmail.com

Thanks, will take a look.

In the meantime, could you check this message:
  https://marc.info/?l=linux-kernel=152016852803716

It lists several commit IDs that you might backport and try out.
Thanks in advance!

-ss

Re: [Bug 199003] console stalled, cause Hard LOCKUP.

2018-03-05 Thread Sergey Senozhatsky 
Hello,

Let's switch to email.

Cc-ing Petr and Steven


On (03/05/18 07:50), bugzilla-dae...@bugzilla.kernel.org wrote:
> 
> https://bugzilla.kernel.org/show_bug.cgi?id=199003
> 
> yangwen (wen.yan...@zte.com.cn) changed:
> 
>What|Removed |Added
> 
>  CC||sergey.senozhat...@gmail.com

Thanks, will take a look.

In the meantime, could you check this message:
  https://marc.info/?l=linux-kernel=152016852803716

It lists several commit IDs that you might backport and try out.
Thanks in advance!

-ss