flypig.co.uk

We're continuing to dig deeper into the first paint trigger code today. I've spent a couple of days digging around this already now and it's turning out to be a surprisingly complex investigation. I'm hoping the reward will be worth it, and to be honest, I think it will be: WebView rendering isn't going to work without getting to the bottom of this.

Yesterday we saw that the crucial OnFirstPaint() call was being made from EmbedLiteViewParent::RecvOnFirstPaint(). That's because the QMozViewPrivate class implements the EmbedLiteViewListener interface like this:

class QMozViewPrivate : public QObject,
    public mozilla::embedlite::EmbedLiteViewListener
{
[...]

This listener is set up to get called by EmbedLiteViewParent on receipt of the OnFirstPaint message:

mozilla::ipc::IPCResult EmbedLiteViewParent::RecvOnFirstPaint(const int32_t &aX,
                                                              const int32_t &aY)
{
  LOGT();
  NS_ENSURE_TRUE(mView && !mViewAPIDestroyed, IPC_OK());

  mView->GetListener()->OnFirstPaint(aX, aY);
  return IPC_OK();
}

This is called at the far end of a channel after receipt of a message sent potentially across a thread or process boundary. Sending things across process boundaries like this messes up the backtraces but are otherwise a pretty commonplace in Gecko. We just need to find out where the message is being sent from. Searching the code for where the Send happens is usually the way to go with this, and here it's no different. These send and receive messages are auto-generated from the interface files, so they always follow a strict pattern. A search for a call to SendOnFirstPaint() therefore throws up the following in the ESR 78 code:

NS_IMETHODIMP
EmbedLiteViewChild::OnFirstPaint(int32_t aX, int32_t aY)
{
  if (mDOMWindow) {
    nsCOMPtr<nsIDocShell> docShell = mDOMWindow->GetDocShell();
    if (docShell) {
      RefPtr<PresShell> presShell = docShell->GetPresShell();
      if (presShell) {
        nscolor bgcolor = presShell->GetCanvasBackground();
        Unused << SendSetBackgroundColor(bgcolor);
      }
    }
  }

  return SendOnFirstPaint(aX, aY) ? NS_OK : NS_ERROR_FAILURE;
}

We want to find out where this is called and for that we can use the debugger. Using it gives us the following backtrace.

Thread 7 "GeckoWorkerThre" hit Breakpoint 2, non-virtual thunk to 
    mozilla::embedlite::EmbedLiteViewChild::OnFirstPaint(int, int) ()
    at mobile/sailfishos/embedshared/EmbedLiteViewChild.h:57
57        NS_DECL_NSIEMBEDBROWSERCHROMELISTENER
(gdb) bt
#0  non-virtual thunk to mozilla::embedlite::EmbedLiteViewChild::OnFirstPaint(
    int, int) ()
    at mobile/sailfishos/embedshared/EmbedLiteViewChild.h:57
#1  0x0000007fbb306f38 in WebBrowserChrome::HandleEvent (this=0x7f8ccba130, 
    aEvent=0x7f8dd57a60)
    at mobile/sailfishos/utils/WebBrowserChrome.cpp:443
#2  0x0000007fb9d4b4a0 in mozilla::EventListenerManager::HandleEventSubType (
    this=this@entry=0x7f8ccbd3d0, aListener=<optimized out>, 
    aListener@entry=0x7f8cdb7d78, aDOMEvent=0x7f8dd57a60, 
    aCurrentTarget=<optimized out>, aCurrentTarget@entry=0x7eac138da0)
    at dom/events/EventListenerManager.cpp:1087
#3  0x0000007fb9d4e984 in mozilla::EventListenerManager::HandleEventInternal (
    this=0x7f8ccbd3d0, aPresContext=0x7f8cf82940, aEvent=0x7f8d5c7e80, 
    aDOMEvent=0x7fa7972858, aCurrentTarget=<optimized out>, 
    aEventStatus=<optimized out>, aItemInShadowTree=<optimized out>)
    at dom/events/EventListenerManager.cpp:1279
