Question took too long

bb-centrum · August 25, 2023, 12:55pm

Hi All

I have a question that takes quite a long time to run. I can run the question in DBeaver and I get the results in 12 mins but in metabase it seems to time out after 10 mins.

I have read several errors here that its a timeout due to a proxy such as Nginx. However I am not running a proxy. I am running metabase via .JAR file and connecting through the local network. So that is not the issue.

Metabase Question
Raw SQL query. I filled in the variable JobCode but left the optional account code blank.

select pileData.*, `concdiary`.*
from `concdiary`
right join
(select `piles`.*, jobData.JobCode
from `piles`
right join
(select * from jobcodes
where JobCode = {{JobCode}}
[[AND AccCode = {{AccountCode}}]]) jobData
on `piles`.Serials = jobData.serial) pileData
on pileData.ID = `concdiary`.ID

Metabase verion
I'm running v0.4.0.0 The latest as of writing
Java Version

java 19 2022-09-20
Java(TM) SE Runtime Environment (build 19+36-2238)
Java HotSpot(TM) 64-Bit Server VM (build 19+36-2238, mixed mode, sharing)

Relevant Logs
Only thing either side of these logs were the database sync processes which I don;t think are related.

[62c3c945-d069-42db-86c9-0107ebde6043] 2023-08-25T13:39:50+01:00 DEBUG metabase.server.middleware.log POST /api/card/6/query 202 [ASYNC: canceled] 10.1 mins (8 DB calls) App DB connections: 0/3 Jetty threads: 5/50 (1 idle, 0 queued) (123 total active threads) Queries in flight: 0 (0 queued); mysql DB 2 connections: 0/1 (0 threads blocked)
[62c3c945-d069-42db-86c9-0107ebde6043] 2023-08-25T13:39:50+01:00 ERROR metabase.query-processor.middleware.catch-exceptions Error processing query: (conn=191) Query execution was interrupted
{:database_id 2,
 :started_at #t "2023-08-25T13:29:46.426350700+01:00[Europe/London]",
 :via
 [{:status :failed,
   :class clojure.lang.ExceptionInfo,
   :error "Error executing query: (conn=191) Query execution was interrupted",
   :stacktrace
   ["--> driver.sql_jdbc.execute$execute_reducible_query$fn__71852.invoke(execute.clj:505)"
    "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:502)"
    "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:489)"
    "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:497)"
    "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:489)"
    "driver.sql_jdbc$fn__105186.invokeStatic(sql_jdbc.clj:63)"
    "driver.sql_jdbc$fn__105186.invoke(sql_jdbc.clj:61)"
    "query_processor.context$executef.invokeStatic(context.clj:60)"
    "query_processor.context$executef.invoke(context.clj:49)"
    "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:46)"
    "query_processor.context$runf.invoke(context.clj:40)"
    "query_processor.reducible$identity_qp.invokeStatic(reducible.clj:15)"
    "query_processor.reducible$identity_qp.invoke(reducible.clj:12)"
    "query_processor.middleware.cache$maybe_return_cached_results$maybe_return_cached_results_STAR___69236.invoke(cache.clj:224)"
    "query_processor.middleware.permissions$check_query_permissions$fn__64708.invoke(permissions.clj:126)"
    "query_processor.middleware.mbql_to_native$mbql__GT_native$fn__68127.invoke(mbql_to_native.clj:24)"
    "query_processor$fn__70755$combined_post_process__70760$combined_post_process_STAR___70761.invoke(query_processor.clj:243)"
    "query_processor$fn__70755$combined_pre_process__70756$combined_pre_process_STAR___70757.invoke(query_processor.clj:240)"
    "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__69147$fn__69152.invoke(resolve_database_and_driver.clj:36)"
    "driver$do_with_driver.invokeStatic(driver.clj:90)"
    "driver$do_with_driver.invoke(driver.clj:86)"
    "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__69147.invoke(resolve_database_and_driver.clj:35)"
    "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__65018.invoke(fetch_source_query.clj:316)"
    "query_processor.middleware.store$initialize_store$fn__65196$fn__65197.invoke(store.clj:12)"
    "query_processor.store$do_with_store.invokeStatic(store.clj:47)"
    "query_processor.store$do_with_store.invoke(store.clj:41)"
    "query_processor.middleware.store$initialize_store$fn__65196.invoke(store.clj:11)"
    "query_processor.middleware.normalize_query$normalize$fn__69436.invoke(normalize_query.clj:25)"
    "query_processor.middleware.constraints$add_default_userland_constraints$fn__66374.invoke(constraints.clj:54)"
    "query_processor.middleware.process_userland_query$process_userland_query$fn__69372.invoke(process_userland_query.clj:151)"
    "query_processor.middleware.catch_exceptions$catch_exceptions$fn__69749.invoke(catch_exceptions.clj:171)"
    "query_processor.reducible$async_qp$qp_STAR___59517$thunk__59519.invoke(reducible.clj:103)"
    "query_processor.reducible$async_qp$qp_STAR___59517$fn__59521.invoke(reducible.clj:108)"],
   :error_type :invalid-query,
   :ex-data
   {:driver :mysql,
    :sql
    ["-- Metabase:: userID: 3 queryType: native queryHash: d913eb340b9693353536fac58820b67dab8c98c92aac3ee750aef77fef92a3d2"
     "select"
     "  pileData.*,"
     "  `concdiary`.*"
     "from"
     "  `concdiary`"
     "  right join ("
     "    select"
     "      `piles`.*,"
     "      jobData.JobCode"
     "    from"
     "      `piles`"
     "      right join ("
     "        select"
     "          *"
     "        from"
     "          jobcodes"
     "        where"
     "          JobCode = ?"
     "      ) jobData on `piles`.Serials = jobData.serial"
     "  ) pileData on pileData.ID = `concdiary`.ID"],
    :params ["2016959"],
    :type :invalid-query}}],
 :state "70100",
 :error_type :invalid-query,
 :json_query
 {:constraints {:max-results 10000, :max-results-bare-rows 2000},
  :type :native,
  :middleware {:js-int-to-string? true, :ignore-cached-results? true, :process-viz-settings? false},
  :native
  {:query
   "select pileData.*, `concdiary`.*\r\nfrom `concdiary`\r\nright join\r\n(select `piles`.*, jobData.JobCode\r\nfrom `piles`\r\nright join\r\n(select * from jobcodes\r\nwhere JobCode = {{JobCode}}\r\n[[AND AccCode = {{AccountCode}}]]) jobData\r\non `piles`.Serials = jobData.serial) pileData\r\non pileData.ID = `concdiary`.ID",
   :template-tags
   {"JobCode" {:id "624217d5-04c9-207b-78cc-7c088b4a957b", :name "JobCode", :display-name "Jobcode", :type :text},
    "AccountCode"
    {:id "97c29b75-86c2-24f7-b1b8-ac591ddf9af0", :name "AccountCode", :display-name "Accountcode", :type :text}},
   :collection "Barcodes"},
  :database 2,
  :parameters
  [{:id "624217d5-04c9-207b-78cc-7c088b4a957b",
    :type "category",
    :value "2016959",
    :target ["variable" ["template-tag" "JobCode"]]}],
  :async? true,
  :cache-ttl nil},
 :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:158)"
  "org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:262)"
  "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:1471)"
  "--> driver.sql_jdbc.execute$fn__71775.invokeStatic(execute.clj:380)"
  "driver.sql_jdbc.execute$fn__71775.invoke(execute.clj:378)"
  "driver.sql_jdbc.execute$execute_statement_or_prepared_statement_BANG_.invokeStatic(execute.clj:393)"
  "driver.sql_jdbc.execute$execute_statement_or_prepared_statement_BANG_.invoke(execute.clj:389)"
  "driver.sql_jdbc.execute$execute_reducible_query$fn__71852.invoke(execute.clj:503)"
  "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:502)"
  "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:489)"
  "driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:497)"
  "driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:489)"
  "driver.sql_jdbc$fn__105186.invokeStatic(sql_jdbc.clj:63)"
  "driver.sql_jdbc$fn__105186.invoke(sql_jdbc.clj:61)"
  "query_processor.context$executef.invokeStatic(context.clj:60)"
  "query_processor.context$executef.invoke(context.clj:49)"
  "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:46)"
  "query_processor.context$runf.invoke(context.clj:40)"
  "query_processor.reducible$identity_qp.invokeStatic(reducible.clj:15)"
  "query_processor.reducible$identity_qp.invoke(reducible.clj:12)"
  "query_processor.middleware.cache$maybe_return_cached_results$maybe_return_cached_results_STAR___69236.invoke(cache.clj:224)"
  "query_processor.middleware.permissions$check_query_permissions$fn__64708.invoke(permissions.clj:126)"
  "query_processor.middleware.mbql_to_native$mbql__GT_native$fn__68127.invoke(mbql_to_native.clj:24)"
  "query_processor$fn__70755$combined_post_process__70760$combined_post_process_STAR___70761.invoke(query_processor.clj:243)"
  "query_processor$fn__70755$combined_pre_process__70756$combined_pre_process_STAR___70757.invoke(query_processor.clj:240)"
  "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__69147$fn__69152.invoke(resolve_database_and_driver.clj:36)"
  "driver$do_with_driver.invokeStatic(driver.clj:90)"
  "driver$do_with_driver.invoke(driver.clj:86)"
  "query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__69147.invoke(resolve_database_and_driver.clj:35)"
  "query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__65018.invoke(fetch_source_query.clj:316)"
  "query_processor.middleware.store$initialize_store$fn__65196$fn__65197.invoke(store.clj:12)"
  "query_processor.store$do_with_store.invokeStatic(store.clj:47)"
  "query_processor.store$do_with_store.invoke(store.clj:41)"
  "query_processor.middleware.store$initialize_store$fn__65196.invoke(store.clj:11)"
  "query_processor.middleware.normalize_query$normalize$fn__69436.invoke(normalize_query.clj:25)"
  "query_processor.middleware.constraints$add_default_userland_constraints$fn__66374.invoke(constraints.clj:54)"
  "query_processor.middleware.process_userland_query$process_userland_query$fn__69372.invoke(process_userland_query.clj:151)"
  "query_processor.middleware.catch_exceptions$catch_exceptions$fn__69749.invoke(catch_exceptions.clj:171)"
  "query_processor.reducible$async_qp$qp_STAR___59517$thunk__59519.invoke(reducible.clj:103)"
  "query_processor.reducible$async_qp$qp_STAR___59517$fn__59521.invoke(reducible.clj:108)"],
 :card_id 6,
 :context :question,
 :error "(conn=191) Query execution was interrupted",
 :row_count 0,
 :running_time 0,
 :data {:rows [], :cols []}}

