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 CPU1 CPU2 > spin_lock(queue_lock) > printk printk > cfqg_print_rwstat_recursive() serial8250 > spin_lock(queue_lock) printk > serial8250 > serial8250 printk > > 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