ROSUDP(roscpp)での100KB以上のメッセージのPub/Subについて

[Junya Miyamoto]

ROS JAPAN Users Groupのみなさま

お世話になっております。
NTTソフトウェアの宮本と申します。


ROSUDP(roscpp)の動作について質問です。

■質問
ROSUDPで100KB以上のメッセージのPub/Subを行うと、
分割されてPub/Subされるメッセージで70個目以降のデータに関して、
ROSUDPのヘッダのブロック番号が異常な値になり、メッセージの受信が中断され
てしまう事象が発生しています。

本事象に対する対処法をご存知の方がいらっしゃいましたら、
ご教示願えないでしょうか。
(下に詳細を記載しております。)

■詳細
以下のチュートリアルを参考に、ROSUDP(roscpp)を用いて、異なるマシン間で
Pub/Subを行うプログラムを作成いたしました。
http://wiki.ros.org/ja/ROS/Tutorials/WritingPublisherSubscriber(c%2B%2B)

ROSUDPの通信を行うため、Sub側のSubscriverにTransportHints().unreliable()
オプションを追加しております。
ros::Subscriber sub = n.subscribe("chatter", 1000, chatterCallback,
ros::TransportHints().unreliable());

そこで、大容量のメッセージのPub/Subを行った際の動作を確認しました。
100KBまでは、問題なくメッセージのPub/Subを行うことが可能なのですが、
それより上のサイズとなると、メッセージが受信できない事象が発生しました。

本事象が発生した原因を特定するため、
デバッグログを出力した結果、Sub側で以下が出力されていました。

・デバッグログ
-------------------------
[DEBUG] [1469499668.731550467] Expected block 70, received 3599
[DEBUG] [1469499668.731670841] Expected block 70, received 3600
[DEBUG] [1469499668.731854232] Expected block 70, received 3601
[DEBUG] [1469499668.732016387] Expected block 70, received 3602
(上記のようなログが70回ほど出力される)
-------------------------

調べてみたところ、以下のソースに記載されている処理が実行されていました。
・transport_udp.cpp L495～
-------------------------
if (header.block_ != last_block_ + 1)
{
ROS_DEBUG("Expected block %d, received %d", last_block_ +
1, header.block_);
data_filled_ = 0; // discard datagram
return 0;
}
-------------------------

メッセージのサイズが一定以上の場合、
max_datagram_size_で指定されたbyte数毎にメッセージを分割して送信を行い、
ROSUDPのヘッダにブロック番号を付加していることは分かりました。
本来であれば、70が付加されているはずであるものが、
受信したメッセージのブロック番号が3599という異常な値になっているため、
エラーが発生し、データを破棄しているようでした。

そこで、受信側でヘッダの値を画面出力するよう、
該当ソースを改造・ビルドして実行した結果、
69番目まではブロック番号が正常に付加されており、
70番目になった途端に異常な値になることを確認いたしました。
異常な値としてはおおよそですが、
250、1200、3500など実行するたびに値が変わっていました。

100KBの場合ですと、ブロックの数が69個となっており、
上記のデバッグログが出力されることはありませんでした。

発生している事象は判明したのですが、原因が究明できていない状況です。
どなたか、対処法をご存知の方がいらっしゃいましたら、
ご教示をお願いいたします。

[Moirai]

なかなかおもしろい現象ですね．

これは毎回このような現象がおこっていますでしょうか？それとも，時々おこるものでしょうか？

添付のコードでこちらでも試した所，

```

[ INFO] [1471065142.826295674]: I heard: [ 9999:hello world (1552)]

[ INFO] [1471065142.924764475]: Sending 168896 length of data

[ INFO] [1471065143.024173158]: Sending 168896 length of data

[DEBUG] [1471065143.025238098]: Received new message [23:114], while

still working on [22] (block 93 of 114)

[DEBUG] [1471065143.025802505]: Expected block 93, received 98

[DEBUG] [1471065143.025951318]: Expected block 93, received 99

[DEBUG] [1471065143.026087739]: Expected block 93, received 100

[DEBUG] [1471065143.026208823]: Expected block 93, received 101

[DEBUG] [1471065143.026469552]: Expected block 93, received 102

[DEBUG] [1471065143.026658755]: Expected block 93, received 103

[DEBUG] [1471065143.026791758]: Expected block 93, received 104

[DEBUG] [1471065143.026915471]: Expected block 93, received 105

[DEBUG] [1471065143.027032590]: Expected block 93, received 106

[DEBUG] [1471065143.027149029]: Expected block 93, received 107

[DEBUG] [1471065143.027269872]: Expected block 93, received 108

[DEBUG] [1471065143.027385048]: Expected block 93, received 109

[DEBUG] [1471065143.027510865]: Expected block 93, received 110

[DEBUG] [1471065143.027629647]: Expected block 93, received 111

[DEBUG] [1471065143.027754700]: Expected block 93, received 112

[DEBUG] [1471065143.027878186]: Expected block 93, received 113

[ INFO] [1471065143.124085561]: Sending 168896 length of data

[DEBUG] [1471065143.124557414]: Received new message [24:114], while

still working on [23] (block 93 of 114)

[ INFO] [1471065143.124801273]: I heard: [ 9999:hello world (1555)]

[ INFO] [1471065143.224099150]: Sending 168896 length of data

[ INFO] [1471065143.224729317]: I heard: [ 9999:hello world (1556)]

[ INFO] [1471065143.324096278]: Sending 168896 length of data

```

