Bug 1330918 - Add VideoTrackEncoder::AppendVideoSegment logs. r?jesup draft
authorAndreas Pehrson <pehrsons@gmail.com>
Wed, 18 Jan 2017 19:28:32 +0100
changeset 463332 6465a6a049465268c59504ad200f886f8abc8b02
parent 463331 e5bcd5281d74fb2ccb7205d840f4f97f25a0ead6
child 463572 5e6f58e506a58e385b35d200fa38fdb00004e4e3
push id42028
push userbmo:pehrson@telenordigital.com
push dateWed, 18 Jan 2017 21:37:16 +0000
reviewersjesup
bugs1330918
milestone53.0a1
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
@@ -294,33 +294,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;
@@ -329,19 +341,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);