Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1713044 > unrolled thread

[PATCH 0/2 v6] printk: Add new timestamps

Started byPrarit Bhargava <prarit@redhat.com>
First post2017-08-16 17:20 +0200
Last post2017-08-17 05:50 +0200
Articles 5 — 3 participants

Back to article view | Back to linux.kernel

Contents

  [PATCH 0/2 v6] printk: Add new timestamps Prarit Bhargava <prarit@redhat.com> - 2017-08-16 17:20 +0200
    [PATCH 1/2 v6] time: Make fast functions return 0 before timekeeping is initialized Prarit Bhargava <prarit@redhat.com> - 2017-08-16 17:20 +0200
      Re: [PATCH 1/2 v6] time: Make fast functions return 0 before  timekeeping is initialized John Stultz <john.stultz@linaro.org> - 2017-08-17 05:50 +0200
    Re: [PATCH 2/2 v6] printk: Add monotonic, boottime, and realtime  timestamps Mark Salyzyn <salyzyn@android.com> - 2017-08-16 17:50 +0200
    Re: [PATCH 2/2 v6] printk: Add monotonic, boottime, and realtime timestamps John Stultz <john.stultz@linaro.org> - 2017-08-17 05:50 +0200

#1713044 — [PATCH 0/2 v6] printk: Add new timestamps

FromPrarit Bhargava <prarit@redhat.com>
Date2017-08-16 17:20 +0200
Subject[PATCH 0/2 v6] printk: Add new timestamps
Message-ID<uf8gV-gn-3@gated-at.bofh.it>
printk.time=1/CONFIG_PRINTK_TIME=1 adds a unmodified local hardware clock
timestamp to printk messages.  The local hardware clock loses time each
day making it difficult to determine exactly when an issue has occurred in
the kernel log, and making it difficult to determine how kernel and
hardware issues relate to each other in real time.

Add monotonic, boottime, and real clock timestamps in addition to the existing
local hardware clock timestamp.

Signed-off-by: Prarit Bhargava <prarit@redhat.com>
Cc: Mark Salyzyn <salyzyn@android.com>
Cc: Jonathan Corbet <corbet@lwn.net>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Stephen Boyd <sboyd@codeaurora.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Cc: Christoffer Dall <cdall@linaro.org>
Cc: Deepa Dinamani <deepa.kernel@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Joel Fernandes <joelaf@google.com>
Cc: Prarit Bhargava <prarit@redhat.com>
Cc: Kees Cook <keescook@chromium.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Geert Uytterhoeven <geert+renesas@glider.be>
Cc: "Luis R. Rodriguez" <mcgrof@kernel.org>
Cc: Nicholas Piggin <npiggin@gmail.com>
Cc: "Jason A. Donenfeld" <Jason@zx2c4.com>
Cc: Olof Johansson <olof@lixom.net>
Cc: Josh Poimboeuf <jpoimboe@redhat.com>
Cc: linux-doc@vger.kernel.org

