[PATCH 0/4] Convert timekeeping core to use printk_deferred (v3)

[PATCH 0/4] Convert timekeeping core to use printk_deferred (v3)

[John Stultz]

Recently, Jiri pointed out a potential deadlock when calling printk
while holding the timekeeping seqlock.

Annoyingly, the seqlock lockdep enablement doesn't catch this, as
printk disables lockdep.

When looking for possible solutions, one idea was to use a local buffer
and defer the printk to later. Ends up there is already similar
functionality in printk_sched() to avoid similar style deadlocks w/
the scheduler.

Thus this patchset (based on next/akpm) renames printk_sched to
printk_deferred and then moves the affected timekeeping printks to make
use of it.

There were some points in the discussion between Jan and Peter that
made it seem that there may still be problems lurking in the console
layer, and I'm not sure I fully understand their point, so this solution
may be incomplete.

Additionally, the same issue likely affects any WARN_ONs as well, but
I wanted to get some thoughts on this approach before trying to remove
or convert affected WARN_ONS.

Your thoughts and feedback are greatly appreciated!

thanks
-john

Changes since v2:
* Renamed printk_once_deferred() to printk_deferred_once(), per
  Andrew's suggestion
* Changed adding irqsave/restore to preempt_disable/enable, per
  Jan's suggestion

Changes since v1:
* Rebased on next/akpm, since there are queued prink patches there
* Re-added irqsave/restore per irc discussion w/ PeterZ 


Cc: Jan Kara <jack@suse.cz>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Bohac <jbohac@suse.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Steven Rostedt <rostedt@goodmis.org>


John Stultz (4):
  printk: Disable preemption for printk_sched
  printk: Rename printk_sched to printk_deferred
  printk: Add printk_deferred_once
  timekeeping: Use printk_deferred when holding timekeeping seqlock

 include/linux/printk.h    | 17 ++++++++++++++---
 kernel/printk/printk.c    |  4 +++-
 kernel/sched/core.c       |  2 +-
 kernel/sched/deadline.c   |  7 +------
 kernel/sched/rt.c         |  8 +-------
 kernel/time/ntp.c         | 15 +++++++++------
 kernel/time/timekeeping.c |  7 ++++---
 7 files changed, 33 insertions(+), 27 deletions(-)

-- 
1.9.1

[PATCH 1/4] printk: Disable preemption for printk_sched

[John Stultz]

An earlier change in -mm (printk: remove separate printk_sched
buffers...), removed the printk_sched irqsave/restore lines
since it was safe for current users. Since we may be expanding
usage of printk_sched(), disable preepmtion for this function
to make it more generally safe to call.

Cc: Jan Kara <jack@suse.cz>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Bohac <jbohac@suse.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: John Stultz <john.stultz@linaro.org>
---
 kernel/printk/printk.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 82d19e6..57467df 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2589,12 +2589,14 @@ int printk_sched(const char *fmt, ...)
 	va_list args;
 	int r;
 
+	preempt_disable();
 	va_start(args, fmt);
 	r = vprintk_emit(0, SCHED_MESSAGE_LOGLEVEL, NULL, 0, fmt, args);
 	va_end(args);
 
 	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
 	irq_work_queue(&__get_cpu_var(wake_up_klogd_work));
+	preempt_enable();
 
 	return r;
 }
-- 
1.9.1

Re: [PATCH 1/4] printk: Disable preemption for printk_sched

[Jan Kara]

On Mon 05-05-14 13:47:41, John Stultz wrote:
> An earlier change in -mm (printk: remove separate printk_sched
> buffers...), removed the printk_sched irqsave/restore lines
> since it was safe for current users. Since we may be expanding
> usage of printk_sched(), disable preepmtion for this function
> to make it more generally safe to call.
  Looks good to me. You can add:
Reviewed-by: Jan Kara <jack@suse.cz>

							Honza
> 
> Cc: Jan Kara <jack@suse.cz>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Jiri Bohac <jbohac@suse.cz>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Signed-off-by: John Stultz <john.stultz@linaro.org>
> ---
>  kernel/printk/printk.c | 2 ++
>  1 file changed, 2 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 82d19e6..57467df 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2589,12 +2589,14 @@ int printk_sched(const char *fmt, ...)
>  	va_list args;
>  	int r;
>  
> +	preempt_disable();
>  	va_start(args, fmt);
>  	r = vprintk_emit(0, SCHED_MESSAGE_LOGLEVEL, NULL, 0, fmt, args);
>  	va_end(args);
>  
>  	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
>  	irq_work_queue(&__get_cpu_var(wake_up_klogd_work));
> +	preempt_enable();
>  
>  	return r;
>  }
> -- 
> 1.9.1
> 
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

[PATCH 2/4] printk: Rename printk_sched to printk_deferred

[John Stultz]

After learning we'll need some sort of deferred printk functionality
in the timekeeping core, Peter suggested we rename the printk_sched
function so it can be reused by needed subsystems.

This only changes the function name. No logic changes.

Cc: Jan Kara <jack@suse.cz>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Bohac <jbohac@suse.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Reviewed-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: John Stultz <john.stultz@linaro.org>
---
 include/linux/printk.h  | 6 +++---
 kernel/printk/printk.c  | 2 +-
 kernel/sched/core.c     | 2 +-
 kernel/sched/deadline.c | 2 +-
 kernel/sched/rt.c       | 2 +-
 5 files changed, 7 insertions(+), 7 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 8752f75..7847301 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -128,9 +128,9 @@ asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 
 /*
- * Special printk facility for scheduler use only, _DO_NOT_USE_ !
+ * Special printk facility for scheduler/timekeeping use only, _DO_NOT_USE_ !
  */
-__printf(1, 2) __cold int printk_sched(const char *fmt, ...);
+__printf(1, 2) __cold int printk_deferred(const char *fmt, ...);
 
 /*
  * Please don't use printk_ratelimit(), because it shares ratelimiting state
@@ -165,7 +165,7 @@ int printk(const char *s, ...)
 	return 0;
 }
 static inline __printf(1, 2) __cold
-int printk_sched(const char *s, ...)
+int printk_deferred(const char *s, ...)
 {
 	return 0;
 }
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 57467df..7587f67 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2584,7 +2584,7 @@ void wake_up_klogd(void)
 	preempt_enable();
 }
 
-int printk_sched(const char *fmt, ...)
+int printk_deferred(const char *fmt, ...)
 {
 	va_list args;
 	int r;
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 805b8a9..263c790 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -1336,7 +1336,7 @@ out:
 		 * leave kernel.
 		 */
 		if (p->mm && printk_ratelimit()) {
-			printk_sched("process %d (%s) no longer affine to cpu%d\n",
+			printk_deferred("process %d (%s) no longer affine to cpu%d\n",
 					task_pid_nr(p), p->comm, cpu);
 		}
 	}
