is printk() safe within a timekeeper_seq write section?

is printk() safe within a timekeeper_seq write section?

[Jiri Bohac]

Hi,

I'm looking at the printk call in
__timekeeping_inject_sleeptime(), introduced in cb5de2f8
(time: Catch invalid timespec sleep values in __timekeeping_inject_sleeptime)

Is it safe to call printk() while timekeeper_seq is held for
writing?

What about this call chain?
  printk
    vprintk_emit
      console_unlock
        up(&console_sem)
          __up
	    wake_up_process
	      try_to_wake_up
	        ttwu_do_activate
		  ttwu_activate
		    activate_task
		      enqueue_task
		        enqueue_task_fair
			  hrtick_update
			    hrtick_start_fair
			      hrtick_start_fair
			        get_time
				  ktime_get
				    --> endless loop on
				    read_seqcount_retry(&timekeeper_seq, ...)
		  

It looks like an unlikely but possible deadlock. 
Or did I overlook something?

Thanks!

-- 
Jiri Bohac <jbohac@suse.cz>
SUSE Labs, SUSE CZ

Re: is printk() safe within a timekeeper_seq write section?

[John Stultz]

On 03/06/2014 09:45 AM, Jiri Bohac wrote:
> Hi,
>
> I'm looking at the printk call in
> __timekeeping_inject_sleeptime(), introduced in cb5de2f8
> (time: Catch invalid timespec sleep values in __timekeeping_inject_sleeptime)
>
> Is it safe to call printk() while timekeeper_seq is held for
> writing?
>
> What about this call chain?
>   printk
>     vprintk_emit
>       console_unlock
>         up(&console_sem)
>           __up
> 	    wake_up_process
> 	      try_to_wake_up
> 	        ttwu_do_activate
> 		  ttwu_activate
> 		    activate_task
> 		      enqueue_task
> 		        enqueue_task_fair
> 			  hrtick_update
> 			    hrtick_start_fair
> 			      hrtick_start_fair
> 			        get_time
> 				  ktime_get
> 				    --> endless loop on
> 				    read_seqcount_retry(&timekeeper_seq, ...)
> 		  
>
> It looks like an unlikely but possible deadlock. 
> Or did I overlook something?

So I don't think I've seen anything like the above in my testing, but it
may just be very hard to get that path to trigger.

I was also surprised the seqlock lockdep enablement changes wouldn't
catch this, but Jiri pointed out printk calls lockdep_off in
vprintk_emit() - which makes sense as you don't want lockdep splats
calling printk and recursing - but is frustrating to have that hole in
the checking.

There's a few spots where we do printks with the timekeeping seqlock
held, and they're annoyingly nested far enough to make deferring the
printk awkward. So I'm half thinking we could have some sort of buffer
something like time_printk() could fill and then flush it after the lock
is dropped. Then we just need something to warn if any new printks' are
added to timekeeping seqlock sequences.

The whole thing makes my head spin a bit, since even if we remove the
explicit printks, I'm not sure where else printk might be triggered
(like via lockdep warnings, for instance), where it might be unsafe.

Peter/Thomas: Any thoughts on the deferred printk buffer? Does printk
already have something like this? Any other ideas here?

thanks
-john

Re: is printk() safe within a timekeeper_seq write section?

[Thomas Gleixner]

On Tue, 11 Mar 2014, John Stultz wrote:
> On 03/06/2014 09:45 AM, Jiri Bohac wrote:
> > Hi,
> >
> > I'm looking at the printk call in
> > __timekeeping_inject_sleeptime(), introduced in cb5de2f8
> > (time: Catch invalid timespec sleep values in __timekeeping_inject_sleeptime)
> >
> > Is it safe to call printk() while timekeeper_seq is held for
> > writing?
> >
> > What about this call chain?
> >   printk
> >     vprintk_emit
> >       console_unlock
> >         up(&console_sem)
> >           __up
> > 	    wake_up_process
> > 	      try_to_wake_up
> > 	        ttwu_do_activate
> > 		  ttwu_activate
> > 		    activate_task
> > 		      enqueue_task
> > 		        enqueue_task_fair
> > 			  hrtick_update
> > 			    hrtick_start_fair
> > 			      hrtick_start_fair
> > 			        get_time
> > 				  ktime_get
> > 				    --> endless loop on
> > 				    read_seqcount_retry(&timekeeper_seq, ...)
> > 		  
> >
> > It looks like an unlikely but possible deadlock. 
> > Or did I overlook something?
> 
> So I don't think I've seen anything like the above in my testing, but it
> may just be very hard to get that path to trigger.

