🚣🏿 🏀 🍖 ftraceを使用したカーネルトレース 🔺 🤞🏾 🤔

以前の出版物では、カーネルのトレースとプロファイリングの問題にすでに取り組んでいます。カーネルレベルでイベントを分析するための多くの専用ツールがあります： SystemTap 、 Ktap 、 Sysdig 、 LTTNGなど。これらのツールに関する多くの詳細な記事とトレーニング資料が公開されています。

システムイベントの追跡、デバッグ情報の受信と分析を行うことができる「ネイティブ」なLinuxメカニズムに関する情報はほとんどありません。今日の記事でこのトピックを検討したいと思います。カーネルに追加された最初でこれまで唯一のトレースツールであるftraceに特に注意を払います。基本的な概念を定義することから始めましょう。

カーネルのプロファイリングとトレース

カーネルプロファイリングは、パフォーマンスのボトルネックを特定することです。プロファイリングを使用すると、特定のプログラムでパフォーマンスの低下が発生した場所を正確に特定できます。特別なプログラムはプロファイル-イベントの要約を生成します。これに基づいて、最も時間のかかった機能を見つけることができます。ただし、これらのプログラムは、パフォーマンス低下の原因を特定するのに役立ちません。

プロファイリング中に特定できない特定の条件下では、ボトルネックが非常に頻繁に発生します。イベントが発生した理由を理解するには、コンテキストを復元する必要があります。同様に、コンテキストを復元するにはトレースが必要です。

トレースとは、稼働中のシステム内で何が起こっているかに関する情報を取得することです。このために、特別なソフトウェアツールが使用されます。テープレコーダーが環境のすべての音を記録するように、システム内のすべてのイベントを記録します。

トレーサープログラムは、個々のアプリケーションレベルとオペレーティングシステムレベルの両方でイベントを同時に追跡できます。トレース中に取得した情報は、多くのシステム問題の診断と解決に役立ちます。

トレースは、ロギングと比較される場合があります。 2つの手順には確かに類似点がありますが、違いがあります。

トレース中に、低レベルで発生するイベントに関する情報が記録されます。その数は数百、数千です。ログには、システムにログインするユーザー、アプリケーションの操作のエラー、データベースのトランザクションなど、あまり頻繁に発生しない高レベルのイベントに関する情報が含まれています。

ログと同様に、トレースデータを含むファイルは「ワークシートから」読み取ることができます。ただし、特定のアプリケーションの操作に関連する情報をそれらから抽出する方がはるかに興味深く有用です。すべてのトレーサプログラムには、対応する機能があります。

Linuxカーネルには、カーネルトレースとプロファイリングの手順を実装する3つの主要なメカニズムがあります。

トレースポイント-コードの静的インスツルメンテーションを通じて機能するメカニズム。
kprobes-カーネルコードの実行をどこでも中断し、独自のハンドラーを呼び出し、必要なすべての操作が完了したら戻ることができる動的トレースメカニズム。
perf_events-PMU（パフォーマンスモニタリングユニット）アクセスインターフェイス。

これらすべてのメカニズムの機能については詳しく説明しません。興味のある読者は、NTC MetroTech社の記事とBrendan Greggのブログを参照してください。

ftraceを使用すると、これらのメカニズムと対話し、ユーザー空間でデバッグデータを取得できます。これについては、以下で詳しく説明します。すべてのサンプルコマンドは、カーネルバージョン3.13.0-24のUbuntu 14.04用に提供されています。

Ftrace：一般情報

ftraceという名前は、Function Trace-function tracingの略です。ただし、このツールの機能ははるかに広く、その助けにより、コンテキストスイッチの追跡、割り込みの処理時間の測定、優先度の高いタスクのアクティブ化時間の計算などができます。

FtraceはStephen Rostedtによって開発され、2008年にバージョン2.6.27からカーネルに追加されました。これは、データを書き込むためのデバッグリングバッファを提供するフレームワークです。このデータは、カーネルに組み込まれているトレーサープログラムによって収集されます。

Ftraceは、ほとんどの最新のLinuxディストリビューションでデフォルトでマウントされているdebugfsファイルシステムに基づいて実行されます。 ftraceを開始するには、sys / kernel / debug / tracingディレクトリに移動するだけです（rootユーザーのみが使用できます）。

# cd /sys/kernel/debug/tracing

その中に含まれるすべてのファイルとサブディレクトリについては詳しく説明しません。これはすでに公式ドキュメントで行われています。検討のコンテキストで関心のあるもののみを簡単に説明します。

available_tracers-利用可能なトレーサープログラム。

current_tracer-現在アクティブなトレーサプログラム。
tracing_on-リングバッファでのデータ記録を有効または無効にするサービスファイル（記録を有効にするには、このファイルに1を書き込み、無効にするには0）。
トレース-トレースデータが人間が読める形式で保存されているファイル。