diff --git a/kernel/sched/deadline.c b/kernel/sched/deadline.c
index b080957..657ed68 100644
--- a/kernel/sched/deadline.c
+++ b/kernel/sched/deadline.c
@@ -352,7 +352,7 @@ static void replenish_dl_entity(struct sched_dl_entity *dl_se,
 
 		if (!lag_once) {
 			lag_once = true;
-			printk_sched("sched: DL replenish lagged to much\n");
+			printk_deferred("sched: DL replenish lagged to much\n");
 		}
 		dl_se->deadline = rq_clock(rq) + pi_se->dl_deadline;
 		dl_se->runtime = pi_se->dl_runtime;
diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c
index 7795e29..e7dc728 100644
--- a/kernel/sched/rt.c
+++ b/kernel/sched/rt.c
@@ -896,7 +896,7 @@ static int sched_rt_runtime_exceeded(struct rt_rq *rt_rq)
 
 			if (!once) {
 				once = true;
-				printk_sched("sched: RT throttling activated\n");
+				printk_deferred("sched: RT throttling activated\n");
 			}
 		} else {
 			/*
-- 
1.9.1

Re: [PATCH 2/4] printk: Rename printk_sched to printk_deferred

[Jan Kara]

On Mon 05-05-14 13:47:42, John Stultz wrote:
> After learning we'll need some sort of deferred printk functionality
> in the timekeeping core, Peter suggested we rename the printk_sched
> function so it can be reused by needed subsystems.
> 
> This only changes the function name. No logic changes.
  Fine by me. You can add:
Reviewed-by: Jan Kara <jack@suse.cz>

								Honza

> 
> Cc: Jan Kara <jack@suse.cz>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Jiri Bohac <jbohac@suse.cz>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Reviewed-by: Steven Rostedt <rostedt@goodmis.org>
> Signed-off-by: John Stultz <john.stultz@linaro.org>
> ---
>  include/linux/printk.h  | 6 +++---
>  kernel/printk/printk.c  | 2 +-
>  kernel/sched/core.c     | 2 +-
>  kernel/sched/deadline.c | 2 +-
>  kernel/sched/rt.c       | 2 +-
>  5 files changed, 7 insertions(+), 7 deletions(-)
> 
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 8752f75..7847301 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -128,9 +128,9 @@ asmlinkage __printf(1, 2) __cold
>  int printk(const char *fmt, ...);
>  
>  /*
> - * Special printk facility for scheduler use only, _DO_NOT_USE_ !
> + * Special printk facility for scheduler/timekeeping use only, _DO_NOT_USE_ !
>   */
> -__printf(1, 2) __cold int printk_sched(const char *fmt, ...);
> +__printf(1, 2) __cold int printk_deferred(const char *fmt, ...);
>  
>  /*
>   * Please don't use printk_ratelimit(), because it shares ratelimiting state
> @@ -165,7 +165,7 @@ int printk(const char *s, ...)
>  	return 0;
>  }
>  static inline __printf(1, 2) __cold
> -int printk_sched(const char *s, ...)
> +int printk_deferred(const char *s, ...)
>  {
>  	return 0;
>  }
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 57467df..7587f67 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2584,7 +2584,7 @@ void wake_up_klogd(void)
>  	preempt_enable();
>  }
>  
> -int printk_sched(const char *fmt, ...)
> +int printk_deferred(const char *fmt, ...)
>  {
>  	va_list args;
>  	int r;
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index 805b8a9..263c790 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -1336,7 +1336,7 @@ out:
>  		 * leave kernel.
>  		 */
>  		if (p->mm && printk_ratelimit()) {
> -			printk_sched("process %d (%s) no longer affine to cpu%d\n",
> +			printk_deferred("process %d (%s) no longer affine to cpu%d\n",
>  					task_pid_nr(p), p->comm, cpu);
>  		}
>  	}
> diff --git a/kernel/sched/deadline.c b/kernel/sched/deadline.c
> index b080957..657ed68 100644
> --- a/kernel/sched/deadline.c
> +++ b/kernel/sched/deadline.c
> @@ -352,7 +352,7 @@ static void replenish_dl_entity(struct sched_dl_entity *dl_se,
>  
>  		if (!lag_once) {
>  			lag_once = true;
> -			printk_sched("sched: DL replenish lagged to much\n");
> +			printk_deferred("sched: DL replenish lagged to much\n");
>  		}
>  		dl_se->deadline = rq_clock(rq) + pi_se->dl_deadline;
>  		dl_se->runtime = pi_se->dl_runtime;
> diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c
> index 7795e29..e7dc728 100644
> --- a/kernel/sched/rt.c
> +++ b/kernel/sched/rt.c
> @@ -896,7 +896,7 @@ static int sched_rt_runtime_exceeded(struct rt_rq *rt_rq)
>  
>  			if (!once) {
>  				once = true;
> -				printk_sched("sched: RT throttling activated\n");
> +				printk_deferred("sched: RT throttling activated\n");
>  			}
>  		} else {
>  			/*
> -- 
> 1.9.1
> 
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

[PATCH 3/4] printk: Add printk_deferred_once

[John Stultz]

Two of the three prink_deferred uses are really printk_once style
uses, so add a printk_deferred_once macro to simplify those call
sites.

Cc: Jan Kara <jack@suse.cz>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Bohac <jbohac@suse.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Reviewed-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: John Stultz <john.stultz@linaro.org>
---
 include/linux/printk.h  | 11 +++++++++++
 kernel/sched/deadline.c |  7 +------
 kernel/sched/rt.c       |  8 +-------
 3 files changed, 13 insertions(+), 13 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 7847301..f086d6c 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -266,9 +266,20 @@ extern asmlinkage void dump_stack(void) __cold;
 		printk(fmt, ##__VA_ARGS__);			\
 	}							\
 })
+#define printk_deferred_once(fmt, ...)				\
+({								\
+	static bool __print_once __read_mostly;			\
+								\
+	if (!__print_once) {					\
+		__print_once = true;				\
+		printk_deferred(fmt, ##__VA_ARGS__);		\
+	}							\
+})
 #else
 #define printk_once(fmt, ...)					\
 	no_printk(fmt, ##__VA_ARGS__)
+#define printk_deferred_once(fmt, ...)				\
+	no_printk(fmt, ##__VA_ARGS__)
 #endif
 
 #define pr_emerg_once(fmt, ...)					\
diff --git a/kernel/sched/deadline.c b/kernel/sched/deadline.c
index 657ed68..80837e9 100644
--- a/kernel/sched/deadline.c
+++ b/kernel/sched/deadline.c
@@ -348,12 +348,7 @@ static void replenish_dl_entity(struct sched_dl_entity *dl_se,
 	 * entity.
 	 */
 	if (dl_time_before(dl_se->deadline, rq_clock(rq))) {
-		static bool lag_once = false;
-
-		if (!lag_once) {
-			lag_once = true;
-			printk_deferred("sched: DL replenish lagged to much\n");
-		}
+		printk_deferred_once("sched: DL replenish lagged to much\n");
 		dl_se->deadline = rq_clock(rq) + pi_se->dl_deadline;
 		dl_se->runtime = pi_se->dl_runtime;
 	}
diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c
index e7dc728..ea4d500 100644
--- a/kernel/sched/rt.c
+++ b/kernel/sched/rt.c
@@ -890,14 +890,8 @@ static int sched_rt_runtime_exceeded(struct rt_rq *rt_rq)
 		 * but accrue some time due to boosting.
 		 */
 		if (likely(rt_b->rt_runtime)) {
-			static bool once = false;
-
 			rt_rq->rt_throttled = 1;
-
-			if (!once) {
-				once = true;
-				printk_deferred("sched: RT throttling activated\n");
-			}
+			printk_deferred_once("sched: RT throttling activated\n");
 		} else {
 			/*
 			 * In case we did anyway, make it go away,
-- 
1.9.1

Re: [PATCH 3/4] printk: Add printk_deferred_once

[Jan Kara]

On Mon 05-05-14 13:47:43, John Stultz wrote:
> Two of the three prink_deferred uses are really printk_once style
> uses, so add a printk_deferred_once macro to simplify those call
> sites.
> 
> Cc: Jan Kara <jack@suse.cz>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Jiri Bohac <jbohac@suse.cz>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Reviewed-by: Steven Rostedt <rostedt@goodmis.org>
> Signed-off-by: John Stultz <john.stultz@linaro.org>
  The patch looks good. You can add:
Reviewed-by: Jan Kara <jack@suse.cz>

								Honza

> ---
>  include/linux/printk.h  | 11 +++++++++++
>  kernel/sched/deadline.c |  7 +------
>  kernel/sched/rt.c       |  8 +-------
>  3 files changed, 13 insertions(+), 13 deletions(-)
> 
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 7847301..f086d6c 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -266,9 +266,20 @@ extern asmlinkage void dump_stack(void) __cold;
>  		printk(fmt, ##__VA_ARGS__);			\
>  	}							\
>  })
> +#define printk_deferred_once(fmt, ...)				\
> +({								\
> +	static bool __print_once __read_mostly;			\
> +								\
> +	if (!__print_once) {					\
> +		__print_once = true;				\
> +		printk_deferred(fmt, ##__VA_ARGS__);		\
> +	}							\
> +})
>  #else
>  #define printk_once(fmt, ...)					\
>  	no_printk(fmt, ##__VA_ARGS__)
> +#define printk_deferred_once(fmt, ...)				\
> +	no_printk(fmt, ##__VA_ARGS__)
>  #endif
>  
>  #define pr_emerg_once(fmt, ...)					\
> diff --git a/kernel/sched/deadline.c b/kernel/sched/deadline.c
> index 657ed68..80837e9 100644
> --- a/kernel/sched/deadline.c
> +++ b/kernel/sched/deadline.c
> @@ -348,12 +348,7 @@ static void replenish_dl_entity(struct sched_dl_entity *dl_se,
>  	 * entity.
>  	 */
>  	if (dl_time_before(dl_se->deadline, rq_clock(rq))) {
> -		static bool lag_once = false;
> -
> -		if (!lag_once) {
> -			lag_once = true;
> -			printk_deferred("sched: DL replenish lagged to much\n");
> -		}
> +		printk_deferred_once("sched: DL replenish lagged to much\n");
>  		dl_se->deadline = rq_clock(rq) + pi_se->dl_deadline;
>  		dl_se->runtime = pi_se->dl_runtime;
>  	}
> diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c
> index e7dc728..ea4d500 100644
> --- a/kernel/sched/rt.c
> +++ b/kernel/sched/rt.c
> @@ -890,14 +890,8 @@ static int sched_rt_runtime_exceeded(struct rt_rq *rt_rq)
>  		 * but accrue some time due to boosting.
>  		 */
>  		if (likely(rt_b->rt_runtime)) {
> -			static bool once = false;
> -
>  			rt_rq->rt_throttled = 1;
> -
> -			if (!once) {
> -				once = true;
> -				printk_deferred("sched: RT throttling activated\n");
> -			}
> +			printk_deferred_once("sched: RT throttling activated\n");
>  		} else {
>  			/*
>  			 * In case we did anyway, make it go away,
> -- 
> 1.9.1
> 
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

[PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[John Stultz]

Jiri Bohac pointed out that there are rare but potential deadlock
possibilities when calling printk while holding the timekeeping
seqlock.

This is due to printk() triggering console sem wakeup, which can
cause scheduling code to trigger hrtimers which may try to read
the time.

Specifically, as Jiri pointed out, that path is:
  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, ...)

This patch tries to avoid this issue by using printk_deferred (previously
named printk_sched) which should defer printing via a irq_work_queue.

Cc: Jan Kara <jack@suse.cz>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Bohac <jbohac@suse.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Reported-by: Jiri Bohac <jbohac@suse.cz>
Reviewed-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: John Stultz <john.stultz@linaro.org>
---
 kernel/time/ntp.c         | 15 +++++++++------
 kernel/time/timekeeping.c |  7 ++++---
 2 files changed, 13 insertions(+), 9 deletions(-)

diff --git a/kernel/time/ntp.c b/kernel/time/ntp.c
index 419a52c..5b0ac4d 100644
--- a/kernel/time/ntp.c
+++ b/kernel/time/ntp.c
@@ -786,8 +786,9 @@ static long hardpps_update_freq(struct pps_normtime freq_norm)
 		time_status |= STA_PPSERROR;
 		pps_errcnt++;
 		pps_dec_freq_interval();
-		pr_err("hardpps: PPSERROR: interval too long - %ld s\n",
-				freq_norm.sec);
+		printk_deferred(KERN_ERR
+			"hardpps: PPSERROR: interval too long - %ld s\n",
+			freq_norm.sec);
 		return 0;
 	}
 
@@ -800,7 +801,8 @@ static long hardpps_update_freq(struct pps_normtime freq_norm)
 	delta = shift_right(ftemp - pps_freq, NTP_SCALE_SHIFT);
 	pps_freq = ftemp;
 	if (delta > PPS_MAXWANDER || delta < -PPS_MAXWANDER) {
-		pr_warning("hardpps: PPSWANDER: change=%ld\n", delta);
+		printk_deferred(KERN_WARNING
+				"hardpps: PPSWANDER: change=%ld\n", delta);
 		time_status |= STA_PPSWANDER;
 		pps_stbcnt++;
 		pps_dec_freq_interval();
@@ -844,8 +846,9 @@ static void hardpps_update_phase(long error)
 	 * the time offset is updated.
 	 */
 	if (jitter > (pps_jitter << PPS_POPCORN)) {
-		pr_warning("hardpps: PPSJITTER: jitter=%ld, limit=%ld\n",
-		       jitter, (pps_jitter << PPS_POPCORN));
+		printk_deferred(KERN_WARNING
+				"hardpps: PPSJITTER: jitter=%ld, limit=%ld\n",
+				jitter, (pps_jitter << PPS_POPCORN));
 		time_status |= STA_PPSJITTER;
 		pps_jitcnt++;
 	} else if (time_status & STA_PPSTIME) {
@@ -902,7 +905,7 @@ void __hardpps(const struct timespec *phase_ts, const struct timespec *raw_ts)
 		time_status |= STA_PPSJITTER;
 		/* restart the frequency calibration interval */
 		pps_fbase = *raw_ts;
-		pr_err("hardpps: PPSJITTER: bad pulse\n");
+		printk_deferred(KERN_ERR "hardpps: PPSJITTER: bad pulse\n");
 		return;
 	}
 
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index f7df8ea..32d8d6a 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -852,8 +852,9 @@ static void __timekeeping_inject_sleeptime(struct timekeeper *tk,
 							struct timespec *delta)
 {
 	if (!timespec_valid_strict(delta)) {
-		printk(KERN_WARNING "__timekeeping_inject_sleeptime: Invalid "
-					"sleep delta value!\n");
+		printk_deferred(KERN_WARNING
+				"__timekeeping_inject_sleeptime: Invalid "
+				"sleep delta value!\n");
 		return;
 	}
 	tk_xtime_add(tk, delta);
@@ -1157,7 +1158,7 @@ static void timekeeping_adjust(struct timekeeper *tk, s64 offset)
 
 	if (unlikely(tk->clock->maxadj &&
 		(tk->mult + adj > tk->clock->mult + tk->clock->maxadj))) {
-		printk_once(KERN_WARNING
+		printk_deferred_once(KERN_WARNING
 			"Adjusting %s more than 11%% (%ld vs %ld)\n",
 			tk->clock->name, (long)tk->mult + adj,
 			(long)tk->clock->mult + tk->clock->maxadj);
-- 
1.9.1

Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[George Spelvin]

One misfeature in the timekeeping seqlock code I noticed is that
read_seqcount_begin returns "unsigned int", not "unsigned long".

Casting to a larger type is harmless, but inefficient.

> This is due to printk() triggering console sem wakeup, which can
> cause scheduling code to trigger hrtimers which may try to read
> the time.

An alternative solution, which avoids the need for this entire patch
series, is to make ktime_get completely nonblocking.

To do that, use a seqlock variant wherein you mintain an array of "struct
timekeeper" structures so that reading is always non-blocking if there
is no writer progress.  (I.e. livelock is remotely possible, but deadlock
is not.)

In the basic version, there are two.  (You can add more to further
reduce the chance of livelock.)  The currently stable one is indicated
by (timekeeper_seq->sequence & 2).  Writers update the appropriate
one ping-pong.  The low two bits indicate four phases:

0: Both timekeepers stable, [0] preferred for reading
1: Timekeeper[1] is being written; read timekeeper[0] only
2: Both timekeepers stable, [1] preferred for reading
3: Timekeeper[0] is being written; read timekeeper[1] only

The actual writer locking code is exactly the current write_seqcount_begin
and write_seqcount_end code.

A reader needs to retry only if end_seq > (start_seq & ~1u) + 2.
Accounting for wraparound, the read sequence is:

unsigned raw_read_FOO_begin(seqcount_t const *s)
{
	unsigned ret = ACCESS_ONCE(s->sequence);
	smp_rmb();
	return ret;
}

unsigned raw_read_FOO_retry(seqcount_t const *s, unsigned start)
{
	smp_rmb();
	start &= ~1u;
	return unlikely(s->seqence - start > 2);
}


A reader does:

        unsigned seq;

        do {
		struct timekeeper const *tk;
                seq = read_FOO_begin(&timekeeper_seq);
 		tk = timekeeper + (seq >> 1 & 1);
		frobnicate(tk);
        } while (read_FOO_retry(&timekeeper_seq, seq));

I haven't yet thought of a good name (to replace FOO) for this.
"seqnonblock"?


If you have more frequent updates, there's another variant that does
away with lsbit of the sequence number, so the writer only increments it
once, after update.  This reduces coherency traffic.  It does, however,
cause more readers to retry unless you go to an array of 4 structures.

Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[John Stultz]

First: My apologies, for some reason your mail got tagged as spam, so I
only saw it just now looking for another missing email.


On 05/06/2014 02:33 PM, George Spelvin wrote:
> One misfeature in the timekeeping seqlock code I noticed is that
> read_seqcount_begin returns "unsigned int", not "unsigned long".
>
> Casting to a larger type is harmless, but inefficient.
Thanks for pointing this out. If you want to spin up a patch for this,
I'd be fine applying it. Otherwise I'll try to clean this up sometime soon.

>> This is due to printk() triggering console sem wakeup, which can
>> cause scheduling code to trigger hrtimers which may try to read
>> the time.
> An alternative solution, which avoids the need for this entire patch
> series, is to make ktime_get completely nonblocking.
>
> To do that, use a seqlock variant wherein you mintain an array of "struct
> timekeeper" structures so that reading is always non-blocking if there
> is no writer progress.  (I.e. livelock is remotely possible, but deadlock
> is not.)
>
> In the basic version, there are two.  (You can add more to further
> reduce the chance of livelock.)  The currently stable one is indicated
> by (timekeeper_seq->sequence & 2).  Writers update the appropriate
> one ping-pong.  The low two bits indicate four phases:
>
> 0: Both timekeepers stable, [0] preferred for reading
> 1: Timekeeper[1] is being written; read timekeeper[0] only
> 2: Both timekeepers stable, [1] preferred for reading
> 3: Timekeeper[0] is being written; read timekeeper[1] only


So this has been suggested before (and I've spent some time awhile back
trying to implement it).  The problem is that should the update be
significantly delayed (by for instance, the host preempting a VM's cpu
for some extended period), and a frequency adjustment slowing the clock
was being applied to the new timekeeper, the continued use of the old
timekeeper could cause the current time to over-shoot the new
timekeeper, causing time to go backwards when we finally made the switch. :(

But I believe the sched_clock code does something like this on x86,
since it doesn't have to handle frequency changes.

I would very much like to have a non-blocking implementation! We've also
looked at variants where we keep a valid-interval range in the structure
so readers can be sure the timekeeper they're using is still active
(sort of an expiration date), so we would only block if an update was
delayed. However this is problematic, since there are a number of
timekeeping calls in the hrtimer logic required to trigger the
timekeeping update. So if the update interrupt was delayed, those reads
would block, deadlocking the box.

So maybe you can come up with a tweak to make it possible, but when
discussing this at length w/ Matheiu Desnoyers, it seemed like the main
problem was there was no way to atomically validate that we hadn't been
delayed and update the pointer to the new structure without stopping all
the cpus with some sort of serializing lock.

thanks
-john

Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[George Spelvin]

On Mon, 12 May 2014, John Stultz wrote:
> First: My apologies, for some reason your mail got tagged as spam, so I
> only saw it just now looking for another missing email.

No problem; it happens to everyone.  Curse you, Canter & Siegel!

>> One misfeature in the timekeeping seqlock code I noticed is that
>>  read_seqcount_begin returns "unsigned int", not "unsigned long".
>>
> Casting to a larger type is harmless, but inefficient.

> Thanks for pointing this out. If you want to spin up a patch for this,
> I'd be fine applying it. Otherwise I'll try to clean this up sometime soon.

Appended.  And a second one that you may or may not like.

> So this has been suggested before (and I've spent some time awhile back
> trying to implement it).  The problem is that should the update be
> significantly delayed (by for instance, the host preempting a VM's cpu
> for some extended period), and a frequency adjustment slowing the clock
> was being applied to the new timekeeper, the continued use of the old
> timekeeper could cause the current time to over-shoot the new
> timekeeper, causing time to go backwards when we finally made the switch. :(

Thank you very much!  "I'd like to, but it's very very tricky" is encouraging,
if daunting.

> I would very much like to have a non-blocking implementation! We've also
> looked at variants where we keep a valid-interval range in the structure
> so readers can be sure the timekeeper they're using is still active
> (sort of an expiration date), so we would only block if an update was
> delayed. However this is problematic, since there are a number of
> timekeeping calls in the hrtimer logic required to trigger the
> timekeeping update. So if the update interrupt was delayed, those reads
> would block, deadlocking the box.

> So maybe you can come up with a tweak to make it possible, but when
> discussing this at length w/ Matheiu Desnoyers, it seemed like the main
> problem was there was no way to atomically validate that we hadn't been
> delayed and update the pointer to the new structure without stopping all
> the cpus with some sort of serializing lock.

Okay, two approaches come to mind:

1) Dividing the "get the time" calls into "strictly monotonic, but
   blocking", and "only approximately non-monotonic".  Debugging/printk
   would use the latter.  The downside is API complexity pushed onto the
   users.
2) Using wait-free coding techniques where readers help the writer if
   they notice a stall.  This is much hairier internal code, but makes
   life easier on the callers.  The basic procedure is:

   - A conventionally locked writer decides that the frequency is to be
     adjusted, effective at the current time (or perhaps slightly in the
     future).
   - It publishes its idea of the effective time, and that an update is
     in progress.
   - A reader comes in, reads the hardware clock, and checks:
     - Is a rate update in progress, and is the effective time *before*
       the time I just read?
     - If so, I'm going to force a postponement to the time I just read,
       using compare-and-swap trickery.
     - Then it proceeds to use the old timekeeper rate information.
   - When the writer finishes figuring out the new timekeeper state,
     as part of the atomic installation of a new state, it checks to
     see if a reader has forced a postponement.  If so, it goes back and
     recomputes the state with the later effective time and tries again.

   Going down a level to how to implement this, one way (I may be biased
   because my mind is already on this track) is to extend the technique
   of using the seqlock counter to control ping-pong between 2 states:

   - The writer publishes the effective time in a global variable (and
     does an smp_wmb) before setting the lsbit of the sequence.
   - Readers, if they see the lsbit set, check the effective time,
     and if they see a conflict, atomically clear the lsbit, forcing
     the final write-unlock to abort.
   - If a reader loses the race to clear the lsbit, the reader recomputes
     using the new state.
   - When the writer tries to complete the update, it does an atomic update
     of the sequence counter and notices that someone has messed with it.
     Then it retries, recomputing the rate update with a later effective
     time.
     (Rather than a compare-and-swap, it could simply do an atomic
     increment which releases the lock if there was no race, and starts
     a new write if there was one).

   This approach has some horrible complexity inside the (already quite
   convoluted) timekeeper code, but allows all the read operations to
   be wait-free.

   The question is whether this can be implemented in a way that's
   comprehensible to anyone but Paul McKenney.

Does that make sense, or am I hallucinating?

Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[John Stultz]

On 05/12/2014 07:44 PM, George Spelvin wrote:
> On Mon, 12 May 2014, John Stultz wrote:
>> First: My apologies, for some reason your mail got tagged as spam, so I
>> only saw it just now looking for another missing email.
> No problem; it happens to everyone.  Curse you, Canter & Siegel!
>
>>> One misfeature in the timekeeping seqlock code I noticed is that
>>>  read_seqcount_begin returns "unsigned int", not "unsigned long".
>>>
>> Casting to a larger type is harmless, but inefficient.
>> Thanks for pointing this out. If you want to spin up a patch for this,
>> I'd be fine applying it. Otherwise I'll try to clean this up sometime soon.
> Appended.  And a second one that you may or may not like.
>
>> So this has been suggested before (and I've spent some time awhile back
>> trying to implement it).  The problem is that should the update be
>> significantly delayed (by for instance, the host preempting a VM's cpu
>> for some extended period), and a frequency adjustment slowing the clock
>> was being applied to the new timekeeper, the continued use of the old
>> timekeeper could cause the current time to over-shoot the new
>> timekeeper, causing time to go backwards when we finally made the switch. :(
> Thank you very much!  "I'd like to, but it's very very tricky" is encouraging,
> if daunting.
>
>> I would very much like to have a non-blocking implementation! We've also
>> looked at variants where we keep a valid-interval range in the structure
>> so readers can be sure the timekeeper they're using is still active
>> (sort of an expiration date), so we would only block if an update was
>> delayed. However this is problematic, since there are a number of
>> timekeeping calls in the hrtimer logic required to trigger the
>> timekeeping update. So if the update interrupt was delayed, those reads
>> would block, deadlocking the box.
>> So maybe you can come up with a tweak to make it possible, but when
>> discussing this at length w/ Matheiu Desnoyers, it seemed like the main
>> problem was there was no way to atomically validate that we hadn't been
>> delayed and update the pointer to the new structure without stopping all
>> the cpus with some sort of serializing lock.
> Okay, two approaches come to mind:
>
> 1) Dividing the "get the time" calls into "strictly monotonic, but
>    blocking", and "only approximately non-monotonic".  Debugging/printk
>    would use the latter.  The downside is API complexity pushed onto the
>    users.

So the printk/debugging is covered by sched_clock which uses a
completely separate code path. So if I'm following along I think this
divide is already in place.


> 2) Using wait-free coding techniques where readers help the writer if
>    they notice a stall.  This is much hairier internal code, but makes
>    life easier on the callers.  The basic procedure is:
>
>    - A conventionally locked writer decides that the frequency is to be
>      adjusted, effective at the current time (or perhaps slightly in the
>      future).
>    - It publishes its idea of the effective time, and that an update is
>      in progress.
>    - A reader comes in, reads the hardware clock, and checks:
>      - Is a rate update in progress, and is the effective time *before*
>        the time I just read?
>      - If so, I'm going to force a postponement to the time I just read,
>        using compare-and-swap trickery.
>      - Then it proceeds to use the old timekeeper rate information.
>    - When the writer finishes figuring out the new timekeeper state,
>      as part of the atomic installation of a new state, it checks to
>      see if a reader has forced a postponement.  If so, it goes back and
>      recomputes the state with the later effective time and tries again.

Hrm.. So basically during the update you lock readers to the counter
value read at the beginning of the update. So readers don't block, but
time doesn't progress while the update is being made. Sounds promising!
Though I worry it rhymes a bit with an idea Matheiu and I were throwing
around during plumbers last year, but didn't work out. I think the
concern with this sort of approach is: how do you prevent a race between
a reader and the update thread such that a reader doesn't sneak in and
read a counter value that is after the value the updater read, but
before the value is stored locking the structure?

You can imagine the updater reads the counter value, then is immediately
stalled for some very long time by a hyper-visor. Various readers on
other cpus read time that continues to increase. Then when the updater
finally returns, he locks the time to that value in the past. Following
readers then see time that appears to go backwards.

I have to admit its getting late and I'm not sure I'm completely
following the bit about the update restarting depending on a forced
postponement.

>    Going down a level to how to implement this, one way (I may be biased
>    because my mind is already on this track) is to extend the technique
>    of using the seqlock counter to control ping-pong between 2 states:
>
>    - The writer publishes the effective time in a global variable (and
>      does an smp_wmb) before setting the lsbit of the sequence.
>    - Readers, if they see the lsbit set, check the effective time,
>      and if they see a conflict, atomically clear the lsbit, forcing
>      the final write-unlock to abort.
>    - If a reader loses the race to clear the lsbit, the reader recomputes
>      using the new state.
>    - When the writer tries to complete the update, it does an atomic update
>      of the sequence counter and notices that someone has messed with it.
>      Then it retries, recomputing the rate update with a later effective
>      time.
>      (Rather than a compare-and-swap, it could simply do an atomic
>      increment which releases the lock if there was no race, and starts
>      a new write if there was one).

Oh.. so its actually more like the update is canceled if a reader can
complete a read and set a flag while the update is in flight? Hrm.. I
worry with the number and frequency of time reads on many systems, you'd
end up with update starvation (something which use to be a problem back
when timekeeping was managed with just spinlocks, and SMP wasn't that
common - so I suspect it can only be worse now).

Further, the write in the read path would cause problems for VDSO time,
where everything is computed on read-only data in userspace.



>    This approach has some horrible complexity inside the (already quite
>    convoluted) timekeeper code, but allows all the read operations to
>    be wait-free.
>
>    The question is whether this can be implemented in a way that's
>    comprehensible to anyone but Paul McKenney.
>
> Does that make sense, or am I hallucinating?

Yea. It definitely gets complex. But timekeeping is always a very
hotpath, so complexity for performance is a normal trade. So there may
be a way to make it work. But finding a way to make it easier to
comprehend (even just having a clear metaphor for whats being done)
would be excellent.

thanks
-john

Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[George Spelvin]

>> 2) Using wait-free coding techniques where readers help the writer if
>>    they notice a stall.  This is much hairier internal code, but makes
>>    life easier on the callers.  The basic procedure is:
>>
>>    - A conventionally locked writer decides that the frequency is to be
>>      adjusted, effective at the current time (or perhaps slightly in the
>>      future).
>>    - It publishes its idea of the effective time, and that an update is
>>      in progress.
>>    - A reader comes in, reads the hardware clock, and checks:
>>      - Is a rate update in progress, and is the effective time *before*
>>        the time I just read?
>>      - If so, I'm going to force a postponement to the time I just read,
>>        using compare-and-swap trickery.
>>      - Then it proceeds to use the old timekeeper rate information.
>>    - When the writer finishes figuring out the new timekeeper state,
>>      as part of the atomic installation of a new state, it checks to
>>      see if a reader has forced a postponement.  If so, it goes back and
>>      recomputes the state with the later effective time and tries again.
> 
> Hrm.. So basically during the update you lock readers to the counter
> value read at the beginning of the update. So readers don't block, but
> time doesn't progress while the update is being made. Sounds promising!

Er... no.  I guess my explanation didn't work.  I thought of that (it's
quite simple, after all), but I was worried that the stuttering would
mess up fine accounting for e.g. interrupt handlers.

Also, it's not implementable.  The writer must pick a rate-change moment,
then announce it.  If it stalls between those two operations (and there's
no way to make them atomic), then it might announce a moment already in
the past, causing a later reader to return the stalled time, while an
earlier reader that didn't see the announcement has already returned
a later time.

Inseate, the writer announces a *proposed* rate-change time, but a number
of conditions can cause that time to be postponed.  (Basically, the writer
loops back to the beginning and applies the rate change later.)

One condition is enforced by the writer itself: it reads the time again
after making the announcement, and if the announced time has already
passed, loops.

But this is also checked by all readers.  If an update is in progress,
with a proposed time earlier than the reader is in the process of reading,
the writer is told to try again later.


One trick that can minimize the number of retries is to add a very small
time delta (equal to the typical write update cycle) to the writer's
effective time.  If the writer completes before that time happens (the
common case), readers happily use the old time values during the update.
Only if the writer is delayed more than expected will a reader notice
a problem.  "Hey, I read the hardware at tick x, but the writer is trying
to update tick-to-seconds translations for times later than tick y < x.
Hey, writer, recompute with a higher y!"


There is also the issue of a reader coming along after the change-over
and wanting to translate a time x < y.  There are several ways to
handle this.  Either the old parameters have to be kept around until
time y has passed, or the readers must wait until time y.

(They may not return early reporting time y or there may be race conditions.)

> Oh.. so its actually more like the update is canceled if a reader can
> complete a read and set a flag while the update is in flight? Hrm.. I
> worry with the number and frequency of time reads on many systems, you'd
> end up with update starvation (something which use to be a problem back
> when timekeeping was managed with just spinlocks, and SMP wasn't that
> common - so I suspect it can only be worse now).

The solution, mentioned above, is to have the effective time of the
update set to the predicted write completion time.  Then the readers will
never see an effective time less than their time and need to postpone
the writer.

Only if the writer is delayed unexpectedly does that happen.

> Further, the write in the read path would cause problems for VDSO time,
> where everything is computed on read-only data in userspace.

Ah!  Now *that* poses a potential problem.  I didn't think of that.
Arrgh, that's going to take some work.

Two possibilities:
1) The VDSO code could just spin.  It's not holding any kernel locks,
   so there's not much problem.
2) Possibly after some optimistic spinning, the VDSO code could
   trap to the kernel as a fallback.

> Yea. It definitely gets complex. But timekeeping is always a very
> hotpath, so complexity for performance is a normal trade. So there may
> be a way to make it work. But finding a way to make it easier to
> comprehend (even just having a clear metaphor for what's being done)
> would be excellent.

I'll try.

Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[Mathieu Desnoyers]

----- Original Message -----
> From: "George Spelvin" <linux@horizon.com>
> To: "john stultz" <john.stultz@linaro.org>, linux@horizon.com
> Cc: linux-kernel@vger.kernel.org, "mathieu desnoyers" <mathieu.desnoyers@efficios.com>
> Sent: Tuesday, May 13, 2014 1:13:24 AM
> Subject: Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock
> 
> >> 2) Using wait-free coding techniques where readers help the writer if
> >>    they notice a stall.  This is much hairier internal code, but makes
> >>    life easier on the callers.  The basic procedure is:
> >>
> >>    - A conventionally locked writer decides that the frequency is to be
> >>      adjusted, effective at the current time (or perhaps slightly in the
> >>      future).
> >>    - It publishes its idea of the effective time, and that an update is
> >>      in progress.
> >>    - A reader comes in, reads the hardware clock, and checks:
> >>      - Is a rate update in progress, and is the effective time *before*
> >>        the time I just read?
> >>      - If so, I'm going to force a postponement to the time I just read,
> >>        using compare-and-swap trickery.
> >>      - Then it proceeds to use the old timekeeper rate information.
> >>    - When the writer finishes figuring out the new timekeeper state,
> >>      as part of the atomic installation of a new state, it checks to
> >>      see if a reader has forced a postponement.  If so, it goes back and
> >>      recomputes the state with the later effective time and tries again.
> > 
> > Hrm.. So basically during the update you lock readers to the counter
> > value read at the beginning of the update. So readers don't block, but
> > time doesn't progress while the update is being made. Sounds promising!
> 
> Er... no.  I guess my explanation didn't work.  I thought of that (it's
> quite simple, after all), but I was worried that the stuttering would
> mess up fine accounting for e.g. interrupt handlers.
> 
> Also, it's not implementable.  The writer must pick a rate-change moment,
> then announce it.  If it stalls between those two operations (and there's
> no way to make them atomic), then it might announce a moment already in
> the past, causing a later reader to return the stalled time, while an
> earlier reader that didn't see the announcement has already returned
> a later time.

Your description above summarizes well the conclusions I reached when doing
my nonblocking-read clock source implementation prototype a while back. If
we can add a new clock semantic, there is a solution I proposed last year
that might just achieve what you are looking for:

We could expose a new clock type (besides monotonic and realtime) that is
documented as non-strictly monotonic. It may return a time very slightly in
the past if readers race with clock source frequency change. The caller could
handle this situation (e.g. in user-space) by keeping its own per-cpu or
per-thread "last clock value" data structure (something we cannot do in a
vDSO) if it really cares about per-cpu/thread clock monotonicity.

This could be implemented with the scheme I proposed as a prototype here:

   https://lkml.org/lkml/2013/9/14/136

The idea here would be to keep both a read seqlock (for realtime and
monotonic), as well as an API/ABI that allows reading this "latched
clock" value (documented as non-strictly-monotonic).

Thoughts ?

Thanks,

Mathieu


> 
> Inseate, the writer announces a *proposed* rate-change time, but a number
> of conditions can cause that time to be postponed.  (Basically, the writer
> loops back to the beginning and applies the rate change later.)
> 
> One condition is enforced by the writer itself: it reads the time again
> after making the announcement, and if the announced time has already
> passed, loops.
> 
> But this is also checked by all readers.  If an update is in progress,
> with a proposed time earlier than the reader is in the process of reading,
> the writer is told to try again later.
> 
> 
> One trick that can minimize the number of retries is to add a very small
> time delta (equal to the typical write update cycle) to the writer's
> effective time.  If the writer completes before that time happens (the
> common case), readers happily use the old time values during the update.
> Only if the writer is delayed more than expected will a reader notice
> a problem.  "Hey, I read the hardware at tick x, but the writer is trying
> to update tick-to-seconds translations for times later than tick y < x.
> Hey, writer, recompute with a higher y!"
> 
> 
> There is also the issue of a reader coming along after the change-over
> and wanting to translate a time x < y.  There are several ways to
> handle this.  Either the old parameters have to be kept around until
> time y has passed, or the readers must wait until time y.
> 
> (They may not return early reporting time y or there may be race conditions.)
> 
> > Oh.. so its actually more like the update is canceled if a reader can
> > complete a read and set a flag while the update is in flight? Hrm.. I
> > worry with the number and frequency of time reads on many systems, you'd
> > end up with update starvation (something which use to be a problem back
> > when timekeeping was managed with just spinlocks, and SMP wasn't that
> > common - so I suspect it can only be worse now).
> 
> The solution, mentioned above, is to have the effective time of the
> update set to the predicted write completion time.  Then the readers will
> never see an effective time less than their time and need to postpone
> the writer.
> 
> Only if the writer is delayed unexpectedly does that happen.
> 
> > Further, the write in the read path would cause problems for VDSO time,
> > where everything is computed on read-only data in userspace.
> 
> Ah!  Now *that* poses a potential problem.  I didn't think of that.
> Arrgh, that's going to take some work.
> 
> Two possibilities:
> 1) The VDSO code could just spin.  It's not holding any kernel locks,
>    so there's not much problem.
> 2) Possibly after some optimistic spinning, the VDSO code could
>    trap to the kernel as a fallback.
> 
> > Yea. It definitely gets complex. But timekeeping is always a very
> > hotpath, so complexity for performance is a normal trade. So there may
> > be a way to make it work. But finding a way to make it easier to
> > comprehend (even just having a clear metaphor for what's being done)
> > would be excellent.
> 
> I'll try.
> 

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[George Spelvin]

> We could expose a new clock type (besides monotonic and realtime) that is
> documented as non-strictly monotonic. It may return a time very slightly in
> the past if readers race with clock source frequency change. The caller could
> handle this situation (e.g. in user-space) by keeping its own per-cpu or
> per-thread "last clock value" data structure (something we cannot do in a
> vDSO) if it really cares about per-cpu/thread clock monotonicity.

That the first of two options I proposed.  The problem, with respect to
the immediate problem of debugging during a write deadlocking, is
that it makes a more complex API which callers must understand the
subtleties of.

Perhaps necessary, but definitely a minus.

> This could be implemented with the scheme I proposed as a prototype here:
> 
>    https://lkml.org/lkml/2013/9/14/136

I'm working my way though it.  I definitely like the first patch!

> Thoughts ?

I was trying to tackle the "hard problem" of making *all* time reads
non-blocking, with monotonicity guarantees.  There has to be *some* bound
on blocking times (in particular, time between reading hardware tiemrs
and translating them to real time), but they can be reasonably long.

I think I have an idea that could work, but given the hairiness of
the timeeeping code, implementing it would be a major project.

Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[Mathieu Desnoyers]

----- Original Message -----
> From: "George Spelvin" <linux@horizon.com>
> To: linux@horizon.com, "mathieu desnoyers" <mathieu.desnoyers@efficios.com>
> Cc: "john stultz" <john.stultz@linaro.org>, linux-kernel@vger.kernel.org, peterz@infradead.org, tglx@linutronix.de
> Sent: Tuesday, May 13, 2014 9:29:18 AM
> Subject: Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock
> 
> > We could expose a new clock type (besides monotonic and realtime) that is
> > documented as non-strictly monotonic. It may return a time very slightly in
> > the past if readers race with clock source frequency change. The caller
> > could
> > handle this situation (e.g. in user-space) by keeping its own per-cpu or
> > per-thread "last clock value" data structure (something we cannot do in a
> > vDSO) if it really cares about per-cpu/thread clock monotonicity.
> 
> That the first of two options I proposed.  The problem, with respect to
> the immediate problem of debugging during a write deadlocking, is
> that it makes a more complex API which callers must understand the
> subtleties of.
> 
> Perhaps necessary, but definitely a minus.
> 
> > This could be implemented with the scheme I proposed as a prototype here:
> > 
> >    https://lkml.org/lkml/2013/9/14/136
> 
> I'm working my way though it.  I definitely like the first patch!

Thanks! :)