It's hard, but possible:

CPU0	     		CPU1

T1 down(&console_sem);
			T2 down(&console_sem);
			   --> preemption or interrupt
			        write_seqcount_begin(&timekeeper_seq);
T1 up(&console_sem);
				down(&console_sem);
				....
				up(&console_sem);
				   wakeup(T2);
				     ....
				     hrtick_update();
				     
> I was also surprised the seqlock lockdep enablement changes wouldn't
> catch this, but Jiri pointed out printk calls lockdep_off in
> vprintk_emit() - which makes sense as you don't want lockdep splats
> calling printk and recursing - but is frustrating to have that hole in
> the checking.
> 
> There's a few spots where we do printks with the timekeeping seqlock
> held, and they're annoyingly nested far enough to make deferring the
> printk awkward. So I'm half thinking we could have some sort of buffer
> something like time_printk() could fill and then flush it after the lock
> is dropped. Then we just need something to warn if any new printks' are
> added to timekeeping seqlock sequences.
> 
> The whole thing makes my head spin a bit, since even if we remove the
> explicit printks, I'm not sure where else printk might be triggered
> (like via lockdep warnings, for instance), where it might be unsafe.
> 
> Peter/Thomas: Any thoughts on the deferred printk buffer? Does printk
> already have something like this? Any other ideas here?

I was thinking about something like that for RT as on RT printk is a
complete nightmare. It's simple to implement that, but as we know from
the RT experience it can lead to painful loss of debug output.

Assume you printk inside such a region, which just fills the dmesg
buffer and schedules the delayed output. Now in that same region you
run into a deadlock which causes the whole machine to freeze. Then you
won't see the debug output, which might actually give you the hint why
the system deadlocked ....

Thanks,

	tglx

Re: is printk() safe within a timekeeper_seq write section?

[John Stultz]

On 03/11/2014 02:32 PM, Thomas Gleixner wrote:
> On Tue, 11 Mar 2014, John Stultz wrote:
>> On 03/06/2014 09:45 AM, Jiri Bohac wrote:
>>> Hi,
>>>
>>> I'm looking at the printk call in
>>> __timekeeping_inject_sleeptime(), introduced in cb5de2f8
>>> (time: Catch invalid timespec sleep values in __timekeeping_inject_sleeptime)
>>>
>>> Is it safe to call printk() while timekeeper_seq is held for
>>> writing?
>>>
>>> What about this call chain?
>>>   printk
>>>     vprintk_emit
>>>       console_unlock
>>>         up(&console_sem)
>>>           __up
>>> 	    wake_up_process
>>> 	      try_to_wake_up
>>> 	        ttwu_do_activate
>>> 		  ttwu_activate
>>> 		    activate_task
>>> 		      enqueue_task
>>> 		        enqueue_task_fair
>>> 			  hrtick_update
>>> 			    hrtick_start_fair
>>> 			      hrtick_start_fair
>>> 			        get_time
>>> 				  ktime_get
>>> 				    --> endless loop on
>>> 				    read_seqcount_retry(&timekeeper_seq, ...)
>>> 		  
>>>
>>> It looks like an unlikely but possible deadlock. 
>>> Or did I overlook something?
>> So I don't think I've seen anything like the above in my testing, but it
>> may just be very hard to get that path to trigger.
> It's hard, but possible:
>
> CPU0	     		CPU1
>
> T1 down(&console_sem);
> 			T2 down(&console_sem);
> 			   --> preemption or interrupt
> 			        write_seqcount_begin(&timekeeper_seq);
> T1 up(&console_sem);
> 				down(&console_sem);
> 				....
> 				up(&console_sem);
> 				   wakeup(T2);
> 				     ....
> 				     hrtick_update();
> 				     
>> I was also surprised the seqlock lockdep enablement changes wouldn't
>> catch this, but Jiri pointed out printk calls lockdep_off in
>> vprintk_emit() - which makes sense as you don't want lockdep splats
>> calling printk and recursing - but is frustrating to have that hole in
>> the checking.
>>
>> There's a few spots where we do printks with the timekeeping seqlock
>> held, and they're annoyingly nested far enough to make deferring the
>> printk awkward. So I'm half thinking we could have some sort of buffer
>> something like time_printk() could fill and then flush it after the lock
>> is dropped. Then we just need something to warn if any new printks' are
>> added to timekeeping seqlock sequences.
>>
>> The whole thing makes my head spin a bit, since even if we remove the
>> explicit printks, I'm not sure where else printk might be triggered
>> (like via lockdep warnings, for instance), where it might be unsafe.
>>
>> Peter/Thomas: Any thoughts on the deferred printk buffer? Does printk
>> already have something like this? Any other ideas here?
> I was thinking about something like that for RT as on RT printk is a
> complete nightmare. It's simple to implement that, but as we know from
> the RT experience it can lead to painful loss of debug output.
>
> Assume you printk inside such a region, which just fills the dmesg
> buffer and schedules the delayed output. Now in that same region you
> run into a deadlock which causes the whole machine to freeze. Then you
> won't see the debug output, which might actually give you the hint why
> the system deadlocked ....
Ok, so a generic solution is probably not going to be worth it then. My
thought was that since we do a very limited amount of informational
printks in the timekeeping code, we can be fairly safe delaying the
print-out until we drop the locks.

