Bugfix: Timestamp wrapping when initializing SubscriptionInterval less than the interval time after boot

[MaEtUgR]

Solved Problem

When debugging #23378 , the only instance where timestamps get negative/wrap the unsigned datatype was the case where SubscriptionIntervals are initialized less than the interval time (e.g. 1 second) after boot and hence the start of the microcontroller timer. This made the cases fail after invalid assumptions were made that this case would never normally happen without checking even once here: https://github.com/PX4/PX4-Autopilot/pull/22881/files#diff-5971d648b2b246dfb01ec5d5006b5258cfdbc41b73f50db1abe7dd5236f855e1R167-R172

The change producing a few timestamps after boot that wrap was introduced here:
https://github.com/PX4/PX4-Autopilot/pull/14181/files#diff-c82d12a48f93eeb820597a14504a6a2d58cb7c09ad86d2e7da6aa6b04e144628L124-R128
and it never resulted in any problem because even across the wrapping the result of the elapsed time calculation was correct again.

Fixes #23378

Solution

The stamp stays 0 if subscriptions are initialized less than the interval time after boot instead of wrapping the unsigned timestamp.

It might not be optimal when the 64 bit time actually wraps because then for one intervals time the _last_update is not updated anymore but I hope that's acceptable given this should only happen after 500+k years of runtime.

Changelog Entry

Bugfix: Timestamp wrapping when initializing SubscriptionInterval less than the interval time after boot

Alternatives

Even with this fix I highly suggest reverting the change that made elapsed time across wrapping calculations impossible: #23380

Test coverage

I ran this in SITL printing out all the _last_update timestamps of all instances and they do not wrap anymore shortly after boot but rather stay zero until the interval time passed once.

[DronecodeBot]

This pull request has been mentioned on Discussion Forum for PX4, Pixhawk, QGroundControl, MAVSDK, MAVLink. There might be relevant details there:

https://discuss.px4.io/t/px4-sync-q-a-july-10-2024/39614/1

[MaEtUgR]

@dagar Do you have any idea why this change consumes so much flash (2.5kb) if I saw it correctly? It wasn't on my radar until I saw 1.15 failing and now I saw also on main it fails quite a few. How can one more branch in the code path without templating contribute to so much usage? 😱

[MaEtUgR]

I ran a bloaty compare and the if case adds ~2kb, the else case another 0.5kb 🤯

