Трасування ядра з ftrace

PR-1801-2-2

Проблеми трасування і профілювання ядра ми вже зачіпали  попередніх публікаціях. Для аналізу подій на рівні ядра існує багато спеціалізованих інструментів: SystemTap, Ktap, Sysdig, LTTNG інші. Про цих інструментах опубліковано багато докладних статей і навчальних матеріалів.

Набагато менше інформації можна знайти про «рідних» механізми Linux, з допомогою яких можна відслідковувати системні події, отримувати і аналізувати налагоджувальну інформацію. Цю тему ми хотіли б розглянути в сьогоднішньої статті. Особливу увагу ми приділимо ftrace   першого і поки що єдиного інструменту трасування, доданого в ядро. Почнемо з визначення основних понять.


Профілювання і трасування ядра

Профілювання ядра — це виявлення «вузьких місць» в продуктивності. З допомогою профілювання можна визначити, де саме сталася втрата продуктивності в тій чи іншій програмі. Спеціальні програми генерують профіль   зведення подій, на основі якої можна з'ясувати, на виконання якихось функцій пішло більше всього часу. Ці програми, однак, не допомагають виявити причину зниження продуктивності.

«Вузькі місця» дуже часто виникають при певних умовах, які при профілюванні виявити неможливо. Щоб зрозуміти, чому сталося те чи іншу подію, потрібно відновлювати контекст. У свою чергу, для відновлення контекстом не вимагається трасування.

Під трасуванням розуміється отримання інформації про те, що відбувається всередині працюючої системи. Для цього використовуються спеціальні програмні інструменти. Вони реєструють усі події в системі подібно до того, як магнітофон записує всі звуки навколишнього середовища.

Програми-трасувальники можуть одночасно відстежувати події як на рівні окремих програм, так і на рівні операційної системи. Отримана в час трасування інформація може виявитися корисною для діагностики і вирішення багатьох системних проблем.

Трасування іноді порівнюють з логгированием. Подібність між цими двома процедурами справді є, але і відмінності.

У час трасування записується інформація про події, що відбуваються на низькому рівні. Їх кількість обчислюється сотнями і навіть тисячами. У логи ж записується інформація про високорівневих події, які трапляються набагато рідше: наприклад, вхід користувачів систему, помилки в роботі додатків, транзакції в базах даних і інші.

Як і логи, файли з даними трасування можна читати «з листа». Набагато цікавіше і корисніше, однак, витягати з них інформацію, яка відноситься до роботі конкретних додатків. Відповідні функції є у всіх програм-трасувальників.

У ядрі Linux існує три основних механізми, за допомогою яких здійснюються процедури трасування і профілювання ядра:

  • tracepoints   механізм, що працює через статичну инструментирование коду;
  • kprobes   механізм динамічної трасування, з допомогою якого можна перервати виконання коду ядра в будь-якому місці, викликати власний обробник і  завершення усіх необхідних операцій повернутися назад;
  • perf_events   інтерфейс доступу до PMU (Performance Monitoring Unit).


Детально розписувати особливості всіх цих механізмів не будемо; зацікавлених читачів відсилаємо до статті компанії «НТЦ МетроТек», а також блогу Брендана Грегга.

З допомогою ftrace можна взаємодіяти з цими механізмами і отримувати дані налагодження, перебуваючи в користувацькому просторі. Більш докладно про це ми поговоримо нижче. Всі приклади команд наводяться для ОС Ubuntu 14.04, ядро версії 3.13.0-24.

Ftrace: загальна інформація

Назва ftrace являє собою скорочення від Function Trace   трасування функцій. Однак можливості цього інструменту набагато ширше: з його допомогою можна відстежувати контекстні перемикачі, вимірювати час обробки переривань, вираховувати час на активізацію завдань з високим пріоритетом і багато іншого.

Ftrace був розроблений Стівеном Ростедтом і доданий в ядро в 2008 році, починаючи з версії 2.6.27. Це   фреймворк, що надає налагоджувальний кільцевої буфер для запису даних. Збирають ці дані вбудовані в ядро програми-трасувальники.

Працює ftrace на базі файлової системи debugfs, яка в більшості сучасних дистрибутивів Linux змонтована замовчуванням. Щоб приступити до роботі з ftrace, потрібно просто перейти в директорію sys/kernel/debug/tracing (вона доступна тільки для root користувача):

# cd /sys/kernel/debug/tracing


