Armadilloフォーラム

800EVAで6分間停止

koma

2017年8月27日 13時19分

800EVAを使用しています。
ETHERNETのドライバ(ETHERCAT)を作成し、
1ms周期で通信しているのですが、
1日に数回 作成したソフトが約6分間(358秒)停止します。
この間TERATERMのモニタもできません。
約6分停止後、再度通常の動作、モニタが可能になります。
必ず約6分(357~358秒)なのですが、
6分停止する理由想定できるものありますでしょうか?

これ以外のソフトは実行しておらず、処理時間も
100μSEC以下/1msecです。

コメント

saitoh

2017年8月29日 12時50分

齊藤と申します。
誰も応答しないので、雑な推論を申し上げます。

> ETHERNETのドライバ(ETHERCAT)を作成し、
> 1ms周期で通信しているのですが、

この「1msごと」のソフトウェアロジックが間違っていて
カーネルモードでの6分間のロック(とかループ)が
発生している、というのが一つ疑われます。

358秒はだいたい 100×512×7 ミリ秒ですね。

外部からの割り込み信号で強制的にパニックを起こさせるなどで
スタックトレースが取れればどこの命令コードを実行して止まってるか
わかるのですが。800EVAってその辺の機能は無かったでしたっけ?

koma

2017年10月3日 18時49分

> 齊藤と申します。
> 誰も応答しないので、雑な推論を申し上げます。
>
> > ETHERNETのドライバ(ETHERCAT)を作成し、
> > 1ms周期で通信しているのですが、
>
> この「1msごと」のソフトウェアロジックが間違っていて
> カーネルモードでの6分間のロック(とかループ)が
> 発生している、というのが一つ疑われます。
>
> 358秒はだいたい 100×512×7 ミリ秒ですね。
>
> 外部からの割り込み信号で強制的にパニックを起こさせるなどで
> スタックトレースが取れればどこの命令コードを実行して止まってるか
> わかるのですが。800EVAってその辺の機能は無かったでしたっけ?
>
・停止している箇所は、
添付 ICE停止時画面.PNGのproc-v7.sの割込待ち(ENTRY cpu_v7_do_idle)です。
wfi命令で待ち、約6分後に抜けてきます。
この間、teraterm操作ができないのですが、
teratermでentを押すと、wfi部分は受け付けます。
但し、6分立つまでは、wfiで待ちになります。
通常は数msec程度でwfiを抜けてきます
また、logを見る場合、添付20171003_var_log.txtの
どのファイルをみれば良いでしょうか?

ファイル ファイルの説明
20171003_var_log.txt

koma

2017年10月3日 18時58分

komaです。
添付 ICE停止画面つけ忘れましたので送付します。

> > 齊藤と申します。
> > 誰も応答しないので、雑な推論を申し上げます。
> >
> > > ETHERNETのドライバ(ETHERCAT)を作成し、
> > > 1ms周期で通信しているのですが、
> >
> > この「1msごと」のソフトウェアロジックが間違っていて
> > カーネルモードでの6分間のロック(とかループ)が
> > 発生している、というのが一つ疑われます。
> >
> > 358秒はだいたい 100×512×7 ミリ秒ですね。
> >
> > 外部からの割り込み信号で強制的にパニックを起こさせるなどで
> > スタックトレースが取れればどこの命令コードを実行して止まってるか
> > わかるのですが。800EVAってその辺の機能は無かったでしたっけ?
> >
> ・停止している箇所は、
> 添付 ICE停止時画面.PNGのproc-v7.sの割込待ち(ENTRY cpu_v7_do_idle)です。
> wfi命令で待ち、約6分後に抜けてきます。
> この間、teraterm操作ができないのですが、
> teratermでentを押すと、wfi部分は受け付けます。
> 但し、6分立つまでは、wfiで待ちになります。
> 通常は数msec程度でwfiを抜けてきます
> また、logを見る場合、添付20171003_var_log.txtの
> どのファイルをみれば良いでしょうか?
>
>
>
>
>
>

