关联 /var/log/* 时间戳

关联 /var/log/* 时间戳

/var/log/messages/var/log/syslog和其他一些日志文件使用包含绝对时间的时间戳,例如Jan 13 14:13:10.

/var/log/Xorg.0.log/var/log/dmesg以及 的输出$ dmesg,使用如下格式

[50595.991610] malkovich: malkovich malkovich malkovich malkovich

我猜测/收集这些数字代表自启动以来的秒和微秒。

然而,我尝试关联这两组时间戳(使用 的输出uptime),结果存在大约 5000 秒的差异。

这大约是我的计算机暂停的时间。

有没有一种方便的方法将 dmesg 和 Xorg 使用的数字时间戳映射为绝对时间戳?

更新

作为弄清楚这一点的初步步骤,也希望使我的问题更加清晰,我写了一个Python脚本解析/var/log/syslog并输出时间偏差。在我运行 ubuntu 10.10 的机器上,该文件包含许多源自内核的行,这些行都带有 dmesg 时间戳和 syslog 时间戳。该脚本为该文件中的每一行输出一行,其中包含内核时间戳。

用法:

python syslogdriver.py /var/log/syslog | column -nts $'\t'

清除的输出(有关列定义,请参见下文):

abs              abs_since_boot  rel_time      rel_offset  message
Jan 13 07:49:15  32842.1276569   32842.301498  0           malkovich malkovich

...rel_offset对于所有中间行都是 0 ...

Jan 13 09:55:14  40401.1276569   40401.306386  0           PM: Syncing filesystems ... done.
Jan 13 09:55:14  40401.1276569   40401.347469  0           PM: Preparing system for mem sleep
Jan 13 11:23:21  45688.1276569   40402.128198  -5280       Skipping EDID probe due to cached edid
Jan 13 11:23:21  45688.1276569   40402.729152  -5280       Freezing user space processes ... (elapsed 0.03 seconds) done.
Jan 13 11:23:21  45688.1276569   40402.760110  -5280       Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 13 11:23:21  45688.1276569   40402.776102  -5280       PM: Entering mem sleep

...rel_offset对于所有剩余的行来说是-5280 ...

Jan 13 11:23:21  45688.1276569   40403.149074  -5280       ACPI: Preparing to enter system sleep state S3
Jan 13 11:23:21  45688.1276569   40403.149477  -5280       PM: Saving platform NVS memory
Jan 13 11:23:21  45688.1276569   40403.149495  -5280       Disabling non-boot CPUs ...
Jan 13 11:23:21  45688.1276569   40403.149495  -5280       Back to C!
Jan 13 11:23:21  45688.1276569   40403.149495  -5280       PM: Restoring platform NVS memory
Jan 13 11:23:21  45688.1276569   40403.151034  -5280       ACPI: Waking up from system sleep state S3

...最后几行是从稍远的地方开始的,仍然远高于输出的末尾。 其中一些可能dmesg在挂起发生之前被写入 的循环缓冲区,并且仅syslog在挂起之后才传播到。这解释了为什么它们都具有相同的系统日志时间戳。

列定义:

abs是系统日志记录的时间。

abs_since_boot是自系统启动以来的同一时间(以秒为单位),基于 的内容/proc/uptime和 的值time.time()

rel_time是内核时间戳。

rel_offsetabs_since_boot是和之间的差异rel_time。我将其四舍五入到几十秒,以避免由于绝对(即生成的syslog)时间戳仅具有秒精度而导致的一次性错误。这实际上不是正确的方法,因为它确实(我认为..)只会导致出现 10 倍误差的可能性更小。如果有人有更好的主意,请告诉我。

我对 syslog 的日期格式也有一些疑问;特别是,我想知道其中是否出现过一年。我猜不会,无论如何,我很可能会在 TFM 中找到这些信息,但如果有人碰巧知道它会很有用。 ..当然,假设有人在将来的某个时候使用这个脚本,而不是仅仅删除几行 Perl 代码。

下一个:

因此,除非你们中的一个人给了我一些受欢迎的启示,否则我的下一步将是添加一个函数来获取给定内核时间戳的时间偏差。我应该能够向脚本提供一个或一组系统日志以及内核时间戳,以获得绝对时间戳。然后我就可以继续调试 Xorg 问题,这些问题目前我还没有解决。

答案1

有趣的问题,不确定我是否尝试过这样做。但我注意到你所说的时间戳,我一直相信它是自启动以来的秒数。

在我的服务器上的系统日志中,我有:

Jan 10 19:58:55 wdgitial kernel: [    0.000000] Initializing cgroup subsys cpuset
Jan 10 19:58:55 wdgitial kernel: [    0.000000] Initializing cgroup subsys cpu
Jan 10 19:58:55 wdgitial kernel: [    0.000000] Linux version 2.6.32-21-server (buildd@yellow) (gcc version 4.4.3 (Ubuntu 4.4.3-4ubuntu5) ) #32-Ubuntu SMP Fri Apr 16     09:17:34 UTC 2010 (Ubuntu 2.6.32-21.32-server 2.6.32.11+drm33.2)
Jan 10 19:58:55 wdgitial kernel: [    0.000000] Command line:  root=/dev/xvda1 ro quiet splash

我想这在大多数 Linux 发行版中是相当一致的,因为这是内核吐出它的东西。

这里我有日期和时间戳。

答案2

您可以尝试一下:

首先,获取 dmesg 文件的时间戳(我的假设是这将是 dmesg 的时间 0)。你会使用

ls -l --时间样式=+%s

/var/log$ ls -l --time-style=+%s dmesg
-rw-r----- 1 root adm 56181 1294941018 dmesg

您可以将秒转换为人类可读的日期

perl -e 'print scalar localtime(1294941018)' 

因此,要查看可读的事件时间,请在 dmesg 中添加事件的秒数。如果 dmesg 事件发生时间为 55.290387 秒,请添加 55 或 55.290387 :

perl -e 'print scalar localtime(1294953978 + 55)'

将纪元秒转换为可读时间的另一种方法是按照建议使用 date -d 。如果您告诉 'date' 表示由 -d 提供的时间,则可以使用 @ 指示要转换的时间以自纪元以​​来的秒数为单位。

date -d "@1294953978"

这将为您提供类似“Thu Jan 13 15:26:18 CST 2011”的输出。

日期+%s
将以自纪元以​​来的秒数格式打印当前时间。

我不记得如何做 shell 数学,所以我通常使用上面的 perl 方法。 :)

答案3

将 dmesg 中的数字映射到日期的最简单方法是使用该date程序。

date -d "-50595 seconds"

此命令显示当前时间减去 50595 秒的日期。

man date

-d, --date=STRING
       display time described by STRING, not `now'

该数字等于开机时间,而不是自启动以来经过的时间。

答案4

快速、肮脏、有效。

$ dmesg | grep 3w | perl /root/print_time_offset.pl

该脚本的内容:

$ cat /root/print_time_offset.pl

#!/usr/bin/perl

$uptime = `cat /proc/uptime | awk '{print $1}';`;
$boot = time() - $uptime;
chomp $boot;
while (<STDIN>) {
        if ($_ =~ /^\[([\s\d\.]+)\]/) {
                $time_offset = $1;
        }
        $real_time = sprintf scalar localtime($boot + $time_offset);
        $_ =~ s/\[[\s\d\.]+\]/\[$real_time\]/;
        print $_;
}

示例输出如下:

[Mon Feb 21 23:06:33 2011] 3ware 9000 Storage Controller device driver for Linux v2.26.02.012.
[Mon Feb 21 23:06:33 2011] 3w-9xxx 0000:03:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[Mon Feb 21 23:06:33 2011] 3w-9xxx 0000:03:00.0: setting latency timer to 64
[Mon Feb 21 23:06:33 2011] scsi4 : 3ware 9000 Storage Controller
[Mon Feb 21 23:06:33 2011] 3w-9xxx: scsi4: Found a 3ware 9000 Storage Controller at 0xfbcde000, IRQ: 16.
[Mon Feb 21 23:06:34 2011] 3w-9xxx: scsi4: Firmware FE9X 4.08.00.006, BIOS BE9X 4.08.00.001, Ports: 4.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Sat Feb 26 02:01:01 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=1.
[Sat Feb 26 02:01:01 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=0.
[Sat Feb 26 16:49:13 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=1.
[Sat Feb 26 17:07:19 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=0.
[Sat Mar  5 02:00:16 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=1.
[Sat Mar  5 02:00:16 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=0.
[Sat Mar  5 18:48:57 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=1.
[Sat Mar  5 19:05:17 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=0.
[Sat Mar 12 02:00:30 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=1.
[Sat Mar 12 02:00:30 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=0.

相关内容