> 
> > Thoughts ?
> 
> I was trying to tackle the "hard problem" of making *all* time reads
> non-blocking, with monotonicity guarantees.  There has to be *some* bound
> on blocking times (in particular, time between reading hardware tiemrs
> and translating them to real time), but they can be reasonably long.

What I gathered from my past discussion with John on this topic is that
virtualization blows away pretty much any assumption we can make on
"update should be reasonably short". A virtualized CPU can be preempted
for a rather long time (AFAIU not possible to bound).

> I think I have an idea that could work, but given the hairiness of
> the timeeeping code, implementing it would be a major project.

Indeed, timekeeping is not for the faint of heart. ;-)

Thanks,

Mathieu


-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[George Spelvin]

>> I was trying to tackle the "hard problem" of making *all* time reads
>> non-blocking, with monotonicity guarantees.  There has to be *some* bound
>> on blocking times (in particular, time between reading hardware tiemrs
>> and translating them to real time), but they can be reasonably long.

> What I gathered from my past discussion with John on this topic is that
> virtualization blows away pretty much any assumption we can make on
> "update should be reasonably short". A virtualized CPU can be preempted
> for a rather long time (AFAIU not possible to bound).

Well, there are two kinds of time reads:

1) "What is the current time now?"  This is easy, because if we stall
   it's okay to return any time in the appropriate window.
