Korelowanie znaczników czasu / var / log / *

20

/var/log/messages, /var/log/syslogi niektóre inne pliki dziennika używają znacznika czasu zawierającego czas bezwzględny, np Jan 13 14:13:10.

/var/log/Xorg.0.logoraz /var/log/dmesg, podobnie jak wynik $ dmesg, użyj formatu, który wygląda

[50595.991610] malkovich: malkovich malkovich malkovich malkovich

Zgaduję / zbieram, że liczby reprezentują sekundy i mikrosekundy od uruchomienia.

Jednak moja próba skorelowania tych dwóch zestawów znaczników czasu (przy użyciu danych wyjściowych z uptime) dała rozbieżność około 5000 sekund.

To mniej więcej tyle czasu, ile czasu mój komputer został zawieszony.

Czy istnieje wygodny sposób odwzorowania numerycznych znaczników czasu używanych przez dmesg i Xorg na absolutne znaczniki czasu?

aktualizacja

Jako wstępny krok w kierunku wyjaśnienia tego, a także, aby mam nadzieję, że moje pytanie będzie nieco jaśniejsze, napisałem skrypt w języku Python, który analizuje /var/log/syslogi wyświetla odchylenie czasu. Na moim komputerze z systemem Ubuntu 10.10 plik ten zawiera wiele linii pochodzących z jądra, które są stemplowane zarówno znacznikiem czasu dmesg, jak i znacznikiem czasu syslog. Skrypt wyświetla wiersz dla każdego wiersza w tym pliku, który zawiera znacznik czasu jądra.

Stosowanie:

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

Wyjściowe dane wyjściowe (definicje kolumn poniżej):

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

... rel_offsetwynosi 0 dla wszystkich linii pośrednich ...

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_offsetwynosi -5280 dla wszystkich pozostałych linii ...

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

... Ostatnie linie znajdują się nieco dalej, wciąż znacznie powyżej końca wyjścia. Niektóre z nich prawdopodobnie zostały zapisane w dmesgokrągłym buforze przed zawieszeniem i zostały przeniesione dopiero syslogpóźniej. To wyjaśnia, dlaczego wszystkie mają ten sam znacznik czasu syslog.

Definicje kolumn:

abs to czas rejestrowany przez syslog.

abs_since_bootto ten sam czas w sekundach od uruchomienia systemu, na podstawie zawartości /proc/uptimei wartości time.time().

rel_time jest znacznikiem czasu jądra.

rel_offsetjest różnica między abs_since_booti rel_time. Zaokrąglam to do kilkudziesięciu sekund, aby uniknąć jednorazowych błędów z powodu bezwzględnych (tj. syslogGenerowanych) znaczników czasowych posiadających jedynie precyzję sekundową. W rzeczywistości nie jest to właściwy sposób, aby to zrobić, ponieważ naprawdę (tak myślę ...) po prostu zmniejsza szansę na wystąpienie błędu przekroczenia 10. Jeśli ktoś ma lepszy pomysł, daj mi znać.

Mam również pytania dotyczące formatu daty syslog; w szczególności zastanawiam się, czy kiedykolwiek pojawi się w tym roku. Zgaduję, że nie, a w każdym razie najprawdopodobniej mógłbym pomóc sobie w uzyskaniu tych informacji w TFM, ale jeśli ktoś się dowie, będzie to przydatne. .. Zakładając oczywiście, że ktoś użyje tego skryptu w pewnym momencie w przyszłości, zamiast po prostu wykasować kilka wierszy kodu Perla.

Kolejny:

Więc jeśli jakieś powitanie nie zostanie mi przekazane przez jednego z was, moim następnym krokiem będzie dodanie funkcji, aby uzyskać przesunięcie czasu dla określonego znacznika czasu jądra. Powinienem być w stanie nakarmić skrypt jednym zestawem syslogów wraz ze znacznikiem czasu jądra, aby uzyskać absolutny znacznik czasu. Następnie mogę wrócić do debugowania moich problemów Xorg, które w tej chwili mi uciekają.

