Использование ftrace

ftrace — это инструмент отладки для понимания того, что происходит внутри ядра Linux. В следующих разделах подробно описаны базовые функции ftrace, использование ftrace с atrace (которая фиксирует события ядра) и динамическая ftrace.

Подробную информацию о расширенных функциях ftrace, недоступных в systrace, см. в документации по ftrace по адресу <kernel tree>/Documentation/trace/ftrace.txt .

Захват событий ядра с помощью atrace

atrace ( frameworks/native/cmds/atrace ) использует ftrace для захвата событий ядра. В свою очередь, systrace.py (или run_systrace.py в более поздних версиях Catapult ) использует adb для запуска atrace на устройстве. atrace делает следующее:

• Настраивает трассировку в пользовательском режиме, устанавливая свойство ( debug.atrace.tags.enableflags ).
• Включает желаемую функциональность ftrace путем записи в соответствующие узлы ftrace sysfs. Однако, поскольку ftrace поддерживает больше функций, вы можете самостоятельно установить некоторые узлы sysfs, а затем использовать atrace.

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

Включение событий ftrace

Узлы ftrace sysfs находятся в /sys/kernel/tracing , а события трассировки разделены на категории в /sys/kernel/tracing/events .

Чтобы включить события для каждой категории, используйте:

echo 1 > /sys/kernel/tracing/events/irq/enable

Чтобы включить события для каждого события, используйте:

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

Если дополнительные события были включены путем записи в узлы sysfs, они не будут сброшены atrace. Распространенным шаблоном запуска устройства Qualcomm является включение kgsl (GPU) и mdss (конвейер отображения), а затем использование atrace или systrace :

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

Вы также можете использовать ftrace без atrace или systrace, что полезно, когда вам нужны трассировки только для ядра (или если вы потратили время на то, чтобы вручную написать свойство трассировки пользовательского режима). Чтобы запустить только ftrace:

1. Установите размер буфера на значение, достаточное для вашей трассировки:

   echo 96000 > /sys/kernel/tracing/buffer_size_kb
   

2. Включить трассировку:

   echo 1 > /sys/kernel/tracing/tracing_on
   

3. Запустите тест, затем отключите трассировку:

   echo 0 > /sys/kernel/tracing/tracing_on
   

4. Дамп трассировки:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output
   

trace_output дает трассировку в текстовом виде. Чтобы визуализировать его с помощью Catapult, получите репозиторий Catapult с GitHub и запустите trace2html:

catapult/tracing/bin/trace2html ~/path/to/trace_file

По умолчанию это записывает trace_file.html в тот же каталог.

Корреляция событий

Часто полезно одновременно просматривать визуализацию Catapult и журнал ftrace; например, некоторые события ftrace (особенно связанные с поставщиком) не визуализируются Catapult. Однако временные метки Catapult относятся либо к первому событию в трассировке, либо к определенной временной метке, полученной atrace, в то время как необработанные временные метки ftrace основаны на конкретном источнике абсолютных часов в ядре Linux.

Чтобы найти заданное событие ftrace из события Catapult:

1. Откройте необработанный журнал ftrace. Трассировки в последних версиях systrace по умолчанию сжаты:
   • Если вы захватили свою системную трассу с помощью --no-compress , она находится в html-файле в разделе, начинающемся с BEGIN TRACE.
   • Если нет, запустите html2trace из дерева Catapult ( tracing/bin/html2trace ), чтобы распаковать трассировку.
2. Найдите относительную метку времени в визуализации Catapult.
3. Найдите строку в начале трассировки, содержащую tracing_mark_sync . Это должно выглядеть примерно так:

   <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
   

   
   Если этой строки не существует (или если вы использовали ftrace без atrace), то тайминги будут относительными от первого события в логе ftrace.
   1. Добавьте относительную метку времени (в миллисекундах) к значению в parent_ts (в секундах).
   2. Найдите новую метку времени.

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

Использование динамического ftrace

Когда systrace и стандартная ftrace недостаточны, остается последнее средство: динамическая ftrace . Динамический ftrace включает в себя перезапись кода ядра после загрузки, в результате чего он недоступен в рабочих ядрах по соображениям безопасности. Тем не менее, каждая серьезная ошибка производительности в 2015 и 2016 годах в конечном итоге была вызвана использованием динамического ftrace. Он особенно полезен для отладки непрерываемого спящего режима, поскольку вы можете получать трассировку стека в ядре каждый раз, когда вы нажимаете функцию, запускающую непрерываемый сон. Вы также можете отлаживать разделы с отключенными прерываниями и прерываниями, что может быть очень полезно для выявления проблем.

Чтобы включить динамическую ftrace, отредактируйте defconfig вашего ядра:

1. Удалите CONFIG_STRICT_MEMORY_RWX (если он присутствует). Если у вас 3.18 или новее и arm64, его там нет.
2. Добавьте следующее: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y и CONFIG_PREEMPT_TRACER=y
3. Пересоберите и загрузите новое ядро.
4. Выполните следующее, чтобы проверить наличие доступных трассировщиков:

   cat /sys/kernel/tracing/available_tracers
   

5. Подтвердите, что команда возвращает function , irqsoff , preemptoff и preemptirqsoff .
6. Запустите следующее, чтобы убедиться, что динамический ftrace работает:

   cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
   

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

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

