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



Практические руководства по трассировке

Примеры фильтрации трассировочных данных

В этой главе рассматривается практика управления трассировкой событий с помощью функции TraceEvent():

Обзор
Заголовочный файл common.h
Сбор всех событий всех классов
Сбор всех событий одного класса
Сбор пяти событий четырех классов
Сбор вызовов ядра
Простой пример обработки событий
Вставка простого пользовательского события

Обзор

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

  1. Скомпилируйте указанную программу на языке C в одноименный файл без расширения .c.

  2. Выполните указанную команду tracelogger. Поскольку мы выполняем утилиту tracelogger в режиме демона, она начинает регистрировать события только по команде нашей программы. Это означает, что не нужно торопиться запускать C-программу — трассировка подождет вас.

    Поcкольку по умолчанию используются 32 буфера, создаваемый файл трассировки имеет весьма большой объем; чтобы сократить его, мы уменьшим количество буферов при помощи ключа -n. Можно смело использовать значение по умолчанию, но учитывая, что файл будет большим.

  3. Запустите скомпилированную C-программу в отдельном окне терминала. В некоторых примерах используются аргументы.

  4. Наблюдайте за первым окном терминала; через несколько секунд после запуска C-программы утилита tracelogger завершится.

  5. В результате запуска программы будет сгенерирован отдельный файл результатов. Файлы "tracebuffer" представляют собой двоичные файлы, которые интерпретируются только с помощью библиотеки libtraceparser утилиты traceprinter.

    Если вы не желаете запускать программу, изучите наши результаты утилиты traceprinter (имейте в виду, что эти результаты могут незначительно варьироваться в зависимости от версии утилиты и используемой системы).

Заголовочный файл common.h

Во избежание дублирования кода и повышения его наглядности мы разместили некоторые функции программ в заголовочном файле common.h: 

/* common.h */
                                       
#ifndef __COMMON_H_INCLUDED
#define __COMMON_H_INCLUDED
                                       
#include <errno.h>
#include <stdio.h>
#include <unistd.h>
#include <string.h>
#include <stdlib.h>
#include <sys/trace.h>
                                       
/* Контроль статуса выполнения TraceEvent() */
#define CHECK( program, retval )                                                        \
if ( retval == -1 ) {                                                                   \
    fprintf( stderr, "%s: %s():%d - call TraceEvent() failed (errno:%d, message:%s)\n", \
             program, __FUNCTION__, __LINE__, errno, strerror( errno ) );               \
    return (-1);                                                                        \
}
                                       
/* Отключаем все фильтры, поскольку их текущее состояние заранее неизвестно */
#define INIT( program )                                                         \
CHECK( program, TraceEvent( _NTO_TRACE_DELALLCLASSES ) );                       \
CHECK( program, TraceEvent( _NTO_TRACE_CLRCLASSPID, _NTO_TRACE_KERCALL ) );     \
CHECK( program, TraceEvent( _NTO_TRACE_CLRCLASSTID, _NTO_TRACE_KERCALL ) );     \
CHECK( program, TraceEvent( _NTO_TRACE_CLRCLASSPID, _NTO_TRACE_THREAD ) );      \
CHECK( program, TraceEvent( _NTO_TRACE_CLRCLASSTID, _NTO_TRACE_THREAD ) );
                                       
#endif  /* __COMMON_H_INCLUDED */

Для компиляции программ необходимо поместить файл common.h в каталог, где находится C-код.

Сбор всех событий всех классов

В первом примере мы настроим режим демона для сбора всех событий всех классов. Ниже приведен исходный код программы all_classes.c.

Пример иллюстрирует основы использования вызова ядра TraceEvent() и диагностического модуля с утилитой tracelogger в режиме демона. В мониторинге участвуют все классы и события, которые входят в их состав. Для использования этого примера запустите утилиту tracelogger в режиме демона:

tracelogger -n количество_итераций -d1

где количество_итераций - число от 1 до 10. После запуска этого примера утилита tracelogger зарегистрирует указанное количество итераций и завершит работу. При успешном завершении примера не печатаются никакие сообщения. Собранные события можно просматривать с помощью утилиты traceprinter. Дополнительную информацию см. в сопроводительной документации и комментариях в исходном коде.

#include "common.h"
                                       
int main( int argc, char **argv )
{
    /* Отключаем все фильтры, поскольку их текущее состояние заранее неизвестно */
    INIT( argv[0] );
                                       
    /* Задаем режим генерации кратких событий всех классов */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_SETALLCLASSESFAST ) );
                                       
    /* Сбор событий всех классов */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDALLCLASSES ) );
                                       
    /* Запуск процесса трассировки. В процессе трассировки демон tracelogger регистрирует
     * все события. При его запуске можно задать количество итераций (т.е. буферов ядра,
     * в которых регистрируются события). */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_START ) );
                                       
    /* Утилита tracelogger продолжит выполнение до регистрации указанного количества событий */
    return (0);
}

