Your question took too long - Metabase v0.36.7 on MacOS Catalina against MySQL 8.0.21

All of my long queries end in “Your question took too long” after 60 seconds.

I am running the MacOS version of Metabase on a MacOS laptop against a locally installed mySQL database via localhost, so there are no networking components involved that could be closing the connection.

Metabase log shows:
:status :failed,
:class java.sql.SQLTimeoutException,

I tried setting Mac environment variable, MB_JETTY_ASYNC_RESPONSE_TIMEOUT=1800000, but it is not being honored by Metabase.

I copied the Metabase-generated SQL script and ran it against the mySQL database using DBeaver database client version 7.2.2.202010041557. It completed successfully in 4.5 minutes.

The timeout appears to be happening within Metabase. I’m guessing within its bundled mysql database client code.

Any ideas?

Hi @dgindin
So even though you’re connecting to localhost, you’re still using network TCP and not sockets, but you don’t have various proxies between at least.

Please post the full stacktrace error message.

It has nothing to do with Jetty - but the Mac App doesn’t read environment variables at all.

There are so many settings in DBeaver, so it’s difficult to know what could be different without comparing SHOW VARIABLES; executed from both DBeaver and Metabase, and comparing for difference.

I’ve just tested SELECT sleep(300); on several versions of MySQL and MariaDB, with default configuration, and without getting any timeouts.