Prarit Bhargava (2):
  time: Make fast functions return 0 before timekeeping is initialized
  printk: Add monotonic, boottime, and realtime timestamps

 Documentation/admin-guide/kernel-parameters.txt    |   6 +-
 arch/arm/configs/aspeed_g4_defconfig               |   2 +-
 arch/arm/configs/aspeed_g5_defconfig               |   2 +-
 arch/arm/configs/axm55xx_defconfig                 |   2 +-
 arch/arm/configs/bcm2835_defconfig                 |   2 +-
 arch/arm/configs/colibri_pxa270_defconfig          |   2 +-
 arch/arm/configs/colibri_pxa300_defconfig          |   2 +-
 arch/arm/configs/dove_defconfig                    |   2 +-
 arch/arm/configs/efm32_defconfig                   |   2 +-
 arch/arm/configs/exynos_defconfig                  |   2 +-
 arch/arm/configs/ezx_defconfig                     |   2 +-
 arch/arm/configs/h5000_defconfig                   |   2 +-
 arch/arm/configs/hisi_defconfig                    |   2 +-
 arch/arm/configs/imote2_defconfig                  |   2 +-
 arch/arm/configs/imx_v6_v7_defconfig               |   2 +-
 arch/arm/configs/keystone_defconfig                |   2 +-
 arch/arm/configs/lpc18xx_defconfig                 |   2 +-
 arch/arm/configs/magician_defconfig                |   2 +-
 arch/arm/configs/mmp2_defconfig                    |   2 +-
 arch/arm/configs/moxart_defconfig                  |   2 +-
 arch/arm/configs/mps2_defconfig                    |   2 +-
 arch/arm/configs/multi_v7_defconfig                |   2 +-
 arch/arm/configs/mvebu_v7_defconfig                |   2 +-
 arch/arm/configs/mxs_defconfig                     |   2 +-
 arch/arm/configs/omap2plus_defconfig               |   2 +-
 arch/arm/configs/pxa168_defconfig                  |   2 +-
 arch/arm/configs/pxa3xx_defconfig                  |   2 +-
 arch/arm/configs/pxa910_defconfig                  |   2 +-
 arch/arm/configs/pxa_defconfig                     |   2 +-
 arch/arm/configs/qcom_defconfig                    |   2 +-
 arch/arm/configs/raumfeld_defconfig                |   2 +-
 arch/arm/configs/shmobile_defconfig                |   2 +-
 arch/arm/configs/socfpga_defconfig                 |   2 +-
 arch/arm/configs/stm32_defconfig                   |   2 +-
 arch/arm/configs/sunxi_defconfig                   |   2 +-
 arch/arm/configs/tango4_defconfig                  |   2 +-
 arch/arm/configs/tegra_defconfig                   |   2 +-
 arch/arm/configs/u300_defconfig                    |   2 +-
 arch/arm/configs/u8500_defconfig                   |   2 +-
 arch/arm/configs/vt8500_v6_v7_defconfig            |   2 +-
 arch/arm/configs/xcep_defconfig                    |   2 +-
 arch/arm/configs/zx_defconfig                      |   2 +-
 arch/arm64/configs/defconfig                       |   2 +-
 arch/m68k/configs/amcore_defconfig                 |   2 +-
 arch/mips/configs/ath25_defconfig                  |   2 +-
 arch/mips/configs/bcm47xx_defconfig                |   2 +-
 arch/mips/configs/bmips_be_defconfig               |   2 +-
 arch/mips/configs/bmips_stb_defconfig              |   2 +-
 arch/mips/configs/ci20_defconfig                   |   2 +-
 arch/mips/configs/generic_defconfig                |   2 +-
 arch/mips/configs/lemote2f_defconfig               |   2 +-
 arch/mips/configs/loongson3_defconfig              |   2 +-
 arch/mips/configs/nlm_xlp_defconfig                |   2 +-
 arch/mips/configs/nlm_xlr_defconfig                |   2 +-
 arch/mips/configs/pistachio_defconfig              |   2 +-
 arch/mips/configs/qi_lb60_defconfig                |   2 +-
 arch/mips/configs/rt305x_defconfig                 |   2 +-
 arch/mips/configs/xway_defconfig                   |   2 +-
 arch/parisc/configs/generic-64bit_defconfig        |   2 +-
 arch/powerpc/configs/40x/virtex_defconfig          |   2 +-
 arch/powerpc/configs/44x/fsp2_defconfig            |   2 +-
 arch/powerpc/configs/44x/virtex5_defconfig         |   2 +-
 arch/powerpc/configs/44x/warp_defconfig            |   2 +-
 arch/powerpc/configs/52xx/cm5200_defconfig         |   2 +-
 arch/powerpc/configs/52xx/lite5200b_defconfig      |   2 +-
 arch/powerpc/configs/52xx/motionpro_defconfig      |   2 +-
 arch/powerpc/configs/52xx/tqm5200_defconfig        |   2 +-
 arch/powerpc/configs/gamecube_defconfig            |   2 +-
 arch/powerpc/configs/mpc5200_defconfig             |   2 +-
 arch/powerpc/configs/pasemi_defconfig              |   2 +-
 arch/powerpc/configs/wii_defconfig                 |   2 +-
 arch/s390/configs/default_defconfig                |   2 +-
 arch/s390/configs/gcov_defconfig                   |   2 +-
 arch/s390/configs/performance_defconfig            |   2 +-
 arch/s390/configs/zfcpdump_defconfig               |   2 +-
 arch/sh/configs/edosk7760_defconfig                |   2 +-
 arch/sh/configs/sdk7786_defconfig                  |   2 +-
 arch/sh/configs/se7722_defconfig                   |   2 +-
 arch/sh/configs/sh7785lcr_32bit_defconfig          |   2 +-
 arch/sh/configs/urquell_defconfig                  |   2 +-
 arch/sparc/configs/sparc64_defconfig               |   2 +-
 arch/x86/configs/i386_defconfig                    |   2 +-
 arch/x86/configs/x86_64_defconfig                  |   2 +-
 arch/xtensa/configs/audio_kc705_defconfig          |   2 +-
 arch/xtensa/configs/cadence_csp_defconfig          |   2 +-
 arch/xtensa/configs/generic_kc705_defconfig        |   2 +-
 arch/xtensa/configs/nommu_kc705_defconfig          |   2 +-
 arch/xtensa/configs/smp_lx200_defconfig            |   2 +-
 include/linux/timekeeping.h                        |   1 +
 kernel/printk/printk.c                             | 147 ++++++++++++++++++++-
 kernel/time/timekeeping.c                          |  46 +++++--
 lib/Kconfig.debug                                  |  54 +++++++-
 .../selftests/rcutorture/configs/lock/CFcommon     |   2 +-
 .../selftests/rcutorture/configs/rcu/CFcommon      |   2 +-
 .../selftests/rcutorture/configs/rcuperf/CFcommon  |   2 +-
 95 files changed, 320 insertions(+), 114 deletions(-)

