trace-cmd — программа для работы с ftrace

trace-cmd

PDF

Программа для взаимодействия со встроенным трассировщиком ядра Linux ftrace.

Синтаксис

trace-cmd COMMAND [OPTIONS]

Описание

Программа trace-cmd взаимодействует с трассировщиком ftrace, встроенным в ядро Linux. Взаимодействие происходит через файлы файловой системы debugfs. Параметр COMMAND задает операции, выполняемые trace-cmd.

Разработчиком программы является Steven Rostedt, <rostedt@goodmis.org>, исходный код доступен по ссылке https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/.

Команды

record

Задает запись трассировки в файл trace.dat на локальном диске или через сеть.

report

Читает файл trace.dat и преобразует двоичные данные в удобочитаемый текст ASCII.

profile

Запускает профилирование и считывание вывода напрямую.

hist

Выводит гистограмму событий.

stat

Показывает статус системы трассировки (ftrace).

extract

Извлекает данные из кольцевого буфера ядра и создает файл trace.dat.

show

Показывает содержимое буфера трассировки ядра.

options

Выводит список опций плагинов, доступных для отчета.

start

Запускает трассировку без записи в файл trace.dat.

stop

Останавливает трассировку (прекращается лишь запись, а издержки трассировщика сохраняются).

restart

Повторно запускает остановленную ранее трассировку (воздействует лишь на запись).

reset

Отключает все трассировки, возвращая полную производительность системы (данные из буферов ядра теряются).

split

Расщепляет файл trace.dat на более мелкие файлы.

list

Выводит список доступных плагинов, событий и опций ftrace.

listen

Открывает порт для прослушивания соединений от удаленных точек трассировки.

restore

Восстанавливает файлы данных отказавшего запуска команды trace-cmd record.

stack

Запускает и показывает трассировщик стека.

check-events

Анализирует строки формата для всех событий и возвращает информацию о возможности разбора всех.

clear

Очищает буферы трассировки.

stream

Запускает трассировку и считывает вывод напрямую.

snapshot

Делает «моментальный снимок» действующей трассировки.

Опции

-h, —help

Выводит краткую справку о поддерживаемых командах.

Другие опции приведены в описаниях соответствующих команд.

record

Записывает трассировку из внутреннего трассировщика ядра Linux ftrace.

Синтаксис

trace-cmd record [OPTIONS] [command]

Описание

Команда trace-cmd record будет переводить встроенный трассировщик ядра Linux в режим записи указанных подключаемых модулей (plugin) и событий при выполнении пользовательской команды (command). Если команда для выполнения не указана, запись будет продолжаться до прерывания пользователем с помощью клавиш Ctrl-C.

При записи ftrace отслеживать события и подключаемые модули, указанные в командной строке. Это может приводить к запуску множества процессов трассировки (по одному на CPU), которые будут записываться из кольцевого буфера ядра напрямую во временные файлы. По завершении работы команды (или при нажатии Ctrl-C) все временные файлы будут объединены в один файл trace.dat, который потом может использоваться для анализа (см. report).

Опции

-p tracer

Задает трассировщик, который обычно не просто отслеживает события, но и выполняют другие операции. Обычно применяются трассировщики function, function_graph, preemptirqsoff, irqsoff, preemptoff и wakeup. Трассировщик должен поддерживаться работающим ядром. Список доступных трассировщиков можно посмотреть с помощью команды list.

-e event

Задает событие для трассировки. В ядре Linux имеется множество статических точек трассировки, сгруппированных по подсистемам, в которых можно включить все события или выбрать из них нужные. События указываются в формате subsystem:event-name. Можно просто указать подсистему без :event-name или event-name без subsystem:. Например, опция -e sched_switch будет включать событие sched_switch, а -e sched — все события подсистемы sched.

Параметр event может также включать шаблонные выражения. Т. е. *stat* будет выбирать все события (или подсистемы), в именах которых присутствует stat.

Для включения всех событий служит ключевое слово all.

-a

Каждое записываемое событие имеет файл формата, помещаемый в начало выходного файла трассировки (заголовок). Если разрешена трассировка событий, не известных trace-cmd, формат этих событий не будет записываться и отчет trace-cmd не будет включать их. В таких случаях опция -a позволяет сохранить формат для всех событий в системе.

-T

Включает трассировку стека для каждого события. Например,

	<idle>-0	[003] 58549.289091: sched_switch:	kworker/0:1:0 [120] R ==> trace-cmd:2603 [120] 
	<idle>-0	[003] 58549.289092: kernel_stack:	<stack trace> 
=> schedule (ffffffff814b260e) 
=> cpu_idle (ffffffff8100a38c) 
=> start_secondary (ffffffff814ab828)

—func-stack

Включает трассировку стека для всех функций. Отметим, что это применимо только для подключаемого модуля function и будет работать только с опцией -l для ограничения числа функций. Если трассировка функций не фильтруется и включена трассировка стека, это может «подвесить» машину.

-f filter

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

==, >=, <=, >, <, &, |, && and ||

Приведенные выше операторы обычно можно безопасно применять для сравнения полей.

—no-filter

Отключает фильтрацию потоков (thread) в trace-cmd. По умолчанию потоки фильтруются, чтобы не отслеживаться событиями. Эта опция приводит к отслеживанию потоков командой trace-cmd.

-R trigger

Задает триггер для предыдущего события и должна указываться после опции -e. Это позволяет добавить указанный триггер к данному событию. Чтобы включить лишь триггер, но не событие, следует поместить событие после опции -v.

Дополнительную информацию о триггерах можно найти в файле Documentation/trace/events.txt кода ядра Linux.

-v

Опция будет отключать трассировку всех событий, указанных после нее в командной строке. Это полезно при выборе подсистемы для трассировки с пропуском ненужных событий. Например, -e sched -v -e «*stat\*»» будет обеспечивать трассировку всех событий sched, за исключением тех, в имени которых присутствует stat.

Примечание. Опция -v была заимствована из grep, где она инвертирует последующие совпадения.

-F

Эта опция будет фильтровать лишь исполняемый файл, указанный в командной строке, а при отсутствии его — самое себя (бессмысленно). Использование опции -F позволяет трассировать лишь события, вызванные данной командой.

-P

Похожа на -F, но позволяет задать идентификатор процесса для трассировки.

-c

Используется с опцией -F (или -P, если ядро поддерживает ее) для трассировки также потомков процесса.

-C clock

Устанавливает значение clock для часов трассировки. Для проверки доступности часов используйте команду trace-cmd list -C.

-o output-file

По умолчанию отчет trace-cmd сохраняется в файле trace.dat, но эта опция позволяет задать другой файл.

-l function-name

Будет ограничивать трассировщики function и function_graph лишь указанной параметром function-name функцией. Для трассировки нескольких функций опция -l может указываться неоднократно. Возможно ограниченное применение выражений-шаблонов вида match*, когда будут трассироваться лишь функции, начинающиеся с match, и *match для функций, завершающихся match. Выражению *match\* будут соответствовать функции, содержащие match.

-g function-name

Эта опция служит для плагина function_graph и будет создавать граф заданной функции. Т. е. будет трассироваться только указанная функция и все вызываемые из нее функции. Опция -g может применяться многократно.

-n function-name

Опция имеет противоположный опции -l эффект — указанная -n функция не будет трассироваться. Эта опция имеет более высокий приоритет, поэтому при указании одной функции в -n и -l эта функция не будет трассироваться.

-d

Некоторые плагины трассировки (например, трассировщик задержек) включают трассировщик function по умолчанию. Эта опция предотвращает включение трассировки функций при старте.

-D

Опция -d будет пытаться использовать опцию function-trace для запрета трассировщика функции (если это возможно), в противном случае будет по умолчанию использоваться файл /proc/sys/kernel/ftrace_enabled, но без использования для него операции touch, если опция function-trace доступна. Опция -D будет отключать (0) файл /proc/ftrace_enabled, а также опцию function-trace, если она есть.

Отметим, что это отключение относится ко всем пользователям, включая находящихся вне трассировщиков ftrace (stack_tracer, perf и т. п.).

-O option

Трассировщик ftrace имеет различные опции, которые можно включать и отключать. Добавление no перед именем опции отключает ее. Например, -O nograph-time отключит опцию graph-time.

-s interval

Процессы, создаваемые trace-cmd для записи из кольцевого буфера, нужно активизировать. Установка нулевого интервала будут активизировать процессы при каждой новой записи данных в буфер. Однако, поскольку ftrace записывает активность ядра, возврат этих процессов в спящий режим может вызывать новые события, которые снова будут будить процесс, что приведет к добавлению в буфер избыточных данных.

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

-r priority

Приоритет для запуска захвата потоков. В загруженной системе потоки захвата трассировки могут быть заторможены с потерей событий. Данная опция повышает уровень приоритета до real time (FIFO). Опцию следует применять с осторожностью, поскольку она может менять поведение отслеживаемой системы.

-b size

Эта опция устанавливает размер кольцевого буфера в килобайтах. Поскольку кольцевые буферы ftrace работают на уровне CPU, заданный опцией размер выделяется в ядре для буфера каждого процессора. Опция -b 10000 на машине с 4 CPU будет создавать буферы ftrace общим размером 40 Мегабайт.

-B buffer-name

Если ядро поддерживает множество буферов, эта опция будет добавлять буфер с заданным именем. Если такой буфер уже имеется, он просто будут сброшен, а по завершении записи не будет удаляться. Если создается новый буфер, он будет удален по завершении записи (если не используется опция -k или команда start).

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

-m size

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

Применение этой опции позволяет предотвратить нехватку дискового пространства для журнальных файлов.

-M cpumask

Устанавливает маску процессора cpumask для трассировки. Опция влияет лишь на последний данный экземпляр буфера. Значение маски должно быть шестнадцатеричным числом.

trace-cmd record -p function -M c -B events13 -e all -M 5

Если опция -M пропущена, маска не изменяется. Для трассировки всех CPU используется маска -1.

-k

По умолчанию при завершении трассировки trace-cmd сбрасывает буферы и отключает все включенные трассировки. Эта опция отменяет выключение трассировки и сброс буферов. Опция полезна для отладки trace-cmd.

Примечание. Обычно trace-cmd возвращает файл tracing_on в состояние, существовавшее до вызова. Эта опция оставит нулевой (пустой) файл.

-i

По умолчанию trace-cmd завершает работу с ошибкой, если указанного в командной строке события не существует. Эта опция позволяет игнорировать события, указанные в командной строке, но не найденные в системе.

-N host:port

Если другая машина работает в режиме trace-cmd listen, эта опция позволяет передать данные такой машине по протоколу UDP. Вместо записи в выходной файл данные передаются удаленной машине. Это очень удобно для встраиваемых систем с небольшим хранилищем или для сохранения на одной машине данных с разных систем.

Примечание. Эта опция не поддерживается с плагинами трассировщиков задержки wakeup, wakeup_rt, irqsoff, preemptoff и preemptirqsoff

-t

Эта опция применяется вместе с -N, когда нужно передавать данные на удаленную машину по протоколу TCP вместо UDP. Хотя TCP работает медленней UDP, этот протокол может потребоваться в ненадежной сети, если объем передаваемых данных невелик, но нужна гарантированная доставка.

-q | —quiet

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

—date

Опция задает trace-cmd запись временных меток в буфер трассировки по завершении записи. Опция будет отображать timestamp в gettimeofday для вывода системного времени при чтении созданного файла trace.dat.

—max-graph-depth depth

Задает максимальную глубину трассировки function_graph в функции. При значении 1 будет указываться лишь пользовательский вход в ядро без каких-либо функций, вызываемых в ядре. По умолчанию применяется неограниченная глубина (0).

—module module

Задает фильтрацию имени модуля в трассировке. Это эквивалентно добавлению :mod:module после всех других функций, которые будут фильтроваться. Если других фильтров функцией не указано, будут фильтроваться все функции.

—module snd эквивалентно -l :mod:snd;

—module snd -l «*jack*»‘ эквивалентно -l «*jack*:mod:snd»;

—module snd -n «*»‘ эквивалентно -n :mod:snd.

—profile

С опцией —profile программа trace-cmd будет включать трассировку, которая может использоваться с командой trace-cmd report —profile. Если опция -p не задана и глубина графа функции поддерживается ядром, трассировщик function_graph будет включен с глубиной 1 (показывать лишь пользовательский вход в ядро). Будут также включены различные трассировочные точки с трассировкой стека, так что отчет может показать, где задачи были заблокированы дольше всего.