#4  0x0000007fb9d4f604 in mozilla::EventTargetChainItem::HandleEventTargetChain 
    (aChain=..., aVisitor=..., aCallback=aCallback@entry=0x0, aCd=...)
    at dom/events/EventDispatcher.cpp:558
#5  0x0000007fb9d50eb8 in mozilla::EventDispatcher::Dispatch (
    aTarget=<optimized out>, aPresContext=0x7f8cf82940, aEvent=0x7f8d5c7e80, 
    aDOMEvent=0x7f8dd57a60, aEventStatus=<optimized out>, aCallback=0x0, 
    aTargets=<optimized out>)
    at dom/events/EventDispatcher.cpp:1055
#6  0x0000007fba7f8f50 in nsPresContext::FireDOMPaintEvent (this=0x7f8cf82940, 
    aList=aList@entry=0x7ecc05ae78, aTransactionId=..., aTimeStamp=...)
    at obj-build-mer-qt-xr/dist/include/nsCOMPtr.h:847
#7  0x0000007fba7f9090 in DelayedFireDOMPaintEvent::Run (this=0x7ecc05ae50)
    at obj-build-mer-qt-xr/dist/include/mozilla/RefPtr.h:313
#8  0x0000007fb917d1a8 in nsContentUtils::RemoveScriptBlocker ()
    at dom/base/nsContentUtils.cpp:5407
#9  0x0000007fb917d218 in nsContentUtils::RemoveScriptBlocker ()
    at dom/base/nsContentUtils.cpp:5386
#10 0x0000007fba7fd020 in nsAutoScriptBlocker::~nsAutoScriptBlocker (
    this=<synthetic pointer>, __in_chrg=<optimized out>)
    at dom/base/nsContentUtils.h:3461
#11 nsRootPresContext::<lambda()>::operator() (__closure=0x7f8dd1cfe8)
    at layout/base/nsPresContext.cpp:2825
#12 mozilla::layers::GenericNamedTimerCallback<nsRootPresContext::
    EnsureEventualDidPaintEvent(nsPresContext::TransactionId)::<lambda()> >::
    Notify(nsITimer *) (this=0x7f8dd1cfd0) at obj-build-mer-qt-xr/dist/include/
    mozilla/layers/APZThreadUtils.h:81
#13 0x0000007fb84653e0 in nsTimerImpl::Fire (this=0x7f8cecfb50, aGeneration=1)
    at obj-build-mer-qt-xr/dist/include/mozilla/TimeStamp.h:136
#14 0x0000007fb84654c0 in nsTimerEvent::Run (this=0x7ed4001ab0)
    at obj-build-mer-qt-xr/dist/include/mozilla/RefPtr.h:313
#15 0x0000007fb845e4c4 in nsThread::ProcessNextEvent (aResult=0x7fa7972d77, 
    aMayWait=<optimized out>, this=0x7f8c02f610)
    at xpcom/threads/nsThread.cpp:1211
[...]
#32 0x0000007fbe70b89c in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/
    clone.S:78
(gdb) 

That's a long backtrace but the magic appears to be happening inside a call to DelayedFireDOMPaintEvent() and we can check for this by searching through the code. It gets set up in nsPresContext::NotifyDidPaintForSubtree() inside nsPresContext.cpp where we have the following code, which is basically the same in both ESR 78 and ESR 91. This is a long piece of code, but the important parts are the two calls to DelayedFireDOMPaintEvent() which you can see around the middle and towards the end of the method:

