bosch_bmi160: add debug logging for hanging SPI transactions
Bug: 29625330
Change-Id: I5a8d70f85e02ff2f32bc63dee190b8c3de725b07
diff --git a/firmware/src/drivers/bosch_bmi160/bosch_bmi160.c b/firmware/src/drivers/bosch_bmi160/bosch_bmi160.c
index a694187..6e21cb5 100644
--- a/firmware/src/drivers/bosch_bmi160/bosch_bmi160.c
+++ b/firmware/src/drivers/bosch_bmi160/bosch_bmi160.c
@@ -458,6 +458,7 @@
uint8_t *sensorTimeBuffer;
uint8_t *temperatureBuffer;
uint8_t txrxBuffer[SPI_BUF_SIZE];
+ uint32_t spiTimeoutTimerHandle;
// states
volatile uint8_t state; //task state, type enum SensorState, do NOT change this directly
@@ -487,9 +488,11 @@
// spi rw
struct SlabAllocator *mDataSlab;
uint16_t mWbufCnt;
- uint8_t mRegCnt;
+ uint8_t mRegCnt, mLastRegCnt;
uint8_t mRetryLeft;
bool spiInUse;
+ int spiBatches, spiCallbacks;
+ const char * spiSrc;
};
static uint32_t AccRates[] = {
@@ -741,6 +744,37 @@
T(mRegCnt)++;
}
+static void printDebug()
+{
+ int i;
+ int wbufCnt = 0;
+ // TODO (trevorbunker)
+ INFO_PRINT("stepPower\n");
+ INFO_PRINT("DEBUG: state = %" PRI_STATE "\n", getStateName(atomicReadByte(&(mTask.state))));
+ INFO_PRINT("DEBUG: interrupt_enable_0 = 0x%02x\n", mTask.interrupt_enable_0);
+ INFO_PRINT("DEBUG: interrupt_enable_2 = 0x%02x\n", mTask.interrupt_enable_2);
+ INFO_PRINT("DEBUG: spiInUse = %d\n", mTask.spiInUse);
+ INFO_PRINT("DEBUG: Int1 = %d\n", gpioGet(mTask.Int1));
+ INFO_PRINT("DEBUG: Int2 = %d\n", gpioGet(mTask.Int2));
+ INFO_PRINT("DEBUG: pending_int[0] = %d\n", mTask.pending_int[0]);
+ INFO_PRINT("DEBUG: pending_int[1] = %d\n", mTask.pending_int[1]);
+ INFO_PRINT("DEBUG: spiBatches = %d\n", mTask.spiBatches);
+ INFO_PRINT("DEBUG: spiCallbacks = %d\n", mTask.spiCallbacks);
+ INFO_PRINT("DEBUG: spiSrc = %s\n", mTask.spiSrc);
+ for (i = 0; i < mTask.mLastRegCnt; i++) {
+ INFO_PRINT("Request %d, reg addr 0x%02x, size %d, txBuf 0x%08x, rxBuf 0x%08x, delay %d\n",
+ i, (unsigned int)mTask.txrxBuffer[wbufCnt], (int)mTask.packets[i].size, (unsigned int)mTask.packets[i].txBuf,
+ (unsigned int)mTask.packets[i].rxBuf, (int)mTask.packets[i].delay);
+ wbufCnt += mTask.packets[i].size;
+ }
+}
+
+static void spiTimeoutCallback(uint32_t timerId, void *data)
+{
+ ERROR_PRINT("SPI transaction never returned\n");
+ printDebug();
+}
+
static void spiBatchTxRx(struct SpiMode *mode,
SpiCbkF callback, void *cookie, const char * src)
{
@@ -753,9 +787,24 @@
ERROR_PRINT("spiBatchTxRx too many packets!\n");
return;
}
+ if (T(spiInUse)) {
+ ERROR_PRINT("cannot call spiBatchTxRx when spi is already in use!\n");
+ return;
+ }
+ T(spiBatches)++;
T(spiInUse) = true;
- spiMasterRxTx(T(spiDev), T(cs), T(packets), T(mRegCnt), mode, callback, cookie);
+
+ mTask.spiTimeoutTimerHandle = timTimerSet(1000000000ull, 0, 50, spiTimeoutCallback, NULL, true);
+ if (!mTask.spiTimeoutTimerHandle)
+ ERROR_PRINT("Couldn't get a timer for the SPI timeout timer\n");
+
+ T(spiSrc) = src;
+ if (spiMasterRxTx(T(spiDev), T(cs), T(packets), T(mRegCnt), mode, callback, cookie) < 0) {
+ ERROR_PRINT("spiMasterRxTx failed!\n");
+ }
+
+ T(mLastRegCnt) = T(mRegCnt);
T(mRegCnt) = 0;
T(mWbufCnt) = 0;
}
@@ -792,6 +841,13 @@
static void sensorSpiCallback(void *cookie, int err)
{
mTask.spiInUse = false;
+ mTask.spiCallbacks++;
+
+ if (mTask.spiTimeoutTimerHandle) {
+ timTimerCancel(mTask.spiTimeoutTimerHandle);
+ mTask.spiTimeoutTimerHandle = 0;
+ }
+
if (!osEnqueuePrivateEvt(EVT_SPI_DONE, cookie, NULL, mTask.tid))
ERROR_PRINT("sensorSpiCallback: osEnqueuePrivateEvt() failed\n");
}
@@ -1191,6 +1247,8 @@
static bool stepPower(bool on, void *cookie)
{
+ printDebug();
+
TDECL();
if (trySwitchState(on ? SENSOR_POWERING_UP : SENSOR_POWERING_DOWN)) {
// if step counter is powered, no need to change actual config of step
@@ -1615,6 +1673,9 @@
}
mTask.stepCntSamplingTimerHandle = timTimerSet(sensorTimerLookupCommon(StepCntRates, stepCntRateTimerVals, rate),
0, 50, stepCntSamplingCallback, NULL, false);
+ if (!mTask.stepCntSamplingTimerHandle)
+ ERROR_PRINT("Couldn't get a timer for the step counter timer\n");
+
}
sensorSignalInternalEvt(mTask.sensors[STEPCNT].handle,
@@ -2296,7 +2357,7 @@
#endif
} else {
size = 0; // drop this batch
- ERROR_PRINT("Invalid fh_mode\n");
+ ERROR_PRINT("Invalid fh_mode %d\n", fh_mode);
}
}
@@ -3177,7 +3238,8 @@
// For some reason the first ID read will fail to get the
// correct value. need to retry a few times.
SET_STATE(SENSOR_BOOT);
- timTimerSet(100000000, 100, 100, sensorTimerCallback, NULL, true);
+ if (timTimerSet(100000000, 100, 100, sensorTimerCallback, NULL, true) == 0)
+ ERROR_PRINT("Couldn't get a timer to verify ID\n");
break;
} else {
SET_STATE(SENSOR_INITIALIZING);
@@ -3303,8 +3365,9 @@
if (mTask.active_poll_generation == mTask.poll_generation) {
// attach the generation number to event
- timTimerSet(kTimeSyncPeriodNs, 100, 100, timeSyncCallback,
- (void *)mTask.poll_generation, true);
+ if (timTimerSet(kTimeSyncPeriodNs, 100, 100, timeSyncCallback,
+ (void *)mTask.poll_generation, true) == 0)
+ ERROR_PRINT("Couldn't get a timer for time sync\n");
}
returnIdle = true;
@@ -3340,7 +3403,8 @@
// wait 100ms for sensor to boot
currTime = timGetTime();
if (currTime < 100000000ULL) {
- timTimerSet(100000000 - currTime, 100, 100, sensorTimerCallback, NULL, true);
+ if (timTimerSet(100000000 - currTime, 100, 100, sensorTimerCallback, NULL, true) == 0)
+ ERROR_PRINT("Couldn't get a timer for boot delay\n");
break;
}
/* We have already been powered on long enough - fall through */
@@ -3420,6 +3484,7 @@
T(cs) = GPIO_PB(12);
T(watermark) = 0;
+ T(spiSrc) = "xxx";
spiMasterRequest(BMI160_SPI_BUS_ID, &T(spiDev));
@@ -3656,12 +3721,19 @@
static void chunkedReadSpiCallback(void *cookie, int err) {
TASK = (_Task*) cookie;
+ if (T(spiTimeoutTimerHandle)) {
+ timTimerCancel(T(spiTimeoutTimerHandle));
+ T(spiTimeoutTimerHandle) = 0;
+ }
+
+ T(spiCallbacks)++;
T(spiInUse) = false;
DEBUG_PRINT_IF(err !=0 || GET_STATE() != SENSOR_INT_1_HANDLING,
"crcb,e:%d,s:%d", err, (int)GET_STATE());
bool int1 = gpioGet(T(Int1));
if (err != 0) {
- DEBUG_PRINT_IF(DBG_CHUNKED, "crd retry");
+ //DEBUG_PRINT_IF(DBG_CHUNKED, "crd retry");
+ INFO_PRINT("crd retry");
// read full fifo length to be safe
chunkedReadInit(0, FIFO_READ_SIZE);
return;
@@ -3679,6 +3751,7 @@
// real frame parse works properly
T(dataBuffer) = T(txrxBuffer);
T(xferCnt) = FIFO_READ_SIZE;
+ T(spiCallbacks)--;
sensorSpiCallback(cookie, err);
} else {
DEBUG_PRINT_IF(DBG_CHUNKED, "crd cont");
