kdump-toolsでカーネルダンプの取得が正常に完了しない

archtomi

2022年11月14日 10時12分

Armadillo-IoT G3とG3Lの機器でカーネルパニックが発生した時にカーネルダンプを出力するためにkdump-toolsを導入して後から原因を調査しようとしていたのですが、両方の機器でカーネルダンプが正常に出力されない状態になっています。

カーネルダンプの準備として以下の作業を行っています。
１．以下の設定を有効にしてカーネルをビルド
・CONFIG_KEXEC
・CONFIG_SYSFS
・CONFIG_CRASH_DUMP
・CONFIG_DEBUG_INFO
・CONFIG_PROC_VMCORE
・AUTO_ZRELADDR

２．ブートローダのカーネルパラメータに以下の内容が追加されるようにしてビルド(遠隔で更新する用)
　optargs crashkernel=192M

３．armadilloで以下のパッケージをインストールする
・kexec-tools
・kdump-tools
・makedumpfile

４．/etc/default内の設定を以下のように変更
・kexecファイル
　・LOAD_KEXEC=false　　（必要がなさそうだったので無効）
・kdumo-toolsファイル
　・USE_KDUMP=1
　・KDUMP_KERNEL=/home/atmark/linux_at25/zImage
　・KDUMP_INITRDをコメントアウト
　・MAKEDUMP_ARGS="-d 31 --message-level 1"　（デフォルトから圧縮を無効、メッセージ出力を有効に変更）

５．ビルドしたカーネルとブートローダを適用して再起動

ここまでの作業を行って、「free -h」コマンドで使用できるRAM容量が１GBからcrashkernel分の空き容量が少なくなている事と「kdump-config test」コマンドでクラッシュカーネルのアドレスを参照されていることを確認しました。
カーネルクラッシュは、「echo c > /proc/sysrq-trigger」コマンドを実行して発生させています。
実際にカーネルパニックを発生させると、「/var/crash/日時」フォルダにファイルは作成されているのですが、ファイルがvmcore-incompleteしか作成されず、作成されるはずのdmesgは作成されていませんでした。
vmcore-incompleteはファイル容量はほとんどの場合が256MBでした。
カーネルのビルド時に作成されたSystem.mapとvmlinuxを使用してcrashコマンドでvmcore-incompleteを解析しようとしましたが、正常な出力ではないからかcrashのコマンド受付にならないで終了してしまいます。
vmcore-incompleteをバイナリエディタ等で開くとデータは書き込まれているので途中で失敗しているようです。

何とかしてできないかと以下の設定などを変更して試したが効果がありませんでした。
・armadilloのメモリ容量を1.3GBまで開放する
・LOAD_KEXECを有効化
・KDUMP_KERNELの参照先をuImageに変更
・MAKEDUMP_ARGSに"-c"を追加して圧縮の有無を変更
・crashkernelの内容を「auto」「64M」「260M」に変更
・KDUMP_COREDIRのカーネルダンプの出力先を変更
・カーネルのバージョンを「at17」と「at25」を入れ替えてビルド

確認したところ以下の点で気になることがあったのですが、これがカーネルダンプが作成されない原因でしょうか。
・「/proc/vmcore」が通常時に存在しない
・「kdump-config load」コマンドを実行すると「[FAIL] Invalid kernel version : 4.9.133-at25 ... failed!」が表示される。
・通常時に「kdump-config savecore」を実行しても失敗する
・クラッシュダンプ作成時のシリアル出力にkdumpのエラーが表示している。
　「kdump-tools[1837]: cp: '/proc/vmcore' の読み込みエラー: メモリを確保できません」

カーネルダンプが正常に出力されないのがカーネルが原因なのか、こちらの設定に問題があるのかわからないので確認お願いいたします。

ファイル	ファイルの説明
kdump_コマンド実行.txt	「kdump-config load」「kdump-config test」「kdump-config savecore」を実行した内容
kernel_dump_失敗_シリアル出力.txt	カーネルパニックを起こした時のシリアル出力内容

コメントを投稿するにはログインまたは登録をしてください

at_dominique.m…