Bloaty output if case only

       VM SIZE    
 -------------- 
  [NEW]    +174    uORB::SubscriptionInterval::copy(void*) (.part.0)
  +3.9%    +116    px4::logger::Logger::run()
  +3.2%    +112    EKF2::Run()
  +5.7%    +112    sensors::VehicleAngularVelocity::Run()
  +4.5%     +84    ControlAllocator::Run()
  +3.0%     +60    FwAutotuneAttitudeControl::Run()
  +2.6%     +56    McAutotuneAttitudeControl::Run()
  +4.3%     +56    TargetEstimator::update()
  +2.0%     +52    MulticopterAttitudeControl::Run() (.part.0)
  +2.2%     +52    MulticopterRateControl::Run() (.part.0)
   +24%     +52    RtlTimeEstimator::update()
  +2.8%     +52    UavcanNode::Run()
  +2.7%     +52    do_gyro_calibration(void**)
  +4.2%     +52    sensors::VotedSensorsUpdate::imuPoll(sensor_combined_s&)
  +3.2%     +48    MulticopterHoverThrustEstimator::Run()
  +6.2%     +44    SensorBaroSim::Run()
   +19%     +40    CdcAcmAutostart::UpdateParams(bool)
  +2.8%     +40    Commander::run()
  +3.2%     +36    LedController::update(LedControlData&)
   +17%     +36    RtlDirect::parameters_update()
  +3.5%     +32    EKF2Selector::PublishVehicleAttitude()
   +14%     +32    FlightTaskTransition::updateParameters()
   +14%     +32    Heater::update_params(bool)
   +18%     +32    MissionBase::parameters_update()
  +0.9%     +32    Navigator::run()
  +8.2%     +32    PWMOut::Run()
  +5.2%     +32    Sih::sensor_step()
  +2.1%     +32    gimbal_thread_main(int, char**)
  +3.1%     +32    sensors::VehicleAcceleration::Run()
  +8.0%     +28    PWMSim::Run()
  +5.9%     +28    px4::logger::Logger::handle_event_updates(unsigned long&)
   +11%     +26    landing_target_estimator::LandingTargetEstimator::_check_params(bool)
  +6.3%     +24    INA226::collect()
  +1.1%     +24    RCInput::Run()
  +3.3%     +24    SensorGpsSim::Run() (.part.0)
  +2.5%     +24    SensorMagSim::Run() (.part.0)
  +1.9%     +24    detect_orientation(void**, bool)
  +2.8%     +24    read_accelerometer_avg(float (&) [4][6][3], unsigned int, unsigned int) (.constprop.0)
   +14%     +24    uORB::SubscriptionInterval::update(void*)
  +1.1%     +20    EKF2Selector::UpdateErrorScores()
  +9.1%     +20    FunctionServos::update()
  +3.3%     +20    PX4IO::Run()
  +8.5%     +20    RTL::parameters_update()
  +3.4%     +20    Sensors::Run()
  +2.4%     +20    sensors::VehicleAcceleration::SensorSelectionUpdate(bool)
  +8.5%     +16    DShot::update_params()
  +1.2%     +16    GyroCalibration::Run() (.part.0)
  +2.9%     +16    PCA9685Wrapper::Run()
  +4.7%     +16    TargetEstimator::parameters_update(bool)
  +2.5%     +16    ToneAlarm::Run()
  +0.7%     +16    sensors::VehicleIMU::UpdateGyro()
  +3.0%     +16    temperature_compensation::TemperatureCompensationModule::Run()
   +21%     +16    uORB::SubscriptionInterval::copy(void*)
  +2.5%     +12    FunctionMotors::update()
  +1.6%     +12    MspOsd::Run() (.part.0)
  +3.7%     +12    px4::logger::Logger::update_params()
  +3.4%     +12    sensors::VehicleAcceleration::ParametersUpdate(bool)
  +0.7%     +12    sensors::VehicleAngularVelocity::ParametersUpdate(bool)
  +9.7%     +12    uORB::DeviceNode::read(file*, char*, unsigned int)
  +1.2%      +8    CameraFeedback::Run()
  +0.4%      +8    sensors::VehicleAngularVelocity::SensorSelectionUpdate(unsigned long long const&, bool)
  +1.1%      +8    sensors::VehicleIMU::ParametersUpdate(bool)
  +8.3%      +4    McAutotuneAttitudeControl::stopAutotune()
  +0.2%      +4    do_level_calibration(void**)
  +2.0%      +4    matrix::Dcm<float>::Dcm(matrix::Euler<float> const&)
   +17%      +4    px4::logger::util::file_exist(char const*)
   +33%      +4    srand
  +5.6%      +2    matrix::Dcm<float>::Dcm()
  -0.8%      -4    ControlAllocator::publish_actuator_controls() (.part.0)
  -0.4%      -4    Ekf::resetMagStates(matrix::Vector3<float> const&, bool)
  -0.9%      -4    FixedwingPositionControl::set_control_mode_current(unsigned long long const&)
 -25.0%      -4    ModuleBase<CrsfRc>::unlock_module()
  -8.3%      -4    Navigator::stop_capturing_images()
  -1.8%      -4    SensorGpsSim::generate_wgn()
 -16.7%      -4    _file_shutdown()
  -2.8%      -4    msp_osd::construct_BATTERY_STATE(battery_status_s const&)
  -5.0%      -4    px4::logger::Logger::task_spawn(int, char**)
  -6.2%      -4    uavcan::TimerEventForwarder<uavcan::MethodBinder<UavcanBeepController*, void (UavcanBeepController::*)(uavcan::TimerEvent const&)> >::handleTimerEvent(uavcan::TimerEvent const&)
  -3.7%      -4    uavcan_stm32::CanDriver::init(unsigned long, uavcan_stm32::CanIface::OperatingMode, unsigned long)
 -13.0%      -6    uORB::SubscriptionBlocking<sensor_mag_s>::call()
  -5.7%    -116    mag_calibration_worker(detect_orientation_return, void*)
  +0.1% +2.02Ki    TOTAL

