Bug 1859025: Add some profiler markers as guideposts for what's going on during long print operations. r=profiler-reviewers,canaltinova

This patch adds a new layout profiling sub-category "LAYOUT_Printing" for the
markers added here.

I'm adding an "interval"-type marker ("AUTO_PROFILER_MARKER_TEXT") for the
function-calls that seem likely to occupy measurable amounts of time (due to
touching the filesystem or printer driver), vs. single-point-in-time markers
("PROFILER_MARKER_TEXT") for functions whose duration isn't particularly long
or interesting, or whose durations we're already measuring with other
closely-associated interval-markers.

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

dom/html/HTMLCanvasElement.cpp

@@ -34,6 +34,7 @@
 #include "mozilla/MouseEvents.h"
 #include "mozilla/Preferences.h"
 #include "mozilla/ProfilerLabels.h"
+#include "mozilla/ProfilerMarkers.h"
 #include "mozilla/StaticPrefs_privacy.h"
 #include "mozilla/Telemetry.h"
 #include "mozilla/webgpu/CanvasContext.h"
@@ -649,6 +650,8 @@ nsresult HTMLCanvasElement::DispatchPrintCallback(nsITimerCallback* aCallback) {
 }
 
 void HTMLCanvasElement::CallPrintCallback() {
+  AUTO_PROFILER_MARKER_TEXT("HTMLCanvasElement Printing", LAYOUT_Printing, {},
+                            "HTMLCanvasElement::CallPrintCallback"_ns);
   if (!mPrintState) {
     // `mPrintState` might have been destroyed by cancelling the previous
     // printing (especially the canvas frame destruction) during processing

gfx/src/nsDeviceContext.cpp

@@ -14,7 +14,8 @@
 #include "mozilla/gfx/PathHelpers.h"
 #include "mozilla/gfx/PrintTarget.h"
 #include "mozilla/Preferences.h"  // for Preferences
-#include "mozilla/Services.h"     // for GetObserverService
+#include "mozilla/ProfilerMarkers.h"
+#include "mozilla/Services.h"  // for GetObserverService
 #include "mozilla/StaticPrefs_layout.h"
 #include "mozilla/Try.h"            // for MOZ_TRY
 #include "mozilla/mozalloc.h"       // for operator new
@@ -269,6 +270,8 @@ nsresult nsDeviceContext::BeginDocument(const nsAString& aTitle,
                                         int32_t aStartPage, int32_t aEndPage) {
   MOZ_DIAGNOSTIC_ASSERT(!mIsCurrentlyPrintingDoc,
                         "Mismatched BeginDocument/EndDocument calls");
+  AUTO_PROFILER_MARKER_TEXT("DeviceContext Printing", LAYOUT_Printing, {},
+                            "nsDeviceContext::BeginDocument"_ns);
 
   nsresult rv = mPrintTarget->BeginPrinting(aTitle, aPrintToFileName,
                                             aStartPage, aEndPage);
@@ -292,6 +295,8 @@ RefPtr<PrintEndDocumentPromise> nsDeviceContext::EndDocument() {
   MOZ_DIAGNOSTIC_ASSERT(mIsCurrentlyPrintingDoc,
                         "Mismatched BeginDocument/EndDocument calls");
   MOZ_DIAGNOSTIC_ASSERT(mPrintTarget);
+  AUTO_PROFILER_MARKER_TEXT("DeviceContext Printing", LAYOUT_Printing, {},
+                            "nsDeviceContext::EndDocument"_ns);
 
   mIsCurrentlyPrintingDoc = false;
 
@@ -315,6 +320,8 @@ RefPtr<PrintEndDocumentPromise> nsDeviceContext::EndDocument() {
 nsresult nsDeviceContext::AbortDocument() {
   MOZ_DIAGNOSTIC_ASSERT(mIsCurrentlyPrintingDoc,
                         "Mismatched BeginDocument/EndDocument calls");
+  AUTO_PROFILER_MARKER_TEXT("DeviceContext Printing", LAYOUT_Printing, {},
+                            "nsDeviceContext::AbortDocument"_ns);
 
   nsresult rv = mPrintTarget->AbortPrinting();
   mIsCurrentlyPrintingDoc = false;
@@ -331,6 +338,9 @@ nsresult nsDeviceContext::AbortDocument() {
 nsresult nsDeviceContext::BeginPage(const IntSize& aSizeInPoints) {
   MOZ_DIAGNOSTIC_ASSERT(!mIsCurrentlyPrintingDoc || mPrintTarget,
                         "What nulled out our print target while printing?");
+  AUTO_PROFILER_MARKER_TEXT("DeviceContext Printing", LAYOUT_Printing, {},
+                            "nsDeviceContext::BeginPage"_ns);
+
   if (mDeviceContextSpec) {
     MOZ_TRY(mDeviceContextSpec->BeginPage(aSizeInPoints));
   }
@@ -343,6 +353,9 @@ nsresult nsDeviceContext::BeginPage(const IntSize& aSizeInPoints) {
 nsresult nsDeviceContext::EndPage() {
   MOZ_DIAGNOSTIC_ASSERT(!mIsCurrentlyPrintingDoc || mPrintTarget,
                         "What nulled out our print target while printing?");
+  AUTO_PROFILER_MARKER_TEXT("DeviceContext Printing", LAYOUT_Printing, {},
+                            "nsDeviceContext::EndPage"_ns);
+
   if (mPrintTarget) {
     MOZ_TRY(mPrintTarget->EndPage());
   }

layout/printing/PrintTranslator.cpp

@@ -10,6 +10,7 @@
 #include "nsDeviceContext.h"
 #include "mozilla/gfx/RecordedEvent.h"
 #include "mozilla/gfx/RecordingTypes.h"
+#include "mozilla/ProfilerMarkers.h"
 #include "mozilla/UniquePtr.h"
 #include "InlineTranslator.h"
 
@@ -26,6 +27,9 @@ PrintTranslator::PrintTranslator(nsDeviceContext* aDeviceContext)
 }
 
 bool PrintTranslator::TranslateRecording(PRFileDescStream& aRecording) {
+  AUTO_PROFILER_MARKER_TEXT("PrintTranslator", LAYOUT_Printing, {},
+                            "PrintTranslator::TranslateRecording"_ns);
+
   uint32_t magicInt;
   ReadElement(aRecording, magicInt);
   if (magicInt != mozilla::gfx::kMagicInt) {

layout/printing/ipc/RemotePrintJobParent.cpp

@@ -10,6 +10,7 @@
 
 #include "gfxContext.h"
 #include "mozilla/Attributes.h"
+#include "mozilla/ProfilerMarkers.h"
 #include "mozilla/Unused.h"
 #include "nsAppDirectoryServiceDefs.h"
 #include "nsComponentManagerUtils.h"
@@ -34,6 +35,9 @@ RemotePrintJobParent::RemotePrintJobParent(nsIPrintSettings* aPrintSettings)
 mozilla::ipc::IPCResult RemotePrintJobParent::RecvInitializePrint(
     const nsAString& aDocumentTitle, const int32_t& aStartPage,
     const int32_t& aEndPage) {
+  PROFILER_MARKER_TEXT("RemotePrintJobParent", LAYOUT_Printing, {},
+                       "RemotePrintJobParent::RecvInitializePrint"_ns);
+
   nsresult rv = InitializePrintDevice(aDocumentTitle, aStartPage, aEndPage);
   if (NS_FAILED(rv)) {
     Unused << SendPrintInitializationResult(rv, FileDescriptor());
@@ -59,6 +63,9 @@ mozilla::ipc::IPCResult RemotePrintJobParent::RecvInitializePrint(
 nsresult RemotePrintJobParent::InitializePrintDevice(
     const nsAString& aDocumentTitle, const int32_t& aStartPage,
     const int32_t& aEndPage) {
+  AUTO_PROFILER_MARKER_TEXT("RemotePrintJobParent", LAYOUT_Printing, {},
+                            "RemotePrintJobParent::InitializePrintDevice"_ns);
+
   nsresult rv;
   nsCOMPtr<nsIDeviceContextSpec> deviceContextSpec =
       do_CreateInstance("@mozilla.org/gfx/devicecontextspec;1", &rv);
@@ -94,6 +101,9 @@ nsresult RemotePrintJobParent::InitializePrintDevice(
 }
 
 nsresult RemotePrintJobParent::PrepareNextPageFD(FileDescriptor* aFd) {
+  AUTO_PROFILER_MARKER_TEXT("RemotePrintJobParent", LAYOUT_Printing, {},
+                            "RemotePrintJobParent::PrepareNextPageFD"_ns);
+
   PRFileDesc* prFd = nullptr;
   nsresult rv = NS_OpenAnonymousTemporaryFile(&prFd);
   if (NS_FAILED(rv)) {
@@ -108,6 +118,8 @@ nsresult RemotePrintJobParent::PrepareNextPageFD(FileDescriptor* aFd) {
 mozilla::ipc::IPCResult RemotePrintJobParent::RecvProcessPage(
     const int32_t& aWidthInPoints, const int32_t& aHeightInPoints,
     nsTArray<uint64_t>&& aDeps) {
+  PROFILER_MARKER_TEXT("RemotePrintJobParent", LAYOUT_Printing, {},
+                       "RemotePrintJobParent::RecvProcessPage"_ns);
   if (!mCurrentPageStream.IsOpen()) {
     Unused << SendAbortPrint(NS_ERROR_FAILURE);
     return IPC_OK();
@@ -154,6 +166,8 @@ nsresult RemotePrintJobParent::PrintPage(
     const gfx::IntSize& aSizeInPoints, PRFileDescStream& aRecording,
     gfx::CrossProcessPaint::ResolvedFragmentMap* aFragments) {
   MOZ_ASSERT(mPrintDeviceContext);
+  AUTO_PROFILER_MARKER_TEXT("RemotePrintJobParent", LAYOUT_Printing, {},
+                            "RemotePrintJobParent::PrintPage"_ns);
 
   nsresult rv = mPrintDeviceContext->BeginPage(aSizeInPoints);
   if (NS_WARN_IF(NS_FAILED(rv))) {
@@ -233,6 +247,9 @@ static void Cleanup(const nsCOMArray<nsIWebProgressListener>& aListeners,
 }
 
 mozilla::ipc::IPCResult RemotePrintJobParent::RecvFinalizePrint() {
+  PROFILER_MARKER_TEXT("RemotePrintJobParent", LAYOUT_Printing, {},
+                       "RemotePrintJobParent::RecvFinalizePrint"_ns);
+
   // EndDocument is sometimes called in the child even when BeginDocument has
   // not been called. See bug 1223332.
   if (mPrintDeviceContext) {
@@ -263,6 +280,9 @@ mozilla::ipc::IPCResult RemotePrintJobParent::RecvFinalizePrint() {
 
 mozilla::ipc::IPCResult RemotePrintJobParent::RecvAbortPrint(
     const nsresult& aRv) {
+  PROFILER_MARKER_TEXT("RemotePrintJobParent", LAYOUT_Printing, {},
+                       "RemotePrintJobParent::RecvAbortPrint"_ns);
+
   // Leave the cleanup to `ActorDestroy()`.
   Unused << Send__delete__(this);
   return IPC_OK();
@@ -271,6 +291,8 @@ mozilla::ipc::IPCResult RemotePrintJobParent::RecvAbortPrint(
 mozilla::ipc::IPCResult RemotePrintJobParent::RecvProgressChange(
     const long& aCurSelfProgress, const long& aMaxSelfProgress,
     const long& aCurTotalProgress, const long& aMaxTotalProgress) {
+  PROFILER_MARKER_TEXT("RemotePrintJobParent", LAYOUT_Printing, {},
+                       "RemotePrintJobParent::RecvProgressChange"_ns);
   // Our progress follows that of `RemotePrintJobChild` closely enough - forward
   // it instead of keeping more state variables here.
   for (auto* listener : mPrintProgressListeners) {
@@ -283,6 +305,8 @@ mozilla::ipc::IPCResult RemotePrintJobParent::RecvProgressChange(
 
 mozilla::ipc::IPCResult RemotePrintJobParent::RecvStatusChange(
     const nsresult& aStatus) {
+  PROFILER_MARKER_TEXT("RemotePrintJobParent", LAYOUT_Printing, {},
+                       "RemotePrintJobParent::RecvProgressChange"_ns);
   if (NS_FAILED(aStatus)) {
     // Remember the failure status for cleanup to forward to listeners.
     mStatus = aStatus;

layout/printing/nsPagePrintTimer.cpp

@@ -7,6 +7,7 @@
 #include "nsPagePrintTimer.h"
 
 #include "mozilla/dom/Document.h"
+#include "mozilla/ProfilerMarkers.h"
 #include "mozilla/Unused.h"
 #include "nsPrintJob.h"
 #include "nsPrintObject.h"
@@ -148,6 +149,10 @@ nsPagePrintTimer::Notify(nsITimer* timer) {
     }
   } else if (timer == mWatchDogTimer) {
     mWatchDogCount++;
+    PROFILER_MARKER_TEXT(
+        "nsPagePrintTimer::Notify", LAYOUT_Printing, {},
+        nsPrintfCString("Watchdog Timer Count %d", mWatchDogCount));
+
     if (mWatchDogCount > WATCH_DOG_MAX_COUNT) {
       Fail();
       return NS_OK;
@@ -211,6 +216,8 @@ void nsPagePrintTimer::Stop() {
 
 void nsPagePrintTimer::Fail() {
   NS_WARNING("nsPagePrintTimer::Fail called");
+  PROFILER_MARKER_TEXT("nsPagePrintTimer", LAYOUT_Printing, {},
+                       "nsPagePrintTimer::Fail aborting print operation"_ns);
 
   mDone = true;
   Stop();

layout/printing/nsPrintJob.cpp

@@ -581,6 +581,8 @@ nsresult nsPrintJob::CleanupOnFailure(nsresult aResult, bool aIsPrinting) {
   PR_PL(("****  Failed %s - rv 0x%" PRIX32,
          aIsPrinting ? "Printing" : "Print Preview",
          static_cast<uint32_t>(aResult)));
+  PROFILER_MARKER_TEXT("PrintJob", LAYOUT_Printing, MarkerStack::Capture(),
+                       "nsPrintJob::CleanupOnFailure"_ns);
 
   /* cleanup... */
   if (mPagePrintTimer) {

mozglue/baseprofiler/build/profiling_categories.yaml

@@ -114,6 +114,8 @@
       label: Style computation
     - name: LAYOUT_Destroy
       label: Layout cleanup
+    - name: LAYOUT_Printing
+      label: Printing
 
 - name: JS
   label: JavaScript