Использование 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 и запустите трассировку2html:

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 из дерева катапульты ( tracing/bin/html2trace ), чтобы распаковать трассировку.
2. Найдите относительную метку времени в визуализации «Катапульта».
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. Найдите новую временную метку.

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

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

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

Чтобы включить динамический 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-файл трассировок (который также включает в себя другие трассировки, упомянутые в этом разделе), разархивируйте файл и откройте файл трассировки_30898724.html в своем браузере.

Трассировка показывает, что несколько потоков в процессе cameraserver заблокированы в непрерывном режиме сна на ion_client_destroy . Это дорогая функция, но ее следует вызывать очень редко, поскольку ионные клиенты должны охватывать множество распределений. Первоначально вина падала на код Hexagon в Halide, который действительно был одним из виновников (он создавал новый клиент для каждого распределения ионов и уничтожал этого клиента, когда выделение освобождалось, что было слишком дорого). Переход на единый клиент ion для всех аллокаций 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. У нас были следы, показывающие значительную конкуренцию за блокировку файлового диска в приложениях VR, но мы не могли легко определить используемый файловый диск. Чтобы следовать примеру, загрузите zip-файл трассировок (который также включает в себя другие трассировки, упомянутые в этом разделе), разархивируйте файл и откройте файл трассировки_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> категории) генерирует (состояние статуса);
• DisableAllCategories() генерирует (состояние статуса);

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