We're sending twice the necessary number of requests on x-ray first load

[paoliniluis]

Describe the bug

UPDATE: getting the issue on a release version. The x-rays send lots of calls, that get rejected and then it sends again queries that get answered

To Reproduce

1. set up 48.3 with a database
2. add a db
3. use any x-ray

Expected behavior

This should work normally, only the needed api calls

Logs

2023-12-13 21:43:12,749 DEBUG middleware.log :: GET /api/collection/tree 200 4.6 ms (5 DB calls) App DB connections: 0/15 Jetty threads: 8/50 (10 idle, 0 queued) (136 total active threads) Queries in flight: 0 (0 queued)
2023-12-13 21:43:12,753 DEBUG middleware.log :: GET /api/search 200 10.2 ms (4 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (10 idle, 0 queued) (136 total active threads) Queries in flight: 0 (0 queued)
2023-12-13 21:46:14,797 DEBUG middleware.log :: GET /api/database/2/schema/public 200 4.6 ms (4 DB calls) App DB connections: 0/15 Jetty threads: 7/50 (11 idle, 0 queued) (132 total active threads) Queries in flight: 0 (0 queued)
2023-12-13 21:46:17,964 DEBUG middleware.log :: GET /api/automagic-dashboards/table/62 200 35.9 ms (31 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (11 idle, 0 queued) (133 total active threads) Queries in flight: 0 (0 queued)
2023-12-13 21:46:17,982 DEBUG middleware.log :: GET /api/table/62/query_metadata 200 8.2 ms (9 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (11 idle, 0 queued) (133 total active threads) Queries in flight: 0 (0 queued)
2023-12-13 21:46:18,679 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 675.3 ms (15 DB calls) App DB connections: 0/15 Jetty threads: 5/50 (9 idle, 0 queued) (133 total active threads) Queries in flight: 11 (0 queued); redshift DB 2 connections: 0/1 (0 threads blocked)
2023-12-13 21:46:19,821 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: canceled] 1.8 s (15 DB calls) App DB connections: 0/15 Jetty threads: 5/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 10 (0 queued); redshift DB 2 connections: 1/1 (0 threads blocked)
2023-12-13 21:46:19,859 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 1.6 s (15 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 9 (0 queued); redshift DB 2 connections: 1/1 (10 threads blocked)
2023-12-13 21:46:19,865 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: canceled] 1.9 s (15 DB calls) App DB connections: 1/15 Jetty threads: 7/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 8 (0 queued); redshift DB 2 connections: 1/1 (1 threads blocked)
2023-12-13 21:46:20,851 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 2.5 s (15 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 8 (0 queued); redshift DB 2 connections: 1/1 (6 threads blocked)
2023-12-13 21:46:20,876 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 1.0 s (15 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 8 (0 queued); redshift DB 2 connections: 4/4 (8 threads blocked)
2023-12-13 21:46:20,877 WARN middleware.log :: OST /api/dataset 404 94.0 µs (0 DB calls) 
#metabase.util.i18n.UserLocalizedString{:format-string "API endpoint does not exist.", :args [], :pluralization-opts {}}

2023-12-13 21:46:20,972 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 2.7 s (15 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 8 (0 queued); redshift DB 2 connections: 1/1 (9 threads blocked)
2023-12-13 21:46:21,754 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: canceled] 3.7 s (15 DB calls) App DB connections: 0/15 Jetty threads: 5/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 8 (0 queued); redshift DB 2 connections: 1/1 (2 threads blocked)
2023-12-13 21:46:21,841 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: canceled] 3.8 s (15 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 6 (0 queued); redshift DB 2 connections: 1/1 (3 threads blocked)
2023-12-13 21:46:21,841 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 3.5 s (15 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 6 (0 queued); redshift DB 2 connections: 1/1 (6 threads blocked)
2023-12-13 21:46:21,928 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 3.6 s (15 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 6 (0 queued); redshift DB 2 connections: 1/1 (6 threads blocked)
2023-12-13 21:46:21,998 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 1.0 s (16 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 6 (0 queued); redshift DB 2 connections: 7/7 (8 threads blocked)
2023-12-13 21:46:21,999 WARN middleware.log :: OST /api/dataset 404 101.7 µs (0 DB calls) 
#metabase.util.i18n.UserLocalizedString{:format-string "API endpoint does not exist.", :args [], :pluralization-opts {}}

2023-12-13 21:46:22,714 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 4.4 s (15 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 6 (0 queued); redshift DB 2 connections: 1/1 (5 threads blocked)
2023-12-13 21:46:22,730 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 728.7 ms (16 DB calls) App DB connections: 0/15 Jetty threads: 5/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 5 (0 queued); redshift DB 2 connections: 10/10 (4 threads blocked)
2023-12-13 21:46:22,867 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 1.0 s (16 DB calls) App DB connections: 0/15 Jetty threads: 5/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 4 (0 queued); redshift DB 2 connections: 10/10 (2 threads blocked)
2023-12-13 21:46:22,916 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: canceled] 4.9 s (15 DB calls) App DB connections: 0/15 Jetty threads: 6/50 (8 idle, 0 queued) (138 total active threads) Queries in flight: 3 (0 queued); redshift DB 2 connections: 1/1 (4 threads blocked)
2023-12-13 21:46:22,978 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 1.0 s (16 DB calls) App DB connections: 0/15 Jetty threads: 5/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 2 (0 queued); redshift DB 2 connections: 10/10 (3 threads blocked)
2023-12-13 21:46:28,818 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 7.9 s (16 DB calls) App DB connections: 0/15 Jetty threads: 5/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 1 (0 queued); redshift DB 2 connections: 7/7 (7 threads blocked)
2023-12-13 21:46:28,985 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 8.1 s (15 DB calls) App DB connections: 0/15 Jetty threads: 5/50 (9 idle, 0 queued) (138 total active threads) Queries in flight: 0 (0 queued); redshift DB 2 connections: 7/7 (6 threads blocked)

Information about your Metabase installation

48.3

Severity

P3

Additional context

[paoliniluis]

getting this on 48.3 on postgres with a completely normal deployment

[darksciencebase]

@paoliniluis you've added the regression label — any hint on which version did this work normally on?

[paoliniluis]

worked fine in 47.13, Jetty dependency upgrade maybe?

[piranha]

Bisect indicates that the first faulty commit is d161a9c, which is puzzling to me - there are almost no back-end changes.

[piranha]

I'm not sure if that commit is the problem, maybe I need to dig deeper. Why this commit appeared in bisect: it stopped removing null-values from parameterValues map. And DashboardData component would initiate request first with an empty map and then with map like {param1id: null, param2id: null}. So on the first look this change fixes the problem:

diff --git frontend/src/metabase/parameters/utils/parameter-values.ts frontend/src/metabase/parameters/utils/parameter-values.ts
index 06a18b1b26..beffe9ff33 100644
--- frontend/src/metabase/parameters/utils/parameter-values.ts
+++ frontend/src/metabase/parameters/utils/parameter-values.ts
@@ -105,6 +105,6 @@ export function getParameterValuesByIdFromQueryParams(
     parameters.map(parameter => [
       parameter.id,
       getParameterValueFromQueryParams(parameter, queryParams),
-    ]),
+    ]).filter(([_, v]) => v !== null),
   );
 }

But it turns out that if you select any parameter, then DashboardData first fetches data with empty map, and then with {param1id: "actualValue"} and double-requests are still happening! So it seems like d161a9c only surfaced the issue, but the issue itself happened somewhere earlier.

[piranha]

Okaaay! So the thing is, I've tested 47.13, and if you choose at least one of parameters, then you'll get that problem with sending and cancelling requests immediately. So obviously d161a9c just exposed that issue for the empty parameters, but it's there for a long time.

I think this is an escalation for some front-end dev to handle.