-- 
1.8.5.5

[toc] | [next] | [standalone]

#1713050 — [PATCH 1/2 v6] time: Make fast functions return 0 before timekeeping is initialized

FromPrarit Bhargava <prarit@redhat.com>
Date2017-08-16 17:20 +0200
Subject[PATCH 1/2 v6] time: Make fast functions return 0 before timekeeping is initialized
Message-ID<uf8gZ-gn-53@gated-at.bofh.it>
In reply to#1713044
printk timestamps will be extended to include mono and boot time by using
the fast timekeeping functions ktime_get_mono|boot_fast_ns() functions.
The functions can return garbage before timekeeping is initialized
resulting in garbage timestamps.

The fast time functions must return 0 before timekeeping is initialized.

v6: Separate these changes out into their own patch.

Signed-off-by: Prarit Bhargava <prarit@redhat.com>
Suggested-by: Peter Zijlstra <peterz@infradead.org>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Stephen Boyd <sboyd@codeaurora.org>
---
 kernel/time/timekeeping.c | 47 +++++++++++++++++++++++++++++++++--------------
 1 file changed, 33 insertions(+), 14 deletions(-)

diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index cedafa008de5..d111039e0245 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -60,8 +60,39 @@ struct tk_fast {
 	struct tk_read_base	base[2];
 };
 
-static struct tk_fast tk_fast_mono ____cacheline_aligned;
-static struct tk_fast tk_fast_raw  ____cacheline_aligned;
+/* Suspend-time cycles value for halted fast timekeeper. */
+static u64 cycles_at_suspend;
+
+static u64 dummy_clock_read(struct clocksource *cs)
+{
+	return cycles_at_suspend;
+}
+
+static struct clocksource dummy_clock = {
+	.read = dummy_clock_read,
+};
+
+static struct tk_fast tk_fast_mono ____cacheline_aligned = {
+	.base = {
+		(struct tk_read_base){
+			.clock = &dummy_clock,
+		},
+		(struct tk_read_base){
+			.clock = &dummy_clock,
+		},
+	},
+};
+
+static struct tk_fast tk_fast_raw  ____cacheline_aligned = {
+	.base = {
+		(struct tk_read_base){
+			.clock = &dummy_clock,
+		},
+		(struct tk_read_base){
+			.clock = &dummy_clock,
+		},
+	},
+};
 
 /* flag for if timekeeping is suspended */
 int __read_mostly timekeeping_suspended;
@@ -477,18 +508,6 @@ u64 notrace ktime_get_boot_fast_ns(void)
 }
 EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns);
 
