Операционная система ЗОСРВ «Нейтрино» > Руководство разработчика > Основные принципы системной разработки > Программные интерфейсы микроядра > Системная трассировка и анализ > Интерпретация трассировочных данных

Интерпретация трассировочных данных

Анализ данных, полученных из системной трассы

В этой главе:

Обзор

Использование утилиты traceprinter и интерпретация вывода

Создание собственного анализатора

Библиотека traceparser

Простые и составные события

Структура traceevent_t

Наложение событий

Отметки времени

Обзор

Собранные данные можно обрабатывать в реальном времени или автономно.

Рисунок 1. Возможные конфигурации системы интерпретации данных

В состав ЗОСРВ «Нейтрино» входит утилита traceprinter, которая отправляет трассировочные данные в текстовом формате на устройство stdout или записывает их в файл.

Разработчик также может создать собственный интерпретатор с помощью библиотеки traceparser.

Использование утилиты traceprinter и интерпретация вывода

Наиболее простым способом преобразования трассировочных данных в подходящую для анализа форму является обработка файла .kev с помощью утилиты traceprinter.

Рассмотрим пример результатов утилиты traceprinter из раздела Сбор всех событий всех классов.

В первом разделе указана информация о том, как выполнялась трассировка:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: all_classes.kev
            TRACE_DATE:: Wed Jun 24 10:52:58 2009
       TRACE_VER_MAJOR:: 1
       TRACE_VER_MINOR:: 01
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Tue Jun 23 11:47:46 2009
  TRACE_CYCLES_PER_SEC:: 736629000
         TRACE_CPU_NUM:: 1
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: localhost
     TRACE_SYS_RELEASE:: 6.4.1
     TRACE_SYS_VERSION:: 2009/05/20-17:35:56EDT
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2264
TRACE_TRACELOGGER_ARGS:: tracelogger -d1 -n 3 -f all_classes.kev

В следующем разделе перечислены все процессы, которые существовали на момент запуска трассировки:

 -- KERNEL EVENTS -- 
t:0x4f81e320 CPU:00 CONTROL: BUFFER sequence = 33, num_events = 714
t:0x4f81e320 CPU:00 CONTROL :TIME msb:0x000037b0 lsb(offset):0x4f81e014             
t:0x4f82017a CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:0
                       pid:1
                      name:proc/boot/procnto-smp-instr
t:0x4f820f9a CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x4f821358 CPU:00 THREAD  :THREADY       pid:1 tid:1 
t:0x4f821698 CPU:00 THREAD  :THCREATE      pid:1 tid:2
t:0x4f821787 CPU:00 THREAD  :THRECEIVE     pid:1 tid:2 
t:0x4f8219ca CPU:00 THREAD  :THCREATE      pid:1 tid:3
t:0x4f821ac6 CPU:00 THREAD  :THRECEIVE     pid:1 tid:3 
t:0x4f821c94 CPU:00 THREAD  :THCREATE      pid:1 tid:4
t:0x4f821d90 CPU:00 THREAD  :THRECEIVE     pid:1 tid:4 
t:0x4f821f6c CPU:00 THREAD  :THCREATE      pid:1 tid:5
t:0x4f82205b CPU:00 THREAD  :THRECEIVE     pid:1 tid:5 
t:0x4f8222aa CPU:00 THREAD  :THCREATE      pid:1 tid:7
t:0x4f822399 CPU:00 THREAD  :THRECEIVE     pid:1 tid:7 
t:0x4f8225bd CPU:00 THREAD  :THCREATE      pid:1 tid:8
t:0x4f8226ac CPU:00 THREAD  :THRECEIVE     pid:1 tid:8 
t:0x4f8228ca CPU:00 THREAD  :THCREATE      pid:1 tid:10
t:0x4f8229b9 CPU:00 THREAD  :THRECEIVE     pid:1 tid:10 
t:0x4f822b7d CPU:00 THREAD  :THCREATE      pid:1 tid:11
t:0x4f822c6c CPU:00 THREAD  :THRECEIVE     pid:1 tid:11 
t:0x4f822dd7 CPU:00 THREAD  :THCREATE      pid:1 tid:12
t:0x4f822ec6 CPU:00 THREAD  :THRECEIVE     pid:1 tid:12 
t:0x4f8230ac CPU:00 THREAD  :THCREATE      pid:1 tid:15
t:0x4f82319b CPU:00 THREAD  :THRECEIVE     pid:1 tid:15 
t:0x4f8233ca CPU:00 THREAD  :THCREATE      pid:1 tid:20
t:0x4f8234b9 CPU:00 THREAD  :THRECEIVE     pid:1 tid:20 
t:0x4f823ad0 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:1
                       pid:2
                      name:sbin/tinit