void nsPresContext::NotifyDidPaintForSubtree(
    TransactionId aTransactionId, const mozilla::TimeStamp& aTimeStamp) {
  if (mFirstContentfulPaintTransactionId && !mHadContentfulPaintComposite) {
    if (aTransactionId >= *mFirstContentfulPaintTransactionId) {
      mHadContentfulPaintComposite = true;
      RefPtr<nsDOMNavigationTiming> timing = mDocument->GetNavigationTiming();
      if (timing && !aTimeStamp.IsNull()) {
        timing->NotifyContentfulPaintForRootContentDocument(aTimeStamp);
      }
    }
  }

  if (IsRoot()) {
    static_cast<nsRootPresContext*>(this)->CancelDidPaintTimers(aTransactionId);

    if (mTransactions.IsEmpty()) {
      return;
    }
  }

  if (!PresShell()->IsVisible() && mTransactions.IsEmpty()) {
    return;
  }

  // Non-root prescontexts fire MozAfterPaint to all their descendants
  // unconditionally, even if no invalidations have been collected. This is
  // because we don't want to eat the cost of collecting invalidations for
  // every subdocument (which would require putting every subdocument in its
  // own layer).

  bool sent = false;
  uint32_t i = 0;
  while (i < mTransactions.Length()) {
    if (mTransactions[i].mTransactionId <= aTransactionId) {
      if (!mTransactions[i].mInvalidations.IsEmpty()) {
        nsCOMPtr<nsIRunnable> ev = new DelayedFireDOMPaintEvent(
            this, &mTransactions[i].mInvalidations,
            mTransactions[i].mTransactionId, aTimeStamp);
        nsContentUtils::AddScriptRunner(ev);
        sent = true;
      }
      mTransactions.RemoveElementAt(i);
    } else {
      i++;
    }
  }

  if (!sent) {
    nsTArray<nsRect> dummy;
    nsCOMPtr<nsIRunnable> ev =
        new DelayedFireDOMPaintEvent(this, &dummy, aTransactionId, aTimeStamp);
    nsContentUtils::AddScriptRunner(ev);
  }

As anticipated there's no hit for this method on ESR 91, but on ESR 78 we can get a backtrace:

(gdb) break DelayedFireDOMPaintEvent::DelayedFireDOMPaintEvent
Breakpoint 8 at 0x7fba7fcc8c: DelayedFireDOMPaintEvent::
    DelayedFireDOMPaintEvent. (2 locations)
(gdb) r
[...]
Thread 7 "GeckoWorkerThre" hit Breakpoint 8, 0x0000007fba7fcc8c in 
    DelayedFireDOMPaintEvent::DelayedFireDOMPaintEvent (aTimeStamp=..., 
    aTransactionId=..., aList=<optimized out>, aPresContext=<optimized out>, 
    this=<optimized out>)
    at layout/base/nsPresContext.h:173
173         return mPresShell;
(gdb) bt
#0  0x0000007fba7fcc8c in DelayedFireDOMPaintEvent::DelayedFireDOMPaintEvent (
    aTimeStamp=..., aTransactionId=..., aList=<optimized out>, 
    aPresContext=<optimized out>, this=<optimized out>)
    at layout/base/nsPresContext.h:173
#1  nsPresContext::NotifyDidPaintForSubtree (this=0x7f8ce6dda0, 
    aTransactionId=..., aTimeStamp=...)
    at layout/base/nsPresContext.cpp:2082
#2  0x0000007fba7fd01c in nsRootPresContext::<lambda()>::operator() (
    __closure=0x7f8dc1af58)
    at obj-build-mer-qt-xr/dist/include/mozilla/TimeStamp.h:400
#3  mozilla::layers::GenericNamedTimerCallback<nsRootPresContext::
    EnsureEventualDidPaintEvent(nsPresContext::TransactionId)::<lambda()> >::
    Notify(nsITimer *) (this=0x7f8dc1af40) at obj-build-mer-qt-xr/dist/include/
    mozilla/layers/APZThreadUtils.h:81
#4  0x0000007fb84653e0 in nsTimerImpl::Fire (this=0x7f8c72bfd0, aGeneration=1)
    at obj-build-mer-qt-xr/dist/include/mozilla/TimeStamp.h:136
#5  0x0000007fb84654c0 in nsTimerEvent::Run (this=0x7ecc001ab0)
    at obj-build-mer-qt-xr/dist/include/mozilla/RefPtr.h:313
#6  0x0000007fb845e4c4 in nsThread::ProcessNextEvent (aResult=0x7fa7972d77, 
    aMayWait=<optimized out>, this=0x7f8c02f610)
    at xpcom/threads/nsThread.cpp:1211
#7  nsThread::ProcessNextEvent (this=0x7f8c02f610, aMayWait=<optimized out>, 
    aResult=0x7fa7972d77)
    at xpcom/threads/nsThread.cpp:1047
