subject:"\[PATCH 2\/2\] printk\: Add boottime and real timestamps"

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-28 Thread Thomas Gleixner

On Fri, 28 Jul 2017, Prarit Bhargava wrote:
> On 07/25/2017 09:00 AM, Peter Zijlstra wrote:
> Thanks for the above change.  I can see that makes the code simpler.
> 
> > Although I must strongly discourage using REALTIME, DST will make
> > untangling your logs an absolute nightmare. I would simply not provide
> > it.
> 
> I understand your concern, however, I've been in situations where REALTIME
> stamping has pointed me in the direction of where a bug was.  Even with the
> complicated logs I think it is worthwhile.

As Mark pointed out. ktime_get_real() and the fast variant return UTC. The
timezone mess plus the DST nonsense are done in user space.

Thanks,

tglx

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-28 Thread Thomas Gleixner

On Fri, 28 Jul 2017, Prarit Bhargava wrote:
> On 07/25/2017 09:00 AM, Peter Zijlstra wrote:
> Thanks for the above change.  I can see that makes the code simpler.
> 
> > Although I must strongly discourage using REALTIME, DST will make
> > untangling your logs an absolute nightmare. I would simply not provide
> > it.
> 
> I understand your concern, however, I've been in situations where REALTIME
> stamping has pointed me in the direction of where a bug was.  Even with the
> complicated logs I think it is worthwhile.

As Mark pointed out. ktime_get_real() and the fast variant return UTC. The
timezone mess plus the DST nonsense are done in user space.

Thanks,

tglx

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-28 Thread Prarit Bhargava



On 07/25/2017 09:00 AM, Peter Zijlstra wrote:
> On Tue, Jul 25, 2017 at 08:17:27AM -0400, Prarit Bhargava wrote:
>> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
>> index 5b1662ec546f..6cd38a25f8ea 100644
>> --- a/lib/Kconfig.debug
>> +++ b/lib/Kconfig.debug
>> @@ -1,8 +1,8 @@
>>  menu "printk and dmesg options"
>>  
>>  config PRINTK_TIME
>> -int "Show timing information on printks (0-1)"
>> -range 0 1
>> +int "Show timing information on printks (0-3)"
>> +range 0 3
>>  default "0"
>>  depends on PRINTK
>>  help
>> @@ -13,7 +13,8 @@ config PRINTK_TIME
>>The timestamp is always recorded internally, and exported
>>to /dev/kmsg. This flag just specifies if the timestamp should
>>be included, not that the timestamp is recorded. 0 disables the
>> -  timestamp and 1 uses the local clock.
>> +  timestamp and 1 uses the local clock, 2 uses the monotonic clock, and
>> +  3 uses real clock.
>>  
>>The behavior is also controlled by the kernel command line
>>parameter printk.time=1. See 
>> Documentation/admin-guide/kernel-parameters.rst
> 
> 
> choice
>   prompt "printk default clock"
>   default PRIMTK_TIME_DISABLE
>   help
>goes here
> 
>   config PRINTK_TIME_DISABLE
>   bool "Disabled"
>   help
>goes here
> 
>   config PRINTK_TIME_LOCAL
>   bool "local clock"
>   help
>goes here
> 
>   config PRINTK_TIME_MONO
>   bool "CLOCK_MONOTONIC"
>   help
>goes here
> 
>   config PRINTK_TIME_REAL
>   bool "CLOCK_REALTIME"
>   help
>goes here
> 
> endchoice
> 
> config PRINTK_TIME
>   int
>   default 0 if PRINTK_TIME_DISABLE
>   default 1 if PRINTK_TIME_LOCAL
>   default 2 if PRINTK_TIME_MONO
>   default 3 if PRINTK_TIME_REAL
> 
> 

Thanks for the above change.  I can see that makes the code simpler.

> Although I must strongly discourage using REALTIME, DST will make
> untangling your logs an absolute nightmare. I would simply not provide
> it.

I understand your concern, however, I've been in situations where REALTIME
stamping has pointed me in the direction of where a bug was.  Even with the
complicated logs I think it is worthwhile.

P.

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-28 Thread Prarit Bhargava