Показать проблему: фото HDR + вращающийся видоискатель

В этой проблеме использование Pixel XL для съемки фотографии HDR+ с последующим немедленным поворотом видоискателя каждый раз приводило к рывкам. Мы использовали профилировщик функций для отладки проблемы менее чем за час. Чтобы следовать примеру, загрузите ZIP-файл трассировок (который также включает другие трассировки, упомянутые в этом разделе), разархивируйте файл и откройте файл trace_30898724.html в браузере.

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

На данный момент нам нужно знать, кто вызывает ion_client_destroy , поэтому пришло время использовать профилировщик функций:

1. Поскольку функции иногда переименовываются компилятором, подтвердите ion_client_destroy , используя:

   cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
   

2. Убедившись, что он есть, используйте его в качестве фильтра ftrace:

   echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
   

3. Включите профилировщик функций:

   echo function > /sys/kernel/tracing/current_tracer
   

4. Включайте трассировку стека всякий раз, когда вызывается функция фильтра:

   echo func_stack_trace > /sys/kernel/tracing/trace_options
   

5. Увеличьте размер буфера:

   echo 64000 > /sys/kernel/tracing/buffer_size_kb
   

6. Включить трассировку:

   echo 1 > /sys/kernel/tracing/trace_on
   

7. Запустите тест и получите трассировку:

   cat /sys/kernel/tracing/trace > /data/local/tmp/trace
   

8. Просмотрите трассировку, чтобы увидеть множество трассировок стека:

       cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
       cameraserver-643   [003] ...1    94.192997: <stack trace>
    => ftrace_ops_no_ops
    => ftrace_graph_call
    => ion_client_destroy
    => ion_release
    => __fput
    => ____fput
    => task_work_run
    => do_notify_resume
    => work_pending
    

Основываясь на проверке драйвера ion, мы видим, что ion_client_destroy рассылается спамом функцией пользовательского пространства, закрывающей fd на /dev/ion , а не случайным драйвером ядра. При поиске в кодовой базе Android по запросу \"/dev/ion\" мы находим несколько драйверов поставщиков, которые делают то же самое, что и драйвер Hexagon, и открывают/закрывают /dev/ion (создают и уничтожают новый клиент ion) каждый раз, когда им требуется выделение новых ионов. Изменение их для использования одного ионного клиента на время жизни процесса исправило ошибку.

---

Если данные из профилировщика функций недостаточно точны, вы можете комбинировать точки трассировки ftrace с профилировщиком функций. События ftrace можно включить точно так же, как обычно, и они будут чередоваться с вашей трассировкой. Это здорово, если есть случайный длительный непрерывный сон в конкретной функции, которую вы хотите отладить: установите фильтр ftrace на нужную функцию, включите точки трассировки, выполните трассировку. Вы можете проанализировать полученную трассировку с помощью trace2html , найти нужное событие, а затем получить ближайшие трассировки стека в необработанной трассировке.

Использование локстата

Иногда ftrace недостаточно, и вам действительно нужно отладить то, что кажется конфликтом блокировки ядра. Стоит попробовать еще одну опцию ядра: CONFIG_LOCK_STAT . Это крайняя мера, так как крайне сложно начать работать на устройствах Android, потому что размер ядра увеличивается за пределы того, что может обработать большинство устройств.

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

Показать проблему: зависание в SCHED_FIFO при максимальной загрузке ядер без SCHED_FIFO

В этой проблеме поток SCHED_FIFO останавливался, когда все ядра были максимально загружены потоками, отличными от SCHED_FIFO. У нас были трассировки, показывающие значительные конфликты за блокировку fd в приложениях виртуальной реальности, но мы не могли легко идентифицировать используемый fd. Чтобы следовать примеру, загрузите ZIP-файл трассировок (который также включает другие трассировки, упомянутые в этом разделе), разархивируйте файл и откройте файл trace_30905547.html в браузере.

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

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

---

Если вы можете загрузить ядро ​​с параметром config, трассировка блокировки аналогична ftrace:

1. Включить трассировку:

   echo 1 > /proc/sys/kernel/lock_stat
   

2. Запустите свой тест.
3. Отключить трассировку:

   echo 0 > /proc/sys/kernel/lock_stat
   

4. Сброс трассировки:

   cat /proc/lock_stat > /data/local/tmp/lock_stat
   

Чтобы получить помощь в интерпретации полученных результатов, обратитесь к документации lockstat по адресу <kernel>/Documentation/locking/lockstat.txt .

Использование точек трассировки поставщиков

Сначала используйте восходящие точки трассировки, но иногда вам потребуется использовать точки трассировки поставщиков:

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

Точки трассировки расширяются службой HAL, что позволяет добавлять точки/категории трассировки для конкретных устройств. Точки трассировки интегрированы с perfetto, atrace/systrace и приложением для отслеживания системы на устройстве.

API для реализации точек трассировки/категорий:

• listCategories() генерирует (категории vec<TracingCategory>);
• enableCategories(vec<string> Categories) генерирует (состояние состояния);
• disableAllCategories() генерирует (статус состояния);

Для получения дополнительной информации обратитесь к определению HAL и реализации по умолчанию в AOSP :