Докладно розповідати про всіх містяться в ній файлах і піддиректоріях ми не будемо — це вже зроблено в офіційній документації. Коротко опишемо лише ті з них, які представляють інтерес у контексті нашого розгляду:

  • available_tracers   доступні програми-трасувальники;
    current_tracer   програма-трасувальник, активна в поточний момент;
  • tracing_on   службовий файл, що відповідає за включення і відключення запису даних в кільцевий буфер (щоб включити запис, потрібно записати в цей файл цифру 1, а щоб вимкнути   0);
  • trace   файл, де зберігаються дані трасування в человекочитаемом форматі.


Доступні трасувальники

Переглянути список доступних трасувальників можна з допомогою команди

root@andrei:/sys/kernel/debug/tracing#: cat available_tracers
blk mmiotrace function_graph wakeup_rt wakeup function nop


Наведемо коротку характеристику для кожного трассировщика:

  • function   трасувальник функцій викликів ядра без можливості отримання аргументів;
  • function_graph   трасувальник функцій викликів ядра з подвызовами;
  • blk   трасувальник викликів і подій, пов'язаних з введенням-виведенням на блокові пристрої; саме він використовується в утиліті blktrace, про яку ми вже писали;
  • mmiotrace   трасувальник операцій вводу-виводу, що відображаються у пам'ять.
  • nop   найпростіший трасувальник, який, як і з назви, нічого не робить (проте в деяких ситуаціях і він може бути корисний, що ще піде мова нижче).


Трасувальник function

Знайомство з ftrace ми почнемо з трассировщика function. Розглядати його ми будемо на матеріалі ось такого тестового скрипта:

#!/bin/sh

dir=/sys/kernel/debug/tracing

sysctl kernel.ftrace_enabled=1
echo function > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on 
sleep 1
echo 0 > ${dir}/tracing_on
less ${dir}/trace


крипт дуже простий і в цілому зрозумілий, однак у ньому є моменти, на які варто звернути увагу.
Команда sysctl ftrace.enabled=1 включає трасування функцій. Далі ми встановлюємо поточний трасувальник, записуючи його ім'я в файл current_tracer.

Після цього ми записуємо 1 у файл tracing_on і тим самим активуємо оновлення кільцевого буфера. Важлива особливість синтаксису: між 1 і знаком > обов'язково повинен бути пробіл: команда виду echo1> tracing_on не спрацює. Буквально через один рядок ми його відключаємо (зверніть увагу: якщо в файл tracing_on записати 0, кільцевий буфер не буде очищений; не буде відключений і ftrace).

Навіщо ми це робимо? Між двома командами echo знаходиться команда sleep 1. Ми включаємо оновлення буфера, виконуємо цю команду і потім відразу ж його відключаємо. Завдяки цьому в трасування буде включена інформація про всі системні виклики, які мали місце під час виконання цієї команди.

У останньому рядку скрипта ми  даємо команду вивести дані трасування на консоль.

У внаслідок виконання цього скрипта ми побачимо наступний висновок (наводимо лише невеликий фрагмент):

# tracer: function
#
# entries-in-buffer/entries-written: 29571/29571 #P:2
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU#|||| TIMESTAMP FUNCTION
# | | | |||| | |
trace.sh-1295 [000] .... 90.502874: mutex_unlock <-rb_simple_write
trace.sh-1295 [000] .... 90.502875: __fsnotify_parent <-vfs_write
trace.sh-1295 [000] .... 90.502876: fsnotify <-vfs_write
trace.sh-1295 [000] .... 90.502876: __srcu_read_lock <-fsnotify
trace.sh-1295 [000] .... 90.502876: __srcu_read_unlock <-fsnotify
trace.sh-1295 [000] .... 90.502877: __sb_end_write <-vfs_write
trace.sh-1295 [000] .... 90.502877: syscall_trace_leave <-int_check_syscall_exit_work
trace.sh-1295 [000] .... 90.502878: context_tracking_user_exit <-syscall_trace_leave
trace.sh-1295 [000] .... 90.502878: context_tracking_user_enter <-syscall_trace_leave
trace.sh-1295 [000] d... 90.502878: vtime_user_enter <-context_tracking_user_enter
trace.sh-1295 [000] d... 90.502878: _raw_spin_lock <-vtime_user_enter
trace.sh-1295 [000] d... 90.502878: __vtime_account_system <-vtime_user_enter
trace.sh-1295 [000] d... 90.502878: get_vtime_delta <-__vtime_account_system
trace.sh-1295 [000] d... 90.502879: account_system_time <-__vtime_account_system
trace.sh-1295 [000] d... 90.502879: cpuacct_account_field <-account_system_time
trace.sh-1295 [000] d... 90.502879: acct_account_cputime <-account_system_time
trace.sh-1295 [000] d... 90.502879: __acct_update_інтегралів <-acct_account_cputime