Скомпилируйте программу и запустите утилиту tracelogger:

tracelogger -d1 -n 3 -f all_classes.kev

Запустите в другом окне:

./all_classes

Несмотря на то, что программа быстро завершила работу, она сгенерировала огромное количество данных. Трассировочные данные находятся в файле all_classes.kev. Чтобы изучить его, введите команду:

traceprinter -f all_classes.kev | less

Результаты утилиты 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:0x4f854048 CPU:00 THREAD  :THCREATE      pid:1511472 tid:1
t:0x4f854140 CPU:00 THREAD  :THRUNNING     pid:1511472 tid:1 
t:0x4f854910 CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
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 
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 
t:0x4f879db8 CPU:00 KER_EXIT:MSG_REPLYV/15 ret_val:0 empty:0x00000000
t:0x4f87a84f CPU:00 KER_CALL:MSG_RECEIVEV/14 chid:0x00000001 rparts:1
                                       
...

В этом примере демонстрируется способность трассировочного модуля собирать гигантские объемы данных о событиях. Первая часть трассировочных данных включает в себя сведения о начальном состоянии всех выполняемых процессов; чтобы отключить сбор этих данных, следует запускать трассировку с флагом _NTO_TRACE_STARTNOSTATE вместо _NTO_TRACE_START.

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

Сбор всех событий одного класса

Теперь мы соберем все события одного класса _NTO_TRACE_THREAD. Он произвольно выбран для демонстрации фильтрации по классам и принципиально ничем не отличается от других классов. Полный список классов см. в разделе Классы и события. Ниже приведен исходный код программы one_class.c.

Пример иллюстрирует основы использования вызова ядра TraceEvent() и диагностического модуля с утилитой tracelogger в режиме демона. Выполняется мониторинг (сбор) только событий класса потоков ( _NTO_TRACE_THREAD). Для использования этого примера запустите утилиту tracelogger в режиме демона:

tracelogger -n количество_итераций -d1

где количество_итераций - число от 1 до 10. После запуска этого примера утилита tracelogger зарегистрирует указанное количество итераций и завершит работу. При успешном завершении примера не печатаются никакие сообщения. Собранные события можно просматривать с помощью утилиты traceprinter.

#include "common.h"
                                       
int main( int argc, char **argv )
{
    /* Отключаем все фильтры, поскольку их текущее состояние заранее неизвестно */
    INIT( argv[0] );
                                       
    /* Сбор только событий класса "Поток" */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDCLASS, _NTO_TRACE_THREAD ) );
                                       
    /* Запуск процесса трассировки. В процессе трассировки демон tracelogger регистрирует
     * все события. При его запуске можно задать количество итераций (т.е. буферов ядра,
     * в которых регистрируются события). */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_START ) );
                                       
    /* Утилита tracelogger продолжит выполнение до регистрации указанного количества событий */
    return (0);
}

Скомпилируйте программу и запустите утилиту tracelogger:

tracelogger -d1 -n 3 -f one_class.kev

Запустите в другом окне:

./one_class

Трассировочные данные находятся в файле one_class.kev. Чтобы изучить его, введите команду:

traceprinter -f one_class.kev | less

Результаты утилиты traceprinter выглядят следующим образом:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: one_class.kev
            TRACE_DATE:: Wed Jun 24 10:55:05 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 one_class.kev
 -- KERNEL EVENTS -- 
