Correlacionando / var / log / * timestamps

20

/var/log/messages , /var/log/syslog e alguns outros arquivos de log usam um timestamp que contém um tempo absoluto, como Jan 13 14:13:10 .

/var/log/Xorg.0.log e /var/log/dmesg , bem como a saída de $ dmesg , use um formato que pareça

[50595.991610] malkovich: malkovich malkovich malkovich malkovich

Acredito que os números representam segundos e microssegundos desde a inicialização.

No entanto, minha tentativa de correlacionar esses dois conjuntos de registros de data e hora (usando a saída de uptime ) gerou uma discrepância de aproximadamente 5.000 segundos.

Isso é aproximadamente a quantidade de tempo que meu computador foi suspenso.

Existe uma maneira conveniente de mapear os timestamps numéricos usados pelo dmesg e Xorg em timestamps absolutos?

atualizar

Como um passo preliminar para descobrir isso e também para tornar minha pergunta mais clara, escrevi um script em Python para analisar /var/log/syslog e gerar o desvio de tempo. Na minha máquina, executando o Ubuntu 10.10, esse arquivo contém várias linhas originadas no kernel, que são carimbadas com o registro de data e hora do dmesg e com o registro de data e hora do syslog. O script gera uma linha para cada linha desse arquivo que contém um timestamp do kernel.

Uso:

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

Saída expurgada (veja abaixo as definições das colunas):

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

... rel_offset é 0 para todas as linhas de intervenção ...

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 para todas as linhas restantes ...

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

... As linhas finais são um pouco mais abaixo, ainda bem acima do final da saída. Algumas delas presumivelmente foram gravadas no buffer circular de dmesg antes da suspensão acontecer e só foram propagados para syslog depois. Isso explica por que todos eles têm o mesmo registro de data e hora do syslog.

Definições de coluna:

abs é o tempo registrado pelo syslog.

abs_since_boot é o mesmo tempo em segundos desde a inicialização do sistema, com base no conteúdo de /proc/uptime e no valor de time.time() .

rel_time é o registro de data e hora do kernel.

rel_offset é a diferença entre abs_since_boot e rel_time . Eu estou arredondando isso para as dezenas de segundos, de modo a evitar erros pontuais devido ao tempo absoluto (ou seja, syslog -gerado) apenas com precisão de segundos. Na verdade, esse não é o jeito certo de fazer isso, já que realmente (acho que ...) resulta em uma chance menor de ter um erro off-10. Se alguém tiver uma ideia melhor, por favor me avise.

Eu também tenho algumas perguntas sobre o formato de data do syslog; em particular, eu estou querendo saber se um ano aparece nele. Eu suponho que não, e em qualquer caso, muito provavelmente poderia me ajudar com essa informação no TFM, mas se alguém souber que seria útil. .. Supondo, claro, que alguém use esse script em algum momento no futuro, em vez de apenas eliminar algumas linhas de código Perl.

Próximo:

Então, a menos que alguma revelação bem-vinda seja para mim dada por um de Você, meu próximo passo será adicionar uma função para obter o tempo de inclinação para um determinado timestamp do kernel. Eu deveria ser capaz de alimentar o script um ou um conjunto de syslogs, juntamente com um timestamp do kernel, para obter um timestamp absoluto. Então eu posso voltar a depurar meus problemas com o Xorg, que me escapam no momento.

    
por intuited 13.01.2011 / 19:47

5 respostas

4

Problema interessante, não tenho certeza se já tentei fazer isso. Mas eu tenho notado o timestamp que você está falando e eu sempre acreditei em segundos após o boot.

No meu syslog que tenho no meu servidor, tenho:

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

Eu imagino que isso é bastante consistente entre a maioria das distro Linux, já que este é o kernel que cuspiu suas coisas.

E aqui eu tenho a data junto com o timestamp.

    
por 13.01.2011 / 23:20
3

Você pode experimentar:

Primeiro, obtenha o timestamp do arquivo dmesg (minha suposição é de que este será o tempo 0 do dmesg). Você vai usar

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

Você pode converter os segundos em uma data legível por humanos com

perl -e 'print scalar localtime(1294941018)' 

Então, para ver um tempo de evento legível, adicione os segundos do evento no dmesg. Se o evento dmesg tiver 55.290387 segundos, adicione 55 ou 55.290387:

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

Outra maneira de transformar segundos enraizados em tempo legível é usar data -d como sugerido. Se você informar "data" para representar um horário fornecido com -d, poderá indicar que o tempo a ser convertido está em segundos desde a época, usando @.

date -d "@1294953978"

Isso dá a você algo como "Qui Jan 13 15:26:18 CST 2011" como saída.

date +%s
imprime a hora atual no formato de segundos desde a época.

Não consigo me lembrar de como fazer a matemática do shell, então, normalmente, uso o método perl como acima. :)

    
por 13.01.2011 / 22:41
2

A maneira mais fácil de mapear o número do dmesg para uma data é usando o programa date .

date -d "-50595 seconds"

Este comando exibe a data da hora atual menos 50595 segundos.

De man date :

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

O número é igual ao tempo ligado, não ao tempo decorrido desde o momento da inicialização.

    
por 13.01.2011 / 21:41
2

Como você observou a mudança de horário durante a suspensão / retomada, observo que isso está documentado em pelo menos um lugar. A página man do dmesg (1) diz:

The time source used for the logs is not updated after system SUSPEND/RESUME.

Não consegui encontrar uma maneira de fazer com que o kernel mantenha esses timestamps em sincronia com o tempo de exibição.

    
por 23.01.2012 / 20:13
1

Rápido, sujo, funciona.

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

Conteúdo desse script:

$ 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 $_;
}

A saída da amostra é a seguinte:

[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.
    
por 12.03.2011 / 22:22