☰

/var/log/* 타임스탬프 관련

tag-icon • tag-icon linux xorg logs timestamps
/var/log/* 타임스탬프 관련

/var/log/messages, /var/log/syslog일부 다른 로그 파일은 절대 시간을 포함하는 타임스탬프를 사용합니다 Jan 13 14:13:10.

/var/log/Xorg.0.logsum 및 /var/log/dmesg의 출력은 $ dmesg다음 형식을 사용합니다.

[50595.991610] malkovich: malkovich malkovich malkovich malkovich

나는 이 숫자가 부팅 이후 초와 마이크로초를 나타내는 것으로 추측/수집하고 있습니다.

그러나 (output을 사용하여) 두 개의 타임스탬프 세트를 연관시키려고 시도했는데 uptime약 5000초의 차이가 있었습니다.

이것은 대략 내 컴퓨터가 일시 중지되는 시간입니다.

dmesg 및 Xorg에서 사용하는 숫자 타임스탬프를 절대 타임스탬프에 매핑하는 편리한 방법이 있습니까?

고쳐 쓰다

이 문제를 파악하고 내 질문을 더 명확하게 하기 위한 예비 단계로 다음과 같은 글을 썼습니다.파이썬 스크립트/var/log/syslog시간 오프셋을 구문 분석 하고 출력합니다. 우분투 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정지 후에만 전파되었습니다. 이는 모두 동일한 syslog 타임스탬프를 갖는 이유를 설명합니다.

열 정의:

abs시스템 로그에 기록된 시간입니다.

abs_since_boot는 의 내용 /proc/uptime과 값을 기준으로 시스템이 시작된 이후 동일한 시간(초)입니다 time.time().

rel_time커널 타임스탬프입니다.

rel_offsetabs_since_boot는 와 의 차이입니다 rel_time. syslog두 번째 정밀도만 갖는 절대(즉, 생성된) 타임스탬프에 의해 발생하는 일회성 오류를 방지하기 위해 이를 수십 초로 반올림했습니다 . 이것은 실제로 올바른 접근 방식이 아닙니다. 왜냐하면 (제 생각에는..) 오류 가능성이 10배만 작아지기 때문입니다. 누구든지 더 좋은 아이디어가 있으면 알려주시기 바랍니다.

또한 syslog 날짜 형식에 대한 몇 가지 질문이 있습니다. 특히 연도가 표시되는지 알고 싶습니다. 내 생각에는 그렇지 않을 것 같습니다. 어차피 TFM에서 이 정보를 찾을 수 있겠지만, 누군가가 이 정보를 알게 된다면 유용할 것입니다. ..물론 누군가가 Perl 코드 몇 줄을 삭제하는 대신 미래의 어느 시점에 이 스크립트를 사용한다고 가정합니다.

다음:

따라서 여러분 중 누군가가 나에게 환영할 만한 사실을 알려주지 않는 한, 다음 단계는 주어진 커널 타임스탬프에 대한 시간 오프셋을 얻는 함수를 추가하는 것입니다. 절대 타임스탬프를 얻으려면 커널 타임스탬프와 함께 syslog 또는 syslog 세트를 스크립트에 제공할 수 있어야 합니다. 그런 다음 아직 해결하지 못한 Xorg 문제를 계속 디버깅할 수 있습니다.

답변1

흥미로운 질문입니다. 제가 이 작업을 시도했는지 확실하지 않습니다. 하지만 나는 타임스탬프에 대해 당신이 말한 것을 알아차렸고, 나는 그것이 부팅 이후의 초 수라고 항상 믿었습니다.

내 서버의 syslog에는 다음이 있습니다.

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)'

epoch 초를 읽을 수 있는 시간으로 변환하는 또 다른 방법은 제안된 대로 date -d를 사용하는 것입니다. -d에서 제공하는 시간을 나타내도록 'date'에 지시하는 경우 @를 사용하여 에포크 이후의 시간을 초 단위로 변환한다는 것을 나타낼 수 있습니다.

date -d "@1294953978"

이렇게 하면 "Thu Jan 13 15:26:18 CST 2011"과 같은 출력이 제공됩니다.

날짜+%s
에포크 형식 이후 현재 시간을 초 단위로 인쇄합니다.

쉘 수학을 어떻게 하는지 기억이 안나서 주로 위의 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.

관련 정보