VPLAY-12472 [CSAT][AAMP] Add logging for buffering start/end and buffering duration (#1160)

* VPLAY-12472 [CSAT][AAMP] Add logging for buffering start/end and buffering duration

Reason for change: Added buffering duration in the telementary along with buffer start and end
Risks: Low
Test Procedure: Refer jira ticket
Priority: P1

Signed-off-by: lashminthaj <lashminthaj17@gmail.com>
---------

Signed-off-by: lashminthaj <lashminthaj17@gmail.com>
Signed-off-by: Philip Stroffolino <philip_stroffolino@cable.comcast.com>
Co-authored-by: pstroffolino <Philip_Stroffolino@cable.comcast.com>
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>

Author: 3 people

priv_aamp.cpp

@@ -1635,7 +1635,7 @@ int PrivateInstanceAAMP::HandleSSLProgressCallback ( void *clientp, double dltot
 /**
  * @brief PrivateInstanceAAMP Constructor
  */
-PrivateInstanceAAMP::PrivateInstanceAAMP(AampConfig *config) : mReportProgressPosn(0.0), mLastTelemetryTimeMS(0), mDiscontinuityFound(false), mTelemetryInterval(0), mLock(),
+PrivateInstanceAAMP::PrivateInstanceAAMP(AampConfig *config) : mReportProgressPosn(0.0), mLastTelemetryTimeMS(0), mBufferingStartTimeMS(-1), mDiscontinuityFound(false), mTelemetryInterval(0), mLock(),
 	mpStreamAbstractionAAMP(NULL), mInitSuccess(false), mVideoFormat(FORMAT_INVALID), mAudioFormat(FORMAT_INVALID), mDownloadsDisabled(),
 	mDownloadsEnabled(true), profiler(), licenceFromManifest(false), previousAudioType(eAUDIO_UNKNOWN),isPreferredDRMConfigured(false),
 	mbDownloadsBlocked(false), streamerIsActive(false), mFogTSBEnabled(false), mIscDVR(false), mLiveOffset(AAMP_LIVE_OFFSET),
@@ -3246,11 +3246,42 @@ void PrivateInstanceAAMP::SendBufferChangeEvent(bool bufferingStopped)
 	BufferingChangedEventPtr e = std::make_shared<BufferingChangedEvent>(!bufferingStopped, GetSessionId());
 
 	SetBufUnderFlowStatus(bufferingStopped);
-	AAMPLOG_INFO("PrivateInstanceAAMP: Sending Buffer Change event status (Buffering): %s", (e->buffering() ? "End": "Start"));
+	// Calculating the duration for which buffering was happening and sending it as part of telemetry.
+	// This will help in understanding the buffering duration for each buffering event and also help in calculating the total buffering duration for a session.
+	long long bufferingDurationMs = 0;
+	if (bufferingStopped)
+	{
+		// Atomically set the start time only if no episode is already being tracked (-1).
+		// compare_exchange_strong ensures that concurrent SendBufferChangeEvent(true) calls
+		// from different threads (underflow monitor, GStreamer error path) cannot both "win"
+		// and reset the clock. Uses the monotonic steady clock to be immune to NTP jumps.
+		long long expected = -1LL;
+		mBufferingStartTimeMS.compare_exchange_strong(expected, NOW_STEADY_TS_MS);
+	}
+	else
+	{
+		// Atomically swap to -1 and capture the previous start time in one operation.
+		// This prevents two concurrent SendBufferChangeEvent(false) calls from both
+		// observing a valid start time and both computing (and reporting) a duration.
+		long long startTime = mBufferingStartTimeMS.exchange(-1LL);
+		if (startTime >= 0)
+		{
+			bufferingDurationMs = NOW_STEADY_TS_MS - startTime;
+			// Clamp to 0 as a safety net (should not happen with a monotonic clock).
+			if (bufferingDurationMs < 0)
+			{
+				bufferingDurationMs = 0;
+			}
+		}
+	}
+
+	AAMPLOG_INFO("PrivateInstanceAAMP: Sending Buffer Change event status (Buffering): %s durationMs: %lld", (e->buffering() ? "End": "Start"), bufferingDurationMs);
 #ifdef AAMP_TELEMETRY_SUPPORT
 	AAMPTelemetry2 at2(mAppName);
 	std::string telemetryName = bufferingStopped?"VideoBufferingStart":"VideoBufferingEnd";
-	at2.send(telemetryName,{/*int data*/},{/*string data*/},{/*float data*/});
+	std::map<std::string,int> intData;
+	intData["dur"] = static_cast<int>(bufferingDurationMs);
+	at2.send(telemetryName, intData, {/*string data*/}, {/*float data*/});
 #endif //AAMP_TELEMETRY_SUPPORT
 	SendEvent(e,AAMP_EVENT_ASYNC_MODE);
 

priv_aamp.h

@@ -586,6 +586,13 @@ class PrivateInstanceAAMP : public DrmCallbacks, public std::enable_shared_from_
 	//The position previously reported by MonitorProgress() (i.e. the position really sent, using SendEvent())
 	double mReportProgressPosn;
 	long long mLastTelemetryTimeMS;
+	// The time when buffering started (steady clock ms), used to calculate buffering duration
+	// for telemetry. -1 means no episode is in progress. Declared atomic because
+	// SendBufferChangeEvent() is reached concurrently from the underflow monitor thread and
+	// from GStreamer error callbacks (via ScheduleRetune), with no common lock held at the
+	// call site. The compound check-and-set operations in SendBufferChangeEvent use
+	// compare_exchange_strong / exchange to keep the read-modify-write sequences race-free.
+	std::atomic<long long> mBufferingStartTimeMS;
 	std::chrono::system_clock::time_point m_lastSubClockSyncTime;
 	std::shared_ptr<TSB::Store> mTSBStore; /**< Local TSB Store object */
 	void SanitizeLanguageList(std::vector<std::string>& languages) const;
@@ -1579,6 +1586,9 @@ class PrivateInstanceAAMP : public DrmCallbacks, public std::enable_shared_from_
 	bool GetBufUnderFlowStatus() { return mBufUnderFlowStatus.load(); }
 	void SetBufUnderFlowStatus(bool statusFlag) { mBufUnderFlowStatus.store(statusFlag); }
 	void ResetBufUnderFlowStatus() { mBufUnderFlowStatus.store(false);}
+	/** Returns the steady-clock timestamp (ms) at which the current buffering episode began,
+	 *  or -1 if no episode is in progress. Exposed for unit testing. */
+	long long GetBufferingStartTimeMS() const { return mBufferingStartTimeMS.load(); }
 
 	/**
 	 * @fn SendEvent

test/utests/tests/PrivAampTests/PrivAampTests.cpp

@@ -21,13 +21,15 @@
 #include <iostream>
 #include <string>
 #include <string.h>
+#include <thread>
 #include <type_traits>
 
 #include <gtest/gtest.h>
 #include <gmock/gmock.h>
 
 #include "priv_aamp.h"
 #include "AampProfiler.h"
+#include "AampUtils.h"
 
 #include "MockPrivateInstanceAAMP.h"
 #include "main_aamp.h"
@@ -1716,14 +1718,118 @@ TEST_F(PrivAampTests,UpdateRefreshPlaylistIntervalTest)
 	p_aamp->UpdateRefreshPlaylistInterval(-12.43265);
 }
 
-TEST_F(PrivAampTests,SendBufferChangeEventTest)
+// --- Buffering duration tracking tests ---
+
+// mBufferingStartTimeMS is initialised to -1 in the constructor; no episode in flight yet.
+TEST_F(PrivAampTests, SendBufferChangeEvent_InitialTimestampIsUnset)
+{
+	EXPECT_EQ(p_aamp->GetBufferingStartTimeMS(), -1LL);
+}
+
+// Start event must capture a plausible steady-clock timestamp (>= before, <= after).
+TEST_F(PrivAampTests, SendBufferChangeEvent_StartSetsTimestamp)
+{
+	long long beforeMs = NOW_STEADY_TS_MS;
+	p_aamp->SendBufferChangeEvent(true);
+	long long afterMs = NOW_STEADY_TS_MS;
+
+	long long recorded = p_aamp->GetBufferingStartTimeMS();
+	EXPECT_GE(recorded, beforeMs);
+	EXPECT_LE(recorded, afterMs);
+}
+
+// End event must reset mBufferingStartTimeMS back to -1.
+TEST_F(PrivAampTests, SendBufferChangeEvent_EndResetsTimestamp)
+{
+	p_aamp->SendBufferChangeEvent(true);
+	EXPECT_GE(p_aamp->GetBufferingStartTimeMS(), 0LL);
+
+	p_aamp->SendBufferChangeEvent(false);
+	EXPECT_EQ(p_aamp->GetBufferingStartTimeMS(), -1LL);
+}
+
+// End call without a preceding start is a no-op: no crash, state stays -1.
+TEST_F(PrivAampTests, SendBufferChangeEvent_EndWithoutStartIsNoOp)
+{
+	ASSERT_EQ(p_aamp->GetBufferingStartTimeMS(), -1LL);
+	p_aamp->SendBufferChangeEvent(false);
+	EXPECT_EQ(p_aamp->GetBufferingStartTimeMS(), -1LL);
+}
+
+// Duplicate start events must not reset the timestamp; only the first call wins.
+// Verified by sleeping briefly so a second capture would produce a strictly later value.
+TEST_F(PrivAampTests, SendBufferChangeEvent_DuplicateStartDoesNotResetTimestamp)
+{
+	p_aamp->SendBufferChangeEvent(true);
+	long long firstTimestamp = p_aamp->GetBufferingStartTimeMS();
+	ASSERT_GE(firstTimestamp, 0LL);
+
+	std::this_thread::sleep_for(std::chrono::milliseconds(5));
+	p_aamp->SendBufferChangeEvent(true);
+
+	EXPECT_EQ(p_aamp->GetBufferingStartTimeMS(), firstTimestamp);
+}
+
+// The duration that would be reported to telemetry is bounded by the elapsed real time.
+// We verify this indirectly: capture the steady-clock window around the end call and
+// confirm it brackets (end_clock - startTime), then confirm the episode is closed out.
+TEST_F(PrivAampTests, SendBufferChangeEvent_DurationBoundedByElapsedRealTime)
+{
+	p_aamp->SendBufferChangeEvent(true);
+	long long startTime = p_aamp->GetBufferingStartTimeMS();
+	ASSERT_GE(startTime, 0LL);
+
+	std::this_thread::sleep_for(std::chrono::milliseconds(5));
+
+	long long beforeEnd = NOW_STEADY_TS_MS;
+	p_aamp->SendBufferChangeEvent(false);
+	long long afterEnd  = NOW_STEADY_TS_MS;
+
+	// The internal duration = (steady_clock at end) - startTime.
+	// It must be >= (beforeEnd - startTime) and <= (afterEnd - startTime).
+	long long minDuration = beforeEnd - startTime;
+	long long maxDuration = afterEnd  - startTime;
+	EXPECT_GE(minDuration, 0LL);
+	EXPECT_LE(minDuration, maxDuration);
+
+	// Episode must be closed out.
+	EXPECT_EQ(p_aamp->GetBufferingStartTimeMS(), -1LL);
+}
+
+// BufUnderFlowStatus flag must follow start/end transitions.
+TEST_F(PrivAampTests, SendBufferChangeEvent_UnderflowStatusTracksTransitions)
 {
+	EXPECT_FALSE(p_aamp->GetBufUnderFlowStatus());
+
 	p_aamp->SendBufferChangeEvent(true);
+	EXPECT_TRUE(p_aamp->GetBufUnderFlowStatus());
+
+	p_aamp->SendBufferChangeEvent(false);
+	EXPECT_FALSE(p_aamp->GetBufUnderFlowStatus());
 }
 
-TEST_F(PrivAampTests,SendBufferChangeEventTest_1)
+// Back-to-back episodes must each be tracked independently: the second start time
+// must be strictly later than the first (monotonic clock), and each episode closes cleanly.
+TEST_F(PrivAampTests, SendBufferChangeEvent_SequentialEpisodesTrackedIndependently)
 {
+	// First episode
+	p_aamp->SendBufferChangeEvent(true);
+	long long t1 = p_aamp->GetBufferingStartTimeMS();
+	ASSERT_GE(t1, 0LL);
+
+	std::this_thread::sleep_for(std::chrono::milliseconds(2));
+	p_aamp->SendBufferChangeEvent(false);
+	EXPECT_EQ(p_aamp->GetBufferingStartTimeMS(), -1LL);
+
+	// Second episode
+	std::this_thread::sleep_for(std::chrono::milliseconds(2));
+	p_aamp->SendBufferChangeEvent(true);
+	long long t2 = p_aamp->GetBufferingStartTimeMS();
+	ASSERT_GE(t2, 0LL);
+	EXPECT_GT(t2, t1); // monotonic: second start must be later than first
+
 	p_aamp->SendBufferChangeEvent(false);
+	EXPECT_EQ(p_aamp->GetBufferingStartTimeMS(), -1LL);
 }
 
 TEST_F(PrivAampTests,PausePipelineTest)