2) "Some time in the past I read the hardware clock with value c.
   What is the time in seconds corresponding to that?"

I'll call number 2 "time conversion".  This can be handled as long as the
time between reading the clock and doing the conversion is reasonable.
Otherwise, it'll fail, with "I don't remember that part of the piecewise
clock/time conversion function."

Now, obviously number 1 can be implemented by reading the hardware clock
and converting it.  As you point out, virtualization makes it impossible
to guarantee any reasonable bound on the time between the two steps.
But in case 1, we can easily handle failure by retrying the read.  (Or,
equivalently, returning the earliest time which we know how to convert.)

All we can guarantee in case 1 is that we return the timestamp of some
instant between call and return.  If that time is made very long by
the hypervisor descheduling us, it reduces the required precision.


So it's possible to allow arbirearily long delays in time writes, in
current-time reads, but conversion has a risk of failure.

I don't think it's possible to do better, so that's kind of the limit.

>> I think I have an idea that could work, but given the hairiness of
>> the timeeeping code, implementing it would be a major project.
>
> Indeed, timekeeping is not for the faint of heart. ;-)

But at least it's interesting, with problems other than undocumented bugs
in hardware.

[PATCH 0/4] Convert timekeeping core to use printk_deferred (v2)

[John Stultz]

Recently, Jiri pointed out a potential deadlock when calling printk
while holding the timekeeping seqlock.