Luiggi · August 25, 2023, 6:37pm

how are you running Metabase? the default timeout seems to come from nginx

bb-centrum · August 29, 2023, 6:52am

I'm running the .JAR version of Metabase using the following command java -jar metabase.jar

I am then accessing it via the local network only. No proxy is involved.

Luiggi · August 29, 2023, 7:08am

Then your db is killing the connection

bb-centrum · August 29, 2023, 7:15am

Ok, but I can run the query without issue in DBeaver

DBeaver uses a JDBC driver and I believe Metabase does too. So if this is the issue, there is something unique to Metabase that is causing the issue. Is there a property in the connection settings I can change to extend this timeout?

bb-centrum · September 5, 2023, 9:30am

@Luiggi - Any ideas on what else I can try to fix this?

AndrewMBaines · September 5, 2023, 10:22am

Looks like you have 3 choices:

Write a better query (what's with all the right joins?)
Check for missing indexes
Cache the data - looks like MySQL syntax, so you might be limited there. Upgrade to Postgres?

12 mins is a long time for a query in a dashboard.

Luiggi · September 5, 2023, 10:34am

BTW: you're using Java 19 which is not supported, you need to go with Java 11. Thanks @AndrewMBaines

jamesbontempo · January 19, 2024, 7:14pm

@bb-centrum, did you ever find a way to address the timeout? I have a similar issue: I've extended timeouts on the DB, the proxy, and everywhere else I can think of, but am still getting timeouts whenever a query/question runs for longer than 10 minutes.

It's almost as if, somewhere, Metabase has a hard-coded 10-minute timeout; unless there's a configuration somewhere that I'm missing. Not having a way to extend what appears to be a Metabase-enforced timeout would be odd.

sao · January 22, 2024, 9:20am

It's almost as if, somewhere, Metabase has a hard-coded 10-minute timeout;

It does, thumb up this issue to have it removed:
https://github.com/metabase/metabase/issues/26325

jamesbontempo · January 22, 2024, 6:47pm

Thanks @sao!