On 07/25/2017 09:00 AM, Peter Zijlstra wrote:
> On Tue, Jul 25, 2017 at 08:17:27AM -0400, Prarit Bhargava wrote:
>> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
>> index 5b1662ec546f..6cd38a25f8ea 100644
>> --- a/lib/Kconfig.debug
>> +++ b/lib/Kconfig.debug
>> @@ -1,8 +1,8 @@
>>  menu "printk and dmesg options"
>>  
>>  config PRINTK_TIME
>> -int "Show timing information on printks (0-1)"
>> -range 0 1
>> +int "Show timing information on printks (0-3)"
>> +range 0 3
>>  default "0"
>>  depends on PRINTK
>>  help
>> @@ -13,7 +13,8 @@ config PRINTK_TIME
>>The timestamp is always recorded internally, and exported
>>to /dev/kmsg. This flag just specifies if the timestamp should
>>be included, not that the timestamp is recorded. 0 disables the
>> -  timestamp and 1 uses the local clock.
>> +  timestamp and 1 uses the local clock, 2 uses the monotonic clock, and
>> +  3 uses real clock.
>>  
>>The behavior is also controlled by the kernel command line
>>parameter printk.time=1. See 
>> Documentation/admin-guide/kernel-parameters.rst
> 
> 
> choice
>   prompt "printk default clock"
>   default PRIMTK_TIME_DISABLE
>   help
>goes here
> 
>   config PRINTK_TIME_DISABLE
>   bool "Disabled"
>   help
>goes here
> 
>   config PRINTK_TIME_LOCAL
>   bool "local clock"
>   help
>goes here
> 
>   config PRINTK_TIME_MONO
>   bool "CLOCK_MONOTONIC"
>   help
>goes here
> 
>   config PRINTK_TIME_REAL
>   bool "CLOCK_REALTIME"
>   help
>goes here
> 
> endchoice
> 
> config PRINTK_TIME
>   int
>   default 0 if PRINTK_TIME_DISABLE
>   default 1 if PRINTK_TIME_LOCAL
>   default 2 if PRINTK_TIME_MONO
>   default 3 if PRINTK_TIME_REAL
> 
> 

Thanks for the above change.  I can see that makes the code simpler.

> Although I must strongly discourage using REALTIME, DST will make
> untangling your logs an absolute nightmare. I would simply not provide
> it.

I understand your concern, however, I've been in situations where REALTIME
stamping has pointed me in the direction of where a bug was.  Even with the
complicated logs I think it is worthwhile.

P.

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-26 Thread kbuild test robot

Hi Prarit,

[auto build test ERROR on linus/master]
[also build test ERROR on v4.13-rc2]
[cannot apply to next-20170726]
[if your patch is applied to the wrong git tree, please drop us a note to help 
improve the system]

url:
https://github.com/0day-ci/linux/commits/Prarit-Bhargava/printk-allow-different-timestamps-for-printk-time/20170727-104148
config: i386-tinyconfig (attached as .config)
compiler: gcc-6 (Debian 6.2.0-3) 6.2.0 20160901
reproduce:
# save the attached .config to linux build tree
make ARCH=i386 

All errors (new ones prefixed by >>):

   kernel/printk/printk.c: In function 'printk_late_init':
>> kernel/printk/printk.c:2746:6: error: 'printk_time_setting' undeclared 
>> (first use in this function)
 if (printk_time_setting == 0)
 ^~~
   kernel/printk/printk.c:2746:6: note: each undeclared identifier is reported 
only once for each function it appears in
>> kernel/printk/printk.c:2747:25: error: 'printk_time' undeclared (first use 
>> in this function)
  printk_time_setting = printk_time;
^~~

