Multiple Queries

#1

Not sure if this is a bug but it does not seem right to me.

I have an embedded dashboard with 1 chart (query).
The query is a long one and can take up to 3 minutes to run

When I request the dash board the query is created every 30 seconds until 6 versions are running.
The dash board displays when the first query completes in about 3 minutes. The other 5 queries each complete in turn after runing about 3 minutes.

I’ve verified only 1 xhr request is sent to the server from the browser.

http://xxxxxxxxxxxxxxxxxxx.com:3000/api/embed/dashboard/eyJhbGciOiJIUzI1NiIsInR5…/dashcard/163/card/146

Name Status Type Initiator Size Time
146 200 xhr VM1529:1 3.4 KB 3.1 min

Tested in Firefox 66.0.1 and Chrome 73.0.3683.86 Metabase 0.32.0-snapshot PG backend 10.6
Note that this happens even when displaying the dashboard inside Metabase.
Anyone seen something like this ?

Notice the hashes are identical:

23641 00:00:37.421377 "-- Metabase:: userID: 1 queryType: native queryHash: 80aa26fe57d9c39f39906a95e78efaa3a1e0db0de2f80b4ab852ef74abcbcb1f
–active customer used over 300 wh in last 30 days (Avg 10 wh / day)
select case when g.operational_date >…

26226 00:01:07.434552 "-- Metabase:: userID: 1 queryType: native queryHash: 80aa26fe57d9c39f39906a95e78efaa3a1e0db0de2f80b4ab852ef74abcbcb1f
–active customer used over 300 wh in last 30 days (Avg 10 wh / day)
select case when g.operational_date>…

23116 00:01:37.450687 "-- Metabase:: userID: 1 queryType: native queryHash: 80aa26fe57d9c39f39906a95e78efaa3a1e0db0de2f80b4ab852ef74abcbcb1f
–active customer used over 300 wh in last 30 days (Avg 10 wh / day)
select case when g.operational_date>…

23112 00:02:07.464164 "-- Metabase:: userID: 1 queryType: native queryHash: 80aa26fe57d9c39f39906a95e78efaa3a1e0db0de2f80b4ab852ef74abcbcb1f
–active customer used over 300 wh in last 30 days (Avg 10 wh / day)
select case when g.operational_date >…

23642 00:02:37.481506 "-- Metabase:: userID: 1 queryType: native queryHash: 80aa26fe57d9c39f39906a95e78efaa3a1e0db0de2f80b4ab852ef74abcbcb1f
–active customer used over 300 wh in last 30 days (Avg 10 wh / day)
select case when g.operational_date>…

23644 00:03:07.487371 "-- Metabase:: userID: 1 queryType: native queryHash: 80aa26fe57d9c39f39906a95e78efaa3a1e0db0de2f80b4ab852ef74abcbcb1f
–active customer used over 300 wh in last 30 days (Avg 10 wh / day)
select case when g.operational_date>…

#2

Looking at some of my other dashboards, they also spawn the same query multiple times every 30 seconds.
Does not seem to matter if they are custom or native queries.

Also note that even running the query in the query editor produces the same problem.
Clicking cancel kills the first query while the others run to completion.

#3

Good news bad news, looking at Metabase logs requests are coming every 30 seconds.
So not a Metabase issue, but I’ll leave it open for a bit to see if I get any replies.

So my question is, why does Chrome and firefox show only 1 xhr request ?

