Armadilloフォーラム

python time.sleepの設定値とデットロックの関係

k-marine

2021年5月11日 11時55分

お世話になります。
上村と申します。

python time.sleepに設定するsleep時間の最短時間はありますでしょうか。
現在、この時間を短く(1msec以下)で設定することで、

futex(0x7dac48, FUTEX_WAIT_PRIVATE, 2, NULL)

で停止した状態になります。(straceを使用して確認)

おそらく、デットロックが発生しているかと思いますが、なにか原因は
考えられますでしょうか。ご教示ください。

<環境>
Python3.5
・起動アプリケーション 10種類同時に起動している(すべてpyrthon)
・主に、UDP通信を処理
・各プロセスには、sleepを使用している
・各プロセスは、5~15程度のスレッドを持っている
・発生頻度 不定(数時間~数十時間に1回程度)
・発生時は、topで確認すると、該当プロセスは、状態が S(SLEEP)となっている
・発生プロセスへのKILLシグナル以外、受け付けない。
・TOPのCPU負荷率 60%程度 IDLE 40%程度

コメント

アットマークテクノの古賀です。

上村さん:
>python time.sleepに設定するsleep時間の最短時間はありますでしょうか。
>現在、この時間を短く(1msec以下)で設定することで、
>
>futex(0x7dac48, FUTEX_WAIT_PRIVATE, 2, NULL)
>
>で停止した状態になります。(straceを使用して確認)
>
>おそらく、デットロックが発生しているかと思いますが、なにか原因は
>考えられますでしょうか。ご教示ください。

お使いの python アプリケーションの実装において、デッドロック要因のある可能性もありますが、time.sleep() で 1[ms] 以下のスリープを指定していらっしゃり、さらに以下の構造ということですから、python の実行系が要因となっている *かも* 知れません。

><環境>
>Python3.5
>・起動アプリケーション 10種類同時に起動している(すべてpyrthon)
>・主に、UDP通信を処理
>・各プロセスには、sleepを使用している
>・各プロセスは、5~15程度のスレッドを持っている
>・発生頻度 不定(数時間~数十時間に1回程度)
>・発生時は、topで確認すると、該当プロセスは、状態が S(SLEEP)となっている
>・発生プロセスへのKILLシグナル以外、受け付けない。
>・TOPのCPU負荷率 60%程度 IDLE 40%程度

以下、直接の回答ではなく恐縮ですが、上記を拝見してのコメントです。

「各プロセスは、5~15程度のスレッドを持っている」、「起動アプリケーション 10種類」で、time.sleep() により 1[ms] 以下のスリープ時間を指定ということですから、実行対象のスレッドが切り替わる際のコンテキストスイッチのオーバーヘッドは、それなりに大きいかと思います。
各スレッドの処理内容は「主に、UDP通信を処理」ということで、I/O 動作が主なようですから、スレッドではなく、asyncio を使う設計に変更する、というのも選択肢として有効ではないかと思います。

asyncio による、async/await を使った非同期処理での UDP 通信については、次のページやソースが参考になるかと思います:

 python3 asyncioの効果を実感したい!
 https://qiita.com/some-nyan/items/3a229e628f126eb3d9ce

 High-level UDP endpoints for asyncio(※MIT ライセンス)
 https://gist.github.com/vxgmichel/e47bff34b68adb3cf6bd4845c4bed448

 Pythonの非同期通信(asyncioモジュール)入門を書きました
 https://iuk.hateblo.jp/entry/2017/01/27/173449

以上、もし参考になりましたら幸いです。

古賀様
 
上村です。

ご返答ありがとうございました。

asyncioなど、こちらで色々と調査したのですが、改善いたしませんでした。

パッケージの確認をするためsoftware-properties-commonをインストール後、
apt-upgradeをおこなったところ、何かしらのライブラリが更新されたようで
発生しなくなりました。

straceでの、fmutexの表示内容も変更されていました。(添付)

結果としては、なにかのバグだったようです。
なにに起因するかまでは、調査手段がわからないのですが、なにかご存知であれば
ご教示いただけると幸いです。

改善前のdpkgのデータとfutexの抜粋を添付いたします。

ご教示いただければ幸いです。

以上、ご連絡いたします。

ファイル ファイルの説明
比較.zip 改善前後のdpkgとfutexの違い

古賀様

上村です。

パッケージの違いを調べていると、
atmark-x1-base が 2.3.2-1 → 2.4.3-1
に変わっておりました。