vim +/printk_time_setting +2746 kernel/printk/printk.c

  2724  
  2725  /*
  2726   * Some boot consoles access data that is in the init section and which 
will
  2727   * be discarded after the initcalls have been run. To make sure that no 
code
  2728   * will access this data, unregister the boot consoles in a late 
initcall.
  2729   *
  2730   * If for some reason, such as deferred probe or the driver being a 
loadable
  2731   * module, the real console hasn't registered yet at this point, there 
will
  2732   * be a brief interval in which no messages are logged to the console, 
which
  2733   * makes it difficult to diagnose problems that occur during this time.
  2734   *
  2735   * To mitigate this problem somewhat, only unregister consoles whose 
memory
  2736   * intersects with the init section. Note that code exists elsewhere to 
get
  2737   * rid of the boot console as soon as the proper console shows up, so 
there
  2738   * won't be side-effects from postponing the removal.
  2739   */
  2740  static int __init printk_late_init(void)
  2741  {
  2742  struct console *con;
  2743  int ret;
  2744  
  2745  /* initialize printk_time settings */
> 2746  if (printk_time_setting == 0)
> 2747  printk_time_setting = printk_time;
  2748  
  2749  for_each_console(con) {
  2750  if (!keep_bootcon && con->flags & CON_BOOT) {
  2751  /*
  2752   * Make sure to unregister boot consoles whose 
data
  2753   * resides in the init section before the init 
section
  2754   * is discarded. Boot consoles whose data will 
stick
  2755   * around will automatically be unregistered 
when the
  2756   * proper console replaces them.
  2757   */
  2758  if (init_section_intersects(con, sizeof(*con)))
  2759  unregister_console(con);
  2760  }
  2761  }
  2762  ret = cpuhp_setup_state_nocalls(CPUHP_PRINTK_DEAD, 
"printk:dead", NULL,
  2763  console_cpu_notify);
  2764  WARN_ON(ret < 0);
  2765  ret = cpuhp_setup_state_nocalls(CPUHP_AP_ONLINE_DYN, 
"printk:online",
  2766  console_cpu_notify, NULL);
  2767  WARN_ON(ret < 0);
  2768  return 0;
  2769  }
  2770  late_initcall(printk_late_init);
  2771  

---
0-DAY kernel test infrastructureOpen Source Technology Center
https://lists.01.org/pipermail/kbuild-all   Intel Corporation


.config.gz
Description: application/gzip

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-26 Thread kbuild test robot

Hi Prarit,

[auto build test ERROR on linus/master]
[also build test ERROR on v4.13-rc2]
[cannot apply to next-20170726]
[if your patch is applied to the wrong git tree, please drop us a note to help 
improve the system]

url:
https://github.com/0day-ci/linux/commits/Prarit-Bhargava/printk-allow-different-timestamps-for-printk-time/20170727-104148
config: i386-tinyconfig (attached as .config)
compiler: gcc-6 (Debian 6.2.0-3) 6.2.0 20160901
reproduce:
# save the attached .config to linux build tree
make ARCH=i386 

All errors (new ones prefixed by >>):

   kernel/printk/printk.c: In function 'printk_late_init':
>> kernel/printk/printk.c:2746:6: error: 'printk_time_setting' undeclared 
>> (first use in this function)
 if (printk_time_setting == 0)
 ^~~
   kernel/printk/printk.c:2746:6: note: each undeclared identifier is reported 
only once for each function it appears in
>> kernel/printk/printk.c:2747:25: error: 'printk_time' undeclared (first use 
>> in this function)
  printk_time_setting = printk_time;
^~~

vim +/printk_time_setting +2746 kernel/printk/printk.c

  2724  
  2725  /*
  2726   * Some boot consoles access data that is in the init section and which 
will
  2727   * be discarded after the initcalls have been run. To make sure that no 
code
  2728   * will access this data, unregister the boot consoles in a late 
initcall.
  2729   *
  2730   * If for some reason, such as deferred probe or the driver being a 
loadable
  2731   * module, the real console hasn't registered yet at this point, there 
will
  2732   * be a brief interval in which no messages are logged to the console, 
which
  2733   * makes it difficult to diagnose problems that occur during this time.
  2734   *
  2735   * To mitigate this problem somewhat, only unregister consoles whose 
memory
  2736   * intersects with the init section. Note that code exists elsewhere to 
get
  2737   * rid of the boot console as soon as the proper console shows up, so 
there
  2738   * won't be side-effects from postponing the removal.
  2739   */
  2740  static int __init printk_late_init(void)
  2741  {
  2742  struct console *con;
  2743  int ret;
  2744  
  2745  /* initialize printk_time settings */
> 2746  if (printk_time_setting == 0)
> 2747  printk_time_setting = printk_time;
  2748  
  2749  for_each_console(con) {
  2750  if (!keep_bootcon && con->flags & CON_BOOT) {
  2751  /*
  2752   * Make sure to unregister boot consoles whose 
data
  2753   * resides in the init section before the init 
section
  2754   * is discarded. Boot consoles whose data will 
stick
  2755   * around will automatically be unregistered 
when the
  2756   * proper console replaces them.
  2757   */
  2758  if (init_section_intersects(con, sizeof(*con)))
  2759  unregister_console(con);
  2760  }
  2761  }
  2762  ret = cpuhp_setup_state_nocalls(CPUHP_PRINTK_DEAD, 
"printk:dead", NULL,
  2763  console_cpu_notify);
  2764  WARN_ON(ret < 0);
  2765  ret = cpuhp_setup_state_nocalls(CPUHP_AP_ONLINE_DYN, 
"printk:online",
  2766  console_cpu_notify, NULL);
  2767  WARN_ON(ret < 0);
  2768  return 0;
  2769  }
  2770  late_initcall(printk_late_init);
  2771  

