Bug 1330918 - Add VideoTrackEncoder::AppendVideoSegment logs. r=jesup
authorAndreas Pehrson <pehrsons@gmail.com>
Wed, 18 Jan 2017 19:28:32 +0100
changeset 375184 49a053732072dcba2e556c74a67b58cd750fe073
parent 375183 a20498d3c1a2da550a771230e6fb47bf2953b7d6
child 375185 a3538d0e7314f9dae25af9353b88dc06aa110fe6
push id6996
push userjlorenzo@mozilla.com
push dateMon, 06 Mar 2017 20:48:21 +0000
treeherdermozilla-beta@d89512dab048 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjesup
bugs1330918
milestone53.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1330918 - Add VideoTrackEncoder::AppendVideoSegment logs. r=jesup MozReview-Commit-ID: FwG0EHuaxpW
dom/media/encoder/TrackEncoder.cpp
--- a/dom/media/encoder/TrackEncoder.cpp
+++ b/dom/media/encoder/TrackEncoder.cpp
@@ -292,33 +292,45 @@ VideoTrackEncoder::AppendVideoSegment(co
       }
 
       // This is the first real chunk in the track. Use its timestamp as the
       // starting point for this track.
       MOZ_ASSERT(!chunk.mTimeStamp.IsNull());
       const StreamTime nullDuration = mLastChunk.mDuration;
       mLastChunk = chunk;
 
+      TRACK_LOG(LogLevel::Verbose,
+                ("[VideoTrackEncoder]: Got first video chunk after %lld ticks.",
+                 nullDuration));
       // Adapt to the time before the first frame. This extends the first frame
       // from [start, end] to [0, end], but it'll do for now.
       mLastChunk.mTimeStamp -=
         TimeDuration::FromMicroseconds(
           RateConvertTicksRoundUp(PR_USEC_PER_SEC, mTrackRate, nullDuration));
     }
 
     MOZ_ASSERT(!mLastChunk.IsNull());
     if (mLastChunk.CanCombineWithFollowing(chunk) || chunk.IsNull()) {
+      TRACK_LOG(LogLevel::Verbose,
+                ("[VideoTrackEncoder]: Got dupe or null chunk."));
       // This is the same frame as before (or null). We extend the last chunk
       // with its duration.
       mLastChunk.mDuration += chunk.mDuration;
 
       if (mLastChunk.mDuration < mTrackRate) {
+        TRACK_LOG(LogLevel::Verbose,
+                  ("[VideoTrackEncoder]: Ignoring dupe/null chunk of duration "
+                   "%lld", chunk.mDuration));
         continue;
       }
 
+      TRACK_LOG(LogLevel::Verbose,
+                ("[VideoTrackEncoder]: Chunk >1 second. duration=%lld, "
+                 "trackRate=%lld", mLastChunk.mDuration, mTrackRate));
+
       // If we have gotten dupes for over a second, we force send one
       // to the encoder to make sure there is some output.
       chunk.mTimeStamp = mLastChunk.mTimeStamp + TimeDuration::FromSeconds(1);
 
       if (chunk.IsNull()) {
         // Ensure that we don't pass null to the encoder by making mLastChunk
         // null later on.
         chunk.mFrame = mLastChunk.mFrame;
@@ -327,19 +339,25 @@ VideoTrackEncoder::AppendVideoSegment(co
 
     TimeDuration diff = chunk.mTimeStamp - mLastChunk.mTimeStamp;
     if (diff <= TimeDuration::FromSeconds(0)) {
       // The timestamp from mLastChunk is newer than from chunk.
       // This means the durations reported from MediaStreamGraph for mLastChunk
       // were larger than the timestamp diff - and durations were used to
       // trigger the 1-second frame above. This could happen due to drift or
       // underruns in the graph.
+      TRACK_LOG(LogLevel::Warning,
+                ("[VideoTrackEncoder]: Underrun detected. Diff=%.5fs",
+                 diff.ToSeconds()));
       chunk.mTimeStamp = mLastChunk.mTimeStamp;
     } else {
       RefPtr<layers::Image> lastImage = mLastChunk.mFrame.GetImage();
+      TRACK_LOG(LogLevel::Verbose,
+                ("[VideoTrackEncoder]: Appending video frame %p, duration=%.5f",
+                 lastImage.get(), diff.ToSeconds()));
       mRawSegment.AppendFrame(lastImage.forget(),
                               RateConvertTicksRoundUp(
                                   mTrackRate, PR_USEC_PER_SEC,
                                   diff.ToMicroseconds()),
                               mLastChunk.mFrame.GetIntrinsicSize(),
                               PRINCIPAL_HANDLE_NONE,
                               mLastChunk.mFrame.GetForceBlack(),
                               mLastChunk.mTimeStamp);