For timekeeping, its really 4 call sites:
* invalid inject_sleep_time deltas
* > 11% clocksource freq adjustments
* insert leap second
* delete leap second

The first can probably be dropped all together, and signaled via an
error return.

The second can probably be replaced by a hard cap, although it would be
good to still know we hit that limit.

The last two (only one of which ever really happens) are mostly just
informative to the system admin, as most users don't check the TIME_OOP
flag to note the leap occurred.

So unless you have other suggestions I think delaying the printouts it
is the best approach for the timekeeping code.

We then just have to hope we don't have any other call-out sites that
conditionally trip printks as well (nor any that might add printks any
time in the future). Any clue on how best to catch those cases? Audits
like Jiri's here probably won't scale over time.

thanks
-john

Re: is printk() safe within a timekeeper_seq write section?

[Peter Zijlstra]

On Tue, Mar 11, 2014 at 10:32:26PM +0100, Thomas Gleixner wrote:
> > Peter/Thomas: Any thoughts on the deferred printk buffer? Does printk
> > already have something like this? Any other ideas here?
> 
> I was thinking about something like that for RT as on RT printk is a
> complete nightmare. It's simple to implement that, but as we know from
> the RT experience it can lead to painful loss of debug output.
> 
> Assume you printk inside such a region, which just fills the dmesg
> buffer and schedules the delayed output. Now in that same region you
> run into a deadlock which causes the whole machine to freeze. Then you
> won't see the debug output, which might actually give you the hint why
> the system deadlocked ....

Ok so I started writing a rant that I don't give a crap about klogd and
that deferring that wakeup would be perfectly fine; then I looked at the
code and found that we in fact do this already.

wake_up_klogd() schedules a lazy irqwork to go wake up, so that's out.

That leaves the console sem wakeup; but I suppose we could redo this
patch:

  lkml.kernel.org/r/20110621153806.286257129@chello.nl

to get rid of that one.

However, at that point we run into the fact that many console drivers do
wakeups themselves. I did fix 8250, because that is in fact the only
console I really care about, but in general Linus said to give up and
deal with the fact that console drivers suck already (or something along
those lines).

And while I was looking at all that; I got reminded that I really need
to respin this one:

  lkml.kernel.org/r/20111221111143.511565321@chello.nl

Since that whole printk recursion + zap_locks thing is terminally
broken.

Re: is printk() safe within a timekeeper_seq write section?

[Peter Zijlstra]