---
0-DAY kernel test infrastructureOpen Source Technology Center
https://lists.01.org/pipermail/kbuild-all   Intel Corporation


.config.gz
Description: application/gzip

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-25 Thread Mark Salyzyn


On 07/25/2017 06:00 AM, Peter Zijlstra wrote:

On Tue, Jul 25, 2017 at 08:17:27AM -0400, Prarit Bhargava wrote:

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 5b1662ec546f..6cd38a25f8ea 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -1,8 +1,8 @@
  menu "printk and dmesg options"
  
  config PRINTK_TIME

-   int "Show timing information on printks (0-1)"
-   range 0 1
+   int "Show timing information on printks (0-3)"
+   range 0 3
default "0"
depends on PRINTK
help
@@ -13,7 +13,8 @@ config PRINTK_TIME
  The timestamp is always recorded internally, and exported
  to /dev/kmsg. This flag just specifies if the timestamp should
  be included, not that the timestamp is recorded. 0 disables the
- timestamp and 1 uses the local clock.
+ timestamp and 1 uses the local clock, 2 uses the monotonic clock, and
+ 3 uses real clock.
  
  	  The behavior is also controlled by the kernel command line

  parameter printk.time=1. See 
Documentation/admin-guide/kernel-parameters.rst


choice
prompt "printk default clock"
default PRIMTK_TIME_DISABLE
help
 goes here

config PRINTK_TIME_DISABLE
bool "Disabled"
help
 goes here

config PRINTK_TIME_LOCAL
bool "local clock"
help
 goes here

config PRINTK_TIME_MONO
bool "CLOCK_MONOTONIC"
help
 goes here

config PRINTK_TIME_REAL
bool "CLOCK_REALTIME"
help
 goes here

endchoice

config PRINTK_TIME
int
default 0 if PRINTK_TIME_DISABLE
default 1 if PRINTK_TIME_LOCAL
default 2 if PRINTK_TIME_MONO
default 3 if PRINTK_TIME_REAL


Although I must strongly discourage using REALTIME, DST will make
untangling your logs an absolute nightmare. I would simply not provide
it.


I agree with using select, ensures only valid values are landed. It does 
mean that CONFIG_PRINTK_TIME in-effect gets deprecated.


REALTIME is always UTC in the kernel.

What about BOOTTIME?

-- Mark

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-25 Thread Mark Salyzyn


On 07/25/2017 06:00 AM, Peter Zijlstra wrote:

On Tue, Jul 25, 2017 at 08:17:27AM -0400, Prarit Bhargava wrote:

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 5b1662ec546f..6cd38a25f8ea 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -1,8 +1,8 @@
  menu "printk and dmesg options"
  
  config PRINTK_TIME

-   int "Show timing information on printks (0-1)"
-   range 0 1
+   int "Show timing information on printks (0-3)"
+   range 0 3
default "0"
depends on PRINTK
help
@@ -13,7 +13,8 @@ config PRINTK_TIME
  The timestamp is always recorded internally, and exported
  to /dev/kmsg. This flag just specifies if the timestamp should
  be included, not that the timestamp is recorded. 0 disables the
- timestamp and 1 uses the local clock.
+ timestamp and 1 uses the local clock, 2 uses the monotonic clock, and
+ 3 uses real clock.
  
  	  The behavior is also controlled by the kernel command line

  parameter printk.time=1. See 
Documentation/admin-guide/kernel-parameters.rst


choice
prompt "printk default clock"
default PRIMTK_TIME_DISABLE
help
 goes here

config PRINTK_TIME_DISABLE
bool "Disabled"
help
 goes here

config PRINTK_TIME_LOCAL
bool "local clock"
help
 goes here

config PRINTK_TIME_MONO
bool "CLOCK_MONOTONIC"
help
 goes here

config PRINTK_TIME_REAL
bool "CLOCK_REALTIME"
help
 goes here

endchoice

