Extremely poor UI performance - activity/dashboard/database apis run MANY queries

[mattdoran]

We are running 0.27.2 with MySQL 5.7 hosted in Google Cloud.

We are seeing very poor performance on our metabase instance rendering the commonly viewed pages. In analysing the network calls using Chrome inspector we see calls to /api/activity, /api/dashboard and /api/database that are very slow, and consistently 30-40 seconds on our production database. These APIs being slow make the UI nearly unusable.

This is likely related to #6782.

I raised the issue in discourse too - http://discourse.metabase.com/t/slow-api-calls-resulting-in-very-poor-user-experience/2885

I got metabase running in development environment, tweaked the debug logging levels and captured the evidence. The attached logs show the debug logs from these API calls, each performs a HUGE number of SQL queries. Maybe this isn't obvious to you when running low latency H2 DB, but with latency of network DB, these become more obvious??

NOTE: these logs show me connecting to cloud hosted SQL in north america from Australia - so latencies are exacerbated.

As a sample:

metabase.middleware :: GET /api/database 200 (3 mins) (915 DB calls)
metabase.middleware :: GET /api/dashboard 200 (1 mins) (333 DB calls)

for the activity API, it returns the above debug line quickly, but then runs for another 40+ seconds hitting the report_card table repeatedly.

This is particularly bad for us because we have a docker cluster running in APAC and this SQL database is in the USA (don't ask!!).

database-api.txt
dashboard-api.txt
activity-api.txt

[salsakran]

Hey @mattdoran -

We're taking these scaling/performance issues fairly seriously and closed a number of them in 0.28. If you can, I'd love to see if any of these have been resolved in 0.28 which is on docker hub now as we get ready to release things.

We'd like to squash as many of these as we can in 0.28.1 and 0.29.

[mattdoran]

Just pulled 0.28 branch and at first glance it does seem better.

Not testing quite as I was before (I'm running on a local copy of the db now - didn't want to change schema under the production instance).

But the /api/database/ had 1022 DB calls (!) on first call, less on second. Cached? But 1000 calls would KILL the performance in our setup.

/api/dashboard has ~90 db calls

/api/activity seems better ... for some reason there are lots of db calls after id dumps the call count for that API.

[mattdoran]

the /api/card API is also nasty in 0.27.2.

DEBUG metabase.middleware :: GET /api/card 200 (13 s) (1877 DB calls)

ouch!

PS: we moved the DB to the same region hoping it would help, but with 0.27.2 the performance is still terrible.

Even if each query only takes 30ms, that's 56 seconds... so it doesn't take much latency to make this unusable.

[mattdoran]

Just upgraded to 0.28.0, it's better ... more caching? Still see very slow loads (see below), but in some places the second attempt is much faster with less DB calls.

... still room for improvement. ;)

Dashboard loading is pretty slow, 21 seconds - was about 40 seconds.

DEBUG metabase.middleware :: GET /api/dashboard 200 (21 s) (128 DB calls)

Loading the /api/database is still way too slow... 2 mins, 893 db calls

DEBUG metabase.middleware :: GET /api/database 200 (2 mins) (893 DB calls)

Same story for loading the questions:

DEBUG metabase.middleware :: GET /api/card 200 (2 mins) (849 DB calls)

[salsakran]

@mattdoran part caching, part more efficient querying, and optimizations on a number of fronts. Think remaining problem you're seeing is in applying permissions. The linked PR should help by pre-computing these on card edits rather than at read time.

[mattdoran]

@salsakran is this due to our config? If we allow access to all then are these checks not done?

(I ask coz we previously used permission and then decided it wasn’t needed so opened it up again.

[camsaul]

Fixed by #6945

[salsakran]

@mattdoran

I'm not entirely sure. @camsaul can you weigh in? Also, if you can, could you check whether that PR fixes your performance woes?

[mattdoran]

@salsakran it seems to be better. The /database API call is now taking 79 DB queries when it was almost 900 before.

PR #6945 seems to have been merged to 0.28.1 branch .... should that have been 0.28.2 branch?

[mattdoran]

@salsakran This coming to maintenance release, or waiting for 0.29?

[VikramTiwari]

@mattdoran Seem so, based on the milestone.

[salsakran]

@mattdoran we're releasing this shortly in 0.28.2. We'll be folding a few other performance improvements in 0.29 which is nearly feature complete.