Дополнительная информация и примеры представлены в описании profile.

-H event-hooks

Добавляет пользовательское сопоставление событий для связывания вместе пары событий. При использовании вместе с опцией —profile параметр сохраняется и будет применяться также командой trace-cmd report —profile. Т. е. команды

trace-cmd record -H hrtimer_expire_entry,hrtimer/hrtimer_expire_exit,hrtimer,sp
trace-cmd report --profile

будут профилировать время hrtimer_expire_entry и hrtimer_expire_ext.

Формат приведен в описании profile.

-S

(только —profile) Включает лишь трассировщик или события, указанные в командной строке. С этой опцией трассировщик function_graph, равно как и другие события (такие как sched_switch) не включаются, пока не указаны явно в командной строке (например, -p function -e sched_switch -e sched_wakeup).

—ts-offset offset

Добавляет смещение для временных меток в файле trace.dat. Смещение задается в необработанных единицах, т. е. при записи меток в наносекундах смещение также будет в наносекундах, даже если для отображения применяются миллисекунды.

—stderr

Задает вывод в stderr вместо stdout без изменения выходного потока отслеживаемой команды. Это полезно в тех случаях, когда хочется видеть вывод команды без вывода trace-cmd.

Примеры

Базовый вариант трассировки всех событий

# trace-cmd record -e all ls > /dev/null 
# trace-cmd report 
	trace-cmd-13541 [003] 106260.693809: filemap_fault: address=0x128122 offset=0xce 
	trace-cmd-13543 [001] 106260.693809: kmalloc: call_site=81128dd4 ptr=0xffff88003dd83800 bytes_req=768 bytes_alloc=1024 gfp_flags=GFP_KERNEL|GFP_ZERO 
		ls-13545 [002] 106260.693809: kfree: call_site=810a7abb ptr=0x0 
		ls-13545 [002] 106260.693818: sys_exit_write: 	0x1

Для трассировки с отслеживанием sched_switch

# trace-cmd record -p function -e sched_switch ls > /dev/null 
# trace-cmd report 
		-13587 [002] 106467.860310: function: hrtick_start_fair <-- pick_next_task_fair 
		ls-13587 [002] 106467.860313: sched_switch: prev_comm=trace-cmd prev_pid=13587 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=13583 next_prio=120 
	trace-cmd-13585 [001] 106467.860314: function: native_set_pte_at <-- __do_fault 
	trace-cmd-13586 [003] 106467.860314: function:	up_read <-- do_page_fault 
		ls-13587 [002] 106467.860317: function:	__phys_addr <-- schedule 
	trace-cmd-13585 [001] 106467.860318: function: _raw_spin_unlock <-- __do_fault 
		ls-13587 [002] 106467.860320: function: native_load_sp0 <-- __switch_to 
	trace-cmd-13586 [003] 106467.860322: function: down_read_trylock <-- do_page_fault

Ниже показан хороший способ обнаружить прерывания с наибольшей задержкой.

# trace-cmd record -p function_graph -e irq_handler_entry -l do_IRQ sleep 10 
# trace-cmd report 
	<idle>-0	[000] 157412.933969: funcgraph_entry:	|	do_IRQ() { 
	<idle>-0     [000] 157412.933974: irq_handler_entry:    irq=48 name=eth0 
	<idle>-0     [000] 157412.934004: funcgraph_exit:       + 36.358 us |  } 
	<idle>-0     [000] 157413.895004: funcgraph_entry:                  |  do_IRQ() { 
	<idle>-0     [000] 157413.895011: irq_handler_entry:    irq=48 name=eth0 
	<idle>-0     [000] 157413.895026: funcgraph_exit:                        + 24.014 us |  } 
	<idle>-0     [000] 157415.891762: funcgraph_entry:                  |  do_IRQ() { 
	<idle>-0     [000] 157415.891769: irq_handler_entry:    irq=48 name=eth0 
	<idle>-0     [000] 157415.891784: funcgraph_exit:       + 22.928 us |  } 
	<idle>-0     [000] 157415.934869: funcgraph_entry:                  |  do_IRQ() { 
	<idle>-0     [000] 157415.934874: irq_handler_entry:    irq=48 name=eth0 
	<idle>-0     [000] 157415.934906: funcgraph_exit:       + 37.512 us |  } 
	<idle>-0     [000] 157417.888373: funcgraph_entry:                  |  do_IRQ() { 
	<idle>-0     [000] 157417.888381: irq_handler_entry:    irq=48 name=eth0 
	<idle>-0     [000] 157417.888398: funcgraph_exit:       + 25.943 us |  }

Ниже приведен пример записи профиля.

# trace-cmd record --profile sleep 1 
# trace-cmd report --profile --comm sleep 
          task: sleep-21611 
            Event: sched_switch:R (1) Total: 99442 Avg: 99442 Max: 99442 Min:99442 
               <stack> 1 total:99442 min:99442 max:99442 avg=99442 
                 => ftrace_raw_event_sched_switch (0xffffffff8105f812) 
                 => __schedule (0xffffffff8150810a) 
                 => preempt_schedule (0xffffffff8150842e) 
                 => ___preempt_schedule (0xffffffff81273354) 
                 => cpu_stop_queue_work (0xffffffff810b03c5) 
                 => stop_one_cpu (0xffffffff810b063b) 
                 => sched_exec (0xffffffff8106136d) 
                 => do_execve_common.isra.27 (0xffffffff81148c89) 
                 => do_execve (0xffffffff811490b0)
                 => SyS_execve (0xffffffff811492c4) 
                 => return_to_handler (0xffffffff8150e3c8) 
                 => stub_execve (0xffffffff8150c699) 
            Event: sched_switch:S (1) Total: 1000506680 Avg: 1000506680 Max: 1000506680 Min:1000506680 
               <stack> 1 total:1000506680 min:1000506680 max:1000506680 avg=1000506680 
                 => ftrace_raw_event_sched_switch (0xffffffff8105f812) 
                 => __schedule (0xffffffff8150810a) 
                 => schedule (0xffffffff815084b8) 
                 => do_nanosleep (0xffffffff8150b22c) 
                 => hrtimer_nanosleep (0xffffffff8108d647) 
                 => SyS_nanosleep (0xffffffff8108d72c) 
                 => return_to_handler (0xffffffff8150e3c8) 
                 => tracesys_phase2 (0xffffffff8150c304) 
            Event: sched_wakeup:21611 (1) Total: 30326 Avg: 30326 Max: 30326 Min:30326 
               <stack> 1 total:30326 min:30326 max:30326 avg=30326 
                 => ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653) 
                 => ttwu_do_wakeup (0xffffffff810606eb) 
                 => ttwu_do_activate.constprop.124 (0xffffffff810607c8) 
                 => try_to_wake_up (0xffffffff8106340a)

report

Показывает текст ASCII с результатами трассировки, записанной ранее в файл.

Синтаксис

trace-cmd report [OPTIONS] [input-file]

Описание

Команда trace-cmd report выводит понятный человеку отчет о трассировке, выполненной по команде trace-cmd record.

Опции

-i input-file

По умолчанию trace-cmd будет читать файл отчета trace.dat, но эта опция позволяет указать иной файл параметром input-file. Отметим, что входной файл можно также задать в конце командной строки (без опции -i).

-e

Эта опция позволяет увидеть тип файла отчета. Команда trace-cmd достаточно эффективна и может читать файлы big endian на машинах little endian и наоборот.

-f

Обеспечивает вывод списка функций, записанных в файл.

-P

Обеспечивает вывод списка данных trace_printk(). Необработанные данные трассировки показывают статические указатели в ядре. Эти данные должны сохраняться в файле трассировки.

-E

Обеспечивает вывод списка возможных событий в файле (это не обязательно список реально записанных событий).

—events

Обеспечивает вывод списка форматов событий, сохраненных в файле трассировки.

—event regex

Обеспечивает вывод событий, соответствующих регулярному выражению regex. При включении двоеточия символы перед ним служат для сопоставления системы, а символы после двоеточия — для сопоставления событий.

trace-cmd report --event sys:read

Приведенная выше команда будет соответствовать лишь системам, содержащим в имени sys, и событиям, содержащим read.

trace-cmd report --event read

Эта команда будет соответствовать всем событиям и системам, содержащим read в имени.

—check-events

Задает анализ строк формата событий в файле трассировки и возврат информации о возможности их корректного анализа. Опция ведет к загрузке плагинов, если не задана опция -N.

-t

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

-F

Добавляет фильтр отображаемых событий. Формат фильтра показан ниже.

<events> ':' <filter>
<events> = SYSTEM'/'EVENT  | SYSTEM | EVENT | <events> ',' <events>
<filter> = EVENT_FIELD <op> <value> | <filter> '&&' <filter> | <filter> '||' <filter> | '(' <filter> ')' | '!' <filter>
<op> = '==' | '!=' | '>=' | '<=' | '>' | '<' | '&' | '|' | '^' | '+' | '-' | '*' | '/' | '%'
<value> = NUM | STRING | EVENT_FIELD

SYSTEM указывает имя системы для фильтра. Если поле EVENT опущено, фильтр применяется ко всем событиям SYSTEM. Если используется лишь одна строка без символа / для разделения SYSTEM и EVENT, фильтр будет применяться ко всем системам и событиям, соответствующим заданной строке.

Пробельные символы игнорируются, поэтому строки «sched:next_pid==123» и «sched : next_pid == 123» эквивалентны.

Строка STRING указывается в одинарных или двойных кавычках (одинаковых с обеих сторон), пробельные символы внутри кавычек принимаются во внимание.

В качестве SYSTEM и/или EVENT могут также указываться регулярные выражения, соответствующие regcomp.

EVENT_FIELD указывает имя фильтруемого поля в событии. Если событие не включает EVENT_FIELD, эта часть выражения считается ложной (false).

-F 'sched : bogus == 1 || common_pid == 2'

Выражение bogus == 1 всегда будет иметь значение FALSE, поскольку ни в одном событии нет поля bogus, но common_pid == 2 все равно будет проверяться, поскольку все события имеют поле common_pid. Все события sched, трассируемые процессом с PID = 2, будут показаны.

Отметим, что EVENT_FIELD является именем поля, показываемым в формате события (как при выводе с опцией *—events*), а не в выводе. Если вывод показывает ID:foo, но поле, к которому относится foo, называется name в формате события, в качестве фильтра нужно применять name. То же самое относится к значениям. Если отображаемое значение конвертировано в строку символов, фильтр проверяет исходное, а не отображаемое значение. Например, для фильтрации всех задач, которые работали в контексте switch служит выражение

-F 'sched/sched_switch : prev_state==0'

Хотя вывод показывает R, фильтр prev_stat==»R» не будет работать.

Примечание. Можно также указать COMM в качестве EVENT_FIELD. При этом для сравнения будет использоваться имя задачи (или or comm) в записи. Например, для фильтрации всех задач trace-cmd можно применить выражение

-F '.*:COMM != "trace-cmd"'

-I

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

-S

Отключает вывод событий с установленным флагом задержки SOFTIRQ. Это будет фильтровать большинство событий из контекста программного прерывания.

-v

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

-v -F 'sched/sched_switch : prev_state == 0'

Приведенное выражение исключит все события sched_switch с prev_state = 0. Удаление -v приведет лишь к выводу этих событий.

-T

Проверка фильтров опции -F. После обработки строки фильтра для каждого события будет выводиться результирующий фильтр. Это полезно при использовании фильтра для нескольких событий, когда поле может присутствовать во всех событиях может применяться также для гарантии отсутствия некорректно введенных имен событий, которые будет просто игнорироваться. Опция -T не принимается во внимание при отсутствии опции -F.

-V

Задает вывод загружаемых плагинов.

-L

Отменяет загрузку плагинов системного уровня, загружая лишь локальные (т. е. расположенные в каталоге ~/.trace-cmd/plugins).

-N

Отменяет загрузку всех плагинов.

-n event-re

Заставляет все события, соответствующие опции, игнорировать все зарегистрированные (плагинами) обработчики для вывода события, используя взамен обычный формат. Параметр event-re является регулярным выражением, соответствующим regcomp.

—profile