t:0x002c4d55 CPU:00 CONTROL: BUFFER sequence = 37, num_events = 714
t:0x002c4d55 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x002c5531 CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x002c5bbe CPU:00 THREAD  :THCREATE      pid:1 tid:2
t:0x002c5cd2 CPU:00 THREAD  :THRECEIVE     pid:1 tid:2 priority:255 policy:2
t:0x002c6185 CPU:00 THREAD  :THCREATE      pid:1 tid:3
t:0x002c6272 CPU:00 THREAD  :THRECEIVE     pid:1 tid:3 priority:255 policy:2
t:0x002c64eb CPU:00 THREAD  :THCREATE      pid:1 tid:4
t:0x002c65d8 CPU:00 THREAD  :THRECEIVE     pid:1 tid:4 priority:10 policy:2
t:0x002c67fc CPU:00 THREAD  :THCREATE      pid:1 tid:5
t:0x002c68ea CPU:00 THREAD  :THRECEIVE     pid:1 tid:5 priority:255 policy:2
t:0x002c6bae CPU:00 THREAD  :THCREATE      pid:1 tid:7
t:0x002c6c9b CPU:00 THREAD  :THRECEIVE     pid:1 tid:7 priority:10 policy:2
t:0x002c6f03 CPU:00 THREAD  :THCREATE      pid:1 tid:8
t:0x002c6ff0 CPU:00 THREAD  :THRECEIVE     pid:1 tid:8 priority:10 policy:2
t:0x002c72ec CPU:00 THREAD  :THCREATE      pid:1 tid:10
t:0x002c73d9 CPU:00 THREAD  :THRECEIVE     pid:1 tid:10 priority:10 policy:2
t:0x002c7665 CPU:00 THREAD  :THCREATE      pid:1 tid:11
t:0x002c7752 CPU:00 THREAD  :THRECEIVE     pid:1 tid:11 priority:10 policy:2
t:0x002c7a9d CPU:00 THREAD  :THCREATE      pid:1 tid:12
t:0x002c7b8a CPU:00 THREAD  :THRECEIVE     pid:1 tid:12 priority:10 policy:2
t:0x002c7e44 CPU:00 THREAD  :THCREATE      pid:1 tid:15
t:0x002c7f31 CPU:00 THREAD  :THRECEIVE     pid:1 tid:15 priority:10 policy:2
t:0x002c81a2 CPU:00 THREAD  :THCREATE      pid:1 tid:20
t:0x002c828f CPU:00 THREAD  :THRECEIVE     pid:1 tid:20 priority:10 policy:2
t:0x002c88e3 CPU:00 THREAD  :THCREATE      pid:2 tid:1
t:0x002c89d3 CPU:00 THREAD  :THREPLY       pid:2 tid:1 priority:10 policy:3
t:0x002c8fad CPU:00 THREAD  :THCREATE      pid:4099 tid:1
t:0x002c909a CPU:00 THREAD  :THRECEIVE     pid:4099 tid:1 priority:10 policy:3
t:0x002c95b7 CPU:00 THREAD  :THCREATE      pid:4100 tid:1
t:0x002c96a4 CPU:00 THREAD  :THRECEIVE     pid:4100 tid:1 priority:10 policy:3
t:0x002c9b6e CPU:00 THREAD  :THCREATE      pid:4101 tid:1
t:0x002c9ccd CPU:00 THREAD  :THSIGWAITINFO pid:4101 tid:1 priority:10 policy:3
                                       
...

Обратите внимание, что количество отображаемых результатов значительно уменьшилось.

Сбор пяти событий четырех классов

В предыдущем разделе мы рассмотрели сбор событий определенного класса. Теперь мы можем дополнительно сузить критерии поиска и настроить сбор пяти отдельных событий из четырех классов. Ниже приведен исходный код программы five_events.c.

Пример иллюстрирует основы использования вызова ядра TraceEvent() и диагностического модуля с утилитой tracelogger в режиме демона. В мониторинге участвуют только пять событий из четырех классов. События класса _NTO_TRACE_KERCALL регистрируются в подробном режиме. Для использования этого примера запустите утилиту tracelogger в режиме демона:

tracelogger -n количество_итераций -d1

где количество_итераций - число от 1 до 10. После запуска этого примера утилита tracelogger зарегистрирует указанное количество итераций и завершит работу. При успешном завершении примера не печатаются никакие сообщения. Собранные события можно просматривать с помощью утилиты traceprinter.

#include <sys/kercalls.h>
#include "common.h"
                                       
int main(int argc, char **argv)
{
    /* Отключаем все фильтры, поскольку их текущее состояние заранее неизвестно */
    INIT( argv[0] );
                                       
    /* Установка подробного режима сбора событий */
    CHECK(argv[0], TraceEvent(_NTO_TRACE_SETALLCLASSESWIDE));
                                       
    /*
     * Сбор двух событий класса _NTO_TRACE_THREAD
     */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENT, _NTO_TRACE_THREAD, _NTO_TRACE_THRUNNING ) );
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENT, _NTO_TRACE_THREAD, _NTO_TRACE_THCREATE ) );
                                       
    /* Сбор одного события класса _NTO_TRACE_PROCESS */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENT, _NTO_TRACE_PROCESS, _NTO_TRACE_PROCCREATE_NAME ) );
                                       
    /* Сбор одного события класса _NTO_TRACE_INTENTER */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENT, _NTO_TRACE_INTENTER, _NTO_TRACE_INTFIRST ) );
                                       
    /* Сбор одного события класса _NTO_TRACE_KERCALLEXIT, события __KER_MSG_READV. */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENT, _NTO_TRACE_KERCALLEXIT, __KER_MSG_READV ) );
                                       
    /* Запуск процесса трассировки. В процессе трассировки демон tracelogger регистрирует
     * все события. При его запуске можно задать количество итераций (т.е. буферов ядра,
     * в которых регистрируются события). */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_START ) );
                                       
    /* Утилита tracelogger продолжит выполнение до регистрации указанного количества событий */
    return (0);
}

Скомпилируйте программу и запустите утилиту tracelogger:

tracelogger -d1 -n 3 -f five_events.kev

Запустите в другом окне:

./five_events

