How to use Metabase with a slow external MySQL database

edward_hibbert · May 27, 2021, 7:29pm

I'm new to Metabase, so apologies for aspects of this which turn out to be a FAQ.

I've downloaded the Docker image, and added a MySQL data source. That MySQL database is quite large, and while it is is well-optimised for queries for the application that uses it, it's not necessarily well-indexed for Metabase's queries.

This means that queries can take several minutes to run. But there's a low timeout of around a minute on the MySQL queries that Metabase issues, which means it fails.

I can't find any way to change that timeout. But I am new to Metabase and may have missed it. Is there one?

I do not want to get into adding new indexes to the database in order to support queries that Metabase does - that takes disk space (which is an issue), is difficult to do on a live system, and is hard to predict in advance. Part of the purpose of using Metabase is to make it easier to do ad hoc queries.

Ideally I wouldn't be hitting my real database at all with ad hoc queries I don't control. So I'm wondering if I can use Metabase's caching to query the relevant information from MySQL database once a day. I wouldn't mind if that cache took hours to update, because I could schedule them to run overnight. Is something like that possible?

Any other alternative approaches welcome.

flamber · May 27, 2021, 7:45pm

Hi @edward_hibbert

Post "Diagnostic Info" from Admin > Troubleshooting, and which version of MySQL you're querying.

And please post the full stacktrace from Admin > Troubleshooting > Logs, since Metabase does not have a timeout after one minute.
It's either a reverse-proxy: https://www.metabase.com/docs/latest/troubleshooting-guide/proxies.html
Or the MySQL user/database has a query execution timeout set, but that would be the same problem if you made the query from a different problem.

You can enable caching for queries:
https://www.metabase.com/docs/latest/administration-guide/14-caching.html

And then you can use the API to "view" the questions during the night with a script, but I would probably recommend that you truncate the application database table query_cache before, so you're sure that there isn't any stale cache:
https://www.metabase.com/learn/developing-applications/advanced-metabase/metabase-api.html

I would recommend that you also read this:
https://www.metabase.com/learn/data-diet/analytics/making-dashboards-faster.html

edward_hibbert · May 28, 2021, 10:02pm

Thanks @flamber for replying.

Here's what I see on screen after about a minute:

Here's the kind of thing I see in the logs:

