VPAAMP-683 : add log to to check time taken between first frame to pipeline moved to PLAYING state

aampgstplayer.cpp

@@ -109,6 +109,7 @@ static void InitializePlayerConfigs(AAMPGstPlayer *_this, void *playerInstance)
 	interfacePlayer->m_gstConfigParam->audioOnlyMode = _this->aamp->mAudioOnlyPb;
 	interfacePlayer->m_gstConfigParam->gstreamerSubsEnabled = _this->aamp->IsGstreamerSubsEnabled();
 	interfacePlayer->m_gstConfigParam->media = _this->aamp->GetMediaFormatTypeEnum();
+	interfacePlayer->m_gstConfigParam->isNewTune = _this->aamp->mIsNewTune;
 }
 
 /*

middleware/InterfacePlayerPriv.h

@@ -226,6 +226,7 @@ struct GstPlayerPriv
 	int NumberOfTracks;                                               /**< Indicates the number of tracks */
 	GstPlaybackQualityStruct playbackQuality; /**< video playback quality info */
 	bool isMp4DemuxPlayback; /**< flag to denote mp4demux path needs BMFF-like semantics */
+	long long mFirstFrameTimeInMS;                /**< Steady-clock timestamp (ms) when first video frame was received; 0 if unset */
 	struct CallbackData
 	{
 		gpointer instance;

middleware/InterfacePlayerRDK.cpp

@@ -299,6 +299,7 @@ void InterfacePlayerRDK::ConfigurePipeline(int format, int audioFormat, int subF
 	GstStreamOutputFormat newFormat[GST_TRACK_COUNT];
 	newFormat[eGST_MEDIATYPE_VIDEO] = gstFormat;
 	newFormat[eGST_MEDIATYPE_AUDIO] = gstAudioFormat;
+	interfacePlayerPriv->gstPrivateContext->mFirstFrameTimeInMS = 0;
 
 	bool newClosedCaptionsControl = false;
 
@@ -3726,6 +3727,7 @@ void InterfacePlayerRDK::NotifyFirstFrame(int mediaType)
 
 	if (eGST_MEDIATYPE_VIDEO == mediaType)
 	{
+		interfacePlayerPriv->gstPrivateContext->mFirstFrameTimeInMS = NOW_STEADY_TS_MS;
 		MW_LOG_MIL("OnFirstVideoFrame. got First Video Frame");
 
 		if (!interfacePlayerPriv->gstPrivateContext->decoderHandleNotified)
@@ -4275,7 +4277,20 @@ static gboolean bus_message(GstBus * bus, GstMessage * msg, InterfacePlayerRDK *
 			busEvent.msg = srcName ? srcName : "Unknown source";
 			busEvent.dbg_info = "N/A";
 			busEvent.msgType = MESSAGE_STATE_CHANGE;
-
+
+			std::string oldState(gst_element_state_get_name(old_state));
+			std::string newState(gst_element_state_get_name(new_state));
+			if(isPlaybinStateChangeEvent && oldState == "PAUSED" && newState == "PLAYING")
+			{
+				if(privatePlayer->gstPrivateContext->mFirstFrameTimeInMS > 0 && pInterfacePlayerRDK->m_gstConfigParam->isNewTune)
+				{
+					const long long timeToPlayingMs = NOW_STEADY_TS_MS - privatePlayer->gstPrivateContext->mFirstFrameTimeInMS;
+ 					MW_LOG_WARN("Time taken from First Frame to PLAYING state %.3f seconds", (static_cast<double>(timeToPlayingMs) / 1000.0));
+				}
+				privatePlayer->gstPrivateContext->mFirstFrameTimeInMS = 0;
+				pInterfacePlayerRDK->m_gstConfigParam->isNewTune = false;
+			}
+
 			if(isPlaybinStateChangeEvent && privatePlayer->gstPrivateContext->pauseOnStartPlayback && (new_state == GST_STATE_PAUSED))
 			{
 				GstElement *video_sink = privatePlayer->gstPrivateContext->video_sink;

middleware/InterfacePlayerRDK.h

@@ -137,6 +137,7 @@ struct Configs
 	int monitorAvsyncThresholdPositiveMs;
 	int monitorAvsyncThresholdNegativeMs;
 	int monitorAvJumpThresholdMs;
+	bool isNewTune;
 };
 
 

priv_aamp.cpp

@@ -1824,6 +1824,7 @@ PrivateInstanceAAMP::PrivateInstanceAAMP(AampConfig *config) : mReportProgressPo
 	, mLastSleThumbnailInfo()
 	, mLatencyMonitor(std::make_unique<AampLatencyMonitor>(this))
 	, mTuneTimeMetricData()
+	, mIsNewTune(false)
 {
 	AAMPLOG_MIL("Create Private Player %d", mPlayerId);
 	mAampCacheHandler = new AampCacheHandler(mPlayerId);
@@ -3912,6 +3913,7 @@ void PrivateInstanceAAMP::TuneFail(bool fail)
 		// Send the tune time metrics event as the progress event will not fire here.
 		SendTuneMetricsEvent();
 	}
+	mIsNewTune = false;
 	AdditionalTuneFailLogEntries();
 }
 
@@ -3920,6 +3922,7 @@ void PrivateInstanceAAMP::TuneFail(bool fail)
  */
 void PrivateInstanceAAMP::LogTuneComplete(void)
 {
+	mIsNewTune = false;
 	TuneEndMetrics mTuneMetrics = {0, 0, 0,0,0,0,0,0,0,(ContentType)0};
 
 	mTuneMetrics.success 		 	 = true;
@@ -6928,6 +6931,7 @@ void PrivateInstanceAAMP::Tune(const char *mainManifestUrl,
 	{
 		char tuneStrPrefix[64] = {};
 		mTsbSessionRequestUrl.clear();
+		mIsNewTune = true;
 		if (!mAppName.empty())
 		{
 			snprintf(tuneStrPrefix, sizeof(tuneStrPrefix), "%s PLAYER[%d] APP: %s",(mbPlayEnabled?STRFGPLAYER:STRBGPLAYER), mPlayerId, mAppName.c_str());

priv_aamp.h

@@ -1236,6 +1236,7 @@ class PrivateInstanceAAMP : public DrmCallbacks, public std::enable_shared_from_
 
 	bool mIsFlushFdsInCurlStore;	/**< Mark to clear curl store instance in case of playback stopped due to download Error */
 	bool mIsFlushOperationInProgress;		/**< Flag to indicate pipeline flush operation is going on */
+	bool mIsNewTune;		/**< Flag to indicate it is new tune */
 
 	/**
 	 * @fn ProcessID3Metadata