Трассировочные данные находятся в файле five_events.kev. Чтобы изучить его, введите команду:

traceprinter -f five_events.kev | less

Результаты утилиты traceprinter выглядят следующим образом:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: five_events.kev
            TRACE_DATE:: Wed Jun 24 10:56:04 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 five_events.kev
 -- KERNEL EVENTS -- 
t:0x1a14da34 CPU:00 CONTROL: BUFFER sequence = 41, num_events = 714
t:0x1a14da34 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:0
                       pid:1
                      name:proc/boot/procnto-smp-instr
t:0x1a14ea7d CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x1a14ed04 CPU:00 THREAD  :THCREATE      pid:1 tid:2
                                       
...
                                       
t:0x1a1cc345 CPU:00 THREAD  :THRUNNING     pid:1 tid:15 priority:10 policy:2
t:0x1a1d01b9 CPU:00 THREAD  :THRUNNING     pid:8200 tid:5 priority:10 policy:3
t:0x1a1d6424 CPU:00 INT_ENTR:0x00000000 (0)       IP:0xb8229890
t:0x1a1ed261 CPU:00 THREAD  :THRUNNING     pid:1 tid:4 priority:10 policy:2
t:0x1a1f0016 CPU:00 THREAD  :THRUNNING     pid:426022 tid:1 priority:10 policy:2
                                       
...
                                       
t:0x2e77ebc5 CPU:00 THREAD  :THRUNNING     pid:1613871 tid:1 priority:10 policy:2
t:0x2e78598d CPU:00 THREAD  :THRUNNING     pid:8200 tid:5 priority:10 policy:3
t:0x2e7ac4fc CPU:00 INT_ENTR:0x00000000 (0)       IP:0xb8229f61
t:0x2e7cec3b CPU:00 KER_EXIT:MSG_READV/16
                    rbytes:22540
                      rmsg:"" (0x1a15080f 0x6e696273 0x6e69742f)
t:0x2e7da478 CPU:00 THREAD  :THRUNNING     pid:1003562 tid:1 priority:10 policy:2
t:0x2e7dc288 CPU:00 THREAD  :THRUNNING     pid:1 tid:15 priority:10 policy:2
                                       
...

Теперь мы выборочно трассируем события и значительно уменьшаем объем генерируемых данных.

Сбор вызовов ядра

Возможно, вызовы ядра следует считать самым важным классом вызовов. В этом примере демонстрируется не только фильтрация, но и аргументы, принимаемые диагностической версией ядра. В простейшем виде эта программа аналогична программе one_class.c, в которой выполнялся сбор событий одного класса. Ниже приведен исходный код программы ker_calls.c.

Пример иллюстрирует основы использования вызова ядра TraceEvent() и диагностического модуля с утилитой tracelogger в режиме демона. Выполняется сбор состояний всех потоков и всех вызовов ядра либо одного вызова с заданным номером. Сбор вызовов ядра осуществляется в подробном режиме. Параметр программы -n num позволяет задать номер регистрируемого вызова ядра (по умолчанию выполняется сбор всех вызовов ядра). Для использования этого примера запустите утилиту tracelogger в режиме демона:

tracelogger -n количество_итераций -d1

где количество_итераций - число от 1 до 10. После запуска этого примера утилита tracelogger зарегистрирует указанное количество итераций и завершит работу. При успешном завершении примера не печатаются никакие сообщения. Собранные события можно просматривать с помощью утилиты traceprinter.

#include "common.h"
                                       
int main(int argc, char **argv)
{
    int arg_var;       /* для анализа введенных аргументов */
    int call_num=(-1); /* номер регистрируемого вызова ядра */
                                       
    /* Анализ командно-строковых аргументов - определение номера вызова ядра */
    while ( (arg_var = getopt( argc, argv, "n:" )) != (-1) )
    {
        switch ( arg_var ) 
        {
            case 'n':
                call_num = strtoul( optarg, NULL, 10 );
                break;
            default:
                fprintf( stderr, "%s: %s\n", argv[0], "error parsing command-line arguments - exiting" );
                return (-1);
        }
    }
                                       
    /* Отключаем все фильтры, поскольку их текущее состояние заранее неизвестно */
    INIT( argv[0] );
                                       
    /* Установка режима генерации подробных событий всех классов */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_SETALLCLASSESWIDE ) );
                                       
    /* Сбор событий класса _NTO_TRACE_THREAD. Они нужны нам для определения состояния активного потока. */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDCLASS, _NTO_TRACE_THREAD ) );
                                       
    /* Добавление всех или одного вызова ядра */
    if ( call_num != (-1) )
    {
        CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENT, _NTO_TRACE_KERCALL, call_num ) );
    } else {
        CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDCLASS, _NTO_TRACE_KERCALL ) );
    }
                                       
    /* Запуск процесса трассировки. В процессе трассировки демон tracelogger регистрирует
     * все события. При его запуске можно задать количество итераций (т.е. буферов ядра,
     * в которых регистрируются события). */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_START ) );
                                       
    /* Утилита tracelogger продолжит выполнение до регистрации указанного количества событий */
    return (0);
}