[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:50:48+01:00 INFO metabase.driver.impl Initializing driver :mysql...
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:50:48+01:00 DEBUG metabase.server.middleware.log GET /api/database 200 217.7 ms (6 DB calls) App DB connections: 0/4 Jetty threads: 4/50 (6 idle, 0 queued) (53 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:50:48+01:00 DEBUG metabase.server.middleware.log GET /api/table/7/query_metadata 200 391.2 ms (9 DB calls) App DB connections: 0/4 Jetty threads: 3/50 (7 idle, 0 queued) (53 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:50:53+01:00 DEBUG metabase.server.middleware.log POST /api/dataset 202 [ASYNC: completed] 4.9 s (16 DB calls) App DB connections: 1/4 Jetty threads: 2/50 (8 idle, 0 queued) (61 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:50:54+01:00 DEBUG metabase.server.middleware.log GET /api/user/current 200 6.7 ms (3 DB calls) App DB connections: 0/4 Jetty threads: 4/50 (7 idle, 0 queued) (61 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:50:54+01:00 DEBUG metabase.server.middleware.log GET /api/database 200 14.0 ms (3 DB calls) App DB connections: 0/4 Jetty threads: 4/50 (6 idle, 0 queued) (61 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:50:54+01:00 DEBUG metabase.server.middleware.log GET /api/session/properties 200 52.3 ms (2 DB calls) App DB connections: 0/4 Jetty threads: 4/50 (6 idle, 0 queued) (61 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:29+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/124/87/53/51/1/2/ 200 1.2 s (11 DB calls) App DB connections: 0/15 Jetty threads: 26/50 (1 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:29+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/125/87/53/51/1/2/ 200 1.3 s (11 DB calls) App DB connections: 0/15 Jetty threads: 25/50 (2 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:29+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/126/87/53/51/1/2/ 200 1.3 s (11 DB calls) App DB connections: 0/15 Jetty threads: 25/50 (2 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:29+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/128/87/53/51/1/2/ 200 1.3 s (11 DB calls) App DB connections: 0/15 Jetty threads: 25/50 (2 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:29+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/127/87/53/51/1/2/ 200 1.2 s (11 DB calls) App DB connections: 0/15 Jetty threads: 24/50 (3 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:29+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/129/87/53/51/1/2/ 200 1.2 s (11 DB calls) App DB connections: 0/15 Jetty threads: 24/50 (3 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:38+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/128/86/53/51/1/2/ 200 10.1 s (11 DB calls) App DB connections: 0/15 Jetty threads: 20/50 (7 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:39+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/129/85/53/51/1/2/ 200 10.6 s (11 DB calls) App DB connections: 0/15 Jetty threads: 19/50 (8 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:39+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/124/84/53/51/1/2/ 200 11.3 s (11 DB calls) App DB connections: 1/15 Jetty threads: 18/50 (9 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:40+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/129/86/53/51/1/2/ 200 11.4 s (11 DB calls) App DB connections: 1/15 Jetty threads: 17/50 (10 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:40+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/124/85/53/51/1/2/ 200 11.9 s (11 DB calls) App DB connections: 0/15 Jetty threads: 16/50 (11 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:42+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/127/86/53/51/1/2/ 200 14.1 s (11 DB calls) App DB connections: 0/15 Jetty threads: 15/50 (12 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:43+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/129/84/53/51/1/2/ 200 15.0 s (11 DB calls) App DB connections: 0/15 Jetty threads: 14/50 (13 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:47+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/126/86/53/51/1/2/ 200 19.1 s (11 DB calls) App DB connections: 0/15 Jetty threads: 13/50 (14 idle, 0 queued) (81 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:51:53+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/125/86/53/51/1/2/ 200 24.7 s (11 DB calls) App DB connections: 0/15 Jetty threads: 12/50 (15 idle, 0 queued) (77 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:02+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/124/86/53/51/1/2/ 200 33.7 s (11 DB calls) App DB connections: 0/15 Jetty threads: 11/50 (16 idle, 0 queued) (75 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:45+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/125/84/53/51/1/2/ 200 1.3 mins (12 DB calls) App DB connections: 0/15 Jetty threads: 10/50 (16 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:45+01:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:45+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/125/84/53/51/1/2/ null 1.3 mins (12 DB calls) App DB connections: 0/15 Jetty threads: 10/50 (16 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:59+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/61/44/53/51/1/2/ 200 451.6 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 33/50 (1 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:59+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/62/44/53/51/1/2/ 200 482.9 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 33/50 (1 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:59+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/65/43/53/51/1/2/ 200 383.4 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 31/50 (3 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:59+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/60/41/53/51/1/2/ 200 429.4 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 30/50 (4 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:59+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/60/44/53/51/1/2/ 200 361.1 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 29/50 (5 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:59+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/65/41/53/51/1/2/ 200 370.9 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 29/50 (5 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:59+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/65/44/53/51/1/2/ 200 525.4 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 27/50 (7 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:52:59+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/60/43/53/51/1/2/ 200 623.1 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 27/50 (7 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:53:02+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/61/42/53/51/1/2/ 200 2.9 s (11 DB calls) App DB connections: 0/15 Jetty threads: 31/50 (4 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:53:02+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/61/41/53/51/1/2/ 200 3.1 s (11 DB calls) App DB connections: 0/15 Jetty threads: 30/50 (5 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:53:02+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/63/44/53/51/1/2/ 200 3.0 s (11 DB calls) App DB connections: 0/15 Jetty threads: 30/50 (5 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:53:02+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/65/40/53/51/1/2/ 200 302.5 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 29/50 (5 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:53:02+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/65/42/53/51/1/2/ 200 3.1 s (11 DB calls) App DB connections: 0/15 Jetty threads: 27/50 (7 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:53:07+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/64/43/53/51/1/2/ 200 8.7 s (11 DB calls) App DB connections: 0/15 Jetty threads: 26/50 (8 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:53:11+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/7/60/40/53/51/1/2/ 200 9.3 s (11 DB calls) App DB connections: 0/15 Jetty threads: 25/50 (9 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:53:11+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/8/125/85/53/51/1/2/ 200 1.7 mins (11 DB calls) App DB connections: 0/15 Jetty threads: 24/50 (10 idle, 0 queued) (82 total active threads) Queries in flight: 0 (0 queued)
[1d2fa7c1-3cc2-45a4-ba28-21d5088a892f] 2021-05-28T22:53:11+01:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.

I'm not using a proxy, and I don't have problems with other connections to that database being closed. There's a little bit in the MySQL logs:

2021-05-28T21:48:31.456365Z 190828 [Note] Got an error writing communication packets
2021-05-28T21:49:01.500912Z 190954 [Note] Got an error writing communication packets
2021-05-28T21:49:31.543138Z 191080 [Note] Got an error writing communication packets
2021-05-28T21:49:50.193627Z 188740 [Note] Aborted connection 188740 to db: 'iznik' user: 'metabase' host: 'localhost' (Got an error reading communication packets)

flamber · May 28, 2021, 10:26pm

@edward_hibbert

Post "Diagnostic Info" from Admin > Troubleshooting.
Can you try with a non-map question, since it's confusing to read the logs.
From what I can see, the query is returned in 4.9 seconds - /api/dataset 202 [ASYNC: completed] 4.9 s - and that's the only data source there is. Everything else is map tile requests.
I'm guessing you're seeing this issue, but it's hard to tell with so few details.
https://github.com/metabase/metabase/issues/4844

edward_hibbert · June 1, 2021, 1:55pm

Here's the diagnostic info:

{
  "browser-info": {
    "language": "en-GB",
    "platform": "Win32",
    "userAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.212 Safari/537.36",
    "vendor": "Google Inc."
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "11.0.10+9",
    "java.vendor": "AdoptOpenJDK",
    "java.vendor.url": "https://adoptopenjdk.net/",
    "java.version": "11.0.10",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "11.0.10+9",
    "os.name": "Linux",
    "os.version": "4.15.0-143-generic",
    "user.language": "en",
    "user.timezone": "GMT"
  },
  "metabase-info": {
    "databases": [
      "h2",
      "mysql"
    ],
    "hosting-env": "unknown",
    "application-database": "h2",
    "application-database-details": {
      "database": {
        "name": "H2",
        "version": "1.4.197 (2018-03-18)"
      },
      "jdbc-driver": {
        "name": "H2 JDBC Driver",
        "version": "1.4.197 (2018-03-18)"
      }
    },
    "run-mode": "prod",
    "version": {
      "date": "2021-03-17",
      "tag": "v0.38.2",
      "branch": "release-x.38.x",
      "hash": "91f0ed6"
    },
    "settings": {
      "report-timezone": null
    }
  }
}

The problem here is specific to the map view, I think. I had a look at what queries were being issues on the DB server. I have multiple instances of queries like this:

SELECT MB_messages.arrivalASarrival, MB_messages.latASlat, MB_messages.lngASlngFROMMB_messages WHERE (MB_messages.latBETWEEN 50.736456644995705 AND 51.6180180634215 ANDMB_messages.lng BETWEEN -2.8124999318970385 AND -1.4062499659485193) LIMIT 1048576 ;

It looks like it's divided the map up into sections and is trying to grab data for each section. Some of those queries complete in tens of seconds and populate the map (see below), but it seems to be giving up when one of those queries hits around 60s. There is a "Request canceled before finishing" log here.

[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:30+01:00 INFO metabase.driver.impl Initializing driver :mysql...
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:30+01:00 DEBUG metabase.server.middleware.log GET /api/database 200 105.7 ms (5 DB calls) App DB connections: 1/4 Jetty threads: 6/50 (3 idle, 0 queued) (52 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:31+01:00 DEBUG metabase.server.middleware.log GET /api/database 200 209.8 ms (6 DB calls) App DB connections: 0/4 Jetty threads: 4/50 (5 idle, 0 queued) (53 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:31+01:00 DEBUG metabase.server.middleware.log GET /api/table/7/query_metadata 200 359.0 ms (9 DB calls) App DB connections: 0/4 Jetty threads: 3/50 (6 idle, 0 queued) (53 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:36+01:00 DEBUG metabase.server.middleware.log POST /api/dataset 202 [ASYNC: completed] 4.9 s (16 DB calls) App DB connections: 0/4 Jetty threads: 4/50 (6 idle, 0 queued) (61 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:40+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/32/19/53/51/1/2/ 200 1.0 s (11 DB calls) App DB connections: 0/15 Jetty threads: 17/50 (1 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:40+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/33/19/53/51/1/2/ 200 816.8 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 17/50 (1 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:40+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/29/21/53/51/1/2/ 200 820.6 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 17/50 (1 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:40+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/29/20/53/51/1/2/ 200 1.0 s (11 DB calls) App DB connections: 0/15 Jetty threads: 17/50 (1 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:40+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/29/19/53/51/1/2/ 200 900.7 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 17/50 (1 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:40+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/33/20/53/51/1/2/ 200 920.3 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 14/50 (4 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:40+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/33/21/53/51/1/2/ 200 990.3 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 14/50 (4 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:45+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/30/19/53/51/1/2/ 200 5.6 s (11 DB calls) App DB connections: 0/15 Jetty threads: 10/50 (8 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:47+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/30/21/53/51/1/2/ 200 8.1 s (11 DB calls) App DB connections: 0/15 Jetty threads: 9/50 (9 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:40:52+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/30/20/53/51/1/2/ 200 12.6 s (11 DB calls) App DB connections: 0/15 Jetty threads: 8/50 (10 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:41:38+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/32/20/53/51/1/2/ 200 58.6 s (11 DB calls) App DB connections: 0/15 Jetty threads: 7/50 (11 idle, 0 queued) (70 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:20+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/31/19/53/51/1/2/ 200 1.7 mins (11 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (13 idle, 0 queued) (67 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:20+01:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:20+01:00 DEBUG metabase.server.middleware.log GET /api/tiles/6/31/19/53/51/1/2/ null 1.7 mins (11 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (13 idle, 0 queued) (67 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:34+01:00 DEBUG metabase.server.middleware.log GET /api/user/current 200 21.8 ms (3 DB calls) App DB connections: 0/15 Jetty threads: 7/50 (11 idle, 0 queued) (67 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:34+01:00 DEBUG metabase.server.middleware.log GET /api/session/properties 200 19.7 ms (2 DB calls) App DB connections: 0/15 Jetty threads: 7/50 (11 idle, 0 queued) (67 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:34+01:00 DEBUG metabase.server.middleware.log GET /api/setting 200 10.3 ms (0 DB calls) App DB connections: 0/15 Jetty threads: 8/50 (9 idle, 0 queued) (71 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:34+01:00 DEBUG metabase.server.middleware.log GET /api/database 200 32.7 ms (3 DB calls) App DB connections: 0/15 Jetty threads: 8/50 (9 idle, 0 queued) (71 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:34+01:00 DEBUG metabase.server.middleware.log GET /api/session/properties 200 18.2 ms (2 DB calls) App DB connections: 0/15 Jetty threads: 8/50 (9 idle, 0 queued) (71 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:34+01:00 DEBUG metabase.server.middleware.log GET /api/setup/admin_checklist 200 108.8 ms (11 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (11 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)
[294b367e-2803-43b8-a917-c295057d6843] 2021-06-01T14:42:37+01:00 DEBUG metabase.server.middleware.log GET /api/util/bug_report_details 200 10.6 ms (1 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (12 idle, 0 queued) (73 total active threads) Queries in flight: 0 (0 queued)

At this point the map is partially populated:

I wanted to try doing a query from within the Docker image using the mysql command, to verify whether or not the connection is being terminated, but it doesn't recognise apt-get or yum, so I'm not sure how to install that client. Which flavour of OS is it running?

flamber · June 1, 2021, 3:34pm

@edward_hibbert If you are seeing requests being cancelled after 60 seconds, then it's your reverse-proxy that is closing the connection, so adjust that.
The Metabase release Docker images are using Alpine as the OS.
I can see from the requests that you're returning more than 1000 results, which means that Metabase will render the map server-side instead of showing pins. I would recommend if you could limit the results to less than 1000 by filtering by region.

edward_hibbert · June 1, 2021, 5:10pm

Thanks for your continued helpful replies. You say this:

then it's your reverse-proxy that is closing the connection, so adjust that.

Can you give me a pointer for how to do that? Sorry, that feels like a really dumb question, but I'm new to Metabase.

I can reproduce this by running a raw SQL question. That times out after 60 seconds with a "Your question took too long".

I've installed mysql-client, and run the same SQL query from within the Docker image using that. That doesn't time out. I think that rules out anything on the host OS and the database side.

This seems to have logs which show the timeout:

cc3031d2-4dea-4152-b027-7573b467cf7e] 2021-06-01T17:54:49+01:00 DEBUG metabase.server.middleware.log POST /api/dataset 202 [ASYNC: canceled] 1.0 mins (4 DB calls) App DB connections: 0/7 Jetty threads: 2/50 (6 idle, 0 queued) (62 total active threads) Queries in flight: 0 (0 queued)
[cc3031d2-4dea-4152-b027-7573b467cf7e] 2021-06-01T17:57:47+01:00 ERROR metabase.query-processor.middleware.catch-exceptions Error processing query: null
{:database_id 7,
 :started_at #t "2021-06-01T16:56:47.144370Z[GMT]",
 :via
 [{:status :failed,
   :class clojure.lang.ExceptionInfo,
   :error "Error executing query",
   :stacktrace
   ["--> driver.sql_jdbc.execute$execute_reducible_query$fn__77755.invoke(execute.clj:393)"
    "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:390)"
    "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:375)"
    "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:384)"
    "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:375)"
    "driver.sql_jdbc$fn__79191.invokeStatic(sql_jdbc.clj:54)"
    "driver.sql_jdbc$fn__79191.invoke(sql_jdbc.clj:52)"
    "query_processor.context$executef.invokeStatic(context.clj:59)"
    "query_processor.context$executef.invoke(context.clj:48)"
    "query_processor.context.default$default_runf.invokeStatic(default.clj:68)"
    "query_processor.context.default$default_runf.invoke(default.clj:66)"
    "query_processor.context$runf.invokeStatic(context.clj:45)"
    "query_processor.context$runf.invoke(context.clj:39)"
    "query_processor.reducible$pivot.invokeStatic(reducible.clj:34)"
    "query_processor.reducible$pivot.invoke(reducible.clj:31)"
    "query_processor.middleware.mbql_to_native$mbql__GT_native$fn__46455.invoke(mbql_to_native.clj:25)"
    "query_processor.middleware.check_features$check_features$fn__45707.invoke(check_features.clj:41)"
    "query_processor.middleware.limit$limit$fn__46441.invoke(limit.clj:37)"
    "query_processor.middleware.cache$maybe_return_cached_results$fn__45365.invoke(cache.clj:211)"
    "query_processor.middleware.optimize_datetime_filters$optimize_datetime_filters$fn__46620.invoke(optimize_datetime_filters.clj:133)"
    "query_processor.middleware.auto_parse_filter_values$auto_parse_filter_values$fn__44511.invoke(auto_parse_filter_values.clj:43)"
    "query_processor.middleware.wrap_value_literals$wrap_value_literals$fn__40828.invoke(wrap_value_literals.clj:147)"
    "query_processor.middleware.annotate$add_column_info$fn__40691.invoke(annotate.clj:582)"
    "query_processor.middleware.permissions$check_query_permissions$fn__45582.invoke(permissions.clj:75)"
    "query_processor.middleware.pre_alias_aggregations$pre_alias_aggregations$fn__47143.invoke(pre_alias_aggregations.clj:40)"
    "query_processor.middleware.cumulative_aggregations$handle_cumulative_aggregations$fn__45780.invoke(cumulative_aggregations.clj:60)"
    "query_processor.middleware.resolve_joined_fields$resolve_joined_fields$fn__47456.invoke(resolve_joined_fields.clj:94)"
    "query_processor.middleware.resolve_joins$resolve_joins$fn__47761.invoke(resolve_joins.clj:178)"
    "query_processor.middleware.add_implicit_joins$add_implicit_joins$fn__44105.invoke(add_implicit_joins.clj:181)"
    "query_processor.middleware.large_int_id$convert_id_to_string$fn__46416.invoke(large_int_id.clj:44)"
    "query_processor.middleware.format_rows$format_rows$fn__46396.invoke(format_rows.clj:74)"
    "query_processor.middleware.desugar$desugar$fn__45846.invoke(desugar.clj:21)"
    "query_processor.middleware.binning$update_binning_strategy$fn__44871.invoke(binning.clj:228)"
    "query_processor.middleware.resolve_fields$resolve_fields$fn__45389.invoke(resolve_fields.clj:24)"
    "query_processor.middleware.add_dimension_projections$add_remapping$fn__43735.invoke(add_dimension_projections.clj:314)"
    "query_processor.middleware.add_implicit_clauses$add_implicit_clauses$fn__43966.invoke(add_implicit_clauses.clj:146)"
    "query_processor.middleware.upgrade_field_literals$upgrade_field_literals$fn__48191.invoke(upgrade_field_literals.clj:45)"
    "query_processor.middleware.add_source_metadata$add_source_metadata_for_source_queries$fn__44258.invoke(add_source_metadata.clj:122)"
    "query_processor.middleware.reconcile_breakout_and_order_by_bucketing$reconcile_breakout_and_order_by_bucketing$fn__47340.invoke(reconcile_breakout_and_order_by_bucketing.clj:97)"
    "query_processor.middleware.auto_bucket_datetimes$auto_bucket_datetimes$fn__44458.invoke(auto_bucket_datetimes.clj:139)"
    "query_processor.middleware.resolve_source_table$resolve_source_tables$fn__45436.invoke(resolve_source_table.clj:45)"
    "query_processor.middleware.parameters$substitute_parameters$fn__47125.invoke(parameters.clj:111)"
    "query_processor.middleware.resolve_referenced$resolve_referenced_card_resources$fn__45488.invoke(resolve_referenced.clj:79)"
    "query_processor.middleware.expand_macros$expand_macros$fn__46102.invoke(expand_macros.clj:155)"
    "query_processor.middleware.add_timezone_info$add_timezone_info$fn__44267.invoke(add_timezone_info.clj:15)"
    "query_processor.middleware.splice_params_in_response$splice_params_in_response$fn__48127.invoke(splice_params_in_response.clj:32)"
    "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__47351$fn__47355.invoke(resolve_database_and_driver.clj:31)"
    "driver$do_with_driver.invokeStatic(driver.clj:60)"
    "driver$do_with_driver.invoke(driver.clj:56)"
    "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__47351.invoke(resolve_database_and_driver.clj:25)"
    "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__46342.invoke(fetch_source_query.clj:274)"
    "query_processor.middleware.store$initialize_store$fn__48136$fn__48137.invoke(store.clj:11)"
    "query_processor.store$do_with_store.invokeStatic(store.clj:44)"
    "query_processor.store$do_with_store.invoke(store.clj:38)"
    "query_processor.middleware.store$initialize_store$fn__48136.invoke(store.clj:10)"
    "query_processor.middleware.validate$validate_query$fn__48198.invoke(validate.clj:10)"
    "query_processor.middleware.normalize_query$normalize$fn__46468.invoke(normalize_query.clj:22)"
    "query_processor.middleware.add_rows_truncated$add_rows_truncated$fn__44123.invoke(add_rows_truncated.clj:35)"
    "query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__48112.invoke(results_metadata.clj:147)"
    "query_processor.middleware.constraints$add_default_userland_constraints$fn__45723.invoke(constraints.clj:42)"
    "query_processor.middleware.process_userland_query$process_userland_query$fn__47214.invoke(process_userland_query.clj:135)"
    "query_processor.middleware.catch_exceptions$catch_exceptions$fn__45666.invoke(catch_exceptions.clj:173)"
    "query_processor.reducible$async_qp$qp_STAR___37431$thunk__37432.invoke(reducible.clj:103)"
    "query_processor.reducible$async_qp$qp_STAR___37431.invoke(reducible.clj:109)"
    "query_processor.reducible$sync_qp$qp_STAR___37440$fn__37443.invoke(reducible.clj:135)"
    "query_processor.reducible$sync_qp$qp_STAR___37440.invoke(reducible.clj:134)"
    "query_processor$process_userland_query.invokeStatic(query_processor.clj:237)"
    "query_processor$process_userland_query.doInvoke(query_processor.clj:233)"
    "query_processor$fn__48244$process_query_and_save_execution_BANG___48253$fn__48256.invoke(query_processor.clj:249)"
    "query_processor$fn__48244$process_query_and_save_execution_BANG___48253.invoke(query_processor.clj:241)"
    "query_processor$fn__48288$process_query_and_save_with_max_results_constraints_BANG___48297$fn__48300.invoke(query_processor.clj:261)"
    "query_processor$fn__48288$process_query_and_save_with_max_results_constraints_BANG___48297.invoke(query_processor.clj:254)"
    "api.dataset$run_query_async$fn__54402.invoke(dataset.clj:56)"
    "query_processor.streaming$streaming_response_STAR_$fn__54381$fn__54382.invoke(streaming.clj:72)"
    "query_processor.streaming$streaming_response_STAR_$fn__54381.invoke(streaming.clj:71)"
    "async.streaming_response$do_f_STAR_.invokeStatic(streaming_response.clj:65)"
    "async.streaming_response$do_f_STAR_.invoke(streaming_response.clj:63)"
    "async.streaming_response$do_f_async$fn__16058.invoke(streaming_response.clj:84)"],
   :error_type :driver,
   :ex-data
   {:sql
    "-- Metabase:: userID: 2 queryType: native queryHash: 75b557e2baabdfa88753feab5976886b5126c0c066a99b3cfc9291f273f3ebe0\nSELECT makedate(year(`MB_messages`.`arrival`), 1) AS `arrival`, count(*) AS `count` FROM `MB_messages` GROUP BY makedate(year(`MB_messages`.`arrival`), 1) ORDER BY makedate(year(`MB_messages`.`arrival`), 1) ASC",
    :params nil,
    :type :driver}}],
 :state "70100",
 :error_type :driver,
 :json_query
 {:type "native",
  :native
  {:query
   "SELECT makedate(year(`MB_messages`.`arrival`), 1) AS `arrival`, count(*) AS `count` FROM `MB_messages` GROUP BY makedate(year(`MB_messages`.`arrival`), 1) ORDER BY makedate(year(`MB_messages`.`arrival`), 1) ASC",
   :template-tags {}},
  :database 7,
  :parameters [],
  :middleware {:js-int-to-string? true, :add-default-userland-constraints? true}},
 :status :failed,
 :class java.sql.SQLTimeoutException,
 :stacktrace
 ["org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.createException(ExceptionFactory.java:47)"
  "org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.create(ExceptionFactory.java:153)"
  "org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:274)"
  "org.mariadb.jdbc.ClientSidePreparedStatement.executeInternal(ClientSidePreparedStatement.java:229)"
  "org.mariadb.jdbc.ClientSidePreparedStatement.execute(ClientSidePreparedStatement.java:149)"
  "org.mariadb.jdbc.ClientSidePreparedStatement.executeQuery(ClientSidePreparedStatement.java:163)"
  "com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:431)"
  "--> driver.sql_jdbc.execute$fn__77676.invokeStatic(execute.clj:265)"
  "driver.sql_jdbc.execute$fn__77676.invoke(execute.clj:263)"
  "driver.sql_jdbc.execute$execute_reducible_query$fn__77755.invoke(execute.clj:391)"
  "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:390)"
  "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:375)"
  "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:384)"
  "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:375)"
  "driver.sql_jdbc$fn__79191.invokeStatic(sql_jdbc.clj:54)"
  "driver.sql_jdbc$fn__79191.invoke(sql_jdbc.clj:52)"
  "query_processor.context$executef.invokeStatic(context.clj:59)"
  "query_processor.context$executef.invoke(context.clj:48)"
  "query_processor.context.default$default_runf.invokeStatic(default.clj:68)"
  "query_processor.context.default$default_runf.invoke(default.clj:66)"
  "query_processor.context$runf.invokeStatic(context.clj:45)"
  "query_processor.context$runf.invoke(context.clj:39)"
  "query_processor.reducible$pivot.invokeStatic(reducible.clj:34)"
  "query_processor.reducible$pivot.invoke(reducible.clj:31)"
  "query_processor.middleware.mbql_to_native$mbql__GT_native$fn__46455.invoke(mbql_to_native.clj:25)"
  "query_processor.middleware.check_features$check_features$fn__45707.invoke(check_features.clj:41)"
  "query_processor.middleware.limit$limit$fn__46441.invoke(limit.clj:37)"
  "query_processor.middleware.cache$maybe_return_cached_results$fn__45365.invoke(cache.clj:211)"
  "query_processor.middleware.optimize_datetime_filters$optimize_datetime_filters$fn__46620.invoke(optimize_datetime_filters.clj:133)"
  "query_processor.middleware.auto_parse_filter_values$auto_parse_filter_values$fn__44511.invoke(auto_parse_filter_values.clj:43)"
  "query_processor.middleware.wrap_value_literals$wrap_value_literals$fn__40828.invoke(wrap_value_literals.clj:147)"
  "query_processor.middleware.annotate$add_column_info$fn__40691.invoke(annotate.clj:582)"
  "query_processor.middleware.permissions$check_query_permissions$fn__45582.invoke(permissions.clj:75)"
  "query_processor.middleware.pre_alias_aggregations$pre_alias_aggregations$fn__47143.invoke(pre_alias_aggregations.clj:40)"
  "query_processor.middleware.cumulative_aggregations$handle_cumulative_aggregations$fn__45780.invoke(cumulative_aggregations.clj:60)"
  "query_processor.middleware.resolve_joined_fields$resolve_joined_fields$fn__47456.invoke(resolve_joined_fields.clj:94)"
  "query_processor.middleware.resolve_joins$resolve_joins$fn__47761.invoke(resolve_joins.clj:178)"
  "query_processor.middleware.add_implicit_joins$add_implicit_joins$fn__44105.invoke(add_implicit_joins.clj:181)"
  "query_processor.middleware.large_int_id$convert_id_to_string$fn__46416.invoke(large_int_id.clj:44)"
  "query_processor.middleware.format_rows$format_rows$fn__46396.invoke(format_rows.clj:74)"
  "query_processor.middleware.desugar$desugar$fn__45846.invoke(desugar.clj:21)"
  "query_processor.middleware.binning$update_binning_strategy$fn__44871.invoke(binning.clj:228)"
  "query_processor.middleware.resolve_fields$resolve_fields$fn__45389.invoke(resolve_fields.clj:24)"
  "query_processor.middleware.add_dimension_projections$add_remapping$fn__43735.invoke(add_dimension_projections.clj:314)"
  "query_processor.middleware.add_implicit_clauses$add_implicit_clauses$fn__43966.invoke(add_implicit_clauses.clj:146)"
  "query_processor.middleware.upgrade_field_literals$upgrade_field_literals$fn__48191.invoke(upgrade_field_literals.clj:45)"
  "query_processor.middleware.add_source_metadata$add_source_metadata_for_source_queries$fn__44258.invoke(add_source_metadata.clj:122)"
  "query_processor.middleware.reconcile_breakout_and_order_by_bucketing$reconcile_breakout_and_order_by_bucketing$fn__47340.invoke(reconcile_breakout_and_order_by_bucketing.clj:97)"
  "query_processor.middleware.auto_bucket_datetimes$auto_bucket_datetimes$fn__44458.invoke(auto_bucket_datetimes.clj:139)"
  "query_processor.middleware.resolve_source_table$resolve_source_tables$fn__45436.invoke(resolve_source_table.clj:45)"
  "query_processor.middleware.parameters$substitute_parameters$fn__47125.invoke(parameters.clj:111)"
  "query_processor.middleware.resolve_referenced$resolve_referenced_card_resources$fn__45488.invoke(resolve_referenced.clj:79)"
  "query_processor.middleware.expand_macros$expand_macros$fn__46102.invoke(expand_macros.clj:155)"
  "query_processor.middleware.add_timezone_info$add_timezone_info$fn__44267.invoke(add_timezone_info.clj:15)"
  "query_processor.middleware.splice_params_in_response$splice_params_in_response$fn__48127.invoke(splice_params_in_response.clj:32)"
  "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__47351$fn__47355.invoke(resolve_database_and_driver.clj:31)"
  "driver$do_with_driver.invokeStatic(driver.clj:60)"
  "driver$do_with_driver.invoke(driver.clj:56)"
  "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__47351.invoke(resolve_database_and_driver.clj:25)"
  "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__46342.invoke(fetch_source_query.clj:274)"
  "query_processor.middleware.store$initialize_store$fn__48136$fn__48137.invoke(store.clj:11)"
  "query_processor.store$do_with_store.invokeStatic(store.clj:44)"
  "query_processor.store$do_with_store.invoke(store.clj:38)"
  "query_processor.middleware.store$initialize_store$fn__48136.invoke(store.clj:10)"
  "query_processor.middleware.validate$validate_query$fn__48198.invoke(validate.clj:10)"
  "query_processor.middleware.normalize_query$normalize$fn__46468.invoke(normalize_query.clj:22)"
  "query_processor.middleware.add_rows_truncated$add_rows_truncated$fn__44123.invoke(add_rows_truncated.clj:35)"
  "query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__48112.invoke(results_metadata.clj:147)"
  "query_processor.middleware.constraints$add_default_userland_constraints$fn__45723.invoke(constraints.clj:42)"
  "query_processor.middleware.process_userland_query$process_userland_query$fn__47214.invoke(process_userland_query.clj:135)"
  "query_processor.middleware.catch_exceptions$catch_exceptions$fn__45666.invoke(catch_exceptions.clj:173)"
  "query_processor.reducible$async_qp$qp_STAR___37431$thunk__37432.invoke(reducible.clj:103)"
  "query_processor.reducible$async_qp$qp_STAR___37431.invoke(reducible.clj:109)"
  "query_processor.reducible$sync_qp$qp_STAR___37440$fn__37443.invoke(reducible.clj:135)"
  "query_processor.reducible$sync_qp$qp_STAR___37440.invoke(reducible.clj:134)"
  "query_processor$process_userland_query.invokeStatic(query_processor.clj:237)"
  "query_processor$process_userland_query.doInvoke(query_processor.clj:233)"
  "query_processor$fn__48244$process_query_and_save_execution_BANG___48253$fn__48256.invoke(query_processor.clj:249)"
  "query_processor$fn__48244$process_query_and_save_execution_BANG___48253.invoke(query_processor.clj:241)"
  "query_processor$fn__48288$process_query_and_save_with_max_results_constraints_BANG___48297$fn__48300.invoke(query_processor.clj:261)"
  "query_processor$fn__48288$process_query_and_save_with_max_results_constraints_BANG___48297.invoke(query_processor.clj:254)"
  "api.dataset$run_query_async$fn__54402.invoke(dataset.clj:56)"
  "query_processor.streaming$streaming_response_STAR_$fn__54381$fn__54382.invoke(streaming.clj:72)"
  "query_processor.streaming$streaming_response_STAR_$fn__54381.invoke(streaming.clj:71)"
  "async.streaming_response$do_f_STAR_.invokeStatic(streaming_response.clj:65)"
  "async.streaming_response$do_f_STAR_.invoke(streaming_response.clj:63)"
  "async.streaming_response$do_f_async$fn__16058.invoke(streaming_response.clj:84)"],
 :context :ad-hoc,
 :error "(conn=1597326) Query execution was interrupted",
 :row_count 0,
 :running_time 0,
 :data {:rows [], :cols []}}

I notice that there is some discussion of 60 second timeouts for some drivers, e.g. https://github.com/metabase/metabase/blob/256f8cef7a7c68ea9c29ff66b2c8c5168fb3c837/modules/drivers/bigquery/src/metabase/driver/bigquery.clj#L129. So it doesn't seem implausible that this value is lurking somewhere. Does this callstack help at all?

edward_hibbert · June 1, 2021, 5:27pm

I now understand what @flamber was driving at, and he or she is quite right, as you'd expect.

For the benefit of anyone stumbling across this thread who is as slow on the uptake as I am, this is what I did.

I installed the Metabase docker image.
I set up a reverse proxy to expose that on the web, in my case nginx.
nginx has a default timeout of 60 seconds on the proxy_pass directive. My mind was focused on Metabase itself.
Once that timeout expires, nginx closes the connection even though the query is still in progress.
On the server side, the connection being closed causes Metabase to cancel the underlying database query - which makes it look a bit like it decided to do so itself, but is just reacting to the closed connection.
On the web client, it handles the loss of connection to the server gracefully, and displays an error - which makes it look as though it is showing an error from the server, but it's not, it's just also reacting to the closed connection.

Changing the proxy configuration to add something like this helps

   proxy_read_timeout 300;
   proxy_connect_timeout 300;
   proxy_send_timeout 300;

@flamber, sorry for being a bit dim. Would it be worth mentioning something about proxy timeouts in https://www.metabase.com/docs/latest/operations-guide/running-metabase-on-docker.html ?

flamber · June 1, 2021, 5:43pm

@edward_hibbert
Excellent that you found the proxy stuff, and you actually took the time to write it up

There's no reverse-proxy together with Metabase out-of-the-box (except for ElasticBeanstalk, which will be removed), so that's outside of what Metabase can control and handle. And there are so many different ways of running Metabase, and so many different reverse-proxies that it would put a load on us to maintain.

You're seeing this issue:
https://github.com/metabase/metabase/issues/12423 - upvote by clicking on the first post

And just for reference, but completely unrelated to your problem, but since you were linking to the BigQuery driver source - that's this issue:
https://github.com/metabase/metabase/issues/12003