Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
pstroffolino merged 6 commits into from
Mar 25, 2026
Merged

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

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
65786fd
VPLAY-12472 [CSAT][AAMP] Add logging for buffering start/end and buff…
lashmintha Mar 10, 2026
edaa138
Merge branch 'dev_sprint_25_2' into feature/VPLAY-12472_2
pstroffolino Mar 24, 2026
23c1f11
Reason for Change: fixes for various copilot raised edge cases
pstroffolino Mar 24, 2026
174ba8b
Merge branch 'dev_sprint_25_2' into feature/VPLAY-12472_2
pstroffolino Mar 24, 2026
7bacb32
Reason for Change: l1 test added
pstroffolino Mar 24, 2026
0a41cff
Apply suggestions from code review
pstroffolino Mar 25, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
37 changes: 34 additions & 3 deletions priv_aamp.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
Expand Down Expand Up @@ -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);
Copy link

Copilot AI Mar 24, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

bufferingDurationMs is cast from long long to int for telemetry without bounds checking. If the value is negative (time jump) or exceeds INT_MAX, this will wrap/truncate and emit incorrect telemetry. Consider clamping to a safe range before casting (e.g., 0..INT_MAX) or changing the telemetry schema to avoid narrowing if that’s supported.

Suggested change
intData["dur"] = static_cast<int>(bufferingDurationMs);
long long clampedDurationMs = bufferingDurationMs;
if (clampedDurationMs < 0)
{
clampedDurationMs = 0;
}
else if (clampedDurationMs > static_cast<long long>(INT_MAX))
{
clampedDurationMs = static_cast<long long>(INT_MAX);
}
intData["dur"] = static_cast<int>(clampedDurationMs);

Copilot uses AI. Check for mistakes.
Copy link

Copilot AI Mar 24, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

bufferingDurationMs is a long long but is narrowed to int for telemetry. If the buffering episode (or an unpaired start/end due to an error path) exceeds INT_MAX milliseconds, the cast becomes implementation-defined and can produce incorrect/negative values. Consider clamping to std::numeric_limits<int>::max() (or sending duration via a wider telemetry field type if available).

Suggested change
intData["dur"] = static_cast<int>(bufferingDurationMs);
int durationForTelemetry;
if (bufferingDurationMs < 0)
{
durationForTelemetry = 0;
}
else if (bufferingDurationMs > INT_MAX)
{
durationForTelemetry = INT_MAX;
}
else
{
durationForTelemetry = static_cast<int>(bufferingDurationMs);
}
intData["dur"] = durationForTelemetry;

Copilot uses AI. Check for mistakes.
at2.send(telemetryName, intData, {/*string data*/}, {/*float data*/});
Comment on lines +3282 to +3284
Copy link

Copilot AI Mar 25, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

bufferingDurationMs is a long long but is unconditionally narrowed to int for telemetry (static_cast<int>(bufferingDurationMs)). If a buffering episode is very long (or if the start timestamp is ever corrupted/uninitialized), this can overflow and send a negative/garbled duration. Clamp to INT_MAX (and 0) before casting, or extend the telemetry API usage to carry a 64-bit value if supported.

Copilot uses AI. Check for mistakes.
#endif //AAMP_TELEMETRY_SUPPORT
SendEvent(e,AAMP_EVENT_ASYNC_MODE);

Expand Down
7 changes: 7 additions & 0 deletions priv_aamp.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Copy link

Copilot AI Mar 24, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

mBufferingStartTimeMS has no in-class initializer. There are alternate PrivateInstanceAAMP constructor definitions used by unit-test fakes/mocks (e.g. test/utests/drm/mocks/aampMocks.cpp, test/utests/fakes/FakePrivateInstanceAAMP.cpp) that don't initialize this new member, leaving the atomic's value indeterminate. That can yield undefined behavior / bogus buffering durations when SendBufferChangeEvent() does compare_exchange_strong/exchange. Prefer giving the member an in-class initializer (e.g., {-1}) or updating all constructors to initialize it.

Suggested change
std::atomic<long long> mBufferingStartTimeMS;
std::atomic<long long> mBufferingStartTimeMS{-1};

Copilot uses AI. Check for mistakes.
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;
Expand Down
Loading