Bug 1170958 - Improve logging of MediaStreams and playback. r=roc

This commit is contained in:
Andreas Pehrson 2015-09-25 23:23:18 +08:00
parent 7f8b2b04db
commit 39106f84a4
3 changed files with 69 additions and 2 deletions

View File

@ -979,6 +979,8 @@ void HTMLMediaElement::NotifyMediaTrackEnabled(MediaTrack* aTrack)
return;
}
LOG(LogLevel::Debug, ("MediaElement %p MediaStreamTrack %p enabled", this));
// TODO: We are dealing with single audio track and video track for now.
if (AudioTrack* track = aTrack->AsAudioTrack()) {
if (!track->Enabled()) {
@ -997,6 +999,8 @@ void HTMLMediaElement::NotifyMediaStreamTracksAvailable(DOMMediaStream* aStream)
return;
}
LOG(LogLevel::Debug, ("MediaElement %p MediaStream tracks available", this));
bool videoHasChanged = IsVideo() && HasVideo() != !VideoTracks()->IsEmpty();
if (videoHasChanged) {
@ -3116,6 +3120,10 @@ void HTMLMediaElement::UpdateSrcMediaStreamPlaying(uint32_t aFlags)
}
mSrcStreamIsPlaying = shouldPlay;
LOG(LogLevel::Debug, ("MediaElement %p %s playback of DOMMediaStream %p",
this, shouldPlay ? "Setting up" : "Removing",
mSrcStream.get()));
if (shouldPlay) {
mSrcStreamPausedCurrentTime = -1;
@ -3584,6 +3592,8 @@ HTMLMediaElement::UpdateReadyStateInternal()
{
if (!mDecoder && !mSrcStream) {
// Not initialized - bail out.
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Not initialized", this));
return;
}
@ -3591,6 +3601,8 @@ HTMLMediaElement::UpdateReadyStateInternal()
// aNextFrame might have a next frame because the decoder can advance
// on its own thread before MetadataLoaded gets a chance to run.
// The arrival of more data can't change us out of this readyState.
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Decoder ready state < HAVE_METADATA", this));
return;
}
@ -3598,11 +3610,23 @@ HTMLMediaElement::UpdateReadyStateInternal()
bool hasAudio = !AudioTracks()->IsEmpty();
bool hasVideo = !VideoTracks()->IsEmpty();
if ((!hasAudio && !hasVideo) ||
(IsVideo() && hasVideo && !HasVideo())) {
if (!hasAudio && !hasVideo) {
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Stream with no tracks", this));
return;
}
if (IsVideo() && hasVideo && !HasVideo()) {
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Stream waiting for video", this));
return;
}
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() Stream has "
"metadata; audioTracks=%d, videoTracks=%d, "
"hasVideoFrame=%d", this, AudioTracks()->Length(),
VideoTracks()->Length(), HasVideo()));
// We are playing a stream that has video and a video frame is now set.
// This means we have all metadata needed to change ready state.
MediaInfo mediaInfo = mMediaInfo;
@ -3616,6 +3640,8 @@ HTMLMediaElement::UpdateReadyStateInternal()
}
if (NextFrameStatus() == MediaDecoderOwner::NEXT_FRAME_UNAVAILABLE_SEEKING) {
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"NEXT_FRAME_UNAVAILABLE_SEEKING; Forcing HAVE_METADATA", this));
ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_METADATA);
return;
}
@ -3626,6 +3652,8 @@ HTMLMediaElement::UpdateReadyStateInternal()
// Also, if video became available after advancing to HAVE_CURRENT_DATA
// while we are still playing, we need to revert to HAVE_METADATA until
// a video frame is available.
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Playing video but no video frame; Forcing HAVE_METADATA", this));
ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_METADATA);
return;
}
@ -3640,11 +3668,15 @@ HTMLMediaElement::UpdateReadyStateInternal()
// should remain at HAVE_CURRENT_DATA in this case.
// Note that this state transition includes the case where we finished
// downloaded the whole data stream.
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Decoder download suspended by cache", this));
ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA);
return;
}
if (NextFrameStatus() != MediaDecoderOwner::NEXT_FRAME_AVAILABLE) {
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Next frame not available", this));
ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA);
if (!mWaitingFired && NextFrameStatus() == MediaDecoderOwner::NEXT_FRAME_UNAVAILABLE_BUFFERING) {
FireTimeUpdate(false);
@ -3655,6 +3687,8 @@ HTMLMediaElement::UpdateReadyStateInternal()
}
if (mSrcStream) {
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Stream HAVE_ENOUGH_DATA", this));
ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA);
return;
}
@ -3669,9 +3703,13 @@ HTMLMediaElement::UpdateReadyStateInternal()
// without stopping to buffer.
if (mDecoder->CanPlayThrough())
{
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Decoder can play through", this));
ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA);
return;
}
LOG(LogLevel::Debug, ("MediaElement %p UpdateReadyStateInternal() "
"Default; Decoder has future data", this));
ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_FUTURE_DATA);
}

