Closed Bug 1407810 Opened 8 years ago Closed 8 years ago

Add minimal DDLogging in media stack

Categories

(Core :: Audio/Video: Playback, enhancement, P3)

Product:
Core
Component:
Audio/Video: Playback
Version:
58 Branch
Type:
enhancement

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla59
Tracking Flags:
Tracking Status
firefox59 --- fixed

People

(Reporter: mozbugz, Assigned: mozbugz)

References

(Depends on 1 open bug, Blocks 1 open bug)

Details

Attachments

(9 files, 1 obsolete file)

Bug 1407810 - Make DecoderDoctorLogger::sLogState 'ReleaseAcquire' -
59 bytes, text/x-review-board-request
jwwang
: review+
Details
Bug 1407810 - Tweak atomics in MultiWriterQueue -
59 bytes, text/x-review-board-request
jwwang
: review+
Details
Bug 1407810 - webidl for HTMLMediaElement.mozRequestDebugLog -
59 bytes, text/x-review-board-request
smaug
: review+
jwwang
: review+
Details
Bug 1407810 - Implement HTMLMediaElement::Moz{Enable,Request}DebugLog -
59 bytes, text/x-review-board-request
jwwang
: review+
Details
Bug 1407810 - Use DDLogger in media stack -
59 bytes, text/x-review-board-request
jwwang
: review+
Details
Bug 1407810 - DDMOZ_LOG to replace MOZ_LOG and also output to DDLogger -
59 bytes, text/x-review-board-request
jwwang
: review+
Details
Bug 1407810 - Use DDMOZ_LOG in media stack -
59 bytes, text/x-review-board-request
jwwang
: review+
Details
Bug 1407810 - DDMediaLogs::SizeOf accounts for shallow message queue size -
59 bytes, text/x-review-board-request
jwwang
: review+
Details
Bug 1407810 - Enable DDLogging from the beginning if MOZ_LOG contains DDLogger -
59 bytes, text/x-review-board-request
jwwang
: review+
Details
First pass at adding useful logging: - Construction & destruction of most media stack objects, - Linking between objects (so they can be associated with the correct media element), - Log most events coming from HTMLMediaElement, - Interesting internal state values, - Including existing MOZ_LOGs if possible. Latest prototype: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b3f7af3cb0731ed834b2da0039789744f3120468
Comment on attachment 8918757 [details] Bug 1407810 - Make DecoderDoctorLogger::sLogState 'ReleaseAcquire' - https://reviewboard.mozilla.org/r/189602/#review194740
Attachment #8918757 - Flags: review?(jwwang) → review+
Comment on attachment 8918758 [details] Bug 1407810 - Tweak atomics in MultiWriterQueue - https://reviewboard.mozilla.org/r/189604/#review194742
Attachment #8918758 - Flags: review?(jwwang) → review+
First push for review! Some notes: - The first two patches tweak the Atomics for speed, I believe they're correct and I've tested them thoroughly (though it's no proof of correctness), and they give a nice speed boost. Once again, all these patches (except the very first one) should only run when the user explicitly runs a webextension, so there should be no/little impact if something is wrong. - I've left some patches with no reviewer for now, as *I* want to review them myself first and fix obvious issues. - I intend to publish an updated webextension shortly, so all this can be tested. But in the meantime, it can still be used with MOZ_LOG=DDLogger:5 and/or DDLoggerEnd:5. - Thank you in advance to all reviewers :-) Try with DDLogging forcefully enabled: https://treeherder.mozilla.org/#/jobs?repo=try&revision=4c79a1d71491e9e9cc2e83a18c908ee1bd24b2c0
Comment on attachment 8918759 [details] Bug 1407810 - Enable DDLogging from the beginning if MOZ_LOG contains DDLogger - https://reviewboard.mozilla.org/r/189606/#review194764 ::: dom/media/doctor/DecoderDoctorLogger.cpp:95 (Diff revision 1) > + LogState state = static_cast<LogState>(sLogState); > + switch (state) { > + case scUninitialized: > + // If the env-var's MOZ_LOG contains one of the DDLoggers, enable > + // DDLogging now. > + if (MOZ_LOG_TEST(sDecoderDoctorLoggerLog, LogLevel::Error) || I think it would be easier to set sLogState to 'enabled' in nsLayoutStatics::Initialize() without introducing a new state.
Comment on attachment 8918760 [details] Bug 1407810 - webidl for HTMLMediaElement.mozRequestDebugLog - https://reviewboard.mozilla.org/r/189608/#review194766 ::: dom/webidl/HTMLMediaElement.webidl:111 (Diff revision 1) > readonly attribute DOMString mozDebugReaderData; > [Func="HasDebuggerOrTabsPrivilege", NewObject] > Promise<DOMString> mozRequestDebugInfo(); > > + static void mozEnableDebugLog(); > + Promise<DOMString> mozRequestDebugLog(); The name is similar to 'mozRequestDebugInfo'. Might be worth calling it mozRequestDecoderDoctorLog to avoid confusion.
Attachment #8918760 - Flags: review?(jwwang) → review+
Comment on attachment 8918761 [details] Bug 1407810 - Implement HTMLMediaElement::Moz{Enable,Request}DebugLog - https://reviewboard.mozilla.org/r/189610/#review194768 ::: dom/html/HTMLMediaElement.cpp:1600 (Diff revision 1) > > return promise.forget(); > } > > +/* static */ void > +HTMLMediaElement::MozEnableDebugLog(const GlobalObject&) The webidl binding is missing?
Attachment #8918761 - Flags: review?(jwwang) → review+
Comment on attachment 8918762 [details] Bug 1407810 - Use DDLogger in media stack - https://reviewboard.mozilla.org/r/189612/#review194770 C/C++ static analysis found 1 defect in this patch. You can run this analysis locally with: `./mach static-analysis check path/to/file.cpp` If you see a problem in this automated review, please report it here: http://bit.ly/2y9N9Vx ::: dom/media/MediaFormatReader.cpp:661 (Diff revision 1) > + this, > + "decoder", > + mDecoder.get()); > + } > + > + ~Wrapper() Warning: Annotate this function with 'override' or (rarely) 'final' [clang-tidy: modernize-use-override] ~Wrapper() ^ override
Comment on attachment 8918760 [details] Bug 1407810 - webidl for HTMLMediaElement.mozRequestDebugLog - https://reviewboard.mozilla.org/r/189608/#review194832 ::: dom/webidl/HTMLMediaElement.webidl:112 (Diff revision 1) > [Func="HasDebuggerOrTabsPrivilege", NewObject] > Promise<DOMString> mozRequestDebugInfo(); > > + static void mozEnableDebugLog(); > + Promise<DOMString> mozRequestDebugLog(); > + We should not expose moz-prefixes API to the web.
Attachment #8918760 - Flags: review?(bugs) → review-
Comment on attachment 8918761 [details] Bug 1407810 - Implement HTMLMediaElement::Moz{Enable,Request}DebugLog - https://reviewboard.mozilla.org/r/189610/#review194768 > The webidl binding is missing? It's in the other patch "webidl for ...".
Attachment #8918759 - Attachment is obsolete: true
Attachment #8918759 - Flags: review?(jwwang)
Comment on attachment 8918760 [details] Bug 1407810 - webidl for HTMLMediaElement.mozRequestDebugLog - https://reviewboard.mozilla.org/r/189608/#review210914
Attachment #8918760 - Flags: review?(bugs) → review+
Comment on attachment 8918762 [details] Bug 1407810 - Use DDLogger in media stack - https://reviewboard.mozilla.org/r/189612/#review210930 ::: dom/html/HTMLAudioElement.cpp:33 (Diff revision 2) > NS_IMPL_ELEMENT_CLONE(HTMLAudioElement) > > HTMLAudioElement::HTMLAudioElement(already_AddRefed<NodeInfo>& aNodeInfo) > : HTMLMediaElement(aNodeInfo) > { > + DecoderDoctorLogger::LogConstruction(this); Isn't it enough to just call LogConstruction/LogDestruction in the ctor/dtor of HTMLMediaElement? ::: dom/html/HTMLMediaElement.cpp:1812 (Diff revision 2) > > RemoveMediaElementFromURITable(); > mLoadingSrc = nullptr; > mLoadingSrcTriggeringPrincipal = nullptr; > + DDLOG(DDLogCategory::Property, "loading_src", ""); > + DDUNLINKCHILD(mMediaSource.get()); Is it OK when mMediaSource.get() is already null? ::: dom/html/HTMLMediaElement.cpp:2415 (Diff revision 2) > RemoveMediaElementFromURITable(); > mLoadingSrc = uri; > mLoadingSrcTriggeringPrincipal = childSrc->GetSrcTriggeringPrincipal(); > + DDLOG(DDLogCategory::Property, > + "loading_src", > + nsCString(NS_ConvertUTF16toUTF8(src))); It might be handy to add an EagerLogValue overload which takes nsAString so we can omit NS_ConvertUTF16toUTF8(). ::: dom/media/ChannelMediaDecoder.cpp:83 (Diff revision 2) > MOZ_ASSERT(NS_IsMainThread()); > + DDLOGEX2("ChannelMediaDecoder::ResourceCallback", > + this, > + DDLogCategory::Log, > + "network_error", > + DDNoValue{}); Might be worth passing aError.Description() instead. ::: dom/media/ChannelMediaDecoder.cpp:269 (Diff revision 2) > mResource = > BaseMediaResource::Create(mResourceCallback, aChannel, aIsPrivateBrowsing); > if (!mResource) { > return NS_ERROR_FAILURE; > } > + DecoderDoctorLogger::LinkParentAndChild( This is already done in ChannelMediaDecoder::ResourceCallback::Connect(). Do we still need it here? ::: dom/media/ChannelMediaDecoder.cpp:296 (Diff revision 2) > > mResource = aOriginal->CloneData(mResourceCallback); > if (!mResource) { > return NS_ERROR_FAILURE; > } > + DecoderDoctorLogger::LinkParentAndChild( Ditto. ::: dom/media/MediaDecoder.h:85 (Diff revision 2) > } > }; > > -class MediaDecoder > +DDLoggedTypeDeclName(MediaDecoder); > + > +class MediaDecoder : public DecoderDoctorLifeLogger<MediaDecoder> Notify Chris since this change might affect the Servo porting. ::: dom/media/MediaFormatReader.cpp:568 (Diff revision 2) > - }, > + }, > - [type, this, p, d](const MediaResult& aError) { > + [type, this, p, d](const MediaResult& aError) { > + DDLOGEX2("MediaFormatReader::DecoderData", > + this, > + DDLogCategory::Log, > + "flushing_error", "flush_error". ::: dom/media/MediaFormatReader.cpp:783 (Diff revision 2) > mOwner->NotifyError(aData.mTrack, rv); > return; > } > > aData.mDecoder = new Wrapper(aData.mDecoder.forget(), aData.mToken.forget()); > + DecoderDoctorLogger::LinkParentAndChild( aData should be the parent instead of DecoderFactory. ::: dom/media/MediaFormatReader.cpp:1335 (Diff revision 2) > , mFrameStats(aInit.mFrameStats) > , mMediaDecoderOwnerID(aInit.mMediaDecoderOwnerID) > { > MOZ_ASSERT(aDemuxer); > MOZ_COUNT_CTOR(MediaFormatReader); > + DecoderDoctorLogger::LinkParentAndChild( Why not using the DDLINKCHILD macro? ::: dom/media/MediaFormatReader.cpp:2038 (Diff revision 2) > aSamples->mSamples[0]->mTrackInfo > ? aSamples->mSamples[0]->mTrackInfo->GetID() > : 0); > + DDLOG(DDLogCategory::Log, > + "audio_demuxed_samples", > + uint64_t(aSamples->mSamples.Length())); Why explicit casting is needed? ::: dom/media/mp4/MP4Demuxer.cpp:156 (Diff revision 2) > > RefPtr<BufferStream> bufferstream = > new BufferStream(initData.Ref()); > > MP4Metadata metadata{bufferstream}; > + DDLINKCHILD("metadata", &metadata); I won't count |metadata| as a child since it is a temp variable.
Attachment #8918762 - Flags: review?(jwwang) → review+
Comment on attachment 8934397 [details] Bug 1407810 - DDMediaLogs::SizeOf accounts for shallow message queue size - https://reviewboard.mozilla.org/r/205318/#review210942 ::: dom/media/doctor/MultiWriterQueue.h:491 (Diff revision 1) > // visible to readers. > Atomic<Buffer*, ReleaseAcquire> mReusableBuffers; > > // Template-provided locking mechanism to protect PopAll()-only member > // variables below. > - ReaderLocking mReaderLocking; > + mutable ReaderLocking mReaderLocking; Why 'mutable'?
Attachment #8934397 - Flags: review?(jwwang) → review+
Comment on attachment 8934398 [details] Bug 1407810 - Enable DDLogging from the beginning if MOZ_LOG contains DDLogger - https://reviewboard.mozilla.org/r/205320/#review210944
Attachment #8934398 - Flags: review?(jwwang) → review+
Comment on attachment 8918763 [details] Bug 1407810 - DDMOZ_LOG to replace MOZ_LOG and also output to DDLogger - https://reviewboard.mozilla.org/r/189614/#review210946
Attachment #8918763 - Flags: review?(jwwang) → review+
Comment on attachment 8918764 [details] Bug 1407810 - Use DDMOZ_LOG in media stack - https://reviewboard.mozilla.org/r/189616/#review210950 ::: dom/media/MediaDecoderStateMachine.cpp:89 (Diff revision 2) > + DDMOZ_LOG(gMediaDecoderLog, \ > + LogLevel::Verbose, \ > + "Decoder=%p " x, \ > + mDecoderID, \ > + ##__VA_ARGS__) > +#define FMT(x, ...) "MDSM=%p Decoder=%p " x, this, mDecoderID, ##__VA_ARGS__ Why adding 'MDSM=%p'? 'Decoder=%p' is enough to tell us which decoder this MDSM belongs to. Adding 'MDSM=%p' gives us just noise instead of information. ::: dom/media/MediaDecoderStateMachine.cpp:102 (Diff revision 2) > + LogLevel::Debug, \ > + "state=%s " x, \ > + ToStateStr(GetState()), \ > + ##__VA_ARGS__) > +#define SFMT(x, ...) \ > + "MDSM=%p Decoder=%p state=%s " x, mMaster, mMaster->mDecoderID, \ Ditto. ::: dom/media/mediasource/MediaSource.cpp:409 (Diff revision 2) > DecoderDoctorDiagnostics diagnostics; > nsresult rv = IsTypeSupported(aType, &diagnostics); > nsCOMPtr<nsPIDOMWindowInner> window = do_QueryInterface(aOwner.GetAsSupports()); > diagnostics.StoreFormatDiagnostics(window ? window->GetExtantDoc() : nullptr, > aType, NS_SUCCEEDED(rv), __func__); > -#define this nullptr > + MSE_STATIC_API("IsTypeSupported(aType=%s) %s", Since this is used only once, we might just call MOZ_LOG() instead of defining a new macro.
Attachment #8918764 - Flags: review?(jwwang) → review+
Comment on attachment 8918763 [details] Bug 1407810 - DDMOZ_LOG to replace MOZ_LOG and also output to DDLogger - https://reviewboard.mozilla.org/r/189614/#review211270 ::: dom/media/doctor/DecoderDoctorLogger.h:199 (Diff revision 2) > + aSubjectPointer, > + CategoryForMozLogLevel(aLogLevel), > + aLogModule->Name(), // LogModule name as label. > + DDLogValue{ nsCString{ aString } }); > + // Don't even call MOZ_LOG on Android non-release/beta; See Logging.h. > +#if !defined(ANDROID) || !defined(RELEASE_OR_BETA) Why this #if is needed? Won't MOZ_LOG expand to nothing if MOZ_LOGGING_ENABLED is false?
Comment on attachment 8934397 [details] Bug 1407810 - DDMediaLogs::SizeOf accounts for shallow message queue size - https://reviewboard.mozilla.org/r/205318/#review210942 Thanks for the further reviews. > Why 'mutable'? My guess is that there may have been some code that needed to access lock-protected members from a const method (probably when gathering statistics). But there is no need now, so I'll remove it to avoid confusion.
Comment on attachment 8918762 [details] Bug 1407810 - Use DDLogger in media stack - https://reviewboard.mozilla.org/r/189612/#review210930 > Isn't it enough to just call LogConstruction/LogDestruction in the ctor/dtor of HTMLMediaElement? The con/des logs from HTMLMediaElement only tell us it's a media element! So we need these extra logs from the derived class, to know the actual concrete type of a media element. E.g., in the output it will allow showing something like: "dom::HTMLVideoElement[134073800]#1 (as dom::HTMLMediaElement)". And it's the same for all other class hierarchies, e.g. "MediaSourceDecoder[136078200]#5 (as MediaDecoder)". > Is it OK when mMediaSource.get() is already null? Yes, there's a nullptr check in the unlink functions. > It might be handy to add an EagerLogValue overload which takes nsAString so we can omit NS_ConvertUTF16toUTF8(). I tried that, but because of the existing catch-all `template<T> EagerLogValue(..., T&&)`, I would need to declare all possible types fairly exactly. E.g., I added `EagerLogValue(..., const nsAString&)`, but it was ignored when trying to call it with an nsAutoString! So I'll defer this (if still wanted) to another bug -- I'm even thinking that EagerLogValue could be simplified, and DDLogValue should handle the extra accepted types directly. > Might be worth passing aError.Description() instead. Good idea. I can even just pass `aError`, as DDLogValue accepts MediaResult's. > This is already done in ChannelMediaDecoder::ResourceCallback::Connect(). Do we still need it here? This line doesn't make sense: It thinks `this` is a ChannelMediaDecoder::ResourceCallback. I'm guessing I wrote this before one of your many refactorings! I'll replace it with a simple DDLINK. The LinkParentAndChild in ResourceCallback::Connect is still needed, to link the callback object with its owning ChannelMediaDecoder. > Why explicit casting is needed? Because otherwise the build fails, at least on Mac! Among other types, DDLogValue accepts uint32_t and uint64_t. They are aliases respectively for `unsigned` and `unsigned long long`. nsTArray::Length() returns size_t, which is `unsigned long`, and therefore doesn't correspond to the other two; hence the need for an explicit cast. Adding size_t or `unsigned long` to DDLogValue's Variant would not work either, as on some platforms size_t *is* uint32_t, so we'd have twice the same type in the Variant, leading to other issues when accessing them. It would probably be possible to have some template magic to add size_t only when it's a distinct type, but it feels much more complicated than just adding this cast in a few DDLog calls. > I won't count |metadata| as a child since it is a temp variable. It is indeed a temp variable, however I think it's important to keep track of it: Its type MP4Metadata is already tracked (construction, destruction, linking to the stream, and more logging). In order to associate the logs from this metadata object to the correct media element, we need to create a link to another associated object; in this case I'm linking the metadata to its creator and sole user MP4Demuxer. Maybe 'parent'/'child' is confusing the matter? In some cases, it's just meant as 'source'/'target', i.e., just a directed link with no strong parent/child meaning. (And in fact the link direction is not used during processing, it's only exposed as extra information for the human reader of the logs, in case they care about the direction.) Names could be changed in another bug. ;-)
Comment on attachment 8918764 [details] Bug 1407810 - Use DDMOZ_LOG in media stack - https://reviewboard.mozilla.org/r/189616/#review210950 > Why adding 'MDSM=%p'? 'Decoder=%p' is enough to tell us which decoder this MDSM belongs to. Adding 'MDSM=%p' gives us just noise instead of information. It was to match the output with what DDMOZ_LOG produces. But if you don't need it, I'll remove it.
(In reply to JW Wang [:jwwang] [:jw_wang] from comment #29) > Comment on attachment 8918762 [details] > Bug 1407810 - Use DDLogger in media stack - > > https://reviewboard.mozilla.org/r/189612/#review210930 > > ::: dom/media/MediaDecoder.h > -class MediaDecoder > > +class MediaDecoder : public DecoderDoctorLifeLogger<MediaDecoder> > > Notify Chris since this change might affect the Servo porting. Chris, consider yourself notified! In particular https://reviewboard.mozilla.org/r/189612/ modifies a lot of media classes, usually adding `DecoderDoctorLifeLogger` as a base CRTP class (which has no data, it's only used to track constructions and destructions), except for inner classes where I modify the constructors&destructors. Please let me know if there are any concerns related to your servo port. I'd be happy to delay landing, and discuss next week in Austin.
Flags: needinfo?(cpearce)
I've talked with Chris, he didn't think there should be any issues, as DDLogger doesn't rely on nsDocument or other problematic-to-import classes.
Flags: needinfo?(cpearce)
Pushed by gsquelart@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/5a46043493c8 Make DecoderDoctorLogger::sLogState 'ReleaseAcquire' - r=jwwang https://hg.mozilla.org/integration/autoland/rev/33286af56de7 Tweak atomics in MultiWriterQueue - r=jwwang https://hg.mozilla.org/integration/autoland/rev/11d29f2ac55d DDMediaLogs::SizeOf accounts for shallow message queue size - r=jwwang https://hg.mozilla.org/integration/autoland/rev/ce2d2aa44948 Enable DDLogging from the beginning if MOZ_LOG contains DDLogger - r=jwwang https://hg.mozilla.org/integration/autoland/rev/ee5648a75a04 Implement HTMLMediaElement::Moz{Enable,Request}DebugLog - r=jwwang https://hg.mozilla.org/integration/autoland/rev/2628267820ff webidl for HTMLMediaElement.mozRequestDebugLog - r=jwwang,smaug https://hg.mozilla.org/integration/autoland/rev/bce6b611bced Use DDLogger in media stack - r=jwwang https://hg.mozilla.org/integration/autoland/rev/7867f6cde036 DDMOZ_LOG to replace MOZ_LOG and also output to DDLogger - r=jwwang https://hg.mozilla.org/integration/autoland/rev/dca4b9b236d7 Use DDMOZ_LOG in media stack - r=jwwang
Depends on: 1501982
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: