/var/log/messages
,, /var/log/syslog
et certains autres fichiers journaux utilisent un horodatage qui contient une heure absolue, comme Jan 13 14:13:10
.
/var/log/Xorg.0.log
et /var/log/dmesg
, ainsi que la sortie de $ dmesg
, utilisez un format qui ressemble à
[50595.991610] malkovich: malkovich malkovich malkovich malkovich
Je suppose / collecte que les chiffres représentent les secondes et les microsecondes depuis le démarrage.
Cependant, ma tentative de corrélation de ces deux ensembles d'horodatages (en utilisant la sortie de uptime
) a donné un écart d'environ 5000 secondes.
C'est à peu près la durée pendant laquelle mon ordinateur a été suspendu.
Existe-t-il un moyen pratique de mapper les horodatages numériques utilisés par dmesg et Xorg en horodatages absolus?
mise à jour
En tant qu'étape préliminaire pour comprendre cela, et aussi pour, espérons-le, clarifier un peu ma question, j'ai écrit un script Python pour analyser /var/log/syslog
et produire le décalage temporel. Sur ma machine, exécutant ubuntu 10.10, ce fichier contient de nombreuses lignes d'origine du noyau qui sont estampillées à la fois avec l'horodatage dmesg et l'horodatage syslog. Le script génère une ligne pour chaque ligne de ce fichier qui contient un horodatage du noyau.
Usage:
python syslogdriver.py /var/log/syslog | column -nts $'\t'
Sortie expurgée (voir ci-dessous pour les définitions des colonnes):
abs abs_since_boot rel_time rel_offset message
Jan 13 07:49:15 32842.1276569 32842.301498 0 malkovich malkovich
... rel_offset
vaut 0 pour toutes les lignes intermédiaires ...
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
est -5280 pour toutes les lignes 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
... Les lignes finales sont un peu plus bas, toujours bien au-dessus de la fin de la sortie. Certains d 'entre eux ont probablement été écrits dans dmesg
le tampon circulaire d' avant la suspension, et n'ont été propagés syslog
qu'après. Cela explique pourquoi tous ont le même horodatage Syslog.
Définitions des colonnes:
abs
est le temps enregistré par syslog.
abs_since_boot
est la même durée en secondes depuis le démarrage du système, en fonction du contenu /proc/uptime
et de la valeur de time.time()
.
rel_time
est l'horodatage du noyau.
rel_offset
est la différence entre abs_since_boot
et rel_time
. J'arrondis cela à des dizaines de secondes afin d'éviter les erreurs ponctuelles dues aux syslog
horodatages absolus (c'est-à-dire générés) n'ayant qu'une précision de secondes. En fait, ce n'est pas la bonne façon de le faire, car cela entraîne vraiment (je pense ..) juste une plus petite chance d'avoir une erreur off-by-10. Si quelqu'un a une meilleure idée, faites-le moi savoir.
J'ai également quelques questions sur le format de date de syslog; en particulier, je me demande si une année ne s'y est jamais présentée. Je suppose que non, et dans tous les cas, je pourrais probablement m'aider à ces informations dans TFM, mais si quelqu'un le savait, cela serait utile. .. En supposant, bien sûr, que quelqu'un utilise ce script à un moment donné dans le futur, au lieu de simplement casser quelques lignes de code Perl.
Prochain:
Donc, à moins qu'une révélation bienvenue ne me soit donnée par l'un de vous, ma prochaine étape sera d'ajouter une fonction pour obtenir le décalage temporel pour un horodatage du noyau donné. Je devrais pouvoir alimenter le script un ou un ensemble de syslogs, avec un horodatage du noyau, pour obtenir un horodatage absolu. Ensuite, je peux revenir au débogage de mes problèmes Xorg, qui m'échappent pour le moment.
la source
sort
, avoir l'année, le fuseau horaire, etc. +1 pour le script python.Freezing user space processes
ce qui est clairement fait avant de dormir.[12345.6789]..
) émis par le noyau, donc il fait les choses correctement , sous réserve des problèmes traités par mon dernier commentaire. Je ne suis pas sûr de ce que le noyau devrait vraiment faire ici; cela dépend de ce que ces horodatages relatifs au démarrage sont censés indiquer. Le temps d'exécution (par opposition au temps écoulé depuis le démarrage) peut être significatif dans certains contextes. Je suppose que dans l'idéal, il y aurait un enregistrement fiable de ces deux valeurs.Réponses:
Problème intéressant, je ne suis pas sûr d'avoir déjà essayé de le faire. Mais j'ai remarqué l'horodatage dont vous parlez et je l'ai toujours cru être quelques secondes depuis le démarrage.
Dans mon syslog que j'ai sur mon serveur, j'ai:
J'imagine que c'est assez cohérent parmi la plupart des distributions Linux car c'est le noyau qui crache ses trucs.
Et ici, j'ai la date avec l'horodatage.
la source
Vous pouvez essayer ceci:
Tout d'abord, obtenez l'horodatage du fichier dmesg (mon hypothèse est que ce sera l'heure de dmesg 0). Vous utiliserez
Vous pouvez convertir les secondes en une date lisible par l'homme avec
Donc, pour voir une heure d'événement lisible, ajoutez les secondes de l'événement dans dmesg. Si l'événement dmesg a duré 55,290387 secondes, ajoutez 55 ou 55.290387:
Une autre façon de transformer les secondes enracinées dans l'époque en heure lisible est d'utiliser la date -d comme suggéré. Si vous dites à «date» de représenter une heure fournie avec -d, vous pouvez indiquer que l'heure à convertir est en secondes depuis l'époque en utilisant @.
Cela vous donne quelque chose comme "Thu Jan 13 15:26:18 CST 2011" en sortie.
affichera l'heure actuelle au format secondes depuis l'époque.Je ne me souviens pas comment faire des calculs shell, donc j'utilise généralement la méthode perl comme ci-dessus. :)
la source
date -d @$((1294953978 + 55))
, au moins sous bash. Cependant, certains horodatages du noyau sont asymétriques, ce qui signifie que les heures produites par cette méthode seraient antérieures à leurs horodatages correspondants/var/log/syslog
. Il semble que cela se produise à la suite d'événements de suspension sur RAM, probablement en plus de l'hibernation et éventuellement d'autres choses, car le temps du noyau n'augmente pas pendant ces périodes. Voir la mise à jour de la question pour plus d'informations.Le moyen le plus simple de mapper le nombre de dmesg à une date est d'utiliser le
date
programme.Cette commande affiche la date de l'heure actuelle moins 50595 secondes.
De
man date
:Le nombre est égal au temps de mise sous tension et non au temps écoulé depuis le démarrage.
la source
Puisque vous avez noté le décalage temporel lors de la suspension / reprise, je noterai que cela est documenté à au moins un endroit. La page de manuel dmesg (1) indique:
Je n'ai pas trouvé de moyen de faire en sorte que le noyau garde ces horodatages synchronisés avec l'heure du mur.
la source
Rapide, sale, fonctionne.
Contenu de ce script:
Voici un exemple de sortie:
la source