hitx.ito
2022年7月25日 14時07分
以前よりX1を何台か設置・導入しておりますが、
先日新規に設置した１台において、アプリケーションが起動できていない事象が発生し、
調査したところoom killerが発生していることが確認できました。
過去のフォーラムトピックや記事等拝見してメモリリークの可能性があるというのは理解したのですが
起動後必ず発生するわけではなく（起きる日もあれば起きない日もある）、
発生時はsyslogやmessagesのOOM Killerの情報しか得られずどのプロセスが原因か調査の仕方など教えていただきたいです。
また同環境の別端末（同一OS、同一アプリケーションを実行）一度も発生したことがないことから
ハードウェア不良の疑いはないかと言われており、確認する方法があるかも教えていただければと思います。
製品: Armadillo-X1
OS: 9.13
Kernel: Linux armadillo 4.9.133-at15 #2 SMP PREEMPT Tue Jul 14 13:02:57 JST 2020 armv7l GNU/Linux
コメント
hitx.ito
アットマークテクノ
マルティネ様
回答ありがとうございます。
プロセス一覧に関してはログとっていなかったので、
対象のX1に調査用のシェルを仕込んでみました。再発時に確認するようにしてみます。
手動でのOOM killer実行も開いてる他の端末で試してみるようにします。
以下、OOM killer発生時のsyslogを添付します。
・7/21 11:00ごろ(syslog.4)
毎日0:00ごろにX1の再起動をcronから実行しており、
OOM killerが発生する時は再起動後からcronで起動しているアプリケーションのログがほとんど出ていない状況です。
(7/21 00:00以降のログが確認できるよう、２ファイル添付します。)
以下、7/21に再起動直前のmeminfoも取れていたので以下記載します。
Thu Jul 21 12:10:01 JST 2022
MemTotal: 1019032 kB
MemFree: 4552 kB
MemAvailable: 4768 kB
Buffers: 220 kB
Cached: 28244 kB
SwapCached: 0 kB
Active: 895776 kB
Inactive: 25596 kB
Active(anon): 893580 kB
Inactive(anon): 23276 kB
Active(file): 2196 kB
Inactive(file): 2320 kB
Unevictable: 12 kB
Mlocked: 12 kB
HighTotal: 0 kB
HighFree: 0 kB
LowTotal: 1019032 kB
LowFree: 4552 kB
SwapTotal: 0 kB
SwapFree: 0 kB
Dirty: 0 kB
Writeback: 0 kB
AnonPages: 893220 kB
Mapped: 4648 kB
Shmem: 23648 kB
Slab: 30100 kB
SReclaimable: 5856 kB
SUnreclaim: 24244 kB
KernelStack: 10056 kB
PageTables: 26432 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
WritebackTmp: 0 kB
CommitLimit: 509516 kB
Committed_AS: 1520436 kB
VmallocTotal: 1032192 kB
VmallocUsed: 0 kB
VmallocChunk: 0 kB
CmaTotal: 327680 kB
CmaFree: 1328 kB
よろしくお願いします。
| ファイル | ファイルの説明 |
|---|---|
| syslog_20220721.zip | 7/21発生時のsyslogファイルです。 |
at_dominique.m…
hitx.itoさん、
ログありがとうございます。
> プロセス一覧に関してはログとっていなかったので、
> 対象のX1に調査用のシェルを仕込んでみました。再発時に確認するようにしてみます。
すみません、説明が足りませんでしたがプロセス一覧はログにあります。
例えば、syslog.4 の 「Jul 21 11:10:29 armadillo kernel: [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name」で始まります。
どれかを参考にしたら、oom発生時には 644 の sh, 254 の python, 127 の cron と 75 の bluepy-helper プロセスが起動していたそうです。
それで正常状態でしょうか？実行時間が分かりませんが、cron がたまっているので、スクリプトが最後まで実行できずに固まってしていたらこうやってプロセスが増える一方で oom-killer につながります。
そうなっていたら、何か bluetooth 関係の問題がありそうですね。
とりあえずプロセスの数を制限するにはスクリプトの同時実行を禁止した方がいいかもしれません。（例えば、systemd のサービスで実行すれば cron で systemctl start を実行する時にすでに実行中の場合に何も起きません)
syslogでbluetoothのログに情報があまりなかったので、次に発生した際に bluetoothctl で何かが分かるかもしれません。この時間に遅かっただけか、完全に固まったかにもよりますが…
よろしくお願いします。
hitx.ito
回答ありがとうございます。
頂いた情報をもとに調査した結果、ネットワークが繋がっていない場合に特定のプロセスが起動せず
定期的にcronで起動するpython, shellが待ちになって今回の事象が発生することがわかりました。
(明らかにプロセス数が異常でした・・・)
ただ、今回のように再起動後にネットワークが繋がらない（それに関するプロセスが起動できていない）原因がわからない状況です。
また、エラーハンドリングについても検討し直す必要性は認識してますがそのアプローチ方法がわからず、調査の仕方や対応例など教えていただきたいです。
・起動後にネットワークに問題があるかどうか調べる方法
…再発時にsyslogなどに情報を出力できるなど・・・
・問題があった場合に再接続する方法
・接続されるまで待機する方法（もしくは接続ができているか確認する方法）
などでしょうか・・・
よろしくお願いします。
at_dominique.m…
hitx.itoさん、
> 頂いた情報をもとに調査した結果、ネットワークが繋がっていない場合に特定のプロセスが起動せず
なるほど、bluetoothではなくネットワークの方の問題でしたね。
> また、エラーハンドリングについても検討し直す必要性は認識してますがそのアプローチ方法がわからず、調査の仕方や対応例など教えていただきたいです。
> ・起動後にネットワークに問題があるかどうか調べる方法
> …再発時にsyslogなどに情報を出力できるなど・・・
> ・問題があった場合に再接続する方法
> ・接続されるまで待機する方法（もしくは接続ができているか確認する方法）
> などでしょうか・・・
そうですね… 具体的に何が失敗しているのが気になります。
残念ですが、送っていただいたsyslogにはoomが発生する前の起動ログがのこっていませんでした。
oom-killer は Jul 21 11-12時に発生しましたが、もっとも早い起動ログはそのすぐ後になって、いつからまたはどうしてネットワークがなくなっていたの情報がないです。
チェックとしては NetworkManager を使ってるので、ハイレベルでは「nmcli networking connectivity」で分かると思います。
また、スクリプトに単純なタイムアウト入れていたらそれでも判断できるかもしれません。
よろしくお願いします。
hitx.ito
syslog残ってましたが、見てもわからず、添付しましたのでご確認いただけると助かります。
※毎日0:00ごろに再起動しており、7/21も0:03ごろに再起動をしております。
> チェックとしては NetworkManager を使ってるので、ハイレベルでは「nmcli networking connectivity」で分かると思います。
> また、スクリプトに単純なタイムアウト入れていたらそれでも判断できるかもしれません。
情報ありがとうございます。
こちらで確認・検討してみます。
| ファイル | ファイルの説明 |
|---|---|
| syslog.5.zip | 7/21起動後のログです。7/21 00:00過ぎに再起動をしています。 |
at_dominique.m…
> syslog残ってましたが、見てもわからず、添付しましたのでご確認いただけると助かります。
> ※毎日0:00ごろに再起動しており、7/21も0:03ごろに再起動をしております。
ありがとうございます。
このログでは NetworkManager が無事に dhcp で eth2 の IP をもらえたようで、oom-killerが発生するまでに特に問題は見当たらないですね…
cron のメッセージには ping www.google.com で定期的にチェックしていますが、 /var/log/applog.log に何かエラーがあるかもしれません。
ケーブルが途中で認識できなくなってる形跡もないですし、eth2 は USB のデバイスでそちらに不具合が出たらログに USB のエラーが残ると思います。ハードウェアではなくネットワーク的なトラブルの可能性もあります。
次に再現できたらネットワークの状態を具体的に把握していただければと思います。
その問題がいつも同じ Armadillo で発生していたら、別の Armadillo と交換できたらハードウェアの問題かどうかも分かります。
よろしくお願いします。
hitx.ito
確認ありがとうございます。
システム的には問題なさそうとのことで理解しました。
ネットワークの疎通確認でたしかにpingを飛ばしているようです。
ただapplog側にも有用なログが残っていないため、アプリケーションログを増やすことを検討しつつ端末交換もしくは再発待ちになるかと思います
(21日以降再発してないので不気味ですが…)
> 次に再現できたらネットワークの状態を具体的に把握していただければと思います。
ネットワーク端末の状況等確認は可能な限り行おうかと思いますが、
X1側からネットワークの状況について確認できそうな方法はありますでしょうか。
(先日回答いただいた「nmcli networking connectivity」など…？)
よろしくお願いいたします。
at_dominique.m…
2022年7月25日 15時32分
hitx.itoさん
アットマークテクノのマルティネです。
お世話になっています。
> 過去のフォーラムトピックや記事等拝見してメモリリークの可能性があるというのは理解したのですが
> 起動後必ず発生するわけではなく（起きる日もあれば起きない日もある）、
> 発生時はsyslogやmessagesのOOM Killerの情報しか得られずどのプロセスが原因か調査の仕方など教えていただきたいです。
そのログを共有していただけないでしょうか？何か手がかりにつながる物があるかもしれません。
具体的には細かい情報がいくつかありますが、プロセス一覧を見てこの問題が発生しない Armadillo と「ps aux」で比べれますし、
そのいい状態の Armadillo にログインして「echo f > /proc/sysrq-trigger」で強制的に OOM Killer を起動させれば他の値も比べれます。
（sysrq-trigger に書いてログを回収した後に再起動させてあげてください）
> また同環境の別端末（同一OS、同一アプリケーションを実行）一度も発生したことがないことから
> ハードウェア不良の疑いはないかと言われており、確認する方法があるかも教えていただければと思います。
そうですね、ドライバに何かリークしていたらハードウェア的な問題も考えれますが、まずは何がメモリを使ってるかを把握しましょう。
OOM Killerのログのプロセス表に特にメモリを使ってるプロセスがなければ、問題ある直後の /proc/meminfo の内容も比べておきたいのでその中身も添付していただければ幸いです。
これを見て次に見るべきところが分かるかもしれません。
よろしくお願いします。