Re: [RFC][PATCHv6 00/12] printk: introduce printing kernel thread

[Sergey Senozhatsky]

On (12/18/17 18:36), Sergey Senozhatsky wrote:
[..]
>    I see *a lot* of cases when CPU that call printk in a loop does not
>    end up flushing its messages. And the problem seems to be - preemption.
> 
> 
>   CPU0						CPU1
> 
>   for_each_process_thread(g, p)
>     printk()
>     console_unlock()				printk
>     						 console_trylock() fails
>     sets console_owner
> 						 sees console_owner
> 						 sets console_waiter
>     call_console_drivers
>     clears console_owner
>     sees console_waiter
>     hand off					 spins with local_irq disabled
> 						 sees that it has acquired console_sem ownership
> 
> 						 enables local_irq
>     printk
>     ..						 << preemption >>
>     printk
>     ...         unbound number of printk-s
>     printk
>     ..
>     printk
> 						back to TASK_RUNNING
> 						goes to console_unlock()
>     printk
> 						local_irq_save
> 
>     ???
> 						*** if it will see console_waiter [being in any
> 						context] it will hand off. otherwise, preemption
> 						again and CPU0 can add even more messages to logbuf
> 
> 						local_irq_restore
> 
> 						<< preemption >>


hm... adding preemption_disable()/preemption_enable() to vprintk_emit()
does not fix the issues on my side.

	preemption_disable();
	...
	if (console_trylock()) {
		console_unlock();
	} else {
		
		// console_owner check and loop if needed
		// console_unlock();
	}
	preemption_enable();


the root cause seems to be the fact that log_store() is significantly
faster than msg_print_text() + call_console_drivers().


looking at this

   systemd-udevd-671   [002] dn.3    66.736432: offloading: set console_owner  :0
   systemd-udevd-671   [002] dn.3    66.749927: offloading: clear console_owner  waiter != NULL :0
   systemd-udevd-671   [002] dn.3    66.749931: offloading: set console_owner  :0
   systemd-udevd-671   [002] dn.3    66.763426: offloading: clear console_owner  waiter != NULL :0
   systemd-udevd-671   [002] dn.3    66.763430: offloading: set console_owner  :0
   systemd-udevd-671   [002] dn.3    66.776925: offloading: clear console_owner  waiter != NULL :0

which is this thing

                len += msg_print_text(msg, console_prev, false,
                                      text + len, sizeof(text) - len);
                console_idx = log_next(console_idx);
                console_seq++;
                console_prev = msg->flags;
                raw_spin_unlock(&logbuf_lock);

                /*
                 * While actively printing out messages, if another printk()
                 * were to occur on another CPU, it may wait for this one to
                 * finish. This task can not be preempted if there is a
                 * waiter waiting to take over.
                 */
                raw_spin_lock(&console_owner_lock);
                console_owner = current;
                raw_spin_unlock(&console_owner_lock);

+                trace_offloading("set console_owner", " ", 0);

                /* The waiter may spin on us after setting console_owner */
                spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);

                stop_critical_timings();        /* don't trace print latency */
                call_console_drivers(level, text, len);
                start_critical_timings();

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

+                trace_offloading("clear console_owner",
+                                " waiter != NULL ", !!waiter);


it takes call_console_drivers() 0.01+ of a second to print some of
the messages [I think we can ignore raw_spin_lock(&console_owner_lock)
and fully blame call_console_drivers()]. so vprintk_emit() seems to be
gazillion times faster and i_do_printks can add tons of messages while
some other process prints just one.


to be more precise, I see from the traces that i_do_printks can add 1100
messages to the logbuf while call_console_drivers() prints just one.


systemd-udevd-671 owns the lock. sets the console_owner. i_do_printks
keeps adding printks. there kworker/0:1-135 that just ahead of
i_do_printks-1992 and registers itself as the console_sem waiter.

   systemd-udevd-671   [003] d..3    66.334866: offloading: set console_owner  :0
     kworker/0:1-135   [000] d..2    66.335999: offloading: vprintk_emit()->trylock FAIL  will spin? :1
    i_do_printks-1992  [002] d..2    66.345474: offloading: vprintk_emit()->trylock FAIL  will spin? :0    x 1100
   ...
   systemd-udevd-671   [003] d..3    66.345917: offloading: cleaar console_owner  waiter != NULL :1


i_do_printks-1992 finishes printing [it does limited number of printks],
it does not compete for console_sem anymore, so those are other tasks
that have to flush pending messages stored by i_do_printks-1992           :(

	-ss