ROSでの通信遅延時間検証 その①

#概要
ROS(melodic)での通信遅延時間について検証してみました。

最近ROSでの本格的な開発を始めたROS初心者です。
ROSはリアルタイム性が低い事が知られていますが、実際にどの程度のリアルタイム性が期待できるのか、ノード間通信の遅延時間という観点で検証してみました。
ここでは検証プログラムの基本的な動作とROSでの時間システムを基本から説明しています。適当なVM上で検証しているので詳細な性能検証は別途投稿します。

#ROSでの処理時間計測
C/C++ではchrono関数等の時間計測用関数で処理時間計測を行っていると思います。
処理時間計測関数

ROSでも当然同じ関数を用いて時間計測が可能ですが、ROSを理解するためにも、ここではROSのログから処理時間を計測してみたいと思います。

#検証用のコードと実行結果
では、ノード間通信の遅延時間を見ていきたいと思います。
ここでは、簡単な文字列を送信して、送信時と受信時のタイムスタンプを見る事で遅延時間を計測したいと思います。

検証では、下記のROS講座を参考にさせて頂きました。
ROS講座03 Pub & Sub 通信

検証用のpublisher(送信)のコードです。
詳細な動作説明は上記のROS講座に記載がありますので割愛しますが、ここで注目して頂きたいのは、ros::Rate loop_rate(100);です。
これは、publisher側のデータ送信レートです。つまり、このコードでは100Hz(10msに1回)でデータを送信する事になります。この時、送信されるデータは、msg.data = "Test msg";にあるように、'Test msg'という文字列になります。

test_publisher.cpp

#include <ros/ros.h>
#include <std_msgs/String.h>

int main(int argc, char** argv)
{
  ros::init(argc, argv, "test_publisher");
  ros::NodeHandle nh;
  ros::Publisher chatter_pub = nh.advertise<std_msgs::String>("chatter", 10);
  ros::Rate loop_rate(100);

  while (ros::ok())
  {
    std_msgs::String msg;
    msg.data = "Test msg";
    ROS_INFO("publish: %s", msg.data.c_str());
    chatter_pub.publish(msg);

    ros::spinOnce();
    loop_rate.sleep();
  }
  return 0;
}

これに対応するsubscriber(受信)が下記になります。

test_subscriber.cpp

#include <ros/ros.h>
#include <std_msgs/String.h>

void chatterCallback(const std_msgs::String& msg)
{
  ROS_INFO("subscribe: %s", msg.data.c_str());
}

int main(int argc, char** argv)
{
  ros::init(argc, argv, "test_subscriber");
  ros::NodeHandle nh;
  ros::Subscriber sub = nh.subscribe("chatter", 10, chatterCallback);

  ros::spin();
  return 0;
}

また、publisher, subscriberそれぞれにROS_INFOという関数が使用されていますが、これはターミナルに結果を出力するためのprintfのような物です。
下記がlaunchファイルになります。

test_pubsub.launch

<launch>
  <node name="test_publisher"   pkg="latency_test" type="test_publisher" output="screen"/>
  <node name="test_sybscriber" pkg="latency_test" type="test_subscriber" output="screen"/>
</launch>

これで、上記のlaunchファイルを実行すると、下記のように、ひたすら'Test msg'という文字列の送受信が行われます。
また、この時ROS_INFOの実行された時間も同時に表示されます。
ROSの時間フォーマットは、こちらの公式ドキュメントに記載がありますが小数点前はsec、小数点以降はnsecです。また、secはエポック秒です。
このターミナル出力をみると、publishは10msec程度の間隔で行われていて、publishからsubscribeの間隔は1msec以下である事がわかります。

#送信レートと通信遅延時間の検証

ターミナルの表示結果をscriptでログをとって解析しても良いのですが、ROSの機能でこの結果は自動的にログとして残っています。デフォルトでは、ユーザフォルダ直下に/.ros/log/latestrosout.logとして保存されています。

このログファイルを下記のスクリプトで簡単に解析してみました。

check_time_stamp_pubsub.py

import csv
import numpy as np
import matplotlib.pyplot as plt

# Specify file name of log file
file = 'rosout.log'
log_file = open(file, "r", encoding="UTF-8")
dataList = log_file.readlines()

# Specify extract name
extract_word1 = 'publish' 
extract_word2 = 'subscribe' 

published_time = []
subscribed_time = []

for row in dataList:
    if extract_word1 in row:
        published_time.append(float(row[:20]))
    if extract_word2 in row:
        subscribed_time.append(float(row[:20]))

# Convert to numpy array
published_time = np.array(published_time)
subscribed_time = np.array(subscribed_time)

diff_pub_time = []

for t in range(0,len(published_time)-1):
   diff_pub_time.append(published_time[t+1]-published_time[t])

# Remove surplus index
diff_num = len(published_time) - len(subscribed_time)
published_time = np.delete(published_time,slice(0,diff_num)) 

transmit_time = subscribed_time - published_time

pub_time_ave = np.mean(diff_pub_time)
pub_time_std = np.std(diff_pub_time)

transmit_time_ave = np.mean(transmit_time)
transmit_time_std = np.std(transmit_time)

print('Pub time : Ave = {0}, STD = {1}'.format(pub_time_ave, pub_time_std))
print('Transmit time : Ave = {0}, STD = {1}'.format(transmit_time_ave, transmit_time_std))

plt.figure()
plt.scatter(range(0,len(diff_pub_time)),diff_pub_time)
plt.xlabel('Frame')
plt.ylabel('Time [sec.]')
plt.figure()
plt.scatter(range(0,len(transmit_time)),transmit_time)
plt.xlabel('Frame')
plt.ylabel('Time [sec.]')
plt.show()

下記が送信レートになります。送信した時間と１回前の送信時間との差分をプロットしています。100Hzで送信しているので、ここは10msecになるはずですが、最大で2msec程度のずれがありました。平均は10msec, 標準偏差は400usecとなったので、おおむね100Hzで送信されている事がわかります。

次に送信してから、受信されるまでの遅延を検証しました。
一番遅延が大きい時では3msec程度の遅延がありましたが、平均は300us, 標準偏差は90usecの遅延となりました。300usなら十分速いと思いますが、3msecとなると後段の処理によってはリアルタイム動作に影響を与える可能性がありそうですね。
また、この時publishの回数とsubscribeの回数があっておらず、publishのほうが先に動作を始めており11回送信後にsubscribeの動作が始まっていました。解析用のスクリプトでは、publish側が先に動作し始める事を前提にsubscribeの動作開始までのデータを捨てるようにしています。

#まとめ
pub&sub送信時の遅延時間を簡単に検証してみました。
・送信レート、通信遅延ともにばらつき有り(それぞれ最大2msec,3msec)
・通信遅延は短い文字列であれば300us程度
・ノードの動作開始タイミングに差分有り

今後は、下記を変えて遅延時間の検証を行っていく予定です。
・送信データ容量
・バッファサイズ

ROS初心者ですので、記載内容に間違い、または、アドバイス等あればコメント頂けますと幸いです。

(追記) データサイズと遅延時間について検証しました。ROSでの通信遅延時間検証　その②