#8  0x0000007fb845cdcc in NS_ProcessPendingEvents (
    aThread=aThread@entry=0x7f8c02f610, aTimeout=10)
    at xpcom/threads/nsThreadUtils.cpp:449
#9  0x0000007fba63c430 in nsBaseAppShell::NativeEventCallback (
    this=0x7f8c3e6ac0)
    at widget/nsBaseAppShell.cpp:87
#10 0x0000007fba64f0bc in nsAppShell::event (this=<optimized out>, e=<optimized 
    out>)
    at widget/qt/nsAppShell.cpp:75
[...]
#23 0x0000007fbe70b89c in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/
    clone.S:78
(gdb) 

Frustratingly it's called within a lambda function, which is messing up the backtrace yet again. So we'll have to resort to digging through the code again. There we can see that the NotifyDidPaintForSubtree() method gets called in a lambda function that's triggered inside itself. But this can't be the one we're after because we'd have seen the hit on the containing method first.

But there's another case where a lambda function gets configured to then call nsPresContext::NotifyDidPaintForSubtree() and that's in the following method from nsPresContext.cpp (this is the ESR 78 version):

void
nsRootPresContext::EnsureEventualDidPaintEvent(TransactionId aTransactionId)
{
  for (NotifyDidPaintTimer& t : mNotifyDidPaintTimers) {
    if (t.mTransactionId == aTransactionId) {
      return;
    }
  }

  nsCOMPtr<nsITimer> timer;
  RefPtr<nsRootPresContext> self = this;
  nsresult rv = NS_NewTimerWithCallback(
    getter_AddRefs(timer),
    NewNamedTimerCallback([self, aTransactionId](){
      nsAutoScriptBlocker blockScripts;
      self->NotifyDidPaintForSubtree(aTransactionId);
     }, &quot;NotifyDidPaintForSubtree&quot;), 100, nsITimer::TYPE_ONE_SHOT,
    Document()->EventTargetFor(TaskCategory::Other));

  if (NS_SUCCEEDED(rv)) {
    NotifyDidPaintTimer* t = mNotifyDidPaintTimers.AppendElement();
    t->mTransactionId = aTransactionId;
    t->mTimer = timer;
  }
}

That's the only other case I can see, so we could check to find out how this EnsureEventualDidPaintEvent() method gets called. However as I was in the process of configuring the debugger I noticed that this method doesn't exist in ESR 91. That's unexpected. In ESR 78 it's called from nsPresContext::NotifyInvalidation() like this:

