ROSノードの実行時間プロファイリングしたかったメモ

ROSノードの実行時間を知りたい

どうにも処理が重いnodeがいて、どこがボトルネックになっているのか知りたくプロファイリングをしたメモ。

実行環境

• Ubuntu 16.04 LTS
• ROS Kinetic Kame

pprofile

pythonで各行実行時間を知るにはcProfileなどいろいろある様子。
今回は特に理由はないがpprofileを使用。各行の実行時間を知りたいだけなので特にどれでも問題なし。

launchファイルにprefix追加

pprofileをlaunchファイルから実行できるようにnodeタグにオプションを加える。
同じようなことを考える人たちはやはりいるようで、ROS標準でprefixをつけてノードを実行できるようになっている。
参考：How to Roslaunch Nodes in Valgrind or GDB

launchファイルの記述は下記のような形。

<launch>
 ...いろいろ

    <node pkg="pkgname" 
          name="nodename" 
          type="script.py" 
          launch-prefix="pprofile --out $(find pkgname)/log/script.pprofile" >
        ...いろいろ
    </node>

</launch>

これでlaunchファイルを実行すれば、prefixがついた状態で実行されるのでプロファイリングができる。

実行結果

$(find pkgname)/log/script.pprofileを開くと下記の通りpprofileの結果が出力されている。

File: /home/***/catkin_ws/src/pkgname/script/script.py
File duration: 0.018404s (0.79%)
Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
     1|         0|            0|            0|  0.00%|#!/usr/bin/env python
     2|         0|            0|            0|  0.00%|
     3|         2|     0.018404|     0.009202|  0.79%|import sys
     4|         0|            0|            0|  0.00%|import rospy
(call)|         1|   1.5974e-05|   1.5974e-05|  0.00%|# /usr/lib/python2.7/dist-packages/pkg_resources/_vendor/six.py:184 find_module
(call)|         1|   2.7895e-05|   2.7895e-05|  0.00%|# /usr/lib/python2.7/dist-packages/pkg_resources/extern/__init__.py:22 find_module
     5|         0|            0|            0|  0.00%|import tf
     6|         0|            0|            0|  0.00%|import numpy as np
     7|         0|            0|            0|  0.00%|from sensor_msgs.msg import Image
     8|         0|            0|            0|  0.00%|from cv_bridge import CvBridge, CvBridgeError
...

やったね！

その他雑感

• プロファイルした結果の出力先はパッケージ下のlogにしたけれど、こういう場合も.rosを使用していいもの…？ 今の形だと若干行儀が悪い感はある。
• pprofileを使ったけれど、cProfileやvalgrindなどもある様子。用途によるのだろうけれど、もう少し勉強せねば。