t:0x4f823f38 CPU:00 THREAD  :THCREATE      pid:2 tid:1
t:0x4f82402e CPU:00 THREAD  :THREPLY       pid:2 tid:1 
t:0x4f82447d CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:2
                       pid:4099
                      name:proc/boot/pci-bios
t:0x4f824957 CPU:00 THREAD  :THCREATE      pid:4099 tid:1
t:0x4f824a4d CPU:00 THREAD  :THRECEIVE     pid:4099 tid:1 
t:0x4f824ff8 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:2
                       pid:4100
                      name:proc/boot/slogger

Можно отключить вывод вышеуказанной информации с помощью команды _NTO_TRACE_STARTNOSTATE функции TraceEvent(), однако эта информация (в том числе идентификаторы процессов и потоков), как правило, необходима для интерпретации трассировочных данных.

Приведенный пример демонстрирует создание и присвоение имен диагностической версии ядра procnto-smp-instr (идентификатор процесса 1) и ее потокам (идентификатор 1 соответствует бездействующему idle потоку), утилите tinit (идентификатор процесса 2), менеджеру pci-bios и сервису slogger. Некоторые из этих процессов запускаются при загрузке системы; подробнее см. в главе Управление запуском ЗОСРВ «Нейтрино».

В последнюю очередь создаются процессы утилиты tracelogger и нашей собственной программы all_classes (идентификатор процесса 1511472):

t:0x4f852aa8 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:426015
                       pid:1507375
                      name:usr/sbin/tracelogger
t:0x4f853360 CPU:00 THREAD  :THCREATE      pid:1507375 tid:1
t:0x4f853579 CPU:00 THREAD  :THRECEIVE     pid:1507375 tid:1 
t:0x4f85392a CPU:00 THREAD  :THCREATE      pid:1507375 tid:2
t:0x4f853a19 CPU:00 THREAD  :THSIGWAITINFO pid:1507375 tid:2 
t:0x4f853d96 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:426022
                       pid:1511472
                      name:./all_classes
t:0x4f854048 CPU:00 THREAD  :THCREATE      pid:1511472 tid:1
t:0x4f854140 CPU:00 THREAD  :THRUNNING     pid:1511472 tid:1

Далее следует выход из функции TraceEvent(), которая была вызвана в нашей программе:

t:0x4f854910 CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000

Почему в трассировке отсутствует вход в TraceEvent()? Потому, что утилита tracelogger начала сбор событий после того, как получила команду от утилиты TraceEvent(), вызванной в нашей программе!

Следующий фрагмент более сложен для понимания:

t:0x4f856aac CPU:00 KER_CALL:THREAD_DESTROY/47 tid:-1 status_p:0
t:0x4f857dca CPU:00 KER_EXIT:THREAD_DESTROY/47 ret_val:0x00000030 empty:0x00000000
t:0x4f8588d3 CPU:00 KER_CALL:THREAD_DESTROYALL/48 empty:0x00000000 empty:0x00000000 
t:0x4f858ed7 CPU:00 THREAD  :THDESTROY     pid:1511472 tid:1
t:0x4f8598b9 CPU:00 THREAD  :THDEAD        pid:1511472 tid:1 
t:0x4f859c4c CPU:00 THREAD  :THRUNNING     pid:1 tid:1

Мы видим, что здесь уничтожается поток, однако неясно, какой именно. Идентификатор потока tid, равный -1, указывает на текущий поток, однако необходимо определить идентификатор процесса, которому он принадлежит. Как было сказано ранее, большинство событий не содержат информацию о своем источнике; чтобы определить его, необходимо обнаружить предшествующее событие запуска потока. В данном случае это завершение нашей собственной программы с идентификатором 1511472, которая запускает трасссировку и завершает работу. Затем выполняется поток 1 процесса procnto-smp-instr (бездействующий поток).

Дальнейшая трассировка выглядит следующим образом:

