CiviMail compose UI very slow to initialize when many mailing groups, past mailings and templates

Testing a 4.7 upgrade of a big site that's currently live on 4.6.30 . The site has 2.7k mailing groups and 13k non-archived mailings.

The CiviMail compose interface is extremely slow to initialize in the 4.7.23 version of the site. It was fairly slow in 4.6 but much slower in 4.7 . From clicking New Mailing, it's taking well over a minute for the UI to load at all, in Firefox (vs. ~8 sec in 4.6). Almost five minutes for the default From address to populate (vs. ~15 sec in 4.6). During this time, the server is quiet, 99+% idle, no activity showing in MySQL. However Firefox is using 100% CPU throughout.

Eileen McNaughton and Seamus Lee directed me to CRM-20521 / #10303, fixed in 4.7.24, so I tried 4.7.24 next.

After upgrading from 4.7.23 to 4.7.24, it's much faster initially loading the UI: in Firefox, down from over a minute to ~10 sec. However it still takes ~3 mins to set the default From address and ~5 mins for the recipient count to go from "(Estimating)" to "No recipients", at which point the WYSIWYG buttons load. During this time, server is 99-100% idle, MySQL processlist shows empty but Firefox is using 100% CPU.

(Up to this point, I haven't clicked in the mailing UI at all. If I now click the Recipients select, it takes ~2 minutes to populate. So that's actually slower to load the UI + recipients.)

In Chrome, it's a fair bit faster but still tediously slow to finish initialising: ~8 sec to load the UI, ~1 min to set default From address, ~2m15s for recipient "(Estimating)" -> "No recipients" / WYSIWYG load. (On clicking Recipients select, it loaded in a second or so, vs 2 mins in Firefox! I re-tested this in Firefox afterwards and it again took over 2 mins, so a dramatic and consistent difference there.)

The fact that the server is idle but client busy while waiting for the UI to initialise, and that the time is about half on Chrome vs Firefox, puts the blame on the client side. (After selecting recipients, I saw some slow ROLLBACKs in MySQL but that's a separate issue from the slow initialisation time, as no recipients have been selected while initialising and no ROLLBACKs or other queries were seen in MySQL processlist while initialising.)

For comparison, the whole initialisation including loading recipient count & WYSIWYG takes ~20 sec in Firefox or Chrome on the 4.6 version of the same site.

I've investigated with Firebug & with Chrome's network tools to see what's taking the time.

There are 20 AJAX requests that fire before the UI finishes initializing, (the last stages of this being the recipient count changing from "(Estimating)" to "No recipients" and the WYSIWYG editor loading). A few test runs in Chrome, where the whole initialization took 2 minutes, showed some interesting features.

The first 18 AJAX requests completed after 25-30 seconds (from clicking New Mailing), many happening concurrently. There was then a gap of about 55 seconds before the next AJAX request began. The default From address is set after the 18th request completes and before the 19th starts. This 19th request was the slowest, taking approx 35 seconds. The 20th followed as soon as this completed and was quick. So the thing that took the most time (55s) occurred when no requests were in progress - presumably purely client-side processing.

Here are details of the 20 AJAX requests and the time taken, from Chrome dev tools Network tab.

No = request number
Stalled (ms)
TTFB (ms) = Time to first byte - these are mostly ~200ms
CD (ms) = Content Download - times vary greatly.
Explanation of timings.

No  Stalled TTFB  CD    Request
1   2       313   2     Mailing create
2   3       173   1     Mailing getsingle
3   29      196   1     Attachment get
4   23      178   1     MailingGroup get
5   24      243   1     MailingJob get
6   3       278   3250  Mailing getfields
7   4       199   556   Group getlist
8   166     187   658   Group getlist
9   352     173   997   Group getlist
10  524     169   2080  Group getlist
11  692     170   3060  Group getlist
12  6       200   4000  Mailing getlist
13  2       231   4640  Mailing getlist
14  2       189   5380  Mailing getlist
15  2       197   5980  Group getlist
16  3       176   7250  Mailing getlist
17  1       193   9660  Mailing getlist
18  3       231   16450 Mailing getlist
19  16      334   35360 Mailing create
20  3       313   83    Mailing create

One interesting feature there is that the Content Download time increases steadily through requests 7-19.

The Group getlist & Mailing getlist requests 7-18 have another interesting feature: they all return is_error = 1, e.g.

• Params:

action: getlist
entity:    Group
json:    {"params":{"id":{"IN":[]}},"extra":["is_hidden"]}

• Response:

{"is_error":1,"error_message":"invalid criteria for IN"}

Odd that the Content Download time for this 400-byte response is up to 35 seconds! I'm guessing maybe Angular is Very Busy by this point and isn't available to process the incoming response? Though I would have expected Chrome's timings to reflect the time for the browser to receive the response, rather than the time for JS code to process it.

The biggest unknown here is what's happening during the 55 seconds between request 18 completing and request 19 starting.

(Discussed on Mattermost dev channel: https://chat.civicrm.org/civicrm/pl/xnsnzozmw3fyp8xtn89iwtcpqo onwards.)