Bug 1190897 - Add MP3Demuxer logging. r=kinetik
authorEugen Sawin <esawin@me73.com>
Mon, 13 Jul 2015 18:22:17 +0200
changeset 287948 0f4864d20e8cd84dcd3dd47a1c5840c7aecc0a39
parent 287947 eb6b06526c5d4c7259c36c2ff64865e6fc3e3866
child 287949 8a31c820b381e29e2db38a713e1c4bf421097976
push id5067
push userraliiev@mozilla.com
push dateMon, 21 Sep 2015 14:04:52 +0000
treeherdermozilla-beta@14221ffe5b2f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerskinetik
bugs1190897
milestone42.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 1190897 - Add MP3Demuxer logging. r=kinetik
dom/media/MP3Demuxer.cpp
--- a/dom/media/MP3Demuxer.cpp
+++ b/dom/media/MP3Demuxer.cpp
@@ -8,16 +8,28 @@
 
 #include <inttypes.h>
 #include <algorithm>
 
 #include "mozilla/Assertions.h"
 #include "mozilla/Endian.h"
 #include "VideoUtils.h"
 #include "TimeUnits.h"
+#include "prenv.h"
+
+#ifdef PR_LOGGING
+PRLogModuleInfo* gMP3DemuxerLog;
+#define MP3DEMUXER_LOG(msg, ...) \
+  MOZ_LOG(gMP3DemuxerLog, LogLevel::Debug, ("MP3Demuxer " msg, ##__VA_ARGS__))
+#define MP3DEMUXER_LOGV(msg, ...) \
+  MOZ_LOG(gMP3DemuxerLog, LogLevel::Verbose, ("MP3Demuxer " msg, ##__VA_ARGS__))
+#else
+#define MP3DEMUXER_LOG(msg, ...)
+#define MP3DEMUXER_LOGV(msg, ...)
+#endif
 
 using media::TimeUnit;
 using media::TimeIntervals;
 
 namespace mozilla {
 namespace mp3 {
 
 // MP3Demuxer
@@ -32,20 +44,23 @@ MP3Demuxer::InitInternal() {
     mTrackDemuxer = new MP3TrackDemuxer(mSource);
   }
   return mTrackDemuxer->Init();
 }
 
 nsRefPtr<MP3Demuxer::InitPromise>
 MP3Demuxer::Init() {
   if (!InitInternal()) {
+    MP3DEMUXER_LOG("MP3Demuxer::Init() failure: waiting for data");
+
     return InitPromise::CreateAndReject(
       DemuxerFailureReason::WAITING_FOR_DATA, __func__);
   }
 
+  MP3DEMUXER_LOG("MP3Demuxer::Init() successful");
   return InitPromise::CreateAndResolve(NS_OK, __func__);
 }
 
 already_AddRefed<MediaDataDemuxer>
 MP3Demuxer::Clone() const {
   nsRefPtr<MP3Demuxer> demuxer = new MP3Demuxer(mSource);
   if (!demuxer->InitInternal()) {
     NS_WARNING("Couldn't recreate MP3Demuxer");
@@ -76,39 +91,52 @@ bool
 MP3Demuxer::IsSeekable() const {
   return true;
 }
 
 void
 MP3Demuxer::NotifyDataArrived(uint32_t aLength, int64_t aOffset) {
   // TODO: bug 1169485.
   NS_WARNING("Unimplemented function NotifyDataArrived");
+  MP3DEMUXER_LOGV("NotifyDataArrived(%u, %" PRId64 ") mOffset=%" PRId64,
+                  aLength, aOffset, mTrackDemuxer->GetResourceOffset());
 }
 
 void
 MP3Demuxer::NotifyDataRemoved() {
   // TODO: bug 1169485.
   NS_WARNING("Unimplemented function NotifyDataRemoved");
+  MP3DEMUXER_LOGV("NotifyDataRemoved()");
 }
 
 
 // MP3TrackDemuxer
 
 MP3TrackDemuxer::MP3TrackDemuxer(MediaResource* aSource)
   : mSource(aSource)
 {
   Reset();
+
+#ifdef PR_LOGGING
+  if (!gMP3DemuxerLog) {
+    gMP3DemuxerLog = PR_NewLogModule("MP3Demuxer");
+  }
+#endif
 }
 
 bool
 MP3TrackDemuxer::Init() {
   Reset();
   FastSeek(TimeUnit());
   // Read the first frame to fetch sample rate and other meta data.
   nsRefPtr<MediaRawData> frame(GetNextFrame(FindNextFrame()));
+
+  MP3DEMUXER_LOG("Init StreamLength()=%" PRId64 " first-frame-found=%d",
+                 StreamLength(), !!frame);
+
   if (!frame) {
     return false;
   }
 
   // Rewind back to the stream begin to avoid dropping the first frame.
   FastSeek(TimeUnit());
 
   if (!mInfo) {
@@ -116,16 +144,20 @@ MP3TrackDemuxer::Init() {
   }
 
   mInfo->mRate = mSamplesPerSecond;
   mInfo->mChannels = mChannels;
   mInfo->mBitDepth = 16;
   mInfo->mMimeType = "audio/mpeg";
   mInfo->mDuration = Duration().ToMicroseconds();
 
+  MP3DEMUXER_LOG("Init mInfo={mRate=%d mChannels=%d mBitDepth=%d mDuration=%" PRId64 "}",
+                 mInfo->mRate, mInfo->mChannels, mInfo->mBitDepth,
+                 mInfo->mDuration);
+
   return mSamplesPerSecond && mChannels;
 }
 
 #ifdef ENABLE_TESTS
 const FrameParser::Frame&
 MP3TrackDemuxer::LastFrame() const {
   return mParser.PrevFrame();
 }
@@ -160,16 +192,21 @@ nsRefPtr<MP3TrackDemuxer::SeekPromise>
 MP3TrackDemuxer::Seek(TimeUnit aTime) {
   const TimeUnit seekTime = ScanUntil(aTime);
 
   return SeekPromise::CreateAndResolve(seekTime, __func__);
 }
 
 TimeUnit
 MP3TrackDemuxer::FastSeek(TimeUnit aTime) {
+  MP3DEMUXER_LOG("FastSeek(%" PRId64 ") avgFrameLen=%f mNumParsedFrames=%" PRIu64
+                 " mFrameIndex=%" PRId64 " mOffset=%" PRIu64,
+                 aTime, AverageFrameLength(), mNumParsedFrames, mFrameIndex,
+                 mOffset);
+
   if (!aTime.ToMicroseconds()) {
     // Quick seek to the beginning of the stream.
     mOffset = mFirstFrameOffset;
     mFrameIndex = 0;
     mParser.EndFrameSession();
     return TimeUnit();
   }
 
@@ -177,66 +214,103 @@ MP3TrackDemuxer::FastSeek(TimeUnit aTime
     return TimeUnit::FromMicroseconds(-1);
   }
 
   const int64_t numFrames = aTime.ToSeconds() *
                             mSamplesPerSecond / mSamplesPerFrame;
   mOffset = mFirstFrameOffset + numFrames * AverageFrameLength();
   mFrameIndex = numFrames;
 
+  MP3DEMUXER_LOG("FastSeek mSamplesPerSecond=%d mSamplesPerFrame=%d "
+                 "numFrames=%" PRId64,
+                 mSamplesPerSecond, mSamplesPerFrame, numFrames);
+
   mParser.EndFrameSession();
 
   return Duration(mFrameIndex);
 }
 
 TimeUnit
 MP3TrackDemuxer::ScanUntil(TimeUnit aTime) {
+  MP3DEMUXER_LOG("ScanUntil(%" PRId64 ") avgFrameLen=%f mNumParsedFrames=%" PRIu64
+                 " mFrameIndex=%" PRId64 " mOffset=%" PRIu64,
+                 aTime, AverageFrameLength(), mNumParsedFrames, mFrameIndex,
+                 mOffset);
+
   if (!aTime.ToMicroseconds()) {
     return FastSeek(aTime);
   }
 
   if (Duration(mFrameIndex) > aTime) {
     FastSeek(aTime);
   }
 
   MediaByteRange nextRange = FindNextFrame();
   while (SkipNextFrame(nextRange) && Duration(mFrameIndex + 1) < aTime) {
     nextRange = FindNextFrame();
+    MP3DEMUXER_LOGV("ScanUntil* avgFrameLen=%f mNumParsedFrames=%" PRIu64
+                " mFrameIndex=%" PRId64 " mOffset=%" PRIu64 " Duration=%" PRId64,
+                aTime, AverageFrameLength(), mNumParsedFrames, mFrameIndex,
+                mOffset, Duration(mFrameIndex + 1));
   }
 
+  MP3DEMUXER_LOG("ScanUntil End avgFrameLen=%f mNumParsedFrames=%" PRIu64
+              " mFrameIndex=%" PRId64 " mOffset=%" PRIu64,
+              aTime, AverageFrameLength(), mNumParsedFrames, mFrameIndex,
+              mOffset);
+
   return Duration(mFrameIndex);
 }
 
 nsRefPtr<MP3TrackDemuxer::SamplesPromise>
 MP3TrackDemuxer::GetSamples(int32_t aNumSamples) {
+  MP3DEMUXER_LOGV("GetSamples(%d) Begin mOffset=%" PRIu64 " mNumParsedFrames=%" PRIu64
+              " mFrameIndex=%" PRId64
+              " mTotalFrameLen=%" PRIu64 " mSamplesPerFrame=%d mSamplesPerSecond=%d "
+              "mChannels=%d",
+              aNumSamples,
+              mOffset, mNumParsedFrames, mFrameIndex, mTotalFrameLen, mSamplesPerFrame,
+              mSamplesPerSecond, mChannels);
+
   if (!aNumSamples) {
     return SamplesPromise::CreateAndReject(
         DemuxerFailureReason::DEMUXER_ERROR, __func__);
   }
 
   nsRefPtr<SamplesHolder> frames = new SamplesHolder();
 
   while (aNumSamples--) {
     nsRefPtr<MediaRawData> frame(GetNextFrame(FindNextFrame()));
     if (!frame) {
       break;
     }
 
     frames->mSamples.AppendElement(frame);
   }
 
+  MP3DEMUXER_LOGV("GetSamples() End mSamples.Size()=%d aNumSamples=%d mOffset=%" PRIu64
+              " mNumParsedFrames=%" PRIu64
+              " mFrameIndex=%" PRId64
+              " mTotalFrameLen=%" PRIu64 " mSamplesPerFrame=%d mSamplesPerSecond=%d "
+              "mChannels=%d",
+              frames->mSamples.Length(), aNumSamples,
+              mOffset, mNumParsedFrames, mFrameIndex, mTotalFrameLen, mSamplesPerFrame,
+              mSamplesPerSecond, mChannels);
+
   if (frames->mSamples.IsEmpty()) {
     return SamplesPromise::CreateAndReject(
         DemuxerFailureReason::END_OF_STREAM, __func__);
   }
   return SamplesPromise::CreateAndResolve(frames, __func__);
 }
 
 void
 MP3TrackDemuxer::Reset() {
+  MP3DEMUXER_LOG("Reset()");
+
   mOffset = 0;
   mFirstFrameOffset = 0;
   mNumParsedFrames = 0;
   mFrameIndex = 0;
   mTotalFrameLen = 0;
   mSamplesPerFrame = 0;
   mSamplesPerSecond = 0;
   mChannels = 0;
@@ -254,16 +328,17 @@ MP3TrackDemuxer::SkipToNextRandomAccessP
 int64_t
 MP3TrackDemuxer::GetResourceOffset() const {
   return mOffset;
 }
 
 TimeIntervals
 MP3TrackDemuxer::GetBuffered() {
   // TODO: bug 1169485.
+  MP3DEMUXER_LOG("MP3TrackDemuxer::GetBuffered()");
   NS_WARNING("Unimplemented function GetBuffered");
   return TimeIntervals();
 }
 
 int64_t
 MP3TrackDemuxer::GetEvictionOffset(TimeUnit aTime) {
   return 0;
 }
@@ -301,67 +376,95 @@ MP3TrackDemuxer::Duration(int64_t aNumFr
   const double usPerFrame = USECS_PER_S * mSamplesPerFrame / mSamplesPerSecond;
   return TimeUnit::FromMicroseconds(aNumFrames * usPerFrame);
 }
 
 MediaByteRange
 MP3TrackDemuxer::FindNextFrame() {
   static const int BUFFER_SIZE = 4096;
 
+  MP3DEMUXER_LOGV("FindNext() Begin mOffset=%" PRIu64 " mNumParsedFrames=%" PRIu64
+              " mFrameIndex=%" PRId64
+              " mTotalFrameLen=%" PRIu64 " mSamplesPerFrame=%d mSamplesPerSecond=%d "
+              "mChannels=%d",
+              mOffset, mNumParsedFrames, mFrameIndex, mTotalFrameLen, mSamplesPerFrame,
+              mSamplesPerSecond, mChannels);
+
   uint8_t buffer[BUFFER_SIZE];
   int32_t read = 0;
   const uint8_t* frameBeg = nullptr;
   const uint8_t* bufferEnd = nullptr;
 
   while (frameBeg == bufferEnd &&
          (read = Read(buffer, mOffset, BUFFER_SIZE)) > 0) {
     MOZ_ASSERT(mOffset + read > mOffset);
     mOffset += read;
     bufferEnd = buffer + read;
     frameBeg = mParser.Parse(buffer, bufferEnd);
   }
 
   if (frameBeg == bufferEnd || !mParser.CurrentFrame().Length()) {
+    MP3DEMUXER_LOG("FindNext() Exit frameBeg=%p bufferEnd=%p "
+                "mParser.CurrentFrame().Length()=%d ",
+                frameBeg, bufferEnd, mParser.CurrentFrame().Length());
     return { 0, 0 };
   }
 
+  MP3DEMUXER_LOGV("FindNext() End mOffset=%" PRIu64 " mNumParsedFrames=%" PRIu64
+              " mFrameIndex=%" PRId64 " bufferEnd=%p frameBeg=%p"
+              " mTotalFrameLen=%" PRIu64 " mSamplesPerFrame=%d mSamplesPerSecond=%d "
+              "mChannels=%d",
+              mOffset, mNumParsedFrames, mFrameIndex, bufferEnd, frameBeg,
+              mTotalFrameLen, mSamplesPerFrame,
+              mSamplesPerSecond, mChannels);
+
   const int64_t nextBeg = mOffset - (bufferEnd - frameBeg) + 1;
   return { nextBeg, nextBeg + mParser.CurrentFrame().Length() };
 }
 
 bool
 MP3TrackDemuxer::SkipNextFrame(const MediaByteRange& aRange) {
   if (!mNumParsedFrames || !aRange.Length()) {
     // We can't skip the first frame, since it could contain VBR headers.
     nsRefPtr<MediaRawData> frame(GetNextFrame(aRange));
     return frame;
   }
 
   UpdateState(aRange);
 
+  MP3DEMUXER_LOGV("SkipNext() End mOffset=%" PRIu64 " mNumParsedFrames=%" PRIu64
+              " mFrameIndex=%" PRId64
+              " mTotalFrameLen=%" PRIu64 " mSamplesPerFrame=%d mSamplesPerSecond=%d "
+              "mChannels=%d",
+              mOffset, mNumParsedFrames, mFrameIndex, mTotalFrameLen, mSamplesPerFrame,
+              mSamplesPerSecond, mChannels);
+
   return true;
 }
 
 already_AddRefed<MediaRawData>
 MP3TrackDemuxer::GetNextFrame(const MediaByteRange& aRange) {
+  MP3DEMUXER_LOG("GetNext() Begin({mStart=%" PRId64 " Length()=%" PRId64 "})");
   if (!aRange.Length()) {
     return nullptr;
   }
 
   nsRefPtr<MediaRawData> frame = new MediaRawData();
   frame->mOffset = aRange.mStart;
 
   nsAutoPtr<MediaRawDataWriter> frameWriter(frame->CreateWriter());
   if (!frameWriter->SetSize(aRange.Length())) {
+    MP3DEMUXER_LOG("GetNext() Exit failed to allocated media buffer");
     return nullptr;
   }
 
   const uint32_t read = Read(frameWriter->mData, frame->mOffset, frame->mSize);
 
   if (read != aRange.Length()) {
+    MP3DEMUXER_LOG("GetNext() Exit read=%u frame->mSize=%u", read, frame->mSize);
     return nullptr;
   }
 
   UpdateState(aRange);
 
   frame->mTime = Duration(mFrameIndex - 1).ToMicroseconds();
   frame->mDuration = Duration(1).ToMicroseconds();
 
@@ -370,16 +473,23 @@ MP3TrackDemuxer::GetNextFrame(const Medi
 
   if (mNumParsedFrames == 1) {
     // First frame parsed, let's read VBR info if available.
     // TODO: read info that helps with seeking (bug 1163667).
     mParser.ParseVBRHeader(frame->mData, frame->mData + frame->mSize);
     mFirstFrameOffset = frame->mOffset;
   }
 
+  MP3DEMUXER_LOGV("GetNext() End mOffset=%" PRIu64 " mNumParsedFrames=%" PRIu64
+              " mFrameIndex=%" PRId64
+              " mTotalFrameLen=%" PRIu64 " mSamplesPerFrame=%d mSamplesPerSecond=%d "
+              "mChannels=%d",
+              mOffset, mNumParsedFrames, mFrameIndex, mTotalFrameLen, mSamplesPerFrame,
+              mSamplesPerSecond, mChannels);
+
   return frame.forget();
 }
 
 void
 MP3TrackDemuxer::UpdateState(const MediaByteRange& aRange) {
   // Prevent overflow.
   if (mTotalFrameLen + aRange.Length() < mTotalFrameLen) {
     // These variables have a linear dependency and are only used to derive the
@@ -400,23 +510,26 @@ MP3TrackDemuxer::UpdateState(const Media
   MOZ_ASSERT(mFrameIndex > 0);
 
   // Prepare the parser for the next frame parsing session.
   mParser.EndFrameSession();
 }
 
 int32_t
 MP3TrackDemuxer::Read(uint8_t* aBuffer, int64_t aOffset, int32_t aSize) {
+  MP3DEMUXER_LOGV("MP3TrackDemuxer::Read(%p %" PRId64 " %d)", aBuffer, aOffset, aSize);
+
   const int64_t streamLen = StreamLength();
   if (mInfo && streamLen > 0) {
     // Prevent blocking reads after successful initialization.
     aSize = std::min<int64_t>(aSize, streamLen - aOffset);
   }
 
   uint32_t read = 0;
+  MP3DEMUXER_LOGV("MP3TrackDemuxer::Read        -> ReadAt(%d)", aSize);
   const nsresult rv = mSource->ReadAt(aOffset, reinterpret_cast<char*>(aBuffer),
                                       static_cast<uint32_t>(aSize), &read);
   NS_ENSURE_SUCCESS(rv, 0);
   return static_cast<int32_t>(read);
 }
 
 double
 MP3TrackDemuxer::AverageFrameLength() const {