С этой опцией команда trace-cmd report будет сначала обрабатывать все события, а затем выводить формат, показывающий, где задачи тратили свое время в ядре, а также где они были дольше всего заблокированы и где была наибольшая задержка пробуждения.

Дополнительная информация и примеры приведены в описании команды profile.

-G

Устанавливает событие прерывания (программного или аппаратного) как глобальное (связанное с CPU, а не задачей). Работает только в опцией —profile.

-H event-hooks

Добавляет пользовательское сопоставление событий для связывания вместе пары событий.

Формат приведен в описании profile.

-R

Задает вывод событий в необработанном (raw) виде, т. е. форматирование для печати будет игнорироваться.

-r event-re

Задает вывод всех соответствующих опции событий в необработанном формате. Параметр event-re является регулярным выражением, соответствующим regcomp.

-l

Добавляет формат «вывода задержки». Информация о прерываниях и программные прерывания отключаются, устанавливается флаг need_resched, записывается счетчик вытеснения и большая блокировка ядра (big kernel lock) с каждым событием. Однако по умолчанию эта информация не отображается. Данная опция задает 6-символьное отображение отмеченных данных. Если одно из полей равно нулю или недоступно (N/A), выводится ‘.\’.

<idle>-0       0d.h1. 106467.859747: function:             ktime_get <-- tick_check_idle

Поле 0d.h1. указывает эту информацию. Точка никогда не бывает первым символом, который указывает на каком процессоре была записана трассировка (CPU 0). Буква d указывает запрет прерывания, h говорит о вызове внутри обработчика прерывания, 1 указывает, что для запрета вытеснения (preempt_count) было установлено значение 1. Две точки являются флагом need_resched и счетчиком блокировки ядра. Если флаг need_resched установлен, вместо точки будет показан символ N.

-w

Если включены события sched_switch и sched_wakeup, эта опция будет включать вывод задержки между первым вызовом задачи и запланированным временем.

-q

Отключает некритичные предупреждения.

-O

Передает опции в загружаемые плагины trace-cmd.

-O plugin:var=value

Параметры plugin: и =value являются необязательными. Значения логических параметров можно пропускать. Если параметр plugin: не включен, будут установлены любые переменные, соответствующие всем плагинам.

-O fgraph:tailprint --stat

Если в файле трассировки записана финальная статистика (выводится в конце записи), для ее извлечения может служить опция —stat.

—uname

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

—version

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

—ts-offset offset

Добавляет (вычитает при отрицательном значении) смещение ко всем временным меткам предыдущего файла данных, заданного опцией -i. Это полезно для сортируемого слияния множества файлов трассировки с разными временными метками, например, при выполнении трассировки на виртуальной машине одновременно с другой трассировкой на хосте. Если временная метка хоста опережает гостевую на 1000 единиц, можно воспользоваться командой

trace-cmd report -i host.dat --ts-offset -1000 -i guest.dat

Это будет вычитать 1000 единиц времени для всех событий на хосте при слиянии с событиями из файла guest.dat. Отметим, что единицы относятся к необработанным данным, записанным в файл. Если единицей является наносекунда, вычитаться или добавляться будут наносекунды даже при отображении времени в микросекундах.

—ts2secs HZ

Задает преобразование текущего источника времени во второй (с наносекундным разрешением) выход. При использовании часов типа x86-tsc и известной частоте время можно преобразовать в секунды путем указания частоты.

Эта опция влияет на любой файл трассировки, переданный с обработкой -i. Если опция расположена до всех опций -i, значение становится используемым по умолчанию преобразованием для всех других файлов трассировки. При наличии другой опции —ts2secs после -i trace.dat, эта опция будет переопределять принятое по умолчанию значение.

Например, при частоте 3.4 ГГц и командах

trace-cmd record -p function -C x86-tsc
trace-cmd report --ts2ns 3400000000

отчет будет преобразовывать временные метки тактов в читаемые значения секунд. По умолчанию будет применяться микросекундное разрешение, если не задана опция -t.

Значение —ts-offset должно оставаться в единицах необработанных меток даже при наличии этой опции, поскольку сдвиг также будет преобразован.

—ts-diff

Показывает временную разницу между событиями (в скобках после временной метки).

Примеры

При использовании файла trace.dat, созданного командой

# trace-cmd record -p function -e all sleep 5

отчет по умолчанию будет иметь вид

# trace-cmd report
	trace-cmd-16129 [002] 158126.498411: function: __mutex_unlock_slowpath <-- mutex_unlock 
	trace-cmd-16131 [000] 158126.498411: kmem_cache_alloc: call_site=811223c5 ptr=0xffff88003ecf2b40 bytes_req=272 bytes_alloc=320 gfp_flags=GFP_KERNEL|GFP_ZERO 
	trace-cmd-16130 [003] 158126.498411: function:             do_splice_to <-- sys_splice 
		sleep-16133 [001] 158126.498412: function: inotify_inode_queue_event <-- vfs_write 
	trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key 
	trace-cmd-16131 [000] 158126.498421: function: security_file_alloc <-- get_empty_filp 
		sleep-16133 [001] 158126.498422: function: __fsnotify_parent <-- vfs_write 
	trace-cmd-16130 [003] 158126.498422: function: rw_verify_area <-- do_splice_to 
	trace-cmd-16131 [000] 158126.498424: function: cap_file_alloc_security <-- security_file_alloc 
	trace-cmd-16129 [002] 158126.498425: function: syscall_trace_leave <-- int_check_syscall_exit_work 
		sleep-16133 [001] 158126.498426: function: inotify_dentry_parent_queue_event <-- vfs_write 
	trace-cmd-16130 [003] 158126.498426: function: security_file_permission <-- rw_verify_area 
	trace-cmd-16129 [002] 158126.498428: function: audit_syscall_exit <-- syscall_trace_leave 
	[…]

Для просмотра без трассировки функций служит команда

# trace-cmd report -v -F 'function' 
	trace-cmd-16131 [000] 158126.498411: kmem_cache_alloc: call_site=811223c5 ptr=0xffff88003ecf2b40 bytes_req=272 bytes_alloc=320 gfp_flags=GFP_KERNEL|GFP_ZERO 
	trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key 
	trace-cmd-16130 [003] 158126.498436: lock_acquire: 0xffffffff8166bf78 read all_cpu_access_lock 
	trace-cmd-16131 [000] 158126.498438: lock_acquire: 0xffff88003df5b520 read &fs->lock 
	trace-cmd-16129 [002] 158126.498446: kfree: call_site=810a7abb ptr=0x0 
	trace-cmd-16130 [003] 158126.498448: lock_acquire: 0xffff880002250a80 &per_cpu(cpu_access_lock, cpu) 
	trace-cmd-16129 [002] 158126.498450: sys_exit_splice:      0xfffffff5 
	trace-cmd-16131 [000] 158126.498454: lock_release: 0xffff88003df5b520 &fs->lock 
		sleep-16133 [001] 158126.498456: kfree: call_site=810a7abb ptr=0x0 
		sleep-16133 [001] 158126.498460: sys_exit_write:       0x1 
	trace-cmd-16130 [003] 158126.498462: kmalloc: call_site=810bf95b ptr=0xffff88003dedc040 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO

Для просмотра лишь вызовов kmalloc с размером больше 1000 служит команда

#trace-cmd report -F 'kmalloc: bytes_req > 1000' 
	<idle>-0     [000] 158128.126641: kmalloc: call_site=81330635 ptr=0xffff88003c2fd000 bytes_req=2096 bytes_alloc=4096 gfp_flags=GFP_ATOMIC

Для просмотра пробуждений и sched_switch, оставивших предыдущую задачу в рабочем состоянии, служит команда

# trace-cmd report -F 'sched: prev_state == 0 || (success == 1)' 
trace-cmd-16132 [002] 158126.499951: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002 
trace-cmd-16132 [002] 158126.500401: sched_switch: prev_comm=trace-cmd prev_pid=16132 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16129 next_prio=120 
	<idle>-0     [003] 158126.500585: sched_wakeup: comm=trace-cmd pid=16130 prio=120 success=1 target_cpu=003 
	<idle>-0     [003] 158126.501241: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16130 next_prio=120 
trace-cmd-16132 [000] 158126.502475: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
trace-cmd-16131 [002] 158126.506516: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002 <idle>-0     [003] 158126.550110: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16130 next_prio=120 
trace-cmd-16131 [003] 158126.570243: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=003 trace-cmd-16130 [002] 158126.618202: sched_switch: prev_comm=trace-cmd prev_pid=16130 prev_prio=120 prev_state=R ==> next_comm=yum-updatesd next_pid=3088 next_prio=1 20 
trace-cmd-16129 [003] 158126.622379: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003 trace-cmd-16129 [000] 158126.649287: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000

Приведенный выше пример требует некоторых пояснений. Фильтр задает подсистему sched, включающую события sched_switch и sched_wakeup. Любое событие, не имеющее поля формата prev_state или success, будет давать для выражения значение FALSE (отсутствие совпадения). Использование || будет задавать проверку prev_state для sched_switch и success для sched_wakeup.

# trace-cmd report -w -F 'sched_switch, sched_wakeup.*' 
 [...] 
trace-cmd-16130 [003] 158131.580616: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003 
trace-cmd-16129 [000] 158131.581502: sched_switch: prev_comm=trace-cmd prev_pid=16129 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=16131 next_prio=120 Latency: 885.901 usecs 
trace-cmd-16131 [000] 158131.582414: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=000 
trace-cmd-16132 [001] 158131.583219: sched_switch: prev_comm=trace-cmd prev_pid=16132 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=16129 next_prio=120 Latency: 804.809 usecs 
sleep-16133 [002] 158131.584121: sched_wakeup: comm=trace-cmd pid=16120 prio=120 success=1 target_cpu=002 
trace-cmd-16129 [001] 158131.584128: sched_wakeup: comm=trace-cmd pid=16132 prio=120 success=1 target_cpu=001 
sleep-16133 [002] 158131.584275: sched_switch: prev_comm=sleep prev_pid=16133 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16120 next_prio=120 Latency: 153.915 usecs 
trace-cmd-16130 [003] 158131.585284: sched_switch: prev_comm=trace-cmd prev_pid=16130 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=16132 next_prio=120 Latency: 1155.677 usecs

Average wakeup latency: 26626.656 usecs

Приведенная выше трассировка показывает задержку пробуждения задач. Событие sched_switch указывает отдельную задержку после записи информации о событии. В конце отчета указана средняя задержка пробуждения.

# trace-cmd report -w -F 'sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100' 
	<idle>-0     [003] 158131.516753: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003 
	<idle>-0     [003] 158131.516855: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/3 next_pid=13 next_prio=49 Latency: 101.244 usecs 
	<idle>-0     [003] 158131.533781: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003 
	<idle>-0     [003] 158131.533897: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/3 next_pid=13 next_prio=49 Latency: 115.608 usecs 
	<idle>-0     [003] 158131.569730: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003 
	<idle>-0     [003] 158131.569851: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/3 next_pid=13 next_prio=49 Latency: 121.024 usecs 

	Average wakeup latency: 110.021 usecs

Приведенный выше вариант показывает лишь пробуждения и переключатели контекста задач Real Time. Используемый в ядре приоритет prio имеет значение 0 в качестве максимального приоритета. Это значение 0 эквивалентно приоритету 99 в пользовательском пространстве, а пользовательский приоритет 98 эквивалентен приоритету 1 в ядре. Значения prio меньше 100 представляют задачи в реальном масштабе времени (Real Time).

Ниже приведен пример профиля.