Bloaty output if and else case

     VM SIZE    
 -------------- 
  [NEW]    +184    uORB::SubscriptionInterval::copy(void*) (.part.0)
  +3.9%    +136    EKF2::Run()
  +4.6%    +136    px4::logger::Logger::run()
  +5.8%    +108    ControlAllocator::Run()
  +4.5%     +88    sensors::VehicleAngularVelocity::Run()
  +3.8%     +76    FwAutotuneAttitudeControl::Run()
  +3.4%     +72    McAutotuneAttitudeControl::Run()
  +5.2%     +68    TargetEstimator::update()
  +3.5%     +64    UavcanNode::Run()
  +4.0%     +60    MulticopterHoverThrustEstimator::Run()
  +2.5%     +60    MulticopterRateControl::Run() (.part.0)
  +3.1%     +60    do_gyro_calibration(void**)
   +25%     +56    RtlTimeEstimator::update()
  +7.8%     +56    SensorGpsSim::Run() (.part.0)
  +7.3%     +52    SensorBaroSim::Run()
  +4.2%     +52    sensors::VotedSensorsUpdate::imuPoll(sensor_combined_s&)
   +23%     +48    CdcAcmAutostart::UpdateParams(bool)
  +3.4%     +48    Commander::run()
  +4.0%     +44    LedController::update(LedControlData&)
  +1.7%     +44    MulticopterAttitudeControl::Run() (.part.0)
   +20%     +42    RtlDirect::parameters_update()
   +22%     +40    MissionBase::parameters_update()
  +1.1%     +40    Navigator::run()
  +6.5%     +40    Sih::sensor_step()
  +2.6%     +40    gimbal_thread_main(int, char**)
   +17%     +38    FlightTaskTransition::updateParameters()
  +4.0%     +36    EKF2Selector::PublishVehicleAttitude()
   +16%     +36    Heater::update_params(bool)
  +9.2%     +36    PWMOut::Run()
   +10%     +36    PWMSim::Run()
  +7.6%     +36    px4::logger::Logger::handle_event_updates(unsigned long&)
  +1.4%     +32    RCInput::Run()
  +3.3%     +32    SensorMagSim::Run() (.part.0)
  +2.5%     +32    detect_orientation(void**, bool)
  +3.7%     +32    read_accelerometer_avg(float (&) [4][6][3], unsigned int, unsigned int) (.constprop.0)
  +3.8%     +32    sensors::VehicleAcceleration::SensorSelectionUpdate(bool)
  +1.6%     +28    EKF2Selector::UpdateErrorScores()
   +13%     +28    FunctionServos::update()
  +7.4%     +28    INA226::collect()
  +4.7%     +28    Sensors::Run()
  +2.7%     +28    sensors::VehicleAcceleration::Run()
   +17%     +28    uORB::SubscriptionInterval::update(void*)
   +11%     +26    landing_target_estimator::LandingTargetEstimator::_check_params(bool)
   +13%     +24    DShot::update_params()
  +1.8%     +24    GyroCalibration::Run() (.part.0)
  +3.9%     +24    PX4IO::Run()
   +10%     +24    RTL::parameters_update()
  +7.1%     +24    TargetEstimator::parameters_update(bool)
  +2.7%     +20    MspOsd::Run() (.part.0)
  +3.7%     +20    PCA9685Wrapper::Run()
  +3.2%     +20    ToneAlarm::Run()
  +6.1%     +20    px4::logger::Logger::update_params()
  +5.7%     +20    sensors::VehicleAcceleration::ParametersUpdate(bool)
  +1.2%     +20    sensors::VehicleAngularVelocity::ParametersUpdate(bool)
  +3.8%     +20    temperature_compensation::TemperatureCompensationModule::Run()
   +26%     +20    uORB::SubscriptionInterval::copy(void*)
  +2.3%     +16    CameraFeedback::Run()
  +3.3%     +16    FunctionMotors::update()
  +0.9%     +16    do_level_calibration(void**)
  +0.8%     +16    sensors::VehicleAngularVelocity::SensorSelectionUpdate(unsigned long long const&, bool)
  +2.2%     +16    sensors::VehicleIMU::ParametersUpdate(bool)
  +0.7%     +16    sensors::VehicleIMU::UpdateGyro()
   +13%     +16    uORB::DeviceNode::read(file*, char*, unsigned int)
  +0.6%      +8    EKF2Selector::Run()
  +3.4%      +4    FlightTaskOrbit::_is_position_on_circle() const
  +8.3%      +4    McAutotuneAttitudeControl::stopAutotune()
   +11%      +4    Report::canArm(unsigned char) const
  +2.0%      +4    matrix::Dcm<float>::Dcm(matrix::Euler<float> const&)
   +12%      +4    matrix::Vector<float, 3u>::norm() const
  +3.7%      +4    temperature_compensation::TemperatureCompensationModule::task_spawn(int, char**)
   +11%      +2    FlightTaskTransition::updateInitialize()
  +1.9%      +2    RtlDirect::on_active()
  +5.6%      +2    matrix::Dcm<float>::Dcm()
  +1.6%      +2    sensors::VotedSensorsUpdate::SensorData::SensorData(ORB_ID)
  -0.8%      -4    ControlAllocator::publish_actuator_controls() (.part.0)
  -0.9%      -4    FixedwingPositionControl::set_control_mode_current(unsigned long long const&)
 -25.0%      -4    ModuleBase<CrsfRc>::unlock_module()
  -1.4%      -4    RtlDirect::on_activation()
  -3.4%      -4    SHT3X::print_usage()
  -1.8%      -4    SensorGpsSim::generate_wgn()
 -16.7%      -4    _file_shutdown()
 -11.1%      -4    float matrix::detail::wrap_floating<float>(float, float, float) (.part.0)
  -2.8%      -4    msp_osd::construct_BATTERY_STATE(battery_status_s const&)
  -5.0%      -4    px4::logger::Logger::task_spawn(int, char**)
  -0.9%      -4    sensors::VehicleGPSPosition::VehicleGPSPosition()
  -8.0%      -4    uavcan::IntegerSpec<48u, (uavcan::Signedness)0, (uavcan::CastMode)0>::encode(unsigned long long, uavcan::ScalarCodec&, uavcan::TailArrayOptimizationMode) (.isra.0)
  -3.7%      -4    uavcan_stm32::CanDriver::init(unsigned long, uavcan_stm32::CanIface::OperatingMode, unsigned long)
 -13.0%      -6    uORB::SubscriptionBlocking<sensor_mag_s>::call()
  -5.7%    -116    mag_calibration_worker(detect_orientation_return, void*)
  +0.1% +2.48Ki    TOTAL

👀

[MaEtUgR]

I found out thanks to @niklaut 's analysis for the decompiled binary 🙏🙏
I'm working on a fix.

[MaEtUgR]

Here we go: #23395

I wonder how much the tradeoff for less jumps makes sense on the microcontroller and how much flash we waste by unintentionally inlining 🤔