Скомпилируйте программу и запустите утилиту tracelogger:

tracelogger -d1 -n 3 -f ker_calls.all.kev

Запустите в другом окне:

./ker_calls

Трассировочные данные находятся в файле ker_calls.all.kev. Чтобы изучить его, введите команду:

traceprinter -f ker_calls.all.kev | less

Результаты утилиты traceprinter выглядят следующим образом:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: ker_calls.all.kev
            TRACE_DATE:: Wed Jun 24 10:57:01 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 ker_calls.all.kev
 -- KERNEL EVENTS -- 
t:0x463ad541 CPU:00 CONTROL: BUFFER sequence = 45, num_events = 714
t:0x463ad541 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x463adbe1 CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x463adfa8 CPU:00 THREAD  :THCREATE      pid:1 tid:2
t:0x463ae098 CPU:00 THREAD  :THRECEIVE     pid:1 tid:2 priority:255 policy:2
t:0x463ae375 CPU:00 THREAD  :THCREATE      pid:1 tid:3
                                       
...
                                       
t:0x463d59b6 CPU:00 THREAD  :THSIGWAITINFO pid:1658927 tid:2 priority:10 policy:2
t:0x463d5cb2 CPU:00 THREAD  :THCREATE      pid:1663024 tid:1
t:0x463d5da7 CPU:00 THREAD  :THRUNNING     pid:1663024 tid:1 priority:10 policy:2
t:0x463d666e CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0x463d8e65 CPU:00 KER_CALL:THREAD_DESTROY/47
                       tid:-1
                  priority:-1
                  status_p:0
t:0x463da615 CPU:00 KER_EXIT:THREAD_DESTROY/47 ret_val:0x00000030 empty:0x00000000
t:0x463daf0a CPU:00 KER_CALL:THREAD_DESTROYALL/48 empty:0x00000000 empty:0x00000000
t:0x463db531 CPU:00 THREAD  :THDESTROY     pid:1663024 tid:1
t:0x463dc114 CPU:00 THREAD  :THDEAD        pid:1663024 tid:1 priority:10 policy:2
t:0x463dc546 CPU:00 THREAD  :THRUNNING     pid:1 tid:1 priority:0 policy:1
t:0x463df45d CPU:00 THREAD  :THRUNNING     pid:1 tid:4 priority:10 policy:2
t:0x463dfa7f CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x463e36b4 CPU:00 KER_CALL:THREAD_CREATE/46
                       pid:1663024
                    func_p:f0023170
                     arg_p:eff4e000
                     flags:0x00000000
                 stacksize:10116
               stackaddr_p:eff4e264
                exitfunc_p:0
                    policy:0
            sched_priority:0
         sched_curpriority:0
   param.__ss_low_priority:0
       param.__ss_max_repl:0
param.__ss_repl_period.tv_sec:0
param.__ss_repl_period.tv_nsec:0
param.__ss_init_budget.tv_sec:0
param.__ss_init_budget.tv_nsec:0
               param.empty:0
                 guardsize:0
                     empty:0
t:0x463e50b0 CPU:00 THREAD  :THCREATE      pid:1663024 tid:1
t:0x463e51d0 CPU:00 THREAD  :THWAITTHREAD  pid:1 tid:4 priority:10 policy:2
t:0x463e5488 CPU:00 THREAD  :THRUNNING     pid:1663024 tid:1 priority:10 policy:2
t:0x463e6408 CPU:00 THREAD  :THREADY       pid:1 tid:4 priority:10 policy:2
                                       
...

Программа ker_calls.c принимает аргумент -n, который позволяет наблюдать только за одним типом вызовов ядра. Выполним эту программу еще раз и укажем номер 14, которому соответствует __KER_MSG_RECEIVE. Полный список значений аргумента -n см. в заголовочном файле <sys/kercalls.h>.

Скомпилируйте программу и запустите утилиту tracelogger:

tracelogger -d1 -n 3 -f ker_calls.14.kev

Запустите в другом окне:

./ker_calls -n 14

Трассировочные данные находятся в файле ker_calls.14.kev. Чтобы изучить его, введите команду:

traceprinter -f ker_calls.14.kev | less

Результаты утилиты traceprinter выглядят следующим образом:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: ker_calls.14.kev
            TRACE_DATE:: Wed Jun 24 13:39:20 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 ker_calls.14.kev
 -- KERNEL EVENTS -- 
t:0x73bf28d0 CPU:00 CONTROL: BUFFER sequence = 62, num_events = 714
t:0x73bf28d0 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x73bf2e16 CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x73bf3203 CPU:00 THREAD  :THCREATE      pid:1 tid:2
                                       