# trace-cmd record --profile sleep 1 
           # trace-cmd report --profile --comm sleep 
          task: sleep-21611 
            Event: sched_switch:R (1) Total: 99442 Avg: 99442 Max: 99442 Min:99442 
               <stack> 1 total:99442 min:99442 max:99442 avg=99442 
                 => ftrace_raw_event_sched_switch (0xffffffff8105f812) 
                 => __schedule (0xffffffff8150810a) 
                 => preempt_schedule (0xffffffff8150842e) 
                 => ___preempt_schedule (0xffffffff81273354) 
                 => cpu_stop_queue_work (0xffffffff810b03c5) 
                 => stop_one_cpu (0xffffffff810b063b) 
                 => sched_exec (0xffffffff8106136d) 
                 => do_execve_common.isra.27 (0xffffffff81148c89) 
                 => do_execve (0xffffffff811490b0) 
                 => SyS_execve (0xffffffff811492c4) 
                 => return_to_handler (0xffffffff8150e3c8) 
                 => stub_execve (0xffffffff8150c699) 
            Event: sched_switch:S (1) Total: 1000506680 Avg: 1000506680 Max: 1000506680 Min:1000506680 
               <stack> 1 total:1000506680 min:1000506680 max:1000506680 avg=1000506680 
                 => ftrace_raw_event_sched_switch (0xffffffff8105f812) 
                 => __schedule (0xffffffff8150810a) 
                 => schedule (0xffffffff815084b8) 
                 => do_nanosleep (0xffffffff8150b22c) 
                 => hrtimer_nanosleep (0xffffffff8108d647) 
                 => SyS_nanosleep (0xffffffff8108d72c) 
                 => return_to_handler (0xffffffff8150e3c8) 
                 => tracesys_phase2 (0xffffffff8150c304) 
            Event: sched_wakeup:21611 (1) Total: 30326 Avg: 30326 Max: 30326 Min:30326 
               <stack> 1 total:30326 min:30326 max:30326 avg=30326 
                 => ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653) 
                 => ttwu_do_wakeup (0xffffffff810606eb) 
                 => ttwu_do_activate.constprop.124 (0xffffffff810607c8) 
                 => try_to_wake_up (0xffffffff8106340a)

profile

Профилировка работы задачи.

Синтаксис

trace-cmd profile [OPTIONS] [command]

Описание

Команда trace-cmd profile будет запускать трассировку, подобно команде trace-cmd record —profile, за исключением того, что запись в файл не будет осуществляться и события будут считываться по мере возникновения с одновременным их учетом. По завершении трассировки будет выводиться отчет как по команде trace-cmd report —profile. Иными словами, команда profile работает подобно trace-cmd record —profile и trace-cmd report —profile без промежуточной записи данных на диск.

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

Эта команда включает некоторые события, а также трассировщик function_graph с глубиной 1 (если поддерживает ядро). Это позволяет видеть вход задач в ядро и выход из него, а также продолжительность обработки в ядре.

Для запрета вызова function_graph служит опция -p, включающая другой трассировщик. Для отключения всех трассировщиков служит -p nop.

Время при профилировании указывается в наносекундах.

Опции

Команда использует те же опции, что и trace-cmd record —profile.

-p tracer

Задает плагин трассировки для использования вместо function_graph с глубиной 1. Для отключения всех трассировщиков служит -p nop.

-S

Включает лишь трассировщик или события, указанные в командной строке. С этой опцией трассировщик function_graph, равно как и другие события (такие как sched_switch) не включаются, пока не указаны явно в командной строке (например, -p function -e sched_switch -e sched_wakeup).

-G

Устанавливает события прерываний (программных и аппаратных) как глобальные (связанные с CPU, а не задачей).

-o file

Задает запись профиля в файл file. Это заменяет опцию —stderr.

-H event-hooks

Добавляет пользовательское сопоставление событий для связывания вместе пары событий в формате

[<start_system>:]<start_event>,<start_match>[,<start_pid>]/ [<end_system>:]<end_event>,<end_match>[,<flags>]

Поле start_system:start_event (start_system не обязательно) указывает событие, с которого начинается отсчет времени. Поле start_match в стартовом событии служит для сопоставления с полем end_match в финальном событии. Параметр start_pid является необязательным, поскольку сопоставления присоединяются к задачам, которые запускают события. Если для поиска этой задачи следует применять другое поле, оно указывается start_pid. Параметр end_system:end_event указывает событие, на котором завершается отсчет времени (end_system не обязательно). Поле end_match в финальном событии сопоставляется с полем start_match в стартовом событии. Необязательное поле может включать приведенные ниже флаги (без учета регистра).

p — два события привязаны к одному CPU (начало и завершение всегда происходят на одном CPU).

s — событию следует иметь отслеживаемый стек (включается трассировка стека для стартового события).

g — событие является глобальным (не связано с задачей). Параметр start_pid не применим с этим флагом.

—stderr

Перенаправляет вывод профиля в stderr, не изменяя вывода трассируемой команды. Это позволяет видеть вывод команды, сохраняя вывод профиля в другом файле.

Примеры