2022年11月14日 16時15分

archtomiさん

お世話になっています。アットマークテクノのマルティンです。

確認したところ以下の点で気になることがあったのですが、これがカーネルダンプが作成されない原因でしょうか。・「/proc/vmcore」が通常時に存在しない

これで正常です。crash ブートの場合にちゃんと作成されますので、問題ないです。

・「kdump-config load」コマンドを実行すると「[FAIL] Invalid kernel version : 4.9.133-at25 ... failed!」が表示される。

スクリプトの中身を確認したところで、このメッセージは /boot から /var/lib/kdump への symlink を作成できなかった時に出力されます。 KDUMP_KERNEL/INITRD の変更で使わないことになりましたので、このエラーも問題ないです。見たところ設定でスキップできないので、メッセージが気になりましたらスクリプトに直接に kdump_create_symlinks を無効化するしかなさそうですね… とりあえず無視していいです。

・通常時に「kdump-config savecore」を実行しても失敗する

/proc/vmcore がないため、これも正常ですね。 crash kernel に再起動して実行されるコマンドですので、通常時に使えなくても大丈夫です。（できたらデバグに便利でしたけど…）

・クラッシュダンプ作成時のシリアル出力にkdumpのエラーが表示している。　「kdump-tools[1837]: cp: '/proc/vmcore' の読み込みエラー: メモリを確保できません」

こちらで再現できました。 - makedumpfile が「The kernel version is not supported. The makedumpfile operation may be incomplete. check_release: Can't get the kernel version.」のエラーで使えないようです。 - メモリ不足に見えるエラーですが、メモリの半分以上を crashkernel に提供しても治りませんのでカーネルの不具合かもしれません。

makedumpfile を更新したところ、 makedumpfile -d 31 を正常に実行できました。 cp の場合はアクセスしてはならないページを読もうとしていると推測します。 makedumpfile -d 31 --message-level 1 でも、 echo c > /proc/sysrq-trigger で確認して、無事に /var/crash/202211141412/dump.202211141412 と /var/crash/202211141412/dmesg.202211141412 を作成できました。 https://github.com/makedumpfile/makedumpfile の maste` ブランチを使ってREADMEにしたがっただけですが、bullseye のバージョンをバックポートしたら動くかもしれません。試してません。

その dump を crash で使ってみたら、 makedumpfile と似たような crash が古いと言うエラーが出力されて、 crash も、単純に https://github.com/crash-utility/crash を取得してビルドしたら無事に動くようになりました。

(G3上のビルドに結構時間かかります…)

root@armadillo:~/crash# ./crash /root/vmlinux /var/crash/202211141412/dump.202211141412 

crash 8.0.1++

[...]

      KERNEL: /root/vmlinux                     
    DUMPFILE: /var/crash/202211141412/dump.202211141412  [PARTIAL DUMP]
        CPUS: 2 [OFFLINE: 1]
        DATE: Mon Nov 14 14:11:50 JST 2022
      UPTIME: 00:00:40
LOAD AVERAGE: 3.90, 1.05, 0.36
       TASKS: 169
    NODENAME: armadillo.test.domain
     RELEASE: 4.9.133-at23-00014-g19cf18212e95-dirty
     VERSION: #37 SMP PREEMPT Mon Nov 14 12:17:48 JST 2022
     MACHINE: armv7l  (unknown Mhz)
      MEMORY: 2 GB
       PANIC: "sysrq: SysRq : Trigger a crash"
         PID: 2851
     COMMAND: "bash"
        TASK: d8845640  [THREAD_INFO: d9c44000]
         CPU: 1
       STATE: TASK_RUNNING (SYSRQ)

