kowata
2021年8月31日 17時05分
お世話になります。渡辺と申します。
8年ほど前からArmadillo-420を使ったデータロガーを作成しています。
以前は安定稼動していた自社アプリケーションが最近度々落ちる様になって頭を悩ませています。
自社アプリケーションはマルチスレッドのプログラムなのですが
落ちる直前の動きを見ているとコンソールに
imx-uart imx-uart.2 Rx FIFO overrun
が連続で出ています。
受信したデータはタイマー割り込み処理で読み取る動作をさせています。
タイマー割り込み処理をmutex lockをかけている様子は無いのですが、デバック用の表示にmutex lockでタイマー割り込み処理がキャンセルされている様な表示をしています。タイマー割り込み処理が実行されないためuart.2 Rx FIFO overrunにつながっていると推定しています。
通常アプリケーションが落ちた時、自動再起動させているため中々原因がつかめません。
その中でたまたま起動直後のログに下記メッセージを見つけました。
------------[ cut here ]------------
WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:264 dev_watchdog+0x1a8/0x2dc()
NETDEV WATCHDOG: eth0 (fec): transmit queue 0 timed out
Modules linked in:
CPU: 0 PID: 0 Comm: swapper Not tainted 3.14.36-at13 #1
Backtrace:
[] (dump_backtrace) from [] (show_stack+0x18/0x1c)
r6:c05b543b r5:00000009 r4:c0619e08 r3:00200000
[] (show_stack) from [] (dump_stack+0x20/0x28)
[] (dump_stack) from [] (warn_slowpath_common+0x6c/0x8c)
[] (warn_slowpath_common) from [] (warn_slowpath_fmt+0x38/0x40)
r8:00000001 r7:00000001 r6:00000000 r5:c0650e4b r4:c61e8800
[] (warn_slowpath_fmt) from [] (dev_watchdog+0x1a8/0x2dc)
r3:c61e8800 r2:c05b5453
[] (dev_watchdog) from [] (call_timer_fn.isra.35+0x2c/0x98)
r7:c0618000 r6:c03bed3c r5:c0618000 r4:00000101
[] (call_timer_fn.isra.35) from [] (run_timer_softirq+0x1f4/0x29c)
r7:c03bed3c r6:c61e8800 r5:c0618000 r4:c0651bc0
[] (run_timer_softirq) from [] (__do_softirq+0xbc/0x200)
r7:00000101 r6:c0651a80 r5:c0618000 r4:00000202
[] (__do_softirq) from [] (irq_exit+0x88/0xf0)
r10:c7ffca20 r9:41069264 r8:c0620000 r7:c0619f6c r6:c0619f38 r5:00000000
r4:00000046
[] (irq_exit) from [] (handle_IRQ+0x6c/0x8c)
r4:00000046 r3:000000d0
[] (handle_IRQ) from [] (avic_handle_irq+0x3c/0x48)
r5:0000ffff r4:c0651334
[] (avic_handle_irq) from [] (__irq_svc+0x40/0x6c)
Exception stack(0xc0619f38 to 0xc0619f80)
9f20: 00000000 0005317f
9f40: 0005217f 60000013 c0618000 c0650d52 c0620080 c0612228 c0620000 41069264
9f60: c7ffca20 c0619f8c 600000d3 c0619f80 c0009f7c c0009f88 60000013 ffffffff
r6:ffffffff r5:60000013 r4:c0009f88 r3:c0009f7c
[] (arch_cpu_idle) from [] (cpu_startup_entry+0x80/0xe8)
[] (cpu_startup_entry) from [] (rest_init+0x78/0x90)
[] (rest_init) from [] (start_kernel+0x33c/0x3a8)
r4:c0620130 r3:00000000
[] (start_kernel) from [<80008040>] (0x80008040)
---[ end trace 0ca2cacd7e4d33c4 ]---
自社アプリケーションを開発したのはカーネルが2.26のArmadillo-420時代ですがこのようなメッセージは見たことがありません。
現在は（カーネル3.14になってから）Atde5で再コンパイルして使用しています。
このメッセージはどの様は時に発生するものなのでしょうか？
直接アプリケーションが落ちる原因になりうるのでしょうか？
又、2.26から3.14になった事によりmutex lockの動作に変化はあるのでしょうか？
ご教示くださいますようお願い申し上げます。
コメント
kowata
2021年9月1日 18時29分
渡辺です。
早速のコメント有難う御座います。
実装はアプリケーション起動時に設定ファイルを読んでその中にあるネットワーク情報を元にinterfacisファイルを書き換えsysrem関数でeth0のdown upを行います。
その後、タイマー割込設定、シリアル通信スレッド、ネットワーク通信スレッドを生成します。
シリアル通信とネットワーク通信は非同期なので時計会わせ等システムに対するリクエスト発行時にはmutex lockで競合を回避しています。
全体的な動作としては、1秒毎にシリアル通信で受けたデータ(30バイト程度)を一時記憶して、ネットワークからのudpソケットで受けた要求に対してデータ編集してudp出力するものです。
質問したwatchdocログはスレッド等が動作開始後2秒後ぐらいしてから出力されます。動作開始後ログが出力されるまでの間にパケットを受けているかは不明です。
異常の挙動としては、起動後数時間～数日は特に問題なく動作していて、突然タイマー割込開始時にmuyexロックに失敗して各種処理を行わずにリターンしてしまう現象に陥ります。タイマー割込処理内でシリアルバッファからの読み取りを行っている為、タイマー処理が行われない為にある程度時間が経つとrxバッファオーバーランが発生するのだと考えています。
タイマー割込処理のmutexロック処理はタイマー割込処理先頭で行って、割込処理終了時にアンロックしています。
> 入江です。
>
> > このメッセージはどの様は時に発生するものなのでしょうか？
>
> ネットワークの送出パケットが一定時間(デフォルトでは5秒)以内に送出できない場合に発生します。
>
> > 直接アプリケーションが落ちる原因になりうるのでしょうか？
>
> アプリケーションの仕様次第だと思います。
>
> > 又、2.26から3.14になった事によりmutex lockの動作に変化はあるのでしょうか？
>
> 恐らくmutexを取る以外のことはしないと思います。
> 実際にどのように実装して、どのような挙動を示すか教えていただけますか?
>
> 以上、よろしくお願いいたします。
>
at_akihito.irie
2021年9月1日 13時58分
入江です。
> このメッセージはどの様は時に発生するものなのでしょうか？
ネットワークの送出パケットが一定時間(デフォルトでは5秒)以内に送出できない場合に発生します。
> 直接アプリケーションが落ちる原因になりうるのでしょうか？
アプリケーションの仕様次第だと思います。
> 又、2.26から3.14になった事によりmutex lockの動作に変化はあるのでしょうか？
恐らくmutexを取る以外のことはしないと思います。
実際にどのように実装して、どのような挙動を示すか教えていただけますか?
以上、よろしくお願いいたします。