# trace-cmd profile -F sleep 1 
[..] 
          task: sleep-1121 
            Event: sched_switch:R (2) Total: 234559 Avg: 117279 Max: 129886 Min:104673 
                    | 
                    + ftrace_raw_event_sched_switch (0xffffffff8109f310) 
                        100% (2) time:234559 max:129886 min:104673 avg:117279 
                         __schedule (0xffffffff816c1e81) 
                         preempt_schedule (0xffffffff816c236e) 
                         ___preempt_schedule (0xffffffff81351a59) 
                          | 
                          + unmap_single_vma (0xffffffff81198c05) 
                          |   55% (1) time:129886 max:129886 min:0 avg:129886 
                          |    stop_one_cpu (0xffffffff8110909a) 
                          |    sched_exec (0xffffffff810a119b) 
                          |    do_execveat_common.isra.31 (0xffffffff811de528) 
                          |    do_execve (0xffffffff811dea8c) 
                          |    SyS_execve (0xffffffff811ded1e) 
                          |    return_to_handler (0xffffffff816c8458) 
                          |    stub_execve (0xffffffff816c6929) 
                          | 
                          + unmap_single_vma (0xffffffff81198c05) 
                              45% (1) time:104673 max:104673 min:0 avg:104673 
                               unmap_vmas (0xffffffff81199174) 
                               exit_mmap (0xffffffff811a1f5b) 
                               mmput (0xffffffff8107699a) 
                               flush_old_exec (0xffffffff811ddb75)
                               load_elf_binary (0xffffffff812287df) 
                               search_binary_handler (0xffffffff811dd3e0) 
                               do_execveat_common.isra.31 (0xffffffff811de8bd) 
                               do_execve (0xffffffff811dea8c) 
                               SyS_execve (0xffffffff811ded1e) 
                               return_to_handler (0xffffffff816c8458) 
                               stub_execve (0xffffffff816c6929) 

          Event: sched_switch:S (1) Total: 1000513242 Avg: 1000513242 Max: 1000513242 Min:1000513242 
                  | 
                  + ftrace_raw_event_sched_switch (0xffffffff8109f310) 
                      100% (1) time:1000513242 max:1000513242 min:0 avg:1000513242 
                       __schedule (0xffffffff816c1e81) 
                       schedule (0xffffffff816c23b9) 
                       do_nanosleep (0xffffffff816c4f1c) 
                       hrtimer_nanosleep (0xffffffff810dcd86) 
                       SyS_nanosleep (0xffffffff810dcea6) 
                       return_to_handler (0xffffffff816c8458) 
                       tracesys_phase2 (0xffffffff816c65b0) 

          Event: sched_wakeup:1121 (1) Total: 43405 Avg: 43405 Max: 43405 Min:43405 
                  | 
                  + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 
                      100% (1) time:43405 max:43405 min:0 avg:43405 
                       ttwu_do_wakeup (0xffffffff810a01a2) 
                       ttwu_do_activate.constprop.122 (0xffffffff810a0236) 
                       try_to_wake_up (0xffffffff810a3ec3) 
                       wake_up_process (0xffffffff810a4057) 
                       hrtimer_wakeup (0xffffffff810db772) 
                       __run_hrtimer (0xffffffff810dbd91) 
                       hrtimer_interrupt (0xffffffff810dc6b7) 
                       local_apic_timer_interrupt (0xffffffff810363e7) 
                       smp_trace_apic_timer_interrupt (0xffffffff816c8c6a) 
                       trace_apic_timer_interrupt (0xffffffff816c725a) 
                       finish_task_switch (0xffffffff8109c3a4) 
                       __schedule (0xffffffff816c1e01) 
                       schedule (0xffffffff816c23b9) 
                       ring_buffer_wait (0xffffffff811323a3) 
                       wait_on_pipe (0xffffffff81133d93) 
                       tracing_buffers_splice_read (0xffffffff811350b0) 
                       do_splice_to (0xffffffff8120476f) 
                       SyS_splice (0xffffffff81206c1f) 
                       tracesys_phase2 (0xffffffff816c65b0) 

          Event: func: sys_nanosleep() (1) Total: 1000598016 Avg: 1000598016 Max: 1000598016 Min:1000598016 
          Event: func: sys_munmap() (1) Total: 14300 Avg: 14300 Max: 14300 Min:14300 
          Event: func: sys_arch_prctl() (1) Total: 571 Avg: 571 Max: 571 Min:571 
          Event: func: sys_mprotect() (4) Total: 14382 Avg: 3595 Max: 7196 Min:2190 
          Event: func: SyS_read() (1) Total: 2640 Avg: 2640 Max: 2640 Min:2640 
          Event: func: sys_close() (5) Total: 4001 Avg: 800 Max: 1252 Min:414
          Event: func: sys_newfstat() (3) Total: 11684 Avg: 3894 Max: 10206 Min:636 
          Event: func: SyS_open() (3) Total: 23615 Avg: 7871 Max: 10535 Min:4743 
          Event: func: sys_access() (1) Total: 5924 Avg: 5924 Max: 5924 Min:5924 
          Event: func: SyS_mmap() (8) Total: 39153 Avg: 4894 Max: 12354 Min:1518 
          Event: func: smp_trace_apic_timer_interrupt() (1) Total: 10298 Avg: 10298 Max: 10298 Min:10298 
          Event: func: SyS_brk() (4) Total: 2407 Avg: 601 Max: 1564 Min:206 
          Event: func: do_notify_resume() (2) Total: 4095 Avg: 2047 Max: 2521 Min:1574 
          Event: func: sys_execve() (5) Total: 1625251 Avg: 325050 Max: 1605698 Min:3570 
                  | 
                  + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 
                      100% (1) time:1605698 max:1605698 min:0 avg:1605698 
                       ttwu_do_wakeup (0xffffffff810a01a2) 
                       ttwu_do_activate.constprop.122 (0xffffffff810a0236) 
                       try_to_wake_up (0xffffffff810a3ec3) 
                       wake_up_process (0xffffffff810a4057) 
                       cpu_stop_queue_work (0xffffffff81108df8) 
                       stop_one_cpu (0xffffffff8110909a) 
                       sched_exec (0xffffffff810a119b) 
                       do_execveat_common.isra.31 (0xffffffff811de528) 
                       do_execve (0xffffffff811dea8c) 
                       SyS_execve (0xffffffff811ded1e) 
                       return_to_handler (0xffffffff816c8458) 
                       stub_execve (0xffffffff816c6929) 
                       stub_execve (0xffffffff816c6929) 

          Event: func: syscall_trace_enter_phase2() (38) Total: 21544 Avg: 566 Max: 1066 Min:329 
          Event: func: syscall_trace_enter_phase1() (38) Total: 9202 Avg: 242 Max: 376 Min:150 
          Event: func: __do_page_fault() (53) Total: 257672 Avg: 4861 Max: 27745 Min:458 
                  | 
                  + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 
                      100% (1) time:27745 max:27745 min:0 avg:27745 
                       ttwu_do_wakeup (0xffffffff810a01a2) 
                       ttwu_do_activate.constprop.122 (0xffffffff810a0236) 
                       try_to_wake_up (0xffffffff810a3ec3) 
                       default_wake_function (0xffffffff810a4002) 
                       autoremove_wake_function (0xffffffff810b50fd) 
                       __wake_up_common (0xffffffff810b4958) 
                       __wake_up (0xffffffff810b4cb8) 
                       rb_wake_up_waiters (0xffffffff8112f126) 
                       irq_work_run_list (0xffffffff81157d0f) 
                       irq_work_run (0xffffffff81157d5e) 
                       smp_trace_irq_work_interrupt (0xffffffff810082fc) 
                       trace_irq_work_interrupt (0xffffffff816c7aaa) 
                       return_to_handler (0xffffffff816c8458) 
                       trace_do_page_fault (0xffffffff810478b2) 
                       trace_page_fault (0xffffffff816c7dd2) 

          Event: func: syscall_trace_leave() (38) Total: 26145 Avg: 688 Max: 1264 Min:381 
          Event: func: __sb_end_write() (1) Total: 373 Avg: 373 Max: 373 Min:373 
          Event: func: fsnotify() (1) Total: 598 Avg: 598 Max: 598 Min:598
          Event: func: __fsnotify_parent() (1) Total: 286 Avg: 286 Max: 286 Min:286 
          Event: func: mutex_unlock() (2) Total: 39636 Avg: 19818 Max: 39413 Min:223 
          Event: func: smp_trace_irq_work_interrupt() (6) Total: 236459 Avg: 39409 Max: 100671 Min:634 
                  | 
                  + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 
                      100% (4) time:234348 max:100671 min:38745 avg:58587 
                       ttwu_do_wakeup (0xffffffff810a01a2) 
                       ttwu_do_activate.constprop.122 (0xffffffff810a0236) 
                       try_to_wake_up (0xffffffff810a3ec3) 
                       default_wake_function (0xffffffff810a4002) 
                       autoremove_wake_function (0xffffffff810b50fd) 
                       __wake_up_common (0xffffffff810b4958) 
                       __wake_up (0xffffffff810b4cb8) 
                       rb_wake_up_waiters (0xffffffff8112f126) 
                       irq_work_run_list (0xffffffff81157d0f) 
                       irq_work_run (0xffffffff81157d5e) 
                       smp_trace_irq_work_interrupt (0xffffffff810082fc) 
                       return_to_handler (0xffffffff816c8458) 
                       trace_irq_work_interrupt (0xffffffff816c7aaa) 
                        | 
                        + ftrace_return_to_handler (0xffffffff81140840) 
                        |   84% (3) time:197396 max:100671 min:38745 avg:65798 
                        |    return_to_handler (0xffffffff816c846d) 
                        |    trace_page_fault (0xffffffff816c7dd2) 
                        | 
                        + ftrace_return_to_handler (0xffffffff81140840) 
                            16% (1) time:36952 max:36952 min:0 avg:36952 
                             ftrace_graph_caller (0xffffffff816c8428) 
                             mutex_unlock (0xffffffff816c3f75) 
                             rb_simple_write (0xffffffff81133142) 
                             vfs_write (0xffffffff811d7727) 
                             SyS_write (0xffffffff811d7acf) 
                             tracesys_phase2 (0xffffffff816c65b0) 

          Event: sys_enter:35 (1) Total: 1000599765 Avg: 1000599765 Max: 1000599765 Min:1000599765 
          Event: sys_enter:11 (1) Total: 55025 Avg: 55025 Max: 55025 Min:55025 
          Event: sys_enter:158 (1) Total: 1584 Avg: 1584 Max: 1584 Min:1584 
          Event: sys_enter:10 (4) Total: 18359 Avg: 4589 Max: 8764 Min:2933 
          Event: sys_enter:0 (1) Total: 4223 Avg: 4223 Max: 4223 Min:4223 
          Event: sys_enter:3 (5) Total: 9948 Avg: 1989 Max: 2606 Min:1203 
          Event: sys_enter:5 (3) Total: 15530 Avg: 5176 Max: 11840 Min:1405 
          Event: sys_enter:2 (3) Total: 28002 Avg: 9334 Max: 12035 Min:5656 
          Event: sys_enter:21 (1) Total: 7814 Avg: 7814 Max: 7814 Min:7814 
          Event: sys_enter:9 (8) Total: 49583 Avg: 6197 Max: 14137 Min:2362 
          Event: sys_enter:12 (4) Total: 108493 Avg: 27123 Max: 104079 Min:922 
          Event: sys_enter:59 (5) Total: 1631608 Avg: 326321 Max: 1607529 Min:4563 
          Event: page_fault_user:0x398d86b630 (1) 
          Event: page_fault_user:0x398d844de0 (1) 
          Event: page_fault_user:0x398d8d9020 (1) 
          Event: page_fault_user:0x1d37008 (1)
          Event: page_fault_user:0x7f0b89e91074 (1) 
          Event: page_fault_user:0x7f0b89d98ed0 (1) 
          Event: page_fault_user:0x7f0b89ec8950 (1) 
          Event: page_fault_user:0x7f0b89d83644 (1) 
          Event: page_fault_user:0x7f0b89d622a8 (1) 
          Event: page_fault_user:0x7f0b89d5a560 (1) 
          Event: page_fault_user:0x7f0b89d34010 (1) 
          Event: page_fault_user:0x1d36008 (1) 
          Event: page_fault_user:0x398d900510 (1) 
          Event: page_fault_user:0x398dbb3ae8 (1) 
          Event: page_fault_user:0x398d87f490 (1) 
          Event: page_fault_user:0x398d8eb660 (1) 
          Event: page_fault_user:0x398d8bd730 (1) 
          Event: page_fault_user:0x398d9625d9 (1) 
          Event: page_fault_user:0x398d931810 (1) 
          Event: page_fault_user:0x398dbb7114 (1) 
          Event: page_fault_user:0x398d837610 (1) 
          Event: page_fault_user:0x398d89e860 (1) 
          Event: page_fault_user:0x398d8f23b0 (1) 
          Event: page_fault_user:0x398dbb4510 (1) 
          Event: page_fault_user:0x398dbad6f0 (1) 
          Event: page_fault_user:0x398dbb1018 (1) 
          Event: page_fault_user:0x398d977b37 (1) 
          Event: page_fault_user:0x398d92eb60 (1) 
          Event: page_fault_user:0x398d8abff0 (1) 
          Event: page_fault_user:0x398dbb0d30 (1) 
          Event: page_fault_user:0x398dbb6c24 (1) 
          Event: page_fault_user:0x398d821c50 (1) 
          Event: page_fault_user:0x398dbb6c20 (1) 
          Event: page_fault_user:0x398d886350 (1) 
          Event: page_fault_user:0x7f0b90125000 (1) 
          Event: page_fault_user:0x7f0b90124740 (1) 
          Event: page_fault_user:0x7f0b90126000 (1) 
          Event: page_fault_user:0x398d816230 (1) 
          Event: page_fault_user:0x398d8002b8 (1) 
          Event: page_fault_user:0x398dbb0b40 (1) 
          Event: page_fault_user:0x398dbb2880 (1) 
          Event: page_fault_user:0x7f0b90141cc6 (1) 
          Event: page_fault_user:0x7f0b9013b85c (1) 
          Event: page_fault_user:0x7f0b90127000 (1) 
          Event: page_fault_user:0x606e70 (1) 
          Event: page_fault_user:0x7f0b90144010 (1) 
          Event: page_fault_user:0x7fffcb31b038 (1) 
          Event: page_fault_user:0x606da8 (1) 
          Event: page_fault_user:0x400040 (1) 
          Event: page_fault_user:0x398d222218 (1) 
          Event: page_fault_user:0x398d015120 (1) 
          Event: page_fault_user:0x398d220ce8 (1) 
          Event: page_fault_user:0x398d220b80 (1) 
          Event: page_fault_user:0x7fffcb2fcff8 (1)
          Event: page_fault_user:0x398d001590 (1) 
          Event: page_fault_user:0x398d838490 (1) 
          Event: softirq_raise:RCU (3) Total: 252931 Avg: 84310 Max: 243288 Min:4639 
          Event: softirq_raise:SCHED (2) Total: 241249 Avg: 120624 Max: 239076 Min:2173 
                  | 
                  + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 
                      100% (1) time:239076 max:239076 min:0 avg:239076 
                       ttwu_do_wakeup (0xffffffff810a01a2) 
                       ttwu_do_activate.constprop.122 (0xffffffff810a0236) 
                       try_to_wake_up (0xffffffff810a3ec3) 
                       default_wake_function (0xffffffff810a4002) 
                       autoremove_wake_function (0xffffffff810b50fd) 
                       __wake_up_common (0xffffffff810b4958) 
                       __wake_up (0xffffffff810b4cb8) 
                       rb_wake_up_waiters (0xffffffff8112f126) 
                       irq_work_run_list (0xffffffff81157d0f) 
                       irq_work_run (0xffffffff81157d5e) 
                       smp_trace_irq_work_interrupt (0xffffffff810082fc) 
                       trace_irq_work_interrupt (0xffffffff816c7aaa) 
                       irq_exit (0xffffffff8107dd66) 
                       smp_trace_apic_timer_interrupt (0xffffffff816c8c7a) 
                       trace_apic_timer_interrupt (0xffffffff816c725a) 
                       prepare_ftrace_return (0xffffffff8103d4fd) 
                       ftrace_graph_caller (0xffffffff816c8428) 
                       mem_cgroup_begin_page_stat (0xffffffff811cfd25) 
                       page_remove_rmap (0xffffffff811a4fc5) 
                       stub_execve (0xffffffff816c6929) 
                       unmap_single_vma (0xffffffff81198b1c) 
                       unmap_vmas (0xffffffff81199174) 
                       exit_mmap (0xffffffff811a1f5b) 
                       mmput (0xffffffff8107699a) 
                       flush_old_exec (0xffffffff811ddb75) 
                       load_elf_binary (0xffffffff812287df) 
                       search_binary_handler (0xffffffff811dd3e0) 
                       do_execveat_common.isra.31 (0xffffffff811de8bd) 
                       do_execve (0xffffffff811dea8c) 
                       SyS_execve (0xffffffff811ded1e) 
                       return_to_handler (0xffffffff816c8458) 

          Event: softirq_raise:HI (3) Total: 72472 Avg: 24157 Max: 64186 Min:3430 
          Event: softirq_entry:RCU (2) Total: 3191 Avg: 1595 Max: 1788 Min:1403 
                  | 
                  + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 
                      100% (1) time:1788 max:1788 min:0 avg:1788 
                       ttwu_do_wakeup (0xffffffff810a01a2) 
                       ttwu_do_activate.constprop.122 (0xffffffff810a0236) 
                       try_to_wake_up (0xffffffff810a3ec3) 
                       default_wake_function (0xffffffff810a4002) 
                       autoremove_wake_function (0xffffffff810b50fd) 
                       __wake_up_common (0xffffffff810b4958)
                       __wake_up (0xffffffff810b4cb8) 
                       rb_wake_up_waiters (0xffffffff8112f126) 
                       irq_work_run_list (0xffffffff81157d0f) 
                       irq_work_run (0xffffffff81157d5e) 
                       smp_trace_irq_work_interrupt (0xffffffff810082fc) 
                       trace_irq_work_interrupt (0xffffffff816c7aaa) 
                       irq_work_queue (0xffffffff81157e95) 
                       ring_buffer_unlock_commit (0xffffffff8113039f) 
                       __buffer_unlock_commit (0xffffffff811367d5) 
                       trace_buffer_unlock_commit (0xffffffff811376a2) 
                       ftrace_event_buffer_commit (0xffffffff81146d5f) 
                       ftrace_raw_event_sched_process_exec (0xffffffff8109c511) 
                       do_execveat_common.isra.31 (0xffffffff811de9a3) 
                       do_execve (0xffffffff811dea8c) 
                       SyS_execve (0xffffffff811ded1e) 
                       return_to_handler (0xffffffff816c8458) 
                       stub_execve (0xffffffff816c6929) 

           Event: softirq_entry:SCHED (2) Total: 2289 Avg: 1144 Max: 1350 Min:939 
           Event: softirq_entry:HI (3) Total: 180146 Avg: 60048 Max: 178969 Min:499 
                   | 
                   + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 
                       100% (1) time:178969 max:178969 min:0 avg:178969 
                        ttwu_do_wakeup (0xffffffff810a01a2) 
                        ttwu_do_activate.constprop.122 (0xffffffff810a0236) 
                        try_to_wake_up (0xffffffff810a3ec3) 
                        wake_up_process (0xffffffff810a4057) 
                        wake_up_worker (0xffffffff8108de74) 
                        insert_work (0xffffffff8108fca6) 
                        __queue_work (0xffffffff8108fe12) 
                        delayed_work_timer_fn (0xffffffff81090088) 
                        call_timer_fn (0xffffffff810d8f89) 
                        run_timer_softirq (0xffffffff810da8a1) 
                        __do_softirq (0xffffffff8107d8fa) 
                        irq_exit (0xffffffff8107dd66) 
                        smp_trace_apic_timer_interrupt (0xffffffff816c8c7a) 
                        trace_apic_timer_interrupt (0xffffffff816c725a) 
                        prepare_ftrace_return (0xffffffff8103d4fd) 
                        ftrace_graph_caller (0xffffffff816c8428) 
                        mem_cgroup_begin_page_stat (0xffffffff811cfd25) 
                        page_remove_rmap (0xffffffff811a4fc5) 
                        stub_execve (0xffffffff816c6929) 
                        unmap_single_vma (0xffffffff81198b1c) 
                        unmap_vmas (0xffffffff81199174) 
                        exit_mmap (0xffffffff811a1f5b) 
                        mmput (0xffffffff8107699a) 
                        flush_old_exec (0xffffffff811ddb75) 
                        load_elf_binary (0xffffffff812287df) 
                        search_binary_handler (0xffffffff811dd3e0) 
                        do_execveat_common.isra.31 (0xffffffff811de8bd)
                        do_execve (0xffffffff811dea8c) 
                        SyS_execve (0xffffffff811ded1e) 
                        return_to_handler (0xffffffff816c8458)

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

