From 1f6c986a0cf6542e48fc7ef7ae4427b63c6a7989 Mon Sep 17 00:00:00 2001 From: Robin Mueller Date: Tue, 28 Mar 2023 14:59:31 +0200 Subject: [PATCH] add instrumentation code --- linux/ipcore/PapbVcInterface.cpp | 2 +- mission/tmtc/PersistentLogTmStoreTask.cpp | 8 +- mission/tmtc/PersistentSingleTmStoreTask.cpp | 18 +++- mission/tmtc/TmStoreTaskBase.cpp | 107 +++++++++++-------- mission/tmtc/TmStoreTaskBase.h | 3 + mission/tmtc/VirtualChannel.cpp | 8 +- mission/tmtc/VirtualChannelWithQueue.cpp | 10 +- 7 files changed, 89 insertions(+), 67 deletions(-) diff --git a/linux/ipcore/PapbVcInterface.cpp b/linux/ipcore/PapbVcInterface.cpp index 5d88de94..b7081f0f 100644 --- a/linux/ipcore/PapbVcInterface.cpp +++ b/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; diff --git a/mission/tmtc/PersistentLogTmStoreTask.cpp b/mission/tmtc/PersistentLogTmStoreTask.cpp index 906c7547..84886cf6 100644 --- a/mission/tmtc/PersistentLogTmStoreTask.cpp +++ b/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... diff --git a/mission/tmtc/PersistentSingleTmStoreTask.cpp b/mission/tmtc/PersistentSingleTmStoreTask.cpp index ec507a44..121df1b7 100644 --- a/mission/tmtc/PersistentSingleTmStoreTask.cpp +++ b/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; } } diff --git a/mission/tmtc/TmStoreTaskBase.cpp b/mission/tmtc/TmStoreTaskBase.cpp index ea1153ff..d0787535 100644 --- a/mission/tmtc/TmStoreTaskBase.cpp +++ b/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; +} diff --git a/mission/tmtc/TmStoreTaskBase.h b/mission/tmtc/TmStoreTaskBase.h index 149f0804..c75ac8e4 100644 --- a/mission/tmtc/TmStoreTaskBase.h +++ b/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. diff --git a/mission/tmtc/VirtualChannel.cpp b/mission/tmtc/VirtualChannel.cpp index 5724ae69..8e225674 100644 --- a/mission/tmtc/VirtualChannel.cpp +++ b/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; } diff --git a/mission/tmtc/VirtualChannelWithQueue.cpp b/mission/tmtc/VirtualChannelWithQueue.cpp index bfc74907..44a20031 100644 --- a/mission/tmtc/VirtualChannelWithQueue.cpp +++ b/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 {