On Tue, Mar 11, 2014 at 02:54:13PM -0700, John Stultz wrote:
> Ok, so a generic solution is probably not going to be worth it then. My
> thought was that since we do a very limited amount of informational
> printks in the timekeeping code, we can be fairly safe delaying the
> print-out until we drop the locks.
> 
> For timekeeping, its really 4 call sites:
> * invalid inject_sleep_time deltas
> * > 11% clocksource freq adjustments
> * insert leap second
> * delete leap second
> 

There is the printk_sched() you can reuse; you might want to change the
name and the generic [sched_delayed] prefix it gets though.

Re: is printk() safe within a timekeeper_seq write section?

[Peter Zijlstra]

On Thu, Mar 06, 2014 at 06:45:31PM +0100, Jiri Bohac wrote:
> Hi,
> 
> I'm looking at the printk call in
> __timekeeping_inject_sleeptime(), introduced in cb5de2f8
> (time: Catch invalid timespec sleep values in __timekeeping_inject_sleeptime)
> 
> Is it safe to call printk() while timekeeper_seq is held for
> writing?
> 
> What about this call chain?
>   printk
>     vprintk_emit
>       console_unlock
>         up(&console_sem)
>           __up
> 	    wake_up_process
> 	      try_to_wake_up
> 	        ttwu_do_activate
> 		  ttwu_activate
> 		    activate_task
> 		      enqueue_task
> 		        enqueue_task_fair
> 			  hrtick_update
> 			    hrtick_start_fair
> 			      hrtick_start_fair
> 			        get_time
> 				  ktime_get
> 				    --> endless loop on
> 				    read_seqcount_retry(&timekeeper_seq, ...)
> 		  
> 
> It looks like an unlikely but possible deadlock. 
> Or did I overlook something?

So HRTICK is disabled by default; but yes this is a problem when you
enable it.

The problem is that our timers are in an entirely different clock base
than our (scheduler) clocks.

On SNB+ hardware with TSC deadline timers we have the same clockbase I
suppose but I'm not sure that's something we can (and want) to rely on.

Now, I've long had the idea to mess up the hrtimer code to optimize this
particular timer, but I'm not entirely sure we can get around having to
use the timerkeeper_seq thing, we simply have to get into timer clock
space :/

Re: is printk() safe within a timekeeper_seq write section?

[Jiri Bohac]

On Tue, Mar 11, 2014 at 02:54:13PM -0700, John Stultz wrote:
> Ok, so a generic solution is probably not going to be worth it then. My
> thought was that since we do a very limited amount of informational
> printks in the timekeeping code, we can be fairly safe delaying the
> print-out until we drop the locks.
> 
> For timekeeping, its really 4 call sites:
> * invalid inject_sleep_time deltas
> * > 11% clocksource freq adjustments
> * insert leap second
> * delete leap second

I believe these last two were made safe by 
commit ca4523cd (timekeeping: Shorten seq_count region). 

write_seqcount_begin(&timekeeper_seq) is now done after the
accumulate_nsecs_to_secs(tk) from where the printks are called.

Regards,

-- 
Jiri Bohac <jbohac@suse.cz>
SUSE Labs, SUSE CZ

Re: is printk() safe within a timekeeper_seq write section?

[Peter Zijlstra]

On Tue, Mar 11, 2014 at 12:29:45PM -0700, John Stultz wrote:
> So I don't think I've seen anything like the above in my testing, but it
> may just be very hard to get that path to trigger.

You have to explicitly enable HRTICK for this to be possible; its
disabled by default.

Re: is printk() safe within a timekeeper_seq write section?

[Jan Kara]

