I am working on QT console application to execute on a ARM CPU and I met a very strange behavior of QTimer: instead of planned 100 ms, the timer expired after 1946 ms. I changed the duration but the observed behavior does not change (about some milliseconds, ex. 1958 ms instead of 40 ms). When the same code is executed on x86_AMD64 (I stubbed the call to a specific HW API function; the execution of this function without QTimer slot requires less than 3 ms), the timer duration is as expected +/- 100 ms.
Note: the version of embedded QT is 5.4.1; the version of PC QT is 5.9.5
I tried different durations, including 0. The expiring is about the same duration.
I monitored the CPU usage (less than 30%) and load average (less than 0.15).
I wrote also a small QT console application which starts some timers of different durations and logs the elapsed times. The results are corrects (the elapsed times drift, as "expected" ;), so I think buildchain and embedded QT installation are good.
I added to my initial code a QElapsedTimer and I logged the elapsed time in the slot method of 40 ms QTimer.
I obtained the trace on PC:
mDebugMessage = ("elapsed time = 42 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=true - time = 46", "elapsed time = 81 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=true - time = 81", "elapsed time = 122 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=true - time = 122", "elapsed time = 162 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 163", "elapsed time = 201 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 201", "elapsed time = 242 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=true - time = 242", "elapsed time = 281 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 281", ...
On ARM, the trace is different, instead of expected +/- 40 ms, the duration is about 2 seconds:
mDebugMessage = ("elapsed time = 1958 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 1961", "elapsed time = 3916 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 3919", "elapsed time = 5873 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 5876", "elapsed time = 7830 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 7833", "elapsed time = 9787 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 9790", "elapsed time = 11744 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 11747", "elapsed time = 13700 ms - INPUT_DOOR_LOCKED_SENSOR=false - INPUT_DOOR_UNLOCKED_SENSOR=false - time = 13705", ...
I need your help to understand why my QTimer does not expire as expected or any clue to investigate on target what may prevent my timer to expire.
Thank you for your idea.
Best regards,
EDIT: as demanded, the code
const int CDoorManagement::I_DOOR_LOCKING_DURATION_MS = 40;
const int CDoorManagement::I_DOOR_LOCKING_ALARM_DURATION_MS = 12000;
CDoorManagement::CDoorManagement(CInputOutputManagerPtr ioPtr)
: QObject(nullptr)
, mIOManagerPtr(ioPtr)
, mOperationElapsedTimer()
, mDoorLockingTimer()
, mDebugMessages()
{
connect(&mDoorLockingTimer, SIGNAL(timeout()), this, SLOT(slotDoorLocking()), Qt::UniqueConnection);
}
void CDoorManagement::slotDoorLocking()
{
const auto elapsedTime = mOperationElapsedTimer.elapsed();
if (elapsedTime > I_DOOR_LOCKING_ALARM_DURATION_MS)
{
mDoorLockingTimer.stop();
mIOManagerPtr->setActuator(OUTPUT_DOOR_LOCKING_ACTUATOR, false);
mDebugMessages << QString("elapsed time = %1 ms - INPUT_DOOR_LOCKED_SENSOR=%2 - INPUT_DOOR_UNLOCKED_SENSOR=%3 - time = %4")
.arg(elapsedTime)
.arg(mIOManagerPtr->getTorInputState(INPUT_DOOR_LOCKED_SENSOR)?"true":"false")
.arg(mIOManagerPtr->getTorInputState(INPUT_DOOR_UNLOCKED_SENSOR)?"true":"false")
.arg(mOperationElapsedTimer.elapsed());
qDebug() << "door locking - mDebugMessage =" << mDebugMessages;
abort(QSTR_LOCKING_ABORTED);
}
if(mIOManagerPtr->getTorInputState(INPUT_DOOR_LOCKED_SENSOR))
{
mDoorLockingTimer.stop();
mIOManagerPtr->setActuator(OUTPUT_DOOR_LOCKING_ACTUATOR, false);
syslog(LOG_INFO, "%s::%s() - locked: elapsedTime = %lld, max time=%d",
LOG_PREFIX, __FUNCTION__, elapsedTime, I_DOOR_LOCKING_ALARM_DURATION_MS);
mDebugMessages << QString("elapsed time = %1 ms - INPUT_DOOR_LOCKED_SENSOR=%2 - INPUT_DOOR_UNLOCKED_SENSOR=%3 - time = %4")
.arg(elapsedTime)
.arg(mIOManagerPtr->getTorInputState(INPUT_DOOR_LOCKED_SENSOR)?"true":"false")
.arg(mIOManagerPtr->getTorInputState(INPUT_DOOR_UNLOCKED_SENSOR)?"true":"false")
.arg(mOperationElapsedTimer.elapsed());
qDebug() << "door locking - mDebugMessage =" << mDebugMessages;
emit signalDoorLocked();
}
else
{
mDebugMessages << QString("elapsed time = %1 ms - INPUT_DOOR_LOCKED_SENSOR=%2 - INPUT_DOOR_UNLOCKED_SENSOR=%3 - time = %4")
.arg(elapsedTime)
.arg(mIOManagerPtr->getTorInputState(INPUT_DOOR_LOCKED_SENSOR)?"true":"false")
.arg(mIOManagerPtr->getTorInputState(INPUT_DOOR_UNLOCKED_SENSOR)?"true":"false")
.arg(mOperationElapsedTimer.elapsed());
}
}
void CDoorManagement::startLocking()
{
mDebugMessages.clear();
qDebug() << "start of mDoorLockingTimer using " << I_DOOR_LOCKING_DURATION_MS << " ms delay";
mOperationElapsedTimer.start();
mDoorLockingTimer.start(I_DOOR_LOCKING_DURATION_MS);
if(!mIOManagerPtr->setActuator(OUTPUT_DOOR_LOCKING_ACTUATOR, true))
{
mIOManagerPtr->setActuator(OUTPUT_DOOR_LOCKING_ACTUATOR, false);
syslog(LOG_WARNING, "%s::%s() - failed to activate OUTPUT_DOOR_LOCKING_ACTUATOR", LOG_PREFIX, __FUNCTION__);
abort(QSTR_LOCKING_ACTIVATION_FAILURE);
}
}
I found the root cause of observed behavior: in example slot, I read a digital input and this reading requires 3 ms. in another slot, I read two RTD inputs and these readings require up to 2000 ms. the reading of digital and RTD inputs use the same library where there is a mutex to access the HW, either the access to digital or to RTD :(