Embedding loading slow #13472

flamber · 2020-10-14T15:54:39Z

Describe the bug
Loading an embedding is a lot slower on 0.35.0+, and when there's multiple embeds on a page, then it blocks loading for many seconds without showing any indication (spinner etc).
I'm not sure if this is caused by pure JS blockers, or if this is something in the connection handling (Jetty etc). I have tried to debug, but got lost. At least I have found when the problem started.

To Reproduce

Create 8 questions, with embedding enabled. Something simple like SELECT 1 as "Q1", SELECT 2 as "Q2" etc
Example embed loader (rename to .html) and update all the embed URLs

Show HTML code

<!DOCTYPE html>
<html>
<head>
    <title>Metabase Embedding Test</title>
</head>
<body>

<script type="text/javascript">
var startTime = Date.now();
var interval = setInterval(function() {
    var elapsedTime = Date.now() - startTime;
    document.getElementById("timer").innerHTML = (elapsedTime / 1000).toFixed(1);
}, 100);
window.onload = function() { clearInterval(interval); }
</script>
<h1 id="timer"></h1>

<!-- ->

<script type="text/javascript">
  window.onload = function(){
    for (let step = 0; step < 8; step++) {
        var f = document.createElement('iframe');
        f.src = "http://localhost:3001/embed/question/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJxdWVzdGlvbiI6Mjk2fSwicGFyYW1zIjp7fSwiaWF0IjoxNjAxNjQ0ODMxLCJfZW1iZWRkaW5nX3BhcmFtcyI6e319.V20fOWJ1Se9qeNd2lpORHuEMLREkJOE2Nx7fWMg10BY#bordered=true&titled=true";
        f.width = "400"; 
        f.height = "300";
        f.frameborder = "0";
        f.allowtransparency = "true";
        document.body.appendChild(f);
    }
  }
</script>

<!-- -->

<iframe src="http://localhost:3001/embed/question/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJxdWVzdGlvbiI6Mjk2fSwicGFyYW1zIjp7fSwiaWF0IjoxNjAxNjQ0ODMxLCJfZW1iZWRkaW5nX3BhcmFtcyI6e319.V20fOWJ1Se9qeNd2lpORHuEMLREkJOE2Nx7fWMg10BY#bordered=true&titled=true"
        style="border:5px solid red;" onload="this.style.border='5px solid green';"
        width="400"
        height="300"
        allowtransparency></iframe>

<!-- -->

<iframe src="http://localhost:3001/embed/question/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJxdWVzdGlvbiI6Mjk3fSwicGFyYW1zIjp7fSwiaWF0IjoxNjAxNjQ0ODg4LCJfZW1iZWRkaW5nX3BhcmFtcyI6e319.XR744oNUn6sEiLmqGKKuNkLPlLF6OEgrxmAnPy1U6ZM#bordered=true&titled=true"
        style="border:5px solid red;" onload="this.style.border='5px solid green';"
        width="400"
        height="300"
        allowtransparency></iframe>

<iframe src="http://localhost:3001/embed/question/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJxdWVzdGlvbiI6Mjk4fSwicGFyYW1zIjp7fSwiaWF0IjoxNjAxNjQ0OTQzLCJfZW1iZWRkaW5nX3BhcmFtcyI6e319.TPuKIsPht1cZ0Z5c_lD_KbYnSO573l9_kr3pcOr32cI#bordered=true&titled=true"
        style="border:5px solid red;" onload="this.style.border='5px solid green';"
        width="400"
        height="300"
        allowtransparency></iframe>

<iframe src="http://localhost:3001/embed/question/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJxdWVzdGlvbiI6Mjk5fSwicGFyYW1zIjp7fSwiaWF0IjoxNjAxNjQ0OTczLCJfZW1iZWRkaW5nX3BhcmFtcyI6e319.SxQA96xEHOXIuIaNCjoYyaOJva80w95PkVmiXRrhL2I#bordered=true&titled=true"
        style="border:5px solid red;" onload="this.style.border='5px solid green';"
        width="400"
        height="300"
        allowtransparency></iframe>