ファイル ファイルの説明
ICE_停止時画面.png

koma

2017年10月8日 20時44分

komaです。
6分停止する直前のlogをデバッカでとってみました。
6分停止する理由とそのトリガをしりたいのですが。

> komaです。
> 添付 ICE停止画面つけ忘れましたので送付します。
>
> > > 齊藤と申します。
> > > 誰も応答しないので、雑な推論を申し上げます。
> > >
> > > > ETHERNETのドライバ(ETHERCAT)を作成し、
> > > > 1ms周期で通信しているのですが、
> > >
> > > この「1msごと」のソフトウェアロジックが間違っていて
> > > カーネルモードでの6分間のロック(とかループ)が
> > > 発生している、というのが一つ疑われます。
> > >
> > > 358秒はだいたい 100×512×7 ミリ秒ですね。
> > >
> > > 外部からの割り込み信号で強制的にパニックを起こさせるなどで
> > > スタックトレースが取れればどこの命令コードを実行して止まってるか
> > > わかるのですが。800EVAってその辺の機能は無かったでしたっけ?
> > >
> > ・停止している箇所は、
> > 添付 ICE停止時画面.PNGのproc-v7.sの割込待ち(ENTRY cpu_v7_do_idle)です。
> > wfi命令で待ち、約6分後に抜けてきます。
> > この間、teraterm操作ができないのですが、
> > teratermでentを押すと、wfi部分は受け付けます。
> > 但し、6分立つまでは、wfiで待ちになります。
> > 通常は数msec程度でwfiを抜けてきます
> > また、logを見る場合、添付20171003_var_log.txtの
> > どのファイルをみれば良いでしょうか?
> >
> >
> >
> >
> >
> >

ファイル ファイルの説明
20171006_4_trace1と停止箇所_.zip

saitoh

2017年10月17日 16時12分

応答が無くなった状態でログを取っても解決は難しいかと思います。
応答がなくなる直前に自作ドライバで何をしていたかのログが欲しいところです。
wake_up系とsleep_on系のカーネル内ルーチン、あとタイマー関係の呼び出し記録をとって眺めてみたら分かるかも・・。
コンピューテックスのICEでしたらリプレイデバッガ機能とかありませんでしたっけ?

koma

2017年10月18日 18時12分

回答ありがとうございます。
前回送付したXLSは停止直前のもののトレース結果の認識です。
PID1460(自作)->PID1467(自作)の切替が1000μSEC間隔で発生しています。
セルAの黄色部です。Aのセル2438行目を最後に、1000μsecの
PIDの切り替えが停止しています。
PID1459(自作)からPID2230(?)の切り替えがAセル番号2506以降、
自作ソフトには戻ってこない状態です。(定周期イベントが発生しなくなる)
その間でBIN/CATの実行やメモリアクセスが行われるのですが、
PID610 agent.netが頻繁に処理をしており、
試しにこのプロセスをKILLすると、この数日間は6分停止現象が発生していない
という状態です。
何か6分間という固定停止する地雷を踏んでいると想像しているのですが。

> 応答が無くなった状態でログを取っても解決は難しいかと思います。
> 応答がなくなる直前に自作ドライバで何をしていたかのログが欲しいところです。
> wake_up系とsleep_on系のカーネル内ルーチン、あとタイマー関係の呼び出し記録をとって眺めてみたら分かるかも・・。
> コンピューテックスのICEでしたらリプレイデバッガ機能とかありませんでしたっけ?

at_mizo

2017年10月19日 9時51分

溝渕です。

自作されたドライバ内で、長期間割り込みのマスクをしていたり送受信をdisableするなど、Ethernetとしての動作を阻害する処理はありませんか?

hidetoshi-miyao

2017年10月19日 11時28分

宮尾と申します。
数年前に似たような現象に嵌ったので、その時の原因と対応を参考に記載します。