LOG:
Mar 28 23:58:32 DEBUG metabase.middleware.log :: GET /api/embed/dashboard/eyJhbGciOiJIUzI1NiIsI…/163/card/146 200 (11 ms) (6 DB calls). Jetty threads: 8/50 (3 busy, 3 idle, 0 queued) (207 total active threads)
Mar 28 23:58:32 DEBUG metabase.async.util :: Running metabase.async.semaphore_channel$do_f_with_permit$f__40020@172f9feb on separate thread…
Mar 28 23:58:32 DEBUG metabase.async.api-response :: starting streaming response
Mar 28 23:58:36 DEBUG metabase.async.semaphore-channel :: f finished, permit will be returned
Mar 28 23:58:36 DEBUG metabase.async.semaphore-channel :: f finished, permit will be returned
Mar 28 23:58:46 DEBUG metabase.async.semaphore-channel :: f finished, permit will be returned
Mar 28 23:59:02 DEBUG metabase.middleware.log :: GET /api/embed/dashboard/eyJhbGciOiJIUzI1NiIsInR…/card/146 200 (12 ms) (6 DB calls). Jetty threads: 8/50 (3 busy, 3 idle, 0 queued) (208 total active threads)
Mar 28 23:59:02 DEBUG metabase.async.util :: Running metabase.async.semaphore_channel$do_f_with_permit$f__40020@34a7f722 on separate thread…
Mar 28 23:59:02 DEBUG metabase.async.api-response :: starting streaming response
Mar 28 23:59:32 DEBUG metabase.middleware.log :: GET /api/embed/dashboard/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJyZXNvdXJjZSI6eyJkYXNoYm9hcmQiOjExfSwicGFyYW1zIjp7fSwiaWF0IjoxNTU…/163/card/146 200 (11 ms) (6 DB calls). Jetty threads: 8/50 (3 busy, 3 idle, 0 queued) (208 total active threads)
Mar 28 23:59:32 DEBUG metabase.async.util :: Running metabase.async.semaphore_channel$do_f_with_permit$f__40020@650635b4 on separate thread…
Mar 28 23:59:32 DEBUG metabase.async.api-response :: starting streaming response
Mar 28 23:59:33 DEBUG metabase.async.semaphore-channel :: f finished, permit will be returned
Mar 28 23:59:34 DEBUG metabase.async.semaphore-channel :: f finished, permit will be returned

#4

So it seems I’m experiencing this: https://blogs.oracle.com/ravello/beware-http-requests-automatic-retries

If anyone has dealt with this please let me know.

I’m running Metabase on AWS EC2 server with ngnix load balancer.

If I find a way to stop it I will post here.

#5

So I use nodejs express server to make the requests to get the dashboard.
I added a timeout module and set the timeout to 3 minutes.
I still get duplicate requests every 30 seconds.

So this seem to most certainly be the browser sending the duplicate requests per the article sited above.
BTW closing the tab does not stop Chrome or Firefox from sending the duplicates.You have to close the browser including background jobs.

I guess now I would have to say this is a bug in Metabase in that it does not discard duplicate requests while it is working on the original request. Or you might say this is not a bug and your queries should run under 30 secs.

What does everyone think ? Should this stay a bug ? Change to a feature request ? Or I just shorten my queries.

#6

So after further testing, this is definitely the browser sending duplicate embedded dashboard card requests, and metabase honors them and starts a new thread and makes all the DB calls as the dashboard requires. When Metabase returns data from the DB for each request, the browser stops sending duplicates.

I wrote some code to detect identical calls from the identical referrer with the identical headers. When I detected the second call I tried not responding, responding with a 200 immediately, respond with a 100. None worked. So it seems this feature of HTTP 1.1 causes Metabase to put a heavier load on the DB server than necessary.

So far no opinions from this group, so I’ll close this soon.

#7

Hi @shermes641
This might be related to the change of async webserver, which was added in 0.32
There has been a few fixes for some issues, which was added to 0.32.1 and 0.32.2, but there’s still some problems, which should be part of the upcoming 0.32.3.
https://github.com/metabase/metabase/issues/9693

#8

thanks for the response.
Fix bug where async keepalive characters would not always be written #9704.
This might exactly be the problem.
I’ll build a new jar and see if this fix makes a difference.

Got the latest from the repo and built the jar, reporting 0.33.0
No difference in the problem I’m reporting.
Any query running more than 30 seconds, the browser repeats the request to Metabase and Metabase starts the queries again. When the first query completes, results are displayed on the dashboard, and the other queries eventually run to completion.

#9

So I downloaded the jar v0.31.2. It does not have the problem.
I built the jar from commit:

Commit: a246791de009633288f375b7d0f078ab70723cb4 [a246791]
Parents: dfaea4218c
Author: Tom Robinson tlrobinson@gmail.com
Date: Friday, March 15, 2019 12:37:24
Committer: Tom Robinson
Commit Date: Friday, March 15, 2019 12:41:22

And it does not have the problem.

#10

@shermes641
What if you try to build release-0.32.0, which now includes 60f3c43 (#9704)?
It would be great to know if it is fixed - otherwise you should open a new issue.

#11

Good news. I got the latest 27 commits about an hour ago.
The problem is gone, and long running queries are canceled if you navigate away from the page before they are finished.

04-08 18:55:58 e[1mDEBUG async.api-responsee[0m :: starting streaming response
04-08 18:55:59 e[1mDEBUG async.api-responsee[0m :: Response not ready, writing one byte & sleeping…
04-08 18:56:00 e[1mDEBUG async.api-responsee[0m :: Response not ready, writing one byte & sleeping…

So should be fixed in the next release.