...
                                       
t:0x73c21746 CPU:00 THREAD  :THRUNNING     pid:1 tid:1 priority:0 policy:1
t:0x73c24352 CPU:00 THREAD  :THRUNNING     pid:1 tid:15 priority:10 policy:2
t:0x73c247e0 CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x73c2547b CPU:00 KER_EXIT:MSG_RECEIVEV/14
                     rcvid:0x00000000
                      rmsg:"" (0x00000000 0x00000081 0x001dd030)
                  info->nd:0
               info->srcnd:0
                 info->pid:1953840
                 info->tid:1
                info->chid:1
               info->scoid:1073741874
                info->coid:1073741824
              info->msglen:0
           info->srcmsglen:56
           info->dstmsglen:24
            info->priority:10
               info->flags:0
            info->reserved:0
t:0x73c29270 CPU:00 THREAD  :THCREATE      pid:1953840 tid:1
t:0x73c293ca CPU:00 THREAD  :THWAITTHREAD  pid:1 tid:15 priority:10 policy:2
t:0x73c2964a CPU:00 THREAD  :THRUNNING     pid:1953840 tid:1 priority:10 policy:2
t:0x73c2a36c CPU:00 THREAD  :THREADY       pid:1 tid:15 priority:10 policy:2
t:0x73c2fccc CPU:00 THREAD  :THREPLY       pid:1953840 tid:1 priority:10 policy:2
t:0x73c30f6b CPU:00 THREAD  :THREADY       pid:159762 tid:1 priority:10 policy:3
t:0x73c311b0 CPU:00 THREAD  :THRUNNING     pid:159762 tid:1 priority:10 policy:3
t:0x73c31835 CPU:00 KER_EXIT:MSG_RECEIVEV/14
                     rcvid:0x0000004f
                      rmsg:"" (0x00040116 0x00000000 0x00000004)
                  info->nd:0
               info->srcnd:0
                 info->pid:1953840
                 info->tid:1
                info->chid:1
               info->scoid:1073741903
                info->coid:0
              info->msglen:4
           info->srcmsglen:4
           info->dstmsglen:0
            info->priority:10
               info->flags:0
            info->reserved:0
t:0x73c3a359 CPU:00 THREAD  :THREADY       pid:1953840 tid:1 priority:10 policy:2
t:0x73c3af50 CPU:00 KER_CALL:MSG_RECEIVEV/14 chid:0x00000001 rparts:1
t:0x73c3b25e CPU:00 THREAD  :THRECEIVE     pid:159762 tid:1 priority:10 policy:3
                                       
...

Простой пример обработки событий

В этом примере мы собираем два события, которые относятся к двум различным классам. С каждым событием связан обработчик; эти обработчики открывают и закрывают поток. Ниже приведен исходный код программы eh_simple.c.

Пример иллюстрирует основы использования вызова ядра TraceEvent() и диагностического модуля с утилитой tracelogger в режиме демона. В мониторинге участвуют два события различных классов. Управление мониторингом указанных событий осуществляется с помощью назначенных им обработчиков. Для использования этого примера запустите утилиту tracelogger в режиме демона:

tracelogger -n 1 -d1

После запуска этого примера утилита tracelogger зарегистрирует указанное количество итераций и завершит работу. При успешном завершении примера не печатаются никакие сообщения. Собранные события можно просматривать с помощью утилиты traceprinter.

#include <sys/kercalls.h>
#include "common.h"
                                       
/* Подготовка структуры для хранения данных события и их передачи обработчику  */
event_data_t    e_d_1,
                e_d_2;
_Uint32t        data_array_1[20],   /* 20 элементов для возможных аргументов */
                data_array_2[20];   /* 20 элементов для возможных аргументов */
                                       
/* Глобальная переменная состояния, которая управляет потоком двух событий */
int             g_state;
                                       
/* Обработчик события __KER_MSG_SENDV класса _NTO_TRACE_KERCALL */
int call_msg_send_eh( event_data_t *e_d )
{
    if ( g_state )
    {
        g_state = !g_state;
        return (1);
    }
    return (0);
}
                                       
/* Обработчик события _NTO_TRACE_THRUNNING класса _NTO_TRACE_THREAD (поток) */
int thread_run_eh( event_data_t *e_d )
{
    if ( !g_state )
    {
        g_state = !g_state;
        return (1);
    }
    return (0);
}
                                       