Linuxでのタイマ要求は、最終的には、arch/arm/mach-shmobile/sh_cmt.c内 213行目
sh_cmt_set_next(struct sh_cmt_priv *p, unsigned long delta)
で R-Mobile SoCのタイマユニットに設定されます。
引数 deltaが ディレイ値ですが、ディレイ値はカーネル内での遅延時間を補正して設定されます。
1msecという短いタイマを多用し、かつシステムがビジーになってくると、この遅延時間が大きくなり、deltaが 0に近い値になることがあります。
sh_cmt_set_nextの中では、タイマの現在値を CMCNTレジスタから読み、deltaを加えてから、比較レジスタである CMCORに設定しますが、deltaが0に近いと、バスの状態によっては、CMCORに値を設定した時点で CMCNTが CMCORより大きくなってしまうケースが発生します。この状態になると、CMCNTがラップアラウンドして再び CMCORと一致するまで(約6分間)タイムアウトが発生しなくなります。

このときの対処としては、sh_cmt_set_nextを修正し、
・CMCORに設定後、CMCNTを再度読み、CMCOR > CMCNTで、かつタイマユニットにタイムアウトが発生していなければリトライする
・リトライしても同様の現象が発生するようであれば、ディレイ値を少し大きくして再度リトライする。以上を繰り返す
ようにしたところ、現象は発生しなくなりました。
修正後の sh_cmt_set_nextを参考添付します。

ファイル ファイルの説明
sh_cmt_set_next.c

hidetoshi-miyao

2017年10月19日 11時37分

> ・CMCORに設定後、CMCNTを再度読み、CMCOR > CMCNTで、かつタイマユニットにタイムアウトが発生していなければリトライする

失礼、CMCOR < CMCNTでした。

koma

2017年10月19日 13時21分

ありがとうございます。
発生している現象と一致しており、最後の砦としての対策になると思います。
対策を実施して改善を確認致します。本当に助かります。ありがとうございます。
また、不具合原因は「短い定周期があるのにも関わらず
システムをBUSY状態にしていることが、
6分停止を引き起こしている」と理解します。

> > ・CMCORに設定後、CMCNTを再度読み、CMCOR > CMCNTで、かつタイマユニットにタイムアウトが発生していなければリトライする
>
> 失礼、CMCOR < CMCNTでした。

koma

2017年10月31日 18時17分

ありがとうございました。
3台で1週間起動テストを行い、6分停止はなくなりました。
1点だけお教えねがいたいのですが、rc.localは特別な記述をしていないのですが
/bin/sh -e/lib/udev/net.agent というプロセスが存在します。
起動しない方法または起動を自動停止させる方法を教えて頂きたいのですが?

> ありがとうございます。
> 発生している現象と一致しており、最後の砦としての対策になると思います。
> 対策を実施して改善を確認致します。本当に助かります。ありがとうございます。
> また、不具合原因は「短い定周期があるのにも関わらず
> システムをBUSY状態にしていることが、
> 6分停止を引き起こしている」と理解します。
>
>
>
>
> > > ・CMCORに設定後、CMCNTを再度読み、CMCOR > CMCNTで、かつタイマユニットにタイムアウトが発生していなければリトライする
> >
> > 失礼、CMCOR < CMCNTでした。

hidetoshi-miyao

2017年11月7日 11時16分

詳しくはわかりませんが、net.agentは udevから起動されていると思いますので、udevの起動ルール(多分、/etc/udev/rules.d/*.rules)を変更すれば起動しないようにできると思います。起動しないことによる影響の見極めは必要と思いますが、

> ありがとうございました。
> 3台で1週間起動テストを行い、6分停止はなくなりました。
> 1点だけお教えねがいたいのですが、rc.localは特別な記述をしていないのですが
> /bin/sh -e/lib/udev/net.agent というプロセスが存在します。
> 起動しない方法または起動を自動停止させる方法を教えて頂きたいのですが?