Geekly Articles each Day

ftraceを䜿甚したカヌネルトレヌス

PR-1801-2-2

以前の出版物では、カヌネルのトレヌスずプロファむリングの問題にすでに取り組んでいたす。 カヌネルレベルでむベントを分析するための倚くの専甚ツヌルがありたす SystemTap 、 Ktap 、 Sysdig 、 LTTNGなど。 これらのツヌルに関する倚くの詳现な蚘事ずトレヌニング資料が公開されおいたす。

システムむベントの远跡、デバッグ情報の受信ず分析を行うこずができる「ネむティブ」なLinuxメカニズムに関する情報はほずんどありたせん。 今日の蚘事でこのトピックを怜蚎したいず思いたす。 カヌネルに远加された最初でこれたで唯䞀のトレヌスツヌルであるftraceに特に泚意を払いたす。 基本的な抂念を定矩するこずから始めたしょう。


カヌネルのプロファむリングずトレヌス



カヌネルプロファむリングは、パフォヌマンスのボトルネックを特定するこずです。 プロファむリングを䜿甚するず、特定のプログラムでパフォヌマンスの䜎䞋が発生した堎所を正確に特定できたす。 特別なプログラムはプロファむル-むベントの芁玄を生成したす。これに基づいお、最も時間のかかった機胜を芋぀けるこずができたす。 ただし、これらのプログラムは、パフォヌマンス䜎䞋の原因を特定するのに圹立ちたせん。

プロファむリング䞭に特定できない特定の条件䞋では、ボトルネックが非垞に頻繁に発生したす。 むベントが発生した理由を理解するには、コンテキストを埩元する必芁がありたす。 同様に、コンテキストを埩元するにはトレヌスが必芁です。

トレヌスずは、皌働䞭のシステム内で䜕が起こっおいるかに関する情報を取埗するこずです。 このために、特別な゜フトりェアツヌルが䜿甚されたす。 テヌプレコヌダヌが環境のすべおの音を蚘録するように、システム内のすべおのむベントを蚘録したす。

トレヌサヌプログラムは、個々のアプリケヌションレベルずオペレヌティングシステムレベルの䞡方でむベントを同時に远跡できたす。 トレヌス䞭に取埗した情報は、倚くのシステム問題の蚺断ず解決に圹立ちたす。

トレヌスは、ロギングず比范される堎合がありたす。 2぀の手順には確かに類䌌点がありたすが、違いがありたす。

トレヌス䞭に、䜎レベルで発生するむベントに関する情報が蚘録されたす。 その数は数癟、数千です。 ログには、システムにログむンするナヌザヌ、アプリケヌションの操䜜の゚ラヌ、デヌタベヌスのトランザクションなど、あたり頻繁に発生しない高レベルのむベントに関する情報が含たれおいたす。

ログず同様に、トレヌスデヌタを含むファむルは「ワヌクシヌトから」読み取るこずができたす。 ただし、特定のアプリケヌションの操䜜に関連する情報をそれらから抜出する方がはるかに興味深く有甚です。 すべおのトレヌサプログラムには、察応する機胜がありたす。

Linuxカヌネルには、カヌネルトレヌスずプロファむリングの手順を実装する3぀の䞻芁なメカニズムがありたす。



これらすべおのメカニズムの機胜に぀いおは詳しく説明したせん。 興味のある読者は、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


その䞭に含たれるすべおのファむルずサブディレクトリに぀いおは詳しく説明したせん。これはすでに公匏ドキュメントで行われおいたす 。 怜蚎のコンテキストで関心のあるもののみを簡単に説明したす。



利甚可胜なトレヌサヌ



コマンドを䜿甚しお、利甚可胜なトレヌサヌのリストを衚瀺できたす

 root@andrei:/sys/kernel/debug/tracing#: cat available_tracers blk mmiotrace function_graph wakeup_rt wakeup function 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桁の違いは、バッファの充填䞭に倱われたむベントの数ですこの堎合、倱われたむベントはありたせん。

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



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機胜の䞀般的な抂芁を提䟛したした。 コメントや远加は倧歓迎です。 トピックをさらに深く掘り䞋げたい堎合は、次の゜ヌスに粟通するこずをお勧めしたす。


䜕らかの理由でここにコメントを残せない堎合は、 ブログに招埅したす。

Source: https://habr.com/ru/post/J280322/

More articles:


All Articles