<iframe src="http://localhost:3001/embed/question/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJxdWVzdGlvbiI6MzAwfSwicGFyYW1zIjp7fSwiaWF0IjoxNjAxNjQ1MDAzLCJfZW1iZWRkaW5nX3BhcmFtcyI6e319.zcDkxlL_hPvSkI5uAzxovxKqa4QY2QrrscfR7eM64m0#bordered=true&titled=true"
        style="border:5px solid red;" onload="this.style.border='5px solid green';"
        width="400"
        height="300"
        allowtransparency></iframe>

<iframe src="http://localhost:3001/embed/question/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJxdWVzdGlvbiI6MzAxfSwicGFyYW1zIjp7fSwiaWF0IjoxNjAxNjQ1MDM2LCJfZW1iZWRkaW5nX3BhcmFtcyI6e319.zawd6wwzv0SEzUHfrOtI1SjpDHdatLKUlZEOUBPV5Cs#bordered=true&titled=true"
        style="border:5px solid red;" onload="this.style.border='5px solid green';"
        width="400"
        height="300"
        allowtransparency></iframe>

<iframe src="http://localhost:3001/embed/question/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJxdWVzdGlvbiI6MzAyfSwicGFyYW1zIjp7fSwiaWF0IjoxNjAxNjQ1MDY0LCJfZW1iZWRkaW5nX3BhcmFtcyI6e319.QD6onB-bYtrEPkIqpPVnnCQWR9JgqpMMJH1zFX_nYDQ#bordered=true&titled=true"
        style="border:5px solid red;" onload="this.style.border='5px solid green';"
        width="400"
        height="300"
        allowtransparency></iframe>

<iframe src="http://localhost:3001/embed/question/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJxdWVzdGlvbiI6MzAzfSwicGFyYW1zIjp7fSwiaWF0IjoxNjAxNjQ1MTMwLCJfZW1iZWRkaW5nX3BhcmFtcyI6e319.SdZYxiDyHjXk0gRbo9Q6q_79gAFaddEYUoTdRB3WZD0#bordered=true&titled=true"
        style="border:5px solid red;" onload="this.style.border='5px solid green';"
        width="400"
        height="300"
        allowtransparency></iframe>

<!-- -->

</body>
</html>

Run the test on 0.35.0 (or any version above, I have tested up to 0.37.0-rc2)
- 1 embed will load in ~2.5 seconds, with visual spinner maybe showing .1 seconds before load.
- 8 embeds will load in ~19 seconds, with no indication of what is happening until about 1 second before the end.
Run the test on 0.34.3
- 1 embed will load in ~0.9 seconds, with visual spinner maybe showing .1 seconds before load.
- 8 embeds will load in ~5 seconds, with visual spinner showing on all embeds around 4 second mark.

Another way to "reproduce":
Simply go to the embed preview in 0.34.3, which will load the preview much faster than any newer versions.

Expected behavior
At least non-blocking behavior, so a spinner is shown. Preferably sub-1-second load time.

The text was updated successfully, but these errors were encountered:

salsakran · 2020-11-03T17:19:28Z

Since this is both a regression, and a brutal slowdown (19s for 8 cards is not ok) I'm bumping this to a P1

ariya · 2020-12-15T20:41:48Z

Thank you @flamber for such a detailed analysis!

I followed up your track and bisected all the ~200 commits between v0.34 and v0.35. Finally, I managed to narrow it down to single commit, 09001d6, that started to cause the embedding speed regression.

Looking at the front-end code difference between v0.34 and commit 09001d6 (and effectively, v0.35 or later), the JavaScript grows by approximately 280KB. Here is the breakdown:

In v0.34:

 3576195 resources/frontend_client/app/dist/vendor.bundle.js
    2487 resources/frontend_client/app/dist/styles.bundle.js
 1345125 resources/frontend_client/app/dist/app-embed.bundle.js
   13084 resources/frontend_client/app/dist/0.bundle.js
 4936891 TOTAL (4.71 MB)

In v0.35 (right after commit 09001d6):

 3763334 resources/frontend_client/app/dist/vendor.bundle.js
    2510 resources/frontend_client/app/dist/styles.bundle.js
 1460501 resources/frontend_client/app/dist/app-embed.bundle.js
 5226345 TOTAL (4.98 KB)

