川井拓真

Linuxカーネルのバックトレースの読み方 (arm64)

組み込みLinuxの顧客サポートでは、カーネルパニックのログのみによってアドバイスを求められることが多々あります。 ビルドオプション(.config)やカーネルの実行バイナリは提供されることがありますが、状況の再現に必要なユーザ空間アプリを含むルートファイルシステムやハードウェアを含む実行環境は入手できないことがあります。

本稿では、Linuxカーネルのエラーや警告が発生した際に表示されるバックトレースの読み方を説明します。

バックトレースの例

以下のバックトレースはlinux-5.10.yのarm64カーネルでブロックデバイスに書き込みを行っている最中にブロックデバイスをunbindして削除した際、確率的に発生する警告ログです。 例えばdd if=/dev/zero of=/dev/vda &; echo virtio1 > /sys/bus/virtio/drivers/virtio_blk/unbindなどとして再現できます。 writeでページキャッシュにdirtyフラグを付ける際、ひもづいているデバイスがremove済みのときに表示されます。 このあとwriteはEIOで失敗します。

[   32.974917] ------------[ cut here ]------------
[   32.974996] bdi-254:0 not registered
[   32.975404] WARNING: CPU: 0 PID: 111 at fs/fs-writeback.c:2309 __mark_inode_dirty+0x178/0x230
[   32.975476] Modules linked in:
[   32.975680] CPU: 0 PID: 111 Comm: dd Not tainted 5.10.83-rt58+ #28
[   32.975769] Hardware name: linux,dummy-virt (DT)
[   32.975940] pstate: 40000005 (nZcv daif -PAN -UAO -TCO BTYPE=--)
[   32.975985] pc : __mark_inode_dirty+0x178/0x230
[   32.976021] lr : __mark_inode_dirty+0x178/0x230
[   32.976044] sp : ffffff80043d7aa0
[   32.977591] x29: ffffff80043d7aa0 x28: 0000000000000000
[   32.977659] x27: ffffff8002c882f8 x26: 0000000000001000
[   32.977679] x25: fffffffefffeb8c0 x24: 0000000000000001
[   32.977698] x23: 0000000000000000 x22: ffffff800135e860
[   32.977716] x21: ffffff800135e8b8 x20: ffffff8001f800f8
dd: error writing '/dev/vda': Input/output error
[   32.977735] x19: ffffff800135e800 x18: ffffffffffffffff
[   32.977753] x17: 0000000000000000 x16: 0000000000000000
[   32.977772] x15: ffffffc010a48cc8 x14: ffffffc010a48c88
[   32.977790] x13: ffffffffffffc000 x12: 0000000000000000
[   32.977808] x11: ffffff80043d79f0 x10: ffffff80043d79f0
[   32.977826] x9 : ffffff80043d7aa0 x8 : ffffff80043d7aa0
[   32.977874] x7 : 0000000000000005 x6 : ffffffc010a53cd8
[   32.977893] x5 : 0000000000000001 x4 : 0000000000000000
[   32.977910] x3 : 0000000000000001 x2 : 0000000000000001
[   32.977928] x1 : d570edbcce262b00 x0 : 0000000000000000
[   32.978098] Call trace:
[   32.978152]  __mark_inode_dirty+0x178/0x230
[   32.978182]  mark_buffer_dirty+0xd4/0xf8
[   32.978204]  __block_commit_write.isra.54+0xd4/0x118
[   32.978218]  block_write_end+0x44/0xa0
[   32.978232]  blkdev_write_end+0x18/0x80
[   32.978279]  generic_perform_write+0x104/0x1a8
[   32.978301]  __generic_file_write_iter+0xfc/0x1c0
[   32.978317]  blkdev_write_iter+0xb4/0x160
[   32.978331]  new_sync_write+0xf0/0x190
[   32.978345]  vfs_write+0x33c/0x3e0
[   32.978358]  ksys_write+0x6c/0x100
[   32.978371]  __arm64_sys_write+0x1c/0x28
[   32.978384]  el0_svc_common.constprop.3+0x68/0x1b0
[   32.978400]  do_el0_svc_compat+0x1c/0x48
[   32.978415]  el0_svc_compat+0x14/0x20
[   32.978430]  el0_sync_compat_handler+0xf4/0x148
[   32.978443]  el0_sync_compat+0x164/0x180
[   32.978557] ---[ end trace 0000000000000002 ]---

本稿ではこのログを例にとり、バックトレースの読み方を説明します。

ヘッダー

[   32.974996] bdi-254:0 not registered
[   32.975404] WARNING: CPU: 0 PID: 111 at fs/fs-writeback.c:2309 __mark_inode_dirty+0x178/0x230
[   32.975476] Modules linked in:
[   32.975680] CPU: 0 PID: 111 Comm: dd Not tainted 5.10.83-rt58+ #28
[   32.975769] Hardware name: linux,dummy-virt (DT)