int main( int argc, char **argv )
{
    /* Заполняем массивы, входящие в состав структур данных событий */
    e_d_1.data_array = data_array_1;
    e_d_2.data_array = data_array_2;
                                       
    /* Отключаем все фильтры, поскольку их текущее состояние заранее неизвестно */
    INIT( argv[0] );
                                       
    /* Установка краткого режима сбора событий */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_SETALLCLASSESFAST ) );
                                       
    /* Получение привилегий ввода/вывода перед добавлением обработчиков событий */
    if ( ThreadCtl( _NTO_TCTL_IO, 0 ) != EOK )   /* получение привилегий ввода/вывода */
    {
        (void)fprintf( stderr, "argv[0]: Failed to obtain I/O privileges\n" );
        return (-1);
    }
                                       
    /* Сбор одного события __KER_MSG_SENDV класса _NTO_TRACE_KERCALL */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENT, _NTO_TRACE_KERCALLENTER, __KER_MSG_SENDV ) );
                                       
    /* Добавление обработчика события __KER_MSG_SENDV класса _NTO_TRACE_KERCALL */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENTHANDLER, _NTO_TRACE_KERCALLENTER,
                                __KER_MSG_SENDV, call_msg_send_eh, &e_d_1 ) );
                                       
    /* Сбор одного события класса _NTO_TRACE_THREAD */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENT, _NTO_TRACE_THREAD, _NTO_TRACE_THRUNNING ) );
                                       
    /* Добавление обработчика события _NTO_TRACE_THRUNNING класса _NTO_TRACE_THREAD (поток) */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDEVENTHANDLER, _NTO_TRACE_THREAD,
                                _NTO_TRACE_THRUNNING, thread_run_eh, &e_d_2 ) );
                                       
    /* Запуск процесса трассировки. В процессе трассировки демон tracelogger регистрирует
     * все события. Заданное количество итераций равно 1. */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_START ) );
                                       
    /* Сбор всех событий в течение 1 секунды */
    (void)sleep( 1 );
                                       
    /* Прекращение трассировки путем закрытия потока событий */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_STOP ) );
                                       
    /* Сброс внутреннего буфера, поскольку количество сохраненных событий может быть меньше
     * "высокой отметки" одного буфера (715 событий). Вероятно, в этот момент утилита
     * tracelogger завершит работу, поскольку количество ее итераций равно 1 (аргумент -n 1). */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_FLUSHBUFFER ) );
                                       
    /* Удаление обработчиков событий перед завершением во избежание их выполнения в
     * несуществующем адресном пространстве */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_DELEVENTHANDLER, _NTO_TRACE_KERCALLENTER, __KER_MSG_SENDV ) );
    CHECK( argv[0], TraceEvent( _NTO_TRACE_DELEVENTHANDLER, _NTO_TRACE_THREAD, _NTO_TRACE_THRUNNING ) );
                                       
    /* Ожидание длительностью 1 секунду перед завершением для сохранения адресного пространства
     * обработчиков событий */
    (void)sleep( 1 );
                                       
    return (0);
}

Скомпилируйте программу и запустите утилиту tracelogger:

tracelogger -d1 -n 1 -f eh_simple.kev

Note: В этом примере мы задали количество итераций равным 1.

Запустите в другом окне:

./eh_simple

Трассировочные данные находятся в файле eh_simple.kev. Чтобы изучить его, введите команду:

traceprinter -f eh_simple.kev | less

Результаты утилиты traceprinter выглядят следующим образом:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: eh_simple.kev
            TRACE_DATE:: Wed Jun 24 10:58:41 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 1 -f eh_simple.kev
 -- KERNEL EVENTS -- 
t:0x33139a74 CPU:00 CONTROL: BUFFER sequence = 53, num_events = 482
t:0x33139a74 CPU:00 THREAD  :THRUNNING     pid:1749040 tid:1 
t:0x362d0710 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00100102)
t:0x362d1d04 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x362e8e3e CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000000 msg:"" (0x00200113)
t:0x362ea264 CPU:00 THREAD  :THRUNNING     pid:4102 tid:8 
t:0x362f1248 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x362f1c67 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x362fd08b CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00100102)
t:0x362fd949 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x36305424 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x36305e35 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x3630a572 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x3630aeb7 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x3631bd5b CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00100102)
t:0x3631c6aa CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x363253bb CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x36325d95 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x369b2349 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x369b2bbe CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x369b88d8 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000007 msg:"" (0x00100106)
t:0x369b974a CPU:00 THREAD  :THRUNNING     pid:1 tid:15 
t:0x369c48ab CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000008 msg:"" (0x00100106)
t:0x369c53db CPU:00 THREAD  :THRUNNING     pid:126997 tid:2 
t:0x369cee17 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000008 msg:"" (0x00100106)
t:0x369cf533 CPU:00 THREAD  :THRUNNING     pid:126997 tid:2 
t:0x369d82b6 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000009 msg:"" (0x00100106)
t:0x369d9178 CPU:00 THREAD  :THRUNNING     pid:8200 tid:10 
t:0x369eae84 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000006 msg:"" (0x00020100)
t:0x369eb687 CPU:00 THREAD  :THRUNNING     pid:1 tid:15 
t:0x369f56b1 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000006 msg:"" (0x00020100)
                                       