-/* Suspend-time cycles value for halted fast timekeeper. */
-static u64 cycles_at_suspend;
-
-static u64 dummy_clock_read(struct clocksource *cs)
-{
-	return cycles_at_suspend;
-}
-
-static struct clocksource dummy_clock = {
-	.read = dummy_clock_read,
-};
-
 /**
  * halt_fast_timekeeper - Prevent fast timekeeper from accessing clocksource.
  * @tk: Timekeeper to snapshot.
-- 
1.8.5.5

[toc] | [prev] | [next] | [standalone]

#1713520 — Re: [PATCH 1/2 v6] time: Make fast functions return 0 before timekeeping is initialized

FromJohn Stultz <john.stultz@linaro.org>
Date2017-08-17 05:50 +0200
SubjectRe: [PATCH 1/2 v6] time: Make fast functions return 0 before timekeeping is initialized
Message-ID<ufjYK-7yX-19@gated-at.bofh.it>
In reply to#1713050
On Wed, Aug 16, 2017 at 8:17 AM, Prarit Bhargava <prarit@redhat.com> wrote:
> printk timestamps will be extended to include mono and boot time by using
> the fast timekeeping functions ktime_get_mono|boot_fast_ns() functions.
> The functions can return garbage before timekeeping is initialized
> resulting in garbage timestamps.
>
> The fast time functions must return 0 before timekeeping is initialized.
>

This looks reasonable. I can queue it, but you still have feedback to
address on 2/2, so I may wait until that is sorted.

thanks
-john

[toc] | [prev] | [next] | [standalone]

#1713072 — Re: [PATCH 2/2 v6] printk: Add monotonic, boottime, and realtime timestamps

FromMark Salyzyn <salyzyn@android.com>
Date2017-08-16 17:50 +0200
SubjectRe: [PATCH 2/2 v6] printk: Add monotonic, boottime, and realtime timestamps
Message-ID<uf8JY-pO-11@gated-at.bofh.it>
In reply to#1713044
On 08/16/2017 08:17 AM, Prarit Bhargava wrote:
> . . .
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fc47863f629c..f627a9bb97d1 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -576,6 +576,9 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
>   	return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
>   }
>   
> +static u64 printk_set_timestamp(void);
> +static u64 (*printk_get_ts)(void) = printk_set_timestamp;
> +
>   /* insert record into the buffer, discard old ones, update heads */
>   static int log_store(int facility, int level,
>   		     enum log_flags flags, u64 ts_nsec,
> @@ -624,7 +627,7 @@ static int log_store(int facility, int level,
>   	if (ts_nsec > 0)
>   		msg->ts_nsec = ts_nsec;
>   	else
> -		msg->ts_nsec = local_clock();
> +		msg->ts_nsec = printk_get_ts();
>   	memset(log_dict(msg) + dict_len, 0, pad_len);
>   	msg->len = size;
>   
> . . .
> +/**
> + * enum timestamp_sources - Timestamp sources for printk() messages.
> + * @PRINTK_TIME_UNDEFINED: Timestamp undefined.  This option is not selectable
> + * from the configs, and is used as a reference in the code.
> + * @PRINTK_TIME_DISABLE: No time stamp.
> + * @PRINTK_TIME_LOCAL: Local hardware clock timestamp.
> + * @PRINTK_TIME_BOOT: Boottime clock timestamp.
> + * @PRINTK_TIME_MONO: Monotonic clock timestamp.
> + * @PRINTK_TIME_REAL: Realtime clock timestamp.  On 32-bit
> + * systems selecting the real clock printk timestamp may lead to unlikely
> + * situations where a timestamp is wrong because the real time offset is read
> + * without the protection of a sequence lock when printk_get_ts() is set to
> + * printk_get_real_ns().
> + */
> +enum timestamp_sources {
> +	PRINTK_TIME_UNDEFINED = 0,
> +	PRINTK_TIME_DISABLE = 1,
> +	PRINTK_TIME_LOCAL = 2,
> +	PRINTK_TIME_BOOT = 3,
> +	PRINTK_TIME_MONO = 4,
> +	PRINTK_TIME_REAL = 5,
> +};
> +. . .
> +
> +static u64 printk_set_timestamp(void)
> +{
> +	switch (printk_time) {
> +	case PRINTK_TIME_LOCAL:
> +	case PRINTK_TIME_DISABLE:
> +		printk_get_ts = local_clock;
> +		break;
> +	case PRINTK_TIME_BOOT:
> +		printk_get_ts = ktime_get_boot_fast_ns;
> +		break;
> +	case PRINTK_TIME_MONO:
> +		printk_get_ts = ktime_get_mono_fast_ns;
> +		break;
> +	case PRINTK_TIME_REAL:
> +		printk_get_ts = printk_get_real_ns;
> +		break;
> +	}
> +	return printk_get_ts();
> +}
I am really nervous about the default case, despite 
PRINTK_TIME_UNDEFINED being declared impossible. Either set 
printk_get_ts to local_clock for default: (which I prefer), or return 
(printk_get_ts != printk_set_timestamp) ? printk_get_ts() : 0; (which at 
least prevents the infinite loop).

> +
> +static int printk_time_set(const char *val, const struct kernel_param *kp)
> +{
> +	char *param = strstrip((char *)val);
> +	int _printk_time = PRINTK_TIME_UNDEFINED;
> +	int ts;
> +
> +	if (strlen(param) == 1) {
> +		/* Preserve legacy boolean settings */
> +		if ((param[0] == '0') || (param[0] == 'n') ||
> +		    (param[0] == 'N'))
> +			_printk_time = PRINTK_TIME_DISABLE;
> +		if ((param[0] == '1') || (param[0] == 'y') ||
> +		    (param[0] == 'Y'))
> +			_printk_time = PRINTK_TIME_LOCAL;
> +	}
> +	if (_printk_time == PRINTK_TIME_UNDEFINED) {
> +		for (ts = 0; ts < ARRAY_SIZE(timestamp_sources_str); ts++) {
> +			if (!strncmp(timestamp_sources_str[ts], param,
> +				     strlen(param))) {
> +				_printk_time = ts;
> +				break;
> +			}
> +		}
> +	}
> +	if (_printk_time == PRINTK_TIME_UNDEFINED) {
> +		pr_warn("printk: invalid timestamp option %s\n", param);
> +		return -EINVAL;
> +	}
> +
> +	/*
> +	 * Only allow enabling and disabling of the current printk_time
> +	 * setting.  Changing it from one setting to another confuses
> +	 * userspace.
> +	 */
> +	if (printk_time_source == PRINTK_TIME_UNDEFINED)
> +		printk_time_source = _printk_time;
(I've asked this before) Could we add something like #ifndef 
PRINTK_TIME_DEBUG around the following to allow the option to chose for 
those that like to 'play' with the value?
> +	else if ((printk_time_source != _printk_time) &&
> +		 (_printk_time != PRINTK_TIME_DISABLE)) {
> +		pr_warn("printk: timestamp can only be set to 0, disabled, or %s\n",
> +			timestamp_sources_str[printk_time_source]);
> +		return -EINVAL;
> +	}
> +
-- Mark

[toc] | [prev] | [next] | [standalone]

#1713521 — Re: [PATCH 2/2 v6] printk: Add monotonic, boottime, and realtime timestamps

FromJohn Stultz <john.stultz@linaro.org>
Date2017-08-17 05:50 +0200
SubjectRe: [PATCH 2/2 v6] printk: Add monotonic, boottime, and realtime timestamps
Message-ID<ufjYK-7yX-21@gated-at.bofh.it>
In reply to#1713044
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index 98fe715522e8..c303b235a0b1 100644
> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -1,19 +1,61 @@
>  menu "printk and dmesg options"
>
> +choice
> +       prompt "printk default clock timestamp"
> +
> +config PRINTK_TIME_DISABLE
> +       bool "Disabled"
> +       help
> +        Selecting this option disables the time stamps of printk().
> +
> +config PRINTK_TIME_LOCAL
> +       bool "Local Clock"
> +       help
> +         Selecting this option causes the time stamps of printk() to be
> +         stamped with the unadjusted hardware clock.
> +
> +config PRINTK_TIME_BOOT
> +       bool "CLOCK_BOOTTIME"
> +       help
> +         Selecting this option causes the time stamps of printk() to be
> +         stamped with the adjusted boottime clock.
> +
> +config PRINTK_TIME_MONO
> +       bool "CLOCK_MONOTONIC"
> +       help
> +         Selecting this option causes the time stamps of printk() to be
> +         stamped with the adjusted monotonic clock.
> +
> +config PRINTK_TIME_REAL
> +       bool "CLOCK_REALTIME"
> +       help
> +         Selecting this option causes the time stamps of printk() to be
> +         stamped with the adjusted realtime clock.
> +
> +endchoice
> +
>  config PRINTK_TIME
> -       bool "Show timing information on printks"
> +       int "Show timestamp information on printks"

You need to drop the prompt on this, as it ends up with this insane
setup where you chose from the choice list, but then you can go and
set the PRINTK_TIME manually to something else?

So PRINTK_TIME_REAL can be y, but PRINTK_TIME can be 2...  Yuck.

I'm still annoyed enough with this Kconfig/defconfig noise in the
patch that I'm going to take my own shot at it ( hopefully there's a
better way, but likely it will help me understand why it was done this
way :).

thanks
-john

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web