この例はWARN()マクロによる警告表示なので、はじめに警告メッセージ(bdi-254:0 not registered)が表示され、 また警告発生個所のファイル名・行番号(fs/fs-writeback.c:2309)まで最初から判明していますが、 例えばCPU例外によるカーネルパニックなどの際は行番号などは通常表示されません。

PIDはcurrent->pidを表示しており、PIDと書かれていますが、実行状態のスレッドIDです。 カーネルスレッドかもしれないし、ユーザースレッドかもしれません。 割込みハンドラ中で例外が起きた場合も表示されますが、あまり意味がありません。 アイドル状態で発生した割込みハンドラ中で例外が起きた場合、CPU: 0 PID: 0 Comm: swapper/0という具合に表示されます。 LinuxのアイドルタスクはPID 0です。

レジスタダンプ

例外が発生したときのレジスタ値を表示しています。 同期例外なら、その例外が発生した命令を実行する直前のレジスタ値が表示されます。 解析の初期段階では通常無視しますが、逆アセを調べる段階で直近の命令列と見比べるとCソースコードレベルで変数の内容が分かることがあります。

バックトレースの1行目

バックトレースの1行目は極めて重要で、ここをみるとエラー発生個所がわかります。

[   32.978098] Call trace:
[   32.978152]  __mark_inode_dirty+0x178/0x230

この例ではビルドツリーでobjdump -d fs/fs-writeback.oなどとして__mark_inode_dirtyからオフセット+0x178のところをみると逆アセで例外発生個所がわかります。 この例では以下のcd8: d4210000 brk #0x800のところで例外が起きています。 WARN()マクロはブレークポイント命令を使って詳細なログ表示を実現しています。 レジスタダンプやバックトレースを表示する仕組みはカーネルパニックと同じです。

