RDKEMW-27275_prints

drm/AampDRMLicManager.cpp

@@ -37,6 +37,19 @@
 
 #include "AAMPAnomalyMessageType.h"
 #include "AuthTokenErrors.h"
+#include <chrono>
+#include <atomic>
+
+namespace
+{
+using WatermarkTimingClock = std::chrono::steady_clock;
+static std::atomic<unsigned long long> gWatermarkTimingId{0};
+
+static long long WatermarkElapsedUs(WatermarkTimingClock::time_point start, WatermarkTimingClock::time_point end)
+{
+	return std::chrono::duration_cast<std::chrono::microseconds>(end - start).count();
+}
+}
 
 #define SESSION_TOKEN_URL "http://localhost:50050/authService/getSessionToken"
 
@@ -123,13 +136,15 @@ AampDRMLicenseManager::AampDRMLicenseManager(int maxDrmSessions, PrivateInstance
     mLicensePrefetcher = new AampLicensePreFetcher(aampInstance);
     ContentSecurityManager::UseFireboltSDK(aampInstance->mConfig->IsConfigSet(eAAMPConfig_UseFireboltSDK));
     mLicensePrefetcher->Init();
+	mWatermarkWorker = std::thread(&AampDRMLicenseManager::WatermarkWorkerThread, this);
 }
 
 /**
  *  @brief AampDRMLicenseManager destructor
  */
 AampDRMLicenseManager::~AampDRMLicenseManager()
 {
+	StopWatermarkWorker();
 	SAFE_DELETE(mLicensePrefetcher);
 	SAFE_DELETE(mDrmSessionManager);
 	releaseLicenseRenewalThreads();
@@ -1420,28 +1435,159 @@ void AampDRMLicenseManager::QueueProtectionEvent(std::shared_ptr<DrmHelper> drmH
  */
 void AampDRMLicenseManager::setPlaybackSpeedState(bool live, double currentLatency, bool livepoint , double liveOffsetMs,int speed, double positionMs, bool firstFrameSeen)
 {
-	mDrmSessionManager->setPlaybackSpeedState(live, currentLatency, livepoint, liveOffsetMs, speed, positionMs, firstFrameSeen);
+	const auto callerStart = WatermarkTimingClock::now();
+	const auto timingId = ++gWatermarkTimingId;
+	auto task = [this, live, currentLatency, livepoint, liveOffsetMs, speed, positionMs, firstFrameSeen, callerStart, timingId]() {
+		const auto taskStart = WatermarkTimingClock::now();
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=setPlaybackSpeedState phase=task_start dispatch_delay_us=%lld",
+			timingId, WatermarkElapsedUs(callerStart, taskStart));
+		mDrmSessionManager->setPlaybackSpeedState(live, currentLatency, livepoint, liveOffsetMs, speed, positionMs, firstFrameSeen);
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=setPlaybackSpeedState phase=task_end operation_us=%lld",
+			timingId, WatermarkElapsedUs(taskStart, WatermarkTimingClock::now()));
+	};
+	const bool queued = EnqueueWatermarkTask(task);
+	if (!queued)
+	{
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=setPlaybackSpeedState phase=caller_fallback", timingId);
+		task();
+	}
+	MW_LOG_ERR("[WM_TIMING] id=%llu op=setPlaybackSpeedState phase=caller_return dispatch=%s caller_us=%lld",
+		timingId, queued ? "queued" : "fallback", WatermarkElapsedUs(callerStart, WatermarkTimingClock::now()));
 }
 
 /**
  * @brief De-activate watermark and prevent it from being re-enabled until we get a new first video frame at normal play speed
  */
 void AampDRMLicenseManager::hideWatermarkOnDetach(void)
 {
-	mDrmSessionManager->hideWatermarkOnDetach( );
+	const auto callerStart = WatermarkTimingClock::now();
+	const auto timingId = ++gWatermarkTimingId;
+	auto task = [this, callerStart, timingId]() {
+		const auto taskStart = WatermarkTimingClock::now();
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=hideWatermarkOnDetach phase=task_start dispatch_delay_us=%lld",
+			timingId, WatermarkElapsedUs(callerStart, taskStart));
+		mDrmSessionManager->hideWatermarkOnDetach();
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=hideWatermarkOnDetach phase=task_end operation_us=%lld",
+			timingId, WatermarkElapsedUs(taskStart, WatermarkTimingClock::now()));
+	};
+	const bool queued = EnqueueWatermarkTask(task);
+	if (!queued)
+	{
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=hideWatermarkOnDetach phase=caller_fallback", timingId);
+		task();
+	}
+	MW_LOG_ERR("[WM_TIMING] id=%llu op=hideWatermarkOnDetach phase=caller_return dispatch=%s caller_us=%lld",
+		timingId, queued ? "queued" : "fallback", WatermarkElapsedUs(callerStart, WatermarkTimingClock::now()));
 }
 
 /**
  * @brief Deactivate the session while video on mute and then activate it and update the speed once video is unmuted
  */
 void AampDRMLicenseManager::setVideoMute(bool live, double currentLatency, bool livepoint , double liveOffsetMs,bool isVideoOnMute, double positionMs)
 {
-	mDrmSessionManager->setVideoMute(live, currentLatency, livepoint, liveOffsetMs,isVideoOnMute, positionMs);
+	const auto callerStart = WatermarkTimingClock::now();
+	const auto timingId = ++gWatermarkTimingId;
+	auto task = [this, live, currentLatency, livepoint, liveOffsetMs, isVideoOnMute, positionMs, callerStart, timingId]() {
+		const auto taskStart = WatermarkTimingClock::now();
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=setVideoMute phase=task_start dispatch_delay_us=%lld",
+			timingId, WatermarkElapsedUs(callerStart, taskStart));
+		mDrmSessionManager->setVideoMute(live, currentLatency, livepoint, liveOffsetMs, isVideoOnMute, positionMs);
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=setVideoMute phase=task_end operation_us=%lld",
+			timingId, WatermarkElapsedUs(taskStart, WatermarkTimingClock::now()));
+	};
+	const bool queued = EnqueueWatermarkTask(task);
+	if (!queued)
+	{
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=setVideoMute phase=caller_fallback", timingId);
+		task();
+	}
+	MW_LOG_ERR("[WM_TIMING] id=%llu op=setVideoMute phase=caller_return dispatch=%s caller_us=%lld",
+		timingId, queued ? "queued" : "fallback", WatermarkElapsedUs(callerStart, WatermarkTimingClock::now()));
 }
 
 void AampDRMLicenseManager::setVideoWindowSize(int width, int height)
 {
-	mDrmSessionManager->setVideoWindowSize(width, height);
+	const auto callerStart = WatermarkTimingClock::now();
+	const auto timingId = ++gWatermarkTimingId;
+	auto task = [this, width, height, callerStart, timingId]() {
+		const auto taskStart = WatermarkTimingClock::now();
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=setVideoWindowSize phase=task_start dispatch_delay_us=%lld",
+			timingId, WatermarkElapsedUs(callerStart, taskStart));
+		mDrmSessionManager->setVideoWindowSize(width, height);
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=setVideoWindowSize phase=task_end operation_us=%lld",
+			timingId, WatermarkElapsedUs(taskStart, WatermarkTimingClock::now()));
+	};
+	const bool queued = EnqueueWatermarkTask(task);
+	if (!queued)
+	{
+		MW_LOG_ERR("[WM_TIMING] id=%llu op=setVideoWindowSize phase=caller_fallback", timingId);
+		task();
+	}
+	MW_LOG_ERR("[WM_TIMING] id=%llu op=setVideoWindowSize phase=caller_return dispatch=%s caller_us=%lld",
+		timingId, queued ? "queued" : "fallback", WatermarkElapsedUs(callerStart, WatermarkTimingClock::now()));
+}
+
+/**
+ * @brief Queue and process watermarking state updates serially away from caller threads.
+ */
+bool AampDRMLicenseManager::EnqueueWatermarkTask(std::function<void()> task)
+{
+	{
+		std::lock_guard<std::mutex> lock(mWatermarkTaskMutex);
+		if (mWatermarkWorkerStopping)
+		{
+			return false;
+		}
+		mWatermarkTaskQueue.emplace_back(std::move(task));
+	}
+	mWatermarkTaskCondition.notify_one();
+	return true;
+}
+
+void AampDRMLicenseManager::WatermarkWorkerThread()
+{
+	for (;;)
+	{
+		std::function<void()> task;
+		{
+			std::unique_lock<std::mutex> lock(mWatermarkTaskMutex);
+			mWatermarkTaskCondition.wait(lock, [this]() {
+				return mWatermarkWorkerStopping || !mWatermarkTaskQueue.empty();
+			});
+			if (mWatermarkTaskQueue.empty())
+			{
+				if (mWatermarkWorkerStopping)
+				{
+					return;
+				}
+				continue;
+			}
+			task = std::move(mWatermarkTaskQueue.front());
+			mWatermarkTaskQueue.pop_front();
+		}
+
+		try
+		{
+			task();
+		}
+		catch (...)
+		{
+			MW_LOG_ERR("Watermark worker task threw an exception");
+		}
+	}
+}
+
+void AampDRMLicenseManager::StopWatermarkWorker()
+{
+	{
+		std::lock_guard<std::mutex> lock(mWatermarkTaskMutex);
+		mWatermarkWorkerStopping = true;
+	}
+	mWatermarkTaskCondition.notify_all();
+	if (mWatermarkWorker.joinable())
+	{
+		mWatermarkWorker.join();
+	}
 }
 
 /**

drm/AampDRMLicManager.h

@@ -30,6 +30,11 @@
 #include "DrmSession.h"
 #include "AampCurlDownloader.h"
 #include "DrmSessionManager.h"
+#include <condition_variable>
+#include <deque>
+#include <functional>
+#include <mutex>
+#include <thread>
 
 enum ProfilerAction
 {
@@ -344,4 +349,15 @@ class AampDRMLicenseManager
 		const unsigned char* contentMetadataPtr = nullptr, bool isPrimarySession = false);
 
 	AAMPTuneFailure MapDrmToAampTuneFailure(DrmTuneFailure drmError);
+
+private:
+	void WatermarkWorkerThread();
+	void EnqueueWatermarkTask(const char *operation, std::function<void()> task);
+	void StopWatermarkWorker();
+
+	std::mutex mWatermarkTaskMutex;
+	std::condition_variable mWatermarkTaskCondition;
+	std::deque<std::function<void()>> mWatermarkTaskQueue;
+	bool mWatermarkWorkerStopping{false};
+	std::thread mWatermarkWorker;
 };

middleware/drm/DrmSessionManager.cpp

@@ -30,13 +30,22 @@
 #include <inttypes.h>
 #include "PlayerUtils.h"
 #include "ContentSecurityManager.h"
+#include <chrono>
 #define DRM_METADATA_TAG_START "<ckm:policy xmlns:ckm=\"urn:ccp:ckm\">"
 #define DRM_METADATA_TAG_END "</ckm:policy>"
 #define SESSION_TOKEN_URL "http://localhost:50050/authService/getSessionToken"
 
 #define INVALID_SESSION_SLOT -1
 #define DEFAULT_CDM_WAIT_TIMEOUT_MS 2000
 
+namespace
+{
+static long long SecurityManagerElapsedUs(std::chrono::steady_clock::time_point start, std::chrono::steady_clock::time_point end)
+{
+	return std::chrono::duration_cast<std::chrono::microseconds>(end - start).count();
+}
+}
+
 /**
  * @brief KeyIdEntries constructor.
  */
