Open GiulioRomualdi opened 2 years ago
traversaro
commented
2 years ago Accordingly to the outcome seems that the bottleneck is caused by the
sendfunction inside the meshcat package.
Probably an obvious question, but I am missing something: how can you understand this from the output you posted?
GiulioRomualdi
commented
2 years ago Accordingly to the outcome seems that the bottleneck is caused by the
sendfunction inside the meshcat package.Probably an obvious question, but I am missing something: how can you understand this from the output you posted?
As you can see here the cumtime is pretty high (0.012)
ncalls tottime percall cumtime percall filename:lineno(function)
42 0.000 0.000 0.012 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/meshcat/visualizer.py:151(set_transform)From the documentation
tottimefor the total time spent in the given function (and excluding time made in calls to sub-functions)[...]
cumtimeis the cumulative time spent in this and all subfunctions (from invocation till exit). This figure is accurate even for recursive functions.
traversaro
commented
2 years ago Thanks, I wonder how I was not able to see it before.
GiulioRomualdi
commented
2 years ago Bytheway if you noticed here https://github.com/ami-iit/robot-log-visualizer/issues/24#issuecomment-1021041658 the cumulative time per call is actually small. So the problem happens in the case of a multibody system where meshcat should send to the server a pose for each mesh (in our case 42)
traversaro
commented
2 years ago Yes, probably having some kind of set_transforms to set all the transforms at once would be useful (this was exactly the bottleneck in the MATLAB visualizer). It may be worth to check what they do in Drake.
traversaro
commented
2 years ago It may be worth to check what they do in Drake.
GiulioRomualdi
commented
2 years ago It may be worth to check what they do in Drake.
So it's similar to what we do in our code
diegoferigo
commented
2 years ago @GiulioRomualdi when debugging, it's often more useful ordering the function calls with tottime instead of cumtime, you can do it as follows:
python -m cProfile -s tottime mu_script.py This being said, I also noticed in another application that meshcat is pretty slow when sending the json message with the new link transform. Multiply this time for all the links and you can easily get the problems that have occurred here. Though, I couldn't find any way to send a single message containing multiple transforms.
traversaro
commented
2 years ago However, if the problem is sending the transform to meshcat, I am not sure why this happens only when loading a dataset and not when the dataset is played back.
GiulioRomualdi
commented
2 years ago However, if the problem is sending the transform to meshcat, I am not sure why this happens only when loading a dataset and not when the dataset is played back.
Ops. I should explain it better. This happens only after loading the dataset (so also when it is played back). If the dataset is not loaded the meshcat.set_transform() is not called.
GiulioRomualdi
commented
2 years ago @diegoferigo I sorted the list by tottime (and the winner is meshcat send)
ncalls tottime percall cumtime percall filename:lineno(function)
42 0.009 0.000 0.013 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/meshcat/visualizer.py:56(send)
42 0.001 0.000 0.001 0.000 {built-in method idyntree._iDynTree.ExternalMesh_getFileLocationOnLocalFileSystem}
966/42 0.001 0.000 0.003 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/umsgpack.py:544(_pack3)
42 0.001 0.000 0.016 0.000 /home/gromualdi/robot-code/robot-log-visualizer/robot_visualizer/meshcat_visualizer.py:110(__apply_transform)
126 0.001 0.000 0.001 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/zmq/sugar/socket.py:480(send)
1 0.001 0.001 0.019 0.019 /home/gromualdi/robot-code/robot-log-visualizer/robot_visualizer/meshcat_visualizer.py:192(set_multy_body_system_state)
672 0.000 0.000 0.001 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/umsgpack.py:325(_pack_float)
3570 0.000 0.000 0.000 0.000 {built-in method builtins.isinstance}
84 0.000 0.000 0.001 0.000 {built-in method numpy.core._multiarray_umath.implement_array_function}
42 0.000 0.000 0.000 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/numpy/lib/twodim_base.py:234(diag)
210 0.000 0.000 0.000 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/umsgpack.py:336(_pack_string)
42 0.000 0.000 0.002 0.000 /home/gromualdi/robot-code/robot-log-visualizer/robot_visualizer/meshcat_visualizer.py:36(__is_mesh)
42 0.000 0.000 0.000 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/meshcat/commands.py:40(lower)
42 0.000 0.000 0.003 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/umsgpack.py:438(_pack_map)
42 0.000 0.000 0.002 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/umsgpack.py:423(_pack_array)
84 0.000 0.000 0.000 0.000 {method 'flatten' of 'numpy.ndarray' objects}
69 0.000 0.000 0.000 0.000 {built-in method idyntree._iDynTree.LinksSolidShapesVector___getitem__}
42 0.000 0.000 0.001 0.000 /home/gromualdi/robot-code/robot-log-visualizer/visualizer-env/lib/python3.8/site-packages/zmq/sugar/socket.py:549(send_multipart)
966 0.000 0.000 0.000 0.000 {built-in method _struct.pack}
42 0.000 0.000 0.000 0.000 {method 'dot' of 'numpy.ndarray' objects}
966 0.000 0.000 0.000 0.000 {method 'write' of '_io.BytesIO' objects}Related to https://github.com/duburcqa/jiminy/pull/543
In the past few days, I noticed that the application is greedy for resources. This happens when a new dataset is loaded. Indeed on the
icub-console-guithe CPU usage jumps to160%when the dataset is loaded. I tried to investigate the problem and I noticed that the thread related to meshcat requires more than its period (0.02s) to compute a cycle.https://github.com/ami-iit/robot-log-visualizer/blob/bdb99ce16fcbed41132e7db221416ca47e9550aa/robot_visualizer/meshcat_provider.py#L35-L56
In the beginning, I thought that the problem was related to the dynamical allocation of the vector associated with the robot joints and the base pose every time
set_multy_body_system_stateis called.https://github.com/ami-iit/robot-log-visualizer/blob/bdb99ce16fcbed41132e7db221416ca47e9550aa/robot_visualizer/meshcat_visualizer.py#L198-L217
I reduced the time this memory allocation is performed (associated PR: https://github.com/robotology/idyntree/pull/959) but the problem was still there.
To better understand the problem I wrote a simple script that isolates the "slow" function (
set_multy_body_system_state) (I know there is a typo. I'm sorry for that 😞)Accordingly to the outcome seems that the bottleneck is caused by the
sendfunction inside the meshcat package. I am afraid that we should increase the period of the meshcat thread in order to avoid undesired behavior in the application.@traversaro @diegoferigo @isorrentino @paolo-viceconte @RiccardoGrieco @S-Dafarra do you have any idea on how to avoid this problem?