From 3a2501e3dcd707412f8ccbfdf06241259e253d2e Mon Sep 17 00:00:00 2001 From: Daniel Holbert Date: Wed, 18 Oct 2023 05:34:50 +0000 Subject: [PATCH] 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 | 3 +++ gfx/src/nsDeviceContext.cpp | 15 +++++++++++- layout/printing/PrintTranslator.cpp | 4 ++++ layout/printing/ipc/RemotePrintJobParent.cpp | 24 +++++++++++++++++++ layout/printing/nsPagePrintTimer.cpp | 7 ++++++ layout/printing/nsPrintJob.cpp | 2 ++ .../build/profiling_categories.yaml | 2 ++ 7 files changed, 56 insertions(+), 1 deletion(-) diff --git a/dom/html/HTMLCanvasElement.cpp b/dom/html/HTMLCanvasElement.cpp index b25edbe71c44..e4fa5513e505 100644 --- a/dom/html/HTMLCanvasElement.cpp +++ b/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 diff --git a/gfx/src/nsDeviceContext.cpp b/gfx/src/nsDeviceContext.cpp index 0171f892b280..28b2c34652f1 100644 --- a/gfx/src/nsDeviceContext.cpp +++ b/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 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 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()); } diff --git a/layout/printing/PrintTranslator.cpp b/layout/printing/PrintTranslator.cpp index dfb8974c7cbb..2929c48bb37a 100644 --- a/layout/printing/PrintTranslator.cpp +++ b/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) { diff --git a/layout/printing/ipc/RemotePrintJobParent.cpp b/layout/printing/ipc/RemotePrintJobParent.cpp index bf9459b8e062..4e4e363a8ab4 100644 --- a/layout/printing/ipc/RemotePrintJobParent.cpp +++ b/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 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&& 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& 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; diff --git a/layout/printing/nsPagePrintTimer.cpp b/layout/printing/nsPagePrintTimer.cpp index 90e39c758fde..a970b0be4ddc 100644 --- a/layout/printing/nsPagePrintTimer.cpp +++ b/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(); diff --git a/layout/printing/nsPrintJob.cpp b/layout/printing/nsPrintJob.cpp index 490be9cb89fb..fbb444c25c44 100644 --- a/layout/printing/nsPrintJob.cpp +++ b/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(aResult))); + PROFILER_MARKER_TEXT("PrintJob", LAYOUT_Printing, MarkerStack::Capture(), + "nsPrintJob::CleanupOnFailure"_ns); /* cleanup... */ if (mPagePrintTimer) { diff --git a/mozglue/baseprofiler/build/profiling_categories.yaml b/mozglue/baseprofiler/build/profiling_categories.yaml index 62fd5d06175b..602974db68b3 100644 --- a/mozglue/baseprofiler/build/profiling_categories.yaml +++ b/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