/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.