The above size difference causes the trigger to fetch the JSON (via XHR) to happen at different times as well. Notionly, it is a bit later for v0.35.

To demonstrate this, I captured the network waterfall diagram (see the attached HARs, can be displayed with e.g.Online HAR Viewer) for both v0.34 and v0.35. To further stress the front-end code, this was carried out under the "Fast 3G" network throttling simulation in Chrome Dev Tools.

v34.har.txt
v35.har.txt

With v0.34, the fetch is initiated after 8.69 seconds.

However, with v0.35, it happens almost a full second later, at 9.60 seconds.

This delay contributes to the slow down of iframe rendering for this embedding use case. Note that this is just testing a single (embedded) iframe. With a few more, there will be a cascading effect, adding further to the overall slow experience.

My next attemp is to figure out why this extra 280 KB of JavaScript code adds so much delay (~1 s) to the initial data fetch and if there is a way to workaround it.

ariya · 2020-12-16T17:23:39Z

For completeness, here is the code inflation due to the said commit, restricted to frontend/src:

File	Before	After	Delta
metabase-lib/lib/queries/StructuredQuery.js	42916	43211	295
metabase-lib/lib/queries/structured/Aggregation.js	6821	6813	-8
metabase-lib/lib/queries/structured/Filter.js	8295	8434	139
metabase-lib/lib/queries/structured/MBQLClause.js	2472	2529	57
metabase/lib/expressions/compile.js	0	5414	5414
metabase/lib/expressions/config.js	560	8181	7621
metabase/lib/expressions/format.js	0	3927	3927
metabase/lib/expressions/formatter.js	2155	0	-2155
metabase/lib/expressions/index.js	2148	4787	2639
metabase/lib/expressions/lexer.js	0	7800	7800
metabase/lib/expressions/parser.js	16306	13146	-3160
metabase/lib/expressions/process.js	0	1291	1291
metabase/lib/expressions/suggest.js	0	15513	15513
metabase/lib/expressions/syntax.js	0	10224	10224
metabase/lib/expressions/tokens.js	2308	0	-2308
metabase/lib/query.js	13634	13631	-3
metabase/lib/query/field_ref.js	5310	5539	229
metabase/lib/query/filter.js	3080	3117	37
metabase/lib/query_aggregation.js	3190	3078	-112
metabase/lib/schema_metadata.js	18048	18152	104
metabase/modes/components/drill/UnderlyingRecordsDrill.jsx	1333	2234	901
metabase/query_builder/components/AggregationName.jsx	3870	3921	51
metabase/query_builder/components/AggregationPopover.jsx	13874	12115	-1759
metabase/query_builder/components/DimensionList.jsx	7687	7707	20
metabase/query_builder/components/ExpressionPopover.jsx	0	2601	2601
metabase/query_builder/components/ExtendedOptions.jsx	6669	6611	-58
metabase/query_builder/components/FieldList.jsx	2919	2934	15
metabase/query_builder/components/expressions/ExpressionEditorTextfield.jsx	11473	11241	-232
metabase/query_builder/components/expressions/ExpressionWidget.jsx	4046	4254	208
metabase/query_builder/components/expressions/Expressions.jsx	2079	1959	-120
metabase/query_builder/components/expressions/TokenizedExpression.jsx	3366	703	-2663
metabase/query_builder/components/expressions/TokenizedInput.jsx	4926	5157	231
metabase/query_builder/components/filters/FilterPopover.jsx	5571	7098	1527
metabase/query_builder/components/filters/FilterPopoverHeader.jsx	1608	1565	-43
metabase/query_builder/components/filters/FilterPopoverPicker.jsx	1312	1786	474
TOTAL	197976	246673	48697

The bulk of it is concentrated inside metabase/lib/expressions, therefore if we zoom in there:

