/var/log/* タイムスタンプ関連

/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

私はこの数字が起動後の秒とマイクロ秒を表すと推測/収集しています。

しかし、(出力を使用して)2つのタイムスタンプセットを関連付けようとしましたが、uptime約5000秒の違いがありました。

これはおよそ私のコンピュータが一時停止する時間です。

dmesgとXorgで使用される数値タイムスタンプを絶対タイムスタンプにマッピングする便利な方法はありますか?

修正する

この問題を特定し、私の質問をより明確にするための予備的な手順として、次の記事を書きました。Pythonスクリプト/var/log/syslog時間オフセットを解析して出力します。 Ubuntu 10.10を実行しているマイコンピュータでは、ファイルにはカーネルから始まる多くの行が含まれており、すべてdmesgタイムスタンプとsyslogタイムスタンプがあります。スクリプトは、ファイルの各行にカーネルタイムスタンプを含む1行を出力します。

使用法:

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_timesyslog2番目の精度のみを持つ絶対(つまり生成された)タイムスタンプによって引き起こされる1回のエラーを防ぐために、これを数十秒に丸めました。これは実際に正しいアプローチではありません。なぜなら(私の考えでは…)エラーの可能性が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秒を読みやすい時間に変換するもう1つの方法は、提案されているように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.

関連情報