View File

@ -21,6 +21,13 @@
#include "VideoStreamTrack.h"
#include "Layers.h"
#ifdef LOG
#undef LOG
#endif
static PRLogModuleInfo* gMediaStreamLog;
#define LOG(type, msg) MOZ_LOG(gMediaStreamLog, type, msg)
using namespace mozilla;
using namespace mozilla::dom;
using namespace mozilla::layers;
@ -146,14 +153,23 @@ public:
}
MOZ_ASSERT(mEvents & MediaStreamListener::TRACK_EVENT_ENDED);
LOG(LogLevel::Debug, ("DOMMediaStream %p Track %u of stream %p ended",
stream, mInputTrackID, mInputStream.get()));
nsRefPtr<MediaStreamTrack> track = stream->FindOwnedDOMTrack(mInputStream, mID);
if (track) {
LOG(LogLevel::Debug, ("DOMMediaStream %p Owned track; notifying track listeners.", stream));
track->NotifyEnded();
} else {
LOG(LogLevel::Debug, ("DOMMediaStream %p Not an owned track.", stream));
}
track = stream->FindPlaybackDOMTrack(mInputStream, mInputTrackID);
if (track) {
LOG(LogLevel::Debug, ("DOMMediaStream %p Playback track; notifying stream listeners.", stream));
stream->NotifyMediaStreamTrackEnded(track);
} else {
LOG(LogLevel::Debug, ("DOMMediaStream %p Not a playback track.", stream));
}
return NS_OK;
}
@ -268,6 +284,10 @@ DOMMediaStream::DOMMediaStream()
nsCOMPtr<nsIUUIDGenerator> uuidgen =
do_GetService("@mozilla.org/uuid-generator;1", &rv);
if (!gMediaStreamLog) {
gMediaStreamLog = PR_NewLogModule("MediaStream");
}
if (NS_SUCCEEDED(rv) && uuidgen) {
nsID uuid;
memset(&uuid, 0, sizeof(uuid));
@ -288,6 +308,7 @@ DOMMediaStream::~DOMMediaStream()
void
DOMMediaStream::Destroy()
{
LOG(LogLevel::Debug, ("DOMMediaStream %p Being destroyed.", this));
if (mListener) {
mListener->Forget();
mListener = nullptr;
@ -428,6 +449,9 @@ DOMMediaStream::InitStreamCommon(MediaStream* aStream,
mPlaybackStream->SetAutofinish(true);
mPlaybackPort = mPlaybackStream->AllocateInputPort(mOwnedStream);
LOG(LogLevel::Debug, ("DOMMediaStream %p Initiated with mInputStream=%p, mOwnedStream=%p, mPlaybackStream=%p",
this, mInputStream, mOwnedStream, mPlaybackStream));
// Setup track listener
mListener = new PlaybackStreamListener(this);
mPlaybackStream->AddListener(mListener);
@ -554,6 +578,8 @@ DOMMediaStream::CreateOwnDOMTrack(TrackID aTrackID, MediaSegment::Type aType)
MOZ_CRASH("Unhandled track type");
}
LOG(LogLevel::Debug, ("DOMMediaStream %p Created new track %p with ID %u", this, track, aTrackID));
nsRefPtr<TrackPort> ownedTrackPort =
new TrackPort(mOwnedPort, track, TrackPort::InputPortOwnership::EXTERNAL);
mOwnedTracks.AppendElement(ownedTrackPort.forget());

View File

@ -55,8 +55,10 @@ TrackUnionStream::TrackUnionStream(DOMMediaStream* aWrapper) :
void TrackUnionStream::RemoveInput(MediaInputPort* aPort)
{
STREAM_LOG(LogLevel::Debug, ("TrackUnionStream %p removing input %p", this, aPort));
for (int32_t i = mTrackMap.Length() - 1; i >= 0; --i) {
if (mTrackMap[i].mInputPort == aPort) {
STREAM_LOG(LogLevel::Debug, ("TrackUnionStream %p removing trackmap entry %d", this, i));
EndTrack(i);
mTrackMap.RemoveElementAt(i);
}
@ -218,6 +220,7 @@ TrackUnionStream::TrackUnionStream(DOMMediaStream* aWrapper) :
StreamBuffer::Track* outputTrack = mBuffer.FindTrack(mTrackMap[aIndex].mOutputTrackID);
if (!outputTrack || outputTrack->IsEnded())
return;
STREAM_LOG(LogLevel::Debug, ("TrackUnionStream %p ending track %d", this, outputTrack->GetID()));
for (uint32_t j = 0; j < mListeners.Length(); ++j) {
MediaStreamListener* l = mListeners[j];
StreamTime offset = outputTrack->GetSegment()->GetDuration();