Корреляция / var / log / * timestamps

/var/log/messages , /var/log/syslog и некоторые другие файлы журналов используют временную метку, которая содержит абсолютное время, например Jan 13 14:13:10 .

/var/log/Xorg.0.log и /var/log/dmesg , а также вывод $ dmesg , используйте формат, который выглядит

 [50595.991610] malkovich: malkovich malkovich malkovich malkovich 

Я предполагаю / собираю, что цифры представляют секунды и микросекунды с момента запуска.

Тем не менее, моя попытка сопоставить эти два набора временных меток (с использованием выходных данных от uptime ) дала расхождение около 5000 секунд.

Это примерно то количество времени, на которое мой компьютер был приостановлен.

Есть ли удобный способ сопоставить числовые временные метки, используемые dmesg и Xorg, в абсолютные временные метки?

Обновить

В качестве предварительного шага к тому, чтобы понять это, а также, надеюсь, сделать мой вопрос немного более ясным, я написал сценарий Python для анализа /var/log/syslog и вывода временного перекоса. На моей машине, запущенной ubuntu 10.10, этот файл содержит многочисленные строки, созданные из ядра, которые отмечены как меткой времени dmesg, так и временной меткой syslog. Сценарий выводит строку для каждой строки в этом файле, которая содержит метку времени ядра.

Применение:

 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 . Это объясняет, почему все они имеют одну и ту же временную метку syslog.

Определения столбцов:

abs – это время, зарегистрированное syslog.

abs_since_boot – это то же самое за несколько секунд с момента запуска системы, на основе содержимого /proc/uptime и значения time.time() .

rel_time – это метка времени ядра.

rel_offset – это разница между abs_since_boot и rel_time . Я округляю это на десятки секунд, чтобы избежать одноразовых ошибок из-за абсолютных (т.е. syslog -генерированных) временных меток, имеющих только секундную точность. На самом деле это не правильный способ сделать это, так как он действительно (я думаю ..) просто приводит к меньшему шансу иметь ошибку «за-10». Если у кого-то есть лучшая идея, пожалуйста, дайте мне знать.

У меня также есть некоторые вопросы о формате даты syslog; в частности, мне интересно, появился ли в нем год. Я предполагаю, что нет, и в любом случае, скорее всего, поможет мне в этой информации в TFM, но если кто-то узнает, что это будет полезно. Разумеется, кто-то использует этот скрипт в какой-то момент в будущем, вместо того, чтобы просто выкидывать пару строк кода Perl.

Следующий:

Поэтому, если какое-то приветственное откровение для меня дано одним из вас, моим следующим шагом будет добавление функции для получения временного перекоса для заданной метки времени ядра. Я должен иметь возможность кормить сценарий один или набор системных журналов вместе с меткой времени ядра, чтобы получить абсолютную метку времени. Затем я могу вернуться к отладке моих проблем Xorg, которые сейчас меня избегают.

5 Solutions collect form web for “Корреляция / var / log / * timestamps”

Интересная проблема. Не уверен, что я когда-либо пытался это сделать. Но я заметил временную метку, о которой вы говорите, и я всегда верил, что она будет секунд с момента загрузки.

В моем 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, так как это ядро, выплевывающее его.

И здесь у меня есть дата вместе с меткой времени.

Вы можете попробовать:

Во-первых, получите временную метку файла dmesg (мое предположение – это время dmesg 0). Вы будете использовать

  ls -l -time-style = +% 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)' 

Другой способ превратить эпохально-ориентированные секунды в читаемое время – использовать дату -d, как было предложено. Если вы укажете «дата» для представления времени, предоставленного с -d, вы можете указать, что время, которое нужно преобразовать, находится в секундах с тех пор, используя @.

 date -d "@1294953978" 

Это дает вам что-то вроде «Thu Jan 13 15:26:18 CST 2011» в качестве выхода.

  date +% s 

будет печатать текущее время в формате секунд-эпох.

Я не могу вспомнить, как сделать математику оболочки, поэтому я обычно использую метод perl, как указано выше. 🙂

Самый простой способ сопоставить число от dmesg до даты – это использовать программу date .

 date -d "-50595 seconds" 

Эта команда отображает дату текущего времени минус 50595 секунд.

man date :

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

Число равно времени включения, а не времени, прошедшего с момента загрузки.

Поскольку вы заметили изменение времени во время приостановки / возобновления, я отмечу, что это зарегистрировано, по крайней мере, в одном месте. В справочной странице dmesg (1) говорится:

Источник времени, используемый для журналов, не обновляется после системы SUSPEND / RESUME.

Я не мог найти способ заставить ядро ​​синхронизировать эти временные метки со временем стены.

Быстро, грязно, работает.

 $ 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. 
  • Почему сервер Xnest имеет другой glxinfo, чем обычный сервер Xorg?
  • Какую графическую программу запуска я могу использовать?
  • Переключатель Xorg DISPLAY между двумя пользователями
  • Разрешение 1366x768 в Debian Wheezy на плате Atom D525
  • Как Xserver может определить, какое устройство является мышью или клавиатурой?
  • Установите mouspointer, если вы авторизуетесь через startx
  • X Запуск вместо Openbox (Arch)
  • Полноэкранные приложения для настройки двойного монитора
  • xrandr и панорамирование дают случайные результаты
  • Что такое xcalib-экран для монитора HDMI?
  • Программа для выбора компьютеров для запуска X-клиентов - назовите такие программы?
  • Linux и Unix - лучшая ОС в мире.