Call Traceとは
Call Trace (読み方:こーるとれーす)とは、Linux Kernel の呼び出した関数のスタックトレースです。
OS (Kernel) がハングアップした場合などでログに出力されます。
スタックトレースとは、関数がどのようにスタックされていったのか (どの関数がどの関数を呼び出したか) を示したものです。
スタックとは、LIFO (Last IN First OUT) のデータ格納方式のことです。
プログラムにおいては、例えばプログラム内の関数 A から別の関数 B を呼び出し、関数 B の仕事が終わった後に関数 A に戻るためのメモリアドレスを格納する方式のことです。
スタックを格納するメモリ領域をスタック領域と言います。
プログラム実行中のCPU、メモリの変化
プログラムは Main 関数から始まり、様々な関数を次々に呼び出すことができます。
上図のようにメモリ上に展開されたプログラム A はメモリアドレス 100 から実行するために、CPU のプログラムカウンタという Register の初期値を 100 にセットします。
100 の "命令 1" が終わると次は 101 を実行します。それが終わると 102 へ、、、と順に命令を実行していきます。
しかし途中で関数を呼び出し (Call)すると、実行する命令はその関数が展開されているメモリアドレスへ飛びます。
上記例では、105 の次は関数 A の最初のメモリアドレスである 200 へ飛びます。
しかしただ飛んでは戻ってこれなくなるので、スタック領域に関数 A が終わった後に戻るべきメモリアドレス「106」を格納します。
そして関数 A に飛び、同様に命令を実行していきますが、途中でまた同様に関数 B へ飛びます。そして同じようにスタック領域に戻るべきメモリアドレス「203」を格納します。
このときスタック領域には 203 と 106 が格納されています。
そして関数 B が終わるとスタック領域から戻るべきメモリアドレスを取得するのですが、このときに LIFO に従い、最後に格納した「203」へ戻り、スタック領域から「203」を削除します。
そして関数 A に戻った後、関数 A も終了し、同様にスタック領域の「106」へ戻り、「106」を削除します。
と、このような流れになるのですが、話は戻って Call Trace は、このように関数の呼び出し (Call) のスタックを追跡 (Trace) した状態を吐き出したものになります。
Call Traceの見方
例えば以下の Call Trace の場合を考えます。
[ 4.679750] Call Trace: [ 4.679774] [<ffffffff812676b4>] dump_stack+0x44/0x55 [ 4.679803] [<ffffffff81055434>] warn_slowpath_common+0x9a/0xb3 [ 4.679842] [<ffffffffa005214f>] ? drm_wait_one_vblank+0x12c/0x145 [drm] [ 4.679870] [<ffffffff81055494>] warn_slowpath_fmt+0x47/0x49 [ 4.679896] [<ffffffff81083c09>] ? finish_wait+0x57/0x60 [ 4.679935] [<ffffffffa005214f>] drm_wait_one_vblank+0x12c/0x145 [drm] [ 4.679959] [<ffffffff81083d14>] ? wait_woken+0x70/0x70 [ 4.680041] [<ffffffffa01e44ef>] intel_atomic_commit+0x403/0x526 [i915] [ 4.680083] [<ffffffffa00659fa>] drm_atomic_commit+0x48/0x4d [drm] [ 4.680124] [<ffffffffa00e411f>] restore_fbdev_mode+0xee/0x26c [drm_kms_helper] [ 4.680178] [<ffffffffa00e5b35>] drm_fb_helper_restore_fbdev_mode_unlocked+0x2b/0x6a [drm_kms_helper] [ 4.680218] [<ffffffffa00e5bae>] drm_fb_helper_set_par+0x3a/0x46 [drm_kms_helper] [ 4.680295] [<ffffffffa01fa9a2>] intel_fbdev_set_par+0x12/0x4f [i915] [ 4.680320] [<ffffffff812a9283>] fbcon_init+0x309/0x406 [ 4.680345] [<ffffffff81314fd5>] visual_init+0xc8/0x11d [ 4.680372] [<ffffffff813166fc>] do_bind_con_driver+0x1ab/0x2cd [ 4.680400] [<ffffffff81316ae6>] do_take_over_console+0x142/0x172 [ 4.680427] [<ffffffff812a8942>] do_fbcon_takeover+0x56/0x9a [ 4.680457] [<ffffffff812abe1e>] fbcon_event_notify+0x31c/0x644 [ 4.680484] [<ffffffff8106cb08>] notifier_call_chain+0x37/0x59 [ 4.680517] [<ffffffff8106cd5f>] __blocking_notifier_call_chain+0x41/0x5a [ 4.680549] [<ffffffff8106cd87>] blocking_notifier_call_chain+0xf/0x11 [ 4.680577] [<ffffffff812b0b0a>] fb_notifier_call_chain+0x16/0x18 [ 4.680606] [<ffffffff812b282a>] register_framebuffer+0x26f/0x2a7 [ 4.680652] [<ffffffffa00e5e66>] drm_fb_helper_initial_config+0x2ac/0x321 [drm_kms_helper] [ 4.680730] [<ffffffffa01fb338>] intel_fbdev_initial_config+0x16/0x18 [i915] [ 4.680758] [<ffffffff8106ddce>] async_run_entry_fn+0x34/0xbe [ 4.680786] [<ffffffff81067583>] process_one_work+0x1b2/0x327 [ 4.680812] [<ffffffff81067e85>] worker_thread+0x277/0x36f [ 4.680843] [<ffffffff81067c0e>] ? cancel_delayed_work_sync+0x10/0x10 [ 4.680865] [<ffffffff8106bf63>] kthread+0xcd/0xd5 [ 4.680895] [<ffffffff8106be96>] ? kthread_create_on_node+0x15c/0x15c [ 4.680921] [<ffffffff814f801f>] ret_from_fork+0x3f/0x70 [ 4.680952] [<ffffffff8106be96>] ? kthread_create_on_node+0x15c/0x15c [ 4.680973] ---[ end trace f295b50a7b94aa26 ]---
最後の "kthread_create_on_node" というのが大元の関数で、それから ret_from_fork, kthread_create_on_node, kthread,,, と呼び出していっています。
横にある ffffffff8106be96 等の値がスタック領域に格納されているメモリアドレスです。
上から 2 番目にある "warn_slowpath_common" が耐え切れなくなり、最後に "dump_stack" により Call Trace を吐き出した、となっています。
IT/インフラエンジニアの地位とスキル向上のために
あなたが成長の日々を歩めますように。
コメント