[3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:53-04:00 INFO metabase.driver.impl Initializing driver :mysql… [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:53-04:00 DEBUG metabase.middleware.log GET /api/database 200 16.1 ms (4 DB calls) App DB connections: 0/7 Jetty threads: 8/50 (4 idle, 0 queued) (54 total active threads) Queries in flight: 0 (0 queued) [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:53-04:00 DEBUG metabase.middleware.log GET /api/database 200 24.1 ms (9 DB calls) App DB connections: 0/7 Jetty threads: 7/50 (4 idle, 0 queued) (54 total active threads) Queries in flight: 0 (0 queued) [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:53-04:00 DEBUG metabase.middleware.log GET /api/card/1 200 33.7 ms (5 DB calls) App DB connections: 0/7 Jetty threads: 6/50 (4 idle, 0 queued) (54 total active threads) Queries in flight: 0 (0 queued) [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:53-04:00 DEBUG metabase.middleware.log GET /api/alert/question/1 200 2.8 ms (1 DB calls) App DB connections: 0/7 Jetty threads: 6/50 (4 idle, 0 queued) (54 total active threads) Queries in flight: 0 (0 queued) [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:53-04:00 DEBUG metabase.middleware.log GET /api/table/78/query_metadata 200 21.7 ms (10 DB calls) App DB connections: 0/7 Jetty threads: 6/50 (4 idle, 0 queued) (54 total active threads) Queries in flight: 0 (0 queued) [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:53-04:00 DEBUG metabase.middleware.log GET /api/table/80/query_metadata 200 5.6 ms (8 DB calls) App DB connections: 0/7 Jetty threads: 6/50 (4 idle, 0 queued) (54 total active threads) Queries in flight: 0 (0 queued) [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:53-04:00 DEBUG metabase.middleware.log GET /api/table/79/query_metadata 200 5.6 ms (8 DB calls) App DB connections: 0/7 Jetty threads: 6/50 (4 idle, 0 queued) (54 total active threads) Queries in flight: 0 (0 queued) [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:54-04:00 INFO metabase.api.card Question’s average execution duration is 1.0 mins; using ‘magic’ TTL of 10.3 mins :floppy_disk: [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:10:54-04:00 ERROR metabase.driver.sql-jdbc.execute Failed to set timezone ‘UTC’ for :mysql database [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:11:54-04:00 DEBUG metabase.middleware.log POST /api/card/1/query 202 [ASYNC: canceled] 1.0 mins (15 DB calls) App DB connections: 0/7 Jetty threads: 6/50 (6 idle, 0 queued) (56 total active threads) Queries in flight: 0 (0 queued) [3eef3231-be5b-45b6-89ad-7380a8c92c82] 2020-10-15T11:11:55-04:00 ERROR metabase.query-processor.middleware.catch-exceptions Error processing query: null {:database_id 4, :started_at #t “2020-10-15T11:10:54.128769-04:00[America/New_York]”, :state “70100”, :json_query {:constraints {:max-results 10000, :max-results-bare-rows 2000}, :type :query, :middleware {:js-int-to-string? true}, :database 4, :query {:source-table 78, :filter [:and [:= [:fk-> [:field-id 609] [:field-id 617]] “active”] [:= [:fk-> [:field-id 612] [:field-id 620]] 1007 1008 1009 1010 1011 1013]], :breakout [[:field-id 612] [:fk-> [:field-id 612] [:field-id 619]] [:field-id 615] [:field-id 610] [:field-id 613] [:field-id 611]], :aggregation [[:distinct [:field-id 609]]], :order-by [[:asc [:fk-> [:field-id 612] [:field-id 619]]] [:asc [:field-id 615]] [:asc [:field-id 610]] [:asc [:field-id 613]] [:asc [:field-id 611]]]}, :parameters [], :async? true, :cache-ttl 620}, :native {:query “SELECT all-packages.customer_id AS customer_id, customers__via__customer_id.name AS name, all-packages.platform AS platform, all-packages.platform_version AS platform_version, all-packages.package_name AS package_name, all-packages.package_version AS package_version, count(distinct all-packages.asset_id) AS count FROM all-packages LEFT JOIN agent_instances agent_instances__via__asset_id ON all-packages.asset_id = agent_instances__via__asset_id.uuid LEFT JOIN customers customers__via__customer_id ON all-packages.customer_id = customers__via__customer_id.id WHERE (agent_instances__via__asset_id.last_seen_state = ? AND (customers__via__customer_id.id = 1007 OR customers__via__customer_id.id = 1008 OR customers__via__customer_id.id = 1009 OR customers__via__customer_id.id = 1010 OR customers__via__customer_id.id = 1011 OR customers__via__customer_id.id = 1013)) GROUP BY all-packages.customer_id, customers__via__customer_id.name, all-packages.platform, all-packages.platform_version, all-packages.package_name, all-packages.package_version ORDER BY customers__via__customer_id.name ASC, all-packages.platform ASC, all-packages.platform_version ASC, all-packages.package_name ASC, all-packages.package_version ASC, all-packages.customer_id ASC”, :params (“active”)}, :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__72672.invokeStatic(execute.clj:267)” “driver.sql_jdbc.execute$fn__72672.invoke(execute.clj:265)” “driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:389)” “driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:377)” “driver.sql_jdbc$fn__73987.invokeStatic(sql_jdbc.clj:49)” “driver.sql_jdbc$fn__73987.invoke(sql_jdbc.clj:47)” “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:69)” “query_processor.context.default$default_runf.invoke(default.clj:67)” “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__45639.invoke(mbql_to_native.clj:26)” “query_processor.middleware.check_features$check_features$fn__44915.invoke(check_features.clj:42)” “query_processor.middleware.optimize_datetime_filters$optimize_datetime_filters$fn__45804.invoke(optimize_datetime_filters.clj:133)” “query_processor.middleware.wrap_value_literals$wrap_value_literals$fn__47332.invoke(wrap_value_literals.clj:137)” “query_processor.middleware.annotate$add_column_info$fn__43536.invoke(annotate.clj:574)” “query_processor.middleware.permissions$check_query_permissions$fn__44790.invoke(permissions.clj:64)” “query_processor.middleware.pre_alias_aggregations$pre_alias_aggregations$fn__46322.invoke(pre_alias_aggregations.clj:40)” “query_processor.middleware.cumulative_aggregations$handle_cumulative_aggregations$fn__44988.invoke(cumulative_aggregations.clj:61)” “query_processor.middleware.resolve_joins$resolve_joins$fn__46854.invoke(resolve_joins.clj:183)” “query_processor.middleware.add_implicit_joins$add_implicit_joins$fn__39262.invoke(add_implicit_joins.clj:245)” “query_processor.middleware.large_int_id$convert_id_to_string$fn__45600.invoke(large_int_id.clj:44)” “query_processor.middleware.limit$limit$fn__45625.invoke(limit.clj:38)” “query_processor.middleware.format_rows$format_rows$fn__45580.invoke(format_rows.clj:81)” “query_processor.middleware.desugar$desugar$fn__45054.invoke(desugar.clj:22)” “query_processor.middleware.binning$update_binning_strategy$fn__44080.invoke(binning.clj:229)” “query_processor.middleware.resolve_fields$resolve_fields$fn__44596.invoke(resolve_fields.clj:24)” “query_processor.middleware.add_dimension_projections$add_remapping$fn__38811.invoke(add_dimension_projections.clj:318)” “query_processor.middleware.add_implicit_clauses$add_implicit_clauses$fn__39018.invoke(add_implicit_clauses.clj:141)” “query_processor.middleware.add_source_metadata$add_source_metadata_for_source_queries$fn__39411.invoke(add_source_metadata.clj:105)” “query_processor.middleware.reconcile_breakout_and_order_by_bucketing$reconcile_breakout_and_order_by_bucketing$fn__46519.invoke(reconcile_breakout_and_order_by_bucketing.clj:98)” “query_processor.middleware.auto_bucket_datetimes$auto_bucket_datetimes$fn__43721.invoke(auto_bucket_datetimes.clj:125)” “query_processor.middleware.resolve_source_table$resolve_source_tables$fn__44643.invoke(resolve_source_table.clj:46)” “query_processor.middleware.parameters$substitute_parameters$fn__46304.invoke(parameters.clj:114)” “query_processor.middleware.resolve_referenced$resolve_referenced_card_resources$fn__44695.invoke(resolve_referenced.clj:80)” “query_processor.middleware.expand_macros$expand_macros$fn__45310.invoke(expand_macros.clj:158)” “query_processor.middleware.add_timezone_info$add_timezone_info$fn__39442.invoke(add_timezone_info.clj:15)” “query_processor.middleware.splice_params_in_response$splice_params_in_response$fn__47216.invoke(splice_params_in_response.clj:32)” “query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__46530$fn__46534.invoke(resolve_database_and_driver.clj:33)” “driver$do_with_driver.invokeStatic(driver.clj:61)” “driver$do_with_driver.invoke(driver.clj:57)” “query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__46530.invoke(resolve_database_and_driver.clj:27)” “query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__45528.invoke(fetch_source_query.clj:267)” “query_processor.middleware.store$initialize_store$fn__47225$fn__47226.invoke(store.clj:11)” “query_processor.store$do_with_store.invokeStatic(store.clj:46)” “query_processor.store$do_with_store.invoke(store.clj:40)” “query_processor.middleware.store$initialize_store$fn__47225.invoke(store.clj:10)” “query_processor.middleware.cache$run_query_with_cache.invokeStatic(cache.clj:182)” “query_processor.middleware.cache$run_query_with_cache.invoke(cache.clj:173)” “query_processor.middleware.cache$maybe_return_cached_results$fn__44572.invoke(cache.clj:208)” “query_processor.middleware.validate$validate_query$fn__47234.invoke(validate.clj:10)” “query_processor.middleware.normalize_query$normalize$fn__45652.invoke(normalize_query.clj:22)” “query_processor.middleware.add_rows_truncated$add_rows_truncated$fn__39280.invoke(add_rows_truncated.clj:36)” “query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__47201.invoke(results_metadata.clj:147)” “query_processor.middleware.constraints$add_default_userland_constraints$fn__44931.invoke(constraints.clj:42)” “query_processor.middleware.process_userland_query$process_userland_query$fn__46393.invoke(process_userland_query.clj:136)” “query_processor.middleware.catch_exceptions$catch_exceptions$fn__44874.invoke(catch_exceptions.clj:174)” “query_processor.reducible$async_qp$qp_STAR___38074$thunk__38075.invoke(reducible.clj:101)” “query_processor.reducible$async_qp$qp_STAR___38074$fn__38077.invoke(reducible.clj:106)”], :context :question, :error “(conn=109) Query execution was interrupted”, :row_count 0, :running_time 0, :preprocessed {:constraints {:max-results 10000, :max-results-bare-rows 2000}, :type :query, :middleware {:js-int-to-string? true}, :info {:executed-by 1, :context :question, :card-id 1, :query-hash [6, 27, 101, -36, -48, -37, -91, -37, 50, 74, 17, 28, 85, 27, -114, 58, -1, 83, 17, 7, -3, 88, 41, 25, 45, -65, -49, 34, 34, 94, 89, 108]}, :database 4, :query {:source-table 78, :filter [:and [:= [:joined-field “agent_instances__via__asset_id” [:field-id 617]] [:value “active” {:base_type :type/Text, :special_type :type/State, :database_type “VARCHAR”, :name “last_seen_state”}]] [:or [:= [:joined-field “customers__via__customer_id” [:field-id 620]] [:value 1007 {:base_type :type/Integer, :special_type :type/PK, :database_type “INT”, :name “id”}]] [:= [:joined-field “customers__via__customer_id” [:field-id 620]] [:value 1008 {:base_type :type/Integer, :special_type :type/PK, :database_type “INT”, :name “id”}]] [:= [:joined-field “customers__via__customer_id” [:field-id 620]] [:value 1009 {:base_type :type/Integer, :special_type :type/PK, :database_type “INT”, :name “id”}]] [:= [:joined-field “customers__via__customer_id” [:field-id 620]] [:value 1010 {:base_type :type/Integer, :special_type :type/PK, :database_type “INT”, :name “id”}]] [:= [:joined-field “customers__via__customer_id” [:field-id 620]] [:value 1011 {:base_type :type/Integer, :special_type :type/PK, :database_type “INT”, :name “id”}]] [:= [:joined-field “customers__via__customer_id” [:field-id 620]] [:value 1013 {:base_type :type/Integer, :special_type :type/PK, :database_type “INT”, :name “id”}]]]], :breakout [[:field-id 612] [:joined-field “customers__via__customer_id” [:field-id 619]] [:field-id 615] [:field-id 610] [:field-id 613] [:field-id 611]], :aggregation [[:aggregation-options [:distinct [:field-id 609]] {:name “count”}]], :order-by [[:asc [:joined-field “customers__via__customer_id” [:field-id 619]]] [:asc [:field-id 615]] [:asc [:field-id 610]] [:asc [:field-id 613]] [:asc [:field-id 611]] [:asc [:field-id 612]]], :joins [{:strategy :left-join, :source-table 79, :alias “agent_instances__via__asset_id”, :fk-field-id 609, :condition [:= [:field-id 609] [:joined-field “agent_instances__via__asset_id” [:field-id 618]]]} {:strategy :left-join, :source-table 80, :alias “customers__via__customer_id”, :fk-field-id 612, :condition [:= [:field-id 612] [:joined-field “customers__via__customer_id” [:field-id 620]]]}]}, :async? true, :cache-ttl 620}, :data {:rows [], :cols []}}

@dgindin
Metabase is receiving SQLSTATE[70100] Query execution was interrupted from the driver/database.
But since I don’t know your database configuration, then I don’t know which parameter is causing it - perhaps max_execution_time. Check the MySQL log for further details.