利用可能なトレーサー

コマンドを使用して、利用可能なトレーサーのリストを表示できます

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

各トレーサーの簡単な説明を次に示します。

function-引数を受け取る可能性のないカーネル呼び出し関数のトレーサー。
function_graph-サブコールを使用したカーネル呼び出し関数のトレーサー。
blk-ブロックデバイスへの入出力に関連する呼び出しとイベントのトレーサー。すでに書いたのはblktraceユーティリティで使用される人です。
mmiotraceは、メモリI / Oのトレーサーです。
nopは最も単純なトレーサーであり、その名前が示すように、何もしません（ただし、状況によっては、後で説明します）。

トレーサー機能

関数tracerからftraceの紹介を始めます。このようなテストスクリプトの材料で検討します。

 #!/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ファイルに名前を書き込んで、現在のトレーサーをインストールします。

その後、tracing_onファイルに1を書き込むことにより、リングバッファーの更新をアクティブにします。構文の重要な機能：1とsign>の間にはスペースが必要です：echo1> tracing_onの形式のコマンドは機能しません。文字通り1行で無効にします（注：tracing_onファイルに0を書き込んだ場合、リングバッファはクリアされません; ftraceは無効になりません）。

なぜこれを行うのですか？ 2つのエコーコマンドの間には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_integrals <-acct_account_cputime

出力は、バッファ内のイベントレコードの数（バッファ内のエントリ）および記録されたイベントの総数（書き込まれたエントリ）に関する情報から始まります。これらの2桁の違いは、バッファの充填中に失われたイベントの数です（この場合、失われたイベントはありません）。

次は、次の情報を含む関数のリストです。

プロセス識別子（PID）;
トレースが実行されるプロセッサコアの番号（CPU＃）。
タイムスタンプ（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 us | _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 us | _raw_spin_unlock(); 0) ! 205.655 us | } /* tcp_v4_rcv */ 0) ! 208.154 us | } /* ip_local_deliver_finish */

DURATION列は、機能の完了にかかった時間を示しています。 +および！マークの付いたアイテムには特に注意を払ってください。 +記号は、関数が10マイクロ秒以上かかり、感嘆符が100以上かかったことを意味します。

関数呼び出しに関する情報を含むFUNCTION_CALLS列。

各関数の開始と終了は、Cで慣例となっているように、その中に示されています。関数の先頭に中括弧、最後にもう1つがあります。グラフのリーフであり、他の関数を呼び出さない関数は、セミコロン（;）で示されます。

関数のフィルター

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のStephen Rostedtの記事で、それらについて詳しく読むことができます。

イベントトレース

トレースポイントメカニズムについては既に説明しました。翻訳のトレースポイントという言葉は「トレースポイント」を意味します。トレースポイントは、特定のシステムイベントを記録するコードへの特別な挿入です。トレースポイントは、アクティブ（検証が割り当てられていることを意味する）または非アクティブ（検証が割り当てられていない）になります。

非アクティブなトレースポイントは、システムの動作に影響を与えません。インストルメント化された関数の最後にトレース関数を呼び出すために数バイトを追加するだけでなく、データ構造を別のセクションに追加します。

トレースポイントがアクティブな場合、対応するコードフラグメントが実行されると、トレース関数が呼び出されます。トレースデータはデバッグリングバッファに書き込まれます。

トレースポイントは、コードの任意の場所に挿入できます。それらはすでに多くの核機能のコードに存在しています。たとえば、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を書き込むことで、必要なトレースポイントをアクティブにします。

 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機能の一般的な概要を提供しました。コメントや追加は大歓迎です。トピックをさらに深く掘り下げたい場合は、次のソースに精通することをお勧めします。

https://www.kernel.org/doc/Documentation/trace/tracepoints.txt-トレースポイントのメカニズムの詳細な説明。
https://www.kernel.org/doc/Documentation/trace/events.txt-Linuxでシステムイベントをトレースするためのガイド。
https://www.kernel.org/doc/Documentation/trace/ftrace.txt-公式のftraceドキュメント。
https://lttng.org/files/thesis/desnoyers-dissertation-2009-12-v27.pdf-カーネルのトレースとプロファイリングに関するMathieu Denoir（トレースポイントのメカニズムの作成者およびLTTNGの作成者）による論文。
https://lwn.net/Articles/370423/-ftrace機能に関するStephen Rodstedtの記事。
http://alex.dzyoba.com/linux/profiling-ftrace.html-実用的なケーススタディを含むftraceのレビュー記事。
http://panda-nox.livejournal.com/2235.html-ロシア語でのftraceに関する唯一の詳細な出版物。

何らかの理由でここにコメントを残せない場合は、ブログに招待します。

ftraceを使用したカーネルトレース