Annoyingly, the seqlock lockdep enablement doesn't catch this, as
printk disables lockdep.

When looking for possible solutions, one idea was to use a local buffer
and defer the printk to later. Ends up there is already similar
functionality in printk_sched() to avoid similar style deadlocks w/
the scheduler.

Thus this patchset (based on next/akpm) renames printk_sched to
printk_deferred and then moves the affected timekeeping printks to make
use of it.

There were some points in the discussion between Jan and Peter that
made it seem that there may still be problems lurking in the console
layer, and I'm not sure I fully understand their point, so this solution
may be incomplete.

Additionally, the same issue likely affects any WARN_ONs as well, but
I wanted to get some thoughts on this approach before trying to remove
or convert affected WARN_ONS.

Your thoughts and feedback are greatly appreciated!

thanks
-john

Changes since v1:
* Rebased on next/akpm, since there are queued prink patches there
* Re-added irqsave/restore per irc discussion w/ PeterZ 

Cc: Jan Kara <jack@suse.cz>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Bohac <jbohac@suse.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Steven Rostedt <rostedt@goodmis.org>

John Stultz (4):
  printk: Re-add irqsave/restore in printk_sched
  printk: Rename printk_sched to printk_deferred
  printk: Add printk_once_deferred
  timekeeping: Use printk_deferred when holding timekeeping seqlock

 include/linux/printk.h    | 17 ++++++++++++++---
 kernel/printk/printk.c    |  5 ++++-
 kernel/sched/core.c       |  2 +-
 kernel/sched/deadline.c   |  7 +------
 kernel/sched/rt.c         |  8 +-------
 kernel/time/ntp.c         | 15 +++++++++------
 kernel/time/timekeeping.c |  7 ++++---
 7 files changed, 34 insertions(+), 27 deletions(-)

