Bug 1248507 - p5. DecoderDoctorDiagnostics implementation - r=jya,bz draft
authorGerald Squelart <gsquelart@mozilla.com>
Tue, 19 Apr 2016 11:13:20 +1000
changeset 353014 87fa1aec1802da9057f1c622aa8ed5adfaf22d35
parent 353013 7cd4142d7027e3a92e423481af7fecda20dcfe45
child 353015 573b0818d6af71247e7ae59ed70f5bbd70fc36e0
push id15860
push usergsquelart@mozilla.com
push dateTue, 19 Apr 2016 04:00:08 +0000
reviewersjya, bz
bugs1248507
milestone48.0a1
Bug 1248507 - p5. DecoderDoctorDiagnostics implementation - r=jya,bz Minimal implementation of DecoderDoctorDiagnostics. If the Decoder Doctor analysis needs to report something, a notification is logged to the web console, with the media format(s) that cannot be decoded. In this patch, there are only two notification types: "Cannot play" when no decoders are found for any of the requested formats), or "Can play" (if pref "media.decoderdoctor.verbose" is true) when decoders are missing for only some of the requested formats. MozReview-Commit-ID: 4QkiVvcNSU3
dom/base/nsGkAtomList.h
dom/media/DecoderDoctorDiagnostics.cpp
--- a/dom/base/nsGkAtomList.h
+++ b/dom/base/nsGkAtomList.h
@@ -269,16 +269,17 @@ GK_ATOM(datasources, "datasources")
 GK_ATOM(datetime, "datetime")
 GK_ATOM(dblclick, "dblclick")
 GK_ATOM(dd, "dd")
 GK_ATOM(debug, "debug")
 GK_ATOM(decimalFormat, "decimal-format")
 GK_ATOM(decimalSeparator, "decimal-separator")
 GK_ATOM(deck, "deck")
 GK_ATOM(declare, "declare")
+GK_ATOM(decoderDoctor, "decoder-doctor")
 GK_ATOM(decrement, "decrement")
 GK_ATOM(_default, "default")
 GK_ATOM(headerDefaultStyle, "default-style")
 GK_ATOM(defaultAction, "defaultAction")
 GK_ATOM(defaultchecked, "defaultchecked")
 GK_ATOM(defaultLabel, "defaultLabel")
 GK_ATOM(defaultselected, "defaultselected")
 GK_ATOM(defaultvalue, "defaultvalue")
--- a/dom/media/DecoderDoctorDiagnostics.cpp
+++ b/dom/media/DecoderDoctorDiagnostics.cpp
@@ -2,34 +2,373 @@
 /* vim:set ts=2 sw=2 sts=2 et cindent: */
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "DecoderDoctorDiagnostics.h"
 
 #include "mozilla/Logging.h"
+#include "nsGkAtoms.h"
+#include "nsIDocument.h"
+#include "nsITimer.h"
+#include "nsIWeakReference.h"
 
 static mozilla::LazyLogModule sDecoderDoctorLog("DecoderDoctor");
 #define DD_LOG(level, arg, ...) MOZ_LOG(sDecoderDoctorLog, level, (arg, ##__VA_ARGS__))
 #define DD_DEBUG(arg, ...) DD_LOG(mozilla::LogLevel::Debug, arg, ##__VA_ARGS__)