crash> bt
PID: 2851     TASK: d8845640  CPU: 1    COMMAND: "bash"
 #0 [<804e28a8>] (sysrq_handle_crash) from [<804e2e24>]
 #1 [<804e2e24>] (__handle_sysrq) from [<804e3370>]
 #2 [<804e3370>] (write_sysrq_trigger) from [<8028c344>]
 #3 [<8028c344>] (proc_reg_write) from [<8022e0c8>]
 #4 [<8022e0c8>] (vfs_write) from [<8022ee40>]
 #5 [<8022ee40>] (sys_write) from [<80107440>]
    pc : [<76e67746>]    lr : [<76ede3b3>]    psr: 60000030
    sp : 7e8fb870  ip : 00000004  fp : 00000000
    r10: 00000000  r9 : 00000002  r8 : 00000002
    r7 : 00000004  r6 : 76f46db0  r5 : 0139b820  r4 : 00000074
    r3 : 00000000  r2 : 00000002  r1 : 0139b820  r0 : 00000001
    Flags: nZCv  IRQs on  FIQs on  Mode USER_32  ISA Thumb

大変な作業で申し訳ございませんが、正式にサポートしていないコマンドですのでこれ以上は難しいと思います。

よろしくお願いします。

コメントを投稿するにはログインまたは登録をしてください

archtomi

2022年11月18日 15時55分

アットマークテクノ　マルティンさん

いつもお世話になっております　冨澤です。
カーネルダンプについての調査して頂きありがとうございます。
https://github.com/makedumpfile/makedumpfile のページを参照してソフトを更新しましたが、効果がありませんでした。
そこでクラッシュカーネルが呼ばれた時に操作ができるようにして、クラッシュカーネルの状態で確認すると/proc/vmcoreファイルが存在していました。
容量は800MBあるのでカーネルパニック前のRAMの容量のようです。
このファイルを別の場所に保存したかったのですが、SDカードにコピーやSFTPで転送しようとしたところ、256MBから先のファイルを読み込んだところでエラーが発生するみたいで、途中までしか保存できませんでした。
「kdump-tools[1837]: cp: '/proc/vmcore' の読み込みエラー: メモリを確保できません」の内容はこれが原因のようです。
途中まで出力したファイルでmakedumpfileを実行すると問題なく処理できているようなのでソフトは問題なさそうです。
一応dmesgは取得できるようになったので、今のところはこの内容で解析しようと思います。

ありがとうございました。

ファイル	ファイルの説明
vmcore_SSH転送エラー.txt	vmcoreをSFTPで転送した時に発生したエラー

コメントを投稿するにはログインまたは登録をしてください

archtomi

2022年11月18日 17時25分

いつもお世話になっております　冨澤です。
この後でクラッシュカーネルのサイズを192MBから64MBにしてカーネルパニックを発生させるとmakedumpfileによるカーネルダンプができていることを確認できました。
クラッシュカーネルを小さくすることで切り替え時の起動でNetworkManagerのメモリ不足によるエラーが発生しているようですが、G3・G3L共にカーネルダンプが出力されることを確認したので、この件については解決しました。
ありがとうございました。

ファイル	ファイルの説明
kernel_dump_成功_シリアル出力.txt	カーネルダンプ成功時に発生していたNetworkManagerのエラー内容

コメントを投稿するにはログインまたは登録をしてください

at_dominique.m…

2022年11月18日 18時00分

冨澤さん、

報告ありがとうございました。
解決できてよかったです。

クラッシュのメモリを小さくすることで解決できてとても興味深いですが、とりあえずまた聞かれたら覚えておきます。
64MB では普通の rootfs / init で狭いですので、NetworkManager のエラーも無理もないですね。最適化を考えたら簡単な initrd を作成して、その initrd から rootfs をマウントして dump するだけの実装が最善ですが、今のままで動いていたらよしとしましょう…
もともと問題があってから解析したかったと思いますので、お手数をおかけしました。

また何かありましたらまたご連絡ください。

コメントを投稿するにはログインまたは登録をしてください

archtomi

2022年11月23日 9時58分

いつもお世話になっております　冨澤です。

sysrq以外のカーネルパニックでも出力されるか確かめるために、https://armadillo.atmark-techno.com/forum/armadillo/8124 で発生している内容でカーネルパニックを発生させてみました。
実際にカーネルパニックが発生した時に、クラッシュカーネルへの移行が成功する時と失敗する時があります。
シリアルでの出力を確認するとクラッシュカーネルを動作させるCPUの確保に失敗しているように見えます。
sysrqによるカーネルパニックは何回行ってもカーネルダンプが出力されていたので問題はなさそうです。
他のカーネルパニックでカーネルダンプが出力されない可能性がありそうなので確認して頂けないでしょうか。