-- 
1.9.1

[PATCH 4/4] timekeeping: Use printk_deferred when holding timekeeping seqlock

[John Stultz]

Jiri Bohac pointed out that there are rare but potential deadlock
possibilities when calling printk while holding the timekeeping
seqlock.

This is due to printk() triggering console sem wakeup, which can
cause scheduling code to trigger hrtimers which may try to read
the time.

Specifically, as Jiri pointed out, that path is:
  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, ...)

This patch tries to avoid this issue by using printk_deferred (previously
named printk_sched) which should defer printing via a irq_work_queue.

Cc: Jan Kara <jack@suse.cz>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Bohac <jbohac@suse.cz>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Reported-by: Jiri Bohac <jbohac@suse.cz>
Signed-off-by: John Stultz <john.stultz@linaro.org>
---
 kernel/time/ntp.c         | 15 +++++++++------
 kernel/time/timekeeping.c |  7 ++++---
 2 files changed, 13 insertions(+), 9 deletions(-)

diff --git a/kernel/time/ntp.c b/kernel/time/ntp.c
index 419a52c..5b0ac4d 100644
--- a/kernel/time/ntp.c
+++ b/kernel/time/ntp.c
@@ -786,8 +786,9 @@ static long hardpps_update_freq(struct pps_normtime freq_norm)
 		time_status |= STA_PPSERROR;
 		pps_errcnt++;
 		pps_dec_freq_interval();
