Надежные метки времени ядра Linux (или их настройка) с использованием usbmon и ftrace?

Я пытаюсь проверить модуль ядра, который использует USB, и поэтому из самого модуля я пишу сообщение ftrace с помощью trace_printk; а затем я хотел проверить, когда после этого в системе появится USB Bulk Out URB Submit.

Проблема в том, что на моем Ubuntu Lucid 11.04 (ядро 2.6.38-16) есть только local а также global часы в ftrace - и хотя их разрешение такое же (микросекунды), что и временные метки от usbmon, их значения значительно различаются.

Так что, не зная ничего лучшего (как я нигде больше не мог говорить об этом), я попытался перенаправить usbmon в trace_marker, с помощью cat:

# ... activate ftrace here ...
usbpid=$(sudo bash -c 'cat /sys/kernel/debug/usb/usbmon/2u > /sys/kernel/debug/tracing/trace_marker & echo $!')
sleep 3 # do test, etc.
sudo kill $usbpid
# ... deactivate ftrace here...

... а потом, когда я прочитал из /sys/kernel/debug/tracing/traceЯ получаю журнал с проблемными метками времени (см. Ниже). Итак, что я хотел бы знать, это:

  • Есть ли способ сделать usbmon есть сообщения появляются прямо в /debug/tracing/traceвместо того, чтобы в /debug/usb/usbmon/2u? (не то, чтобы я мог видеть, но я хотел бы, чтобы это подтвердили)
  • Если нет, есть ли лучший способ "напрямую" перенаправить вывод /sys/kernel/debug/usb/usbmon/2u без каких-либо возможных проблем с буферизацией cat и / или перенаправление оболочки?
  • Если нет, есть ли какой-то алгоритм, где я мог бы использовать дополнительные usbmon timestamp, чтобы как-то "исправить" положение этих событий в домене timestamp ядра? (см. пример ниже)

Вот краткий пример фрагмента /sys/kernel/debug/tracing/trace Журнал я получил:

      <idle>-0     [000] 44989.403572: my_kernel_function: 1 00 00 64 1 64 5
       <...>-29765 [000] 44989.403918: my_kernel_function: 1 00 00 64 2 128 2
       <...>-29787 [000] 44989.404202: 0: f1f47280 3237249791 S Bo:2:002:2 -115 64 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
       <...>-29787 [000] 44989.404234: 0: f1f47080 3237250139 S Bo:2:002:2 -115 64 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
      <idle>-0     [000] 44989.404358: my_kernel_function: 1 00 00 64 3 192 4
       <...>-29787 [000] 44989.404402: 0: f1f47c00 3237250515 S Bo:2:002:2 -115 64 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

Поэтому, когда метка времени ядра равна 44989.404202, метка времени usbmon равна 3237.249791 (= 3237249791/1e6); ни секундная, ни микросекундная части не совпадают. Чтобы сделать это немного проще для глаз, вот тот же фрагмент с оставшейся только информацией о времени:

(1) 44989.403572 MYF  0
(2) 44989.403918 MYF  0.000346
(3) 44989.404202 USB  |           0          3237.249791  0
(4) 44989.404234 USB  |           0.000032   3237.250139  0.000348
(5) 44989.404358 MYF  0.000440    |                       |
(6) 44989.404402 USB              0.000168   3237.250515  0.000376

Таким образом, судя по временным меткам ядра, 32 мкс истекло между событием (3) и событием (4) - но, судя по usbmon временные метки, 348 мкс истек между теми же событиями! Кому доверять сейчас?!

Теперь, если мы предположим, что usbmon временные метки являются более правильными для этих сообщений, поскольку они "напечатаны" до того, как попали в ftrace буфер для начала - мы могли бы предположить, что первое usb-сообщение (3), возможно, было запланировано сразу после выполнения (1), но что-то его прервало - и поэтому второе USB-сообщение (4) вызвало "распечатку" (или, скорее, "запись") обоих (3) и (4) в ftrace буфер (именно поэтому их временные метки в ядре так близки?)

Итак, если я предполагаю, что (4) является более правильным, я могу попробовать нажать (3) назад в течение 348 мкс:

(1) 44989.403572 MYF  0
(3) 44989.403854 USB  |           0          3237.249791  0
(2) 44989.403918 MYF  0.000346    |                       |
(4) 44989.404234 USB  |           0.000380   3237.250139  0.000348
(5) 44989.404358 MYF  0.000440    |                       |
(6) 44989.404402 USB              0.000168   3237.250515  0.000376

... и этот вид выглядит лучше (также USB теперь срабатывает через 282 мкс, 316 мкс и 44 мкс после MYF) - для первой и второй пар MYF/USB (если это действительно так, как они себя ведут); но тогда третий шаг не совсем совпадает, и так далее... Не могу придумать алгоритм, который бы помог мне отрегулировать положение событий USB в соответствии с данными в usbmon Отметка времени...

Источник

1 ответ

Хотя лучший подход для перенаправления вывода usbmon на ftrace все еще остается открытым вопросом, я получил ответ о корреляции их временных меток из этого потока:

Используете и usbmon, и ftrace? [список рассылки linux-usb]

Вы можете вызвать следующую подпрограмму, чтобы получить значение метки времени в стиле usbmon, которое затем может быть добавлено в сообщение ftrace или просто напечатано в журнале ядра:

#include <linux/time.h>

static unsigned usbmon_timestamp(void)
{
  struct timeval tval;
  unsigned stamp;

  do_gettimeofday(&tval);
  stamp = tval.tv_sec & 0xFFF;
  stamp = stamp * 1000000 + tval.tv_usec;
  return stamp;
}

Например,

pr_info("The usbmon time is: %u\n", usbmon_timestamp());
Источник
Другие вопросы по тегам