Show timestamped kernel log buffer (tslog)

The tslog program prints the kernel message buffer (output of the crash 'log' command) with each log entry prepended by its timestamp in human-readable form. Time conversion is performed according to the current TZ setting, so this should be set to match the time zone of the system where the vmcore was generated.

This is similar to the functionality provided by crash's 'log -T' command; however, 'log -T' timestamps may be inaccurate on vmcores with more than a small amount of uptime. Specifically, they are accurate at boot time but become less accurate later in the log. This happens because printk() stores the log entry timestamp based on a call to local_clock(), which provides the raw time in the local CPU, which is not adjusted by NTP. As such, inaccuracy tends to accumulate as the clock drifts over time.

The tslog command attempts to work around this by computing the boot time using the same method that crash does (crash time minus uptime) as well as a scale factor for the time discrepancy equal to (uptime)/(seconds part of final log entry). Then each log entry’s timestamp is computed as (boot time) + (seconds part of log entry)*(scale factor). This version results in correct timestamps at both ends of the log.

Timestamps in the middle of the log may still be somewhat inaccurate because there is no guarantee that clock drift will be uniform throughout the uptime. However, they should be significantly closer to accurate than they would be without this adjustment.

If there are no timestamps available in the log buffer, tslog prints a message to that effect and exits.

Options provided by ‘tslog’:

crash> tslog -h
usage: tslog [-h] [-c]

optional arguments:
  -h, --help      show this help message and exit
  -c, --callerid  show caller ID (thread or CPU) if supported by kernel and crash versions

Show caller ID (-c)

The '-c' option shows the caller ID field that identifies either the thread ID or the CPU ID (if in CPU context) that called printk(), if available. This is supported with crash version 8.0.5 and later, and is available on Linux 5.1-5.9 kernels configured with CONFIG_PRINTK_CALLER or Linux 5.10 and later kernels.

Example:

2023-11-14 17:15:36 [189257.510205] [T14482] EXT4-fs (loop0): mounted filesystem without journal. Opts: (null). Quota mode: none.
2023-11-14 17:17:17 [189358.114742] [T24169] lp: driver loaded but no devices found
2023-11-15 01:43:17 [219719.261102] [    C1] perf: interrupt took too long (3945 > 3938), lowering kernel.perf_event_max_sample_rate to 50500

[T14482] and [T24169] indicate thread IDs (PIDs) in the first two messages above, while [C1] indicates that CPU 1 logged the last message in CPU context.