add instrumentation code

linux/ipcore/PapbVcInterface.cpp

@@ -80,7 +80,7 @@ ReturnValue_t PapbVcInterface::pollPapbBusySignal(uint32_t maxPollRetries) const
     // Ignore signal handling here for now.
     nanosleep(&nextDelay, &remDelay);
     // Adaptive delay.
-    if(nextDelay.tv_nsec == 0) {
+    if (nextDelay.tv_nsec == 0) {
       nextDelay.tv_nsec = FIRST_NON_NULL_DELAY_NS;
     } else if (nextDelay.tv_nsec * 2 <= MAX_DELAY_PAPB_POLLING_NS) {
       nextDelay.tv_nsec *= 2;

mission/tmtc/PersistentLogTmStoreTask.cpp

@@ -23,10 +23,10 @@ ReturnValue_t PersistentLogTmStoreTask::performOperation(uint8_t opCode) {
     if (fileHasSwapped) {
       someFileWasSwapped = fileHasSwapped;
     }
-    if(ctx.vcBusyDuringDump) {
+    if (ctx.vcBusyDuringDump) {
       vcBusyDuringDump = true;
     }
-    if(ctx.dumpedBytes - ctx.bytesDumpedAtLastDelay >= 2048) {
+    if (ctx.dumpedBytes - ctx.bytesDumpedAtLastDelay >= 2048) {
       byteFlowControl = true;
       ctx.bytesDumpedAtLastDelay = ctx.dumpedBytes;
     }
@@ -45,9 +45,9 @@ ReturnValue_t PersistentLogTmStoreTask::performOperation(uint8_t opCode) {
       TaskFactory::delayTask(100);
     } else if (someFileWasSwapped) {
       TaskFactory::delayTask(20);
-    } else if(vcBusyDuringDump) {
+    } else if (vcBusyDuringDump) {
       TaskFactory::delayTask(20);
-    } else if(byteFlowControl) {
+    } else if (byteFlowControl) {
       TaskFactory::delayTask(10);
     } else {
       // TODO: Lower this as much as possible...

mission/tmtc/PersistentSingleTmStoreTask.cpp

@@ -12,6 +12,10 @@ PersistentSingleTmStoreTask::PersistentSingleTmStoreTask(
 
 ReturnValue_t PersistentSingleTmStoreTask::performOperation(uint8_t opCode) {
   ReturnValue_t result = returnvalue::OK;
+  uint32_t delaysVcBusyDuringDump = 0;
+  uint32_t delaysFlowControl = 0;
+  uint32_t delayNotBusy = 0;
+  uint32_t delayHotLoop = 0;
   while (true) {
     // Delay done by the check
     if (not cyclicStoreCheck()) {
@@ -20,17 +24,27 @@ ReturnValue_t PersistentSingleTmStoreTask::performOperation(uint8_t opCode) {
     bool busy = handleOneStore(storeWithQueue, dumpContext);
     if (not busy) {
       result = TaskFactory::delayTask(100);
+      delayNotBusy++;
     } else if (dumpContext.vcBusyDuringDump) {
+      delaysVcBusyDuringDump++;
       result = TaskFactory::delayTask(10);
     } else if (dumpContext.packetWasDumped and
                dumpContext.dumpedBytes - dumpContext.bytesDumpedAtLastDelay >= 2048) {
       dumpContext.bytesDumpedAtLastDelay = dumpContext.dumpedBytes;
       result = TaskFactory::delayTask(10);
+      delaysFlowControl++;
     } else {
       // TODO: Lower this as much as possible...
-      result = TaskFactory::delayTask(10);
+      result = TaskFactory::delayTask(5);
+      delayHotLoop++;
     }
-    if(result != returnvalue::OK) {
+    if ((delaysVcBusyDuringDump + delaysFlowControl + delayNotBusy + delayHotLoop) % 2000000 == 0) {
+      sif::debug << "DLY NBUSY: " << delayNotBusy << std::endl;
+      sif::debug << "DLY FLCTRL: " << delaysFlowControl << std::endl;
+      sif::debug << "DLY BUSYDUMP: " << delaysVcBusyDuringDump << std::endl;
+      sif::debug << "DLY HOTLOOP: " << delayHotLoop << std::endl;
+    }
+    if (result != returnvalue::OK) {
       sif::warning << "TmStoreTask: Delay failed" << std::endl;
     }
   }

mission/tmtc/TmStoreTaskBase.cpp

@@ -16,7 +16,7 @@ bool TmStoreTaskBase::handleOneStore(PersistentTmStoreWithTmQueue& store,
   ReturnValue_t result;
   bool tmToStoreReceived = false;
   bool tcRequestReceived = false;
-  bool dumpsPerformed = false;
+  bool dumpPerformed = false;
   fileHasSwapped = false;
   dumpContext.packetWasDumped = false;
   dumpContext.vcBusyDuringDump = false;
@@ -28,50 +28,8 @@ bool TmStoreTaskBase::handleOneStore(PersistentTmStoreWithTmQueue& store,
   }
   // Dump TMs when applicable
   if (store.getState() == PersistentTmStore::State::DUMPING) {
-    // The PTME might have been reset an transmitter state change, so there is
-    // not point in continuing the dump.
-    if(not channel.isTxOn()) {
-      cancelDump(dumpContext, store, false);
-      return returnvalue::OK;
-    }
-    size_t dumpedLen = 0;
-    if (not channel.isBusy()) {
-      dumpContext.ptmeBusyCounter = 0;
-      tmSinkBusyCd.resetTimer();
-      result = store.dumpNextPacket(channel, dumpedLen, fileHasSwapped);
-      if (result == DirectTmSinkIF::IS_BUSY) {
-        sif::warning << "Unexpected PAPB busy" << std::endl;
-      }
-      if ((result == PersistentTmStore::DUMP_DONE or result == returnvalue::OK) and dumpedLen > 0) {
-        dumpContext.dumpedBytes += dumpedLen;
-        dumpContext.numberOfDumpedPackets += 1;
-        dumpContext.packetWasDumped = true;
-      }
-      if (result == PersistentTmStore::DUMP_DONE) {
-        uint32_t startTime;
-        uint32_t endTime;
-        store.getStartAndEndTimeCurrentOrLastDump(startTime, endTime);
-        triggerEvent(dumpContext.eventIfDone, dumpContext.numberOfDumpedPackets,
-                     dumpContext.dumpedBytes);
-        dumpContext.reset();
-        dumpsPerformed = true;
-      } else if (result == returnvalue::OK) {
-        dumpsPerformed = true;
-      }
-    } else {
-      dumpContext.vcBusyDuringDump = true;
-      dumpContext.ptmeBusyCounter++;
-      if (dumpContext.ptmeBusyCounter == 100) {
-        // If this happens, something is probably wrong.
-        sif::warning << "PTME busy for longer period. Dumped length so far: "
-                     << dumpContext.dumpedBytes << std::endl;
-        triggerEvent(persTmStore::DUMP_WAS_CANCELLED, store.getObjectId());
-        cancelDump(dumpContext, store, channel.isTxOn());
-      }
-    }
-    if (cancelDumpCd.hasTimedOut() or tmSinkBusyCd.hasTimedOut()) {
-      triggerEvent(persTmStore::DUMP_WAS_CANCELLED, store.getObjectId());
-      cancelDump(dumpContext, store, channel.isTxOn());
+    if (handleOneDump(store, dumpContext, dumpPerformed) != returnvalue::OK) {
+      return result;
     }
   } else {
     Command_t execCmd;
@@ -86,7 +44,7 @@ bool TmStoreTaskBase::handleOneStore(PersistentTmStoreWithTmQueue& store,
       tcRequestReceived = true;
     }
   }
-  if (tcRequestReceived or tmToStoreReceived or dumpsPerformed) {
+  if (tcRequestReceived or tmToStoreReceived or dumpPerformed) {
     return true;
   }
   return false;
@@ -114,7 +72,62 @@ bool TmStoreTaskBase::cyclicStoreCheck() {
 void TmStoreTaskBase::cancelDump(DumpContext& ctx, PersistentTmStore& store, bool isTxOn) {
   ctx.reset();
   store.cancelDump();
-  if(isTxOn) {
+  if (isTxOn) {
     channel.cancelTransfer();
   }
 }
+
+ReturnValue_t TmStoreTaskBase::handleOneDump(PersistentTmStoreWithTmQueue& store,
+                                             DumpContext& dumpContext, bool& dumpPerformed) {
+  ReturnValue_t result = returnvalue::OK;
+  // The PTME might have been reset an transmitter state change, so there is
+  // not point in continuing the dump.
+  if (not channel.isTxOn()) {
+    cancelDump(dumpContext, store, false);
+    return returnvalue::FAILED;
+  }
+  size_t dumpedLen = 0;
+  if (not channel.isBusy()) {
+    // Dump the next packet into the PTME.
+    dumpContext.ptmeBusyCounter = 0;
+    tmSinkBusyCd.resetTimer();
+    result = store.dumpNextPacket(channel, dumpedLen, fileHasSwapped);
+    if (result == DirectTmSinkIF::IS_BUSY) {
+      sif::warning << "Unexpected PAPB busy" << std::endl;
+    }
+    if ((result == PersistentTmStore::DUMP_DONE or result == returnvalue::OK)) {
+      dumpPerformed = true;
+      if (dumpedLen > 0) {
+        dumpContext.dumpedBytes += dumpedLen;
+        dumpContext.numberOfDumpedPackets += 1;
+        dumpContext.packetWasDumped = true;
+      }
+    }
+    if (result == PersistentTmStore::DUMP_DONE) {
+      uint32_t startTime;
+      uint32_t endTime;
+      store.getStartAndEndTimeCurrentOrLastDump(startTime, endTime);
+      triggerEvent(dumpContext.eventIfDone, dumpContext.numberOfDumpedPackets,
+                   dumpContext.dumpedBytes);
+      dumpContext.reset();
+    }
+  } else {
+    // The PTME might be at full load, so it might sense to delay for a bit to let it do
+    // its work until some more bandwidth is available. Set a flag here so the upper layer can
+    // do ths.
+    dumpContext.vcBusyDuringDump = true;
+    dumpContext.ptmeBusyCounter++;
+    if (dumpContext.ptmeBusyCounter == 100) {
+      // If this happens, something is probably wrong.
+      sif::warning << "PTME busy for longer period. Dumped length so far: "
+                   << dumpContext.dumpedBytes << std::endl;
+      triggerEvent(persTmStore::DUMP_WAS_CANCELLED, store.getObjectId());
+      cancelDump(dumpContext, store, channel.isTxOn());
+    }
+  }
+  if (cancelDumpCd.hasTimedOut() or tmSinkBusyCd.hasTimedOut()) {
+    triggerEvent(persTmStore::DUMP_WAS_CANCELLED, store.getObjectId());
+    cancelDump(dumpContext, store, channel.isTxOn());
+  }
+  return result;
+}

mission/tmtc/TmStoreTaskBase.h

@@ -37,6 +37,9 @@ class TmStoreTaskBase : public SystemObject {
    */
   bool handleOneStore(PersistentTmStoreWithTmQueue& store, DumpContext& dumpContext);
 
+  ReturnValue_t handleOneDump(PersistentTmStoreWithTmQueue& store, DumpContext& dumpContext,
+                              bool& dumpPerformed);
+
   /**
    * Occasionally check whether SD card is okay to be used. If not, poll whether it is ready to
    * be used again and re-initialize stores. Returns whether store is okay to be used.

mission/tmtc/VirtualChannel.cpp

@@ -29,10 +29,6 @@ bool VirtualChannel::isBusy() const {
   return ptme.isBusy(vcId);
 }
 
-void VirtualChannel::cancelTransfer() {
-  ptme.cancelTransfer(vcId);
-}
+void VirtualChannel::cancelTransfer() { ptme.cancelTransfer(vcId); }
 
-bool VirtualChannel::isTxOn() const {
-  return txOn;
-}
+bool VirtualChannel::isTxOn() const { return txOn; }

mission/tmtc/VirtualChannelWithQueue.cpp

@@ -37,14 +37,10 @@ ReturnValue_t VirtualChannelWithQueue::sendNextTm() {
   }
 
   result = write(data, size);
-  if (result != returnvalue::OK) {
-    return result;
-  }
+  // Try delete in any case, ignore failures (which should not happen), it is more important to
+  // propagate write errors.
   tmStore.deleteData(storeId);
-  if (result != returnvalue::OK) {
-    return result;
-  }
-  return returnvalue::OK;
+  return result;
 }
 
 MessageQueueId_t VirtualChannelWithQueue::getReportReceptionQueue(uint8_t virtualChannel) const {