Bug 1582565 - Log transactions into readable format. r=jrmuizel

Differential Revision: https://phabricator.services.mozilla.com/D46657

--HG--
extra : moz-landing-system : lando

browser/base/content/browser-graphics-utils.js

@@ -10,6 +10,7 @@
  */
 var gGfxUtils = {
   _isRecording: false,
+  _isTransactionLogging: false,
   /**
    * Toggle composition recording for the current window.
    */
@@ -23,4 +24,12 @@ var gGfxUtils = {
   webrenderCapture() {
     window.windowUtils.wrCapture();
   },
+
+  /**
+   * Toggle transaction logging to text file.
+   */
+  toggleTransactionLogging() {
+    window.windowUtils.setTransactionLogging(!this._isTransactionLogging);
+    this._isTransactionLogging = !this._isTransactionLogging;
+  },
 };

browser/base/content/browser-sets.inc

@@ -98,6 +98,7 @@
 #ifdef NIGHTLY_BUILD
     <command id="wrCaptureCmd" oncommand="gGfxUtils.webrenderCapture();"/>
     <command id="windowRecordingCmd" oncommand="gGfxUtils.toggleWindowRecording();"/>
+    <command id="wrTransactionLoggingCmd" oncommand="gGfxUtils.toggleTransactionLogging();"/>
 #endif
 #ifdef XP_MACOSX
     <command id="minimizeWindow"
@@ -331,6 +332,13 @@
     key="$" modifiers="control"
 #endif
     command="windowRecordingCmd"/>
+    <key id="key_transactionLoggingCmd"
+#ifdef XP_MACOSX
+    key="5" modifiers="control,shift"
+#else
+    key="%" modifiers="control"
+#endif
+    command="wrTransactionLoggingCmd"/>
 #endif
 #ifdef XP_MACOSX
     <key id="key_minimizeWindow"

dom/base/nsDOMWindowUtils.cpp

@@ -4069,6 +4069,12 @@ nsDOMWindowUtils::SetCompositionRecording(bool aValue) {
   return NS_OK;
 }
 
+NS_IMETHODIMP
+nsDOMWindowUtils::SetTransactionLogging(bool aValue) {
+  Preferences::SetBool("gfx.webrender.debug.log-transactions", aValue);
+  return NS_OK;
+}
+
 void nsDOMWindowUtils::ReportErrorMessageForWindow(
     const nsAString& aErrorMessage, const char* aClassification,
     bool aFromChrome) {

dom/interfaces/base/nsIDOMWindowUtils.idl

@@ -1917,6 +1917,11 @@ interface nsIDOMWindowUtils : nsISupports {
    */
   void setCompositionRecording(in boolean aValue);
 
+  /**
+   * Toggle transaction logging on and off.
+   */
+  void setTransactionLogging(in boolean aValue);
+
   /**
    * Returns whether the document we're associated to has recorded a given CSS
    * property via the use counter mechanism.

gfx/thebes/gfxPlatform.cpp

@@ -599,6 +599,7 @@ static void WebRenderDebugPrefChangeCallback(const char* aPrefName, void*) {
                       wr::DebugFlags_DISABLE_GRADIENT_PRIMS)
   GFX_WEBRENDER_DEBUG(".obscure-images",
                       wr::DebugFlags_OBSCURE_IMAGES)
+  GFX_WEBRENDER_DEBUG(".log-transactions", wr::DebugFlags_LOG_TRANSACTIONS)
 #undef GFX_WEBRENDER_DEBUG
 
   gfx::gfxVars::SetWebRenderDebugFlags(flags.bits);

gfx/wr/webrender/src/record.rs

@@ -61,6 +61,36 @@ impl ApiRecordingReceiver for BinaryRecorder {
     }
 }
 
+#[derive(Debug)]
+pub struct LogRecorder {
+    file: File,
+}
+
+impl LogRecorder {
+    pub fn new(dest: &PathBuf) -> LogRecorder {
+        let file = File::create(dest).unwrap();
+        LogRecorder { file }
+    }
+}
+
+impl ApiRecordingReceiver for LogRecorder {
+    fn write_msg(&mut self, _: u32, msg: &ApiMsg) {
+        let current_time = time::now_utc();
+        writeln!(self.file, "{}:{}ms - {:?}", current_time.rfc3339(), current_time.tm_nsec / 1000000, msg).unwrap();
+        match *msg {
+            ApiMsg::UpdateDocuments(_, ref msgs) => {
+                for msg in msgs {
+                    writeln!(self.file, "\tTransaction: {:?}", msg).unwrap();
+                }
+            }
+            _ => {},
+        }
+    }
+
+    fn write_payload(&mut self, _: u32, _data: &[u8]) {
+    }
+}
+
 fn should_record_transaction_msg(msgs: &TransactionMsg) -> bool {
     if msgs.generate_frame {
         return true;

gfx/wr/webrender/src/render_backend.rs

@@ -38,6 +38,7 @@ use crate::prim_store::{PrimitiveInstanceKind, PrimTemplateCommonData};
 use crate::prim_store::interned::*;
 use crate::profiler::{BackendProfileCounters, IpcProfileCounters, ResourceProfileCounters};
 use crate::record::ApiRecordingReceiver;
+use crate::record::LogRecorder;
 use crate::render_task_graph::RenderTaskGraphCounters;
 use crate::renderer::{AsyncPropertySampler, PipelineInfo};
 use crate::resource_cache::ResourceCache;
@@ -51,7 +52,6 @@ use crate::scene_builder_thread::*;
 use serde::{Serialize, Deserialize};
 #[cfg(feature = "debugger")]
 use serde_json;
-#[cfg(any(feature = "capture", feature = "replay"))]
 use std::path::PathBuf;
 use std::sync::Arc;
 use std::sync::atomic::{AtomicUsize, Ordering};
@@ -701,6 +701,7 @@ pub struct RenderBackend {
 
     notifier: Box<dyn RenderNotifier>,
     recorder: Option<Box<dyn ApiRecordingReceiver>>,
+    logrecorder: Option<Box<dyn ApiRecordingReceiver>>,
     sampler: Option<Box<dyn AsyncPropertySampler + Send>>,
     size_of_ops: Option<MallocSizeOfOps>,
     debug_flags: DebugFlags,
@@ -742,6 +743,7 @@ impl RenderBackend {
             documents: FastHashMap::default(),
             notifier,
             recorder,
+            logrecorder: None,
             sampler,
             size_of_ops,
             debug_flags,
@@ -954,6 +956,23 @@ impl RenderBackend {
 
             status = match self.api_rx.recv() {
                 Ok(msg) => {
+                    if self.debug_flags.contains(DebugFlags::LOG_TRANSACTIONS) {
+                        if let None = self.logrecorder {
+                            let current_time = time::now_utc().to_local();
+                            let name = format!("wr-log-{}.log",
+                                current_time.strftime("%Y%m%d_%H%M%S").unwrap()
+                            );
+                            self.logrecorder = Some(Box::new(LogRecorder::new(&PathBuf::from(name))))
+                        }
+                    } else {
+                        self.logrecorder = None;
+                    }
+
+                    if let Some(ref mut r) = self.logrecorder {
+                        r.write_msg(frame_counter, &msg);
+                    }
+
+
                     if let Some(ref mut r) = self.recorder {
                         r.write_msg(frame_counter, &msg);
                     }

gfx/wr/webrender_api/src/api.rs

@@ -39,6 +39,35 @@ pub enum ResourceUpdate {
     DeleteFontInstance(font::FontInstanceKey),
 }
 
+impl fmt::Debug for ResourceUpdate {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        match self {
+            ResourceUpdate::AddImage(ref i) => f.write_fmt(format_args!(
+                "ResourceUpdate::AddImage size({:?})",
+                &i.descriptor.size
+            )),
+            ResourceUpdate::UpdateImage(ref i) => f.write_fmt(format_args!(
+                "ResourceUpdate::UpdateImage size({:?})",
+                &i.descriptor.size
+            )),
+            ResourceUpdate::AddBlobImage(ref i) => f.write_fmt(format_args!(
+                "ResourceUpdate::AddBlobImage size({:?})",
+                &i.descriptor.size
+            )),
+            ResourceUpdate::UpdateBlobImage(i) => f.write_fmt(format_args!(
+                "ResourceUpdate::UpdateBlobImage size({:?})",
+                &i.descriptor.size
+            )),
+            ResourceUpdate::DeleteImage(..) => f.write_str("ResourceUpdate::DeleteImage"),
+            ResourceUpdate::SetBlobImageVisibleArea(..) => f.write_str("ResourceUpdate::SetBlobImageVisibleArea"),
+            ResourceUpdate::AddFont(..) => f.write_str("ResourceUpdate::AddFont"),
+            ResourceUpdate::DeleteFont(..) => f.write_str("ResourceUpdate::DeleteFont"),
+            ResourceUpdate::AddFontInstance(..) => f.write_str("ResourceUpdate::AddFontInstance"),
+            ResourceUpdate::DeleteFontInstance(..) => f.write_str("ResourceUpdate::DeleteFontInstance"),
+        }
+    }
+}
+
 /// A Transaction is a group of commands to apply atomically to a document.
 ///
 /// This mechanism ensures that:
@@ -468,6 +497,29 @@ pub struct TransactionMsg {
     pub notifications: Vec<NotificationRequest>,
 }
 
+impl fmt::Debug for TransactionMsg {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        writeln!(f, "threaded={}, genframe={}, invalidate={}, low_priority={}",
+                        self.use_scene_builder_thread,
+                        self.generate_frame,
+                        self.invalidate_rendered_frame,
+                        self.low_priority,
+                    ).unwrap();
+        for scene_op in &self.scene_ops {
+            writeln!(f, "\t\t{:?}", scene_op).unwrap();
+        }
+
+        for frame_op in &self.frame_ops {
+            writeln!(f, "\t\t{:?}", frame_op).unwrap();
+        }
+
+        for resource_update in &self.resource_updates {
+            writeln!(f, "\t\t{:?}", resource_update).unwrap();
+        }
+        Ok(())
+    }
+}
+
 impl TransactionMsg {
     pub fn is_empty(&self) -> bool {
         !self.generate_frame &&
@@ -1088,6 +1140,7 @@ bitflags! {
         const DISABLE_TEXT_PRIMS = 1 << 22;
         const DISABLE_GRADIENT_PRIMS = 1 << 23;
         const OBSCURE_IMAGES = 1 << 24;
+        const LOG_TRANSACTIONS = 1 << 25;
     }
 }
 

modules/libpref/init/all.js

@@ -669,6 +669,7 @@ pref("gfx.webrender.debug.picture-caching", false);
 pref("gfx.webrender.debug.primitives", false);
 pref("gfx.webrender.debug.small-screen", false);
 pref("gfx.webrender.debug.obscure-images", false);
+pref("gfx.webrender.debug.log-transactions", false);
 
 pref("accessibility.warn_on_browsewithcaret", true);