ROS 2 camera publish frequency is loosely respected

[pijaro]

Describe the bug
ROS 2 camera publish frequency is loosely respected.

Example: Full HD resolution. Setting output frequency to 60Hz results in ~30Hz on ros2 topic hz. Changing output on the very same scene and machine to 120Hz results in ~60hz on output. Differences vary depending on level complexity, but this suggest it is possible to achieve the desired frequency, but for some reason it is not the case.

Steps to reproduce
Steps to reproduce the behavior:

1. Create empty level
2. Add ROS 2 camera sensor.
3. Set camera output frequency.
4. Use ros2 topic hz <topic_name> to check the output frequency.

Expected behavior
Output frequency is relatively close to the desired.

Actual behavior
Output frequency is lower than desired.

Found in Branch
development

Desktop/Device (please complete the following information):

• OS: Ubuntu 22.04

• Version [e.g. 10, Monterey, Oreo]

• CPU I7 13th gen.

• GPU RTX 4080

• Memory 64GB

[michalpelka]

Yes, it will be loosely respected by its design.

Sensor triggering in O3DE ROS 2 gem

Sensors in O3DE can be triggered by two sources:

• first is onTick event, that is more-or-less main loop called every graphics frame
• second is Simulation Finished event from Physics engine.
  The main difference is frequency. Former is about 30FPS - 60FPS and is limited by graphics, second can easily reach 500 FPS.

I've modified ROS 2 gem to log those event and put two sensors in scene, one camera set to 10FPS and Imu set to 30 Hz.
I've limited framerate to 60 FPS and plotted events in real-time (wall) time domain:

You can see in the images above:

• the blue dots (representing OnTick events) are spaced evenly 16.6 ms
• the green dot (representing camera triggering) appears every 6 frames.
• the camera "readout" event (purple dot) is little later
• the yellowish dots represents Physics Simulation Finished. They are computed next to each other in bulks of three - four.
• Imu triggering is aligned with some of Physics Simulation Finished events.

Note that we look at data in Wall-Time domain. In simulation time (referenced to /clock topic) they are distributed evenly.

Algorithm

Algorithm that is introduced in ROS 2 gem works as expected (for camera sensor):

• the base class for sensor trigger get time of last frame (it should be median of few frames, it is fixed in PR )
• It computes how many frames need to be skipped to get closest to requested framerate,
• Its finally triggers rendering, sending request to Atom to attach to Render tick (here ROS 2 headers for images are created)
• Atom renders frame and it published (slightly later)

Let us do some math, assume that your machine delivers 100 FPS and you requested 60FPS.
Let us assume that there is no jitter in your rendering, so every frame should be expected :

t_s =  1000 / 90 = 1.1 ms

The ideal triggering time for 60 FPS is 16.7 ms.
Triggering algorithm will wait this number of frames:

n_w = round(16.7/9.1)  = round(1.835) = 2

With that will give triggering time of 2 * 9.1 ms = 18.2 what is in FPS is 54 fps.
It will loosely follow - the algorithm tries to make as small error as possible.

However, you expect large discrepancy (not 5 FPs but 2x times).

Known issues

One frame statistic

We use only one frame to compute waiting number of frame - that is bad.
We use frame that was used to render extras pipelines - that is worse.
There is no frame limiter enabled - it is the worst.

Let's do our test again with no frame limiter:

Frame with extra camera rendered takes twice time.
If you request ROS 2 camera to render large frequency it can affect frequency, degrading it.

What should we do? / tldr.

Always use framelimiter and set its value to the fastest camera. It can be done in command line, can be done with lua:

local SetMaxFPS = 
{
    Properties =
    {
         MaxFPS = {default = 60}
    }
}

function SetMaxFPS:OnActivate()
     command = string.format("sys_MaxFPS=%f", self.Properties.MaxFPS)
     ConsoleRequestBus.Broadcast.ExecuteConsoleCommand("vsync_interval=0")
     ConsoleRequestBus.Broadcast.ExecuteConsoleCommand(command)
     Debug.Log("Set max FPS")
end

function SetMaxFPS:OnDeactivate()
     ConsoleRequestBus.Broadcast.ExecuteConsoleCommand("vsync_interval=0")
     ConsoleRequestBus.Broadcast.ExecuteConsoleCommand("sys_MaxFPS=100")
end

return SetMaxFPS

• Review and merge fix to gather statistics on execution time in PR Use ROS 2 clock for sensor triggering #807

Other materials:

Experimental branch with logging:
https://github.com/RobotecAI/o3de-extras/tree/mp/trigger_noted
Python script to visualize:
https://gist.github.com/michalpelka/3f2c66f16d20ba714c6389d5cd173032

[michalpelka]

Since it can be easily solved with framelimiter I lowered priority to major.