config PRINTK_TIME
int
default 0 if PRINTK_TIME_DISABLE
default 1 if PRINTK_TIME_LOCAL
default 2 if PRINTK_TIME_MONO
default 3 if PRINTK_TIME_REAL


Although I must strongly discourage using REALTIME, DST will make
untangling your logs an absolute nightmare. I would simply not provide
it.


I agree with using select, ensures only valid values are landed. It does 
mean that CONFIG_PRINTK_TIME in-effect gets deprecated.


REALTIME is always UTC in the kernel.

What about BOOTTIME?

-- Mark

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-25 Thread Peter Zijlstra

On Tue, Jul 25, 2017 at 08:17:27AM -0400, Prarit Bhargava wrote:
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index 5b1662ec546f..6cd38a25f8ea 100644
> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -1,8 +1,8 @@
>  menu "printk and dmesg options"
>  
>  config PRINTK_TIME
> - int "Show timing information on printks (0-1)"
> - range 0 1
> + int "Show timing information on printks (0-3)"
> + range 0 3
>   default "0"
>   depends on PRINTK
>   help
> @@ -13,7 +13,8 @@ config PRINTK_TIME
> The timestamp is always recorded internally, and exported
> to /dev/kmsg. This flag just specifies if the timestamp should
> be included, not that the timestamp is recorded. 0 disables the
> -   timestamp and 1 uses the local clock.
> +   timestamp and 1 uses the local clock, 2 uses the monotonic clock, and
> +   3 uses real clock.
>  
> The behavior is also controlled by the kernel command line
> parameter printk.time=1. See 
> Documentation/admin-guide/kernel-parameters.rst


choice
prompt "printk default clock"
default PRIMTK_TIME_DISABLE
help
 goes here

config PRINTK_TIME_DISABLE
bool "Disabled"
help
 goes here

config PRINTK_TIME_LOCAL
bool "local clock"
help
 goes here

config PRINTK_TIME_MONO
bool "CLOCK_MONOTONIC"
help
 goes here

config PRINTK_TIME_REAL
bool "CLOCK_REALTIME"
help
 goes here

endchoice

config PRINTK_TIME
int
default 0 if PRINTK_TIME_DISABLE
default 1 if PRINTK_TIME_LOCAL
default 2 if PRINTK_TIME_MONO
default 3 if PRINTK_TIME_REAL


Although I must strongly discourage using REALTIME, DST will make
untangling your logs an absolute nightmare. I would simply not provide
it.

Re: [PATCH 2/2] printk: Add boottime and real timestamps

2017-07-25 Thread Peter Zijlstra

On Tue, Jul 25, 2017 at 08:17:27AM -0400, Prarit Bhargava wrote:
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index 5b1662ec546f..6cd38a25f8ea 100644
> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -1,8 +1,8 @@
>  menu "printk and dmesg options"
>  
>  config PRINTK_TIME
> - int "Show timing information on printks (0-1)"
> - range 0 1
> + int "Show timing information on printks (0-3)"
> + range 0 3
>   default "0"
>   depends on PRINTK
>   help
> @@ -13,7 +13,8 @@ config PRINTK_TIME
> The timestamp is always recorded internally, and exported
> to /dev/kmsg. This flag just specifies if the timestamp should
> be included, not that the timestamp is recorded. 0 disables the
> -   timestamp and 1 uses the local clock.
> +   timestamp and 1 uses the local clock, 2 uses the monotonic clock, and
> +   3 uses real clock.
>  
> The behavior is also controlled by the kernel command line
> parameter printk.time=1. See 
> Documentation/admin-guide/kernel-parameters.rst


choice
prompt "printk default clock"
default PRIMTK_TIME_DISABLE
help
 goes here

config PRINTK_TIME_DISABLE
bool "Disabled"
help
 goes here

config PRINTK_TIME_LOCAL
bool "local clock"
help
 goes here

config PRINTK_TIME_MONO
bool "CLOCK_MONOTONIC"
help
 goes here

config PRINTK_TIME_REAL
bool "CLOCK_REALTIME"
help
 goes here

endchoice

config PRINTK_TIME
int
default 0 if PRINTK_TIME_DISABLE
default 1 if PRINTK_TIME_LOCAL
default 2 if PRINTK_TIME_MONO
default 3 if PRINTK_TIME_REAL


Although I must strongly discourage using REALTIME, DST will make
untangling your logs an absolute nightmare. I would simply not provide
it.