linux xorg logs timestamps intuicyjny
źródło
1
Myślę, że to kwalifikuje się jako błąd i powinno zostać zgłoszone. BTW syslog-ng używa rozsądnych znaczników czasu, z którymi możesz sortować sort, mieć rok, strefę czasową itp. +1 dla skryptu python.
stribika
@stribika: czy byłby to problem z jądrem czy syslog? Lub oba? Wygląda na to, że syslog musi zostać powiadomiony, że system został zawieszony .. może mógłby zrobić to sam z zawieszeniem i wznowieniem haków.
intuicyjnie
Wydaje mi się, że jądro jest winne. Wartości rel_time nie „pomijają” czasu, kiedy system został zawieszony. Wydaje mi się jednak dziwne, że przekrzywienie zaczyna się zanim naprawdę nastąpi zawieszenie. Wartości są już błędne, Freezing user space processesco wyraźnie zostało wykonane przed snem.
stribika
2
@stribika: Moja robocza teoria polega na tym, że te zdarzenia nie są wypychane do syslog aż do wznowienia, ponieważ mają miejsce po zawieszeniu samego syslog.
intuicyjnie,
@stribika: Masz również rację, że jądro jest „winne”: jak rozumiem (po ponownym rozpatrzeniu), syslog po prostu poprzedza absolutną sygnaturę czasową tekstu (zaczynając od [12345.6789]..) emitowanego przez jądro, więc działa poprawnie , z zastrzeżeniem kwestii poruszonych przez mój ostatni komentarz. Nie jestem pewien, co naprawdę powinno tutaj robić jądro; zależy to od tego, co te znaczniki czasu związane ze startem mają oznaczać. Czas działania (w przeciwieństwie do czasu od rozruchu) może mieć znaczenie w niektórych kontekstach. Myślę, że idealnie byłby wiarygodny zapis obu tych wartości.
intuicyjnie,

Odpowiedzi:

4

Ciekawy problem, nie jestem pewien, czy kiedykolwiek próbowałem to zrobić. Ale zauważyłem znacznik czasu, o którym mówisz, i zawsze uważałem, że minęły sekundy od uruchomienia.

W moim dzienniku systemowym, który mam na serwerze, mam:

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

Wyobrażam sobie, że jest to dość spójne wśród większości dystrybucji Linuksa, ponieważ to jądro wyrzuca to z siebie.

I tutaj mam datę wraz ze znacznikiem czasu.

Ryan Gibbons
źródło
3

Możesz spróbować:

Najpierw uzyskaj znacznik czasu pliku dmesg (zakładam, że będzie to czas 0 dmesg). Użyjesz

ls -l --time-style = +% s

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

Możesz przekonwertować sekundy na datę czytelną dla człowieka za pomocą

perl -e 'print scalar localtime(1294941018)'

Aby zobaczyć czytelny czas zdarzenia, dodaj w sekundach od zdarzenia w dmesg. Jeśli zdarzenie dmesg miało 55.290387 sekund, dodaj 55 lub 55.290387:

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

Innym sposobem na przekształcenie zakorzenionych w epoce sekund w czas czytelny jest użycie date -d zgodnie z sugestią. Jeśli powiesz „data”, aby reprezentowała czas dostarczony z opcją -d, możesz wskazać, że czas do konwersji jest wyrażony w sekundach od epoki za pomocą @.

date -d "@1294953978"

To daje ci coś takiego jak „czw 13 stycznia 15:26:18 CST 2011” jako wynik.

data +% s
wydrukuje bieżący czas w formacie sekund od epoki.

Nie pamiętam, jak wykonywać matematykę powłoki, więc zwykle używam metody perl jak wyżej. :)

Belacqua
źródło
1
@jgbelacqua: Chcesz date -d @$((1294953978 + 55)), przynajmniej pod bash. Jednak niektóre znaczniki czasu jądra są wypaczone, co oznacza, że ​​czasy wytworzone tą metodą byłyby wcześniejsze niż odpowiadające im znaczniki czasu w /var/log/syslog. Wygląda na to, że dzieje się tak w wyniku zdarzeń zawieszenia do pamięci RAM, prawdopodobnie oprócz hibernacji i prawdopodobnie innych rzeczy, ponieważ czas jądra nie zwiększa się w tych okresach. Zobacz aktualizację pytania, aby uzyskać więcej informacji.
intuicyjnie
2

Najłatwiejszym sposobem zmapowania numeru z dmesg na datę jest użycie dateprogramu.

date -d "-50595 seconds"

To polecenie wyświetla datę bieżącego czasu minus 50595 sekund.

Od man date:

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

Liczba równa się czasowi włączenia, a nie czasowi, który upłynął od czasu rozruchu.

Lekensteyn
źródło
2

Ponieważ zauważyłeś zmianę skosu czasu podczas zawieszania / wznawiania, zauważę, że jest to udokumentowane w co najmniej jednym miejscu. Strona podręcznika dmesg (1) mówi:

Źródło czasu używane dla dzienników nie jest aktualizowane po systemie ZAWIESZENIE / WZNÓW.

Nie mogłem znaleźć sposobu, aby jądro utrzymywało te znaczniki czasu w synchronizacji z czasem ściany.

Andrzej
źródło
1

Szybko, brudno, działa.

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

Zawartość tego skryptu:

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

Przykładowe dane wyjściowe są następujące:

[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.
Dacav
źródło
1
Zgaduję, że przeczytałeś tylko kilka pierwszych akapitów pytania. Sprawdź to bardziej szczegółowo. Możesz też spróbować zawiesić komputer i sprawdzić, czy skrypt poprawnie zgłasza bezwzględne znaczniki czasu nowo zalogowanych wiadomości.
intuicyjnie,