よろしくお願いいたします。

ファイル	ファイルの説明
シリアルソフト_クラッシュカーネル起動失敗_bash.txt	クラッシュカーネルの起動失敗時のログ
シリアルソフト_クラッシュカーネル起動成功.txt	クラッシュカーネルの起動成功時のログ

コメントを投稿するにはログインまたは登録をしてください

at_dominique.m…

2022年11月24日 10時45分

冨澤さん

お世話になっています、
マルティネです。

> sysrq以外のカーネルパニックでも出力されるか確かめるために、https://armadillo.atmark-techno.com/forum/armadillo/8124 で発生している内容でカーネルパニックを発生させてみました。
> 実際にカーネルパニックが発生した時に、クラッシュカーネルへの移行が成功する時と失敗する時があります。
> シリアルでの出力を確認するとクラッシュカーネルを動作させるCPUの確保に失敗しているように見えます。
> sysrqによるカーネルパニックは何回行ってもカーネルダンプが出力されていたので問題はなさそうです。
> 他のカーネルパニックでカーネルダンプが出力されない可能性がありそうなので確認して頂けないでしょうか。

失敗する時のログを確認したところ、原因はこれですね：

Non-crashing CPUs did not react to IPI

`machine_kexec()` での BUG は説明のコメントもあります：

        /*
         * This can only happen if machine_shutdown() failed to disable some
         * CPU, and that can only happen if the checks in
         * machine_kexec_prepare() were not correct. If this fails, we can't
         * reliably kexec anyway, so BUG_ON is appropriate.
         */
        BUG_ON(num_online_cpus() > 1);

他の CPU を無事に停止できなかったため、kexec を拒否して kdump が失敗します。

原因は何でしょうね。
手元に他の方法で crash をさせてみましたが再現できませんでしたが、そちらのログと違って interrupt内の crash ではなかったのでそこに何かの手がかりになるかもしれません。
成功と失敗のログを比べたら、2つとも「imx_dma_tx()」で失敗しますが、スタックの上の呼ぶ関数が違います。handle_percpu_devid_irq か hrtimer_interrupt の処理で IPI を無効化するものがあるか、ただの偶然で IPI を無視したコアの方で何かの処理が入っているか、ちょっと判断しにくいですがどうでしょうね。

先ほどのメッセージは machine_crash_shutdown() での処理がタイムアウトした後ですので、とりあえず情報をもう少し提供していただけますでしょうか？

- arch/arm/kernel/machine_kexec.c の machine_crash_nonpanic_core() の「CPU 1 will stop doing anything useful since another CPU has crashed」を成功した場合に確認できますが、「CPU 0 will stop...」で成功することもありますでしょうか？
なければ、CPU1 に割り込みがくる場合に失敗しますので、rs485 の割り込み番号を確認して /proc/irq/xx/smp_affinity で常に cpu0 に処理してもらったらこの問題を回避出きるかもしれません。
- machine_kexec() の BUG_ON の前にBUG_ONと同じチェックを追加して、問題の場合に trigger_all_cpu_backtrace() を実行して cpu1 の情報を取り出せないかも確認したいです。停止命令を無視していたのでこれもダメかもしれませんが、方法が少し違いますので試していただければと思います。
- kdump の場合はすでに nr_cpus=1 で kexec していますので、反応しない cpu も何かの crash によって反応しなくなった場合は無視できます。単純に machine_kexec() の BUG_ON を削除したらどうなりますか？（変わりに何かの printk で区別出きるようにしてください）
CPU1 がまだ生きていたら危ないですので、運用に向いてないですが、一度試して運よく dump が作成されたらその cpu1 の情報を少しもらえるかもしれません。

よろしくお願いします。

コメントを投稿するにはログインまたは登録をしてください

archtomi

2022年11月24日 14時39分

お世話になっております　冨澤です。