[PATCH 2/2] printk: Add boottime and real timestamps

2017-07-25 Thread Prarit Bhargava

printk.time=1/CONFIG_PRINTK_TIME=Y timestamps printks with an unmodified
hardware clock timestamp.  This clock loses time each day making it
difficult to determine when an issue has occurred in the kernel log.

Modify printk.time to output local, monotonic, or a real timestamp.
Modify the output of /sys/module/printk/parameters/time to output the type
of clock 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().

Signed-off-by: Prarit Bhargava 
Cc: Mark Salyzyn 
Cc: Jonathan Corbet 
Cc: Petr Mladek 
Cc: Sergey Senozhatsky 
Cc: Steven Rostedt 
Cc: John Stultz 
Cc: Thomas Gleixner 
Cc: Stephen Boyd 
Cc: Andrew Morton 
Cc: Greg Kroah-Hartman 
Cc: "Paul E. McKenney" 
Cc: Christoffer Dall 
Cc: Deepa Dinamani 
Cc: Ingo Molnar 
Cc: Joel Fernandes 
Cc: Kees Cook 
Cc: Peter Zijlstra 
Cc: Geert Uytterhoeven 
Cc: "Luis R. Rodriguez" 
Cc: Nicholas Piggin 
Cc: "Jason A. Donenfeld" 
Cc: Olof Johansson 
Cc: "Theodore Ts'o" 
Cc: Josh Poimboeuf 
Cc: linux-...@vger.kernel.org