Висновок починається з інформації про кількості записів подій в буфері (entries in buffer) і загальній кількості записаних подій (entries written). Різниця між цими двома цифрами — це кількість подій, втрачених при заповненні буфера (в нашому випадку ніяких загублених подій немає).

Далі йде перелік функцій, що включає наступну інформацію:

  • ідентифікатор процесу (PID);
  • номер процесорного ядра, на якому виконується трасування(СPU#);
  • мітка часу (TIMESTAMP; вказує час, коли стався вхід в функцію);
  • ім'я трассируемой функції і ім'я батьківського функції, яка її викликала(FUNCTION); наприклад, в першій рядку наведеного нами виведення функцію mutex-unlock викликає функція rb_simple_write.


Висновок починається з інформації про кількості записів подій в буфері (entries in buffer) і загальній кількості записаних подій (entries written). Різниця між цими двома цифрами — це кількість подій, втрачених при заповненні буфера (в нашому випадку ніяких загублених подій немає).

Далі йде перелік функцій, що включає наступну інформацію:

  • ідентифікатор процесу (PID);
  • номер процесорного ядра, на якому виконується трасування(СPU#);
  • мітка часу (TIMESTAMP; вказує час, коли стався вхід в функцію);
  • ім'я трассируемой функції і ім'я батьківського функції, яка її викликала(FUNCTION); наприклад, в першій рядку наведеного нами виведення функцію mutex-unlock викликає функція rb_simple_write.


Трасувальник function_graph

Трасувальник function_graph працює точно так ж, як function, але відстежує функції більш детально: для кожної функції він вказує точку входу і точку виходу. З допомогою цього трассировщика можна відстежувати функції з подвызовами і вимірювати час виконання для кожної функції.

Відредагуємо використаний в попередньому прикладі скрипт:

#!/bin/sh

dir=/sys/kernel/debug/tracing

sysctl kernel.ftrace_enabled=1
echo function_graph > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on 
sleep 1
echo 0 > ${dir}/tracing_on
less ${dir}/trace


В результаті виконання цього скрипта ми отримаємо наступний висновок:

# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) 0.120 us | } /* resched_task */
0) 1.877 us | } /* check_preempt_curr */
0) 4.264 us | } /* ttwu_do_wakeup */
0) + 29.053 us | } /* ttwu_do_activate.constprop.74 */
0) 0.091 usd | _raw_spin_unlock();
0) 0.260 us | ttwu_stat();
0) 0.133 us | _raw_spin_unlock_irqrestore();
0) + 37.785 us | } /* try_to_wake_up */
0) + 38.478 us | } /* default_wake_function */
0) + 39.203 us | } /* pollwake */
0) + 40.793 us | } /* __wake_up_common */
0) 0.104 us | _raw_spin_unlock_irqrestore();
0) + 42.920 us | } /* __wake_up_sync_key */
0) + 44.160 us | } /* sock_def_readable */
0) ! 192.850 us | } /* tcp_rcv_established */
0) ! 197.445 us | } /* tcp_v4_do_rcv */
0) 0.113 usd | _raw_spin_unlock();
0) ! 205.655 us | } /* tcp_v4_rcv */
0) ! 208.154 us | } /* ip_local_deliver_finish */


У графі DURATION вказується час, витрачений на виконання функції. Особливу увагу слід звернути на пункти, відмічені значками + і! Знак + означає, що виконання функції зайняло більше 10 мікросекунд, а знак оклику — понад 100.

У графі FUNCTION_CALLS з інформацією про виклики функцій.
Початок і кінець виконання кожної функції позначаються в нею так, як це прийнято в мовою C: фігурна дужка в початку функції і ще одна   кінці. Функції, які є листям графа і не викликають ніяких інших функцій, позначаються крапкою з комою (;).

Фільтри для функцій

Висновок ftrace часом може бути дуже великим, і знайти в ньому потрібну інформацію вкрай важко. Спростити пошук можна з фільтри: у висновок буде потрапляти інформація не про всіх функціях, а про тих, які нас цікавлять. Для цього достатньо просто записати в файл set_ftrace_filter імена потрібних функцій, наприклад:

root@andrei:/sys/kernel/debug/tracing# echo kfree > set_ftrace_filter


Щоб відключити фільтр потрібно записати в це файл порожній рядок:

