Bug 1612557 - part4 : use Media category for markers r=bryce,gerald,canaltinova

This patch will do :
- add `Media` markers in related codes
- implement `MediaSampleMarkerPayload` to record the media sample

The advantage of doing so :
- using markers can help us know what happens on the media by a glance without expanding the call stack
- adding sample markers allows us compare the speed of decoding sample in `MediaDecoderStataMachine` and rendering sample in `VideoSink`

Differential Revision: https://phabricator.services.mozilla.com/D74174
This commit is contained in:
alwu 2020-05-16 19:58:25 +00:00
parent 4562999fec
commit fd606724bc
9 changed files with 168 additions and 2 deletions

View File

@ -210,6 +210,7 @@ nsresult AudioStream::SetPlaybackRate(double aPlaybackRate) {
return NS_ERROR_FAILURE;
}
PROFILER_ADD_MARKER("AudioStream::SetPlaybackRate", MEDIA_PLAYBACK);
mAudioClock.SetPlaybackRate(aPlaybackRate);
if (mAudioClock.GetPreservesPitch()) {

View File

@ -37,6 +37,19 @@
#include "VideoSegment.h"
#include "VideoUtils.h"
#ifdef MOZ_GECKO_PROFILER
# include "ProfilerMarkerPayload.h"
# define MDSM_ERROR_MARKER(tag, error, markerTime) \
PROFILER_ADD_MARKER_WITH_PAYLOAD(tag, MEDIA_PLAYBACK, TextMarkerPayload, \
(error, markerTime))
# define MDSM_SAMPLE_MARKER(tag, startTime, endTime) \
PROFILER_ADD_MARKER_WITH_PAYLOAD( \
tag, MEDIA_PLAYBACK, MediaSampleMarkerPayload, (startTime, endTime))
#else
# define MDSM_ERROR_MARKER(tag, error)
# define MDSM_SAMPLE_MARKER(tag, startTime, endTime)
#endif
namespace mozilla {
using namespace mozilla::media;
@ -379,6 +392,7 @@ class MediaDecoderStateMachine::DormantState
explicit DormantState(Master* aPtr) : StateObject(aPtr) {}
void Enter() {
PROFILER_ADD_MARKER("MDSM::EnterDormantState", MEDIA_PLAYBACK);
if (mMaster->IsPlaying()) {
mMaster->StopPlayback();
}
@ -1387,6 +1401,7 @@ class MediaDecoderStateMachine::AccurateSeekingState
"] target=%" PRId64,
aVideo->mTime.ToMicroseconds(),
aVideo->GetEndTime().ToMicroseconds(), target.ToMicroseconds());
PROFILER_ADD_MARKER("MDSM::DropVideoUpToSeekTarget", MEDIA_PLAYBACK);
mFirstVideoFrameAfterSeek = aVideo;
} else {
if (target >= aVideo->mTime && aVideo->GetEndTime() >= target) {
@ -1865,6 +1880,7 @@ class MediaDecoderStateMachine::BufferingState
explicit BufferingState(Master* aPtr) : StateObject(aPtr) {}
void Enter() {
PROFILER_ADD_MARKER("MDSM::EnterBufferingState", MEDIA_PLAYBACK);
if (mMaster->IsPlaying()) {
mMaster->StopPlayback();
}
@ -2613,6 +2629,7 @@ void MediaDecoderStateMachine::BufferingState::HandleEndOfVideo() {
}
RefPtr<ShutdownPromise> MediaDecoderStateMachine::ShutdownState::Enter() {
PROFILER_ADD_MARKER("MDSM::EnterShutdownState", MEDIA_PLAYBACK);
auto master = mMaster;
master->mDelayedScheduler.Reset();
@ -2840,6 +2857,8 @@ void MediaDecoderStateMachine::PushAudio(AudioData* aSample) {
MOZ_ASSERT(OnTaskQueue());
MOZ_ASSERT(aSample);
AudioQueue().Push(aSample);
MDSM_SAMPLE_MARKER("MDSM::PushAudio", aSample->mTime.ToMicroseconds(),
aSample->GetEndTime().ToMicroseconds());
}
void MediaDecoderStateMachine::PushVideo(VideoData* aSample) {
@ -2847,6 +2866,8 @@ void MediaDecoderStateMachine::PushVideo(VideoData* aSample) {
MOZ_ASSERT(aSample);
aSample->mFrameID = ++mCurrentFrameID;
VideoQueue().Push(aSample);
MDSM_SAMPLE_MARKER("MDSM::PushVideo", aSample->mTime.ToMicroseconds(),
aSample->GetEndTime().ToMicroseconds());
}
void MediaDecoderStateMachine::OnAudioPopped(const RefPtr<AudioData>& aSample) {
@ -3137,6 +3158,7 @@ void MediaDecoderStateMachine::BufferedRangeUpdated() {
RefPtr<MediaDecoder::SeekPromise> MediaDecoderStateMachine::Seek(
const SeekTarget& aTarget) {
AUTO_PROFILER_LABEL("MediaDecoderStateMachine::Seek", MEDIA_PLAYBACK);
PROFILER_ADD_MARKER("MDSM::Seek", MEDIA_PLAYBACK);
MOZ_ASSERT(OnTaskQueue());
// We need to be able to seek in some way
@ -3446,6 +3468,8 @@ bool MediaDecoderStateMachine::HasLowBufferedData(const TimeUnit& aThreshold) {
void MediaDecoderStateMachine::DecodeError(const MediaResult& aError) {
MOZ_ASSERT(OnTaskQueue());
LOGE("Decode error: %s", aError.Description().get());
MDSM_ERROR_MARKER("MDSM::DecodeError", aError.Description(),
TimeStamp::NowUnfuzzed());
// Notify the decode error and MediaDecoder will shut down MDSM.
mOnPlaybackErrorEvent.Notify(aError);
}

View File

@ -2491,7 +2491,7 @@ void MediaFormatReader::SkipVideoDemuxToNextKeyFrame(TimeUnit aTimeThreshold) {
}
void MediaFormatReader::VideoSkipReset(uint32_t aSkipped) {
PROFILER_ADD_MARKER("SkippedVideoDecode", GRAPHICS);
PROFILER_ADD_MARKER("SkippedVideoDecode", MEDIA_PLAYBACK);
MOZ_ASSERT(OnTaskQueue());
// Some frames may have been output by the decoder since we initiated the

View File

@ -15,6 +15,24 @@
#include "mozilla/StaticPrefs_media.h"
#include "nsPrintfCString.h"
#ifdef MOZ_GECKO_PROFILER
# include "ProfilerMarkerPayload.h"
# define PROFILER_MARKER(tag, sample) \
do { \
uint64_t startTime = (sample)->mTime.ToMicroseconds(); \
uint64_t endTime = (sample)->GetEndTime().ToMicroseconds(); \
auto profilerTag = (tag); \
mOwnerThread->Dispatch(NS_NewRunnableFunction( \
"AudioSink:AddMarker", [profilerTag, startTime, endTime] { \
PROFILER_ADD_MARKER_WITH_PAYLOAD(profilerTag, MEDIA_PLAYBACK, \
MediaSampleMarkerPayload, \
(startTime, endTime)); \
})); \
} while (0)
#else
# define PROFILER_MARKER(sample)
#endif
namespace mozilla {
extern LazyLogModule gMediaDecoderLog;
@ -267,6 +285,7 @@ UniquePtr<AudioStream::Chunk> AudioSink::PopFrames(uint32_t aFrames) {
SINK_LOG_V("playing audio at time=%" PRId64 " offset=%u length=%u",
mCurrentData->mTime.ToMicroseconds(),
mCurrentData->Frames() - mCursor->Available(), framesToPop);
PROFILER_MARKER("PlayAudio", mCurrentData);
UniquePtr<AudioStream::Chunk> chunk =
MakeUnique<Chunk>(mCurrentData, framesToPop, mCursor->Ptr());

View File

@ -39,7 +39,7 @@ extern LazyLogModule gMediaDecoderLog;
# define VSINK_ADD_PROFILER_MARKER(tag, markerTime, aTime, vTime) \
do { \
if (profiler_thread_is_being_profiled()) { \
PROFILER_ADD_MARKER_WITH_PAYLOAD(tag, GRAPHICS, \
PROFILER_ADD_MARKER_WITH_PAYLOAD(tag, MEDIA_PLAYBACK, \
VideoFrameMarkerPayload, \
(markerTime, aTime, vTime)); \
} \

View File

@ -464,6 +464,52 @@ void LogMarkerPayload::StreamPayload(SpliceableJSONWriter& aWriter,
aWriter.StringProperty("module", mModule.c_str());
}
MediaSampleMarkerPayload::MediaSampleMarkerPayload(
const int64_t aSampleStartTimeUs, const int64_t aSampleEndTimeUs)
: mSampleStartTimeUs(aSampleStartTimeUs),
mSampleEndTimeUs(aSampleEndTimeUs) {}
MediaSampleMarkerPayload::MediaSampleMarkerPayload(
CommonProps&& aCommonProps, const int64_t aSampleStartTimeUs,
const int64_t aSampleEndTimeUs)
: ProfilerMarkerPayload(std::move(aCommonProps)),
mSampleStartTimeUs(aSampleStartTimeUs),
mSampleEndTimeUs(aSampleEndTimeUs) {}
ProfileBufferEntryWriter::Length
MediaSampleMarkerPayload::TagAndSerializationBytes() const {
return CommonPropsTagAndSerializationBytes() +
ProfileBufferEntryWriter::SumBytes(mSampleStartTimeUs,
mSampleEndTimeUs);
}
void MediaSampleMarkerPayload::SerializeTagAndPayload(
ProfileBufferEntryWriter& aEntryWriter) const {
static const DeserializerTag tag = TagForDeserializer(Deserialize);
SerializeTagAndCommonProps(tag, aEntryWriter);
aEntryWriter.WriteObject(mSampleStartTimeUs);
aEntryWriter.WriteObject(mSampleEndTimeUs);
}
/* static */
UniquePtr<ProfilerMarkerPayload> MediaSampleMarkerPayload::Deserialize(
ProfileBufferEntryReader& aEntryReader) {
ProfilerMarkerPayload::CommonProps props =
DeserializeCommonProps(aEntryReader);
auto sampleStartTimeUs = aEntryReader.ReadObject<int64_t>();
auto sampleEndTimeUs = aEntryReader.ReadObject<int64_t>();
return UniquePtr<ProfilerMarkerPayload>(new MediaSampleMarkerPayload(
std::move(props), sampleStartTimeUs, sampleEndTimeUs));
}
void MediaSampleMarkerPayload::StreamPayload(
SpliceableJSONWriter& aWriter, const TimeStamp& aProcessStartTime,
UniqueStacks& aUniqueStacks) const {
StreamCommonProps("MediaSample", aWriter, aProcessStartTime, aUniqueStacks);
aWriter.IntProperty("sampleStartTimeUs", mSampleStartTimeUs);
aWriter.IntProperty("sampleEndTimeUs", mSampleEndTimeUs);
}
HangMarkerPayload::HangMarkerPayload(const TimeStamp& aStartTime,
const TimeStamp& aEndTime)
: ProfilerMarkerPayload(aStartTime, aEndTime) {}

View File

@ -318,6 +318,21 @@ class LogMarkerPayload : public ProfilerMarkerPayload {
std::string mText;
};
class MediaSampleMarkerPayload : public ProfilerMarkerPayload {
public:
MFBT_API MediaSampleMarkerPayload(const int64_t aSampleStartTimeUs,
const int64_t aSampleEndTimeUs);
DECL_BASE_STREAM_PAYLOAD
private:
MFBT_API MediaSampleMarkerPayload(CommonProps&& aCommonProps,
const int64_t aSampleStartTimeUs,
const int64_t aSampleEndTimeUs);
int64_t mSampleStartTimeUs;
int64_t mSampleEndTimeUs;
};
} // namespace baseprofiler
// Serialize a pointed-at ProfilerMarkerPayload, may be null when there are no

View File

@ -405,6 +405,52 @@ void DOMEventMarkerPayload::SerializeTagAndPayload(
aEntryWriter.WriteObject(mEventType);
}
MediaSampleMarkerPayload::MediaSampleMarkerPayload(
const int64_t aSampleStartTimeUs, const int64_t aSampleEndTimeUs)
: mSampleStartTimeUs(aSampleStartTimeUs),
mSampleEndTimeUs(aSampleEndTimeUs) {}
MediaSampleMarkerPayload::MediaSampleMarkerPayload(
CommonProps&& aCommonProps, const int64_t aSampleStartTimeUs,
const int64_t aSampleEndTimeUs)
: ProfilerMarkerPayload(std::move(aCommonProps)),
mSampleStartTimeUs(aSampleStartTimeUs),
mSampleEndTimeUs(aSampleEndTimeUs) {}
ProfileBufferEntryWriter::Length
MediaSampleMarkerPayload::TagAndSerializationBytes() const {
return CommonPropsTagAndSerializationBytes() +
ProfileBufferEntryWriter::SumBytes(mSampleStartTimeUs,
mSampleEndTimeUs);
}
void MediaSampleMarkerPayload::SerializeTagAndPayload(
ProfileBufferEntryWriter& aEntryWriter) const {
static const DeserializerTag tag = TagForDeserializer(Deserialize);
SerializeTagAndCommonProps(tag, aEntryWriter);
aEntryWriter.WriteObject(mSampleStartTimeUs);
aEntryWriter.WriteObject(mSampleEndTimeUs);
}
/* static */
UniquePtr<ProfilerMarkerPayload> MediaSampleMarkerPayload::Deserialize(
ProfileBufferEntryReader& aEntryReader) {
ProfilerMarkerPayload::CommonProps props =
DeserializeCommonProps(aEntryReader);
auto sampleStartTimeUs = aEntryReader.ReadObject<int64_t>();
auto sampleEndTimeUs = aEntryReader.ReadObject<int64_t>();
return UniquePtr<ProfilerMarkerPayload>(new MediaSampleMarkerPayload(
std::move(props), sampleStartTimeUs, sampleEndTimeUs));
}
void MediaSampleMarkerPayload::StreamPayload(
SpliceableJSONWriter& aWriter, const TimeStamp& aProcessStartTime,
UniqueStacks& aUniqueStacks) const {
StreamCommonProps("MediaSample", aWriter, aProcessStartTime, aUniqueStacks);
aWriter.IntProperty("sampleStartTimeUs", mSampleStartTimeUs);
aWriter.IntProperty("sampleEndTimeUs", mSampleEndTimeUs);
}
// static
UniquePtr<ProfilerMarkerPayload> DOMEventMarkerPayload::Deserialize(
ProfileBufferEntryReader& aEntryReader) {

View File

@ -664,6 +664,21 @@ class LogMarkerPayload : public ProfilerMarkerPayload {
nsCString mText;
};
class MediaSampleMarkerPayload : public ProfilerMarkerPayload {
public:
MediaSampleMarkerPayload(const int64_t aSampleStartTimeUs,
const int64_t aSampleEndTimeUs);
DECL_STREAM_PAYLOAD
private:
MediaSampleMarkerPayload(CommonProps&& aCommonProps,
const int64_t aSampleStartTimeUs,
const int64_t aSampleEndTimeUs);
int64_t mSampleStartTimeUs;
int64_t mSampleEndTimeUs;
};
class JsAllocationMarkerPayload : public ProfilerMarkerPayload {
public:
JsAllocationMarkerPayload(const mozilla::TimeStamp& aStartTime,