On Tue 11-03-14 22:32:26, Thomas Gleixner wrote:
> On Tue, 11 Mar 2014, John Stultz wrote:
> > I was also surprised the seqlock lockdep enablement changes wouldn't
> > catch this, but Jiri pointed out printk calls lockdep_off in
> > vprintk_emit() - which makes sense as you don't want lockdep splats
> > calling printk and recursing - but is frustrating to have that hole in
> > the checking.
> > 
> > There's a few spots where we do printks with the timekeeping seqlock
> > held, and they're annoyingly nested far enough to make deferring the
> > printk awkward. So I'm half thinking we could have some sort of buffer
> > something like time_printk() could fill and then flush it after the lock
> > is dropped. Then we just need something to warn if any new printks' are
> > added to timekeeping seqlock sequences.
> > 
> > The whole thing makes my head spin a bit, since even if we remove the
> > explicit printks, I'm not sure where else printk might be triggered
> > (like via lockdep warnings, for instance), where it might be unsafe.
> > 
> > Peter/Thomas: Any thoughts on the deferred printk buffer? Does printk
> > already have something like this? Any other ideas here?
> 
> I was thinking about something like that for RT as on RT printk is a
> complete nightmare. It's simple to implement that, but as we know from
> the RT experience it can lead to painful loss of debug output.
> 
> Assume you printk inside such a region, which just fills the dmesg
> buffer and schedules the delayed output. Now in that same region you
> run into a deadlock which causes the whole machine to freeze. Then you
> won't see the debug output, which might actually give you the hint why
> the system deadlocked ....
  Certainly just adding messages to printk buffer is more prone to loosing
the messages on error. OTOH if we schedule something like irq work to do
the printing (as currently happens with scheduler messages), loosing
messages should be relatively rare, shouldn't it?

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

Re: is printk() safe within a timekeeper_seq write section?

[Jan Kara]

On Wed 12-03-14 07:46:45, Peter Zijlstra wrote:
> On Tue, Mar 11, 2014 at 10:32:26PM +0100, Thomas Gleixner wrote:
> > > Peter/Thomas: Any thoughts on the deferred printk buffer? Does printk
> > > already have something like this? Any other ideas here?
> > 
> > I was thinking about something like that for RT as on RT printk is a
> > complete nightmare. It's simple to implement that, but as we know from
> > the RT experience it can lead to painful loss of debug output.
> > 
> > Assume you printk inside such a region, which just fills the dmesg
> > buffer and schedules the delayed output. Now in that same region you
> > run into a deadlock which causes the whole machine to freeze. Then you
> > won't see the debug output, which might actually give you the hint why
> > the system deadlocked ....
> 
> Ok so I started writing a rant that I don't give a crap about klogd and
> that deferring that wakeup would be perfectly fine; then I looked at the
> code and found that we in fact do this already.
> 
> wake_up_klogd() schedules a lazy irqwork to go wake up, so that's out.
> 
> That leaves the console sem wakeup; but I suppose we could redo this
> patch:
> 
>   lkml.kernel.org/r/20110621153806.286257129@chello.nl
> 
> to get rid of that one.
  I don't know if you've noticed but there's also the following patch:
https://lkml.org/lkml/2013/12/23/310
  which would make it pretty easy to just add messages to printk buffer in
timer code and schedule printing later using irq work.

  Regarding your referenced patch - the way it is written, it would make
all printk users spin on console_sem->lock all the time while we are
flushing buffer to console. I don't think we want that - we trylock the
console_sem exactly so that other printk users can proceed while one poor
guy is pushing stuff to console.

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

Re: is printk() safe within a timekeeper_seq write section?

[Peter Zijlstra]

On Wed, Mar 12, 2014 at 03:34:56PM +0100, Jan Kara wrote:
> On Wed 12-03-14 07:46:45, Peter Zijlstra wrote:
> > On Tue, Mar 11, 2014 at 10:32:26PM +0100, Thomas Gleixner wrote:
> > > > Peter/Thomas: Any thoughts on the deferred printk buffer? Does printk
> > > > already have something like this? Any other ideas here?
> > > 
> > > I was thinking about something like that for RT as on RT printk is a
> > > complete nightmare. It's simple to implement that, but as we know from
> > > the RT experience it can lead to painful loss of debug output.
> > > 
> > > Assume you printk inside such a region, which just fills the dmesg
> > > buffer and schedules the delayed output. Now in that same region you
> > > run into a deadlock which causes the whole machine to freeze. Then you
> > > won't see the debug output, which might actually give you the hint why
> > > the system deadlocked ....
> > 
> > Ok so I started writing a rant that I don't give a crap about klogd and
> > that deferring that wakeup would be perfectly fine; then I looked at the
> > code and found that we in fact do this already.
> > 
> > wake_up_klogd() schedules a lazy irqwork to go wake up, so that's out.
> > 
> > That leaves the console sem wakeup; but I suppose we could redo this
> > patch:
> > 
> >   lkml.kernel.org/r/20110621153806.286257129@chello.nl
> > 
> > to get rid of that one.
>   I don't know if you've noticed but there's also the following patch:
> https://lkml.org/lkml/2013/12/23/310
>   which would make it pretty easy to just add messages to printk buffer in
> timer code and schedule printing later using irq work.