root@andrei:/sys/kernel/debug/tracing# echo > set_ftrace_filter


У результаті виконання команди

root@andrei:/sys/kernel/debug/tracing# echo kfree > set_ftrace_notrace 


ми отримаємо абсолютно протилежний результат: в висновок буде потрапляти інформація про всі функції, крім kfree().

Ще одна корисна опція   set_ftrace_pid. Вона призначена для трасування функцій, що викликаються у час виконання зазначеного процесу.

Можливості фільтрації в ftrace набагато ширше; детальніше про них можна прочитати в статті Стівена Ростедта на LWN.net.

Трасування подій

Вище ми вже згадували про механізм tracepoints. Слово tracepoint в перекладі означає «точка трасування. Точка трасування — це спеціальне вставлення у код, що реєструє певні системні події. Точка трасування можуть бути активною (це означає, що за ній закріплена певна перевірка) або неактивній (ніякої перевірки за ній не закріплено).

Неактивна точка трасування ніякого впливу на роботу системи не надає; вона лише додає кілька байт для виклику трассировочной функції в наприкінці инструментированной функції, а також додає структуру даних в окрему секцію.

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

Точки трасування можуть бути вставлені в в коді. Вони вже присутні в коді багатьох ядерних функцій. Розглянемо, наприклад, функцію kmem_cache_alloc (взято звідси):

{
void *ret = slab_alloc(cachep, flags, _RET_IP_);

trace_kmem_cache_alloc(_RET_IP_, ret,
cachep->object_size, cachep->size, flags);
return ret;
}


Зверніть увагу на рядок trace_kmem_cache_alloc — це як раз і є точка трасування. Кількість подібних прикладів можна помножити, звернувшись до вихідного коду інших функцій ядра.

У ядрі Linux є спеціальний API, з допомогою якого можна працювати з точками трасування з користувацького простору. У директорії /sys/kernel/debug/tracing є піддиректорія events, якою зберігаються доступні для відстеження системні події. Системне подія в цьому контексті   не що інше, як включені в ядро точки трасування.

Їх список можна переглянути за допомогою команди:

root@andrei:/sys/kernel/debug/tracing# cat available_events


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

root@andrei:/sys/kernel/debug/tracing# ls events


Перш ніж приступати до відстеження подій, перевіримо, включена запис подій в кільцевий буфер:

root@andrei:/sys/kernel/debug/tracing# cat tracing_on


Якщо після виконання цієї команди на консоль буде виведена цифра 0, виконаємо:

root@andrei:/sys/kernel/debug/tracing# echo 1 > tracing_on


У минулій статті ми писали про системному виклику chroot() — вхід в цьому системний виклик ми і будемо відслідковувати. Як трассировщика ми виберемо nop: function і function_graph записують занадто багато інформації, в тому числі і не має відношення до питання, що нас події.

root@andrei:/sys/kernel/debug/tracing# echo nop > current_tracer


Всі події, пов'язані з системними викликами, зберігаються в директорії syscalls. У ній, свою чергу, зберігаються директорії для входу і виходу з різних системних викликів. Активуємо потрібну нам точку трасування, записавши 1 на enable-файл:

root@andrei:/sys/kernel/debug/tracing# echo 1 > events/syscalls/sys_enter_chroot/enable


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

root@andrei:/sys/kernel/debug/tracing# echo 0 > tracing_on


Далі переглянемо вміст кільцевого буфера. В самому кінці виводу буде міститися інформація про цікавлячий нас системному виклику (наводимо невеликий фрагмент):


root@andrei:/sys/kernel/debug/tracing# сat trace

......
chroot-11321 [000] .... 4606.265208: sys_chroot(filename: 7fff785ae8c2)
chroot-11325 [000] .... 4691.677767: sys_chroot(filename: 7fff242308cc)
bash-11338 [000] .... 4746.971300: sys_chroot(filename: 7fff1efca8cc)
bash-11351 [000] .... 5379.020609: sys_chroot(filename: 7fffbf9918cc)


Більш детально про налаштування трасування подій можна почитати тут.

Висновок

У цій статті ми зробили загальний огляд можливостей ftrace. Будемо вдячні за будь-які зауваження і доповнення. Якщо ви хочете глибше зануритися в тему, рекомендуємо ознайомитися з наступними джерелами:

Якщо ви з тих чи інших причин не можете залишати коментарі тут — запрошуємо до нас блог.

Джерело: Хабрахабр

0 коментарів

Тільки зареєстровані та авторизовані користувачі можуть залишати коментарі.