+#define DD_INFO(arg, ...) DD_LOG(mozilla::LogLevel::Info, arg, ##__VA_ARGS__)
 #define DD_WARN(arg, ...) DD_LOG(mozilla::LogLevel::Warning, arg, ##__VA_ARGS__)
 
 namespace mozilla
 {
 
+// Class that collects a sequence of diagnostics from the same document over a
+// small period of time, in order to provide a synthesized analysis.
+//
+// Referenced by the document through a nsINode property, mTimer, and
+// inter-task captures.
+// When notified that the document is dead, or when the timer expires but
+// nothing new happened, StopWatching() will remove the document property and
+// timer (if present), so no more work will happen and the watcher will be
+// destroyed once all references are gone.
+class DecoderDoctorDocumentWatcher : public nsITimerCallback
+{
+public:
+  static RefPtr<DecoderDoctorDocumentWatcher>
+  RetrieveOrCreate(nsIDocument* aDocument);
+
+  NS_DECL_ISUPPORTS
+  NS_DECL_NSITIMERCALLBACK
+
+  void AddDiagnostics(const nsAString& aFormat,
+                      const char* aCallSite,
+                      DecoderDoctorDiagnostics&& aDiagnostics);
+
+private:
+  explicit DecoderDoctorDocumentWatcher(nsIDocument* aDocument);
+  virtual ~DecoderDoctorDocumentWatcher();
+
+  // This will prevent further work from happening, watcher will deregister
+  // itself from document (if requested) and cancel any timer, and soon die.
+  void StopWatching(bool aRemoveProperty);
+
+  // Remove property from document; will call DestroyPropertyCallback.
+  void RemovePropertyFromDocument();
+  // Callback for property destructor, will be automatically called when the
+  // document (in aObject) is being destroyed.
+  static void DestroyPropertyCallback(void* aObject,
+                                      nsIAtom* aPropertyName,
+                                      void* aPropertyValue,
+                                      void* aData);
+
+  static const uint32_t sAnalysisPeriod_ms = 1000;
+  void EnsureTimerIsStarted();
+
+  void ReportAnalysis(const char* aReportStringId,
+                      const nsAString& aFormats);
+
+  void SynthesizeAnalysis();
+
+  // Raw pointer to an nsIDocument.
+  // Must be non-null during construction.
+  // Nulled when we want to stop watching, because either:
+  // 1. The document has been destroyed (notified through
+  //    DestroyPropertyCallback).
+  // 2. We have not received new diagnostic information within a short time
+  //    period, so we just stop watching.
+  // Once nulled, no more actual work will happen, and the watcher will be
+  // destroyed soon.
+  nsIDocument* mDocument;
+
+  struct Diagnostics
+  {
+    Diagnostics(DecoderDoctorDiagnostics&& aDiagnostics,
+                const nsAString& aFormat,
+                const char* aCallSite)
+      : mDecoderDoctorDiagnostics(Move(aDiagnostics))
+      , mFormat(aFormat)
+      , mCallSite(aCallSite)
+    {}
+    Diagnostics(const Diagnostics&) = delete;
+    Diagnostics(Diagnostics&& aOther)
+      : mDecoderDoctorDiagnostics(Move(aOther.mDecoderDoctorDiagnostics))
+      , mFormat(Move(aOther.mFormat))
+      , mCallSite(Move(aOther.mCallSite))
+    {}
+
+    const DecoderDoctorDiagnostics mDecoderDoctorDiagnostics;
+    const nsString mFormat;
+    const nsCString mCallSite;
+  };
+  typedef nsTArray<Diagnostics> DiagnosticsSequence;
+  DiagnosticsSequence mDiagnosticsSequence;
+
+  nsCOMPtr<nsITimer> mTimer; // Keep timer alive until we run.
+  DiagnosticsSequence::size_type mDiagnosticsHandled = 0;
+};
+
+
+NS_IMPL_ISUPPORTS(DecoderDoctorDocumentWatcher, nsITimerCallback)
+
+// static
+RefPtr<DecoderDoctorDocumentWatcher>
+DecoderDoctorDocumentWatcher::RetrieveOrCreate(nsIDocument* aDocument)
+{
+  MOZ_ASSERT(NS_IsMainThread());
+  MOZ_ASSERT(aDocument);
+  RefPtr<DecoderDoctorDocumentWatcher> watcher =
+    static_cast<DecoderDoctorDocumentWatcher*>(
+      aDocument->GetProperty(nsGkAtoms::decoderDoctor));
+  if (!watcher) {
+    watcher = new DecoderDoctorDocumentWatcher(aDocument);
+    if (NS_WARN_IF(NS_FAILED(
+          aDocument->SetProperty(nsGkAtoms::decoderDoctor,
+                                 watcher.get(),
+                                 DestroyPropertyCallback,
+                                 /*transfer*/ false)))) {
+      DD_WARN("DecoderDoctorDocumentWatcher::RetrieveOrCreate(doc=%p) - Could not set property in document, will destroy new watcher[%p]",
+              aDocument, watcher.get());
+      return nullptr;
+    }
+    // Document owns watcher through this property.
+    // Released in DestroyPropertyCallback().
+    NS_ADDREF(watcher.get());
+  }
+  return watcher;
+}
+
+DecoderDoctorDocumentWatcher::DecoderDoctorDocumentWatcher(nsIDocument* aDocument)
+  : mDocument(aDocument)
+{
+  MOZ_ASSERT(NS_IsMainThread());
+  MOZ_ASSERT(mDocument);
+  DD_DEBUG("DecoderDoctorDocumentWatcher[%p]::DecoderDoctorDocumentWatcher(doc=%p)",
+           this, mDocument);
+}
+
+DecoderDoctorDocumentWatcher::~DecoderDoctorDocumentWatcher()
+{
+  MOZ_ASSERT(NS_IsMainThread());
+  DD_DEBUG("DecoderDoctorDocumentWatcher[%p, doc=%p <- expect 0]::~DecoderDoctorDocumentWatcher()",
+           this, mDocument);
+  // mDocument should have been reset through StopWatching()!
+  MOZ_ASSERT(!mDocument);
+}
+
+void
+DecoderDoctorDocumentWatcher::RemovePropertyFromDocument()
+{
+  MOZ_ASSERT(NS_IsMainThread());
+  DecoderDoctorDocumentWatcher* watcher =
+    static_cast<DecoderDoctorDocumentWatcher*>(
+      mDocument->GetProperty(nsGkAtoms::decoderDoctor));
+  if (!watcher) {
+    return;
+  }
+  DD_DEBUG("DecoderDoctorDocumentWatcher[%p, doc=%p]::RemovePropertyFromDocument()\n",
+           watcher, watcher->mDocument);
+  // This will remove the property and call our DestroyPropertyCallback.
+  mDocument->DeleteProperty(nsGkAtoms::decoderDoctor);
+}
+
+// Callback for property destructors. |aObject| is the object
+// the property is being removed for, |aPropertyName| is the property
+// being removed, |aPropertyValue| is the value of the property, and |aData|
+// is the opaque destructor data that was passed to SetProperty().
+// static
+void
+DecoderDoctorDocumentWatcher::DestroyPropertyCallback(void* aObject,
+                                                      nsIAtom* aPropertyName,
+                                                      void* aPropertyValue,
+                                                      void*)
+{
+  MOZ_ASSERT(NS_IsMainThread());
+#ifdef DEBUG
+  nsIDocument* document = static_cast<nsIDocument*>(aObject);
+#endif
+  MOZ_ASSERT(aPropertyName == nsGkAtoms::decoderDoctor);
+  DecoderDoctorDocumentWatcher* watcher =
+    static_cast<DecoderDoctorDocumentWatcher*>(aPropertyValue);
+  MOZ_ASSERT(watcher);
+  MOZ_ASSERT(watcher->mDocument == document);
+  DD_DEBUG("DecoderDoctorDocumentWatcher[%p, doc=%p]::DestroyPropertyCallback()\n",
+           watcher, watcher->mDocument);
+  // 'false': StopWatching should not try and remove the property.
+  watcher->StopWatching(false);
+  NS_RELEASE(watcher);
+}
+
+void
+DecoderDoctorDocumentWatcher::StopWatching(bool aRemoveProperty)
+{
+  MOZ_ASSERT(NS_IsMainThread());
+  // StopWatching() shouldn't be called twice.
+  MOZ_ASSERT(mDocument);
+
+  if (aRemoveProperty) {
+    RemovePropertyFromDocument();
+  }
+
+  // Forget document now, this will prevent more work from being started.
+  mDocument = nullptr;
+
+  if (mTimer) {
+    mTimer->Cancel();
+    mTimer = nullptr;
+  }
+}
+
+void
+DecoderDoctorDocumentWatcher::EnsureTimerIsStarted()
+{
+  MOZ_ASSERT(NS_IsMainThread());
+
+  if (!mTimer) {
+    mTimer = do_CreateInstance(NS_TIMER_CONTRACTID);
+    if (NS_WARN_IF(!mTimer)) {
+      return;
+    }
+    if (NS_WARN_IF(NS_FAILED(
+          mTimer->InitWithCallback(
+            this, sAnalysisPeriod_ms, nsITimer::TYPE_ONE_SHOT)))) {
+      mTimer = nullptr;
+    }
+  }
+}
+
+void
+DecoderDoctorDocumentWatcher::ReportAnalysis(const char* aReportStringId,
+                                             const nsAString& aFormats)
+{
+  MOZ_ASSERT(NS_IsMainThread());
+
+  if (!mDocument) {
+    return;
+  }
+
+  const char16_t* params[] = { aFormats.Data() };
+  DD_DEBUG("DecoderDoctorDocumentWatcher[%p, doc=%p]::ReportAnalysis() ReportToConsole - aMsg='%s' params[0]='%s'",
+           this, mDocument, aReportStringId,
+           NS_ConvertUTF16toUTF8(params[0]).get());
+  nsContentUtils::ReportToConsole(nsIScriptError::warningFlag,
+                                  NS_LITERAL_CSTRING("Media"),
+                                  mDocument,
+                                  nsContentUtils::eDOM_PROPERTIES,
+                                  aReportStringId,
+                                  params,
+                                  ArrayLength(params));
+}
+
+void
+DecoderDoctorDocumentWatcher::SynthesizeAnalysis()
+{
+  MOZ_ASSERT(NS_IsMainThread());
+
+  bool canPlay = false;
+  nsAutoString formats;
+  for (auto& diag : mDiagnosticsSequence) {
+    if (diag.mDecoderDoctorDiagnostics.CanPlay()) {
+      canPlay = true;
+    } else {
+      if (!formats.IsEmpty()) {
+        formats += NS_LITERAL_STRING(", ");
+      }
+      formats += diag.mFormat;
+    }
+  }
+  if (!canPlay) {
+    DD_WARN("DecoderDoctorDocumentWatcher[%p, doc=%p]::Notify() - Cannot play media, formats: %s",
+            this, mDocument, NS_ConvertUTF16toUTF8(formats).get());
+    ReportAnalysis("MediaCannotPlayNoDecoders", formats);
+  } else if (!formats.IsEmpty()) {
+    DD_INFO("DecoderDoctorDocumentWatcher[%p, doc=%p]::Notify() - Can play media, but no decoders for some requested formats: %s",
+            this, mDocument, NS_ConvertUTF16toUTF8(formats).get());
+    if (Preferences::GetBool("media.decoderdoctor.verbose", false)) {
+      ReportAnalysis("MediaNoDecoders", formats);
+    }
+  } else {
+    DD_DEBUG("DecoderDoctorDocumentWatcher[%p, doc=%p]::Notify() - Can play media, decoders available for all requested formats",
+             this, mDocument);
+  }
+}
+
+void
+DecoderDoctorDocumentWatcher::AddDiagnostics(const nsAString& aFormat,
+                                            const char* aCallSite,
+                                            DecoderDoctorDiagnostics&& aDiagnostics)
+{
+  MOZ_ASSERT(NS_IsMainThread());
+
+  if (!mDocument) {
+    return;
+  }
+
+  DD_DEBUG("DecoderDoctorDocumentWatcher[%p, doc=%p]::AddDiagnostics(format='%s', call site '%s', can play=%d)",
+           this, mDocument, NS_ConvertUTF16toUTF8(aFormat).get(),
+           aCallSite, aDiagnostics.CanPlay());
+  mDiagnosticsSequence.AppendElement(
+    Diagnostics(Move(aDiagnostics), aFormat, aCallSite));
+  EnsureTimerIsStarted();
+}
+
+NS_IMETHODIMP
+DecoderDoctorDocumentWatcher::Notify(nsITimer* timer)
+{
+  MOZ_ASSERT(NS_IsMainThread());
+  MOZ_ASSERT(timer == mTimer);
+
+  // Forget timer. (Assuming timer keeps itself and us alive during this call.)
+  mTimer = nullptr;
+
+  if (!mDocument) {
+    return NS_OK;
+  }
+
+  if (mDiagnosticsSequence.Length() > mDiagnosticsHandled) {
+    // We have new diagnostic data.
+    mDiagnosticsHandled = mDiagnosticsSequence.Length();
+
+    SynthesizeAnalysis();
+
+    // Restart timer, to redo analysis or stop watching this document,
+    // depending on whether anything new happens.
+    EnsureTimerIsStarted();
+  } else {
+    DD_DEBUG("DecoderDoctorDocumentWatcher[%p, doc=%p]::Notify() - No new diagnostics to analyze -> Stop watching",
+             this, mDocument);
+    // Stop watching this document, we don't expect more diagnostics for now.
+    // If more diagnostics come in, we'll treat them as another burst, separately.
+    // 'true' to remove the property from the document.
+    StopWatching(true);
+  }
+
+  return NS_OK;
+}
+
+
 void
 DecoderDoctorDiagnostics::StoreDiagnostics(nsIDocument* aDocument,
                                            const nsAString& aFormat,
                                            const char* aCallSite)
 {
+  MOZ_ASSERT(NS_IsMainThread());
   if (NS_WARN_IF(!aDocument)) {
     DD_WARN("DecoderDoctorDiagnostics[%p]::StoreDiagnostics(nsIDocument* aDocument=nullptr, format='%s', call site '%s')",
             this, NS_ConvertUTF16toUTF8(aFormat).get(), aCallSite);
     return;
   }
 
-  // TODO: Actually analyze data.
-  DD_DEBUG("DecoderDoctorDiagnostics[%p]::StoreDiagnostics(nsIDocument* aDocument=%p, format='%s', call site '%s')",
-           this, aDocument, NS_ConvertUTF16toUTF8(aFormat).get(), aCallSite);
+  RefPtr<DecoderDoctorDocumentWatcher> watcher =
+    DecoderDoctorDocumentWatcher::RetrieveOrCreate(aDocument);
+
+  if (NS_WARN_IF(!watcher)) {
+    DD_WARN("DecoderDoctorDiagnostics[%p]::StoreDiagnostics(nsIDocument* aDocument=nullptr, format='%s', call site '%s') - Could not create document watcher",
+            this, NS_ConvertUTF16toUTF8(aFormat).get(), aCallSite);
+    return;
+  }
+
+  // StoreDiagnostics should only be called once, after all data is available,
+  // so it is safe to Move() from this object.
+  watcher->AddDiagnostics(aFormat, aCallSite, Move(*this));
 }
 
 } // namespace mozilla