---
 Documentation/admin-guide/kernel-parameters.txt |  6 +-
 include/linux/timekeeping.h |  1 +
 kernel/printk/printk.c  | 77 +
 kernel/time/timekeeping.c   | 14 +
 lib/Kconfig.debug   |  7 ++-
 5 files changed, 89 insertions(+), 16 deletions(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt 
b/Documentation/admin-guide/kernel-parameters.txt
index c3b14abf9da4..c03240d057b1 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3188,8 +3188,10 @@
ratelimit - ratelimit the logging
Default: ratelimit
 
-   printk.time=Show timing data prefixed to each printk message line
-   Format:   (1/Y/y=enable, 0/N/n=disable)
+   printk.time=Show timestamp prefixed to each printk message line
+   Format: 
+   (0/N/n = disable, 1/Y/y = local/unadjusted HW,
+2 = monotonic, 3 = real)
 
processor.max_cstate=   [HW,ACPI]
Limit processor to maximum C-state
diff --git a/include/linux/timekeeping.h b/include/linux/timekeeping.h
index ddc229ff6d1e..adb84af42deb 100644
--- a/include/linux/timekeeping.h
+++ b/include/linux/timekeeping.h
@@ -239,6 +239,7 @@ static inline u64 ktime_get_raw_ns(void)
 extern u64 ktime_get_mono_fast_ns(void);
 extern u64 ktime_get_raw_fast_ns(void);
 extern u64 ktime_get_boot_fast_ns(void);
+extern u64 ktime_get_log_ts(u64 *offset_real);
 
 /*
  * Timespec interfaces utilizing the ktime based ones
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 26cf6cadd267..35536369a56d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -576,6 +576,8 @@ 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_get_ts(void);
+
 /* 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 +626,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;
 
@@ -1203,26 +1205,60 @@ static inline void boot_delay_msec(int level)
 #endif
 
 static int printk_time = CONFIG_PRINTK_TIME;
+static int printk_time_setting; /* initial setting */
 
+/*
+ * 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() below.
+ */
 static int printk_time_set(const char *val, const struct kernel_param *kp)
 {
char *param = strstrip((char *)val);
+   int _printk_time;
 
if (strlen(param) != 1)

[PATCH 2/2] printk: Add boottime and real timestamps

2017-07-25 Thread Prarit Bhargava

printk.time=1/CONFIG_PRINTK_TIME=Y timestamps printks with an unmodified
hardware clock timestamp.  This clock loses time each day making it
difficult to determine when an issue has occurred in the kernel log.

Modify printk.time to output local, monotonic, or a real timestamp.
Modify the output of /sys/module/printk/parameters/time to output the type
of clock 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().

Signed-off-by: Prarit Bhargava 
Cc: Mark Salyzyn 
Cc: Jonathan Corbet 
Cc: Petr Mladek 
Cc: Sergey Senozhatsky 
Cc: Steven Rostedt 
Cc: John Stultz 
Cc: Thomas Gleixner 
Cc: Stephen Boyd 
Cc: Andrew Morton 
Cc: Greg Kroah-Hartman 
Cc: "Paul E. McKenney" 
Cc: Christoffer Dall 
Cc: Deepa Dinamani 
Cc: Ingo Molnar 
Cc: Joel Fernandes 
Cc: Kees Cook 
Cc: Peter Zijlstra 
Cc: Geert Uytterhoeven 
Cc: "Luis R. Rodriguez" 
Cc: Nicholas Piggin 
Cc: "Jason A. Donenfeld" 
Cc: Olof Johansson 
Cc: "Theodore Ts'o" 
Cc: Josh Poimboeuf 
Cc: linux-...@vger.kernel.org


---
 Documentation/admin-guide/kernel-parameters.txt |  6 +-
 include/linux/timekeeping.h |  1 +
 kernel/printk/printk.c  | 77 +
 kernel/time/timekeeping.c   | 14 +
 lib/Kconfig.debug   |  7 ++-
 5 files changed, 89 insertions(+), 16 deletions(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt 
b/Documentation/admin-guide/kernel-parameters.txt
index c3b14abf9da4..c03240d057b1 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3188,8 +3188,10 @@
ratelimit - ratelimit the logging
Default: ratelimit
 
-   printk.time=Show timing data prefixed to each printk message line
-   Format:   (1/Y/y=enable, 0/N/n=disable)
+   printk.time=Show timestamp prefixed to each printk message line
+   Format: 
+   (0/N/n = disable, 1/Y/y = local/unadjusted HW,
+2 = monotonic, 3 = real)
 
processor.max_cstate=   [HW,ACPI]
Limit processor to maximum C-state
diff --git a/include/linux/timekeeping.h b/include/linux/timekeeping.h
index ddc229ff6d1e..adb84af42deb 100644
--- a/include/linux/timekeeping.h
+++ b/include/linux/timekeeping.h
@@ -239,6 +239,7 @@ static inline u64 ktime_get_raw_ns(void)
 extern u64 ktime_get_mono_fast_ns(void);
 extern u64 ktime_get_raw_fast_ns(void);
 extern u64 ktime_get_boot_fast_ns(void);
+extern u64 ktime_get_log_ts(u64 *offset_real);
 
 /*
  * Timespec interfaces utilizing the ktime based ones
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 26cf6cadd267..35536369a56d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -576,6 +576,8 @@ 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_get_ts(void);
+
 /* 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 +626,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;
 
@@ -1203,26 +1205,60 @@ static inline void boot_delay_msec(int level)
 #endif
 
 static int printk_time = CONFIG_PRINTK_TIME;
+static int printk_time_setting; /* initial setting */
 
+/*
+ * 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() below.
+ */
 static int printk_time_set(const char *val, const struct kernel_param *kp)
 {
char *param = strstrip((char *)val);
+   int _printk_time;
 
if (strlen(param) != 1)
return -EINVAL;
 
-   if (!strncmp("0", param, 1) || !strncmp("n", param, 1) ||
-   !strncmp("N", param, 1)) {
-   printk_time = 0;
-   } else if (!strncmp("1", param, 1) || !strncmp("y", param, 1) ||
-  !strncmp("Y", param, 1)) {
-   printk_time = 1;
-   } else {
-   pr_warn("printk: invalid timestamp value %s.\n", param);
+   switch (param[0]) {
+   case '0':
+   case 'n':
+   case 'N':
+   _printk_time = 0; /*

Re: [PATCH 2/2] printk: Add boottime and real timestamps

Re: [PATCH 2/2] printk: Add boottime and real timestamps

Re: [PATCH 2/2] printk: Add boottime and real timestamps

Re: [PATCH 2/2] printk: Add boottime and real timestamps

Re: [PATCH 2/2] printk: Add boottime and real timestamps

Re: [PATCH 2/2] printk: Add boottime and real timestamps

Re: [PATCH 2/2] printk: Add boottime and real timestamps

Re: [PATCH 2/2] printk: Add boottime and real timestamps

Re: [PATCH 2/2] printk: Add boottime and real timestamps

Re: [PATCH 2/2] printk: Add boottime and real timestamps

[PATCH 2/2] printk: Add boottime and real timestamps

[PATCH 2/2] printk: Add boottime and real timestamps

12 matches

Site Navigation

Mail list logo

Footer information