How to enable time stamps for logs in 'dmesg' on Gaia and SecurePlatform

Symptoms

• Logs that are written into dmesg kernel ring buffer do not have timestamps.

Cause

Default configuration.

Solution

Table of Contents:

• Background
• Enable time stamps at runtime ( on-the-fly)
• Enable time stamps at boot time ( permanently)
• Time stamp conversion algorithm

 

Background

For troubleshooting purposes, it can be helpful to have time stamps for logs that are written into dmesg kernel ring buffer.

Important Note: The time stamps are printed in "seconds since boot". The system uptime can be helpful to calculate an absolute time stamp if needed (run the 'uptime' command).

 

Enable time stamps at runtime (on-the-fly)

1. Run this command in Expert mode: 
   
   [Expert@HostName]# echo 1 > /sys/module/printk/parameters/printk_time 
   
   
2. Check whether the logs are written with time stamps: 
   
   
   1. Send a test message:
      
      [Expert@HostName]# echo "hello world" > /dev/kmsg 
      
      
   2. Check the dmesg kernel ring buffer:
      
      [Expert@HostName]# dmesg | tail -n 5 
      
      Should see an output similar to this:

      ..............
      [196149.728085] hello world
      

 

Enable time stamps at boot time (permanently)

The relevant command can be added to the existing Linux start-up script /etc/rc.d/rc.local.
As a best practice, it is recommended to create a separate start-up script /etc/rc.d/rc.local.user to separate Linux OS initialization commands from user-defined commands.

1. Verify that /etc/rc.d/rc.local start-up script contains the call for /etc/rc.d/rc.local.user script: 
   
   Run the following command in Expert mode: 
   
   [Expert@HostName]# grep -C 1 'rc.local.user' /etc/rc.d/rc.local 
   
   Should get the following output:

   if [ -f /etc/rc.d/rc.local.user ]; then
    . /etc/rc.d/rc.local.user
   fi
   

2. Create the start-up script for user-defined commands: 
   
   [Expert@HostName]# touch /etc/rc.d/rc.local.user 
   
   
3. Add these lines into the /etc/rc.d/rc.local.user script:

   
   #!/bin/sh
   #
   # enable time stamps in dmesg
   echo 1 > /sys/module/printk/parameters/printk_time
   
   

4. Assign the relevant permissions to the script file: 
   
   [Expert@HostName]# chmod -v u=rwx,g=rx,o=rx /etc/rc.d/rc.local.user 
   
   
5. Reboot the machine. 
   
   Note: Time stamps will be enabled after the kernel has correctly booted up. 
   
   
6. Check whether the logs are written with time stamps: 
   
   [Expert@HostName]# dmesg | tail -n 5 
   
   Should see an output similar to this:

   ..............
   [196149.728085] hello world
   

 

Time stamp conversion algorithm

Important Note: The time stamps are printed in "seconds since boot" (this is the way the kernel is programmed to print the time stamps, and it can not be changed to print the time stamps in a human readable format). The system uptime can be helpful to calculate an absolute time stamp if needed (run the 'uptime' command).

The algorithm below for converting the printed time stamps to a human readable format is demonstrated on the example given above:
[196149.728085] hello world

1. Take the log's time stamp in seconds: 
   
   196149.728085 seconds (round the number down/up if needed) 
   
   
2. Divide the time stamp in seconds by 60 to get the total amount of minutes: 
   
   196150 : 60 = 3269.1667 minutes (round the number down/up if needed) 
   
   
3. Divide the time stamp in minutes by 60 to get the total amount of hours: 
   
   3269.1667 : 60 = 54.486111666666666666666666666667 hours 
   
   
4. Break the decimal number into 2 parts: 
   
   54.486111666666666666666666666667 hours = (54 hours) + (0.486111666666666666666666666667 decimal hours) 
   
   
5. Use the time conversion charts below to convert decimal hours to minutes: 
   
   0.486111666666666666666666666667 decimal hours ~ 0.48 decimal hours ~ 29 minutes 
   
   Note: For more precise conversion (down to seconds), you can use various time converters available on the Internet. Just search for 'convert decimal time' in any search engine. 
   
   
6. Hence, we get that the log was created this amount of time since boot: 
   
   196149.728085 seconds ~ 54 hours 29 minutes 
   
   
7. Check the current system's uptime: 
   
   [Expert@HostName]# uptime 
   
   
8. To get the log's real time stamp, subtract the log's time stamp in dmesg kernel ring buffer from the current system's uptime.

 

Time conversion chart (Decimal Hours --> Minutes)

Hour/100	Minutes		Hour/100	Minutes		Hour/100	Minutes		Hour/100	Minutes
0.01	1		0.26	16		0.51	31		0.76	46
0.02	1		0.27	16		0.52	31		0.77	46
0.03	2		0.28	17		0.53	32		0.78	47
0.04	2		0.29	17		0.54	32		0.79	47
0.05	3		0.30	18		0.55	33		0.80	48
0.06	4		0.31	19		0.56	34		0.81	49
0.07	4		0.32	19		0.57	34		0.82	49
0.08	5		0.33	20		0.58	35		0.83	50
0.09	5		0.34	20		0.59	35		0.84	50
0.10	6		0.35	21		0.60	36		0.85	51
0.11	7		0.36	22		0.61	37		0.86	52
0.12	7		0.37	22		0.62	37		0.87	52
0.13	8		0.38	23		0.63	38		0.88	53
0.14	8		0.39	23		0.64	38		0.89	53
0.15	9		0.40	24		0.65	39		0.90	54
0.16	10		0.41	25		0.66	40		0.91	55
0.17	10		0.42	25		0.67	40		0.92	55
0.18	11		0.43	26		0.68	41		0.93	56
0.19	11		0.44	26		0.69	41		0.94	56
0.20	12		0.45	27		0.70	42		0.95	57
0.21	13		0.46	28		0.71	43		0.96	58
0.22	13		0.47	28		0.72	43		0.97	58
0.23	14		0.48	29		0.73	44		0.98	59
0.24	14		0.49	29		0.74	44		0.99	59
0.25	15		0.50	30		0.75	45		1.00	60

Time conversion chart (Minutes --> Decimal Hours)

Minutes	Hours/100		Minutes	Hours/100		Minutes	Hours/100		Minutes	Hours/100
1	0.02		16	0.27		31	0.52		46	0.77
2	0.03		17	0.28		32	0.53		47	0.78
3	0.05		18	0.30		33	0.55		48	0.80
4	0.07		19	0.32		34	0.57		49	0.82
5	0.08		20	0.33		35	0.58		50	0.84
6	0.10		21	0.35		36	0.60		51	0.85
7	0.12		22	0.37		37	0.62		52	0.87
8	0.13		23	0.38		38	0.63		53	0.89
9	0.15		24	0.40		39	0.65		54	0.90
10	0.17		25	0.42		40	0.67		55	0.92
11	0.18		26	0.43		41	0.68		56	0.94
12	0.20		27	0.45		42	0.70		57	0.95
13	0.22		28	0.47		43	0.72		58	0.97
14	0.23		29	0.48		44	0.73		59	0.99
15	0.25		30	0.50		45	0.75		60	1.00