確認して頂きありがとうございます。
今あるログで確認したところ、sysrqによるカーネルパニックではCPU0・CPU1のどちらの場合でも成功しています。
RT485によるカーネルパニックではCPU0で発生した場合はCPU1を停止していますが、CPU1で発生した場合はCPU0の停止は失敗しているようです。
CPUの情報の出力の方は試してみます。

コメントを投稿するにはログインまたは登録をしてください

archtomi

2022年11月25日 11時19分

お世話になっております　冨澤です。

CPUの情報を出力するために、「arch/arm/kernel/machine_kexec.c」を以下のように変更して、カーネルをビルドしました。

・・・・・・・・・・・・・・・・・・・・・・・・・・・・・
#include <linux/nmi.h>　　・・・追加
・・・・・・・・・・・・・・・・・・・・・・・・・・・・・
void machine_kexec(struct kimage *image)
{
・・・・・・・・・・・・・・・・・・・・・・・・・・・・・
	//BUG_ON(num_online_cpus() > 1);
	if(num_online_cpus() > 1)
	{
		printk("kdump add message\n");
		trigger_all_cpu_backtrace();
		printk("kdump add message end\n");
	}
	else
	{
		BUG_ON(num_online_cpus() > 1);
	}
・・・・・・・・・・・・・・・・・・・・・・・・・・・・・
}

ビルドしたカーネルをarmadilloに更新して、シリアルでログを取得していました。
クラッシュカーネルの移行失敗時のログでは「kdump add message」の後にCPU1の情報を出力していますが、trigger_all_cpu_backtrace()の後の「kdump add message end」が表示されていないので、途中でハングアップしているようです。
バックトレースを確認するといくつかパターンがありそうですが、この情報で調査できるでしょうか。

よろしくお願いいたします。

ファイル	ファイルの説明
シリアル出力_CPUメッセージ.txt

コメントを投稿するにはログインまたは登録をしてください

at_dominique.m…

2022年11月25日 11時38分

冨澤さん

> ビルドしたカーネルをarmadilloに更新して、シリアルでログを取得していました。
> クラッシュカーネルの移行失敗時のログでは「kdump add message」の後にCPU1の情報を出力していますが、trigger_all_cpu_backtrace()の後の「kdump add message end」が表示されていないので、途中でハングアップしているようです。

そうですね、CPU1 が落ちる場合には CPU0 に命令が届かずに kexec ではなく uboot からの再起動になってしまいます。
元々その可能性が高いと思っていましたので、ご確認ありがとうございました。

> バックトレースを確認するといくつかパターンがありそうですが、この情報で調査できるでしょうか。

そうですね、やっぱり「cpu0 が何をしているのか」の質問を答えないと調査が難しいですが、
cpu0 が割り込みの処理をすればその問題がないとのことですので /proc/irq での調整で何とかなりそうだと思います。
# 気持ち的には満足できない回避にしかなりませんが…

手元に armadillo x1 がないので確認を月曜日行いますが、以下のコマンドで割り込みを cpu0 だけに処理させると思います。

irq 番号を調べます。スクリプトなどでは変数に設定してください
# cat /sys/class/tty/ttymxc<rs485のポート>/irq
31 
# cat /proc/irq/31/smp_affinity_list
0-1
# echo 0 > /proc/irq/31/smp_affinity_list
# cat /proc/irq/31/smp_affinity_list
0

よろしくお願いします

コメントを投稿するにはログインまたは登録をしてください

archtomi

2022年11月28日 9時25分

お世話になっております　冨澤です。

内容を参考にして、armadillo起動時にttymxc0のポートをCPU0に処理させる設定を行いました。
ログを見た感じだと、クラッシュカーネルに移行しない事象はいまだ発生しますが頻度は下がっているように感じます。
もしかしたら新しい情報があるかもしれないので、シリアル出力の内容を載せます。

よろしくお願いいたします。

ファイル	ファイルの説明
シリアル出力_CPUメッセージ2.log

コメントを投稿するにはログインまたは登録をしてください

Armadilloフォーラム

kdump-toolsでカーネルダンプの取得が正常に完了しない

製品

コメント