File	Before	After	Delta
metabase/lib/expressions/compile.js	0	5414	5414
metabase/lib/expressions/config.js	560	8181	7621
metabase/lib/expressions/format.js	0	3927	3927
metabase/lib/expressions/formatter.js	2155	0	-2155
metabase/lib/expressions/index.js	2148	4787	2639
metabase/lib/expressions/lexer.js	0	7800	7800
metabase/lib/expressions/parser.js	16306	13146	-3160
metabase/lib/expressions/process.js	0	1291	1291
metabase/lib/expressions/suggest.js	0	15513	15513
metabase/lib/expressions/syntax.js	0	10224	10224
metabase/lib/expressions/tokens.js	2308	0	-2308
metabase/lib/query.js	13634	13631	-3
metabase/lib/query/field_ref.js	5310	5539	229
metabase/lib/query/filter.js	3080	3117	37
metabase/lib/query_aggregation.js	3190	3078	-112
metabase/lib/schema_metadata.js	18048	18152	104
TOTAL	66739	113800	47061

My next step is find out why this extra 45 KB code adds so much to the initial delay of the (embedding) app.

ariya · 2020-12-18T00:43:43Z

Another quick update.

I can now see an obvious place where the said commit introduces a new significant JavaScript code execution.

Before the commit, an illustrative example of the call tree from the code execution flame chart, before DOMContentLoaded event (which happens at 550 ms):

Chrome DevTools estimated the total blocking time to be ~167 ms.

In the meantime, after the commit was introduced (look at that deep, nested call tree!):

which contributed to a whopping (estimated) 730 ms blocking time. This also explains why DOMContentLoaded event fires after 1.12 seconds.

Next step: navigate the flame chart, understand the breakdown of the slow down even more.

ariya · 2020-12-18T15:59:51Z

I can now confirm that the slow-down is caused by Chevrotain's performSelfAnalysis, which needs to be called in the construction of the expression parsers (there are 3 instances of different parsers). In fact, this has nothing to do with embedding at all! The problem already manifests itself in the regular Metabase app, e.g. by going to the Sign In screen (however, the slow down is much much more perceptible when doing embedding, since there could be multiple iframes at once).

To reproduce:

Launch Metabase, go to the Sign In screen
Open Chrome DevTools, Performance panel
Click Record, reload the page and once the page is completed, click Stop
Drill-down the flame chart to locate the execution tree

As shown in the following screenshot, performSelfAnalysis is rather expensive (220 ms, and I'm on a fast 3.6 GHz desktop rig!) and it must be carried out for all the 3 different parsers. Because these steps happen in the beginning (application initialization), it delays the DOMContentLoaded up to 700 ms (or more, on a slower machine).

Next step: find a way to avoid this up-front expensive initialization.

ariya · 2020-12-24T14:47:35Z

This is now fixed with PR #14133.

flamber added Type:Bug Product defects Priority:P2 Average run of the mill bug Embedding/Static Static embedding, previously known as signed embedding .Performance labels Oct 14, 2020

salsakran added Priority:P1 Security holes w/o exploit, crashing, setup/upgrade, login, broken common features, correctness and removed Priority:P2 Average run of the mill bug labels Nov 3, 2020

rlotun added this to the 0.37.3 milestone Nov 16, 2020

rlotun modified the milestones: 0.37.3, 0.37.4 Dec 7, 2020

ariya self-assigned this Dec 16, 2020

rlotun modified the milestones: 0.37.4, 0.37.5 Dec 18, 2020

ariya mentioned this issue Dec 18, 2020

Defer the parser and its related construction until it's needed #14133

Merged

ariya closed this as completed Dec 24, 2020

ariya mentioned this issue Mar 8, 2021

Shared CLJ/CLJS lib #14980

Merged

2 tasks

flamber mentioned this issue Apr 29, 2021

Errors on Embedded Dashboards with Pre-defined Filter Resulting In Longer HTTP Request #15861

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Embedding loading slow #13472

Embedding loading slow #13472

flamber commented Oct 14, 2020

salsakran commented Nov 3, 2020

ariya commented Dec 15, 2020

ariya commented Dec 16, 2020

ariya commented Dec 18, 2020

ariya commented Dec 18, 2020

ariya commented Dec 24, 2020

Embedding loading slow #13472

Embedding loading slow #13472

Comments

flamber commented Oct 14, 2020

salsakran commented Nov 3, 2020

ariya commented Dec 15, 2020

ariya commented Dec 16, 2020

ariya commented Dec 18, 2020

ariya commented Dec 18, 2020

ariya commented Dec 24, 2020