-		pr_err("hardpps: PPSERROR: interval too long - %ld s\n",
-				freq_norm.sec);
+		printk_deferred(KERN_ERR
+			"hardpps: PPSERROR: interval too long - %ld s\n",
+			freq_norm.sec);
 		return 0;
 	}
 
@@ -800,7 +801,8 @@ static long hardpps_update_freq(struct pps_normtime freq_norm)
 	delta = shift_right(ftemp - pps_freq, NTP_SCALE_SHIFT);
 	pps_freq = ftemp;
 	if (delta > PPS_MAXWANDER || delta < -PPS_MAXWANDER) {
-		pr_warning("hardpps: PPSWANDER: change=%ld\n", delta);
+		printk_deferred(KERN_WARNING
+				"hardpps: PPSWANDER: change=%ld\n", delta);
 		time_status |= STA_PPSWANDER;
 		pps_stbcnt++;
 		pps_dec_freq_interval();
@@ -844,8 +846,9 @@ static void hardpps_update_phase(long error)
 	 * the time offset is updated.
 	 */
 	if (jitter > (pps_jitter << PPS_POPCORN)) {
-		pr_warning("hardpps: PPSJITTER: jitter=%ld, limit=%ld\n",
-		       jitter, (pps_jitter << PPS_POPCORN));
+		printk_deferred(KERN_WARNING
+				"hardpps: PPSJITTER: jitter=%ld, limit=%ld\n",
+				jitter, (pps_jitter << PPS_POPCORN));
 		time_status |= STA_PPSJITTER;
 		pps_jitcnt++;
 	} else if (time_status & STA_PPSTIME) {
@@ -902,7 +905,7 @@ void __hardpps(const struct timespec *phase_ts, const struct timespec *raw_ts)
 		time_status |= STA_PPSJITTER;
 		/* restart the frequency calibration interval */
 		pps_fbase = *raw_ts;
-		pr_err("hardpps: PPSJITTER: bad pulse\n");
+		printk_deferred(KERN_ERR "hardpps: PPSJITTER: bad pulse\n");
 		return;
 	}
 
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index f7df8ea..ffd3113 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -852,8 +852,9 @@ static void __timekeeping_inject_sleeptime(struct timekeeper *tk,
 							struct timespec *delta)
 {
 	if (!timespec_valid_strict(delta)) {
-		printk(KERN_WARNING "__timekeeping_inject_sleeptime: Invalid "
-					"sleep delta value!\n");
+		printk_deferred(KERN_WARNING
+				"__timekeeping_inject_sleeptime: Invalid "
+				"sleep delta value!\n");
 		return;
 	}
 	tk_xtime_add(tk, delta);
@@ -1157,7 +1158,7 @@ static void timekeeping_adjust(struct timekeeper *tk, s64 offset)
 
 	if (unlikely(tk->clock->maxadj &&
 		(tk->mult + adj > tk->clock->mult + tk->clock->maxadj))) {
-		printk_once(KERN_WARNING
+		printk_once_deferred(KERN_WARNING
 			"Adjusting %s more than 11%% (%ld vs %ld)\n",
 			tk->clock->name, (long)tk->mult + adj,
 			(long)tk->clock->mult + tk->clock->maxadj);
-- 
1.9.1