...

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

Вставка простого пользовательского события

В этом примере демонстрируется вставка пользовательского события в поток событий. Ниже приведен исходный код программы usr_event_simple.c.

Пример иллюстрирует основы использования вызова ядра TraceEvent() и диагностического модуля с утилитой tracelogger в режиме демона. В мониторинге участвуют все классы и события, которые входят в их состав. Также регистрируются четыре простых события, заданные пользователем, и одно строковое событие. Для использования этого примера запустите утилиту tracelogger в режиме демона:

tracelogger -n количество_итераций -d1

где количество_итераций - число от 1 до 10. После запуска этого примера утилита tracelogger зарегистрирует указанное количество итераций и завершит работу. При успешном завершении примера не печатаются никакие сообщения. Собранные события можно просматривать с помощью утилиты traceprinter. Пользовательские события (класс USREVENT) зарегистрированы с идентификаторами (EVENT) 111, 222, 333, 444 и 555.

#include "common.h"
                                       
int main(int argc, char **argv)
{
    /* Отключаем все фильтры, поскольку их текущее состояние заранее неизвестно */
    INIT( argv[0] );
                                       
    /* Задаем режим генерации кратких событий всех классов */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_SETALLCLASSESFAST ) );
                                       
    /* Сбор событий всех классов */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_ADDALLCLASSES ) );
                                       
    /* Запуск процесса трассировки. В процессе трассировки демон tracelogger регистрирует
     * все события. При его запуске можно задать количество итераций (т.е. буферов ядра,
     * в которых регистрируются события). */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_START ) );
                                       
    /* Вставка четырех простых пользовательских событий и одного строкового события в поток.
     * Пользовательские события имеют произвольные идентификаторы - 111, 222, 333, 444 и 555
     * (допустимые значения находятся в диапазоне 0...1023). Пользовательские события с
     * идентификаторами (111, ..., 444) являются простыми событиями, с которыми связаны два
     * числа:({1,11}, ..., {4,44}). Строковое пользовательское событие (с идентификатором 555)
     * содержит строку "Hello world". */
    CHECK( argv[0], TraceEvent( _NTO_TRACE_INSERTSUSEREVENT, 111, 1, 11 ) );
    CHECK( argv[0], TraceEvent( _NTO_TRACE_INSERTSUSEREVENT, 222, 2, 22 ) );
    CHECK( argv[0], TraceEvent( _NTO_TRACE_INSERTSUSEREVENT, 333, 3, 33 ) );
    CHECK( argv[0], TraceEvent( _NTO_TRACE_INSERTSUSEREVENT, 444, 4, 44 ) );
    CHECK( argv[0], TraceEvent( _NTO_TRACE_INSERTUSRSTREVENT,555, "Hello world" ) );
                                       
    /* Утилита tracelogger продолжит выполнение до регистрации указанного количества событий */
    return (0);
}

Скомпилируйте программу и запустите утилиту tracelogger:

tracelogger -d1 -n 3 -f usr_event_simple.kev

Запустите в другом окне:

./usr_event_simple

Трассировочные данные находятся в файле usr_event_simple.kev. Чтобы изучить его, введите команду:

traceprinter -f usr_event_simple.kev | less

Результаты утилиты traceprinter выглядят следующим образом:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: usr_event_simple.kev
            TRACE_DATE:: Wed Jun 24 10:59:34 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 usr_event_simple.kev
 -- KERNEL EVENTS -- 
t:0x254620e4 CPU:00 CONTROL: BUFFER sequence = 54, num_events = 714
                                       
...
                                       
t:0x25496c81 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:426022
                       pid:1810480
                      name:./usr_event_simple
t:0x2549701a CPU:00 THREAD  :THCREATE      pid:1810480 tid:1
t:0x25497112 CPU:00 THREAD  :THRUNNING     pid:1810480 tid:1 
t:0x2549793a CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0x25497f48 CPU:00 USREVENT:EVENT:111, d0:0x00000001 d1:0x0000000b
t:0x254982c5 CPU:00 USREVENT:EVENT:222, d0:0x00000002 d1:0x00000016
t:0x25498638 CPU:00 USREVENT:EVENT:333, d0:0x00000003 d1:0x00000021
t:0x25498996 CPU:00 USREVENT:EVENT:444, d0:0x00000004 d1:0x0000002c
t:0x25499451 CPU:00 USREVENT:EVENT:555 STR:"Hello world"
t:0x2549bde5 CPU:00 KER_CALL:THREAD_DESTROY/47 tid:-1 status_p:0
t:0x2549d0d6 CPU:00 KER_EXIT:THREAD_DESTROY/47 ret_val:0x00000030 empty:0x00000000
t:0x2549d8ae CPU:00 KER_CALL:THREAD_DESTROYALL/48 empty:0x00000000 empty:0x00000000
                                       
...

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




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