StimBuff: Deferral: print message at start and end; timestamp too

commonLibs/attachmentSupport/stimulusBuffer.cpp

@@ -1,10 +1,12 @@
 #include <boostAsioLinkageFix.h>
-#include <iostream>
 #include <config.h>
-#include <componentThread.h>
+#include <iostream>
+#include <chrono>
 #include <boost/asio/io_service.hpp>
 #include <boost/asio/deadline_timer.hpp>
 #include <boost/system/error_code.hpp>
+#include <opts.h>
+#include <componentThread.h>
 #include <spinLock.h>
 #include <user/stimulusBuffer.h>
 
@@ -74,6 +76,21 @@ void StimulusBuffer::onTimeout(const boost::system::error_code& error)
 	{
 		nextWakeupDelayMs = CONFIG_STIMBUFF_FRAME_PERIOD_MS;
 
+		// Check if we're ending a deferral period
+		if (nDeferrals > 0)
+		{
+			auto deferralEndTime = std::chrono::high_resolution_clock::now();
+			auto duration = deferralEndTime - deferralStartTime;
+			auto durationMs = std::chrono::duration_cast<
+				std::chrono::milliseconds>(duration);
+
+			std::cout << __func__ << ": Deferral period ended. "
+				<< "Total deferrals: " << nDeferrals
+				<< ", Duration: " << durationMs.count() << "ms" << std::endl;
+
+			nDeferrals = 0;
+		}
+
 		/**	EXPLANATION:
 		 * Call the derived class's frame production handler
 		 * Note: The derived class's frame production handler (aka
@@ -86,15 +103,25 @@ void StimulusBuffer::onTimeout(const boost::system::error_code& error)
 	{
 		nextWakeupDelayMs = CONFIG_STIMBUFF_FRAME_RETRY_DELAY_MS;
 		deferred = true;
+
+		++nDeferrals;
+		// If this is first deferral, capture start stamp and print message
+		if (nDeferrals == 1)
+		{
+			deferralStartTime = std::chrono::high_resolution_clock::now();
+			std::cerr << __func__ << ": Deferral period beginning. "
+				"Configured deferral period: " << nextWakeupDelayMs << "ms"
+				<< std::endl;
+		}
 	}
 
-	// Schedule next timeout with the pre-determined duration
 	scheduleNextTimeout(nextWakeupDelayMs);
 
-	// We should be able to release the start/stop lock before printing here.
+	// FIXME: We should be able to release the start/stop lock at this point.
-	if (deferred)
+
+	if (deferred && OptionParser::getOptions().verbose)
 	{
-		std::cout << __func__ << ": Deferring frame by " << nextWakeupDelayMs
+		std::cerr << __func__ << ": Deferring frame by " << nextWakeupDelayMs
 			<< "ms due to rate limit." << std::endl;
 	}
 }

include/user/stimulusBuffer.h

@@ -9,6 +9,7 @@
 #include <mutex>
 #include <functional>
 #include <iostream>
+#include <chrono>
 #include <config.h>
 #include <boost/asio/io_service.hpp>
 #include <boost/asio/deadline_timer.hpp>
@@ -56,7 +57,8 @@ public:
 	: deviceAttachmentSpec(deviceAttachmentSpec),
 	ringBuffer(nSlots, ringBufferConstraints),
 	ioService(ioService_),
-	shouldContinue(false), timer(ioService)
+	shouldContinue(false), timer(ioService),
+	nDeferrals(0)
 	{}
 
 	virtual ~StimulusBuffer() = default;
@@ -74,6 +76,7 @@ public:
 			<< deviceAttachmentSpec->deviceSelector << std::endl;
 
 		shouldContinue = true;
+		nDeferrals = 0;
 		scheduleNextTimeout();
 	}
 
@@ -107,6 +110,8 @@ private:
 	SpinLock shouldContinueLock;
 	bool shouldContinue;
 	boost::asio::deadline_timer timer;
+	size_t nDeferrals;
+	std::chrono::high_resolution_clock::time_point deferralStartTime;
 
 	void scheduleNextTimeout(int delayMs = CONFIG_STIMBUFF_FRAME_PERIOD_MS);
 };