Dashboard with 14 Cards loads slow. What could be the bottleneck?

wuarmin · May 2, 2022, 1:44pm

Hey,
we have a dashboard with about 14 boxes. In my current tests the slowest query needs about 650 ms to finish. It still takes about 5-15! (we are using Firefox and I see performance differences between FF under Linux and Windows, Linux is faster) seconds to load the whole dashboard (until the last box is rendered). In my tests the slowest XHR-request needs about 700 ms. So I can rule out a server or network problem, in my opinion.

Does anyone have a hint why it takes so long for the box contents to become visible?

Thanks and best regards

flamber · May 2, 2022, 1:49pm

Hi @wuarmin
Post "Diagnostic Info" from Admin > Troubleshooting.
If the requests finishes within expected, then it's about browser rendering. Many things can be involved, everything from browser addons/extensions to bugs in Metabase for specific visualizations.

wuarmin · May 2, 2022, 1:52pm

@flamber thanks for the fast response. This is logged while loading the dashboard:

[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log GET /api/dashboard/15 200 150.5 ms (27 DB-Aufrufe) DB-Verbindungen anwenden: 1/15 Jetty threads: 8/50 (2 untätig, 0 wartend) (168 aktive threads ingesamt) Abfragen in Ausführung: 0 (0 wartend)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log GET /api/table/995/query_metadata 200 20.7 ms (10 DB-Aufrufe) DB-Verbindungen anwenden: 0/15 Jetty threads: 9/50 (2 untätig, 0 wartend) (168 aktive threads ingesamt) Abfragen in Ausführung: 0 (0 wartend)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log GET /api/table/949/query_metadata 200 33.7 ms (11 DB-Aufrufe) DB-Verbindungen anwenden: 0/15 Jetty threads: 9/50 (2 untätig, 0 wartend) (168 aktive threads ingesamt) Abfragen in Ausführung: 0 (0 wartend)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log GET /api/table/997/query_metadata 200 15.7 ms (8 DB-Aufrufe) DB-Verbindungen anwenden: 1/15 Jetty threads: 9/50 (2 untätig, 0 wartend) (168 aktive threads ingesamt) Abfragen in Ausführung: 0 (0 wartend)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log GET /api/table/942/query_metadata 200 35.2 ms (10 DB-Aufrufe) DB-Verbindungen anwenden: 0/15 Jetty threads: 8/50 (2 untätig, 0 wartend) (168 aktive threads ingesamt) Abfragen in Ausführung: 0 (0 wartend)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 292.0 ms; bei Verwendung der "magischen" TTL von 29.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 334.0 ms; bei Verwendung der "magischen" TTL von 33.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 384.0 ms; bei Verwendung der "magischen" TTL von 38.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 310.0 ms; bei Verwendung der "magischen" TTL von 31.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 338.0 ms; bei Verwendung der "magischen" TTL von 34.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 456.0 ms; bei Verwendung der "magischen" TTL von 46.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 280.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log POST /api/card/49/query 202 [ASYNC: completed] 333.0 ms (15 DB-Aufrufe) DB-Verbindungen anwenden: 2/15 Jetty threads: 7/50 (2 untätig, 0 wartend) (171 aktive threads ingesamt) Abfragen in Ausführung: 5 (0 wartend); postgres DB 5 connections: 0/1 (0 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 275.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log POST /api/card/51/query 202 [ASYNC: completed] 318.0 ms (16 DB-Aufrufe) DB-Verbindungen anwenden: 2/15 Jetty threads: 7/50 (2 untätig, 0 wartend) (171 aktive threads ingesamt) Abfragen in Ausführung: 4 (0 wartend); postgres DB 5 connections: 1/1 (2 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 321.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 239.0 ms; bei Verwendung der "magischen" TTL von 24.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 317.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log POST /api/card/44/query 202 [ASYNC: completed] 386.7 ms (17 DB-Aufrufe) DB-Verbindungen anwenden: 3/15 Jetty threads: 8/50 (2 untätig, 0 wartend) (171 aktive threads ingesamt) Abfragen in Ausführung: 4 (0 wartend); postgres DB 5 connections: 1/1 (0 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log POST /api/card/48/query 202 [ASYNC: completed] 365.6 ms (15 DB-Aufrufe) DB-Verbindungen anwenden: 3/15 Jetty threads: 8/50 (2 untätig, 0 wartend) (171 aktive threads ingesamt) Abfragen in Ausführung: 3 (0 wartend); postgres DB 5 connections: 1/1 (1 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 303.0 ms; bei Verwendung der "magischen" TTL von 30.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 270.0 ms; bei Verwendung der "magischen" TTL von 27.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 283.0 ms; bei Verwendung der "magischen" TTL von 28.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 344.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log POST /api/card/43/query 202 [ASYNC: completed] 437.0 ms (20 DB-Aufrufe) DB-Verbindungen anwenden: 1/15 Jetty threads: 7/50 (2 untätig, 0 wartend) (171 aktive threads ingesamt) Abfragen in Ausführung: 5 (0 wartend); postgres DB 5 connections: 1/1 (3 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.api.card Die durchschnittliche Ausführungsdauer der Frage ist 251.0 ms; bei Verwendung der "magischen" TTL von 25.0 s 💾
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 379.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 DEBUG metabase.server.middleware.log POST /api/card/46/query 202 [ASYNC: completed] 485.3 ms (31 DB-Aufrufe) DB-Verbindungen anwenden: 1/15 Jetty threads: 7/50 (2 untätig, 0 wartend) (171 aktive threads ingesamt) Abfragen in Ausführung: 5 (0 wartend); postgres DB 5 connections: 5/5 (0 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:02+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 161.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 DEBUG metabase.server.middleware.log POST /api/card/322/query 202 [ASYNC: completed] 220.2 ms (15 DB-Aufrufe) DB-Verbindungen anwenden: 2/15 Jetty threads: 8/50 (2 untätig, 0 wartend) (172 aktive threads ingesamt) Abfragen in Ausführung: 4 (0 wartend); postgres DB 5 connections: 2/6 (0 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 DEBUG metabase.server.middleware.log GET /api/table/969/query_metadata 200 15.4 ms (10 DB-Aufrufe) DB-Verbindungen anwenden: 0/15 Jetty threads: 8/50 (2 untätig, 0 wartend) (172 aktive threads ingesamt) Abfragen in Ausführung: 4 (0 wartend)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 DEBUG metabase.server.middleware.log GET /api/table/966/query_metadata 200 17.2 ms (10 DB-Aufrufe) DB-Verbindungen anwenden: 0/15 Jetty threads: 8/50 (2 untätig, 0 wartend) (172 aktive threads ingesamt) Abfragen in Ausführung: 4 (0 wartend)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 191.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 DEBUG metabase.server.middleware.log POST /api/card/367/query 202 [ASYNC: completed] 268.9 ms (17 DB-Aufrufe) DB-Verbindungen anwenden: 2/15 Jetty threads: 7/50 (2 untätig, 0 wartend) (172 aktive threads ingesamt) Abfragen in Ausführung: 3 (0 wartend); postgres DB 5 connections: 4/6 (0 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 287.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 DEBUG metabase.server.middleware.log POST /api/card/356/query 202 [ASYNC: completed] 381.5 ms (16 DB-Aufrufe) DB-Verbindungen anwenden: 2/15 Jetty threads: 7/50 (2 untätig, 0 wartend) (172 aktive threads ingesamt) Abfragen in Ausführung: 2 (0 wartend); postgres DB 5 connections: 3/6 (0 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 315.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 INFO metabase.query-processor.middleware.cache Die Abfrage dauerte 350.0 ms, um ausgeführt zu werden. Das Minimum für die Cache-Berechtigung beträgt 10.0 s
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 DEBUG metabase.server.middleware.log POST /api/card/365/query 202 [ASYNC: completed] 413.8 ms (17 DB-Aufrufe) DB-Verbindungen anwenden: 3/15 Jetty threads: 7/50 (3 untätig, 0 wartend) (174 aktive threads ingesamt) Abfragen in Ausführung: 1 (0 wartend); postgres DB 5 connections: 4/6 (0 threads blocked)
[3257d725-6469-45f2-9ed4-926b6e6af35c] 2022-05-02T15:43:03+02:00 DEBUG metabase.server.middleware.log POST /api/card/357/query 202 [ASYNC: completed] 419.5 ms (16 DB-Aufrufe) DB-Verbindungen anwenden: 3/15 Jetty threads: 7/50 (3 untätig, 0 wartend) (174 aktive threads ingesamt) Abfragen in Ausführung: 0 (0 wartend); postgres DB 5 connections: 2/6 (0 threads blocked)

flamber · May 2, 2022, 1:54pm

@wuarmin Post "Diagnostic Info" from Admin > Troubleshooting.

wuarmin · May 2, 2022, 1:56pm

@flamber sorry, here:

LINUX (faster than windows)

{
  "browser-info": {
    "language": "de-AT",
    "platform": "Linux x86_64",
    "userAgent": "Mozilla/5.0 (X11; Linux x86_64; rv:100.0) Gecko/20100101 Firefox/100.0",
    "vendor": ""
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "11.0.13+8",
    "java.vendor": "Eclipse Adoptium",
    "java.vendor.url": "https://adoptium.net/",
    "java.version": "11.0.13",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "11.0.13+8",
    "os.name": "Linux",
    "os.version": "5.10.0-10-amd64",
    "user.language": "en",
    "user.timezone": "Europe/Vienna"
  },
  "metabase-info": {
    "databases": [
      "sqlserver",
      "mysql",
      "postgres"
    ],
    "hosting-env": "unknown",
    "application-database": "postgres",
    "application-database-details": {
      "database": {
        "name": "PostgreSQL",
        "version": "11.14 (Debian 11.14-1.pgdg90+1)"
      },
      "jdbc-driver": {
        "name": "PostgreSQL JDBC Driver",
        "version": "42.2.23"
      }
    },
    "run-mode": "prod",
    "version": {
      "date": "2021-12-16",
      "tag": "v0.41.5",
      "branch": "release-x.41.x",
      "hash": "fbfffc6"
    },
    "settings": {
      "report-timezone": "Europe/Vienna"
    }
  }
}

Windows (very slow)

{
  "browser-info": {
    "language": "de",
    "platform": "Win32",
    "userAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:99.0) Gecko/20100101 Firefox/99.0",
    "vendor": ""
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "11.0.13+8",
    "java.vendor": "Eclipse Adoptium",
    "java.vendor.url": "https://adoptium.net/",
    "java.version": "11.0.13",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "11.0.13+8",
    "os.name": "Linux",
    "os.version": "5.10.0-10-amd64",
    "user.language": "en",
    "user.timezone": "Europe/Vienna"
  },
  "metabase-info": {
    "databases": [
      "sqlserver",
      "mysql",
      "postgres"
    ],
    "hosting-env": "unknown",
    "application-database": "postgres",
    "application-database-details": {
      "database": {
        "name": "PostgreSQL",
        "version": "11.14 (Debian 11.14-1.pgdg90+1)"
      },
      "jdbc-driver": {
        "name": "PostgreSQL JDBC Driver",
        "version": "42.2.23"
      }
    },
    "run-mode": "prod",
    "version": {
      "date": "2021-12-16",
      "tag": "v0.41.5",
      "branch": "release-x.41.x",
      "hash": "fbfffc6"
    },
    "settings": {
      "report-timezone": "Europe/Vienna"
    }
  }
}

flamber · May 2, 2022, 2:03pm

@wuarmin There's been several fixes to visualization and dashboard performance in newer version, and a lot of performance fixes coming in the upcoming 0.43.0. Latest release is 0.42.4:
https://github.com/metabase/metabase/releases

You are using Firefox 100 on Linux, and Firefox 99 on Windows. And you are using different display drivers on the different OS. And you likely have different browser addons/extensions and settings too.

wuarmin · May 2, 2022, 2:41pm

@flamber Thanks for your hints. We will update to latest Metabase and I will post feedback.

wuarmin · May 2, 2022, 4:26pm

@flamber we upgraded to 0.43 RC. Unfortunately, we cannot observe any performance improvement.
I think that 14 boxes with graphics and values are just too many, at the moment. WDYT?

flamber · May 2, 2022, 5:27pm

@wuarmin I've seen dashboards with 50+ visualizations - it depends on the client browser if you are adding a lot of data for the browser to process.

Use the browser developer Network and Performance-tabs to see if you can figure out what is causing the problem.

wuarmin · May 3, 2022, 7:21am

@flamber In the network tab, I can't see what's making it so slow. In the performance tab I can produce the following:

The time of waiting to transmit the response is very high:

Do you have further hints? Our server runs on Docker.
Thanks

flamber · May 3, 2022, 9:07am

@wuarmin Please read this, specially the part about http/2: https://www.metabase.com/learn/administration/metabase-at-scale
And you are using a reverse-proxy in front of Metabase, which could be part of the cause.
I cannot help you much, since it's something in your setup, which is not publicly available.

wuarmin · May 5, 2022, 11:44am

@flamber Thank you. We will try to enable HTTP/2. Yes we have a reverse-proxy (HA Proxy) in front of Metabase. However, if I bypass the reverse proxy, the performance is the same.

flamber · May 5, 2022, 11:50am

@wuarmin Use the Sample Database. Create a couple of graphs. Validate the speed with that.
There's more than 40k installations of Metabase. If this was a common problem, then it would have been noted.

But something is telling me that you have defined the environment variable https://www.metabase.com/docs/latest/operations-guide/environment-variables.html#mb_jdbc_data_warehouse_max_connection_pool_size to some custom value, which is way too low.

wuarmin · May 5, 2022, 12:29pm

@flamber we set up at HA-Proxy to HTTP/2, but performance does not change. The environment var, you mentioned, is set to 15 (default).

flamber · May 5, 2022, 12:37pm

@wuarmin Run Metabase locally on your computer, then try to debug from there. Like I mention, there's millions of users, we would have seen reports about this if it was a general problem.

mmoole · May 13, 2022, 10:06pm

I also came across this and thought its still being fixed in the next releases (after reading the github issues), but now I just spun up metabase.jar on a linux machine, and its blazingly fast.
On the Windows box which runs it normally I use Amazon Coretto Java, and there always is a kind of lag of about 6 to 7 seconds before any dashboard completes loading and begins displaying the contents.
I will get to more details of this in the next days...

loctranp · May 16, 2022, 1:54am

Most of the time the slow loading is caused by your DB server. Metabase only runs queries, fetches the data, and visualizes them. I tried with a 65mil records DB and I can feel my DB server is screaming for help when running queries.

mmoole · May 21, 2022, 11:50am

As it turns out in this specific case, it is a network configuration issue. On localhost and other subnets, all is working instantly, but it was not from the subnet that I was in