void nsPresContext::NotifyInvalidation(TransactionId aTransactionId,
                                       const nsRect& aRect) {
  MOZ_ASSERT(GetContainerWeak(), "Invalidation in detached pres 
    context");

  // If there is no paint event listener, then we don't need to fire
  // the asynchronous event. We don't even need to record invalidation.
  // MayHavePaintEventListener is pretty cheap and we could make it
  // even cheaper by providing a more efficient
  // nsPIDOMWindow::GetListenerManager.

  nsPresContext* pc;
  for (pc = this; pc; pc = pc->GetParentPresContext()) {
    TransactionInvalidations* transaction =
        pc->GetInvalidations(aTransactionId);
    if (transaction) {
      break;
    } else {
      transaction = pc->mTransactions.AppendElement();
      transaction->mTransactionId = aTransactionId;
    }
  }
  if (!pc) {
    nsRootPresContext* rpc = GetRootPresContext();
    if (rpc) {
      rpc->EnsureEventualDidPaintEvent(aTransactionId);
    }
  }

  TransactionInvalidations* transaction = GetInvalidations(aTransactionId);
  MOZ_ASSERT(transaction);
  transaction->mInvalidations.AppendElement(aRect);
}

But as we can see, the call to EnsureEventualDidPaintEvent() has been removed in the ESR 91 version of the same method:

void nsPresContext::NotifyInvalidation(TransactionId aTransactionId,
                                       const nsRect& aRect) {
  MOZ_ASSERT(GetContainerWeak(), "Invalidation in detached pres 
    context");

  // If there is no paint event listener, then we don't need to fire
  // the asynchronous event. We don't even need to record invalidation.
  // MayHavePaintEventListener is pretty cheap and we could make it
  // even cheaper by providing a more efficient
  // nsPIDOMWindow::GetListenerManager.

  nsPresContext* pc;
  for (pc = this; pc; pc = pc->GetParentPresContext()) {
    TransactionInvalidations* transaction =
        pc->GetInvalidations(aTransactionId);
    if (transaction) {
      break;
    } else {
      transaction = pc->mTransactions.AppendElement();
      transaction->mTransactionId = aTransactionId;
    }
  }

  TransactionInvalidations* transaction = GetInvalidations(aTransactionId);
  MOZ_ASSERT(transaction);
  transaction->mInvalidations.AppendElement(aRect);
}

I wasn't expecting that. For completeness, the backtrace from ESR 78 confirms that this is indeed the correct method to be looking at, at least on the ESR 78 side:

Thread 7 "GeckoWorkerThre" hit Breakpoint 9, nsRootPresContext::
    EnsureEventualDidPaintEvent (this=0x7f8ce70330, 
    aTransactionId=aTransactionId@entry=...)
    at layout/base/nsPresContext.cpp:2813
2813    {
(gdb) bt
#0  nsRootPresContext::EnsureEventualDidPaintEvent (this=0x7f8ce70330, 
    aTransactionId=aTransactionId@entry=...)
    at layout/base/nsPresContext.cpp:2813
#1  0x0000007fba7fb480 in nsPresContext::NotifyInvalidation (
    this=this@entry=0x7f8ce70330, aTransactionId=..., aRect=...)
    at layout/base/nsPresContext.cpp:1964
#2  0x0000007fba7fb5d8 in nsPresContext::NotifyInvalidation (
    this=this@entry=0x7f8ce70330, aTransactionId=..., aRect=...)
    at layout/base/nsPresContext.cpp:1927
#3  0x0000007fbaa4dbe4 in nsDisplayList::PaintRoot (
    this=this@entry=0x7fa7971f48, aBuilder=aBuilder@entry=0x7fa7970170, 
    aCtx=aCtx@entry=0x0, 
    aFlags=aFlags@entry=13) at layout/painting/nsDisplayList.cpp:2526
#4  0x0000007fba7d656c in nsLayoutUtils::PaintFrame (
    aRenderingContext=aRenderingContext@entry=0x0, 
    aFrame=aFrame@entry=0x7f8dba5c40, aDirtyRegion=..., 
    aBackstop=aBackstop@entry=4294967295, 
    aBuilderMode=aBuilderMode@entry=nsDisplayListBuilderMode::Painting, 
    aFlags=<optimized out>, 
    aFlags@entry=(nsLayoutUtils::PaintFrameFlags::WidgetLayers | nsLayoutUtils::
    PaintFrameFlags::ExistingTransaction | nsLayoutUtils::PaintFrameFlags::
    NoComposite)) at layout/base/nsLayoutUtils.cpp:4168
#5  0x0000007fba79a258 in mozilla::PresShell::Paint (
    this=this@entry=0x7f8d2dd790, aViewToPaint=aViewToPaint@entry=0x7f8d210390, 
    aDirtyRegion=..., 
    aFlags=aFlags@entry=mozilla::PaintFlags::PaintLayers)
    at layout/base/PresShell.cpp:6254
#6  0x0000007fba6110ac in nsViewManager::ProcessPendingUpdatesPaint (
    this=this@entry=0x7f8d210df0, aWidget=aWidget@entry=0x7f8d210e60)
    at obj-build-mer-qt-xr/dist/include/nsTArray.h:554
#7  0x0000007fba6113c0 in nsViewManager::ProcessPendingUpdatesForView (
    this=this@entry=0x7f8d210df0, aView=<optimized out>, 
    aFlushDirtyRegion=aFlushDirtyRegion@entry=true) at view/nsViewManager.cpp:
    395
#8  0x0000007fba611b50 in nsViewManager::ProcessPendingUpdates (
    this=0x7f8d210df0)
    at view/nsViewManager.cpp:1018
