diff --git a/drm/AampDRMLicManager.cpp b/drm/AampDRMLicManager.cpp index 2c2c77e3ee..c0712cf54c 100644 --- a/drm/AampDRMLicManager.cpp +++ b/drm/AampDRMLicManager.cpp @@ -37,6 +37,19 @@ #include "AAMPAnomalyMessageType.h" #include "AuthTokenErrors.h" +#include +#include + +namespace +{ +using WatermarkTimingClock = std::chrono::steady_clock; +static std::atomic gWatermarkTimingId{0}; + +static long long WatermarkElapsedUs(WatermarkTimingClock::time_point start, WatermarkTimingClock::time_point end) +{ + return std::chrono::duration_cast(end - start).count(); +} +} #define SESSION_TOKEN_URL "http://localhost:50050/authService/getSessionToken" @@ -123,6 +136,7 @@ AampDRMLicenseManager::AampDRMLicenseManager(int maxDrmSessions, PrivateInstance mLicensePrefetcher = new AampLicensePreFetcher(aampInstance); ContentSecurityManager::UseFireboltSDK(aampInstance->mConfig->IsConfigSet(eAAMPConfig_UseFireboltSDK)); mLicensePrefetcher->Init(); + mWatermarkWorker = std::thread(&AampDRMLicenseManager::WatermarkWorkerThread, this); } /** @@ -130,6 +144,7 @@ AampDRMLicenseManager::AampDRMLicenseManager(int maxDrmSessions, PrivateInstance */ AampDRMLicenseManager::~AampDRMLicenseManager() { + StopWatermarkWorker(); SAFE_DELETE(mLicensePrefetcher); SAFE_DELETE(mDrmSessionManager); releaseLicenseRenewalThreads(); @@ -1420,7 +1435,24 @@ void AampDRMLicenseManager::QueueProtectionEvent(std::shared_ptr 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())); } /** @@ -1428,7 +1460,24 @@ void AampDRMLicenseManager::setPlaybackSpeedState(bool live, double currentLaten */ 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())); } /** @@ -1436,12 +1485,109 @@ void AampDRMLicenseManager::hideWatermarkOnDetach(void) */ 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 task) +{ + { + std::lock_guard lock(mWatermarkTaskMutex); + if (mWatermarkWorkerStopping) + { + return false; + } + mWatermarkTaskQueue.emplace_back(std::move(task)); + } + mWatermarkTaskCondition.notify_one(); + return true; +} + +void AampDRMLicenseManager::WatermarkWorkerThread() +{ + for (;;) + { + std::function task; + { + std::unique_lock 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 lock(mWatermarkTaskMutex); + mWatermarkWorkerStopping = true; + } + mWatermarkTaskCondition.notify_all(); + if (mWatermarkWorker.joinable()) + { + mWatermarkWorker.join(); + } } /** diff --git a/drm/AampDRMLicManager.h b/drm/AampDRMLicManager.h index b1cf5c1b16..772a36f87f 100644 --- a/drm/AampDRMLicManager.h +++ b/drm/AampDRMLicManager.h @@ -30,6 +30,11 @@ #include "DrmSession.h" #include "AampCurlDownloader.h" #include "DrmSessionManager.h" +#include +#include +#include +#include +#include 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 task); + void StopWatermarkWorker(); + + std::mutex mWatermarkTaskMutex; + std::condition_variable mWatermarkTaskCondition; + std::deque> mWatermarkTaskQueue; + bool mWatermarkWorkerStopping{false}; + std::thread mWatermarkWorker; }; diff --git a/middleware/drm/DrmSessionManager.cpp b/middleware/drm/DrmSessionManager.cpp index 65fe1d5dad..13df97c438 100755 --- a/middleware/drm/DrmSessionManager.cpp +++ b/middleware/drm/DrmSessionManager.cpp @@ -30,6 +30,7 @@ #include #include "PlayerUtils.h" #include "ContentSecurityManager.h" +#include #define DRM_METADATA_TAG_START "" #define DRM_METADATA_TAG_END "" #define SESSION_TOKEN_URL "http://localhost:50050/authService/getSessionToken" @@ -37,6 +38,14 @@ #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(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 {