1543403 - Normandy hangs the browser UI for over one second when verifying signatures

Status: RESOLVED FIXED

(Firefox :: Normandy Client, defect, P2)

Description

[Markus Stange [:mstange]]

Profile: https://perfht.ml/2VARfOm

I just encountered a one second UI freeze in a local build. The profile shows time spent in verifyObjectSignature, which runs on the main thread of the parent process.

This function was added in bug 1538248, so I'm tentatively marking this bug as a regression from that bug.

Comment 1

[Mathieu Leplatre [:leplatrem]]

verifyObjectSignature() was just extracted in bug 1538248, but I would say that the real issue is bug 1540642

Comment 2

[:Gijs (he/him)]

(In reply to Mathieu Leplatre [:leplatrem] from comment #1)

verifyObjectSignature() was just extracted in bug 1538248, but I would say that the real issue is bug 1540642

I don't know that that's true. If you look at the hang in the profile as a flame graph, and compare the implementation of verifyobjectsignature:

ContentSignatureVerifier::VerifyContentSignature(const nsACString& aData,
                                                 const nsACString& aCSHeader,
                                                 const nsACString& aCertChain,
                                                 const nsACString& aName,
                                                 bool* _retval) {
  NS_ENSURE_ARG(_retval);
  nsresult rv = CreateContext(aData, aCSHeader, aCertChain, aName);
  if (NS_FAILED(rv)) {
    /* elided */;
    return; // early
  }

  return End(_retval);
}

We spend the first 57% of hang in CreateContextInternal(), and then the remaining time in VFY_EndWithSignature.

So what I'm saying is, this is one call to verifyContentSignature. If there were multiple calls, you'd see alternating samples for the stuff going on inside VerifyContentSignature. Coalescing calls or reusing the context (which is what bug 1540642 is about) wouldn't really help for this case because we're only calling it once.

It'd be more interesting to understand why this 1s freeze happens. Mark, looks like you created some of this code, does the profile tell you anything? Anything else Markus may be able to provide that'd help figure out what's so expensive here?

We can obviously attempt to move this off the main thread (with some amount of cost in terms of copying buffers etc. around, and potentially with some difficulty depending on how threadsafe the underlying NSS bits are) but if it takes whatever thread does the work 1s that still seems a bit sad generally...

Comment 3

[:Gijs (he/him)]

Oh, never mind comment #2, it turns out the flame graph isn't actually time-sequential, as I assumed. The stack graph is, and that does show we're verifying a whole bunch of things. So yes, coalescing things (fixing bug 1540642) should help.

Comment 4

[:Gijs (he/him)]

That said, that'd cut the time needed here approximately in half, which still isn't really brilliant...

Comment 5

[Michael Cooper [:mythmon]]

I think this is the same thing we were discussing in bug 1534600. This seems like a duplicate bug to me.

Comment 6

[Jean Gong :jgong]

QF triage team wanted to ask if you know how frequently this code get hits to help us assess how bad the problem is for users.

Comment 7

[Michael Cooper [:mythmon]]

This code currently runs automatically every 6 hours, when Normandy checks the server for new recipes. It uses the same timer as the update service to trigger itself. We are planning to switch to a push-based model in the near future. At that point it would run anytime sometime changes on the server. I don't know how often that is, but my intuition makes me think it would be fairly limited, spiking up to a few times an hour.

Comment 8

[Julien Cristau [:jcristau]]

From bug 1534600 this doesn't seem likely to get fixed in 68.

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

The priority flag is not set for this bug.
:mythmon, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 10

[Michael Cooper [:mythmon]]

Setting to P2 to match the qf priority label.

Comment 11

[Michael Cooper [:mythmon]]

Dana, with bug 1534600 fixed, I expect there isn't a problem here anymore? Or do you think there is more work to be done in Normandy specifically?

Comment 12

[Dana Keeler (she/her) (use needinfo) [:keeler] (on leave)]

I imagine that took care of the issue, but it would probably be good to confirm with a profile.

Comment 13

[Michael Cooper [:mythmon]]

I took a profile of Normandy running at startup, which should be a worst case scenario. https://perfht.ml/2Ez8DfQ

In the original profile, searching for normandy showed 1286ms of time spent in the call tree, most of which is attributable to verifyObjectSignature. In this new profile, I see 56ms of time spent. This seems too good to be true, but I haven't been able to find any other places where time is spent on Normandy code in the profile.