Yeah; I suppose that one is prettier.

>   Regarding your referenced patch - the way it is written, it would make
> all printk users spin on console_sem->lock all the time while we are
> flushing buffer to console. I don't think we want that - we trylock the
> console_sem exactly so that other printk users can proceed while one poor
> guy is pushing stuff to console.

That should be fixable though; just keep enough state for the other
printk()s to see they don't need to also flush.

But the idea is to not do the sleep+wakeup dance.

But as stated; that's not going to actually matter much, since the
popular console drivers are crap and do wakeups too.

Re: is printk() safe within a timekeeper_seq write section?

[Jan Kara]

On Wed 12-03-14 16:06:17, Peter Zijlstra wrote:
> On Wed, Mar 12, 2014 at 03:34:56PM +0100, Jan Kara wrote:
> > On Wed 12-03-14 07:46:45, Peter Zijlstra wrote:
> > > On Tue, Mar 11, 2014 at 10:32:26PM +0100, Thomas Gleixner wrote:
> > > > > Peter/Thomas: Any thoughts on the deferred printk buffer? Does printk
> > > > > already have something like this? Any other ideas here?
> > > > 
> > > > I was thinking about something like that for RT as on RT printk is a
> > > > complete nightmare. It's simple to implement that, but as we know from
> > > > the RT experience it can lead to painful loss of debug output.
> > > > 
> > > > Assume you printk inside such a region, which just fills the dmesg
> > > > buffer and schedules the delayed output. Now in that same region you
> > > > run into a deadlock which causes the whole machine to freeze. Then you
> > > > won't see the debug output, which might actually give you the hint why
> > > > the system deadlocked ....
> > > 
> > > Ok so I started writing a rant that I don't give a crap about klogd and
> > > that deferring that wakeup would be perfectly fine; then I looked at the
> > > code and found that we in fact do this already.
> > > 
> > > wake_up_klogd() schedules a lazy irqwork to go wake up, so that's out.
> > > 
> > > That leaves the console sem wakeup; but I suppose we could redo this
> > > patch:
> > > 
> > >   lkml.kernel.org/r/20110621153806.286257129@chello.nl
> > > 
> > > to get rid of that one.
> >   I don't know if you've noticed but there's also the following patch:
> > https://lkml.org/lkml/2013/12/23/310
> >   which would make it pretty easy to just add messages to printk buffer in
> > timer code and schedule printing later using irq work.
> 
> Yeah; I suppose that one is prettier.
  JFYI, that patch has been just added to -mm tree.

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

Re: is printk() safe within a timekeeper_seq write section?

[John Stultz]

On 03/12/2014 02:21 AM, Jiri Bohac wrote:
> On Tue, Mar 11, 2014 at 02:54:13PM -0700, John Stultz wrote:
>> Ok, so a generic solution is probably not going to be worth it then. My
>> thought was that since we do a very limited amount of informational
>> printks in the timekeeping code, we can be fairly safe delaying the
>> print-out until we drop the locks.
>>
>> For timekeeping, its really 4 call sites:
>> * invalid inject_sleep_time deltas
>> * > 11% clocksource freq adjustments
>> * insert leap second
>> * delete leap second
> I believe these last two were made safe by 
> commit ca4523cd (timekeeping: Shorten seq_count region). 
>
> write_seqcount_begin(&timekeeper_seq) is now done after the
> accumulate_nsecs_to_secs(tk) from where the printks are called.

So I started looking into deferring the printk with a small local
buffer, but I suddenly realized there are all these WARN_ON's around
which would likely have the same problem, no?

So I'm starting to doubt we can safely get away with a timekeeping
specific hack to defer the printk. :(

thanks
-john