申し訳ありませんが、この間に改善された内容一覧ありますでしょうか。
ご教示願います。

古賀様

 上村です。

立て続けに申し訳ありません。

atmark-x1-base が  2.4.3-1 → 2.3.2-1

にダウングレードする方法をご教示願います。

アットマークテクノの古賀です。
返事が遅くなってしまい、申し訳ありません。

上村さん(2021年6月3日 20時14分):
>立て続けに申し訳ありません。
>
>atmark-x1-base が  2.4.3-1 → 2.3.2-1
>
>にダウングレードする方法をご教示願います。

ダウングレードですが、
https://download.atmark-techno.com/debian/dists/stretch/main/binary-arm…
に置いているメタデータが過去バージョンに対応していないため、apt-get でのダウングレードが出来ません。
ダウングレードされる場合は、以下から、2.3.2-1 の .deb を直接ダウンロードして、お使い下さいませ。
https://download.atmark-techno.com/debian/pool/main/a/atmark-x1-base/

アットマークテクノの古賀です。

上村さん(2021年6月3日 18時54分):
>パッケージの違いを調べていると、
>atmark-x1-base が 2.3.2-1 → 2.4.3-1
>に変わっておりました。
>
>申し訳ありませんが、この間に改善された内容一覧ありますでしょうか。
>ご教示願います。

atmark-x1-base の 2.3.2-1 から 2.4.3-1 の間の変更は、次の通りです:
https://armadillo.atmark-techno.com/news/20190731/software-update-ax1
https://armadillo.atmark-techno.com/news/20200331/software-update-ax1
https://armadillo.atmark-techno.com/news/20200417/software-update-ax1
https://armadillo.atmark-techno.com/news/20200331/software-update-ax1
https://armadillo.atmark-techno.com/news/20200427/software-update-ax1
https://armadillo.atmark-techno.com/news/20210428/software-update-aiotg3

いずれも、3G/LTE モジュールに関するユーザランドの変更であり、futex 周りの動作に影響を与えるものではないと思われます。

その他の製品アップデート内容については、上のものを含め、こちらにある一覧から、ご覧ください。

アットマークテクノの古賀です。
書き漏らしがありました。ごめんなさい。

>その他の製品アップデート内容については、上のものを含め、こちらにある一覧から、ご覧ください。

「こちらにある一覧」というのは、次のページのことでした:
https://armadillo.atmark-techno.com/news/software-updates

アットマークテクノの古賀です。

上村さん(2021年6月2日 16時31分):
>ご返答ありがとうございました。
>
>asyncioなど、こちらで色々と調査したのですが、改善いたしませんでした。
>
>パッケージの確認をするためsoftware-properties-commonをインストール後、
>apt-upgradeをおこなったところ、何かしらのライブラリが更新されたようで
>発生しなくなりました。
>
>straceでの、fmutexの表示内容も変更されていました。(添付)

futexの違い.txt を見ましたが、

---------
改善前
futex(0x80f1cc, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 206263, {tv_sec=1621228408, tv_nsec=162846000}, 0xffffffff) = -1 EAGAIN (Resource temporarily unavailable)

futex(0x80f1f8, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)

改善後
futex(0x764c38, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1618266578, tv_nsec=314511000}, FUTEX_BITSET_MATCH_ANY
futex(0x764c40, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
---------

となっていて、改善後に 'FUTEX_BITSET_MATCH_ANY' と表示されているところが、改善前は 0xffffffff なのが、不思議といえば不思議ですね。
FUTEX_BITSET_MATCH_ANY の定義値は 0xffffffff ですが、なぜか、改善前は数値表示されています。

>結果としては、なにかのバグだったようです。
>なにに起因するかまでは、調査手段がわからないのですが、なにかご存知であれば
>ご教示いただけると幸いです。
>
>改善前のdpkgのデータとfutexの抜粋を添付いたします。
>
>ご教示いただければ幸いです。

添付して頂いたアーカイブに入っていた、改善後dpkg.txt と 改善前dpkg.txt を比較してみましたが、全く同じ内容でした。そのため、改善前と後でのパッケージ一覧の違いが分かりませんでした。

古賀様

上村です。

ご回答ありがとうございました。

再度調査した結果、以下のライブラリに問題があったようです。

libc6 2.24-11(strech) →2.28-10(buster)

こちらのパッケージをアップデートすることで、事象は発生しなくなりました。

以上、ありがとうございました。