#9  nsViewManager::ProcessPendingUpdates (this=<optimized out>)
    at view/nsViewManager.cpp:1004
#10 0x0000007fba611c0c in nsViewManager::WillPaintWindow (
    this=this@entry=0x7f8d210df0, aWidget=0x7f8d210e60)
    at view/nsViewManager.cpp:664
#11 0x0000007fba611c88 in nsView::WillPaintWindow (this=<optimized out>, 
    aWidget=<optimized out>)
    at view/nsView.cpp:1048
#12 0x0000007fbb2f6344 in mozilla::embedlite::PuppetWidgetBase::Invalidate (
    aRect=..., this=0x7f8d210e60)
    at mobile/sailfishos/embedshared/PuppetWidgetBase.cpp:268
#13 mozilla::embedlite::PuppetWidgetBase::Invalidate (this=0x7f8d210e60, 
    aRect=...)
    at mobile/sailfishos/embedshared/PuppetWidgetBase.cpp:253
#14 0x0000007fbb2ef768 in mozilla::embedlite::EmbedLitePuppetWidget::Show (
    this=0x7f8d210e60, aState=<optimized out>)
    at mobile/sailfishos/embedshared/EmbedLitePuppetWidget.cpp:97
#15 0x0000007fba7f03e8 in nsDocumentViewer::Show (this=0x7f8d15df90)
    at layout/base/nsDocumentViewer.cpp:2132
#16 0x0000007fba7f8b7c in nsPresContext::EnsureVisible (this=0x7f8ce70330)
    at obj-build-mer-qt-xr/dist/include/nsCOMPtr.h:857
#17 0x0000007fba79c114 in mozilla::PresShell::UnsuppressAndInvalidate (
    this=0x7f8d2dd790)
    at obj-build-mer-qt-xr/dist/include/mozilla/RefPtr.h:313
#18 0x0000007fba7a1638 in mozilla::PresShell::ProcessReflowCommands (
    this=this@entry=0x7f8d2dd790, aInterruptible=aInterruptible@entry=false)
    at layout/base/PresShell.cpp:9712
#19 0x0000007fba7a0630 in mozilla::PresShell::DoFlushPendingNotifications (
    this=this@entry=0x7f8d2dd790, aFlush=...)
    at layout/base/PresShell.cpp:4209
[...]
#33 0x0000007fba772840 in mozilla::VsyncRefreshDriverTimer::
    RefreshDriverVsyncObserver::NotifyVsync (this=0x7f8cc9de00, aVsync=...)
    at layout/base/nsRefreshDriver.cpp:644
[...]
#53 0x0000007fbe70b89c in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/
    clone.S:78
(gdb)

Alright, let's rewind back to the top again. We've now reached the point where we know how the OnFirstPaint() method is getting called in ESR 78. And we can see why it's not happening the same way in ESR 91, viz. that the code to call it has been removed from the NotifyInvalidation() method. The next step is to find out why it's been removed and what should be triggering the OnFirstPaint() instead (assuming there is still something).

The best way to investigate this further will be to look a the Bugzilla ticket and associated changeset where this change was made upstream. We've searched for these kinds of changes many times before and now is no different. Here's the log for the change:

$ git log -S EnsureEventualDidPaintEvent -1 -- layout/base/nsPresContext.cpp
commit 1deccd7ac14706ad1849343cfb2b93df191a1c42
Author: Mantaroh Yoshinaga <mantaroh@gmail.com>
Date:   Thu Sep 6 02:21:39 2018 +0000

    Bug 1445570 - Remove EnsureEventualAfterPaint timer. r=tnikkel
    
    MozReview-Commit-ID: C7WICJ5Q0ES
    
    Differential Revision: https://phabricator.services.mozilla.com/D5005
    
    --HG--
    extra : moz-landing-system : lando

After reading through Bug 1445570 and the associated code changes my conclusion is that unravelling this is going to be too complicated for my brain in its current state, so best to let it sink in overnight. I'll pick this up again tomorrow where we'll try to find out what's replacing the trigger that we need in the updated ESR 91 code.

If you'd like to read any of my other gecko diary entries, they're all available on my Gecko-dev Diary page.