@@ -221,7 +230,10 @@ void DrmSessionManager::setVideoWindowSize(int width, int height)
 	if(localSession.isSessionValid())
 	{
 		MW_LOG_WARN("In DrmSessionManager:: valid session ID. Calling setVideoWindowSize().");
-		ContentSecurityManager::GetInstance()->setVideoWindowSize(localSession.getSessionID(), width, height);
+		auto apiStart = std::chrono::steady_clock::now();
+		bool result = ContentSecurityManager::GetInstance()->setVideoWindowSize(localSession.getSessionID(), width, height);
+		MW_LOG_ERR("[WM_TIMING] op=setVideoWindowSize phase=api_end api_us=%lld result=%d",
+			SecurityManagerElapsedUs(apiStart, std::chrono::steady_clock::now()), result);
 	}
 }
 /**
@@ -235,7 +247,10 @@ void DrmSessionManager::setVideoMute(bool live, double currentLatency, bool live
 	auto localSession = mContentSecurityManagerSession; //Remove potential isSessionValid(), getSessionID() race by using a local copy
 	if(localSession.isSessionValid())
 	{
-		ContentSecurityManager::GetInstance()->UpdateSessionState(localSession.getSessionID(), !mIsVideoOnMute.load());
+		auto apiStart = std::chrono::steady_clock::now();
+		bool result = ContentSecurityManager::GetInstance()->UpdateSessionState(localSession.getSessionID(), !mIsVideoOnMute.load());
+		MW_LOG_ERR("[WM_TIMING] op=setVideoMute.UpdateSessionState phase=api_end api_us=%lld result=%d",
+			SecurityManagerElapsedUs(apiStart, std::chrono::steady_clock::now()), result);
 		if(!mIsVideoOnMute.load())
 		{
 			//this is required as secmanager waits for speed update to show wm once session is active
@@ -255,7 +270,10 @@ void DrmSessionManager::hideWatermarkOnDetach(void)
 	auto localSession = mContentSecurityManagerSession; //Remove potential isSessionValid(), getSessionID() race by using a local copy
 	if(localSession.isSessionValid())
 	{
-		ContentSecurityManager::GetInstance()->UpdateSessionState(localSession.getSessionID(), false);
+		auto apiStart = std::chrono::steady_clock::now();
+		bool result = ContentSecurityManager::GetInstance()->UpdateSessionState(localSession.getSessionID(), false);
+		MW_LOG_ERR("[WM_TIMING] op=hideWatermarkOnDetach.UpdateSessionState phase=api_end api_us=%lld result=%d",
+			SecurityManagerElapsedUs(apiStart, std::chrono::steady_clock::now()), result);
 	}
 	mFirstFrameSeen.store(false);
 }
@@ -297,7 +315,10 @@ void DrmSessionManager::setPlaybackSpeedState(bool live, double currentLatency,
 		}
 
 		MW_LOG_INFO("setPlaybackSpeedState pos=%fs speed=%d", adjustedPos/1000, speed );
-		ContentSecurityManager::GetInstance()->setPlaybackSpeedState(localSession.getSessionID(), speed, adjustedPos);
+		auto apiStart = std::chrono::steady_clock::now();
+		bool result = ContentSecurityManager::GetInstance()->setPlaybackSpeedState(localSession.getSessionID(), speed, adjustedPos);
+		MW_LOG_ERR("[WM_TIMING] op=setPlaybackSpeedState phase=api_end api_us=%lld result=%d",
+			SecurityManagerElapsedUs(apiStart, std::chrono::steady_clock::now()), result);
 	}
 	else
 	{