[fetch1075] fetchでjsk-fetch-startupのjobが立ち上がらない

[708yamaguchi]

エラーメッセージで検索すると、thread数が上限に達している、みたいなことを言われる。

全部のログ
https://gist.github.com/708yamaguchi/ff32e5921570e7e004836a758665acde

[sktometometo]

@tkmtnt7000 のChatでのコメントから

・insta360用のlibuvccameraがthreadを食いまくっていてrosのsocket通信ができていなかった(rosの起動に失敗しているように見えた)
でした．libuvcにバグがありそう，というところです．再起動以外の対処法がわかっていない状況なので一旦様子を見つつ必要であればlibuvcをデバッグすることになると思います．

とあるので、一つの仮説としてthread数が多すぎるせいで新規スレッドが立ち上げられないという可能性が挙げられています。

[sktometometo]

ただ、fetch1075 で htopすると, thread数はたかだか4000~5000程度で、 ulimit やらで出てくるプロセス数上限には達していないように見えるため、他の要因も疑っています。

参考: https://www.yunabe.jp/docs/maximum_number_of_threads.html

[sktometometo]

気になる点

• 発生条件
  • 起動直後にも起こるのか、しばらく時間経過してから起こるのか、supervisor job の上げ下げをしていると起こるようになるのか。
  • supervisor 経由のみか、roslaunchで直に立ち上げても起こるのか。
• エラーが出ているとして、何のリソース制約でエラーが出ているのか。
  • スレッド数
  • メモリ
  • 開くファイル数
  • etc

[708yamaguchi]

この問題は、jsk-fetch-startupをsupervisorから起動する時に発生しています。

sudo supervisorctl stop jsk-fetch-startup
sudo supervisorctl start jsk-fetch-startup

この状態になっても、手動でfetch_bringup.launchを立ち上げるとこのエラーは発生しません。

sudo supervisorctl stop jsk-fetch-startup
roslaunch jsk_fetch_startup fetch_bringup.launch

[sktometometo]

問題が置きているときのhtop (superviso

スレッド数が4000くらい

リブート直後のhtop

スレッド数が2000くらい

ゾンビプロセスがいる?

[sktometometo]

@708yamaguchi @mqcmd196 @tkmtnt7000 @iory
問題の再現方法を見つけた方はご報告ください。

[sktometometo]

ひょっとして関係或るかも?
Supervisor/supervisor#1025

[sktometometo]

ただ、ソケット通信を張れる数の制約に引っかかったとしても、エラーが出るタイミングはTCPソケット通信を開始するタイミングであって、スレッドを作るタイミングでは無さそう....

[sktometometo]

OpenBLASエラーみたいなの見ていると、起動時にはスレッド数の制限には引っかかっていそう。

OpenBLAS blas_thread_init: RLIMIT_NPROC 126864 current, 126864 max

[708yamaguchi]

この件ですが犯人は僕で、最近m5stack用に使っていたrosrun rosserial_python serial_node.pyが大量のスレッドを生成していました。
大変申し訳ありません。

問題を簡単にまとめると、以下のとおりです。
・serial_node.pyはUnexpected Errorをcatchすると、SerialClientクラスのオブジェクトを再作成して通信をやり直す。
・再作成の際に、元々のSerialClientオブジェクトで利用されていたthreadを解放していない。
・結果、Unexpected Errorが繰り返されると、serial_node.pyが作成したthreadが無限に増えていく。
https://github.com/ros-drivers/rosserial/blob/c169ae2173dcfda7cee567d64beae45198459400/rosserial_python/nodes/serial_node.py#L92-L109

この問題を修正したプルリクエストをrosserialに送りました。
cherry-pickして、fetch体内で使われている708yamaguchi/rosserialのfetch15ブランチも更新しました。
ros-drivers/rosserial#595
ros-drivers/rosserial#596

参考までに、エラーが発生していたときの状況を書きます。
以下の27156のプロセスがserial_node.pyなのですが、スレッド数を調べるたびに増えています。

fetch@fetch1075:~$ ps huH p 27156 | wc -l
439
fetch@fetch1075:~$ ps huH p 27156 | wc -l
445
fetch@fetch1075:~$ ps huH p 27156 | wc -l
495

コマンド参考：
https://stackoverflow.com/questions/268680/how-can-i-monitor-the-thread-count-of-a-process-on-linux

ちなみにpythonプログラムの中から使用しているスレッド数を調べるには、以下のコマンドが有用です。

import threading
threading.active_count()

また各スレッドの中身は以下のような感じで、同じ名前のスレッドが大量にありました。

fetch@fetch1075:~$ ps huH p 27156
fetch    27156  3.1  0.2 10853160 89992 ?      Ssl   7月18   2:12 python /home/fetch/ros/melodic/src/ros-drivers/rosserial/rosserial_python/nodes/serial_node.py __name:=serial_node __log:=/home/fetch/.ro
fetch    27156  0.0  0.2 10853160 89992 ?      Ssl   7月18   0:00 python /home/fetch/ros/melodic/src/ros-drivers/rosserial/rosserial_python/nodes/serial_node.py __name:=serial_node __log:=/home/fetch/.ro
fetch    27156  0.0  0.2 10853160 89992 ?      Ssl   7月18   0:03 python /home/fetch/ros/melodic/src/ros-drivers/rosserial/rosserial_python/nodes/serial_node.py __name:=serial_node __log:=/home/fetch/.ro
fetch    27156  0.0  0.2 10853160 89992 ?      Ssl   7月18   0:00 python /home/fetch/ros/melodic/src/ros-drivers/rosserial/rosserial_python/nodes/serial_node.py __name:=serial_node __log:=/home/fetch/.ro
fetch    27156  0.0  0.2 10853160 89992 ?      Ssl   7月18   0:00 python /home/fetch/ros/melodic/src/ros-drivers/rosserial/rosserial_python/nodes/serial_node.py __name:=serial_node __log:=/home/fetch/.ro

このエラーに気づくのが遅れた原因として、serial_node.pyのlogger levelをerror以上にしていたことがあります。
https://github.com/jsk-ros-pkg/jsk_robot/blob/master/jsk_fetch_robot/jsk_fetch_startup/launch/fetch_rosserial.launch#L7

logger levelを変更した理由は、fetchとm5stackが離れたりm5stackが一時的に電源OFFになったりすると数秒に1回くらいのペースで以下のようなUnexpected Errorをwarningとして出力するのですが、これによりjsk-fetch-startup.logの視認性を下げたくなかったからです。

[WARN] [1658160863.741048] [/sgp30/serial_node:rosout]: Last read step: None
[WARN] [1658160863.743609] [/sgp30/serial_node:rosout]: Run loop error: [Errno 5] Input/output error
[WARN] [1658160863.746358] [/sgp30/serial_node:rosout]: Unexpected Error.<class 'termios.error'>
[WARN] [1658160869.877148] [/sgp30/serial_node:rosout]: Last read step: None
[WARN] [1658160869.878822] [/sgp30/serial_node:rosout]: Run loop error: [Errno 5] Input/output error
[WARN] [1658160869.880893] [/sgp30/serial_node:rosout]: Unexpected Error.<class 'termios.error'>

同じ過ちを繰り返さないように、当面はlogger levelをデフォルトのinfoに戻しておきます。
warningがうるさいかも知れないですが、rosserialを安定して使用できるようになるまで我慢してもらえると助かります。