0000000000000b60 <__mark_inode_dirty>:
__mark_inode_dirty():
     b60:       d503233f        paciasp
     b64:       a9bc7bfd        stp     x29, x30, [sp, #-64]!
     b68:       52810062        mov     w2, #0x803                      // #2051
     b6c:       6a02003f        tst     w1, w2
...
     ccc:       90000002        adrp    x2, 0 <move_expired_inodes>
     cd0:       91000040        add     x0, x2, #0x0
     cd4:       94000000        bl      0 <__warn_printk>
     cd8:       d4210000        brk     #0x800                          // !!!!
     cdc:       90000000        adrp    x0, 0 <jiffies>
     ce0:       f9400001        ldr     x1, [x0]
     ce4:       f9007681        str     x1, [x20, #232]

CONFIG_DEBUG_INFO=yとすると生成される.oやvmlinuxにデバッグ情報が入り、objdump -lでソースコードの行番号がわかります。 この例では以下のように表示されます。

/home/****/linux/fs/fs-writeback.c:2307
     cc4:       94000000        bl      0 <bdi_dev_name>
     cc8:       aa0003e1        mov     x1, x0
     ccc:       90000002        adrp    x2, 0 <move_expired_inodes>
     cd0:       91000040        add     x0, x2, #0x0
     cd4:       94000000        bl      0 <__warn_printk>
     cd8:       d4210000        brk     #0x800

バックトレースの末尾 (arm64)

メモリ破壊などの場合、経験的にエラー発生個所よりもコンテキストのほうが重要です。 バックトレースの末尾をみると、どういったコンテキストでエラーが発生したか分かります。

[   32.978371]  __arm64_sys_write+0x1c/0x28
[   32.978384]  el0_svc_common.constprop.3+0x68/0x1b0
[   32.978400]  do_el0_svc_compat+0x1c/0x48
[   32.978415]  el0_svc_compat+0x14/0x20
[   32.978430]  el0_sync_compat_handler+0xf4/0x148
[   32.978443]  el0_sync_compat+0x164/0x180

この例では、32ビット(compat)のユーザーモード(el0)からwriteシステムコール(sys_write)を実行したコンテキストで異常が発生したことがわかります。el0_sync_compatのsyncは同期例外の意味です。 この場合呼び出し元がユーザ空間アプリなので、例えばメモリ破壊などエラー発生個所と不具合箇所が異なる場合、まずは呼び出し元アプリを調べ、現象が発生した状況を考えることになります。

カーネルスレッドで例外が起きると以下のようになり、

process_one_work+0x1f0/0x500
worker_thread+0x48/0x480
kthread+0x160/0x180
ret_from_fork+0x10/0x18

割込みハンドラ中で例外が起きた場合は以下のようになります。

handle_irq_event+0x50/0xc0
handle_fasteoi_irq+0xbc/0x200
handle_domain_irq+0x94/0xe0
gic_handle_irq+0x48/0xd0
call_on_irq_stack+0x28/0x44
do_interrupt_handler+0x4c/0x54
el1_interrupt+0x2c/0x6c
el1h_64_irq_handler+0x14/0x20
el1h_64_irq+0x74/0x78

カーネルスレッドを実行中に割込みが発生した場合は、上記のログが末尾にならず、割込み発生元スレッドのスタックがさらに表示されることがあります。

CPU例外ハンドラの読み方と最近の変更 (arm64)

arm64のentry.Sはときどきリファクタリングが行われているのですが、Linux 5.14でシンボル名の変更が行われ、バックトレースの見た目が変わりました。

最近のバージョンでは、例えば割込みハンドラ中で不正アクセスによりカーネルパニックが起きると、以下のようなログになります。

[    8.120340] Call trace:
[    8.121402]  string+0x50/0x100
[    8.122063]  vsnprintf+0x2bc/0x7f0
[    8.122781]  vprintk_store+0xd8/0x434
[    8.123518]  vprintk_emit+0xe4/0x21c
[    8.124282]  vprintk_default+0x34/0x40
[    8.125145]  vprintk+0xb8/0xf0
[    8.125745]  _printk+0x48/0x50
[    8.126361]  pl011_irq+0x24/0x30
[    8.127025]  __handle_irq_event_percpu+0x54/0x160
[    8.127800]  handle_irq_event+0x50/0xc0
[    8.128451]  handle_fasteoi_irq+0xbc/0x200
[    8.129394]  handle_domain_irq+0x94/0xe0
[    8.130127]  gic_handle_irq+0x48/0xd0
[    8.130821]  call_on_irq_stack+0x28/0x44
[    8.131595]  do_interrupt_handler+0x4c/0x54
[    8.132250]  el1_interrupt+0x2c/0x6c
[    8.132939]  el1h_64_irq_handler+0x14/0x20
[    8.133604]  el1h_64_irq+0x74/0x78
[    8.134218]  arch_cpu_idle+0x14/0x20
[    8.134961]  do_idle+0xb4/0x130
[    8.135575]  cpu_startup_entry+0x24/0x50
[    8.136259]  rest_init+0xe0/0xf0
[    8.137056]  arch_call_rest_init+0xc/0x14
[    8.137928]  start_kernel+0x464/0x484
[    8.138618]  __primary_switched+0xa0/0xa8
[    8.140128] Code: 91000400 110004e1 eb08009f 540000c0 (38646845)
[    8.142208] ---[ end trace 6fc36ef3c81b26b2 ]---
[    8.143700] Kernel panic - not syncing: Oops: Fatal exception in interrupt
[    8.145259] Kernel Offset: disabled
[    8.145780] CPU features: 0x00002000,00000802
[    8.147072] Memory Limit: none
[    8.148086] ---[ end Kernel panic - not syncing: Oops: Fatal exception in interrupt ]---

CPU例外ハンドラのシンボル名がel[01][th]_(64|32)_(sync|irq|fiq|error)という表現に統一されました。 わかりやすいので、それぞれの意味を以下にまとめました。

キーワード 意味
el0 ユーザーモード
el1 カーネルモード
t スレッドモード
h ハンドラモード
sync 同期例外
irq IRQ,通常割込み
fiq FIQ,高速割込み
error SError,非同期に起きるメモリバスエラー

これらは組み合わせに制約があり、ハンドラは以下の組み合わせしかありません。

ハンドラ 意味
el1t_64_(sync|irq|fiq|error) この例外は通常起きないが、発生すると必ずパニックになる
el1h_64_(sync|irq|fiq|error) カーネル空間のプログラムを実行中にエラーが発生した
el0t_64_(sync|irq|fiq|error) ユーザー空間の64ビットプログラムを実行中にエラーが発生した
el0t_32_(sync|irq|fiq|error) ユーザー空間の32ビットプログラムを実行中にエラーが発生した

ハンドラとしてはel1t_64_(sync|irq|fiq|error)も定義されていますが、通常このハンドラが実行されることはありません。 AArch64ではSPSEL=0としたときELxでSPがSP_EL0を指すようになり、この状態をEL1tと呼びますが(Armv8 ARM D1.6.2)、Linuxは常にSPSEL=1で動くように設計されており通常はEL1tの状態を取りません。 無理やりEL1tに切り替えると、例外が発生してel1t_64_(sync|irq|fiq|error)ハンドラが実行され、必ずカーネルパニックが起きます。 このことはカーネル空間でasm volatile("msr spsel,#0")などとして確かめることができます。

https://github.com/torvalds/linux/blob/v5.15/arch/arm64/kernel/entry-common.c#L346

また、EL0にハンドラモードは存在しません。

Mem abort info, Data abort infoの読み方 (arm64)

Linux 4.14以降はメモリ不正アクセスが起きた際にMem abort infoといった形で詳細な例外情報が表示されます。

[    5.165950] Unable to handle kernel paging request at virtual address ffffdeadbeef0000
[    5.166421] Mem abort info:
[    5.166582]   ESR = 0x96000004
[    5.166758]   EC = 0x25: DABT (current EL), IL = 32 bits
[    5.166983]   SET = 0, FnV = 0
[    5.167185]   EA = 0, S1PTW = 0
[    5.167339]   FSC = 0x04: level 0 translation fault
[    5.167568] Data abort info:
[    5.167716]   ISV = 0, ISS = 0x00000004
[    5.167900]   CM = 0, WnR = 0

それぞれ以下の意味があります。

ラベル 意味
ESR ESRは例外発生時にエラーの種類を調べるための特殊レジスタです(Armv8-A ARM D13.2.36)。この内容を細かく分解したものが次の行以降に表示されていて、下の4行とこの行は同じ内容です。
EC Error Classで例外の最も大きな分類です(Armv8-A ARM D1.10.4)。Linuxでは最初にこれを確認して分岐します。DABT (current EL)の部分はEC=0x25がどういう意味か説明していて、この場合はエラー発生元がcurrent ELつまりカーネルモードでData abortが起きたという意味です。ユーザモードで起きるとEC=0x24になります。DABTはページフォルトなどで極めて頻繁に発生する同期例外で、これだけで異常とは言えません。
IL 16または32と表示されます。呼び出し元がT32ステートかA32ステートかということです(Armv8-A ARM D1.10.4)。
SET 例外から回復可能かを表します(Armv8-A ARM D13.2.36)。Linuxはこのフィールドを使用しません(5.15)。
FnV FAR_ELxレジスタの値に意味があるかどうかを表します(Armv8-A ARM D13.2.36)。FnV=0の場合、フォールトが起きたときにアクセスを試みたアドレスがFAR_ELxに入っています。
EA Armv8-A ARMではIMPLEMENTATION DEFINEDです(Armv8-A ARM D13.2.36)。
S1PTW Stage 1のtranslation table walk中にStage 2のフォールトが起きたかどうかを表す(Armv8-A ARM D13.2.36)。ハイパーバイザを利用する文脈で、Stage 1のtarnslation table walkとはゲストOS内でのアドレス変換プロセスのことを言い、Stage 2のtarnslation table walkとは、ゲストOSが思っている物理アドレスからハイパーバイザに見えている物理アドレスへの変換を言います。LinuxではKVMのみこのフィールドを使います(Linuxは通常EL1で動くがKVMのみEL2で動く)。
FSC フォールトの詳細な種類を表します(Armv8-A ARM D13.2.36)。ざっくりわけて異常系のフォールトとマップがない・属性が合わない時の正常系フォールトがあります。詳細はfault_infoテーブルを見てください。
ISV ESRのSAS, SSE, SRT, SF, ARフィールドが有効かどうかを表します(Armv8-A ARM D13.2.36)。ISV=1なら以下のAccess size, SSE, SRT, SF, ARが表示され、ISV=0ならISSが表示されます。
Access size アクセスを試みたサイズ(1,2,4,8バイト)を表します(Armv8-A ARM D13.2.36)。
SSE Access sizeが1,2,4バイトのいずれかのとき、符号拡張が必要かどうかを表します(Armv8-A ARM D13.2.36)。
SRT オペランドRtのレジスタ番号です(Armv8-A ARM D13.2.36)。
SF アクセスを試みたレジスタが64ビット幅かどうか(Armv8-A ARM D13.2.36)。
AR ロードストア命令のAcquire/Releaseどちらか(Armv8-A ARM D13.2.36)。
ISS ESR[24:0]で、Mem abort infoに表示されている値と同じです。
CM キャッシュメンテナンスで起きたかどうか(Armv8-A ARM D13.2.36)。
WnR 書き込みで起きたか読み込みで起きたか(Armv8-A ARM D13.2.36)。

まとめ

本稿ではカーネルパニックやWARN()マクロによって表示されるエラーログの全体像と、バックトレースの読み方を説明しました。 ほとんどの場合は例外発生個所に不具合があるので、バックトレースの1行目からソースコード上でのエラー発生個所を調べることで不具合の原因を特定できます。

次回はメモリ破壊の解析手法について説明します。

コメントを残す

メールアドレスが公開されることはありません。 ※ が付いている欄は必須項目です