t:0x4f85c6e3 CPU:00 COMM    :SND_PULSE_EXE scoid:0x40000002 pid:1
t:0x4f85cecd CPU:00 THREAD  :THRUNNING     pid:1 tid:12 
t:0x4f85d5ad CPU:00 THREAD  :THREADY       pid:1 tid:1 
t:0x4f85e5b3 CPU:00 COMM    :REC_PULSE     scoid:0x40000002 pid:1
t:0x4f860ee2 CPU:00 KER_CALL:THREAD_CREATE/46 func_p:f0023170 arg_p:eff6e000
t:0x4f8624c7 CPU:00 THREAD  :THCREATE      pid:1511472 tid:1
t:0x4f8625ff CPU:00 THREAD  :THWAITTHREAD  pid:1 tid:12 
t:0x4f8627b4 CPU:00 THREAD  :THRUNNING     pid:1511472 tid:1 
t:0x4f8636fd CPU:00 THREAD  :THREADY       pid:1 tid:12 
t:0x4f865c34 CPU:00 KER_CALL:CONNECT_SERVER_INFO/41 pid:0 coid:0x00000000
t:0x4f866836 CPU:00 KER_EXIT:CONNECT_SERVER_INFO/41 coid:0x00000000 info->nd:0
t:0x4f86735e CPU:00 KER_CALL:TIMER_TIMEOUT/75 timeout_flags:0x00000050 ntime(sec):30
t:0x4f868445 CPU:00 KER_EXIT:TIMER_TIMEOUT/75 prev_timeout_flags:0x00000000 otime(sec):0
t:0x4f8697d3 CPU:00 INT_ENTR:0x00000000 (0)       IP:0xf008433e
t:0x4f86a276 CPU:00 INT_HANDLER_ENTR:0x00000000 (0)       PID:126997 IP:0x080b7334 AREA:0x0812a060
t:0x4f86afa7 CPU:00 INT_HANDLER_EXIT:0x00000000 (0) SIGEVENT:NONE
t:0x4f86b304 CPU:00 INT_HANDLER_ENTR:0x00000000 (0)       PID:1 IP:0xf0056570 AREA:0x00000000
t:0x4f86ca12 CPU:00 INT_HANDLER_EXIT:0x00000000 (0) SIGEVENT:NONE
t:0x4f86cff6 CPU:00 INT_EXIT:0x00000000 (0) inkernel:0x00000f01
t:0x4f86e276 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000000 msg:"" (0x00040116)
t:0x4f86e756 CPU:00 COMM    :SND_MESSAGE   rcvid:0x0000004f pid:159762
t:0x4f86f84a CPU:00 THREAD  :THREPLY       pid:1511472 tid:1 
t:0x4f8705dd CPU:00 THREAD  :THREADY       pid:159762 tid:1 
t:0x4f8707d4 CPU:00 THREAD  :THRUNNING     pid:159762 tid:1 
t:0x4f870bff CPU:00 COMM    :REC_MESSAGE   rcvid:0x0000004f pid:159762
t:0x4f878b6c CPU:00 KER_CALL:MSG_REPLYV/15 rcvid:0x0000004f status:0x00000000
t:0x4f878f4b CPU:00 COMM    :REPLY_MESSAGE tid:1 pid:1511472
t:0x4f8798d2 CPU:00 THREAD  :THREADY       pid:1511472 tid:1

Событие SND_PULSE_EXE указывает, что импульс SIGEV_PULSE был послан серверному соединению 0x40000002 от procnto-smp-instr, однако неясно, какой именно импульс и кто является его отправителем. Поток 12 ядра принимает этот импульс, а затем неожиданно создает новый поток 1 в нашем процессе с идентификатором 1511472 и начинает взаимодействовать с ним. Здесь мы наблюдаем завершение нашего процесса: он отправляет ядру импульс-уведомление о завершении; один из потоков ядра принимает его и создает в нашем процессе поток для очистки.

В ходе завершения возникает прерывание, выполняется его обработчик и отправляется сообщение процессу с идентификатором 159762. Изучив начальную информацию о системе, мы видим, что процесс с идентификатором 159762 называется devc-pty.

Дальнейшая трассировка демонстрирует завершение нашего процесса all_classes:

t:0x4f8faa68 CPU:00 THREAD  :THRUNNING     pid:1 tid:20 
t:0x4f8fb09f CPU:00 COMM    :REC_PULSE     scoid:0x40000002 pid:1
t:0x4f8ff1a5 CPU:00 PROCESS :PROCDESTROY   ppid:426022 pid:1511472

Эта трассировка показывает, что ее подробное изучение может занимать много времени, однако она позволяет подробно исследовать события, которые происходят в системе.

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

Создание собственного анализатора

Утилита traceprinter содержит длинный список определений обратных вызовов и несложную процедуру анализа. Все определения обратных вызовов относятся к выводу данных. Но возможности утилиты traceprinter ограничены.