Другие задачи тоже будут включены в профиль, если события указывают более одной задачи (подобно sched_switch и sched_wakeup — prev_pid и next_pid для sched_switch, common_pid и pid для sched_wakeup).

Трассировки стека присоединяются к событиям, с которыми они связаны.

Рассмотрим приведенный ниже вывод.

Event: sched_switch:R (2) Total: 234559 Avg: 117279 Max: 129886 Min:104673

Это показывает, что задача была вытеснена (находится в состоянии R). Задача была вытеснена дважды в целом на 234559 нсек со средним временем вытеснения 117279 нсек, максимальным 128886 нсек и минимальным 104673 нсек.

Дерево ниже показывает точки вытеснения.

          | 
          + ftrace_raw_event_sched_switch (0xffffffff8109f310) 
              100% (2) time:234559 max:129886 min:104673 avg:117279 
               __schedule (0xffffffff816c1e81) 
               preempt_schedule (0xffffffff816c236e) 
               ___preempt_schedule (0xffffffff81351a59) 
                | 
                + unmap_single_vma (0xffffffff81198c05) 
                |   55% (1) time:129886 max:129886 min:0 avg:129886 
                |    stop_one_cpu (0xffffffff8110909a) 
                |    sched_exec (0xffffffff810a119b) 
                |    do_execveat_common.isra.31 (0xffffffff811de528) 
                |    do_execve (0xffffffff811dea8c) 
                |    SyS_execve (0xffffffff811ded1e) 
                |    return_to_handler (0xffffffff816c8458) 
                |    stub_execve (0xffffffff816c6929) 
                | 
                + unmap_single_vma (0xffffffff81198c05) 
                    45% (1) time:104673 max:104673 min:0 avg:104673 
                     unmap_vmas (0xffffffff81199174) 
                     exit_mmap (0xffffffff811a1f5b) 
                     mmput (0xffffffff8107699a) 
                     flush_old_exec (0xffffffff811ddb75) 
                     load_elf_binary (0xffffffff812287df) 
                     search_binary_handler (0xffffffff811dd3e0) 
                     do_execveat_common.isra.31 (0xffffffff811de8bd) 
                     do_execve (0xffffffff811dea8c) 
                     SyS_execve (0xffffffff811ded1e) 
                     return_to_handler (0xffffffff816c8458)
                     stub_execve (0xffffffff816c6929) 

          Event: sched_switch:S (1) Total: 1000513242 Avg: 1000513242 Max: 1000513242 Min:10005132

Это показывает, что задача была запланирована в состоянии INTERRUPTIBLE (прерываемая) один раз на суммарное время 1000513242 нсек (~1 сек.), что соответствует sleep 1.

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

Event: func: sys_nanosleep() (1) Total: 1000598016 Avg: 1000598016 Max: 1000598016 Min:1000598016 
Event: func: sys_munmap() (1) Total: 14300 Avg: 14300 Max: 14300 Min:14300 
Event: func: sys_arch_prctl() (1) Total: 571 Avg: 571 Max: 571 Min:571 
Event: func: sys_mprotect() (4) Total: 14382 Avg: 3595 Max: 7196 Min:2190 
Event: func: SyS_read() (1) Total: 2640 Avg: 2640 Max: 2640 Min:2640 
Event: func: sys_close() (5) Total: 4001 Avg: 800 Max: 1252 Min:414 
Event: func: sys_newfstat() (3) Total: 11684 Avg: 3894 Max: 10206 Min:636 
Event: func: SyS_open() (3) Total: 23615 Avg: 7871 Max: 10535 Min:4743 
Event: func: sys_access() (1) Total: 5924 Avg: 5924 Max: 5924 Min:5924 
Event: func: SyS_mmap() (8) Total: 39153 Avg: 4894 Max: 12354 Min:1518 
Event: func: smp_trace_apic_timer_interrupt() (1) Total: 10298 Avg: 10298 Max: 10298 Min:10298 
Event: func: SyS_brk() (4) Total: 2407 Avg: 601 Max: 1564 Min:206 
Event: func: do_notify_resume() (2) Total: 4095 Avg: 2047 Max: 2521 Min:1574 
Event: func: sys_execve() (5) Total: 1625251 Avg: 325050 Max: 1605698 Min:3570 

      Count of times the event was hit is always in parenthesis (5).

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

-l 'sys_*' -l 'SyS_*'

Для полного отключения function_graph служит опция

-p nop

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

-p function

Показанные ниже функции являются записываемыми событиями.

          Event: sys_enter:35 (1) Total: 1000599765 Avg: 1000599765 Max: 1000599765 Min:1000599765 
          Event: sys_enter:11 (1) Total: 55025 Avg: 55025 Max: 55025 Min:55025 
          Event: sys_enter:158 (1) Total: 1584 Avg: 1584 Max: 1584 Min:1584 
          Event: sys_enter:10 (4) Total: 18359 Avg: 4589 Max: 8764 Min:2933 
          Event: sys_enter:0 (1) Total: 4223 Avg: 4223 Max: 4223 Min:4223 
          Event: sys_enter:3 (5) Total: 9948 Avg: 1989 Max: 2606 Min:1203 
          Event: sys_enter:5 (3) Total: 15530 Avg: 5176 Max: 11840 Min:1405 
          Event: sys_enter:2 (3) Total: 28002 Avg: 9334 Max: 12035 Min:5656 
          Event: sys_enter:21 (1) Total: 7814 Avg: 7814 Max: 7814 Min:7814
          Event: sys_enter:9 (8) Total: 49583 Avg: 6197 Max: 14137 Min:2362 
          Event: sys_enter:12 (4) Total: 108493 Avg: 27123 Max: 104079 Min:922 
          Event: sys_enter:59 (5) Total: 1631608 Avg: 326321 Max: 1607529 Min:4563

Это необработанные события системных вызовов с указанием идентификатора вызова после sys_enter:. Например, 59 — это execve. Почему эта функция вызывалась 5 раз? Рассмотрение strace показывает

          execve("/usr/lib64/ccache/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 
          <... execve resumed> )      = -1 ENOENT (No such file or directory) 
          execve("/usr/local/sbin/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 
          <... execve resumed> )      = -1 ENOENT (No such file or directory) 
          execve("/usr/local/bin/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 
          <... execve resumed> )      = -1 ENOENT (No such file or directory) 
          execve("/usr/sbin/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 
          <... execve resumed> )      = -1 ENOENT (No such file or directory) 
          execve("/usr/bin/sleep", ["sleep", "1"], [/* 27 vars */] <unfinished ...> 
          <... execve resumed> )      = 0

Видно попытку выполнить команду sleep для каждого пути в $PATH, пока не будет найден исполняемый файл.

События page_fault_user показывают, какой адрес в пользовательском пространстве принимает отказ страницы.

          Event: softirq_raise:RCU (3) Total: 252931 Avg: 84310 Max: 243288 Min:4639 
          Event: softirq_raise:SCHED (2) Total: 241249 Avg: 120624 Max: 239076 Min:2173 
                  | 
                  + ftrace_raw_event_sched_wakeup_template (0xffffffff8109d960) 
                      100% (1) time:239076 max:239076 min:0 avg:239076 
                       ttwu_do_wakeup (0xffffffff810a01a2) 
                       ttwu_do_activate.constprop.122 (0xffffffff810a0236) 
                       try_to_wake_up (0xffffffff810a3ec3) 
                       default_wake_function (0xffffffff810a4002) 
                       autoremove_wake_function (0xffffffff810b50fd) 
                       __wake_up_common (0xffffffff810b4958) 
                       __wake_up (0xffffffff810b4cb8) 
                       rb_wake_up_waiters (0xffffffff8112f126) 
                       irq_work_run_list (0xffffffff81157d0f) 
                       irq_work_run (0xffffffff81157d5e) 
                       smp_trace_irq_work_interrupt (0xffffffff810082fc) 
                       trace_irq_work_interrupt (0xffffffff816c7aaa) 
                       irq_exit (0xffffffff8107dd66)

Время событий softirq_raise измеряет интервал от поднятия softirq до момента завершения прерывания.

Время softirq_entry показывает продолжительность выполнения softirq.

Трассировка стека для softirq (и возможно других событий) используется в тех случаях, когда стек присоединен к событию. Это может происходить, если профиль запускает больше стеков, чем просто события sched, или события отбрасываются и стекируются.

Для полного контроля трассировки служит опция -S, по которой trace-cmd не будет включать трассировщики событий и function_graph, показывая лишь события, указанные в командной строке.

Если нужно видеть лишь время kmalloc и место записи, опция -S и включение трассировки стека и function_graph лишь для нужной функции будут давать профиль лишь для этой функции.

          # trace-cmd profile -S -p function_graph -l '*kmalloc*' -l '*kmalloc*:stacktrace' sleep 1 
          task: sshd-11786 
            Event: func: __kmalloc_reserve.isra.59() (2) Total: 149684 Avg: 74842 Max: 75598 Min:74086 
                    | 
                    + __alloc_skb (0xffffffff815a8917) 
                    |   67% (2) time:149684 max:75598 min:74086 avg:74842 
                    |    __kmalloc_node_track_caller (0xffffffff811c6635) 
                    |    __kmalloc_reserve.isra.59 (0xffffffff815a84ac) 
                    |    return_to_handler (0xffffffff816c8458) 
                    |    sk_stream_alloc_skb (0xffffffff81604ea1) 
                    |    tcp_sendmsg (0xffffffff8160592c) 
                    |    inet_sendmsg (0xffffffff8162fed1) 
                    |    sock_aio_write (0xffffffff8159f9fc) 
                    |    do_sync_write (0xffffffff811d694a) 
                    |    vfs_write (0xffffffff811d7825) 
                    |    SyS_write (0xffffffff811d7adf) 
                    |    system_call_fastpath (0xffffffff816c63d2) 
                    | 
                    + __alloc_skb (0xffffffff815a8917) 
                        33% (1) time:74086 max:74086 min:74086 avg:74086 
                         __alloc_skb (0xffffffff815a8917) 
                         sk_stream_alloc_skb (0xffffffff81604ea1) 
                         tcp_sendmsg (0xffffffff8160592c) 
                         inet_sendmsg (0xffffffff8162fed1) 
                         sock_aio_write (0xffffffff8159f9fc) 
                         do_sync_write (0xffffffff811d694a) 
                         vfs_write (0xffffffff811d7825) 
                         SyS_write (0xffffffff811d7adf) 
                         system_call_fastpath (0xffffffff816c63d2) 
           [..]

Для наблюдения вывода команды с сохранением вывода профиля в файл служит опция —stderr и перенаправление стандартного вывода ошибок в файл

# trace-cmd profile --stderr cyclictest -p 80 -n -t1 2> profile.out

или просто -o

# trace-cmd profile -o profile.out cyclictest -p 80 -n -t1

hist

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

Синтаксис

trace-cmd hist [OPTIONS][input-file]

Описание

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

Опции

-i input-file

По умолчанию trace-cmd hist будет считывать данные из файла trace.dat, но с помощью этой опции можно задать другой файл (input-file). Отметим, что входной файл может быть также указан последним параметром командной строки.

-P

Задает компактирование всех событий и отображение вызовов с игнорированием задач и разных PID. Вместо указания имен задач все цепочки группируются и выводятся как <all pids>.

stat

Показывает статус системы трассировки (ftrace).

Синтаксис

trace-cmd stat

Описание

Команда trace-cmd stat выводит статус системы трассировки (ftrace).

Tracer — если один из трассировщиков (таких как function_graph) активен, в остальных случаях не выводится ничего.

