logger: poll sensor_combined if estimator replay enabled

[dagar]

Noticed primarily in #14676 where the default IMU integration period changes (sensor_combined at 400 Hz instead of 250 Hz). This should help things even with existing setups and 250 Hz IMU.

[bkueng]

I'm not fond of the added dependency on the topic publication.
What's the CPU impact on increasing the default rate?

[dagar]

I'm not fond of the added dependency on the topic publication.
What's the CPU impact on increasing the default rate?

Yes, it's a bit gross. Let's get some data across a few boards and see if it's justified.

The reason this seems potentially compelling is it nicely schedules logger to run right after the bulk of the data is produced (sensor_combined, estimator, controllers). If you follow it through from each sensor_combined publication and everything downstream triggered as a result (estimator, attitude & position controllers) that's somewhere around 60% of a typical log (default settings).

[dagar]

Interesting discovery, the logging rate has increased drastically with this change.

Looking at px4_fmu-v4 on the test rack.

INFO  [logger] Wrote 1.91 MiB (avg 40.02 KiB/s)     <- master
INFO  [logger] Wrote 35.12 MiB (avg 189.89 KiB/s)   <- PR

A portion of this is sensor_combined, but that still doesn't account for it. My guess is we're capturing a much larger percentage of the estimator messages (estimator_innovations, estimator_innovation_variances, estimator_innovation_test_ratios, etc), but I'll need to look in detail tomorrow. The other minor note is that logger cpu usage increased 3%, which is actually not that bad at this somewhat ridiculous extreme.

[dagar]

Currently logger disables the interval for all topics if a polling topic if enabled, so that explains the weird behavior above.

This is what I'm seeing now.

INFO  [logger] Wrote 1.91 MiB (avg 40.02 KiB/s)     <- master
INFO  [logger] Wrote 4.94 MiB (avg 47.06 KiB/s)     <- PR

Logger CPU usage increase.

 PID COMMAND                   CPU(ms) CPU(%)  USED/STACK PRIO(BASE) STATE FD
 586 logger                       2957  3.458  2832/ 3644 233 (233)  READY  4  <- master
 586 logger                       2652  5.115  2832/ 3644 233 (233)  w:sem  5  <- PR

The other thing that stood out to me is that although the logging rate increased, the dropouts were shorter. I'm not sure if that's meaningful over a ~2 minute log.

Master ulog info

Logging start time: 0:00:38, duration: 0:01:54
Dropouts: count: 4, total duration: 1.3 s, max: 804 ms, mean: 326 ms

PR ulog info

Logging start time: 0:00:26, duration: 0:02:27
Dropouts: count: 5, total duration: 0.1 s, max: 27 ms, mean: 10 ms

The throttled topics also appear to be much closer to their configured intervals.

 estimator_status (0, 284)                    555     157620 = 4.87 Hz  <- master
 estimator_status (0, 284)                    732     207888 = 5 Hz     <- PR

Note the default IMU integration period changed (4000 us -> 2500 us) to align with the new ecl/EKF filter update period (10 ms), so either way we'll need to do something with logger (polling or increase default rate).

Later I think we could effectively bring down the ekf2 replay logging requirements considerably by only logging the downsampled IMU (100 Hz). I'll revisit that soon during multi-EKF development where ekf replay logging by default is going to become quite problematic.

[dagar]

Note the default IMU integration period changed (4000 us -> 2500 us) to align with the new ecl/EKF filter update period (10 ms), so either way we'll need to do something with logger (polling or increase default rate).

Later I think we could effectively bring down the ekf2 replay logging requirements considerably by only logging the downsampled IMU (100 Hz). I'll revisit that soon during multi-EKF development where ekf replay logging by default is going to become quite problematic.

Related: #14759 (comment)

[bkueng]

Logger's main loop is quite efficient, so increasing the rate should be viable.

I'm only ok with polling as default config if we use a short timeout of around 3ms.

[bkueng]

This still breaks replay.

[dagar]

Could you expand on that? What would you suggest given the overall goal?

[bkueng]

The rate limitation of the topics uses the absolute time which does not match the replay time.
We need to use the time abstraction for replay to resolve this cleanly.
The quick-and-dirty way would be to check _replay_file_name.

[dagar]

Ok, I'll put this on hold depending on the outcome of #14759.

[dagar]

#14759 has merged with a default IMU integration rate of 200 Hz, which works well with the current logger interval.