h.adachi
2021年8月24日 15時07分
安達と申します。
お世話になります。
Armadillo-X1とアドオンボードATB-AGAD-USBLANを組み合わせ、
ATB-AGAD-USBLANのCN2に4Port USB-HUBを接続、そのUSB-HUBに
SD-CardReader×4を接続する構成で使用しています。
以下の問題が発生しております。
お手数おかけして申し訳ありませんが、御助力いただけないでしょうか。
現象：
SD-CardReaderの中の1個を接続しない状態で運用を続けていると、以下の
メッセージが接続中のTTYに表示され、また多くのコマンド(ftp/新規の
telet接続、cat、reboot、poweroff等)が実行出来なくなります。
lighttpd経由でのWeb操作も出来なくなっています。
外部との通信が出来なくなるため、実質的にハングアップ状態です。
--------------- ここから ---------------
Message from syslogd@armadillo at Aug 5 21:20:17 ...
kernel:Internal error: Oops: 5 [#1] PREEMPT SMP ARM
Message from syslogd@armadillo at Aug 5 21:20:17 ...
kernel:Process mmcqd/2 (pid: 117, stack limit = 0xa89ac218)
Message from syslogd@armadillo at Aug 5 21:20:17 ...
kernel:Stack: (0xa89add90 to 0xa89ae000)
Message from syslogd@armadillo at Aug 5 21:20:17 ...
kernel:dda0: a6cf5740 00000000 00000000 00001000 abaa1d4c a9f5db40 a9ea8c18 801ca82c
～～～ 中略 ～～～
Message from syslogd@armadillo at Aug 5 21:20:17 ...
kernel:dfe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000
Message from syslogd@armadillo at Aug 5 21:20:17 ...
kernel:Code: e10f0000 f10c0080 e5943020 ee1d1f90 (e593318c)
--------------- ここまで ---------------
調査状況：
topコマンドで表示される、load average、Tasksが徐々に増加していきます。
SD-CardReaderを接続し、代わりにSDカードを挿入しない状態で運用すると、
上記の現象にはならない様です。
＃アプリ的には、書込み先がないと判定して書込み動作を行わないという点で、
＃上記二つでの振る舞いに相違は相違はない設計です。
なお、syslog/kern.log/messages等には、該当時刻のログが採取されていません。
独自に採取しているログファイルにも何も出力されていないため、
ディスクアクセス全般がNGになっているのではないかと推測しています。
依頼事項：
お手数おかけしますが、以下についてご教授いただけないでしょうか。
・原因として何が考えられるか
・解決策／回避策として、何をすればよいか。
宜しくお願いいたします。
以上です。
コメント
h.adachi
入江様
安達です。
ご回答、ありがとうございます。
以下の様に、nice値をそれぞれ5, 10, 19に変更して試してみました。
しかし、残念ながら何れの場合も同様のログが出力されます。
root@armadillo:~# ps -ef |grep mmcqd
root 117 2 0 09:11 ? 00:00:00 [mmcqd/2]
root 119 2 0 09:11 ? 00:00:00 [mmcqd/2boot0]
root 166 2 0 09:11 ? 00:00:00 [mmcqd/2boot1]
root 178 2 0 09:11 ? 00:00:00 [mmcqd/2rpmb]
root 2215 2185 0 09:13 pts/0 00:00:00 grep mmcqd
root@armadillo:~# renice -n 5 117 119 166 178
117 (process ID) old priority 0, new priority 5
119 (process ID) old priority 0, new priority 5
166 (process ID) old priority 0, new priority 5
178 (process ID) old priority 0, new priority 5
root@armadillo:~#
root@armadillo:/var/log# ps -ef |grep mmcq
root 117 2 0 13:05 ? 00:00:00 [mmcqd/2]
root 119 2 0 13:05 ? 00:00:00 [mmcqd/2boot0]
root 166 2 0 13:05 ? 00:00:00 [mmcqd/2boot1]
root 178 2 0 13:05 ? 00:00:00 [mmcqd/2rpmb]
root 3024 2864 0 17:31 pts/2 00:00:00 grep mmcq
root@armadillo:/var/log# renice -n 10 117 119 166 178
117 (process ID) old priority 0, new priority 10
119 (process ID) old priority 0, new priority 10
166 (process ID) old priority 0, new priority 10
178 (process ID) old priority 0, new priority 10
root@armadillo:/var/log#
root@armadillo:~# ps -efl |grep mmcqd
1 S root 117 2 0 80 0 - 0 mmc_qu 10:28 ? 00:00:00 [mmcqd/2]
1 S root 163 2 0 80 0 - 0 mmc_qu 10:28 ? 00:00:00 [mmcqd/2boot0]
1 S root 175 2 0 80 0 - 0 mmc_qu 10:28 ? 00:00:00 [mmcqd/2boot1]
1 S root 179 2 0 80 0 - 0 mmc_qu 10:28 ? 00:00:00 [mmcqd/2rpmb]
0 S root 2245 2202 0 80 0 - 519 pipe_w 10:39 pts/0 00:00:00 grep mmcqd
root@armadillo:~#
root@armadillo:~# renice -n 19 117 163 175 179
117 (process ID) old priority 0, new priority 19
163 (process ID) old priority 0, new priority 19
175 (process ID) old priority 0, new priority 19
179 (process ID) old priority 0, new priority 19
root@armadillo:~#
調査、アドバイスをいただくに当たって、他にどの様な情報が必要でしょうか。
御教示いただけますよう、お願いいたします。
宜しくお願いいたします。
以上です。
> 入江です。
>
> 申し訳ございませんが、頂いた情報のみでは原因を特定できません。
>
> mmcqdのnice値(優先度)を下げた状態ではログは出力されますでしょうか。
>
> reniceコマンドなどで実行中のプロセスのnice値を変更できます。
>
> 以上、お手数おかけしますがよろしくお願いいたします。
>
h.adachi
入江様
安達です。
継続してテスト中ですが、前回の情報に誤りがある事に気づきました。
topコマンドの出力で、Load average, taskが徐々に増加していると書きましたが、
間違いでした。Load averageは確かに(CardReaderが接続されている時よりは)高いのですが、
徐々に増加している訳ではありませんでした。
但し、ランニング中に事象発生してから、数時間経過後に確認すると増えています。
ですので、事象発生を契機に増加していくのではないかと考えなおしました。
＃そうだとすると、事象発生のトリガが何か増々分からないのですが。
別件で、もう一つ教えていただけませんか。
増えているプロセスをみると、cron -F となっている様です。
時間毎に呼ぶのは、cron.hourlyに設定したntpdateだけなのですが、
cronのログは何処かに出力されないでしょうか。
/var/log下には見つけられませんでした。
宜しくお願いいたします。
以上です。
> 入江様
>
> 安達です。
>
> ご回答、ありがとうございます。
>
> 以下の様に、nice値をそれぞれ5, 10, 19に変更して試してみました。
> しかし、残念ながら何れの場合も同様のログが出力されます。
>
> root@armadillo:~# ps -ef |grep mmcqd
> root 117 2 0 09:11 ? 00:00:00 [mmcqd/2]
> root 119 2 0 09:11 ? 00:00:00 [mmcqd/2boot0]
> root 166 2 0 09:11 ? 00:00:00 [mmcqd/2boot1]
> root 178 2 0 09:11 ? 00:00:00 [mmcqd/2rpmb]
> root 2215 2185 0 09:13 pts/0 00:00:00 grep mmcqd
> root@armadillo:~# renice -n 5 117 119 166 178
> 117 (process ID) old priority 0, new priority 5
> 119 (process ID) old priority 0, new priority 5
> 166 (process ID) old priority 0, new priority 5
> 178 (process ID) old priority 0, new priority 5
> root@armadillo:~#
> root@armadillo:/var/log# ps -ef |grep mmcq
> root 117 2 0 13:05 ? 00:00:00 [mmcqd/2]
> root 119 2 0 13:05 ? 00:00:00 [mmcqd/2boot0]
> root 166 2 0 13:05 ? 00:00:00 [mmcqd/2boot1]
> root 178 2 0 13:05 ? 00:00:00 [mmcqd/2rpmb]
> root 3024 2864 0 17:31 pts/2 00:00:00 grep mmcq
> root@armadillo:/var/log# renice -n 10 117 119 166 178
> 117 (process ID) old priority 0, new priority 10
> 119 (process ID) old priority 0, new priority 10
> 166 (process ID) old priority 0, new priority 10
> 178 (process ID) old priority 0, new priority 10
> root@armadillo:/var/log#
> root@armadillo:~# ps -efl |grep mmcqd
> 1 S root 117 2 0 80 0 - 0 mmc_qu 10:28 ? 00:00:00 [mmcqd/2]
> 1 S root 163 2 0 80 0 - 0 mmc_qu 10:28 ? 00:00:00 [mmcqd/2boot0]
> 1 S root 175 2 0 80 0 - 0 mmc_qu 10:28 ? 00:00:00 [mmcqd/2boot1]
> 1 S root 179 2 0 80 0 - 0 mmc_qu 10:28 ? 00:00:00 [mmcqd/2rpmb]
> 0 S root 2245 2202 0 80 0 - 519 pipe_w 10:39 pts/0 00:00:00 grep mmcqd
> root@armadillo:~#
>
> root@armadillo:~# renice -n 19 117 163 175 179
> 117 (process ID) old priority 0, new priority 19
> 163 (process ID) old priority 0, new priority 19
> 175 (process ID) old priority 0, new priority 19
> 179 (process ID) old priority 0, new priority 19
> root@armadillo:~#
>
> 調査、アドバイスをいただくに当たって、他にどの様な情報が必要でしょうか。
> 御教示いただけますよう、お願いいたします。
>
> 宜しくお願いいたします。
> 以上です。
>
> > 入江です。
> >
> > 申し訳ございませんが、頂いた情報のみでは原因を特定できません。
> >
> > mmcqdのnice値(優先度)を下げた状態ではログは出力されますでしょうか。
> >
> > reniceコマンドなどで実行中のプロセスのnice値を変更できます。
> >
> > 以上、お手数おかけしますがよろしくお願いいたします。
> >
at_shinya.koga
アットマークテクノの古賀です。
安達さん：
>別件で、もう一つ教えていただけませんか。
>増えているプロセスをみると、cron -F となっている様です。
>時間毎に呼ぶのは、cron.hourlyに設定したntpdateだけなのですが、
>cronのログは何処かに出力されないでしょうか。
>/var/log下には見つけられませんでした。
確認ですが、「/var/log下には」とおっしゃっているのは、/var/log/cron.log のことでしょうか？
あるいは、/var/log/ にある全てのファイルを指していらっしゃるでしょうか。
もし前者（/var/log/cron.log）であれば、/var/log/syslog をご覧になってみて下さい。
/var/log/syslog に cron のログが出力されているのであれば、/etc/syslog.conf の cron に対する設定行のコメントアウトを解除することで、/var/log/cron.log へ出力されるようになるでしょう：
https://raspi.ryo.sc/cron_log/
https://wiki.debian.org/Rsyslog
h.adachi
アットマークテクノ)古賀様
安達です。
お世話になっております。
ご回答ありがとうございます。
はい、/var/log/下にcron.logが作成されるものかと思っていました。
デフォルトでは、/var/log/syslogに出力され、独自にcron.logに
出力させたい時は、/etc/rsyslog.confで設定変更するということですね。
syslog参照することで、何が呼び出されているか確認することが出来ました。
推測とおり、/etc/cron.hourlyでした。
以上です。
宜しくお願いします。
> アットマークテクノの古賀です。
>
> 安達さん：
> >別件で、もう一つ教えていただけませんか。
> >増えているプロセスをみると、cron -F となっている様です。
> >時間毎に呼ぶのは、cron.hourlyに設定したntpdateだけなのですが、
> >cronのログは何処かに出力されないでしょうか。
> >/var/log下には見つけられませんでした。
>
> 確認ですが、「/var/log下には」とおっしゃっているのは、/var/log/cron.log のことでしょうか？
> あるいは、/var/log/ にある全てのファイルを指していらっしゃるでしょうか。
>
> もし前者（/var/log/cron.log）であれば、/var/log/syslog をご覧になってみて下さい。
> /var/log/syslog に cron のログが出力されているのであれば、/etc/syslog.conf の cron に対する設定行のコメントアウトを解除することで、/var/log/cron.log へ出力されるようになるでしょう：
> https://raspi.ryo.sc/cron_log/
> https://wiki.debian.org/Rsyslog
>
at_shinya.koga
アットマークテクノの古賀です。
安達さん：
>ご回答ありがとうございます。
>
>はい、/var/log/下にcron.logが作成されるものかと思っていました。
>デフォルトでは、/var/log/syslogに出力され、独自にcron.logに
>出力させたい時は、/etc/rsyslog.confで設定変更するということですね。
>
>syslog参照することで、何が呼び出されているか確認することが出来ました。
>推測とおり、/etc/cron.hourlyでした。
…
>>>別件で、もう一つ教えていただけませんか。
>>>増えているプロセスをみると、cron -F となっている様です。
>>>時間毎に呼ぶのは、cron.hourlyに設定したntpdateだけなのですが、
>>>cronのログは何処かに出力されないでしょうか。
>>>/var/log下には見つけられませんでした。
>>
>>確認ですが、「/var/log下には」とおっしゃっているのは、/var/log/cron.log のことでしょうか？
>>あるいは、/var/log/ にある全てのファイルを指していらっしゃるでしょうか。
cron.hourly で実行する ntpdate ですが、-s オプションを指定していらっしゃるという認識で合っているでしょうか？
もしそうであれば、ntpdate が /var/log/ 配下にログ出力しようとしたところで停止してしまい、そのため、cron ジョブが完了せずに、cron -F のプロセスが一時間ごとに増えていく、ということなのかも知れませんね。
安達さん（2021年8月24日 15時07分）：
>現象：
> SD-CardReaderの中の1個を接続しない状態で運用を続けていると、以下の
> メッセージが接続中のTTYに表示され、また多くのコマンド(ftp/新規の
> telet接続、cat、reboot、poweroff等)が実行出来なくなります。
> lighttpd経由でのWeb操作も出来なくなっています。
> 外部との通信が出来なくなるため、実質的にハングアップ状態です。
>
> --------------- ここから ---------------
> Message from syslogd@armadillo at Aug 5 21:20:17 ...
> kernel:Internal error: Oops: 5 [#1] PREEMPT SMP ARM
>
> Message from syslogd@armadillo at Aug 5 21:20:17 ...
> kernel:Process mmcqd/2 (pid: 117, stack limit = 0xa89ac218)
>
> Message from syslogd@armadillo at Aug 5 21:20:17 ...
> kernel:Stack: (0xa89add90 to 0xa89ae000)
>
> Message from syslogd@armadillo at Aug 5 21:20:17 ...
> kernel:dda0: a6cf5740 00000000 00000000 00001000 abaa1d4c a9f5db40 a9ea8c18 801ca82c
> ～～～ 中略 ～～～
> Message from syslogd@armadillo at Aug 5 21:20:17 ...
> kernel:dfe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000
>
> Message from syslogd@armadillo at Aug 5 21:20:17 ...
> kernel:Code: e10f0000 f10c0080 e5943020 ee1d1f90 (e593318c)
>--------------- ここまで ---------------
ここで、mmqcqd は、MMC カードドライバが生成するカーネルスレッドであり、キューに投入された MMC アクセスのリクエストを順に処理する mmc_queue_thread() を実行します：
https://github.com/atmark-techno/linux-4.9-at/blob/e58af3a93f3c60c6842f…
上記ログが出た時点で、/ をマウントしているパーティションに対する mmcqpd の動作が停止してしまい、その結果、同パーティションに対する MMC アクセスのリクエストが処理されなくなり、/ 配下へのファイルアクセスの実行が永久待ちになってしまう、という状況なのかも知れません。
>依頼事項：
> お手数おかけしますが、以下についてご教授いただけないでしょうか。
> ・原因として何が考えられるか
> ・解決策／回避策として、何をすればよいか。
mmqcqd がエラー停止する原因は、分かりません。解決策／回避策ですが、
> SD-CardReaderを接続し、代わりにSDカードを挿入しない状態で運用すると、
> 上記の現象にはならない様です。
という運用が可能なのであれば、それが回避策の一つだと思います。
また、エラーログを見ると、
> Message from syslogd@armadillo at Aug 5 21:20:17 ...
> kernel:Internal error: Oops: 5 [#1] PREEMPT SMP ARM
となっており、Oops の次の数字が 5 になっていますので、カーネルモードでの書込み要求の実行時にエラーになっているようです。従って、/ 配下へのファイル書込みが起点になっていると思われます。とすると、もし /var/log/ 配下に記録されるログを永続化する必要がないのであれば、/var/log/ を tmpfs に移す設定を行うことで回避できるかも知れません。
/var/log/ を揮発化する設定手順については、以下のページが参考になるかと思います：
https://elinux.org/images/6/61/Debian%E3%81%AB%E3%81%8A%E3%81%91%E3%82%…
https://qiita.com/s8ta/items/9e08242e30ec7929fa89
以上、もし参考になりましたら幸いです。
at_akihito.irie
2021年8月25日 16時51分
入江です。
申し訳ございませんが、頂いた情報のみでは原因を特定できません。
mmcqdのnice値(優先度)を下げた状態ではログは出力されますでしょうか。
reniceコマンドなどで実行中のプロセスのnice値を変更できます。以上、お手数おかけしますがよろしくお願いいたします。