Events — список событий, которые разрешены.

Event filters — показывает любые фильтры, установленные для любых событий.

Function filters — показывает любые фильтры, установленные для любых трассировщиков функций.

Graph functions — показывает любые функции, которые трассировщику function_graph следует отображать.

Buffers — показывает размер буфера трассировки. По умолчанию буферы трассировки в процессе использования находятся в сжатом формате и отображение буфера не представляется.

Trace clock — если трассировочные часы отличаются от принятых по умолчанию локальных часов (local), они будут указаны.

Trace CPU mask — если не все доступные CPU попадают в маску трассировки, указывается эта маска.

Trace max latency — указывает значение максимальной задержки трассировки, если оно отлично от 0.

Kprobes — показывает любые kprobe, определенные для трассировки.

Uprobes — показывает любые uprobe, определенные для трассировки.

extract

Извлекает данные трассировщика Linux ftrace.

Синтаксис

trace-cmd extract [OPTIONS]

Описание

Команда trace-cmd extract обычно применяется после trace-cmd-start и trace-cmd-stop, а также может применяться после запуска трассировщика ftrace вручную через псевдофайловую систему.

Команда extract создает файл trace.dat, который может использоваться trace-cmd report для считывания и анализа данных. Исходные данные для создания файла trace.dat извлекаются из внутреннего кольцевого буфера ядра.

Опции

-p plugin

Хотя команда extract не запускает никакой трассировки, некоторые плагины требуют чтения вывода в формате ASCII. К ним относятся трассировщики задержки, поскольку они используют отдельный внутренний буфер. Опция нужна лишь для плагинов wakeup, wakeup-rt, irqsoff, preemptoff и preemptirqsoff.

Без этой опции команда extract будет извлекать внутренние буферы ftrace.

-O option

Если извлекается трассировка задержки и применяется опция -p, некоторые опции ftrace могут менять формат. Данная опция будет менять их до извлечения. Просмотреть опции можно с помощью команды trace-cmd list. Для включения опции указывается ее имя, для отключения имя указывается с префиксом no. Например, noprint-parent будет отключать опцию print-parent, которая выводит родительскую функцию при отображении функционального события.

-o outputfile

По умолчанию команда extract создает файл trace.dat, но с помощью этой опции можно задать иной файл для вывода.

-s

Задает извлечение данных из буфера «моментальных снимков» (snapshot), если это поддерживается ядром.

—date

То же самое, что опция trace-cmd record —date, но с отключением всей трассировки в программе извлечения. Т. е. в конце извлечения данных выполняется что-то вроде trace-cmd reset.

-B buffer-name

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

-a

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

-t

Задает извлечение данных из буфера верхнего уровня. Без опций -B или -a это обеспечивает принятое по умолчанию поведение, но при указании -B или -a данные из буфера верхнего уровня извлекается вместе с данными из указанных этими опциями буферов.

show

Показывает содержимое буфера трассировки ядра (ftrace).

Синтаксис

trace-cmd show [OPTIONS]

Описание

Команда trace-cmd show выводит содержимое одного из файлов трассировки (ftrace) ядра Linux — trace, snapshot или trace_pipe. Это эквивалентно использованию команд вида

cat /sys/kernel/debug/tracing/trace

Опции

-p

Задает вывод содержимого файла trace_pipe вместо выводимого по умолчанию trace, который является статическим (т. е. по завершении трассировки содержимое файла trace остается неизменным).

Чтение файла trace_pipe является поглощающим и данные не будут повторяться при следующем чтении. Файл при этом блокируется. Если в файле нет данных, trace-cmd show будет останавливаться и ждать их появления.

-s

Задает вывод содержимого файла snapshot вместо выводимого по умолчанию trace. Снимки делаются записывающим приложением и ядро будет переключаться между текущим активным буфером snapshot и следующим буфером. Без переключения файл snapshot является статическим. Считывание файла не поглощает данные из него.

-c cpu

Задает чтение файла trace лишь для указанного CPU.

-f

Выводит полный путь к отображаемому файлу.

-B buf

Если был создан экземпляр буфера, опция -B обеспечивает доступ к файлам, связанным с этим буфером.

—tracing_on

Указывает, включена ли трассировка на данном экземпляре.

—current_tracer

Показывает, что служит текущим трассировщиком.

—buffer_size

Показывает текущий размер буфера (на процессор)

—buffer_total_size

Показывает общий размер всех буферов.

—ftrace_filter

Показывает установленные фильтры функций.

—ftrace_notrace

Показывает, какие функции отключены установленными фильтрами.

—ftrace_pid

Показывает PID трассировщиков функций (если они есть).

—graph_function

Показывает функции, которые будут отображены.

—graph_notrace

Показывает функции, которые не будут отображены.

—cpumask

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

options

Выводит список доступных опций для плагинов trace-cmd.

Синтаксис

trace-cmd options

Описание

Команда trace-cmd options будет проверять плагины trace-cmd, используемые командой trace-cmd report, и выводить их список.

start

Запускает трассировщик ftrace без записи в файл.

Синтаксис

trace-cmd start [OPTIONS]

Описание

Команда trace-cmd start включает всю трассировку ftrace, как это делает trace-cmd record(1), но без запуска потоков для создания файла trace.dat. Это полезно, когда нужно просто включить ftrace и интересна лишь трассировка после того, как произошло некоторое событие и до момента остановки. Затем трассировку можно считать напрямую из псевдофайловой системы ftrace или извлечь с помощью команды trace-cmd extract.

Опции

Опции этой команды совпадают с опциями trace-cmd record, за исключением относящихся к записи (-s, -o, -F, -N, -t).

stop

Команда останавливает запись трассировщика ядра Linux ftrace в кольцевой буфер

Синтаксис

trace-cmd stop

Описание

Команда trace-cmd stop служит дополнением к trace-cmd-start и будет отключать запись ftrace в кольцевой буфер, не отменяя издержек, которые могут быть связаны с трассировкой. Отключается лишь обновление кольцевого буфера, но трассировка ftrace может продолжаться, создавая издержки.

После остановки команда trace-cmd extract позволяет прочитать данные из кольцевого буфера и создать файл trace.dat. Возможно также прямое считывание данных из псевдофайловой системы.

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

Опции

-B buffer-name

Если ядро поддерживает множество буферов, эта опция позволяет остановить трассировку для определенного буфера, не воздействуя на остальные. Опцию можно указать несколько раз для разных буферов. При указании этой опции экземпляр верхнего уровня не останавливается, если не была задана также опция -t.

-a

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

-t

Останавливает буфер верхнего уровня. Без опции -B или -a эта опция обеспечивает принятое по умолчанию поведение, но при наличии -B или -a, будет останавливаться также буфер верхнего уровня.

reset

Отключает все трассировки ftrace, восстанавливая полную производительность.

Синтаксис

trace-cmd reset [OPTIONS]

Описание

Команда trace-cmd reset выключает все трассировки ftrace, возвращая полную производительность системы, которая была до включения трассировки. Это нужно делать, поскольку команды trace-cmd record, trace-cmd stop и trace-cmd extract не отключают трассировщик даже после извлечения данных из буфера. Причина этого заключается в том, что пользователь может просто захотеть включить трассировщик вручную с использованием псевдофайловой системы или проверить другие части ftrace на предмет результатов работы trace-cmd. После команды reset все данные в кольцевых буферах и установленные опции будут потеряны.

Опции

Следует отметить, что для этой команды важен порядок указания опций в командной строке (см. Примеры).

-b buffer_size

При загрузке ядра кольцевой буфер ftrace имеет минимальный размер (3 страницы на CPU). При первом использовании трассировщика кольцевой буфер расширяется до установленного значения (по умолчанию 1,4 Мбайт на CPU).

Если дальнейшей трассировки не предполагается, эта опция позволяет уменьшить кольцевой буфер, сохраняя память.

trace-cmd reset -b 1

Задает воздействие на экземпляры буфера, заданные последней опцией -B, -t или -a:

при использовании после -B, изменяет размер экземпляра буфера, предшествующего опции в командной строке;

при использовании после -a меняет размер всех экземпляров буферов, за исключением верхнего уровня;

при использовании после -t или перед -B или -a, меняет размер буфера верхнего уровня.

-B buffer-name

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

-a

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

-d

Эта опция удаляет экземпляры буферов, заданные последними опциями -B или -a. Поскольку буфер верхнего уровня не может быть удален, эту опцию нельзя указывать после опции -t или перед опцией -B или -a в командной строке.

-t

Сбрасывает экземпляр буфер верхнего уровня. Без опции -B или -a эта опция обеспечивает принятое по умолчанию поведение, но при наличии -B или -a, будет сбрасываться также буфер верхнего уровня.

Примеры

Для сброса трассировки в instance-one и установки размера буфера 4096 Кбайт на процессор, а также удаления instance-two служит приведенная ниже команда. Экземпляр верхнего уровня и другие буферы сохраняются.

trace-cmd reset -B instance-one -b 4096 -B instance-two -d

Для удаления всех экземпляров кроме буфера верхнего уровня служит приведенная ниже команда.

trace-cmd reset -a -d

Для удаления всех экземпляров и буфера верхнего уровня служит команда

trace-cmd reset -t -a -d

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

trace-cmd reset -a -t -d

Для сброса экземпляра верхнего уровня и установки размера буфера 1024 Кбайт на процессор служит приведенная ниже команда. На другие буферы она не воздействует.

trace-cmd reset -b 1024

split

Расщепляет файл trace.dat на более мелкие файлы.

Синтаксис

trace-cmd split [OPTIONS] [start-time [end-time]]

Описание

Команда trace-cmd служит для разбиения trace.dat на более мелкие файлы. Параметр start-time указывает время, с которого начнется новый файл. Команду trace-cmd report и копирование временной метки определенного события можно использовать в качестве start-time или end-time. Расщепление прекратит создание файлов по достижении времени end-time. Если нужно лишь время окончания, в качестве start-time служит 0.0.

Если параметр start-time опущен, расщепление начинается с начала файла. Если опущен параметр end-time, расщепление будет продолжаться до конца файла, если его не остановят другие опции.

Опции

-i file

Если эта опция не задана, команда будет расщеплять файл trace.dat. С помощью опции можно указать иной файл.

-o file

По умолчанию команда split будет использовать имя входного файла в качестве основы для имен создаваемых файлов, добавляя к входному имени суффиксы вида .# (trace.dat.1, trace.dat.2 и т. п.). Данная опция позволяет изменить базовое имя файлов. Например, -o приведет к созданию файлов file.1, file.2 и т. д.

-s seconds

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

-m milliseconds

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

-u microseconds

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

-e events

Задает число событий, записываемых в файл прежде, чем начать новый.

-p pages

Задает число страниц, записываемых в файл прежде, чем начать новый.

Примечание. Опции -p, -e, -u, -m и -s являются взаимоисключающими, т. е. не может присутствовать более одной из них.

При установке опции -p автоматически добавляется опция -c.

-r

Эта опция заставляет повторять разбиение, пока не будет достигнуто значение end-time (или конец файла при отсутствии end-time).

trace-cmd split -r -e 10000

Будет разбивать trace.dat на файлы, содержащие не более 10000 событий в каждом.

-c

Эта опция приводит к разбиению файла по процессорам.

trace-cmd split -c -p 10

будет создавать файл, имеющий 10 страниц на каждый CPU.

-C cpu

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

trace-cmd split -C 1

будет выделять в файл все события для cpu 1.

list

Выводит список доступных плагинов, событий и опций ftrace.

Синтаксис

trace-cmd list [OPTIONS]

Описание

Команда trace-cmd list выводит список доступных плагинов, событий и опций ftrace, которые настроены на текущей машине. Если команда используется без опций, выводятся все плагины, события и опции ftrace на стандартный вывод.

Опции

-e [regex]

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

trace-cmd list -e '^sys.*'

-F

Применяется вместе с -e regex для вывода форматов событий.

-l

Применяется вместе с -e regex для вывода фильтров событий.

-R

Применяется вместе с -e regex для вывода триггеров событий.

-t

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

-p

Совпадает с -t и применяется для унаследованных систем.

-o

Обеспечивает вывод списка доступных опций ftrace, настроенных на локальной системе.

-f [regex]

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

trace-cmd list -f '^sched.*'

-P

Обеспечивает вывод списка файлов плагинов, загружаемых trace-cmd report.

