Re: [PATCH v4] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava <prarit@redhat.com>]

On 08/07/2017 12:52 PM, John Stultz wrote:
> On Mon, Aug 7, 2017 at 8:52 AM, Prarit Bhargava <prarit@redhat.com> wrote:
>> 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.
>>
>> Make printk output different timestampes by adding options for no
>> timestamp, the local hardware clock, the monotonic clock, the boottime
>> clock, and the real clock.  Allow a user to pick one of the clocks by
>> using the printk.time kernel parameter.  Output the type of clock in
>> /sys/module/printk/parameters/time so userspace programs can interpret the
>> timestamp.
>>
>> Real clock & 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 in the call to
>> ktime_get_log_ts() in printk_get_ts().
>>
>> v2: Use peterz's suggested Kconfig options.  Merge patchset together.
>> Fix i386 !CONFIG_PRINTK builds.
>>
>> v3: Fixed x86_64_defconfig. Added printk_time_type enum and
>> printk_time_str for better output. Added BOOTTIME clock functionality.
>>
>> v4: Fix messages, add additional printk.time options, and fix configs.
>>
>> 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
>> ---
>>  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 +-
> 
> Still not quite following why you're updating all the defconfigs. I'd
> make sure the Kconfig default settings are right, and leave updating
> the defconfig to arch/device maintainers. It adds a lot of noise to
> the patch.

Hmm ... I thought it was up to the patch submitter to make sure that
'make defconfig' still worked?  Are you sure I can leave that broken?

/me *really* doesn't want to get yelled at by every arch maintainer.

> 
> 
>> +u64 ktime_get_real_log_ts(u64 *offset_real)
>> +{
>> +       *offset_real = ktime_to_ns(tk_core.timekeeper.offs_real);
>> +
>> +       if (timekeeping_active)
>> +               return ktime_get_mono_fast_ns();
>> +       else
>> +               return local_clock();
>> +}
>> +
>> +u64 ktime_get_boot_log_ts(void)
>> +{
>> +       if (timekeeping_active)
>> +               return ktime_get_boot_fast_ns();
>> +       else
>> +               return local_clock();
>> +}
> 
> This feels a little tacked on and duplicative.  I'd suggest having one
> function that returns the offset_real and offset_boot or have a
> separate get_mono_log_ts() so its at least consistent.   

I have a better suggestion that I was toying with -- exporting
timekeeping_active and using the existing ktime_get_mono|boot|real|_fast_ns()
functions with a function pointer would simplify this code.

> Additionally,
> in the commit message, you call out the lack of locking between
> grabing the offs_real and calling get_mono_fast_ns(), but I worry it
> may be particularly problematic on 32bit systems, and you don't have
> any notes in the actual code about it (it looks like an oversight).
> 

I was told to move that comment to the kdoc description by Luis R. Rodriguez.

> Also, when timekeeping_active flips over, and we change from local
> clock to the specified clock, do we see a discontinuity in the log? I
> know folks use to gripe about that back in the day.
> 

I have tested this across many systems and haven't seen a discontinunity
yet.  I've done both large and small cpu footprint systems and haven't seen
anything like that.

P.


> thanks
> -john
>