と，93のところで現象が時々見られ，また，その時に受け取るブロック値も100前後のものが多いように思います．

また，Expected block ,,, を表示せずにメッセージを取りこぼす例も見られました．

```

INFO] [1471065150.724761772]: I heard: [ 9999:hello world (1631)]

[ INFO] [1471065150.824121774]: Sending 168896 length of data

[ INFO] [1471065150.924185734]: Sending 168896 length of data

[DEBUG] [1471065150.924513053]: Received new message [102:114], while

still working on [101] (block 93 of 114)

[ INFO] [1471065150.924858838]: I heard: [ 9999:hello world (1633)]

[ INFO] [1471065151.024083593]: Sending 168896 length of data

[ INFO] [1471065151.024728569]: I heard: [ 9999:hello world (1634)]

[ INFO] [1471065151.124852174]: Sending 168896 length of data

[ INFO] [1471065151.224098052]: Sending 168896 length of data

[DEBUG] [1471065151.224641488]: Received new message [105:114], while

still working on [104] (block 93 of 114)

[ INFO] [1471065151.224953142]: I heard: [ 9999:hello world (1636)]

[ INFO] [1471065151.324086516]: Sending 168896 length of data

[ INFO] [1471065151.324813610]: I heard: [ 9999:hello world (1637)]

[ INFO] [1471065151.424086629]: Sending 168896 length of data

[ INFO] [1471065151.424811884]: I heard: [ 9999:hello world (1638)]

[ INFO] [1471065151.524067245]: Sending 168896 length of data

[ INFO] [1471065151.524777459]: I heard: [ 9999:hello world (1639)]

[ INFO] [1471065151.624622572]: Sending 168896 length of data

```

UDPには詳しくないので，詳しい方に補足いただきたいところですが，調べてみると，UDPのバッファサイズは

```

$ cat  /proc/sys/net/core/rmem_max

26214400

```

として調べることができ，またこれは，

```

sudo sysctl -w net.core.rmem_max=46214400

```

として変更できるようです．定量的な評価はしていませんが，なんとなくですが，バッファサイズを上げると

少なくとも`Expected block 93, received 113` のようなエラーは出ないような気がします．ただ，

`Received new message [105:114], while still working on [104] (block

93 of 114)` は出ている気がします．

（前者の問題は解決はむつかしそうですが，後者はプログラムを賢くしたら修正できそうですね）

とはいえほとんどの場合は通信ができているので，UDP通信を行うとこういうものか，という気もします．

もし可能でしたら，そちらで試しているコードをgithubのリポジトリ等に上げてシェアさせていただけると

状況を共有できてよいかとおもいました．

なおこちらの確認している環境は以下になります．

```

$ lsb_release -a

No LSB modules are available.

Distributor ID: Ubuntu

Description: Ubuntu 14.04.4 LTS

Release: 14.04

Codename: trusty

$ echo $ROS_DISTRO

indigo

$ uname -a

Linux kokada-t440s 3.19.0-65-generic #73~14.04.1-Ubuntu SMP Wed Jun 29

21:05:22 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

$ rosversion roscpp

1.11.20

```

[Junya Miyamoto]

Moiraiさん

ご返答ありがとうございます。
返事が遅れてしまい、申し訳ございません。


ご指摘の通り、UDPのバッファサイズを変更したところ、
"Expected block 93, received 113"のようなエラーが出なくなり、
100KBを超えるメッセージを受信することができるようになりました。
本当にありがとうございました。

ちなみに、私の環境では、"Received new message [105:114], while still working
on [104]"といったメッセージは出力されませんでした。


> なかなかおもしろい現象ですね．
> これは毎回このような現象がおこっていますでしょうか？それとも，時々おこるものでしょうか？
毎回100KB以上のメッセージを送ると発生しておりました。

> もし可能でしたら，そちらで試しているコードをgithubのリポジトリ等に上げてシェアさせていただけると
> 状況を共有できてよいかとおもいました．
業務の関係上、コードを公開することは難しかったため、
こちらで共有をすることができませんでした。
大変申し訳ございません。


参考までに、私が実行したコマンドおよび実行環境を以下に記載いたします。

Sub側の値だけでなく、Pub側の送信バッファサイズも変更しました。
(Sub側の受信バッファサイズの変更のみだと、事象の解決はしませんでした。)
また、roscppでソケットバッファサイズを変更する際、ROS内部のコード修正が必要そうであったため、バッファサイズのデフォルト値も変更しております。

■実行したコマンド
-----
[Pub側マシンで実行]
$ cat /proc/sys/net/core/rmem_default
212992
$ cat /proc/sys/net/core/rmem_max
212992

$ sudo sysctl -w net.core.wmem_default=16777216
$ sudo sysctl -w net.core.wmem_max=16777216

[Sub側マシンで実行]
$ cat /proc/sys/net/core/rmem_default
212992
$ cat /proc/sys/net/core/rmem_max
212992

$ sudo sysctl -w net.core.rmem_default=16777216
$ sudo sysctl -w net.core.rmem_max=16777216
-----

■実行環境
-----
[Pub側]
CPU：Intel(R) Core(TM) i3-4160 CPU @ 3.60GHz
MEM：8GB
OS：Ubuntu 14.04.3 LTS
ROS：indigo
roscpp:1.11.13

[Sub側]
CPU：Intel(R) Core(TM) i3-4160 CPU @ 3.60GHz
MEM：8GB
OS：Ubuntu 14.04.4 LTS
ROS：indigo
roscpp:1.11.20
-----