В следующих разделах кратко описаны этапы создания пользовательского анализатора и некоторые сопутствующие проблемы:

Библиотека traceparser
Простые и составные события
Структура traceevent_t
Наложение событий
Отметки времени

Библиотека traceparser

Библиотека traceparser облегчает обработку и анализ событий, принимаемых от диагностической версии ядра и утилиты сбора данных. Она представляет собой компактный промежуточный уровень, который выполняет следующие функции:

компоновка нескольких элементов буфера в одно событие
анализ данных и выполнение пользовательских обратных вызовов, которые инициируются конкретными событиями

Как правило, использование функций traceparser состоит из следующих этапов:

Инициализация библиотеки traceparser с помощью функции traceparser_init(). Эта функция также возвращает состояние пользовательского анализатора.
Включение отладочного режима traceparser и указание файлового потока для отладочного вывода с помощью функции traceparser_debug().
Настройка обратных вызовов обработки интересующих трассировочных событий:

traceparser_cs()
Присоединение обратного вызова к событию.
traceparser_cs_range()
Присоединение обратного вызова к диапазону событий.

При настройке обратного вызова с помощью любой из указанных функций можно задавать указатель на произвольные пользовательские данные, передаваемые обратному вызову.
Запуск анализа трассировочных данных с помощью функции traceparser()
Уничтожение анализатора с помощью функции traceparser_destroy()

Можно получать информацию об анализаторе в любой момент времени с помощью функции traceparser_get_info().

Простые и составные события

Простое событие размещается в одном элементе буфера событий, а составное событие — в нескольких элементах. Как простые, так и составные события соответствуют строго одному событию ядра.

Каждый элемент буфера событий представляет собой непрозрачную структуру traceevent_t.

Структура traceevent_t

Часть структуры traceevent_t непрозрачна — ; несмотря на доступность некоторых ее полей, с ней следует работать только при помощи API библиотеки libtraceparser.

Размер структуры traceevent_t составляет всего 16 байт, и лишь половина из них описывает событие. Благодаря компактности структуры traceevent_t уменьшаются административные расходы при диагностике и повышается степень ее детализации. Если одной структуры traceevent_t недостаточно для хранения информации, она размещается в необходимом количестве структур, которые образуют составное событие. Составное событие — это не несколько объединенных событий, а одно большое событие, которое представлено несколькими элементами traceevent_t.

Для обозначения простых и составных событий структура traceevent_t включает в себя 2-разрядный флаг, который указывает, что она содержит простое событие либо является первым, средним или последним элементом составного события. Этот флаг также применяется для простейшей проверки целостности. Все элементы буфера, в которых хранится составное событие, имеют одинаковую отметку времени, которая отличается от отметок времени всех остальных событий.

Этот «тонкий» протокол не нагружает диагностическую версию ядра и позволяет хранить в структуре traceevent_t небольшой объем информации. «Побочный эффект» компактности заключается в том, что для представления одного события ядра иногда требуется множество структур traceevent_t.

Наложение событий

Несмотря на то, что отметки времени присваиваются событиям немедленно, события не всегда записываются в буфер с помощью одной операции (атомарно). Запись событий, которые занимают несколько элементов буфера (составных событий) часто прерывается потоками других процессов. События, генерируемые потоками с высоким приоритетом, обычно записываются в буфер первыми. Таким образом, события могут накладываться друг на друга. Несмотря на то, что события не обязательно следуют непосредственно друг за другом, их порядок не нарушается (если буфер не переполнен). Составное событие всегда упорядочено корректно, даже если оно прервано другим событием.

Для сохранения скорости работы системы диагностическая версия ядра записывает события максимально быстро, не сортируя их; необходимо выполнять пересборку составных событий на этапе постобработки. API библиотеки libtraceparser выполняет пересборку событий прозрачно для пользователя.

Отметки времени

Отметка времени состоит из 32 младших разрядов 64-разрядных часов. В момент переполнения 32-битной составляющей часов генерируется событие управления _NTO_TRACE_CONTROLTIME. Несмотря на то, что близкие по времени события никогда не происходят строго одновременно, переполнение часов может приводить к возникновению событий с одинаковыми отметками времени.

В событии переполнения указаны 32 старших бита, что позволяет при необходимости восстанавливать полные показания часов. В целях минимизации объема генерируемых данных отметка времени включает в себя только младшие биты (период переполнения часов с частотой 1 ГГц составляет 4,29 с, что является «вечностью» с учетом количества генерируемых событий).

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

Предыдущий раздел: перейти