-O

Обеспечивает вывод списка опций плагинов, которые могут применяться в команде trace-cmd report -O option.

-B

Выводит список экземпляров буферов.

-C

Выводит список часов, которые могут применяться в команде trace-cmd record -C. Активные часы указываются в квадратных скобках [].

listen

Задает прослушивание входящих соединений для записи трассировки.

Синтаксис

trace-cmd listen -p port [OPTIONS]

Описание

Команда trace-cmd listen активизирует порт для прослушивания входящих соединений от других хостов, на которых используется команда trace-cmd record с опцией -N. Когда соединение организовано, удаленный хост будет передавать через него данные, которые будут сохраняться в файле с именем trace.HOST:PORT.dat (HOST — имя удаленного хоста, PORT -номер порта, используемый удаленным хостом для соединения).

Опции

-p port

Эта опция задает порт для прослушивания входящих соединений.

-D

Эта опция переводит trace-cmd listen в режим демона.

-d dir

Эта опция задает каталог для записи файлов данных.

-o filename

Эта опция заменяет принятую по умолчанию запись в файл trace.HOST:PORT.dat записью в указанный файл.

-l filename

Эта опция задает запись выходных сообщений в указанный файл вместо стандартного вывода.

restore

Восстанавливает отказавшую запись трассировки.

Синтаксис

trace-cmd restore [OPTIONS] [command] cpu-file [cpu-file …]

Описание

Команда trace-cmd restore восстанавливает файл после отказа trace-cmd record. Если при работе trace-cmd record возникает отказ, программа оставляет файлы данных для отдельных процессоров, не создавая финального файла trace.dat. Команда trace-cmd restore будет собирать эти файлы для создания рабочего файла trace.dat, который может быть прочитан командой trace-cmd-report.

При работе команды trace-cmd record она запускает отдельный процесс для каждого CPU и записывает для них файлы данных, обычно называемые trace.dat.cpuX, где X указывает номер процессора. Если для команды trace-cmd record использовалась опция -o, файлы данных CPU будут иметь другие имена вместо trace.dat. При возникновении отказа до завершения трассировки файлы отдельных CPU сохраняются, но файла trace.dat не будет. Команда trace-cmd restore создает trace.dat из имеющихся файлов данных.

Опции

-c

Задает создание частичного файла trace.dat для машины, который можно потом использовать в команде trace-cmd restore. Эта опция полезна для встраиваемых систем. Если сервер содержит файлы отдельных процессоров отказавшей команды trace-cmd record (или trace-cmd listen), trace-cmd restore можно запустить на встраиваемом устройстве с опцией -c для получения всех данных этого встраиваемого устройства. Затем созданный файл копируется на сервер для запуска команды trace-cmd restore.

Если опция -o не задана, создается файл trace-partial.dat. Это связано с тем, что файл не будет полной версией, пригодной для использования в trace-cmd report.

-t tracing_dir

При использовании вместе с опцией -c переопределяет место для считывания данных о событиях. По умолчанию данные трассировки считываются из каталога debugfs/tracing, но опция -t позволяет указать иное место. Это может быть полезно при создании файла trace.dat с другой машины.

-k kallsyms

При использовании вместе с опцией -c переопределяет место для считывания данных kallsyms. По умолчанию используется /proc/kallsyms, но опция -k позволяет указать иное место. Это может быть полезно при создании файла trace.dat с другой машины.

-o output

По умолчанию trace-cmd restore будет создавать файл trace.dat (или trace-partial.dat при наличии опции -c), но опция -o позволяет указать другой файл.

-i input

По умолчанию trace-cmd restore читает информацию текущей системы для создания начальных данных, хранящихся в файле trace.dat. Если отказ произошел на другой машине, на ней следует запустить команду trace-cmd с опцией -c для создания частичного файла trace.dat. Затем этот файл копируется на машину, где используется команда trace-cmd restore с опцией -i для загрузки данных из файла вместо считывания из локальной системы.

Примеры

Если отказ произошел на другой машине, можно воспользоваться командой

$ trace-cmd restore -c -o box-partial.dat

Затем на сервер, где размещены файлы данных cpu используется команда

$ trace-cmd restore -i box-partial.dat trace.dat.cpu0 trace.dat.cpu1

Это позволяет восстановить файл trace.dat для встраиваемого устройства.

stack

Читает, включает или отключает трассировку ядра Linux ftrace.

Синтаксис

trace-cmd stack

Описание

Команда trace-cmd stack включает трассировщик стека в ядре, который включает трассировщик функций и при каждом вызове функции в ядре проверяется стек. При обнаружении нового максимума использования стека это записывается.

При отсутствии опции отображается текущий стек.

Для включения трассировщика стека используется опция —start, для отключения — —stop. Выводиться будет максимальный стек, найденный с момента старта.

Для сброса счетчика стека служит опция —reset.

check-events

Анализирует форматы событий в локальной системе.

Синтаксис

trace-cmd check-events [OPTIONS]

Описание

Команда trace-cmd check-events разбирает строки форматов для всех событий в локальной системе. Она возвращает информацию о возможности корректного анализа каждого формата. Если явно не указано иное, команда будет загружать плагины.

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

Опции

-N

Отменяет загрузку плагинов.

stream

Направляет трассировку в stdout.

Синтаксис

trace-cmd stream [OPTIONS] [command]

Описание

Команда trace-cmd запускает трассировку подобно trace-cmd record, но не выводит данные в файл, а считывает их напрямую из двоичного буфера, преобразуя в понятный человеку формат и выводит на stdout.

В основном это совпадает с командой trace-cmd start и последующей командой trace-cmd show с опцией -p. Команда trace-cmd stream не так эффективна как чтение из канала, поскольку большая часть потока выполняется в пользовательском пространстве. Эта команда полезна в тех случаях. Когда нужно выполнить основную работу в пользовательском пространстве, а не в ядре, а также помогает отлаживать команды trace-cmd profile, использующие код потока для анализа данных профиля в реальном масштабе времени.

Опции

Опции команды совпадают с опциями trace-cmd record за исключением -o.

snapshot

Принимает, сбрасывает, освобождает и выводит моментальные снимки трассировки ftrace (snapshot).

Синтаксис

trace-cmd snapshot [OPTIONS]

Описание

Команда trace-cmd snapshot управляет или показывает моментальный снимок трассировки ftrace (если ядро поддерживает это). Она полезна для «замораживания» экземпляра трассировки без остановки процесса.

           trace-cmd start -p function 
           trace-cmd snapshot -s 
           trace-cmd snapshot 
          [ выводит содержимое буфера в момент trace-cmd snapshot -s ] 
           trace-cmd snapshot -s 
           trace-cmd snapshot 
          [ выводит новое содержимое буфера при последней операции -s ]

Опции

-s

Делает моментальный снимок работающего буфера.

-r

Очищает буфер.

-f

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

-c cpu

Задает вывод моментального снимка для отдельного процессора (может поддерживаться ядром не полностью)

-B buf

Если экземпляр буфер создан, опция -B будет работать со снимком в этом буфере.

Формат файла trace-cmd.dat

Описание

Утилита trace-cmd создает файл trace.dat. Этот файл может иметь другое имя, если пользователь указал его, но в любом случае он будет иметь некий двоичный формат. Файл применяется программой trace-cmd для хранения трассировок ядра с возможностью извлечения данных (см. report).

Начальный формат

Первые три байта файла содержат «магическое значение»

0x17 0x08  0x44

В следующий 7 байтах содержится строка

tracing

Далее следует строка символов с завершающим \0, указывающая версию файла. Например,

"6\0"

Следующий байт указывает тип значений

          0 = little endian 
          1 = big endian

Далее следует байт, указывающий размер значения типа long

          4 — 32-битовые значения long
          8 - 64-битовые значения long

Примечание. Этот размер long предназначен для пользовательского пространства и не связан с размером в ядре.

Далее все числа указываются в зависимости от заданного порядка байтов (endianess).

Следующие 4 байта образуют 32-битовое слово, определяющее размер страницы на трассируемом хосте.

Формат данных заголовка

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

Следующие 12 байтов содержат строку

header_page\0

Затем следуют 8 байтов, образующих 64-битовое слово размера данных заголовка страницы, которая храниться далее.

Следующий блок данных имеет размер, указанный в предыдущих 8 байтах и содержит данные из debugfs/tracing/events/header_page.

Примечание. Размер второго поля commit содержит размер long в целевом ядре. Например,

field: local_t commit;        offset:8;       \fBsize:8;\fR   signed:1;

указывает, что в ядре используются 64-битовые значения long.

Следующие 13 байтов содержат строку

header_event\0

Затем следуют 8 байтов, образующих 64-битовое слово размера заголовка данных событий, хранящегося далее.

Следующий блок, размер которого указан предыдущими 8 байтами, содержит данные из debugfs/tracing/events/header_event.

Эти данные позволяют trace-cmd узнать о наличии каких-либо изменений в кольцевом буфере ядра.

Формат событий ftrace

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

Первые 4 байта содержат 32-битовое слово числа файлов формата событий ftrace, сохраненных в файле.

Для числа вхождений, указанного предыдущими 4 байтами, 8 байтов указывают размер файла формата событий ftrace. Файл формата событий ftrace копируется с целевой машины

debugfs/tracing/events/ftrace/<event>/format

Формат событий

Сразу после форматов ftrace размещается информация о схеме событий.

Первые 4 байта содержат 32-битовое слово числа систем событий, хранящихся в файле. Это каталоги в структуре debugfs/tracing/events за исключением каталога ftrace.

Для числа вхождений, указанного предыдущими 4 байтами, указывается строка с null-символом в конце, задающая имя системы, 4 байта 32-битового слова числа событий в системе.

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

Файл формата событий ftrace копируется с целевой машины

debugfs/tracing/events/<system>/<event>/format

Информация KALLSYMS

Сразу за форматами событий следуют данные отображения имен функций на их адреса.

Первые 4 байта содержат 32-битовое слово размера данных об отображении функций.

Следующий блок, размер которого определен предыдущими 4 байтами, содержит данные из файла целевой машины

/proc/kallsyms

Информация TRACE_PRINTK

Если разработчики применяли в ядре trace_printk(), можно сохранять строку формата вне кольцевого буфера, в файле

debugfs/tracing/printk_formats

Следующие 4 байта содержат 32-битовое слово размера данных, хранящихся в формате printk.

Далее следует блок, размер которого задан предыдущими 4 байтами, с данными из debugfs/tracing/printk_formats.

Данные процессов

Сразу после форматов trace_printk следуют данные отображения PID на имена процессов.

Следующие 8 содержат 64-битовое слово размера данных отображения PID на имена процессов.

Далее следует блок, размер которого задан предыдущими 8 байтами, с данными из debugfs/tracing/saved_cmdlines.

Остальная часть заголовка TRACE-CMD

Сразу после данных о процессах следует последний бит заголовка trace.dat.

Следующие 4 байта содержат 32-битовое слово числа CPU, обнаруженных на целевой машине (и имеющих данные трассировки).

Следующие 10 байтов содержат одну из строк

options  \0 
latency  \0 
flyrecord\0

Для случая options \0 следующие 2 байта содержат 16-битовое слово, задающее текущие опции (0 — больше нет опций).

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

Следующая опция размещается сразу за предыдущей и опции завершаются 0 в поле типа опции.

Следующие 10 байтов содержат одну из строк

latency  \0 
flyrecord\0

которые были бы и при отсутствии опций.

Для случая latency \0, остальная часть файла представляет просто текст ASCII из файла целевой системы

debugfs/tracing/trace

Для случая flyrecord\0 далее следует представленная ниже информация.

Для числа CPU, определенного раньше указывается:

8 байтов 64-битового слова, указывающего смещение в файле, где хранятся данные для CPU;

8 байтов 64-битового слова, указывающего размер данных CPU, расположенных по этому смещению.

Данные CPU

Данные процессоров хранятся в части файла, указанной в конце заголовка. Между заголовком и данными CPU помещается заполнение, для выравнивания данных CPU по краю страницы (страница цели) в файле.

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

Программа trace-cmd будет пытаться выполнить mmap для данных страница за страницей с размером страниц целевой системы, если это возможно. При отказе mmap будут просто считываться данные.

Запись опубликована в рубрике Linux, Измерения и тестирование. Добавьте в закладки постоянную ссылку.